Skip to content
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

File descriptor leaks #1439

Closed
JasonBarnabe opened this issue Mar 19, 2015 · 33 comments

Comments

Projects
None yet
5 participants
@JasonBarnabe
Copy link

commented Mar 19, 2015

I upgraded my site from 4.0.52 to Passenger 5.0.4 and within an hour it crashed. The problem appears to be it was bumping up against the numothersock limit in OpenVZ. Never had this problem before upgrading, never had it on my other, busier site which also runs 4.0.52.

The previous numothersock limit was 360. Right now, the Passenger 5 site is using 381. The Passenger 4 site currently has 79.

sudo netstat -np | grep Passenger on my Passenger 4 site gives:

tcp        0      0 127.0.0.1:55448             127.0.0.1:11211             ESTABLISHED 9848/Passenger Rack 
tcp        0      0 127.0.0.1:55426             127.0.0.1:11211             ESTABLISHED 9824/Passenger Rack 
tcp        0      0 127.0.0.1:55533             127.0.0.1:11211             ESTABLISHED 9929/Passenger Rack 
tcp        0      0 127.0.0.1:55785             127.0.0.1:11211             ESTABLISHED 10137/Passenger Rac 
unix  3      [ ]         STREAM     CONNECTED     2570960464 10137/Passenger Rac 
unix  3      [ ]         STREAM     CONNECTED     2570960385 10137/Passenger Rac /tmp/passenger.1.0.18334/generation-0/backends/preloader.1c88rlz
unix  3      [ ]         STREAM     CONNECTED     2570960384 11782/PassengerHelp 
unix  3      [ ]         STREAM     CONNECTED     2570952903 9929/Passenger Rack 
unix  3      [ ]         STREAM     CONNECTED     2570952771 9929/Passenger Rack /tmp/passenger.1.0.18334/generation-0/backends/preloader.1c88rlz
unix  3      [ ]         STREAM     CONNECTED     2570952770 11782/PassengerHelp 
unix  3      [ ]         STREAM     CONNECTED     2570949935 9848/Passenger Rack 
unix  3      [ ]         STREAM     CONNECTED     2570949819 9848/Passenger Rack /tmp/passenger.1.0.18334/generation-0/backends/preloader.1c88rlz
unix  3      [ ]         STREAM     CONNECTED     2570949818 11782/PassengerHelp 
unix  3      [ ]         STREAM     CONNECTED     2570949616 9824/Passenger Rack 
unix  3      [ ]         STREAM     CONNECTED     2570949475 9824/Passenger Rack /tmp/passenger.1.0.18334/generation-0/backends/preloader.1c88rlz
unix  3      [ ]         STREAM     CONNECTED     2570949474 11782/PassengerHelp 
unix  3      [ ]         STREAM     CONNECTED     2570948230 11782/PassengerHelp 
unix  3      [ ]         STREAM     CONNECTED     2570948229 9707/Passenger AppP 
unix  3      [ ]         STREAM     CONNECTED     1542921496 11788/PassengerLogg 
unix  3      [ ]         STREAM     CONNECTED     1542921495 11779/PassengerWatc 
unix  3      [ ]         STREAM     CONNECTED     1542921474 11782/PassengerHelp 
unix  3      [ ]         STREAM     CONNECTED     1542921473 11779/PassengerWatc 
unix  3      [ ]         STREAM     CONNECTED     1542921452 11779/PassengerWatc 

On the Passenger 5 site:

