Take the 2-minute tour ×
Server Fault is a question and answer site for system and network administrators. It's 100% free, no registration required.

Been stuck with this one for a few days. Will try to provide as much information as possible, but please feel free to ask for extra detail.

I have 2 VMs behind a NAT, 192.168.0.100 and 192.168.0.102, both running Ubuntu 11.04 x64. The first one is mapped to the exterior and is our webserver, has one Apache/2.2.17 install with several vhosts to serve static content, and there's also mod_jk for load balancing. The second one has a tomcat 7 install with several J2EE REST webservices but no apache - requests are expected to be passed directly from .100 apache to .102 tomcat. It is my intention to prepare a tomcat clustered environment.

My problem: Requests reach to 192.168.0.100 with no trouble whatsoever, but then take about... 100 seconds for data to actually arrive to .102 - by that time apache has already timeouted, but tomcat receives and processes the request pretty normally. This happens both when using mod_jk, mod_proxy, or mod_ajp_proxy. No idea why, since there are no firewalls in either of the machines, both are pingable - more than that, there are NFS shares active working like a charm - and a mod_proxy experience shown that requests originating directly from .100 are processed normally.

Also, to add insult to injury, a similar environment is set up at our office network. Everything works perfectly. -_- The only difference? We have no ip translation at the office and do everything by internal addresses - dunno if that's relevant in any way.

Some configs:

Apache vhost:

<VirtualHost *:80>
    ServerAdmin webmaster@localhost
    DocumentRoot /var/www/
    ServerName www.example.com

    ProxyRequests Off
    <Proxy *>
            Options Indexes FollowSymLinks MultiViews
            AllowOverride all
            Order allow,deny
            allow from all
    </Proxy>

    ProxyPass /bork http://192.168.0.102:8080/bork
    ProxyPassReverse /bork http://192.168.0.102:8080/bork
    LogLevel debug

    CustomLog ${APACHE_LOG_DIR}/api_access.log combined
    ErrorLog ${APACHE_LOG_DIR}/api_error.log
</VirtualHost>

Tomcat connectors

<Connector port="8080" protocol="HTTP/1.1"
           connectionTimeout="20000"
           redirectPort="8443" />
<Connector port="8009"
    enableLookups="false"
    redirectPort="8443"
    protocol="AJP/1.3"
/>

And a debug log from apache, from a test using mod_proxy_ajp. The behavior is pretty much the same in mod_proxy, at least regarding the delay. Please note that tomcat eventually receives and processes the request, more or less when the log starts being updated again:

