Structured logging Embrace the power of machine-readable logs

“ Logging: The process of recording events during the execution of a computer program.

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”

>>> import logging

log = logging.getLogger() log.info(“Starting up”) log.warning(“Something is going wrong here”)

“ Structured logging: Logging events with specific fields (key=value)

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

>>> import structlog

Structlog example >>> log = get_logger() >>> log = log.bind( … user=”nick”, … remote=”127.0.0.1:36509” … )

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”

“Unstructured” logs suffer from two big problems

It is difficult to parse 1

Humans are rarely the first consumer of logs

Why? Parsed and sent to graphite Filtered or transformed with awk/cut/grep/sed Shipped to logstash/graylog/splunk

Parsing free-form logs is hard

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

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}))

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" }

Structured logs are perfect for computers to consume 1

JSON makes my eyes bleed

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

Individual messages lack context 2

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”

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

Context makes filtering and correlation simple 2

Ask yourself: Will I ever feed this to a computer?

Thanks! ANY QUESTIONS? @NickGroenen nick@groenen.me

Credits Many thanks to ◦ SlidesCarnival for providing the design for this presentation. ◦ My employer Byte for hosting these meet-ups.