Deadlock happening in ChukwaDailyRollingFileAppender

[Abhijit Dhar]

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)
        at org.apache.hadoop.mapred.MapTask.run(MapTask.java:305)
        at org.apache.hadoop.mapred.Child.main(Child.java:170)
"communication thread":
        at org.apache.hadoop.chukwa.inputtools.log4j.ChukwaDailyRollingFileAppender.checkEntryConditions(ChukwaDailyRollingFileAppender.java:489)
        - waiting to lock <0x00000000d6736ec0> (a java.lang.Object)
        at org.apache.log4j.WriterAppender.append(WriterAppender.java:156)
        at org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:230)
        - locked <0x00000000d65b2c50> (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 <0x00000000d65c3e80> (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 org.apache.hadoop.mapred.Task$TaskReporter.run(Task.java:554)
        at java.lang.Thread.run(Thread.java:662)

Found 1 deadlock.



I took a look at the code and surely, it is locking on chukwaLock object in checkEntryConditions() and subAppend() methods. I'm not too sure if we need to lock on chukwaLock for checkEntryConditions().
Anybody has a clue of what is going on ? This deadlock has happened twice now so far.

Thanks,
Abhijit

[Eric Yang-3]

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 <[hidden email]> 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)
>        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)
>        at org.apache.hadoop.mapred.MapTask.run(MapTask.java:305)
>        at org.apache.hadoop.mapred.Child.main(Child.java:170)
> "communication thread":
>        at
> org.apache.hadoop.chukwa.inputtools.log4j.ChukwaDailyRollingFileAppender.checkEntryConditions(ChukwaDailyRollingFileAppender.java:489)
>        - waiting to lock <0x00000000d6736ec0> (a java.lang.Object)
>        at org.apache.log4j.WriterAppender.append(WriterAppender.java:156)
>        at
> org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:230)
>        - locked <0x00000000d65b2c50> (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 <0x00000000d65c3e80> (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 org.apache.hadoop.mapred.Task$TaskReporter.run(Task.java:554)
>        at java.lang.Thread.run(Thread.java:662)
>
> Found 1 deadlock.
>
>
>
> I took a look at the code and surely, it is locking on chukwaLock object in
> checkEntryConditions() and subAppend() methods. I'm not too sure if we need
> to lock on chukwaLock for checkEntryConditions().
> Anybody has a clue of what is going on ? This deadlock has happened twice
> now so far.
>
> Thanks,
> Abhijit
>
> --
> View this message in context: http://apache-chukwa.679492.n3.nabble.com/Deadlock-happening-in-ChukwaDailyRollingFileAppender-tp4025029.html
> Sent from the Chukwa - Users mailing list archive at Nabble.com.

[Abhijit Dhar]

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" <[hidden email]> 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 <[hidden email]> 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)
>        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)
>        at org.apache.hadoop.mapred.MapTask.run(MapTask.java:305)
>        at org.apache.hadoop.mapred.Child.main(Child.java:170)
> "communication thread":
>        at
> org.apache.hadoop.chukwa.inputtools.log4j.ChukwaDailyRollingFileAppender.checkEntryConditions(ChukwaDailyRollingFileAppender.java:489)
>        - waiting to lock <0x00000000d6736ec0> (a java.lang.Object)
>        at org.apache.log4j.WriterAppender.append(WriterAppender.java:156)
>        at
> org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:230)
>        - locked <0x00000000d65b2c50> (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 <0x00000000d65c3e80> (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 org.apache.hadoop.mapred.Task$TaskReporter.run(Task.java:554)
>        at java.lang.Thread.run(Thread.java:662)
>
> Found 1 deadlock.
>
>
>
> I took a look at the code and surely, it is locking on chukwaLock object in
> checkEntryConditions() and subAppend() methods. I'm not too sure if we need
> to lock on chukwaLock for checkEntryConditions().
> Anybody has a clue of what is going on ? This deadlock has happened twice
> now so far.
>
> Thanks,
> Abhijit
>
> --
> View this message in context: http://apache-chukwa.679492.n3.nabble.com/Deadlock-happening-in-ChukwaDailyRollingFileAppender-tp4025029.html
> Sent from the Chukwa - Users mailing list archive at Nabble.com.

[Eric Yang-3]

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 <[hidden email]> 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" <[hidden email]> 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 <[hidden email]>
>> 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)
>> >        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)
>> >        at org.apache.hadoop.mapred.MapTask.run(MapTask.java:305)
>> >        at org.apache.hadoop.mapred.Child.main(Child.java:170)
>> > "communication thread":
>> >        at
>> >
>> > org.apache.hadoop.chukwa.inputtools.log4j.ChukwaDailyRollingFileAppender.checkEntryConditions(ChukwaDailyRollingFileAppender.java:489)
>> >        - waiting to lock <0x00000000d6736ec0> (a java.lang.Object)
>> >        at
>> > org.apache.log4j.WriterAppender.append(WriterAppender.java:156)
>> >        at
>> > org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:230)
>> >        - locked <0x00000000d65b2c50> (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 <0x00000000d65c3e80> (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 org.apache.hadoop.mapred.Task$TaskReporter.run(Task.java:554)
>> >        at java.lang.Thread.run(Thread.java:662)
>> >
>> > Found 1 deadlock.
>> >
>> >
>> >
>> > I took a look at the code and surely, it is locking on chukwaLock object
>> > in
>> > checkEntryConditions() and subAppend() methods. I'm not too sure if we
>> > need
>> > to lock on chukwaLock for checkEntryConditions().
>> > Anybody has a clue of what is going on ? This deadlock has happened
>> > twice
>> > now so far.
>> >
>> > Thanks,
>> > Abhijit
>> >
>> > --
>> > View this message in context:
>> > http://apache-chukwa.679492.n3.nabble.com/Deadlock-happening-in-ChukwaDailyRollingFileAppender-tp4025029.html
>> > Sent from the Chukwa - Users mailing list archive at Nabble.com.

[Abhijit Dhar]

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

[Eric Yang-3]

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 <[hidden email]> 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.