Tests freeze with Ruby2.5

[utkarsh2102]

Hi,

Thanks for your work on serverengine! However, whilst building this against Ruby2.5, tests seems to be frozen. Here are the logs:

┌──────────────────────────────────────────────────────────────────────────────┐
│ Run tests for ruby2.5 from debian/ruby-tests.rake                            │
└──────────────────────────────────────────────────────────────────────────────┘

RUBYLIB=/<<PKGBUILDDIR>>/debian/ruby-serverengine/usr/lib/ruby/vendor_ruby:. GEM_PATH=/<<PKGBUILDDIR>>/debian/ruby-serverengine/usr/share/rubygems-integration/all:/var/lib/gems/2.5.0:/usr/lib/ruby/gems/2.5.0:/usr/share/rubygems-integration/2.5.0:/usr/share/rubygems-integration/all:/usr/lib/x86_64-linux-gnu/rubygems-integration/2.5.0 ruby2.5 -S rake -f debian/ruby-tests.rake
/usr/bin/ruby2.5 -I/usr/share/rubygems-integration/all/gems/rspec-support-3.9.2/lib:/usr/share/rubygems-integration/all/gems/rspec-core-3.9.1/lib /usr/share/rubygems-integration/all/gems/rspec-core-3.9.1/exe/rspec --pattern ./spec/\*\*/\*_spec.rb --format documentation
`/sbuild-nonexistent` is not a directory.
Bundler will use `/tmp/bundler20200221-101365-2kcu2s101365' as your home directory temporarily.
Resolving dependencies...

ServerEngine::BlockingFlag
  set and reset (FAILED - 1)
  set! and reset! return whether it toggled the state (FAILED - 2)
  wait_for_set timeout (FAILED - 3)
  wait_for_reset timeout (FAILED - 4)
  wait (FAILED - 5)

ServerEngine::DaemonLogger
  reopen (FAILED - 6)
  reset path (FAILED - 7)
  default level is debug (FAILED - 8)
  level set by int (FAILED - 9)
  level set by string (FAILED - 10)
  unknown level (FAILED - 11)
  rotation (FAILED - 12)
  IO logger (FAILED - 13)
  inter-process locking on rotation (FAILED - 14)

ServerEngine::Daemon
  run and graceful stop by signal (FAILED - 15)
  signals (FAILED - 16)
  run and graceful stop by pipe (FAILED - 17)
  recieve commands from pipe (FAILED - 18)
I, [2020-02-21T22:02:37.663785 #101365]  INFO -- : Received graceful stop
  exits with status 0 when it was stopped normally (FAILED - 19)
I, [2020-02-21T22:02:39.678877 #101365]  INFO -- : Worker 0 finished unexpectedly with status 5
  exits with status of workers if worker exits with status specified in unrecoverable_exit_codes, without supervisor (FAILED - 20)
I, [2020-02-21T22:02:41.704615 #101426]  INFO -- : Worker 0 finished unexpectedly with status 5
I, [2020-02-21T22:02:41.706802 #101426]  INFO -- : Server is exitting with code 5
I, [2020-02-21T22:02:42.191146 #101365]  INFO -- : Server finished unexpectedly with status 5
  exits with status of workers if worker exits with status specified in unrecoverable_exit_codes, with supervisor (FAILED - 21)

ServerEngine::MultiThreadServer
I, [2020-02-21T22:02:42.995102 #101365]  INFO -- : Received graceful stop
  scale up (FAILED - 22)
I, [2020-02-21T22:02:44.005669 #101365]  INFO -- : Received graceful stop
  scale down (FAILED - 23)

ServerEngine::MultiProcessServer
I, [2020-02-21T22:02:45.016693 #101365]  INFO -- : Received graceful stop
I, [2020-02-21T22:02:45.233402 #101365]  INFO -- : Worker 0 finished with status 0
I, [2020-02-21T22:02:45.234291 #101365]  INFO -- : Worker 1 finished with status 0
  scale up (FAILED - 24)
I, [2020-02-21T22:02:46.037171 #101365]  INFO -- : Received graceful stop
I, [2020-02-21T22:02:46.249161 #101365]  INFO -- : Worker 0 finished with status 0
I, [2020-02-21T22:02:46.249956 #101365]  INFO -- : Worker 1 finished with status 0
  scale down (FAILED - 25)

ServerEngine::MultiSpawnServer
  with command_sender=pipe
I, [2020-02-21T22:02:47.053373 #101365]  INFO -- : Received graceful stop
I, [2020-02-21T22:02:47.058652 #101365]  INFO -- : Worker 1 finished with status 0
I, [2020-02-21T22:02:47.563346 #101365]  INFO -- : Worker 0 finished with signal SIGTERM
    starts worker processes (FAILED - 26)

ServerEngine::SignalThread
  start and stop (FAILED - 27)
  call handler (FAILED - 28)
  SIG_IGN
  signal in handler (FAILED - 29)
  stop in handler
  should not deadlock (FAILED - 30)

ServerEngine::SocketManager
  is unix
  Server.generate_path
    returns socket path under /tmp (FAILED - 31)
    can be changed via environment variable (FAILED - 32)
  with thread
    using ipv4
{:here=>"rescue in server thread", :error=>#<Errno::EADDRINUSE: Address already in use - bind(2) for 127.0.0.1:9101>}
/usr/lib/ruby/2.5.0/socket.rb:201:in `bind'
/usr/lib/ruby/2.5.0/socket.rb:201:in `listen'
/<<PKGBUILDDIR>>/lib/serverengine/socket_manager_unix.rb:66:in `listen_tcp_new'
/<<PKGBUILDDIR>>/lib/serverengine/socket_manager.rb:121:in `block in listen'
/<<PKGBUILDDIR>>/lib/serverengine/socket_manager.rb:119:in `synchronize'
/<<PKGBUILDDIR>>/lib/serverengine/socket_manager.rb:119:in `listen'
/<<PKGBUILDDIR>>/lib/serverengine/socket_manager.rb:128:in `listen_tcp'
/<<PKGBUILDDIR>>/lib/serverengine/socket_manager_unix.rb:117:in `send_socket'
/<<PKGBUILDDIR>>/lib/serverengine/socket_manager.rb:155:in `process_peer'
#<Thread:0x000056204bb4f408@/<<PKGBUILDDIR>>/spec/socket_manager_spec.rb:46 run> terminated with exception (report_on_exception is true):
/<<PKGBUILDDIR>>/spec/socket_manager_spec.rb:74:in `ensure in block (5 levels) in <top (required)>': undefined method `close' for nil:NilClass (NoMethodError)
    from /<<PKGBUILDDIR>>/spec/socket_manager_spec.rb:75:in `block (5 levels) in <top (required)>'

Any idea what is causing this?

[henrich]

@utkarsh2102 It seems that only happens in debian testing/unstable, not debian stable with ruby2.5.5 and ruby2.5.7.

[repeatedly]

It seems that only happens in debian testing/unstable,

I think so too. I checked tests on travis and test passed without the problem: https://travis-ci.org/treasure-data/serverengine/jobs/654883273

[utkarsh2102]

Hi @henrich, @repeatedly, Thank you for taking a look. I've raised this here: https://bugs.debian.org/951806 Hopefully, someone would be able to figure out why is that happening!

[kenhys]

FYI: https://bugs.debian.org/951806 was fixed in version 2.2.1-1

[kenhys]

This issue was already fixed. I'll close it.