WAF not working? Long lost child come home, graceful restarting

Running 9.400-9 soft release. Not sure if the problem is specific to 9.4 or would have existed under 9.3.

WAF log:

2016:04:06-05:43:01 astaro1-1 reverseproxy: id="0299" srcip="127.0.0.1" localip="127.0.0.1" size="1" user="-" host="127.0.0.1" method="GET" statuscode="200" reason="-" extra="-" exceptions="-" time="96039" url="/session-cleanup" server="localhost" referer="-" cookie="-" set-cookie="-"
2016:04:06-05:43:01 astaro1-1 reverseproxy: regular session cleanup: success (sessions deleted: 0)
2016:04:06-05:43:02 astaro1-2 reverseproxy: regular session cleanup: success (sessions deleted: 0)
2016:04:06-05:43:02 astaro1-2 reverseproxy: id="0299" srcip="127.0.0.1" localip="127.0.0.1" size="1" user="-" host="127.0.0.1" method="GET" statuscode="200" reason="-" extra="-" exceptions="-" time="198011" url="/session-cleanup" server="localhost" referer="-" cookie="-" set-cookie="-"
2016:04:06-13:31:27 astaro1-2 reverseproxy: [Wed Apr 06 13:31:27.190702 2016] [mpm_worker:notice] [pid 6068:tid 4148152000] AH00297: SIGUSR1 received.  Doing graceful restart
2016:04:06-13:31:30 astaro1-1 reverseproxy: [Wed Apr 06 13:31:30.767132 2016] [mpm_worker:notice] [pid 6090:tid 4147971776] AH00297: SIGUSR1 received.  Doing graceful restart
2016:04:06-13:31:31 astaro1-2 reverseproxy: [Wed Apr 06 13:31:31.001367 2016] [mpm_worker:notice] [pid 6068:tid 4148152000] AH00292: Apache/2.4.10 (Unix) OpenSSL/1.0.1k configured -- resuming normal operations
2016:04:06-13:31:31 astaro1-2 reverseproxy: [Wed Apr 06 13:31:31.001417 2016] [core:notice] [pid 6068:tid 4148152000] AH00094: Command line: '/usr/apache/bin/httpd'
2016:04:06-13:31:31 astaro1-2 reverseproxy: [Wed Apr 06 13:31:31.001529 2016] [mpm_worker:warn] [pid 6068:tid 4148152000] AH00291: long lost child came home! (pid 7889)
2016:04:06-13:31:31 astaro1-2 reverseproxy: [Wed Apr 06 13:31:31.001579 2016] [mpm_worker:warn] [pid 6068:tid 4148152000] AH00291: long lost child came home! (pid 7890)
2016:04:06-13:31:34 astaro1-1 reverseproxy: [Wed Apr 06 13:31:34.000430 2016] [mpm_worker:notice] [pid 6090:tid 4147971776] AH00292: Apache/2.4.10 (Unix) OpenSSL/1.0.1k configured -- resuming normal operations
2016:04:06-13:31:34 astaro1-1 reverseproxy: [Wed Apr 06 13:31:34.000462 2016] [core:notice] [pid 6090:tid 4147971776] AH00094: Command line: '/usr/apache/bin/httpd'
2016:04:06-13:31:34 astaro1-1 reverseproxy: [Wed Apr 06 13:31:34.000516 2016] [mpm_worker:warn] [pid 6090:tid 4147971776] AH00291: long lost child came home! (pid 8297)
2016:04:06-13:31:34 astaro1-1 reverseproxy: [Wed Apr 06 13:31:34.000543 2016] [mpm_worker:warn] [pid 6090:tid 4147971776] AH00291: long lost child came home! (pid 8298)
2016:04:06-13:33:09 astaro1-2 reverseproxy: [Wed Apr 06 13:33:09.069603 2016] [mpm_worker:notice] [pid 6068:tid 4148152000] AH00297: SIGUSR1 received.  Doing graceful restart
2016:04:06-13:33:09 astaro1-2 reverseproxy: AH00112: Warning: DocumentRoot [/var/www/REF_RevFroInterPlain] does not exist
2016:04:06-13:33:09 astaro1-1 reverseproxy: [Wed Apr 06 13:33:09.989042 2016] [mpm_worker:notice] [pid 6090:tid 4147971776] AH00297: SIGUSR1 received.  Doing graceful restart
2016:04:06-13:33:10 astaro1-2 reverseproxy: [Wed Apr 06 13:33:10.000385 2016] [mpm_worker:notice] [pid 6068:tid 4148152000] AH00292: Apache/2.4.10 (Unix) OpenSSL/1.0.1k configured -- resuming normal operations
2016:04:06-13:33:10 astaro1-2 reverseproxy: [Wed Apr 06 13:33:10.000417 2016] [core:notice] [pid 6068:tid 4148152000] AH00094: Command line: '/usr/apache/bin/httpd'
2016:04:06-13:33:10 astaro1-2 reverseproxy: [Wed Apr 06 13:33:10.000460 2016] [mpm_worker:warn] [pid 6068:tid 4148152000] AH00291: long lost child came home! (pid 10085)
2016:04:06-13:33:10 astaro1-2 reverseproxy: [Wed Apr 06 13:33:10.000484 2016] [mpm_worker:warn] [pid 6068:tid 4148152000] AH00291: long lost child came home! (pid 10086)
2016:04:06-13:33:10 astaro1-1 reverseproxy: AH00112: Warning: DocumentRoot [/var/www/REF_RevFroInterPlain] does not exist
2016:04:06-13:33:11 astaro1-1 reverseproxy: [Wed Apr 06 13:33:11.000749 2016] [mpm_worker:notice] [pid 6090:tid 4147971776] AH00292: Apache/2.4.10 (Unix) OpenSSL/1.0.1k configured -- resuming normal operations
2016:04:06-13:33:11 astaro1-1 reverseproxy: [Wed Apr 06 13:33:11.000779 2016] [core:notice] [pid 6090:tid 4147971776] AH00094: Command line: '/usr/apache/bin/httpd'
2016:04:06-13:33:11 astaro1-1 reverseproxy: [Wed Apr 06 13:33:11.000821 2016] [mpm_worker:warn] [pid 6090:tid 4147971776] AH00291: long lost child came home! (pid 31736)
2016:04:06-13:33:11 astaro1-1 reverseproxy: [Wed Apr 06 13:33:11.000842 2016] [mpm_worker:warn] [pid 6090:tid 4147971776] AH00291: long lost child came home! (pid 31737)

