Logs failing to flush in `Logdna::Client` due to concurrency issue in rails
Nobody has claimed this yet.
Assessment
- Difficulty
- 4/5
- Estimated time
- 3-5 days
- Newbie friendliness
- 35/100
- Issue type
- Bug
- Clarity
- Mostly clear
- Activity status
- Stale
- Tech stack
- rails, ruby
- Domain
- backend, observability-sre
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.
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 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.
- Dominant language
- Ruby
- Stars
- 19
- Forks
- 18
- PR merge metrics
- No merged PRs in 30d
Contributor guide
First steps
- Read the whole issue, then the project's contributing guide.
- Comment on the issue to say you are picking it up — it saves two people doing the same work.
- Fork the repository and make your change on a branch.
- Open a pull request that references the issue number.
More from logdna/ruby
-
Difficulty 2/5 1-3 hours Newbie friendliness 52/100
-
Difficulty 2/5 1-3 hours Newbie friendliness 45/100
-
Difficulty 3/5 1-2 days Newbie friendliness 35/100
-
Difficulty 3/5 1-2 days Newbie friendliness 45/100
-
Difficulty 3/5 1-2 days Newbie friendliness 30/100
Similar issues
-
Difficulty 2/5 1-3 hours Newbie friendliness 75/100
TheOdinProject/curriculum#31417 · 2 comments ·
-
Difficulty 2/5 1-3 hours Newbie friendliness 70/100
-
Difficulty 2/5 1-3 hours Newbie friendliness 70/100
-
Difficulty 2/5 1-3 hours Newbie friendliness 65/100
glossarist/glossarist-ruby#238 ·
-
Difficulty 2/5 1-3 hours Newbie friendliness 75/100
palladius/rails8-app-on-gcp#145 ·