httpproxy hangs

You should be able to see in the Web Filtering log "when" the problem starts.  Does that correspond to a daily reset of a PPPoE connection, or something similar?

Cheers - Bob

You are correct.  I found the point where we lost it.
Right after it tries to do that DNS lookup, it never recovers.

I checked the logs on the domain controllers and DNS servers.  There are no reported problems.  (and they are in the same rack as UTM).

2013:01:13-07:43:22 basil httpproxy[30798]: id="0001" severity="info" sys="SecureWeb" sub="http" name="http access" action="pass" method="GET" srcip="192.168.0.28" dstip="50.17.238.167" user="" statuscode="200" cached="0" profile="REF_HttProServers (Linux Servers)" filteraction="REF_HttCffLinuxServe (Linux Servers)" size="4187" request="0x76d76878" url="http://www.mysqueezebox.com/api/v1/players" exceptions="" error="" content-type="text/x-json" application="itunes"
2013:01:13-07:43:48 basil httpproxy[30798]: id="0003" severity="info" sys="SecureWeb" sub="http" request="(nil)" function="dns_expire" file="dns.c" line="151" message="dns query timed out, retransmitting (retry 1)"
2013:01:13-07:43:53 basil httpproxy[30798]: id="0003" severity="info" sys="SecureWeb" sub="http" request="(nil)" function="dns_expire" file="dns.c" line="151" message="dns query timed out, retransmitting (retry 2)"
2013:01:13-07:44:08 basil httpproxy[30798]: id="0003" severity="info" sys="SecureWeb" sub="http" request="(nil)" function="dns_expire" file="dns.c" line="151" message="dns query timed out, retransmitting (retry 1)"
2013:01:13-07:44:13 basil httpproxy[30798]: id="0003" severity="info" sys="SecureWeb" sub="http" request="(nil)" function="dns_expire" file="dns.c" line="151" message="dns query timed out, retransmitting (retry 2)"
2013:01:13-07:44:28 basil httpproxy[30798]: id="0003" severity="info" sys="SecureWeb" sub="http" request="(nil)" function="dns_expire" file="dns.c" line="151" message="dns query timed out, retransmitting (retry 1)"
2013:01:13-07:44:33 basil httpproxy[30798]: id="0003" severity="info" sys="SecureWeb" sub="http" request="(nil)" function="dns_expire" file="dns.c" line="151" message="dns query timed out, retransmitting (retry 2)"
2013:01:13-07:44:48 basil httpproxy[30798]: id="0003" severity="info" sys="SecureWeb" sub="http" request="(nil)" function="dns_expire" file="dns.c" line="151" message="dns query timed out, retransmitting (retry 1)"
2013:01:13-07:44:53 basil httpproxy[30798]: id="0003" severity="info" sys="SecureWeb" sub="http" request="(nil)" function="dns_expire" file="dns.c" line="151" message="dns query timed out, retransmitting (retry 2)"
2013:01:13-07:45:08 basil httpproxy[30798]: id="0003" severity="info" sys="SecureWeb" sub="http" request="(nil)" function="dns_expire" file="dns.c" line="151" message="dns query timed out, retransmitting (retry 1)"
2013:01:13-07:45:13 basil httpproxy[30798]: id="0003" severity="info" sys="SecureWeb" sub="http" request="(nil)" function="dns_expire" file="dns.c" line="151" message="dns query timed out, retransmitting (retry 2)"
2013:01:13-07:48:06 basil httpproxy[30798]: id="0003" severity="info" sys="SecureWeb" sub="http" request="(nil)" function="saviscanner_log" file="saviscanner.c" line="153" message="Reloading SAVI threat data"
2013:01:13-07:48:10 basil httpproxy[30798]: id="0003" severity="info" sys="SecureWeb" sub="http" request="(nil)" function="saviscanner_log" file="saviscanner.c" line="153" message="Reloading SAVI threat data finished, engine 3.37.2, threat data 4.83 from 5/11/2012 (4208268 detected threats)"
2013:01:13-07:50:50 basil httpproxy[30798]: id="0003" severity="info" sys="SecureWeb" sub="http" request="(nil)" function="sc_check_servers" file="scr_scanner.c" line="702" message="server 'cffs23.astaro.com' access time: 54ms"
2013:01:13-07:50:50 basil httpproxy[30798]: id="0003" severity="info" sys="SecureWeb" sub="http" request="(nil)" function="sc_check_servers" file="scr_scanner.c" line="702" message="server 'cffs13.astaro.com' access time: 48ms"
2013:01:13-07:50:50 basil httpproxy[30798]: id="0003" severity="info" sys="SecureWeb" sub="http" request="(nil)" function="sc_check_servers" file="scr_scanner.c" line="702" message="server 'cffs03.astaro.com' access time: 79ms"
2013:01:13-07:50:50 basil httpproxy[30798]: id="0003" severity="info" sys="SecureWeb" sub="http" request="(nil)" function="sc_check_servers" file="scr_scanner.c" line="702" message="server 'cffs06.astaro.com' access time: 96ms"
2013:01:13-07:50:51 basil httpproxy[30798]: id="0003" severity="info" sys="SecureWeb" sub="http" request="(nil)" function="sc_check_servers" file="scr_scanner.c" line="702" message="server 'cffs07.astaro.com' access time: 123ms"
2013:01:13-07:50:51 basil httpproxy[30798]: id="0003" severity="info" sys="SecureWeb" sub="http" request="(nil)" function="sc_check_servers" file="scr_scanner.c" line="702" message="server 'cffs14.astaro.com' access time: 188ms"
2013:01:13-07:50:51 basil httpproxy[30798]: id="0003" severity="info" sys="SecureWeb" sub="http" request="(nil)" function="sc_check_servers" file="scr_scanner.c" line="702" message="server 'cffs25.astaro.com' access time: 187ms"
2013:01:13-07:50:51 basil httpproxy[30798]: id="0003" severity="info" sys="SecureWeb" sub="http" request="(nil)" function="sc_check_servers" file="scr_scanner.c" line="702" message="server 'cffs24.astaro.com' access time: 185ms"
2013:01:13-07:50:51 basil httpproxy[30798]: id="0003" severity="info" sys="SecureWeb" sub="http" request="(nil)" function="sc_check_servers" file="scr_scanner.c" line="702" message="server 'cffs18.astaro.com' access time: 189ms"
2013:01:13-07:50:52 basil httpproxy[30798]: id="0003" severity="info" sys="SecureWeb" sub="http" request="(nil)" function="sc_check_servers" file="scr_scanner.c" line="702" message="server 'cffs20.astaro.com' access time: 210ms"
2013:01:13-07:50:52 basil httpproxy[30798]: id="0003" severity="info" sys="SecureWeb" sub="http" request="(nil)" function="sc_check_servers" file="scr_scanner.c" line="702" message="server 'cffs05.astaro.com' access time: 209ms"
2013:01:13-07:50:52 basil httpproxy[30798]: id="0003" severity="info" sys="SecureWeb" sub="http" request="(nil)" function="sc_check_servers" file="scr_scanner.c" line="702" message="server 'cffs22.astaro.com' access time: 210ms"
2013:01:13-07:50:52 basil httpproxy[30798]: id="0003" severity="info" sys="SecureWeb" sub="http" request="(nil)" function="sc_check_servers" file="scr_scanner.c" line="702" message="server 'cffs04.astaro.com' access time: 216ms"

