Crystal: Hard to trace errors if raise multiple errors on MT

[firejox]

The code

4.times do                                                                                                                                                                    
  spawn do                                                                                                                                                                    
    raise "Error here"                                                                                                                                                        
  end                                                                                                                                                                         
end                                                                                                                                                                           

sleep 3 

The output

Unhandled exception in spawn: Error hereUnhandled exception in spawn: Error here (Exception)                                                                                  
 (Exception)                                                                                                                                                                  
Unhandled exception in spawn: Error here (Exception)                                                                                                                          
Unhandled exception in spawn: Error here (Exception)                                                                                                                          
  from /home/developer/workspace/src/fiber.cr:255:3 in 'run'                                                                                                                  
  from /home/developer/workspace/src/fiber.cr:255:3 in 'run'                                                                                                                  
  from /home/developer/workspace/src/fiber.cr:48:34 in '->'                                                                                                                   
  from ???                                                                                                                                                                    
  from /home/developer/workspace/src/fiber.cr:48:34 in '->'                                                                                                                   
  from ???                                                                                                                                                                    
  from /home/developer/workspace/src/fiber.cr:255:3 in 'run'                                                                                                                  
  from /home/developer/workspace/src/fiber.cr:48:34 in '->'                                                                                                                   
  from ???                                                                                                                                                                    
  from /home/developer/workspace/src/fiber.cr:255:3 in 'run'                                                                                                                  
  from /home/developer/workspace/src/fiber.cr:48:34 in '->'                                                                                                                   
  from ???

Crystal version

Crystal 0.32.0-dev [0505d1c2e] (2019-10-09)                                                                                                                                   

LLVM: 8.0.1                                                                                                                                                                   
Default target: x86_64-pc-linux-gnu

[jhass]

I guess we should just have a global lock around the exception printer to stdout. It's a rare thing to happen anyways so shouldn't incur any performance penalty, I hope

[ysbaddaden]

Unwinding the stack, extracting the file:line info from DWARF tables are already a high cost. Adding a mutex to print errors shouldn't add that much. Especially since in production apps it should be redirected to a logger anyway.

[firejox]

I think my code is not good enough to indicate the problem. The mess of error log is bad, not the worst. The worst is that errors can generate error. I have no idea to design a minimal straightforward code for the worst case, but we can take the issue #8288 as an example. Sometimes I got the error when I ran this code.

[0x55863b6e1bb6] *CallStack::print_backtrace:Int32 +118                                                                                                                       
[0x55863b6d3019] __crystal_sigfault_handler +217                                                                                                                              
[0x55863b73aec0] sigfault_handler +40                                                                                                                                         
[0x7fc08a7444d0] ???                                                                                                                                                          
[0x7fc08a771587] GC_malloc_kind_global +87                                                                                                                                    
[0x55863b6e9f36] *GC::malloc<UInt64>:Pointer(Void) +6                                                                                                                         
[0x55863b6c4dde] __crystal_malloc64 +14                                                                                                                                       
[0x55863b719c88] *Pointer(Tuple(String, Int32, Int32, Int32)) +72                                                                                                             
[0x55863b7197e7] *Array(Tuple(String, Int32, Int32, Int32)) +183                                                                                                              
[0x55863b719712] *Array(Tuple(String, Int32, Int32, Int32)) +82                                                                                                               
[0x55863b7191e0] *Debug::DWARF::LineNumbers::Sequence#initialize:Array(UInt8) +208                                                                                            
[0x55863b718f80] *Debug::DWARF::LineNumbers::Sequence::new:Debug::DWARF::LineNumbers::Sequence +560                                                                           
[0x55863b713cbc] *Debug::DWARF::LineNumbers#decode_sequences<(UInt32 | UInt64)>:Nil +380                                                                                      
[0x55863b713b2c] *Debug::DWARF::LineNumbers#initialize<IO::FileDescriptor+, (UInt32 | UInt64)>:Nil +108                                                                       
[0x55863b713a84] *Debug::DWARF::LineNumbers::new<IO::FileDescriptor+, (UInt32 | UInt64)>:Debug::DWARF::LineNumbers +132                                                       
[0x55863b6daeb8] *CallStack::read_dwarf_sections:(Array(Tuple(UInt64, UInt64, String)) | Nil) +9928                                                                           
[0x55863b6d85ed] *CallStack::decode_line_number<UInt64>:Tuple(String, Int32, Int32) +45                                                                                       
[0x55863b6d7d78] *CallStack#decode_backtrace:Array(String) +296                                                                                                               
[0x55863b6d7c32] *CallStack#printable_backtrace:Array(String) +50                                                                                                             
[0x55863b72d8fd] *Exception+ +77                                                                                                                                              
[0x55863b72d748] *Exception+ +120                                                                                                                                             
[0x55863b6f5647] *Fiber#run:(IO::FileDescriptor | Nil) +583                                                                                                                   
[0x55863b6d2b06] ~proc2Proc(Fiber, (IO::FileDescriptor | Nil)) +6                                                                                                             
[0x0] ??? 

This error is generated by other errors. The bugs which we want to resolve are hided by new error, and it is extremely hard to debug.

@ysbaddaden The cost of mutex depends on how frequently the mutex is competed by different threads/fibers. There is no reason to frequently unwind stacks in production app.