[prev in list] [next in list] [prev in thread] [next in thread] 

List:       log4cxx-dev
Subject:    [jira] [Updated] (LOGCXX-436) Logging statement is hanging
From:       "Venkatesh (JIRA)" <log4cxx-dev () logging ! apache ! org>
Date:       2014-04-30 12:09:18
Message-ID: JIRA.12711445.1398858171484.205878.1398859758237 () arcas
[Download RAW message or body]


     [ https://issues.apache.org/jira/browse/LOGCXX-436?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel \
]

Venkatesh updated LOGCXX-436:
-----------------------------

    Description: 
We have a standlone VC++ application and we added logging using the log4cxx0.10.0 \
version.  The application will initiate a thread (for some time consuming operation) \
and if it takes more than threshold time then the main thread will kill the thread \
using TerminateThread method. The child thread function also has some logging \
prints.Log4CXX configured with rolling file appender of 1 MB size of 5 backup copies. \
Logging is working fine in most of the scenarios. But in some scenarios main thread \
logging function call is hanging after killing the child thread and hence the entire \
application is in hanging state. Subsequent instances of the application is also \
hanging. We took the full crash dumps of the application and analyzed using the \
WinDbg.  Here is the call stack of the application

00 ntdll!NtWaitForSingleObject+0xa
01 ntdll!RtlpWaitOnCriticalSection+0xe8
02 ntdll!RtlEnterCriticalSection+0xd1
03 log4cxx!log4cxx::filter::DenyAllFilter::decide+0x194
04 log4cxx!log4cxx::helpers::synchronized::synchronized+0x31
05 log4cxx!log4cxx::Logger::callAppenders+0x81
06 log4cxx!log4cxx::Logger::forcedLog+0xe5
07 Test!CXX_LOG(int LOG_TYPE = 0n2, char * format = 0x00000001`3f2a2ad8 "Main thread \
pint...")+0x463 [d:\test\saf\test.cpp @ 2360] 08 test!TestFunction(int argc = 0n3, \
char ** argv = 0x00000001`3f2ae880, int level = 0n1)+0x586 [d:\test\saf\test.cpp @ \
1634] 09 test!main(int argc = 0n4, char ** argv = 0x00000000`00282920)+0x1820 \
[d:\test\saf\test.cpp @ 2309] 0a test!__tmainCRTStartup(void)+0x13b \
[f:\dd\vctools\crt_bld\self_64_amd64\crt\src\crt0.c @ 278] 0b \
kernel32!BaseThreadInitThunk+0xd 0c ntdll!RtlUserThreadStart+0x1d

and subsequent applications hangs for locking the file and call stack of the instance \
as follows

ntdll!ZwLockFile+0xa
KERNELBASE!LockFileEx+0xb2
kernel32!LockFileEx+0x1b
log4cxx!log4cxx::filter::DenyAllFilter::decide+0x2a89
log4cxx!log4cxx::helpers::DatagramPacket::setData+0x559c
log4cxx!log4cxx::helpers::FileOutputStream::write+0x82
log4cxx!log4cxx::rolling::RollingFileAppenderSkeleton::getTriggeringPolicy+0x1ca
log4cxx!log4cxx::helpers::OutputStreamWriter::write+0xbe
log4cxx!log4cxx::WriterAppender::subAppend+0x7c
log4cxx!log4cxx::rolling::RollingFileAppenderSkeleton::subAppend+0xd0
log4cxx!log4cxx::WriterAppender::append+0x31
log4cxx!log4cxx::AppenderSkeleton::doAppend+0x293
log4cxx!log4cxx::helpers::AppenderAttachableImpl::appendLoopOnAppenders+0x40
log4cxx!log4cxx::Logger::callAppenders+0xa3
log4cxx!log4cxx::Logger::forcedLog+0xe5
test!CXX_LOG(int LOG_TYPE = 0n2, char * format = 0x00000001`3f2a3868 "Starting the \
application")+0x463 test!main(int argc = 0n4, char ** argv = \
0x00000000`00162920)+0x1806 test!__tmainCRTStartup(void)+0x13b
kernel32!BaseThreadInitThunk+0xd
ntdll!RtlUserThreadStart+0x21

We have checked the function 'decide' and it has nothing to do with locking. it is \
just returning some constant value. I have read that LOG4CXX is thread safe. This \
issue is not occurring frequently and hence we didn't have the steps to reproduce in \
consistent way.  Is it anything needs to be addressed when we killing the child \
thread?? 



  was:
We have a standlone VC++ application and we added logging using the log4cxx0.10.0 \
version.  The application will initiate a thread (for some time consuming operation) \
and if it takes more than threshold time then the main thread will kill the thread \
using TerminateThread method. The child thread function also has some logging \
prints.Log4CXX configured with rolling file appender of 1 MB size of 5 backup copies. \
Logging is working fine in most of the scenarios. But in some scenarios main thread \
logging function call is hanging after killing the child thread and hence the entire \
application is in hanging state. Subsequent instances of the application is also \
hanging. We took the full crash dumps of the application and analyzed using the \
WinDbg.  Here is the call stack of the application

00 ntdll!NtWaitForSingleObject+0xa
01 ntdll!RtlpWaitOnCriticalSection+0xe8
02 ntdll!RtlEnterCriticalSection+0xd1
03 log4cxx!log4cxx::filter::DenyAllFilter::decide+0x194
04 log4cxx!log4cxx::helpers::synchronized::synchronized+0x31
05 log4cxx!log4cxx::Logger::callAppenders+0x81
06 log4cxx!log4cxx::Logger::forcedLog+0xe5
07 Test!CXX_LOG(int LOG_TYPE = 0n2, char * format = 0x00000001`3f2a2ad8 "Main thread \
pint...")+0x463 [d:\test\saf\test.cpp @ 2360] 08 test!TestFunction(int argc = 0n3, \
char ** argv = 0x00000001`3f2ae880, int level = 0n1)+0x586 [d:\test\saf\test.cpp @ \
1634] 09 test!main(int argc = 0n4, char ** argv = 0x00000000`00282920)+0x1820 \
[d:\test\saf\test.cpp @ 2309] 0a test!__tmainCRTStartup(void)+0x13b \
[f:\dd\vctools\crt_bld\self_64_amd64\crt\src\crt0.c @ 278] 0b \
kernel32!BaseThreadInitThunk+0xd 0c ntdll!RtlUserThreadStart+0x1d