I got them too now. It did not directly start after an Up2Date installation, will check logs when there is a little timegap. for now, just want to push this, there is something not right and in my case, the UTM is mostly idle...

Rule #1

Whenever anything seems strange, look in the Firewall and Intrusion Prevention log. 

Any luck with that?

Cheers - Bob

Sorry for any short responses!  Posted from my iPhone.

hello, i have maybe a similiar problem.

since yesterday the internet is  not working over http proxy.

i can only see these log entries:

2013:01:17-09:40:37 asg-2 httpproxy[1989]: id="0003" severity="info" sys="SecureWeb" sub="http" request="(nil)" function="sc_check_servers" file="scr_scanner.c" line="702" message="server 'cffs15.astaro.com' access time: 741ms" 
2013:01:17-09:40:37 asg-1 httpproxy[9978]: id="0003" severity="info" sys="SecureWeb" sub="http" request="(nil)" function="sc_check_servers" file="scr_scanner.c" line="702" message="server 'cffs10.astaro.com' access time: 753ms" 
2013:01:17-09:40:37 asg-2 httpproxy[1989]: id="0003" severity="info" sys="SecureWeb" sub="http" request="(nil)" function="sc_check_servers" file="scr_scanner.c" line="702" message="server 'cffs17.astaro.com' access time: 729ms" 
2013:01:17-09:40:38 asg-1 httpproxy[9978]: id="0003" severity="info" sys="SecureWeb" sub="http" request="(nil)" function="sc_check_servers" file="scr_scanner.c" line="702" message="server 'cffs17.astaro.com' access time: 747ms" 
2013:01:17-09:40:38 asg-1 httpproxy[9978]: id="0003" severity="info" sys="SecureWeb" sub="http" request="(nil)" function="sc_check_servers" file="scr_scanner.c" line="702" message="server 'cffs11.astaro.com' access time: 142ms" 
2013:01:17-09:40:38 asg-1 httpproxy[9978]: id="0003" severity="info" sys="SecureWeb" sub="http" request="(nil)" function="sc_check_servers" file="scr_scanner.c" line="702" message="server 'cffs01.astaro.com' access time: 171ms" 
2013:01:17-09:40:38 asg-2 httpproxy[1989]: id="0003" severity="info" sys="SecureWeb" sub="http" request="(nil)" function="sc_check_servers" file="scr_scanner.c" line="702" message="server 'cffs10.astaro.com' access time: 761ms" 
2013:01:17-09:40:38 asg-1 httpproxy[9978]: id="0003" severity="info" sys="SecureWeb" sub="http" request="(nil)" function="sc_check_servers" file="scr_scanner.c" line="702" message="server 'cffs19.astaro.com' access time: 253ms" 
2013:01:17-09:40:40 asg-2 httpproxy[1989]: id="0003" severity="info" sys="SecureWeb" sub="http" request="(nil)" function="sc_check_servers" file="scr_scanner.c" line="702" message="server 'cffs19.astaro.com' access time: 1549ms" 
2013:01:17-09:40:41 asg-2 httpproxy[1989]: id="0003" severity="info" sys="SecureWeb" sub="http" request="(nil)" function="sc_check_servers" file="scr_scanner.c" line="702" message="server 'cffs01.astaro.com' access time: 1123ms



