Stop logging 2xx responses

[ckolos]

This was raised as a problem early on in shavar development, but I suspect that it was discussed in IRC as I can find no formal issue for it.

Currently, the application logs every 2xx response to stdout/err. When this is run in a docker container, these lines are logged to the systems journal through systemd. As a result, each system is logging 2xx's from nginx as well as in the journal. This is negatively affecting IO on the box and requiring the application stack to be horizontally scaled above previous non-docker levels.

A sample message is shown below:

Mar 28 14:59:13 ip-172-31-20-252 docker[1821]: {"code": 200, "v": 1, "pid": 27, "agent": "curl/7.29.0", "path": "http://localhost/list", "remoteAddressChain": ["127.0.0.1"], "request_time": 0.0007231235504150391, "hostname": "ip-172-31-20-252", "name": "mozsvc.metrics", "time": "2017-03-28T14:59:13.969059Z", "method": "GET", "op": "mozsvc.metrics"}

Some remediation for this has been done, evidenced by a setting in the shavar.ini called 'stfu_200_logging', this doesn't seem to stop the 2xx logging in any way.

Please devise a method to log only non-2xx responses from the application and drop all 2xx logging.

[groovecoder]

The StfuWsgi200LogFilter did work locally, when I set stfu_200_logging = True in my shavar.testing.ini file. ...

[ckolos]

Well, I can't get all fancy and post an animated gif, but....

[root@ip-172-31-42-162 ~]# grep stfu /data/shavar/shavar.ini
  stfu_200_logging = True
[root@ip-172-31-42-162 ~]# curl http://localhost/list
allow-flashallow-digest256
base-track-digest256
baseeff-track-digest256
basew3c-track-digest256
block-flash-digest256
block-flashsubdoc-digest256
content-track-digest256
contenteff-track-digest256
contentw3c-track-digest256
except-flash-digest256
except-flashallow-digest256
except-flashsubdoc-digest256
mozfull-track-digest256
mozfullstaging-track-digest256
mozplugin-block-digest256
mozpub-track-digest256
mozstd-track-digest256
mozstd-trackwhite-digest256
mozstdstaging-track-digest256
mozstdstaging-trackwhite-digest256
moztestpub-track-digest256
moztestpub-trackwhite-digest256

<another window>

[root@ip-172-31-42-162 ~]# journalctl -flexu docker-shavar.service | grep -v heartbeat 

Mar 30 15:22:13 ip-172-31-42-162 docker[9610]: {"code": 200, "v": 1, "pid": 20, "agent": "curl
/7.29.0", "path": "http://localhost/list", "remoteAddressChain": ["127.0.0.1"], "request_time": 0.0005898475646972656, "hostname": "ip-172-31-42-162", "name": "mozsvc.metrics", "time": "2017-03-30T15:22:13.096897Z", "method": "GET", "op": "mozsvc.metrics"}                          Mar 30 15:22:13 ip-172-31-42-162 docker[9610]: [pid: 20|app: 0|req: 3/24] 127.0.0.1 () {32 var
s in 346 bytes} [Thu Mar 30 15:22:13 2017] GET /list => generated 583 bytes in 1 msecs (HTTP/1.1 200) 2 headers in 81 bytes (1 switches on core 0

So maybe what we're seeing here is that this 200 isn't part of the app code?

[ckolos]

[root@ip-172-31-42-162 ~]# curl http://localhost/fooboo
The requested page was not found.

<another window>
[root@ip-172-31-42-162 ~]# journalctl -flexu docker-shavar.service | grep -v heartbeat 

Mar 30 15:25:21 ip-172-31-42-162 docker[9610]: {"code": 404, "v": 1, "pid": 27, "agent": "curl
/7.29.0", "path": "http://localhost/fooboo", "remoteAddressChain": ["127.0.0.1"], "request_time": 0.00033402442932128906, "hostname": "ip-172-31-42-162", "name": "mozsvc.metrics", "time": "2017-03-30T15:25:21.040391Z", "method": "GET", "op": "mozsvc.metrics"}
Mar 30 15:25:21 ip-172-31-42-162 docker[9610]: [pid: 27|app: 0|req: 37/52] 127.0.0.1 () {32 va
rs in 350 bytes} [Thu Mar 30 15:25:21 2017] GET /fooboo => generated 33 bytes in 0 msecs (HTTP/1.1 404) 2 headers in 86 bytes (1 switches on core 0)

[groovecoder]

Hmm ... the only thing I can think to double-check is that the stfu_200_logging = True line is under the [shavar] section of the .ini file?

[ckolos]

Top line of comment 2. It's True.

[groovecoder]

Sorry, meant to check that it's under the [shavar] section and not in some other section?

[ckolos]

No worries. ;)

[root@ip-172-31-42-162 ~]# grep -B4 stfu /data/shavar/shavar.ini
[shavar]
default_interval = 3600
default_proto_ver = 2.0
  refresh_check_interval = 60
  stfu_200_logging = True

[ckolos]

Maybe the spacing?

[ckolos]

Okay, removed the spaces and some progress made

Mar 30 16:47:20 ip-172-31-42-162 docker[21742]: [pid: 27|app: 0|req: 5/5] 127.0.0.1 () {32 var
s in 346 bytes} [Thu Mar 30 16:47:20 2017] GET /list => generated 583 bytes in 1 msecs (HTTP/1.1 200) 2 headers in 81 bytes (1 switches on core 0)

This is much less annoying/hurtful than the previously and it still allows the error messages through.

Mar 30 16:48:18 ip-172-31-42-162 docker[21742]: {"code": 404, "v": 1, "pid": 20, "agent": "cur
l/7.29.0", "path": "http://localhost/fooboo", "remoteAddressChain": ["127.0.0.1"], "request_time": 0.00037407875061035156, "hostname": "ip-172-31-42-162", "name": "mozsvc.metrics", "time": "2017-03-30T16:48:18.427118Z", "method": "GET", "op": "mozsvc.metrics"}
Mar 30 16:48:18 ip-172-31-42-162 docker[21742]: [pid: 20|app: 0|req: 3/15] 127.0.0.1 () {32 va
rs in 350 bytes} [Thu Mar 30 16:48:18 2017] GET /fooboo => generated 33 bytes in 1 msecs (HTTP/1.1 404) 2 headers in 86 bytes (1 switches on core 0)

I will make the changes required to get this into prod.

[groovecoder]

Cool. So can we close this without changes to the code-base?

[ckolos]

yes