Server responding with 404 to all requests

[fugee ohu]

My rails nginx/passenger server is responding with 404 to all requests Location block includes passenger_enable=on

[Daniel Knoppel]

Can you post information on your setup? Config file etc.? 

- Daniel

[Matt M]

Hi Daniel, 

I'm experiencing the same thing with my Grape/Sinatra Rack app. The logs work fine without passenger standalone but once I tried to implement SSL all requests appear as a 404's in the logs. These 404's happen even happen on successful requests. I setup a test endpoint that returns a simple JSON object {'test':123}, when I curl the route I get a 200 and the object but the logs show a 404.

I'm currently running Rack::Cascade to run Grape and Sinatra concurrently with Passenger  gem (5.0.24). Below is config.ru :

require './app'

require 'rack/cors'

require 'rack/session/abstract/id'

set :root, File.dirname(__FILE__)

use Rack::Cors do

  allow do

    origins '*'

    resource '*', :headers => :any, :methods => [:get, :post, :options, :put],

    :expose => ['Access-Header']

  end

end

run Rack::Cascade.new [App, API::Base]

And here is the start command I'm using (for simplicity I took out the ssl configuration options, still run into the same issues):

bundle exec passenger start ./ --port 9294 --rackup config.ru

[Daniel Knoppel]

Matt, it's better not to tag onto others' threads, 404 can be due to many different causes.

I don't understand what you mean by a 404 if you get a 200 and the expected result. Can you set the --log-level to 7 and post the logfile, what url(s) you tried, what result you expected, what you got, etc.?

- Daniel

[Matt M]

Daniel,

Sorry for hijacking the thread, I'll be sure to create a separate one next time.

I've set up a test grape endpoint /api/v1/voice/test that is supposed to return a simple JSON object {"test":"123"}. When I hit that endpoint using curl I get the object back and an http 200 status code:

* Adding handle: conn: 0x7fc040804400

 

* Adding handle: send: 0

* Adding handle: recv: 0

* Curl_addHandleToPipeline: length: 1

* - Conn 0 (0x7fc040804400) send_pipe: 1, recv_pipe: 0

