php long running process with 'at' acting very strangely

Question

Firstly, I am far from a Linux expert so that might be the issue here, but anyway, to the problem:

I followed what is written here : http://symcbean.blogspot.com/2010/02/php-and-long-running-processes.html

to launch a long-running PHP process. This works flawlessly in my MAMP config on my Mac. However once I deployed it to our VPS I got some really weird results.

So first I do a simple test, using an SSH connection:

echo '/usr/local/php53/bin/php -d memory_limit=512M -q /home/user/www/Update/Update.php;' | at now + 2minutes

The result:

warning: commands will be executed using /bin/sh
job 2300 at 2012-04-29 19:24

and indeed, 2 minutes later the php script is executed. So far so good.

Next I try the following approach:

in my browser I open:

www.myserver.com/Update/LaunchUpdates.php

this php script contains the line:

exec("echo '/usr/local/php53/bin/php -d memory_limit=512M -q /home/user/www/Update/Update.php;' | at now + 2minutes");

What happens is the following: I check with at -l the state and I see:

job 2304 at 2012-04-29 19:32

Then I wait 2 minutes and run at -l again. I expect to see an empty result but instead I get:

job 2305 at 2012-04-29 19:34

and 2 minutes later I get

job 2306 at 2012-04-29 19:36

I haven't got the slightest idea of what is going on there. The php script is not executed and the job seems to reschedule itself 2 minutes later. And this goes on and on until i atrm the job.

Does anyone know what might be going on?

Some more info:

cat /etc/*-release
Gentoo Base System version 1.6.14

Some more details. Here is the content of the at job when it is scheduled: (at -c [ID])

#!/bin/sh
# atrun uid=1002 gid=100
# mail user 1
umask 33
SERVER_SIGNATURE=\<address\>Apache/2.2.20\ \(Unix\)\ mod_ssl/2.2.20\ OpenSSL/0.9.8o\ Server\ at\ xxx.yyyyy.com\ Port\ 80\</address\>"
"; export SERVER_SIGNATURE
HTTP_USER_AGENT=Mozilla/5.0\ \(Macintosh\;\ Intel\ Mac\ OS\ X\ 10_7_3\)\ AppleWebKit/534.55.3\ \(KHTML,\ like\ Gecko\)\ Version/5.1.5\ Safari/534.55.3; export HTTP_USER_AGENT
HTTP_HOST=xxx.yyyyy.com; export HTTP_HOST
SERVER_PORT=80; export SERVER_PORT
DOCUMENT_ROOT=/home/user/www; export DOCUMENT_ROOT
SCRIPT_FILENAME=/home/user/www/Update/LaunchUpdates.php; export SCRIPT_FILENAME
REQUEST_URI=/Update/LaunchUpdates.php; export REQUEST_URI
SCRIPT_NAME=/Update/LaunchUpdates.php; export SCRIPT_NAME
HTTP_CONNECTION=keep-alive; export HTTP_CONNECTION
REMOTE_PORT=36291; export REMOTE_PORT
PATH=/bin:/usr/bin; export PATH
PWD=/home/user/www/Update; export PWD
[email protected]; export SERVER_ADMIN
REDIRECT_STATUS=200; export REDIRECT_STATUS
HTTP_ACCEPT_LANGUAGE=en-us; export HTTP_ACCEPT_LANGUAGE
HTTP_ACCEPT=text/html,application/xhtml+xml,application/xml\;q=0.9,\*/\*\;q=0.8; export HTTP_ACCEPT
REMOTE_ADDR=83.101.41.41; export REMOTE_ADDR
SHLVL=764; export SHLVL
SERVER_NAME=xxx.yyyyy.com; export SERVER_NAME
SERVER_SOFTWARE=Apache/2.2.20\ \(Unix\)\ mod_ssl/2.2.20\ OpenSSL/0.9.8o; export SERVER_SOFTWARE
QUERY_STRING=; export QUERY_STRING
SERVER_ADDR=1.2.3.4; export SERVER_ADDR
GATEWAY_INTERFACE=CGI/1.1; export GATEWAY_INTERFACE
SERVER_PROTOCOL=HTTP/1.1; export SERVER_PROTOCOL
HTTP_ACCEPT_ENCODING=gzip,\ deflate; export HTTP_ACCEPT_ENCODING
REQUEST_METHOD=GET; export REQUEST_METHOD
cd /home/user/www/Update || {
     echo 'Execution directory inaccessible' >&2
     exit 1
}
/usr/local/php53/bin/php -d memory_limit=512M -q /home/user/www/Update/Update.php;

When waiting for the job to reschedule after 2 minutes I get the new job's contents and it is identical except for:

SHLVL=764 that has become SHLVL=765

More info!

As a user suggested I tried using nohup instead of at. So what I did was the following:

Generate the command to be run by nohup in a .sh file (with execute permissions). and then do exec('nohup .....')

I also added a check in LaunchUpdates to make sure it is not called again before the nohup batch has done running (I basically rm the .sh file and the end of its batch, and in LaunchUpdates I check for the existence of that file).

So in short.

batchProcess.sh contains:

/usr/local/php53/bin/php -d memory_limit=512M -q /home/user/www/Update/Update.php; 
rm /home/user/batchProcess.sh

my LaunchUpdates php code contains:

$batchFile = "/home/user/batchProcess.sh";

if (file_exists($batchFile))
{
    echo 'Process still running. Try again later!';
    exit;
}

exec('nohup /home/user/batchProcess.sh > ~/process.out 2> ~/process.err < /dev/null &');

No what happens:

I comment out the exec line in my php script so the file does not get executed but generated. I test the file by hand by logging in with ssh, change to user "user" and run:

nohup /home/user/batchProcess.sh > ~/process.out 2> ~/process.err < /dev/null &

all works fine (and the .sh file is deleted at the end)!

Next I uncomment the exec line and rerun the php script. process.out contains:

Process still running. Try again later!

This means that it IS executing the base-script again and not the exec statement??? I am COMPLETELY lost here! Since on both accounts I run the same bash script there can be no error as to what commands get executed.

Should I start digging in the apache logs?

This was supposed to take little time, boy was I wrong ....

Answer 1

Since the "at" command in your example is used to unbind the script from the calling terminal you could use "nohup" instead of "at".

Try this one (unbind from the calling process, wait 120 secs and call php):

/usr/bin/nohup /bin/sleep 120 2> /dev/null && \
/bin/date >> /tmp/longphp.log && \
/usr/local/php53/bin/php -d memory_limit=512M \
  -q /home/user/www/Update/Update.php >> /tmp/longphp.log 2>> /tmp/longphp.log

It creates the/tmp/longphp.log file for analysis. You could also create a shell wrapper containing the previous script, to simplify.

Answer 2

Besides using "at -l" to check the queue, also try using "at -c [ID]" to see the actual command that AT will be running. I think that will help diagnose what the error is.

I highly suspect that the at command is running itself, so it is rescheduling itself every 2 minutes.

Answer 3

If you look at /var/spool/at/atjobs you will find a .SEQ and file(s) similar to this

-rwx------ 1 sergio at   5077 may  3 17:53 a000010153c71d

This file has all the environment vars and also the command that atd executes. Hope this helps

Answer 4

I assume you are logged in as root (or the uid PHP runs as in the webserver) when running at -l, and that the jobs are associated with the uid PHP runs as in the webserver ?

It is possible that someone else is accessing the webpage, however, since new jobs are being added at the same interval as the delay for the initial run makes me think that Update.php might be calling the command to run itself again?