Any ideas what the problem is or where I should look?

Thanks,

James.
Parents
  • Hi,

    the logs don't show any unusual behavior. OK, there are many restarts of the WAF but if you have configured multiple things that's possible.
    What's the exact problem?

    Sabine

  • We had a security audit done and WAF wasn't stopping anything. There were no WAF logs from back then, so it must have been turned off. There are logs now, so I'm just wanting to make sure it is all working OK.

    What about the poor long lost children?

    And I'm not sure why the WAF would keep restarting? Does it start apache every time there is new connection to a real web server, and then quit it when the connection closes?

    How do I know it is working OK I suppose is the real problem (without firing up Metasploit or something like that).

    James.

  • Every time you change something in the Webadmin for WAF, the Apache must restart otherwise it would not take up the changes. Therefore, if you set up your WAF the first time, you'll get many restarts.

    The long lost child messages are normal in the case of doing a graceful restart. The message sounds like something is wrong but it's not.

    If traffic goes over the WAF, you should see that traffic in the log. At the moment, there is not traffic at all.

    Traffic looks like this:
    2016:04:06-10:44:28 myUTM reverseproxy: id="0299" srcip="10.x.x.x" localip="10.x.x.y" size="209" user="-" host="10.x.x.x" method="GET" statuscode="200" reason="-" extra="-" exceptions="-" time="3255" url="/" server="myserver.local" referer="-" cookie="-" set-cookie="-"


    Sabine

  • Also keep in mind that a DNAT comes before WAF, so make sure to not have DNATs on the WAF interfaces and ports.

    ----------
    Sophos user, admin and reseller.
    Private Setup:

    • XG: HPE DL20 Gen9 (Core i3-7300, 8GB RAM, 120GB SSD) | XG 18.0 (Home License) with: Web Protection, Site-to-Site-VPN (IPSec, RED-Tunnel), Remote Access (SSL, HTML5)
    • UTM: 2 vCPUs, 2GB RAM, 50GB vHDD, 2 vNICs on vServer (KVM) | UTM 9.7 (Home License) with: Email Protection, Webserver Protection, RED-Tunnel (server)
  • Well, that might be the problem! My first NAT rule is:

    So if I have the Web Server as a real server in WAF:

    I should disable the DNAT rule and all will still work?

    James.

  • I cannot see your screenshots. Please upload them here in your post (edit your post and click on the picture icon at the menu bar), not via external hoster.

    ----------
    Sophos user, admin and reseller.
    Private Setup:

    • XG: HPE DL20 Gen9 (Core i3-7300, 8GB RAM, 120GB SSD) | XG 18.0 (Home License) with: Web Protection, Site-to-Site-VPN (IPSec, RED-Tunnel), Remote Access (SSL, HTML5)
    • UTM: 2 vCPUs, 2GB RAM, 50GB vHDD, 2 vNICs on vServer (KVM) | UTM 9.7 (Home License) with: Email Protection, Webserver Protection, RED-Tunnel (server)
  • OK. Copy and paste of screenshots doesn't work in forum. Have uploaded the files.

