Upgrade to Pro — share decks privately, control downloads, hide ads and more …

Structured logging

Structured logging

Amsterdam Python meetup user group
Thursday, July 16, 2015

18bdcd2f189a9b8fe2f836dde8db09fc?s=128

Nick Groenen

July 16, 2015
Tweet

More Decks by Nick Groenen

Other Decks in Programming

Transcript

  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.