logdna / logdna/ruby

Logs failing to flush in `Logdna::Client` due to concurrency issue in rails

Open
#46 0 comments 0 reactions 0 assignees View on GitHub
Dominant language
Ruby
Stars
19
Forks
18
PR merge metrics
No merged PRs in 30d

Description

Found that any uses of `Logdna::Client` within the boot sequence of rails results in subsequent logs never flushing.

For background, using logdna 1.5.0 w/ rails 6.1.7.5 on ruby 3.2.2. Configuring `Logdna::Ruby` following the instructions in [TAMING RUBY ON RAILS LOGGING WITH LOGRAGE AND MEZMO](https://www.mezmo.com/blog/taming-ruby-on-rails-logging-with-lograge-and-logdna) in `config/application.rb`. As long as `Rails.logger` isn't used within the subsequent application setup steps, then logging works as expected. But if any other subsequent step of the application setup process attempts to log, then all subsequent logs fail to be emitted.

Tracked this down to `Logdna::Client#schedule_flush`. By adding logging, I found that the associated `Concurrent::ScheduledTask` in `@scheduled_flush` remains in the `pending` state indefinitely. Further logging shows that the `ScheduledTask` is associated with a `Concurrent::CachedThreadPool` that contains a single thread and that thread has is marked as `dead`.

Guessing that as part of the rails boot up process, the default executor is terminated and therefore the `@scheduled_flush` never completes. Not that using the `@work_thread_pool` thread pool doesn't fix the issue; the same behavior is observed. By not logging anything during rails configurations/boot, a `ScheduledTask` isn't created while the application is still booting, and therefore this issue doesn't occur.

I think this issue could be addressed by tracking the time at which `@scheduled_flush` is created and then in subsequent invocations of `schedule_flush` checking if it has been pending far longer than expected. If it is sufficiently stale, then the outstanding `ScheduledTask` would be cancelled and a new one created. There may be more robust/elegant ways to address this because I'm not particularly familiar with ruby/rails thread management.

Contributor guide

Open the contributing guide

Research direction

Start at Logdna::Client#schedule_flush and inspect how @scheduled_flush and @work_thread_pool use Concurrent scheduled tasks during Rails boot. Reproduce with the Rails 6.1.7.5, Ruby 3.2.2 setup described, including a log call from config/application.rb; done means logs continue flushing after boot even when configuration logs occur.

Written by the indexing model from the issue text.

Assessment

Tech stack
rails, ruby
Domain
backend, observability-sre
Issue type
Bug
Difficulty
4/5
Estimated time
3-5 days
Activity status
Stale
Clarity
Mostly clear
Newbie friendliness
35/100

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.