Onur Karaman created KAFKA-4891:
-----------------------------------
Summary: kafka.request.logger TRACE regression
Key: KAFKA-4891
URL: https://issues.apache.org/jira/browse/KAFKA-4891
Project: Kafka
Issue Type: Bug
Reporter: Onur Karaman
Assignee: Onur Karaman
Here's what kafka-request.log shows with {{kafka.request.logger}} set to TRACE:
{code}
[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)
{code}
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|https://github.com/apache/kafka/commit/fc1cfe475e8ae8458d8ddf119ce18d0c64653a70]
The logs should look something like this:
{code}
[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)
{code}
--
This message was sent by Atlassian JIRA
(v6.3.15#6346)
