Add securedrop-proxy logging

[sssoleileraaa]

Resolves #142

Test

1. Make a securedrop-proxy debian package from this branch
2. Copy it to sd-proxy VM (you might need to add a FileCopy policy to allow this
3. dpkg install it
4. Run the client
5. Tail ~/.securedrop-proxy/logs/proxy.log in sd-proxy and see your requests going through

I was able to cause a BrokenPipeError and see the traceback in the logs. The proxy was able to gracefully recover on the next request, but we now have record of things like that happening.

[emkll]

Thanks @creviera! Followed your test plan and installed the resulting proxy .deb in sd-proxy, works as expected, logs appear in the expected location:

[...]
2019-10-29 13:02:57,330 - root:39(start) INFO: Starting SecureDrop Proxy 0.1.4

2019-10-29 13:02:57,332 - root:15(__main__) DEBUG: Creating request to be sent by proxy
2019-10-29 13:02:57,333 - root:142(proxy) DEBUG: Sending request
2019-10-29 13:02:57,334 - urllib3.connectionpool:205(_new_conn) DEBUG: Starting new HTTP connection (1): <something>.onion:80
2019-10-29 13:02:57,961 - urllib3.connectionpool:393(_make_request) DEBUG: http://<something>.onion:80 "GET /api/v1/sources/c9905c88-ad13-4018-95b1-68ff7a2d0718/submissions HTTP/1.1" 200 1327
2019-10-29 13:02:57,962 - root:121(handle_response) DEBUG: Handling response
[...]

Based on my preliminary testing, I have some concerns over the volume of logs generated (2 minutes of proxy activity results in 16KB of logs, many at the DEBUG level.

What do you think about setting the logging threshold to INFO? Static message that provide information such as "starting proxy", "creating request" and "handling request" without any request-specific information could be set to DEBUG log level, and any request-specific information (such as the request object), could remain at INFO level. Perhaps this will help us balance the noise in the "production" logs with the ability to debug in development environments.

Somehow I can't find the source of where the line below is logged. Do you have any idea how/where this is logged?

2019-10-29 13:02:57,961 - urllib3.connectionpool:393(_make_request) DEBUG: http://<something>.onion:80 "GET /api/v1/sources/c9905c88-ad13-4018-95b1-68ff7a2d0718/submissions HTTP/1.1" 200 1327

[sssoleileraaa]

What do you think about setting the logging threshold to INFO?

Yes to this suggestion! I didn't realize it defaulted to DEBUG level. I'll make the change.

[sssoleileraaa]

nevermind it didn't default, i set it to debug level because i copy-pasted from the client... this should be updated in the client too

[sssoleileraaa]

hey @emkll - you should no longer see any debug logging now when you follow the log file, unless you set the env var for loglevel to be debug

ready for review

[emkll]

Thanks @creviera this looks good to me!

• In normal working situations, I get no log messages
• When inducing a failure (e.g. removing network to sd-proxy), I observe the errors/stacktrace in logs. While it does contain the URI of the request, it doesn't contain POST or response data, only URI and port
• overriding log level works as expected