Error logging session variable: undefined method `[]=' for nil:NilClass

[alextsui05]

Setup

• Rails 4.2.4
• act-fluent-logger-rails 0.4.0

I followed the setup in the README to replace the local logger:

# config/environments/development.rb
config.log_level = :info
config.logger = ActFluentLoggerRails::Logger.
  new(log_tags: {
        ip: :ip,
        ua: :user_agent,
        uid: ->(request) { request.session[:uid] }
      })

Expected

I expect to be able to see uid field set in the fluentd log with the contents of the session variable uid.

Actual

I get an error message before the page loads:

12:26:11 web.1           | NoMethodError - undefined method `[]=' for nil:NilClass:
12:26:11 web.1           |   actionpack (4.2.4) lib/action_dispatch/request/session.rb:181:in `load!'
12:26:11 web.1           |   actionpack (4.2.4) lib/action_dispatch/request/session.rb:176:in `load_for_write!'
12:26:11 web.1           |   actionpack (4.2.4) lib/action_dispatch/request/session.rb:165:in `merge!'
12:26:11 web.1           |   actionpack (4.2.4) lib/action_dispatch/request/session.rb:16:in `create'
12:26:11 web.1           |   actionpack (4.2.4) lib/action_dispatch/middleware/session/abstract_store.rb:69:in `prepare_session'
12:26:11 web.1           |   rack (1.6.4) lib/rack/session/abstract/id.rb:224:in `context'
12:26:11 web.1           |   rack (1.6.4) lib/rack/session/abstract/id.rb:220:in `call'

...

12:26:11 web.1           |   railties (4.2.4) lib/rails/rack/logger.rb:20:in `block in call'
12:26:11 web.1           |   /home/atsui/work/act-fluent-logger-rails/lib/act-fluent-logger-rails/logger.rb:68:in `tagged'
12:26:11 web.1           |   railties (4.2.4) lib/rails/rack/logger.rb:20:in `call'

Debugging

I use act-fluent-logger-rails 0.1.7 in production with no problem.

I used git bisect to find the commit that introduced this error to be: 286f5ee

I think the problem is that after this commit, log_tags get evaluated too early. Here is part of the output of my bundle exec rake middleware:

use Rails::Rack::Logger
use ActionDispatch::ShowExceptions
use ActionDispatch::DebugExceptions
use BetterErrors::Middleware
use Bugsnag::Rack
use ActionDispatch::RemoteIp
use ActionDispatch::Reloader
use ActionDispatch::Callbacks
use ActiveRecord::Migration::CheckPending
use ActiveRecord::ConnectionAdapters::ConnectionManagement
use ActiveRecord::QueryCache
use ActionDispatch::Cookies
use ActionDispatch::Session::CookieStore

I think log_tags get evaluated at the Rails::Rack::Logger level, but this is before the session is loaded (in the CookieStore level). If I comment out the request.session[:uid] from log_tags, then there is no error.

I think before 286f5ee, (1) the logger saves the request object, and (2) log_tags get evaluated when the logger calls flush. This way, it evaluates it later after the session is loaded.

How can we resolve this error?

[ryosuke-endo]

@alextsui05

Hi

If you put rails 4.2.x ver 0.4.0, you will encounter the bug.
I am sorry, please use ver.0.1.7 as it is once.

Investigate the bug and fix it.

Thank you very much!

[miguelperez]

Hi, I am having the same issue with rails 5.
How could we fix this issue @ryosuke-endo ?

[ryosuke-endo]

@miguelperez

Thanks!

Hi, I am having the same issue with rails 5.

Which version occurred in Rails 5?

How could we fix this issue

If you support Rails 4.2, change the action in railtie version in the method.

[c0ze]

still encountering this issue

[bhanuone]

and still encountering this in 2020.

[fabirydel]

and still in 2021

[jibranusman95]

and still in 2023

[sampokuokkanen]

Hi! New maintainer here.
Just saying that I'm looking into this.

I think we need to add a middleware to this gem for now to ensure we have the request object available.
Then, in a major version upgrade, I'd like to get rid of the Thread.current stuff plus the middleware we are adding and start using config.log_tags.