1package logger
2
3// Copyright 2017 Microsoft Corporation
4//
5//  Licensed under the Apache License, Version 2.0 (the "License");
6//  you may not use this file except in compliance with the License.
7//  You may obtain a copy of the License at
8//
9//      http://www.apache.org/licenses/LICENSE-2.0
10//
11//  Unless required by applicable law or agreed to in writing, software
12//  distributed under the License is distributed on an "AS IS" BASIS,
13//  WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
14//  See the License for the specific language governing permissions and
15//  limitations under the License.
16
17import (
18	"fmt"
19	"io/ioutil"
20	"net/http"
21	"os"
22	"path"
23	"regexp"
24	"strings"
25	"testing"
26)
27
28func TestNilLogger(t *testing.T) {
29	// verify no crash with no logging
30	Instance.WriteRequest(nil, Filter{})
31}
32
33const (
34	reqURL                = "https://fakething/dot/com"
35	reqHeaderKey          = "x-header"
36	reqHeaderVal          = "value"
37	reqBody               = "the request body"
38	respHeaderKey         = "response-header"
39	respHeaderVal         = "something"
40	respBody              = "the response body"
41	logFileTimeStampRegex = `\(\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}\.\d{7}(-\d{2}:\d{2}|Z)\)`
42)
43
44func TestLogReqRespNoBody(t *testing.T) {
45	err := os.Setenv("AZURE_GO_SDK_LOG_LEVEL", "info")
46	if err != nil {
47		t.Fatalf("failed to set log level: %v", err)
48	}
49	lf := path.Join(os.TempDir(), "testloggingbasic.log")
50	err = os.Setenv("AZURE_GO_SDK_LOG_FILE", lf)
51	if err != nil {
52		t.Fatalf("failed to set log file: %v", err)
53	}
54	initDefaultLogger()
55	if Level() != LogInfo {
56		t.Fatalf("wrong log level: %d", Level())
57	}
58	// create mock request and response for logging
59	req, err := http.NewRequest(http.MethodGet, reqURL, nil)
60	if err != nil {
61		t.Fatalf("failed to create mock request: %v", err)
62	}
63	req.Header.Add(reqHeaderKey, reqHeaderVal)
64	Instance.WriteRequest(req, Filter{})
65	resp := &http.Response{
66		Status:     "200 OK",
67		StatusCode: 200,
68		Proto:      "HTTP/1.0",
69		ProtoMajor: 1,
70		ProtoMinor: 0,
71		Request:    req,
72		Header:     http.Header{},
73	}
74	resp.Header.Add(respHeaderKey, respHeaderVal)
75	Instance.WriteResponse(resp, Filter{})
76	if fl, ok := Instance.(fileLogger); ok {
77		fl.logFile.Close()
78	} else {
79		t.Fatal("expected Instance to be fileLogger")
80	}
81	// parse log file to ensure contents match
82	b, err := ioutil.ReadFile(lf)
83	if err != nil {
84		t.Fatalf("failed to read log file: %v", err)
85	}
86	parts := strings.Split(string(b), "\n")
87	reqMatch := fmt.Sprintf("%s INFO: REQUEST: %s %s", logFileTimeStampRegex, req.Method, req.URL.String())
88	respMatch := fmt.Sprintf("%s INFO: RESPONSE: %d %s", logFileTimeStampRegex, resp.StatusCode, resp.Request.URL.String())
89	if !matchRegex(t, reqMatch, parts[0]) {
90		t.Fatalf("request header doesn't match: %s", parts[0])
91	}
92	if !matchRegex(t, fmt.Sprintf("(?i)%s: %s", reqHeaderKey, reqHeaderVal), parts[1]) {
93		t.Fatalf("request header entry doesn't match: %s", parts[1])
94	}
95	if !matchRegex(t, respMatch, parts[2]) {
96		t.Fatalf("response header doesn't match: %s", parts[2])
97	}
98	if !matchRegex(t, fmt.Sprintf("(?i)%s: %s", respHeaderKey, respHeaderVal), parts[3]) {
99		t.Fatalf("response header value doesn't match: %s", parts[3])
100	}
101	// disable logging
102	err = os.Setenv("AZURE_GO_SDK_LOG_LEVEL", "")
103	if err != nil {
104		t.Fatalf("failed to clear log level: %v", err)
105	}
106}
107
108func TestLogReqRespWithBody(t *testing.T) {
109	err := os.Setenv("AZURE_GO_SDK_LOG_LEVEL", "debug")
110	if err != nil {
111		t.Fatalf("failed to set log level: %v", err)
112	}
113	lf := path.Join(os.TempDir(), "testloggingfull.log")
114	err = os.Setenv("AZURE_GO_SDK_LOG_FILE", lf)
115	if err != nil {
116		t.Fatalf("failed to set log file: %v", err)
117	}
118	initDefaultLogger()
119	if Level() != LogDebug {
120		t.Fatalf("wrong log level: %d", Level())
121	}
122	// create mock request and response for logging
123	req, err := http.NewRequest(http.MethodGet, reqURL, strings.NewReader(reqBody))
124	if err != nil {
125		t.Fatalf("failed to create mock request: %v", err)
126	}
127	req.Header.Add(reqHeaderKey, reqHeaderVal)
128	Instance.WriteRequest(req, Filter{})
129	resp := &http.Response{
130		Status:     "200 OK",
131		StatusCode: 200,
132		Proto:      "HTTP/1.0",
133		ProtoMajor: 1,
134		ProtoMinor: 0,
135		Request:    req,
136		Header:     http.Header{},
137		Body:       ioutil.NopCloser(strings.NewReader(respBody)),
138	}
139	resp.Header.Add(respHeaderKey, respHeaderVal)
140	Instance.WriteResponse(resp, Filter{})
141	if fl, ok := Instance.(fileLogger); ok {
142		fl.logFile.Close()
143	} else {
144		t.Fatal("expected Instance to be fileLogger")
145	}
146	// parse log file to ensure contents match
147	b, err := ioutil.ReadFile(lf)
148	if err != nil {
149		t.Fatalf("failed to read log file: %v", err)
150	}
151	parts := strings.Split(string(b), "\n")
152	reqMatch := fmt.Sprintf("%s INFO: REQUEST: %s %s", logFileTimeStampRegex, req.Method, req.URL.String())
153	respMatch := fmt.Sprintf("%s INFO: RESPONSE: %d %s", logFileTimeStampRegex, resp.StatusCode, resp.Request.URL.String())
154	if !matchRegex(t, reqMatch, parts[0]) {
155		t.Fatalf("request header doesn't match: %s", parts[0])
156	}
157	if !matchRegex(t, fmt.Sprintf("(?i)%s: %s", reqHeaderKey, reqHeaderVal), parts[1]) {
158		t.Fatalf("request header value doesn't match: %s", parts[1])
159	}
160	if !matchRegex(t, reqBody, parts[2]) {
161		t.Fatalf("request body doesn't match: %s", parts[2])
162	}
163	if !matchRegex(t, respMatch, parts[3]) {
164		t.Fatalf("response header doesn't match: %s", parts[3])
165	}
166	if !matchRegex(t, fmt.Sprintf("(?i)%s: %s", respHeaderKey, respHeaderVal), parts[4]) {
167		t.Fatalf("response header value doesn't match: %s", parts[4])
168	}
169	if !matchRegex(t, respBody, parts[5]) {
170		t.Fatalf("response body doesn't match: %s", parts[5])
171	}
172	// disable logging
173	err = os.Setenv("AZURE_GO_SDK_LOG_LEVEL", "")
174	if err != nil {
175		t.Fatalf("failed to clear log level: %v", err)
176	}
177}
178
179func matchRegex(t *testing.T, pattern, s string) bool {
180	match, err := regexp.MatchString(pattern, s)
181	if err != nil {
182		t.Fatalf("regexp failure: %v", err)
183	}
184	return match
185}
186