fortio.org/log@v1.12.2/http_logging_test.go (about) 1 package log // import "fortio.org/fortio/log" 2 3 import ( 4 "bufio" 5 "bytes" 6 "crypto/tls" 7 "crypto/x509" 8 "crypto/x509/pkix" 9 "errors" 10 "log" 11 "net/http" 12 "net/url" 13 "strings" 14 "testing" 15 "time" 16 ) 17 18 // There is additional functional testing in fortio.org/fortio/fhttp. 19 func TestLogRequest(t *testing.T) { 20 SetLogLevel(Verbose) // make sure it's already verbose when we capture 21 Config.LogFileAndLine = false 22 Config.JSON = true 23 Config.NoTimestamp = true 24 var b bytes.Buffer 25 w := bufio.NewWriter(&b) 26 SetOutput(w) 27 h := http.Header{"FoO": []string{"bar1", "bar2"}, "X-Forwarded-Host": []string{"fOO.fortio.org"}} 28 cert := &x509.Certificate{Subject: pkix.Name{CommonName: "x\nyz"}} // make sure special chars are escaped 29 r := &http.Request{TLS: &tls.ConnectionState{PeerCertificates: []*x509.Certificate{cert}}, Header: h, Host: "foo-host:123"} 30 LogRequest(r, "test1") 31 r.TLS = nil 32 r.Header = nil 33 LogRequest(r, "test2", Str("extra1", "v1"), Str("extra2", "v2")) 34 w.Flush() 35 actual := b.String() 36 //nolint: lll 37 expected := `{"level":"info","msg":"test1","method":"","url":null,"host":"foo-host:123","proto":"","remote_addr":"","tls":true,"tls.peer_cn":"x\nyz","header.foo":"bar1,bar2","header.x-forwarded-host":"fOO.fortio.org"} 38 {"level":"info","msg":"test2","method":"","url":null,"host":"foo-host:123","proto":"","remote_addr":"","extra1":"v1","extra2":"v2"} 39 ` 40 if actual != expected { 41 t.Errorf("unexpected:\n%s\nvs:\n%s\n", actual, expected) 42 } 43 } 44 45 func testHandler(w http.ResponseWriter, r *http.Request) { 46 if r.URL != nil && r.URL.Path == "/tea" { 47 w.WriteHeader(http.StatusTeapot) 48 } 49 w.Write([]byte("hello")) 50 time.Sleep(100 * time.Millisecond) 51 } 52 53 type NullHTTPWriter struct { 54 doErr bool 55 doPanic bool 56 } 57 58 func (n *NullHTTPWriter) Header() http.Header { 59 return nil 60 } 61 62 func (n *NullHTTPWriter) Write(b []byte) (int, error) { 63 if n.doPanic { 64 panic("some fake http write panic") 65 } 66 if n.doErr { 67 return 0, errors.New("some fake http write error") 68 } 69 return len(b), nil 70 } 71 72 // Also implement http.Flusher interface. 73 func (n *NullHTTPWriter) Flush() { 74 } 75 76 func (n *NullHTTPWriter) WriteHeader(_ int) {} 77 78 func TestLogAndCall(t *testing.T) { 79 Config.LogFileAndLine = true // yet won't show up in output 80 Config.JSON = true 81 Config.NoTimestamp = true 82 Config.CombineRequestAndResponse = false // Separate request and response logging 83 SetLogLevelQuiet(Info) 84 var b bytes.Buffer 85 w := bufio.NewWriter(&b) 86 SetOutput(w) 87 hr := &http.Request{} 88 hr.Header = http.Header{"foo": []string{"bar1", "bar2"}, "X-Forwarded-Host": []string{"foo2.fortio.org"}} 89 n := &NullHTTPWriter{} 90 hw := &ResponseRecorder{w: n} 91 LogAndCall("test-log-and-call", testHandler).ServeHTTP(hw, hr) 92 w.Flush() 93 actual := b.String() 94 //nolint: lll 95 expectedPrefix := `{"level":"info","msg":"test-log-and-call","method":"","url":null,"host":"","proto":"","remote_addr":"","header.x-forwarded-host":"foo2.fortio.org"} 96 {"level":"info","msg":"test-log-and-call","status":200,"size":5,"microsec":1` // the 1 is for the 100ms sleep 97 if !strings.HasPrefix(actual, expectedPrefix) { 98 t.Errorf("unexpected:\n%s\nvs should start with:\n%s\n", actual, expectedPrefix) 99 } 100 if hw.Header() != nil { 101 t.Errorf("unexpected non nil header: %v", hw.Header()) 102 } 103 hr.URL = &url.URL{Path: "/tea"} 104 b.Reset() 105 Config.CombineRequestAndResponse = true // Combined logging test 106 LogAndCall("test-log-and-call2", testHandler).ServeHTTP(hw, hr) 107 w.Flush() 108 actual = b.String() 109 //nolint: lll 110 expectedPrefix = `{"level":"info","msg":"test-log-and-call2","method":"","url":"/tea","host":"","proto":"","remote_addr":"","header.x-forwarded-host":"foo2.fortio.org","status":418,"size":5,"microsec":10` 111 if !strings.HasPrefix(actual, expectedPrefix) { 112 t.Errorf("unexpected:\n%s\nvs should start with:\n%s\n", actual, expectedPrefix) 113 } 114 b.Reset() 115 n.doErr = true 116 LogAndCall("test-log-and-call3", testHandler).ServeHTTP(hw, hr) 117 w.Flush() 118 actual = b.String() 119 expectedFragment := `"header.x-forwarded-host":"foo2.fortio.org","status":500,"size":0,"microsec":1` 120 if !strings.Contains(actual, expectedFragment) { 121 t.Errorf("unexpected:\n%s\nvs should contain error:\n%s\n", actual, expectedFragment) 122 } 123 n.doPanic = true 124 n.doErr = false 125 SetLogLevelQuiet(Verbose) 126 b.Reset() 127 LogAndCall("test-log-and-call4", testHandler).ServeHTTP(hw, hr) 128 w.Flush() 129 actual = b.String() 130 expectedFragment = `,"size":0,` 131 Config.GoroutineID = false 132 if !strings.Contains(actual, expectedFragment) { 133 t.Errorf("unexpected:\n%s\nvs should contain error:\n%s\n", actual, expectedFragment) 134 } 135 if !strings.Contains(actual, `{"level":"crit","msg":"panic in handler","error":"some fake http write panic"`) { 136 t.Errorf("unexpected:\n%s\nvs should contain error:\n%s\n", actual, "some fake http write panic") 137 } 138 // restore for other tests 139 Config.GoroutineID = true 140 // check for flusher interface 141 var hwi http.ResponseWriter = hw 142 flusher, ok := hwi.(http.Flusher) 143 if !ok { 144 t.Fatalf("expected http.ResponseWriter to be an http.Flusher") 145 } 146 flusher.Flush() 147 } 148 149 func TestLogResponseOnHTTPResponse(t *testing.T) { 150 SetLogLevel(Info) 151 Config.LogFileAndLine = false 152 Config.JSON = true 153 Config.NoTimestamp = true 154 var b bytes.Buffer 155 w := bufio.NewWriter(&b) 156 SetOutput(w) 157 r := &http.Response{StatusCode: http.StatusTeapot, ContentLength: 123} 158 LogResponse(r, "test1") 159 w.Flush() 160 actual := b.String() 161 expected := `{"level":"info","msg":"test1","status":418,"size":123} 162 ` 163 if actual != expected { 164 t.Errorf("unexpected:\n%s\nvs:\n%s\n", actual, expected) 165 } 166 SetLogLevelQuiet(Warning) 167 b.Reset() 168 LogResponse(r, "test2") 169 w.Flush() 170 actual = b.String() 171 if actual != "" { 172 t.Errorf("unexpected: %q", actual) 173 } 174 SetLogLevelQuiet(Verbose) 175 } 176 177 func TestLogRequestNoLog(t *testing.T) { 178 SetLogLevel(Warning) // make sure it's already debug when we capture 179 Config.LogFileAndLine = false 180 Config.JSON = true 181 var b bytes.Buffer 182 w := bufio.NewWriter(&b) 183 SetOutput(w) 184 r := &http.Request{} 185 LogRequest(r, "test1") 186 w.Flush() 187 actual := b.String() 188 if actual != "" { 189 t.Errorf("unexpected: %q", actual) 190 } 191 } 192 193 // Test for the "old" TLSInfo. 194 func TestTLSInfo(t *testing.T) { 195 h := http.Header{"foo": []string{"bar"}} 196 cert := &x509.Certificate{Subject: pkix.Name{CommonName: "x\nyz"}} // make sure special chars are escaped 197 r := &http.Request{TLS: &tls.ConnectionState{PeerCertificates: []*x509.Certificate{cert}}, Header: h} 198 got := TLSInfo(r) 199 expected := " https 0x0000 \"CN=x\\nyz\"" 200 if got != expected { 201 t.Errorf("unexpected for tls:\n%s\nvs:\n%s\n", got, expected) 202 } 203 r.TLS = nil 204 got = TLSInfo(r) 205 expected = "" 206 if got != expected { 207 t.Errorf("unexpected for no tls:\n%s\nvs:\n%s\n", got, expected) 208 } 209 } 210 211 func TestInterceptStandardLogger(t *testing.T) { 212 SetLogLevel(Warning) 213 Config.LogFileAndLine = true 214 Config.JSON = false // check that despite this, it'll be json anyway (so it doesn't go infinite loop) 215 Config.NoTimestamp = true 216 var b bytes.Buffer 217 w := bufio.NewWriter(&b) 218 SetOutput(w) 219 InterceptStandardLogger(Warning) 220 log.Printf("\n\na test\n\n") 221 w.Flush() 222 actual := b.String() 223 expected := `{"level":"warn","msg":"a test","src":"std"}` + "\n" 224 if actual != expected { 225 t.Errorf("unexpected:\n%s\nvs:\n%s\n", actual, expected) 226 } 227 } 228 229 func TestNewStdLogger(t *testing.T) { 230 SetLogLevel(Info) 231 Config.LogFileAndLine = true 232 Config.JSON = false 233 Config.NoTimestamp = true 234 var b bytes.Buffer 235 w := bufio.NewWriter(&b) 236 SetOutput(w) 237 logger := NewStdLogger("test src", Info) 238 logger.Printf("\n\nanother test\n\n") 239 w.Flush() 240 actual := b.String() 241 expected := `{"level":"info","msg":"another test","src":"test src"}` + "\n" 242 if actual != expected { 243 t.Errorf("unexpected:\n%s\nvs:\n%s\n", actual, expected) 244 } 245 }