kemalcr / kemal

Fast, Effective, Simple Web Framework
https://kemalcr.com
MIT License
3.62k stars 188 forks source link

Logs are messed up in multithreaded mode #646

Closed GeopJr closed 2 years ago

GeopJr commented 2 years ago

Description

In multithreaded mode (-Dpreview_mt), logs are messed up (see "Actual behavior").

Steps to Reproduce

  1. Create an example Kemal app:
    
    require "kemal"

get "/" do "Hello World!" end

Kemal.run

2. Run it using the `-Dpreview_mt` flag
3. Spam it using `wrk` or any other similar tool

**Expected behavior:** Logs to show up as such:

2022-09-03 13:42:42 UTC 200 GET / 9.22µs 2022-09-03 13:42:42 UTC 200 GET / 8.47µs 2022-09-03 13:42:42 UTC 200 GET / 9.87µs 2022-09-03 13:42:42 UTC 200 GET / 8.69µs 2022-09-03 13:42:42 UTC 200 GET / 9.63µs 2022-09-03 13:42:42 UTC 200 GET / 9.05µs


**Actual behavior:** Logs show up as such:

13:37:57 UTC 2022-200 GET0 9-/0 7.68µs� 13:UTC 200 GET / 7.94µs 2022-09-03 13:37:57 UTC 200 GET / 7.69µs 2022-09-032022 -093 -0373 57 13:UTC379:20 2022GET 0 200-GET 10.33µs012022-09-032022 -093 -0373 57 13:UTC379:20 2022GET 0 200-GET 10.33µs01/ 7.96µs0 20 / 7.12µs 2022-09-03 13:37:57 UTC 200 GET / 7.63µs 2022-09--0 9-:2022-003C 2-03 3:37::37:57s 57 UTCU 200 200 GET GET / /.74µs� 9.86µs 2022-09-03 13:37:57 UTC 200 GET / 7.63µs 2022-09-033 3132022:-370:9-2022570-36 0UTC9-13:200 337G T057 13G: 370 � 2022-09-033 3132022:-370:9-2022570-36 0UTC9-13:200 337G T057 13G: 370 � 8.26µs 033 3132022:-370:9-2022570-36 0UTC9-13:200 337G T057 13G: 370 � :GET 57 / 7.59µs 9 8.26µs 2022-09-03 13:37:57 UTC 2022200 GET3 00/ 7.88µs-13:3709:57 1 UTC 200 GET202 / 09.63µs 13:3709:57 1 UTC 200 GET202 / 09.63µs 113:37:57 UTC 200 GET / 10.2µs


**Reproduces how often:** 100%

### Versions

Crystal 1.5.0 [994c70b10] (2022-07-06)

LLVM: 10.0.0 Default target: x86_64-unknown-linux-gnu

Linux 5.19.2-1-default

kemal: git: https://github.com/kemalcr/kemal.git version: 1.2.0


### Additional Information

This issue is related to https://github.com/crystal-lang/crystal/issues/8140 (AFAIK).
On sabo-tabby, I fixed it by [creating a string instead of appending to STDOUT directly](https://github.com/GeopJr/sabo-tabby/blob/main/src/sabo-tabby/log_handler.cr#L37-L46):
```crystal
{% if flag?(:preview_mt) %}
    @io << "#{Time.utc} #{context.response.status_code} #{context.request.method} #{context.request.resource} #{elapsed_text}\n"
{% else %}
    @io << Time.utc << ' ' << context.response.status_code << ' ' << context.request.method << ' ' << context.request.resource << ' ' << elapsed_text << '\n'
{% end %}

This fixes it. I can make a PR if needed!

straight-shoota commented 2 years ago

I don't think Kemal is meant to be run multi-threaded.

And I actually don't see much reason for that. If you want your web server to run on multiple cores, you can spawn multiple processes, one for each core, and bind them all to the same network interface using kernel load-balancing.

GeopJr commented 2 years ago

Oh, I see. I remember seeing it mentioned back in 2019 (?) but it was probably just for benchmarks.

I'll go ahead and close this, thanks for info!