L'appender di file di logback non viene eseguito immediatamente

Question

Per alcune circostanze, è necessario forzare immediatamente lo scaricamento nel file appender di logback. Ho trovato in docs questa opzione è abilitata per impostazione predefinita. Misteriosamente questo non funziona. Come vedo nelle fonti il ​​processo sottostante coinvolge correttamente BufferedOutputSream. C'è qualche problema con BufferedOutputSream.flush()? Probabilmente questo è piuttosto correlato al problema del flushing.

Aggiornamento: Ho trovato il problema su Windows XP Pro SP 3 e su Red Hat Enterprise Linux Server versione 5.3 (Tikanga). Ho usato queste librerie:

jcl-over-slf4j-1.6.6.jar 
logback-classic-1.0.6.jar 
logback-core-1.0.6.jar 
slf4j-api-1.6.6.jar 

Il logback.xml è:

<configuration> 
    <appender name="FILE" class="ch.qos.logback.core.rolling.RollingFileAppender"> 
     <file>/somepath/file.log</file> 
     <rollingPolicy class="ch.qos.logback.core.rolling.FixedWindowRollingPolicy"> 
      <fileNamePattern>file.log.%i</fileNamePattern> 
      <minIndex>1</minIndex> 
      <maxIndex>3</maxIndex> 
     </rollingPolicy> 
     <triggeringPolicy class="ch.qos.logback.core.rolling.SizeBasedTriggeringPolicy"> 
      <maxFileSize>5MB</maxFileSize> 
     </triggeringPolicy> 
     <encoder> 
      <pattern>%d{HH:mm:ss.SSS} [%thread] %-5level %logger - %msg%n</pattern> 
     </encoder> 
    </appender> 

    <root level="debug"> 
     <appender-ref ref="FILE"/> 
    </root> 
</configuration> 

Aggiornato: mi piacerebbe fornire una prova di unità, ma che non sembra così semplice. Lasciami descrivere la questione più chiaramente.

1. evento di registrazione si è verificato
2. evento è passato attraverso il file appender
3. evento viene serializzato con il modello definito
4. Serialized messaggio di evento viene passato al file appender ed è in procinto di scrivere per l'output stream
5. La scrittura sullo stream è terminata, il flusso di output viene svuotato (ho controllato l'implementazione). Notare che è impostato su predefinito, pertanto il metodo flush() viene invocato in modo esplicito
6. Nessun risultato nel file!

Un po 'più tardi quando è stato eseguito il flusso di un buffer sottostante, l'evento appare nel file. Quindi la domanda è: il flusso di output garantisce un flush immediato?

A dire il vero, ho già risolto questo problema implementando il mio ImmediateRollingFileAppender che sfrutta la funzione di sincronizzazione immediata di FileDescriptor. Chiunque sia interessato può seguire this.

Quindi questo non è un problema di logback.

Answer 1

Ho deciso di portare la mia soluzione a tutti. Prima di tutto chiarisco che questo non è un problema di logback e non un problema con JRE. Questo è descritto nel javadoc e generalmente non dovrebbe essere un problema finché non ci si trova di fronte ad alcune soluzioni di integrazione della vecchia scuola sulla sincronizzazione dei file.

Quindi questo è un appender logback implementato per irrigare immediatamente:

public class ImmediateFileAppender<E> extends RollingFileAppender<E> { 

    @Override 
    public void openFile(String file_name) throws IOException { 
     synchronized (lock) { 
      File file = new File(file_name); 
      if (FileUtil.isParentDirectoryCreationRequired(file)) { 
       boolean result = FileUtil.createMissingParentDirectories(file); 
       if (!result) { 
        addError("Failed to create parent directories for [" + file.getAbsolutePath() + "]"); 
       } 
      } 

      ImmediateResilientFileOutputStream resilientFos = new ImmediateResilientFileOutputStream(file, append); 
      resilientFos.setContext(context); 
      setOutputStream(resilientFos); 
     } 
    } 

    @Override 
    protected void writeOut(E event) throws IOException { 
     super.writeOut(event); 
    } 

} 

Questo è corrispondente flusso di output classe di utilità. A causa di alcuni metodi e campi dell'originale ResilientOutputStreamBase che si supponeva inizialmente di estendere i modificatori di accesso impacchettati, dovevo estendere lo OutputStream e copiare il resto e invariato di ResilientOutputStreamBase e ResilientFileOutputStream in questo nuovo.Ho appena visualizzare il codice modificato:

public class ImmediateResilientFileOutputStream extends OutputStream { 

    // merged code from ResilientOutputStreamBase and ResilientFileOutputStream 

    protected FileOutputStream os; 

    public FileOutputStream openNewOutputStream() throws IOException { 
     return new FileOutputStream(file, true); 
    } 

    @Override 
    public void flush() { 
     if (os != null) { 
      try { 
       os.flush(); 
       os.getFD().sync(); // this's make sence 
       postSuccessfulWrite(); 
      } catch (IOException e) { 
       postIOFailure(e); 
      } 
     } 
    } 

} 

E infine la configurazione:

<appender name="FOR_INTEGRATION" class="package.ImmediateFileAppender"> 
    <file>/somepath/for_integration.log</file> 
    <rollingPolicy class="ch.qos.logback.core.rolling.FixedWindowRollingPolicy"> 
     <fileNamePattern>for_integration.log.%i</fileNamePattern> 
     <minIndex>1</minIndex> 
     <maxIndex>3</maxIndex> 
    </rollingPolicy> 
    <triggeringPolicy class="ch.qos.logback.core.rolling.SizeBasedTriggeringPolicy"> 
     <maxFileSize>5MB</maxFileSize> 
    </triggeringPolicy> 
    <encoder> 
     <pattern>%d{HH:mm:ss.SSS} - %msg%n</pattern> 
     <immediateFlush>true</immediateFlush> 
    </encoder> 
</appender> 

Answer 2

Hai fatto un buon lavoro - ben fatto. Ecco una proposta per farlo più concisa:

public class ImmediateFlushPatternLayoutEncoder extends PatternLayoutEncoder { 
    public void doEncode(ILoggingEvent event) throws IOException { 
     super.doEncode(event); 
     if (isImmediateFlush()) { 
      if (outputStream.os instanceof FileOutputStream) { 
       ((FileOutputStream) outputStream.os).getFD().sync(); 
      } 
     } 
    } 
} 

Nella configurazione, è necessario utilizzare tale encoder specifico:

<encoder class="ch.qos.logback.core.recovery.ImmediateFlushPatternLayoutEncoder"> 

Non testato. Probabilmente ci saranno problemi di visibilità con i campi, che richiedono l'uso del pacchetto di logback ch.qos.logback.core.recovery.

A proposito, vi invito a submit a bug report per effettuare il logback per ottenere un'opzione aggiuntiva immediateSync su LayoutWrappingEncoder.

Answer 3

Molti middleware di monitoraggio trovano i nuovi eventi controllando gli aggiornamenti di data e ora e dimensione del file. Per questo motivo, è necessario che l'evento venga registrato, che la data e la dimensione del file vengano aggiornate.

Questa classe potrebbe risolverlo

public class MyFileAppender<E> extends FileAppender<E> { 
    protected void writeOut(E event) throws IOException { 
     super.writeOut(event); 
     ResilientFileOutputStream resilientFos = (ResilientFileOutputStream) super.getOutputStream(); 
     resilientFos.flush(); 
     resilientFos.getChannel().force(true); 
    } 
} 

Set classe MyFileAppender per appender.

<appender name="FILE" class="MyFileAppender"> 

Spero che questo logback risolva questo problema.