minyk opened a new issue, #5425: URL: https://github.com/apache/kyuubi/issues/5425
### Code of Conduct - [X] I agree to follow this project's [Code of Conduct](https://www.apache.org/foundation/policies/conduct) ### Search before asking - [X] I have searched in the [issues](https://github.com/apache/kyuubi/issues?q=is%3Aissue) 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? - [X] 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. -- This is an automated message from the Apache Git Service. To respond to the message, please log on to GitHub and use the URL above to go to the specific comment. To unsubscribe, e-mail: [email protected] For queries about this service, please contact Infrastructure at: [email protected] --------------------------------------------------------------------- To unsubscribe, e-mail: [email protected] For additional commands, e-mail: [email protected]