tcp        0      0 127.0.0.1:56153             127.0.0.1:11211             ESTABLISHED 13457/Passenger Rub 
tcp        0      0 127.0.0.1:56484             127.0.0.1:11211             ESTABLISHED 13612/Passenger Rub 
tcp        0      0 127.0.0.1:56851             127.0.0.1:11211             ESTABLISHED 13768/Passenger Rub 
unix  142    [ ]         STREAM     CONNECTED     2571008521 24106/PassengerAgen /tmp/passenger.xrLmjj2/agents.s/server
unix  178    [ ]         STREAM     CONNECTED     2571008470 24106/PassengerAgen /tmp/passenger.xrLmjj2/agents.s/server
unix  3      [ ]         STREAM     CONNECTED     2571003143 13457/Passenger Rub /tmp/passenger.xrLmjj2/apps.s/ruby.JFzY1GQiowe6t46BboAP9KiRWoSvehS6WqDV4jK1BGp4150c4ee28eBUcC8ZPhi
unix  3      [ ]         STREAM     CONNECTED     2571003147 24106/PassengerAgen 
unix  3      [ ]         STREAM     CONNECTED     2571001504 13768/Passenger Rub 
unix  3      [ ]         STREAM     CONNECTED     2571000895 13768/Passenger Rub /tmp/passenger.xrLmjj2/apps.s/ruby.UjI03Avqt4rvFZ5VuiiN2cCzefz45658WC4pW7uLOl6gzz23TZV1fXSyp72XIl8
unix  3      [ ]         STREAM     CONNECTED     2571001503 24106/PassengerAgen 
unix  3      [ ]         STREAM     CONNECTED     2571000784 13768/Passenger Rub /tmp/passenger.xrLmjj2/apps.s/preloader.17rndcp
unix  3      [ ]         STREAM     CONNECTED     2571000783 24106/PassengerAgen 
unix  2      [ ]         STREAM     CONNECTED     2570998803 24106/PassengerAgen 
unix  3      [ ]         STREAM     CONNECTED     2570988950 13612/Passenger Rub /tmp/passenger.xrLmjj2/apps.s/ruby.M3d9zal7Tt9c8aOnk4J6luGbtxBaJPLPxnVECIZRLru9kwstESaBTBHfUhcUgza
unix  3      [ ]         STREAM     CONNECTED     2570988949 24106/PassengerAgen 
unix  3      [ ]         STREAM     CONNECTED     2570988716 13612/Passenger Rub 
unix  3      [ ]         STREAM     CONNECTED     2570988450 13612/Passenger Rub /tmp/passenger.xrLmjj2/apps.s/preloader.17rndcp
unix  3      [ ]         STREAM     CONNECTED     2570988449 24106/PassengerAgen 
unix  2      [ ]         STREAM     CONNECTED     2570983664 24106/PassengerAgen 
unix  3      [ ]         STREAM     CONNECTED     2570975726 13457/Passenger Rub 
unix  3      [ ]         STREAM     CONNECTED     2570975256 13457/Passenger Rub /tmp/passenger.xrLmjj2/apps.s/preloader.17rndcp
unix  3      [ ]         STREAM     CONNECTED     2570975255 24106/PassengerAgen 
unix  2      [ ]         STREAM     CONNECTED     2570960770 24106/PassengerAgen 
unix  2      [ ]         STREAM     CONNECTED     2570954757 24106/PassengerAgen 
unix  2      [ ]         STREAM     CONNECTED     2570922665 24106/PassengerAgen 
unix  2      [ ]         STREAM     CONNECTED     2570899353 24106/PassengerAgen 
unix  2      [ ]         STREAM     CONNECTED     2570899346 24106/PassengerAgen 
unix  2      [ ]         STREAM     CONNECTED     2570898669 24106/PassengerAgen 
unix  2      [ ]         STREAM     CONNECTED     2570878344 24106/PassengerAgen 
unix  3      [ ]         STREAM     CONNECTED     2570866791 7302/Passenger AppP 
unix  3      [ ]         STREAM     CONNECTED     2570866228 24106/PassengerAgen 
unix  3      [ ]         STREAM     CONNECTED     2570866227 7302/Passenger AppP 
unix  2      [ ]         STREAM     CONNECTED     2570839101 24106/PassengerAgen 
unix  2      [ ]         STREAM     CONNECTED     2570833089 24106/PassengerAgen 
unix  2      [ ]         STREAM     CONNECTED     2570805494 24106/PassengerAgen 
unix  2      [ ]         STREAM     CONNECTED     2570800252 24106/PassengerAgen 
unix  2      [ ]         STREAM     CONNECTED     2570746263 24106/PassengerAgen 
unix  2      [ ]         STREAM     CONNECTED     2570745184 24106/PassengerAgen 
unix  2      [ ]         STREAM     CONNECTED     2570738277 24106/PassengerAgen 
unix  2      [ ]         STREAM     CONNECTED     2570731969 24106/PassengerAgen 
unix  2      [ ]         STREAM     CONNECTED     2570718296 24106/PassengerAgen 
unix  2      [ ]         STREAM     CONNECTED     2570710858 24106/PassengerAgen 
unix  2      [ ]         STREAM     CONNECTED     2570686334 24106/PassengerAgen 
unix  2      [ ]         STREAM     CONNECTED     2570680755 24106/PassengerAgen 
unix  2      [ ]         STREAM     CONNECTED     2570667023 24106/PassengerAgen 
unix  2      [ ]         STREAM     CONNECTED     2570649975 24106/PassengerAgen 
unix  2      [ ]         STREAM     CONNECTED     2570627501 24106/PassengerAgen 
unix  2      [ ]         STREAM     CONNECTED     2570609594 24106/PassengerAgen 
unix  2      [ ]         STREAM     CONNECTED     2570607269 24106/PassengerAgen 
unix  2      [ ]         STREAM     CONNECTED     2570591177 24106/PassengerAgen 
unix  2      [ ]         STREAM     CONNECTED     2570582091 24106/PassengerAgen 
unix  2      [ ]         STREAM     CONNECTED     2570571124 24106/PassengerAgen 
unix  2      [ ]         STREAM     CONNECTED     2570555673 24106/PassengerAgen 
unix  2      [ ]         STREAM     CONNECTED     2570542090 24106/PassengerAgen 
unix  2      [ ]         STREAM     CONNECTED     2570530367 24106/PassengerAgen 
unix  2      [ ]         STREAM     CONNECTED     2570519698 24106/PassengerAgen 
unix  2      [ ]         STREAM     CONNECTED     2570505410 24106/PassengerAgen 
unix  2      [ ]         STREAM     CONNECTED     2570486179 24106/PassengerAgen 
unix  2      [ ]         STREAM     CONNECTED     2570475143 24106/PassengerAgen 
unix  2      [ ]         STREAM     CONNECTED     2570438982 24106/PassengerAgen 
unix  2      [ ]         STREAM     CONNECTED     2570432704 24106/PassengerAgen 
unix  2      [ ]         STREAM     CONNECTED     2570422351 24106/PassengerAgen 
unix  2      [ ]         STREAM     CONNECTED     2570416913 24106/PassengerAgen 
unix  2      [ ]         STREAM     CONNECTED     2570379627 24106/PassengerAgen 
unix  2      [ ]         STREAM     CONNECTED     2570366283 24106/PassengerAgen 
unix  2      [ ]         STREAM     CONNECTED     2570358768 24106/PassengerAgen 
unix  2      [ ]         STREAM     CONNECTED     2570354185 24106/PassengerAgen 
unix  2      [ ]         STREAM     CONNECTED     2570340792 24106/PassengerAgen 
unix  2      [ ]         STREAM     CONNECTED     2570328806 24106/PassengerAgen 
unix  2      [ ]         STREAM     CONNECTED     2570314974 24106/PassengerAgen 
unix  2      [ ]         STREAM     CONNECTED     2570301534 24106/PassengerAgen 
unix  2      [ ]         STREAM     CONNECTED     2570287690 24106/PassengerAgen 
unix  2      [ ]         STREAM     CONNECTED     2570275278 24106/PassengerAgen 
unix  2      [ ]         STREAM     CONNECTED     2570252476 24106/PassengerAgen 
unix  2      [ ]         STREAM     CONNECTED     2570241896 24106/PassengerAgen 
unix  2      [ ]         STREAM     CONNECTED     2570217981 24106/PassengerAgen 
unix  2      [ ]         STREAM     CONNECTED     2570216560 24106/PassengerAgen 
unix  2      [ ]         STREAM     CONNECTED     2570198280 24106/PassengerAgen 
unix  2      [ ]         STREAM     CONNECTED     2570181505 24106/PassengerAgen 
unix  2      [ ]         STREAM     CONNECTED     2570158913 24106/PassengerAgen 
unix  2      [ ]         STREAM     CONNECTED     2570126504 24106/PassengerAgen 
unix  2      [ ]         STREAM     CONNECTED     2570097418 24106/PassengerAgen 
unix  2      [ ]         STREAM     CONNECTED     2570075278 24106/PassengerAgen 
unix  2      [ ]         STREAM     CONNECTED     2570074566 24106/PassengerAgen 
unix  2      [ ]         STREAM     CONNECTED     2570067961 24106/PassengerAgen 
unix  2      [ ]         STREAM     CONNECTED     2570055902 24106/PassengerAgen 
unix  2      [ ]         STREAM     CONNECTED     2570046314 24106/PassengerAgen 
unix  2      [ ]         STREAM     CONNECTED     2570026506 24106/PassengerAgen 
unix  2      [ ]         STREAM     CONNECTED     2570010710 24106/PassengerAgen 
unix  2      [ ]         STREAM     CONNECTED     2569994752 24106/PassengerAgen 
unix  2      [ ]         STREAM     CONNECTED     2569971669 24106/PassengerAgen 
unix  2      [ ]         STREAM     CONNECTED     2569965131 24106/PassengerAgen 
unix  2      [ ]         STREAM     CONNECTED     2569946977 24106/PassengerAgen 
unix  2      [ ]         STREAM     CONNECTED     2569935879 24106/PassengerAgen 
unix  2      [ ]         STREAM     CONNECTED     2569918331 24106/PassengerAgen 
unix  2      [ ]         STREAM     CONNECTED     2569904061 24106/PassengerAgen 
unix  2      [ ]         STREAM     CONNECTED     2569889648 24106/PassengerAgen 
unix  2      [ ]         STREAM     CONNECTED     2569872882 24106/PassengerAgen 
unix  2      [ ]         STREAM     CONNECTED     2569860258 24106/PassengerAgen 
unix  2      [ ]         STREAM     CONNECTED     2569835766 24106/PassengerAgen 
unix  2      [ ]         STREAM     CONNECTED     2569829181 24106/PassengerAgen 
unix  2      [ ]         STREAM     CONNECTED     2569800704 24106/PassengerAgen 
unix  2      [ ]         STREAM     CONNECTED     2569789572 24106/PassengerAgen 
unix  2      [ ]         STREAM     CONNECTED     2569765927 24106/PassengerAgen 
unix  2      [ ]         STREAM     CONNECTED     2569760475 24106/PassengerAgen 
unix  2      [ ]         STREAM     CONNECTED     2569744488 24106/PassengerAgen 
unix  2      [ ]         STREAM     CONNECTED     2569700773 24106/PassengerAgen 
unix  2      [ ]         STREAM     CONNECTED     2569680094 24106/PassengerAgen 
unix  2      [ ]         STREAM     CONNECTED     2569678839 24106/PassengerAgen 
unix  2      [ ]         STREAM     CONNECTED     2569674017 24106/PassengerAgen 
unix  2      [ ]         STREAM     CONNECTED     2569659224 24106/PassengerAgen 
unix  2      [ ]         STREAM     CONNECTED     2569628893 24106/PassengerAgen 
unix  2      [ ]         STREAM     CONNECTED     2569622755 24106/PassengerAgen 
unix  2      [ ]         STREAM     CONNECTED     2569610030 24106/PassengerAgen 
unix  2      [ ]         STREAM     CONNECTED     2569594741 24106/PassengerAgen 
unix  2      [ ]         STREAM     CONNECTED     2569575770 24106/PassengerAgen 
unix  2      [ ]         STREAM     CONNECTED     2569545299 24106/PassengerAgen 
unix  2      [ ]         STREAM     CONNECTED     2569544622 24106/PassengerAgen 
unix  2      [ ]         STREAM     CONNECTED     2569528930 24106/PassengerAgen 
unix  2      [ ]         STREAM     CONNECTED     2569506149 24106/PassengerAgen 
unix  2      [ ]         STREAM     CONNECTED     2569500270 24106/PassengerAgen 
unix  2      [ ]         STREAM     CONNECTED     2569460325 24106/PassengerAgen 
unix  2      [ ]         STREAM     CONNECTED     2569444164 24106/PassengerAgen 
unix  2      [ ]         STREAM     CONNECTED     2569419461 24106/PassengerAgen 
unix  2      [ ]         STREAM     CONNECTED     2569416911 24106/PassengerAgen 
unix  2      [ ]         STREAM     CONNECTED     2569404544 24106/PassengerAgen 
unix  2      [ ]         STREAM     CONNECTED     2569382621 24106/PassengerAgen 
unix  2      [ ]         STREAM     CONNECTED     2569371966 24106/PassengerAgen 
unix  2      [ ]         STREAM     CONNECTED     2569370328 24106/PassengerAgen 
unix  2      [ ]         STREAM     CONNECTED     2569350458 24106/PassengerAgen 
unix  2      [ ]         STREAM     CONNECTED     2569324406 24106/PassengerAgen 
unix  2      [ ]         STREAM     CONNECTED     2569312448 24106/PassengerAgen 
unix  2      [ ]         STREAM     CONNECTED     2569280624 24106/PassengerAgen 
unix  2      [ ]         STREAM     CONNECTED     2569267455 24106/PassengerAgen 
unix  2      [ ]         STREAM     CONNECTED     2569262882 24106/PassengerAgen 
unix  2      [ ]         STREAM     CONNECTED     2569238433 24106/PassengerAgen 
unix  2      [ ]         STREAM     CONNECTED     2569220547 24106/PassengerAgen 
unix  2      [ ]         STREAM     CONNECTED     2569216344 24106/PassengerAgen 
unix  2      [ ]         STREAM     CONNECTED     2569192906 24106/PassengerAgen 
unix  2      [ ]         STREAM     CONNECTED     2569186877 24106/PassengerAgen 
unix  2      [ ]         STREAM     CONNECTED     2569160242 24106/PassengerAgen 
unix  2      [ ]         STREAM     CONNECTED     2569155176 24106/PassengerAgen 
unix  2      [ ]         STREAM     CONNECTED     2569145791 24106/PassengerAgen 
unix  2      [ ]         STREAM     CONNECTED     2569118147 24106/PassengerAgen 
unix  2      [ ]         STREAM     CONNECTED     2569104655 24106/PassengerAgen 
unix  2      [ ]         STREAM     CONNECTED     2569098304 24106/PassengerAgen 
unix  2      [ ]         STREAM     CONNECTED     2569076593 24106/PassengerAgen 
unix  2      [ ]         STREAM     CONNECTED     2569055085 24106/PassengerAgen 
unix  2      [ ]         STREAM     CONNECTED     2569032323 24106/PassengerAgen 
unix  2      [ ]         STREAM     CONNECTED     2569019312 24106/PassengerAgen 
unix  2      [ ]         STREAM     CONNECTED     2568994214 24106/PassengerAgen 
unix  2      [ ]         STREAM     CONNECTED     2568994119 24106/PassengerAgen 
unix  2      [ ]         STREAM     CONNECTED     2568968128 24106/PassengerAgen 
unix  2      [ ]         STREAM     CONNECTED     2568960529 24106/PassengerAgen 
unix  2      [ ]         STREAM     CONNECTED     2568950293 24106/PassengerAgen 
unix  2      [ ]         STREAM     CONNECTED     2568938853 24106/PassengerAgen 
unix  2      [ ]         STREAM     CONNECTED     2568914173 24106/PassengerAgen 
unix  2      [ ]         STREAM     CONNECTED     2568909015 24106/PassengerAgen 
unix  2      [ ]         STREAM     CONNECTED     2568888703 24106/PassengerAgen 
unix  2      [ ]         STREAM     CONNECTED     2568850392 24106/PassengerAgen 
unix  2      [ ]         STREAM     CONNECTED     2568842691 24106/PassengerAgen 
unix  2      [ ]         STREAM     CONNECTED     2568832838 24106/PassengerAgen 
unix  2      [ ]         STREAM     CONNECTED     2568830897 24106/PassengerAgen 
unix  2      [ ]         STREAM     CONNECTED     2568802993 24106/PassengerAgen 
unix  2      [ ]         STREAM     CONNECTED     2568780001 24106/PassengerAgen 
unix  2      [ ]         STREAM     CONNECTED     2568764125 24106/PassengerAgen 
unix  2      [ ]         STREAM     CONNECTED     2568740707 24106/PassengerAgen 
unix  2      [ ]         STREAM     CONNECTED     2568740122 24106/PassengerAgen 
unix  2      [ ]         STREAM     CONNECTED     2568728429 24106/PassengerAgen 
unix  2      [ ]         STREAM     CONNECTED     2568717006 24106/PassengerAgen 
unix  2      [ ]         STREAM     CONNECTED     2568702455 24106/PassengerAgen 
unix  3      [ ]         STREAM     CONNECTED     2568679987 24112/PassengerAgen 
unix  3      [ ]         STREAM     CONNECTED     2568679986 24103/PassengerAgen 
unix  3      [ ]         STREAM     CONNECTED     2568679959 24106/PassengerAgen 
unix  3      [ ]         STREAM     CONNECTED     2568679958 24103/PassengerAgen 
unix  3      [ ]         STREAM     CONNECTED     2568679927 24103/PassengerAgen 

Is this indicative of a problem, or is this just how things go in Passenger 5?

@JasonBarnabe

This comment has been minimized.

Copy link
Author

commented Mar 19, 2015

After a few hours it's up to 600. A restart of nginx brings it back down to 80.

@FooBarWidget

This comment has been minimized.

Copy link
Member

commented Mar 19, 2015

How much traffic do you get on your website?

I wonder whether this is a file descriptor leak.

@FooBarWidget FooBarWidget added this to the 5.0.5 milestone Mar 19, 2015

@JasonBarnabe

This comment has been minimized.

Copy link
Author

commented Mar 19, 2015

1.3M requests yesterday.

I ran lsof | wc -l on both the Passenger 4 and Passenger 5 sites, the result is about 800 on both. Not sure if this helpful information for your file description leak theory.

@FooBarWidget

This comment has been minimized.

Copy link
Member

commented Mar 19, 2015

There are no known file descriptor leaks.

So you're saying that the file number of file descriptors don't differ that much between Passenger 4 and Passenger 5 after all?

What do you see if you run 'passenger-status --show=requests'? How many requests are open? Is the number of open requests comparable to the number of file descriptors + number of app processes?

@JasonBarnabe

This comment has been minimized.

Copy link
Author

commented Mar 19, 2015

I'm saying the results of lsof are similar. I'm not sure if the results of lsof represent "file descriptors".

The differences I've noticed so far are:

  • sudo netstat -np | grep Passenger | wc -l: 23 in Passenger 4. 483 in Passenger 5.
  • numothersock as reported by OpenVZ's /proc/user_beancounters: 76 in Passenger 4. 968 in Passenger 5.

Here is passenger-status --show=requests

Version : 5.0.4
Date    : 2015-03-19 14:48:11 +0000
Instance: Vn2mgUoU (nginx/1.6.2 Phusion_Passenger/5.0.4)

{
   "thread1" : {
      "active_client_count" : 2,
      "active_clients" : {
         "1-58316" : {
            "connected_at" : {
               "local" : "Thu Mar 19 14:48:09 2015",
               "relative" : "2s ago",
               "timestamp" : 1426776489.820637
            },
            "connection_state" : "ACTIVE",
            "current_request" : {
               "app_response_body_already_read" : {
                  "bytes" : 1199753,
                  "human_readable" : "1.1 MB"
               },
               "app_response_body_fully_read" : true,
               "app_response_body_type" : "CHUNKED",
               "app_response_end_chunk_reached" : true,
               "app_response_http_major" : 1,
               "app_response_http_minor" : 1,
               "app_response_http_state" : "PARSING_CHUNKED_BODY",
               "app_response_want_keep_alive" : true,
               "app_sink_state" : {
                  "callback_in_progress" : false,
                  "initialized" : false,
                  "io_watcher_active" : false
               },
               "app_source_state" : {
                  "callback_in_progress" : true,
                  "initialized" : false,
                  "io_watcher_active" : false
               },
               "flags" : {
                  "dechunk_response" : true,
                  "https" : true,
                  "request_body_buffering" : false
               },
               "http_major" : 1,
               "http_minor" : 1,
               "http_state" : "FLUSHING_OUTPUT",
               "method" : "GET",
               "path" : "",
               "refcount" : 1,
               "request_body_already_read" : 0,
               "request_body_fully_read" : true,
               "request_body_type" : "NO_BODY",
               "response_begun" : true,
               "session_checkout_try" : 1,
               "started_at" : {
                  "local" : "Thu Mar 19 14:48:09 2015",
                  "relative" : "2s ago",
                  "timestamp" : 1426776489.820679
               },
               "state" : "WAITING_FOR_APP_OUTPUT",
               "sticky_session" : false,
               "want_keep_alive" : false
            },
            "lingering_request_count" : 4,
            "name" : "1-58316",
            "number" : 58316,
            "output_channel_state" : {
               "bytes_buffered" : {
                  "bytes" : 0,
                  "human_readable" : "0 bytes"
               },
               "callback_in_progress" : true,
               "mode" : "IN_FILE_MODE",
               "nbuffers" : 1,
               "read_offset" : {
                  "bytes" : 285376,
                  "human_readable" : "278.7 KB"
               },
               "reader_state" : "RS_WAITING_FOR_CHANNEL_IDLE",
               "writer_state" : "WS_TERMINATED",
               "written" : {
                  "bytes" : 797357,
                  "human_readable" : "778.7 KB"
               }
            },
            "refcount" : 2,
            "requests_begun" : 3418
         },
         "1-58318" : {
            "connected_at" : {
               "local" : "Thu Mar 19 14:48:10 2015",
               "relative" : "1s ago",
               "timestamp" : 1426776490.922604
            },
            "connection_state" : "ACTIVE",
            "current_request" : {
               "app_response_body_already_read" : {
                  "bytes" : 0,
                  "human_readable" : "0 bytes"
               },
               "app_response_body_fully_read" : true,
               "app_response_body_type" : "NO_BODY",
               "app_response_http_major" : 1,
               "app_response_http_minor" : 0,
               "app_response_http_state" : "PARSING_HEADERS",
               "app_response_want_keep_alive" : false,
               "app_sink_state" : {
                  "callback_in_progress" : false,
                  "initialized" : true,
                  "io_watcher_active" : false
               },
               "app_source_state" : {
                  "callback_in_progress" : false,
                  "initialized" : true,
                  "io_watcher_active" : true
               },
               "flags" : {
                  "dechunk_response" : true,
                  "https" : true,
                  "request_body_buffering" : false
               },
               "host" : "greasyfork.org",
               "http_major" : 1,
               "http_minor" : 1,
               "http_state" : "COMPLETE",
               "method" : "GET",
               "path" : "/tr/scripts.json?page=48&sort=updated",
               "refcount" : 1,
               "request_body_already_read" : 0,
               "request_body_fully_read" : true,
               "request_body_type" : "NO_BODY",
               "response_begun" : false,
               "session" : {
                  "gupid" : "16ad914-TNLQRQwa0m",
                  "pid" : 11864
               },
               "session_checkout_try" : 1,
               "started_at" : {
                  "local" : "Thu Mar 19 14:48:10 2015",
                  "relative" : "1s ago",
                  "timestamp" : 1426776490.922656
               },
               "state" : "WAITING_FOR_APP_OUTPUT",
               "sticky_session" : false,
               "want_keep_alive" : false
            },
            "lingering_request_count" : 9,
            "name" : "1-58318",
            "number" : 58318,
            "output_channel_state" : {
               "bytes_buffered" : {
                  "bytes" : 0,
                  "human_readable" : "0 bytes"
               },
               "callback_in_progress" : false,
               "mode" : "IN_MEMORY_MODE",
               "nbuffers" : 0,
               "reader_state" : "RS_INACTIVE"
            },
            "refcount" : 2,
            "requests_begun" : 12311
         }
      },
      "disconnected_client_count" : 0,
      "disconnected_clients" : {},
      "free_client_count" : 126,
      "free_request_count" : 8,
      "mbuf_pool" : {
         "active_blocks" : 94567,
         "active_memory" : {
            "bytes" : 48418304,
            "human_readable" : "46.2 MB"
         },
         "chunk_size" : 512,
         "free_blocks" : 291,
         "offset" : 448,
         "spare_memory" : {
            "bytes" : 148992,
            "human_readable" : "145.5 KB"
         }
      },
      "pid" : 20100,
      "server_state" : "ACTIVE",
      "total_bytes_consumed" : 47410007,
      "total_clients_accepted" : 58318,
      "total_requests_begun" : 58318,
      "turbocaching" : {
         "fetches" : 3,
         "hit_ratio" : 0.0,
         "hits" : 0,
         "store_success_ratio" : 0.0,
         "store_successes" : 0,
         "stores" : 3
      }
   },
   "thread2" : {
      "active_client_count" : 1,
      "active_clients" : {
         "2-58316" : {
            "connected_at" : {
               "local" : "Thu Mar 19 14:48:09 2015",
               "relative" : "2s ago",
               "timestamp" : 1426776489.827848
            },
            "connection_state" : "ACTIVE",
            "current_request" : {
               "app_response_body_already_read" : {
                  "bytes" : 1085799,
                  "human_readable" : "1.0 MB"
               },
               "app_response_body_fully_read" : true,
               "app_response_body_type" : "CHUNKED",
               "app_response_end_chunk_reached" : true,
               "app_response_http_major" : 1,
               "app_response_http_minor" : 1,
               "app_response_http_state" : "PARSING_CHUNKED_BODY",
               "app_response_want_keep_alive" : true,
               "app_sink_state" : {
                  "callback_in_progress" : false,
                  "initialized" : false,
                  "io_watcher_active" : false
               },
               "app_source_state" : {
                  "callback_in_progress" : true,
                  "initialized" : false,
                  "io_watcher_active" : false
               },
               "flags" : {
                  "dechunk_response" : true,
                  "https" : true,
                  "request_body_buffering" : false
               },
               "http_major" : 1,
               "http_minor" : 1,
               "http_state" : "FLUSHING_OUTPUT",
               "method" : "GET",
               "path" : "",
               "refcount" : 1,
               "request_body_already_read" : 0,
               "request_body_fully_read" : true,
               "request_body_type" : "NO_BODY",
               "response_begun" : true,
               "session_checkout_try" : 1,
               "started_at" : {
                  "local" : "Thu Mar 19 14:48:09 2015",
                  "relative" : "2s ago",
                  "timestamp" : 1426776489.827885
               },
               "state" : "WAITING_FOR_APP_OUTPUT",
               "sticky_session" : false,
               "want_keep_alive" : false
            },
            "lingering_request_count" : 1,
            "name" : "2-58316",
            "number" : 58316,
            "output_channel_state" : {
               "bytes_buffered" : {
                  "bytes" : 0,
                  "human_readable" : "0 bytes"
               },
               "callback_in_progress" : true,
               "mode" : "IN_FILE_MODE",
               "nbuffers" : 1,
               "read_offset" : {
                  "bytes" : 195776,
                  "human_readable" : "191.2 KB"
               },
               "reader_state" : "RS_WAITING_FOR_CHANNEL_IDLE",
               "writer_state" : "WS_TERMINATED",
               "written" : {
                  "bytes" : 773451,
                  "human_readable" : "755.3 KB"
               }
            },
            "refcount" : 2,
            "requests_begun" : 1248
         }
      },
      "disconnected_client_count" : 0,
      "disconnected_clients" : {},
      "free_client_count" : 127,
      "free_request_count" : 10,
      "mbuf_pool" : {
         "active_blocks" : 94919,
         "active_memory" : {
            "bytes" : 48598528,
            "human_readable" : "46.3 MB"
         },
         "chunk_size" : 512,
         "free_blocks" : 294,
         "offset" : 448,
         "spare_memory" : {
            "bytes" : 150528,
            "human_readable" : "147.0 KB"
         }
      },
      "pid" : 20100,
      "server_state" : "ACTIVE",
      "total_bytes_consumed" : 47376310,
      "total_clients_accepted" : 58318,
      "total_requests_begun" : 58318,
      "turbocaching" : {
         "fetches" : 1,
         "hit_ratio" : 0.0,
         "hits" : 0,
         "store_success_ratio" : 0.0,
         "store_successes" : 0,
         "stores" : 1
      }
   },
   "thread3" : {
      "active_client_count" : 1,
      "active_clients" : {
         "3-58316" : {
            "connected_at" : {
               "local" : "Thu Mar 19 14:48:09 2015",
               "relative" : "2s ago",
               "timestamp" : 1426776489.834409
            },
            "connection_state" : "ACTIVE",
            "current_request" : {
               "app_response_body_already_read" : {
                  "bytes" : 1355479,
                  "human_readable" : "1.3 MB"
               },
               "app_response_body_fully_read" : true,
               "app_response_body_type" : "CHUNKED",
               "app_response_end_chunk_reached" : true,
               "app_response_http_major" : 1,
               "app_response_http_minor" : 1,
               "app_response_http_state" : "PARSING_CHUNKED_BODY",
               "app_response_want_keep_alive" : true,
               "app_sink_state" : {
                  "callback_in_progress" : false,
                  "initialized" : false,
                  "io_watcher_active" : false
               },
               "app_source_state" : {
                  "callback_in_progress" : true,
                  "initialized" : false,
                  "io_watcher_active" : false
               },
               "flags" : {
                  "dechunk_response" : true,
                  "https" : true,
                  "request_body_buffering" : false
               },
               "http_major" : 1,
               "http_minor" : 1,
               "http_state" : "FLUSHING_OUTPUT",
               "method" : "GET",
               "path" : "",
               "refcount" : 1,
               "request_body_already_read" : 0,
               "request_body_fully_read" : true,
               "request_body_type" : "NO_BODY",
               "response_begun" : true,
               "session_checkout_try" : 1,
               "started_at" : {
                  "local" : "Thu Mar 19 14:48:09 2015",
                  "relative" : "2s ago",
                  "timestamp" : 1426776489.834457
               },
               "state" : "WAITING_FOR_APP_OUTPUT",
               "sticky_session" : false,
               "want_keep_alive" : false
            },
            "lingering_request_count" : 3,
            "name" : "3-58316",
            "number" : 58316,
            "output_channel_state" : {
               "bytes_buffered" : {
                  "bytes" : 0,
                  "human_readable" : "0 bytes"
               },
               "callback_in_progress" : true,
               "mode" : "IN_FILE_MODE",
               "nbuffers" : 1,
               "read_offset" : {
                  "bytes" : 65408,
                  "human_readable" : "63.9 KB"
               },
               "reader_state" : "RS_WAITING_FOR_CHANNEL_IDLE",
               "writer_state" : "WS_TERMINATED",
               "written" : {
                  "bytes" : 1177531,
                  "human_readable" : "1.1 MB"
               }
            },
            "refcount" : 2,
            "requests_begun" : 1884
         }
      },
      "disconnected_client_count" : 0,
      "disconnected_clients" : {},
      "free_client_count" : 127,
      "free_request_count" : 8,
      "mbuf_pool" : {
         "active_blocks" : 94604,
         "active_memory" : {
            "bytes" : 48437248,
            "human_readable" : "46.2 MB"
         },
         "chunk_size" : 512,
         "free_blocks" : 291,
         "offset" : 448,
         "spare_memory" : {
            "bytes" : 148992,
            "human_readable" : "145.5 KB"
         }
      },
      "pid" : 20100,
      "server_state" : "ACTIVE",
      "total_bytes_consumed" : 48230438,
      "total_clients_accepted" : 58318,
      "total_requests_begun" : 58318,
      "turbocaching" : {
         "fetches" : 1,
         "hit_ratio" : 0.0,
         "hits" : 0,
         "store_success_ratio" : 0.0,
         "store_successes" : 0,
         "stores" : 1
      }
   },
   "thread4" : {
      "active_client_count" : 0,
      "active_clients" : {},
      "disconnected_client_count" : 0,
      "disconnected_clients" : {},
      "free_client_count" : 128,
      "free_request_count" : 10,
      "mbuf_pool" : {
         "active_blocks" : 94193,
         "active_memory" : {
            "bytes" : 48226816,
            "human_readable" : "46.0 MB"
         },
         "chunk_size" : 512,
         "free_blocks" : 292,
         "offset" : 448,
         "spare_memory" : {
            "bytes" : 149504,
            "human_readable" : "146.0 KB"
         }
      },
      "pid" : 20100,
      "server_state" : "ACTIVE",
      "total_bytes_consumed" : 47567608,
      "total_clients_accepted" : 58318,
      "total_requests_begun" : 58318,
      "turbocaching" : {
         "fetches" : 1,
         "hit_ratio" : 0.0,
         "hits" : 0,
         "store_success_ratio" : 0.0,
         "store_successes" : 0,
         "stores" : 1
      }
   },
   "thread5" : {
      "active_client_count" : 0,
      "active_clients" : {},
      "disconnected_client_count" : 0,
      "disconnected_clients" : {},
      "free_client_count" : 128,
      "free_request_count" : 10,
      "mbuf_pool" : {
         "active_blocks" : 94634,
         "active_memory" : {
            "bytes" : 48452608,
            "human_readable" : "46.2 MB"
         },
         "chunk_size" : 512,
         "free_blocks" : 75,
         "offset" : 448,
         "spare_memory" : {
            "bytes" : 38400,
            "human_readable" : "37.5 KB"
         }
      },
      "pid" : 20100,
      "server_state" : "ACTIVE",
      "total_bytes_consumed" : 47456960,
      "total_clients_accepted" : 58318,
      "total_requests_begun" : 58318,
      "turbocaching" : {
         "fetches" : 1,
         "hit_ratio" : 0.0,
         "hits" : 0,
         "store_success_ratio" : 0.0,
         "store_successes" : 0,
         "stores" : 1
      }
   },
   "thread6" : {
      "active_client_count" : 0,
      "active_clients" : {},
      "disconnected_client_count" : 0,
      "disconnected_clients" : {},
      "free_client_count" : 128,
      "free_request_count" : 9,
      "mbuf_pool" : {
         "active_blocks" : 94347,
         "active_memory" : {
            "bytes" : 48305664,
            "human_readable" : "46.1 MB"
         },
         "chunk_size" : 512,
         "free_blocks" : 237,
         "offset" : 448,
         "spare_memory" : {
            "bytes" : 121344,
            "human_readable" : "118.5 KB"
         }
      },
      "pid" : 20100,
      "server_state" : "ACTIVE",
      "total_bytes_consumed" : 48304976,
      "total_clients_accepted" : 58318,
      "total_requests_begun" : 58318,
      "turbocaching" : {
         "fetches" : 1,
         "hit_ratio" : 0.0,
         "hits" : 0,
         "store_success_ratio" : 0.0,
         "store_successes" : 0,
         "stores" : 1
      }
   },
   "thread7" : {
      "active_client_count" : 0,
      "active_clients" : {},
      "disconnected_client_count" : 0,
      "disconnected_clients" : {},
      "free_client_count" : 128,
      "free_request_count" : 10,
      "mbuf_pool" : {
         "active_blocks" : 94367,
         "active_memory" : {
            "bytes" : 48315904,
            "human_readable" : "46.1 MB"
         },
         "chunk_size" : 512,
         "free_blocks" : 3,
         "offset" : 448,
         "spare_memory" : {
            "bytes" : 1536,
            "human_readable" : "1.5 KB"
         }
      },
      "pid" : 20100,
      "server_state" : "ACTIVE",
      "total_bytes_consumed" : 47439641,
      "total_clients_accepted" : 58317,
      "total_requests_begun" : 58317,
      "turbocaching" : {
         "fetches" : 2,
         "hit_ratio" : 0.0,
         "hits" : 0,
         "store_success_ratio" : 0.0,
         "store_successes" : 0,
         "stores" : 2
      }
   },
   "thread8" : {
      "active_client_count" : 0,
      "active_clients" : {},
      "disconnected_client_count" : 0,
      "disconnected_clients" : {},
      "free_client_count" : 128,
      "free_request_count" : 10,
      "mbuf_pool" : {
         "active_blocks" : 94202,
         "active_memory" : {
            "bytes" : 48231424,
            "human_readable" : "46.0 MB"
         },
         "chunk_size" : 512,
         "free_blocks" : 250,
         "offset" : 448,
         "spare_memory" : {
            "bytes" : 128000,
            "human_readable" : "125.0 KB"
         }
      },
      "pid" : 20100,
      "server_state" : "ACTIVE",
      "total_bytes_consumed" : 47479229,
      "total_clients_accepted" : 58317,
      "total_requests_begun" : 58317,
      "turbocaching" : {
         "fetches" : 3,
         "hit_ratio" : 0.0,
         "hits" : 0,
         "store_success_ratio" : 0.0,
         "store_successes" : 0,
         "stores" : 3
      }
   },
   "threads" : 8
}
@JasonBarnabe

