Calling 'reopen' and Adding an Appender Creates 2 Logging Threads

[eviljoel]

Environment

Provide at least:

• Ruby Version: 2.7.6
• Semantic Logger Version: 4.12.0
• Application/framework names and versions: N/A
• Rails Semantic Logger Version: N/A
• Rails configuration: N/A
• Full Stack Trace: N/A

Expected Behavior

• Semantic Logger should never create more than one logging thread.

Actual Behavior

• Under some conditions, 2 logging threads are created.
• Standalone Ruby script:

def running_thread_count
  Thread.list.select { |thread| ['sleep', 'run', 'aborting'].include?(thread.status) }.count
end

require 'semantic_logger'
SemanticLogger.add_appender(file_name: '/dev/null')
puts("Expecting a thread count of 2: #{running_thread_count}")
SemanticLogger.reopen
SemanticLogger.add_appender(file_name: '/dev/null')
puts("Expecting a thread count of 3 (correct behavior is 2): #{running_thread_count}")

I can only seem to get this script to work on Ubuntu 20.04. You might have to run this script several times. Most of the time, two logging threads will be created. (Three threads total.)

This occurs because, this line can execute before this line.

We came across this situation by unit testing forking code outside of an actual fork. The two logging threads created a confusing situation for us where log events were seemingly ending up in CaptureLogEvents's events array in seemingly random order.

Pull Request

• My existing PR fixes this issue: Lost Threads and Hanging Due to Lack of Mutexes #240

[chriscz]

Interesting, we have been trying to complete a migration to semantic_logger part-time for nearly a month now, but we have been seeing segfaults on the CI and locally, I wonder if this might the reason.

[reidmorrison]

See the test frameworks for examples on how to test for specific metrics and other attributes. Removing and adding back appenders between every test is not recommended.