(Answering now from my work email so please don't be confused.) The topic is already existing.
-----Original Message----- From: Jaikiran Pai [mailto:jai.forums2...@gmail.com] Sent: Sunday, November 5, 2017 10:56 PM To: users@kafka.apache.org Subject: [EXTERNAL]Re: 0.9.0.0 Log4j appender slow startup 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:\kafkadem > oworkspace\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 >
