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
SERVER_ADMIN=webmaster@abcdef.com; 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 ....

**exec("echo** is wrong, exec takes a command line, drop the echo. you don't want to call the nix echo command. — , Apr 29 '12 at 21:59
also i would try: exec("nohup php /home/user/www/Update/Update.php >/dev/null 2>&1 &"); — , Apr 29 '12 at 22:05
so you are saying that what the author of the article claims is completely unusable? — Joris Mans, Apr 29 '12 at 22:14
didn't read it, but if he suggested the above, it's just wrong. — , Apr 29 '12 at 22:16
@Dagon: he really _does_ want to execute `echo`, in order to send the desired command string through a pipe into the stdin of the `at` command. — ottomeister, Apr 30 '12 at 06:04
Anything new on this? Have you resolved the problem? Would much like to hear what it was! (If not: see update below) — alexis, May 10 '12 at 08:21
As always with this kind of problem in a work-related environment I couldn't afford to spend another 4 days investigating it. So I have a cron job on one side and the php UpdateData file generating an sh file on the other. The cron job checks for the existence of the bash file and executes it if it exists. Problem solved (or worked around). Never found out what the 'at' problem is though. — Joris Mans, May 11 '12 at 13:42

score 3 · Answer 1 · answered May 03 '12 at 15:55

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.

symcbean · Answer 2 · 2012-05-04T08:16:09.467

2

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?

edited May 04 '12 at 08:16

answered May 03 '12 at 11:48

symcbean

47,736
6
59
94

No not logged in as root, and nobody else is accessing the webpage nor is update.php calling the command to run itself again. We have been looking at the problem with several people here. Nobody understands what is going on. – Joris Mans May 03 '12 at 11:55
If you're not logged in as root nor the webserver uid then you shouldn't be able see the atq for the webserver uid – symcbean May 04 '12 at 08:16
Yeah sorry for that. To check at-l I indeed logged in as root – Joris Mans May 06 '12 at 13:15

score 2 · Answer 3 · answered May 03 '12 at 13:22

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.

answered May 03 '12 at 13:22

iWantSimpleLife

1,944
14
22

Try running the command from the terminal then see what the "at -c" returns. Maybe we can compare the 2 and find the difference between schedulingh it from apache and that from the terminal. – iWantSimpleLife May 07 '12 at 07:43

score 2 · Answer 4 · answered May 03 '12 at 16:00

2

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

answered May 03 '12 at 16:00

Serx_Mz

39
4

going to check that one out. Thanks! – Joris Mans May 06 '12 at 13:12
added the contents to the question – Joris Mans May 06 '12 at 13:28

alexis · Answer 5 · 2012-05-10T08:44:15.040

First try: As others said, LaunchUpdates.php (which you call from the browser) must be invoking itself. It probably does not invoke .../Update.php as you report and intend, but ... /LaunchUpdates.php. An easy mistake to make, and to overlook, so my money is on that. [Edit: That was not the problem.]

Second try: Now that you've added the generated at script, we can see that you do in fact call Update.php. Next clue: A subshell normally increments the variable SHLVL to one more than the value of its parent. It is extremely unusual for it to go beyond single digits, and in this case it shows that you've got a chain of more than 700 at commands, each launched by the previous one. This rules out LaunchUpdates.php somehow being run via http, since SHLVL would then be reset to one more than its value in apache.

My new guess: Update.php is somehow executing $SCRIPT_NAME or $SCRIPT_FILENAME, which (as we can see in the generated script) are set by at to LaunchUpdates.php instead of Update.php. You can check that the problem is in Update.php by replacing it with an empty file, or with a stub that just writes out a message to a file: the problem should disappear.

Most likely the cause are those environment settings. If you can't figure it out, show us the code for Update.php (in simplified form, but make sure the problem is still present) so we can all take a look.

Edit 2: So you've confirmed that LaunchUpdates.php is being re-launched. Since it doesn't call itself, it must be called by Update.php.

Well, it was worth asking... I've added another suggestion based on the at script. — alexis, May 06 '12 at 15:49

score 2 · Answer 6 · answered May 09 '12 at 14:52

The author of the article wrote the following code to effect the scheduling:

print `echo /usr/bin/php -q longThing.php | at now`;

Making the script show the results of the scheduling command using backticks. This might give you a hint if at is giving any unexpected output ... perhaps add 2>&1 to see if there were any errors.

Nick · Answer 7 · 2012-05-09T18:18:07.113

2

Not so much an answer to the "at" issue but as an alternative you could setup a timeout to run in 2 minutes using the prggmr library that will execute the code contained in the Update.php file.

require 'path/to/prggmr/src/prggmr.php';

prggmr\timeout(function(){
    // Put logic from Update.php HERE
}, 120000);
// note the time is in milliseconds

prggmr\loop();

To run the code you would use the same command only drop the "at"

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

This would run the code within that timeout in 2 minutes and kill the script automatically afterwords, note that the library requires PHP 5.4 to run and again this is only a thought as an alternative, if installing 5.4 is not an option just ignore this.

edited May 09 '12 at 18:18

answered May 09 '12 at 18:09

Nick

763
1
11
26

Out of curiosity, for what does that library need PHP 5.4? – hakre May 10 '12 at 10:57
The biggest reason for 5.4 is to allow binding of the handle functions to the current event object [code](https://github.com/nwhitingx/prggmr/blob/master/src/handle.php#L173), previous version of the library required giving the event as the first parameter. It also uses traits for giving objects [state](https://github.com/nwhitingx/prggmr/blob/master/src/state.php) and [storage](https://github.com/nwhitingx/prggmr/blob/master/src/storage.php). I also couldn't wait to use the new array syntax :) – Nick May 10 '12 at 12:51

score 1 · Answer 8 · answered May 03 '12 at 15:35

You should make your script you launch at now + 2 minutes creating and appending a logfile, e.g.:

file_put_contents(__FILE__.'.log', date('c') . "\n", FILE_APPEND);

Then you can easily check what happens. The two minute difference let one assume that it re-shedules itself.

score 1 · Answer 9 · answered May 10 '12 at 00:55

1

Try this:

exec('/home/user/batchProcess.sh >> ~/process.out 2>&1 | at now &');

answered May 10 '12 at 00:55

Rob

12,659
4
39
56

php long running process with 'at' acting very strangely

9 Answers9