after disable and enable proxy the internet is working again, but are the access times ok?


when i ping 8.8.8.8 the response is about 30ms, might be good.


any ideas?


firmware is 9.004-33

kind regards,

sebastian

I contacted Sophos since we had the same problem now every once and a while. They say that there might be problem in 9.004 which should be fixed in 9.005 coming out next week. Until then one should choose "avira" as scan engine under Management-System Settings-Scan Settings and reboot the UTM. I doubt it has to do with the daily PPPoE reset on our side since we're on a steady fiber line which is available 24/7.

Hope that helps.

Best regards, Marcus

hello,

thanks for your info.

does it need the reboot?


pppoe reset? i have a static internet access, we have no customers with pppoe, only if the router from the provider makes this, but i don´t know this.


kind regards,

sebastian

I'm not sure if it *needs* this reboot. Tech support said to do so, and we had rebooted it at an appropriate time. 

PPPoE Reset is common among private DSL lines in Germany for example when your provider is resetting your connection every 24 hours. Guess that doesnt concern your internet-line then.

Best regards, Marcus

We are still having this problem.  I switch scanning over to Avira a few weeks ago.  Proxy has hung 2 or 3 times since then.

This is really killing us.  Is anyone looking at this problem?  Switching scanning engine had no effect.

Here is another log capture from last night.  I always see the same thing.  DNS errors, AD authentication fails, firewall continues to work, but httpproxy service is dead.  As soon as I restart the proxy, we are working again for a few more hours.

I now have a telnet window open to the firewall 24x7 so I can restart the httpproxy each time it hangs.

Please someone help.  I don't want to go back to squid.  If not for this one fatal problem, our Sophos system would be perfect.

9.004-34

httpproxy log dump - Pastebin.com