Multiple simultaneous connections cause errors

[denysvitali]

When multiple static files (>1MB) are loaded at the same time, the following error(s) appears, and the resource isn't loaded

Unhandled exception in spawn:
Error writing file: Broken pipe (Errno)
0x41405e: ??? at /root/.cache/crystal/macro57889200.cr 10:28
0x4ad5ed: ??? at /opt/crystal/src/io/file_descriptor.cr 274:11
0x4ad0e7: ??? at /opt/crystal/src/io/buffered.cr 268:5
0x52561b: ??? at /opt/crystal/src/http/server/request_processor.cr 65:7
0x4167c8: ??? at /opt/crystal/src/fiber.cr 114:3
0x0: ??? at ??
Exception: Error writing file: Connection reset by peer (Errno)
0x41405e: ??? at /root/.cache/crystal/macro57889200.cr 10:28
0x424c8d: ??? at /opt/crystal/src/io/file_descriptor.cr 274:11
0x42a555: ??? at /opt/crystal/src/io/buffered.cr 194:14
0x430071: ??? at /opt/crystal/src/http/server/response.cr 179:11
0x42fbd7: ??? at /opt/crystal/src/io/buffered.cr 266:5
0x42f82f: ??? at /opt/crystal/src/http/server/response.cr 68:7
0x531c26: ??? at /opt/crystal/src/io.cr 968:18
0x53b0af: ??? at /opt/crystal/src/http/server/handler.cr 24:7
0x53915e: ??? at /opt/crystal/src/http/server/handler.cr 24:7
0x53ef46: ??? at /opt/crystal/src/http/server/handler.cr 24:7
0x52453e: ??? at /root/mich/lib/kemal/src/kemal/init_handler.cr 11:7
0x4167c8: ??? at /opt/crystal/src/fiber.cr 114:3
0x0: ??? at ??


Unhandled exception in spawn:
Error writing file: Broken pipe (Errno)
0x41405e: ??? at /root/.cache/crystal/macro57889200.cr 10:28
0x4ad5ed: ??? at /opt/crystal/src/io/file_descriptor.cr 274:11
0x4ad0e7: ??? at /opt/crystal/src/io/buffered.cr 268:5
0x52561b: ??? at /opt/crystal/src/http/server/request_processor.cr 65:7
0x4167c8: ??? at /opt/crystal/src/fiber.cr 114:3
0x0: ??? at ??

[rdp]

What's the minimal test case to reproduce this? (my hunch is that it's actually caused by the client closing the connection, not the server...also note you can get a better stacktrace by not compiling it with --release mode...)

[rdp]

FWIW I can download a large file from two different clients and the files come down as two "good" copies and are streamed simultaneously (this is a static file from /public ). Cheers!

[sdogruyol]

@denysvitali have you checked your OS limits like ulimit -n ?

[sdogruyol]

I can reproduce this with stress loading serving big static files like videos.

Using wrk i tried to download 50MB video file with 10 connections for 20 seconds

wrk -c 10 -d 20 http://localhost:3000/video.mp4
Running 20s test @ http://localhost:3000/video.mp4
  2 threads and 10 connections
  Thread Stats   Avg      Stdev     Max   +/- Stdev
    Latency   603.97ms  272.95ms   1.79s    80.94%
    Req/Sec     9.71      5.09    20.00     66.54%
  329 requests in 20.08s, 15.65GB read
Requests/sec:     16.39
Transfer/sec:    798.42MB

Kemal process crashes when the test finishes (not in between). I guess that the event loop can't handle that much load and blows up in the end. Memory consumption was around 3-5 MB which is fine

Unhandled exception in spawn:
Error writing file: Broken pipe (Errno)
0x106fff355: *CallStack::new:CallStack at ??
0x107001c4e: *raise<Errno>:NoReturn at ??
0x10706bbb9: *TCPSocket+@IO::Buffered#flush:TCPSocket+ at ??
0x10707345c: *TCPSocket+@IO::Buffered#close:Nil at ??
0x10706fe54: *HTTP::Server::RequestProcessor#process<(OpenSSL::SSL::Socket::Server | TCPSocket+), (OpenSSL::SSL::Socket::Server | TCPSocket+), IO::FileDescriptor>:Nil at ??
0x10700367c: *Fiber#run:(IO::FileDescriptor | Nil) at ??

Invalid memory access (signal 10) at address 0x109a47520
[4412989111] *CallStack::print_backtrace:Int32 +39
[4412495875] __crystal_sigfault_handler +35
[140735702649786] _sigtramp +26

//cc @asterite

[sdogruyol]

Funny enough this only happens while all the connections are being closed @denysvitali

I ran wrk for 200 seconds and not a single exception till the end

[denysvitali]

Really, really strange!

[sdogruyol]

I reduced the case with only using Kemal::StaticFileHandler and this won't blow up the process

