github.com/opensearch-project/opensearch-go/v2@v2.3.0/opensearchtransport/logger_internal_test.go (about) 1 // SPDX-License-Identifier: Apache-2.0 2 // 3 // The OpenSearch Contributors require contributions made to 4 // this file be licensed under the Apache-2.0 license or a 5 // compatible open source license. 6 // 7 // Modifications Copyright OpenSearch Contributors. See 8 // GitHub history for details. 9 10 // Licensed to Elasticsearch B.V. under one or more contributor 11 // license agreements. See the NOTICE file distributed with 12 // this work for additional information regarding copyright 13 // ownership. Elasticsearch B.V. licenses this file to you under 14 // the Apache License, Version 2.0 (the "License"); you may 15 // not use this file except in compliance with the License. 16 // You may obtain a copy of the License at 17 // 18 // http://www.apache.org/licenses/LICENSE-2.0 19 // 20 // Unless required by applicable law or agreed to in writing, 21 // software distributed under the License is distributed on an 22 // "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY 23 // KIND, either express or implied. See the License for the 24 // specific language governing permissions and limitations 25 // under the License. 26 27 // +build !integration 28 29 package opensearchtransport 30 31 import ( 32 "encoding/json" 33 "errors" 34 "fmt" 35 "io" 36 "io/ioutil" 37 "net/http" 38 "net/url" 39 "os" 40 "regexp" 41 "strings" 42 "sync" 43 "testing" 44 "time" 45 ) 46 47 var ( 48 _ = fmt.Print 49 _ = os.Stdout 50 ) 51 52 func TestTransportLogger(t *testing.T) { 53 newRoundTripper := func() http.RoundTripper { 54 return &mockTransp{ 55 RoundTripFunc: func(req *http.Request) (*http.Response, error) { 56 return &http.Response{ 57 Status: "200 OK", 58 StatusCode: 200, 59 ContentLength: 13, 60 Header: http.Header(map[string][]string{"Content-Type": {"application/json"}}), 61 Body: ioutil.NopCloser(strings.NewReader(`{"foo":"bar"}`)), 62 }, nil 63 }, 64 } 65 } 66 67 t.Run("Defaults", func(t *testing.T) { 68 var wg sync.WaitGroup 69 70 tp, _ := New(Config{ 71 URLs: []*url.URL{{Scheme: "http", Host: "foo"}}, 72 Transport: newRoundTripper(), 73 // Logger: ioutil.Discard, 74 }) 75 76 for i := 0; i < 100; i++ { 77 wg.Add(1) 78 go func() { 79 defer wg.Done() 80 81 req, _ := http.NewRequest("GET", "/abc", nil) 82 _, err := tp.Perform(req) 83 if err != nil { 84 t.Errorf("Unexpected error: %s", err) 85 return 86 } 87 }() 88 } 89 wg.Wait() 90 }) 91 92 t.Run("Nil", func(t *testing.T) { 93 tp, _ := New(Config{ 94 URLs: []*url.URL{{Scheme: "http", Host: "foo"}}, 95 Transport: newRoundTripper(), 96 Logger: nil, 97 }) 98 99 req, _ := http.NewRequest("GET", "/abc", nil) 100 _, err := tp.Perform(req) 101 if err != nil { 102 t.Fatalf("Unexpected error: %s", err) 103 } 104 }) 105 106 t.Run("No HTTP response", func(t *testing.T) { 107 tp, _ := New(Config{ 108 URLs: []*url.URL{{Scheme: "http", Host: "foo"}}, 109 Transport: &mockTransp{ 110 RoundTripFunc: func(req *http.Request) (*http.Response, error) { 111 return nil, errors.New("Mock error") 112 }, 113 }, 114 Logger: &TextLogger{Output: ioutil.Discard}, 115 }) 116 117 req, _ := http.NewRequest("GET", "/abc", nil) 118 res, err := tp.Perform(req) 119 if err == nil { 120 t.Errorf("Expected error: %v", err) 121 } 122 if res != nil { 123 t.Errorf("Expected nil response, got: %v", err) 124 } 125 }) 126 127 t.Run("Keep response body", func(t *testing.T) { 128 var dst strings.Builder 129 130 tp, _ := New(Config{ 131 URLs: []*url.URL{{Scheme: "http", Host: "foo"}}, 132 Transport: newRoundTripper(), 133 Logger: &TextLogger{Output: &dst, EnableRequestBody: true, EnableResponseBody: true}, 134 }) 135 136 req, _ := http.NewRequest("GET", "/abc?q=a,b", nil) 137 req.Body = ioutil.NopCloser(strings.NewReader(`{"query":"42"}`)) 138 139 res, err := tp.Perform(req) 140 if err != nil { 141 t.Fatalf("Unexpected error: %s", err) 142 } 143 144 body, err := ioutil.ReadAll(res.Body) 145 if err != nil { 146 t.Fatalf("Error reading response body: %s", err) 147 } 148 149 if len(dst.String()) < 1 { 150 t.Errorf("Log is empty: %#v", dst.String()) 151 } 152 153 if len(body) < 1 { 154 t.Fatalf("Body is empty: %#v", body) 155 } 156 }) 157 158 t.Run("Text with body", func(t *testing.T) { 159 var dst strings.Builder 160 161 tp, _ := New(Config{ 162 URLs: []*url.URL{{Scheme: "http", Host: "foo"}}, 163 Transport: newRoundTripper(), 164 Logger: &TextLogger{Output: &dst, EnableRequestBody: true, EnableResponseBody: true}, 165 }) 166 167 req, _ := http.NewRequest("GET", "/abc?q=a,b", nil) 168 req.Body = ioutil.NopCloser(strings.NewReader(`{"query":"42"}`)) 169 170 res, err := tp.Perform(req) 171 if err != nil { 172 t.Fatalf("Unexpected error: %s", err) 173 } 174 175 _, err = ioutil.ReadAll(res.Body) 176 if err != nil { 177 t.Fatalf("Error reading response body: %s", err) 178 } 179 180 output := dst.String() 181 output = strings.TrimSuffix(output, "\n") 182 // fmt.Println(output) 183 184 lines := strings.Split(output, "\n") 185 186 if len(lines) != 3 { 187 t.Fatalf("Expected 3 lines, got %d", len(lines)) 188 } 189 190 if !strings.Contains(lines[0], "GET http://foo/abc?q=a,b") { 191 t.Errorf("Unexpected output: %s", lines[0]) 192 } 193 194 if lines[1] != `> {"query":"42"}` { 195 t.Errorf("Unexpected output: %s", lines[1]) 196 } 197 198 if lines[2] != `< {"foo":"bar"}` { 199 t.Errorf("Unexpected output: %s", lines[1]) 200 } 201 }) 202 203 t.Run("Color with body", func(t *testing.T) { 204 var dst strings.Builder 205 206 tp, _ := New(Config{ 207 URLs: []*url.URL{{Scheme: "http", Host: "foo"}}, 208 Transport: newRoundTripper(), 209 Logger: &ColorLogger{Output: &dst, EnableRequestBody: true, EnableResponseBody: true}, 210 }) 211 212 req, _ := http.NewRequest("GET", "/abc?q=a,b", nil) 213 req.Body = ioutil.NopCloser(strings.NewReader(`{"query":"42"}`)) 214 215 res, err := tp.Perform(req) 216 if err != nil { 217 t.Fatalf("Unexpected error: %s", err) 218 } 219 220 _, err = ioutil.ReadAll(res.Body) 221 if err != nil { 222 t.Fatalf("Error reading response body: %s", err) 223 } 224 225 var output string 226 stripANSI := regexp.MustCompile("(?sm)\x1b\\[.+?m([^\x1b]+?)|\x1b\\[0m") 227 for _, v := range strings.Split(dst.String(), "\n") { 228 if v != "" { 229 output += stripANSI.ReplaceAllString(v, "$1") 230 if !strings.HasSuffix(output, "\n") { 231 output += "\n" 232 } 233 } 234 } 235 output = strings.TrimSuffix(output, "\n") 236 // fmt.Println(output) 237 238 lines := strings.Split(output, "\n") 239 240 if len(lines) != 4 { 241 t.Fatalf("Expected 4 lines, got %d", len(lines)) 242 } 243 244 if !strings.Contains(lines[0], "GET http://foo/abc?q=a,b") { 245 t.Errorf("Unexpected output: %s", lines[0]) 246 } 247 248 if !strings.Contains(lines[1], `» {"query":"42"}`) { 249 t.Errorf("Unexpected output: %s", lines[1]) 250 } 251 252 if !strings.Contains(lines[2], `« {"foo":"bar"}`) { 253 t.Errorf("Unexpected output: %s", lines[2]) 254 } 255 }) 256 257 t.Run("Curl", func(t *testing.T) { 258 var dst strings.Builder 259 260 tp, _ := New(Config{ 261 URLs: []*url.URL{{Scheme: "http", Host: "foo"}}, 262 Transport: newRoundTripper(), 263 Logger: &CurlLogger{Output: &dst, EnableRequestBody: true, EnableResponseBody: true}, 264 }) 265 266 req, _ := http.NewRequest("GET", "/abc?q=a,b", nil) 267 req.Body = ioutil.NopCloser(strings.NewReader(`{"query":"42"}`)) 268 269 res, err := tp.Perform(req) 270 if err != nil { 271 t.Fatalf("Unexpected error: %s", err) 272 } 273 274 _, err = ioutil.ReadAll(res.Body) 275 if err != nil { 276 t.Fatalf("Error reading response body: %s", err) 277 } 278 279 output := dst.String() 280 output = strings.TrimSuffix(output, "\n") 281 282 lines := strings.Split(output, "\n") 283 284 if len(lines) != 9 { 285 t.Fatalf("Expected 9 lines, got %d", len(lines)) 286 } 287 288 if !strings.Contains(lines[0], "curl -X GET 'http://foo/abc?pretty&q=a%2Cb'") { 289 t.Errorf("Unexpected output: %s", lines[0]) 290 } 291 }) 292 293 t.Run("JSON", func(t *testing.T) { 294 var dst strings.Builder 295 296 tp, _ := New(Config{ 297 URLs: []*url.URL{{Scheme: "http", Host: "foo"}}, 298 Transport: newRoundTripper(), 299 Logger: &JSONLogger{Output: &dst}, 300 }) 301 302 req, _ := http.NewRequest("GET", "/abc?q=a,b", nil) 303 req.Body = ioutil.NopCloser(strings.NewReader(`{"query":"42"}`)) 304 _, err := tp.Perform(req) 305 if err != nil { 306 t.Fatalf("Unexpected error: %s", err) 307 } 308 309 output := dst.String() 310 output = strings.TrimSuffix(output, "\n") 311 // fmt.Println(output) 312 313 lines := strings.Split(output, "\n") 314 315 if len(lines) != 1 { 316 t.Fatalf("Expected 1 line, got %d", len(lines)) 317 } 318 319 var j map[string]interface{} 320 if err := json.Unmarshal([]byte(output), &j); err != nil { 321 t.Errorf("Error decoding JSON: %s", err) 322 } 323 324 domain := j["url"].(map[string]interface{})["domain"] 325 if domain != "foo" { 326 t.Errorf("Unexpected JSON output: %s", domain) 327 } 328 }) 329 330 t.Run("JSON with request body", func(t *testing.T) { 331 var dst strings.Builder 332 333 tp, _ := New(Config{ 334 URLs: []*url.URL{{Scheme: "http", Host: "foo"}}, 335 Transport: newRoundTripper(), 336 Logger: &JSONLogger{Output: &dst, EnableRequestBody: true}, 337 }) 338 339 req, _ := http.NewRequest("GET", "/abc?q=a,b", nil) 340 req.Body = ioutil.NopCloser(strings.NewReader(`{"query":"42"}`)) 341 342 res, err := tp.Perform(req) 343 if err != nil { 344 t.Fatalf("Unexpected error: %s", err) 345 } 346 347 _, err = ioutil.ReadAll(res.Body) 348 if err != nil { 349 t.Fatalf("Error reading response body: %s", err) 350 } 351 352 output := dst.String() 353 output = strings.TrimSuffix(output, "\n") 354 // fmt.Println(output) 355 356 lines := strings.Split(output, "\n") 357 358 if len(lines) != 1 { 359 t.Fatalf("Expected 1 line, got %d", len(lines)) 360 } 361 362 var j map[string]interface{} 363 if err := json.Unmarshal([]byte(output), &j); err != nil { 364 t.Errorf("Error decoding JSON: %s", err) 365 } 366 367 body := j["http"].(map[string]interface{})["request"].(map[string]interface{})["body"].(string) 368 if !strings.Contains(body, "query") { 369 t.Errorf("Unexpected JSON output: %s", body) 370 } 371 }) 372 373 t.Run("Custom", func(t *testing.T) { 374 var dst strings.Builder 375 376 tp, _ := New(Config{ 377 URLs: []*url.URL{{Scheme: "http", Host: "foo"}}, 378 Transport: newRoundTripper(), 379 Logger: &CustomLogger{Output: &dst}, 380 }) 381 382 req, _ := http.NewRequest("GET", "/abc?q=a,b", nil) 383 req.Body = ioutil.NopCloser(strings.NewReader(`{"query":"42"}`)) 384 385 _, err := tp.Perform(req) 386 if err != nil { 387 t.Fatalf("Unexpected error: %s", err) 388 } 389 390 if !strings.HasPrefix(dst.String(), "GET http://foo/abc?q=a,b") { 391 t.Errorf("Unexpected output: %s", dst.String()) 392 } 393 }) 394 395 t.Run("Duplicate body", func(t *testing.T) { 396 input := ResponseBody{content: strings.NewReader("FOOBAR")} 397 398 b1, b2, err := duplicateBody(&input) 399 if err != nil { 400 t.Fatalf("Unexpected error: %s", err) 401 } 402 if !input.closed { 403 t.Errorf("Expected input to be closed: %#v", input) 404 } 405 406 read, _ := ioutil.ReadAll(&input) 407 if len(read) > 0 { 408 t.Errorf("Expected input to be drained: %#v", input.content) 409 } 410 411 b1r, _ := ioutil.ReadAll(b1) 412 b2r, _ := ioutil.ReadAll(b2) 413 if len(b1r) != 6 || len(b2r) != 6 { 414 t.Errorf( 415 "Unexpected duplicate content, b1=%q (%db), b2=%q (%db)", 416 string(b1r), len(b1r), string(b2r), len(b2r), 417 ) 418 } 419 }) 420 421 t.Run("Duplicate body with error", func(t *testing.T) { 422 input := ResponseBody{content: &ErrorReader{r: strings.NewReader("FOOBAR")}} 423 424 b1, b2, err := duplicateBody(&input) 425 if err == nil { 426 t.Errorf("Expected error, got: %v", err) 427 } 428 if err.Error() != "MOCK ERROR" { 429 t.Errorf("Unexpected error value, expected [ERROR MOCK], got [%s]", err.Error()) 430 } 431 432 read, _ := ioutil.ReadAll(&input) 433 if string(read) != "BAR" { 434 t.Errorf("Unexpected undrained part: %q", read) 435 } 436 437 b2r, _ := ioutil.ReadAll(b2) 438 if string(b2r) != "FOO" { 439 t.Errorf("Unexpected value, b2=%q", string(b2r)) 440 } 441 442 b1c, err := ioutil.ReadAll(b1) 443 if string(b1c) != "FOO" { 444 t.Errorf("Unexpected value, b1=%q", string(b1c)) 445 } 446 if err == nil { 447 t.Errorf("Expected error when reading b1, got: %v", err) 448 } 449 if err.Error() != "MOCK ERROR" { 450 t.Errorf("Unexpected error value, expected [ERROR MOCK], got [%s]", err.Error()) 451 } 452 }) 453 } 454 455 func TestDebuggingLogger(t *testing.T) { 456 logger := &debuggingLogger{Output: ioutil.Discard} 457 458 t.Run("Log", func(t *testing.T) { 459 if err := logger.Log("Foo"); err != nil { 460 t.Errorf("Unexpected error: %s", err) 461 } 462 }) 463 t.Run("Logf", func(t *testing.T) { 464 if err := logger.Logf("Foo %d", 1); err != nil { 465 t.Errorf("Unexpected error: %s", err) 466 } 467 }) 468 } 469 470 type CustomLogger struct { 471 Output io.Writer 472 } 473 474 func (l *CustomLogger) LogRoundTrip( 475 req *http.Request, 476 res *http.Response, 477 err error, 478 start time.Time, 479 dur time.Duration, 480 ) error { 481 fmt.Fprintln(l.Output, req.Method, req.URL, "->", res.Status) 482 return nil 483 } 484 485 func (l *CustomLogger) RequestBodyEnabled() bool { return false } 486 func (l *CustomLogger) ResponseBodyEnabled() bool { return false } 487 488 type ResponseBody struct { 489 content io.Reader 490 closed bool 491 } 492 493 func (r *ResponseBody) Read(p []byte) (int, error) { 494 return r.content.Read(p) 495 } 496 497 func (r *ResponseBody) Close() error { 498 r.closed = true 499 return nil 500 } 501 502 type ErrorReader struct { 503 r io.Reader 504 } 505 506 func (r *ErrorReader) Read(p []byte) (int, error) { 507 lr := io.LimitReader(r.r, 3) 508 c, _ := lr.Read(p) 509 return c, errors.New("MOCK ERROR") 510 }