Structured logging

Amsterdam Python meetup user group
Thursday, July 16, 2015

1. Structured logging Embrace the power of machine-readable logs
2. “ Logging: The process of recording events during the execution of a computer program.
3. 22:55:40 INFO Initializing hub 22:55:40 INFO Starting webserver 22:55:42 INFO Incoming connection from 127.0.0.1:37843 22:55:42 DEBUG Connection upgraded 22:55:42 DEBUG Received message: “ping”
4. >>> import logging
5. log = logging.getLogger() log.info(“Starting up”) log.warning(“Something is going wrong here”)
6. “ Structured logging: Logging events with specific fields (key=value)
7. INFO[07-07|22:55:42] Incoming connection component=websocket.serveWs remote=127.0.0.1:37843 event=connection.new DBUG[07-07|22:55:42] Connection upgraded component=websocket.serveWs remote=127.0.0.1:37843 event=connection.upgraded DBUG[07-07|22:55:42] Received a message component=websocket.connection remote=127.0.0.1:37843 event=connection.message message=ping
8. >>> import structlog
9. Structlog example >>> log = get_logger() >>> log = log.bind( … user=”nick”, … remote=”127.0.0.1:36509” … )
10. Structlog example >>> log.info(“message.new”, message=”ping”) 22:55:42 DEBUG user=”nick” remote=”127.0.0.1:36509” message=”ping” event=”message.new”
11. “Unstructured” logs suffer from two big problems
12. It is difficult to parse 1
13. Humans are rarely the first consumer of logs
14. Why? Parsed and sent to graphite Filtered or transformed with awk/cut/grep/sed Shipped to logstash/graylog/splunk
15. Parsing free-form logs is hard
16. Jul 15 15:33:06 dhcpd: DHCPDISCOVER from 00:25:90:4d:0c:a8 via bond0 Jul 15 15:33:06 dhcpd: DHCPOFFER on 10.1.99.222 to 00:25:90:4d:0c:a8 via bond0 Jul 15 15:33:06 dhcpd: DHCPDISCOVER from 00:25:90:4d:0c:a8 via bond0.106 Jul 15 15:33:29 dhcpd: DHCPACK on 10.3.227.169 to 84:2b:2b:6a:ee:24 (idrac-3MQ1Y4J) via bond0
17. Grok filter ((%{SYSLOGTIMESTAMP:timestamp})\s* dhcpd\S+\s* (%{WORD:dhcp_action})?.* [for|on] (%{IPV4:dhcp_client_ip})?.* [from|to] (%{COMMONMAC:remote_mac_addr})?.* via (%{USERNAME:interface}))
18. Machine-readable log event { "timestamp": "Jul 15 15:33:06 +0000", "program": "dhcpd", "message": "Offering DHCP lease", "event": "DHCPOFFER", "offered_ip": "10.1.99.222", "remote_mac_addr": "00:25:90:4d:0c:a8", "interface": "bond0" }
19. Structured logs are perfect for computers to consume 1
20. JSON makes my eyes bleed
21. JSON access logs $ parse-nginx-log \ --filename /var/log/nginx/access.log \ --fields status,remote_addr,request 302 69.64.46.86 GET /cgi-bin/rtpd.cgi HTTP/1.0 302 180.97.106.37 GET / HTTP/1.1 200 180.97.106.162 GET / HTTP/1.1 200 180.97.106.162 GET /robots.txt HTTP/1.1
22. Individual messages lack context 2
23. 22:55:42 INFO Incoming connection from 127.0.0.1:37843 22:55:42 DEBUG Connection upgraded 22:55:42 DEBUG Received message: “ping”
24. INFO[07-07|22:55:42] Incoming connection component=websocket.serveWs remote=127.0.0.1:37843 event=connection.new DBUG[07-07|22:55:42] Connection upgraded component=websocket.serveWs remote=127.0.0.1:37843 event=connection.upgraded DBUG[07-07|22:55:42] Received a message component=websocket.connection remote=127.0.0.1:37843 event=connection.message message=ping
25. Context makes filtering and correlation simple 2
26. Ask yourself: Will I ever feed this to a computer?
27. Thanks! ANY QUESTIONS? @NickGroenen nick@groenen.me
28. Credits Many thanks to ◦ SlidesCarnival for providing the design for this presentation. ◦ My employer Byte for hosting these meet-ups.