Is the topic to which the message is being produced, already present or
is it auto created?
-Jaikiran
On 05/11/17 3:43 PM, Dale wrote:
I am using the 0.9.0.0 log4j appender for Kafka because I have a lot of apps
dependent on log4j 1.2.x that cannot be upgraded to use newer versions of
log4j. It appears that the appender has become part of log4j code in later
versions of both tools.
When I start my test app, the first message takes an exact and consistent 60
seconds plus a couple milliseconds to go out. The second message takes right
around 200 milliseconds, and all the messages after that take a couple of
milliseconds. The timing from message 1 to 2 could be tolerated but the 60
seconds will never work since the production use case app would typically run
for 20 to 30 seconds.
For testing, I brought the appender code into my project and added some
additional console messages so I could see what is going on. Here’s a snippet
of the console output:
********START LOG SNIPPET***********
G:\kafkademoworkspace\testlog4jgenerator>java -Dlog4j.debug
-Dlog4j.configuration=file:///g:\kafkademoworkspace\testlog4jgenerator\log4j.properties
-cp
.\;G:\kafkademoworkspace\testlog4jgenerator\target\testlog4jgenerator.jar;g:\kafkademoworkspace\testlog4jgenerator\target\libs\log4j-1.2.17.jar;g:\kafkademoworkspace\testlog4jgenerator\target\libs\*;g:\kafkademoworkspace\testlog4jgenerator\target\libs\kafka-clients-0.9.0.0.jar
com.mydomainname.messaging.testlog4jgenerator.LogGenerator
log4j: Using URL
[file:/g:/kafkademoworkspace/testlog4jgenerator/log4j.properties] for automatic
log4j configuration.
log4j: Reading configuration from URL
file:/g:/kafkademoworkspace/testlog4jgenerator/log4j.properties
log4j: Parsing for [root] with value=[DEBUG,file,KAFKA].
log4j: Level token is [DEBUG].
log4j: Category root set to DEBUG
log4j: Parsing appender named "file".
log4j: Parsing layout options for "file".
log4j: Setting property [conversionPattern] to [%d{yyyy-MM-dd HH:mm:ss,SSS}
%-5p %c{1}:%L - %m%n].
log4j: End of parsing for "file".
log4j: Setting property [file] to [/apps/logs/logtest.log].
log4j: Setting property [maxBackupIndex] to [10].
log4j: Setting property [maxFileSize] to [10MB].
log4j: setFile called: /apps/logs/logtest.log, true
log4j: setFile ended
log4j: Parsed "file" options.
log4j: Parsing appender named "KAFKA".
log4j: Parsing layout options for "KAFKA".
log4j: Setting property [conversionPattern] to [%d{yyyy-MM-dd HH:mm:ss,SSS}
%-5p %c{1}:%L - %m%n].
log4j: End of parsing for "KAFKA".
log4j: Setting property [compressionType] to [none].
log4j: Setting property [topic] to [test].
log4j: Setting property [brokerList] to [localhost:9092].
log4j: Setting property [syncSend] to [false].
DPLOG: 2017-11-05T09:56:16.072Z - in Producer - creating new KafkaProducer
log4j: Kafka producer connected to localhost:9092
log4j: Logging for topic: test
log4j: Parsed "KAFKA" options.
log4j: Finished configuring.
****************************************************************
DPLOG: 2017-11-05T09:56:16.338Z - append START
DPLOG: 2017-11-05T09:56:16.339Z - after subAppend. Message is: 2017-11-05
03:56:16,333 DEBUG Sender:123 - Starting Kafka producer I/O thread.
log4j: [Sun Nov 05 03:56:16 CST 2017]2017-11-05 03:56:16,333 DEBUG Sender:123 -
Starting Kafka producer I/O thread.
DPLOG: 2017-11-05T09:56:16.342Z - getting ready to send to producer.
DPLOG: 2017-11-05T09:57:16.347Z - after send to producer.
DPLOG: 2017-11-05T09:57:16.348Z - append END
****************************************************************
DPLOG: 2017-11-05T09:57:16.352Z - append START
DPLOG: 2017-11-05T09:57:16.353Z - after subAppend. Message is: 2017-11-05
03:56:16,338 INFO root:36 - Logging message: x=0
log4j: [Sun Nov 05 03:56:16 CST 2017]2017-11-05 03:56:16,338 INFO root:36 -
Logging message: x=0
DPLOG: 2017-11-05T09:57:16.361Z - getting ready to send to producer.
DPLOG: 2017-11-05T09:57:16.526Z - after send to producer.
DPLOG: 2017-11-05T09:57:16.526Z - append END
****************************************************************
DPLOG: 2017-11-05T09:57:16.527Z - append START
DPLOG: 2017-11-05T09:57:16.528Z - after subAppend. Message is: 2017-11-05
03:57:16,527 INFO root:36 - Logging message: x=1
log4j: [Sun Nov 05 03:57:16 CST 2017]2017-11-05 03:57:16,527 INFO root:36 -
Logging message: x=1
DPLOG: 2017-11-05T09:57:16.529Z - getting ready to send to producer.
DPLOG: 2017-11-05T09:57:16.530Z - after send to producer.
DPLOG: 2017-11-05T09:57:16.530Z - append END
****************************************************************
DPLOG: 2017-11-05T09:57:16.531Z - append START
DPLOG: 2017-11-05T09:57:16.531Z - after subAppend. Message is: 2017-11-05
03:57:16,531 INFO root:36 - Logging message: x=2
log4j: [Sun Nov 05 03:57:16 CST 2017]2017-11-05 03:57:16,531 INFO root:36 -
Logging message: x=2
DPLOG: 2017-11-05T09:57:16.532Z - getting ready to send to producer.
DPLOG: 2017-11-05T09:57:16.533Z - after send to producer.
DPLOG: 2017-11-05T09:57:16.535Z - append END
****************************************************************
DPLOG: 2017-11-05T09:57:16.536Z - append START
DPLOG: 2017-11-05T09:57:16.536Z - after subAppend. Message is: 2017-11-05
03:57:16,536 INFO root:36 - Logging message: x=3
log4j: [Sun Nov 05 03:57:16 CST 2017]2017-11-05 03:57:16,536 INFO root:36 -
Logging message: x=3
DPLOG: 2017-11-05T09:57:16.538Z - getting ready to send to producer.
DPLOG: 2017-11-05T09:57:16.538Z - after send to producer.
DPLOG: 2017-11-05T09:57:16.538Z - append END
****************************************************************
DPLOG: 2017-11-05T09:57:16.539Z - append START
DPLOG: 2017-11-05T09:57:16.540Z - after subAppend. Message is: 2017-11-05
03:57:16,539 INFO root:36 - Logging message: x=4
log4j: [Sun Nov 05 03:57:16 CST 2017]2017-11-05 03:57:16,539 INFO root:36 -
Logging message: x=4
DPLOG: 2017-11-05T09:57:16.541Z - getting ready to send to producer.
DPLOG: 2017-11-05T09:57:16.542Z - after send to producer.
DPLOG: 2017-11-05T09:57:16.542Z - append END
****************************************************************
********END LOG SNIPPET***********
The code, modified for logging, for sending to the producer is:
********START CODE SNIPPET***********
System.out.println("DPLOG: " + Instant.now().toString() + " - getting ready to send
to producer.");
Future<RecordMetadata> response = producer.send(new ProducerRecord<byte[],
byte[]>(topic, message.getBytes()));
System.out.println("DPLOG: " + Instant.now().toString() + " - after send to
producer.");
********END CODE SNIPPET***********
I have not been able to find any timeout of 60 seconds (60000 ms) anywhere but
it is clear that something is happening that is exactly 60 seconds at the start
of the run. Whatever the timeout is, it is not breaking because the messages
are sent to kafka. I’ve searched the KafkaProducer code and kafka server
configuration looking for any 60 second timeout reference and cannot find one.
In what few examples I could find online of log data using the producer, I see
the Starting kafka producer I/O thread with the next log entries in the same
second so the 60 second delay I am seeing does not always appear to be there
but it’s always there in my case. Any ideas what could be causing it and/or
how I can get rid of it?
Thanks,
Dale
