Primero algunos antecedentes. Tengo un proceso java por lotes que se ejecuta desde un script por lotes de DOS. Todo el registro de Java pasa a stdout, y el script por lotes redirige el stdout a un archivo. (Esto es bueno para mí porque puedo ECHO desde el script y se mete en el archivo de registro, así puedo ver todos los args de la línea de comandos JVM de Java, lo cual es genial para la depuración.) No puedolog-back y terceros escribiendo en stdout. Cómo evitar que se intercalen
Uso slf4j API, y para el backend solía usar log4j, pero recientemente cambié a logback-classic.
Aunque todo el código de mi aplicación usa slf4j, tengo una biblioteca de terceros que hace su propio registro (sin utilizar una API estándar) que también se escribe en stdout.
El problema es que a veces las líneas de registro se mezclan y no aparecen limpiamente en líneas separadas. Aquí está un ejemplo de parte de la producción en mal estado:
2010-05-28 18:00:44.783 [thread-1 ] INFO CreditCorrelationElementBuilderImpl - Bump parameters exist for scenario, now attempting bumping. [indexDisplayName=STANDARD_S1_v300]
2010-05-28 18:01:43.517 [thread-1 ] INFO CreditCorrelationElementBuilderImpl - Found adjusted point in data, now applying bump. [point=0.144040000000000]
2010-05-28 18:01:58.642 [thread-1 ] DEBUG com.company.request.Request - Generated request for [dealName=XXX_20050225_01[5],dealType=GENERIC_XXX,correlationType=2,copulaType=1] in 73.8 s, Simon Stopwatch: [sys1.batchpricer.reqgen.gen INHERIT] total 1049 s, counter 24, max 74.1 s, min 212 ms
2010-05-28 18:05/28/10 18:02:20.236 INFO: [ServiceEvent] SubmittedTask:BC-STRESS_04_FZBC-2010-05-21-545024448189310126-23
01:58.658 [req-writer-2b ] INFO .c.g.r.o.OptionalFileDocumentOutput - Writing request XML to \\filserver\dir\file1.xml - write time: 21.4 ms - Simon Stopwatch: [sys1.batchpricer.reqgen.writeinputfile INHERIT] total 905 ms, counter 24, max 109 ms, min 10.8 ms
2010-05-28 18:02:33.626 [ResponseCallbacks-1: DriverJobSpace$TakeJobRunner$1] ERROR c.c.s.s.D.CalculatorCallback - Id:23 no deal found !!
2010-0505/28/10 18:02:50.267 INFO: [ServiceEvent] CompletedTask:BC-STRESS_04_FZBC-2010-05-21-545024448189310126-23:Total:24
Ahora comparando de nuevo a los archivos de registro más antiguos, parece que el problema no se produce cuando se utiliza log4j como backend de registro. Entonces logback debe estar haciendo algo diferente.
El problema parece ser que aunque PrintStream.write(byte buf[], int off, int len) está sincronizado, sin embargo, puedo ver que en ch.qos.logback.core.joran.spi.ConsoleTarget that System.out.write(int b) es el único método de escritura llamado.
Entonces, entre el logback que da salida a cada byte, la biblioteca de terceros está logrando escribir una cadena completa en la salida estándar. (Esto no solo me causa un problema, ¿pero también debe ser un poco ineficiente?)
¿Hay alguna otra solución a este problema de intercalación que aplicarle el código a ConsoleTarget para que implique los otros métodos de escritura? Cualquier buen trabajo alrededor. ¿O debería simplemente presentar un informe de error?
Aquí es mi logback.xml:
<configuration>
<appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
<encoder>
<pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%-16thread] %-5level %-35.35logger{30} - %msg%n</pattern>
</encoder>
</appender>
<root level="DEBUG">
<appender-ref ref="STDOUT" />
</root>
</configuration>
estoy usando logback 0.9.20 con Java 1.6.0_07.
Hmm, mis bloques de código con formato previo vienen a través de una sola línea, pero estaban bien en la vista previa! Humpf! –
David, puedes volver a editar esta pregunta, usar literalmente si es necesario. –
¿Tiene una referencia o ejemplo al pie de la letra? ¿Quiere decir usar un bloque sin código? –