New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Rails server spams log due to getsockopt(2) TCP_INFO ENOPROTOPT #1982

Open
ArsalanDotMe opened this Issue Apr 22, 2017 · 23 comments

Comments

Projects
None yet
@ArsalanDotMe

ArsalanDotMe commented Apr 22, 2017

Microsoft Windows [Version 10.0.15063]

Clean installed rails 5.0.2 on Ruby 2.4.0 through rebenv 1.1.0-2-g4f8925a.
Went into a directory owned by Windows. Created a new project and started the server with rails s. The command was extremely slow to start and once it showed the following output, I made a simple GET request to localhost:3000.

/home/arsalan/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/railties-5.0.2/lib/rails/app_loader.rb:40: warning: Insecure world writable dir /home/arsalan/.rbenv/versions in PATH, mode 040777
=> Booting Puma
=> Rails 5.0.2 application starting in development on http://0.0.0.0:3000
=> Run `rails server -h` for more startup options
Puma starting in single mode...
* Version 3.8.1 (ruby 2.4.0-p0), codename: Sassy Salamander
* Min threads: 5, max threads: 5
* Environment: development
* Listening on tcp://0.0.0.0:3000
Use Ctrl-C to stop

On making the GET request, the following error showed up.

2017-04-22 11:40:02 +0500: Read error: #<Errno::ENOPROTOOPT: Protocol not available - getsockopt(2)>
/home/arsalan/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/puma-3.8.1/lib/puma/server.rb:124:in `getsockopt'
/home/arsalan/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/puma-3.8.1/lib/puma/server.rb:124:in `closed_socket?'
/home/arsalan/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/puma-3.8.1/lib/puma/server.rb:563:in `handle_request'
/home/arsalan/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/puma-3.8.1/lib/puma/server.rb:425:in `process_client'
/home/arsalan/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/puma-3.8.1/lib/puma/server.rb:289:in `block in run'
/home/arsalan/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/puma-3.8.1/lib/puma/thread_pool.rb:120:in `block in spawn_thread'

I don't know if strace of this command will be useful as it keeps continuously spitting out lines at the speed of light. Never exits.

The relevant error-throwing line from puma seems to be

socket.getsockopt(Socket::SOL_TCP, Socket::TCP_INFO)
@ArsalanDotMe

This comment has been minimized.

ArsalanDotMe commented Apr 22, 2017

It looks like the TCP_INFO option on the linux getsockopt(2) is not supported at this point.

Please see: TCP Options

TCP_INFO (since Linux 2.4)
Used to collect information about this socket. The kernel
returns a struct tcp_info as defined in the file
/usr/include/linux/tcp.h. This option should not be used in
code intended to be portable.

@sunilmut

This comment has been minimized.

Member

sunilmut commented Apr 22, 2017

@ArsalanDotMe - Thanks for reporting the issue and the detailed information. Very helpful. Yes, we don't need the whole trace. You have already provided the relevant pieces. I can confirm that WSL currently does not implement the TCP_INFO socket option.

I have opened a task at our end to track this. Thanks again for trying WSL and providing feedback.

@guenard

This comment has been minimized.

guenard commented Jun 6, 2017

Just wanted to add that I got a similar log from PHP-FPM 5.6. ~ one line per second is written in /var/log/php5.6-fpm.log (TCP_INFO for socket: Protocol not available). Same as #2090.

@adamluzsi

This comment has been minimized.

adamluzsi commented Jun 12, 2017

+1

1 similar comment
@linhecheng

This comment has been minimized.

linhecheng commented Jul 20, 2017

+1

@sunilmut

This comment has been minimized.

Member

sunilmut commented Jul 20, 2017

Can someone share clear (and if possible targeted) repro steps for this? I am looking into it right now and need that for validation.

@ArsalanDotMe

This comment has been minimized.

ArsalanDotMe commented Jul 21, 2017

I'm happy to provide more detailed reproduction steps, but looking at the first message in the thread, what do you think is missing in detail to reproduce the error? I tried to provide exact version numbers and steps for all software involved.

@sunilmut

This comment has been minimized.

Member

sunilmut commented Jul 21, 2017

@ArsalanDotMe - Thanks. Yes, the first thread does provide the exact versions, but I was hoping to get exact instructions since I am not familiar with rails. That way, I can copy paste the instructions for the repro and focus on fixing the issue.

@ArsalanDotMe

This comment has been minimized.

ArsalanDotMe commented Jul 22, 2017

The guide I followed is this one: https://gorails.com/setup/windows/10

You don't need to setup mysql or postgres, otherwise the guide is the same.

@adamluzsi

This comment has been minimized.

adamluzsi commented Jul 22, 2017

Hy @sunilmut ,

Here is a example repo where all you need is to install and run (or if you have both ruby and bundler all you need is to start the app).
I tried to create an install script but I couldn't test it because I'm not in wsl/ubuntu now.

I met with this too and the problem is about a yet not implemented socket protocol.
I can't confirm that the bug stills on, but if you clone the repo and run it and try call it with some http requests, than you can reproduce the problem.

@Marthyn

This comment has been minimized.

