Create thread in shell finalizer

[akihikodaki]

The following call chain was observed:

1. Cmd.close_shell or Powershell.close_shell
2. HttpTransport#send_request
3. HTTPClient#post

And HTTPClient#post internally calls Mutex#synchronize, which raises ThreadError if called from a finalizer. Although the behavior is not documented, it makes sense as a finalizer can be called in a block passed to Mutex#synchronize, and calling Mutex#syncrhonize again for the same mutex in the finalizer can lead to deadlock.

Create a thread in the shell finalizer and do everything in the thread to avoid problems with Mutex#synchronize.

[nikhil2611]

This is also failing with the same error - can't alloc thread (ThreadError) coming from winrm-2.3.6/lib/winrm/shells/base.rb:188:in block in finalize

[akihikodaki]

This is also failing with the same error - can't alloc thread (ThreadError) coming from winrm-2.3.6/lib/winrm/shells/base.rb:188:in block in finalize

We can do nothing when the main thread is already dead. c.f., https://bugs.ruby-lang.org/issues/4992

[nikhil2611]

Is this specific with any ruby version. We started facing this after updating ruby to 3.1

[akihikodaki]

Is this specific with any ruby version. We started facing this after updating ruby to 3.1

No, but Ruby is free to change the timing to run finalizers so it's possible to see errors with an arbitrary condition. Updating Ruby may or may not break code that relies on the finalizer.

[nikhil2611]

Thanks . Hey , I just debug this further and found the the main thread is not in terminated stated, its in sleep state.

[akihikodaki]

Thanks . Hey , I just debug this further and found the the main thread is not in terminated stated, its in sleep state.

That's strange. In any case, there is nothing we can do on the WinRM side. You need to debug Ruby.

[pcai]

Is this still useful to merge?

[akihikodaki]

Is this still useful to merge?

Yes, the situation has not changed since I opened the pull request.

[pcai]

thanks

[pcai]

Just noting here that the test suite passes with this merged, but it's now spamming the logs (see below for a snippet)

It seems rspec doesn't like this change, although I don't know whether this indicates an actual issue or not. At the very least it requires further investigation to ensure that the tests are still valid -- possibly some expectations are now inadvertently running in a different thread, which may not assert correctly.

#<Thread:0x000055564267fe10 /home/runner/work/WinRM/WinRM/vendor/bundle/ruby/3.0.0/gems/logging-2.4.0/lib/logging/diagnostic_context.rb:471 run> terminated with exception (report_on_exception is true):
/home/runner/work/WinRM/WinRM/vendor/bundle/ruby/3.0.0/gems/rspec-mocks-3.13.1/lib/rspec/mocks/error_generator.rb:124:in `raise_expired_test_double_error': #<Double "transport"> was originally created in one example but has leaked into another example and can no longer be used. rspec-mocks' doubles are designed to only last for one example, and you need to create a new one in each example you wish to use it for. (RSpec::Mocks::ExpiredTestDoubleError)
    from /home/runner/work/WinRM/WinRM/vendor/bundle/ruby/3.0.0/gems/rspec-mocks-3.13.1/lib/rspec/mocks/test_double.rb:121:in `__raise_expired_error'
    from /home/runner/work/WinRM/WinRM/vendor/bundle/ruby/3.0.0/gems/rspec-mocks-3.13.1/lib/rspec/mocks/test_double.rb:57:in `__build_mock_proxy_unless_expired'
    from /home/runner/work/WinRM/WinRM/vendor/bundle/ruby/3.0.0/gems/rspec-mocks-3.13.1/lib/rspec/mocks/space.rb:154:in `proxy_not_found_for'
    from /home/runner/work/WinRM/WinRM/vendor/bundle/ruby/3.0.0/gems/rspec-mocks-3.13.1/lib/rspec/mocks/space.rb:114:in `block (2 levels) in proxy_for'
    from /home/runner/work/WinRM/WinRM/vendor/bundle/ruby/3.0.0/gems/rspec-mocks-3.13.1/lib/rspec/mocks/space.rb:114:in `fetch'
    from /home/runner/work/WinRM/WinRM/vendor/bundle/ruby/3.0.0/gems/rspec-mocks-3.13.1/lib/rspec/mocks/space.rb:114:in `block in proxy_for'
    from /home/runner/work/WinRM/WinRM/vendor/bundle/ruby/3.0.0/gems/rspec-support-3.13.1/lib/rspec/support/reentrant_mutex.rb:25:in `synchronize'
    from /home/runner/work/WinRM/WinRM/vendor/bundle/ruby/3.0.0/gems/rspec-mocks-3.13.1/lib/rspec/mocks/space.rb:112:in `proxy_for'
    from /home/runner/work/WinRM/WinRM/vendor/bundle/ruby/3.0.0/gems/rspec-mocks-3.13.1/lib/rspec/mocks/test_double.rb:112:in `__mock_proxy'
    from /home/runner/work/WinRM/WinRM/vendor/bundle/ruby/3.0.0/gems/rspec-mocks-3.13.1/lib/rspec/mocks/test_double.rb:75:in `method_missing'
    from /home/runner/work/WinRM/WinRM/vendor/bundle/ruby/3.0.0/gems/rspec-mocks-3.13.1/lib/rspec/mocks/proxy.rb:222:in `message_received'
    from /home/runner/work/WinRM/WinRM/vendor/bundle/ruby/3.0.0/gems/rspec-mocks-3.13.1/lib/rspec/mocks/method_double.rb:98:in `proxy_method_invoked'
    from /home/runner/work/WinRM/WinRM/vendor/bundle/ruby/3.0.0/gems/rspec-mocks-3.13.1/lib/rspec/mocks/method_double.rb:74:in `block (2 levels) in define_proxy_method'
    from /home/runner/work/WinRM/WinRM/lib/winrm/shells/cmd.rb:25:in `close_shell'
    from /home/runner/work/WinRM/WinRM/lib/winrm/shells/base.rb:98:in `block (2 levels) in finalize'
    from /home/runner/work/WinRM/WinRM/vendor/bundle/ruby/3.0.0/gems/logging-2.4.0/lib/logging/diagnostic_context.rb:474:in `block in create_with_logging_context'

[akihikodaki]

@pcai The logs imply shells are not closed. Shells created with mocks must be closed before tests finish.