Akward delay to connect Apache's proxy request to a node.js App

In my Ubuntu Server 10.04 I'm running an example node.js app:

var http = require("http");

function onRequest(request, response) {

        console.log("Request received.");
        response.writeHead(200, {"Content-Type": "text/html"});
        response.write("Hello World");
        response.end();

}

http.createServer(onRequest).listen(3000);

It simply listens to requests on port 3000, log in console this request and send to the client an HTTP "Hello World"

The goal was to make this app coexists with Apache2. So after some research I edited the default file (/etc/apache2/sites-available/default) this way:

<VirtualHost *:80>
        ServerAdmin [email protected]
        ServerName dev.myserver.com

        <Location /node>

                ProxyPassReverse http://127.0.0.1:3000/
                ProxyPass http://127.0.0.1:3000/

        </Location>

        <Proxy>
                Allow from all
        </Proxy>

        DocumentRoot /home/haj/www/http_home

        <Directory />
                Options FollowSymLinks
                AllowOverride None
        </Directory>

        <Directory /home/haj/www/http_home/>
                Options Indexes FollowSymLinks MultiViews
                AllowOverride None
                Order allow,deny
                allow from all
        </Directory>

        ErrorLog /home/haj/www/log/error.log

        # Possible values include: debug, info, notice, warn, error, crit,
        # alert, emerg.
        LogLevel warn

        CustomLog /home/haj/www/log/access.log combined


</VirtualHost>

So, when a user makes a call to http://dev.myserver.com/node or http://dev.myserver.com/node/, Apache proxies the request, Node.js makes the processing, and the user gets back a "Hello World".

There is just one problem: It takes some time to, Let's call it 'Load' the Proxy, in other words, I get these messages at the browser:

<503 Service Temporarily Unavailable>

Service Temporarily Unavailable

The server is temporarily unable to service your request due to maintenance downtime or capacity problems. Please try again later.

Apache/2.2.14 (Ubuntu) Server at dev.neosource.cl Port 80

Besides, error.log tells me:

[Thu Apr 21 01:02:10 2011] [error] proxy: HTTP: disabled connection for (127.0.0.1)
[Thu Apr 21 01:02:10 2011] [error] proxy: HTTP: disabled connection for (127.0.0.1)
[Thu Apr 21 01:02:10 2011] [error] proxy: HTTP: disabled connection for (127.0.0.1)

Then suddenly, It Works, just like that. No number of requests, no time, no pattern at all.

In layman's terms, the service has to 'load', That's the impression it gives, but, I would like to know if there is a way to minimize this delay. Or I would rather know What is wrong with the configuration noted above.

Edit 1: After modifying LogLevel to debug, during one of these delays I get this per request:

[Thu Apr 21 02:30:40 2011] [debug] mod_proxy_http.c(56): proxy: HTTP: canonicalising URL //127.0.0.1:3000/
[Thu Apr 21 02:30:40 2011] [debug] proxy_util.c(1494): [client 200.xxx.yyy.zzz] proxy: http: found worker http://127.0.0.1:3000/ for http://127.0.0.1:3000/
[Thu Apr 21 02:30:40 2011] [debug] mod_proxy.c(993): Running scheme http handler (attempt 0)
[Thu Apr 21 02:30:40 2011] [debug] mod_proxy_http.c(1940): proxy: HTTP: serving URL http://127.0.0.1:3000/
[Thu Apr 21 02:30:40 2011] [debug] proxy_util.c(1937): proxy: HTTP: retrying the worker for (127.0.0.1)
[Thu Apr 21 02:30:40 2011] [error] proxy: HTTP: disabled connection for (127.0.0.1)
[Thu Apr 21 02:30:40 2011] [debug] mod_deflate.c(615): [client 200.xxx.yyy.zzz] Zlib: Compressed 405 to 273 : URL /node

...and when it is right again:

[Thu Apr 21 02:35:16 2011] [debug] mod_proxy_http.c(56): proxy: HTTP: canonicalising URL //127.0.0.1:3000/
[Thu Apr 21 02:35:16 2011] [debug] proxy_util.c(1494): [client 200.xxx.yyy.zzz] proxy: http: found worker http://127.0.0.1:3000/ for http://127.0.0.1:3000/
[Thu Apr 21 02:35:16 2011] [debug] mod_proxy.c(993): Running scheme http handler (attempt 0)
[Thu Apr 21 02:35:16 2011] [debug] mod_proxy_http.c(1940): proxy: HTTP: serving URL http://127.0.0.1:3000/
[Thu Apr 21 02:35:16 2011] [debug] proxy_util.c(1999): proxy: HTTP: has acquired connection for (127.0.0.1)
[Thu Apr 21 02:35:16 2011] [debug] proxy_util.c(2055): proxy: connecting http://127.0.0.1:3000/ to 127.0.0.1:3000
[Thu Apr 21 02:35:16 2011] [debug] proxy_util.c(2153): proxy: connected / to 127.0.0.1:3000
[Thu Apr 21 02:35:16 2011] [debug] proxy_util.c(2244): proxy: HTTP: backend socket is disconnected.
[Thu Apr 21 02:35:16 2011] [debug] proxy_util.c(2308): proxy: HTTP: fam 2 socket created to connect to 127.0.0.1
[Thu Apr 21 02:35:16 2011] [debug] proxy_util.c(2414): proxy: HTTP: connection complete to 127.0.0.1:3000 (127.0.0.1)
[Thu Apr 21 02:35:16 2011] [debug] mod_proxy_http.c(1723): proxy: start body send
[Thu Apr 21 02:35:16 2011] [debug] mod_deflate.c(615): [client 200.xxx.yyy.zzz] Zlib: Compressed 11 to 13 : URL /node
[Thu Apr 21 02:35:16 2011] [debug] mod_proxy_http.c(1816): proxy: end body send
[Thu Apr 21 02:35:16 2011] [debug] proxy_util.c(2017): proxy: HTTP: has released connection for (127.0.0.1)

Changing LogLevel to debug will give you more information in error.log. Please do so and post the results. Without that information, I have a guess that changing your ProxyPass line to ProxyPass http://127.0.0.1:3000/ retry=0 might help. In general, the Apache mod_proxy documentation has more details on the parameters available to you.

Digging this up. I had this issue on CentOS with SELinux enable. All I needed to do is to allow httpd to make network connections:

/usr/sbin/setsebool httpd_can_network_connect 1

(and restart httpd)

Akward delay to connect Apache's proxy request to a node.js App

Related

Recent Posts