For reading and verification only. You may not copy, use, modify or redistribute this code. Full notice on the main page.
tunnel/loghygiene_test.go
| 1 | package main |
| 2 | |
| 3 | import ( |
| 4 | "context" |
| 5 | "fmt" |
| 6 | "regexp" |
| 7 | "strings" |
| 8 | "testing" |
| 9 | "time" |
| 10 | ) |
| 11 | |
| 12 | // No IP or SNI in persistent logs (plan section 5): a full run of the node through everything it does, then a grep of what it wrote and of its metrics |
| 13 | // for every address, label, host name and device id the run used, and for anything shaped like one. |
| 14 | |
| 15 | func TestLogs_AFullRunLeavesNoAddressNoLabelNoNameInTheLogsOrTheMetrics(t *testing.T) { |
| 16 | e := newVIPEnv(t, func(e *testEnv, c *Config) { |
| 17 | c.UnknownSNIPerIP, c.LabelNewPerS, c.LabelNewBurst, c.PerIPConcurrent = 3, 2, 3, 4 |
| 18 | c.GatedBytesPerDay = 70_000 |
| 19 | c.MaxStreamsPerHost = 6 |
| 20 | c.LabelAnonSlice = 3 |
| 21 | c.PrefixFetch = func(context.Context) ([]byte, error) { |
| 22 | return []byte(`{"prefixes":[{"ipv4Prefix":"192.0.2.0/24"},{"ipv6Prefix":"2001:db8:cafe::/48"}]}`), nil |
| 23 | } |
| 24 | c.PerIPNewPerS = 1 << 20 |
| 25 | }) |
| 26 | eventually(t, "the prefix list", 3*time.Second, func() bool { return e.srv.openai.size() == 2 }) |
| 27 | release := make(chan struct{}) |
| 28 | |
| 29 | paid, gated, offline := e.newDevice(), e.newDevice(), e.newDevice() |
| 30 | e.plan(gated).status, e.plan(gated).plan = statusGated, "trial" |
| 31 | pc := e.connectOK(paid) |
| 32 | pc.serve(holdHandler(paid, release)) |
| 33 | gc := e.connectOK(gated) |
| 34 | gc.serve(nil) |
| 35 | |
| 36 | ips := []string{"198.51.100.17", "203.0.113.200", "2001:db8:1234:5678::9", "192.0.2.77", "2001:db8:cafe::1", "198.51.100.18"} |
| 37 | // streams from several sources, a HINT, the label rate and the host cap |
| 38 | pc.send("HINT 203.0.113.200 2001:db8:1234:5678::9") |
| 39 | eventually(t, "the hint", 3*time.Second, func() bool { return e.srv.hints.size() == 2 }) |
| 40 | for _, ip := range ips { |
| 41 | for i := 0; i < 3; i++ { |
| 42 | _, _ = e.clientFrom(ip, paid) |
| 43 | } |
| 44 | } |
| 45 | // names that are nobody's, a scanner that is banned, junk |
| 46 | scanner := "198.51.100.99" |
| 47 | names := []string{offline.host} |
| 48 | for i := 0; i < 5; i++ { |
| 49 | names = append(names, fmt.Sprintf("%c%019d.devices.all-e2e.test", 'a'+i, i)) |
| 50 | } |
| 51 | for _, n := range names { |
| 52 | e.helloFrom(scanner, n, 500*time.Millisecond) |
| 53 | } |
| 54 | e.helloFrom(scanner, paid.host, 500*time.Millisecond) |
| 55 | ips = append(ips, scanner) |
| 56 | // the gated device runs out of bytes; the paid one renews; a refused device |
| 57 | if c, err := e.clientFrom("198.51.100.50", gated); err == nil { |
| 58 | _, _ = postOver(c, gated.host, make([]byte, 300_000)) |
| 59 | } |
| 60 | ips = append(ips, "198.51.100.50") |
| 61 | pc.drainFeed() |
| 62 | if r := pc.renew(); !strings.HasPrefix(r, "OK ") { |
| 63 | t.Fatalf("renew: %q", r) |
| 64 | } |
| 65 | stranger := e.newDeviceNoPlan() |
| 66 | sc := e.connect(stranger) |
| 67 | sc.hello(func() string { return e.session(stranger, nil) }, func(s, n string) string { return e.proof(stranger, s, n, nil) }) |
| 68 | // a client that is not TLS, a cut hello, a client that says nothing |
| 69 | raw := sendRaw(t, e, []byte("GET / HTTP/1.1\r\n\r\n"), 0) |
| 70 | _ = raw |
| 71 | go e.srv.Drain(3 * time.Second) |
| 72 | eventually(t, "draining", 3*time.Second, func() bool { return e.srv.Draining() }) |
| 73 | e.helloFrom("198.51.100.60", paid.host, 500*time.Millisecond) |
| 74 | ips = append(ips, "198.51.100.60") |
| 75 | close(release) |
| 76 | time.Sleep(300 * time.Millisecond) |
| 77 | |
| 78 | logs, metrics := e.logs.String(), e.srv.renderMetrics() |
| 79 | // The node's own listen address (the "listening" line, written once from its configuration) is the operator's, not a client's, and the time of each |
| 80 | // line is not an address however it reads. |
| 81 | var kept []string |
| 82 | for _, line := range strings.Split(logs, "\n") { |
| 83 | if !strings.Contains(line, `"msg":"listening"`) { |
| 84 | kept = append(kept, regexp.MustCompile(`"time":"[^"]*",`).ReplaceAllString(line, "")) |
| 85 | } |
| 86 | } |
| 87 | logs = strings.Join(kept, "\n") |
| 88 | if len(logs) < 2000 || !strings.Contains(logs, `"msg":"stream_open"`) || !strings.Contains(logs, `"msg":"source_banned"`) || !strings.Contains(logs, `"msg":"conn_reject"`) { |
| 89 | t.Fatalf("the control is empty: the run did not exercise the node (%d bytes of logs)", len(logs)) |
| 90 | } |
| 91 | secrets := map[string]string{ |
| 92 | "the loopback address": "127.0.0.1", "the loopback v6": "::1", |
| 93 | } |
| 94 | for i, ip := range ips { |
| 95 | secrets[fmt.Sprintf("source %d", i)] = ip |
| 96 | } |
| 97 | for _, d := range []*testDevice{paid, gated, offline, stranger} { |
| 98 | secrets["a label"+d.label] = d.label |
| 99 | secrets["a host"+d.label] = d.host |
| 100 | secrets["a device id"+d.label] = d.id |
| 101 | } |
| 102 | for _, n := range names { |
| 103 | secrets["the name "+n] = n |
| 104 | secrets["the label of "+n] = n[:20] |
| 105 | } |
| 106 | secrets["the zone"] = testZone |
| 107 | secrets["the node's own name"] = testNodeHost |
| 108 | for what, secret := range secrets { |
| 109 | for where, text := range map[string]string{"logs": logs, "metrics": metrics} { |
| 110 | if strings.Contains(text, secret) { |
| 111 | t.Errorf("%s hold %s (%q)", where, what, secret) |
| 112 | } |
| 113 | } |
| 114 | } |
| 115 | for what, re := range map[string]*regexp.Regexp{ |
| 116 | "an IPv4 address": regexp.MustCompile(`\b\d{1,3}\.\d{1,3}\.\d{1,3}\.\d{1,3}\b`), |
| 117 | "an IPv6 address": regexp.MustCompile(`(?i)\b[0-9a-f]{0,4}:[0-9a-f]{0,4}:[0-9a-f:]{2,}`), |
| 118 | "something label-like": regexp.MustCompile(`\b[a-z2-7]{20}\b`), // on word boundaries: a 32-character hex stream id holds a run of 20 such characters now and then |
| 119 | "a host name": regexp.MustCompile(`[a-z0-9-]+\.[a-z0-9-]+\.(test|org|com|net)`), |
| 120 | } { |
| 121 | for where, text := range map[string]string{"logs": logs, "metrics": metrics} { |
| 122 | if m := re.FindString(text); m != "" { |
| 123 | t.Errorf("%s hold %s: %q", where, what, m) |
| 124 | } |
| 125 | } |
| 126 | } |
| 127 | // the one way a source appears is the per-boot salted short hash, and it is not the address |
| 128 | re := regexp.MustCompile(`"source":"([0-9a-f]{8})"`) |
| 129 | m := re.FindStringSubmatch(logs) |
| 130 | if m == nil { |
| 131 | t.Fatalf("a ban was logged without the short hash:\n%s", grepLines(logs, "source_banned")) |
| 132 | } |
| 133 | if m[1] != e.srv.short(scanner) { |
| 134 | t.Fatalf("the hash %s is not the scanner's %s", m[1], e.srv.short(scanner)) |
| 135 | } |
| 136 | // the salt is per boot: another node hashes the same address to another word |
| 137 | other := newVIPEnv(t, nil) |
| 138 | if other.srv.short(scanner) == e.srv.short(scanner) { |
| 139 | t.Fatal("two boots hash an address to the same word") |
| 140 | } |
| 141 | } |
| 142 | |
| 143 | func grepLines(text, sub string) string { |
| 144 | var out []string |
| 145 | for _, line := range strings.Split(text, "\n") { |
| 146 | if strings.Contains(line, sub) { |
| 147 | out = append(out, line) |
| 148 | } |
| 149 | } |
| 150 | return strings.Join(out, "\n") |
| 151 | } |