Sto usando slf4j su log-back. A volte i log non vengono stampati nell'ordine (timestamp). Potremmo forzarlo ad accedere nello stesso ordine in cui il codice è in esecuzione?force slf4j per stampare i registri in sequenza
Aggiornamento 1: questo accade quando si eseguono test di unità su Jenkins tramite Maven. Sta accadendo costantemente. Sono in arrivo le prime istruzioni del registro dal codice, quindi verranno fornite le dichiarazioni del registro dal test dell'unità.
Anche tutti i file di registro sembrano normali come di seguito.
<appender name="STDOUT"
class="ch.qos.logback.core.ConsoleAppender">
<layout class="ch.qos.logback.classic.PatternLayout">
Update 2: i frammenti di log sono come questo (ho modificato il nome del file, ecc ..). Durante l'esecuzione del test1 chiamiamo il codice per invertire una transazione che è fallita a causa di un errore. Ma la cosa strana è che prima viene stampata l'eccezione e poi vengono stampate le istruzioni del registro dei metodi di prova. Anche i timestamp di dichiarazioni di log sono come previsto, ma l'ordine di loro nel file è diversa (14:33:34. viene prima 14:33:34.)
14:33:34.667 [[email protected]] [] WARN org.hibernate.ejb.Ejb3Configuration - hibernate.connection.autocommit = false break the EJB3 specification
14:33:34.718 [[email protected]] [] WARN o.h.impl.SessionFactoryObjectFactory - InitialContext did not implement EventContext
14:33:34.843 [[email protected]] [] DEBUG c.r.a.exception.ExceptionMapper - <3003> can't reverse transaction. [id=10000000100120014]
.
.
.
.
.
14:33:34.158 [main] [] DEBUG c.r.a.test - ========================= test0: finished.
14:33:34.158 [main] [] DEBUG c.r.a.test - ========================= test1: started.
.
.
.
.
14:33:34.449 [main] [] DEBUG c.r.a.test - reversing transaction, id=10000000100120014
14:33:34.856 [main] [] DEBUG c.r.a.test - ========================= test2: started.
Aggiornamento 3: il nostro progetto utilizza Maven e ci sono più moduli. Abbiamo logback-test.xml nella cartella src/test/resources.
La struttura del progetto è simile a
codemodule/src/test/resources/logback-test.xml - questo modulo verrà inserito nel file jar. Il test case chiama il codice di questo modulo.
parent/src/test/resources/logback-test.xml - questo è il modulo genitore che avvolge tutti i file jar e pacchetti di altri moduli in una guerra. Qui è dove ho eseguito il test case e chiama sopra il codice del modulo.
Ho delle istruzioni di registro sia nel codice del test case che nel codice effettivo. Ho verificato che sia il caso di test sia il codice utilizzano il pattern dal file di log del genitore (il pattern nel codemodule è diverso). Stampa in modo coerente le istruzioni del registro del codice prima di stampare i log del caso di test.
Inoltre, non stiamo eseguendo test in parallelo.
Concurrency config is parallel='none', perCoreThreadCount=true, threadCount=2, useUnlimitedThreads=false
Update 4: capisco il problema. Stiamo facendo una richiesta http non una chiamata diretta al metodo. Quindi i test case sono in esecuzione nel thread main e il codice effettivo è in esecuzione in un altro thread (Grazie Sebbe).
Capisco che forzare la sequenza di registrazione può essere un successo in termini di prestazioni, ma per la completezza della domanda farò ancora una domanda.
Poiché entrambi i registri sono destinati a singolo appender (STDOUT), posso forzare l'accesso nell'ordine di data/ora?
Stai dicendo che nel tuo diario vedi messaggi di timestamp misti (non crescenti?) Mai visto un fenomeno del genere. Quale appender stai usando? –
@TomaszNurkiewicz Sì, sto usando ch.qos.logback.core.ConsoleAppender – Reddy
Usi una concorrenza? Potrebbe essere una causa. Inoltre, potresti fornire un estratto del registro – Fixpoint