Pythonロガーでlinenoをオーバーライドする最も良い方法

Question

私は、特定の関数またはメソッドを呼び出すために使用される引数を記録するデコレータを作成しました。以下に示すように、それはlogRecordに報告行番号がデコレータの行番号ではなく、ラップされているfuncの行番号であることを除いてうまく機能：

from functools import wraps 
import inspect 
import logging 

arg_log_fmt = "{name}({arg_str})" 


def log_args(logger, level=logging.DEBUG): 
    """Decorator to log arguments passed to func.""" 
    def inner_func(func): 
     line_no = inspect.getsourcelines(func)[-1] 

     @wraps(func) 
     def return_func(*args, **kwargs): 
      arg_list = list("{!r}".format(arg) for arg in args) 
      arg_list.extend("{}={!r}".format(key, val) 
          for key, val in kwargs.iteritems()) 
      msg = arg_log_fmt.format(name=func.__name__, 
            arg_str=", ".join(arg_list)) 
      logger.log(level, msg) 
      return func(*args, **kwargs) 
     return return_func 

    return inner_func 

if __name__ == "__main__": 
    logger = logging.getLogger(__name__) 
    handler = logging.StreamHandler() 
    fmt = "%(asctime)s %(levelname)-8.8s [%(name)s:%(lineno)4s] %(message)s" 
    handler.setFormatter(logging.Formatter(fmt)) 
    logger.addHandler(handler) 
    logger.setLevel(logging.DEBUG) 


    @log_args(logger) 
    def foo(x, y, z): 
     pass 

    class Bar(object): 
     @log_args(logger) 
     def baz(self, a, b, c): 
      pass 

    foo(1, 2, z=3) 
    foo(1, 2, 3) 
    foo(x=1, y=2, z=3) 

    bar = Bar() 
    bar.baz(1, c=3, b=2) 

以下の出力でこのサンプル結果

2015-09-07 12:42:47,779 DEBUG [__main__: 25] foo(1, 2, z=3) 
2015-09-07 12:42:47,779 DEBUG [__main__: 25] foo(1, 2, 3) 
2015-09-07 12:42:47,779 DEBUG [__main__: 25] foo(y=2, x=1, z=3) 
2015-09-07 12:42:47,779 DEBUG [__main__: 25] baz(<__main__.Bar object at 0x1029094d0>, 1, c=3, b=2) 

すべての行番号がデコレータを指していることに注意してください。

inspect.getsourcelines(func)私は関心のある行番号を得ることができますが、linenoを上書きしようとすると、エラーが発生します。logger.debugラップされた関数の行番号をロギングステートメントに表示する最良の方法は何ですか？

Answer 1

Martijnが指摘しているように、ときには物事が変わることがあります。しかし、あなたは、Python 2を（iteritemsがそれを離れて与えた）を使用しているので、あなたは猿パッチングロギングを気にしない場合は、次のコードは動作します：

from functools import wraps 
import logging 

class ArgLogger(object): 
    """ 
    Singleton class -- will only be instantiated once 
    because of the monkey-patching of logger. 
    """ 

    singleton = None 

    def __new__(cls): 
     self = cls.singleton 
     if self is not None: 
      return self 
     self = cls.singleton = super(ArgLogger, cls).__new__(cls) 
     self.code_location = None 

     # Do the monkey patch exactly one time 
     def findCaller(log_self): 
      self.code_location, code_location = None, self.code_location 
      if code_location is not None: 
       return code_location 
      return old_findCaller(log_self) 
     old_findCaller = logging.Logger.findCaller 
     logging.Logger.findCaller = findCaller 

     return self 

    def log_args(self, logger, level=logging.DEBUG): 
     """Decorator to log arguments passed to func.""" 
     def inner_func(func): 
      co = func.__code__ 
      code_loc = (co.co_filename, co.co_firstlineno, co.co_name) 

      @wraps(func) 
      def return_func(*args, **kwargs): 
       arg_list = list("{!r}".format(arg) for arg in args) 
       arg_list.extend("{}={!r}".format(key, val) 
           for key, val in kwargs.iteritems()) 
       msg = "{name}({arg_str})".format(name=func.__name__, 
             arg_str=", ".join(arg_list)) 
       self.code_location = code_loc 
       logger.log(level, msg) 
       return func(*args, **kwargs) 
      return return_func 

     return inner_func 


log_args = ArgLogger().log_args 

if __name__ == "__main__": 
    logger = logging.getLogger(__name__) 
    handler = logging.StreamHandler() 
    fmt = "%(asctime)s %(levelname)-8.8s [%(name)s:%(lineno)4s] %(message)s" 
    handler.setFormatter(logging.Formatter(fmt)) 
    logger.addHandler(handler) 
    logger.setLevel(logging.DEBUG) 


    @log_args(logger) 
    def foo(x, y, z): 
     pass 

    class Bar(object): 
     @log_args(logger) 
     def baz(self, a, b, c): 
      pass 

    def test_regular_log(): 
     logger.debug("Logging without ArgLog still works fine") 

    foo(1, 2, z=3) 
    foo(1, 2, 3) 
    foo(x=1, y=2, z=3) 

    bar = Bar() 
    bar.baz(1, c=3, b=2) 
    test_regular_log() 

