[
https://issues.apache.org/jira/browse/KAFKA-18066?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17943817#comment-17943817
]
Uladzislau Blok commented on KAFKA-18066:
-----------------------------------------
Hey [~ableegoldman] ,
I've taken a look at the problem and the proposed solution, and I'm not sure
how _moving things to the constructor_ would help—since the constructor code
will still be executed by the current thread (StreamThread-1 in your example).
My suggestion would be to use a logger without context in the {{create}} method.
Logs before the fix:
{code:java}
egrep main.*StreamThread kafka-test.log
953 [main] INFO o.a.k.s.p.internals.StreamThread - stream-thread
[streams-linesplit1-aa392bb8-ee8e-44af-9a85-41036d69b423-StreamThread-1]
Creating restore consumer client
1096 [main] INFO o.a.k.c.producer.KafkaProducer - [Producer
clientId=streams-linesplit1-aa392bb8-ee8e-44af-9a85-41036d69b423-StreamThread-1-producer]
Instantiated an idempotent producer.
1151 [main] INFO o.a.k.s.p.internals.StreamThread - stream-thread
[streams-linesplit1-aa392bb8-ee8e-44af-9a85-41036d69b423-StreamThread-1]
Creating consumer client {code}
Logs after change:
{code:java}
egrep main.*StreamThread kafka-test.log
973 [main] INFO o.a.k.s.p.internals.StreamThread - Creating restore consumer
client
1094 [main] INFO o.a.k.c.producer.KafkaProducer - [Producer
clientId=streams-linesplit1-f107dfdf-8786-46c3-97d4-16c6083e242a-StreamThread-1-producer]
Instantiated an idempotent producer.
1149 [main] INFO o.a.k.s.p.internals.StreamThread - Creating consumer client
{code}
> Misleading/mismatched StreamThread id in logging
> ------------------------------------------------
>
> Key: KAFKA-18066
> URL: https://issues.apache.org/jira/browse/KAFKA-18066
> Project: Kafka
> Issue Type: Bug
> Components: streams
> Reporter: A. Sophie Blee-Goldman
> Assignee: Uladzislau Blok
> Priority: Minor
> Labels: newbie, newbie++
>
> While debugging a test application I was confused to see a number of log
> lines where the StreamThread name appeared twice but had a different thread
> id/index in the same message. For example:
> {code:java}
> [INFO ] 2024-11-19 04:59:14.541
> [e2e-963c5b74-0353-4253-bdf2-b71881d9d9f2-StreamThread-1] StreamThread -
> stream-thread [e2e-963c5b74-0353-4253-bdf2-b71881d9d9f2-StreamThread-3]
> Creating thread producer client{code}
> Generally you would expect that the actual Logger prefix (the first thread
> name, in this case StreamThread-1) is the same as the LogContext prefix (the
> second thread name, ie the StreamThread-3 in this example). I dug into it and
> figured out that this happens for all of the messages logged during the
> StreamThread#create method, ie before the new thread is actually created.
> What happened was StreamThread-1 had actually died, and started up a new
> thread (StreamThread-3) to replace itself before shutting down. So we were
> logging things _about_ StreamThread-3, but _from_ StreamThread-1.
> While this doesn't necessarily harm anyone, it's quite confusing to see and
> requires extensive knowledge of Streams to understand (a) that it's not a
> bug, and (b) which thread the messages are actually referring to. It also
> makes things harder to parse and read – for example I often filter logs on
> the Logger prefix to gather everything related to a particular thread and eg
> the clients it owns. The name of the currently executing thread is more
> reliable and gathers everything whereas not every logger is configured with
> the LogContext prefix (eg `stream-thread
> [e2e-963c5b74-0353-4253-bdf2-b71881d9d9f2-StreamThread-3]`).
> We should move things out of the static StreamThread#create method and into
> the thread constructor to make the logging consistent and reliable.
--
This message was sent by Atlassian Jira
(v8.20.10#820010)
