core.rb:203:in `_set_state!': undefined method `state=' for nil:NilClass (NoMethodError)

[cmrtdev]

I'm trying to debug an issue I've been experiencing with GitLab (https://gitlab.com/gitlab-org/gitlab/-/issues/547334 since they're not doing it...), which uses Puma, which in turn depends on ruby-timeout.

My apologies if this is not caused by rack-timeout directly, I am by no means a Ruby expert (I can somewhat read it, but can't develop in it), but I think this may be a case of an unhandled exception in rack-timeout.

I am seeing this in puma_stderr.log

#<Thread:0x00007f3d8e803f18 /opt/gitlab/embedded/lib/ruby/gems/3.2.0/gems/rack-timeout-0.7.0/lib/rack/timeout/support/scheduler.rb:72 run> terminated with exception (report_on_exception is true):
/opt/gitlab/embedded/lib/ruby/gems/3.2.0/gems/rack-timeout-0.7.0/lib/rack/timeout/core.rb:203:in `_set_state!': undefined method `state=' for nil:NilClass (NoMethodError)

      env[ENV_INFO_KEY].state = state
                       ^^^^^^^^
        from /opt/gitlab/embedded/lib/ruby/gems/3.2.0/gems/rack-timeout-0.7.0/lib/rack/timeout/core.rb:128:in `block in call'
        from /opt/gitlab/embedded/lib/ruby/gems/3.2.0/gems/rack-timeout-0.7.0/lib/rack/timeout/core.rb:130:in `block in call'
        from /opt/gitlab/embedded/lib/ruby/gems/3.2.0/gems/rack-timeout-0.7.0/lib/rack/timeout/support/scheduler.rb:38:in `run!'
        from /opt/gitlab/embedded/lib/ruby/gems/3.2.0/gems/rack-timeout-0.7.0/lib/rack/timeout/support/scheduler.rb:51:in `run!'
        from /opt/gitlab/embedded/lib/ruby/gems/3.2.0/gems/rack-timeout-0.7.0/lib/rack/timeout/support/scheduler.rb:99:in `block (2 levels) in run_loop!'
        from /opt/gitlab/embedded/lib/ruby/gems/3.2.0/gems/rack-timeout-0.7.0/lib/rack/timeout/support/scheduler.rb:99:in `each'
        from /opt/gitlab/embedded/lib/ruby/gems/3.2.0/gems/rack-timeout-0.7.0/lib/rack/timeout/support/scheduler.rb:99:in `block in run_loop!'
        from /opt/gitlab/embedded/lib/ruby/gems/3.2.0/gems/rack-timeout-0.7.0/lib/rack/timeout/support/scheduler.rb:80:in `loop'
        from /opt/gitlab/embedded/lib/ruby/gems/3.2.0/gems/rack-timeout-0.7.0/lib/rack/timeout/support/scheduler.rb:80:in `run_loop!'
        from /opt/gitlab/embedded/lib/ruby/gems/3.2.0/gems/rack-timeout-0.7.0/lib/rack/timeout/support/scheduler.rb:72:in `block (2 levels) in runner'
/opt/gitlab/embedded/lib/ruby/gems/3.2.0/gems/rack-timeout-0.7.0/lib/rack/timeout/core.rb:203:in `_set_state!': undefined method `state=' for nil:NilClass (NoMethodError)

      env[ENV_INFO_KEY].state = state
                       ^^^^^^^^
        from /opt/gitlab/embedded/lib/ruby/gems/3.2.0/gems/rack-timeout-0.7.0/lib/rack/timeout/core.rb:128:in `block in call'
        from /opt/gitlab/embedded/lib/ruby/gems/3.2.0/gems/rack-timeout-0.7.0/lib/rack/timeout/core.rb:130:in `block in call'
        from /opt/gitlab/embedded/lib/ruby/gems/3.2.0/gems/rack-timeout-0.7.0/lib/rack/timeout/support/scheduler.rb:38:in `run!'
        from /opt/gitlab/embedded/lib/ruby/gems/3.2.0/gems/rack-timeout-0.7.0/lib/rack/timeout/support/scheduler.rb:51:in `run!'
        from /opt/gitlab/embedded/lib/ruby/gems/3.2.0/gems/rack-timeout-0.7.0/lib/rack/timeout/support/scheduler.rb:99:in `block (2 levels) in run_loop!'
        from /opt/gitlab/embedded/lib/ruby/gems/3.2.0/gems/rack-timeout-0.7.0/lib/rack/timeout/support/scheduler.rb:99:in `each'
        from /opt/gitlab/embedded/lib/ruby/gems/3.2.0/gems/rack-timeout-0.7.0/lib/rack/timeout/support/scheduler.rb:99:in `block in run_loop!'
        from /opt/gitlab/embedded/lib/ruby/gems/3.2.0/gems/rack-timeout-0.7.0/lib/rack/timeout/support/scheduler.rb:80:in `loop'
        from /opt/gitlab/embedded/lib/ruby/gems/3.2.0/gems/rack-timeout-0.7.0/lib/rack/timeout/support/scheduler.rb:80:in `run_loop!'
        from /opt/gitlab/embedded/lib/ruby/gems/3.2.0/gems/rack-timeout-0.7.0/lib/rack/timeout/support/scheduler.rb:72:in `block (2 levels) in runner'

To me this seems like an unhandled exception in cases whererack-timeout calls RT._set_state!,

rack-timeout/lib/rack/timeout/core.rb

Line 128 in 69a26a7

RT._set_state! env, status # update status

Which internally does env[ENV_INFO_KEY].state = state

https://github.com/zombocom/rack-timeout/blob/69a26a7c59ab6bdd1e135ffa81ba871590c53803/lib/rack/timeout/core.rb#L203C7-L203C38

and, somehow, env["rack-timeout.info"]

https://github.com/zombocom/rack-timeout/blob/69a26a7c59ab6bdd1e135ffa81ba871590c53803/lib/rack/timeout/core.rb#L46C1-L46C125

is not returning the correct object.

I'm seeing a similar error in another log, which again is due to a missing state method from scheduler.rb, which makes me think it could be a similar issue.

Trace of the similar error

#<Thread:0x00007f3d9eceb390 /opt/gitlab/embedded/lib/ruby/gems/3.2.0/gems/rack-timeout-0.7.0/lib/rack/timeout/support/scheduler.rb:72 run> terminated with exception (report_on_exception is true):
/opt/gitlab/embedded/lib/ruby/gems/3.2.0/gems/rack-timeout-0.7.0/lib/rack/timeout/logging-observer.rb:44:in `log_state_change': undefined method `state' for nil:NilClass (NoMethodError)

    level = STATE_LOG_LEVEL[info.state]
                                ^^^^^^
        from /opt/gitlab/embedded/lib/ruby/gems/3.2.0/gems/rack-timeout-0.7.0/lib/rack/timeout/core.rb:227:in `block in notify_state_change_observers'
        from /opt/gitlab/embedded/lib/ruby/gems/3.2.0/gems/rack-timeout-0.7.0/lib/rack/timeout/core.rb:227:in `each'
        from /opt/gitlab/embedded/lib/ruby/gems/3.2.0/gems/rack-timeout-0.7.0/lib/rack/timeout/core.rb:227:in `notify_state_change_observers'
        from /opt/gitlab/embedded/lib/ruby/gems/3.2.0/gems/rack-timeout-0.7.0/lib/rack/timeout/core.rb:204:in `_set_state!'
        from /opt/gitlab/embedded/lib/ruby/gems/3.2.0/gems/rack-timeout-0.7.0/lib/rack/timeout/core.rb:128:in `block in call'
        from /opt/gitlab/embedded/lib/ruby/gems/3.2.0/gems/rack-timeout-0.7.0/lib/rack/timeout/core.rb:130:in `block in call'
        from /opt/gitlab/embedded/lib/ruby/gems/3.2.0/gems/rack-timeout-0.7.0/lib/rack/timeout/support/scheduler.rb:38:in `run!'
        from /opt/gitlab/embedded/lib/ruby/gems/3.2.0/gems/rack-timeout-0.7.0/lib/rack/timeout/support/scheduler.rb:51:in `run!'
        from /opt/gitlab/embedded/lib/ruby/gems/3.2.0/gems/rack-timeout-0.7.0/lib/rack/timeout/support/scheduler.rb:99:in `block (2 levels) in run_loop!'
        from /opt/gitlab/embedded/lib/ruby/gems/3.2.0/gems/rack-timeout-0.7.0/lib/rack/timeout/support/scheduler.rb:99:in `each'
        from /opt/gitlab/embedded/lib/ruby/gems/3.2.0/gems/rack-timeout-0.7.0/lib/rack/timeout/support/scheduler.rb:99:in `block in run_loop!'
        from /opt/gitlab/embedded/lib/ruby/gems/3.2.0/gems/rack-timeout-0.7.0/lib/rack/timeout/support/scheduler.rb:80:in `loop'
        from /opt/gitlab/embedded/lib/ruby/gems/3.2.0/gems/rack-timeout-0.7.0/lib/rack/timeout/support/scheduler.rb:80:in `run_loop!'
        from /opt/gitlab/embedded/lib/ruby/gems/3.2.0/gems/rack-timeout-0.7.0/lib/rack/timeout/support/scheduler.rb:72:in `block (2 levels) in runner'
/opt/gitlab/embedded/lib/ruby/gems/3.2.0/gems/rack-timeout-0.7.0/lib/rack/timeout/logging-observer.rb:44:in `log_state_change': undefined method `state' for nil:NilClass (NoMethodError)

    level = STATE_LOG_LEVEL[info.state]
                                ^^^^^^
        from /opt/gitlab/embedded/lib/ruby/gems/3.2.0/gems/rack-timeout-0.7.0/lib/rack/timeout/core.rb:227:in `block in notify_state_change_observers'
        from /opt/gitlab/embedded/lib/ruby/gems/3.2.0/gems/rack-timeout-0.7.0/lib/rack/timeout/core.rb:227:in `each'
        from /opt/gitlab/embedded/lib/ruby/gems/3.2.0/gems/rack-timeout-0.7.0/lib/rack/timeout/core.rb:227:in `notify_state_change_observers'
        from /opt/gitlab/embedded/lib/ruby/gems/3.2.0/gems/rack-timeout-0.7.0/lib/rack/timeout/core.rb:204:in `_set_state!'
        from /opt/gitlab/embedded/lib/ruby/gems/3.2.0/gems/rack-timeout-0.7.0/lib/rack/timeout/core.rb:128:in `block in call'
        from /opt/gitlab/embedded/lib/ruby/gems/3.2.0/gems/rack-timeout-0.7.0/lib/rack/timeout/core.rb:130:in `block in call'
        from /opt/gitlab/embedded/lib/ruby/gems/3.2.0/gems/rack-timeout-0.7.0/lib/rack/timeout/support/scheduler.rb:38:in `run!'
        from /opt/gitlab/embedded/lib/ruby/gems/3.2.0/gems/rack-timeout-0.7.0/lib/rack/timeout/support/scheduler.rb:51:in `run!'
        from /opt/gitlab/embedded/lib/ruby/gems/3.2.0/gems/rack-timeout-0.7.0/lib/rack/timeout/support/scheduler.rb:99:in `block (2 levels) in run_loop!'
        from /opt/gitlab/embedded/lib/ruby/gems/3.2.0/gems/rack-timeout-0.7.0/lib/rack/timeout/support/scheduler.rb:99:in `each'
        from /opt/gitlab/embedded/lib/ruby/gems/3.2.0/gems/rack-timeout-0.7.0/lib/rack/timeout/support/scheduler.rb:99:in `block in run_loop!'
        from /opt/gitlab/embedded/lib/ruby/gems/3.2.0/gems/rack-timeout-0.7.0/lib/rack/timeout/support/scheduler.rb:80:in `loop'
        from /opt/gitlab/embedded/lib/ruby/gems/3.2.0/gems/rack-timeout-0.7.0/lib/rack/timeout/support/scheduler.rb:80:in `run_loop!'
        from /opt/gitlab/embedded/lib/ruby/gems/3.2.0/gems/rack-timeout-0.7.0/lib/rack/timeout/support/scheduler.rb:72:in `block (2 levels) in runner'

I don't know exactly what's triggering this; I suspect that it could be due to something overwriting or cleaning up the env, or an incorrect call ordering (maybe Puma is calling ruby-timeout before it's been initialized?), but should ruby-timeout check that env[ENV_INFO_KEY] is either a valid object, or initialized, before trying to call state on it?

The same applies to that info in the second example, which is initialized as env[::Rack::Timeout::ENV_INFO_KEY]

rack-timeout/lib/rack/timeout/logging-observer.rb

Line 43 in 69a26a7

info = env[::Rack::Timeout::ENV_INFO_KEY]

Thanks!