file_get_contents fails after a few hours and a Hiawatha restart fixes it. Any idea?
1 March 2017, 15:43
I just upgraded to 10.5 so I am still un-sure if it is still the case but here is the issue I had until now:
On Ubuntu, running Hiawatha 10.4, php-fpm and Php 5.6 after a few hours of running all file_get_contents calls start to fail.
Restarting php-fpm doesn't fix it.
Restarting Hiawatha FIXES it.
I see no hints in the logs as to why this happens and it's annoying as I need to keep checking the server to know if the bug is back or not.
Did you see something like that?
Any idea if this is one of the 10.5 bug fixes?
Any idea where I can check for more hints to help fix it?
2 March 2017, 15:05
When this issue occurs, do all requests via Hiawatha fail? Or only the onces for scripts with this specific function?
3 March 2017, 20:45
I can confirm it happens on 10.5 as well.
Seems that only these specific function calls fail. A restart to Hiawatha fixes it but it's really weird.
For now I've set a crontab to restart Hiawatha every 12 hours but that's not a real good solution...
4 March 2017, 00:00
What does the following command say?
lsof | grep '^hiawatha'
4 March 2017, 07:56
It brings in the following and a long list of TCP connections with customer IPs after it. Top list is (IP masked manually by me before posting):
hiawatha 642 www-data cwd DIR 9,2 4096 47187615 /etc/hiawatha
hiawatha 642 www-data rtd DIR 9,2 4096 2 /
hiawatha 642 www-data txt REG 9,2 241720 17439191 /usr/sbin/hiawatha
hiawatha 642 www-data mem REG 9,2 48024 5374327 /lib/x86_64-linux-gnu/libnss_files-2.15.so
hiawatha 642 www-data mem REG 9,2 47680 5374031 /lib/x86_64-linux-gnu/libnss_nis-2.15.so
hiawatha 642 www-data mem REG 9,2 97248 5374319 /lib/x86_64-linux-gnu/libnsl-2.15.so
hiawatha 642 www-data mem REG 9,2 35680 5374326 /lib/x86_64-linux-gnu/libnss_compat-2.15.so
hiawatha 642 www-data mem REG 9,2 1030512 5374328 /lib/x86_64-linux-gnu/libm-2.15.so
hiawatha 642 www-data mem REG 9,2 14768 5374030 /lib/x86_64-linux-gnu/libdl-2.15.so
hiawatha 642 www-data mem REG 9,2 1807032 5374315 /lib/x86_64-linux-gnu/libc-2.15.so
hiawatha 642 www-data mem REG 9,2 245600 17440316 /usr/lib/x86_64-linux-gnu/libxslt.so.1.1.26
hiawatha 642 www-data mem REG 9,2 1421464 17434239 /usr/lib/x86_64-linux-gnu/libxml2.so.2.7.8
hiawatha 642 www-data mem REG 9,2 329488 18880346 /usr/lib/hiawatha/libmbedcrypto.so.2.4.0
hiawatha 642 www-data mem REG 9,2 80712 18880347 /usr/lib/hiawatha/libmbedx509.so.2.4.0
hiawatha 642 www-data mem REG 9,2 163176 18880345 /usr/lib/hiawatha/libmbedtls.so.2.4.0
hiawatha 642 www-data mem REG 9,2 92720 5374180 /lib/x86_64-linux-gnu/libz.so.184.108.40.206
hiawatha 642 www-data mem REG 9,2 135366 5374321 /lib/x86_64-linux-gnu/libpthread-2.15.so
hiawatha 642 www-data mem REG 9,2 43288 5374323 /lib/x86_64-linux-gnu/libcrypt-2.15.so
hiawatha 642 www-data mem REG 9,2 149280 5374325 /lib/x86_64-linux-gnu/ld-2.15.so
hiawatha 642 www-data 0r CHR 1,3 0t0 1029 /dev/null
hiawatha 642 www-data 1w CHR 1,3 0t0 1029 /dev/null
hiawatha 642 www-data 2w CHR 1,3 0t0 1029 /dev/null
hiawatha 642 www-data 3u IPv4 26765324 0t0 TCP *:http (LISTEN)
hiawatha 642 www-data 4u IPv4 26765325 0t0 TCP 220.127.116.11:https (LISTEN)
4 March 2017, 08:20
This list shows that Hiawatha does not leak file descriptors. Otherwise, you would have seen a long list of the same file opened multiple times. With what exact error does file_get_contents() fail?
4 March 2017, 08:56
The list does have a long list of IP entries such as:
hiawatha 642 www-data 55u IPv4 27089637 0t0 TCP 18.104.22.168:https->123-123-123-123.customer.rigidtech.net:55299 (ESTABLISHED)
file_get_contents will give: "failed to open stream: HTTP request failed!"
4 March 2017, 09:03
How long is that list and are there different clients or is it multiple connections to one and the same client?
4 March 2017, 09:05
It happens again now (it re-happens every few hours until I restart Hiawatha).
I checked all logs (system, access, error, exploit and garbage) and there's no information in the time/IP I tested.
All I get is an error 500 on the script, the file_get_contents error - failed to open stream: HTTP request failed! on the app logs and nothing else.
That's really annoying :-S
I now enlarged the maxperip value, the max request size value and restarted Hiawatha to see if it helps.
4 March 2017, 09:07
Do you run PHP via normal CGI or via FastCGI?
4 March 2017, 09:10
I use php-fpm and normal CGI setup
4 March 2017, 09:14
The script that runs file_get_contents() to make a HTTP connection, does it get started by Hiawatha or is it trying to make a connection to Hiawatha?
4 March 2017, 09:14
Here's my config file for Hiawatha:
# Hiawatha main configuration file
# GENERAL SETTINGS
ServerId = www-data
ConnectionsTotal = 50000
ConnectionsPerIP = 60
SystemLogfile = /var/log/hiawatha/system.log
GarbageLogfile = /var/log/hiawatha/garbage.log
ExploitLogfile = /var/log/hiawatha/exploit.log
MonitorServer = 22.214.171.124
LogFormat = extended
ServerString = SimpleHTTPserver
CGIwrapper = /usr/sbin/cgi-wrapper
MaxUrlLength = 9000
# BINDING SETTINGS
# A binding is where a client can connect to.
Port = 80
# Interface = 127.0.0.1
MaxKeepAlive = 45
MaxUploadSize = 12
MaxRequestSize = 8251
TimeForRequest = 45,50
Port = 443
Interface = 126.96.36.199
MaxKeepAlive = 45
MaxUploadSize = 12
MaxRequestSize = 16046
TimeForRequest = 45,50
TLScertFile = /var/ssl/mycert.pem
# BANNING SETTINGS
# Deny service to clients who misbehave.
BanlistMask = allow 188.8.131.52
BanOnGarbage = 60
BanOnMaxPerIP = 35
#BanOnMaxReqSize = 0
#BanOnTimeout = 1800
KickOnBan = yes
RebanDuringBan = yes
#BanOnDeniedBody = 300
BanOnSQLi = 1800
# This settings is proofed to be working on IE, firefox and chrome on Banshee 3.5, 3.7
# Other than the above mentioned, you may need to change the value
BanOnFlooding = 35/1:360
#BanlistMask = deny 192.168.20.0/24, deny 127.0.0.1
BanlistMask = deny 127.0.0.1
#BanOnInvalidURL = 0
BanOnWrongPassword = 3:600
ChallengeClient = 200, httpheader, 60
ReconnectDelay = 5
RequestLimitMask = deny 127.0.0.1
#Load management settings
MaxServerLoad = 8000
ListenBacklog = 5000
ThreadKillRate = 200
ThreadPoolSize = 800
WaitForCGI = yes
# Caching settings
CacheSize = 1024
CacheMaxFilesize = 512
# COMMON GATEWAY INTERFACE (CGI) SETTINGS
# These settings can be used to run CGI applications.
#CGIhandler = /usr/bin/perl:pl
CGIhandler = /usr/bin/php5-cgi:php,php5
#CGIhandler = /usr/bin/python:py
#CGIhandler = /usr/bin/ruby:rb
#CGIhandler = /usr/bin/ssi-cgi:shtml
#CGIextension = cgi
FastCGIid = PHP5
# ConnectTo = /var/lib/hiawatha/php5-fcgi.sock
# ConnectTo = 127.0.0.1:9000
ConnectTo = /var/run/php5-fpm.sock
Extension = php
SessionTimeout = 600
# URL TOOLKIT
# This URL toolkit rule was made for the Banshee PHP framework, which
# can be downloaded from http://www.hiawatha-webserver.org/banshee
And a long list of toolkits is below....
4 March 2017, 09:16
There are two domains on the Hiawatha:
1. HTTPS domain (mysite.com)
2. Non-HTTPS subdomain (sub.mysite.com).
The HTTPS domain (mysite.com) is doing a file_get_contents to the non-http sub domain (sub.mysite.com).
It works a few hours then fails.
4 March 2017, 09:18
When file_get_contents() fails, are you able to browse to sub.mysite.com?
4 March 2017, 09:20
Yes. In fact if I copy the URL inside the file_get_contents and paste it to the browser it opens fine.
The link is always to a png file btw (if that matters).
4 March 2017, 09:22
What happens if you do a simple telnet connect from where your script runs to sub.mysite.com? Emulate what file_get_contents() does.
Could the issue be a simple ban by Hiawatha?
4 March 2017, 09:24
I didn't try to telnet to it (not sure about the sytax but I can check).
I also suspected a ban but I do not see any "kicked" entries on my IP in the log.
4 March 2017, 09:27
telnet sub.mysite.com 80
If it connects and immediately disconnects, you got a ban.
Use the BanlistMask to prevent your server from banning itself.
BanlistMask = deny 127.0.01, deny <your external IP>, allow all
4 March 2017, 09:29
I think I got my mask the other way around.
Do I need to deny my server IP or allow it?
I added it to the allow list.
4 March 2017, 09:33
Well, you don't what your server to end up on the ban list, right? So, deny it from getting there.
4 March 2017, 09:40
Done and will follow and update you later on.
5 March 2017, 06:24
The issue still happens.
I just got it and checked the system.log to see my IP under:
MyIPAddress|Sun 05 Mar 2017 00:21:29 -0500|Client kicked
MyIPAddress|Sun 05 Mar 2017 00:22:19 -0500|Timeout while waiting for first request
Does that mean the ban system kicks in?
5 March 2017, 08:47
No, no ban. The connection is simply dropped because the client doesn't send a (valid) request within the time set via TimeForRequest. In other words, it connects and does nothing (or only sent half a request or an invalid one in which Hiawatha doesn't detect a valid end-of-the-HTTP-header). Maybe, there is a bug in that script?
The 'Client kicked' is not related to the 'Timeout while waiting for first request'. Look at the timestamps. The 'Client kicked' was because the IP, from which the connection was made, was banned. So, one connection misbehaves and gets a ban, all other connections from that IP get 'kicked'.
5 March 2017, 09:20
Oh I see.
I believe that if the script was misbehaving I would get the error every time and not after a few hours of run time.
When I restart Hiawatha it all goes back to work properly for another 6-7 hours and then starts failing again.
Maybe something in my ban settings (listed above) is too aggressive?
5 March 2017, 10:09
Well, it's hard for me to say the exact reason. But I think it will be a good thing to also focus on your script to find the cause.
5 March 2017, 11:03
It's really a simply script that generates a png file and then does a:
return file_get_contents($tmpImage, false);
It works flawlessly until Hiawatha bans it :-)
The thing is that the preview request may be called 10-20 times over (upon each image option change).
Taking a look at the above ban settings - what would you recommend I change or comment out?
6 March 2017, 09:07
Only use the banning option when someone is bugging you. So, I advice to comment it out for now.
7 March 2017, 06:20
I've disabled all ban settings and allowed it to run for a few hours but this issue still happens,
All the system.log shows for my Ip is "Silent client disconnect".
I now got a cron to restart Hiawatha every 4 hours but it still happens sometimes once every 2 or 3 hours. It's not really a solution.
Any more things you can recommend I check?
7 March 2017, 10:12
The 'Silent client disconnect' message is logged when a client connects, does nothing and disconnects (before Hiawatha kicks it for being idle). My advice is to check your script. I really think it's a client issue, not a webserver issue.
This topic has been closed.