send_file HTTP::Server::ClientError

[itsezc]

Description

Throws various errors related to HTTP::Server and IO:Error however the content loads and works.

Steps to Reproduce

require "kemal"

get "/" do | env |
    send_file env, "./public/jingles/1.mp3", "audio/mpeg"
end

Kemal.run

Expected behavior: No errors thrown, as the code is very basic and taken directly from the docs.

Actual behavior:

 main ● ?  ✔  crystal source/server.cr                                                                                               1.86 L  15:04:52
[development] Kemal is ready to lead at http://0.0.0.0:3000
Exception: Error while writing data to the client (HTTP::Server::ClientError)
  from ../../../../../usr/local/Cellar/crystal/0.35.1_1/src/http/server/response.cr:215:9 in 'unbuffered_write'
  from ../../../../../usr/local/Cellar/crystal/0.35.1_1/src/io/buffered.cr:217:5 in 'flush'
  from ../../../../../usr/local/Cellar/crystal/0.35.1_1/src/io/buffered.cr:156:7 in 'write'
  from ../../../../../usr/local/Cellar/crystal/0.35.1_1/src/http/server/response.cr:86:7 in 'write'
  from ../../../../../usr/local/Cellar/crystal/0.35.1_1/src/io.cr:1120:7 in 'copy'
  from lib/kemal/src/kemal/helpers/helpers.cr:169:7 in 'send_file'
  from source/server.cr:7:2 in '->'
  from ../../../../../usr/local/Cellar/crystal/0.35.1_1/src/primitives.cr:255:3 in '->'
  from ../../../../../usr/local/Cellar/crystal/0.35.1_1/src/primitives.cr:255:3 in 'process_request'
  from lib/kemal/src/kemal/route_handler.cr:17:7 in 'call'
  from ../../../../../usr/local/Cellar/crystal/0.35.1_1/src/http/server/handler.cr:28:7 in 'call_next'
  from lib/kemal/src/kemal/websocket_handler.cr:13:14 in 'call'
  from ../../../../../usr/local/Cellar/crystal/0.35.1_1/src/http/server/handler.cr:28:7 in 'call_next'
  from lib/kemal/src/kemal/exception_handler.cr:8:7 in 'call'
  from ../../../../../usr/local/Cellar/crystal/0.35.1_1/src/http/server/handler.cr:28:7 in 'call_next'
  from lib/kemal/src/kemal/log_handler.cr:8:37 in 'call'
  from ../../../../../usr/local/Cellar/crystal/0.35.1_1/src/http/server/handler.cr:28:7 in 'call_next'
  from lib/kemal/src/kemal/init_handler.cr:12:7 in 'call'
  from ../../../../../usr/local/Cellar/crystal/0.35.1_1/src/http/server/request_processor.cr:50:11 in 'process'
  from ../../../../../usr/local/Cellar/crystal/0.35.1_1/src/http/server.cr:513:5 in 'handle_client'
  from ../../../../../usr/local/Cellar/crystal/0.35.1_1/src/http/server.cr:468:13 in '->'
  from ../../../../../usr/local/Cellar/crystal/0.35.1_1/src/primitives.cr:255:3 in 'run'
  from ../../../../../usr/local/Cellar/crystal/0.35.1_1/src/fiber.cr:92:34 in '->'
