Kokbok för loggning

Författare:

Vinay Sajip <vinay_sajip at red-dove dot com>

Denna sida innehåller ett antal recept relaterade till loggning, som har visat sig vara användbara i det förflutna. För länkar till handledning och referensinformation, se Övriga resurser.

Använda loggning i flera moduler

Flera anrop till logging.getLogger('someLogger') returnerar en referens till samma loggerobjekt. Detta gäller inte bara inom samma modul, utan även över moduler så länge som det är i samma Python-tolkningsprocess. Det gäller för referenser till samma objekt; dessutom kan programkod definiera och konfigurera en överordnad logger i en modul och skapa (men inte konfigurera) en underordnad logger i en separat modul, och alla loggeranrop till den underordnade kommer att passera upp till den överordnade. Här är en huvudmodul:

import loggning
import hjälpmodul

# skapa logger med 'spam_application'
logger = logging.getLogger('spam_application')
logger.setLevel(logging.DEBUG)
# skapa filhanterare som loggar även debug-meddelanden
fh = logging.FileHandler('spam.log')
fh.setLevel(logging.DEBUG)
# skapa konsolhanterare med en högre loggnivå
ch = loggning.StreamHandler()
ch.setLevel(logging.ERROR)
# skapa formatter och lägg till den i hanterarna
formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')
fh.setFormatter(formatter)
ch.setFormatter(formatter)
# lägg till hanterarna till loggern
logger.addHandler(fh)
logger.addHandler(ch)

logger.info('skapar en instans av auxiliary_module.Auxiliary')
a = auxiliary_module.Auxiliary()
logger.info('skapade en instans av auxiliary_module.Auxiliary')
logger.info('anropar auxiliary_module.Auxiliary.do_something')
a.gör_något()
logger.info('avslutade auxiliary_module.Auxiliary.do_something')
logger.info('anropar auxiliary_module.some_function()')
auxiliary_module.some_function()
logger.info('klar med auxiliary_module.some_function()')

Här är hjälpmodulen:

import logging

# create logger
module_logger = logging.getLogger('spam_application.auxiliary')

class Auxiliary:
    def __init__(self):
        self.logger = logging.getLogger('spam_application.auxiliary.Auxiliary')
        self.logger.info('creating an instance of Auxiliary')

    def do_something(self):
        self.logger.info('doing something')
        a = 1 + 1
        self.logger.info('done doing something')

def some_function():
    module_logger.info('received a call to "some_function"')

Utmatningen ser ut så här:

2005-03-23 23:47:11,663 - spam_application - INFO -
   skapar en instans av auxiliary_module.Auxiliary
2005-03-23 23:47:11,665 - spam_application.auxiliary.Auxiliary - INFO -
   skapar en instans av Auxiliary
2005-03-23 23:47:11,665 - spam_application - INFO -
   skapade en instans av auxiliary_module.Auxiliary
2005-03-23 23:47:11,668 - spam_application - INFO - Anropar
   anropar auxiliary_module.Auxiliary.do_something
2005-03-23 23:47:11,668 - spam_application.auxiliary.Auxiliary - INFO -
   gör något
2005-03-23 23:47:11,669 - spam_application.auxiliary.Auxiliary - INFO -
   klar med att göra något
2005-03-23 23:47:11,670 - spam_application - INFO -
   klar auxiliary_module.Auxiliary.do_something
2005-03-23 23:47:11,671 - spam_application - INFO -
   anropar auxiliary_module.some_function()
2005-03-23 23:47:11,672 - spam_application.auxiliary - INFO -
   mottog ett anrop till 'some_function'
2005-03-23 23:47:11,673 - spam_application - INFO -
   klar med auxiliary_module.some_function()

Loggning från flera trådar

Loggning från flera trådar kräver ingen särskild ansträngning. Följande exempel visar loggning från huvudtråden (den ursprungliga tråden) och en annan tråd:

import logging
import threading
import time

def worker(arg):
    while not arg['stop']:
        logging.debug('Hi from myfunc')
        time.sleep(0.5)

def main():
    logging.basicConfig(level=logging.DEBUG, format='%(relativeCreated)6d %(threadName)s %(message)s')
    info = {'stop': False}
    thread = threading.Thread(target=worker, args=(info,))
    thread.start()
    while True:
        try:
            logging.debug('Hello from main')
            time.sleep(0.75)
        except KeyboardInterrupt:
            info['stop'] = True
            break
    thread.join()

if __name__ == '__main__':
    main()

När skriptet körs ska det skriva ut något i stil med följande:

   0 Tråd-1 Hej från myfunc
   3 MainThread Hej från main
 505 Tråd-1 Hej från myfunc
 755 MainThread Hej från main
1007 Tråd-1 Hej från myfunc
1507 Huvudtråd Hej från main
1508 Tråd-1 Hej från myfunc
2010 Tråd-1 Hej från myfunc
2258 Huvudtråd Hej från main
2512 Tråd-1 Hej från myfunc
3009 Huvudtråd Hej från huvudtråd
3013 Tråd-1 Hej från myfunc
3515 Tråd-1 Hej från myfunc
3761 Huvudtråd Hej från huvudtråd
4017 Tråd-1 Hej från myfunc
4513 Huvudtråd Hej från huvud
4518 Tråd-1 Hej från myfunc

Detta visar loggningsutmatningen utspridd som man kan förvänta sig. Det här tillvägagångssättet fungerar naturligtvis för fler trådar än vad som visas här.

Flera hanterare och formatterare

Loggar är vanliga Python-objekt. Metoden addHandler() har ingen minimi- eller maximikvot för antalet hanterare du kan lägga till. Ibland kan det vara fördelaktigt för en applikation att logga alla meddelanden av alla allvarlighetsgrader till en textfil samtidigt som fel eller över loggas till konsolen. För att konfigurera detta konfigurerar du helt enkelt lämpliga hanterare. Loggningsanropen i applikationskoden förblir oförändrade. Här är en liten modifiering av det tidigare enkla modulbaserade konfigurationsexemplet:

import logging

logger = logging.getLogger('simple_example')
logger.setLevel(logging.DEBUG)
# create file handler which logs even debug messages
fh = logging.FileHandler('spam.log')
fh.setLevel(logging.DEBUG)
# create console handler with a higher log level
ch = logging.StreamHandler()
ch.setLevel(logging.ERROR)
# create formatter and add it to the handlers
formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')
ch.setFormatter(formatter)
fh.setFormatter(formatter)
# add the handlers to logger
logger.addHandler(ch)
logger.addHandler(fh)

# 'application' code
logger.debug('debug message')
logger.info('info message')
logger.warning('warn message')
logger.error('error message')
logger.critical('critical message')

Observera att ”applikationskoden” inte bryr sig om flera hanterare. Det enda som ändrades var att en ny hanterare med namnet fh lades till och konfigurerades.

Möjligheten att skapa nya hanterare med filter av högre eller lägre allvarlighetsgrad kan vara till stor hjälp när man skriver och testar en applikation. Istället för att använda många print -satser för felsökning, använd logger.debug : Till skillnad från print-satserna, som du måste ta bort eller kommentera senare, kan logger.debug-satserna förbli intakta i källkoden och förbli vilande tills du behöver dem igen. Då är den enda förändring som behöver göras att ändra loggarens och/eller hanterarens allvarlighetsgrad till debug.

Loggning till flera destinationer

Låt oss säga att du vill logga till konsol och fil med olika meddelandeformat och under olika omständigheter. Låt oss säga att du vill logga meddelanden med nivå DEBUG och högre till filen, och de meddelanden som har nivå INFO och högre till konsolen. Låt oss också anta att filen ska innehålla tidsstämplar, men att konsolmeddelandena inte ska göra det. Så här kan du uppnå detta:

import logging

# set up logging to file - see previous section for more details
logging.basicConfig(level=logging.DEBUG,
                    format='%(asctime)s %(name)-12s %(levelname)-8s %(message)s',
                    datefmt='%m-%d %H:%M',
                    filename='/tmp/myapp.log',
                    filemode='w')
# define a Handler which writes INFO messages or higher to the sys.stderr
console = logging.StreamHandler()
console.setLevel(logging.INFO)
# set a format which is simpler for console use
formatter = logging.Formatter('%(name)-12s: %(levelname)-8s %(message)s')
# tell the handler to use this format
console.setFormatter(formatter)
# add the handler to the root logger
logging.getLogger('').addHandler(console)

# Now, we can log to the root logger, or any other logger. First the root...
logging.info('Jackdaws love my big sphinx of quartz.')

# Now, define a couple of other loggers which might represent areas in your
# application:

logger1 = logging.getLogger('myapp.area1')
logger2 = logging.getLogger('myapp.area2')

logger1.debug('Quick zephyrs blow, vexing daft Jim.')
logger1.info('How quickly daft jumping zebras vex.')
logger2.warning('Jail zesty vixen who grabbed pay from quack.')
logger2.error('The five boxing wizards jump quickly.')

När du kör detta kommer du att se följande på konsolen

root : INFO Jackdaws älskar min stora sfinx av kvarts.
myapp.area1 : INFO Hur snabbt dumma hoppande zebror vexar.
myapp.area2 : WARNING Fängsla den kaxiga ragatan som tog betalt av en kvacksalvare.
myapp.area2 : ERROR De fem boxnings-trollkarlarna hoppar snabbt.

och i filen kommer du att se något liknande

10-22 22:19 root INFO Kajor älskar min stora sfinx av kvarts.
10-22 22:19 myapp.area1 DEBUG Snabba zephyrs blåser och förargar dumma Jim.
10-22 22:19 myapp.area1 INFO Hur snabbt dumma hoppande zebror förargar.
10-22 22:19 myapp.area2 WARNING Fängslar den käcka ragatan som tog betalt av kvacksalvaren.
10-22 22:19 myapp.area2 ERROR De fem boxnings-trollkarlarna hoppar snabbt.

Som du kan se dyker bara DEBUG-meddelandet upp i filen. De andra meddelandena skickas till båda destinationerna.

I det här exemplet används konsol- och filhanterare, men du kan använda valfritt antal och valfri kombination av hanterare.

Observera att ovanstående val av loggfilnamn /tmp/myapp.log innebär att en standardplats för temporära filer används på POSIX-system. I Windows kan du behöva välja ett annat katalognamn för loggen - se bara till att katalogen finns och att du har behörighet att skapa och uppdatera filer i den.

Anpassad hantering av nivåer

Ibland kanske du vill göra något som skiljer sig något från standardhanteringen av nivåer i hanterare, där alla nivåer över ett tröskelvärde bearbetas av en hanterare. För att göra detta måste du använda filter. Låt oss titta på ett scenario där du vill ordna saker på följande sätt:

• Skicka meddelanden av allvarlighetsgrad INFO och WARNING till sys.stdout

• Skicka meddelanden med allvarlighetsgrad ERROR och högre till sys.stderr

• Skicka meddelanden av allvarlighetsgrad DEBUG och högre till filen app.log

Anta att du konfigurerar loggning med följande JSON:

{
    "version": 1,
    "disable_existing_loggers": false,
    "formaterare": {
        "simple": {
            "format": "%(levelname)-8s - %(message)s"
        }
    },
    "handlers": {
        "stdout": {
            "class": "logging.StreamHandler",
            "level": "INFO",
            "formatter": "simple",
            "stream": "ext://sys.stdout"
        },
        "stderr": {
            "class": "logging.StreamHandler",
            "level": "ERROR",
            "formatter": "simple",
            "stream": "ext://sys.stderr"
        },
        "file": {
            "class": "logging.FileHandler",
            "formatter": "simple",
            "filnamn": "app.log",
            "mode": "w"
        }
    },
    "root": {
        "nivå": "DEBUG",
        "handlers": [
            "stderr",
            "stdout",
            "file"
        ]
    }
}

Denna konfiguration gör nästan vad vi vill, förutom att sys.stdout skulle visa meddelanden med allvarlighetsgraden ERROR och endast händelser med denna allvarlighetsgrad och högre skulle spåras, liksom meddelanden med allvarlighetsgraden INFO och WARNING. För att förhindra detta kan vi ställa in ett filter som utesluter dessa meddelanden och lägga till det i relevant hanterare. Detta kan konfigureras genom att lägga till en filters -sektion parallellt med formatters och handlers:

{
    "filters": {
        "warnings_and_below": {
            "()" : "__main__.filter_maker",
            "level": "WARNING"
        }
    }
}

och ändra avsnittet om stdout hanteraren för att lägga till det:

{
    "stdout": {
        "class": "logging.StreamHandler",
        "level": "INFO",
        "formatter": "simple",
        "stream": "ext://sys.stdout",
        "filter": ["warnings_and_below"]
    }
}

Ett filter är bara en funktion, så vi kan definiera filter_maker (en fabriksfunktion) på följande sätt:

def filter_maker(nivå):
    level = getattr(loggning, level)

    def filter(record):
        return record.levelno <= nivå

    returnerar filter

Detta konverterar strängargumentet som skickas in till en numerisk nivå och returnerar en funktion som endast returnerar True om nivån på den skickade posten är på eller under den angivna nivån. Observera att jag i det här exemplet har definierat filter_maker i ett testskript main.py som jag kör från kommandoraden, så dess modul kommer att vara __main__ - därav __main__.filter_maker i filterkonfigurationen. Du måste ändra det om du definierar det i en annan modul.

Med filtret tillagt kan vi köra main.py, som i sin helhet är:

import json
import loggning
import loggning.config

CONFIG = ''''
{
    "version": 1,
    "disable_existing_loggers": false,
    "formatters": {
        "simple": {
            "format": "%(levelname)-8s - %(message)s"
        }
    },
    "filter": {
        "varningar_och_under": {
            "()" : "__main__.filter_maker",
            "nivå": "WARNING"
        }
    },
    "handlers": {
        "stdout": {
            "class": "logging.StreamHandler",
            "level": "INFO",
            "formatter": "simple",
            "stream": "ext://sys.stdout",
            "filter": ["warnings_and_below"]
        },
        "stderr": {
            "class": "logging.StreamHandler",
            "level": "ERROR",
            "formatter": "simple",
            "stream": "ext://sys.stderr"
        },
        "file": {
            "class": "logging.FileHandler",
            "formatter": "simple",
            "filnamn": "app.log",
            "mode": "w"
        }
    },
    "root": {
        "nivå": "DEBUG",
        "handlers": [
            "stderr",
            "stdout",
            "file"
        ]
    }
}
'''

def filter_maker(nivå):
    level = getattr(loggning, level)

    def filter(record):
        return record.levelno <= nivå

    returnerar filter

logging.config.dictConfig(json.loads(CONFIG))
logging.debug('Ett DEBUG-meddelande')
logging.info('Ett INFO-meddelande')
logging.warning('Ett WARNING-meddelande')
logging.error('Ett ERROR-meddelande')
logging.critical("Ett CRITICAL-meddelande")

Och efter att ha kört det så här:

python main.py 2>stderr.log >stdout.log

Vi kan se att resultaten är som förväntat:

$ mer *.log
::::::::::::::
app.log
::::::::::::::
DEBUG - Ett DEBUG-meddelande
INFO - Ett INFO-meddelande
WARNING - Ett varningsmeddelande
ERROR - Ett felmeddelande
CRITICAL - Ett meddelande om CRITICAL
::::::::::::::
stderr.log
::::::::::::::
ERROR - Ett felmeddelande
CRITICAL - Ett CRITICAL-meddelande
::::::::::::::
stdout.log
::::::::::::::
INFO - Ett INFO-meddelande
WARNING - Ett varningsmeddelande

Exempel på konfigurationsserver

Här följer ett exempel på en modul som använder konfigurationsservern för loggning:

import logging
import logging.config
import time
import os

# read initial config file
logging.config.fileConfig('logging.conf')

# create and start listener on port 9999
t = logging.config.listen(9999)
t.start()

logger = logging.getLogger('simpleExample')

try:
    # loop through logging calls to see the difference
    # new configurations make, until Ctrl+C is pressed
    while True:
        logger.debug('debug message')
        logger.info('info message')
        logger.warning('warn message')
        logger.error('error message')
        logger.critical('critical message')
        time.sleep(5)
except KeyboardInterrupt:
    # cleanup
    logging.config.stopListening()
    t.join()

Och här är ett skript som tar ett filnamn och skickar den filen till servern, korrekt föregången av den binärt kodade längden, som den nya loggningskonfigurationen:

#!/usr/bin/env python
import socket, sys, struct

with open(sys.argv[1], 'rb') as f:
    data_to_send = f.read()

HOST = 'localhost'
PORT = 9999
s = socket.socket(socket.AF_INET, socket.SOCK_STREAM)
print('connecting...')
s.connect((HOST, PORT))
print('sending config...')
s.send(struct.pack('>L', len(data_to_send)))
s.send(data_to_send)
s.close()
print('complete')

Hantering av handläggare som blockerar

Ibland måste man få sina logghanterare att göra sitt jobb utan att blockera den tråd man loggar från. Detta är vanligt i webbapplikationer, men det förekommer naturligtvis även i andra scenarier.

En vanlig bov som uppvisar ett trögt beteende är SMTPHandler: det kan ta lång tid att skicka e-post av ett antal anledningar som ligger utanför utvecklarens kontroll (till exempel en dåligt fungerande e-post- eller nätverksinfrastruktur). Men nästan alla nätverksbaserade hanterare kan blockera: Även en SocketHandler-operation kan göra en DNS-fråga under huven som är för långsam (och den här frågan kan vara djupt inne i socketbibliotekskoden, under Python-lagret och utanför din kontroll).

En lösning är att använda ett tvådelat tillvägagångssätt. I den första delen kopplar man bara en QueueHandler till de loggrar som nås från prestandakritiska trådar. De skriver helt enkelt till sin kö, som kan dimensioneras till en tillräckligt stor kapacitet eller initialiseras utan någon övre gräns för deras storlek. Skrivningen till kön kommer vanligtvis att accepteras snabbt, men du kommer förmodligen att behöva fånga queue.Full-undantaget som en försiktighetsåtgärd i din kod. Om du är en biblioteksutvecklare som har prestandakritiska trådar i sin kod, se till att dokumentera detta (tillsammans med ett förslag att endast bifoga QueueHandlers till dina loggrar) till förmån för andra utvecklare som kommer att använda din kod.

Den andra delen av lösningen är QueueListener, som har utformats som motsvarigheten till QueueHandler. En QueueListener är mycket enkel: den får en kö och några handlers, och startar en intern tråd som lyssnar på sin kö efter LogRecords som skickas från QueueHandlers (eller någon annan källa till LogRecords, för den delen). LogRecords tas bort från kön och skickas till handläggarna för bearbetning.

