Logging Rethought 2: The Actions of Frank Taylor Jr. (PyCon Australia 2019)

Slide 1

Slide 1 text

Logging Rethought 2 The Actions of Frank Taylor Jr. markusholtermann.eu • gitlab.com/MarkusH • github.com/MarkusH • @m_holtermann

Slide 2

Slide 2 text

Hi, I’m Markus Holtermann ● Engineer at ● Django Core Contributor

Slide 3

Slide 3 text

@m_holtermann The Problem(s) We’re Facing

Slide 4

Slide 4 text

@m_holtermann The Current State Of Logging

Slide 5

Slide 5 text

import logging logger = logging.getLogger(__name__) logger.error( "Login failed because the " "connection to the authentication " "provider %s timed out.", provider_name )

Slide 6

Slide 6 text

[2019-04-01T10:47:04.139+00:00] [ERROR] [srv01] Login failed because the connection to the authentication provider google timed out.

Slide 7

Slide 7 text

@m_holtermann Our Logging Is Broken

Slide 8

Slide 8 text

@m_holtermann What IP and host did the server try to connect to?

Slide 9

Slide 9 text

@m_holtermann What was the timeout limit at the time?

Slide 10

Slide 10 text

@m_holtermann How many other attempts were made to talk to that authentication provider?

Slide 11

Slide 11 text

@m_holtermann Where other outgoing connections affected by timeout errors as well?

Slide 12

Slide 12 text

@m_holtermann Were other servers affected by the same problem as well?

Slide 13

Slide 13 text

@m_holtermann Adding Structure To Our Logs

Slide 14

Slide 14 text

import structlog logger = structlog.get_logger("structlog") logger.error( "auth_provider_failed", provider_name=provider_name, provider_ip=provider_ip, timeout=timeout, )

Slide 15

Slide 15 text

2019-04-01 10:47:04.139 [error ] auth_provider_failed provider_ip='8.8.8.8' provider_name='google' server='srv01' timeout=5

Slide 16

Slide 16 text

{ "event": "auth_provider_failed", "timestamp": 1554115624.139, "level": "error", "provider_name": "google", "provider_ip": "8.8.8.8", "timeout": 5 }

Slide 17

Slide 17 text

WYSIWYU What You See Is What You Understand

Slide 18

Slide 18 text

@m_holtermann

Slide 19

Slide 19 text

@m_holtermann A Picture Says More Than A Thousand Words

Slide 20

Slide 20 text

@m_holtermann

Slide 21

Slide 21 text

@m_holtermann Tracing Events

Slide 22

Slide 22 text

import uuid, structlog logger = structlog.get_logger("structlog") def structlog_middleware(get_response): def _inner(request): request.trace_id = ( request.META.get("HTTP_X_TRACE_ID") or str(uuid.uuid4()) ) log = logger.new(trace_id=request.trace_id) return get_response(request) return _inner

Slide 23

Slide 23 text

import structlog logger = structlog.get_logger("structlog") def structlog_user_middleware(get_response): def _inner(request): if request.user.is_authenticated: logger.bind(user_id=request.user.pk) return get_response(request) return _inner

Slide 24

Slide 24 text

@m_holtermann Logging For European Users

Slide 25

Slide 25 text

@m_holtermann Never log any secrets. EVER!

Slide 26

Slide 26 text

@m_holtermann Ensure your log data store is secured and not world- readable! NO, REALLY!

Slide 27

Slide 27 text

@m_holtermann Explicitly log whatever should end up in logs.

Slide 28

Slide 28 text

# DO logger.error("some_event", foo="bar", lorem="ipsum") # DON'T DO logger.error("some_event", **some_object.__dict__)