Unhandled exception in spawn:
Error writing file: Broken pipe (Errno)
0x10a585f62: *CallStack::unwind:Array(Pointer(Void)) at ??
0x10a585f01: *CallStack#initialize:Array(Pointer(Void)) at ??
0x10a585ed8: *CallStack::new:CallStack at ??
0x10a57f1c1: *raise<Errno>:NoReturn at ??
0x10a63c650: *TCPSocket+@IO::FileDescriptor#unbuffered_write<Slice(UInt8)>:Int32 at ??
0x10a63c365: *TCPSocket+@IO::Buffered#flush:TCPSocket+ at ??
0x10a63e5bb: *TCPSocket+@IO::Buffered#close:Nil at ??
0x10a637bf3: *HTTP::Server::RequestProcessor#process<(OpenSSL::SSL::Socket::Server | TCPSocket+), (OpenSSL::SSL::Socket::Server | TCPSocket+), IO::FileDescriptor>:Nil at ??
0x10a6328a5: *HTTP::Server::RequestProcessor#process<(OpenSSL::SSL::Socket::Server | TCPSocket+), (OpenSSL::SSL::Socket::Server | TCPSocket+)>:Nil at ??
0x10a6327c6: *HTTP::Server#handle_client<(TCPSocket+ | Nil)>:Nil at ??
0x10a584776: ~procProc(Nil)@/usr/local/Cellar/crystal-lang/0.20.4/src/http/server.cr:148 at ??
0x10a590224: *Fiber#run:(IO::FileDescriptor | Nil) at ??
0x10a5826e9: ~proc2Proc(Fiber, (IO::FileDescriptor | Nil))@/usr/local/Cellar/crystal-lang/0.20.4/src/fiber.cr:29 at ?

[rdp]

@denysvitali Could you post a stack trace that has method names as well (I think either adding --debug or not using --release might should do it...FWIW). It does look somehow similar to the OpenSSL 4003 one linked, as well...
@sdogruyol do you get a hard crash? If I run in HTTP I do get the Broken pipe type error messages, but without any hard crashes. It does seem that HTTP leaks sockets the same way the crystal#4003 did, and the fix for that does seem to avoid leaking sockets for it as well...

[rdp]

OK just to mention it, I believe the Broken pipe trace is actually expected, it means that the client cut the connection midstream when server was still trying to send data to the client (which is what wrk does when it finishes a test). The trace is being output to the screen when the fiber dies: https://github.com/crystal-lang/crystal/blob/36d0c369564a2e237bdc30cedc15344db2636557/src/fiber.cr#L120
FWIW...
(it used to hard crash though? That would be non expected obviously :)

[jasonl99]

Is there a way to rescue this error somewhere?

[rdp]

I never saw the crash actually occur, but heard rumors it is fixed in git master FWIW try that? crystal-lang/crystal#4003

[sdogruyol]

These are just warnings and doesn't crash the process anymore 👍

[codenoid]

"These are just warnings and doesn't crash the process anymore"
really ???

[codenoid]

2018-11-03 00:13:04 +07:00 500 GET / 4813.13ms                          
Exception: Error writing to socket: Broken pipe (Errno)                 
  from /usr/share/crystal/src/socket.cr:77:13 in 'unbuffered_write'     
  from /usr/share/crystal/src/io/buffered.cr:139:14 in 'write'          
  from /usr/share/crystal/src/http/server/response.cr:185:11 in 'unbuffe
red_write'                                                              
  from /usr/share/crystal/src/io/buffered.cr:139:14 in 'write'          
  from /usr/share/crystal/src/http/server/response.cr:69:7 in 'write'   
  from /usr/share/crystal/src/io.cr:481:7 in 'write_utf8'               
  from /usr/share/crystal/src/string.cr:4201:5 in 'to_s'                
  from /usr/share/crystal/src/io.cr:184:5 in '<<'                       
  from /usr/share/crystal/src/io.cr:198:5 in 'print'                    
  from lib/kemal/src/kemal/route_handler.cr:54:7 in 'process_request'   
  from lib/kemal/src/kemal/route_handler.cr:17:7 in 'call'              
  from /usr/share/crystal/src/http/server/handler.cr:24:7 in 'call_next'
  from lib/kemal/src/kemal/websocket_handler.cr:13:14 in 'call'         
  from /usr/share/crystal/src/http/server/handler.cr:24:7 in 'call_next'
  from lib/kemal/src/kemal/filter_handler.cr:21:7 in 'call'             
  from /usr/share/crystal/src/http/server/handler.cr:24:7 in 'call_next'
  from lib/kemal/src/kemal/static_file_handler.cr:8:14 in 'call'        
  from /usr/share/crystal/src/http/server/handler.cr:24:7 in 'call_next'
  from lib/kemal/src/kemal/exception_handler.cr:8:7 in 'call'           
  from /usr/share/crystal/src/http/server/handler.cr:24:7 in 'call_next'
  from lib/kemal/src/kemal/log_handler.cr:10:35 in 'call'               
  from /usr/share/crystal/src/http/server/handler.cr:24:7 in 'call_next'
  from lib/kemal/src/kemal/init_handler.cr:11:7 in 'call'               
  from /usr/share/crystal/src/http/server/request_processor.cr:39:11 in 
'process'                                                               
  from /usr/share/crystal/src/http/server/request_processor.cr:16:3 in '
process'                                                                
  from /usr/share/crystal/src/http/server.cr:402:5 in 'handle_client'   
  from /usr/share/crystal/src/http/server.cr:368:13 in '->'             
  from /usr/share/crystal/src/fiber.cr:255:3 in 'run'                   
  from /usr/share/crystal/src/fiber.cr:29:34 in '->'                    
  from ???                                                              

2018-11-03 00:13:04 +07:00 500 GET / 4813.13ms