[create_thread_and_abort_on_exception] rails API throws 404

[Tenzin Chemi]

We have a rails API running on:

rails 4.2.6

ruby 2.2.3

passenger 5.0.18

apache 2.2.15

At some point of time, API starts failing and throws 404 intermittently. I can fix immediately by restarting httpd. I am seeing this for GET & HEAD requests. 

Has anyone able to reproduce this? Also I would like to know the cause if anyone has face this. I am quite sure that passenger is restarting during such events. Correct me if I am wrong. Thanks

`{

"timestamp":"2016-06-11T09:19:02Z",

"severity":"FATAL","type":"exception",

"message":"ActionController::RoutingError(No route matches [HEAD] \"/library-service/authors\"):

vendor/bundle/ruby/2.2.0/gems/actionpack-4.2.6/lib/action_dispatch/middleware/debug_exceptions.rb:21:in `call'",

"exception_id":"d39ef109fc87cd75b225cce1ceb03e5ed2103d5c",

"class":"ActionController::RoutingError",

"backtrace":[

"vendor/bundle/ruby/2.2.3/gems/actionpack-4.2.6/lib/action_dispatch/middleware/debug_exceptions.rb:21:in `call'",

"vendor/bundle/ruby/2.2.3/gems/actionpack-4.2.6/lib/action_dispatch/middleware/show_exceptions.rb:30:in `call'",

"vendor/bundle/ruby/2.2.3/gems/activesupport-4.2.6/lib/active_support/notifications.rb:164:in `block in instrument'",

"vendor/bundle/ruby/2.2.3/gems/activesupport-4.2.6/lib/active_support/notifications/instrumenter.rb:20:in `instrument'",

"vendor/bundle/ruby/2.2.3/gems/activesupport-4.2.6/lib/active_support/notifications.rb:164:in `instrument'",

"vendor/bundle/ruby/2.2.3/gems/request_store-1.3.0/lib/request_store/middleware.rb:9:in `call'",

"vendor/bundle/ruby/2.2.3/gems/actionpack-4.2.6/lib/action_dispatch/middleware/request_id.rb:21:in `call'",

"vendor/bundle/ruby/2.2.3/gems/rack-1.6.4/lib/rack/methodoverride.rb:22:in `call'",

"vendor/bundle/ruby/2.2.3/gems/rack-1.6.4/lib/rack/runtime.rb:18:in `call'",

"vendor/bundle/ruby/2.2.3/gems/activesupport-4.2.6/lib/active_support/cache/strategy/local_cache_middleware.rb:28:in `call'",

"vendor/bundle/ruby/2.2.3/gems/rack-1.6.4/lib/rack/sendfile.rb:113:in `call'",

"vendor/bundle/ruby/2.2.3/gems/railties-4.2.6/lib/rails/engine.rb:518:in `call'",

"vendor/bundle/ruby/2.2.3/gems/railties-4.2.6/lib/rails/application.rb:165:in `call'",

"passenger (5.0.18) lib/phusion_passenger/rack/thread_handler_extension.rb:94:in `process_request'",

"passenger (5.0.18) lib/phusion_passenger/request_handler/thread_handler.rb:157:in `accept_and_process_next_request'",

"passenger (5.0.18) lib/phusion_passenger/request_handler/thread_handler.rb:110:in `main_loop'",

"passenger (5.0.18) lib/phusion_passenger/request_handler.rb:415:in `block (3 levels) in start_threads'",

"passenger (5.0.18) lib/phusion_passenger/utils.rb:112:in `block in create_thread_and_abort_on_exception'"

],

