traceEntryExit

Nézzük meg egy - klasszikus - példán keresztül, hogyan is csinálhatunk mi magunk dekorátorokat. A példa a traceEntryExit nevű dekorátor lesz, ami a dekorált függvény meghívását és befejeződését írja majd ki. A kód, amit a dekorátor fejlődése közben tesztként meghívok, az legyen az alábbi:

from entryexit import traceEntryExit

@traceEntryExit
def proba(param):
    """proba fuggveny a traceEntryExit tesztelesehez"""
    print "a kapott parameter: %s" % param
    return "-> %s <-" % param

proba("proba parameter")

Az entryexit.py fileba pedig elkezdhetjük a dekorátorunkat, első körben csináljunk egy olyat, ami nem csinál semmit, és nézzük meg, hogy műkődik-e a proba.py, ha lefuttatjuk:

def traceEntryExit(func):
  return func

$ python proba.py
a kapott parameter: proba parameter

Amint látható a proba fuggvény működik, mintha misem történt volna, de mondjuk igazából nem is történt semmi :)

Azt szeretnénk tehát, hogy a dekorált függvény lefutása előtt, illetve után közvetlenül kiírnánk valamit. Ehhez nem elég a dekorátorunkban kiírni a valamit - mert az nem a függvény futásakor íródna ki, hanem a dekoráláskor, azaz a függvény deklarációjánál -, hanem egy másik függvényt kell visszaadnunk, ami annyit csinál, hogy kiírja a kívánt dolgokat, és közben lefuttatja a dekorált függvényt. Ezt a függvényt magán a dekorátoron belül deklaráljuk, elég ha csak ott áll a rendelkezésünkre. (Segítségképp meg csináltam egy "logger" függvényt is, csúnya dolog print utasításokat elhelyezni szerte a kódba, később így könnyebben logolhatunk fileba például.)

Az entryexit.py tartalma:

import time

def dummyLogger(txt):
    print "[TraceEE] %s" % txt

logger = dummyLogger

def traceEntryExit(func):

    def inner(*args, **kwargs):
        logger("entering %s" % func.__name__)
        starttime = time.time()
        retVal = func(*args, **kwargs)
        endtime = time.time()
        logger("leaving %s [exec time: %s sec.]" %
          (func.__name__, endtime-starttime))
        return retVal

    return inner

$ python proba.py
[TraceEE] entering proba
a kapott parameter: proba parameter
[TraceEE] leaving proba [exec time: 2.59876251221e-05 sec.]

Ugye nem is olyan bonyolult! És még a dekorált függvény futási idejét is megmérte nekünk. A belső függvény mindenféle argumentumot elfogad, azokat továbbadja a dekoráltnak, és valóban nem csinál mást, mint hogy meghívja a függvényt, előtte és utána pedig lekéri a rendszeridőt, illetve kiírja, hogy ott járunk, a dekorátor pedig ezt a belső függvényt adja vissza. Tökéletes! Vagy mégsem? Nem teljesen:

>>> from proba import proba
>>> proba.__name__
'inner'
>>> proba.__doc__
>>>

Tehát a függvényünk neve, illetve a docstring elveszett, illetve a belső függvényé van meg helyett. Természetesen a problémával nem mi találkozunk először, és 2.5-ös pythontól hivatalos megoldásunk is van, ez pedig a functools.wraps dekorátor, amivel ha a belső függvényünket megdekoráljuk, akkor az a dekorált függvény metaadatait átvarázsolja az eredményre.

from functools import wraps
...
def traceEntryExit(func):

    @wraps(func)
    def inner(*args, **kwargs):
    ...

>>> proba.__name__
'proba'
>>> proba.__doc__
'proba fuggveny a traceEntryExit tesztelesehez'

Szuper, már tudunk is magunknak dekorátort csinálni. Nade mivan, ha valami paramétert szeretnénk adni a dekorátorunknak, azt hogyan tehetjük meg, hiszen azt mondtam, hogy a dekorátornak egyetlen paramétere a dekorálni kívánt valami. Semmi gond, egy olyan függvény kell nekünk, ami több paramétert is fogad, és egy dekorátort ad vissza (ami pedig egy masik függvényt, tehát első ránézésre félelmetes, háromszorosan egymásba ágyazott valaminek tűnik a dolog, de ha szépen végiggondoljuk, és átírjuk a @-os megoldást a hagyományosra, akkor azért logikus a dolog).

Módosítsuk hát a dekorátorunkat, hogy paraméterként átadhassunk neki egy saját logger függvényt, illetve egy showParams paraméterrel állítani lehessen, hogy kiírjuk-e a bejövő paramétereket és a visszatérési értéket.

Lássuk a teljes entryexit.py file-t a módosítások után:

from functools import wraps
import time

def dummyLogger(txt):
    print "[TraceEE] %s" % txt

def traceEntryExit(function=None, showParams=True, logger=dummyLogger):
    def wrapper(func):
        @wraps(func)
        def inner(*args, **kwargs):
            logger("entering %s" % func.__name__)
            if showParams:
                if args:
                    logger("*args:")
                    for arg in args:
                        logger("  - %s" % arg)
                if kwargs:
                    logger("**kwargs:")
                    for kwarg in kwargs:
                        logger("  - %s: %s" % (kwarg, kwargs[kwarg]))
            starttime = time.time()
            retVal = func(*args, **kwargs)
            endtime = time.time()
            logger("leaving %s [exec time: %s sec.]" %
              (func.__name__, endtime-starttime))
            if showParams:
                logger("return value: %s" % retVal)
            return retVal
        return inner

    if function:
        return wrapper(function)
    return wrapper

Annyival egészítettem még ki, hogyha paraméter nélkül használjuk (azaz mintha csak sima dekorátor lenne), akkor úgy is viselkedik, mint egy sima dekorátor - így az eredeti proba.py-nk is működőképes marad:

$ python proba.py
[TraceEE] entering proba
[TraceEE] *args:
[TraceEE]   - proba parameter
a kapott parameter: proba parameter
[TraceEE] leaving proba [exec time: 2.09808349609e-05 sec.]
[TraceEE] return value: -> proba parameter <-

Illetve működnek az új paraméterek is:

>>> def myLogger(txt):
...   print "[%d] %s" % (time.time(), txt)
...
>>> @traceEntryExit(showParams=False, logger=myLogger)
... def proba2(param):
...   print "ez itt a proba2, parameter: %s" % param
...   time.sleep(2)
...
>>> proba2('nagyon proba')
[1282314984] entering proba2
ez itt a proba2, parameter: nagyon proba
[1282314986] leaving proba2 [exec time: 2.00963687897 sec.]

Frankó, ugye? A forrás letölthető változatban: entryexit.py