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