github.com/altipla-consulting/ravendb-go-client@v0.1.3/tests/logging_test.go (about) 1 package tests 2 3 import ( 4 "bytes" 5 "fmt" 6 "io" 7 "io/ioutil" 8 "net/http" 9 "net/http/httputil" 10 "os" 11 "path/filepath" 12 "runtime" 13 "runtime/pprof" 14 "strings" 15 "sync" 16 "sync/atomic" 17 "testing" 18 19 ravendb "github.com/altipla-consulting/ravendb-go-client" 20 ) 21 22 var ( 23 // if true, printing of failed reqeusts is delayed until PrintFailedRequests 24 // is called. 25 // can be enabled by setting LOG_FAILED_HTTP_REQUESTS_DELAYED env variable to "true" 26 logFailedRequestsDelayed = false 27 28 // if true, logs all http requests/responses to a file for further inspection 29 // this is for use in tests so the file has a fixed location: 30 // logs/trace_${test_name}_go.txt 31 logAllRequests = false 32 33 // if true, we log RavenDB's output to stdout 34 // can be enabled by setting LOG_RAVEN_SERVER env variable to "true" 35 ravenServerVerbose = false 36 37 // if true, logs summary of all HTTP requests i.e. "GET /foo" to stdout 38 logRequestSummary = false 39 40 // if true, logs request and response of failed http requests (i.e. those returning 41 // status code >= 400) to stdout 42 logFailedRequests = false 43 44 logTopology = false 45 46 // testFileLog is a per-test file logs/trace_${test_name}_go.txt where we log all http requests, responses and 47 // other stuff 48 testFileLog io.WriteCloser 49 // httpFailedRequestsLogger is where we log failed http requests. 50 // it's either os.Stdout for immediate logging or bytes.Buffer for delayed logging 51 httpFailedRequestsLogger io.Writer 52 // httpRequestCount numbers http requests which helps to match http 53 // traffic from java client with go client 54 httpRequestCount int32 55 56 errLogDisabled int32 // atomic, if > 0, don't log error requests 57 58 muLog sync.Mutex 59 ) 60 61 func logsLock() { 62 muLog.Lock() 63 } 64 65 func logsUnlock() { 66 muLog.Unlock() 67 } 68 69 func logToPerTestFile(format string, args ...interface{}) { 70 logsLock() 71 defer logsUnlock() 72 73 if testFileLog == nil { 74 return 75 } 76 s := fmt.Sprintf(format, args...) 77 _, _ = testFileLog.Write([]byte(s)) 78 } 79 80 // this logs to both stdout and to a per-test file 81 func lg(format string, args ...interface{}) { 82 fmt.Printf(format, args...) 83 logToPerTestFile(format, args...) 84 } 85 86 func logTestName() { 87 /* print the name of the calling function, which we assume is a test */ 88 pc := make([]uintptr, 16) 89 n := runtime.Callers(2, pc) 90 if n == 0 { 91 return 92 } 93 frames := runtime.CallersFrames(pc[:n]) 94 frame, _ := frames.Next() 95 fn := frame.Function 96 parts := strings.Split(fn, ".") 97 n = len(parts) 98 if n > 0 { 99 fn = parts[n-1] 100 } 101 lg("Test: %s\n", fn) 102 } 103 104 func setLoggingStateFromEnv() { 105 if !ravenServerVerbose && isEnvVarTrue("LOG_RAVEN_SERVER") { 106 ravenServerVerbose = true 107 fmt.Printf("Setting ravenServerVerbose to true\n") 108 } 109 110 if !logFailedRequestsDelayed && isEnvVarTrue("LOG_FAILED_HTTP_REQUESTS_DELAYED") { 111 logFailedRequestsDelayed = true 112 fmt.Printf("Setting logFailedRequestsDelayed to true\n") 113 } 114 115 if !ravendb.LogVerbose && isEnvVarTrue("VERBOSE_LOG") { 116 ravendb.LogVerbose = true 117 fmt.Printf("Setting LogVerbose to true\n") 118 } 119 120 if !logRequestSummary && isEnvVarTrue("LOG_HTTP_REQUEST_SUMMARY") { 121 logRequestSummary = true 122 fmt.Printf("Setting LogRequestSummary to true\n") 123 } 124 125 if !logFailedRequests && isEnvVarTrue("LOG_FAILED_HTTP_REQUESTS") { 126 logFailedRequests = true 127 fmt.Printf("Setting LogFailedRequests to true\n") 128 } 129 130 if !logAllRequests && isEnvVarTrue("LOG_ALL_REQUESTS") { 131 logAllRequests = true 132 fmt.Printf("Setting logAllRequests to true\n") 133 } 134 135 if !logTopology && isEnvVarTrue("LOG_TOPOLOGY") { 136 logTopology = true 137 fmt.Printf("Setting logTopology to true\n") 138 } 139 } 140 141 type loggingTransport struct { 142 originalTransport http.RoundTripper 143 } 144 145 func (t *loggingTransport) RoundTrip(req *http.Request) (*http.Response, error) { 146 atomic.AddInt32(&httpRequestCount, 1) 147 148 maybeLogRequestSummary(req) 149 maybeCaptureRequestBody(req) 150 rsp, err := t.originalTransport.RoundTrip(req) 151 maybeLogFailedResponse(req, rsp, err) 152 maybeLogHTTPRequest(req, rsp, err) 153 return rsp, err 154 } 155 156 func httpClientProcessor(c *http.Client) { 157 t := c.Transport 158 c.Transport = &loggingTransport{ 159 originalTransport: t, 160 } 161 } 162 163 func httpLogPathFromTestName(t *testing.T) string { 164 name := "trace_" + testNameToFileName(t.Name()) + "_go.txt" 165 return filepath.Join(getLogDir(), name) 166 } 167 168 func logSubscriptionWorker(op string, d []byte) { 169 logToPerTestFile("SubscriptionWorker: op: %s, data:\n%s\n", op, string(d)) 170 } 171 172 func setupLogging(t *testing.T) { 173 logsLock() 174 defer logsUnlock() 175 176 ravendb.DebugTopology = logTopology 177 178 ravendb.HTTPClientPostProcessor = httpClientProcessor 179 ravendb.LogSubscriptionWorker = logSubscriptionWorker 180 181 testFileLog = nil 182 if logAllRequests { 183 var err error 184 path := httpLogPathFromTestName(t) 185 f, err := os.Create(path) 186 if err != nil { 187 fmt.Printf("os.Create('%s') failed with %s\n", path, err) 188 } else { 189 fmt.Printf("Logging HTTP traffic to %s\n", path) 190 testFileLog = f 191 } 192 } 193 194 httpFailedRequestsLogger = nil 195 if logFailedRequests { 196 if logFailedRequestsDelayed { 197 httpFailedRequestsLogger = bytes.NewBuffer(nil) 198 } else { 199 httpFailedRequestsLogger = os.Stdout 200 } 201 } 202 } 203 204 func finishLogging() { 205 logsLock() 206 defer logsUnlock() 207 w := testFileLog 208 if w != nil { 209 _ = w.Close() 210 testFileLog = nil 211 } 212 } 213 214 func isErrLoggingDisabled() bool { 215 n := atomic.LoadInt32(&errLogDisabled) 216 return n > 0 217 } 218 219 // for temporarily disabling logging of failed requests (if a given 220 // test is known to issue failing requests) 221 // usage: defer disableLogFailedRequests()() 222 // or: 223 // restorer := disableLogFailedRequests() 224 // ... 225 // restorer() 226 // this is not perfect in parallel tests because (it might over-disable) 227 // but we're not doing parallel tests 228 func disableLogFailedRequests() func() { 229 atomic.AddInt32(&errLogDisabled, 1) 230 return func() { 231 atomic.AddInt32(&errLogDisabled, -1) 232 } 233 } 234 235 // returns copy of resp.Body but also makes it available for subsequent reads 236 func getCopyOfResponseBody(resp *http.Response) ([]byte, error) { 237 if resp == nil { 238 return nil, nil 239 } 240 d, err := ioutil.ReadAll(resp.Body) 241 if err != nil { 242 return nil, err 243 } 244 resp.Body = ioutil.NopCloser(bytes.NewBuffer(d)) 245 return d, nil 246 } 247 248 func logRequestAndResponseToWriter(w io.Writer, req *http.Request, rsp *http.Response, reqErr error) { 249 n := atomic.LoadInt32(&httpRequestCount) 250 251 fmt.Fprintf(w, "=========== %d:\n", n) 252 if reqErr != nil { 253 fmt.Fprintf(w, "%s\n", reqErr) 254 } 255 256 d, err := httputil.DumpRequest(req, false) 257 if err == nil { 258 _, _ = w.Write(d) 259 } 260 261 if req.Body != nil { 262 if cr, ok := req.Body.(*CapturingReadCloser); ok { 263 body := cr.capturedData.Bytes() 264 if len(body) > 0 { 265 fmt.Fprintf(w, "Request body %d bytes:\n%s\n", len(body), maybePrettyPrintJSON(body)) 266 } 267 } else { 268 fmt.Fprint(w, "Can't get request body\n") 269 } 270 } 271 272 if reqErr != nil { 273 return 274 } 275 276 if rsp == nil { 277 fmt.Fprint(w, "No response\n") 278 return 279 } 280 fmt.Fprint(w, "--------\n") 281 d, err = httputil.DumpResponse(rsp, false) 282 if err == nil { 283 _, _ = w.Write(d) 284 } 285 if d, err := getCopyOfResponseBody(rsp); err != nil { 286 fmt.Fprintf(w, "Failed to read response body. Error: '%s'\n", err) 287 } else { 288 if len(d) > 0 { 289 fmt.Fprintf(w, "Response body %d bytes:\n%s\n", len(d), maybePrettyPrintJSON(d)) 290 } 291 } 292 } 293 294 func maybePrintFailedRequestsLog() { 295 logsLock() 296 defer logsUnlock() 297 if logFailedRequests && logFailedRequestsDelayed { 298 buf := httpFailedRequestsLogger.(*bytes.Buffer) 299 _, _ = os.Stdout.Write(buf.Bytes()) 300 buf.Reset() 301 } 302 } 303 304 func maybeLogHTTPRequest(req *http.Request, rsp *http.Response, err error) { 305 logsLock() 306 defer logsUnlock() 307 308 if testFileLog == nil { 309 return 310 } 311 logRequestAndResponseToWriter(testFileLog, req, rsp, err) 312 } 313 314 func maybeLogFailedResponse(req *http.Request, rsp *http.Response, err error) { 315 logsLock() 316 defer logsUnlock() 317 318 if !logFailedRequests || isErrLoggingDisabled() { 319 return 320 } 321 if err == nil && rsp.StatusCode < 400 { 322 // not failed 323 return 324 } 325 logRequestAndResponseToWriter(httpFailedRequestsLogger, req, rsp, err) 326 } 327 328 // to be able to print request body for failed requests, we must replace 329 // body with one that captures data read from original body. 330 func maybeCaptureRequestBody(req *http.Request) { 331 shouldCapture := (logFailedRequests && !isErrLoggingDisabled()) || (testFileLog != nil) 332 if !shouldCapture { 333 return 334 } 335 336 switch req.Method { 337 case http.MethodGet, http.MethodHead, "RESET": 338 // just in case (probably redundant with req.Bddy != nil check) 339 return 340 } 341 if req.Body != nil { 342 req.Body = NewCapturingReadCloser(req.Body) 343 } 344 } 345 346 func maybeLogRequestSummary(req *http.Request) { 347 if !logRequestSummary { 348 return 349 } 350 method := req.Method 351 uri := req.URL.String() 352 lg("%s %s\n", method, uri) 353 } 354 355 // This helps debugging leaking gorutines by dumping stack traces 356 // of all goroutines to a file 357 func logGoroutines(file string) { 358 if file == "" { 359 file = "goroutines.txt" 360 } 361 path := filepath.Join("logs", file) 362 dir := filepath.Dir(path) 363 err := os.MkdirAll(dir, 0755) 364 if err != nil { 365 return 366 } 367 profile := pprof.Lookup("goroutine") 368 if profile == nil { 369 return 370 } 371 372 f, err := os.Create(path) 373 if err != nil { 374 return 375 } 376 defer func() { 377 _ = f.Close() 378 }() 379 _ = profile.WriteTo(f, 2) 380 }