Marthyn commented Jul 26, 2017

👍
Ruby 2.2.4
Rails 4.2.7.1
Running bundle exec unicorn -p 5001

Results in
Protocol not available- setsockopt(2) (Errno::ENOPROTOOPT)

@bitcrazed

This comment has been minimized.

Collaborator

bitcrazed commented Mar 30, 2018

@ArsalanDotMe Could you try repro'ing on a recent Insiders build? I am running build 17364, and cannot repro your scenario - all looks good to me!

I installed rvm using DigitalOcean's instructions, and then installed rails, and created a new rails templated site using rails new ./rubytest. I then ran rails s to build & serve the site, and navigated to its URL:

image

Please let us know if your issue persists.

@therealkenc

This comment has been minimized.

Collaborator

therealkenc commented Mar 31, 2018

I think this got picked up with #393 #68. AFAIK, Rails has worked for a while (there would be more noise if it didn't). Best @sunilmut weigh in on the status of TCP_INFO. Caveat being, stuff is being worked around upstream, and it is hard to tell whether the surface was fixed or just dealt with. There is no mention of TCP_INFO for some time. Nothing in the release notes (natch).

@bitcrazed

This comment has been minimized.

Collaborator

bitcrazed commented Apr 2, 2018

Yep - difficult to know if this is upstream or WSL now supporting TCP_INFO - what say you @sunilmut? 😁

@Yay295

This comment has been minimized.

Yay295 commented May 3, 2018

This is still not supported in Redstone 4. A quick test with Python

import socket
socket.socket().getsockopt(socket.SOL_TCP, socket.TCP_INFO)

shows

Traceback (most recent call last):
  File "<stdin>", line 1, in <module>
  File "/usr/lib/python2.7/socket.py", line 228, in meth
    return getattr(self._sock,name)(*args)
socket.error: [Errno 92] Protocol not available
@brucek2

This comment has been minimized.

brucek2 commented Jun 18, 2018

Since #2090 was duped to here and closed, I'll note that for me php7.1-fpm is still generating a once per second log entry:
ERROR: failed to retrieve TCP_INFO for socket: Protocol not available (92)

FPM is otherwise working but it'd be nice if there was a fix for this nuisance. Anyone have a good workaround?

@therealkenc

This comment has been minimized.

Collaborator

therealkenc commented Jun 18, 2018

Thanks @brucek2 and @Yay295 for confirming. So TCP_INFO is just not implemented. The work-around would be to recompile php without config HAVE_LQ_TCP_INFO. Or for that matter, just comment out the zlog() line. It isn't fatal, but I can imagine the over-aggressive logging once per second is pretty problematic.

@sunilmut - You don't from any practical standpoint have to wait on the NT tcp stack people to implement this. The feature wasn't forthcoming from them in April of 2016, and it probably isn't forthcoming in 2018 either. Just let getsockopt() succeed and fill in the struct tcp_info with zeros. As long as .tcpi_sacked is zero then php will just move on (and, mercifully, does so without spamming the log).

There is a decent backgrounder on TCP_INFO here.

@therealkenc therealkenc changed the title from Rails server doesn't boot up due to getsockopt(2) error to Rails server spams log due to getsockopt(2) TCP_INFO ENOPROTOPT Jun 18, 2018

@jbrooksuk

This comment has been minimized.

jbrooksuk commented Jul 23, 2018

I'm seeing:

ERROR: failed to retrieve TCP_INFO for socket: Protocol not available (92)

Every second (although not since changing log_level = alert) but nginx does not respond with anything, it's just a blank screen - although this may be fault of valet-wsl?

@SamSaffron

This comment has been minimized.

SamSaffron commented Aug 14, 2018

The ruby unicorn web server is definitely not working right per:

https://bogomips.org/unicorn-public/CAAtdryOtTO8HGTeKLy_JbeRhWLC7JZpCABVpbpEK+z67JHx=ew@mail.gmail.com/T/#u

@tara-raj

This comment has been minimized.

Member

tara-raj commented Aug 24, 2018

We’re investigating approaches to address this issue and will report back when we have something concrete to share. Will update this thread at that time with details!

@SamSaffron

This comment has been minimized.

SamSaffron commented Aug 27, 2018

Awesome @tara-raj , if you need any help testing I am happy to flick whatever switches I need to run bleeding edge wsl.

@Haacked

This comment has been minimized.

Haacked commented Sep 20, 2018

I'm happy to test as well. Ran into this with nginx and a ruby sinatra app.

@maatinito

This comment has been minimized.

maatinito commented Oct 20, 2018

So to resume:
Unicorn doesn't work on WSL and there are two problems:

  • getsockopt(socket.SOL_TCP, socket.TCP_INFO) ==> ENOPROTOPT
  • getsockopt(TCP_CORK/TCP_NOPUSH) ==> ENOPROTOPT

Waiting for more support, as Unicorn is just a way to laucnh multiple rails server for performance, for the dev, I removed the dependency on Unicorn in file Gemfile, uninstall unicorn using sudo gem uninstall unicorn and everything works fine :-)

WSL is very promising, very exciting so good luck guys and thanks :-)

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment