Hi,

I am getting a deadlock in ChukwaDailyRollingFileAppender. The thread dump
is:

Found one Java-level deadlock:
============================"Thread-4":
  waiting to lock monitor 0x00007f1970004818 (object 0x00000000cb6669e8, a
java.lang.Class),
  which is held by "Thread for syncLogs"
"Thread for syncLogs":
  waiting to lock monitor 0x00007f1970004ea8 (object 0x00000000d65c44b8, a
org.apache.log4j.Logger),
  which is held by "main"
"main":
  waiting to lock monitor 0x00007f1970003d98 (object 0x00000000d65c3e80, a
org.apache.log4j.Logger),
  which is held by "communication thread"
"communication thread":
  waiting to lock monitor 0x0000000041eba250 (object 0x00000000d6736ec0, a
java.lang.Object),
  which is held by "main"

Java stack information for the threads listed above:
=================================================="Thread-4":
        at org.apache.hadoop.mapred.TaskLog.syncLogs(TaskLog.java:213)
        - waiting to lock <0x00000000cb6669e8> (a java.lang.Class for
org.apache.hadoop.mapred.TaskLog)
        at org.apache.hadoop.mapred.Child$1.run(Child.java:75)
"Thread for syncLogs":
        at org.apache.log4j.Category.getAllAppenders(Category.java:409)
        - waiting to lock <0x00000000d65c44b8> (a org.apache.log4j.Logger)
        at org.apache.hadoop.mapred.TaskLog.syncLogs(TaskLog.java:218)
        - locked <0x00000000cb6669e8> (a java.lang.Class for
org.apache.hadoop.mapred.TaskLog)
        at org.apache.hadoop.mapred.Child$2.run(Child.java:89)
"main":
        at org.apache.log4j.Category.callAppenders(Category.java:202)
        - waiting to lock <0x00000000d65c3e80> (a org.apache.log4j.Logger)
        at org.apache.log4j.Category.forcedLog(Category.java:388)
        at org.apache.log4j.Category.warn(Category.java:1008)
        at
org.apache.hadoop.chukwa.datacollection.controller.ChukwaAgentController.addByName(ChukwaAgentController.java:267)
        at
org.apache.hadoop.chukwa.inputtools.log4j.ChukwaDailyRollingFileAppender.subAppend(ChukwaDailyRollingFileAppender.java:565)
        - locked <0x00000000d6736ec0> (a java.lang.Object)
        at org.apache.log4j.WriterAppender.append(WriterAppender.java:159)
        at
org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:230)
        - locked <0x00000000d65b38c0> (a
com.glassdoor.chukwa.inputtools.log4j.GDChukwaDailyRollingFileAppender)
        at
org.apache.log4j.helpers.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:65)
        at org.apache.log4j.Category.callAppenders(Category.java:203)
        - locked <0x00000000d65c44b8> (a org.apache.log4j.Logger)
        at org.apache.log4j.Category.forcedLog(Category.java:388)
        at org.apache.log4j.Category.log(Category.java:853)
        at
org.apache.commons.logging.impl.Log4JLogger.warn(Log4JLogger.java:222)
        at
com.glassdoor.util.netsuite.service.NetSuiteServiceImpl.init(NetSuiteServiceImpl.java:86)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
        at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
        at java.lang.reflect.Method.invoke(Method.java:597)
        at
org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.invokeCustomInitMethod(AbstractAutowireCapableBeanFactory.java:1378)
        at
org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.invokeInitMethods(AbstractAutowireCapableBeanFactory.java:1339)
        at
org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.initializeBean(AbstractAutowireCapableBeanFactory.java:1299)
        at
org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.doCreateBean(AbstractAutowireCapableBeanFactory.java:463)
        at
org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory$1.run(AbstractAutowireCapableBeanFactory.java:404)
        at java.security.AccessController.doPrivileged(Native Method)
        at
org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBean(AbstractAutowireCapableBeanFactory.java:375)
        at
org.springframework.beans.factory.support.AbstractBeanFactory$1.getObject(AbstractBeanFactory.java:263)
        at
org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.getSingleton(DefaultSingletonBeanRegistry.java:170)
        - locked <0x00000000f77044f0> (a
java.util.concurrent.ConcurrentHashMap)
        at
org.springframework.beans.factory.support.AbstractBeanFactory.doGetBean(AbstractBeanFactory.java:260)
at
org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:184)
        at
org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:163)
        at
org.springframework.beans.factory.support.DefaultListableBeanFactory.preInstantiateSingletons(DefaultListableBeanFactory.java:430)
        - locked <0x00000000f7704520> (a
java.util.concurrent.ConcurrentHashMap)
        at
org.springframework.context.support.AbstractApplicationContext.finishBeanFactoryInitialization(AbstractApplicationContext.java:729)
        at
org.springframework.context.support.AbstractApplicationContext.refresh(AbstractApplicationContext.java:381)
        - locked <0x00000000f77045d8> (a java.lang.Object)
        at
org.springframework.context.support.ClassPathXmlApplicationContext.<init>(ClassPathXmlApplicationContext.java:139)
        at
org.springframework.context.support.ClassPathXmlApplicationContext.<init>(ClassPathXmlApplicationContext.java:93)
        at
com.glassdoor.util.hadoop.entity.GDHadoopConfiguration.getAppContext(GDHadoopConfiguration.java:74)
        - locked <0x00000000d6736ef0> (a java.lang.Object)
        at
com.glassdoor.util.hadoop.entity.SpringHadoopMapperWrapper.run(SpringHadoopMapperWrapper.java:116)
        at org.apache.hadoop.mapred.MapTask.runNewMapper(MapTask.java:621)

Hi Abhijit,

The dead lock happens when there are too many registrations with the
agent and agent has exceeded the open file descriptor limit.  I would
recommend to use Log4J SocketAppender with combination of
SocketAdaptor.  It reduces the overhead of file offset tracking and
reduces the number of file descriptors used by the agent.  It works
better than using ChukwaDailyFileAppender and file adaptor
combination.

regards,
Eric

On Fri, Jun 22, 2012 at 9:50 AM, Abhijit Dhar <[EMAIL PROTECTED]> wrote:
> Hi,
>
> I am getting a deadlock in ChukwaDailyRollingFileAppender. The thread dump
> is:
>
> Found one Java-level deadlock:
> ============================> "Thread-4":
>  waiting to lock monitor 0x00007f1970004818 (object 0x00000000cb6669e8, a
> java.lang.Class),
>  which is held by "Thread for syncLogs"
> "Thread for syncLogs":
>  waiting to lock monitor 0x00007f1970004ea8 (object 0x00000000d65c44b8, a
> org.apache.log4j.Logger),
>  which is held by "main"
> "main":
>  waiting to lock monitor 0x00007f1970003d98 (object 0x00000000d65c3e80, a
> org.apache.log4j.Logger),
>  which is held by "communication thread"
> "communication thread":
>  waiting to lock monitor 0x0000000041eba250 (object 0x00000000d6736ec0, a
> java.lang.Object),
>  which is held by "main"
>
> Java stack information for the threads listed above:
> ==================================================> "Thread-4":
>        at org.apache.hadoop.mapred.TaskLog.syncLogs(TaskLog.java:213)
>        - waiting to lock <0x00000000cb6669e8> (a java.lang.Class for
> org.apache.hadoop.mapred.TaskLog)
>        at org.apache.hadoop.mapred.Child$1.run(Child.java:75)
> "Thread for syncLogs":
>        at org.apache.log4j.Category.getAllAppenders(Category.java:409)
>        - waiting to lock <0x00000000d65c44b8> (a org.apache.log4j.Logger)
>        at org.apache.hadoop.mapred.TaskLog.syncLogs(TaskLog.java:218)
>        - locked <0x00000000cb6669e8> (a java.lang.Class for
> org.apache.hadoop.mapred.TaskLog)
>        at org.apache.hadoop.mapred.Child$2.run(Child.java:89)
> "main":
>        at org.apache.log4j.Category.callAppenders(Category.java:202)
>        - waiting to lock <0x00000000d65c3e80> (a org.apache.log4j.Logger)
>        at org.apache.log4j.Category.forcedLog(Category.java:388)
>        at org.apache.log4j.Category.warn(Category.java:1008)
>        at
> org.apache.hadoop.chukwa.datacollection.controller.ChukwaAgentController.addByName(ChukwaAgentController.java:267)
>        at
> org.apache.hadoop.chukwa.inputtools.log4j.ChukwaDailyRollingFileAppender.subAppend(ChukwaDailyRollingFileAppender.java:565)
>        - locked <0x00000000d6736ec0> (a java.lang.Object)
>        at org.apache.log4j.WriterAppender.append(WriterAppender.java:159)
>        at
> org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:230)
>        - locked <0x00000000d65b38c0> (a
> com.glassdoor.chukwa.inputtools.log4j.GDChukwaDailyRollingFileAppender)
>        at
> org.apache.log4j.helpers.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:65)
>        at org.apache.log4j.Category.callAppenders(Category.java:203)
>        - locked <0x00000000d65c44b8> (a org.apache.log4j.Logger)
>        at org.apache.log4j.Category.forcedLog(Category.java:388)
>        at org.apache.log4j.Category.log(Category.java:853)
>        at
> org.apache.commons.logging.impl.Log4JLogger.warn(Log4JLogger.java:222)
>        at
> com.glassdoor.util.netsuite.service.NetSuiteServiceImpl.init(NetSuiteServiceImpl.java:86)
>        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
>        at
> sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
>        at
> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
>        at java.lang.reflect.Method.invoke(Method.java:597)
>        at
> org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.invokeCustomInitMethod(AbstractAutowireCapableBeanFactory.java:1378)

Does SocketAppender ecsape newlines? Like, log an exception with a stack
trace(multiple lines) as a single log statement? And can it register an
adapter automatically?
On Jun 24, 2012 12:20 PM, "Eric Yang" <[EMAIL PROTECTED]> wrote:

> Hi Abhijit,
>
> The dead lock happens when there are too many registrations with the
> agent and agent has exceeded the open file descriptor limit.  I would
> recommend to use Log4J SocketAppender with combination of
> SocketAdaptor.  It reduces the overhead of file offset tracking and
> reduces the number of file descriptors used by the agent.  It works
> better than using ChukwaDailyFileAppender and file adaptor
> combination.
>
> regards,
> Eric
>
> On Fri, Jun 22, 2012 at 9:50 AM, Abhijit Dhar <[EMAIL PROTECTED]>
> wrote:
> > Hi,
> >
> > I am getting a deadlock in ChukwaDailyRollingFileAppender. The thread
> dump
> > is:
> >
> > Found one Java-level deadlock:
> > ============================> > "Thread-4":
> >  waiting to lock monitor 0x00007f1970004818 (object 0x00000000cb6669e8, a
> > java.lang.Class),
> >  which is held by "Thread for syncLogs"
> > "Thread for syncLogs":
> >  waiting to lock monitor 0x00007f1970004ea8 (object 0x00000000d65c44b8, a
> > org.apache.log4j.Logger),
> >  which is held by "main"
> > "main":
> >  waiting to lock monitor 0x00007f1970003d98 (object 0x00000000d65c3e80, a
> > org.apache.log4j.Logger),
> >  which is held by "communication thread"
> > "communication thread":
> >  waiting to lock monitor 0x0000000041eba250 (object 0x00000000d6736ec0, a
> > java.lang.Object),
> >  which is held by "main"
> >
> > Java stack information for the threads listed above:
> > ==================================================> > "Thread-4":
> >        at org.apache.hadoop.mapred.TaskLog.syncLogs(TaskLog.java:213)
> >        - waiting to lock <0x00000000cb6669e8> (a java.lang.Class for
> > org.apache.hadoop.mapred.TaskLog)
> >        at org.apache.hadoop.mapred.Child$1.run(Child.java:75)
> > "Thread for syncLogs":
> >        at org.apache.log4j.Category.getAllAppenders(Category.java:409)
> >        - waiting to lock <0x00000000d65c44b8> (a org.apache.log4j.Logger)
> >        at org.apache.hadoop.mapred.TaskLog.syncLogs(TaskLog.java:218)
> >        - locked <0x00000000cb6669e8> (a java.lang.Class for
> > org.apache.hadoop.mapred.TaskLog)
> >        at org.apache.hadoop.mapred.Child$2.run(Child.java:89)
> > "main":
> >        at org.apache.log4j.Category.callAppenders(Category.java:202)
> >        - waiting to lock <0x00000000d65c3e80> (a org.apache.log4j.Logger)
> >        at org.apache.log4j.Category.forcedLog(Category.java:388)
> >        at org.apache.log4j.Category.warn(Category.java:1008)
> >        at
> >
> org.apache.hadoop.chukwa.datacollection.controller.ChukwaAgentController.addByName(ChukwaAgentController.java:267)
> >        at
> >
> org.apache.hadoop.chukwa.inputtools.log4j.ChukwaDailyRollingFileAppender.subAppend(ChukwaDailyRollingFileAppender.java:565)
> >        - locked <0x00000000d6736ec0> (a java.lang.Object)
> >        at org.apache.log4j.WriterAppender.append(WriterAppender.java:159)
> >        at
> > org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:230)
> >        - locked <0x00000000d65b38c0> (a
> > com.glassdoor.chukwa.inputtools.log4j.GDChukwaDailyRollingFileAppender)
> >        at
> >
> org.apache.log4j.helpers.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:65)
> >        at org.apache.log4j.Category.callAppenders(Category.java:203)
> >        - locked <0x00000000d65c44b8> (a org.apache.log4j.Logger)
> >        at org.apache.log4j.Category.forcedLog(Category.java:388)
> >        at org.apache.log4j.Category.log(Category.java:853)
> >        at
> > org.apache.commons.logging.impl.Log4JLogger.warn(Log4JLogger.java:222)
> >        at
> >
> com.glassdoor.util.netsuite.service.NetSuiteServiceImpl.init(NetSuiteServiceImpl.java:86)
> >        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
> >        at