and subsequent applications hangs for locking the file and call stack of the instance \
as follows

ntdll!ZwLockFile+0xa
KERNELBASE!LockFileEx+0xb2
kernel32!LockFileEx+0x1b
log4cxx!log4cxx::filter::DenyAllFilter::decide+0x2a89
log4cxx!log4cxx::helpers::DatagramPacket::setData+0x559c
log4cxx!log4cxx::helpers::FileOutputStream::write+0x82
log4cxx!log4cxx::rolling::RollingFileAppenderSkeleton::getTriggeringPolicy+0x1ca
log4cxx!log4cxx::helpers::OutputStreamWriter::write+0xbe
log4cxx!log4cxx::WriterAppender::subAppend+0x7c
log4cxx!log4cxx::rolling::RollingFileAppenderSkeleton::subAppend+0xd0
log4cxx!log4cxx::WriterAppender::append+0x31
log4cxx!log4cxx::AppenderSkeleton::doAppend+0x293
log4cxx!log4cxx::helpers::AppenderAttachableImpl::appendLoopOnAppenders+0x40
log4cxx!log4cxx::Logger::callAppenders+0xa3
log4cxx!log4cxx::Logger::forcedLog+0xe5
test!CXX_LOG(int LOG_TYPE = 0n2, char * format = 0x00000001`3f2a3868 "Starting the \
application")+0x463 test!main(int argc = 0n4, char ** argv = \
0x00000000`00162920)+0x1806 test!__tmainCRTStartup(void)+0x13b
kernel32!BaseThreadInitThunk+0xd
ntdll!RtlUserThreadStart+0x21

We have checked the function 'decide' and it has nothing to do with locking. it is \
jusing returning some constant value. I have read that LOG4CXX is thread safe. This \
issue is not occuring frequently and hence we didn't have the steps to rpoduce in \
consistent way.  Is it anything needs to be addressed when we killing the child \
thread?? 




