Issue with apache/mod_php running rsync via exec()

Question

I am having an issue with a php script running rsync on one of my servers, but only when run through apache/mod_php.

Here is a trimmed down version of the script:

<?php
 exec("rsync -a /var/www/html/from/ /var/www/html/to");
?>

Pretty simple. The purpose of this command is to copy a folder structure (complete with appropriate permissions) to a new folder. But the issue is, this rsync command hangs and won't complete.

Doing a bit of investigating, I noticed that the script would spawn two rsync processes:

> ps aux | grep rsync
apache   20752 56.9  0.0  10400   656 ?     R   11:29  1:37 rsync -a /var/www/html/from/ /var/www/html/to
apache   20753  0.0  0.0  10400   276 ?     S   11:29  0:00 rsync -a /var/www/html/from/ /var/www/html/to
root     22305  0.0  0.0  61212   764 pts/1 S+  11:32  0:00 grep rsync

I noticed that the first process was in the 'running' status. So I did an strace on it, but all I got for output was the following:

> strace -p 20752
<snip>
select(1037, [1026 1027 1028 1029], [], NULL, {60, 0}) = 4 (in [1026 1027 1028 1029], left {60, 0})
select(1037, [1026 1027 1028 1029], [], NULL, {60, 0}) = 4 (in [1026 1027 1028 1029], left {60, 0})
select(1037, [1026 1027 1028 1029], [], NULL, {60, 0}) = 4 (in [1026 1027 1028 1029], left {60, 0})
select(1037, [1026 1027 1028 1029], [], NULL, {60, 0}) = 4 (in [1026 1027 1028 1029], left {60, 0})
select(1037, [1026 1027 1028 1029], [], NULL, {60, 0}) = 4 (in [1026 1027 1028 1029], left {60, 0})
select(1037, [1026 1027 1028 1029], [], NULL, {60, 0}) = 4 (in [1026 1027 1028 1029], left {60, 0})
select(1037, [1026 1027 1028 1029], [], NULL, {60, 0}) = 4 (in [1026 1027 1028 1029], left {60, 0})
select(1037, [1026 1027 1028 1029], [], NULL, {60, 0}) = 4 (in [1026 1027 1028 1029], left {60, 0})
select(1037, [1026 1027 1028 1029], [], NULL, {60, 0}) = 4 (in [1026 1027 1028 1029], left {60, 0})
select(1037, [1026 1027 1028 1029], [], NULL, {60, 0}) = 4 (in [1026 1027 1028 1029], left {60, 0})
<snip>

Here is what I know so far:

1. The php script works fine when run from the cli. I enabled the ability to su apache and run the script > php myscript.php and it works fine. But running http://mydomain.com/myscript.php creates the 2 processes, with one of the first one in continual running state. This leads me to believe it's not a permission issue. As further proof, here is the ls -l output:

   > ls -l /var/www | grep html
   drwxr-xr-x 79 apache    apacheftp 4096 Aug 17 12:07 html
   
   > ls -l /var/www/html | grep from
   drwxrwxr-x 2 apache apache 4096 Aug 22 11:27 from
   

   So, apache has permission to write to the directory, and read from the from directory.

2. Running the same script on a different server of same specs works fine. The specs of both servers are:

   Apache version: Apache/2.2.3
   PHP version: 5.3.3
   rsync version: 2.6.8  protocol version 29
   OS: Red Hat Enterprise Linux Server release 5.6 (Tikanga)
   

What I don't know is why apache spawns two rsync processes (or why the first rsync spawns a second), and why the first rsync process seems to be stuck on select(1037...)

Can someone shed light on this?

Answer 1

So after modifying my script to run strace directly through the exec() function like so:

/usr/bin/strace -fo /var/www/html/rsynce.log /usr/bin/rsync -a /var/www/html/from/ /var/www/html/to

and examining the difference in the file generated by running through a browser, and from the command line, I found this line (in the log generated from the browser-run script):

select(1034, [1026 1027 1028 1029], [], NULL, {60, 0}) = -1 EBADF (Bad file descriptor)

This got me researching file descriptors in apache. In my setup, I run many virtualhosts and each one was defining 3 unique logfiles. So while an apache process was using 1143 file descriptors (via lsof -p pid | wc -l ), only 124 of those were not logs.

I was able to remove the unique logfiles from the virtual host, restarted apache, and the script-run-through-the-browser worked fine.