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

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

    View full-size slide


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

    View full-size 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 full-size slide

  4. >>> import logging

    View full-size slide

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

    View full-size slide


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

    View full-size 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 full-size slide

  8. >>> import structlog

    View full-size slide

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

    View full-size 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 full-size slide

  11. “Unstructured” logs suffer
    from two big problems

    View full-size slide

  12. It is difficult to parse
    1

    View full-size slide

  13. Humans are rarely the first
    consumer of logs

    View full-size slide

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

    View full-size slide

  15. Parsing free-form logs is hard

    View full-size 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 full-size 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 full-size 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 full-size slide

  19. Structured logs are perfect
    for computers to consume
    1

    View full-size slide

  20. JSON makes my eyes bleed

    View full-size 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 full-size slide

  22. Individual messages lack
    context
    2

    View full-size 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 full-size 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 full-size slide

  25. Context makes filtering and
    correlation simple
    2

    View full-size slide

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

    View full-size slide

  27. Thanks!
    ANY QUESTIONS?
    @NickGroenen
    [email protected]

    View full-size slide

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

    View full-size slide