HUP restart is delayed by 2 minutes

HUP restart is delayed by 2 minutes

[Thorsten von Eicken]

I'm having trouble getting the HUP restart to work properly (I do have
preload_app=false). What happens is that on HUP the master reloads the
config file, but it then always takes 2 minutes plus 1-2 seconds for the
workers to be reaped. The servers is totally idle, so this is not due to
some open connections. Here's how it looks in the log file with 2 worker
processes:

I, [2014-01-28T21:39:11.106135 #7936]  INFO -- : reloading
config_file=./config/rainbows.rb
I, [2014-01-28T21:39:11.111348 #7936]  INFO -- : done reloading
config_file=./config/rainbows.rb
D, [2014-01-28T21:39:11.112222 #7936] DEBUG -- : waiting 36.5s after
suspend/hibernation
E, [2014-01-28T21:41:14.786059 #7936] ERROR -- : reaped
#<Process::Status: pid 13908 exit 2> worker=0
I, [2014-01-28T21:41:14.786687 #7936]  INFO -- : worker=0 spawning...
E, [2014-01-28T21:41:14.787357 #7936] ERROR -- : reaped
#<Process::Status: pid 13910 exit 2> worker=1
I, [2014-01-28T21:41:14.787576 #7936]  INFO -- : worker=1 spawning...
I, [2014-01-28T21:41:14.789228 #13932]  INFO -- : worker=0 spawned pid=13932
I, [2014-01-28T21:41:14.789925 #13932]  INFO -- : Refreshing Gem list
I, [2014-01-28T21:41:14.794324 #13934]  INFO -- : worker=1 spawned pid=13934
I, [2014-01-28T21:41:14.794639 #13934]  INFO -- : Refreshing Gem list

(The suspend/hibernation message doesn't always appear.)
How can I troubleshoot this?
Thanks much!
_______________________________________________
Rainbows! mailing list - rainbows-talk-GrnCvJ7WPxnNLxjTenLetw@public.gmane.org
http://rubyforge.org/mailman/listinfo/rainbows-talk
Do not quote signatures (like this one) or top post when replying

Re: HUP restart is delayed by 2 minutes

[Eric Wong]

Thorsten von Eicken <tve-nkzjiHSqi6rZJqsBc5GL+g@public.gmane.org> wrote:
> I'm having trouble getting the HUP restart to work properly (I do have
> preload_app=false). What happens is that on HUP the master reloads the
> config file, but it then always takes 2 minutes plus 1-2 seconds for the
> workers to be reaped. The servers is totally idle, so this is not due to
> some open connections. Here's how it looks in the log file with 2 worker
> processes:

Which concurrency option are you using and which version of Rainbows!,
unicorn and Ruby is this?

> I, [2014-01-28T21:39:11.106135 #7936]  INFO -- : reloading
> config_file=./config/rainbows.rb
> I, [2014-01-28T21:39:11.111348 #7936]  INFO -- : done reloading
> config_file=./config/rainbows.rb
> D, [2014-01-28T21:39:11.112222 #7936] DEBUG -- : waiting 36.5s after
> suspend/hibernation
> E, [2014-01-28T21:41:14.786059 #7936] ERROR -- : reaped
> #<Process::Status: pid 13908 exit 2> worker=0

That definitely doesn't look right.  We need to know as much about
your configuration and versions as possible.
_______________________________________________
Rainbows! mailing list - rainbows-talk-GrnCvJ7WPxnNLxjTenLetw@public.gmane.org
http://rubyforge.org/mailman/listinfo/rainbows-talk
Do not quote signatures (like this one) or top post when replying

Re: HUP restart is delayed by 2 minutes

[Thorsten von Eicken]

On 1/28/2014 11:02 PM, Eric Wong wrote:
> Thorsten von Eicken <tve-nkzjiHSqi6rZJqsBc5GL+g@public.gmane.org> wrote:
>> I'm having trouble getting the HUP restart to work properly (I do have
>> preload_app=false). What happens is that on HUP the master reloads the
>> config file, but it then always takes 2 minutes plus 1-2 seconds for the
>> workers to be reaped. The servers is totally idle, so this is not due to
>> some open connections. Here's how it looks in the log file with 2 worker
>> processes:
> Which concurrency option are you using and which version of Rainbows!,
> unicorn and Ruby is this?
root@vscale:/home/vscale-admin/current# bundle show rainbows
/var/lib/gems/1.9.1/gems/rainbows-4.5.0
root@vscale:/home/vscale-admin/current# bundle show unicorn
/var/lib/gems/1.9.1/gems/unicorn-4.7.0
root@vscale:/home/vscale-admin/current# bundle exec ruby -v
ruby 1.9.3p0 (2011-10-30 revision 33570) [x86_64-linux]
root@vscale:/home/vscale-admin/current# bundle exec rainbows --version
Rainbows! v4.5.0

Rainbows! do
  use :EventMachine # concurrency model to use
  worker_connections 5
  keepalive_timeout 2 # zero disables keepalives entirely
  client_max_body_size 5*1024*1024 # 5 megabytes
  Rainbows.module_eval do
    EventMachine.kqueue = false if RUBY_PLATFORM =~ /darwin/i
  end
end

worker_processes 2 # make this configurable later
stderr_path LOG_FILE
stdout_path LOG_FILE
timeout 120
listen "127.0.0.1:8001", :tcp_nopush => true
preload_app false


>
>> I, [2014-01-28T21:39:11.106135 #7936]  INFO -- : reloading
>> config_file=./config/rainbows.rb
>> I, [2014-01-28T21:39:11.111348 #7936]  INFO -- : done reloading
>> config_file=./config/rainbows.rb
>> D, [2014-01-28T21:39:11.112222 #7936] DEBUG -- : waiting 36.5s after
>> suspend/hibernation
>> E, [2014-01-28T21:41:14.786059 #7936] ERROR -- : reaped
>> #<Process::Status: pid 13908 exit 2> worker=0
> That definitely doesn't look right.  We need to know as much about
> your configuration and versions as possible.
I'm happy to add some debug statements if you point me to an appropriate
place in the code.
Thanks!
_______________________________________________
Rainbows! mailing list - rainbows-talk-GrnCvJ7WPxnNLxjTenLetw@public.gmane.org
http://rubyforge.org/mailman/listinfo/rainbows-talk
Do not quote signatures (like this one) or top post when replying

Re: HUP restart is delayed by 2 minutes

[Eric Wong]

Thorsten von Eicken <tve-nkzjiHSqi6rZJqsBc5GL+g@public.gmane.org> wrote:
> I'm happy to add some debug statements if you point me to an appropriate
> place in the code.

Thanks!  I'll try to reproduce it in a bit.  Meanwhile, since you're
on Linux, try running strace on a worker while it happens.
_______________________________________________
Rainbows! mailing list - rainbows-talk-GrnCvJ7WPxnNLxjTenLetw@public.gmane.org
http://rubyforge.org/mailman/listinfo/rainbows-talk
Do not quote signatures (like this one) or top post when replying

Re: HUP restart is delayed by 2 minutes

[Eric Wong]

Thorsten von Eicken <tve-nkzjiHSqi6rZJqsBc5GL+g@public.gmane.org> wrote:
> On 1/28/2014 11:02 PM, Eric Wong wrote:
> > Thorsten von Eicken <tve-nkzjiHSqi6rZJqsBc5GL+g@public.gmane.org> wrote:
> >> I'm having trouble getting the HUP restart to work properly (I do have
> >> preload_app=false). What happens is that on HUP the master reloads the
> >> config file, but it then always takes 2 minutes plus 1-2 seconds for the
> >> workers to be reaped. The servers is totally idle, so this is not due to
> >> some open connections. Here's how it looks in the log file with 2 worker
> >> processes:
> > Which concurrency option are you using and which version of Rainbows!,
> > unicorn and Ruby is this?
> root@vscale:/home/vscale-admin/current# bundle show rainbows
> /var/lib/gems/1.9.1/gems/rainbows-4.5.0
> root@vscale:/home/vscale-admin/current# bundle show unicorn
> /var/lib/gems/1.9.1/gems/unicorn-4.7.0
> root@vscale:/home/vscale-admin/current# bundle exec ruby -v
> ruby 1.9.3p0 (2011-10-30 revision 33570) [x86_64-linux]
> root@vscale:/home/vscale-admin/current# bundle exec rainbows --version
> Rainbows! v4.5.0

This looks like a symptom of unicorn 4.8.0 interacting badly
with rainbows 4.5.0, not unicorn 4.7.0.  Can you give
rainbows 4.6.0 + unicorn 4.8.0 a try?  Unfortunately, I broke
rainbows 4.5.0 and earlier with unicorn 4.8.0 :x

I'll be pushing out unicorn 4.8.1 soon with a minor, unrelated bugfix.
_______________________________________________
Rainbows! mailing list - rainbows-talk-GrnCvJ7WPxnNLxjTenLetw@public.gmane.org
http://rubyforge.org/mailman/listinfo/rainbows-talk
Do not quote signatures (like this one) or top post when replying

Re: HUP restart is delayed by 2 minutes

[Thorsten von Eicken]

On 1/29/2014 12:31 AM, Eric Wong wrote:
> Thorsten von Eicken <tve-nkzjiHSqi6rZJqsBc5GL+g@public.gmane.org> wrote:
>> On 1/28/2014 11:02 PM, Eric Wong wrote:
>>> Thorsten von Eicken <tve-nkzjiHSqi6rZJqsBc5GL+g@public.gmane.org> wrote:
>>>> I'm having trouble getting the HUP restart to work properly (I do have
>>>> preload_app=false). What happens is that on HUP the master reloads the
>>>> config file, but it then always takes 2 minutes plus 1-2 seconds for the
>>>> workers to be reaped. The servers is totally idle, so this is not due to
>>>> some open connections. Here's how it looks in the log file with 2 worker
>>>> processes:
>>> Which concurrency option are you using and which version of Rainbows!,
>>> unicorn and Ruby is this?
>> root@vscale:/home/vscale-admin/current# bundle show rainbows
>> /var/lib/gems/1.9.1/gems/rainbows-4.5.0
>> root@vscale:/home/vscale-admin/current# bundle show unicorn
>> /var/lib/gems/1.9.1/gems/unicorn-4.7.0
>> root@vscale:/home/vscale-admin/current# bundle exec ruby -v
>> ruby 1.9.3p0 (2011-10-30 revision 33570) [x86_64-linux]
>> root@vscale:/home/vscale-admin/current# bundle exec rainbows --version
>> Rainbows! v4.5.0
> This looks like a symptom of unicorn 4.8.0 interacting badly
> with rainbows 4.5.0, not unicorn 4.7.0.  Can you give
> rainbows 4.6.0 + unicorn 4.8.0 a try?  Unfortunately, I broke
> rainbows 4.5.0 and earlier with unicorn 4.8.0 :x
>
> I'll be pushing out unicorn 4.8.1 soon with a minor, unrelated bugfix.
>
I am now running with Rainbows 4.6.0 and Unicorn 4.8.1 and still see the
same, but not always (the first restart only took 3-4 seconds to
happen). I'm printing the versions in the config file:
Rainbows version: 4.6.0
Unicorn version: 4.8.1
I, [2014-01-29T11:55:43.687022 #18919]  INFO -- : done reloading
config_file=./config/rainbows.rb

I did an strace of a worker process and not much is happening:
$ strace -p 19255
Process 19255 attached - interrupt to quit
ppoll([{fd=9, events=POLLIN|POLLPRI}], 1, {0, 805429204}, NULL, 8) = 0
(Timeout)
ppoll([{fd=9, events=POLLIN|POLLPRI}], 1, {0, 999995000}, NULL, 8) = 0
(Timeout)
ppoll([{fd=9, events=POLLIN|POLLPRI}], 1, {0, 999996000}, NULL, 8) = 0
(Timeout)
...
ppoll([{fd=9, events=POLLIN|POLLPRI}], 1, {0, 999997000}, NULL, 8) = 0
(Timeout)
ppoll([{fd=9, events=POLLIN|POLLPRI}], 1, {0, 999996000}, NULL, 8) = 0
(Timeout)
ppoll([{fd=9, events=POLLIN|POLLPRI}], 1, {0, 999997000}, NULL, 8) = 0
(Timeout)
exit_group(2)                           = ?
Process 19255 detached

Here's an strace of the master process (the workers at that time were
19781 and 19783). I marked the spot where everything just sits waiting
for 2 minutes and there clearly is a select call with a 2 minute timeout.

--- SIGVTALRM (Virtual timer expired) @ 0 (0) ---
rt_sigreturn(0x1a)                      = -1 EINTR (Interrupted system call)
futex(0x7f0ac29b67a0, FUTEX_WAIT_PRIVATE, 2, NULL) = 0
futex(0x7f0ac29b67a0, FUTEX_WAKE_PRIVATE, 1) = 0
rt_sigprocmask(SIG_SETMASK, ~[SEGV VTALRM RTMIN RT_1], NULL, 8) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
fcntl(6, F_GETFL)                       = 0x801 (flags O_WRONLY|O_NONBLOCK)
write(6, ".", 1)                        = 1
select(6, [5], NULL, NULL, {77, 985736}) = 1 (in [5], left {77, 985735})
fcntl(5, F_GETFL)                       = 0x800 (flags O_RDONLY|O_NONBLOCK)
read(5, ".", 11)                        = 1
wait4(-1, 0x7fff006feabc, WNOHANG, NULL) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2819, ...}) = 0
write(2, "I, [2014-01-29T12:03:19.875207 #"..., 93) = 93
open("./config/rainbows.rb", O_RDONLY)  = 8
fstat(8, {st_mode=S_IFREG|0644, st_size=1642, ...}) = 0
fstat(8, {st_mode=S_IFREG|0644, st_size=1642, ...}) = 0
ioctl(8, SNDCTL_TMR_TIMEBASE or TCGETS, 0x7fff006fe8c8) = -1 ENOTTY
(Inappropriate ioctl for device)
fstat(8, {st_mode=S_IFREG|0644, st_size=1642, ...}) = 0
lseek(8, 0, SEEK_CUR)                   = 0
read(8, "# See http://unicorn.bogomips.or"..., 1642) = 1642
read(8, "", 8192)                       = 0
close(8)                                = 0
getcwd("/home/vscale-admin/git", 200)   = 23
write(2, "./config/rainbows.rb:4: warning:"..., 71) = 71
write(1, "APP_PATH is /home/vscale-admin/c"..., 38) = 38
write(1, "\n", 1)                       = 1
write(2, "./config/rainbows.rb:8: warning:"..., 71) = 71
write(2, "./config/rainbows.rb:9: warning:"..., 71) = 71
stat("/home/vscale-admin/current/./config/rainbows.rb",
{st_mode=S_IFREG|0644, st_size=1642, ...}) = 0
geteuid()                               = 0
getegid()                               = 0
getuid()                                = 0
getgid()                                = 0
access("/home/vscale-admin/current/./config/rainbows.rb", R_OK) = 0
chdir("/home/vscale-admin/current")     = 0
write(1, "Rainbows version: 4.6.0", 23) = 23
write(1, "\n", 1)                       = 1
write(1, "Unicorn version: 4.8.1", 22)  = 22
write(1, "\n", 1)                       = 1
stat("./config.ru", {st_mode=S_IFREG|0644, st_size=633, ...}) = 0
geteuid()                               = 0
getegid()                               = 0
getuid()                                = 0
getgid()                                = 0
access("./config.ru", R_OK)             = 0
open("./config.ru", O_RDONLY)           = 8
fstat(8, {st_mode=S_IFREG|0644, st_size=633, ...}) = 0
fstat(8, {st_mode=S_IFREG|0644, st_size=633, ...}) = 0
ioctl(8, SNDCTL_TMR_TIMEBASE or TCGETS, 0x7fff006fe8c8) = -1 ENOTTY
(Inappropriate ioctl for device)
fstat(8, {st_mode=S_IFREG|0644, st_size=633, ...}) = 0
lseek(8, 0, SEEK_CUR)                   = 0
read(8, "require 'rack/mount'\nrequire Fil"..., 633) = 633
brk(0x24c6000)                          = 0x24c6000
read(8, "", 8192)                       = 0
brk(0x24c4000)                          = 0x24c4000
close(8)                                = 0
stat("/var/run/admin.pid", {st_mode=S_IFREG|0644, st_size=6, ...}) = 0
geteuid()                               = 0
getegid()                               = 0
getuid()                                = 0
getgid()                                = 0
access("/var/run/admin.pid", W_OK)      = 0
stat("/var/log/admin.log", {st_mode=S_IFREG|0644, st_size=606916, ...}) = 0
geteuid()                               = 0
getegid()                               = 0
getuid()                                = 0
getgid()                                = 0
access("/var/log/admin.log", W_OK)      = 0
stat("/var/log/admin.log", {st_mode=S_IFREG|0644, st_size=606916, ...}) = 0
geteuid()                               = 0
getegid()                               = 0
getuid()                                = 0
getgid()                                = 0
access("/var/log/admin.log", W_OK)      = 0
open("/var/run/admin.pid", O_RDONLY)    = 8
fstat(8, {st_mode=S_IFREG|0644, st_size=6, ...}) = 0
fstat(8, {st_mode=S_IFREG|0644, st_size=6, ...}) = 0
ioctl(8, SNDCTL_TMR_TIMEBASE or TCGETS, 0x7fff006fe3a8) = -1 ENOTTY
(Inappropriate ioctl for device)
fstat(8, {st_mode=S_IFREG|0644, st_size=6, ...}) = 0
lseek(8, 0, SEEK_CUR)                   = 0
read(8, "18919\n", 6)                   = 6
read(8, "", 8192)                       = 0
close(8)                                = 0
kill(18919, SIG_0)                      = 0
getsockname(7, {sa_family=AF_INET, sin_port=htons(8001),
sin_addr=inet_addr("127.0.0.1")}, [16]) = 0
getsockname(7, {sa_family=AF_INET, sin_port=htons(8001),
sin_addr=inet_addr("127.0.0.1")}, [16]) = 0
getsockname(7, {sa_family=AF_INET, sin_port=htons(8001),
sin_addr=inet_addr("127.0.0.1")}, [16]) = 0
getsockname(7, {sa_family=AF_INET, sin_port=htons(8001),
sin_addr=inet_addr("127.0.0.1")}, [16]) = 0
setsockopt(7, SOL_SOCKET, SO_KEEPALIVE, [1], 4) = 0
getsockname(7, {sa_family=AF_INET, sin_port=htons(8001),
sin_addr=inet_addr("127.0.0.1")}, [16]) = 0
setsockopt(7, SOL_TCP, TCP_NODELAY, [1], 4) = 0
getsockname(7, {sa_family=AF_INET, sin_port=htons(8001),
sin_addr=inet_addr("127.0.0.1")}, [16]) = 0
setsockopt(7, SOL_TCP, TCP_CORK, [1], 4) = 0
getsockname(7, {sa_family=AF_INET, sin_port=htons(8001),
sin_addr=inet_addr("127.0.0.1")}, [16]) = 0
setsockopt(7, SOL_TCP, TCP_DEFER_ACCEPT, [60], 4) = 0
listen(7, 1024)                         = 0
open("/var/log/admin.log", O_WRONLY|O_CREAT|O_APPEND, 0666) = 8
fstat(8, {st_mode=S_IFREG|0644, st_size=606916, ...}) = 0
fstat(8, {st_mode=S_IFREG|0644, st_size=606916, ...}) = 0
ioctl(8, SNDCTL_TMR_TIMEBASE or TCGETS, 0x7fff006fe388) = -1 ENOTTY
(Inappropriate ioctl for device)
dup2(8, 2)                              = 2
fstat(2, {st_mode=S_IFREG|0644, st_size=606916, ...}) = 0
close(8)                                = 0
open("/var/log/admin.log", O_WRONLY|O_CREAT|O_APPEND, 0666) = 8
fstat(8, {st_mode=S_IFREG|0644, st_size=606916, ...}) = 0
fstat(8, {st_mode=S_IFREG|0644, st_size=606916, ...}) = 0
ioctl(8, SNDCTL_TMR_TIMEBASE or TCGETS, 0x7fff006fe388) = -1 ENOTTY
(Inappropriate ioctl for device)
dup2(8, 1)                              = 1
fstat(1, {st_mode=S_IFREG|0644, st_size=606916, ...}) = 0
close(8)                                = 0
fcntl(9, F_GETFL)                       = 0x1 (flags O_WRONLY)
fcntl(9, F_SETFL, O_WRONLY|O_NONBLOCK)  = 0
write(9, "\3\0\0\0", 4)                 = 4
fcntl(10, F_GETFL)                      = 0x1 (flags O_WRONLY)
fcntl(10, F_SETFL, O_WRONLY|O_NONBLOCK) = 0
write(10, "\3\0\0\0", 4)                = 4
fstat(2, {st_mode=S_IFREG|0644, st_size=606916, ...}) = 0
fcntl(2, F_GETFL)                       = 0x8401 (flags
O_WRONLY|O_APPEND|O_LARGEFILE)
fstat(1, {st_mode=S_IFREG|0644, st_size=606916, ...}) = 0
fcntl(1, F_GETFL)                       = 0x8401 (flags
O_WRONLY|O_APPEND|O_LARGEFILE)
fstat(2, {st_mode=S_IFREG|0644, st_size=606916, ...}) = 0
stat("/var/log/admin.log", {st_mode=S_IFREG|0644, st_size=606916, ...}) = 0
fstat(1, {st_mode=S_IFREG|0644, st_size=606916, ...}) = 0
stat("/var/log/admin.log", {st_mode=S_IFREG|0644, st_size=606916, ...}) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2819, ...}) = 0
write(2, "I, [2014-01-29T12:03:19.887123 #"..., 98) = 98
wait4(-1, 0x7fff006feabc, WNOHANG, NULL) = 0
select(6, [5], NULL, NULL, {120, 0}
# ======================== LONG DELAY HERE
====================================
)    = 0 (Timeout)
wait4(-1, 0x7fff006feabc, WNOHANG, NULL) = 0
select(6, [5], NULL, NULL, {120, 0})    = ? ERESTARTNOHAND (To be restarted)
--- SIGCHLD (Child exited) @ 0 (0) ---
write(4, "!", 1)                        = 1
--- SIGVTALRM (Virtual timer expired) @ 0 (0) ---
rt_sigreturn(0x1a)                      = 1
rt_sigreturn(0x2)                       = -1 EINTR (Interrupted system call)
futex(0x1902708, FUTEX_WAIT_PRIVATE, 2, NULL) = 0
--- SIGVTALRM (Virtual timer expired) @ 0 (0) ---
rt_sigreturn(0x1a)                      = 0
futex(0x1902708, FUTEX_WAKE_PRIVATE, 1) = 0
rt_sigprocmask(SIG_SETMASK, ~[SEGV VTALRM RTMIN RT_1], NULL, 8) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
fcntl(6, F_GETFL)                       = 0x801 (flags O_WRONLY|O_NONBLOCK)
write(6, ".", 1)                        = 1
select(6, [5], NULL, NULL, {116, 267701}) = 1 (in [5], left {116, 267700})
fcntl(5, F_GETFL)                       = 0x800 (flags O_RDONLY|O_NONBLOCK)
read(5, ".", 11)                        = 1
wait4(-1, [{WIFEXITED(s) && WEXITSTATUS(s) == 2}], WNOHANG, NULL) = 19781
close(9)                                = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2819, ...}) = 0
write(2, "E, [2014-01-29T12:05:23.674893 #"..., 103) = 103
wait4(-1, 0x7fff006feabc, WNOHANG, NULL) = 0
getrlimit(RLIMIT_NOFILE, {rlim_cur=1024, rlim_max=4*1024}) = 0
pipe([8, 9])                            = 0
fstat(8, {st_mode=S_IFIFO|0600, st_size=0, ...}) = 0
fstat(9, {st_mode=S_IFIFO|0600, st_size=0, ...}) = 0
fcntl(8, F_GETFL)                       = 0 (flags O_RDONLY)
fstat(8, {st_mode=S_IFIFO|0600, st_size=0, ...}) = 0
ioctl(8, SNDCTL_TMR_TIMEBASE or TCGETS, 0x7fff006fe338) = -1 ENOTTY
(Inappropriate ioctl for device)
fcntl(9, F_GETFL)                       = 0x1 (flags O_WRONLY)
fstat(9, {st_mode=S_IFIFO|0600, st_size=0, ...}) = 0
ioctl(9, SNDCTL_TMR_TIMEBASE or TCGETS, 0x7fff006fe338) = -1 ENOTTY
(Inappropriate ioctl for device)
fcntl(8, F_SETFD, FD_CLOEXEC)           = 0
fcntl(9, F_SETFD, FD_CLOEXEC)           = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2819, ...}) = 0
write(2, "I, [2014-01-29T12:05:23.676466 #"..., 71) = 71
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
rt_sigaction(SIGPIPE, {0x7f0ac26607a0, [], SA_RESTORER|SA_SIGINFO,
0x7f0ac221b4a0}, {SIG_IGN, [], SA_RESTORER|SA_SIGINFO, 0x7f0ac221b4a0},
8) = 0
write(4, "!", 1)                        = 1
futex(0x7f0ac2bd89d0, FUTEX_WAIT, 19784, NULL) = ? ERESTARTSYS (To be
restarted)
--- SIGCHLD (Child exited) @ 0 (0) ---
write(4, "!", 1)                        = 1
rt_sigreturn(0x2)                       = -1 EINTR (Interrupted system call)
futex(0x7f0ac2bd89d0, FUTEX_WAIT, 19784, NULL) = 0
clone(child_stack=0,
flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD,
child_tidptr=0x7f0ac2bcf9d0) = 19798
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
clone(child_stack=0x7f0ac2bd7ff0,
flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM|CLONE_SETTLS|CLONE_PARENT_SETTID|CLONE_CHILD_CLEARTID,
parent_tidptr=0x7f0ac2bd89d0, tls=0x7f0ac2bd8700,
child_tidptr=0x7f0ac2bd89d0) = 19799
rt_sigprocmask(SIG_SETMASK, ~[SEGV VTALRM RTMIN RT_1], NULL, 8) = 0
rt_sigaction(SIGPIPE, {SIG_IGN, [], SA_RESTORER|SA_SIGINFO,
0x7f0ac221b4a0}, {0x7f0ac26607a0, [], SA_RESTORER|SA_SIGINFO,
0x7f0ac221b4a0}, 8) = 0
rt_sigprocmask(SIG_SETMASK, ~[SEGV VTALRM RTMIN RT_1], NULL, 8) = 0
close(8)                                = 0
select(6, [5], NULL, NULL, {120, 0})    = ? ERESTARTNOHAND (To be restarted)
--- SIGVTALRM (Virtual timer expired) @ 0 (0) ---
rt_sigreturn(0x1a)                      = -1 EINTR (Interrupted system call)
futex(0x1902708, FUTEX_WAIT_PRIVATE, 2, NULL) = 0
futex(0x1902708, FUTEX_WAKE_PRIVATE, 1) = 0
rt_sigprocmask(SIG_SETMASK, ~[SEGV VTALRM RTMIN RT_1], NULL, 8) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
fcntl(6, F_GETFL)                       = 0x801 (flags O_WRONLY|O_NONBLOCK)
write(6, ".", 1)                        = 1
select(6, [5], NULL, NULL, {119, 999369}) = 1 (in [5], left {119, 999368})
fcntl(5, F_GETFL)                       = 0x800 (flags O_RDONLY|O_NONBLOCK)
read(5, ".", 11)                        = 1
wait4(-1, [{WIFEXITED(s) && WEXITSTATUS(s) == 2}], WNOHANG, NULL) = 19783
close(10)                               = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2819, ...}) = 0
write(2, "E, [2014-01-29T12:05:23.681011 #"..., 103) = 103
wait4(-1, 0x7fff006feabc, WNOHANG, NULL) = 0
getrlimit(RLIMIT_NOFILE, {rlim_cur=1024, rlim_max=4*1024}) = 0
pipe([8, 10])                           = 0
fstat(8, {st_mode=S_IFIFO|0600, st_size=0, ...}) = 0
fstat(10, {st_mode=S_IFIFO|0600, st_size=0, ...}) = 0
fcntl(8, F_GETFL)                       = 0 (flags O_RDONLY)
fstat(8, {st_mode=S_IFIFO|0600, st_size=0, ...}) = 0
ioctl(8, SNDCTL_TMR_TIMEBASE or TCGETS, 0x7fff006fe338) = -1 ENOTTY
(Inappropriate ioctl for device)
fcntl(10, F_GETFL)                      = 0x1 (flags O_WRONLY)
fstat(10, {st_mode=S_IFIFO|0600, st_size=0, ...}) = 0
ioctl(10, SNDCTL_TMR_TIMEBASE or TCGETS, 0x7fff006fe338) = -1 ENOTTY
(Inappropriate ioctl for device)
fcntl(8, F_SETFD, FD_CLOEXEC)           = 0
fcntl(10, F_SETFD, FD_CLOEXEC)          = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2819, ...}) = 0
write(2, "I, [2014-01-29T12:05:23.682344 #"..., 71) = 71
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
rt_sigaction(SIGPIPE, {0x7f0ac26607a0, [], SA_RESTORER|SA_SIGINFO,
0x7f0ac221b4a0}, {SIG_IGN, [], SA_RESTORER|SA_SIGINFO, 0x7f0ac221b4a0},
8) = 0
write(4, "!", 1)                        = 1
futex(0x7f0ac2bd89d0, FUTEX_WAIT, 19799, NULL) = 0
clone(child_stack=0,
flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD,
child_tidptr=0x7f0ac2bcf9d0) = 19800
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
clone(child_stack=0x7f0ac2bd7ff0,
flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM|CLONE_SETTLS|CLONE_PARENT_SETTID|CLONE_CHILD_CLEARTID,
parent_tidptr=0x7f0ac2bd89d0, tls=0x7f0ac2bd8700,
child_tidptr=0x7f0ac2bd89d0) = 19801
rt_sigprocmask(SIG_SETMASK, ~[SEGV VTALRM RTMIN RT_1], NULL, 8) = 0
rt_sigaction(SIGPIPE, {SIG_IGN, [], SA_RESTORER|SA_SIGINFO,
0x7f0ac221b4a0}, {0x7f0ac26607a0, [], SA_RESTORER|SA_SIGINFO,
0x7f0ac221b4a0}, 8) = 0
rt_sigprocmask(SIG_SETMASK, ~[SEGV VTALRM RTMIN RT_1], NULL, 8) = 0
close(8)                                = 0
select(6, [5], NULL, NULL, {120, 0}
^C <unfinished ...>
Process 18919 detached

My config file is:
# See http://unicorn.bogomips.org/Unicorn/Configurator.html for complete
# documentation.

APP_PATH = File.expand_path(File.join(File.dirname(__FILE__),
'../../current'))
puts "APP_PATH is #{APP_PATH}"

if [ 'staging', 'production' ].include?(ENV['RACK_ENV'])
  PID_FILE = '/var/run/admin.pid'
  LOG_FILE = '/var/log/admin.log'
else
  PID_FILE = File.join(APP_PATH, 'rainbows.pid')
  LOG_FILE = APP_PATH + "/log/admin.log"
end

Rainbows! do
  use :EventMachine # concurrency model to use
  worker_connections 5
  keepalive_timeout 2 # zero disables keepalives entirely
  client_max_body_size 5*1024*1024 # 5 megabytes

  Rainbows.module_eval do
    EventMachine.kqueue = false if RUBY_PLATFORM =~ /darwin/i
  end

end

# Help ensure your application will always spawn in the symlinked
# "current" directory that Capistrano sets up.
working_directory APP_PATH

worker_processes 2 # make this configurable later

stderr_path LOG_FILE
stdout_path LOG_FILE

# Requests can take a looonng time
timeout 120

# we use a shorter backlog for quicker failover when busy
listen "127.0.0.1:8001", :tcp_nopush => true

# PID file location
pid PID_FILE

# Don't preload app: minimal savings and breaks HUP process control signal
preload_app false

GC.respond_to?(:copy_on_write_friendly=) and GC.copy_on_write_friendly =
true

puts "Rainbows version: #{Rainbows::Const::RAINBOWS_VERSION}"
puts "Unicorn version: #{Rainbows::Const::UNICORN_VERSION}"

_______________________________________________
Rainbows! mailing list - rainbows-talk-GrnCvJ7WPxnNLxjTenLetw@public.gmane.org
http://rubyforge.org/mailman/listinfo/rainbows-talk
Do not quote signatures (like this one) or top post when replying

Re: HUP restart is delayed by 2 minutes

[Eric Wong]

Thanks!  Can you try this?  Sorry I haven't maintained EM support
well, I forgot some versions were broken under Ruby 2.x :x

(also "gem install --pre  -v 4.6.0.4.g4108 rainbows" should work)

--- a/lib/rainbows/event_machine.rb
+++ b/lib/rainbows/event_machine.rb
@@ -88,7 +88,17 @@ module Rainbows::EventMachine
         raise RuntimeError, "EM @conns instance variable not accessible!"
       Rainbows::EventMachine::Server.const_set(:CUR, conns)
       Rainbows.at_quit do
-        EM.next_tick { conns.each_value { |c| client_class === c and c.quit } }
+        EM.next_tick do
+          LISTENERS.clear
+          conns.each_value do |c|
+            case c
+            when client_class
+              c.quit
+            when Rainbows::EventMachine::Server
+              c.detach
+            end
+          end
+        end
       end
       EM.add_periodic_timer(1) do
         EM.stop if ! Rainbows.tick && conns.empty? && EM.reactor_running?
_______________________________________________
Rainbows! mailing list - rainbows-talk-GrnCvJ7WPxnNLxjTenLetw@public.gmane.org
http://rubyforge.org/mailman/listinfo/rainbows-talk
Do not quote signatures (like this one) or top post when replying

Re: HUP restart is delayed by 2 minutes

[Thorsten von Eicken]

On 1/29/2014 2:03 PM, Eric Wong wrote:
> Thanks!  Can you try this?  Sorry I haven't maintained EM support
> well, I forgot some versions were broken under Ruby 2.x :x
>
> (also "gem install --pre  -v 4.6.0.4.g4108 rainbows" should work)
>
> --- a/lib/rainbows/event_machine.rb
> +++ b/lib/rainbows/event_machine.rb
> @@ -88,7 +88,17 @@ module Rainbows::EventMachine
>          raise RuntimeError, "EM @conns instance variable not accessible!"
>        Rainbows::EventMachine::Server.const_set(:CUR, conns)
>        Rainbows.at_quit do
> -        EM.next_tick { conns.each_value { |c| client_class === c and c.quit } }
> +        EM.next_tick do
> +          LISTENERS.clear
> +          conns.each_value do |c|
> +            case c
> +            when client_class
> +              c.quit
> +            when Rainbows::EventMachine::Server
> +              c.detach
> +            end
> +          end
> +        end
>        end
>        EM.add_periodic_timer(1) do
>          EM.stop if ! Rainbows.tick && conns.empty? && EM.reactor_running?
>
This indeed seems to fix it!
Thanks much!
_______________________________________________
Rainbows! mailing list - rainbows-talk-GrnCvJ7WPxnNLxjTenLetw@public.gmane.org
http://rubyforge.org/mailman/listinfo/rainbows-talk
Do not quote signatures (like this one) or top post when replying

Re: HUP restart is delayed by 2 minutes

[Thorsten von Eicken]

Thanks for the 4.6.1 update. I pulled it a few weeks ago, but I am still
having problems with the rainbows restart and EM. I pretty consistently
get a segfault:

/var/lib/gems/1.9.1/gems/eventmachine-1.0.3/lib/eventmachine.rb:187:
[BUG] Segmentation fault
ruby 1.9.3p0 (2011-10-30 revision 33570) [x86_64-linux]

-- Control frame information -----------------------------------------------
c:0014 p:---- s:0064 b:0064 l:000063 d:000063 CFUNC  :run_machine
c:0013 p:0325 s:0061 b:0061 l:000060 d:000060 METHOD
/var/lib/gems/1.9.1/gems/eventmachine-1.0.3/lib/eventmachine.rb:187
c:0012 p:0304 s:0054 b:0054 l:0008e8 d:0008e8 METHOD
/var/lib/gems/1.9.1/gems/rainbows-4.6.1/lib/rainbows/event_machine.rb:86
c:0011 p:0103 s:0047 b:0047 l:000046 d:000046 METHOD
/var/lib/gems/1.9.1/gems/rainbows-4.6.1/lib/rainbows/http_server.rb:45
c:0010 p:0146 s:0041 b:0041 l:000040 d:000040 METHOD
/var/lib/gems/1.9.1/gems/unicorn-4.8.2/lib/unicorn/http_server.rb:521
c:0009 p:0252 s:0034 b:0034 l:000033 d:000033 METHOD
/var/lib/gems/1.9.1/gems/rainbows-4.6.1/lib/rainbows/http_server.rb:61
c:0008 p:0058 s:0030 b:0030 l:000029 d:000029 METHOD
/var/lib/gems/1.9.1/gems/unicorn-4.8.2/lib/unicorn/http_server.rb:532
c:0007 p:0347 s:0026 b:0026 l:000025 d:000025 METHOD
/var/lib/gems/1.9.1/gems/unicorn-4.8.2/lib/unicorn/http_server.rb:290
c:0006 p:0264 s:0019 b:0019 l:001f28 d:001f28 TOP   
/var/lib/gems/1.9.1/gems/rainbows-4.6.1/bin/rainbows:127
c:0005 p:---- s:0013 b:0013 l:000012 d:000012 FINISH
c:0004 p:---- s:0011 b:0011 l:000010 d:000010 CFUNC  :load
c:0003 p:0127 s:0007 b:0007 l:000ae8 d:002080 EVAL  
/var/lib/gems/1.9.1/bin/rainbows:19
c:0002 p:---- s:0004 b:0004 l:000003 d:000003 FINISH
c:0001 p:0000 s:0002 b:0002 l:000ae8 d:000ae8 TOP

-- Ruby level backtrace information ----------------------------------------
/var/lib/gems/1.9.1/bin/rainbows:19:in `<main>'
/var/lib/gems/1.9.1/bin/rainbows:19:in `load'
/var/lib/gems/1.9.1/gems/rainbows-4.6.1/bin/rainbows:127:in `<top
(required)>'
/var/lib/gems/1.9.1/gems/unicorn-4.8.2/lib/unicorn/http_server.rb:290:in
`join'
/var/lib/gems/1.9.1/gems/unicorn-4.8.2/lib/unicorn/http_server.rb:532:in
`maintain_worker_count'
/var/lib/gems/1.9.1/gems/rainbows-4.6.1/lib/rainbows/http_server.rb:61:in `spawn_missing_workers'
/var/lib/gems/1.9.1/gems/unicorn-4.8.2/lib/unicorn/http_server.rb:521:in
`spawn_missing_workers'
/var/lib/gems/1.9.1/gems/rainbows-4.6.1/lib/rainbows/http_server.rb:45:in `worker_loop'
/var/lib/gems/1.9.1/gems/rainbows-4.6.1/lib/rainbows/event_machine.rb:86:in
`worker_loop'
/var/lib/gems/1.9.1/gems/eventmachine-1.0.3/lib/eventmachine.rb:187:in `run'
/var/lib/gems/1.9.1/gems/eventmachine-1.0.3/lib/eventmachine.rb:187:in
`run_machine'

-- C level backtrace information -------------------------------------------
/var/lib/gems/1.9.1/gems/eventmachine-1.0.3/lib/eventmachine.rb:187:
[BUG] Segmentation fault
ruby 1.9.3p0 (2011-10-30 revision 33570) [x86_64-linux]

I'm happy to provide additional information, if useful!

Cheers,
Thorsten

On 1/29/2014 2:03 PM, Eric Wong wrote:
> Thanks!  Can you try this?  Sorry I haven't maintained EM support
> well, I forgot some versions were broken under Ruby 2.x :x
>
> (also "gem install --pre  -v 4.6.0.4.g4108 rainbows" should work)
>
> --- a/lib/rainbows/event_machine.rb
> +++ b/lib/rainbows/event_machine.rb
> @@ -88,7 +88,17 @@ module Rainbows::EventMachine
>          raise RuntimeError, "EM @conns instance variable not accessible!"
>        Rainbows::EventMachine::Server.const_set(:CUR, conns)
>        Rainbows.at_quit do
> -        EM.next_tick { conns.each_value { |c| client_class === c and c.quit } }
> +        EM.next_tick do
> +          LISTENERS.clear
> +          conns.each_value do |c|
> +            case c
> +            when client_class
> +              c.quit
> +            when Rainbows::EventMachine::Server
> +              c.detach
> +            end
> +          end
> +        end
>        end
>        EM.add_periodic_timer(1) do
>          EM.stop if ! Rainbows.tick && conns.empty? && EM.reactor_running?
>

_______________________________________________
Rainbows! mailing list - rainbows-talk-GrnCvJ7WPxnNLxjTenLetw@public.gmane.org
http://rubyforge.org/mailman/listinfo/rainbows-talk
Do not quote signatures (like this one) or top post when replying

Re: HUP restart is delayed by 2 minutes

[Eric Wong]

Thorsten von Eicken <tve-nkzjiHSqi6rZJqsBc5GL+g@public.gmane.org> wrote:
> Thanks for the 4.6.1 update. I pulled it a few weeks ago, but I am still
> having problems with the rainbows restart and EM. I pretty consistently
> get a segfault:
> 
> /var/lib/gems/1.9.1/gems/eventmachine-1.0.3/lib/eventmachine.rb:187:
> [BUG] Segmentation fault
> ruby 1.9.3p0 (2011-10-30 revision 33570) [x86_64-linux]

Can you poke the EM folks about this?  However, keep in mind EM is
basically abandoned at this point:
https://groups.google.com/forum/#!topic/eventmachine/9g7oTzmYERo
_______________________________________________
Rainbows! mailing list - rainbows-talk-GrnCvJ7WPxnNLxjTenLetw@public.gmane.org
http://rubyforge.org/mailman/listinfo/rainbows-talk
Do not quote signatures (like this one) or top post when replying