Error reading client message

[sentry-io]

Sentry Issue: POSEIDON-5C

Error reading client message

By now the error is always websocket: close 1006 (abnormal closure): unexpected EOF. As defined in the RFC6455 this is a low-level WebSocket error, i.e. indicating that the connection was closed without a WebSocket closing message.

This issue is currently just affecting 0.006% of all WebSocket connections (in the last 30 days).

• Check for the last few events if there are any further logs.

[mpass99]

We can match the Poseidon Logs and CodeOcean's Puma Access Logs. The error looks the same in the last three occurrences.

Poseidon Logs

2024-07-23T12:40:06.377646+00:00 msg="Error reading client message" environment_id=29 error="websocket: close 1006 (abnormal closure): unexpected EOF" runner_id=29-e296927e-48ee-11ef-bf70-fa163efe023e

Puma Access Logs

I, [2024-07-23T12:40:06.390377 #2274106]  INFO -- : [bb8caa51-0186-4f51-9706-39bacf173ac6] Completed 500 Internal Server Error in 9994ms (Views: 2.3ms | ActiveRecord: 71.5ms | Allocations: 19105)
E, [2024-07-23T12:40:06.395558 #2274106] ERROR -- : [bb8caa51-0186-4f51-9706-39bacf173ac6]
[bb8caa51-0186-4f51-9706-39bacf173ac6] NoMethodError (undefined method `rails' for nil):
[bb8caa51-0186-4f51-9706-39bacf173ac6]
[bb8caa51-0186-4f51-9706-39bacf173ac6] lib/middleware/web_socket_sentry_headers.rb:12:in `call'

@MrSerth do you have an idea about the underlying issue?

[MrSerth]

Thanks for making me aware of a potential CodeOcean issue here. The fact that both logs align with each other and that you see an exception in CodeOcean suggests that one request is causing an exception that, leading to an abrupt and abnormal termination of the connection. This would match the error generated by Poseidon, I assume.

Unfortunately, however, the log details by CodeOcean are insufficient. The middleware shown is part of our application and all other frames are not (and therefore hidden). In the respective file is no method called rails, so that this must be part of another gem. Logging into the source code further, there are (of course) multiple rails calls, mostly when trying to access some configuration. It might be Sentry (when capturing another exception), but it could be well any other gem, too.

I've extended the logging for exceptions and disabled the backtrace silencer (which normally hides the stack trace of library files) by setting the environment variable BACKTRACE=1. We'll now need to wait for the next occurrence.

[MrSerth]

We observed another occurrence 🥳, allowing us to continue here.

Stack Trace

I, [2024-08-21T14:03:43.007809 #1986508]  INFO -- : [a2b43a9f-e093-4f15-86fb-b8e9318e8a8c] Started GET "/submissions/55300934/run/aufgabe433.py?HTTP_SENTRY_TRACE=XXX&HTTP_BAGGAGE=XXX" for [IP] at 2024-08-21 14:03:43 +0000
I, [2024-08-21T14:03:43.009407 #1986508]  INFO -- : [a2b43a9f-e093-4f15-86fb-b8e9318e8a8c] Processing by SubmissionsController#run as */*
I, [2024-08-21T14:03:43.009502 #1986508]  INFO -- : [a2b43a9f-e093-4f15-86fb-b8e9318e8a8c]   Parameters: {"id"=>"55300934", "filename"=>"aufgabe433.py"}
I, [2024-08-21T14:04:12.787065 #1986508]  INFO -- : [a2b43a9f-e093-4f15-86fb-b8e9318e8a8c] Completed 500 Internal Server Error in 29777ms (Views: 0.6ms | ActiveRecord: 52.0ms | Allocations: 88117)

E, [2024-08-21T14:04:12.794958 #1986508] ERROR -- : [a2b43a9f-e093-4f15-86fb-b8e9318e8a8c]   
[a2b43a9f-e093-4f15-86fb-b8e9318e8a8c] NoMethodError (undefined method `rails' for nil):
[a2b43a9f-e093-4f15-86fb-b8e9318e8a8c]   
[a2b43a9f-e093-4f15-86fb-b8e9318e8a8c] sentry-rails (5.18.2) lib/sentry/rails/rescued_exception_interceptor.rb:20:in `report_rescued_exceptions?'
[a2b43a9f-e093-4f15-86fb-b8e9318e8a8c] sentry-rails (5.18.2) lib/sentry/rails/rescued_exception_interceptor.rb:14:in `rescue in call'
[a2b43a9f-e093-4f15-86fb-b8e9318e8a8c] sentry-rails (5.18.2) lib/sentry/rails/rescued_exception_interceptor.rb:11:in `call'
[a2b43a9f-e093-4f15-86fb-b8e9318e8a8c] actionpack (7.1.3.4) lib/action_dispatch/middleware/debug_exceptions.rb:29:in `call'
[a2b43a9f-e093-4f15-86fb-b8e9318e8a8c] sentry-ruby (5.18.2) lib/sentry/rack/capture_exceptions.rb:30:in `block (2 levels) in call'
[a2b43a9f-e093-4f15-86fb-b8e9318e8a8c] sentry-ruby (5.18.2) lib/sentry/hub.rb:258:in `with_session_tracking'
[a2b43a9f-e093-4f15-86fb-b8e9318e8a8c] sentry-ruby (5.18.2) lib/sentry-ruby.rb:404:in `with_session_tracking'
[a2b43a9f-e093-4f15-86fb-b8e9318e8a8c] sentry-ruby (5.18.2) lib/sentry/rack/capture_exceptions.rb:21:in `block in call'
[a2b43a9f-e093-4f15-86fb-b8e9318e8a8c] sentry-ruby (5.18.2) lib/sentry/hub.rb:59:in `with_scope'
[a2b43a9f-e093-4f15-86fb-b8e9318e8a8c] sentry-ruby (5.18.2) lib/sentry-ruby.rb:384:in `with_scope'
[a2b43a9f-e093-4f15-86fb-b8e9318e8a8c] sentry-ruby (5.18.2) lib/sentry/rack/capture_exceptions.rb:20:in `call'
[a2b43a9f-e093-4f15-86fb-b8e9318e8a8c] actionpack (7.1.3.4) lib/action_dispatch/middleware/show_exceptions.rb:31:in `call'
[a2b43a9f-e093-4f15-86fb-b8e9318e8a8c] railties (7.1.3.4) lib/rails/rack/logger.rb:37:in `call_app'
[a2b43a9f-e093-4f15-86fb-b8e9318e8a8c] railties (7.1.3.4) lib/rails/rack/logger.rb:24:in `block in call'
[a2b43a9f-e093-4f15-86fb-b8e9318e8a8c] activesupport (7.1.3.4) lib/active_support/tagged_logging.rb:135:in `block in tagged'
[a2b43a9f-e093-4f15-86fb-b8e9318e8a8c] activesupport (7.1.3.4) lib/active_support/tagged_logging.rb:39:in `tagged'
[a2b43a9f-e093-4f15-86fb-b8e9318e8a8c] activesupport (7.1.3.4) lib/active_support/tagged_logging.rb:135:in `tagged'
[a2b43a9f-e093-4f15-86fb-b8e9318e8a8c] activesupport (7.1.3.4) lib/active_support/broadcast_logger.rb:240:in `method_missing'
[a2b43a9f-e093-4f15-86fb-b8e9318e8a8c] railties (7.1.3.4) lib/rails/rack/logger.rb:24:in `call'
[a2b43a9f-e093-4f15-86fb-b8e9318e8a8c] actionpack (7.1.3.4) lib/action_dispatch/middleware/remote_ip.rb:92:in `call'
[a2b43a9f-e093-4f15-86fb-b8e9318e8a8c] actionpack (7.1.3.4) lib/action_dispatch/middleware/request_id.rb:28:in `call'
[a2b43a9f-e093-4f15-86fb-b8e9318e8a8c] rack (3.1.7) lib/rack/method_override.rb:28:in `call'
[a2b43a9f-e093-4f15-86fb-b8e9318e8a8c] rack (3.1.7) lib/rack/runtime.rb:24:in `call'
[a2b43a9f-e093-4f15-86fb-b8e9318e8a8c] actionpack (7.1.3.4) lib/action_dispatch/middleware/executor.rb:14:in `call'
[a2b43a9f-e093-4f15-86fb-b8e9318e8a8c] rack (3.1.7) lib/rack/sendfile.rb:114:in `call'
[a2b43a9f-e093-4f15-86fb-b8e9318e8a8c] actionpack (7.1.3.4) lib/action_dispatch/middleware/ssl.rb:79:in `call'
[a2b43a9f-e093-4f15-86fb-b8e9318e8a8c] actionpack (7.1.3.4) lib/action_dispatch/middleware/assume_ssl.rb:21:in `call'
[a2b43a9f-e093-4f15-86fb-b8e9318e8a8c] lib/middleware/web_socket_sentry_headers.rb:12:in `call'
[a2b43a9f-e093-4f15-86fb-b8e9318e8a8c] mnemosyne-ruby (2.0.0) lib/mnemosyne/middleware/rack.rb:78:in `call'
[a2b43a9f-e093-4f15-86fb-b8e9318e8a8c] telegraf (3.0.0) lib/telegraf/rack.rb:67:in `call'
[a2b43a9f-e093-4f15-86fb-b8e9318e8a8c] railties (7.1.3.4) lib/rails/engine.rb:536:in `call'
[a2b43a9f-e093-4f15-86fb-b8e9318e8a8c] rack (3.1.7) lib/rack/urlmap.rb:76:in `block in call'
[a2b43a9f-e093-4f15-86fb-b8e9318e8a8c] rack (3.1.7) lib/rack/urlmap.rb:60:in `each'
[a2b43a9f-e093-4f15-86fb-b8e9318e8a8c] rack (3.1.7) lib/rack/urlmap.rb:60:in `call'
[a2b43a9f-e093-4f15-86fb-b8e9318e8a8c] puma (6.4.2) lib/puma/configuration.rb:272:in `call'
[a2b43a9f-e093-4f15-86fb-b8e9318e8a8c] puma (6.4.2) lib/puma/request.rb:100:in `block in handle_request'
[a2b43a9f-e093-4f15-86fb-b8e9318e8a8c] puma (6.4.2) lib/puma/thread_pool.rb:378:in `with_force_shutdown'
[a2b43a9f-e093-4f15-86fb-b8e9318e8a8c] puma (6.4.2) lib/puma/request.rb:99:in `handle_request'
[a2b43a9f-e093-4f15-86fb-b8e9318e8a8c] puma (6.4.2) lib/puma/server.rb:464:in `process_client'
[a2b43a9f-e093-4f15-86fb-b8e9318e8a8c] puma (6.4.2) lib/puma/server.rb:245:in `block in run'
[a2b43a9f-e093-4f15-86fb-b8e9318e8a8c] puma (6.4.2) lib/puma/thread_pool.rb:155:in `block in spawn_thread'

[1985897] - Worker 5 (PID: 3493267) booted in 0.03s, phase: 0

The error caused an abnormal worker exit, based on the unhandled exception. As you can see, our middleware wasn't causing the issue, but rather the Sentry integration (as I assumed 🤓).

Hence, I created issue getsentry/sentry-ruby#2386 (and getsentry/sentry-ruby#2378 previously). Furthermore, I've added some custom logging before the Sentry-caused issue to identify the actual root cause. Now, we need to wait again.

[MrSerth]

Still waiting for the next occurrence, I need to fix the issue in CodeOcean. This is no Poseidon-related bug.

[MrSerth]

I observed another occurrence of this issue.

Details

I, [2024-10-10T19:04:56.877032 #544012]  INFO -- : [b9293bfe-7e78-464f-a187-9e4d423a4150] Started GET "/submissions/56443662/run/sipl15_skript1.py?HTTP_SENTRY_TRACE=XXX&HTTP_BAGGAGE=XXX" for [IP] at 2024-10-10 19:04:56 +0000
I, [2024-10-10T19:04:56.877960 #544012]  INFO -- : [b9293bfe-7e78-464f-a187-9e4d423a4150] Processing by SubmissionsController#run as HTML
I, [2024-10-10T19:04:56.878007 #544012]  INFO -- : [b9293bfe-7e78-464f-a187-9e4d423a4150]   Parameters: {"id"=>"56443662", "filename"=>"sipl15_skript1.py"}
#<Thread:0x00007ee85af9f3f0 vendor/bundle/ruby/3.3.0/bundler/gems/tubesock-2c83794b85e8/lib/tubesock.rb:78 run> terminated with exception (report_on_exception

vendor/bundle/ruby/3.3.0/bundler/gems/tubesock-2c83794b85e8/lib/tubesock.rb:145:in `each_frame': undefined method `empty?' for nil (NoMethodError)
      break if data.empty?
                   ^^^^^^^
#011from vendor/bundle/ruby/3.3.0/bundler/gems/tubesock-2c83794b85e8/lib/tubesock.rb:82:in `block in listen'
I, [2024-10-10T19:04:57.136278 #544054]  INFO -- : [0305cb10-f166-4ebd-a5a3-35bef46abdee] Completed 500 Internal Server Error in 372ms (Views: 0.3ms | ActiveRecord: 39.9ms (

E, [2024-10-10T19:04:57.138783 #544054] ERROR -- : [0305cb10-f166-4ebd-a5a3-35bef46abdee]
[0305cb10-f166-4ebd-a5a3-35bef46abdee] NoMethodError (undefined method `rails' for nil):
[0305cb10-f166-4ebd-a5a3-35bef46abdee]
[0305cb10-f166-4ebd-a5a3-35bef46abdee] sentry-rails (5.21.0) lib/sentry/rails/rescued_exception_interceptor.rb:22:in `report_rescued_exceptions?'

This time, there was a clear relationship to the tubesock gem and a failed connection to the learner. Therefore, I created a custom fork of tubesock and fixed the underlying issue there: openHPI/tubesock#3. This should avoid an abnormal termination of the thread, and therefore the connection to Poseidon. For now, it fixed the issue and no thread was abnormally terminated in the last 1.5 days (previously, we had at least one occurrence every hour or so based on the current usage).

With the fix in place, I am closing this issue (and the Sentry issue). For the remaining duration of the course, I'll continue to observe it. In the long term, we still want to replace tubesock with ActionCable, which is more stable.