RailsSemanticLogger::Rack::Logger - NoMethodError: undefined method `pop' for nil:NilClass in fanout.rb

[atruskie]

Environment

Provide at least:

• Ruby Version: 3.2.2
• Rails Version: Rails 7.2.1.1
• Semantic Logger Version: 4.16
• Rails Semantic Logger Version: 4.17.0
• Other Application/framework names and versions (e.g. Puma, etc.): passenger (6.0.23)
• Rails configuration. Only need the settings related to Rails Semantic Logger and Semantic Logger.
• Full Stack Trace, if an exception is being raised.

 NoMethodError:
            undefined method `pop' for nil:NilClass
          # /usr/local/bundle/gems/activesupport-7.2.1.1/lib/active_support/notifications/fanout.rb:288:in `finish'
          # /usr/local/bundle/gems/activesupport-7.2.1.1/lib/active_support/notifications/instrumenter.rb:97:in `finish_with_state'
          # /usr/local/bundle/gems/rails_semantic_logger-4.17.0/lib/rails_semantic_logger/rack/logger.rb:41:in `block in call_app'
          # /usr/local/bundle/gems/rack-3.1.8/lib/rack/body_proxy.rb:34:in `close'
          # /usr/local/bundle/gems/rack-3.1.8/lib/rack/body_proxy.rb:32:in `close'
          # /usr/local/bundle/gems/rack-3.1.8/lib/rack/response.rb:349:in `buffered_body!'
          # /usr/local/bundle/gems/rack-3.1.8/lib/rack/mock_response.rb:36:in `initialize'
          # /usr/local/bundle/gems/rack-test-2.1.0/lib/rack/test.rb:362:in `new'
          # /usr/local/bundle/gems/rack-test-2.1.0/lib/rack/test.rb:362:in `process_request'
          # /usr/local/bundle/gems/rack-test-2.1.0/lib/rack/test.rb:153:in `request'
          # /usr/local/bundle/gems/actionpack-7.2.1.1/lib/action_dispatch/testing/integration.rb:287:in `process'
          # ./spec/support/request_spec_helpers.rb:26:in `process'
          # /usr/local/bundle/gems/actionpack-7.2.1.1/lib/action_dispatch/testing/integration.rb:19:in `get'
          # /usr/local/bundle/gems/actionpack-7.2.1.1/lib/action_dispatch/testing/integration.rb:378:in `get'
          # ./spec/support/shared_examples/a_route_that_stores_images.rb:201:in `block (3 levels) in <main>'
          # ./spec/rails_helper.rb:369:in `block (3 levels) in <top (required)>'
          # /usr/local/bundle/gems/semantic_logger-4.16.1/lib/semantic_logger/base.rb:375:in `measure_internal'
          # /usr/local/bundle/gems/semantic_logger-4.16.1/lib/semantic_logger/base.rb:97:in `measure_debug'
          # ./spec/rails_helper.rb:368:in `block (2 levels) in <top (required)>'
          # /usr/local/bundle/gems/webmock-3.24.0/lib/webmock/rspec.rb:39:in `block (2 levels) in <main>'

Expected Behavior

The rails_semantic_logger should not throw an exception when logging requests from an integration test.

Actual Behavior

The above stack track is sometimes thrown - consistently for a request in an integration test.

Pull Request

See #251

---

So, I don't really know what this error is about, or why it is caused, but I'm fairly sure the error is due to the way the instrumenter is set up.

However, if I look at rails' own rack logger and make the rails_semantic_logger look more like the rails version:

       def call_app(request, env)
         instrumenter        = ActiveSupport::Notifications.instrumenter
-        instrumenter_state  = instrumenter.start 'request.action_dispatch', request: request
+        handle              = instrumenter.build_handle 'request.action_dispatch', request: request

         instrumenter_finish = lambda {
-          instrumenter.finish_with_state(instrumenter_state, 'request.action_dispatch', request: request)
+          handle.finish
         }
+        handle.start
         logger.send(self.class.started_request_log_level) { started_request_message(request) }
         status, headers, body = @app.call(env)
         body                  = ::Rack::BodyProxy.new(body, &instrumenter_finish)
         [status, headers, body]
       rescue Exception
         instrumenter_finish.call
         raise
       end

Then my test no longer fails.

I'll submit a PR but I really don't know what is going on here or why there is a difference, or even if this change is correct for other ruby versions....

[pcothenet]

We are experiencing the same issue while upgrading to 8.0. This started showing up in an integration test that was previously passing.

[pcothenet]

@reidmorrison do you have thoughts on this issue and the related PR?