Broken third party plugins can break logging?

Contribute Bug

AI-generated summary

A discussion about an error in the Discourse logging system, specifically with the lograge plugin. pfaffman reported an error where the lograge plugin failed to append a custom payload, causing issues with logging. codinghorror asked if the error occurred with all third-party plugins disabled, and pfaffman replied that the “Who’s online” plugin was enabled at the time of the error. pfaffman expressed concern that if third-party plugins can break logging, it may be a significant issue with the lograge plugin. However, tgxworld identified the issue as a bug in the lograge configuration and has since fixed it in a GitHub commit.

1

I can’t tell if this lograge error is a symptom or a cause of some other problems like this, and this, or it’s a coincidence.

Failed to append custom payload: undefined method `current_user' for #<WebhooksController:0x00007f0aafebe248> /var/www/discourse/config/initializers/101-lograge.rb:22:in `block (2 levels) in <top (req

/var/www/discourse/vendor/bundle/ruby/2.5.0/gems/logster-1.2.9/lib/logster/logger.rb:93:in `add_with_opts'
/var/www/discourse/vendor/bundle/ruby/2.5.0/gems/logster-1.2.9/lib/logster/logger.rb:50:in `add'
/usr/local/lib/ruby/2.5.0/logger.rb:536:in `warn'
/var/www/discourse/config/initializers/101-lograge.rb:39:in `rescue in block (2 levels) in <top (required)>'
/var/www/discourse/config/initializers/101-lograge.rb:19:in `block (2 levels) in <top (required)>'
/var/www/discourse/vendor/bundle/ruby/2.5.0/gems/lograge-0.10.0/lib/lograge.rb:165:in `block in extend_base_controller_class'
/var/www/discourse/vendor/bundle/ruby/2.5.0/gems/actionpack-5.2.0/lib/action_controller/metal/instrumentation.rb:38:in `block in process_action'
/var/www/discourse/vendor/bundle/ruby/2.5.0/gems/activesupport-5.2.0/lib/active_support/notifications.rb:168:in `block in instrument'
/var/www/discourse/vendor/bundle/ruby/2.5.0/gems/activesupport-5.2.0/lib/active_support/notifications/instrumenter.rb:23:in `instrument'
/var/www/discourse/vendor/bundle/ruby/2.5.0/gems/activesupport-5.2.0/lib/active_support/notifications.rb:168:in `instrument'
/var/www/discourse/vendor/bundle/ruby/2.5.0/gems/actionpack-5.2.0/lib/action_controller/metal/instrumentation.rb:32:in `process_action'
/var/www/discourse/vendor/bundle/ruby/2.5.0/gems/actionpack-5.2.0/lib/action_controller/metal/params_wrapper.rb:256:in `process_action'
/var/www/discourse/vendor/bundle/ruby/2.5.0/gems/activerecord-5.2.0/lib/active_record/railties/controller_runtime.rb:24:in `process_action'
/var/www/discourse/vendor/bundle/ruby/2.5.0/gems/actionpack-5.2.0/lib/abstract_controller/base.rb:134:in `process'
/var/www/discourse/vendor/bundle/ruby/2.5.0/gems/actionview-5.2.0/lib/action_view/rendering.rb:32:in `process'
/var/www/discourse/vendor/bundle/ruby/2.5.0/gems/rack-mini-profiler-1.0.0/lib/mini_profiler/profiling_methods.rb:78:in `block in profile_method'
/var/www/discourse/vendor/bundle/ruby/2.5.0/gems/actionpack-5.2.0/lib/action_controller/metal.rb:191:in `dispatch'
/var/www/discourse/vendor/bundle/ruby/2.5.0/gems/actionpack-5.2.0/lib/action_controller/metal.rb:252:in `dispatch'
/var/www/discourse/vendor/bundle/ruby/2.5.0/gems/actionpack-5.2.0/lib/action_dispatch/routing/route_set.rb:52:in `dispatch'
/var/www/discourse/vendor/bundle/ruby/2.5.0/gems/actionpack-5.2.0/lib/action_dispatch/routing/route_set.rb:34:in `serve'
/var/www/discourse/vendor/bundle/ruby/2.5.0/gems/actionpack-5.2.0/lib/action_dispatch/journey/router.rb:52:in `block in serve'
/var/www/discourse/vendor/bundle/ruby/2.5.0/gems/actionpack-5.2.0/lib/action_dispatch/journey/router.rb:35:in `each'
/var/www/discourse/vendor/bundle/ruby/2.5.0/gems/actionpack-5.2.0/lib/action_dispatch/journey/router.rb:35:in `serve'
/var/www/discourse/vendor/bundle/ruby/2.5.0/gems/actionpack-5.2.0/lib/action_dispatch/routing/route_set.rb:840:in `call'
/var/www/discourse/vendor/bundle/ruby/2.5.0/gems/rack-protection-2.0.3/lib/rack/protection/frame_options.rb:31:in `call'
/var/www/discourse/lib/middleware/omniauth_bypass_middleware.rb:24:in `call'
/var/www/discourse/vendor/bundle/ruby/2.5.0/gems/rack-2.0.5/lib/rack/tempfile_reaper.rb:15:in `call'
/var/www/discourse/vendor/bundle/ruby/2.5.0/gems/rack-2.0.5/lib/rack/conditional_get.rb:38:in `call'
/var/www/discourse/vendor/bundle/ruby/2.5.0/gems/rack-2.0.5/lib/rack/head.rb:12:in `call'
/var/www/discourse/vendor/bundle/ruby/2.5.0/gems/actionpack-5.2.0/lib/action_dispatch/http/content_security_policy.rb:18:in `call'
/var/www/discourse/lib/middleware/anonymous_cache.rb:214:in `call'
/var/www/discourse/vendor/bundle/ruby/2.5.0/gems/rack-2.0.5/lib/rack/session/abstract/id.rb:232:in `context'
/var/www/discourse/vendor/bundle/ruby/2.5.0/gems/rack-2.0.5/lib/rack/session/abstract/id.rb:226:in `call'
/var/www/discourse/vendor/bundle/ruby/2.5.0/gems/actionpack-5.2.0/lib/action_dispatch/middleware/cookies.rb:670:in `call'
/var/www/discourse/vendor/bundle/ruby/2.5.0/gems/actionpack-5.2.0/lib/action_dispatch/middleware/callbacks.rb:28:in `block in call'
/var/www/discourse/vendor/bundle/ruby/2.5.0/gems/activesupport-5.2.0/lib/active_support/callbacks.rb:98:in `run_callbacks'
/var/www/discourse/vendor/bundle/ruby/2.5.0/gems/actionpack-5.2.0/lib/action_dispatch/middleware/callbacks.rb:26:in `call'
/var/www/discourse/vendor/bundle/ruby/2.5.0/gems/actionpack-5.2.0/lib/action_dispatch/middleware/debug_exceptions.rb:61:in `call'
/var/www/discourse/vendor/bundle/ruby/2.5.0/gems/actionpack-5.2.0/lib/action_dispatch/middleware/show_exceptions.rb:33:in `call'
/var/www/discourse/vendor/bundle/ruby/2.5.0/gems/logster-1.2.9/lib/logster/middleware/reporter.rb:31:in `call'
/var/www/discourse/vendor/bundle/ruby/2.5.0/gems/lograge-0.10.0/lib/lograge/rails_ext/rack/logger.rb:15:in `call_app'
/var/www/discourse/vendor/bundle/ruby/2.5.0/gems/railties-5.2.0/lib/rails/rack/logger.rb:28:in `call'
/var/www/discourse/config/initializers/100-quiet_logger.rb:16:in `call'
/var/www/discourse/config/initializers/100-silence_logger.rb:29:in `call'
/var/www/discourse/vendor/bundle/ruby/2.5.0/gems/actionpack-5.2.0/lib/action_dispatch/middleware/remote_ip.rb:81:in `call'
/var/www/discourse/vendor/bundle/ruby/2.5.0/gems/actionpack-5.2.0/lib/action_dispatch/middleware/request_id.rb:27:in `call'
/var/www/discourse/vendor/bundle/ruby/2.5.0/gems/rack-2.0.5/lib/rack/method_override.rb:22:in `call'
/var/www/discourse/vendor/bundle/ruby/2.5.0/gems/actionpack-5.2.0/lib/action_dispatch/middleware/executor.rb:14:in `call'
/var/www/discourse/vendor/bundle/ruby/2.5.0/gems/rack-2.0.5/lib/rack/sendfile.rb:111:in `call'
/var/www/discourse/plugins/discourse-prometheus/lib/middleware/metrics.rb:17:in `call'
/var/www/discourse/vendor/bundle/ruby/2.5.0/gems/rack-mini-profiler-1.0.0/lib/mini_profiler/profiler.rb:174:in `call'
/var/www/discourse/vendor/bundle/ruby/2.5.0/gems/message_bus-2.1.5/lib/message_bus/rack/middleware.rb:63:in `call'
/var/www/discourse/lib/middleware/request_tracker.rb:180:in `call'
/var/www/discourse/vendor/bundle/ruby/2.5.0/gems/railties-5.2.0/lib/rails/engine.rb:524:in `call'
/var/www/discourse/vendor/bundle/ruby/2.5.0/gems/railties-5.2.0/lib/rails/railtie.rb:190:in `public_send'
/var/www/discourse/vendor/bundle/ruby/2.5.0/gems/railties-5.2.0/lib/rails/railtie.rb:190:in `method_missing'
/var/www/discourse/vendor/bundle/ruby/2.5.0/gems/rack-2.0.5/lib/rack/urlmap.rb:68:in `block in call'
/var/www/discourse/vendor/bundle/ruby/2.5.0/gems/rack-2.0.5/lib/rack/urlmap.rb:53:in `each'
/var/www/discourse/vendor/bundle/ruby/2.5.0/gems/rack-2.0.5/lib/rack/urlmap.rb:53:in `call'
/var/www/discourse/vendor/bundle/ruby/2.5.0/gems/unicorn-5.4.0/lib/unicorn/http_server.rb:606:in `process_client'
/var/www/discourse/vendor/bundle/ruby/2.5.0/gems/unicorn-5.4.0/lib/unicorn/http_server.rb:701:in `worker_loop'
/var/www/discourse/vendor/bundle/ruby/2.5.0/gems/unicorn-5.4.0/lib/unicorn/http_server.rb:549:in `spawn_missing_workers'
/var/www/discourse/vendor/bundle/ruby/2.5.0/gems/unicorn-5.4.0/lib/unicorn/http_server.rb:142:in `start'
/var/www/discourse/vendor/bundle/ruby/2.5.0/gems/unicorn-5.4.0/bin/unicorn:126:in `<top (required)>'
/var/www/discourse/vendor/bundle/ruby/2.5.0/bin/unicorn:23:in `load'
/var/www/discourse/vendor/bundle/ruby/2.5.0/bin/unicorn:23:in `<main>'
1 Like
2

This is with all third party plugins disabled?

3

EDIT: Who’s online was enabled. I don’t know what made it happen, so I don’t know how to see if the problem is gone now.

BUT

If 3rd party plugins can break logging, then I’m less excited about lograge. If an errant plugin can make it so that errors aren’t logged then. . . that seems worse than unreadable logs.

2 Likes
5

This is a bug in our lograge configuration and I’ve fixed it in

https://github.com/discourse/discourse/commit/6d588e43cc5f7d5107668253323b0b0ca153169b

Thank you for reporting @pfaffman

5 Likes