[Sun May 06 14:40:33 2012] [debug] proxy_util.c(1506): [client 188.81.234.2] proxy: ajp: found worker ajp://192.168.0.102:8008/bork for ajp://192.168.0.102:8008/bork/SSOIdentityProviderSoap
[Sun May 06 14:40:33 2012] [debug] mod_proxy.c(1015): Running scheme ajp handler (attempt 0)
[Sun May 06 14:40:33 2012] [debug] mod_proxy_ajp.c(661): proxy: AJP: serving URL ajp://192.168.0.102:8008/bork/SSOIdentityProviderSoap
[Sun May 06 14:40:33 2012] [debug] proxy_util.c(2011): proxy: AJP: has acquired connection for (192.168.0.102)
[Sun May 06 14:40:33 2012] [debug] proxy_util.c(2067): proxy: connecting ajp://192.168.0.102:8008/bork/SSOIdentityProviderSoap to 192.168.0.102:8008
[Sun May 06 14:40:33 2012] [debug] proxy_util.c(2193): proxy: connected /bork/SSOIdentityProviderSoap to 192.168.0.102:8008
[Sun May 06 14:40:33 2012] [debug] proxy_util.c(2444): proxy: AJP: fam 2 socket created to connect to 192.168.0.102
[Sun May 06 14:40:33 2012] [debug] ajp_header.c(224): Into ajp_marshal_into_msgb
[Sun May 06 14:40:33 2012] [debug] ajp_header.c(290): ajp_marshal_into_msgb: Header[0] [Accept-Encoding] = [gzip,deflate]
[Sun May 06 14:40:33 2012] [debug] ajp_header.c(290): ajp_marshal_into_msgb: Header[1] [Content-Type] = [text/xml;charset=UTF-8]
[Sun May 06 14:40:33 2012] [debug] ajp_header.c(290): ajp_marshal_into_msgb: Header[2] [SOAPAction] = [""]
[Sun May 06 14:40:33 2012] [debug] ajp_header.c(290): ajp_marshal_into_msgb: Header[3] [User-Agent] = [Jakarta Commons-HttpClient/3.1]
[Sun May 06 14:40:33 2012] [debug] ajp_header.c(290): ajp_marshal_into_msgb: Header[4] [Host] = [www.example.com]
[Sun May 06 14:40:33 2012] [debug] ajp_header.c(290): ajp_marshal_into_msgb: Header[5] [Content-Length] = [520]
[Sun May 06 14:40:33 2012] [debug] ajp_header.c(450): ajp_marshal_into_msgb: Done
[Sun May 06 14:40:33 2012] [debug] mod_proxy_ajp.c(267): proxy: APR_BUCKET_IS_EOS
[Sun May 06 14:40:33 2012] [debug] mod_proxy_ajp.c(272): proxy: data to read (max 8186 at 4)
[Sun May 06 14:40:33 2012] [debug] mod_proxy_ajp.c(287): proxy: got 520 bytes of data
[Sun May 06 14:40:33 2012] [debug] ajp_header.c(687): ajp_read_header: ajp_ilink_received 06
[Sun May 06 14:40:33 2012] [debug] ajp_header.c(697): ajp_parse_type: got 06
[Sun May 06 14:40:37 2012] [debug] proxy_util.c(1818): proxy: grabbed scoreboard slot 2 in child 5916 for worker ajp://192.168.0.100:8008/coding
[Sun May 06 14:40:37 2012] [debug] proxy_util.c(1837): proxy: worker ajp://192.168.0.100:8008/coding already initialized
[Sun May 06 14:40:37 2012] [debug] proxy_util.c(1934): proxy: initialized single connection worker 2 in child 5916 for (192.168.0.100)
[Sun May 06 14:40:37 2012] [debug] proxy_util.c(1818): proxy: grabbed scoreboard slot 3 in child 5916 for worker http://192.168.0.102:8080
[Sun May 06 14:40:37 2012] [debug] proxy_util.c(1837): proxy: worker http://192.168.0.102:8080 already initialized
[Sun May 06 14:40:37 2012] [debug] proxy_util.c(1934): proxy: initialized single connection worker 3 in child 5916 for (192.168.0.102)
[Sun May 06 14:40:37 2012] [debug] proxy_util.c(1818): proxy: grabbed scoreboard slot 4 in child 5916 for worker ajp://192.168.0.102:8008/bork
[Sun May 06 14:40:37 2012] [debug] proxy_util.c(1837): proxy: worker ajp://192.168.0.102:8008/bork already initialized
[Sun May 06 14:40:37 2012] [debug] proxy_util.c(1934): proxy: initialized single connection worker 4 in child 5916 for (192.168.0.102)
[Sun May 06 14:40:38 2012] [debug] proxy_util.c(1934): proxy: initialized single connection worker 2 in child 5918 for (192.168.0.100)
[Sun May 06 14:40:38 2012] [debug] proxy_util.c(1818): proxy: grabbed scoreboard slot 3 in child 5918 for worker http://192.168.0.102:8080
[Sun May 06 14:40:38 2012] [debug] proxy_util.c(1837): proxy: worker http://192.168.0.102:8080 already initialized
[Sun May 06 14:40:38 2012] [debug] proxy_util.c(1934): proxy: initialized single connection worker 3 in child 5918 for (192.168.0.102)
[Sun May 06 14:40:38 2012] [debug] proxy_util.c(1818): proxy: grabbed scoreboard slot 4 in child 5918 for worker ajp://192.168.0.102:8008/bork
[Sun May 06 14:40:38 2012] [debug] proxy_util.c(1837): proxy: worker ajp://192.168.0.102:8008/bork already initialized
[Sun May 06 14:40:38 2012] [debug] proxy_util.c(1934): proxy: initialized single connection worker 4 in child 5918 for (192.168.0.102)
[Sun May 06 14:40:38 2012] [debug] proxy_util.c(1818): proxy: grabbed scoreboard slot 2 in child 5917 for worker ajp://192.168.0.100:8008/coding
[Sun May 06 14:40:38 2012] [debug] proxy_util.c(1837): proxy: worker ajp://192.168.0.100:8008/coding already initialized
[Sun May 06 14:40:38 2012] [debug] proxy_util.c(1934): proxy: initialized single connection worker 2 in child 5917 for (192.168.0.100)
[Sun May 06 14:40:38 2012] [debug] proxy_util.c(1818): proxy: grabbed scoreboard slot 3 in child 5917 for worker http://192.168.0.102:8080
[Sun May 06 14:40:38 2012] [debug] proxy_util.c(1837): proxy: worker http://192.168.0.102:8080 already initialized
[Sun May 06 14:40:38 2012] [debug] proxy_util.c(1934): proxy: initialized single connection worker 3 in child 5917 for (192.168.0.102)
[Sun May 06 14:40:38 2012] [debug] proxy_util.c(1818): proxy: grabbed scoreboard slot 4 in child 5917 for worker ajp://192.168.0.102:8008/bork
[Sun May 06 14:40:38 2012] [debug] proxy_util.c(1837): proxy: worker ajp://192.168.0.102:8008/bork already initialized
[Sun May 06 14:40:38 2012] [debug] proxy_util.c(1934): proxy: initialized single connection worker 4 in child 5917 for (192.168.0.102)
[Sun May 06 14:42:09 2012] [debug] ajp_header.c(687): ajp_read_header: ajp_ilink_received 04
[Sun May 06 14:42:09 2012] [debug] ajp_header.c(697): ajp_parse_type: got 04
[Sun May 06 14:42:09 2012] [debug] ajp_header.c(516): ajp_unmarshal_response: status = 200
[Sun May 06 14:42:09 2012] [debug] ajp_header.c(537): ajp_unmarshal_response: Number of headers is = 1
[Sun May 06 14:42:09 2012] [debug] ajp_header.c(599): ajp_unmarshal_response: Header[0]     [Content-Type] = [text/xml;charset=utf-8]
[Sun May 06 14:42:09 2012] [debug] ajp_header.c(609): ajp_unmarshal_response: ap_set_content_type done
[Sun May 06 14:42:09 2012] [debug] ajp_header.c(687): ajp_read_header: ajp_ilink_received 03
[Sun May 06 14:42:09 2012] [debug] ajp_header.c(697): ajp_parse_type: got 03
[Sun May 06 14:42:09 2012] [debug] ajp_header.c(687): ajp_read_header: ajp_ilink_received 03
[Sun May 06 14:42:09 2012] [debug] ajp_header.c(697): ajp_parse_type: got 03
[Sun May 06 14:42:09 2012] [debug] ajp_header.c(687): ajp_read_header: ajp_ilink_received 05
[Sun May 06 14:42:09 2012] [debug] ajp_header.c(697): ajp_parse_type: got 05
[Sun May 06 14:42:09 2012] [debug] mod_deflate.c(615): [client 188.81.234.2] Zlib: Compressed 447 to 255 : URL /bork/SSOIdentityProviderSoap
[Sun May 06 14:42:09 2012] [debug] mod_proxy_ajp.c(570): proxy: got response from (null) (192.168.0.102)
[Sun May 06 14:42:09 2012] [debug] proxy_util.c(2029): proxy: AJP: has released connection for (192.168.0.102)
[Sun May 06 14:42:09 2012] [info] [client 188.81.234.2] Request body read timeout

Was wondering if any one could provide some advice, perhaps even point out any hideous, horrible configuration error? thanks in advance!

share|improve this question

1 Answer 1

up vote 0 down vote accepted

This is almost certainly DNS. Check the time for a reverse DNS lookup of .100 from .102.

share|improve this answer

Your Answer

 
discard

By posting your answer, you agree to the privacy policy and terms of service.

Not the answer you're looking for? Browse other questions tagged or ask your own question.