Slide 1

Slide 1 text

Structured logging Embrace the power of machine-readable logs

Slide 2

Slide 2 text

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

Slide 3

Slide 3 text

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”

Slide 4

Slide 4 text

>>> import logging

Slide 5

Slide 5 text

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

Slide 6

Slide 6 text

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

Slide 7

Slide 7 text

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

Slide 8

Slide 8 text

>>> import structlog

Slide 9

Slide 9 text

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

Slide 10

Slide 10 text

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”

Slide 11

Slide 11 text

“Unstructured” logs suffer from two big problems

Slide 12

Slide 12 text

It is difficult to parse 1

Slide 13

Slide 13 text

Humans are rarely the first consumer of logs

Slide 14

Slide 14 text

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

Slide 15

Slide 15 text

Parsing free-form logs is hard

Slide 16

Slide 16 text

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

Slide 17

Slide 17 text

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

Slide 18

Slide 18 text

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

Slide 19

Slide 19 text

Structured logs are perfect for computers to consume 1

Slide 20

Slide 20 text

JSON makes my eyes bleed

Slide 21

Slide 21 text

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

Slide 22

Slide 22 text

Individual messages lack context 2

Slide 23

Slide 23 text

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”

Slide 24

Slide 24 text

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

Slide 25

Slide 25 text

Context makes filtering and correlation simple 2

Slide 26

Slide 26 text

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

Slide 27

Slide 27 text

Thanks! ANY QUESTIONS? @NickGroenen [email protected]

Slide 28

Slide 28 text

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