Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

[TASK][TRIVIAL] Add thread name and ID to log4j2-defaults.xml #5425

Closed
3 of 4 tasks
minyk opened this issue Oct 16, 2023 · 0 comments
Closed
3 of 4 tasks

[TASK][TRIVIAL] Add thread name and ID to log4j2-defaults.xml #5425

minyk opened this issue Oct 16, 2023 · 0 comments
Assignees

Comments

@minyk
Copy link
Contributor

minyk commented Oct 16, 2023

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.
@pan3793 pan3793 changed the title [Improvement] Add thread name and ID to log4j2-defaults.xml [TASK][TRIVIAL] Add thread name and ID to log4j2-defaults.xml Oct 16, 2023
pan3793 pushed a commit that referenced this issue Oct 16, 2023
### _Why are the changes needed?_

Add `%tn` to `log4j2-defaults.xml` for more informations.

This close #5425

### _How was this patch tested?_
- [ ] Add some test cases that check the changes thoroughly including negative and positive cases if possible

- [X] Add screenshots for manual tests if appropriate
![Screenshot 2023-10-16 at 6 05 00 PM](https://github.com/apache/kyuubi/assets/1802676/0d155d40-78f5-4f9f-beea-f592e409e523)

- [X] [Run test](https://kyuubi.readthedocs.io/en/master/contributing/code/testing.html#running-tests) locally before make a pull request

### _Was this patch authored or co-authored using generative AI tooling?_

No

Closes #5428 from minyk/kyuubi-5425.

Closes #5425

e42a4b2 [minyk] add thread name and id to log4j2.xml.template
705e86e [minyk] add thread name and id to log pattern

Authored-by: minyk <minykreva@gmail.com>
Signed-off-by: Cheng Pan <chengpan@apache.org>
(cherry picked from commit 64ea27c)
Signed-off-by: Cheng Pan <chengpan@apache.org>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
No open projects
Development

Successfully merging a pull request may close this issue.

2 participants