Egy hiba élete

Hogyan logoljunk rosszul Flask-ben

Korábbi döntéseink egész meglepő és váratlan módon tudnak hátba szúrni minket a jelenben. Nincs ez másképp kódunk természetes evolúciója során sem. Csak az idő a megmondhatója annak, hogy a ma meghozott döntéseink a jövőben jónak vagy rossznak fognak bizonyulni.
Persze vannak követhető "szokások", "módszertanok", "minták" és más egyebek, amik követése az esetek többségében jó eredményeket fog hozni, de néha még így is sikerül elég kreatívnak maradni ahhoz, hogy lábon lőjük magunkat.

A mai napon ezt Python és Flask segítségével próbáljuk majd elkövetni, miközben egy nagyon bonyolult "Hello World" alkalmazást bővítgetünk.

Egy hiba születése

Elkezdődik hát a projekt, mindenki hatalmas izgalomban, végre egy üres lapot írhatunk teli, nem fog a fejlesztés a korábbi (rossznak bizonyult) döntéseink súlya alatt vánszorogni. El is készül az első változat.

class HelloView(MethodView):
    def get(self):
        return 'Hello World\n'

app = Flask(__name__)
app.add_url_rule('/', view_func=HelloView.as_view('hello'))

if __name__ == '__main__':
    app.run()

Nem sokkal később rájövünk, hogy egy ilyen bonyolult alkalmazás nem létezhet logolás nélkül, így utólag azt is hozzárakjuk.

class HelloView(MethodView):
    logger = logging.getLogger('view.hello')

    def get(self):
        self.logger.info('hello from view')
        return 'Hello World\n'

Eddig minden szép és jó, az alkalmazást meghívva az elvárt működést tapasztaljuk:

$ curl localhost:8080
Hello World

És a logok között is megjelenik az üzenetünk:

{"name": "view.hello", "message": "hello from view"}

De ahogy telik az idő és a követelmények változnak, felmerül az igény, hogy jó lenne, ha a logsorokhoz tudnánk extra adatokat hozzárakni. Egy ilyen adat lehet mondjuk a kérésekhez generált egyedi azonosító.

class ContextLogger:
    def __init__(self, logger):
        self.__logger = logger
        self.__context = {}

    def add_context(self, key, value):
        self.__context[key] = value

    def info(self, message):
        self.__logger.info(message, extra=self.__context)

def add_request_id(logger):
    def decorator(f):
        @wraps(f)
        def decorated_function(self):
            request_id = uuid.uuid4()
            logger.add_context('request_id', request_id)
            logger.info(f'hello from middleware ({request_id})')
            return f(self, request_id)
        return decorated_function
    return decorator

class HelloView(MethodView):
    logger = ContextLogger(logging.getLogger('view.hello'))

    @add_request_id(logger)
    def get(self, request_id):
        time.sleep(0.01)
        self.logger.info(f'hello from view ({request_id})')
        return 'Hello World\n'

A valóságban a ContextLogger egy fokkal bonyolultabb lenne, megvalósítaná a többi logolással kapcsolatos függvényt (warn, error, stb.) és le kellene kezelnie a kívülről jövő extra paramétereket is.

A sleep hívás a view osztály által elvégzett egyéb munkákat hivatott szimulálni. Mondjuk hátra kell még szólnia valami backend service felé, hogy összeszedje az adatokat, amik a "Hello World" megjelenítéséhez feltétlenül kellenek, vagy valami ilyesmi. Mindenesetre az alkalmazás továbbra is jól működik.

{
  "name": "view.hello",
  "message": "hello from middleware (5f428aa7-cf68-4ae4-a003-2b95085f7f7d)",
  "request_id": "5f428aa7-cf68-4ae4-a003-2b95085f7f7d"
}
{
  "name": "view.hello",
  "message": "hello from view (5f428aa7-cf68-4ae4-a003-2b95085f7f7d)",
  "request_id": "5f428aa7-cf68-4ae4-a003-2b95085f7f7d"
}

Vagy mégsem? Mi történik akkor, ha megpróbálunk egyszerre több kérést küldeni?