> Logging statement is hanging 
> -----------------------------
> 
> Key: LOGCXX-436
> URL: https://issues.apache.org/jira/browse/LOGCXX-436
> Project: Log4cxx
> Issue Type: Bug
> Components: Core, Filter
> Affects Versions: 0.10.0
> Reporter: Venkatesh
> Assignee: Alex Zbarcea
> Priority: Minor
> 
> We have a standlone VC++ application and we added logging using the log4cxx0.10.0 \
> version.  The application will initiate a thread (for some time consuming \
> operation) and if it takes more than threshold time then the main thread will kill \
> the thread using TerminateThread method. The child thread function also has some \
> logging prints.Log4CXX configured with rolling file appender of 1 MB size of 5 \
> backup copies. Logging is working fine in most of the scenarios. But in some \
> scenarios main thread logging function call is hanging after killing the child \
> thread and hence the entire application is in hanging state. Subsequent instances \
> of the application is also hanging. We took the full crash dumps of the application \
> and analyzed using the WinDbg.  Here is the call stack of the application
> 00 ntdll!NtWaitForSingleObject+0xa
> 01 ntdll!RtlpWaitOnCriticalSection+0xe8
> 02 ntdll!RtlEnterCriticalSection+0xd1
> 03 log4cxx!log4cxx::filter::DenyAllFilter::decide+0x194
> 04 log4cxx!log4cxx::helpers::synchronized::synchronized+0x31
> 05 log4cxx!log4cxx::Logger::callAppenders+0x81
> 06 log4cxx!log4cxx::Logger::forcedLog+0xe5
> 07 Test!CXX_LOG(int LOG_TYPE = 0n2, char * format = 0x00000001`3f2a2ad8 "Main \
> thread pint...")+0x463 [d:\test\saf\test.cpp @ 2360] 08 test!TestFunction(int argc \
> = 0n3, char ** argv = 0x00000001`3f2ae880, int level = 0n1)+0x586 \
> [d:\test\saf\test.cpp @ 1634] 09 test!main(int argc = 0n4, char ** argv = \
> 0x00000000`00282920)+0x1820 [d:\test\saf\test.cpp @ 2309] 0a \
> test!__tmainCRTStartup(void)+0x13b \
> [f:\dd\vctools\crt_bld\self_64_amd64\crt\src\crt0.c @ 278] 0b \
> kernel32!BaseThreadInitThunk+0xd 0c ntdll!RtlUserThreadStart+0x1d
> and subsequent applications hangs for locking the file and call stack of the \
> instance as follows ntdll!ZwLockFile+0xa
> KERNELBASE!LockFileEx+0xb2
> kernel32!LockFileEx+0x1b
> log4cxx!log4cxx::filter::DenyAllFilter::decide+0x2a89
> log4cxx!log4cxx::helpers::DatagramPacket::setData+0x559c
> log4cxx!log4cxx::helpers::FileOutputStream::write+0x82
> log4cxx!log4cxx::rolling::RollingFileAppenderSkeleton::getTriggeringPolicy+0x1ca
> log4cxx!log4cxx::helpers::OutputStreamWriter::write+0xbe
> log4cxx!log4cxx::WriterAppender::subAppend+0x7c
> log4cxx!log4cxx::rolling::RollingFileAppenderSkeleton::subAppend+0xd0
> log4cxx!log4cxx::WriterAppender::append+0x31
> log4cxx!log4cxx::AppenderSkeleton::doAppend+0x293
> log4cxx!log4cxx::helpers::AppenderAttachableImpl::appendLoopOnAppenders+0x40
> log4cxx!log4cxx::Logger::callAppenders+0xa3
> log4cxx!log4cxx::Logger::forcedLog+0xe5
> test!CXX_LOG(int LOG_TYPE = 0n2, char * format = 0x00000001`3f2a3868 "Starting the \
> application")+0x463 test!main(int argc = 0n4, char ** argv = \
> 0x00000000`00162920)+0x1806 test!__tmainCRTStartup(void)+0x13b
> kernel32!BaseThreadInitThunk+0xd
> ntdll!RtlUserThreadStart+0x21
> We have checked the function 'decide' and it has nothing to do with locking. it is \
> just returning some constant value. I have read that LOG4CXX is thread safe. This \
> issue is not occurring frequently and hence we didn't have the steps to reproduce \
> in consistent way.  Is it anything needs to be addressed when we killing the child \
> thread?? 



--
This message was sent by Atlassian JIRA
(v6.2#6252)


[prev in list] [next in list] [prev in thread] [next in thread]