Hi Abhijit,

SocketAppender sends log entries as a full entry.  Chunk is created
per log entry (can be multiple lines).  There is no need to do
additional escaping.  SocketAdaptor should be configured in
initial_adaptors like:

add SocketAdaptor JobSummary 9098 0

This means to tag the log file collected through port 9098 as
JobSummary log file.
Hope this helps.

regards,
Eric

On Sun, Jun 24, 2012 at 6:27 PM, Abhijit Dhar <[EMAIL PROTECTED]> wrote:
> Does SocketAppender ecsape newlines? Like, log an exception with a stack
> trace(multiple lines) as a single log statement? And can it register an
> adapter automatically?
>
> On Jun 24, 2012 12:20 PM, "Eric Yang" <[EMAIL PROTECTED]> wrote:
>>
>> Hi Abhijit,
>>
>> The dead lock happens when there are too many registrations with the
>> agent and agent has exceeded the open file descriptor limit.  I would
>> recommend to use Log4J SocketAppender with combination of
>> SocketAdaptor.  It reduces the overhead of file offset tracking and
>> reduces the number of file descriptors used by the agent.  It works
>> better than using ChukwaDailyFileAppender and file adaptor
>> combination.
>>
>> regards,
>> Eric
>>
>> On Fri, Jun 22, 2012 at 9:50 AM, Abhijit Dhar <[EMAIL PROTECTED]>
>> wrote:
>> > Hi,
>> >
>> > I am getting a deadlock in ChukwaDailyRollingFileAppender. The thread
>> > dump
>> > is:
>> >
>> > Found one Java-level deadlock:
>> > ============================>> > "Thread-4":
>> >  waiting to lock monitor 0x00007f1970004818 (object 0x00000000cb6669e8,
>> > a
>> > java.lang.Class),
>> >  which is held by "Thread for syncLogs"
>> > "Thread for syncLogs":
>> >  waiting to lock monitor 0x00007f1970004ea8 (object 0x00000000d65c44b8,
>> > a
>> > org.apache.log4j.Logger),
>> >  which is held by "main"
>> > "main":
>> >  waiting to lock monitor 0x00007f1970003d98 (object 0x00000000d65c3e80,
>> > a
>> > org.apache.log4j.Logger),
>> >  which is held by "communication thread"
>> > "communication thread":
>> >  waiting to lock monitor 0x0000000041eba250 (object 0x00000000d6736ec0,
>> > a
>> > java.lang.Object),
>> >  which is held by "main"
>> >
>> > Java stack information for the threads listed above:
>> > ==================================================>> > "Thread-4":
>> >        at org.apache.hadoop.mapred.TaskLog.syncLogs(TaskLog.java:213)
>> >        - waiting to lock <0x00000000cb6669e8> (a java.lang.Class for
>> > org.apache.hadoop.mapred.TaskLog)
>> >        at org.apache.hadoop.mapred.Child$1.run(Child.java:75)
>> > "Thread for syncLogs":
>> >        at org.apache.log4j.Category.getAllAppenders(Category.java:409)
>> >        - waiting to lock <0x00000000d65c44b8> (a
>> > org.apache.log4j.Logger)
>> >        at org.apache.hadoop.mapred.TaskLog.syncLogs(TaskLog.java:218)
>> >        - locked <0x00000000cb6669e8> (a java.lang.Class for
>> > org.apache.hadoop.mapred.TaskLog)
>> >        at org.apache.hadoop.mapred.Child$2.run(Child.java:89)
>> > "main":
>> >        at org.apache.log4j.Category.callAppenders(Category.java:202)
>> >        - waiting to lock <0x00000000d65c3e80> (a
>> > org.apache.log4j.Logger)
>> >        at org.apache.log4j.Category.forcedLog(Category.java:388)
>> >        at org.apache.log4j.Category.warn(Category.java:1008)
>> >        at
>> >
>> > org.apache.hadoop.chukwa.datacollection.controller.ChukwaAgentController.addByName(ChukwaAgentController.java:267)
>> >        at
>> >
>> > org.apache.hadoop.chukwa.inputtools.log4j.ChukwaDailyRollingFileAppender.subAppend(ChukwaDailyRollingFileAppender.java:565)
>> >        - locked <0x00000000d6736ec0> (a java.lang.Object)
>> >        at
>> > org.apache.log4j.WriterAppender.append(WriterAppender.java:159)
>> >        at
>> > org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:230)
>> >        - locked <0x00000000d65b38c0> (a
>> > com.glassdoor.chukwa.inputtools.log4j.GDChukwaDailyRollingFileAppender)
>> >        at
>> >
>> > org.apache.log4j.helpers.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:65)

