Systemd socket inheritance fails with “not a socket file descriptor”

Systemd socket inheritance fails with “not a socket file descriptor”

[Amir Yalon]

Hi,
 
I have yet to compile a minimal failing configuration, but posting here
in case it’s a common problem.
 
Starting the systemd service with a configuration based on
http://bogomips.org/unicorn-public/20150708130821.GA1361@luke.ws.skroutz.gr/
(also found under examples/ in the source code), it fails, and the
following is seen in the systemd journal:
 
> app/vendor/bundle/ruby/2.0.0/gems/unicorn-5.0.1/lib/unicorn/http_server.rb:780:in `for_fd': not a socket file descriptor (ArgumentError)
> from app/vendor/bundle/ruby/2.0.0/gems/unicorn-5.0.1/lib/unicorn/http_server.rb:780:in `block in inherit_listeners!'
> from app/vendor/bundle/ruby/2.0.0/gems/unicorn-5.0.1/lib/unicorn/http_server.rb:779:in `map!'
> from app/vendor/bundle/ruby/2.0.0/gems/unicorn-5.0.1/lib/unicorn/http_server.rb:779:in `inherit_listeners!'
> from app/vendor/bundle/ruby/2.0.0/gems/unicorn-5.0.1/lib/unicorn/http_server.rb:111:in `start'
> from app/vendor/bundle/ruby/2.0.0/gems/unicorn-5.0.1/bin/unicorn:126:in `<top (required)>'
> from app/vendor/bundle/ruby/2.0.0/bin/unicorn:23:in `load'
> from app/vendor/bundle/ruby/2.0.0/bin/unicorn:23:in `<main>'
 
The error, in `for_fd': not a socket file descriptor (ArgumentError),
occurs when attempting `io = Socket.for_fd(fd.to_i)`.
 
Using Ruby version 2.0.0p645.  Should I try using 2.2 or later?
 
Thanks,
Amir

Re: Systemd socket inheritance fails with “not a socket file descriptor”

[Eric Wong]

Amir Yalon <amiryal@yxejamir.net> wrote:
> Starting the systemd service with a configuration based on
> http://bogomips.org/unicorn-public/20150708130821.GA1361@luke.ws.skroutz.gr/
> (also found under examples/ in the source code), it fails, and the
> following is seen in the systemd journal:
>  
> > app/vendor/bundle/ruby/2.0.0/gems/unicorn-5.0.1/lib/unicorn/http_server.rb:780:in `for_fd': not a socket file descriptor (ArgumentError)

<snip>
 
