[KAFKA-4891] kafka.request.logger TRACE regression

• Type: Bug
• Status: Resolved
• Priority: Major
• Resolution: Fixed
• Fix Version/s: 0.11.0.0
• Assignee: Onur Karaman
• Reporter: Onur Karaman
• Created: 13/Mar/17 17:27
• Updated: 13/Mar/17 20:04
• Resolved: 13/Mar/17 20:04

Description

Here's what kafka-request.log shows with kafka.request.logger set to TRACE:

[2017-03-13 10:06:24,402] TRACE Completed request:org.apache.kafka.common.requests.RequestHeader@2f99ef87 -- org.apache.kafka.common.requests.LeaderAndIsrRequest@34c40fc5 from connection 127.0.0.1:9090-127.0.0.1:50969;totalTime:125,requestQueueTime:0,localTime:124,remoteTime:0,responseQueueTime:0,sendTime:1,securityProtocol:PLAINTEXT,principal:User:ANONYMOUS,listener:PLAINTEXT (kafka.request.logger)
[2017-03-13 10:06:24,406] TRACE Completed request:org.apache.kafka.common.requests.RequestHeader@133b1de8 -- org.apache.kafka.common.requests.UpdateMetadataRequest@795826d from connection 127.0.0.1:9090-127.0.0.1:50969;totalTime:3,requestQueueTime:0,localTime:2,remoteTime:0,responseQueueTime:0,sendTime:1,securityProtocol:PLAINTEXT,principal:User:ANONYMOUS,listener:PLAINTEXT (kafka.request.logger)
[2017-03-13 10:06:24,943] TRACE Completed request:org.apache.kafka.common.requests.RequestHeader@76a9acaa -- org.apache.kafka.common.requests.FetchRequest@33ab3c1b from connection 127.0.0.1:9090-127.0.0.1:50976;totalTime:522,requestQueueTime:0,localTime:13,remoteTime:506,responseQueueTime:0,sendTime:1,securityProtocol:PLAINTEXT,principal:User:ANONYMOUS,listener:PLAINTEXT (kafka.request.logger)

Both the headers and requests have regressed to just show object ids instead of their contents from their underlying structs. I'm guessing this regression came from commit fc1cfe475e8ae8458d8ddf119ce18d0c64653a70

The logs should look something like this:

[2017-03-13 10:14:36,754] TRACE Completed request:{api_key=4,api_version=0,correlation_id=2,client_id=0} -- {controller_id=0,controller_epoch=1,partition_states=[{topic=t,partition=5,controller_epoch=1,leader=1,leader_epoch=0,isr=[1,0],zk_version=0,replicas=[0,1]},{topic=t,partition=4,controller_epoch=1,leader=0,leader_epoch=0,isr=[0,1],zk_version=0,replicas=[0,1]},{topic=t,partition=3,controller_epoch=1,leader=1,leader_epoch=0,isr=[1,0],zk_version=0,replicas=[0,1]},{topic=t,partition=2,controller_epoch=1,leader=0,leader_epoch=0,isr=[0,1],zk_version=0,replicas=[0,1]},{topic=t,partition=1,controller_epoch=1,leader=1,leader_epoch=0,isr=[1,0],zk_version=0,replicas=[0,1]},{topic=t,partition=0,controller_epoch=1,leader=0,leader_epoch=0,isr=[0,1],zk_version=0,replicas=[0,1]},{topic=t,partition=7,controller_epoch=1,leader=1,leader_epoch=0,isr=[1,0],zk_version=0,replicas=[0,1]},{topic=t,partition=6,controller_epoch=1,leader=0,leader_epoch=0,isr=[0,1],zk_version=0,replicas=[0,1]}],live_leaders=[{id=0,host=localhost,port=9090},{id=1,host=localhost,port=9091}]} from connection 127.0.0.1:9090-127.0.0.1:51349;totalTime:155,requestQueueTime:0,localTime:155,remoteTime:0,responseQueueTime:0,sendTime:0,securityProtocol:PLAINTEXT,principal:User:ANONYMOUS,listener:PLAINTEXT (kafka.request.logger)
[2017-03-13 10:14:36,758] TRACE Completed request:{api_key=6,api_version=3,correlation_id=3,client_id=0} -- {controller_id=0,controller_epoch=1,partition_states=[{topic=t,partition=5,controller_epoch=1,leader=1,leader_epoch=0,isr=[1,0],zk_version=0,replicas=[0,1]},{topic=t,partition=4,controller_epoch=1,leader=0,leader_epoch=0,isr=[0,1],zk_version=0,replicas=[0,1]},{topic=t,partition=3,controller_epoch=1,leader=1,leader_epoch=0,isr=[1,0],zk_version=0,replicas=[0,1]},{topic=t,partition=2,controller_epoch=1,leader=0,leader_epoch=0,isr=[0,1],zk_version=0,replicas=[0,1]},{topic=t,partition=1,controller_epoch=1,leader=1,leader_epoch=0,isr=[1,0],zk_version=0,replicas=[0,1]},{topic=t,partition=0,controller_epoch=1,leader=0,leader_epoch=0,isr=[0,1],zk_version=0,replicas=[0,1]},{topic=t,partition=7,controller_epoch=1,leader=1,leader_epoch=0,isr=[1,0],zk_version=0,replicas=[0,1]},{topic=t,partition=6,controller_epoch=1,leader=0,leader_epoch=0,isr=[0,1],zk_version=0,replicas=[0,1]}],live_brokers=[{id=1,end_points=[{port=9091,host=localhost,listener_name=PLAINTEXT,security_protocol_type=0}],rack=null},{id=0,end_points=[{port=9090,host=localhost,listener_name=PLAINTEXT,security_protocol_type=0}],rack=null}]} from connection 127.0.0.1:9090-127.0.0.1:51349;totalTime:3,requestQueueTime:1,localTime:2,remoteTime:0,responseQueueTime:0,sendTime:0,securityProtocol:PLAINTEXT,principal:User:ANONYMOUS,listener:PLAINTEXT (kafka.request.logger)
[2017-03-13 10:14:37,297] TRACE Completed request:{api_key=1,api_version=3,correlation_id=0,client_id=ReplicaFetcherThread-0-0} -- {replica_id=1,max_wait_time=500,min_bytes=1,max_bytes=10485760,topics=[{topic=t,partitions=[{partition=6,fetch_offset=0,max_bytes=1048576},{partition=4,fetch_offset=0,max_bytes=1048576},{partition=2,fetch_offset=0,max_bytes=1048576},{partition=0,fetch_offset=0,max_bytes=1048576}]}]} from connection 127.0.0.1:9090-127.0.0.1:51361;totalTime:524,requestQueueTime:1,localTime:14,remoteTime:506,responseQueueTime:0,sendTime:1,securityProtocol:PLAINTEXT,principal:User:ANONYMOUS,listener:PLAINTEXT (kafka.request.logger)

Issue Links

• links to: GitHub Pull Request #2678