[
https://issues.apache.org/jira/browse/ZOOKEEPER-4557?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Shinya Yoshida updated ZOOKEEPER-4557:
--------------------------------------
Description:
In 3.8.0, zookeeper migrated from log4j to logback in ZOOKEEPER-4427.
Unfortunately, logback doesn't use InheritableThreadLocal for MDC
implementation because it's too dangerous unlike log4j does.
https://jira.qos.ch/browse/LOGBACK-422
https://jira.qos.ch/browse/LOGBACK-624
This causes incompatibility of logging behavior.
Now we missed pretty myid MDC in the logs.
You can easily reproduce this issue by just downloading the zookeeper artifact
and start-up locally.
Zookeeper 3.7.1:
{code:java}
2022-06-14 15:28:04,279 [myid:1] - INFO
[ListenerHandler-localhost/127.0.0.1:3888:QuorumCnxManager$Listener$ListenerHandler@1071]
- 1 is accepting connections now, my election bind port:
localhost/127.0.0.1:3888
2022-06-14 15:28:04,280 [myid:1] - INFO [main:ZKAuditProvider@42] - ZooKeeper
audit is disabled.
2022-06-14 15:28:04,284 [myid:1] - INFO
[QuorumPeer[myid=1](plain=[0:0:0:0:0:0:0:0]:2181)(secure=disabled):QuorumPeer@1438]
- LOOKING
2022-06-14 15:28:04,284 [myid:1] - INFO
[QuorumPeer[myid=1](plain=[0:0:0:0:0:0:0:0]:2181)(secure=disabled):FastLeaderElection@945]
- New election. My id = 1, proposed zxid=0x0
2022-06-14 15:28:04,290 [myid:1] - INFO
[WorkerReceiver[myid=1]:FastLeaderElection$Messenger$WorkerReceiver@390] -
Notification: my state:LOOKING; n.sid:1, n.state:LOOKING, n.leader:1,
n.round:0x1, n.peerEpoch:0x0, n.zxid:0x0, message format version:0x2, n.config
version:0x0
2022-06-14 15:28:04,292 [myid:1] - WARN
[QuorumConnectionThread-[myid=1]-2:QuorumCnxManager@401] - Cannot open channel
to 3 at election address localhost/127.0.0.1:3890
{code}
zookeeper 3.8.0
{code:java}
2022-06-14 15:28:51,461 [myid:] - INFO
[ListenerHandler-localhost/127.0.0.1:3888:o.a.z.s.q.QuorumCnxManager$Listener$ListenerHandler@1071]
- 1 is accepting connections now, my election bind port:
localhost/127.0.0.1:3888
2022-06-14 15:28:51,463 [myid:1] - INFO [main:o.a.z.a.ZKAuditProvider@42] -
ZooKeeper audit is disabled.
2022-06-14 15:28:51,467 [myid:] - INFO
[QuorumPeer[myid=1](plain=[0:0:0:0:0:0:0:0]:2181)(secure=disabled):o.a.z.s.q.QuorumPeer@1455]
- LOOKING
2022-06-14 15:28:51,467 [myid:] - INFO
[QuorumPeer[myid=1](plain=[0:0:0:0:0:0:0:0]:2181)(secure=disabled):o.a.z.s.q.FastLeaderElection@946]
- New election. My id = 1, proposed zxid=0x0
2022-06-14 15:28:51,469 [myid:] - INFO
[WorkerReceiver[myid=1]:o.a.z.s.q.FastLeaderElection$Messenger$WorkerReceiver@391]
- Notification: my state:LOOKING; n.sid:1, n.state:LOOKING, n.leader:1,
n.round:0x1, n.peerEpoch:0x0, n.zxid:0x0, message format version:0x2, n.config
version:0x0
2022-06-14 15:28:51,475 [myid:] - WARN
[QuorumConnectionThread-[myid=1]-1:o.a.z.s.q.QuorumCnxManager@401] - Cannot
open channel to 2 at election address localhost/127.0.0.1:3889
{code}
Now we couldn't see myid in the most of logs.
We need to propagate myid MDC to other threads in the code.
was:
In 3.8.0, zookeeper is migrated from log4j to logback in ZOOKEEPER-4427.
Unfortunately, logback doesn't use InheritableThreadLocal for MDC
implementation because it's too dangerous unlike log4j does.
https://jira.qos.ch/browse/LOGBACK-422
https://jira.qos.ch/browse/LOGBACK-624
This causes incompatibility of logging behavior.
Now we missed pretty myid MDC in the logs.
You can easily reproduce this issue by just downloading the zookeeper artifact
and start-up locally.
Zookeeper 3.7.1:
{code:java}
2022-06-14 15:28:04,279 [myid:1] - INFO
[ListenerHandler-localhost/127.0.0.1:3888:QuorumCnxManager$Listener$ListenerHandler@1071]
- 1 is accepting connections now, my election bind port:
localhost/127.0.0.1:3888
2022-06-14 15:28:04,280 [myid:1] - INFO [main:ZKAuditProvider@42] - ZooKeeper
audit is disabled.
2022-06-14 15:28:04,284 [myid:1] - INFO
[QuorumPeer[myid=1](plain=[0:0:0:0:0:0:0:0]:2181)(secure=disabled):QuorumPeer@1438]
- LOOKING
2022-06-14 15:28:04,284 [myid:1] - INFO
[QuorumPeer[myid=1](plain=[0:0:0:0:0:0:0:0]:2181)(secure=disabled):FastLeaderElection@945]
- New election. My id = 1, proposed zxid=0x0
2022-06-14 15:28:04,290 [myid:1] - INFO
[WorkerReceiver[myid=1]:FastLeaderElection$Messenger$WorkerReceiver@390] -
Notification: my state:LOOKING; n.sid:1, n.state:LOOKING, n.leader:1,
n.round:0x1, n.peerEpoch:0x0, n.zxid:0x0, message format version:0x2, n.config
version:0x0
2022-06-14 15:28:04,292 [myid:1] - WARN
[QuorumConnectionThread-[myid=1]-2:QuorumCnxManager@401] - Cannot open channel
to 3 at election address localhost/127.0.0.1:3890
{code}
zookeeper 3.8.0
{code:java}
2022-06-14 15:28:51,461 [myid:] - INFO
[ListenerHandler-localhost/127.0.0.1:3888:o.a.z.s.q.QuorumCnxManager$Listener$ListenerHandler@1071]
- 1 is accepting connections now, my election bind port:
localhost/127.0.0.1:3888
2022-06-14 15:28:51,463 [myid:1] - INFO [main:o.a.z.a.ZKAuditProvider@42] -
ZooKeeper audit is disabled.
2022-06-14 15:28:51,467 [myid:] - INFO
[QuorumPeer[myid=1](plain=[0:0:0:0:0:0:0:0]:2181)(secure=disabled):o.a.z.s.q.QuorumPeer@1455]
- LOOKING
2022-06-14 15:28:51,467 [myid:] - INFO
[QuorumPeer[myid=1](plain=[0:0:0:0:0:0:0:0]:2181)(secure=disabled):o.a.z.s.q.FastLeaderElection@946]
- New election. My id = 1, proposed zxid=0x0
2022-06-14 15:28:51,469 [myid:] - INFO
[WorkerReceiver[myid=1]:o.a.z.s.q.FastLeaderElection$Messenger$WorkerReceiver@391]
- Notification: my state:LOOKING; n.sid:1, n.state:LOOKING, n.leader:1,
n.round:0x1, n.peerEpoch:0x0, n.zxid:0x0, message format version:0x2, n.config
version:0x0
2022-06-14 15:28:51,475 [myid:] - WARN
[QuorumConnectionThread-[myid=1]-1:o.a.z.s.q.QuorumCnxManager@401] - Cannot
open channel to 2 at election address localhost/127.0.0.1:3889
{code}
Now we couldn't see myid in the most of logs.
We need to propagate myid MDC to other threads in the code.
> MDC for myid is missing in children threads due to log4j vs logback
> incompatibility
> -----------------------------------------------------------------------------------
>
> Key: ZOOKEEPER-4557
> URL: https://issues.apache.org/jira/browse/ZOOKEEPER-4557
> Project: ZooKeeper
> Issue Type: Bug
> Affects Versions: 3.8.0
> Reporter: Shinya Yoshida
> Priority: Major
>
> In 3.8.0, zookeeper migrated from log4j to logback in ZOOKEEPER-4427.
> Unfortunately, logback doesn't use InheritableThreadLocal for MDC
> implementation because it's too dangerous unlike log4j does.
> https://jira.qos.ch/browse/LOGBACK-422
> https://jira.qos.ch/browse/LOGBACK-624
> This causes incompatibility of logging behavior.
> Now we missed pretty myid MDC in the logs.
> You can easily reproduce this issue by just downloading the zookeeper
> artifact and start-up locally.
> Zookeeper 3.7.1:
> {code:java}
> 2022-06-14 15:28:04,279 [myid:1] - INFO
> [ListenerHandler-localhost/127.0.0.1:3888:QuorumCnxManager$Listener$ListenerHandler@1071]
> - 1 is accepting connections now, my election bind port:
> localhost/127.0.0.1:3888
> 2022-06-14 15:28:04,280 [myid:1] - INFO [main:ZKAuditProvider@42] -
> ZooKeeper audit is disabled.
> 2022-06-14 15:28:04,284 [myid:1] - INFO
> [QuorumPeer[myid=1](plain=[0:0:0:0:0:0:0:0]:2181)(secure=disabled):QuorumPeer@1438]
> - LOOKING
> 2022-06-14 15:28:04,284 [myid:1] - INFO
> [QuorumPeer[myid=1](plain=[0:0:0:0:0:0:0:0]:2181)(secure=disabled):FastLeaderElection@945]
> - New election. My id = 1, proposed zxid=0x0
> 2022-06-14 15:28:04,290 [myid:1] - INFO
> [WorkerReceiver[myid=1]:FastLeaderElection$Messenger$WorkerReceiver@390] -
> Notification: my state:LOOKING; n.sid:1, n.state:LOOKING, n.leader:1,
> n.round:0x1, n.peerEpoch:0x0, n.zxid:0x0, message format version:0x2,
> n.config version:0x0
> 2022-06-14 15:28:04,292 [myid:1] - WARN
> [QuorumConnectionThread-[myid=1]-2:QuorumCnxManager@401] - Cannot open
> channel to 3 at election address localhost/127.0.0.1:3890
> {code}
> zookeeper 3.8.0
> {code:java}
> 2022-06-14 15:28:51,461 [myid:] - INFO
> [ListenerHandler-localhost/127.0.0.1:3888:o.a.z.s.q.QuorumCnxManager$Listener$ListenerHandler@1071]
> - 1 is accepting connections now, my election bind port:
> localhost/127.0.0.1:3888
> 2022-06-14 15:28:51,463 [myid:1] - INFO [main:o.a.z.a.ZKAuditProvider@42] -
> ZooKeeper audit is disabled.
> 2022-06-14 15:28:51,467 [myid:] - INFO
> [QuorumPeer[myid=1](plain=[0:0:0:0:0:0:0:0]:2181)(secure=disabled):o.a.z.s.q.QuorumPeer@1455]
> - LOOKING
> 2022-06-14 15:28:51,467 [myid:] - INFO
> [QuorumPeer[myid=1](plain=[0:0:0:0:0:0:0:0]:2181)(secure=disabled):o.a.z.s.q.FastLeaderElection@946]
> - New election. My id = 1, proposed zxid=0x0
> 2022-06-14 15:28:51,469 [myid:] - INFO
> [WorkerReceiver[myid=1]:o.a.z.s.q.FastLeaderElection$Messenger$WorkerReceiver@391]
> - Notification: my state:LOOKING; n.sid:1, n.state:LOOKING, n.leader:1,
> n.round:0x1, n.peerEpoch:0x0, n.zxid:0x0, message format version:0x2,
> n.config version:0x0
> 2022-06-14 15:28:51,475 [myid:] - WARN
> [QuorumConnectionThread-[myid=1]-1:o.a.z.s.q.QuorumCnxManager@401] - Cannot
> open channel to 2 at election address localhost/127.0.0.1:3889
> {code}
> Now we couldn't see myid in the most of logs.
> We need to propagate myid MDC to other threads in the code.
--
This message was sent by Atlassian Jira
(v8.20.7#820007)