> The error, in `for_fd': not a socket file descriptor (ArgumentError),
> occurs when attempting `io = Socket.for_fd(fd.to_i)`.

Curious, that means it's failing at the S_ISSOCK at line 53:

http://bogomips.org/mirrors/ruby.git/tree/ext/socket/init.c?h=v2_0_0_645#n53

fstat() says it's a valid FD, but not a socket.  Maybe IO.for_fd
can enlighten us as to what you're getting if it's not a socket.

Can you try the following change to http_server.rb to dump out
the stat info of the FD that's failing?

It'll still fail at Socket.for_fd, but IO.for_fd should not fail
since fstat() already succeeded.

--- a/lib/unicorn/http_server.rb
+++ b/lib/unicorn/http_server.rb
@@ -777,6 +777,9 @@ def inherit_listeners!
     # to ease debugging, we will not unset LISTEN_PID and LISTEN_FDS
 
     inherited.map! do |fd|
+      io = IO.for_fd(fd.to_i)
+      io.autoclose = false
+      $stderr.write("fd=#{fd.inspect} #{io.stat.inspect}\n")
       io = Socket.for_fd(fd.to_i)
       io.autoclose = false
       io = server_cast(io)

Also, can you verify the UNICORN_FD env is NOT set by systemd?
(It should not be)

Thanks.

> Using Ruby version 2.0.0p645.  Should I try using 2.2 or later?

If it's easy, sure; but I just tried with 2.0.0-p645 without
problems; so I would try making the change above and verifying
UNICORN_FD is not set when systemd is being used, first.

Ruby itself could not emulate systemd behavior for testing until
2.3.0, but the actual functionality of unicorn w/ systemd should
not be diminished with a real systemd with older Rubies.


Also, for reference, which version of systemd is this?

I checked the latest systemd.git but didn't notice any changes
which would break the expectations of our sd_listen_fds(3)
function emulation:

	git clone https://github.com/systemd/systemd.git
	cd systemd && git log -p src/libsystemd/sd-daemon/

But maybe I missed something...
Fwiw, I tested on Debian jessie w/ systemd 215-17+deb8u3

Re: Systemd socket inheritance fails with “not a socket file descriptor”

[Amir Yalon]

Interesting.  With the testing patch applied, we’re now failing this
test in thread_pthread.c:
http://bogomips.org/mirrors/ruby.git/tree/thread_pthread.c#n1720
Which then raises the following exception in io.c:
http://bogomips.org/mirrors/ruby.git/tree/io.c#n7621
 
From the journal:
app/vendor/bundle/ruby/2.0.0/gems/unicorn-5.0.1/lib/unicorn/http_server.rb:780:in
`for_fd': The given fd is not accessible because RubyVM reserves it
(ArgumentError)
from
/home/deploy/src/git/sapi/vendor/bundle/ruby/2.0.0/gems/unicorn-5.0.1/lib/unicorn/http_server.rb:780:in
`block in inherit_listeners!'
from
app/vendor/bundle/ruby/2.0.0/gems/unicorn-5.0.1/lib/unicorn/http_server.rb:779:in
`map!'
from
app/vendor/bundle/ruby/2.0.0/gems/unicorn-5.0.1/lib/unicorn/http_server.rb:779:in
`inherit_listeners!'
from
app/vendor/bundle/ruby/2.0.0/gems/unicorn-5.0.1/lib/unicorn/http_server.rb:111:in
`start'
 
> Also, can you verify the UNICORN_FD env is NOT set by systemd?
> (It should not be)
Verified, not set.
 
> Also, for reference, which version of systemd is this?
Ubuntu Wily 15.10, systemd 225-1ubuntu9
 
Thanks,
Amir

Re: Systemd socket inheritance fails with “not a socket file descriptor”

[Eric Wong]