Fördelen med att ha en separat QueueListener-klass är att du kan använda samma instans för att betjäna flera QueueHandlers. Detta är mer resursvänligt än att till exempel ha trådade versioner av de befintliga hanterarklasserna, som skulle äta upp en tråd per hanterare utan någon särskild fördel.

Ett exempel på användning av dessa två klasser följer (import utelämnad):

que = queue.Queue(-1) # ingen begränsning på storlek
queue_handler = QueueHandler(que)
handler = loggning.StreamHandler()
listener = QueueListener(que, handler)
root = loggning.getLogger()
root.addHandler(queue_handler)
formatter = logging.formatter('%(threadName)s: %(message)s')
handler.setFormatter(formatter)
listener.start()
# Loggutmatningen kommer att visa den tråd som genererade
# händelsen (huvudtråden) snarare än den interna tråden som
# tråd som övervakar den interna kön. Detta är vad
# du vill ska hända.
root.warning("Se upp!")
listener.stop()

som, när den körs, kommer att producera:

MainThread: Se upp!

Anteckning

Även om den tidigare diskussionen inte specifikt handlade om asynkron kod, utan snarare om långsamma logghanterare, bör det noteras att vid loggning från asynkron kod kan nätverks- och till och med filhanterare leda till problem (blockering av händelseslingan) eftersom viss loggning görs från asyncio internals. Det kan vara bäst, om någon asynkron kod används i en applikation, att använda ovanstående tillvägagångssätt för loggning, så att all blockerande kod endast körs i QueueListener-tråden.

Ändrad i version 3.5: Före Python 3.5 skickade QueueListener alltid varje meddelande som togs emot från kön till varje hanterare som den initialiserades med. (Detta berodde på att det antogs att nivåfiltreringen gjordes på andra sidan, där kön fylls på) Från och med 3.5 kan detta beteende ändras genom att skicka ett nyckelordsargument respect_handler_level=True till lyssnarens konstruktör. När detta görs jämför lyssnaren nivån på varje meddelande med hanterarens nivå och skickar bara ett meddelande till en hanterare om det är lämpligt att göra det.

Ändrad i version 3.14: Klassen QueueListener kan startas (och stoppas) via with-satsen. Till exempel

med QueueListener(que, handler) som lyssnare:
    # Kölyssnaren startar automatiskt när
    # när "with"-blocket skrivs in.
    pass
# Kölyssnaren stoppas automatiskt när
# "with"-blocket har avslutats.

Skicka och ta emot loggningshändelser över ett nätverk

Låt oss säga att du vill skicka loggningshändelser över ett nätverk och hantera dem i mottagaränden. Ett enkelt sätt att göra detta är att koppla en SocketHandler-instans till rotloggaren i den sändande änden:

import logging, logging.handlers

rootLogger = logging.getLogger('')
rootLogger.setLevel(logging.DEBUG)
socketHandler = logging.handlers.SocketHandler('localhost',
                    logging.handlers.DEFAULT_TCP_LOGGING_PORT)
# don't bother with a formatter, since a socket handler sends the event as
# an unformatted pickle
rootLogger.addHandler(socketHandler)

# Now, we can log to the root logger, or any other logger. First the root...
logging.info('Jackdaws love my big sphinx of quartz.')

# Now, define a couple of other loggers which might represent areas in your
# application:

logger1 = logging.getLogger('myapp.area1')
logger2 = logging.getLogger('myapp.area2')

logger1.debug('Quick zephyrs blow, vexing daft Jim.')
logger1.info('How quickly daft jumping zebras vex.')
logger2.warning('Jail zesty vixen who grabbed pay from quack.')
logger2.error('The five boxing wizards jump quickly.')

På mottagarsidan kan du sätta upp en mottagare med hjälp av modulen socketserver. Här är ett grundläggande arbetsexempel:

import pickle
import logging
import logging.handlers
import socketserver
import struct


class LogRecordStreamHandler(socketserver.StreamRequestHandler):
    """Handler for a streaming logging request.

    This basically logs the record using whatever logging policy is
    configured locally.
    """

    def handle(self):
        """
        Handle multiple requests - each expected to be a 4-byte length,
        followed by the LogRecord in pickle format. Logs the record
        according to whatever policy is configured locally.
        """
        while True:
            chunk = self.connection.recv(4)
            if len(chunk) < 4:
                break
            slen = struct.unpack('>L', chunk)[0]
            chunk = self.connection.recv(slen)
            while len(chunk) < slen:
                chunk = chunk + self.connection.recv(slen - len(chunk))
            obj = self.unPickle(chunk)
            record = logging.makeLogRecord(obj)
            self.handleLogRecord(record)

    def unPickle(self, data):
        return pickle.loads(data)

    def handleLogRecord(self, record):
        # if a name is specified, we use the named logger rather than the one
        # implied by the record.
        if self.server.logname is not None:
            name = self.server.logname
        else:
            name = record.name
        logger = logging.getLogger(name)
        # N.B. EVERY record gets logged. This is because Logger.handle
        # is normally called AFTER logger-level filtering. If you want
        # to do filtering, do it at the client end to save wasting
        # cycles and network bandwidth!
        logger.handle(record)

class LogRecordSocketReceiver(socketserver.ThreadingTCPServer):
    """
    Simple TCP socket-based logging receiver suitable for testing.
    """

    allow_reuse_address = True

    def __init__(self, host='localhost',
                 port=logging.handlers.DEFAULT_TCP_LOGGING_PORT,
                 handler=LogRecordStreamHandler):
        socketserver.ThreadingTCPServer.__init__(self, (host, port), handler)
        self.abort = 0
        self.timeout = 1
        self.logname = None

    def serve_until_stopped(self):
        import select
        abort = 0
        while not abort:
            rd, wr, ex = select.select([self.socket.fileno()],
                                       [], [],
                                       self.timeout)
            if rd:
                self.handle_request()
            abort = self.abort

def main():
    logging.basicConfig(
        format='%(relativeCreated)5d %(name)-15s %(levelname)-8s %(message)s')
    tcpserver = LogRecordSocketReceiver()
    print('About to start TCP server...')
    tcpserver.serve_until_stopped()

if __name__ == '__main__':
    main()

Kör först servern och sedan klienten. På klientsidan skrivs ingenting ut på konsolen, men på serversidan bör du se något i stil med:

På väg att starta TCP-servern...
   59 root INFO Jackdaws älskar min stora sfinx av kvarts.
   59 myapp.area1 DEBUG Snabba zephyrs blåser, irriterar dumma Jim.
   69 myapp.area1 INFO Hur snabbt hoppande zebror förargar.
   69 myapp.area2 WARNING Fängslar en kaxig kvinna som tog betalt av en kvacksalvare.
   69 myapp.area2 ERROR De fem boxningstrollkarlarna hoppar snabbt.

Observera att det finns vissa säkerhetsproblem med pickle i vissa scenarier. Om dessa påverkar dig kan du använda ett alternativt serialiseringsschema genom att åsidosätta makePickle()-metoden och implementera ditt alternativ där, samt anpassa ovanstående skript för att använda din alternativa serialisering.

Kör en socketlyssnare för loggning i produktion

För att köra en loggningslyssnare i produktion kan du behöva använda ett processhanteringsverktyg som Supervisor. Här är en Gist som innehåller de grundläggande filerna för att köra ovanstående funktionalitet med Supervisor. Den består av följande filer:

Fil	Syfte
prepare.sh	Ett Bash-skript för att förbereda miljön för testning
supervisor.conf (fil:supervisor.conf)	Konfigurationsfilen för Supervisor, som innehåller poster för lyssnaren och en webbapplikation med flera processer
ensure_app.sh	Ett Bash-skript för att säkerställa att Supervisor körs med ovanstående konfiguration
log_listener.py	Socket-lyssnarprogrammet som tar emot logghändelser och registrerar dem i en fil
main.py	En enkel webbapplikation som utför loggning via ett uttag som är anslutet till lyssnaren
webapp.json	En JSON-konfigurationsfil för webbapplikationen
client.py	Ett Python-skript för att träna webbapplikationen

Webbapplikationen använder Gunicorn, som är en populär webbapplikationsserver som startar flera arbetsprocesser för att hantera förfrågningar. Den här exempelkonfigurationen visar hur arbetsprocesserna kan skriva till samma loggfil utan att hamna i konflikt med varandra — de går alla via socketlyssnaren.

För att testa dessa filer gör du följande i en POSIX-miljö:

1. Ladda ner the Gist som ett ZIP-arkiv med hjälp av Download ZIP-knappen.

2. Packa upp ovanstående filer från arkivet till en scratch-katalog.

3. I scratch-katalogen kör du bash prepare.sh för att göra allting klart. Detta skapar en run-underkatalog som innehåller Supervisor-relaterade filer och loggfiler, och en venv-underkatalog som innehåller en virtuell miljö i vilken bottle, gunicorn och supervisor installeras.

4. Kör bash ensure_app.sh för att säkerställa att Supervisor körs med ovanstående konfiguration.

5. Kör venv/bin/python client.py för att träna webbapplikationen, vilket kommer att leda till att poster skrivs till loggen.

6. Inspektera loggfilerna i underkatalogen run. Du bör se de senaste loggraderna i filer som matchar mönstret app.log*. De kommer inte att vara i någon särskild ordning, eftersom de har hanterats samtidigt av olika arbetsprocesser på ett icke-deterministiskt sätt.

7. Du kan stänga av lyssnaren och webbapplikationen genom att köra venv/bin/supervisorctl -c supervisor.conf shutdown.

Du kan behöva justera konfigurationsfilerna i den osannolika händelsen att de konfigurerade portarna krockar med något annat i din testmiljö.

I standardkonfigurationen används ett TCP-socket på port 9020. Du kan använda en Unix Domain-socket i stället för en TCP-socket genom att göra följande:

1. I listener.json lägger du till en socket -nyckel med sökvägen till den domänsockel du vill använda. Om denna nyckel finns lyssnar lyssnaren på motsvarande domänsockel och inte på en TCP-sockel (nyckeln port ignoreras).

2. I webapp.json, ändra konfigurationsordlistan för socket-hanteraren så att värdet host är sökvägen till domänens socket och ställ in värdet port till null.

Lägga till kontextuell information till din loggningsutdata

Ibland vill du att loggningsutdata ska innehålla kontextuell information utöver de parametrar som skickas till loggningsanropet. I en nätverksansluten applikation kan det t.ex. vara önskvärt att logga klientspecifik information i loggen (t.ex. fjärrklientens användarnamn eller IP-adress). Även om du kan använda extra-parametern för att uppnå detta är det inte alltid bekvämt att skicka informationen på det här sättet. Även om det kan vara frestande att skapa Logger-instanser per anslutning, är det inte en bra idé eftersom dessa instanser inte är garbage collected. Även om detta inte är ett problem i praktiken, när antalet Logger-instanser är beroende av den detaljnivå du vill använda för att logga en applikation, kan det vara svårt att hantera om antalet Logger-instanser i praktiken blir obegränsat.

Använda LoggerAdapters för att förmedla kontextuell information

Ett enkelt sätt att skicka kontextuell information som ska matas ut tillsammans med loggningshändelseinformation är att använda klassen LoggerAdapter. Denna klass är utformad för att se ut som en Logger, så att du kan anropa debug(), info(), warning(), error(), exception(), critical() och log(). Dessa metoder har samma signaturer som sina motsvarigheter i Logger, så du kan använda de två typerna av instanser omväxlande.

När du skapar en instans av LoggerAdapter, skickar du en instans av Logger och ett diktliknande objekt som innehåller din kontextuella information. När du anropar en av loggningsmetoderna på en instans av LoggerAdapter delegerar den anropet till den underliggande instansen av Logger som skickats till dess konstruktör och ser till att skicka den kontextuella informationen i det delegerade anropet. Här är ett utdrag från koden för LoggerAdapter:

def debug(self, msg, /, *args, **kwargs):
    """
    Delegera ett debug-anrop till den underliggande loggern, efter att ha lagt till
    kontextuell information från denna adapterinstans.
    """
    msg, kwargs = self.process(msg, kwargs)
    self.logger.debug(msg, *args, **kwargs)

Metoden process() i LoggerAdapter är där den kontextuella informationen läggs till i loggningsutdata. Den passerar meddelande- och nyckelordsargumenten i loggningsanropet och skickar tillbaka (potentiellt) modifierade versioner av dessa för att användas i anropet till den underliggande loggern. Standardimplementeringen av den här metoden lämnar meddelandet ifred, men infogar en ”extra” nyckel i keyword-argumentet vars värde är det diktliknande objekt som skickas till konstruktören. Om du hade skickat ett ”extra” nyckelordsargument i anropet till adaptern, kommer det naturligtvis att skrivas över i tysthet.

Fördelen med att använda ”extra” är att värdena i det diktliknande objektet slås samman till LogRecord-instansens __dict__, vilket gör att du kan använda anpassade strängar med dina Formatter-instanser som känner till nycklarna i det diktliknande objektet. Om du behöver en annan metod, t.ex. om du vill prependla eller appendla den kontextuella informationen till meddelandesträngen, behöver du bara underordna dig LoggerAdapter och åsidosätta process() för att göra vad du behöver. Här är ett enkelt exempel:

class CustomAdapter(loggning.LoggerAdapter):
    """
    Detta exempel på adapter förväntar sig att det skickade diktliknande objektet har en
    "connid"-nyckel, vars värde inom parentes läggs till i loggmeddelandet.
    """
    def process(self, msg, kwargs):
        return '[%s] %s' % (self.extra['connid'], msg), kwargs

som du kan använda så här:

logger = loggning.getLogger(__name__)
adapter = CustomAdapter(logger, {'connid': some_conn_id})

Då kommer alla händelser som du loggar till adaptern att ha värdet some_conn_id prependlat till loggmeddelandena.

Använda andra objekt än dikter för att skicka kontextuell information

Du behöver inte skicka en faktisk dict till en LoggerAdapter - du kan skicka en instans av en klass som implementerar __getitem__ och __iter__ så att den ser ut som en dict för loggning. Detta skulle vara användbart om du vill generera värden dynamiskt (medan värdena i en dict skulle vara konstanta).

Använda filter för att ge kontextuell information

Du kan också lägga till kontextuell information till loggutmatningen med hjälp av ett användardefinierat Filter. Filter -instanser får ändra de LogRecords som skickas till dem, inklusive lägga till ytterligare attribut som sedan kan matas ut med hjälp av en lämplig formatsträng eller, om det behövs, en anpassad Formatter.

Till exempel i en webbapplikation kan den begäran som behandlas (eller åtminstone de intressanta delarna av den) lagras i en threadlocal (threading.local) variabel, och sedan nås från ett Filter för att lägga till, säg, information från begäran - säg, fjärr-IP-adressen och fjärr-användarens användarnamn - till LogRecord, med hjälp av attributnamnen ’ip’ och ’user’ som i LoggerAdapter exemplet ovan. I så fall kan samma formatsträng användas för att få liknande utdata som visas ovan. Här är ett exempel på ett skript:

import logging
from random import choice

class ContextFilter(logging.Filter):
    """
    This is a filter which injects contextual information into the log.

    Rather than use actual contextual information, we just use random
    data in this demo.
    """

    USERS = ['jim', 'fred', 'sheila']
    IPS = ['123.231.231.123', '127.0.0.1', '192.168.0.1']

    def filter(self, record):

        record.ip = choice(ContextFilter.IPS)
        record.user = choice(ContextFilter.USERS)
        return True

if __name__ == '__main__':
    levels = (logging.DEBUG, logging.INFO, logging.WARNING, logging.ERROR, logging.CRITICAL)
    logging.basicConfig(level=logging.DEBUG,
                        format='%(asctime)-15s %(name)-5s %(levelname)-8s IP: %(ip)-15s User: %(user)-8s %(message)s')
    a1 = logging.getLogger('a.b.c')
    a2 = logging.getLogger('d.e.f')

    f = ContextFilter()
    a1.addFilter(f)
    a2.addFilter(f)
    a1.debug('A debug message')
    a1.info('An info message with %s', 'some parameters')
    for x in range(10):
        lvl = choice(levels)
        lvlname = logging.getLevelName(lvl)
        a2.log(lvl, 'A message at %s level with %d %s', lvlname, 2, 'parameters')

som, när den körs, producerar något liknande:

2010-09-06 22:38:15,292 a.b.c DEBUG IP: 123.231.231.123 Användare: fred Ett debug-meddelande
2010-09-06 22:38:15,300 a.b.c INFO IP: 192.168.0.1 Användare: sheila Ett infomeddelande med några parametrar
2010-09-06 22:38:15,300 d.e.f CRITICAL IP: 127.0.0.1 Användare: sheila Ett meddelande på CRITICAL-nivå med 2 parametrar
2010-09-06 22:38:15,300 d.e.f ERROR IP: 127.0.0.1 User: jim Ett meddelande på ERROR-nivå med 2 parametrar
2010-09-06 22:38:15,300 d.e.f DEBUG IP: 127.0.0.1 User: sheila Ett meddelande på DEBUG-nivå med 2 parametrar
2010-09-06 22:38:15,300 d.e.f ERROR IP: 123.231.231.123 Användare: fred Ett meddelande på ERROR-nivå med 2 parametrar
2010-09-06 22:38:15,300 d.e.f CRITICAL IP: 192.168.0.1 User: jim Ett meddelande på CRITICAL-nivå med 2 parametrar
2010-09-06 22:38:15,300 d.e.f CRITICAL IP: 127.0.0.1 Användare: sheila Ett meddelande på CRITICAL-nivå med 2 parametrar
2010-09-06 22:38:15,300 d.e.f DEBUG IP: 192.168.0.1 Användare: jim Ett meddelande på DEBUG-nivå med 2 parametrar
2010-09-06 22:38:15,301 d.e.f ERROR IP: 127.0.0.1 Användare: sheila Ett meddelande på ERROR-nivå med 2 parametrar
2010-09-06 22:38:15,301 d.e.f DEBUG IP: 123.231.231.123 Användare: fred Ett meddelande på DEBUG-nivå med 2 parametrar
2010-09-06 22:38:15,301 d.e.f INFO IP: 123.231.231.123 User: fred Ett meddelande på INFO-nivå med 2 parametrar

Användning av contextvars