Reply Children
  • Thanks. At least a connection should be possible with your WAF setup.

    But remove the real webserver with https from your virtual web server. Adding more than on real server here is intendet for load balancing.

    After disabling the DNAT you can test your published site for correct function. If anything doesn't work have a look at the WAF log. Try to find the corresponding ID of the false matching rule and add this ID to the corresponding WAF firewall profile -> "Skip Filter Rules".

    ----------
    Sophos user, admin and reseller.
    Private Setup:

    • XG: HPE DL20 Gen9 (Core i3-7300, 8GB RAM, 120GB SSD) | XG 18.0 (Home License) with: Web Protection, Site-to-Site-VPN (IPSec, RED-Tunnel), Remote Access (SSL, HTML5)
    • UTM: 2 vCPUs, 2GB RAM, 50GB vHDD, 2 vNICs on vServer (KVM) | UTM 9.7 (Home License) with: Email Protection, Webserver Protection, RED-Tunnel (server)
  • Fantastic - I think it is working now!

    log now shows for e.g.:

    2016:04:06-22:23:05 astaro1-1 reverseproxy: [Wed Apr 06 22:23:05.703380 2016] [url_hardening:error] [pid 9626:tid 3761818480] [client 144.132.67.121:55332] No signature found, URI: internal.bordo.com.au/.../me.ics
    2016:04:06-22:23:05 astaro1-1 reverseproxy: id="0299" srcip="144.132.67.121" localip="203.206.204.254" size="223" user="-" host="144.132.67.121" method="GET" statuscode="403" reason="url hardening" extra="No signature found" exceptions="-" time="719221" url="/calendar/publish.php/me.ics" server="internal.bordo.com.au" referer="-" cookie="-" set-cookie="-"
    2016:04:06-22:28:11 astaro1-1 reverseproxy: id="0299" srcip="85.214.28.229" localip="203.206.204.254" size="209" user="-" host="85.214.28.229" method="GET" statuscode="403" reason="-" extra="-" exceptions="-" time="2589408" url="/" server="internal.bordo.com.au" referer="-" cookie="-" set-cookie="-"
    2016:04:06-22:28:11 astaro1-1 reverseproxy: [Wed Apr 06 22:28:11.334359 2016] [url_hardening:error] [pid 9626:tid 4080741232] [client 85.214.28.229:60419] Hostname in HTTP request (203.206.204.254) does not match the server name (internal.bordo.com.au)
    This is with one virtual server which has one real server (port 80).
    So I should set up another virtual server for the same server but port 443?
    And other ones for each port that the real web server is listening on?