This comment has been minimized.

Copy link
Author

commented Mar 19, 2015

Sorry, the results of lsof are different. I just wasn't running it as root.

sudo lsof > lsof.txt
(wait 5 seconds then abort)
grep -c Passenger lsof.txt

Passenger 4: 164. Passenger 5: 684. The difference seems to be in lines like:

Passenger 20097   root    3u  unix 0xffff810132630c80        0t0 2572301688 socket

Passenger 4 has 10 entries like that. Passenger 5 has 489.

@dmitry

This comment has been minimized.

Copy link

commented Mar 20, 2015

We have something similar. When passenger creates a lot of descriptors we are starting to get "Too many open files in system" across other application in a system. Once we increased number of open files limit, it reduced such number of issues, but still we are receiving them ~ twice a day.

@FooBarWidget

This comment has been minimized.

Copy link
Member

commented Mar 20, 2015

@dmitry Are you on version 5.0.4? There are known file descriptor leaks in 5.0.1 and 5.0.2.

@OnixGH

This comment has been minimized.

Copy link
Contributor

commented Mar 20, 2015

@FooBarWidget yes, he said 5.0.4 in the opening post. [edit] Oops, sorry that was JasonBarbabe, sorry.

@dmitry

This comment has been minimized.

Copy link

commented Mar 20, 2015