$ curl localhost:8080 & curl localhost:8080 &
{
  "name": "view.hello",
  "message": "hello from middleware (36d1627c-2159-4865-92ed-c63969efde47)",
  "request_id": "36d1627c-2159-4865-92ed-c63969efde47"
}
{
  "name": "view.hello",
  "message": "hello from middleware (78062d9e-bb3a-4a74-a24c-e0ba22be6660)",
  "request_id": "78062d9e-bb3a-4a74-a24c-e0ba22be6660"
}
{
  "name": "view.hello",
  "message": "hello from view (36d1627c-2159-4865-92ed-c63969efde47)",
  "request_id": "78062d9e-bb3a-4a74-a24c-e0ba22be6660"
}
{
  "name": "view.hello",
  "message": "hello from view (78062d9e-bb3a-4a74-a24c-e0ba22be6660)",
  "request_id": "78062d9e-bb3a-4a74-a24c-e0ba22be6660"
}

A middleware logok jól néznek ki, de a view logjaiban mindkét kérésnél ugyanaz a request_id szerepel. Ráadásul a message-ben a jó érték van. Mi a f... ene.

A gyors javítás

A hibát az okozza, hogy a logger változónk a HelloView osztályban statikus, így csak egyszer inicializálódik, amikor az alkalmazás elindul és az osztályt tartalmazó modulunk betöltődik. Mi arra számítottunk, hogy kérésenként más-más logger osztályunk lesz. Vagy még inkább bele se gondoltunk. A logolás eddig is működött, utána is működött, nem lesz itt semmi baj.

Egy lehetséges javítása a problémának az lehet, hogy a logger-t a konstruktorban inicializáljuk, de így már nem tudjuk egyszerűen átadni a middleware-nek (amire azért lehet szükség, hogy ugyanolyan névvel logoljon a view és az előtte futó middleware).

def add_request_id():
    def decorator(f):
        @wraps(f)
        def decorated_function(self):
            request_id = uuid.uuid4()
            self.logger.add_context('request_id', request_id)
            self.logger.info(f'hello from middleware ({request_id})')
            return f(self, request_id)
        return decorated_function
    return decorator

class HelloView(MethodView):
    logger = None

    def __init__(self):
        self.logger = ContextLogger(logging.getLogger('view.hello'))

    @add_request_id()
    def get(self, request_id):
        time.sleep(0.01)
        self.logger.info(f'hello from view ({request_id})')
        return 'Hello World\n'

A dekorátor eléri az általa dekorált függvény minden paraméterét, így a self-et is, amin keresztül továbbra is elérhetjük a logger-t. Nem túl elegáns, de működik. Erről szólnak a gyors javítások, nem?

Egy maradandóbb megoldás

A Flask-ben létezik egy Request Context nevezetű dolog, a request változó mindig az éppen feldolgozás alatt lévő kérésre fog vonatkozni, szóval ha esetleg ki tudnánk egészíteni a saját adatainkkal, akkor megoldódna a probléma. Néhány Flask osztály felüldefiniálásával ezt meg is tudjuk oldani.

class MyRequest(Request):
    def __init__(self, environ, populate_request=True, shallow=False):
        super().__init__(environ, populate_request, shallow)
        self.__context = {}

    @property
    def context(self):
        return self.__context

    def add_context(self, key, value):
        self.__context[key] = value

class MyFlask(Flask):
    request_class = MyRequest

class RequestContextLogger:
    def __init__(self, logger):
        self.__logger = logger

    def info(self, message):
        self.__logger.info(message, extra=request.context)

def add_request_id(logger):
    def decorator(f):
        @wraps(f)
        def decorated_function(self):
            request_id = uuid.uuid4()
            request.add_context('request_id', request_id)

            logger.info(f'hello from middleware ({request_id})')
            return f(self, request_id)
        return decorated_function
    return decorator

class HelloView(MethodView):
    logger = RequestContextLogger(logging.getLogger('view.hello'))

    @add_request_id(logger)
    def get(self, request_id):
        time.sleep(0.01)
        self.logger.info(f'hello from view ({request_id})')
        return 'Hello World\n'

app = MyFlask(__name__)
app.add_url_rule('/', view_func=HelloView.as_view('hello'))

if __name__ == '__main__':
    app.run()

A próbálkozásaim során sikerült még egyszer ugyanúgy lábon lőni magam, mint a logger esetében. Az első változatban a __context nem az __init__-ben kapott értéket, így mindenki ugyanazt a dict-et használta, ami miatt úgy tűnt, hogy nem lesz működőképes ez a megoldás. Nem tanultam elég gyorsan a hibáimból.

Egy kis kutakodás után rájöhetünk, hogy nem csak nekünk jutott eszünkbe, hogy a request-hez extra adatokat hozzáadni kívánatos dolog lehet, így lecserélhetjük a házibarkács megoldásunkat a Flask g változójára, amivel megszabadulhatunk egy jó adag kódtól.