Sedan Python 3.7 har modulen contextvars tillhandahållit kontextlokal lagring som fungerar för både threading och asyncio bearbetningsbehov. Den här typen av lagring kan därför vara att föredra framför trådlokal lagring. Följande exempel visar hur loggar i en flertrådad miljö kan fyllas med kontextuell information som t.ex. attribut för förfrågningar som hanteras av webbapplikationer.

Låt oss säga att du har olika webbapplikationer som är oberoende av varandra men som körs i samma Python-process och använder ett bibliotek som är gemensamt för dem. Hur kan var och en av dessa applikationer ha sin egen logg, där alla loggmeddelanden från biblioteket (och annan kod för behandling av förfrågningar) riktas till den lämpliga applikationens loggfil, samtidigt som loggen innehåller ytterligare kontextuell information som klientens IP, HTTP-förfrågningsmetod och klientens användarnamn?

Låt oss anta att biblioteket kan simuleras med hjälp av följande kod:

# webapplib.py
import logging
import time

logger = logging.getLogger(__name__)

def useful():
    # Just a representative event logged from the library
    logger.debug('Hello from webapplib!')
    # Just sleep for a bit so other threads get to run
    time.sleep(0.01)

Vi kan simulera flera webbapplikationer med hjälp av två enkla klasser, Request och WebApp. Dessa simulerar hur riktiga trådade webbapplikationer fungerar - varje förfrågan hanteras av en tråd:

# main.py
import argparse
from contextvars import ContextVar
import logging
import os
from random import choice
import threading
import webapplib

logger = logging.getLogger(__name__)
root = logging.getLogger()
root.setLevel(logging.DEBUG)

class Request:
    """
    A simple dummy request class which just holds dummy HTTP request method,
    client IP address and client username
    """
    def __init__(self, method, ip, user):
        self.method = method
        self.ip = ip
        self.user = user

# A dummy set of requests which will be used in the simulation - we'll just pick
# from this list randomly. Note that all GET requests are from 192.168.2.XXX
# addresses, whereas POST requests are from 192.16.3.XXX addresses. Three users
# are represented in the sample requests.

REQUESTS = [
    Request('GET', '192.168.2.20', 'jim'),
    Request('POST', '192.168.3.20', 'fred'),
    Request('GET', '192.168.2.21', 'sheila'),
    Request('POST', '192.168.3.21', 'jim'),
    Request('GET', '192.168.2.22', 'fred'),
    Request('POST', '192.168.3.22', 'sheila'),
]

# Note that the format string includes references to request context information
# such as HTTP method, client IP and username

formatter = logging.Formatter('%(threadName)-11s %(appName)s %(name)-9s %(user)-6s %(ip)s %(method)-4s %(message)s')

# Create our context variables. These will be filled at the start of request
# processing, and used in the logging that happens during that processing

ctx_request = ContextVar('request')
ctx_appname = ContextVar('appname')

class InjectingFilter(logging.Filter):
    """
    A filter which injects context-specific information into logs and ensures
    that only information for a specific webapp is included in its log
    """
    def __init__(self, app):
        self.app = app

    def filter(self, record):
        request = ctx_request.get()
        record.method = request.method
        record.ip = request.ip
        record.user = request.user
        record.appName = appName = ctx_appname.get()
        return appName == self.app.name

class WebApp:
    """
    A dummy web application class which has its own handler and filter for a
    webapp-specific log.
    """
    def __init__(self, name):
        self.name = name
        handler = logging.FileHandler(name + '.log', 'w')
        f = InjectingFilter(self)
        handler.setFormatter(formatter)
        handler.addFilter(f)
        root.addHandler(handler)
        self.num_requests = 0

    def process_request(self, request):
        """
        This is the dummy method for processing a request. It's called on a
        different thread for every request. We store the context information into
        the context vars before doing anything else.
        """
        ctx_request.set(request)
        ctx_appname.set(self.name)
        self.num_requests += 1
        logger.debug('Request processing started')
        webapplib.useful()
        logger.debug('Request processing finished')

def main():
    fn = os.path.splitext(os.path.basename(__file__))[0]
    adhf = argparse.ArgumentDefaultsHelpFormatter
    ap = argparse.ArgumentParser(formatter_class=adhf, prog=fn,
                                 description='Simulate a couple of web '
                                             'applications handling some '
                                             'requests, showing how request '
                                             'context can be used to '
                                             'populate logs')
    aa = ap.add_argument
    aa('--count', '-c', type=int, default=100, help='How many requests to simulate')
    options = ap.parse_args()

    # Create the dummy webapps and put them in a list which we can use to select
    # from randomly
    app1 = WebApp('app1')
    app2 = WebApp('app2')
    apps = [app1, app2]
    threads = []
    # Add a common handler which will capture all events
    handler = logging.FileHandler('app.log', 'w')
    handler.setFormatter(formatter)
    root.addHandler(handler)

    # Generate calls to process requests
    for i in range(options.count):
        try:
            # Pick an app at random and a request for it to process
            app = choice(apps)
            request = choice(REQUESTS)
            # Process the request in its own thread
            t = threading.Thread(target=app.process_request, args=(request,))
            threads.append(t)
            t.start()
        except KeyboardInterrupt:
            break

    # Wait for the threads to terminate
    for t in threads:
        t.join()

    for app in apps:
        print('%s processed %s requests' % (app.name, app.num_requests))

if __name__ == '__main__':
    main()

Om du kör ovanstående bör du upptäcka att ungefär hälften av förfrågningarna hamnar i app1.log och resten i app2.log, och att alla förfrågningar loggas i app.log. Varje webbappsspecifik logg kommer endast att innehålla loggposter för den webbappen och informationen om förfrågningar kommer att visas konsekvent i loggen (dvs. informationen i varje dummyförfrågan kommer alltid att visas tillsammans i en loggrad). Detta illustreras av följande shell-utdata:

~/logging-kontextuell-webbapp$ python main.py
app1 bearbetade 51 förfrågningar
app2 bearbetade 49 förfrågningar
~/logging-kontextuell-webbapp$ wc -l *.log
  153 app1.log
  147 app2.log
  300 app.log
  600 totalt
~/loggningskontextuell-webbapp$ head -3 app1.log
Tråd-3 (process_request) app1 __main__ jim 192.168.3.21 POST Bearbetning av begäran påbörjad
Tråd-3 (process_request) app1 webapplib jim 192.168.3.21 POST Hej från webapplib!
Thread-5 (process_request) app1 __main__ jim 192.168.3.21 POST Förfrågningsbearbetning påbörjad
~/logging-kontextuell-webapp$ head -3 app2.log
Thread-1 (process_request) app2 __main__ sheila 192.168.2.21 GET Förfrågningsbehandling påbörjad
Tråd-1 (process_request) app2 webapplib sheila 192.168.2.21 GET Hej från webapplib!
Tråd-2 (process_request) app2 __main__ jim 192.168.2.20 GET Förfrågningsbehandling påbörjad
~/logging-kontextuell-webapp$ head app.log
Tråd-1 (process_request) app2 __main__ sheila 192.168.2.21 GET Förfrågningsbehandling påbörjad
Tråd-1 (process_request) app2 webapplib sheila 192.168.2.21 GET Hej från webapplib!
Tråd-2 (process_request) app2 __main__ jim 192.168.2.20 GET Bearbetning av förfrågan påbörjad
Tråd-3 (process_request) app1 __main__ jim 192.168.3.21 POST Förfrågningsbehandling påbörjad
Tråd-2 (process_request) app2 webapplib jim 192.168.2.20 GET Hej från webapplib!
Tråd-3 (process_request) app1 webapplib jim 192.168.3.21 POST Hej från webapplib!
Tråd-4 (process_request) app2 __main__ fred 192.168.2.22 GET Behandling av förfrågan påbörjad
Thread-5 (process_request) app1 __main__ jim 192.168.3.21 POST Förfrågningsbehandling påbörjad
Tråd-4 (process_request) app2 webapplib fred 192.168.2.22 GET Hej från webapplib!
Thread-6 (process_request) app1 __main__ jim 192.168.3.21 POST Förfrågningsbearbetning påbörjad
~/logging-kontextuell-webapp$ grep app1 app1.log | wc -l
153
~/logging-kontextuell-webbapp$ grep app2 app2.log | wc -l
147
~/logging-kontextuell-webbapp$ grep app1 app.log | wc -l
153
~/logging-kontextuell-webbapp$ grep app2 app.log | wc -l
147

Förmedling av kontextuell information till handläggare

Varje Handler har sin egen kedja av filter. Om du vill lägga till kontextuell information till en LogRecord utan att läcka den till andra handlers kan du använda ett filter som returnerar en ny LogRecord istället för att modifiera den på plats, som visas i följande skript:

import copy
import logging

def filter(record: logging.LogRecord):
    record = copy.copy(record)
    record.user = 'jim'
    return record

if __name__ == '__main__':
    logger = logging.getLogger()
    logger.setLevel(logging.INFO)
    handler = logging.StreamHandler()
    formatter = logging.Formatter('%(message)s from %(user)-8s')
    handler.setFormatter(formatter)
    handler.addFilter(filter)
    logger.addHandler(handler)

    logger.info('A log message')

Loggning till en enda fil från flera processer

Även om loggning är trådsäker och loggning till en enda fil från flera trådar i en enda process stödjs, stöds inte loggning till en enda fil från flera processer, eftersom det inte finns något standardiserat sätt att serialisera åtkomst till en enda fil över flera processer i Python. Om du behöver logga till en enda fil från flera processer, är ett sätt att göra detta att låta alla processer logga till en SocketHandler, och ha en separat process som implementerar en socket-server som läser från sockeln och loggar till filen. (Om du föredrar det kan du dedikera en tråd i en av de befintliga processerna för att utföra denna funktion) Detta avsnitt dokumenterar detta tillvägagångssätt mer i detalj och innehåller en fungerande socketmottagare som kan användas som utgångspunkt för att anpassa i dina egna applikationer.

Du kan också skriva en egen hanterare som använder klassen Lock från modulen multiprocessing för att serialisera åtkomst till filen från dina processer. Stdlib FileHandler och dess underklasser använder inte multiprocessing.

Alternativt kan du använda en Queue och en QueueHandler för att skicka alla loggningshändelser till en av processerna i din multiprocessapplikation. Följande exempelskript visar hur du kan göra detta; i exemplet lyssnar en separat lyssnarprocess på händelser som skickas av andra processer och loggar dem enligt sin egen loggningskonfiguration. Även om exemplet bara visar ett sätt att göra det på (du kanske till exempel vill använda en lyssnartråd i stället för en separat lyssnarprocess - implementeringen skulle vara analog) tillåter det helt olika loggningskonfigurationer för lyssnaren och de andra processerna i din applikation, och kan användas som grund för kod som uppfyller dina egna specifika krav:

# You'll need these imports in your own code
import logging
import logging.handlers
import multiprocessing

# Next two import lines for this demo only
from random import choice, random
import time

#
# Because you'll want to define the logging configurations for listener and workers, the
# listener and worker process functions take a configurer parameter which is a callable
# for configuring logging for that process. These functions are also passed the queue,
# which they use for communication.
#
# In practice, you can configure the listener however you want, but note that in this
# simple example, the listener does not apply level or filter logic to received records.
# In practice, you would probably want to do this logic in the worker processes, to avoid
# sending events which would be filtered out between processes.
#
# The size of the rotated files is made small so you can see the results easily.
def listener_configurer():
    root = logging.getLogger()
    h = logging.handlers.RotatingFileHandler('mptest.log', 'a', 300, 10)
    f = logging.Formatter('%(asctime)s %(processName)-10s %(name)s %(levelname)-8s %(message)s')
    h.setFormatter(f)
    root.addHandler(h)

# This is the listener process top-level loop: wait for logging events
# (LogRecords)on the queue and handle them, quit when you get a None for a
# LogRecord.
def listener_process(queue, configurer):
    configurer()
    while True:
        try:
            record = queue.get()
            if record is None:  # We send this as a sentinel to tell the listener to quit.
                break
            logger = logging.getLogger(record.name)
            logger.handle(record)  # No level or filter logic applied - just do it!
        except Exception:
            import sys, traceback
            print('Whoops! Problem:', file=sys.stderr)
            traceback.print_exc(file=sys.stderr)

# Arrays used for random selections in this demo

LEVELS = [logging.DEBUG, logging.INFO, logging.WARNING,
          logging.ERROR, logging.CRITICAL]

LOGGERS = ['a.b.c', 'd.e.f']

MESSAGES = [
    'Random message #1',
    'Random message #2',
    'Random message #3',
]

# The worker configuration is done at the start of the worker process run.
# Note that on Windows you can't rely on fork semantics, so each process
# will run the logging configuration code when it starts.
def worker_configurer(queue):
    h = logging.handlers.QueueHandler(queue)  # Just the one handler needed
    root = logging.getLogger()
    root.addHandler(h)
    # send all messages, for demo; no other level or filter logic applied.
    root.setLevel(logging.DEBUG)

# This is the worker process top-level loop, which just logs ten events with
# random intervening delays before terminating.
# The print messages are just so you know it's doing something!
def worker_process(queue, configurer):
    configurer(queue)
    name = multiprocessing.current_process().name
    print('Worker started: %s' % name)
    for i in range(10):
        time.sleep(random())
        logger = logging.getLogger(choice(LOGGERS))
        level = choice(LEVELS)
        message = choice(MESSAGES)
        logger.log(level, message)
    print('Worker finished: %s' % name)

# Here's where the demo gets orchestrated. Create the queue, create and start
# the listener, create ten workers and start them, wait for them to finish,
# then send a None to the queue to tell the listener to finish.
def main():
    queue = multiprocessing.Queue(-1)
    listener = multiprocessing.Process(target=listener_process,
                                       args=(queue, listener_configurer))
    listener.start()
    workers = []
    for i in range(10):
        worker = multiprocessing.Process(target=worker_process,
                                         args=(queue, worker_configurer))
        workers.append(worker)
        worker.start()
    for w in workers:
        w.join()
    queue.put_nowait(None)
    listener.join()

if __name__ == '__main__':
    main()

En variant av ovanstående skript håller loggningen i huvudprocessen, i en separat tråd:

import logging
import logging.config
import logging.handlers
from multiprocessing import Process, Queue
import random
import threading
import time

def logger_thread(q):
    while True:
        record = q.get()
        if record is None:
            break
        logger = logging.getLogger(record.name)
        logger.handle(record)


def worker_process(q):
    qh = logging.handlers.QueueHandler(q)
    root = logging.getLogger()
    root.setLevel(logging.DEBUG)
    root.addHandler(qh)
    levels = [logging.DEBUG, logging.INFO, logging.WARNING, logging.ERROR,
              logging.CRITICAL]
    loggers = ['foo', 'foo.bar', 'foo.bar.baz',
               'spam', 'spam.ham', 'spam.ham.eggs']
    for i in range(100):
        lvl = random.choice(levels)
        logger = logging.getLogger(random.choice(loggers))
        logger.log(lvl, 'Message no. %d', i)

if __name__ == '__main__':
    q = Queue()
    d = {
        'version': 1,
        'formatters': {
            'detailed': {
                'class': 'logging.Formatter',
                'format': '%(asctime)s %(name)-15s %(levelname)-8s %(processName)-10s %(message)s'
            }
        },
        'handlers': {
            'console': {
                'class': 'logging.StreamHandler',
                'level': 'INFO',
            },
            'file': {
                'class': 'logging.FileHandler',
                'filename': 'mplog.log',
                'mode': 'w',
                'formatter': 'detailed',
            },
            'foofile': {
                'class': 'logging.FileHandler',
                'filename': 'mplog-foo.log',
                'mode': 'w',
                'formatter': 'detailed',
            },
            'errors': {
                'class': 'logging.FileHandler',
                'filename': 'mplog-errors.log',
                'mode': 'w',
                'level': 'ERROR',
                'formatter': 'detailed',
            },
        },
        'loggers': {
            'foo': {
                'handlers': ['foofile']
            }
        },
        'root': {
            'level': 'DEBUG',
            'handlers': ['console', 'file', 'errors']
        },
    }
    workers = []
    for i in range(5):
        wp = Process(target=worker_process, name='worker %d' % (i + 1), args=(q,))
        workers.append(wp)
        wp.start()
    logging.config.dictConfig(d)
    lp = threading.Thread(target=logger_thread, args=(q,))
    lp.start()
    # At this point, the main process could do some useful work of its own
    # Once it's done that, it can wait for the workers to terminate...
    for wp in workers:
        wp.join()
    # And now tell the logging thread to finish up, too
    q.put(None)
    lp.join()

Den här varianten visar hur du t.ex. kan tillämpa konfiguration för särskilda loggrar - t.ex. har loggern foo en speciell hanterare som lagrar alla händelser i delsystemet foo i en fil mplog-foo.log. Detta kommer att användas av loggningssystemet i huvudprocessen (även om loggningshändelserna genereras i arbetsprocesserna) för att styra meddelandena till lämpliga destinationer.

Använda concurrent.futures.ProcessPoolExecutor

Om du vill använda concurrent.futures.ProcessPoolExecutor för att starta dina arbetsprocesser måste du skapa kön på ett lite annorlunda sätt. Istället för

kö = multiprocessing.kö(-1)

du bör använda

queue = multiprocessing.Manager().Queue(-1) # fungerar också med exemplen ovan

och du kan sedan ersätta arbetstagarens skapelse från detta:

arbetare = []
för i i intervall(10):
    worker = multiprocessing.Process(target=worker_process,
                                     args=(kö, arbetare_konfigurerare))
    workers.append(arbetare)
    arbetare.start()
för w i workers:
    w.join()

till detta (kom ihåg att först importera concurrent.futures):

with concurrent.futures.ProcessPoolExecutor(max_arbetare=10) as executor:
    för i i intervall(10):
        executor.submit(arbetare_process, kö, arbetare_konfiguratör)

Driftsättning av webbapplikationer med hjälp av Gunicorn och uWSGI

När du distribuerar webbapplikationer med hjälp av Gunicorn eller uWSGI (eller liknande) skapas flera arbetsprocesser för att hantera klientförfrågningar. I sådana miljöer bör du undvika att skapa filbaserade hanterare direkt i din webbapplikation. Använd istället en SocketHandler för att logga från webbapplikationen till en lyssnare i en separat process. Detta kan ställas in med hjälp av ett processhanteringsverktyg som Supervisor - se Köra en loggningssocketlyssnare i produktion för mer information.

Använda filrotation