@FooBarWidget yes, 5.0.4. Happens only when we are starting to get a lot of requests. On other servers, where are not so insensitive usage, I don't see any issues with "Too many open files".

@OnixGH

This comment has been minimized.

Copy link
Contributor

commented Mar 22, 2015

Found a leak with testing which appears to occur around the spawning of processes: with pool size 6 I see 7 app processes being spawned (this needs to be investigated), of which 6 are cleaned up when traffic quiets down. This would cause file descriptors to slowly leak when the traffic flow is not constant (as long as the processes keep running this particular leak doesn't occur).

@JasonBarnabe

This comment has been minimized.

Copy link
Author

commented Mar 22, 2015

I have passenger_max_requests 1000; so I guess that would exasperbate the problem?

@FooBarWidget

This comment has been minimized.

Copy link
Member

commented Mar 23, 2015

This result is consistent with the potential bug I found through a code review. In Passenger 5 we introduced keep-alive connections with application processes, for the purpose of increasing performance. However these keep-alive connections are never closed.

@OnixGH

This comment has been minimized.

Copy link
Contributor

commented Mar 23, 2015

@JasonBarnabe the cleanup cycle is dependent on passenger_pool_idle_time (default 5 mins).
https://www.phusionpassenger.com/documentation/Users%20guide%20Nginx.html#PassengerPoolIdleTime

As a temporary workaround that could be set to 0 (don't shutdown), which should stop this leak (my passenger holds at 312 sockets).

@FooBarWidget

This comment has been minimized.

Copy link
Member

commented Mar 23, 2015

The bug has been confirmed fixed in 2137e87. :)

@dmitry

This comment has been minimized.

Copy link

commented Mar 24, 2015

We are still have "Too many open files in system" error even after upgrade to the latest 5.0.5 version. ulimit is 64000, worker_rlimit_nofile is 4000.

@OnixGH

This comment has been minimized.

Copy link
Contributor

commented Mar 25, 2015

@dmitry: maybe you are experiencing another issue, because the descripor count remains stable in our setup after this fix. Can you provide us with more information? You are running nginx, right?

So when the open files error happens (still 2x per day?), what do the following commands give?
sudo lsof | grep "Passenger" > test.txt ; wc -l test.txt
passenger-status
passenger-status --show=requests

@rutgerg

This comment has been minimized.

Copy link

commented Mar 25, 2015

Same problem here. Going back to 4.0.59 for now.

@FooBarWidget

This comment has been minimized.

Copy link
Member

commented Mar 28, 2015

Reopening this issue until we've confirmed that it's fully fixed.

@FooBarWidget FooBarWidget reopened this Mar 28, 2015

@FooBarWidget FooBarWidget modified the milestones: 5.0.6, 5.0.5 Mar 28, 2015

@FooBarWidget FooBarWidget changed the title Passenger 5 uses a lot more sockets than Passenger 4 File descriptor leaks Mar 28, 2015

@OnixGH

This comment has been minimized.

Copy link
Contributor

commented Mar 29, 2015

@rutgerg same question for you as for @dmitry, can you run:
sudo lsof | grep "Passenger" > test.txt ; wc -l test.txt
passenger-status
passenger-status --show=requests
..and give us the output?
Note: dmitry raised the ulimit from 4000 to 64000 and has not reported any further problem yet (#1445).

@dmitry

This comment has been minimized.

@FooBarWidget

This comment has been minimized.

Copy link
Member

commented Mar 30, 2015

@dmitry Thanks for the information. Are you using Union Station?

@FooBarWidget

This comment has been minimized.

Copy link
Member

commented Mar 30, 2015

@rutgerg Same question to you. Are you using Union Station?

@rutgerg

This comment has been minimized.

Copy link

commented Mar 30, 2015

@OnixGH Unfortunately I went ahead and downgraded our servers so I have not nothing to test your suggestion against at the moment. I'll see if I can set something up later. A problem we had was that multiple servers stalled at unpredictable times about once a day which did influence our production performance. I wasn't able to trigger the problem in a staging environment.

@rutgerg

This comment has been minimized.

Copy link

commented Mar 30, 2015

@FooBarWidget We don't. Do you suggest to?

@FooBarWidget

This comment has been minimized.

Copy link
Member

commented Mar 30, 2015

No, I was just asking about your setup because I'm analyzing the situation.

@FooBarWidget

This comment has been minimized.

Copy link
Member

commented Mar 30, 2015

@rutgerg As for the stall, that sounds a lot like #1425. That issue has been fixed in 5.0.5.

@OnixGH

This comment has been minimized.

Copy link
Contributor

commented Mar 30, 2015

@rutgerg: I understand, thanks. Just to be clear: you experienced what you were saying with 5.0.5?

FooBarWidget added a commit that referenced this issue Mar 30, 2015

Close Union Station transaction after every request
Otherwise the transaction may not be closed because the Request object
is put into a freelist. This would result in file descriptor leaks.

Closes GH-1439.

FooBarWidget added a commit that referenced this issue Mar 30, 2015

@rutgerg

This comment has been minimized.

Copy link

commented Mar 30, 2015

@OnixGH @FooBarWidget It looks the same. We were at 5.0.4. We'll give 5.0.5 a try.

@OnixGH

This comment has been minimized.

Copy link
Contributor

commented Mar 30, 2015

@rutgerg: we're finalizing 5.0.6 which includes fixes for the issues @dmitry reported against 5.0.5 (memleak and fd w/ union station), it's best to go straight to that one :)

@dmitry

This comment has been minimized.

Copy link

commented Mar 30, 2015

@FooBarWidget yes, we are using Union Station.

@FooBarWidget

This comment has been minimized.

Copy link
Member

commented Mar 30, 2015

I believe I've fixed the leak in commit fee107a. Thanks everyone for the feedback. We'll release 5.0.6 as soon as possible.

@JasonBarnabe

This comment has been minimized.

Copy link
Author

commented Apr 4, 2015

After upgrading to 5.0.6, I'm no longer seeing any issues with numothersock, so this appears fixed to me.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
You can’t perform that action at this time.