Hi Eric,

I tried SocketAppender with SocketAdaptor, but I'm having 3 trouble points:

First, SocketAppender does not use Pattern Layout. I need to format my logs
so that I can parse it at the collector end.
Second, I need to dynamically add the adaptors to the agent with a dynamic
name for the recordType. How can I do this with SocketAppender? Is there a
method that I can override( Like, I could override setRecordType() in
ChukwaDailyRollingFileAppender)
Third, I dont seem to get multiple lines. I debugged and the chunks on the
collector side are only getting the first line for a stack trace for
example. What am I doing wrong?
My setup is this:
log4j.appender.J=org.apache.log4j.net.SocketAppender
log4j.appender.J.RemoteHost=localhost
log4j.appender.J.Port=9095

And I simple log like logger.error("Expected Test error occured", e);

Thanks,
Abhijit

--
View this message in context: http://apache-chukwa.679492.n3.nabble.com/Deadlock-happening-in-ChukwaDailyRollingFileAppender-tp4025029p4025074.html
Sent from the Chukwa - Users mailing list archive at Nabble.com.

Hi Abhijit,

SocketAppender serializes LoggingEvent object to the listening port.
In theory, you can get the full logging event without having to depend
on layout.  SocketAdaptor setRecordType by the type defined during
adaptor creation.  It is not possible to setRecordType using
SocketAppender because recordType is Chukwa specific concept.  Log4J
does not know anything about this.  In SocketAdaptor, it is
serializing the log event into a byte array.  It doesn't handle the
Throwable part of the logging message.  This is why it appears as
first line only.  However, if you put in message like:

log.error("this is line 1.\nthis is line 2.");

This will log as 2 lines.  Chukwa probably should handle throwable
part of the logging event, but it doesn't do that today.

regards,
Eric

On Thu, Jul 5, 2012 at 6:01 PM, Abhijit Dhar <[EMAIL PROTECTED]> wrote:
> Hi Eric,
>
> I tried SocketAppender with SocketAdaptor, but I'm having 3 trouble points:
>
> First, SocketAppender does not use Pattern Layout. I need to format my logs
> so that I can parse it at the collector end.
> Second, I need to dynamically add the adaptors to the agent with a dynamic
> name for the recordType. How can I do this with SocketAppender? Is there a
> method that I can override( Like, I could override setRecordType() in
> ChukwaDailyRollingFileAppender)
> Third, I dont seem to get multiple lines. I debugged and the chunks on the
> collector side are only getting the first line for a stack trace for
> example. What am I doing wrong?
>
>
> My setup is this:
> log4j.appender.J=org.apache.log4j.net.SocketAppender
> log4j.appender.J.RemoteHost=localhost
> log4j.appender.J.Port=9095
>
> And I simple log like logger.error("Expected Test error occured", e);
>
> Thanks,
> Abhijit
>
> --
> View this message in context: http://apache-chukwa.679492.n3.nabble.com/Deadlock-happening-in-ChukwaDailyRollingFileAppender-tp4025029p4025074.html
> Sent from the Chukwa - Users mailing list archive at Nabble.com.