Caused by: Error writing to socket: Broken pipe (IO::Error)
  from ../../../../../usr/local/Cellar/crystal/0.35.1_1/src/io/evented.cr:82:13 in 'unbuffered_write'
  from ../../../../../usr/local/Cellar/crystal/0.35.1_1/src/io/buffered.cr:152:14 in 'write'
  from ../../../../../usr/local/Cellar/crystal/0.35.1_1/src/http/server/response.cr:211:11 in 'unbuffered_write'
  from ../../../../../usr/local/Cellar/crystal/0.35.1_1/src/io/buffered.cr:217:5 in 'flush'
  from ../../../../../usr/local/Cellar/crystal/0.35.1_1/src/io/buffered.cr:156:7 in 'write'
  from ../../../../../usr/local/Cellar/crystal/0.35.1_1/src/http/server/response.cr:86:7 in 'write'
  from ../../../../../usr/local/Cellar/crystal/0.35.1_1/src/io.cr:1120:7 in 'copy'
  from lib/kemal/src/kemal/helpers/helpers.cr:169:7 in 'send_file'
  from source/server.cr:7:2 in '->'
  from ../../../../../usr/local/Cellar/crystal/0.35.1_1/src/primitives.cr:255:3 in '->'
  from ../../../../../usr/local/Cellar/crystal/0.35.1_1/src/primitives.cr:255:3 in 'process_request'
  from lib/kemal/src/kemal/route_handler.cr:17:7 in 'call'
  from ../../../../../usr/local/Cellar/crystal/0.35.1_1/src/http/server/handler.cr:28:7 in 'call_next'
  from lib/kemal/src/kemal/websocket_handler.cr:13:14 in 'call'
  from ../../../../../usr/local/Cellar/crystal/0.35.1_1/src/http/server/handler.cr:28:7 in 'call_next'
  from lib/kemal/src/kemal/exception_handler.cr:8:7 in 'call'
  from ../../../../../usr/local/Cellar/crystal/0.35.1_1/src/http/server/handler.cr:28:7 in 'call_next'
  from lib/kemal/src/kemal/log_handler.cr:8:37 in 'call'
  from ../../../../../usr/local/Cellar/crystal/0.35.1_1/src/http/server/handler.cr:28:7 in 'call_next'
  from lib/kemal/src/kemal/init_handler.cr:12:7 in 'call'
  from ../../../../../usr/local/Cellar/crystal/0.35.1_1/src/http/server/request_processor.cr:50:11 in 'process'
  from ../../../../../usr/local/Cellar/crystal/0.35.1_1/src/http/server.cr:513:5 in 'handle_client'
  from ../../../../../usr/local/Cellar/crystal/0.35.1_1/src/http/server.cr:468:13 in '->'
  from ../../../../../usr/local/Cellar/crystal/0.35.1_1/src/primitives.cr:255:3 in 'run'
  from ../../../../../usr/local/Cellar/crystal/0.35.1_1/src/fiber.cr:92:34 in '->'

2020-10-29T09:34:58.980583Z  ERROR - http.server: Unhandled exception on HTTP::Handler
Closed stream (IO::Error)
  from ../../../../../usr/local/Cellar/crystal/0.35.1_1/src/io.cr:118:5 in 'check_open'
  from ../../../../../usr/local/Cellar/crystal/0.35.1_1/src/io/buffered.cr:131:15 in 'write'
  from ../../../../../usr/local/Cellar/crystal/0.35.1_1/src/http/server/response.cr:86:7 in 'write'
  from ../../../../../usr/local/Cellar/crystal/0.35.1_1/src/io.cr:470:7 in 'write_utf8'
  from ../../../../../usr/local/Cellar/crystal/0.35.1_1/src/string.cr:4789:5 in 'to_s'
  from ../../../../../usr/local/Cellar/crystal/0.35.1_1/src/io.cr:174:5 in '<<'
  from ../../../../../usr/local/Cellar/crystal/0.35.1_1/src/io.cr:188:5 in 'print'
  from lib/kemal/src/kemal/helpers/templates.cr:33:3 in 'render_500'
  from lib/kemal/src/kemal/exception_handler.cr:17:7 in 'call'
  from ../../../../../usr/local/Cellar/crystal/0.35.1_1/src/http/server/handler.cr:28:7 in 'call_next'
  from lib/kemal/src/kemal/log_handler.cr:8:37 in 'call'
  from ../../../../../usr/local/Cellar/crystal/0.35.1_1/src/http/server/handler.cr:28:7 in 'call_next'
  from lib/kemal/src/kemal/init_handler.cr:12:7 in 'call'
  from ../../../../../usr/local/Cellar/crystal/0.35.1_1/src/http/server/request_processor.cr:50:11 in 'process'
  from ../../../../../usr/local/Cellar/crystal/0.35.1_1/src/http/server.cr:513:5 in 'handle_client'
  from ../../../../../usr/local/Cellar/crystal/0.35.1_1/src/http/server.cr:468:13 in '->'
  from ../../../../../usr/local/Cellar/crystal/0.35.1_1/src/primitives.cr:255:3 in 'run'
  from ../../../../../usr/local/Cellar/crystal/0.35.1_1/src/fiber.cr:92:34 in '->'

Reproduces how often: Everytime

Versions

LLVM: 10.0.0
Default target: x86_64-apple-macosx

OS: Mac OS Catalina

[Dan-Do]

I have the same issue. How to reproduce (don't know if it works on your environment):

setup local server (build using kemal), then start the process on terminal
open Firefox then go to the home url of your site, for example mine is http://0.0.0.0:8080/
click any link to go to other page, for example http://0.0.0.0:8080/page1
open terminal, press CTLR+C to shutdown your server process
start a new server instance
go to the browser, click the back button to go 1 level of history (ex http://0.0.0.0:8080/)
check to kemal error log

Exception: Error while writing data to the client (HTTP::Server::ClientError)
  from ../../../../../usr/share/crystal/src/http/server/response.cr:216:9 in 'unbuffered_write'
  from ../../../../../usr/share/crystal/src/io/buffered.cr:152:14 in 'write'
  from ../../../../../usr/share/crystal/src/http/server/response.cr:86:7 in 'write'
  from ../../../../../usr/share/crystal/src/io.cr:470:7 in 'write_utf8'
  from ../../../../../usr/share/crystal/src/string.cr:4961:5 in 'to_s'
  from ../../../../../usr/share/crystal/src/io.cr:174:5 in '<<'
  from ../../../../../usr/share/crystal/src/io.cr:188:5 in 'print'
  from lib/kemal/src/kemal/route_handler.cr:55: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:28: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:28: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:28: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:28:7 in 'call_next'
  from ../../../../../usr/share/crystal/src/http/server/handlers/static_file_handler.cr:103:7 in 'call'
  from ../../../../../usr/share/crystal/src/http/server/handler.cr:28:7 in 'call_next'
  from lib/kemal/src/kemal/null_log_handler.cr:5:7 in 'call'
  from ../../../../../usr/share/crystal/src/http/server/handler.cr:28:7 in 'call_next'
  from lib/kemal/src/kemal/init_handler.cr:12:7 in 'call'
  from ../../../../../usr/share/crystal/src/http/server/request_processor.cr:50:11 in 'process'
  from ../../../../../usr/share/crystal/src/http/server.cr:513:5 in 'handle_client'
  from ../../../../../usr/share/crystal/src/http/server.cr:468:13 in '->'
  from ../../../../../usr/share/crystal/src/primitives.cr:255:3 in 'run'
  from ../../../../../usr/share/crystal/src/fiber.cr:92:34 in '->'
  from ???
Caused by: Error writing to socket: Broken pipe (IO::Error)
  from ../../../../../usr/share/crystal/src/io/evented.cr:82:13 in 'unbuffered_write'
  from ../../../../../usr/share/crystal/src/io/buffered.cr:152:14 in 'write'
  from ../../../../../usr/share/crystal/src/http/server/response.cr:209:11 in 'unbuffered_write'
  from ../../../../../usr/share/crystal/src/io/buffered.cr:152:14 in 'write'
  from ../../../../../usr/share/crystal/src/http/server/response.cr:86:7 in 'write'
  from ../../../../../usr/share/crystal/src/io.cr:470:7 in 'write_utf8'
  from ../../../../../usr/share/crystal/src/string.cr:4961:5 in 'to_s'
  from ../../../../../usr/share/crystal/src/io.cr:174:5 in '<<'
  from ../../../../../usr/share/crystal/src/io.cr:188:5 in 'print'
  from lib/kemal/src/kemal/route_handler.cr:55: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:28: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:28: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:28: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:28:7 in 'call_next'
  from ../../../../../usr/share/crystal/src/http/server/handlers/static_file_handler.cr:103:7 in 'call'
  from ../../../../../usr/share/crystal/src/http/server/handler.cr:28:7 in 'call_next'
  from lib/kemal/src/kemal/null_log_handler.cr:5:7 in 'call'
  from ../../../../../usr/share/crystal/src/http/server/handler.cr:28:7 in 'call_next'
  from lib/kemal/src/kemal/init_handler.cr:12:7 in 'call'
  from ../../../../../usr/share/crystal/src/http/server/request_processor.cr:50:11 in 'process'
  from ../../../../../usr/share/crystal/src/http/server.cr:513:5 in 'handle_client'
  from ../../../../../usr/share/crystal/src/http/server.cr:468:13 in '->'
  from ../../../../../usr/share/crystal/src/primitives.cr:255:3 in 'run'
  from ../../../../../usr/share/crystal/src/fiber.cr:92:34 in '->'
  from ???

There are some reports on this link https://github.com/crystal-lang/crystal/issues/9065

[khan-vinn]

I have the same issue. How to reproduce (don't know if it works on your environment):

setup local server (build using kemal), then start the process on terminal
open Firefox then go to the home url of your site, for example mine is http://0.0.0.0:8080/
click any link to go to other page, for example http://0.0.0.0:8080/page1
open terminal, press CTLR+C to shutdown your server process
start a new server instance
go to the browser, click the back button to go 1 level of history (ex http://0.0.0.0:8080/)
check to kemal error log

Exception: Error while writing data to the client (HTTP::Server::ClientError)
  from ../../../../../usr/share/crystal/src/http/server/response.cr:216:9 in 'unbuffered_write'
  from ../../../../../usr/share/crystal/src/io/buffered.cr:152:14 in 'write'
  from ../../../../../usr/share/crystal/src/http/server/response.cr:86:7 in 'write'
  from ../../../../../usr/share/crystal/src/io.cr:470:7 in 'write_utf8'
  from ../../../../../usr/share/crystal/src/string.cr:4961:5 in 'to_s'
  from ../../../../../usr/share/crystal/src/io.cr:174:5 in '<<'
  from ../../../../../usr/share/crystal/src/io.cr:188:5 in 'print'
  from lib/kemal/src/kemal/route_handler.cr:55: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:28: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:28: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:28: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:28:7 in 'call_next'
  from ../../../../../usr/share/crystal/src/http/server/handlers/static_file_handler.cr:103:7 in 'call'
  from ../../../../../usr/share/crystal/src/http/server/handler.cr:28:7 in 'call_next'
  from lib/kemal/src/kemal/null_log_handler.cr:5:7 in 'call'
  from ../../../../../usr/share/crystal/src/http/server/handler.cr:28:7 in 'call_next'
  from lib/kemal/src/kemal/init_handler.cr:12:7 in 'call'
  from ../../../../../usr/share/crystal/src/http/server/request_processor.cr:50:11 in 'process'
  from ../../../../../usr/share/crystal/src/http/server.cr:513:5 in 'handle_client'
  from ../../../../../usr/share/crystal/src/http/server.cr:468:13 in '->'
  from ../../../../../usr/share/crystal/src/primitives.cr:255:3 in 'run'
  from ../../../../../usr/share/crystal/src/fiber.cr:92:34 in '->'
  from ???
Caused by: Error writing to socket: Broken pipe (IO::Error)
  from ../../../../../usr/share/crystal/src/io/evented.cr:82:13 in 'unbuffered_write'
  from ../../../../../usr/share/crystal/src/io/buffered.cr:152:14 in 'write'
  from ../../../../../usr/share/crystal/src/http/server/response.cr:209:11 in 'unbuffered_write'
  from ../../../../../usr/share/crystal/src/io/buffered.cr:152:14 in 'write'
  from ../../../../../usr/share/crystal/src/http/server/response.cr:86:7 in 'write'
  from ../../../../../usr/share/crystal/src/io.cr:470:7 in 'write_utf8'
  from ../../../../../usr/share/crystal/src/string.cr:4961:5 in 'to_s'
  from ../../../../../usr/share/crystal/src/io.cr:174:5 in '<<'
  from ../../../../../usr/share/crystal/src/io.cr:188:5 in 'print'
  from lib/kemal/src/kemal/route_handler.cr:55: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:28: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:28: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:28: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:28:7 in 'call_next'
  from ../../../../../usr/share/crystal/src/http/server/handlers/static_file_handler.cr:103:7 in 'call'
  from ../../../../../usr/share/crystal/src/http/server/handler.cr:28:7 in 'call_next'
  from lib/kemal/src/kemal/null_log_handler.cr:5:7 in 'call'
  from ../../../../../usr/share/crystal/src/http/server/handler.cr:28:7 in 'call_next'
  from lib/kemal/src/kemal/init_handler.cr:12:7 in 'call'
  from ../../../../../usr/share/crystal/src/http/server/request_processor.cr:50:11 in 'process'
  from ../../../../../usr/share/crystal/src/http/server.cr:513:5 in 'handle_client'
  from ../../../../../usr/share/crystal/src/http/server.cr:468:13 in '->'
  from ../../../../../usr/share/crystal/src/primitives.cr:255:3 in 'run'
  from ../../../../../usr/share/crystal/src/fiber.cr:92:34 in '->'
  from ???

There are some reports on this link crystal-lang/crystal#9065

may be file's path incorrect

should be -> /path/to/your/file/from/parent/directory/

[Sija]

The Error writing to socket: Broken pipe (IO::Error) error most likely occurs when the client disconnects before the server fulfils the request. IIRC in most cases is rather harmless and can be ignored.

See https://github.com/crystal-lang/crystal/pull/9034#discussion_r406977081 and https://github.com/crystal-lang/crystal/pull/9115#discussion_r412258095.

[Sija]

I think this issue can safely be closed.

[unixfox]

It's an issue for high traffic applications, you are flooded by these logs, and you can't read the other useful lines of log.

In invidious, we had to override the class in order to not get these exceptions: https://github.com/iv-org/invidious/blob/master/src/invidious/helpers/crystal_class_overrides.cr#L51

Otherwise, on a high traffic application we would get these errors every second: https://github.com/iv-org/invidious/issues/1416

For me, it is still worth it to keep this issue open until we find a configurable parameter to mute these errors. Kemal is the only library where I have seen these error logs, I have never seen such logs in other libraries in other programming language.

[sdogruyol]

Hey @unixfox thanks a lot for the feedback, I'll reopen the issue. @straight-shoota do you have any idea if we can do anything about this in std-lib or kemal itself?

[curioustolearn]

I think I ran into this issue today when about 60 people tried to access my server at the same time. Here is the error I saw (multiple times) and the server became unresponsive. I just wanted to share this here. Is there a solution to this? It seems like it is not only a problem with logs getting cluttered with these messages, it also affects the responsiveness of the server.

Thank you.

Sep 03 14:26:02 webapps-server crystalquiz[62307]: Unhandled exception in spawn: Error while flushing data to the client (HTTP::Server::ClientError)
Sep 03 14:26:02 webapps-server crystalquiz[62307]:   from /usr/share/crystal/src/http/server/response.cr:328:9 in 'unbuffered_flush'
Sep 03 14:26:02 webapps-server crystalquiz[62307]:   from /usr/share/crystal/src/io/buffered.cr:251:5 in 'flush'
Sep 03 14:26:02 webapps-server crystalquiz[62307]:   from /usr/share/crystal/src/io/buffered.cr:258:5 in 'close'
Sep 03 14:26:02 webapps-server crystalquiz[62307]:   from /usr/share/crystal/src/http/server/response.cr:298:9 in 'close'
Sep 03 14:26:02 webapps-server crystalquiz[62307]:   from /usr/share/crystal/src/http/server/request_processor.cr:63:11 in 'process'
Sep 03 14:26:02 webapps-server crystalquiz[62307]:   from /usr/share/crystal/src/http/server.cr:521:5 in 'handle_client'
Sep 03 14:26:02 webapps-server crystalquiz[62307]:   from /usr/share/crystal/src/http/server.cr:451:5 in '->'
Sep 03 14:26:02 webapps-server crystalquiz[62307]:   from /usr/share/crystal/src/fiber.cr:143:11 in 'run'
Sep 03 14:26:02 webapps-server crystalquiz[62307]:   from /usr/share/crystal/src/fiber.cr:95:34 in '->'
Sep 03 14:26:02 webapps-server crystalquiz[62307]:   from ???
Sep 03 14:26:02 webapps-server crystalquiz[62307]: Caused by: Error writing to socket (#<TCPSocket:0x76ed8e064690>): Broken pipe (IO::Error)
Sep 03 14:26:02 webapps-server crystalquiz[62307]:   from /usr/share/crystal/src/io/evented.cr:45:11 in 'write'
Sep 03 14:26:02 webapps-server crystalquiz[62307]:   from /usr/share/crystal/src/crystal/system/socket.cr:89:5 in 'system_write'
Sep 03 14:26:02 webapps-server crystalquiz[62307]:   from /usr/share/crystal/src/socket.cr:442:16 in 'unbuffered_write'
Sep 03 14:26:02 webapps-server crystalquiz[62307]:   from /usr/share/crystal/src/io/buffered.cr:250:5 in 'flush'