Structured logging

Amsterdam Python meetup user group
Thursday, July 16, 2015

Transcript

1. Structured logging
   Embrace the power of
   machine-readable logs
   

   View Slide

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

   View Slide

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”
   

   View Slide

4. >>> import logging
   

   View Slide

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

   View Slide

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

   View Slide

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
   

   View Slide

8. >>> import structlog
   

   View Slide

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

   View Slide

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”
    

    View Slide

11. “Unstructured” logs suffer
    from two big problems
    

    View Slide

12. It is difficult to parse
    1
    

    View Slide

13. Humans are rarely the first
    consumer of logs
    

    View Slide

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

    View Slide

15. Parsing free-form logs is hard
    

    View Slide

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
    

    View Slide

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

    View Slide

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

    View Slide

19. Structured logs are perfect
    for computers to consume
    1
    

    View Slide

20. JSON makes my eyes bleed
    

    View Slide

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
    

    View Slide

22. Individual messages lack
    context
    2
    

    View Slide

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”
    

    View Slide

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
    

    View Slide

25. Context makes filtering and
    correlation simple
    2
    

    View Slide

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

    View Slide

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

    View Slide

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

    View Slide