"causes":null}`

[Daniel Knoppel]

Hi, you asked the same question in April, I commented but you didn't reply anymore:

https://groups.google.com/forum/#!searchin/phusion-passenger/library-service/phusion-passenger/he9Ptcnmj9k/lNi32lQ-LAAJ

- Daniel

[Tenzin Chemi]

Sorry, 

I missed it and thought the thread wouldn't get reply if I post there. So I posted again. The issue was not happening on passenger 4.x.x and it started happening after 5.0.18. 

I don't think it has to do anything with route because I am seeing 404 alternatively.

10.190.133.44 - - [15/Jun/2016:08:57:10 -0500] "HEAD /library-service/meta/availability HTTP/1.0" 200 - "-" "-" "-" "-" 0/5053 87 435 "-"

10.190.115.10 - - [15/Jun/2016:08:57:11 -0500] "HEAD /library-service/meta/availability HTTP/1.0" 404 - "-" "-" "-" "-" 0/6704 87 247 "-"

10.190.115.11 - - [15/Jun/2016:08:57:11 -0500] "HEAD /library-service/meta/availability HTTP/1.0" 200 - "-" "-" "-" "-" 0/5690 87 435 "-"

10.190.133.44 - - [15/Jun/2016:08:57:12 -0500] "HEAD /library-service/meta/availability HTTP/1.0" 404 - "-" "-" "-" "-" 0/7756 87 247 "-"

10.190.115.10 - - [15/Jun/2016:08:57:13 -0500] "HEAD /library-service/meta/availability HTTP/1.0" 200 - "-" "-" "-" "-" 0/5288 87 435 "-"

10.190.115.11 - - [15/Jun/2016:08:57:13 -0500] "HEAD /library-service/meta/availability HTTP/1.0" 404 - "-" "-" "-" "-" 0/5497 87 247 "-"

[Daniel Knoppel]

Can you try with Passenger 5.0.28?

And post the passenger log at loglevel 7 of a 200 + 404?

- Daniel

[Tenzin Chemi]

We have more than one app running on passenger 5.0.28 and all of them are facing issues. Right now we are waiting for the issues to occur again and then post here with the logs with Passeger LogLevel set to 7. One our app has been downgraded back to passenger 4.x.x and we kinda stopped seeing issues on that node. We will keep watching the other ones which are on passenger 5.0.18 and post the log for the same here. Thanks

[Chemi]

These are the two requests but one failed. It occurs once a week and we have to restart apache to recover from this situation. 

We have two proxy nodes above the service, for anyone wondering what those two IP addresses are.

10.190.115.27 - - [09/Jul/2017:08:55:02 -0500] "HEAD /client-solution-configuration-service/meta/availability HTTP/1.0" 404 - "-" "-" "-" "-" 0/12672 100 247 "-"

10.190.115.28 - - [09/Jul/2017:08:55:02 -0500] "HEAD /client-solution-configuration-service/meta/availability HTTP/1.0" 200 - "-" "-" "-" "-" 0/8850 100 435 "-"

I have been able to extract passenger logs with LogLevel 7

This is the error log: https://gist.github.com/imechemi/adfa410bc34bcf764a09e8aaf8fdbdfe . I was hoping if you could find any useful information that we could consider as a root cause. 

I tried going through the log and this is what I have been able to compared between the above two requests: https://gist.github.com/imechemi/2acaae96bb114e0a716929b70d4e7ea5. I can't really pin point a thing in there for why one of the request failed with 404.

[Daniel Knoppel]

The log shows:

> Processing 157 bytes of application data: "HTTP/1.1 404 Whatever...."

That means the 404 is being sent by your application to Passenger, so you should look at the application to discover why it is sending a 404.

The log is very short, right now it just looks like the app is denying 10.190.115.27 and allowing 10.190.115.28. It's also not clear why you need to restart anything, because after the 404 you still get a 200 again. Either way it doesn't look like a Passenger issue, but you could try with the latest Passenger version (5.1.5).

- Daniel

[Chemi]

>It's also not clear why you need to restart anything, because after the 404 you still get a 200 again.

I get 404 from both the IP address and it continuously throws 404 in between 200's. It doesn't stop once it starts throwing 404. And to recover, restart was needed.

>The log is very short, right now it just looks like the app is denying 10.190.115.27 and allowing 10.190.115.28

We get 200 for both of them right now, but when the issue starts, it's throws 404 and 200 from both the IPs intermittently.

This is our the rails server log (https://gist.github.com/imechemi/04a8d90cdf1083a2e1219210f985284e). The log shows 404 with 200's in between. 

Here are some General information about the system:

     Max pool size : 18

     App groups    : 1

     Processes     : 18

     RAM: 4 Gigs

     CPUs: 6

I doubt if we are running out of memory on the node, do you have any suggestion on debugging and investigating? I haven't tried passenger 5.1.5 yet, but I will soon test this. 

Thanks

- Chemi

[Daniel Knoppel]

Did you see the ActionController::RoutingError errors (FATAL) in your rails log right before every 404?

- Daniel

[Chemi]

Yes I have noticed that before, and i couldn't understand why it would throw error for only few of them when they are of same kind of request