class GContextLogger:
    def __init__(self, logger):
        self.__logger = logger

    def info(self, message):
        self.__logger.info(message, extra=g.log_context)

def add_request_id(logger):
    def decorator(f):
        @wraps(f)
        def decorated_function(self):
            request_id = uuid.uuid4()
            g.log_context = {'request_id': request_id}

            logger.info(f'hello from middleware ({request_id})')
            return f(self, request_id)
        return decorated_function
    return decorator

class HelloView(MethodView):
    logger = GContextLogger(logging.getLogger('view.hello'))

    @add_request_id(logger)
    def get(self, request_id):
        time.sleep(0.01)
        self.logger.info(f'hello from view ({request_id})')
        return 'Hello World\n'

Egy fokkal jobb, de még mindig nem az igazi. Mi történik például olyankor, ha a view dob egy kivételt és azt egy Flask-es error handler lekezeli, ami mellékesen logol is egyet? Rajta lesz az extra adat? És egy általunk használt külső modul logjain?

A "végleges" megoldás

Már amennyire bármi végleges lehet. Talán inkább az "éppen aktuális legjobb tudásunk szerinti megoldás, ami megfelel a jelenlegi követelményeknek" lenne a jó kifejezés. Először is szabaduljunk meg a GContextLogger osztálytól, hogy ne kelljen minden log példányosításunkat becsomagolnunk valamibe. Ehhez használhatunk Python-os log filtert, amit ugyan a logok szűrésére találtak ki, de gyakran használják ilyen esetekben is.

class LogContextFilter(Filter):
    def filter(self, record):
        if has_request_context() and hasattr(g, 'log_context'):
            for k, v in g.log_context.items():
                setattr(record, k, v)

        return True

Itt már egy kicsit óvatosabbak vagyunk a g.log_context elérésével. Csak akkor próbáljuk kiszedni belőle az adatokat, ha épp Flask-es kérést dolgozunk fel és már van benne log_context.

Megszabadulhatunk a logger példányosítástól is, használhatjuk helyette a Flask által felkonfigurált app.logger-t. Egyetlen hátránya, hogy így kézzel kell ráraknunk a logokra a view nevét (ha erre tényleg szükségünk van), mert a name mezőben az app.name értéke lesz.

def add_request_id():
    def decorator(f):
        @wraps(f)
        def decorated_function(self):
            request_id = uuid.uuid4()
            g.log_context = {
                'request_id': request_id,
                'view': self.__class__.__name__,
            }

            app.logger.info(f'hello from middleware ({request_id})')
            return f(self, request_id)
        return decorated_function
    return decorator

class HelloView(MethodView):
    @add_request_id()
    def get(self, request_id):
        time.sleep(0.01)
        app.logger.info(f'hello from view ({request_id})')
        return 'Hello World\n'
{
  "name": "test",
  "message": "hello from middleware (7575ef53-8764-4d17-967b-af2902691ac4)",
  "request_id": "7575ef53-8764-4d17-967b-af2902691ac4",
  "view": "HelloView"
}
{
  "name": "test",
  "message": "hello from view (7575ef53-8764-4d17-967b-af2902691ac4)",
  "request_id": "7575ef53-8764-4d17-967b-af2902691ac4",
  "view": "HelloView"
}

Végül megszabadulhatunk az add_request_id middleware-től is. Mivel jó eséllyel ezt minden kérésnél meg szeretnénk csinálni, lecserélhetjük egy globális megoldásra.

class HelloView(MethodView):
    def get(self):
        g.log_context['view'] = self.__class__.__name__

        app.logger.info(f'hello from view')
        return 'Hello World\n'

app = Flask(__name__)
app.add_url_rule('/', view_func=HelloView.as_view('hello'))

@app.before_request
def init_logging_context():
    g.log_context = {
        'request_id': uuid.uuid4(),
        'ip': request.remote_addr,
    }

Egy hátránya ennek a megoldásnak, hogy a before_request-nél nem tudjuk még milyen view fog futni, így nem is tudjuk belerakni a nevét a log_context-be.

Ezzel el is érkeztünk az éppen aktuális végleges megoldásunkhoz. Az egyes fázisokat teljes terjedelmükben meg lehet tekinteni a kapcsolódó Github repository-ban. További szép logolást.

This post is also available in english: A bug's life

Hozzáfűznél valamit?

Dobj egy emailt a blog kukac deadlime pont hu címre.

Feliratkoznál?

Az RSS feed-et ajánljuk, ha kedveled a régi jó dolgokat.