Ibland vill man låta en loggfil växa till en viss storlek och sedan öppna en ny fil och logga i den. Du kanske vill behålla ett visst antal av dessa filer, och när så många filer har skapats, rotera filerna så att antalet filer och storleken på filerna båda förblir begränsade. För detta användningsmönster tillhandahåller loggningspaketet en RotatingFileHandler:

import glob
import logging
import logging.handlers

LOG_FILENAME = 'logging_rotatingfile_example.out'

# Set up a specific logger with our desired output level
my_logger = logging.getLogger('MyLogger')
my_logger.setLevel(logging.DEBUG)

# Add the log message handler to the logger
handler = logging.handlers.RotatingFileHandler(
              LOG_FILENAME, maxBytes=20, backupCount=5)

my_logger.addHandler(handler)

# Log some messages
for i in range(20):
    my_logger.debug('i = %d' % i)

# See what files are created
logfiles = glob.glob('%s*' % LOG_FILENAME)

for filename in logfiles:
    print(filename)

Resultatet bör bli 6 separata filer, var och en med en del av logghistoriken för programmet:

loggning_roterandefil_exempel.out
loggning_roterandefil_exempel.out.1
loggning_rotationsfil_exempel.out.2
loggning_rotationsfil_exempel.out.3
loggning_rotationsfil_exempel.out.4
loggning_rotationsfil_exempel.out.5

Den mest aktuella filen är alltid logging_rotatingfile_example.out, och varje gång den når storleksgränsen döps den om med suffixet .1. Var och en av de befintliga säkerhetskopiorna byter namn så att suffixet ökar (.1 blir .2 osv.) och filen .6 raderas.

I det här exemplet är logglängden naturligtvis alldeles för liten, som ett extremt exempel. Du bör ställa in maxBytes till ett lämpligt värde.

Användning av alternativa formateringsstilar

När loggning lades till i Pythons standardbibliotek var det enda sättet att formatera meddelanden med variabelt innehåll att använda metoden %-formatting. Sedan dess har Python fått två nya formateringsmetoder: string.Template (tillagd i Python 2.4) och str.format() (tillagd i Python 2.6).

Loggning (från och med 3.2) ger förbättrat stöd för dessa två ytterligare formateringsstilar. Klassen Formatter har förbättrats så att den kan ta emot en ytterligare, valfri nyckelordsparameter med namnet style. Standardvärdet är '%', men andra möjliga värden är '{' och '$', vilket motsvarar de två andra formateringsstilarna. Bakåtkompatibilitet upprätthålls som standard (som du kan förvänta dig), men genom att uttryckligen ange en stilparameter får du möjlighet att ange formatsträngar som fungerar med str.format() eller string.Template. Här är ett exempel på en konsolsession för att visa möjligheterna:

>>> import logging
>>> root = logging.getLogger()
>>> root.setLevel(logging.DEBUG)
>>> handler = logging.StreamHandler()
>>> bf = logging.Formatter('{asctime} {name} {levelname:8s} {message}',
...                        style='{')
>>> handler.setFormatter(bf)
>>> root.addHandler(handler)
>>> logger = logging.getLogger('foo.bar')
>>> logger.debug('This is a DEBUG message')
2010-10-28 15:11:55,341 foo.bar DEBUG    This is a DEBUG message
>>> logger.critical('This is a CRITICAL message')
2010-10-28 15:12:11,526 foo.bar CRITICAL This is a CRITICAL message
>>> df = logging.Formatter('$asctime $name ${levelname} $message',
...                        style='$')
>>> handler.setFormatter(df)
>>> logger.debug('This is a DEBUG message')
2010-10-28 15:13:06,924 foo.bar DEBUG This is a DEBUG message
>>> logger.critical('This is a CRITICAL message')
2010-10-28 15:13:11,494 foo.bar CRITICAL This is a CRITICAL message
>>>

Observera att formateringen av loggade meddelanden för slutlig utmatning till loggar är helt oberoende av hur ett enskilt loggat meddelande är konstruerat. Det kan fortfarande använda %-fellermatting, som visas här:

>>> logger.error('This is an%s %s %s', 'other,', 'ERROR,', 'message')
2010-10-28 15:19:29,833 foo.bar ERROR This is another, ERROR, message
>>>

Loggningsanrop (logger.debug(), logger.info() etc.) tar endast positionsparametrar för själva loggningsmeddelandet, med nyckelordsparametrar som endast används för att bestämma alternativ för hur det faktiska loggningsanropet ska hanteras (t.ex. nyckelordsparametern exc_info för att ange att spårningsinformation ska loggas, eller nyckelordsparametern extra för att ange ytterligare kontextuell information som ska läggas till i loggen). Så du kan inte direkt göra loggningsanrop med str.format() eller string.Template syntax, eftersom loggningspaketet internt använder %-formatting för att slå samman formatsträngen och variabelargumenten. Det skulle inte gå att ändra detta och samtidigt bevara bakåtkompatibilitet, eftersom alla loggningsanrop som finns i befintlig kod kommer att använda %-format-strängar.

Det finns dock ett sätt att använda {}- och $-formatering för att konstruera dina individuella loggmeddelanden. Kom ihåg att du för ett meddelande kan använda ett godtyckligt objekt som en formatsträng för meddelandet och att loggningspaketet anropar str() på det objektet för att få den faktiska formatsträngen. Betrakta följande två klasser:

klass BraceMessage:
    def __init__(self, fmt, /, *args, **kwargs):
        self.fmt = fmt
        self.args = args
        self.kwargs = kwargs

    def __str__(self):
        return self.fmt.format(*self.args, **self.kwargs)

klass DollarMessage:
    def __init__(self, fmt, /, **kwargs):
        self.fmt = fmt
        self.kwargs = kwargs

    def __str__(self):
        från sträng import Template
        return Template(self.fmt).substitute(**self.kwargs)

Båda dessa kan användas i stället för en formatsträng, så att {}- eller $-formatering kan användas för att skapa den faktiska ”meddelande”-delen som visas i den formaterade loggutmatningen i stället för ”%(message)s” eller ”{message}” eller ”$message”. Det är lite otympligt att använda klassnamnen varje gång man vill logga något, men det är ganska smidigt om man använder ett alias som __ (dubbelt understreck — inte att förväxla med _, det enkla understreck som används som synonym/alias för gettext.gettext() eller dess bröder).

Ovanstående klasser ingår inte i Python, men de är lätta att kopiera och klistra in i din egen kod. De kan användas på följande sätt (förutsatt att de deklareras i en modul som heter wherever):

>>> from wherever import BraceMessage as __
>>> print(__('Message with {0} {name}', 2, name='placeholders'))
Message with 2 placeholders
>>> class Point: pass
...
>>> p = Point()
>>> p.x = 0.5
>>> p.y = 0.5
>>> print(__('Message with coordinates: ({point.x:.2f}, {point.y:.2f})',
...       point=p))
Message with coordinates: (0.50, 0.50)
>>> from wherever import DollarMessage as __
>>> print(__('Message with $num $what', num=2, what='placeholders'))
Message with 2 placeholders
>>>

I exemplen ovan används print() för att visa hur formateringen fungerar, men du skulle naturligtvis använda logger.debug() eller liknande för att faktiskt logga på det här sättet.

En sak att notera är att du inte betalar någon betydande prestandaförlust med det här tillvägagångssättet: den faktiska formateringen sker inte när du gör loggningsanropet, utan när (och om) det loggade meddelandet faktiskt är på väg att matas ut till en logg av en hanterare. Så det enda lite ovanliga som kan göra dig förvirrad är att parenteserna går runt formatsträngen och argumenten, inte bara formatsträngen. Det beror på att __-notationen bara är syntaxsocker för ett konstruktoranrop till en av klasserna XXXMessage.

Om du föredrar det kan du använda en LoggerAdapter för att uppnå en liknande effekt som ovan, som i följande exempel:

import logging

class Message:
    def __init__(self, fmt, args):
        self.fmt = fmt
        self.args = args

    def __str__(self):
        return self.fmt.format(*self.args)

class StyleAdapter(logging.LoggerAdapter):
    def log(self, level, msg, /, *args, stacklevel=1, **kwargs):
        if self.isEnabledFor(level):
            msg, kwargs = self.process(msg, kwargs)
            self.logger.log(level, Message(msg, args), **kwargs,
                            stacklevel=stacklevel+1)

logger = StyleAdapter(logging.getLogger(__name__))

def main():
    logger.debug('Hello, {}', 'world!')

if __name__ == '__main__':
    logging.basicConfig(level=logging.DEBUG)
    main()

Ovanstående skript bör logga meddelandet Hello, world! när det körs med Python 3.8 eller senare.

Anpassning av LogRecord

Varje loggningshändelse representeras av en LogRecord-instans. När en händelse loggas och inte filtreras bort av en loggers nivå, skapas en LogRecord, fylls på med information om händelsen och skickas sedan till hanterarna för den loggern (och dess förfäder, upp till och inklusive den logger där ytterligare spridning uppåt i hierarkin är inaktiverad). Före Python 3.2 fanns det bara två ställen där detta skapande gjordes:

• Logger.makeRecord(), som anropas i den normala processen för loggning av en händelse. Detta anropade LogRecord direkt för att skapa en instans.

• makeLogRecord(), som anropas med en ordbok som innehåller attribut som ska läggas till i LogRecord. Detta anropas vanligtvis när en lämplig ordlista har tagits emot över nätverket (t.ex. i pickle-form via en SocketHandler, eller i JSON-form via en HTTPHandler).

Detta har vanligtvis inneburit att om du behöver göra något speciellt med en LogRecord, har du varit tvungen att göra något av följande.

• Skapa din egen Logger-underklass, som åsidosätter Logger.makeRecord(), och ange den med setLoggerClass() innan alla loggar som du bryr dig om instansieras.

• Lägg till en Filter till en logger eller hanterare, som gör den nödvändiga speciella manipuleringen du behöver när dess filter()-metod anropas.

Det första tillvägagångssättet skulle vara lite otympligt i ett scenario där (säg) flera olika bibliotek ville göra olika saker. Alla skulle försöka skapa sin egen Logger-underklass, och den som gjorde det sist skulle vinna.

Det andra tillvägagångssättet fungerar ganska bra i många fall, men gör det inte möjligt att t.ex. använda en specialiserad underklass av LogRecord. Biblioteksutvecklare kan ställa in ett lämpligt filter på sina loggrar, men de skulle behöva komma ihåg att göra detta varje gång de introducerade en ny logger (vilket de skulle göra helt enkelt genom att lägga till nya paket eller moduler och göra

logger = loggning.getLogger(__name__)

på modulnivå). Det är förmodligen en sak för mycket att tänka på. Utvecklare skulle också kunna lägga till filtret i en NullHandler som är kopplad till deras logger på högsta nivån, men detta skulle inte aktiveras om en applikationsutvecklare kopplade en hanterare till en logger på lägre biblioteksnivå — så utdata från den hanteraren skulle inte återspegla biblioteksutvecklarens avsikter.

I Python 3.2 och senare skapas LogRecord genom en fabrik, som du kan ange. Fabriken är bara en anropsbar som du kan ställa in med setLogRecordFactory() och fråga med getLogRecordFactory(). Fabriken anropas med samma signatur som konstruktören LogRecord, eftersom LogRecord är standardinställningen för fabriken.

Detta tillvägagångssätt gör det möjligt för en anpassad fabrik att kontrollera alla aspekter av LogRecord-skapandet. Du kan till exempel returnera en underklass, eller bara lägga till några ytterligare attribut till posten när den har skapats, med ett mönster som liknar detta:

old_factory = loggning.getLogRecordFactory()

def record_factory(*args, **kwargs):
    record = old_factory(*args, **kwargs)
    record.custom_attribute = 0xdecafbad
    returnera record

logging.setLogRecordFactory(record_factory)

Detta mönster gör det möjligt för olika bibliotek att kedja ihop fabriker, och så länge de inte skriver över varandras attribut eller oavsiktligt skriver över de attribut som tillhandahålls som standard, bör det inte bli några överraskningar. Man bör dock komma ihåg att varje länk i kedjan lägger till run-time overhead till alla loggningsoperationer, och tekniken bör endast användas när användningen av en Filter inte ger det önskade resultatet.

Subklassning av QueueHandler och QueueListener - ett ZeroMQ-exempel

Underklass QueueHandler

Du kan använda en QueueHandler subklass för att skicka meddelanden till andra typer av köer, till exempel en ZeroMQ ’publish’ socket. I exemplet nedan skapas sockeln separat och skickas till hanteraren (som dess ’queue’):

import zmq # använder pyzmq, Python-bindningen för ZeroMQ
import json # för portabel serialisering av poster

ctx = zmq.kontext()
sock = zmq.Socket(ctx, zmq.PUB) # eller zmq.PUSH, eller annat lämpligt värde
sock.bind('tcp://*:5556') # eller var som helst

klass ZeroMQSocketHandler(QueueHandler):
    def enqueue(self, record):
        self.queue.send_json(record.__dict__)


handler = ZeroMQSocketHandler(sock)

Det finns naturligtvis andra sätt att organisera detta, till exempel att skicka in de data som behövs av hanteraren för att skapa socket:

klass ZeroMQSocketHandler(QueueHandler):
    def __init__(self, uri, socktype=zmq.PUB, ctx=None):
        self.ctx = ctx eller zmq.Context()
        socket = zmq.Socket(self.ctx, socktype)
        socket.bind(uri)
        super().__init__(socket)

    def enqueue(self, record):
        self.queue.send_json(record.__dict__)

    def close(self):
        self.queue.close()

Underklass QueueListener

Du kan också subklassa QueueListener för att få meddelanden från andra typer av köer, till exempel en ZeroMQ ’subscribe’ socket. Här är ett exempel:

klass ZeroMQSocketListener(QueueListener):
    def __init__(self, uri, /, *handlers, **kwargs):
        self.ctx = kwargs.get('ctx') eller zmq.Context()
        socket = zmq.Socket(self.ctx, zmq.SUB)
        socket.setsockopt_string(zmq.SUBSCRIBE, '') # prenumerera på allt
        socket.connect(uri)
        super().__init__(socket, *handlers, **kwargs)

    def dequeue(self):
        msg = self.queue.recv_json()
        return logging.makeLogRecord(msg)

Subklassning av QueueHandler och QueueListener - ett exempel från pynng

På liknande sätt som i avsnittet ovan kan vi implementera en lyssnare och hanterare med hjälp av pynng, som är en Python-bindning till NNG, marknadsförd som en andlig efterföljare till ZeroMQ. Följande utdrag illustrerar - du kan testa dem i en miljö som har pynng installerat. Bara för variationens skull presenterar vi lyssnaren först.

Underklass QueueListener

# listener.py
import json
import logging
import logging.handlers

import pynng

DEFAULT_ADDR = "tcp://localhost:13232"

interrupted = False

class NNGSocketListener(logging.handlers.QueueListener):

    def __init__(self, uri, /, *handlers, **kwargs):
        # Have a timeout for interruptability, and open a
        # subscriber socket
        socket = pynng.Sub0(listen=uri, recv_timeout=500)
        # The b'' subscription matches all topics
        topics = kwargs.pop('topics', None) or b''
        socket.subscribe(topics)
        # We treat the socket as a queue
        super().__init__(socket, *handlers, **kwargs)

    def dequeue(self, block):
        data = None
        # Keep looping while not interrupted and no data received over the
        # socket
        while not interrupted:
            try:
                data = self.queue.recv(block=block)
                break
            except pynng.Timeout:
                pass
            except pynng.Closed:  # sometimes happens when you hit Ctrl-C
                break
        if data is None:
            return None
        # Get the logging event sent from a publisher
        event = json.loads(data.decode('utf-8'))
        return logging.makeLogRecord(event)

    def enqueue_sentinel(self):
        # Not used in this implementation, as the socket isn't really a
        # queue
        pass

logging.getLogger('pynng').propagate = False
listener = NNGSocketListener(DEFAULT_ADDR, logging.StreamHandler(), topics=b'')
listener.start()
print('Press Ctrl-C to stop.')
try:
    while True:
        pass
except KeyboardInterrupt:
    interrupted = True
finally:
    listener.stop()

Underklass QueueHandler

# sender.py
import json
import logging
import logging.handlers
import time
import random

import pynng

DEFAULT_ADDR = "tcp://localhost:13232"

class NNGSocketHandler(logging.handlers.QueueHandler):

    def __init__(self, uri):
        socket = pynng.Pub0(dial=uri, send_timeout=500)
        super().__init__(socket)

    def enqueue(self, record):
        # Send the record as UTF-8 encoded JSON
        d = dict(record.__dict__)
        data = json.dumps(d)
        self.queue.send(data.encode('utf-8'))

    def close(self):
        self.queue.close()

logging.getLogger('pynng').propagate = False
handler = NNGSocketHandler(DEFAULT_ADDR)
# Make sure the process ID is in the output
logging.basicConfig(level=logging.DEBUG,
                    handlers=[logging.StreamHandler(), handler],
                    format='%(levelname)-8s %(name)10s %(process)6s %(message)s')
levels = (logging.DEBUG, logging.INFO, logging.WARNING, logging.ERROR,
          logging.CRITICAL)
logger_names = ('myapp', 'myapp.lib1', 'myapp.lib2')
msgno = 1
while True:
    # Just randomly select some loggers and levels and log away
    level = random.choice(levels)
    logger = logging.getLogger(random.choice(logger_names))
    logger.log(level, 'Message no. %5d' % msgno)
    msgno += 1
    delay = random.random() * 2 + 0.5
    time.sleep(delay)

Du kan köra de två ovanstående snuttarna i separata kommandosnäckor. Om vi kör lyssnaren i ett skal och kör avsändaren i två separata skal bör vi se något i stil med följande. I det första avsändarskalet:

$ python avsändare.py
DEBUG myapp 613 Meddelande nr.     1
WARNING myapp.lib2 613 Meddelande nr 2
CRITICAL myapp.lib2 613 Meddelande nr.     3
WARNING myapp.lib2 613 Meddelande nr.     4
CRITICAL myapp.lib1 613 Meddelande nr.     5
DEBUG myapp 613 Meddelande nr.     6
CRITICAL myapp.lib1 613 Meddelande nr.     7
INFO myapp.lib1 613 Meddelande nr.     8
(och så vidare)

I det andra avsändarskalet:

$ python avsändare.py
INFO myapp.lib2 657 Meddelande nr.     1
CRITICAL myapp.lib2 657 Meddelande nr 2
CRITICAL myapp 657 Meddelande nr.     3
CRITICAL myapp.lib1 657 Meddelande nr.     4
INFO myapp.lib1 657 Meddelande nr.     5
WARNING myapp.lib2 657 Meddelande nr.     6
CRITICAL myapp 657 Meddelande nr.     7
DEBUG myapp.lib1 657 Meddelande nr.     8
(och så vidare)

I lyssnarens skal:

$ python lyssnare.py
Tryck Ctrl-C för att stoppa.
DEBUG myapp 613 Meddelande nr.     1
WARNING myapp.lib2 613 Meddelande nr 2
INFO myapp.lib2 657 Meddelande nr.     1
CRITICAL myapp.lib2 613 Meddelande nr.     3
CRITICAL myapp.lib2 657 Meddelande nr 2
CRITICAL myapp 657 Meddelande nr.     3
WARNING myapp.lib2 613 Meddelande nr.     4
CRITICAL myapp.lib1 613 Meddelande nr.     5
CRITICAL myapp.lib1 657 Meddelande nr.     4
INFO myapp.lib1 657 Meddelande nr.     5
DEBUG myapp 613 Meddelande nr.     6
WARNING myapp.lib2 657 Meddelande nr.     6
CRITICAL myapp 657 Meddelande nr.     7
CRITICAL myapp.lib1 613 Meddelande nr.     7
INFO myapp.lib1 613 Meddelande nr.     8
DEBUG myapp.lib1 657 Meddelande nr.     8
(och så vidare)

Som du kan se är loggningen från de två sändarprocesserna sammanflätad i lyssnarens utdata.

Ett exempel på ordboksbaserad konfiguration

Nedan följer ett exempel på en konfigurationsordbok för loggning - den är hämtad från dokumentationen om Django-projektet. Denna ordbok skickas till dictConfig() för att konfigurationen ska träda i kraft:

LOGGING = {
    'version': 1,
    'disable_existing_loggers': False,
    'formaterare': {
        'verbose': {
            'format': '{levelname} {asctime} {module} {process:d} {thread:d} {message}',
            'style': '{',
        },
        'simple': {
            'format': '{levelname} {message}',
            'style': '{',
        },
    },
    'filter': {
        'special': {
            '()': 'project.logging.SpecialFilter',
            'foo': 'bar',
        },
    },
    'hanterare': {
        'console': {
            'level': 'INFO',
            'class': 'logging.StreamHandler',
            'formatter': 'simple',
        },
        'mail_admins': {
            'level': 'ERROR',
            'class': 'django.utils.log.AdminEmailHandler',
            'filter': ['special']
        }
    },
    'loggers': {
        'django': {
            'handlers': ['console'],
            'propagate': True,
        },
        'django.request': {
            'handlers': ['mail_admins'],
            'level': 'ERROR',
            'propagate': False,
        },
        'myproject.custom': {
            'handlers': ['console', 'mail_admins'],
            'level': 'INFO',
            'filter': ['special']
        }
    }
}

För mer information om den här konfigurationen kan du se det relevanta avsnittet i Django-dokumentationen.

Använda en rotator och en namer för att anpassa bearbetningen av loggrotation

Ett exempel på hur du kan definiera en namer och rotator ges i följande runnable-skript, som visar gzip-komprimering av loggfilen:

import gzip
import logging
import logging.handlers
import os
import shutil

def namer(name):
    return name + ".gz"

def rotator(source, dest):
    with open(source, 'rb') as f_in:
        with gzip.open(dest, 'wb') as f_out:
            shutil.copyfileobj(f_in, f_out)
    os.remove(source)


rh = logging.handlers.RotatingFileHandler('rotated.log', maxBytes=128, backupCount=5)
rh.rotator = rotator
rh.namer = namer

root = logging.getLogger()
root.setLevel(logging.INFO)
root.addHandler(rh)
f = logging.Formatter('%(asctime)s %(message)s')
rh.setFormatter(f)
for i in range(1000):
    root.info(f'Message no. {i + 1}')

När du har kört detta kommer du att se sex nya filer, varav fem är komprimerade:

$ ls rotated.log*
rotated.log rotated.log.2.gz rotated.log.4.gz
rotated.log.1.gz rotated.log.3.gz rotated.log.5.gz
$ zcat roterad.log.1.gz
2023-01-20 02:28:17,767 Meddelande nr. 996
2023-01-20 02:28:17,767 Meddelande nr. 997
2023-01-20 02:28:17,767 Meddelande nr. 998

Ett mer avancerat exempel på multiprocessing

Följande arbetsexempel visar hur loggning kan användas med multiprocessing med hjälp av konfigurationsfiler. Konfigurationerna är ganska enkla, men tjänar till att illustrera hur mer komplexa konfigurationer kan implementeras i ett verkligt multiprocessing-scenario.

I exemplet skapar huvudprocessen en lyssnarprocess och några arbetsprocesser. Var och en av huvudprocessen, lyssnaren och arbetarna har tre separata konfigurationer (arbetarna delar alla samma konfiguration). Vi kan se loggning i huvudprocessen, hur arbetarna loggar till en QueueHandler och hur lyssnaren implementerar en QueueListener och en mer komplex loggningskonfiguration, och ordnar så att händelser som tas emot via kön skickas till de hanterare som anges i konfigurationen. Observera att dessa konfigurationer är rent illustrativa, men du bör kunna anpassa detta exempel till ditt eget scenario.

Här är skriptet - dokumentationen och kommentarerna förklarar förhoppningsvis hur det fungerar:

import logging
import logging.config
import logging.handlers
from multiprocessing import Process, Queue, Event, current_process
import os
import random
import time

class MyHandler:
    """
    A simple handler for logging events. It runs in the listener process and
    dispatches events to loggers based on the name in the received record,
    which then get dispatched, by the logging system, to the handlers
    configured for those loggers.
    """

    def handle(self, record):
        if record.name == "root":
            logger = logging.getLogger()
        else:
            logger = logging.getLogger(record.name)

        if logger.isEnabledFor(record.levelno):
            # The process name is transformed just to show that it's the listener
            # doing the logging to files and console
            record.processName = '%s (for %s)' % (current_process().name, record.processName)
            logger.handle(record)

def listener_process(q, stop_event, config):
    """
    This could be done in the main process, but is just done in a separate
    process for illustrative purposes.

    This initialises logging according to the specified configuration,
    starts the listener and waits for the main process to signal completion
    via the event. The listener is then stopped, and the process exits.
    """
    logging.config.dictConfig(config)
    listener = logging.handlers.QueueListener(q, MyHandler())
    listener.start()
    if os.name == 'posix':
        # On POSIX, the setup logger will have been configured in the
        # parent process, but should have been disabled following the
        # dictConfig call.
        # On Windows, since fork isn't used, the setup logger won't
        # exist in the child, so it would be created and the message
        # would appear - hence the "if posix" clause.
        logger = logging.getLogger('setup')
        logger.critical('Should not appear, because of disabled logger ...')
    stop_event.wait()
    listener.stop()

def worker_process(config):
    """
    A number of these are spawned for the purpose of illustration. In
    practice, they could be a heterogeneous bunch of processes rather than
    ones which are identical to each other.

    This initialises logging according to the specified configuration,
    and logs a hundred messages with random levels to randomly selected
    loggers.

    A small sleep is added to allow other processes a chance to run. This
    is not strictly needed, but it mixes the output from the different
    processes a bit more than if it's left out.
    """
    logging.config.dictConfig(config)
    levels = [logging.DEBUG, logging.INFO, logging.WARNING, logging.ERROR,
              logging.CRITICAL]
    loggers = ['foo', 'foo.bar', 'foo.bar.baz',
               'spam', 'spam.ham', 'spam.ham.eggs']
    if os.name == 'posix':
        # On POSIX, the setup logger will have been configured in the
        # parent process, but should have been disabled following the
        # dictConfig call.
        # On Windows, since fork isn't used, the setup logger won't
        # exist in the child, so it would be created and the message
        # would appear - hence the "if posix" clause.
        logger = logging.getLogger('setup')
        logger.critical('Should not appear, because of disabled logger ...')
    for i in range(100):
        lvl = random.choice(levels)
        logger = logging.getLogger(random.choice(loggers))
        logger.log(lvl, 'Message no. %d', i)
        time.sleep(0.01)

def main():
    q = Queue()
    # The main process gets a simple configuration which prints to the console.
    config_initial = {
        'version': 1,
        'handlers': {
            'console': {
                'class': 'logging.StreamHandler',
                'level': 'INFO'
            }
        },
        'root': {
            'handlers': ['console'],
            'level': 'DEBUG'
        }
    }
    # The worker process configuration is just a QueueHandler attached to the
    # root logger, which allows all messages to be sent to the queue.
    # We disable existing loggers to disable the "setup" logger used in the
    # parent process. This is needed on POSIX because the logger will
    # be there in the child following a fork().
    config_worker = {
        'version': 1,
        'disable_existing_loggers': True,
        'handlers': {
            'queue': {
                'class': 'logging.handlers.QueueHandler',
                'queue': q
            }
        },
        'root': {
            'handlers': ['queue'],
            'level': 'DEBUG'
        }
    }
    # The listener process configuration shows that the full flexibility of
    # logging configuration is available to dispatch events to handlers however
    # you want.
    # We disable existing loggers to disable the "setup" logger used in the
    # parent process. This is needed on POSIX because the logger will
    # be there in the child following a fork().
    config_listener = {
        'version': 1,
        'disable_existing_loggers': True,
        'formatters': {
            'detailed': {
                'class': 'logging.Formatter',
                'format': '%(asctime)s %(name)-15s %(levelname)-8s %(processName)-10s %(message)s'
            },
            'simple': {
                'class': 'logging.Formatter',
                'format': '%(name)-15s %(levelname)-8s %(processName)-10s %(message)s'
            }
        },
        'handlers': {
            'console': {
                'class': 'logging.StreamHandler',
                'formatter': 'simple',
                'level': 'INFO'
            },
            'file': {
                'class': 'logging.FileHandler',
                'filename': 'mplog.log',
                'mode': 'w',
                'formatter': 'detailed'
            },
            'foofile': {
                'class': 'logging.FileHandler',
                'filename': 'mplog-foo.log',
                'mode': 'w',
                'formatter': 'detailed'
            },
            'errors': {
                'class': 'logging.FileHandler',
                'filename': 'mplog-errors.log',
                'mode': 'w',
                'formatter': 'detailed',
                'level': 'ERROR'
            }
        },
        'loggers': {
            'foo': {
                'handlers': ['foofile']
            }
        },
        'root': {
            'handlers': ['console', 'file', 'errors'],
            'level': 'DEBUG'
        }
    }
    # Log some initial events, just to show that logging in the parent works
    # normally.
    logging.config.dictConfig(config_initial)
    logger = logging.getLogger('setup')
    logger.info('About to create workers ...')
    workers = []
    for i in range(5):
        wp = Process(target=worker_process, name='worker %d' % (i + 1),
                     args=(config_worker,))
        workers.append(wp)
        wp.start()
        logger.info('Started worker: %s', wp.name)
    logger.info('About to create listener ...')
    stop_event = Event()
    lp = Process(target=listener_process, name='listener',
                 args=(q, stop_event, config_listener))
    lp.start()
    logger.info('Started listener')
    # We now hang around for the workers to finish their work.
    for wp in workers:
        wp.join()
    # Workers all done, listening can now stop.
    # Logging in the parent still works normally.
    logger.info('Telling listener to stop ...')
    stop_event.set()
    lp.join()
    logger.info('All done.')

if __name__ == '__main__':
    main()

Infoga en BOM i meddelanden som skickas till en SysLogHandler

RFC 5424 kräver att ett Unicode-meddelande skickas till en syslog-daemon som en uppsättning byte som har följande struktur: en valfri ren ASCII-komponent, följt av en UTF-8 Byte Order Mark (BOM), följt av Unicode kodad med UTF-8. (Se relevant avsnitt i specifikationen.)

I Python 3.1 lades kod till i SysLogHandler för att infoga en BOM i meddelandet, men tyvärr implementerades den felaktigt, så att BOM:en kom i början av meddelandet och därmed inte tillät någon ren ASCII-komponent att komma före den.

Eftersom detta beteende är trasigt, kommer den felaktiga BOM-insättningskoden att tas bort från Python 3.2.4 och senare. Den ersätts dock inte, och om du vill producera RFC 5424-kompatibla meddelanden som innehåller en BOM, en valfri ren ASCII-sekvens före den och godtycklig Unicode efter den, kodad med UTF-8, måste du göra följande:

1. Bifoga en Formatter-instans till din SysLogHandler-instans, med en formatsträng som:

   "ASCII-avsnitt\ufeffUnicode-avsnitt
   

   Unicode-kodpunkten U+FEFF, när den kodas med UTF-8, kommer att kodas som en UTF-8 BOM – byte-strängen b'\xef\xbb\xbf'.

2. Ersätt ASCII-avsnittet med de platshållare du vill, men se till att de data som visas där efter substitutionen alltid är ASCII (på så sätt förblir de oförändrade efter UTF-8-kodning).

3. Ersätt Unicode-avsnittet med de platshållare du vill; om de data som visas där efter substitutionen innehåller tecken utanför ASCII-området är det okej - de kommer att kodas med UTF-8.

Det formaterade meddelandet kommer att kodas med UTF-8-kodning av SysLogHandler. Om du följer ovanstående regler bör du kunna producera meddelanden som överensstämmer med RFC 5424. Om du inte gör det, kanske loggningen inte klagar, men dina meddelanden kommer inte att vara RFC 5424-kompatibla och din syslog-daemon kan klaga.

Implementering av strukturerad loggning

Även om de flesta loggmeddelanden är avsedda att läsas av människor och därmed inte är maskinellt analyserbara, kan det finnas omständigheter där du vill mata ut meddelanden i ett strukturerat format som kan analyseras av ett program (utan att behöva komplexa reguljära uttryck för att analysera loggmeddelandet). Detta är enkelt att åstadkomma med hjälp av paketet logging. Det finns ett antal sätt att göra detta på, men följande är ett enkelt tillvägagångssätt som använder JSON för att serialisera händelsen på ett maskinparserbart sätt:

import json
import logging

class StructuredMessage:
    def __init__(self, message, /, **kwargs):
        self.message = message
        self.kwargs = kwargs

    def __str__(self):
        return '%s >>> %s' % (self.message, json.dumps(self.kwargs))

_ = StructuredMessage   # optional, to improve readability

logging.basicConfig(level=logging.INFO, format='%(message)s')
logging.info(_('message 1', foo='bar', bar='baz', num=123, fnum=123.456))

Om ovanstående skript körs skrivs det ut:

message 1 >>> {"fnum": 123.456, "num": 123, "bar": "baz", "foo": "bar"}

Observera att ordningen på objekten kan variera beroende på vilken version av Python som används.

Om du behöver mer specialiserad bearbetning kan du använda en anpassad JSON-kodare, som i följande kompletta exempel:

import json
import logging


class Encoder(json.JSONEncoder):
    def default(self, o):
        if isinstance(o, set):
            return tuple(o)
        elif isinstance(o, str):
            return o.encode('unicode_escape').decode('ascii')
        return super().default(o)

class StructuredMessage:
    def __init__(self, message, /, **kwargs):
        self.message = message
        self.kwargs = kwargs

    def __str__(self):
        s = Encoder().encode(self.kwargs)
        return '%s >>> %s' % (self.message, s)

_ = StructuredMessage   # optional, to improve readability

def main():
    logging.basicConfig(level=logging.INFO, format='%(message)s')
    logging.info(_('message 1', set_value={1, 2, 3}, snowman='\u2603'))

if __name__ == '__main__':
    main()

När ovanstående skript körs skrivs det ut:

message 1 >>> {"snowman": "\u2603", "set_value": [1, 2, 3]}

Observera att ordningen på objekten kan variera beroende på vilken version av Python som används.

Anpassa handläggare med dictConfig()

Det finns tillfällen då du vill anpassa logghanterare på särskilda sätt, och om du använder dictConfig() kan du kanske göra detta utan att underklassa. Som ett exempel kan du tänka dig att du kanske vill ange ägandeskapet för en loggfil. På POSIX görs detta enkelt med hjälp av shutil.chown(), men filhanterarna i stdlib har inget inbyggt stöd. Du kan anpassa skapandet av hanterare med hjälp av en vanlig funktion som:

def owned_file_handler(filename, mode='a', encoding=None, owner=None):
    if owner:
        if not os.path.exists(filename):
            open(filename, 'a').close()
        shutil.chown(filename, *owner)
    return logging.FileHandler(filename, mode, encoding)

Du kan sedan ange, i en loggningskonfiguration som skickas till dictConfig(), att en loggningshanterare ska skapas genom att anropa denna funktion:

LOGGING = {
    'version': 1,
    'disable_existing_loggers': False,
    'formaterare': {
        'default': {
            'format': '%(asctime)s %(levelname)s %(name)s %(message)s'
        },
    },
    'hanterare': {
        'fil':{
            # Värdena nedan hämtas från den här ordlistan och används
            # används för att skapa hanteraren, ställa in hanterarens nivå och
            # dess formaterare.
            '()': owned_file_handler,
            'level':'DEBUG',
            'formatter': 'default',
            # Värdena nedan skickas till hanterarens skapare som är anropsbar
            # som nyckelordsargument.
            'owner': ['pulse', 'pulse'],
            'filnamn': 'chowntest.log',
            'mode': 'w',
            'encoding': 'utf-8',
        },
    },
    'root': {
        'handlers': ['file'],
        'level': 'DEBUG',
    },
}

I det här exemplet ställer jag in ägandeskapet med hjälp av användaren och gruppen pulse, bara för illustrationens skull. Sätter ihop det till ett fungerande skript, chowntest.py:

import logging, logging.config, os, shutil

def owned_file_handler(filename, mode='a', encoding=None, owner=None):
    if owner:
        if not os.path.exists(filename):
            open(filename, 'a').close()
        shutil.chown(filename, *owner)
    return logging.FileHandler(filename, mode, encoding)

LOGGING = {
    'version': 1,
    'disable_existing_loggers': False,
    'formatters': {
        'default': {
            'format': '%(asctime)s %(levelname)s %(name)s %(message)s'
        },
    },
    'handlers': {
        'file':{
            # The values below are popped from this dictionary and
            # used to create the handler, set the handler's level and
            # its formatter.
            '()': owned_file_handler,
            'level':'DEBUG',
            'formatter': 'default',
            # The values below are passed to the handler creator callable
            # as keyword arguments.
            'owner': ['pulse', 'pulse'],
            'filename': 'chowntest.log',
            'mode': 'w',
            'encoding': 'utf-8',
        },
    },
    'root': {
        'handlers': ['file'],
        'level': 'DEBUG',
    },
}