Answer 2

Logger.findCaller() methodがイントロスペクションでこの情報を抽出するため、回線番号を簡単に変更できません。

あなたはでき問題へリードしたときでしょう（IとVeedracがthis postに通じジャンプフープを参照）を使用すると、生成ラッパー関数のための機能やコードのオブジェクトを、それは確かに非常に毛深いです構築-REとあなたのトレースバックが間違ったソース行を表示するので、バグがあります！

あなたは手動でログを出力する（それはあまりにも異なることがあるため）、行番号、だけでなく、あなたのモジュール名を追加したほうが良いと思います：あなたは常にここに機能を持っているので

arg_log_fmt = "{name}({arg_str}) in {filename}:{lineno}" 

# ... 

codeobj = func.__code__ 
msg = arg_log_fmt.format(
    name=func.__name__, arg_str=", ".join(arg_list), 
    filename=codeobj.co_filename, lineno=codeobj.co_firstlineno) 

、関連するコードオブジェクトを介して関数の最初の行番号を取得するために、より直接的なイントロスペクションを使用しました。

Answer 3

別の可能性はLogger.makeRecordを上書きするLoggerをサブクラス化することです。この予防措置を除去することにより

for key in extra: 
    if (key in ["message", "asctime"]) or (key in rv.__dict__): 
     raise KeyError("Attempt to overwrite %r in LogRecord" % key) 
    rv.__dict__[key] = extra[key] 

、我々はlogger.logに extra引数を供給することにより、LINENOの値を上書きすることができます：あなたはLogRecordで標準属性（rv.linenoのような）のいずれかを変更しようとした場合KeyErrorを提起This is the method呼び出し：

logger.log(level, msg, extra=dict(lineno=line_no)) 

---

from functools import wraps 
import inspect 
import logging 

arg_log_fmt = "{name}({arg_str})" 


def makeRecord(self, name, level, fn, lno, msg, args, exc_info, func=None, extra=None): 
    """ 
    A factory method which can be overridden in subclasses to create 
    specialized LogRecords. 
    """ 
    rv = logging.LogRecord(name, level, fn, lno, msg, args, exc_info, func) 
    if extra is not None: 
     rv.__dict__.update(extra) 
    return rv 

def log_args(logger, level=logging.DEBUG, cache=dict()): 
    """Decorator to log arguments passed to func.""" 
    logger_class = logger.__class__ 
    if logger_class in cache: 
     UpdateableLogger = cache[logger_class] 
    else: 
     cache[logger_class] = UpdateableLogger = type(
      'UpdateableLogger', (logger_class,), dict(makeRecord=makeRecord)) 

    def inner_func(func): 
     line_no = inspect.getsourcelines(func)[-1] 
     @wraps(func) 
     def return_func(*args, **kwargs): 
      arg_list = list("{!r}".format(arg) for arg in args) 
      arg_list.extend("{}={!r}".format(key, val) 
          for key, val in kwargs.iteritems()) 
      msg = arg_log_fmt.format(name=func.__name__, 
            arg_str=", ".join(arg_list)) 
      logger.__class__ = UpdateableLogger 
      try: 
       logger.log(level, msg, extra=dict(lineno=line_no)) 
      finally: 
       logger.__class__ = logger_class 
      return func(*args, **kwargs) 
     return return_func 

    return inner_func 

if __name__ == "__main__": 
    logger = logging.getLogger(__name__) 
    handler = logging.StreamHandler() 
    fmt = "%(asctime)s %(levelname)-8.8s [%(name)s:%(lineno)4s] %(message)s" 
    handler.setFormatter(logging.Formatter(fmt)) 
    logger.addHandler(handler) 
    logger.setLevel(logging.DEBUG) 

    @log_args(logger) 
    def foo(x, y, z): 
     pass 

    class Bar(object): 

     @log_args(logger) 
     def baz(self, a, b, c): 
      pass 

    foo(1, 2, z=3) 
    foo(1, 2, 3) 
    foo(x=1, y=2, z=3) 

    bar = Bar() 
    bar.baz(1, c=3, b=2) 

の利回り

2015-09-07 16:01:22,332 DEBUG [__main__: 48] foo(1, 2, z=3) 
2015-09-07 16:01:22,332 DEBUG [__main__: 48] foo(1, 2, 3) 
2015-09-07 16:01:22,332 DEBUG [__main__: 48] foo(y=2, x=1, z=3) 
2015-09-07 16:01:22,332 DEBUG [__main__: 53] baz(<__main__.Bar object at 0x7f17f75b0490>, 1, c=3, b=2) 

---

ライン

UpdateableLogger = type('UpdateableLogger', (type(logger),), 
          dict(makeRecord=makeRecord)) 

はmakeRecordをオーバーライドするtype(logger)のサブクラスである新しいクラスを作成します。 return_funcの内部にあるloggerのクラスはUpdateableLoggerに変更され、logger.logへの呼び出しによってlinenoが変更され、元のロガークラスが復元されます。 - すべてloggerは、装飾された機能の外で以前と同じように動作します。比較のために、サルパッチ方法はshown hereである。