[TASK][TRIVIAL] Add thread name and ID to log4j2-defaults.xml #5425
Description
Code of Conduct
- I agree to follow this project's Code of Conduct
Search before asking
- I have searched in the issues and found no similar issues.
What would you like to be improved?
Kyuubi has many thread pools for frontends and backends. So without thread name and ID, logs are barely recognizable for each executions. Following logs are extracted from our testbed:
2023-10-16 15:33:33.356 INFO org.apache.curator.framework.imps.CuratorFrameworkImpl: backgroundOperationsLoop exiting
2023-10-16 15:33:33.358 INFO org.apache.zookeeper.ZooKeeper: Session: 0x1091d27535d0219 closed
2023-10-16 15:33:33.358 INFO org.apache.zookeeper.ClientCnxn: EventThread shut down for session: 0x1091d27535d0219
2023-10-16 15:33:33.358 INFO org.apache.kyuubi.operation.LaunchEngine: Processing autouser1%40nexr.com's query[2de35865-10db-47b0-a5b5-6e47022d8c62]: RUNNING_STATE -> FINISHED_STATE, time taken: 0.041 seconds
2023-10-16 15:33:33.362 INFO org.apache.kyuubi.operation.log.OperationLog: Creating operation log file /opt/kyuubi/work/server_operation_logs/f376c0ae-70f5-4ef5-b25b-9f76651f8113/9310c484-057a-48a8-8b77-4d6ebe17823e
2023-10-16 15:33:33.362 INFO org.apache.kyuubi.session.KyuubiSessionImpl: [autouser1%40nexr.com:10.233.122.47] SessionHandle [f376c0ae-70f5-4ef5-b25b-9f76651f8113] - Starting to wait the launch engine operation finished
2023-10-16 15:33:33.362 INFO org.apache.kyuubi.session.KyuubiSessionImpl: [autouser1%40nexr.com:10.233.122.47] SessionHandle [f376c0ae-70f5-4ef5-b25b-9f76651f8113] - Engine has been launched, elapsed time: 0 s
2023-10-16 15:33:33.364 INFO org.apache.kyuubi.operation.ExecuteStatement: Processing autouser1%40nexr.com's query[9310c484-057a-48a8-8b77-4d6ebe17823e]: PENDING_STATE -> RUNNING_STATE, statement:
set spark.ndap.query.invoker=WORKFLOW
2023-10-16 15:33:33.386 INFO org.apache.kyuubi.operation.ExecuteStatement: Query[9310c484-057a-48a8-8b77-4d6ebe17823e] in FINISHED_STATE
2023-10-16 15:33:33.387 INFO org.apache.kyuubi.operation.ExecuteStatement: Processing autouser1%40nexr.com's query[9310c484-057a-48a8-8b77-4d6ebe17823e]: RUNNING_STATE -> FINISHED_STATE, time taken: 0.023 seconds
2023-10-16 15:33:33.389 INFO org.apache.kyuubi.operation.ExecuteStatement: Processing autouser1%40nexr.com's query[9310c484-057a-48a8-8b77-4d6ebe17823e]: FINISHED_STATE -> CLOSED_STATE, time taken: 0.025 seconds
2023-10-16 15:33:33.391 INFO org.apache.kyuubi.client.KyuubiSyncThriftClient: TCloseOperationReq(operationHandle:TOperationHandle(operationId:THandleIdentifier(guid:AD 54 B4 22 A8 E2 43 84 84 C5 BF 77 F4 C8 42 AA, secret:C2 EE 5B 97 3E A0 41 FC AC 16 9B D7 08 ED 8F 38), operationType:EXECUTE_STATEMENT, hasResultSet:true)) succeed on engine side
2023-10-16 15:33:33.392 INFO org.apache.kyuubi.operation.log.OperationLog: Creating operation log file /opt/kyuubi/work/server_operation_logs/f376c0ae-70f5-4ef5-b25b-9f76651f8113/50015686-0028-4d9c-9ef9-d16386f0beeb
2023-10-16 15:33:33.393 INFO org.apache.kyuubi.operation.ExecuteStatement: Processing autouser1%40nexr.com's query[50015686-0028-4d9c-9ef9-d16386f0beeb]: PENDING_STATE -> RUNNING_STATE, statement:
How should we improve?
Just add thread name and ID, logs are filterable for exact execution like this:
$ cat kyuubi-server.log | grep Thread-111
2023-10-16 05:40:15.844 KyuubiSessionManager-exec-pool: Thread-111 INFO org.apache.kyuubi.operation.LaunchEngine: Processing autouser1's query[22ffc72b-b315-41e6-8a62-cc1fe01e6322]: PENDING_STATE -> RUNNING_STATE, statement:
2023-10-16 05:40:15.845 KyuubiSessionManager-exec-pool: Thread-111 INFO org.apache.curator.framework.imps.CuratorFrameworkImpl: Starting
2023-10-16 05:40:15.846 KyuubiSessionManager-exec-pool: Thread-111 INFO org.apache.zookeeper.ZooKeeper: Initiating client connection, connectString=zookeeper-0.zookeeper-headless:2181,zookeeper-1.zookeeper-headless:2181,zookeeper-2.zookeeper-headless:2181 sessionTimeout=60000 watcher=org.apache.curator.ConnectionState@2c31871f
2023-10-16 05:40:15.849 KyuubiSessionManager-exec-pool: Thread-111-SendThread(zookeeper-1.zookeeper-headless:2181) INFO org.apache.zookeeper.ClientCnxn: Opening socket connection to server zookeeper-1.zookeeper-headless/10.233.124.53:2181. Will not attempt to authenticate using SASL (unknown error)
2023-10-16 05:40:15.850 KyuubiSessionManager-exec-pool: Thread-111 INFO org.apache.kyuubi.session.KyuubiSessionImpl: [autouser1:10.233.124.7] SessionHandle [9fdf4e08-7179-4ac7-8b66-9cbd4ec84fe0] - trying to get or create engine
2023-10-16 05:40:15.850 KyuubiSessionManager-exec-pool: Thread-111-SendThread(zookeeper-1.zookeeper-headless:2181) INFO org.apache.zookeeper.ClientCnxn: Socket connection established to zookeeper-1.zookeeper-headless/10.233.124.53:2181, initiating session
2023-10-16 05:40:15.852 KyuubiSessionManager-exec-pool: Thread-111-SendThread(zookeeper-1.zookeeper-headless:2181) INFO org.apache.zookeeper.ClientCnxn: Session establishment complete on server zookeeper-1.zookeeper-headless/10.233.124.53:2181, sessionid = 0x207b8b7e6ac20a5, negotiated timeout = 40000
2023-10-16 05:40:15.852 KyuubiSessionManager-exec-pool: Thread-111-EventThread INFO org.apache.curator.framework.state.ConnectionStateManager: State change: CONNECTED
2023-10-16 05:40:15.857 KyuubiSessionManager-exec-pool: Thread-111 INFO org.apache.kyuubi.ha.client.zookeeper.ZookeeperDiscoveryClient: Get service instance:10.233.120.179:38117 and version:Some(1.6.1-incubating) under /kyuubi_1.6.1-incubating_USER_SPARK_SQL/autouser1/default
2023-10-16 05:40:15.871 KyuubiSessionManager-exec-pool: Thread-111 INFO org.apache.kyuubi.session.KyuubiSessionImpl: [autouser1:10.233.124.7] SessionHandle [9fdf4e08-7179-4ac7-8b66-9cbd4ec84fe0] - Connected to engine [10.233.120.179:38117]/[spark-87519754031b4a9cb29b42602a3e3a1d] with SessionHandle [7a3a5d60-e6fb-4afd-9c16-ca37678a2770]]
2023-10-16 05:40:15.873 KyuubiSessionManager-exec-pool: Thread-111 INFO org.apache.zookeeper.ZooKeeper: Session: 0x207b8b7e6ac20a5 closed
2023-10-16 05:40:15.873 KyuubiSessionManager-exec-pool: Thread-111-EventThread INFO org.apache.zookeeper.ClientCnxn: EventThread shut down for session: 0x207b8b7e6ac20a5
2023-10-16 05:40:15.873 KyuubiSessionManager-exec-pool: Thread-111 INFO org.apache.kyuubi.operation.LaunchEngine: Processing autouser1's query[22ffc72b-b315-41e6-8a62-cc1fe01e6322]: RUNNING_STATE -> FINISHED_STATE, time taken: 0.029 seconds
I just add %tn to PatternLayout. I think we should provide this to default for more easy looking.
Are you willing to submit PR?
- Yes. I would be willing to submit a PR with guidance from the Kyuubi community to improve.
- No. I cannot submit a PR at this time.