2015-01-03 4 views
9

私たちのフラスコアプリケーションで使用されるネイティブのPythonロガーは、例外が発生した後にログへの書き込みを停止するようです。各停止前に記録された最後のエントリは、例外を説明するメッセージです。通常、次のメッセージはafter_requestのコードで書かれたものですが、ロガーが停止した場合には、after_requestメッセージは決して書き出されません。キャッチされていない例外の後にPythonロガーがログを停止する

これを引き起こす原因は何ですか?

注:この問題はインフラストラクチャ上の問題であると考えて、Serverfault(https://serverfault.com/questions/655683/python-logger-stops-logging)に最初に掲載しました。しかし、例外が発生した後で問題を絞り込んだので、この問題はStackoverflowに適している可能性があります。

アップデート[2015年12月22日]:

ロガーインスタンス:

logging.addLevelName(Config.LOG_AUDIT_LEVEL_NUM, Config.LOG_AUDIT_LEVEL_NAME) 

logger = logging.getLogger(Config.LOGGER_NAME) 
logger.setLevel(Config.LOG_LEVEL) 

handler = SysLogHandler(address='/dev/log', facility=SysLogHandler.LOG_LOCAL3) 
handler.setLevel(Config.LOG_LEVEL) 

formatter = log_formatter() 
handler.setFormatter(formatter) 
logger.addHandler(handler) 

log_formatter:

class log_formatter(logging.Formatter): 

    def __init__(self, 
       fmt=None, 
       datefmt=None, 
       json_cls=None, 
       json_default=_default_json_default): 
     """ 
     :param fmt: Config as a JSON string, allowed fields; 
       extra: provide extra fields always present in logs 
       source_host: override source host name 
     :param datefmt: Date format to use (required by logging.Formatter 
      interface but not used) 
     :param json_cls: JSON encoder to forward to json.dumps 
     :param json_default: Default JSON representation for unknown types, 
          by default coerce everything to a string 
     """ 

     if fmt is not None: 
      self._fmt = json.loads(fmt) 
     else: 
      self._fmt = {} 
     self.json_default = json_default 
     self.json_cls = json_cls 

     if 'extra' not in self._fmt: 
      self.defaults = {} 
     else: 
      self.defaults = self._fmt['extra'] 

     try: 
      self.source_host = socket.gethostname() 
     except: 
      self.source_host = "" 

    def format(self, record): 
     """ 
     Format a log record to JSON, if the message is a dict 
     assume an empty message and use the dict as additional 
     fields. 
     """ 

     fields = record.__dict__.copy() 
     aux_fields = [ 
      'relativeCreated', 'process', 'args', 'module', 'funcName', 'name', 
      'thread', 'created', 'threadName', 'msecs', 'filename', 'levelno', 
      'processName', 'pathname', 'lineno', 'levelname' 
     ] 
     for k in aux_fields: 
      del fields[k] 

     if isinstance(record.msg, dict): 
      fields.update(record.msg) 
      fields.pop('msg') 
      msg = "" 
     else: 
      msg = record.getMessage() 

     if 'msg' in fields: 
      fields.pop('msg') 

     if 'exc_info' in fields: 
      if fields['exc_info']: 
       formatted = tb.format_exception(*fields['exc_info']) 
       fields['exception'] = formatted 
      fields.pop('exc_info') 

     if 'exc_text' in fields and not fields['exc_text']: 
      fields.pop('exc_text') 

     logr = self.defaults.copy() 

     logr = { 
      'timestamp': datetime.datetime.utcnow().strftime('%Y-%m-%dT%H:%M:%S.%fZ'), 
      'host': self.source_host, 
     } 
     logr.update(self._build_fields(logr, fields)) 

     if msg: 
      logr['message'] = msg 

     something = json.dumps(logr, default=self.json_default, cls=self.json_cls) 
     return something 

    def _build_fields(self, defaults, fields): 
     return dict(defaults.get('fields', {}).items() + fields.items()) 

アップデート[2015年1月3日]:

解答質問の投稿:

例外の後でもアプリケーションはまだ動作していますか?

はい、アプリケーションは引き続き実行されます。

発生する例外の種類とその原因は何ですか?

内部/カスタム例外。異なるタイプの例外のためにロガーが停止しました。

アプリケーションでスレッドを使用していますか?

はい、アプリはgunicornによってスレッドされています。

ログライブラリはどのように使用されていますか?

私たちは、それがファイルにログオンしていますか?デフォルトのFileHandler、SysLogHandlerのカスタムフォーマッタ(JSONを出力に)

を使用していますかログのローテーションを使用していますか?

はい、ファイルに記録しますが、ローテーションはしません。

+0

http://stackoverflow.com/help/how-to-ask - コードスニペットと何をしようとしたことは有益 – dnozay

+0

@dnozayだろう:コードスニペット追加されました。 – Jason

+1

これはソートされていますか?ログフォーマッタの内部で例外がスローされたとき(オブジェクトを直列化しようとするjson.dumpsからの無限再帰)、同様の問題がありました。 – notpeter

答えて

0

あなたは十分な情報を提供していません。

例外の後でもアプリケーションは動作していますか? 発生する例外の種類と原因は何ですか? アプリケーションでスレッドを使用していますか? ロギングライブラリはどのように使用されていますか?それはファイルにログオンしていますか?ログのローテーションを使用していますか?

アプリケーションでスレッドを使用していると仮定すると、例外によってスレッドがシャットダウンするため、その特定のスレッドからのアクティビティは表示されません。アプリケーションに関する問題も気付くはずです。

アプリケーションがまだ動作しているのにサイレント状態になる場合は、ロギングライブラリが正しく構成されていないと考えられます。あなたがServerfaultで報告したように、アプリケーションがロギングライブラリを使用する方法でうまくいかないかもしれないfluentdを追加した後、問題が現れたようです。ドキュメントからafter_requestに関しては

+0

メインの質問にあなたの質問に答えました。 – Jason

1

この関数は処理されない例外が発生した場合に 要求の終了時に実行されない場合がありフラスコ0.7のように。

また、デバッグフラグがtrueに設定されている可能性があります。デバッグフラグがtrueに設定されていると、デバッガが起動してログを停止する可能性があります。

参考文献:
http://flask.pocoo.org/docs/0.10/api/#flask.Flask.after_request
http://flask.pocoo.org/docs/0.10/errorhandling/#working-with-debuggers

+0

残念ながら、デバッグはtrueに設定されていません。 – Jason

関連する問題