1 package httpretty
2
3 import (
4 "bytes"
5 "context"
6 "crypto/tls"
7 "crypto/x509"
8 "encoding/json"
9 "errors"
10 "fmt"
11 "io"
12 "io/ioutil"
13 "log"
14 "mime"
15 "mime/multipart"
16 "net"
17 "net/http"
18 "net/http/httptest"
19 "net/url"
20 "os"
21 "strings"
22 "sync"
23 "testing"
24 "time"
25 )
26
27 type helloHandler struct{}
28
29 func (h helloHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) {
30 w.Header()["Date"] = nil
31 fmt.Fprintf(w, "Hello, world!")
32 }
33
34 func TestOutgoing(t *testing.T) {
35
36
37 ts := httptest.NewServer(&helloHandler{})
38 defer ts.Close()
39
40 logger := &Logger{
41 TLS: true,
42 RequestHeader: true,
43 RequestBody: true,
44 ResponseHeader: true,
45 ResponseBody: true,
46 }
47
48
49
50 stdout := os.Stdout
51
52 r, w, err := os.Pipe()
53 if err != nil {
54 panic(err)
55 }
56 os.Stdout = w
57 outC := make(chan string)
58 go func() {
59 var buf strings.Builder
60 _, errcp := io.Copy(&buf, r)
61 r.Close()
62 if errcp != nil {
63 panic(errcp)
64 }
65 outC <- buf.String()
66 }()
67
68 var want string
69
70 defer func() {
71 w.Close()
72 os.Stdout = stdout
73 out := <-outC
74
75 if out != want {
76 t.Errorf("logged HTTP request %s; want %s", out, want)
77 }
78 }()
79
80 client := &http.Client{
81
82
83 Transport: logger.RoundTripper(nil),
84 }
85
86 req, err := http.NewRequest(http.MethodGet, ts.URL, nil)
87 req.Header.Add("User-Agent", "Robot/0.1 crawler@example.com")
88
89 if err != nil {
90 t.Errorf("cannot create request: %v", err)
91 }
92
93 resp, err := client.Do(req)
94
95 if err != nil {
96 t.Errorf("cannot connect to the server: %v", err)
97 }
98
99 want = fmt.Sprintf(`* Request to %s
100 > GET / HTTP/1.1
101 > Host: %s
102 > User-Agent: Robot/0.1 crawler@example.com
103
104 < HTTP/1.1 200 OK
105 < Content-Length: 13
106 < Content-Type: text/plain; charset=utf-8
107
108 Hello, world!
109 `, ts.URL, ts.Listener.Addr())
110
111 testBody(t, resp.Body, []byte("Hello, world!"))
112 }
113
114 func outgoingGet(t *testing.T, client *http.Client, ts *httptest.Server, done func()) {
115 defer done()
116
117 req, err := http.NewRequest(http.MethodGet, ts.URL, nil)
118 req.Header.Add("User-Agent", "Robot/0.1 crawler@example.com")
119
120 if err != nil {
121 t.Errorf("cannot create request: %v", err)
122 }
123
124 resp, err := client.Do(req)
125
126 if err != nil {
127 t.Errorf("cannot connect to the server: %v", err)
128 }
129
130 testBody(t, resp.Body, []byte("Hello, world!"))
131 }
132
133 func TestOutgoingConcurrency(t *testing.T) {
134
135
136 if Race {
137 t.Skip("cannot test because until data race issues are resolved on the standard library https://github.com/golang/go/issues/30597")
138 }
139
140 ts := httptest.NewServer(&helloHandler{})
141 defer ts.Close()
142
143 logger := &Logger{
144 TLS: true,
145 RequestHeader: true,
146 RequestBody: true,
147 ResponseHeader: true,
148 ResponseBody: true,
149 }
150
151 logger.SetFlusher(OnEnd)
152
153 var buf bytes.Buffer
154 logger.SetOutput(&buf)
155
156 client := &http.Client{
157 Transport: logger.RoundTripper(newTransport()),
158 }
159
160 var wg sync.WaitGroup
161 concurrency := 100
162 wg.Add(concurrency)
163
164 for i := 0; i < concurrency; i++ {
165 go outgoingGet(t, client, ts, wg.Done)
166 time.Sleep(time.Millisecond)
167 }
168
169 wg.Wait()
170
171 got := buf.String()
172
173 gotConcurrency := strings.Count(got, "< HTTP/1.1 200 OK")
174
175 if concurrency != gotConcurrency {
176 t.Errorf("logged %d requests, wanted %d", concurrency, gotConcurrency)
177 }
178
179 want := fmt.Sprintf(`* Request to %s
180 > GET / HTTP/1.1
181 > Host: %s
182 > User-Agent: Robot/0.1 crawler@example.com
183
184 < HTTP/1.1 200 OK
185 < Content-Length: 13
186 < Content-Type: text/plain; charset=utf-8
187
188 Hello, world!`, ts.URL, ts.Listener.Addr())
189
190 if !strings.Contains(got, want) {
191 t.Errorf("Request doesn't contain expected body")
192 }
193 }
194
195 func TestOutgoingMinimal(t *testing.T) {
196 t.Parallel()
197
198 ts := httptest.NewServer(&helloHandler{})
199 defer ts.Close()
200
201
202 logger := &Logger{}
203
204 var buf bytes.Buffer
205 logger.SetOutput(&buf)
206
207 client := &http.Client{
208 Transport: logger.RoundTripper(newTransport()),
209 }
210
211 req, err := http.NewRequest(http.MethodGet, ts.URL, nil)
212 req.Header.Add("User-Agent", "Robot/0.1 crawler@example.com")
213
214 req.AddCookie(&http.Cookie{
215 Name: "food",
216 Value: "sorbet",
217 })
218
219 if err != nil {
220 t.Errorf("cannot create request: %v", err)
221 }
222
223 _, err = client.Do(req)
224
225 if err != nil {
226 t.Errorf("cannot connect to the server: %v", err)
227 }
228
229 want := fmt.Sprintf("* Request to %s\n", ts.URL)
230
231 if got := buf.String(); got != want {
232 t.Errorf("logged HTTP request %s; want %s", got, want)
233 }
234 }
235
236 func TestOutgoingSanitized(t *testing.T) {
237 t.Parallel()
238
239 ts := httptest.NewServer(&helloHandler{})
240 defer ts.Close()
241
242 logger := &Logger{
243 RequestHeader: true,
244 RequestBody: true,
245 ResponseHeader: true,
246 ResponseBody: true,
247 }
248
249 var buf bytes.Buffer
250 logger.SetOutput(&buf)
251
252 client := &http.Client{
253 Transport: logger.RoundTripper(newTransport()),
254 }
255
256 req, err := http.NewRequest(http.MethodGet, ts.URL, nil)
257 req.Header.Add("User-Agent", "Robot/0.1 crawler@example.com")
258
259 req.AddCookie(&http.Cookie{
260 Name: "food",
261 Value: "sorbet",
262 })
263
264 if err != nil {
265 t.Errorf("cannot create request: %v", err)
266 }
267
268 _, err = client.Do(req)
269
270 if err != nil {
271 t.Errorf("cannot connect to the server: %v", err)
272 }
273
274 want := fmt.Sprintf(`* Request to %s
275 > GET / HTTP/1.1
276 > Host: %s
277 > Cookie: food=████████████████████
278 > User-Agent: Robot/0.1 crawler@example.com
279
280 < HTTP/1.1 200 OK
281 < Content-Length: 13
282 < Content-Type: text/plain; charset=utf-8
283
284 Hello, world!
285 `, ts.URL, ts.Listener.Addr())
286
287 if got := buf.String(); got != want {
288 t.Errorf("logged HTTP request %s; want %s", got, want)
289 }
290 }
291
292 func TestOutgoingSkipSanitize(t *testing.T) {
293 t.Parallel()
294
295 ts := httptest.NewServer(&helloHandler{})
296 defer ts.Close()
297
298 logger := &Logger{
299 RequestHeader: true,
300 RequestBody: true,
301 ResponseHeader: true,
302 ResponseBody: true,
303 SkipSanitize: true,
304 }
305
306 var buf bytes.Buffer
307 logger.SetOutput(&buf)
308
309 client := &http.Client{
310 Transport: logger.RoundTripper(newTransport()),
311 }
312
313 req, err := http.NewRequest(http.MethodGet, ts.URL, nil)
314 req.Header.Add("User-Agent", "Robot/0.1 crawler@example.com")
315
316 req.AddCookie(&http.Cookie{
317 Name: "food",
318 Value: "sorbet",
319 })
320
321 if err != nil {
322 t.Errorf("cannot create request: %v", err)
323 }
324
325 _, err = client.Do(req)
326
327 if err != nil {
328 t.Errorf("cannot connect to the server: %v", err)
329 }
330
331 want := fmt.Sprintf(`* Request to %s
332 > GET / HTTP/1.1
333 > Host: %s
334 > Cookie: food=sorbet
335 > User-Agent: Robot/0.1 crawler@example.com
336
337 < HTTP/1.1 200 OK
338 < Content-Length: 13
339 < Content-Type: text/plain; charset=utf-8
340
341 Hello, world!
342 `, ts.URL, ts.Listener.Addr())
343
344 if got := buf.String(); got != want {
345 t.Errorf("logged HTTP request %s; want %s", got, want)
346 }
347 }
348
349 func TestOutgoingHide(t *testing.T) {
350 t.Parallel()
351
352 ts := httptest.NewServer(&helloHandler{})
353 defer ts.Close()
354
355 logger := &Logger{
356 RequestHeader: true,
357 RequestBody: true,
358 ResponseHeader: true,
359 ResponseBody: true,
360 }
361
362 var buf bytes.Buffer
363 logger.SetOutput(&buf)
364
365 client := &http.Client{
366 Transport: logger.RoundTripper(newTransport()),
367 }
368
369 req, err := http.NewRequest(http.MethodGet, ts.URL, nil)
370 req.Header.Add("User-Agent", "Robot/0.1 crawler@example.com")
371
372 if err != nil {
373 t.Errorf("cannot create request: %v", err)
374 }
375
376 req = req.WithContext(WithHide(context.Background()))
377
378 _, err = client.Do(req)
379
380 if err != nil {
381 t.Errorf("cannot connect to the server: %v", err)
382 }
383
384 if buf.Len() != 0 {
385 t.Errorf("request should not be logged, got %v", buf.String())
386 }
387 want := ""
388
389 if got := buf.String(); got != want {
390 t.Errorf("logged HTTP request %s; want %s", got, want)
391 }
392 }
393
394 func filteredURIs(req *http.Request) (bool, error) {
395 path := req.URL.Path
396
397 if path == "/filtered" {
398 return true, nil
399 }
400
401 if path == "/unfiltered" {
402 return false, nil
403 }
404
405 return false, errors.New("filter error triggered")
406 }
407
408 func TestOutgoingFilter(t *testing.T) {
409 t.Parallel()
410
411 ts := httptest.NewServer(&helloHandler{})
412 defer ts.Close()
413
414 logger := &Logger{
415 RequestHeader: true,
416 RequestBody: true,
417 ResponseHeader: true,
418 ResponseBody: true,
419 }
420
421 logger.SetOutput(ioutil.Discard)
422 logger.SetFilter(filteredURIs)
423
424 client := &http.Client{
425 Transport: logger.RoundTripper(newTransport()),
426 }
427
428 testCases := []struct {
429 uri string
430 want string
431 }{
432 {uri: "filtered"},
433 {uri: "unfiltered", want: "* Request"},
434 {uri: "other", want: "filter error triggered"},
435 }
436 for _, tc := range testCases {
437 t.Run(tc.uri, func(t *testing.T) {
438 var buf bytes.Buffer
439 logger.SetOutput(&buf)
440
441 _, err := client.Get(fmt.Sprintf("%s/%s", ts.URL, tc.uri))
442
443 if err != nil {
444 t.Errorf("cannot create request: %v", err)
445 }
446
447 if tc.want == "" && buf.Len() != 0 {
448 t.Errorf("wanted input to be filtered, got %v instead", buf.String())
449 }
450
451 if !strings.Contains(buf.String(), tc.want) {
452 t.Errorf(`expected input to contain "%v", got %v instead`, tc.want, buf.String())
453 }
454 })
455 }
456 }
457
458 func TestOutgoingFilterPanicked(t *testing.T) {
459 t.Parallel()
460
461 ts := httptest.NewServer(&helloHandler{})
462 defer ts.Close()
463
464 logger := &Logger{
465 RequestHeader: true,
466 RequestBody: true,
467 ResponseHeader: true,
468 ResponseBody: true,
469 }
470
471 logger.SetOutput(ioutil.Discard)
472 logger.SetFilter(func(req *http.Request) (bool, error) {
473 panic("evil panic")
474 })
475
476 client := &http.Client{
477 Transport: logger.RoundTripper(newTransport()),
478 }
479
480 var buf bytes.Buffer
481 logger.SetOutput(&buf)
482
483 _, err := client.Get(ts.URL)
484
485 if err != nil {
486 t.Errorf("cannot create request: %v", err)
487 }
488
489 want := fmt.Sprintf(`* cannot filter request: GET %v: panic: evil panic
490 * Request to %v
491 > GET / HTTP/1.1
492 > Host: %v
493
494 < HTTP/1.1 200 OK
495 < Content-Length: 13
496 < Content-Type: text/plain; charset=utf-8
497
498 Hello, world!
499 `, ts.URL, ts.URL, ts.Listener.Addr())
500
501 if got := buf.String(); got != want {
502 t.Errorf(`expected input to contain "%v", got %v instead`, want, got)
503 }
504 }
505
506 func TestOutgoingSkipHeader(t *testing.T) {
507 t.Parallel()
508
509 ts := httptest.NewServer(&jsonHandler{})
510 defer ts.Close()
511
512 logger := Logger{
513 RequestHeader: true,
514 RequestBody: true,
515 ResponseHeader: true,
516 ResponseBody: true,
517 }
518
519 logger.SkipHeader([]string{
520 "user-agent",
521 "content-type",
522 })
523
524 var buf bytes.Buffer
525 logger.SetOutput(&buf)
526
527 client := &http.Client{
528 Transport: logger.RoundTripper(newTransport()),
529 }
530
531 uri := fmt.Sprintf("%s/json", ts.URL)
532
533 req, err := http.NewRequest(http.MethodGet, uri, nil)
534 req.Header.Add("User-Agent", "Robot/0.1 crawler@example.com")
535
536 if err != nil {
537 t.Errorf("cannot create request: %v", err)
538 }
539
540 _, err = client.Do(req)
541
542 if err != nil {
543 t.Errorf("cannot connect to the server: %v", err)
544 }
545
546 want := fmt.Sprintf(`* Request to %s
547 > GET /json HTTP/1.1
548 > Host: %s
549
550 < HTTP/1.1 200 OK
551 < Content-Length: 40
552
553 {"result":"Hello, world!","number":3.14}
554 `, uri, ts.Listener.Addr())
555
556 if got := buf.String(); got != want {
557 t.Errorf("logged HTTP request %s; want %s", got, want)
558 }
559 }
560
561 func TestOutgoingBodyFilter(t *testing.T) {
562 t.Parallel()
563
564 ts := httptest.NewServer(&jsonHandler{})
565 defer ts.Close()
566
567 logger := Logger{
568 RequestHeader: true,
569 RequestBody: true,
570 ResponseHeader: true,
571 ResponseBody: true,
572 }
573
574 logger.SetBodyFilter(func(h http.Header) (skip bool, err error) {
575 mediatype, _, _ := mime.ParseMediaType(h.Get("Content-Type"))
576 return mediatype == "application/json", nil
577 })
578
579 var buf bytes.Buffer
580 logger.SetOutput(&buf)
581
582 client := &http.Client{
583 Transport: logger.RoundTripper(newTransport()),
584 }
585
586 uri := fmt.Sprintf("%s/json", ts.URL)
587
588 req, err := http.NewRequest(http.MethodGet, uri, nil)
589 req.Header.Add("User-Agent", "Robot/0.1 crawler@example.com")
590
591 if err != nil {
592 t.Errorf("cannot create request: %v", err)
593 }
594
595 _, err = client.Do(req)
596
597 if err != nil {
598 t.Errorf("cannot connect to the server: %v", err)
599 }
600
601 want := fmt.Sprintf(`* Request to %s
602 > GET /json HTTP/1.1
603 > Host: %s
604 > User-Agent: Robot/0.1 crawler@example.com
605
606 < HTTP/1.1 200 OK
607 < Content-Length: 40
608 < Content-Type: application/json; charset=utf-8
609
610 `, uri, ts.Listener.Addr())
611
612 if got := buf.String(); got != want {
613 t.Errorf("logged HTTP request %s; want %s", got, want)
614 }
615 }
616
617 func TestOutgoingBodyFilterSoftError(t *testing.T) {
618 t.Parallel()
619
620 ts := httptest.NewServer(&jsonHandler{})
621 defer ts.Close()
622
623 logger := Logger{
624 RequestHeader: true,
625 RequestBody: true,
626 ResponseHeader: true,
627 ResponseBody: true,
628 }
629
630 logger.SetBodyFilter(func(h http.Header) (skip bool, err error) {
631
632 return true, errors.New("incomplete implementation")
633 })
634
635 var buf bytes.Buffer
636 logger.SetOutput(&buf)
637
638 client := &http.Client{
639 Transport: logger.RoundTripper(newTransport()),
640 }
641
642 uri := fmt.Sprintf("%s/json", ts.URL)
643
644 req, err := http.NewRequest(http.MethodGet, uri, nil)
645 req.Header.Add("User-Agent", "Robot/0.1 crawler@example.com")
646
647 if err != nil {
648 t.Errorf("cannot create request: %v", err)
649 }
650
651 _, err = client.Do(req)
652
653 if err != nil {
654 t.Errorf("cannot connect to the server: %v", err)
655 }
656
657 want := fmt.Sprintf(`* Request to %s
658 > GET /json HTTP/1.1
659 > Host: %s
660 > User-Agent: Robot/0.1 crawler@example.com
661
662 < HTTP/1.1 200 OK
663 < Content-Length: 40
664 < Content-Type: application/json; charset=utf-8
665
666 * error on response body filter: incomplete implementation
667 `, uri, ts.Listener.Addr())
668
669 if got := buf.String(); got != want {
670 t.Errorf("logged HTTP request %s; want %s", got, want)
671 }
672 }
673
674 func TestOutgoingBodyFilterPanicked(t *testing.T) {
675 t.Parallel()
676
677 ts := httptest.NewServer(&jsonHandler{})
678 defer ts.Close()
679
680 logger := Logger{
681 RequestHeader: true,
682 RequestBody: true,
683 ResponseHeader: true,
684 ResponseBody: true,
685 }
686
687 logger.SetBodyFilter(func(h http.Header) (skip bool, err error) {
688 panic("evil panic")
689 })
690
691 var buf bytes.Buffer
692 logger.SetOutput(&buf)
693
694 client := &http.Client{
695 Transport: logger.RoundTripper(newTransport()),
696 }
697
698 uri := fmt.Sprintf("%s/json", ts.URL)
699
700 req, err := http.NewRequest(http.MethodGet, uri, nil)
701 req.Header.Add("User-Agent", "Robot/0.1 crawler@example.com")
702
703 if err != nil {
704 t.Errorf("cannot create request: %v", err)
705 }
706
707 _, err = client.Do(req)
708
709 if err != nil {
710 t.Errorf("cannot connect to the server: %v", err)
711 }
712
713 want := fmt.Sprintf(`* Request to %s
714 > GET /json HTTP/1.1
715 > Host: %s
716 > User-Agent: Robot/0.1 crawler@example.com
717
718 < HTTP/1.1 200 OK
719 < Content-Length: 40
720 < Content-Type: application/json; charset=utf-8
721
722 * panic while filtering body: evil panic
723 {"result":"Hello, world!","number":3.14}
724 `, uri, ts.Listener.Addr())
725
726 if got := buf.String(); got != want {
727 t.Errorf("logged HTTP request %s; want %s", got, want)
728 }
729 }
730
731 func TestOutgoingWithTimeRequest(t *testing.T) {
732 t.Parallel()
733
734 ts := httptest.NewServer(&helloHandler{})
735 defer ts.Close()
736
737 logger := &Logger{
738 Time: true,
739
740 RequestHeader: true,
741 RequestBody: true,
742 ResponseHeader: true,
743 ResponseBody: true,
744 }
745
746 var buf bytes.Buffer
747 logger.SetOutput(&buf)
748
749 client := &http.Client{
750 Transport: logger.RoundTripper(newTransport()),
751 }
752
753 req, err := http.NewRequest(http.MethodGet, ts.URL, nil)
754 req.Header.Add("User-Agent", "Robot/0.1 crawler@example.com")
755
756 if err != nil {
757 t.Errorf("cannot create request: %v", err)
758 }
759
760 _, err = client.Do(req)
761
762 if err != nil {
763 t.Errorf("cannot connect to the server: %v", err)
764 }
765
766 got := buf.String()
767
768 if !strings.Contains(got, "* Request at ") {
769 t.Error("missing printing start time of request")
770 }
771
772 if !strings.Contains(got, "* Request took ") {
773 t.Error("missing printing request duration")
774 }
775 }
776
777 type jsonHandler struct{}
778
779 func (h jsonHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) {
780 w.Header()["Date"] = nil
781 w.Header().Set("Content-Type", "application/json; charset=utf-8")
782
783 type res struct {
784 Result string `json:"result"`
785 Number json.Number `json:"number"`
786 }
787
788 b, err := json.Marshal(res{
789 Result: "Hello, world!",
790 Number: json.Number("3.14"),
791 })
792
793 if err != nil {
794 http.Error(w, err.Error(), http.StatusInternalServerError)
795 return
796 }
797
798 fmt.Fprint(w, string(b))
799 }
800
801 func TestOutgoingFormattedJSON(t *testing.T) {
802 t.Parallel()
803
804 ts := httptest.NewServer(&jsonHandler{})
805 defer ts.Close()
806
807 logger := Logger{
808 RequestHeader: true,
809 RequestBody: true,
810 ResponseHeader: true,
811 ResponseBody: true,
812 }
813
814 var buf bytes.Buffer
815 logger.SetOutput(&buf)
816
817 logger.Formatters = []Formatter{
818 &JSONFormatter{},
819 }
820
821 client := &http.Client{
822 Transport: logger.RoundTripper(newTransport()),
823 }
824
825 uri := fmt.Sprintf("%s/json", ts.URL)
826
827 req, err := http.NewRequest(http.MethodGet, uri, nil)
828 req.Header.Add("User-Agent", "Robot/0.1 crawler@example.com")
829
830 if err != nil {
831 t.Errorf("cannot create request: %v", err)
832 }
833
834 _, err = client.Do(req)
835
836 if err != nil {
837 t.Errorf("cannot connect to the server: %v", err)
838 }
839
840 want := fmt.Sprintf(`* Request to %s
841 > GET /json HTTP/1.1
842 > Host: %s
843 > User-Agent: Robot/0.1 crawler@example.com
844
845 < HTTP/1.1 200 OK
846 < Content-Length: 40
847 < Content-Type: application/json; charset=utf-8
848
849 {
850 "result": "Hello, world!",
851 "number": 3.14
852 }
853 `, uri, ts.Listener.Addr())
854
855 if got := buf.String(); got != want {
856 t.Errorf("logged HTTP request %s; want %s", got, want)
857 }
858 }
859
860 type badJSONHandler struct{}
861
862 func (h badJSONHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) {
863 w.Header()["Date"] = nil
864 w.Header().Set("Content-Type", "application/json; charset=utf-8")
865 fmt.Fprint(w, `{"bad": }`)
866 }
867
868 func TestOutgoingBadJSON(t *testing.T) {
869 t.Parallel()
870
871 ts := httptest.NewServer(&badJSONHandler{})
872 defer ts.Close()
873
874 logger := &Logger{
875 RequestHeader: true,
876 RequestBody: true,
877 ResponseHeader: true,
878 ResponseBody: true,
879 }
880
881 var buf bytes.Buffer
882 logger.SetOutput(&buf)
883
884 logger.Formatters = []Formatter{
885 &JSONFormatter{},
886 }
887
888 client := &http.Client{
889 Transport: logger.RoundTripper(newTransport()),
890 }
891
892 uri := fmt.Sprintf("%s/json", ts.URL)
893
894 req, err := http.NewRequest(http.MethodGet, uri, nil)
895 req.Header.Add("User-Agent", "Robot/0.1 crawler@example.com")
896
897 if err != nil {
898 t.Errorf("cannot create request: %v", err)
899 }
900
901 _, err = client.Do(req)
902
903 if err != nil {
904 t.Errorf("cannot connect to the server: %v", err)
905 }
906
907 want := fmt.Sprintf(`* Request to %s
908 > GET /json HTTP/1.1
909 > Host: %s
910 > User-Agent: Robot/0.1 crawler@example.com
911
912 < HTTP/1.1 200 OK
913 < Content-Length: 9
914 < Content-Type: application/json; charset=utf-8
915
916 * body cannot be formatted: invalid character '}' looking for beginning of value
917 {"bad": }
918 `, uri, ts.Listener.Addr())
919
920 if got := buf.String(); got != want {
921 t.Errorf("logged HTTP request %s; want %s", got, want)
922 }
923 }
924
925 type panickingFormatter struct{}
926
927 func (p *panickingFormatter) Match(mediatype string) bool {
928 return true
929 }
930
931 func (p *panickingFormatter) Format(w io.Writer, src []byte) error {
932 panic("evil formatter")
933 }
934
935 func TestOutgoingFormatterPanicked(t *testing.T) {
936 t.Parallel()
937
938 ts := httptest.NewServer(&badJSONHandler{})
939 defer ts.Close()
940
941 logger := &Logger{
942 RequestHeader: true,
943 RequestBody: true,
944 ResponseHeader: true,
945 ResponseBody: true,
946 }
947
948 var buf bytes.Buffer
949 logger.SetOutput(&buf)
950
951 logger.Formatters = []Formatter{
952 &panickingFormatter{},
953 }
954
955 client := &http.Client{
956 Transport: logger.RoundTripper(newTransport()),
957 }
958
959 uri := fmt.Sprintf("%s/json", ts.URL)
960
961 req, err := http.NewRequest(http.MethodGet, uri, nil)
962 req.Header.Add("User-Agent", "Robot/0.1 crawler@example.com")
963
964 if err != nil {
965 t.Errorf("cannot create request: %v", err)
966 }
967
968 _, err = client.Do(req)
969
970 if err != nil {
971 t.Errorf("cannot connect to the server: %v", err)
972 }
973
974 want := fmt.Sprintf(`* Request to %s
975 > GET /json HTTP/1.1
976 > Host: %s
977 > User-Agent: Robot/0.1 crawler@example.com
978
979 < HTTP/1.1 200 OK
980 < Content-Length: 9
981 < Content-Type: application/json; charset=utf-8
982
983 * body cannot be formatted: panic: evil formatter
984 {"bad": }
985 `, uri, ts.Listener.Addr())
986
987 if got := buf.String(); got != want {
988 t.Errorf("logged HTTP request %s; want %s", got, want)
989 }
990 }
991
992 type panickingFormatterMatcher struct{}
993
994 func (p *panickingFormatterMatcher) Match(mediatype string) bool {
995 panic("evil matcher")
996 }
997
998 func (p *panickingFormatterMatcher) Format(w io.Writer, src []byte) error {
999 return nil
1000 }
1001
1002 func TestOutgoingFormatterMatcherPanicked(t *testing.T) {
1003 t.Parallel()
1004
1005 ts := httptest.NewServer(&badJSONHandler{})
1006 defer ts.Close()
1007
1008 logger := &Logger{
1009 RequestHeader: true,
1010 RequestBody: true,
1011 ResponseHeader: true,
1012 ResponseBody: true,
1013 }
1014
1015 var buf bytes.Buffer
1016 logger.SetOutput(&buf)
1017
1018 logger.Formatters = []Formatter{
1019 &panickingFormatterMatcher{},
1020 }
1021
1022 client := &http.Client{
1023 Transport: logger.RoundTripper(newTransport()),
1024 }
1025
1026 uri := fmt.Sprintf("%s/json", ts.URL)
1027
1028 req, err := http.NewRequest(http.MethodGet, uri, nil)
1029 req.Header.Add("User-Agent", "Robot/0.1 crawler@example.com")
1030
1031 if err != nil {
1032 t.Errorf("cannot create request: %v", err)
1033 }
1034
1035 _, err = client.Do(req)
1036
1037 if err != nil {
1038 t.Errorf("cannot connect to the server: %v", err)
1039 }
1040
1041 want := fmt.Sprintf(`* Request to %s
1042 > GET /json HTTP/1.1
1043 > Host: %s
1044 > User-Agent: Robot/0.1 crawler@example.com
1045
1046 < HTTP/1.1 200 OK
1047 < Content-Length: 9
1048 < Content-Type: application/json; charset=utf-8
1049
1050 * panic while testing body format: evil matcher
1051 {"bad": }
1052 `, uri, ts.Listener.Addr())
1053
1054 if got := buf.String(); got != want {
1055 t.Errorf("logged HTTP request %s; want %s", got, want)
1056 }
1057 }
1058
1059 type formHandler struct{}
1060
1061 func (h formHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) {
1062 w.Header()["Date"] = nil
1063 fmt.Fprint(w, "form received")
1064 }
1065
1066 func TestOutgoingForm(t *testing.T) {
1067 t.Parallel()
1068
1069 ts := httptest.NewServer(&formHandler{})
1070 defer ts.Close()
1071
1072 logger := &Logger{
1073 RequestHeader: true,
1074 RequestBody: true,
1075 ResponseHeader: true,
1076 ResponseBody: true,
1077 }
1078
1079 var buf bytes.Buffer
1080 logger.SetOutput(&buf)
1081
1082 logger.Formatters = []Formatter{
1083 &JSONFormatter{},
1084 }
1085
1086 client := &http.Client{
1087 Transport: logger.RoundTripper(newTransport()),
1088 }
1089
1090 form := url.Values{}
1091 form.Add("foo", "bar")
1092 form.Add("email", "root@example.com")
1093
1094 uri := fmt.Sprintf("%s/form", ts.URL)
1095
1096 req, err := http.NewRequest(http.MethodPost, uri, strings.NewReader(form.Encode()))
1097
1098 if err != nil {
1099 t.Errorf("cannot create request: %v", err)
1100 }
1101
1102 _, err = client.Do(req)
1103
1104 if err != nil {
1105 t.Errorf("cannot connect to the server: %v", err)
1106 }
1107
1108 want := fmt.Sprintf(`* Request to %s
1109 > POST /form HTTP/1.1
1110 > Host: %s
1111
1112 email=root%%40example.com&foo=bar
1113 < HTTP/1.1 200 OK
1114 < Content-Length: 13
1115 < Content-Type: text/plain; charset=utf-8
1116
1117 form received
1118 `, uri, ts.Listener.Addr())
1119
1120 if got := buf.String(); got != want {
1121 t.Errorf("logged HTTP request %s; want %s", got, want)
1122 }
1123 }
1124
1125 func TestOutgoingBinaryBody(t *testing.T) {
1126 t.Parallel()
1127
1128 ts := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
1129 w.Header()["Date"] = nil
1130 fmt.Fprint(w, "\x25\x50\x44\x46\x2d\x31\x2e\x33\x0a\x25\xc4\xe5\xf2\xe5\xeb\xa7")
1131 }))
1132 defer ts.Close()
1133
1134 logger := &Logger{
1135 RequestHeader: true,
1136 RequestBody: true,
1137 ResponseHeader: true,
1138 ResponseBody: true,
1139 }
1140
1141 var buf bytes.Buffer
1142 logger.SetOutput(&buf)
1143
1144 client := &http.Client{
1145 Transport: logger.RoundTripper(newTransport()),
1146 }
1147
1148 b := []byte("RIFF\x00\x00\x00\x00WEBPVP")
1149 uri := fmt.Sprintf("%s/convert", ts.URL)
1150 req, err := http.NewRequest(http.MethodPost, uri, bytes.NewReader(b))
1151 req.Header.Add("Content-Type", "image/webp")
1152
1153 if err != nil {
1154 t.Errorf("cannot create request: %v", err)
1155 }
1156
1157 _, err = client.Do(req)
1158
1159 if err != nil {
1160 t.Errorf("cannot connect to the server: %v", err)
1161 }
1162
1163 want := fmt.Sprintf(`* Request to %s
1164 > POST /convert HTTP/1.1
1165 > Host: %s
1166 > Content-Type: image/webp
1167
1168 * body contains binary data
1169 < HTTP/1.1 200 OK
1170 < Content-Length: 16
1171 < Content-Type: application/pdf
1172
1173 * body contains binary data
1174 `, uri, ts.Listener.Addr())
1175
1176 if got := buf.String(); got != want {
1177 t.Errorf("logged HTTP request %s; want %s", got, want)
1178 }
1179 }
1180
1181 func TestOutgoingBinaryBodyNoMediatypeHeader(t *testing.T) {
1182 t.Parallel()
1183
1184 ts := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
1185 w.Header()["Date"] = nil
1186 w.Header()["Content-Type"] = nil
1187 fmt.Fprint(w, "\x25\x50\x44\x46\x2d\x31\x2e\x33\x0a\x25\xc4\xe5\xf2\xe5\xeb\xa7")
1188 }))
1189 defer ts.Close()
1190
1191 logger := &Logger{
1192 RequestHeader: true,
1193 RequestBody: true,
1194 ResponseHeader: true,
1195 ResponseBody: true,
1196 }
1197
1198 var buf bytes.Buffer
1199 logger.SetOutput(&buf)
1200
1201 client := &http.Client{
1202 Transport: logger.RoundTripper(newTransport()),
1203 }
1204
1205 b := []byte("RIFF\x00\x00\x00\x00WEBPVP")
1206 uri := fmt.Sprintf("%s/convert", ts.URL)
1207 req, err := http.NewRequest(http.MethodPost, uri, bytes.NewReader(b))
1208
1209 if err != nil {
1210 t.Errorf("cannot create request: %v", err)
1211 }
1212
1213 _, err = client.Do(req)
1214
1215 if err != nil {
1216 t.Errorf("cannot connect to the server: %v", err)
1217 }
1218
1219 want := fmt.Sprintf(`* Request to %s
1220 > POST /convert HTTP/1.1
1221 > Host: %s
1222
1223 * body contains binary data
1224 < HTTP/1.1 200 OK
1225 < Content-Length: 16
1226
1227 * body contains binary data
1228 `, uri, ts.Listener.Addr())
1229
1230 if got := buf.String(); got != want {
1231 t.Errorf("logged HTTP request %s; want %s", got, want)
1232 }
1233 }
1234
1235 type longRequestHandler struct{}
1236
1237 func (h longRequestHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) {
1238 w.Header()["Date"] = nil
1239 fmt.Fprint(w, "long request received")
1240 }
1241
1242 func TestOutgoingLongRequest(t *testing.T) {
1243 t.Parallel()
1244
1245 ts := httptest.NewServer(&longRequestHandler{})
1246 defer ts.Close()
1247
1248 logger := &Logger{
1249 RequestHeader: true,
1250 RequestBody: true,
1251 ResponseHeader: true,
1252 ResponseBody: true,
1253 }
1254
1255 var buf bytes.Buffer
1256 logger.SetOutput(&buf)
1257
1258 logger.Formatters = []Formatter{
1259 &JSONFormatter{},
1260 }
1261
1262 client := &http.Client{
1263 Transport: logger.RoundTripper(newTransport()),
1264 }
1265
1266 uri := fmt.Sprintf("%s/long-request", ts.URL)
1267
1268 req, err := http.NewRequest(http.MethodPut, uri, strings.NewReader(petition))
1269
1270 if err != nil {
1271 t.Errorf("cannot create request: %v", err)
1272 }
1273
1274 _, err = client.Do(req)
1275
1276 if err != nil {
1277 t.Errorf("cannot connect to the server: %v", err)
1278 }
1279
1280 want := fmt.Sprintf(`* Request to %s
1281 > PUT /long-request HTTP/1.1
1282 > Host: %s
1283
1284 %s
1285 < HTTP/1.1 200 OK
1286 < Content-Length: 21
1287 < Content-Type: text/plain; charset=utf-8
1288
1289 long request received
1290 `, uri, ts.Listener.Addr(), petition)
1291
1292 if got := buf.String(); got != want {
1293 t.Errorf("logged HTTP request %s; want %s", got, want)
1294 }
1295 }
1296
1297 type longResponseHandler struct{}
1298
1299 func (h longResponseHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) {
1300 w.Header()["Date"] = nil
1301 w.Header().Set("Content-Length", fmt.Sprintf("%d", len(petition)))
1302
1303 if r.Method != http.MethodHead {
1304 fmt.Fprint(w, petition)
1305 }
1306 }
1307
1308 func TestOutgoingLongResponse(t *testing.T) {
1309 t.Parallel()
1310
1311 ts := httptest.NewServer(&longResponseHandler{})
1312 defer ts.Close()
1313
1314 logger := &Logger{
1315 RequestHeader: true,
1316 RequestBody: true,
1317 ResponseHeader: true,
1318 ResponseBody: true,
1319 }
1320
1321 var buf bytes.Buffer
1322 logger.SetOutput(&buf)
1323
1324 logger.MaxResponseBody = int64(len(petition) + 1000)
1325
1326 client := &http.Client{
1327 Transport: logger.RoundTripper(newTransport()),
1328 }
1329
1330 uri := fmt.Sprintf("%s/long-response", ts.URL)
1331
1332 req, err := http.NewRequest(http.MethodGet, uri, nil)
1333
1334 if err != nil {
1335 t.Errorf("cannot create request: %v", err)
1336 }
1337
1338 resp, err := client.Do(req)
1339
1340 if err != nil {
1341 t.Errorf("cannot connect to the server: %v", err)
1342 }
1343
1344 want := fmt.Sprintf(`* Request to %s
1345 > GET /long-response HTTP/1.1
1346 > Host: %s
1347
1348 < HTTP/1.1 200 OK
1349 < Content-Length: 9846
1350 < Content-Type: text/plain; charset=utf-8
1351
1352 %s
1353 `, uri, ts.Listener.Addr(), petition)
1354
1355 if got := buf.String(); got != want {
1356 t.Errorf("logged HTTP request %s; want %s", got, want)
1357 }
1358
1359 testBody(t, resp.Body, []byte(petition))
1360 }
1361
1362 func TestOutgoingLongResponseHead(t *testing.T) {
1363 t.Parallel()
1364
1365 ts := httptest.NewServer(&longResponseHandler{})
1366 defer ts.Close()
1367
1368 logger := &Logger{
1369 RequestHeader: true,
1370 RequestBody: true,
1371 ResponseHeader: true,
1372 ResponseBody: true,
1373 }
1374
1375 var buf bytes.Buffer
1376 logger.SetOutput(&buf)
1377
1378 logger.MaxResponseBody = int64(len(petition) + 1000)
1379
1380 client := &http.Client{
1381 Transport: logger.RoundTripper(newTransport()),
1382 }
1383
1384 uri := fmt.Sprintf("%s/long-response", ts.URL)
1385
1386 req, err := http.NewRequest(http.MethodHead, uri, nil)
1387
1388 if err != nil {
1389 t.Errorf("cannot create request: %v", err)
1390 }
1391
1392 resp, err := client.Do(req)
1393
1394 if err != nil {
1395 t.Errorf("cannot connect to the server: %v", err)
1396 }
1397
1398 want := fmt.Sprintf(`* Request to %s
1399 > HEAD /long-response HTTP/1.1
1400 > Host: %s
1401
1402 < HTTP/1.1 200 OK
1403 < Content-Length: 9846
1404
1405 `, uri, ts.Listener.Addr())
1406
1407 if got := buf.String(); got != want {
1408 t.Errorf("logged HTTP request %s; want %s", got, want)
1409 }
1410
1411 testBody(t, resp.Body, []byte{})
1412 }
1413
1414 func TestOutgoingTooLongResponse(t *testing.T) {
1415 t.Parallel()
1416
1417 ts := httptest.NewServer(&longResponseHandler{})
1418 defer ts.Close()
1419
1420 logger := &Logger{
1421 RequestHeader: true,
1422 RequestBody: true,
1423 ResponseHeader: true,
1424 ResponseBody: true,
1425 }
1426
1427 var buf bytes.Buffer
1428 logger.SetOutput(&buf)
1429
1430 logger.MaxResponseBody = 5000
1431
1432 client := &http.Client{
1433 Transport: logger.RoundTripper(newTransport()),
1434 }
1435
1436 uri := fmt.Sprintf("%s/long-response", ts.URL)
1437
1438 req, err := http.NewRequest(http.MethodGet, uri, nil)
1439
1440 if err != nil {
1441 t.Errorf("cannot create request: %v", err)
1442 }
1443
1444 resp, err := client.Do(req)
1445
1446 if err != nil {
1447 t.Errorf("cannot connect to the server: %v", err)
1448 }
1449
1450 want := fmt.Sprintf(`* Request to %s
1451 > GET /long-response HTTP/1.1
1452 > Host: %s
1453
1454 < HTTP/1.1 200 OK
1455 < Content-Length: 9846
1456 < Content-Type: text/plain; charset=utf-8
1457
1458 * body is too long (9846 bytes) to print, skipping (longer than 5000 bytes)
1459 `, uri, ts.Listener.Addr())
1460
1461 if got := buf.String(); got != want {
1462 t.Errorf("logged HTTP request %s; want %s", got, want)
1463 }
1464
1465 testBody(t, resp.Body, []byte(petition))
1466 }
1467
1468 type longResponseUnknownLengthHandler struct {
1469 repeat int
1470 }
1471
1472 func (h longResponseUnknownLengthHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) {
1473 w.Header()["Date"] = nil
1474 fmt.Fprint(w, strings.Repeat(petition, h.repeat+1))
1475 }
1476
1477 func TestOutgoingLongResponseUnknownLength(t *testing.T) {
1478 t.Parallel()
1479 testCases := []struct {
1480 name string
1481 repeat int
1482 }{
1483 {name: "short", repeat: 1},
1484 {name: "long", repeat: 100},
1485 }
1486
1487 for _, tc := range testCases {
1488 t.Run(tc.name, func(t *testing.T) {
1489 ts := httptest.NewServer(&longResponseUnknownLengthHandler{tc.repeat})
1490 defer ts.Close()
1491
1492 logger := &Logger{
1493 RequestHeader: true,
1494 RequestBody: true,
1495 ResponseHeader: true,
1496 ResponseBody: true,
1497 MaxResponseBody: 10000000,
1498 }
1499
1500 var buf bytes.Buffer
1501 logger.SetOutput(&buf)
1502
1503 client := &http.Client{
1504 Transport: logger.RoundTripper(newTransport()),
1505 }
1506
1507 uri := fmt.Sprintf("%s/long-response", ts.URL)
1508
1509 req, err := http.NewRequest(http.MethodGet, uri, nil)
1510
1511 if err != nil {
1512 t.Errorf("cannot create request: %v", err)
1513 }
1514
1515 resp, err := client.Do(req)
1516
1517 if err != nil {
1518 t.Errorf("cannot connect to the server: %v", err)
1519 }
1520
1521 repeatedBody := strings.Repeat(petition, tc.repeat+1)
1522 want := fmt.Sprintf(`* Request to %s
1523 > GET /long-response HTTP/1.1
1524 > Host: %s
1525
1526 < HTTP/1.1 200 OK
1527 < Content-Type: text/plain; charset=utf-8
1528
1529 %s
1530 `, uri, ts.Listener.Addr(), repeatedBody)
1531
1532 if got := buf.String(); got != want {
1533 t.Errorf("logged HTTP request %s; want %s", got, want)
1534 }
1535
1536 testBody(t, resp.Body, []byte(repeatedBody))
1537 })
1538 }
1539 }
1540
1541 func TestOutgoingLongResponseUnknownLengthTooLong(t *testing.T) {
1542 t.Parallel()
1543 testCases := []struct {
1544 name string
1545 repeat int
1546 }{
1547 {name: "short", repeat: 1},
1548 {name: "long", repeat: 100},
1549 }
1550
1551 for _, tc := range testCases {
1552 t.Run(tc.name, func(t *testing.T) {
1553 ts := httptest.NewServer(&longResponseUnknownLengthHandler{tc.repeat})
1554 defer ts.Close()
1555
1556 logger := &Logger{
1557 RequestHeader: true,
1558 RequestBody: true,
1559 ResponseHeader: true,
1560 ResponseBody: true,
1561 }
1562
1563 var buf bytes.Buffer
1564 logger.SetOutput(&buf)
1565
1566 client := &http.Client{
1567 Transport: logger.RoundTripper(newTransport()),
1568 }
1569
1570 uri := fmt.Sprintf("%s/long-response", ts.URL)
1571
1572 req, err := http.NewRequest(http.MethodGet, uri, nil)
1573
1574 if err != nil {
1575 t.Errorf("cannot create request: %v", err)
1576 }
1577
1578 resp, err := client.Do(req)
1579
1580 if err != nil {
1581 t.Errorf("cannot connect to the server: %v", err)
1582 }
1583
1584 want := fmt.Sprintf(`* Request to %s
1585 > GET /long-response HTTP/1.1
1586 > Host: %s
1587
1588 < HTTP/1.1 200 OK
1589 < Content-Type: text/plain; charset=utf-8
1590
1591 * body is too long, skipping (contains more than 4096 bytes)
1592 `, uri, ts.Listener.Addr())
1593
1594 if got := buf.String(); got != want {
1595 t.Errorf("logged HTTP request %s; want %s", got, want)
1596 }
1597
1598 testBody(t, resp.Body, []byte(strings.Repeat(petition, tc.repeat+1)))
1599 })
1600 }
1601 }
1602
1603 func multipartTestdata(writer *multipart.Writer, body *bytes.Buffer) {
1604 params := []struct {
1605 name string
1606 value string
1607 }{
1608 {"author", "Frédéric Bastiat"},
1609 {"title", "Candlemakers' Petition"},
1610 }
1611
1612 for _, p := range params {
1613 if err := writer.WriteField(p.name, p.value); err != nil {
1614 panic(err)
1615 }
1616 }
1617
1618 part, err := writer.CreateFormFile("file", "petition")
1619
1620 if err != nil {
1621 panic(err)
1622 }
1623
1624 if _, err = part.Write([]byte(petition)); err != nil {
1625 panic(err)
1626 }
1627
1628 if err = writer.Close(); err != nil {
1629 panic(err)
1630 }
1631 }
1632
1633 type multipartHandler struct {
1634 t *testing.T
1635 }
1636
1637 func (h multipartHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) {
1638 t := h.t
1639 w.Header()["Date"] = nil
1640
1641 if err := r.ParseMultipartForm(1000); err != nil {
1642 t.Errorf("cannot parse multipart form at server-side: %v", err)
1643 }
1644
1645 wantAuthor := "Frédéric Bastiat"
1646 wantTitle := "Candlemakers' Petition"
1647 wantFilename := "petition"
1648 gotAuthor := r.Form.Get("author")
1649 gotTitle := r.Form.Get("title")
1650
1651 if gotAuthor != wantAuthor {
1652 t.Errorf("got author %s, wanted %s", gotAuthor, wantAuthor)
1653 }
1654
1655 if gotTitle != wantTitle {
1656 t.Errorf("got author %s, wanted %s", gotTitle, wantTitle)
1657 }
1658
1659 file, header, err := r.FormFile("file")
1660
1661 if err != nil {
1662 t.Errorf("server cannot read file form sent over multipart: %v", err)
1663 }
1664
1665 if header.Filename != wantFilename {
1666 t.Errorf("got filename %s, wanted %s", header.Filename, wantFilename)
1667 }
1668
1669 if header.Size != int64(len(petition)) {
1670 t.Errorf("got size %d, wanted %d", header.Size, len(petition))
1671 }
1672
1673 b, err := ioutil.ReadAll(file)
1674
1675 if err != nil {
1676 t.Errorf("server cannot read file sent over multipart: %v", err)
1677 }
1678
1679 if string(b) != petition {
1680 t.Error("server received different text than uploaded")
1681 }
1682
1683 fmt.Fprint(w, "upload received")
1684 }
1685
1686 func TestOutgoingMultipartForm(t *testing.T) {
1687 t.Parallel()
1688
1689 ts := httptest.NewServer(multipartHandler{t})
1690 defer ts.Close()
1691
1692 logger := &Logger{
1693 RequestHeader: true,
1694
1695 ResponseHeader: true,
1696 ResponseBody: true,
1697 }
1698
1699 var buf bytes.Buffer
1700 logger.SetOutput(&buf)
1701
1702 logger.Formatters = []Formatter{
1703 &JSONFormatter{},
1704 }
1705
1706 client := &http.Client{
1707 Transport: logger.RoundTripper(newTransport()),
1708 }
1709
1710 uri := fmt.Sprintf("%s/multipart-upload", ts.URL)
1711
1712 body := &bytes.Buffer{}
1713 writer := multipart.NewWriter(body)
1714 multipartTestdata(writer, body)
1715
1716 req, err := http.NewRequest(http.MethodPost, uri, body)
1717
1718 if err != nil {
1719 t.Errorf("cannot create request: %v", err)
1720 }
1721
1722 req.Header.Set("Content-Type", writer.FormDataContentType())
1723
1724 _, err = client.Do(req)
1725
1726 if err != nil {
1727 t.Errorf("cannot connect to the server: %v", err)
1728 }
1729
1730 want := fmt.Sprintf(`* Request to %s
1731 > POST /multipart-upload HTTP/1.1
1732 > Host: %s
1733 > Content-Type: %s
1734
1735 < HTTP/1.1 200 OK
1736 < Content-Length: 15
1737 < Content-Type: text/plain; charset=utf-8
1738
1739 upload received
1740 `, uri, ts.Listener.Addr(), writer.FormDataContentType())
1741
1742 if got := buf.String(); got != want {
1743 t.Errorf("logged HTTP request %s; want %s", got, want)
1744 }
1745 }
1746
1747 func TestOutgoingTLS(t *testing.T) {
1748 t.Parallel()
1749
1750 ts := httptest.NewTLSServer(&helloHandler{})
1751 defer ts.Close()
1752
1753 logger := &Logger{
1754 TLS: true,
1755 RequestHeader: true,
1756 RequestBody: true,
1757 ResponseHeader: true,
1758 ResponseBody: true,
1759 }
1760
1761 var buf bytes.Buffer
1762 logger.SetOutput(&buf)
1763
1764 client := ts.Client()
1765
1766 client.Transport = logger.RoundTripper(client.Transport)
1767
1768 req, err := http.NewRequest(http.MethodGet, ts.URL, nil)
1769
1770 req.Host = "example.com"
1771
1772 req.Header.Add("User-Agent", "Robot/0.1 crawler@example.com")
1773
1774 if err != nil {
1775 t.Errorf("cannot create request: %v", err)
1776 }
1777
1778 resp, err := client.Do(req)
1779
1780 if err != nil {
1781 t.Errorf("cannot connect to the server: %v", err)
1782 }
1783
1784 want := fmt.Sprintf(`* Request to %s
1785 > GET / HTTP/1.1
1786 > Host: example.com
1787 > User-Agent: Robot/0.1 crawler@example.com
1788
1789 * TLS connection using TLS 1.3 / TLS_AES_128_GCM_SHA256
1790 * Server certificate:
1791 * subject: O=Acme Co
1792 * start date: Thu Jan 1 00:00:00 UTC 1970
1793 * expire date: Sat Jan 29 16:00:00 UTC 2084
1794 * issuer: O=Acme Co
1795 * TLS certificate verify ok.
1796 < HTTP/1.1 200 OK
1797 < Content-Length: 13
1798 < Content-Type: text/plain; charset=utf-8
1799
1800 Hello, world!
1801 `, ts.URL)
1802
1803 if got := buf.String(); got != want {
1804 t.Errorf("logged HTTP request %s; want %s", got, want)
1805 }
1806
1807 testBody(t, resp.Body, []byte("Hello, world!"))
1808 }
1809
1810 func TestOutgoingTLSInsecureSkipVerify(t *testing.T) {
1811 t.Parallel()
1812
1813 ts := httptest.NewTLSServer(&helloHandler{})
1814 defer ts.Close()
1815
1816 logger := &Logger{
1817 TLS: true,
1818 RequestHeader: true,
1819 RequestBody: true,
1820 ResponseHeader: true,
1821 ResponseBody: true,
1822 }
1823
1824 var buf bytes.Buffer
1825 logger.SetOutput(&buf)
1826
1827 client := ts.Client()
1828
1829 transport := client.Transport.(*http.Transport)
1830 transport.TLSClientConfig.InsecureSkipVerify = true
1831
1832 client.Transport = logger.RoundTripper(transport)
1833
1834 req, err := http.NewRequest(http.MethodGet, ts.URL, nil)
1835
1836 req.Host = "example.com"
1837
1838 req.Header.Add("User-Agent", "Robot/0.1 crawler@example.com")
1839
1840 if err != nil {
1841 t.Errorf("cannot create request: %v", err)
1842 }
1843
1844 resp, err := client.Do(req)
1845
1846 if err != nil {
1847 t.Errorf("cannot connect to the server: %v", err)
1848 }
1849
1850 want := fmt.Sprintf(`* Request to %s
1851 * Skipping TLS verification: connection is susceptible to man-in-the-middle attacks.
1852 > GET / HTTP/1.1
1853 > Host: example.com
1854 > User-Agent: Robot/0.1 crawler@example.com
1855
1856 * TLS connection using TLS 1.3 / TLS_AES_128_GCM_SHA256 (insecure=true)
1857 * Server certificate:
1858 * subject: O=Acme Co
1859 * start date: Thu Jan 1 00:00:00 UTC 1970
1860 * expire date: Sat Jan 29 16:00:00 UTC 2084
1861 * issuer: O=Acme Co
1862 * TLS certificate verify ok.
1863 < HTTP/1.1 200 OK
1864 < Content-Length: 13
1865 < Content-Type: text/plain; charset=utf-8
1866
1867 Hello, world!
1868 `, ts.URL)
1869
1870 got := buf.String()
1871
1872 if got != want {
1873 t.Errorf("logged HTTP request %s; want %s", got, want)
1874 }
1875
1876 testBody(t, resp.Body, []byte("Hello, world!"))
1877 }
1878
1879 func TestOutgoingTLSInvalidCertificate(t *testing.T) {
1880 t.Parallel()
1881
1882 ts := httptest.NewTLSServer(&helloHandler{})
1883 ts.Config.ErrorLog = log.New(ioutil.Discard, "", 0)
1884
1885 defer ts.Close()
1886
1887 logger := &Logger{
1888 TLS: true,
1889 RequestHeader: true,
1890 RequestBody: true,
1891 ResponseHeader: true,
1892 ResponseBody: true,
1893 }
1894
1895 var buf bytes.Buffer
1896 logger.SetOutput(&buf)
1897
1898 client := &http.Client{
1899 Transport: logger.RoundTripper(newTransport()),
1900 }
1901
1902 req, err := http.NewRequest(http.MethodGet, ts.URL, nil)
1903
1904 req.Host = "example.com"
1905
1906 req.Header.Add("User-Agent", "Robot/0.1 crawler@example.com")
1907
1908 if err != nil {
1909 t.Errorf("cannot create request: %v", err)
1910 }
1911
1912 _, err = client.Do(req)
1913
1914 var unknownAuthorityError x509.UnknownAuthorityError
1915 if err == nil || !errors.As(err, &unknownAuthorityError) {
1916 t.Errorf("cannot connect to the server has unexpected error: %v", err)
1917 }
1918
1919 want := fmt.Sprintf(`* Request to %s
1920 > GET / HTTP/1.1
1921 > Host: example.com
1922 > User-Agent: Robot/0.1 crawler@example.com
1923
1924 * x509: certificate signed by unknown authority
1925 `, ts.URL)
1926
1927 if got := buf.String(); got != want {
1928 t.Errorf("logged HTTP request %s; want %s", got, want)
1929 }
1930 }
1931
1932 func TestOutgoingTLSBadClientCertificate(t *testing.T) {
1933 t.Parallel()
1934
1935 ts := httptest.NewUnstartedServer(&helloHandler{})
1936
1937 ts.TLS = &tls.Config{
1938 ClientAuth: tls.RequireAndVerifyClientCert,
1939 }
1940
1941 ts.StartTLS()
1942
1943 defer ts.Close()
1944
1945 logger := &Logger{
1946 TLS: true,
1947 RequestHeader: true,
1948 RequestBody: true,
1949 ResponseHeader: true,
1950 ResponseBody: true,
1951 }
1952
1953 var buf bytes.Buffer
1954 logger.SetOutput(&buf)
1955 ts.Config.ErrorLog = log.New(ioutil.Discard, "", 0)
1956
1957 client := ts.Client()
1958
1959 cert, err := tls.LoadX509KeyPair("testdata/cert-client.pem", "testdata/key-client.pem")
1960
1961 if err != nil {
1962 panic(err)
1963 }
1964
1965 cert.Leaf, err = x509.ParseCertificate(cert.Certificate[0])
1966
1967 if err != nil {
1968 t.Errorf("failed to parse certificate for copying Leaf field")
1969 }
1970
1971 transport := client.Transport.(*http.Transport)
1972 transport.TLSClientConfig.Certificates = []tls.Certificate{
1973 cert,
1974 }
1975
1976 client.Transport = logger.RoundTripper(transport)
1977
1978 req, err := http.NewRequest(http.MethodGet, ts.URL, nil)
1979 req.Host = "example.com"
1980 req.Header.Add("User-Agent", "Robot/0.1 crawler@example.com")
1981
1982 if err != nil {
1983 t.Errorf("cannot create request: %v", err)
1984 }
1985
1986 _, err = client.Do(req)
1987
1988 if err == nil || !strings.Contains(err.Error(), "bad certificate") {
1989 t.Errorf("got: %v, expected bad certificate error message", err)
1990 }
1991
1992 want := fmt.Sprintf(`* Request to %s
1993 * Client certificate:
1994 * subject: CN=User,OU=User,O=Client,L=Rotterdam,ST=Zuid-Holland,C=NL
1995 * start date: Sat Jan 25 20:12:36 UTC 2020
1996 * expire date: Mon Jan 1 20:12:36 UTC 2120
1997 * issuer: CN=User,OU=User,O=Client,L=Rotterdam,ST=Zuid-Holland,C=NL
1998 > GET / HTTP/1.1
1999 > Host: example.com
2000 > User-Agent: Robot/0.1 crawler@example.com
2001
2002 * remote error: tls: bad certificate
2003 `, ts.URL)
2004
2005 if got := buf.String(); got != want {
2006 t.Errorf("logged HTTP request %s; want %s", got, want)
2007 }
2008 }
2009
2010 func TestOutgoingHTTP2MutualTLS(t *testing.T) {
2011 t.Parallel()
2012
2013 caCert, err := ioutil.ReadFile("testdata/cert.pem")
2014
2015 if err != nil {
2016 panic(err)
2017 }
2018
2019 clientCert, err := ioutil.ReadFile("testdata/cert-client.pem")
2020
2021 if err != nil {
2022 panic(err)
2023 }
2024
2025 caCertPool := x509.NewCertPool()
2026 caCertPool.AppendCertsFromPEM(caCert)
2027 caCertPool.AppendCertsFromPEM(clientCert)
2028
2029 tlsConfig := &tls.Config{
2030 ClientCAs: caCertPool,
2031 ClientAuth: tls.RequireAndVerifyClientCert,
2032 }
2033
2034
2035
2036 server := &http.Server{
2037 TLSConfig: tlsConfig,
2038 Handler: &helloHandler{},
2039 }
2040
2041 listener, err := netListener()
2042
2043 if err != nil {
2044 panic(fmt.Sprintf("failed to listen on a port: %v", err))
2045 }
2046
2047 defer listener.Close()
2048
2049 go func() {
2050
2051
2052
2053
2054
2055
2056
2057
2058 if errcp := server.ServeTLS(listener, "testdata/cert.pem", "testdata/key.pem"); errcp != http.ErrServerClosed {
2059 t.Errorf("server exit with unexpected error: %v", errcp)
2060 }
2061 }()
2062
2063 defer server.Shutdown(context.Background())
2064
2065
2066
2067
2068
2069
2070
2071
2072 cert, err := tls.LoadX509KeyPair("testdata/cert-client.pem", "testdata/key-client.pem")
2073
2074 if err != nil {
2075 t.Errorf("failed to load X509 key pair: %v", err)
2076 }
2077
2078 cert.Leaf, err = x509.ParseCertificate(cert.Certificate[0])
2079
2080 if err != nil {
2081 t.Errorf("failed to parse certificate for copying Leaf field")
2082 }
2083
2084
2085 clientTLSConfig := &tls.Config{
2086 RootCAs: caCertPool,
2087 Certificates: []tls.Certificate{cert},
2088 }
2089
2090 transport := newTransport()
2091 transport.TLSClientConfig = clientTLSConfig
2092
2093 client := &http.Client{
2094 Transport: transport,
2095 }
2096
2097 logger := &Logger{
2098 TLS: true,
2099 RequestHeader: true,
2100 RequestBody: true,
2101 ResponseHeader: true,
2102 ResponseBody: true,
2103 }
2104
2105 var buf bytes.Buffer
2106 logger.SetOutput(&buf)
2107
2108 client.Transport = logger.RoundTripper(client.Transport)
2109
2110 _, port, err := net.SplitHostPort(listener.Addr().String())
2111
2112 if err != nil {
2113 panic(err)
2114 }
2115
2116 var host = fmt.Sprintf("https://localhost:%s/mutual-tls-test", port)
2117
2118 resp, err := client.Get(host)
2119
2120 if err != nil {
2121 t.Errorf("cannot create request: %v", err)
2122 }
2123
2124 testBody(t, resp.Body, []byte("Hello, world!"))
2125
2126 want := fmt.Sprintf(`* Request to %s
2127 * Client certificate:
2128 * subject: CN=User,OU=User,O=Client,L=Rotterdam,ST=Zuid-Holland,C=NL
2129 * start date: Sat Jan 25 20:12:36 UTC 2020
2130 * expire date: Mon Jan 1 20:12:36 UTC 2120
2131 * issuer: CN=User,OU=User,O=Client,L=Rotterdam,ST=Zuid-Holland,C=NL
2132 > GET /mutual-tls-test HTTP/1.1
2133 > Host: localhost:%s
2134
2135 * TLS connection using TLS 1.3 / TLS_AES_128_GCM_SHA256
2136 * ALPN: h2 accepted
2137 * Server certificate:
2138 * subject: CN=localhost,OU=Cloud,O=Plifk,L=Carmel-by-the-Sea,ST=California,C=US
2139 * start date: Wed Aug 12 22:20:45 UTC 2020
2140 * expire date: Fri Jul 19 22:20:45 UTC 2120
2141 * issuer: CN=localhost,OU=Cloud,O=Plifk,L=Carmel-by-the-Sea,ST=California,C=US
2142 * TLS certificate verify ok.
2143 < HTTP/2.0 200 OK
2144 < Content-Length: 13
2145 < Content-Type: text/plain; charset=utf-8
2146
2147 Hello, world!
2148 `, host, port)
2149
2150 if got := buf.String(); got != want {
2151 t.Errorf("logged HTTP request %s; want %s", got, want)
2152 }
2153 }
2154
2155 func TestOutgoingHTTP2MutualTLSNoSafetyLogging(t *testing.T) {
2156 t.Parallel()
2157
2158 caCert, err := ioutil.ReadFile("testdata/cert.pem")
2159
2160 if err != nil {
2161 panic(err)
2162 }
2163
2164 clientCert, err := ioutil.ReadFile("testdata/cert-client.pem")
2165
2166 if err != nil {
2167 panic(err)
2168 }
2169
2170 caCertPool := x509.NewCertPool()
2171 caCertPool.AppendCertsFromPEM(caCert)
2172 caCertPool.AppendCertsFromPEM(clientCert)
2173
2174 tlsConfig := &tls.Config{
2175 ClientCAs: caCertPool,
2176 ClientAuth: tls.RequireAndVerifyClientCert,
2177 }
2178
2179
2180
2181 server := &http.Server{
2182 TLSConfig: tlsConfig,
2183 Handler: &helloHandler{},
2184 }
2185
2186 listener, err := netListener()
2187
2188 if err != nil {
2189 panic(fmt.Sprintf("failed to listen on a port: %v", err))
2190 }
2191
2192 defer listener.Close()
2193
2194 go func() {
2195
2196
2197
2198
2199
2200
2201
2202
2203 if errcp := server.ServeTLS(listener, "testdata/cert.pem", "testdata/key.pem"); errcp != http.ErrServerClosed {
2204 t.Errorf("server exit with unexpected error: %v", errcp)
2205 }
2206 }()
2207
2208 defer server.Shutdown(context.Background())
2209
2210
2211
2212
2213
2214
2215
2216
2217 cert, err := tls.LoadX509KeyPair("testdata/cert-client.pem", "testdata/key-client.pem")
2218
2219 if err != nil {
2220 t.Errorf("failed to load X509 key pair: %v", err)
2221 }
2222
2223 cert.Leaf, err = x509.ParseCertificate(cert.Certificate[0])
2224
2225 if err != nil {
2226 t.Errorf("failed to parse certificate for copying Leaf field")
2227 }
2228
2229
2230 clientTLSConfig := &tls.Config{
2231 RootCAs: caCertPool,
2232 Certificates: []tls.Certificate{cert},
2233 }
2234 transport := newTransport()
2235 transport.TLSClientConfig = clientTLSConfig
2236
2237 client := &http.Client{
2238 Transport: transport,
2239 }
2240
2241 logger := &Logger{
2242
2243 RequestHeader: true,
2244 RequestBody: true,
2245 ResponseHeader: true,
2246 ResponseBody: true,
2247 }
2248
2249 var buf bytes.Buffer
2250 logger.SetOutput(&buf)
2251
2252 client.Transport = logger.RoundTripper(client.Transport)
2253
2254 _, port, err := net.SplitHostPort(listener.Addr().String())
2255
2256 if err != nil {
2257 panic(err)
2258 }
2259
2260 var host = fmt.Sprintf("https://localhost:%s/mutual-tls-test", port)
2261
2262 resp, err := client.Get(host)
2263
2264 if err != nil {
2265 t.Errorf("cannot create request: %v", err)
2266 }
2267
2268 testBody(t, resp.Body, []byte("Hello, world!"))
2269
2270 want := fmt.Sprintf(`* Request to %s
2271 > GET /mutual-tls-test HTTP/1.1
2272 > Host: localhost:%s
2273
2274 < HTTP/2.0 200 OK
2275 < Content-Length: 13
2276 < Content-Type: text/plain; charset=utf-8
2277
2278 Hello, world!
2279 `, host, port)
2280
2281 if got := buf.String(); got != want {
2282 t.Errorf("logged HTTP request %s; want %s", got, want)
2283 }
2284 }
2285
2286
2287
2288 func netListener() (listener net.Listener, err error) {
2289 listener, err = net.Listen("tcp", "127.0.0.1:0")
2290
2291 if err != nil {
2292 return net.Listen("tcp6", "[::1]:0")
2293 }
2294
2295 return
2296 }
2297
View as plain text