Il logger Python interrompe la registrazione dopo l'eccezione non rilevata

Question

Il logger Python nativo utilizzato dalla nostra app flask sembra interrompere la scrittura nel log dopo che si è verificata un'eccezione. L'ultima voce registrata prima di ogni interruzione è un messaggio che descrive l'eccezione. In genere il messaggio successivo è uno scritto dal codice in after_request, ma nei casi in cui il logger si arresta, il messaggio after_request non viene mai scritto.

Qualche idea di cosa potrebbe causare questo?

Nota: Inizialmente avevo postato questa domanda su Serverfault (https://serverfault.com/questions/655683/python-logger-stops-logging) pensando che si trattasse di un problema di infrastruttura. Ma ora che abbiamo ridotto il problema fino a quando si è verificato dopo un'eccezione, questo problema potrebbe essere più adatto a StackOverflow.

Aggiornamento [2015/12/22]:

Logger esemplificazione:

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()) 

Aggiornamento [2015/01/03]:

Answering domande postate:

L'applicazione funziona ancora dopo l'eccezione?

Sì, l'applicazione continua a funzionare.

Quale tipo di eccezione viene generato e quale è la causa?

Eccezione interna/personalizzata. Il logger si è fermato a causa di diversi tipi di eccezioni.

Stai utilizzando thread nell'applicazione?

Sì, l'app è infilata da gunicorn.

Come viene utilizzata la libreria di registrazione?

Stiamo utilizzando di default FileHandler, SysLogHandler ed una formattazione personalizzata (uscite JSON)

lo fa collegarvi un file? Usa la rotazione del registro?

Sì, registra in un file, ma senza rotazione.

Answer 1

Non hai fornito informazioni sufficienti.

L'applicazione funziona ancora dopo l'eccezione? Quale tipo di eccezione viene sollevata e qual è la causa? Stai utilizzando thread nella tua applicazione? Come viene utilizzata la libreria di logging? Accede un file? Usa la rotazione del registro?

Supponendo che si stiano utilizzando thread nell'applicazione, la spiegazione è che l'eccezione causa l'arresto del thread, pertanto non verrà visualizzata alcuna attività da quel thread specifico. Dovresti notare problemi con l'applicazione.

Se l'applicazione funziona ancora ma diventa silenziosa, suppongo che la libreria di registrazione non sia configurata correttamente. Come hai segnalato su Serverfault, il problema sembrava comparire dopo aver aggiunto fluentd che potrebbe non funzionare bene con il modo in cui la tua applicazione utilizza la libreria di logging.

Answer 2

Per quanto riguarda after_request, dalla documentazione:

Al Flask 0,7 questa funzione non può essere eseguita al termine della richiesta in caso si è verificato un'eccezione non gestita.

E per quanto riguarda il problema di registrazione, è possibile che il flag di debug sia impostato su true, il che causerebbe l'avvio del debugger e probabilmente l'interruzione della registrazione.

Riferimenti:
(http://flask.pocoo.org/docs/0.10/api/#flask.Flask.after_request)
(http://flask.pocoo.org/docs/0.10/errorhandling/#working-with-debuggers)