logging.config.dictConfig(LOGGING)
logger = logging.getLogger('mylogger')
logger.debug('A debug message')

För att köra detta måste du förmodligen köra som root:

$ sudo python3.3 chowntest.py
$ cat chowntest.log
2013-11-05 09:34:51,128 DEBUG mylogger Ett felsökningsmeddelande
$ ls -l chowntest.log
-rw-r--r-- 1 pulse pulse 55 2013-11-05 09:34 chowntest.log

Observera att det här exemplet använder Python 3.3 eftersom det är där shutil.chown() dyker upp. Detta tillvägagångssätt bör fungera med alla Python-versioner som stöder dictConfig() - nämligen Python 2.7, 3.2 eller senare. Med versioner före 3.3 skulle du behöva implementera den faktiska ägarförändringen med hjälp av t.ex. os.chown().

I praktiken kan den funktion som skapar hanteraren finnas i en verktygsmodul någonstans i projektet. Istället för raden i konfigurationen:

'()': owned_file_handler,

kan du använda t.ex.:

'()': 'ext://project.util.owned_file_handler',

där project.util kan ersättas med det faktiska namnet på det paket där funktionen finns. I ovanstående fungerande skript bör det fungera att använda 'ext://__main__.owned_file_handler'. Här löses den faktiska anropbara funktionen av dictConfig() från ext://-specifikationen.

Detta exempel visar förhoppningsvis också vägen till hur du kan implementera andra typer av filändringar - t.ex. inställning av specifika POSIX-behörighetsbitar - på samma sätt, med hjälp av os.chmod().

Naturligtvis kan metoden också utvidgas till andra typer av hanterare än en FileHandler - till exempel en av de roterande filhanterarna eller en helt annan typ av hanterare.

Använda särskilda formateringsstilar i hela din ansökan

