search

quarkusio / quarkus

Quarkus: Supersonic Subatomic Java.
https://quarkus.io
Apache License 2.0
13.7k stars 2.65k forks source link

ConnectionBase logs NULL messages even with FINE log level #40918

Open mcanzerini opened 4 months ago

mcanzerini commented 4 months ago

Describe the bug

Our Quarkus application logs some strange messages with NULL content (since we left the 3.2 to 3.4 and after):

// Our JSON log:
{
  level: SEVERE
  loggerName: io.vertx.core.net.impl.ConnectionBase
  message: NULL
}

I read the source code of the ConnectionBase class and I saw that if I turn the log level to DEBUG I will get more info (the Cause of the exception, see https://github.com/eclipse-vertx/vert.x/blob/master/src/main/java/io/vertx/core/net/impl/ConnectionBase.java#L265). But nothing happens, only the NULL message.

Is it a bug or did I misunderstand something?

Thanks

dmlloyd commented 4 months ago

Are you paraphrasing your log, or is that the exact, literal JSON block that you are seeing in the file?

mcanzerini commented 4 months ago

I have some other data, here is a more complete log (it comes from a pod in openshift, I have not reproduced the problem in local dev mode yet):

{
  "timestamp":"2024-05-31T10:40:19.730259939Z",
  "host":"worker-04.mydomain.com",
  "level":"SEVERE",
  "loggerName":"io.vertx.core.net.impl.ConnectionBase",
  "mdc":{},
  "message":"NULL",
  "podName":"myapp-5957497c59-pkldh",
  "processId":1,
  "processName":"quarkus-run.jar",
  "threadId":27,
  "threadName":"vert.x-eventloop-thread-1"
}
dmlloyd commented 4 months ago

OK, that helps, thanks. Is this with the included io.quarkus:quarkus-logging-json or with the Quarkiverse io.quarkiverse.loggingjson:quarkus-logging-json?

mcanzerini commented 4 months ago

We developed our own logging extension based on io.quarkus:quarkus-logging-json

mcanzerini commented 4 months ago

Can you give me some feedback about this issue? Is it a bug on io.quarkus:quarkus-logging-json? Just to know if we have to investigate on our side.

mcanzerini commented 3 months ago

Since I am still facing the issue, I keep investigating on my own and here are some additionnal infos:

I deactivated our JSON logging extension based on io.quarkus:quarkus-logging-json and redeployed my app on openshift. The NULL logs are still present (so I think it is not a problem with JSON logging):

2024-06-18 01:22:52,955 ERROR [io.ver.cor.htt.imp.HttpClientRequestImpl] (vert.x-eventloop-thread-0) NULL
2024-06-18 01:22:52,955 ERROR [io.ver.cor.net.imp.ConnectionBase] (vert.x-eventloop-thread-0) NULL

However, if I set the level of the logger to DEBUG, I can now have additionnal info about the error:

2024-06-18 01:22:52,955 ERROR [io.ver.cor.htt.imp.HttpClientRequestImpl] (vert.x-eventloop-thread-0) NULL
2024-06-18 01:22:52,955 ERROR [io.ver.cor.net.imp.ConnectionBase] (vert.x-eventloop-thread-0) NULL: io.netty.channel.StacklessClosedChannelException
at io.netty.channel.AbstractChannel$AbstractUnsafe.write(Object, ChannelPromise)(Unknown Source)
2024-06-18 01:22:52,956 ERROR [io.ver.cor.net.imp.ConnectionBase] (vert.x-eventloop-thread-0) NULL: io.netty.channel.StacklessClosedChannelException
at io.netty.channel.AbstractChannel.close(ChannelPromise)(Unknown Source)

Can someone help me on this please? I would like to be sure there is no bug in background.

Thanks a lot