WSF/PHP apparent hang: PHP script exceeded 30 seconds

The problem

So I am using the WSF/PHP web services for a project. All was fine until web service usage increased. After a while, web service calls started timing out (3o seconds exceeded). Regular web pages were fine, so it had something to do with Web services. I was stumped, but at some point I noticed that the log files produced by the wsf_c extension were just a tiny bit larger than 32MB, which raised my suspicion_.

I recreated the situation on a development system by creating a dummy log file just under 32M and then doing some requests. I used top to observe the httpd process being busy for 30 seconds, and while it was, I attached gdb to it. Some stepping and tracing revealed the cause.

The wsf_c extension starts up early when Apache starts and loads the worker processes. It loads mod_pdp, which then causes PHP to load the extension. At this point, Apache still runs as root. The extension attempts to write a few log lines, creating the log file, which is owned by “root” and has permissions “rw-r–r–”. Next, Apache switches away from root (for security reasons), in my case, to the user “apache”. The running httpd worker processes inherit the open file descriptor and now, effectively, have write permission to this file, so all is fine, and logging can continue as needed. I can separately argue the merits of this strange write permission, but it is not relevant here.

Logging continues until the log file exceeds 32MB, which is the built-in size limit for the underlying Apache Axis code. The code now copies the log file to “logfile.old”, closes it, and attempts to reopen it with “fopen(file, “w+”)”. This would normally truncate the large log file, as intended. However, it fails to reopen due to a permissions issue. The process is “apache” but the file is owned by “root”. Logging silently fails, and things continue.

So what is the problem? Well, the attempt to log a single line of output resulted in 32MB of data being copied. The next attempt at a line of logging will do the same because the file was never truncated. If you are logging enough lines per request, the time involved in all that (useless) copying will cause your script to exceed 30 seconds, and bingo: it gets cut off. Of course, no logging whatsoever happens.

The solution: part I

The obvious solution is for the WSF/PHP folks to fix the problem (perhaps deferring to the Axis folks). Either delay the log file creation until Apache is running as effective uid “apache”, or change ownership of the created log file. If history is any indication, this may take a while to get done.

The solution: part II

The workaround I have installed is to run an hourly cron script that inspects the file size. When it gets uncomfortably close to 32MB, it restarts the server. The theory is that on restart, the rotation attempt happens as well, but now it is done as root, and everything should be fine. Not soooo. Unless you force a restart right when there is not enough room for the initial startup logging, the logging will not trigger a rotate, and nothing will have changed.

The solution: part III

So finally, I modified my script to not restart the server, but instead change the file’s ownership. I do this as soon as the file appears to exist, regardless of size. Running this once an hour or so will not allow the logfile to reach 32MB before ownership is changed.