I Python 3.2 fick Formatter en style nyckelordsparameter som, även om standardvärdet är % för bakåtkompatibilitet, tillät specifikationen av { eller $ för att stödja formateringsmetoderna som stöds av str.format() och string.Template. Observera att detta styr formateringen av loggmeddelanden för slutlig utmatning till loggar, och är helt ortogonalt till hur ett enskilt loggmeddelande konstrueras.

Loggningsanrop (debug(), info() etc.) tar endast positionella parametrar för själva loggningsmeddelandet, med nyckelordsparametrar som endast används för att bestämma alternativ för hur loggningsanropet ska hanteras (t.ex. nyckelordsparametern exc_info för att ange att spårningsinformation ska loggas, eller nyckelordsparametern extra för att ange ytterligare kontextuell information som ska läggas till i loggen). Så du kan inte direkt göra loggningsanrop med str.format() eller string.Template syntax, eftersom loggningspaketet internt använder %-formatting för att slå samman formatsträngen och variabelargumenten. Det skulle inte gå att ändra detta och samtidigt bevara bakåtkompatibilitet, eftersom alla loggningsanrop som finns i befintlig kod kommer att använda %-format-strängar.

Det har funnits förslag på att associera formatstilar med specifika loggrar, men det tillvägagångssättet leder också till problem med bakåtkompatibilitet eftersom all befintlig kod kan använda ett visst loggernamn och använda %-formatting.

För att loggning ska fungera interoperabelt mellan tredjepartsbibliotek och din kod måste beslut om formatering fattas på nivån för det enskilda loggningsanropet. Detta öppnar upp för ett par sätt på vilka alternativa formateringsstilar kan tillgodoses.

Använda LogRecord-fabriker

I Python 3.2, tillsammans med Formatter ändringarna som nämns ovan, fick loggningspaketet möjligheten att låta användare ställa in sina egna LogRecord underklasser, med hjälp av setLogRecordFactory() funktionen. Du kan använda detta för att skapa din egen underklass av LogRecord, som gör det rätta genom att åsidosätta getMessage()-metoden. Basklassens implementering av denna metod är där formateringen av msg % args sker, och där du kan ersätta din alternativa formatering; du bör dock vara noga med att stödja alla formateringsstilar och tillåta %-formatting som standard, för att säkerställa interoperabilitet med annan kod. Man bör också vara noga med att anropa str(self.msg), precis som basimplementationen gör.

Se referensdokumentationen för setLogRecordFactory() och LogRecord för mer information.

Använda anpassade meddelandeobjekt

Det finns ett annat, kanske enklare sätt att använda {}- och $-formatering för att konstruera dina individuella loggmeddelanden. Du kanske minns (från Använda godtyckliga objekt som meddelanden) att när du loggar kan du använda ett godtyckligt objekt som formatsträng för meddelandet, och att loggningspaketet anropar str() på det objektet för att få den faktiska formatsträngen. Betrakta följande två klasser:

klass BraceMessage:
    def __init__(self, fmt, /, *args, **kwargs):
        self.fmt = fmt
        self.args = args
        self.kwargs = kwargs

    def __str__(self):
        return self.fmt.format(*self.args, **self.kwargs)

klass DollarMessage:
    def __init__(self, fmt, /, **kwargs):
        self.fmt = fmt
        self.kwargs = kwargs

    def __str__(self):
        från sträng import Template
        return Template(self.fmt).substitute(**self.kwargs)

Båda dessa kan användas i stället för en formatsträng, så att {}- eller $-formatering kan användas för att skapa den faktiska ”message”-delen som visas i den formaterade loggutmatningen i stället för ”%(message)s” eller ”{message}” eller ”$message”. Om du tycker att det är lite krångligt att använda klassnamnen varje gång du vill logga något kan du göra det mer lätthanterligt genom att använda ett alias som M eller _ för meddelandet (eller kanske __, om du använder _ för lokalisering).

Exempel på detta tillvägagångssätt ges nedan. För det första, formatering med str.format():

>>> __ = BraceMessage
>>> print(__('Message with {0} {1}', 2, 'placeholders'))
Message with 2 placeholders
>>> class Point: pass
...
>>> p = Point()
>>> p.x = 0.5
>>> p.y = 0.5
>>> print(__('Message with coordinates: ({point.x:.2f}, {point.y:.2f})', point=p))
Message with coordinates: (0.50, 0.50)

För det andra, formatering med string.Template:

>>> __ = DollarMessage
>>> print(__('Message with $num $what', num=2, what='placeholders'))
Message with 2 placeholders
>>>

En sak att notera är att du inte betalar någon betydande prestandaförlust med det här tillvägagångssättet: den faktiska formateringen sker inte när du gör loggningsanropet, utan när (och om) det loggade meddelandet faktiskt är på väg att matas ut till en logg av en hanterare. Så det enda lite ovanliga som kan göra dig förvirrad är att parenteserna går runt formatsträngen och argumenten, inte bara formatsträngen. Det beror på att __-notationen bara är syntaxsocker för ett anrop av en konstruktor till en av XXXMessage-klasserna som visas ovan.

Konfigurera filter med dictConfig()

Du kan konfigurera filter med hjälp av dictConfig(), även om det kanske inte är uppenbart vid första anblicken hur du gör det (därav detta recept). Eftersom Filter är den enda filterklassen som ingår i standardbiblioteket, och det är osannolikt att den kommer att tillgodose många krav (den finns bara där som en basklass), kommer du vanligtvis att behöva definiera din egen Filter-underklass med en åsidosatt filter()-metod. För att göra detta anger du nyckeln () i konfigurationsordlistan för filtret och anger en anropsbar som ska användas för att skapa filtret (en klass är det mest uppenbara, men du kan ange vilken anropsbar som helst som returnerar en Filter-instans). Här är ett fullständigt exempel:

import logging
import logging.config
import sys

class MyFilter(logging.Filter):
    def __init__(self, param=None):
        self.param = param

    def filter(self, record):
        if self.param is None:
            allow = True
        else:
            allow = self.param not in record.msg
        if allow:
            record.msg = 'changed: ' + record.msg
        return allow

LOGGING = {
    'version': 1,
    'filters': {
        'myfilter': {
            '()': MyFilter,
            'param': 'noshow',
        }
    },
    'handlers': {
        'console': {
            'class': 'logging.StreamHandler',
            'filters': ['myfilter']
        }
    },
    'root': {
        'level': 'DEBUG',
        'handlers': ['console']
    },
}

if __name__ == '__main__':
    logging.config.dictConfig(LOGGING)
    logging.debug('hello')
    logging.debug('hello - noshow')

Det här exemplet visar hur du kan skicka konfigurationsdata till den callable som konstruerar instansen, i form av nyckelordsparametrar. När skriptet ovan körs kommer det att skrivas ut:

ändrat: hej

vilket visar att filtret fungerar som det ska.

Ett par extra punkter att notera:

• Om du inte kan hänvisa till den anropbara direkt i konfigurationen (t.ex. om den finns i en annan modul och du inte kan importera den direkt där konfigurationsordlistan finns) kan du använda formen ext://... som beskrivs i Tillgång till externa objekt. Du kunde till exempel ha använt texten 'ext://__main__.MyFilter' i stället för MyFilter i exemplet ovan.

• Förutom för filter kan den här tekniken också användas för att konfigurera anpassade hanterare och formaterare. Se Användardefinierade objekt för mer information om hur loggning stöder användning av användardefinierade objekt i sin konfiguration, och se det andra kokboksreceptet Anpassa handläggare med dictConfig() ovan.

Anpassad formatering av undantag

Det kan finnas tillfällen då du vill göra en anpassad formatering av undantag - låt oss säga att du vill ha exakt en rad per loggad händelse, även när det finns information om undantag. Du kan göra detta med en anpassad formatteringsklass, som visas i följande exempel:

import logging

class OneLineExceptionFormatter(logging.Formatter):
    def formatException(self, exc_info):
        """
        Format an exception so that it prints on a single line.
        """
        result = super().formatException(exc_info)
        return repr(result)  # or format into one line however you want to

    def format(self, record):
        s = super().format(record)
        if record.exc_text:
            s = s.replace('\n', '') + '|'
        return s

def configure_logging():
    fh = logging.FileHandler('output.txt', 'w')
    f = OneLineExceptionFormatter('%(asctime)s|%(levelname)s|%(message)s|',
                                  '%d/%m/%Y %H:%M:%S')
    fh.setFormatter(f)
    root = logging.getLogger()
    root.setLevel(logging.DEBUG)
    root.addHandler(fh)

def main():
    configure_logging()
    logging.info('Sample message')
    try:
        x = 1 / 0
    except ZeroDivisionError as e:
        logging.exception('ZeroDivisionError: %s', e)

if __name__ == '__main__':
    main()

När detta körs produceras en fil med exakt två rader:

28/01/2015 07:21:23|INFO|Exempelmeddelande|
28/01/2015 07:21:23|ERROR|ZeroDivisionError: division med noll|'Traceback (senaste anropet senast):\n Fil "logtest7.py", rad 30, i main\n x = 1 / 0\nZeroDivisionError: division med noll'|

Även om ovanstående behandling är förenklad, visar den vägen för hur information om undantag kan formateras efter eget tycke och smak. Modulen traceback kan vara till hjälp för mer specialiserade behov.

Tala om loggade meddelanden

Det kan finnas situationer när det är önskvärt att loggmeddelanden återges i ett hörbart snarare än ett synligt format. Detta är lätt att göra om du har text-till-tal-funktionalitet (TTS) tillgänglig i ditt system, även om den inte har en Python-bindning. De flesta TTS-system har ett kommandoradsprogram som du kan köra, och detta kan anropas från en hanterare med subprocess. Det antas här att TTS-kommandoradsprogram inte förväntar sig att interagera med användare eller tar lång tid att slutföra, och att frekvensen av loggade meddelanden inte kommer att vara så hög att användaren översköljs av meddelanden, och att det är acceptabelt att meddelandena läses upp ett i taget snarare än samtidigt, Exempelimplementeringen nedan väntar på att ett meddelande ska läsas upp innan nästa behandlas, och detta kan leda till att andra hanterare får vänta. Här är ett kort exempel som visar tillvägagångssättet, som förutsätter att TTS-paketet espeak är tillgängligt:

import logging
import subprocess
import sys

class TTSHandler(logging.Handler):
    def emit(self, record):
        msg = self.format(record)
        # Speak slowly in a female English voice
        cmd = ['espeak', '-s150', '-ven+f3', msg]
        p = subprocess.Popen(cmd, stdout=subprocess.PIPE,
                             stderr=subprocess.STDOUT)
        # wait for the program to finish
        p.communicate()

def configure_logging():
    h = TTSHandler()
    root = logging.getLogger()
    root.addHandler(h)
    # the default formatter just returns the message
    root.setLevel(logging.DEBUG)

def main():
    logging.info('Hello')
    logging.debug('Goodbye')

if __name__ == '__main__':
    configure_logging()
    sys.exit(main())

När skriptet körs ska det säga ”Hej” och sedan ”Hej då” med en kvinnlig röst.

Ovanstående metod kan naturligtvis anpassas till andra TTS-system och till och med till andra system som kan behandla meddelanden via externa program som körs från en kommandorad.

Buffra loggade meddelanden och skicka ut dem villkorligt

Det kan finnas situationer där du vill logga meddelanden i ett tillfälligt område och bara mata ut dem om ett visst villkor inträffar. Du kanske t.ex. vill börja logga felsökningshändelser i en funktion, och om funktionen slutförs utan fel vill du inte fylla loggen med den samlade felsökningsinformationen, men om det uppstår ett fel vill du att all felsökningsinformation ska matas ut tillsammans med felet.

Här är ett exempel som visar hur du kan göra detta med hjälp av en dekorator för dina funktioner där du vill att loggning ska bete sig på detta sätt. Det använder sig av logging.handlers.MemoryHandler, som tillåter buffring av loggade händelser tills något villkor inträffar, vid vilken tidpunkt de buffrade händelserna flushed - skickas till en annan hanterare (target hanteraren) för bearbetning. Som standard spolas MemoryHandler när dess buffert fylls upp eller en händelse vars nivå är större än eller lika med ett angivet tröskelvärde ses. Du kan använda detta recept med en mer specialiserad subklass av MemoryHandler om du vill ha ett anpassat spolningsbeteende.

Exempelskriptet har en enkel funktion, foo, som bara cyklar genom alla loggningsnivåer, skriver till sys.stderr för att tala om vilken nivå den ska logga på och sedan faktiskt loggar ett meddelande på den nivån. Du kan skicka en parameter till foo som, om den är sann, loggar på nivåerna ERROR och CRITICAL - annars loggar den bara på nivåerna DEBUG, INFO och WARNING.

Skriptet ordnar bara så att foo dekoreras med en dekorator som gör den villkorliga loggning som krävs. Dekoratorn tar en logger som en parameter och kopplar en minneshanterare under hela anropet till den dekorerade funktionen. Dekoratorn kan dessutom parametriseras med hjälp av en målhanterare, en nivå vid vilken rensning ska ske och en kapacitet för bufferten (antal poster som buffras). Dessa är som standard en StreamHandler som skriver till sys.stderr, logging.ERROR respektive 100.

Här är skriptet:

import logging
from logging.handlers import MemoryHandler
import sys

logger = logging.getLogger(__name__)
logger.addHandler(logging.NullHandler())

def log_if_errors(logger, target_handler=None, flush_level=None, capacity=None):
    if target_handler is None:
        target_handler = logging.StreamHandler()
    if flush_level is None:
        flush_level = logging.ERROR
    if capacity is None:
        capacity = 100
    handler = MemoryHandler(capacity, flushLevel=flush_level, target=target_handler)

    def decorator(fn):
        def wrapper(*args, **kwargs):
            logger.addHandler(handler)
            try:
                return fn(*args, **kwargs)
            except Exception:
                logger.exception('call failed')
                raise
            finally:
                super(MemoryHandler, handler).flush()
                logger.removeHandler(handler)
        return wrapper

    return decorator

def write_line(s):
    sys.stderr.write('%s\n' % s)

def foo(fail=False):
    write_line('about to log at DEBUG ...')
    logger.debug('Actually logged at DEBUG')
    write_line('about to log at INFO ...')
    logger.info('Actually logged at INFO')
    write_line('about to log at WARNING ...')
    logger.warning('Actually logged at WARNING')
    if fail:
        write_line('about to log at ERROR ...')
        logger.error('Actually logged at ERROR')
        write_line('about to log at CRITICAL ...')
        logger.critical('Actually logged at CRITICAL')
    return fail

decorated_foo = log_if_errors(logger)(foo)

if __name__ == '__main__':
    logger.setLevel(logging.DEBUG)
    write_line('Calling undecorated foo with False')
    assert not foo(False)
    write_line('Calling undecorated foo with True')
    assert foo(True)
    write_line('Calling decorated foo with False')
    assert not decorated_foo(False)
    write_line('Calling decorated foo with True')
    assert decorated_foo(True)

När detta skript körs bör följande utdata observeras:

Anropar odekorerad foo med False
på väg att logga vid DEBUG ...
på väg att logga vid INFO ...
på väg att logga in på WARNING ...
Anropar odekorerad foo med True
på väg att logga vid DEBUG ...
på väg att logga vid INFO ...
på väg att logga vid WARNING ...
på väg att logga vid ERROR ...
på väg att logga vid CRITICAL ...
Anropar dekorerad foo med False
på väg att logga vid DEBUG ...
på väg att logga vid INFO ...
på väg att logga vid WARNING ...
Anropar dekorerad foo med True
på väg att logga vid DEBUG ...
på väg att logga vid INFO ...
på väg att logga vid WARNING ...
på väg att logga vid ERROR ...
Faktiskt loggat vid DEBUG
Faktiskt loggat vid INFO
Faktiskt loggat vid WARNING
Faktiskt loggat vid ERROR
på väg att logga vid CRITICAL ...
Faktiskt loggat på CRITICAL

Som du kan se sker den faktiska loggningen endast när en händelse loggas vars allvarlighetsgrad är ERROR eller högre, men i så fall loggas även alla tidigare händelser med lägre allvarlighetsgrad.

Du kan naturligtvis använda de konventionella dekorationsmedlen:

@log_if_errors(logger)
def foo(fail=False):
    ...

Skicka loggade meddelanden till e-post, med buffring

För att illustrera hur du kan skicka loggmeddelanden via e-post, så att ett visst antal meddelanden skickas per e-post, kan du underordna dig BufferingHandler. I följande exempel, som du kan anpassa efter dina specifika behov, tillhandahålls ett enkelt testprogram som gör att du kan köra skriptet med kommandoradsargument som anger vad du vanligtvis behöver för att skicka saker via SMTP. (Kör det nedladdade skriptet med argumentet -h för att se vilka argument som krävs och vilka som är valfria)

import logging
import logging.handlers
import smtplib

class BufferingSMTPHandler(logging.handlers.BufferingHandler):
    def __init__(self, mailhost, port, username, password, fromaddr, toaddrs,
                 subject, capacity):
        logging.handlers.BufferingHandler.__init__(self, capacity)
        self.mailhost = mailhost
        self.mailport = port
        self.username = username
        self.password = password
        self.fromaddr = fromaddr
        if isinstance(toaddrs, str):
            toaddrs = [toaddrs]
        self.toaddrs = toaddrs
        self.subject = subject
        self.setFormatter(logging.Formatter("%(asctime)s %(levelname)-5s %(message)s"))

    def flush(self):
        if len(self.buffer) > 0:
            try:
                smtp = smtplib.SMTP(self.mailhost, self.mailport)
                smtp.starttls()
                smtp.login(self.username, self.password)
                msg = "From: %s\r\nTo: %s\r\nSubject: %s\r\n\r\n" % (self.fromaddr, ','.join(self.toaddrs), self.subject)
                for record in self.buffer:
                    s = self.format(record)
                    msg = msg + s + "\r\n"
                smtp.sendmail(self.fromaddr, self.toaddrs, msg)
                smtp.quit()
            except Exception:
                if logging.raiseExceptions:
                    raise
            self.buffer = []

if __name__ == '__main__':
    import argparse

    ap = argparse.ArgumentParser()
    aa = ap.add_argument
    aa('host', metavar='HOST', help='SMTP server')
    aa('--port', '-p', type=int, default=587, help='SMTP port')
    aa('user', metavar='USER', help='SMTP username')
    aa('password', metavar='PASSWORD', help='SMTP password')
    aa('to', metavar='TO', help='Addressee for emails')
    aa('sender', metavar='SENDER', help='Sender email address')
    aa('--subject', '-s',
       default='Test Logging email from Python logging module (buffering)',
       help='Subject of email')
    options = ap.parse_args()
    logger = logging.getLogger()
    logger.setLevel(logging.DEBUG)
    h = BufferingSMTPHandler(options.host, options.port, options.user,
                             options.password, options.sender,
                             options.to, options.subject, 10)
    logger.addHandler(h)
    for i in range(102):
        logger.info("Info index = %d", i)
    h.flush()
    h.close()

Om du kör det här skriptet och din SMTP-server är korrekt konfigurerad, bör du upptäcka att det skickar elva e-postmeddelanden till den adressat du anger. De första tio e-postmeddelandena kommer att innehålla tio loggmeddelanden vardera och det elfte meddelandet kommer att innehålla två meddelanden. Det blir 102 meddelanden enligt vad som anges i skriptet.

Formatering av tider med UTC (GMT) via konfiguration

Ibland vill du formatera tider med UTC, vilket kan göras med hjälp av en klass som UTCFormatter, som visas nedan:

import logging
import time

class UTCFormatter(logging.Formatter):
    converter = time.gmtime

och du kan sedan använda UTCFormatter i din kod istället för Formatter. Om du vill göra det via konfiguration kan du använda API:et dictConfig() med ett tillvägagångssätt som illustreras av följande fullständiga exempel:

import logging
import logging.config
import time

class UTCFormatter(logging.Formatter):
    converter = time.gmtime

LOGGING = {
    'version': 1,
    'disable_existing_loggers': False,
    'formatters': {
        'utc': {
            '()': UTCFormatter,
            'format': '%(asctime)s %(message)s',
        },
        'local': {
            'format': '%(asctime)s %(message)s',
        }
    },
    'handlers': {
        'console1': {
            'class': 'logging.StreamHandler',
            'formatter': 'utc',
        },
        'console2': {
            'class': 'logging.StreamHandler',
            'formatter': 'local',
        },
    },
    'root': {
        'handlers': ['console1', 'console2'],
   }
}

if __name__ == '__main__':
    logging.config.dictConfig(LOGGING)
    logging.warning('The local time is %s', time.asctime())

När detta skript körs bör det skriva ut något liknande:

2015-10-17 12:53:29,501 Den lokala tiden är Sat Oct 17 13:53:29 2015
2015-10-17 13:53:29,501 Den lokala tiden är Sat Oct 17 13:53:29 2015

som visar hur tiden formateras både som lokal tid och UTC, en för varje hanterare.

Använda en kontexthanterare för selektiv loggning

Det finns tillfällen då det skulle vara användbart att tillfälligt ändra loggningskonfigurationen och återgå till den efter att ha gjort något. För detta ändamål är en kontexthanterare det mest uppenbara sättet att spara och återställa loggningskontexten. Här är ett enkelt exempel på en sådan kontexthanterare, som gör att du kan ändra loggningsnivån och lägga till en loggningshanterare enbart i kontexthanterarens omfattning:

import logging
import sys

class LoggingContext:
    def __init__(self, logger, level=None, handler=None, close=True):
        self.logger = logger
        self.level = level
        self.handler = handler
        self.close = close

    def __enter__(self):
        if self.level is not None:
            self.old_level = self.logger.level
            self.logger.setLevel(self.level)
        if self.handler:
            self.logger.addHandler(self.handler)

    def __exit__(self, et, ev, tb):
        if self.level is not None:
            self.logger.setLevel(self.old_level)
        if self.handler:
            self.logger.removeHandler(self.handler)
        if self.handler and self.close:
            self.handler.close()
        # implicit return of None => don't swallow exceptions

Om du anger ett nivåvärde sätts loggarens nivå till det värdet inom ramen för det with-block som omfattas av kontexthanteraren. Om du anger en hanterare läggs den till i loggern när den kommer in i blocket och tas bort när den lämnar blocket. Du kan också be hanteraren att stänga hanteraren åt dig när du lämnar blocket - det kan du göra om du inte behöver hanteraren längre.

För att illustrera hur det fungerar kan vi lägga till följande kodblock till ovanstående:

if __name__ == '__main__':
    logger = logging.getLogger('foo')
    logger.addHandler(logging.StreamHandler())
    logger.setLevel(logging.INFO)
    logger.info('1. Detta ska bara visas en gång på stderr.')
    logger.debug('2. Det här ska inte visas.')
    med LoggingContext(logger, level=logging.DEBUG):
        logger.debug('3. Detta ska visas en gång på stderr.')
    logger.debug('4. Det här ska inte visas.')
    h = loggning.StreamHandler(sys.stdout)
    med LoggingContext(logger, level=logging.DEBUG, handler=h, close=True):
        logger.debug('5. Detta ska visas två gånger - en gång på stderr och en gång på stdout.')
    logger.info('6. Det här ska bara visas en gång på stderr.')
    logger.debug('7. Det här ska inte visas.')

Vi ställer in loggarens nivå till INFO, så meddelande nr 1 visas och meddelande nr 2 visas inte. Vi ändrar sedan nivån till DEBUG tillfälligt i följande with -block, så meddelande nr 3 visas. När blocket avslutas återställs loggarens nivå till INFO, så meddelande nr 4 visas inte. I nästa with -block ställer vi in nivån till DEBUG igen, men lägger också till en hanterare som skriver till sys.stdout. Därför visas meddelande nr 5 två gånger på konsolen (en gång via stderr och en gång via stdout). Efter att with-satsen har slutförts är statusen densamma som tidigare, så meddelande nr 6 visas (precis som meddelande nr 1), medan meddelande nr 7 inte visas (precis som meddelande nr 2).

Om vi kör det resulterande skriptet blir resultatet som följer:

$ python logctx.py
1. Detta ska bara visas en gång på stderr.
3. Detta ska visas en gång på stderr.
5. Det här ska visas två gånger - en gång på stderr och en gång på stdout.
5. Detta ska visas två gånger - en gång på stderr och en gång på stdout.
6. Detta borde visas bara en gång på stderr.

Om vi kör det igen, men pipar stderr till /dev/null, ser vi följande, vilket är det enda meddelandet som skrivs till stdout:

$ python logctx.py 2>/dev/null
5. Detta ska visas två gånger - en gång på stderr och en gång på stdout.

Återigen, men genom att pipa stdout till /dev/null får vi:

$ python logctx.py >/dev/null
1. Detta ska bara visas en gång på stderr.
3. Detta ska visas en gång på stderr.
5. Det här ska visas två gånger - en gång på stderr och en gång på stdout.
6. Det här ska bara visas en gång på stderr.

I det här fallet visas inte meddelandet #5 som skrivs ut till stdout, som förväntat.

Naturligtvis kan den metod som beskrivs här generaliseras, till exempel för att koppla loggningsfilter temporärt. Observera att ovanstående kod fungerar i Python 2 såväl som Python 3.

En startmall för CLI-applikationer

Här är ett exempel som visar hur du kan göra det:

• Använd en loggningsnivå som baseras på kommandoradsargument

• Utskick till flera underkommandon i separata filer, alla loggar på samma nivå på ett konsekvent sätt

• Använd enkel och minimal konfiguration

Anta att vi har en kommandoradsapplikation vars uppgift är att stoppa, starta eller starta om vissa tjänster. Detta skulle kunna organiseras som en fil app.py som är huvudskriptet för applikationen, med individuella kommandon implementerade i start.py, stop.py och restart.py. Anta vidare att vi vill kontrollera programmets ordrikedom via ett kommandoradsargument, som standard till logging.INFO. Här är ett sätt som app.py skulle kunna skrivas på:

import argparse
import importlib
import logging
import os
import sys

def main(args=None):
    scriptname = os.path.basename(__file__)
    parser = argparse.ArgumentParser(scriptname)
    levels = ('DEBUG', 'INFO', 'WARNING', 'ERROR', 'CRITICAL')
    parser.add_argument('--log-level', default='INFO', choices=levels)
    subparsers = parser.add_subparsers(dest='command',
                                       help='Available commands:')
    start_cmd = subparsers.add_parser('start', help='Start a service')
    start_cmd.add_argument('name', metavar='NAME',
                           help='Name of service to start')
    stop_cmd = subparsers.add_parser('stop',
                                     help='Stop one or more services')
    stop_cmd.add_argument('names', metavar='NAME', nargs='+',
                          help='Name of service to stop')
    restart_cmd = subparsers.add_parser('restart',
                                        help='Restart one or more services')
    restart_cmd.add_argument('names', metavar='NAME', nargs='+',
                             help='Name of service to restart')
    options = parser.parse_args()
    # the code to dispatch commands could all be in this file. For the purposes
    # of illustration only, we implement each command in a separate module.
    try:
        mod = importlib.import_module(options.command)
        cmd = getattr(mod, 'command')
    except (ImportError, AttributeError):
        print('Unable to find the code for command \'%s\'' % options.command)
        return 1
    # Could get fancy here and load configuration from file or dictionary
    logging.basicConfig(level=options.log_level,
                        format='%(levelname)s %(name)s %(message)s')
    cmd(options)

if __name__ == '__main__':
    sys.exit(main())

Och kommandona start, stop och restart kan implementeras i separata moduler, så här för att starta:

# start.py
import logging

logger = logging.getLogger(__name__)

def command(options):
    logger.debug('About to start %s', options.name)
    # actually do the command processing here ...
    logger.info('Started the \'%s\' service.', options.name)

och därmed för att stoppa:

# stop.py
import logging

logger = logging.getLogger(__name__)

def command(options):
    n = len(options.names)
    if n == 1:
        plural = ''
        services = '\'%s\'' % options.names[0]
    else:
        plural = 's'
        services = ', '.join('\'%s\'' % name for name in options.names)
        i = services.rfind(', ')
        services = services[:i] + ' and ' + services[i + 2:]
    logger.debug('About to stop %s', services)
    # actually do the command processing here ...
    logger.info('Stopped the %s service%s.', services, plural)

och på samma sätt för omstart:

# restart.py
import logging

logger = logging.getLogger(__name__)

def command(options):
    n = len(options.names)
    if n == 1:
        plural = ''
        services = '\'%s\'' % options.names[0]
    else:
        plural = 's'
        services = ', '.join('\'%s\'' % name for name in options.names)
        i = services.rfind(', ')
        services = services[:i] + ' and ' + services[i + 2:]
    logger.debug('About to restart %s', services)
    # actually do the command processing here ...
    logger.info('Restarted the %s service%s.', services, plural)

Om vi kör den här applikationen med standardloggnivån får vi utdata som denna:

$ python app.py start foo
INFO start Startade tjänsten "foo".

$ python app.py stop foo bar
INFO stop Stoppade tjänsterna 'foo' och 'bar'.

$ python app.py restart foo bar baz
INFO restart Startade om tjänsterna 'foo', 'bar' och 'baz'.

Det första ordet är loggningsnivån och det andra ordet är modul- eller paketnamnet på den plats där händelsen loggades.

Om vi ändrar loggningsnivån kan vi ändra den information som skickas till loggen. Till exempel om vi vill ha mer information:

$ python app.py --log-nivå DEBUG start foo
DEBUG start På väg att starta foo
INFO start Startade tjänsten "foo".

$ python app.py --log-nivå DEBUG stoppa foo bar
DEBUG stop På väg att stoppa 'foo' och 'bar'
INFO stop Stoppade tjänsterna 'foo' och 'bar'.

$ python app.py --log-nivå DEBUG omstart foo bar baz
DEBUG restart På väg att starta om 'foo', 'bar' och 'baz'
INFO restart Startade om tjänsterna 'foo', 'bar' och 'baz'.

Och om vi vill ha mindre:

$ python app.py --log-nivå VARNING start foo
$ python app.py --log-nivå WARNING stopp foo bar
$ python app.py --log-nivå WARNING starta om foo bar baz

I det här fallet skriver kommandona inte ut något till konsolen, eftersom inget på nivån WARNING eller högre loggas av dem.

Ett Qt GUI för loggning

En fråga som dyker upp då och då handlar om hur man loggar in i en GUI-applikation. Ramverket Qt är ett populärt gränssnittsramverk för flera plattformar med Python-bindningar som använder biblioteken PySide2 eller PyQt5.

Följande exempel visar hur man loggar till ett Qt GUI. Detta introducerar en enkel QtHandler klass som tar en callable, som bör vara en slot i huvudtråden som gör GUI uppdateringar. En arbetstråd skapas också för att visa hur du kan logga till GUI:t från både själva GUI:t (via en knapp för manuell loggning) och en arbetstråd som gör arbete i bakgrunden (här loggas bara meddelanden på slumpmässiga nivåer med slumpmässiga korta fördröjningar däremellan).

Arbetstråden implementeras med hjälp av Qts klass QThread snarare än modulen threading`, eftersom det finns omständigheter där man måste använda QThread, som erbjuder bättre integration med andra Qt-komponenter.

Koden ska fungera med de senaste versionerna av någon av PySide6, PyQt6, PySide2 eller PyQt5. Du bör kunna anpassa tillvägagångssättet till tidigare versioner av Qt. För mer detaljerad information hänvisas till kommentarerna i kodavsnittet.

import datetime
import logging
import random
import sys
import time

# Deal with minor differences between different Qt packages
try:
    from PySide6 import QtCore, QtGui, QtWidgets
    Signal = QtCore.Signal
    Slot = QtCore.Slot
except ImportError:
    try:
        from PyQt6 import QtCore, QtGui, QtWidgets
        Signal = QtCore.pyqtSignal
        Slot = QtCore.pyqtSlot
    except ImportError:
        try:
            from PySide2 import QtCore, QtGui, QtWidgets
            Signal = QtCore.Signal
            Slot = QtCore.Slot
        except ImportError:
            from PyQt5 import QtCore, QtGui, QtWidgets
            Signal = QtCore.pyqtSignal
            Slot = QtCore.pyqtSlot

logger = logging.getLogger(__name__)


#
# Signals need to be contained in a QObject or subclass in order to be correctly
# initialized.
#
class Signaller(QtCore.QObject):
    signal = Signal(str, logging.LogRecord)

#
# Output to a Qt GUI is only supposed to happen on the main thread. So, this
# handler is designed to take a slot function which is set up to run in the main
# thread. In this example, the function takes a string argument which is a
# formatted log message, and the log record which generated it. The formatted
# string is just a convenience - you could format a string for output any way
# you like in the slot function itself.
#
# You specify the slot function to do whatever GUI updates you want. The handler
# doesn't know or care about specific UI elements.
#
class QtHandler(logging.Handler):
    def __init__(self, slotfunc, *args, **kwargs):
        super().__init__(*args, **kwargs)
        self.signaller = Signaller()
        self.signaller.signal.connect(slotfunc)

    def emit(self, record):
        s = self.format(record)
        self.signaller.signal.emit(s, record)

#
# This example uses QThreads, which means that the threads at the Python level
# are named something like "Dummy-1". The function below gets the Qt name of the
# current thread.
#
def ctname():
    return QtCore.QThread.currentThread().objectName()


#
# Used to generate random levels for logging.
#
LEVELS = (logging.DEBUG, logging.INFO, logging.WARNING, logging.ERROR,
          logging.CRITICAL)

#
# This worker class represents work that is done in a thread separate to the
# main thread. The way the thread is kicked off to do work is via a button press
# that connects to a slot in the worker.
#
# Because the default threadName value in the LogRecord isn't much use, we add
# a qThreadName which contains the QThread name as computed above, and pass that
# value in an "extra" dictionary which is used to update the LogRecord with the
# QThread name.
#
# This example worker just outputs messages sequentially, interspersed with
# random delays of the order of a few seconds.
#
class Worker(QtCore.QObject):
    @Slot()
    def start(self):
        extra = {'qThreadName': ctname() }
        logger.debug('Started work', extra=extra)
        i = 1
        # Let the thread run until interrupted. This allows reasonably clean
        # thread termination.
        while not QtCore.QThread.currentThread().isInterruptionRequested():
            delay = 0.5 + random.random() * 2
            time.sleep(delay)
            try:
                if random.random() < 0.1:
                    raise ValueError('Exception raised: %d' % i)
                else:
                    level = random.choice(LEVELS)
                    logger.log(level, 'Message after delay of %3.1f: %d', delay, i, extra=extra)
            except ValueError as e:
                logger.exception('Failed: %s', e, extra=extra)
            i += 1

#
# Implement a simple UI for this cookbook example. This contains:
#
# * A read-only text edit window which holds formatted log messages
# * A button to start work and log stuff in a separate thread
# * A button to log something from the main thread
# * A button to clear the log window
#
class Window(QtWidgets.QWidget):

    COLORS = {
        logging.DEBUG: 'black',
        logging.INFO: 'blue',
        logging.WARNING: 'orange',
        logging.ERROR: 'red',
        logging.CRITICAL: 'purple',
    }

    def __init__(self, app):
        super().__init__()
        self.app = app
        self.textedit = te = QtWidgets.QPlainTextEdit(self)
        # Set whatever the default monospace font is for the platform
        f = QtGui.QFont('nosuchfont')
        if hasattr(f, 'Monospace'):
            f.setStyleHint(f.Monospace)
        else:
            f.setStyleHint(f.StyleHint.Monospace)  # for Qt6
        te.setFont(f)
        te.setReadOnly(True)
        PB = QtWidgets.QPushButton
        self.work_button = PB('Start background work', self)
        self.log_button = PB('Log a message at a random level', self)
        self.clear_button = PB('Clear log window', self)
        self.handler = h = QtHandler(self.update_status)
        # Remember to use qThreadName rather than threadName in the format string.
        fs = '%(asctime)s %(qThreadName)-12s %(levelname)-8s %(message)s'
        formatter = logging.Formatter(fs)
        h.setFormatter(formatter)
        logger.addHandler(h)
        # Set up to terminate the QThread when we exit
        app.aboutToQuit.connect(self.force_quit)

        # Lay out all the widgets
        layout = QtWidgets.QVBoxLayout(self)
        layout.addWidget(te)
        layout.addWidget(self.work_button)
        layout.addWidget(self.log_button)
        layout.addWidget(self.clear_button)
        self.setFixedSize(900, 400)

        # Connect the non-worker slots and signals
        self.log_button.clicked.connect(self.manual_update)
        self.clear_button.clicked.connect(self.clear_display)

        # Start a new worker thread and connect the slots for the worker
        self.start_thread()
        self.work_button.clicked.connect(self.worker.start)
        # Once started, the button should be disabled
        self.work_button.clicked.connect(lambda : self.work_button.setEnabled(False))

    def start_thread(self):
        self.worker = Worker()
        self.worker_thread = QtCore.QThread()
        self.worker.setObjectName('Worker')
        self.worker_thread.setObjectName('WorkerThread')  # for qThreadName
        self.worker.moveToThread(self.worker_thread)
        # This will start an event loop in the worker thread
        self.worker_thread.start()

    def kill_thread(self):
        # Just tell the worker to stop, then tell it to quit and wait for that
        # to happen
        self.worker_thread.requestInterruption()
        if self.worker_thread.isRunning():
            self.worker_thread.quit()
            self.worker_thread.wait()
        else:
            print('worker has already exited.')

    def force_quit(self):
        # For use when the window is closed
        if self.worker_thread.isRunning():
            self.kill_thread()

    # The functions below update the UI and run in the main thread because
    # that's where the slots are set up

    @Slot(str, logging.LogRecord)
    def update_status(self, status, record):
        color = self.COLORS.get(record.levelno, 'black')
        s = '<pre><font color="%s">%s</font></pre>' % (color, status)
        self.textedit.appendHtml(s)

    @Slot()
    def manual_update(self):
        # This function uses the formatted message passed in, but also uses
        # information from the record to format the message in an appropriate
        # color according to its severity (level).
        level = random.choice(LEVELS)
        extra = {'qThreadName': ctname() }
        logger.log(level, 'Manually logged!', extra=extra)

    @Slot()
    def clear_display(self):
        self.textedit.clear()


def main():
    QtCore.QThread.currentThread().setObjectName('MainThread')
    logging.getLogger().setLevel(logging.DEBUG)
    app = QtWidgets.QApplication(sys.argv)
    example = Window(app)
    example.show()
    if hasattr(app, 'exec'):
        rc = app.exec()
    else:
        rc = app.exec_()
    sys.exit(rc)

if __name__=='__main__':
    main()

Loggning till syslog med stöd för RFC5424

Även om RFC 5424 är från 2009, är de flesta syslog-servrar konfigurerade som standard att använda det äldre RFC 3164, som är från 2001. När logging lades till i Python 2003 stödde det det tidigare (och enda existerande) protokollet vid den tiden. Sedan RFC5424 kom ut, eftersom det inte har varit någon utbredd användning av det i syslog-servrar, har SysLogHandler-funktionaliteten inte uppdaterats.

RFC 5424 innehåller en del användbara funktioner som t.ex. stöd för strukturerad data, och om man behöver kunna logga till en syslog-server med stöd för detta kan man göra det med en underklassad hanterare som ser ut ungefär så här:

import datetime
import logging.handlers
import re
import socket
import time

class SysLogHandler5424(logging.handlers.SysLogHandler):

    tz_offset = re.compile(r'([+-]\d{2})(\d{2})$')
    escaped = re.compile(r'([\]"\\])')

    def __init__(self, *args, **kwargs):
        self.msgid = kwargs.pop('msgid', None)
        self.appname = kwargs.pop('appname', None)
        super().__init__(*args, **kwargs)

    def format(self, record):
        version = 1
        asctime = datetime.datetime.fromtimestamp(record.created).isoformat()
        m = self.tz_offset.match(time.strftime('%z'))
        has_offset = False
        if m and time.timezone:
            hrs, mins = m.groups()
            if int(hrs) or int(mins):
                has_offset = True
        if not has_offset:
            asctime += 'Z'
        else:
            asctime += f'{hrs}:{mins}'
        try:
            hostname = socket.gethostname()
        except Exception:
            hostname = '-'
        appname = self.appname or '-'
        procid = record.process
        msgid = '-'
        msg = super().format(record)
        sdata = '-'
        if hasattr(record, 'structured_data'):
            sd = record.structured_data
            # This should be a dict where the keys are SD-ID and the value is a
            # dict mapping PARAM-NAME to PARAM-VALUE (refer to the RFC for what these
            # mean)
            # There's no error checking here - it's purely for illustration, and you
            # can adapt this code for use in production environments
            parts = []

            def replacer(m):
                g = m.groups()
                return '\\' + g[0]

            for sdid, dv in sd.items():
                part = f'[{sdid}'
                for k, v in dv.items():
                    s = str(v)
                    s = self.escaped.sub(replacer, s)
                    part += f' {k}="{s}"'
                part += ']'
                parts.append(part)
            sdata = ''.join(parts)
        return f'{version} {asctime} {hostname} {appname} {procid} {msgid} {sdata} {msg}'

Du måste känna till RFC 5424 för att förstå ovanstående kod fullt ut, och det kan hända att du har något annorlunda behov (t.ex. för hur du skickar strukturella data till loggen). Ovanstående bör dock vara anpassningsbart till dina specifika behov. Med ovanstående hanterare skulle du skicka strukturerad data med något liknande detta:

sd = {
    "foo@12345": {'bar': 'baz', 'baz': 'bozz', 'fizz': r'buzz'},
    'foo@54321': {'rab': 'baz', 'zab': 'bozz', 'zzif': r'buzz'}
}
extra = {'structured_data': sd}
i = 1
logger.debug('Meddelande %d', i, extra=extra)

Så här behandlar du en logger som en utdataström

Ibland behöver du ett gränssnitt mot ett API från tredje part som förväntar sig ett filliknande objekt att skriva till, men du vill rikta API:ets utdata till en logger. Du kan göra detta med hjälp av en klass som omsluter en logger med ett filliknande API. Här är ett kort skript som illustrerar en sådan klass:

import logging

class LoggerWriter:
    def __init__(self, logger, level):
        self.logger = logger
        self.level = level

    def write(self, message):
        if message != '\n':  # avoid printing bare newlines, if you like
            self.logger.log(self.level, message)

    def flush(self):
        # doesn't actually do anything, but might be expected of a file-like
        # object - so optional depending on your situation
        pass

    def close(self):
        # doesn't actually do anything, but might be expected of a file-like
        # object - so optional depending on your situation. You might want
        # to set a flag so that later calls to write raise an exception
        pass

def main():
    logging.basicConfig(level=logging.DEBUG)
    logger = logging.getLogger('demo')
    info_fp = LoggerWriter(logger, logging.INFO)
    debug_fp = LoggerWriter(logger, logging.DEBUG)
    print('An INFO message', file=info_fp)
    print('A DEBUG message', file=debug_fp)

if __name__ == "__main__":
    main()

När detta skript körs skriver det ut

INFO:demo:Ett INFO-meddelande
DEBUG:demo:Ett DEBUG-meddelande

Du kan också använda LoggerWriter för att omdirigera sys.stdout och sys.stderr genom att göra något liknande:

import sys

sys.stdout = LoggerWriter(logger, logging.INFO)
sys.stderr = LoggerWriter(logger, logging.WARNING)

Du bör göra detta efter att du har konfigurerat loggning för dina behov. I exemplet ovan gör anropet basicConfig() detta (genom att använda värdet sys.stderr innan det skrivs över av en LoggerWriter-instans). Då skulle du få den här typen av resultat:

>>> print('Foo')
INFO:demo:Foo
>>> print('Bar', file=sys.stderr)
WARNING:demo:Bar
>>>

Exemplen ovan visar naturligtvis utdata enligt det format som används av basicConfig(), men du kan använda ett annat format när du konfigurerar loggning.

Observera att med ovanstående schema är du något utlämnad till buffring och sekvensen av skrivanrop som du fångar upp. Till exempel, med definitionen av LoggerWriter ovan, om du har utdraget

sys.stderr = LoggerWriter(logger, logging.WARNING)
1 / 0

och sedan kör skriptet resulterar i

WARNING:demo:Traceback (senaste anropet senast):

WARNING:demo:  Fil "/home/runner/cookbook-loggerwriter/test.py", rad 53, i <module>

WARNING:demo:
WARNING:demo:main()
WARNING:demo:  File "/home/runner/cookbook-loggerwriter/test.py", line 49, in main

WARNING:demo:
VARNING:demo:1 / 0
VARNING:demo:NollDivisionsFel
WARNING:demo::
WARNING:demo:division med noll

Som du kan se är den här utskriften inte idealisk. Det beror på att den underliggande koden som skriver till sys.stderr gör flera skrivningar, som var och en resulterar i en separat loggad rad (till exempel de tre sista raderna ovan). För att komma runt det här problemet måste du buffra saker och ting och bara mata ut loggrader när nya rader ses. Låt oss använda en något bättre implementering av LoggerWriter:

klass BufferingLoggerWriter(LoggerWriter):
    def __init__(self, logger, level):
        super().__init__(logger, nivå)
        self.buffer = ''

    def write(self, meddelande):
        om '\n' inte finns i meddelandet:
            self.buffer += meddelande
        else:
            delar = meddelande.split('\n')
            om self.buffer:
                s = self.buffert + delar.pop(0)
                self.logger.log(self.level, s)
            self.buffer = parts.pop()
            för part i parts:
                self.logger.log(self.level, part)

Detta buffrar bara upp saker tills en ny rad ses och loggar sedan hela rader. Med det här tillvägagångssättet får du bättre utdata:

WARNING:demo:Traceback (senaste anropet senast):
WARNING:demo:  Fil "/home/runner/cookbook-loggerwriter/main.py", rad 55, i <module>
WARNING:demo: huvud()
WARNING:demo:  Fil "/home/runner/cookbook-loggerwriter/main.py", rad 52, i main
VARNING:demo:    1/0
WARNING:demo:ZeroDivisionError: division med noll

Hur man hanterar nya linjer i loggningsutdata på ett enhetligt sätt

Vanligtvis består meddelanden som loggas (t.ex. till konsolen eller en fil) av en enda textrad. Ibland finns det dock ett behov av att hantera meddelanden med flera rader - antingen för att en loggningsformatsträng innehåller nya rader eller för att loggade data innehåller nya rader. Om du vill hantera sådana meddelanden enhetligt, så att varje rad i det loggade meddelandet visas enhetligt formaterad som om den loggades separat, kan du göra detta med hjälp av en hanterarmixin, som i följande utdrag:

# Assume this is in a module mymixins.py
import copy

class MultilineMixin:
    def emit(self, record):
        s = record.getMessage()
        if '\n' not in s:
            super().emit(record)
        else:
            lines = s.splitlines()
            rec = copy.copy(record)
            rec.args = None
            for line in lines:
                rec.msg = line
                super().emit(rec)

Du kan använda mixin på samma sätt som i följande skript:

import logging

from mymixins import MultilineMixin

logger = logging.getLogger(__name__)

class StreamHandler(MultilineMixin, logging.StreamHandler):
    pass

if __name__ == '__main__':
    logging.basicConfig(level=logging.DEBUG, format='%(asctime)s %(levelname)-9s %(message)s',
                        handlers = [StreamHandler()])
    logger.debug('Single line')
    logger.debug('Multiple lines:\nfool me once ...')
    logger.debug('Another single line')
    logger.debug('Multiple lines:\n%s', 'fool me ...\ncan\'t get fooled again')

Skriptet, när det körs, skriver ut något liknande:

2025-07-02 13:54:47,234 DEBUG Enkel rad
2025-07-02 13:54:47,234 DEBUG Flera rader:
2025-07-02 13:54:47,234 DEBUG lura mig en gång ...
2025-07-02 13:54:47,234 DEBUG Ytterligare en enkel rad
2025-07-02 13:54:47,234 DEBUG Flera rader:
2025-07-02 13:54:47,234 DEBUG lura mig ...
2025-07-02 13:54:47,234 DEBUG kan inte bli lurad igen

Om du å andra sidan är orolig för log injection kan du använda en formaterare som undviker nya linjer, enligt följande exempel:

import logging

logger = logging.getLogger(__name__)

class EscapingFormatter(logging.Formatter):
    def format(self, record):
        s = super().format(record)
        return s.replace('\n', r'\n')

if __name__ == '__main__':
    h = logging.StreamHandler()
    h.setFormatter(EscapingFormatter('%(asctime)s %(levelname)-9s %(message)s'))
    logging.basicConfig(level=logging.DEBUG, handlers = [h])
    logger.debug('Single line')
    logger.debug('Multiple lines:\nfool me once ...')
    logger.debug('Another single line')
    logger.debug('Multiple lines:\n%s', 'fool me ...\ncan\'t get fooled again')

Du kan naturligtvis använda det escapeschema som är mest meningsfullt för dig. När skriptet körs bör det ge utdata som denna:

2025-07-09 06:47:33,783 DEBUG Enkel rad
2025-07-09 06:47:33,783 DEBUG Flera rader:\nfool me once ...
2025-07-09 06:47:33,783 DEBUG Ytterligare en enkel rad
2025-07-09 06:47:33,783 DEBUG Flera rader:\nlura mig ...\kan inte bli lurad igen

Escaping-beteendet kan inte vara standard i stdlib, eftersom det skulle bryta bakåtkompatibiliteten.

Mönster att undvika

Även om de föregående avsnitten har beskrivit olika sätt att göra saker som du kan behöva göra eller hantera, är det värt att nämna några användningsmönster som är onyttiga och som därför bör undvikas i de flesta fall. Följande avsnitt är inte i någon särskild ordning.

Öppna samma loggfil flera gånger

På Windows kan du i allmänhet inte öppna samma fil flera gånger eftersom det leder till felet ”filen används av en annan process”. På POSIX-plattformar får du dock inga felmeddelanden om du öppnar samma fil flera gånger. Detta kan göras av misstag, till exempel genom att:

• Lägga till en filhanterare mer än en gång som refererar till samma fil (t.ex. genom ett kopiera/klistra in/glöm-att-ändra-fel).

• Öppnar två filer som ser olika ut eftersom de har olika namn, men som är likadana eftersom den ena är en symbolisk länk till den andra.

• Förgrening av en process, varefter både förälder och barn har en referens till samma fil. Detta kan till exempel ske genom användning av modulen multiprocessing.

Att öppna en fil flera gånger kan se ut att fungera för det mesta, men kan leda till ett antal problem i praktiken:

• Loggningsutdata kan bli förvrängda om flera trådar eller processer försöker skriva till samma fil. Även om loggning skyddar mot samtidig användning av samma hanterarinstans av flera trådar, finns det inget sådant skydd om samtidiga skrivförsök görs av två olika trådar som använder två olika hanterarinstanser som råkar peka på samma fil.

• Ett försök att radera en fil (t.ex. under filrotation) misslyckas i tysthet, eftersom det finns en annan referens som pekar på den. Detta kan leda till förvirring och bortkastad felsökningstid - loggposter hamnar på oväntade ställen eller försvinner helt och hållet. Eller så blir en fil som skulle ha flyttats kvar på sin plats och växer oväntat i storlek trots att storleksbaserad rotation skulle ha varit på plats.

Använd de tekniker som beskrivs i Loggning till en enda fil från flera processer för att kringgå sådana problem.

Använda loggrar som attribut i en klass eller skicka dem som parametrar

Även om det kan finnas ovanliga fall där du behöver göra detta, är det i allmänhet ingen mening eftersom loggar är singletons. Koden kan alltid komma åt en viss loggarinstans med namn med hjälp av logging.getLogger(name), så det är meningslöst att skicka runt instanser och hålla dem som instansattribut. Observera att i andra språk som Java och C# är loggar ofta statiska klassattribut. Det här mönstret är dock inte meningsfullt i Python, där modulen (och inte klassen) är enheten för nedbrytning av programvara.

Lägga till andra hanterare än NullHandler till en logger i ett bibliotek

Ansvaret för att konfigurera loggning genom att lägga till hanterare, formaterare och filter ligger hos programutvecklaren, inte hos biblioteksutvecklaren. Om du underhåller ett bibliotek ska du se till att du inte lägger till hanterare till någon av dina loggrar annat än en NullHandler-instans.

Skapar en hel del loggers

Loggrar är singletons som aldrig frigörs under en skriptexekvering, och om du skapar många loggrar kommer det att ta upp minne som sedan inte kan frigöras. I stället för att skapa en logger per t.ex. fil som bearbetas eller nätverksanslutning som görs, använd befintliga mekanismer för att skicka kontextuell information till dina loggar och begränsa de loggar som skapas till de som beskriver områden inom din applikation (i allmänhet moduler, men ibland något mer finkornigt än så).

Övriga resurser

Se även

Modul logging

API-referens för loggningsmodulen.

Modul logging.config

Konfigurations-API för loggningsmodulen.

Modul logging.handlers

Användbara hanterare som ingår i loggningsmodulen.

Grundläggande handledning

Avancerad handledning