SIGABRT when calling LOG from signal handler when interrupted thread was in LOG

Hello,

I am seeing a problem where a SIGABRT is happening when LOG is being called 
from inside a signal handler when the previously running thread was inside 
another call to LOG. I have created a small demo program which demonstrates 
this bug.

What steps will reproduce the problem?
1. Create a file Main.cpp with the following contents:
  1 #include <glog/logging.h>                                                       
  2 #include <signal.h>                                                             
  3                                                                                 
  4 static bool running = true ;                                                    
  5                                                                                 
  6 static void sighandler(int sig) {                                               
  7   running = false ;                                                             
  8   LOG(INFO) << "Shutting Down on signal " << sig << "." << std::endl ;          
  9 }                                                                               
 10                                                                                 
 11 int main( int argc, char* argv[] ) {                                            
 12   google::InitGoogleLogging( argv[0] ) ;                                        
 13   google::SetStderrLogging( google::INFO ) ;                                    
 14                                                                                 
 15   signal( SIGINT, sighandler ) ;                                                
 16                                                                                 
 17   while( running ) {                                                            
 18     LOG(INFO) << "Running..." << std::endl ;                                    
 19   }                                                                             
 20                                                                                 
 21   return EXIT_SUCCESS ;                                                         
 22 }                                                                               
 23  

2. Compile:
  g++ -std=c++11 -lglog Main.cpp
3. Run:
  ./a.out 
4. Ctrl-C, the program should crash with a SIGABRT
5. Alternatively you can run with gdb, Ctrl-C, type 'signal 2', and see the 
stack of the crash.

What is the expected output? What do you see instead?
The SIGABRT should not happen.

What version of the product are you using? On what operating system?
I am using the default fedora packages:
  glog.x86_64 0.3.0-4.fc17
  glog-debuginfo.x86_64 0.3.0-4.fc17
  glog-devel.x86_64 0.3.0-4.fc17

I am on Fedora 17 Linux
  i:uname -a
  Linux epsom.mokon.net 3.8.4-102.fc17.x86_64 #1 SMP Sun Mar 24 13:09:09 UTC 2013 x86_64 x86_64 x86_64 GNU/Linux

Please provide any additional information below.

I am not sure if this is related to this bug:
  https://code.google.com/p/google-glog/issues/detail?id=53&q=SIGABRT

Here is an example gdb trace. As you can see inside LOG we are in a flush. It 
seems like the mutexes are interfering with one another a little.

I0529 22:05:51.392182 27724 Main.cpp:18] Running...
I0529 22:05:51.392189 27724 Main.cpp:18] Running...
I0529 22:05:51.392194 27724 Main.cpp:18] Running...
I0529 22:05:51.392200 27724 Main.cpp:18] Running...
I0529 22:05:51.392206 27724 Main.cpp:18] Running...^C
Program received signal SIGINT, Interrupt.
0x00000039a5ce4950 in __write_nocancel () at 
../sysdeps/unix/syscall-template.S:82
82      T_PSEUDO (SYSCALL_SYMBOL, SYSCALL_NAME, SYSCALL_NARGS)
(gdb) signal 2
Continuing with signal SIGINT.

Program received signal SIGABRT, Aborted.
0x00000039a5c35935 in __GI_raise (sig=sig@entry=6) at 
../nptl/sysdeps/unix/sysv/linux/raise.c:64
64        return INLINE_SYSCALL (tgkill, 3, pid, selftid, sig);
(gdb) where
#0  0x00000039a5c35935 in __GI_raise (sig=sig@entry=6) at 
../nptl/sysdeps/unix/sysv/linux/raise.c:64
#1  0x00000039a5c370e8 in __GI_abort () at abort.c:91
#2  0x00007ffff7daf119 in ReaderUnlock (this=<optimized out>) at 
src/base/mutex.h:250
#3  ~ReaderMutexLock (this=<optimized out>, __in_chrg=<optimized out>) at 
src/base/mutex.h:295
#4  WaitForSinks (data=<optimized out>) at src/logging.cc:597
#5  google::LogMessage::Flush (this=this@entry=0x7fffffffd450) at 
src/logging.cc:1091
#6  0x00007ffff7daf1a9 in google::LogMessage::~LogMessage (this=0x7fffffffd450, 
__in_chrg=<optimized out>) at src/logging.cc:1055
#7  0x0000000000400b11 in sighandler(int) ()
#8  <signal handler called>
#9  0x00000039a5ce4950 in __write_nocancel () at 
../sysdeps/unix/syscall-template.S:82
#10 0x00007ffff7db1aeb in WriteToStderr (len=52, message=0x602070 "I0529 
22:05:51.392206 27724 Main.cpp:18] Running...\n\377\177") at src/logging.cc:506
#11 MaybeLogToStderr (len=52, message=0x602070 "I0529 22:05:51.392206 27724 
Main.cpp:18] Running...\n\377\177", severity=0) at src/logging.cc:512
#12 google::LogMessage::SendToLog (this=0x7fffffffdc00) at src/logging.cc:1169
#13 0x00007ffff7daefc7 in google::LogMessage::Flush 
(this=this@entry=0x7fffffffdc00) at src/logging.cc:1088
#14 0x00007ffff7daf1a9 in google::LogMessage::~LogMessage (this=0x7fffffffdc00, 
__in_chrg=<optimized out>) at src/logging.cc:1055
#15 0x0000000000400bb6 in main ()
(gdb) 

Thanks, David
mokon_AT_mokon_DOT_net
Original issue reported on code.google.com by DavidMok...@gmail.com on 30 May 2013 at 2:09
huiyi1990 / google-glog

SIGABRT when calling LOG from signal handler when interrupted thread was in LOG #161