Amir Yalon <amiryal@yxejamir.net> wrote:
> Interesting.  With the testing patch applied, we’re now failing this
> test in thread_pthread.c:
> http://bogomips.org/mirrors/ruby.git/tree/thread_pthread.c#n1720
> Which then raises the following exception in io.c:
> http://bogomips.org/mirrors/ruby.git/tree/io.c#n7621
>  
> From the journal:
> app/vendor/bundle/ruby/2.0.0/gems/unicorn-5.0.1/lib/unicorn/http_server.rb:780:in
> `for_fd': The given fd is not accessible because RubyVM reserves it
> (ArgumentError)

That should not happen.  So I wonder if LISTEN_FDS is set to
the wrong number, somehow.

How many sockets are you activating? LISTEN_FDS should match
that number.

Can you dump out the inherited, and LISTEN_* env variables with
the following?

--- a/lib/unicorn/http_server.rb
+++ b/lib/unicorn/http_server.rb
@@ -776,6 +776,8 @@ def inherit_listeners!
     end
     # to ease debugging, we will not unset LISTEN_PID and LISTEN_FDS
 
+    $stderr.write("I=#{inherited.inspect} PID=#{sd_pid} FDS=#{sd_fds}\n")
+
     inherited.map! do |fd|
       io = Socket.for_fd(fd.to_i)
       io.autoclose = false


Thanks.

> > Also, can you verify the UNICORN_FD env is NOT set by systemd?
> > (It should not be)
> Verified, not set.
>  
> > Also, for reference, which version of systemd is this?
> Ubuntu Wily 15.10, systemd 225-1ubuntu9

I'll try to test with a newer version this week(*) if the above
can't figure it out.

* maybe Thursday/Friday, my connectivity is inconsistent

Re: Systemd socket inheritance fails with “not a socket file descriptor”

[Amir Yalon]

> How many sockets are you activating? LISTEN_FDS should match
> that number.

I am “activating” only 1 socket, and the error is seen with both a TCP
and a UNIX type socket.

> Can you dump out the inherited, and LISTEN_* env variables with
> the following?

Yes, everything looks as expected, one inherited socket starting at fd
number 3:

I=[3] PID=4869 FDS=1

Also tried with Ruby 2.2.1, same results.  FWIW, my rubies are compiled
by system-wide RVM with no special options given to it.

Thanks for taking the time to investigate, really appreciated.

Regards,
Amir

Re: Systemd socket inheritance fails with “not a socket file descriptor”

[Eric Wong]

Amir Yalon <amiryal@yxejamir.net> wrote:
> Yes, everything looks as expected, one inherited socket starting at fd
> number 3:
> 
> I=[3] PID=4869 FDS=1
> 
> Also tried with Ruby 2.2.1, same results.  FWIW, my rubies are compiled
> by system-wide RVM with no special options given to it.

Interesting.   Can you try using some other non-Ruby daemon
which uses sd_listen_fds, too?   I can't think of any off
the top of my head, but I'm sure there's some.

It seems like systemd is mis-setting FD_CLOEXEC on socket,
even.

> Thanks for taking the time to investigate, really appreciated.

No problem.  I wonder if something else is broken in your systemd
config...

Again, I'll take a harder look at newer systemd later this week
unless somebody beats me to it.

Re: Systemd socket inheritance fails with “not a socket file descriptor” [take2]

[Christos Trochalakis]

On Wed, Mar 09, 2016 at 03:51:57AM +0000, Eric Wong wrote:
>Amir Yalon <amiryal@yxejamir.net> wrote:
>> Yes, everything looks as expected, one inherited socket starting at fd
>> number 3:
>>
>> I=[3] PID=4869 FDS=1
>>
>> Also tried with Ruby 2.2.1, same results.  FWIW, my rubies are compiled
>> by system-wide RVM with no special options given to it.
>
>Interesting.   Can you try using some other non-Ruby daemon
>which uses sd_listen_fds, too?   I can't think of any off
>the top of my head, but I'm sure there's some.
>
>It seems like systemd is mis-setting FD_CLOEXEC on socket,
>even.
>
>> Thanks for taking the time to investigate, really appreciated.
>
>No problem.  I wonder if something else is broken in your systemd
>config...
>
>Again, I'll take a harder look at newer systemd later this week
>unless somebody beats me to it.

I was also unable to reproduce it in:

* debian stretch, ruby2.2 / systemd 229
* ubuntu wily, ruby2.{1,2} / systemd 225

I used system rubies for all the experments, not rvm.

Amir, could you also send us for completeness your unicorn config and
the output of systemctl cat unicorn.socket & systemctl cat
unicorn@1.service ?

Re: Systemd socket inheritance fails with “not a socket file descriptor”

[Christos Trochalakis]

On Wed, Mar 09, 2016 at 03:51:57AM +0000, Eric Wong wrote:
>Amir Yalon <amiryal@yxejamir.net> wrote:
>> Yes, everything looks as expected, one inherited socket starting at fd
>> number 3:
>>
>> I=[3] PID=4869 FDS=1
>>
>> Also tried with Ruby 2.2.1, same results.  FWIW, my rubies are compiled
>> by system-wide RVM with no special options given to it.
>
>Interesting.   Can you try using some other non-Ruby daemon
>which uses sd_listen_fds, too?   I can't think of any off
>the top of my head, but I'm sure there's some.
>
>It seems like systemd is mis-setting FD_CLOEXEC on socket,
>even.
>

Ok, this is my theory, systemd correctly passes the sockets and the
environment to the process, but Amir is using rvm which probably runs
one more exec than usual. In this extra step rvm/ruby closes the fds for
security reasons but the ENV variables remain. In the newly forked ruby
process the timer gets fd=3 (which is now consider internal) and when
unicorn tries to example fd=3 breaks.

Re: Systemd socket inheritance fails with “not a socket file descriptor”

[Amir Yalon]

Christos Trochalakis wrote:
> Ok, this is my theory, systemd correctly passes the sockets and the
> environment to the process, but Amir is using rvm which probably runs
> one more exec than usual. In this extra step rvm/ruby closes the fds for
> security reasons but the ENV variables remain. In the newly forked ruby
> process the timer gets fd=3 (which is now consider internal) and when
> unicorn tries to example fd=3 breaks.

Very plausible!

I ran a few straces to confirm at least part of the theory, and it turns
out RVM runs not one, but 20 more exec than usual. :)

The way my application is launched with RVM:

$ strace -c -e trace=execve /usr/local/rvm/bin/rvm default exec ruby -e
''
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
  0.00    0.000000           0        21        16 execve
------ ----------- ----------- --------- --------- ----------------
100.00    0.000000                    21        16 total

Using system Ruby:

$ strace -c -e trace=execve ruby -e ''
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
  0.00    0.000000           0         1           execve
------ ----------- ----------- --------- --------- ----------------
100.00    0.000000                     1           total

Using RVM ruby without RVM wrapper:

$ strace -c -e trace=execve /usr/local/rvm/rubies/default/bin/ruby -e ''
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
  0.00    0.000000           0         1           execve
------ ----------- ----------- --------- --------- ----------------
100.00    0.000000                     1           total

I will try to run my app using the 3rd method and report back as soon as
I can.

Thanks,
Amir

Re: Systemd socket inheritance fails with “not a socket file descriptor”

[Eric Wong]

Amir Yalon <amiryal@yxejamir.net> wrote:
> I will try to run my app using the 3rd method and report back as soon as
> I can.

Looking forward to it.  I'd like to release 5.1.0 final with any
necessary updates (most likely documentation) needed for this
problem in a week or so.

A huge thanks for bringing this up and to Christos for testing and
bringing up the potential (and IMHO very likely) RVM issue.

Re: Systemd socket inheritance fails with “not a socket file descriptor”

[Amir Yalon]

Hi all,
 
After isolating the problem with the following one-liner in bash:
 
$ /usr/local/rvm/bin/rvm default exec ruby -e 'puts
IO.for_fd(3).inspect' 3<<<test
#<IO:fd 3>
 
$ bundle exec ruby -e 'puts IO.for_fd(3).inspect' 3<<<test
-e:1:in `for_fd': The given fd is not accessible because RubyVM reserves
it (ArgumentError)
        from -e:1:in `<main>'
 
$ /usr/local/rvm/rubies/default/bin/ruby -r bundler/setup -e 'puts
IO.for_fd(3).inspect' 3<<<test
#<IO:fd 3>
 
It became obvious that RVM is not to blame, and the real culprit was
Bundler’s `bundle exec` script.  From here it was just a matter of
figuring out how to launch the unicorn script from within the bundle
using the correct ruby without calling `bundle exec`.  There are a
number of ways to do that, here is what worked for me:
 
ExecStart = /usr/local/rvm/gems/ruby-2.0.0-p645/wrappers/ruby -r
bundler/setup vendor/bundle/ruby/2.0.0/bin/unicorn -c
config/unicorn/unicorn.rb -E staging -s myapp@%i
 
Thanks again to all participants, your input was invaluable.
 
 
P.S.  Notice how I abuse the -s no-op parameter to identify which
template instance is running in systemd (in the output of ps, for
example), maybe worth documenting it as a feature?
 
Regards,
Amir

[PATCH] doc: reference --keep-file-descriptors for "bundle exec"

[Eric Wong]

Amir Yalon <amiryal@yxejamir.net> wrote:
> It became obvious that RVM is not to blame, and the real culprit was
> Bundler’s `bundle exec` script.  From here it was just a matter of
> figuring out how to launch the unicorn script from within the bundle
> using the correct ruby without calling `bundle exec`.  There are a
> number of ways to do that, here is what worked for me:

Ahah, seems like an old problem with bundler defaults.

> ExecStart = /usr/local/rvm/gems/ruby-2.0.0-p645/wrappers/ruby -r
> bundler/setup vendor/bundle/ruby/2.0.0/bin/unicorn -c
> config/unicorn/unicorn.rb -E staging -s myapp@%i

Actually, "bundle exec --keep-file-descriptors" should work
nowadays.  See patch below.

> Thanks again to all participants, your input was invaluable.

No problem.

> P.S.  Notice how I abuse the -s no-op parameter to identify which
> template instance is running in systemd (in the output of ps, for
> example), maybe worth documenting it as a feature?

*shrug* I prefer to use full the full path to the config file
which would already include the app name in it:

	unicorn -c /path/to/my_app/unicorn.conf.rb ...

-------------------------8<-------------------------
Subject: [PATCH] doc: reference --keep-file-descriptors for "bundle exec"

"bundle exec" alone is not suitable for use with systemd-style
socket activation due to Ruby 2.0+ behavior of setting close-on-exec
for file descriptors above 2.  However, the "--keep-file-descriptors"
option was added to bundler 1.4.0 to workaround this Ruby 2.0 change
and may be used to prevent Ruby 2.0+ from closing file descriptors
on exec.

Thanks to Amir Yalon and Christos Trochalakis for bringing up
this issue on the mailing list:

http://bogomips.org/unicorn-public/1457824748.3666627.547425122.2A828B07@webmail.messagingengine.com/
---
 Sandbox                   | 6 +++---
 examples/unicorn@.service | 2 ++
 2 files changed, 5 insertions(+), 3 deletions(-)

diff --git a/Sandbox b/Sandbox
index 997b92f..0760065 100644
--- a/Sandbox
+++ b/Sandbox
@@ -63,9 +63,9 @@ before_exec hook as illustrated by https://gist.github.com/534668
 === Ruby 2.0.0 close-on-exec and SIGUSR2 incompatibility
 
 Ruby 2.0.0 enforces FD_CLOEXEC on file descriptors by default.  unicorn
-has been prepared for this behavior since unicorn 4.1.0, but we forgot
-to remind the Bundler developers.  This issue is being tracked here:
-https://github.com/bundler/bundler/issues/2628
+has been prepared for this behavior since unicorn 4.1.0, and bundler
+needs the "--keep-file-descriptors" option for "bundle exec":
+http://bundler.io/man/bundle-exec.1.html
 
 == Isolate
 
diff --git a/examples/unicorn@.service b/examples/unicorn@.service
index b058da5..5b16b5b 100644
--- a/examples/unicorn@.service
+++ b/examples/unicorn@.service
@@ -11,6 +11,8 @@ Wants = unicorn.socket
 After = unicorn.socket
 
 [Service]
+# bundler users must use the "--keep-file-descriptors" switch, here:
+# ExecStart = bundle exec --keep-file-descriptors /usr/bin/unicorn ...
 ExecStart = /usr/bin/unicorn -c /path/to/unicorn.conf.rb /path/to/config.ru
 Sockets = unicorn.socket
 KillSignal = SIGQUIT
-- 
EW

Re: [PATCH] doc: reference --keep-file-descriptors for "bundle exec"

[Amir Yalon]

> [Service]
> +# bundler users must use the "--keep-file-descriptors" switch, here:
> +# ExecStart = bundle exec --keep-file-descriptors /usr/bin/unicorn ...
 
Small correction: it’s `/usr/bin/bundle exec --keep-file-descriptors
unicorn`, not `bundle exec --keep-file-descriptiors /usr/bin/unicorn`
(first argument to ExecStart must be a full path.)

Re: [PATCH] doc: reference --keep-file-descriptors for "bundle exec"

[Eric Wong]

Amir Yalon <amiryal@yxejamir.net> wrote:
> Small correction: it’s `/usr/bin/bundle exec --keep-file-descriptors
> unicorn`, not `bundle exec --keep-file-descriptiors /usr/bin/unicorn`
> (first argument to ExecStart must be a full path.)

Ah, thanks!  Amended and pushed.