Debug only errors

Author: vfarcic

TODO.md

@@ -16,6 +16,8 @@ The following environment variables can be used to configure the *Docker Flow Pr
 |CONNECTION_MODE    |HAProxy supports 5 connection modes.<br><br>`http-keep-alive`: all requests and responses are processed.<br>`http-tunnel`: only the first request and response are processed, everything else is forwarded with no analysis.<br>`httpclose`: tunnel with "Connection: close" added in both directions.<br>`http-server-close`: the server-facing connection is closed after the response.<br>`forceclose`: the connection is actively closed after end of response.<br><br>In general, it is preferred to use `http-server-close` with application servers, and some static servers might benefit from `http-keep-alive`.|No|http-server-close|http-keep-alive|
 |CONSUL_ADDRESS     |The address of a Consul instance used for storing proxy information and discovering running nodes.  Multiple addresses can be separated with comma (e.g. 192.168.0.10:8500,192.168.0.11:8500).|Only in the `default` mode| |192.168.0.10:8500|
 |DEBUG              |Enables logging of each request sent through the proxy. Please consult [Debug Format](#debug-format) for info about the log entries. This feature should be used with caution. Do not use it in production unless necessary.|No|false|true|
+|DEBUG              |Enables logging of each request sent through the proxy. Please consult [Debug Format](#debug-format) for info about the log entries. This feature should be used with caution. **Do not enable debugging in production unless necessary.**|No|false|true|
+|DEBUG_ERRORS_ONLY  |If set to `true`, only requests that resulted in an error, timeout, retry, and redispatch will be logged. If a request is HTTP, responses with a status 5xx will be logged too.|No|false|true|
 |DEFAULT_PORTS      |The default ports used by the proxy. Multiple values can be separated with comma (`,`). If a port should be for SSL connections, append it with `:ssl.|No|80,443:ssl| |
 |EXTRA_FRONTEND     |Value will be added to the default `frontend` configuration.|No    | | |
 |EXTRA_GLOBAL       |Value will be added to the default `global` configuration.|No      | | |
@@ -38,7 +40,7 @@ The following environment variables can be used to configure the *Docker Flow Pr
 
 ## Debug Format
 
-If debugging is enabled, *Docker Flow Proxy* will log HTTP and TCP requests.
+If debugging is enabled through the environment variable `DEBUG`, *Docker Flow Proxy* will log HTTP and TCP requests in addition to the event requests.
 
 ### HTTP Requests Debug Format
 

docs/config.md

@@ -4,6 +4,9 @@
 
 While the decision to provide minimal logging is a good one when things are working correctly, you might find yourself in a situation when the proxy is not behaving as expected. In such a case, additional logging for a limited time can come in handy.
 
+!!! danger
+	Do not enable debugging in production. It might severally impact *Docker Flow Proxy* performance.
+
 The examples that follow will show you how to enable *Docker Flow Proxy* debugging mode.
 
 ## Creating a Swarm Cluster
@@ -79,9 +82,6 @@ We can see log entries from the requests sent by `swarm-listener`, but there is
 
 By default, debugging is disabled for a reason. It slows down the proxy. While that might not be noticeable in this demo, when working with thousands of requests per second, debugging can prove to be a bottleneck.
 
-!!! danger
-	Do not enable debugging in production.
-
 We'll start by updating the `proxy` service.
 
 ```bash
@@ -118,8 +118,8 @@ Please go back to the other terminal and observe the logs.
 The relevant part of the output is as follows.
 
 ```
-HAPRoxy: 10.255.0.3:52639 [10/Mar/2017:13:18:00.780] services go-demo_main-be8080/go-demo_main 0/0/0/1/1 200 150 - - ---- 1/1/0/0/0 0/0 "GET /dem
-HAPRoxy: 10.255.0.3:52647 [10/Mar/2017:13:18:00.995] services services/<NOSRV> -1/-1/-1/-1/0 503 1271 - - SC-- 0/0/0/0/0 0/0 "GET /this/endpoint/
+HAPRoxy: 10.255.0.3:52639 [10/Mar/2017:13:18:00.780] services go-demo_main-be8080/go-demo_main 0/0/0/1/1 200 150 - - ---- 1/1/0/0/0 0/0 "GET /demo HTTP/1.1"
+HAPRoxy: 10.255.0.3:52647 [10/Mar/2017:13:18:00.995] services services/<NOSRV> -1/-1/-1/-1/0 503 1271 - - SC-- 0/0/0/0/0 0/0 "GET /this/endpoint/does/not/exist HTTP/1.1"
 ```
 
 As you can see, both requests were recorded.
@@ -212,6 +212,36 @@ HAPRoxy: 10.255.0.3:55569 [10/Mar/2017:16:15:40.806] tcpFE_6379 redis_main-be637
 
 As you can see, the TCP request is recorded.
 
+## Debugging Only Errors
+
+Running the proxy in *debug* mode in production might severally impact *Docker Flow Proxy* performance. On the other, not having the relevant information might cause some operational problems. Ideally, you would use a specialized monitoring tool (e.g. Prometheus) that would collect metrics. However, there are cases when you do want to display debugging information directly in the proxy but to have the data limited to errors. Such a choice has much smaller impact on proxy performance then full debugging mode.
+
+Debugging limited to errors can be enabled through the environment variable `DEBUG_ERRORS_ONLY`. Let's try it out.
+
+```bash
+docker service update --env-add DEBUG_ERRORS_ONLY=true proxy_proxy
+```
+
+We updated the `proxy` service by adding the environment variable `DEBUG_ERROR_ONLY`.
+
+Now we should repeat the two requests we tried before.
+
+```bash
+curl -i "http://$(docker-machine ip node-1)/demo/hello"
+
+curl -i "http://$(docker-machine ip node-1)/this/endpoint/does/not/exist"
+```
+
+The relevant parts of the `proxy` service log output is as follows.
+
+```
+HAPRoxy: 10.255.0.3:59755 [10/Mar/2017:19:11:24.860] services services/<NOSRV> -1/-1/-1/-1/0 503 1271 - - SC-- 0/0/0/0/0 0/0 "GET /this/endpoint/does/not/exist HTTP/1.1"
+```
+
+Even though we made two requests, only one was recorded in Docker logs.
+
+With the environment variable `DEBUG_ERRORS_ONLY`, only requests that resulted in an error are output.
+
 ## What Now?
 
 We are finished with the short introduction to *Docker Flow Proxy* debugging feature. We should destroy the demo cluster and free our resources for something else.

docs/debugging.md

@@ -225,6 +225,10 @@ func (m HaProxy) getConfigData() ConfigData {
 		d.ExtraFrontend += `
     option httplog
     log global`
+		if strings.EqualFold(GetSecretOrEnvVar("DEBUG_ERRORS_ONLY", ""), "true") {
+			d.ExtraDefaults += `
+    option  dontlog-normal`
+		}
 	} else {
 		d.ExtraDefaults += `
     option  dontlognull
@@ -319,7 +323,7 @@ frontend tcpFE_%d
 		port,
 		port,
 	)
-	if strings.EqualFold(os.Getenv("DEBUG"), "true") {
+	if strings.EqualFold(GetSecretOrEnvVar("DEBUG", ""), "true") {
 		tmpl += `
     option tcplog
     log global`

proxy/ha_proxy.go

@@ -309,6 +309,31 @@ func (s HaProxyTestSuite) Test_CreateConfigFromTemplates_AddsLogging_WhenDebug()
 	s.Equal(expectedData, actualData)
 }
 
+func (s HaProxyTestSuite) Test_CreateConfigFromTemplates_AddsDoNotLogNormal_WhenDebugErrorsOnlyIsSet() {
+	debugOrig := os.Getenv("DEBUG")
+	debugErrorsOnlyOrig := os.Getenv("DEBUG")
+	defer func() {
+		os.Setenv("DEBUG", debugOrig)
+		os.Setenv("DEBUG_ERRORS_ONLY", debugErrorsOnlyOrig)
+	}()
+	os.Setenv("DEBUG", "true")
+	os.Setenv("DEBUG_ERRORS_ONLY", "true")
+	var actualData string
+	expectedData := fmt.Sprintf(
+		"%s%s",
+		s.getTemplateWithLogsAndErrorsOnly(),
+		s.ServicesContent,
+	)
+	writeFile = func(filename string, data []byte, perm os.FileMode) error {
+		actualData = string(data)
+		return nil
+	}
+
+	NewHaProxy(s.TemplatesPath, s.ConfigsPath).CreateConfigFromTemplates()
+
+	s.Equal(expectedData, actualData)
+}
+
 func (s HaProxyTestSuite) Test_CreateConfigFromTemplates_AddsExtraGlobal() {
 	globalOrig := os.Getenv("EXTRA_GLOBAL")
 	defer func() { os.Setenv("EXTRA_GLOBAL", globalOrig) }()
@@ -584,13 +609,7 @@ frontend tcpFE_1234
     acl domain_my-service-1 hdr(host) -i my-domain.com
     use_backend my-service-1-be1234 if domain_my-service-1
     acl domain_my-service-2 hdr(host) -i my-domain-1.com my-domain-2.com
-    use_backend my-service-2-be1234 if domain_my-service-2
-
-frontend tcpFE_5678
-    bind *:5678
-    mode tcp
-    acl domain_my-service-2 hdr(host) -i my-domain-1.com my-domain-2.com
-    use_backend my-service-2-be5678 if domain_my-service-2%s`,
+    use_backend my-service-2-be1234 if domain_my-service-2%s`,
 		tmpl,
 		s.ServicesContent,
 	)
@@ -612,7 +631,6 @@ frontend tcpFE_5678
 		ServiceName: "my-service-2",
 		ServiceDest: []ServiceDest{
 			{SrcPort: 1234, Port: "4321"},
-			{SrcPort: 5678, Port: "8765"},
 		},
 		ServiceDomain: []string{"my-domain-1.com", "my-domain-2.com"},
 	}
@@ -1357,6 +1375,28 @@ func (s *HaProxyTestSuite) getTemplateWithLogs() string {
 	return tmpl
 }
 
+func (s *HaProxyTestSuite) getTemplateWithLogsAndErrorsOnly() string {
+	tmpl := strings.Replace(s.TemplateContent, "tune.ssl.default-dh-param 2048", "tune.ssl.default-dh-param 2048\n    log 127.0.0.1:1514 local0", -1)
+	tmpl = strings.Replace(tmpl, "    option  dontlognull\n", "", -1)
+	tmpl = strings.Replace(
+		tmpl,
+		`frontend services
+    bind *:80
+    bind *:443
+    mode http
+`,
+		`frontend services
+    bind *:80
+    bind *:443
+    mode http
+
+    option httplog
+    log global`,
+		-1,
+	)
+	return tmpl
+}
+
 // Mocks
 
 type FileInfoMock struct {