* About to connect() to matt.proctorcam.com port 9443 (#0)  

* Connected to matt.proctorcam.com  port 9443 (#0)

* TLS 1.2 connection using TLS_ECDHE_RSA_WITH_AES_256_CBC_SHA384

* Server certificate: *.proctorcam.com

* Server certificate: Go Daddy Secure Certificate Authority - G2

* Server certificate: Go Daddy Root Certificate Authority - G2

> GET /api/v1/voice/test HTTP/1.1

> User-Agent: curl/7.30.0

> Host: matt.proctorcam.com:9443

> Accept: */*

>  

< HTTP/1.1 200 OK

< Content-Type: text/plain

< Content-Length: 14

< Connection: keep-alive

< Status: 200 OK

< Vary: Origin

< Date: Wed, 03 Feb 2016 14:37:51 GMT

< X-Powered-By: Phusion Passenger 5.0.24

* Server nginx/1.8.1 + Phusion Passenger 5.0.24 is not blacklisted

< Server: nginx/1.8.1 + Phusion Passenger 5.0.24

<  

* Connection #0 to host matt.proctorcam.com left intact

{"test":"123"}

The passenger logs (standalone) show this successful request as a 404, below are the logs with level set to 7

[ 2016-02-03 09:37:49.0001 69/7f9d82795700 age/Cor/App/Poo/AnalyticsCollection.cpp:160 ]: Analytics collection time...
[ 2016-02-03 09:37:49.0002 69/7f9d82795700 age/Cor/App/Poo/AnalyticsCollection.cpp:187 ]: Collecting process metrics
[ 2016-02-03 09:37:49.0003 69/7f9d82795700 Utils.cpp:1040 ]: File descriptor opened: 39
[ 2016-02-03 09:37:49.0003 69/7f9d82795700 Utils.cpp:1040 ]: File descriptor opened: 43
[ 2016-02-03 09:37:49.0007 69/7f9d82795700 FileDescriptor.h:94 ]: File descriptor closed: 43
[ 2016-02-03 09:37:49.0055 69/7f9d82795700 FileDescriptor.h:94 ]: File descriptor closed: 39
[ 2016-02-03 09:37:49.0057 69/7f9d82795700 Uti/ScopeGuard.h:114 ]: File descriptor closed: 39
[ 2016-02-03 09:37:49.0058 69/7f9d82795700 age/Cor/App/Poo/AnalyticsCollection.cpp:195 ]: Collecting system metrics
[ 2016-02-03 09:37:49.0058 69/7f9d82795700 Uti/ScopeGuard.h:114 ]: File descriptor closed: 39
[ 2016-02-03 09:37:49.0060 69/7f9d82795700 Uti/ScopeGuard.h:114 ]: File descriptor closed: 39
[ 2016-02-03 09:37:49.0061 69/7f9d82795700 Uti/ScopeGuard.h:114 ]: File descriptor closed: 39
[ 2016-02-03 09:37:49.0064 69/7f9d82795700 age/Cor/App/Poo/AnalyticsCollection.cpp:72 ]: Analytics collection done; next analytics collection in 4.994 sec
[ 2016-02-03 09:37:51.2796 69/7f9d7a7fc700 Ser/AcceptLoadBalancer.h:194 ]: File descriptor opened: 39
[ 2016-02-03 09:37:51.2796 69/7f9d7a7fc700 Ser/AcceptLoadBalancer.h:136 ]: Accepted client file descriptor: 39
[ 2016-02-03 09:37:51.2797 69/7f9d7a7fc700 Ser/AcceptLoadBalancer.h:194 ]: File descriptor opened: -1
[ 2016-02-03 09:37:51.2797 69/7f9d7a7fc700 Ser/AcceptLoadBalancer.h:164 ]: Feeding client to server thread 0: file descriptor 39
[ 2016-02-03 09:37:51.2798 69/7f9d7bfff700 age/Cor/Con/TurboCaching.h:245 ]: Clearing turbocache
[ 2016-02-03 09:37:51.2798 69/7f9d7bfff700 Ser/Server.h:353 ]: [ServerThr.1] Checking out client object from freelist (128 -> 127)
[ 2016-02-03 09:37:51.2798 69/7f9d7bfff700 Ser/Server.h:576 ]: [Client 1-2] Client associated with file descriptor: 39
[ 2016-02-03 09:37:51.2798 69/7f9d7bfff700 Ser/Server.h:733 ]: File descriptor purpose: 39: Server ServerThr.1, client 1-2
[ 2016-02-03 09:37:51.2798 69/7f9d7bfff700 Ser/Server.h:737 ]: [ServerThr.1] 1 new client(s) accepted; there are now 1 active client(s)
[ 2016-02-03 09:37:51.2799 69/7f9d7bfff700 Ser/HttpServer.h:669 ]: [Client 1-2] Event: onClientAccepted
[ 2016-02-03 09:37:51.2799 69/7f9d7bfff700 Ser/HttpServer.h:236 ]: [Client 1-2] Refcount increased; it is now 3
[ 2016-02-03 09:37:51.2799 69/7f9d7bfff700 Ser/FileBufferedChannel.h:1450 ]: [FBC 0x134bed0] Deinitialize
[ 2016-02-03 09:37:51.2799 69/7f9d7bfff700 Ser/HttpServer.h:120 ]: [ServerThr.1] Checking out request object from freelist (1 -> 0)
[ 2016-02-03 09:37:51.2799 69/7f9d7bfff700 Ser/Server.h:529 ]: [Client 1-2] Refcount decreased; it is now 2
[ 2016-02-03 09:37:51.2800 69/7f9d7bfff700 Ser/FdSourceChannel.h:55 ]: [Client 1-2] Refcount increased; it is now 3
[ 2016-02-03 09:37:51.2800 69/7f9d7bfff700 Ser/Server.h:453 ]: [Client 1-2] Processing 464 bytes of client data
[ 2016-02-03 09:37:51.2800 69/7f9d7bfff700 Ser/HttpServer.h:677 ]: [Client 1-2] Event: onClientDataReceived
[ 2016-02-03 09:37:51.2800 69/7f9d7bfff700 Ser/HttpServer.h:680 ]: [Client 1-2] Request refcount increased; it is now 2
[ 2016-02-03 09:37:51.2800 69/7f9d7bfff700 Ser/HttpServer.h:257 ]: [Client 1-2] Parsing 464 bytes of HTTP header: "GET /api/v1/voice/test HTTP/1.1\r\nConnection: close\r\nUser-Agent: curl/7.30.0\r\nHost: matt.proctorcam.com:9443\r\nAccept: */*\r\n!~: Jru6eym5IYRtkxCr66Ls570R\r\n!~DOCUMENT_ROOT: /usr/src/app/public\r\n!~REMOTE_ADDR: 12.119.202.166\r\n!~REMOTE_PORT: 21306\r\n!~PASSENGER_APP_GROUP_NAME: /usr/src/app/public (development)\r\n!~PASSENGER_APP_TYPE: rack\r\n!~PASSENGER_APP_ENV: development\r\n!~PASSENGER_USER: root\r\n!~PASSENGER_APP_ROOT: /usr/src/app\r\n!~PASSENGER_SPAWN_METHOD: smart\r\n!~P"
[ 2016-02-03 09:37:51.2801 69/7f9d7bfff700 Ser/HttpServer.h:680 ]: [Client 1-2] Request refcount decreased; it is now 1
[ 2016-02-03 09:37:51.2801 69/7f9d7bfff700 Ser/Server.h:480 ]: [Client 1-2] 464 bytes of client data consumed in this callback
[ 2016-02-03 09:37:51.2801 69/7f9d7bfff700 Ser/FdSourceChannel.h:55 ]: [Client 1-2] Refcount decreased; it is now 2
[ 2016-02-03 09:37:51.2801 69/7f9d7bfff700 Ser/FdSourceChannel.h:55 ]: [Client 1-2] Refcount increased; it is now 3
[ 2016-02-03 09:37:51.2802 69/7f9d7bfff700 Ser/Server.h:453 ]: [Client 1-2] Processing 98 bytes of client data
[ 2016-02-03 09:37:51.2802 69/7f9d7bfff700 Ser/HttpServer.h:677 ]: [Client 1-2] Event: onClientDataReceived
[ 2016-02-03 09:37:51.2802 69/7f9d7bfff700 Ser/HttpServer.h:680 ]: [Client 1-2] Request refcount increased; it is now 2
[ 2016-02-03 09:37:51.2802 69/7f9d7bfff700 Ser/HttpServer.h:257 ]: [Client 1-2] Parsing 98 bytes of HTTP header: "ASSENGER_LOAD_SHELL_ENVVARS: f\r\n!~PASSENGER_STARTUP_FILE: /usr/src/app/config.ru\r\n!~FLAGS: DCS\r\n\r\n"
[ 2016-02-03 09:37:51.2802 69/7f9d7bfff700 Ser/HttpServer.h:268 ]: [Client 1-2] New request received: #2
[ 2016-02-03 09:37:51.2802 69/7f9d7bfff700 age/Cor/Con/InitRequest.cpp:492 ]: [Client 1-2] Initiating request
[ 2016-02-03 09:37:51.2803 69/7f9d7bfff700 age/Cor/Con/InitRequest.cpp:87 ]: [Client 1-2] Dechunk flag detected
[ 2016-02-03 09:37:51.2803 69/7f9d7bfff700 age/Cor/Con/InitRequest.cpp:93 ]: [Client 1-2] HTTPS flag detected
[ 2016-02-03 09:37:51.2803 69/7f9d7bfff700 age/Cor/Con/InitRequest.cpp:96 ]: [Client 1-2] Stripping 100 Continue header
[ 2016-02-03 09:37:51.2803 69/7f9d7bfff700 age/Cor/Con/InitRequest.cpp:109 ]: [Client 1-2] Turbocaching: trying to reply from cache (key "Smatt.proctorcam.com:9443\n/api/v1/voice/test")
[ 2016-02-03 09:37:51.2803 69/7f9d7bfff700 age/Cor/Con/InitRequest.cpp:110 ]: [Client 1-2] Turbocache entries:
 #0: valid=0, hash=0, expiryDate=0, keySize=0, key=""
 #1: valid=0, hash=0, expiryDate=0, keySize=0, key=""
 #2: valid=0, hash=0, expiryDate=0, keySize=0, key=""
 #3: valid=0, hash=0, expiryDate=0, keySize=0, key=""
 #4: valid=0, hash=0, expiryDate=0, keySize=0, key=""
 #5: valid=0, hash=0, expiryDate=0, keySize=0, key=""
 #6: valid=0, hash=0, expiryDate=0, keySize=0, key=""
 #7: valid=0, hash=0, expiryDate=0, keySize=0, key=""


[ 2016-02-03 09:37:51.2803 69/7f9d7bfff700 age/Cor/Con/InitRequest.cpp:126 ]: [Client 1-2] Turbocaching: cache miss: NOT_FOUND (key "Smatt.proctorcam.com:9443\n/api/v1/voice/test")
[ 2016-02-03 09:37:51.2804 69/7f9d7bfff700 age/Cor/Con/CheckoutSession.cpp:55 ]: [Client 1-2] Checking out session: appRoot=/usr/src/app
[ 2016-02-03 09:37:51.2804 69/7f9d7bfff700 age/Cor/Con/CheckoutSession.cpp:69 ]: [Client 1-2] Request refcount increased; it is now 3
[ 2016-02-03 09:37:51.2804 69/7f9d7bfff700 age/Cor/App/Poo/Miscellaneous.cpp:49 ]: asyncGet(appGroupName=/usr/src/app/public (development))
[ 2016-02-03 09:37:51.2804 69/7f9d7bfff700 age/Cor/App/Poo/Miscellaneous.cpp:82 ]: Found existing Group
[ 2016-02-03 09:37:51.2805 69/7f9d7bfff700 age/Cor/App/Gro/SessionManagement.cpp:330 ]: Session checked out from process (pid=127, group=/usr/src/app/public (development))
[ 2016-02-03 09:37:51.2805 69/7f9d7bfff700 age/Cor/App/Poo/Miscellaneous.cpp:87 ]: asyncGet() finished
[ 2016-02-03 09:37:51.2805 69/7f9d7bfff700 age/Cor/Con/CheckoutSession.cpp:133 ]: [Client 1-2] Session checked out: pid=127, gupid=171e6aa-zTIMEaJ312
[ 2016-02-03 09:37:51.2805 69/7f9d7bfff700 age/Cor/App/Socket.h:90 ]: Connecting to unix:/tmp/passenger.EgkGI59/apps.s/ruby.4DblXcwlwT969W5EvvCtVhXhd8rXhYGgS1vxAKu8kmcZcF1Tg2cwWaUNd4bct9S
[ 2016-02-03 09:37:51.2805 69/7f9d7bfff700 age/Cor/App/Socket.h:91 ]: File descriptor opened: 43
[ 2016-02-03 09:37:51.2806 69/7f9d7bfff700 age/Cor/App/Socket.h:95 ]: File descriptor purpose: 43: App 127 connection
[ 2016-02-03 09:37:51.2806 69/7f9d7bfff700 age/Cor/App/Socket.h:177 ]: Socket unix:/tmp/passenger.EgkGI59/apps.s/ruby.4DblXcwlwT969W5EvvCtVhXhd8rXhYGgS1vxAKu8kmcZcF1Tg2cwWaUNd4bct9S: there are now 1 total connections
[ 2016-02-03 09:37:51.2806 69/7f9d7bfff700 age/Cor/Con/CheckoutSession.cpp:201 ]: [Client 1-2] Session initiated: fd=43
[ 2016-02-03 09:37:51.2806 69/7f9d7bfff700 age/Cor/Con/SendRequest.cpp:90 ]: [Client 1-2] Sending headers to application with session protocol
[ 2016-02-03 09:37:51.2806 69/7f9d7bfff700 age/Cor/Con/SendRequest.cpp:160 ]: [Client 1-2] Header data: "\000\000\001\232REQUEST_URI\000/api/v1/voice/test\000PATH_INFO\000/api/v1/voice/test\000SCRIPT_NAME\000\000QUERY_STRING\000\000REQUEST_METHOD\000GET\000SERVER_NAME\000matt.proctorcam.com\000SERVER_PORT\0009443\000SERVER_SOFTWARE\000nginx/1.8.1 Phusion_Passenger/5.0.24\000SERVER_PROTOCOL\000HTTP/1.1\000REMOTE_ADDR\00012.119.202.166\000REMOTE_PORT\00021306\000PASSENGER_CONNECT_PASSWORD\000S3kjHepAZZntnS12\000HTTPS\000on\000HTTP_USER_AGENT\000curl/7.30.0\000HTTP_ACCEPT\000*/*\000HTTP_HOST\000matt.proctorcam.com:9443\000"
[ 2016-02-03 09:37:51.2807 69/7f9d7bfff700 age/Cor/Con/SendRequest.cpp:945 ]: [Client 1-2] No body to send to application
[ 2016-02-03 09:37:51.2807 69/7f9d7bfff700 age/Cor/Con/CheckoutSession.cpp:94 ]: [Client 1-2] Request refcount decreased; it is now 2
[ 2016-02-03 09:37:51.2807 69/7f9d7bfff700 Ser/HttpServer.h:680 ]: [Client 1-2] Request refcount decreased; it is now 1
[ 2016-02-03 09:37:51.2807 69/7f9d7bfff700 Ser/Server.h:480 ]: [Client 1-2] 98 bytes of client data consumed in this callback
[ 2016-02-03 09:37:51.2807 69/7f9d7bfff700 Ser/FdSourceChannel.h:55 ]: [Client 1-2] Refcount decreased; it is now 2
App 108 stderr: [ 2016-02-03 09:37:51.2809 127/0x007f12f2688d58(Worker 1) request_handler/thread_handler.rb:142 ]: Accepted new request on socket main socket
App 108 stderr: 12.119.202.166 - - [03/Feb/2016:09:37:51 -0500] "GET /api/v1/voice/test HTTP/1.1" 404 547 0.0008
App 127 stdout:
App 127 stdout:
App 127 stdout: IN THE TEST
App 127 stdout:
App 108 stderr: [ 2016-02-03 09:37:51.2836 127/0x007f12f2688d58(Worker 1) request_handler/thread_handler.rb:172 ]: Request done.
[ 2016-02-03 09:37:51.2837 69/7f9d7bfff700 Ser/FdSourceChannel.h:55 ]: [Client 1-2] Request refcount increased; it is now 2
[ 2016-02-03 09:37:51.2837 69/7f9d7bfff700 age/Cor/Con/ForwardResponse.cpp:64 ]: [Client 1-2] Event: onAppSourceData
[ 2016-02-03 09:37:51.2837 69/7f9d7bfff700 age/Cor/Con/ForwardResponse.cpp:75 ]: [Client 1-2] Processing 118 bytes of application data: "HTTP/1.1 200 Whatever\r\nContent-Type: text/plain\r\nContent-Length: 14\r\nVary: Origin\r\nConnection: close\r\n\r\n{"test":"123"}"
[ 2016-02-03 09:37:51.2838 69/7f9d7bfff700 age/Cor/Con/ForwardResponse.cpp:87 ]: [Client 1-2] Application response headers received
[ 2016-02-03 09:37:51.2838 69/7f9d7bfff700 age/Cor/Con/ForwardResponse.cpp:97 ]: [Client 1-2] Expecting an app response body with fixed length
[ 2016-02-03 09:37:51.2838 69/7f9d7bfff700 age/Cor/Con/ForwardResponse.cpp:403 ]: [Client 1-2] Turbocache: preparing response caching
[ 2016-02-03 09:37:51.2838 69/7f9d7bfff700 age/Cor/Con/ForwardResponse.cpp:423 ]: [Client 1-2] Turbocache: response not eligible for turbocaching
[ 2016-02-03 09:37:51.2838 69/7f9d7bfff700 age/Cor/Con/ForwardResponse.cpp:824 ]: [Client 1-2] Sending response headers using writev()
[ 2016-02-03 09:37:51.2839 69/7f9d7bfff700 age/Cor/Con/ForwardResponse.cpp:887 ]: [Client 1-2] Sending response headers: "HTTP/1.1 200 OK\r\nStatus: 200 OK\r\nVary: Origin\r\nContent-Type: text/plain\r\nDate: Wed, 03 Feb 2016 14:37:51 GMT\r\nContent-Length: 14\r\nConnection: close\r\nX-Powered-By: Phusion Passenger 5.0.24\r\n\r\n"

This behavior is happening for all request not just the test route I've set up.

Let me know if you need anything else

Thanks

[Daniel Knoppel]

Thanks for the logs. But in your output it says you are starting passenger on port 9294, but instead connecting to 9443 (that can't be right)? Can you write exactly what you are doing?

- Daniel

[Matt M]

I seemed to have posted my logs while I had SSL configured, here is my passenger startup command: 

bundle exec passenger start --ssl --ssl-certificate /etc/ssl/certs/cert.crt --ssl-certificate-key /etc/ssl/private/key.key --ssl-port 9443 --rackup config.ru

I'm running passenger inside of a docker container.

...

[Daniel Knoppel]

Hmm, well we also run Passenger in docker, so that shouldn't be too special, although it's a little harder to debug. The exec also looks good.

One other thing I noticed is that the 404 comes from "App 108", while the app you've received and pasted the 200 from is "App 127". You've truncated the logs so I can't see where these came from and what they are supposed to be. You should probably check what the app process is behind the 404'ing app (apparently it's something that doesn't implement your endpoint). passenger-memory-status can help with that as well.

- Daniel

...

[Matt M]

Daniel,

I was looking at https://www.phusionpassenger.com/library/config/nginx/reference/ and couldn't find anything about 'passenger-memory-status', can you explain what you meant?

I've attached a set of logs that haven't been truncated

Thanks for the help!

[Daniel Knoppel]

'passenger-memory-status' is just a command to see what Passenger-related processes are running.

It looks like your app is returning a 404 to Passenger initially, but then starts working later on. What happens if you set the max-pool-size to 1 and min-instances also to 1, and then wait for a little bit (like 20 seconds) after starting passenger, and then curl to the app a few times?

- Daniel

...

[Hongli Lai]

It's actually 'passenger-memory-stats' (not '-status').

> --
> You received this message because you are subscribed to the Google Groups
> "Phusion Passenger Discussions" group.
> To unsubscribe from this group and stop receiving emails from it, send an
> email to phusion-passen...@googlegroups.com.
> To post to this group, send email to phusion-...@googlegroups.com.
> Visit this group at https://groups.google.com/group/phusion-passenger.
> To view this discussion on the web visit
> https://groups.google.com/d/msgid/phusion-passenger/2b4224b5-c680-4b11-88d4-0196ed7db61e%40googlegroups.com.
>
> For more options, visit https://groups.google.com/d/optout.



--
Phusion B.V. | Web Application deployment, scaling, and monitoring solutions

Web: http://www.phusion.nl/
E-mail: in...@phusion.nl
Chamber of commerce no: 63501007 (The Netherlands)

[Matt M]

Ok, I was able to run passenger-memory-stats with your updated setting requests (max-pool and min instances to 1):

------------- Apache processes -------------

*** WARNING: The Apache executable cannot be found.

Please set the APXS2 environment variable to your 'apxs2' executable's filename, or set the HTTPD environment variable to your 'httpd' or 'apache2' executable's filename.

-------- Nginx processes --------

### Processes: 0

### Total private dirty RSS: 0.00 MB

---- Passenger processes ----

PID  VMSize    Private  Name

-----------------------------

64   363.9 MB  ?        Passenger watchdog

67   910.6 MB  ?        Passenger core

72   372.1 MB  ?        Passenger ust-router

106  137.5 MB  ?        Passenger AppPreloader: /usr/src/app

125  271.5 MB  ?        Passenger RubyApp: /usr/src/app/public (development)

### Processes: 5

### Total private dirty RSS: 0.00 MB (?)

I've attached the logs with multiple curls to the test endpoint below, nothing looks to be standing out from the logs I uploaded before.

Thanks again

...

[Daniel Knoppel]

Everything looks good from the Passenger side, still.

I re-read the thread and realized I hadn't absorbed your remark about using Rack::Cascade. The output suggests that you've put a logger in the wrong place such that it's logging the intermediate steps in the cascade rather than just the final step.

- Daniel

...