problem with unicorn graceful restart
TeamIguana opened this issue · 3 comments
Hello,
we have an application that runs with Unicorn/Sinatra/Ruby3.
We'd like to use rack-timeout to have visibility on what the app was doing when the timeout occured (with Unicorn timeout seems that is not possible).
So, in the config.ru file we added the line
use Rack::Timeout, service_timeout: 45
When we deploy the application, we send a USR2 signal to unicorn master process, in order to gracefully restart the application, but unicorn processes are not restarted and in the unicorn logs we found these lines:
I, [2022-10-07T16:38:22.206164 #99971] INFO -- : executing ["/home/user/.rvm/gems/ruby-3.0.2/bin/unicorn", "-D", "-c", "/home/user/project/unicorn.conf.rb", {8=>#<Kgio::UNIXServer:/tmp/unicorn.sock>, 12=>#<Unicorn::TCPSrv:fd 12, AF_INET, 0.0.0.0, 8080>}] (in /home/user/project)
I, [2022-10-07T16:38:22.206678 #99971] INFO -- : forked child re-executing...
I, [2022-10-07T16:38:24.302962 #99971] INFO -- : inherited addr=/tmp/unicorn.sock fd=8
I, [2022-10-07T16:38:24.303171 #99971] INFO -- : inherited addr=0.0.0.0:8080 fd=12
I, [2022-10-07T16:38:24.303571 #99971] INFO -- : Refreshing Gem list
E, [2022-10-07T16:38:24.607024 #86513] ERROR -- : reaped #<Process::Status: pid 99971 exit 1> exec()-ed
I, [2022-10-07T16:38:25.273111 #86516] INFO -- : source=rack-timeout id=a419d97f-5356-4476-938b-c53786e384c1 timeout=45000ms state=ready
I, [2022-10-07T16:38:25.280949 #86516] INFO -- : source=rack-timeout id=e0a7c39b-d1d4-4957-b698-70a033a8deb9 timeout=45000ms state=ready
...
I, [2022-10-07T16:38:25.645790 #86516] INFO -- : source=rack-timeout id=c3cba1c7-1d3f-4572-ab74-f2773b1ae94e timeout=45000ms state=ready
I, [2022-10-07T16:38:25.721126 #86516] INFO -- : source=rack-timeout id=8efaa8a1-17b0-4e3a-9ce0-a7aaa3da68fd timeout=45000ms state=ready
Insted, when we remove the line in the config.ru, everything works as expected, and in the unicorn logs we see these lines:
I, [2022-10-07T16:41:27.915059 #100577] INFO -- : executing ["/home/user/.rvm/gems/ruby-3.0.2/bin/unicorn", "-D", "-c", "/home/user/project/unicorn.conf.rb", {8=>#<Kgio::UNIXServer:/tmp/unicorn.sock>, 12=>#<Unicorn::TCPSrv:fd 12, AF_INET, 0.0.0.0, 8080>}] (in /home/user/project)
I, [2022-10-07T16:41:27.915554 #100577] INFO -- : forked child re-executing...
I, [2022-10-07T16:41:29.961820 #100577] INFO -- : inherited addr=/tmp/unicorn.sock fd=8
I, [2022-10-07T16:41:29.962024 #100577] INFO -- : inherited addr=0.0.0.0:8080 fd=12
I, [2022-10-07T16:41:29.962334 #100577] INFO -- : Refreshing Gem list
I, [2022-10-07T16:41:30.357727 #86513] INFO -- : reaped #<Process::Status: pid 86516 exit 0> worker=0
I, [2022-10-07T16:41:30.357984 #86513] INFO -- : reaped #<Process::Status: pid 86517 exit 0> worker=1
I, [2022-10-07T16:41:30.358075 #86513] INFO -- : reaped #<Process::Status: pid 86520 exit 0> worker=2
I, [2022-10-07T16:41:30.358161 #86513] INFO -- : reaped #<Process::Status: pid 86522 exit 0> worker=3
I, [2022-10-07T16:41:30.358232 #86513] INFO -- : master complete
I, [2022-10-07T16:41:31.277283 #100611] INFO -- : worker=0 spawned pid=100611
I, [2022-10-07T16:41:31.277680 #100611] INFO -- : worker=0 ready
I, [2022-10-07T16:41:32.280708 #100627] INFO -- : worker=1 spawned pid=100627
I, [2022-10-07T16:41:32.281081 #100627] INFO -- : worker=1 ready
I, [2022-10-07T16:41:33.284269 #100632] INFO -- : worker=2 spawned pid=100632
I, [2022-10-07T16:41:33.284676 #100632] INFO -- : worker=2 ready
I, [2022-10-07T16:41:34.286872 #100577] INFO -- : master process ready
I, [2022-10-07T16:41:34.288057 #100640] INFO -- : worker=3 spawned pid=100640
I, [2022-10-07T16:41:34.288428 #100640] INFO -- : worker=3 ready
What are we doing wrong?
Thanks in advance!
I'm afraid there's not information here to conclude what is happening / what to fix, and I'm also not familiar with unicorn enough to comment. Most likely it has something to do with how unicorn is managing its forks/children. It's possible that this has now been fixed by #212 but I'm not sure it's related or not.
Please try 0.7.0 and let us know if the behavior has [not] changed.
The problem doesn't seem to occur anymore with version 0.7. Thanks!