Forum

Hi,
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?

Thanks!

When this issue occurs, do all requests via Hiawatha fail? Or only the onces for scripts with this specific function?

Hi,
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...

What does the following command say?

lsof | grep '^hiawatha'

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.1.2.3.4
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 123.123.123.123:https (LISTEN)

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?

The list does have a long list of IP entries such as:
hiawatha 642 www-data 55u IPv4 27089637 0t0 TCP 199.161.98.121:https->123-123-123-123.customer.rigidtech.net:55299 (ESTABLISHED)

file_get_contents will give: "failed to open stream: HTTP request failed!"

How long is that list and are there different clients or is it multiple connections to one and the same client?

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.

Do you run PHP via normal CGI or via FastCGI?

I use php-fpm and normal CGI setup

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?

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 = 123.123.123.123

LogFormat = extended
ServerString = SimpleHTTPserver
CGIwrapper = /usr/sbin/cgi-wrapper
SocketSendTimeout= 80
MaxUrlLength = 9000 

# BINDING SETTINGS
# A binding is where a client can connect to.
#
Binding {
	Port = 80
#	Interface = 127.0.0.1
	MaxKeepAlive = 45
	MaxUploadSize = 12
	MaxRequestSize = 8251
	TimeForRequest = 45,50
}

Binding {
	Port = 443
	Interface = 123.123.123.123
	MaxKeepAlive = 45
	MaxUploadSize = 12
	MaxRequestSize = 16046
	TimeForRequest = 45,50
	TLScertFile = /var/ssl/mycert.pem
}

# BANNING SETTINGS
# Deny service to clients who misbehave.
#
BanlistMask = allow 123.123.123.123
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
	
FastCGIserver {
	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....

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.

When file_get_contents() fails, are you able to browse to sub.mysite.com?

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).

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?

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.

Try this:

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

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.

Well, you don't what your server to end up on the ban list, right? So, deny it from getting there.

Thanks!
Done and will follow and update you later on.

Ok,
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?

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'.

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?

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.

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?

Only use the banning option when someone is bugging you. So, I advice to comment it out for now.

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?

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.