Improve logging for wfShellExec() and ignore missing cgroup
authorTim Starling <tstarling@wikimedia.org>
Tue, 22 Oct 2013 01:16:14 +0000 (12:16 +1100)
committerTim Starling <tstarling@wikimedia.org>
Mon, 28 Oct 2013 21:14:09 +0000 (21:14 +0000)
Allow limit.sh to log its errors to an MW debug log channel, by opening
a separate FD for private communication.

Ensure that the log FD is always closed (3>&-) before executing a
subprocess, so that MW will not hang waiting for background processes
to close the log FD. This means using a fixed FD number, since the bash
syntax for closing a file requires a literal FD number.

The "exec" debug channel is now intended for production monitoring. In
addition to errors from limit.sh, it also records when a subprocess is
terminated by a signal.

The case where stream_select() returns false was tested by patching PHP
to inject EINTR or EBADF into errno.

When wfShellExec() is used with a memory cgroup, and the cgroup is missing, log and continue with no cgroup instead of immediately exiting.

Bug: 55709
Change-Id: Ie40befe9c0d00c9a0ddb01077df4afb774d17e15

includes/GlobalFunctions.php
includes/limit.sh

index d8e6b36..de1ebcd 100644 (file)
@@ -2714,9 +2714,9 @@ function wfShellExecDisabled() {
                        $functions = explode( ',', ini_get( 'disable_functions' ) );
                        $functions = array_map( 'trim', $functions );
                        $functions = array_map( 'strtolower', $functions );
-                       if ( in_array( 'passthru', $functions ) ) {
-                               wfDebug( "passthru is in disabled_functions\n" );
-                               $disabled = 'passthru';
+                       if ( in_array( 'proc_open', $functions ) ) {
+                               wfDebug( "proc_open is in disabled_functions\n" );
+                               $disabled = 'disabled';
                        }
                }
        }
@@ -2728,13 +2728,16 @@ function wfShellExecDisabled() {
  * configuration if supported.
  * @param string $cmd Command line, properly escaped for shell.
  * @param &$retval null|Mixed optional, will receive the program's exit code.
- *                 (non-zero is usually failure)
+ *                 (non-zero is usually failure). If there is an error from
+ *                 read, select, or proc_open(), this will be set to -1.
  * @param array $environ optional environment variables which should be
  *                 added to the executed command environment.
  * @param array $limits optional array with limits(filesize, memory, time, walltime)
  *                 this overwrites the global wgShellMax* limits.
- * @param array $options Array of options. Only one is "duplicateStderr" => true, which
- *                 Which duplicates stderr to stdout, including errors from limit.sh
+ * @param array $options Array of options:
+ *    - duplicateStderr: Set this to true to duplicate stderr to stdout, 
+ *      including errors from limit.sh
+ *      
  * @return string collected stdout as a string
  */
 function wfShellExec( $cmd, &$retval = null, $environ = array(), $limits = array(), $options = array() ) {
@@ -2746,7 +2749,7 @@ function wfShellExec( $cmd, &$retval = null, $environ = array(), $limits = array
                $retval = 1;
                return $disabled == 'safemode' ?
                        'Unable to run external programs in safe mode.' :
-                       'Unable to run external programs, passthru() is disabled.';
+                       'Unable to run external programs, proc_open() is disabled.';
        }
 
        $includeStderr = isset( $options['duplicateStderr'] ) && $options['duplicateStderr'];
@@ -2772,6 +2775,7 @@ function wfShellExec( $cmd, &$retval = null, $environ = array(), $limits = array
        }
        $cmd = $envcmd . $cmd;
 
+       $useLogPipe = false;
        if ( php_uname( 's' ) == 'Linux' ) {
                $time = intval ( isset( $limits['time'] ) ? $limits['time'] : $wgMaxShellTime );
                if ( isset( $limits['walltime'] ) ) {
@@ -2793,8 +2797,10 @@ function wfShellExec( $cmd, &$retval = null, $environ = array(), $limits = array
                                        'MW_CGROUP=' . escapeshellarg( $wgShellCgroup ) . '; ' .
                                        "MW_MEM_LIMIT=$mem; " .
                                        "MW_FILE_SIZE_LIMIT=$filesize; " .
-                                       "MW_WALL_CLOCK_LIMIT=$wallTime"
+                                       "MW_WALL_CLOCK_LIMIT=$wallTime; " .
+                                       "MW_USE_LOG_PIPE=yes"
                                );
+                       $useLogPipe = true;
                } elseif ( $includeStderr ) {
                        $cmd .= ' 2>&1';
                }
@@ -2803,19 +2809,126 @@ function wfShellExec( $cmd, &$retval = null, $environ = array(), $limits = array
        }
        wfDebug( "wfShellExec: $cmd\n" );
 
-       // Default to an unusual value that shouldn't happen naturally,
-       // so in the unlikely event of a weird php bug, it would be
-       // more obvious what happened.
-       $retval = 200;
-       ob_start();
-       passthru( $cmd, $retval );
-       $output = ob_get_contents();
-       ob_end_clean();
+       $desc = array(
+               0 => array( 'file', 'php://stdin', 'r' ),
+               1 => array( 'pipe', 'w' ),
+               2 => array( 'file', 'php://stderr', 'w' ) );
+       if ( $useLogPipe ) {
+               $desc[3] = array( 'pipe', 'w' );
+       }
+       $pipes = null;
+       $proc = proc_open( $cmd, $desc, $pipes );
+       if ( !$proc ) {
+               wfDebugLog( 'exec', "proc_open() failed: $cmd\n" );
+               $retval = -1;
+               return '';
+       }
+       $outBuffer = $logBuffer = '';
+       $emptyArray = array();
+       $status = false;
+       $logMsg = false;
+
+       // According to the documentation, it is possible for stream_select()
+       // to fail due to EINTR. I haven't managed to induce this in testing 
+       // despite sending various signals. If it did happen, the error 
+       // message would take the form: 
+       //
+       // stream_select(): unable to select [4]: Interrupted system call (max_fd=5)
+       //
+       // where [4] is the value of the macro EINTR and "Interrupted system
+       // call" is string which according to the Linux manual is "possibly"
+       // localised according to LC_MESSAGES.
+       $eintr = defined( 'SOCKET_EINTR' ) ? SOCKET_EINTR : 4;
+       $eintrMessage = "stream_select(): unable to select [$eintr]";
+
+       while ( true ) {
+               $status = proc_get_status( $proc );
+               if ( !$status['running'] ) {
+                       break;
+               }
+               $status = false;
+
+               $readyPipes = $pipes;
+
+               // Clear last error
+               @trigger_error( '' );
+               if ( @stream_select( $readyPipes, $emptyArray, $emptyArray, null ) === false ) {
+                       $error = error_get_last();
+                       if ( strncmp( $error['message'], $eintrMessage, strlen( $eintrMessage ) ) == 0 ) {
+                               continue;
+                       } else {
+                               trigger_error( $error['message'], E_USER_WARNING );
+                               $logMsg = $error['message'];
+                               break;
+                       }
+               }
+               foreach ( $readyPipes as $fd => $pipe ) {
+                       $block = fread( $pipe, 65536 );
+                       if ( $block === '' ) {
+                               // End of file
+                               fclose( $pipes[$fd] );
+                               unset( $pipes[$fd] );
+                               if ( !$pipes ) {
+                                       break 2;
+                               }
+                       } elseif ( $block === false ) {
+                               // Read error
+                               $logMsg = "Error reading from pipe";
+                               break 2;
+                       } elseif ( $fd == 1 ) {
+                               // From stdout
+                               $outBuffer .= $block;
+                       } elseif ( $fd == 3 ) {
+                               // From log FD
+                               $logBuffer .= $block;
+                               if ( strpos( $block, "\n" ) !== false ) {
+                                       $lines = explode( "\n", $logBuffer );
+                                       $logBuffer = array_pop( $lines );
+                                       foreach ( $lines as $line ) {
+                                               wfDebugLog( 'exec', $line );
+                                       }
+                               }
+                       }
+               }
+       }
+
+       foreach ( $pipes as $pipe ) {
+               fclose( $pipe );
+       }
 
-       if ( $retval == 127 ) {
-               wfDebugLog( 'exec', "Possibly missing executable file: $cmd\n" );
+       // Use the status previously collected if possible, since proc_get_status()
+       // just calls waitpid() which will not return anything useful the second time.
+       if ( $status === false ) {
+               $status = proc_get_status( $proc );
        }
-       return $output;
+
+       if ( $logMsg !== false ) {
+               // Read/select error
+               $retval = -1;
+               proc_close( $proc );
+       } elseif ( $status['signaled'] ) {
+               $logMsg = "Exited with signal {$status['termsig']}";
+               $retval = 128 + $status['termsig'];
+               proc_close( $proc );
+       } else {
+               if ( $status['running'] ) {
+                       $retval = proc_close( $proc );
+               } else {
+                       $retval = $status['exitcode'];
+                       proc_close( $proc );
+               }
+               if ( $retval == 127 ) {
+                       $logMsg = "Possibly missing executable file";
+               } elseif ( $retval >= 129 && $retval <= 192 ) {
+                       $logMsg = "Probably exited with signal " . ( $retval - 128 );
+               }
+       }
+
+       if ( $logMsg !== false ) {
+               wfDebugLog( 'exec', "$logMsg: $cmd\n" );
+       }
+
+       return $outBuffer;
 }
 
 /**
index 2a1545b..82197b5 100644 (file)
@@ -6,7 +6,40 @@
 # and is available on most Linux systems. If Perl was distributed with
 # BSD::Resource included, we would happily use that instead, but it isn't.
 
+# Clean up cgroup
+cleanup() {
+       # First we have to move the current task into a "garbage" group, otherwise
+       # the cgroup will not be empty, and attempting to remove it will fail with
+       # "Device or resource busy"
+       if [ -w "$MW_CGROUP"/tasks ]; then
+               GARBAGE="$MW_CGROUP"
+       else
+               GARBAGE="$MW_CGROUP"/garbage-`id -un`
+               if [ ! -e "$GARBAGE" ]; then
+                       mkdir -m 0700 "$GARBAGE"
+               fi
+       fi
+       echo $BASHPID > "$GARBAGE"/tasks
+
+       # Suppress errors in case the cgroup has disappeared due to a release script
+       rmdir "$MW_CGROUP"/$$ 2>/dev/null
+}
+
+updateTaskCount() {
+       # There are lots of ways to count lines in a file in shell script, but this
+       # is one of the few that doesn't create another process, which would
+       # increase the returned number of tasks.
+       readarray < "$MW_CGROUP"/$$/tasks
+       NUM_TASKS=${#MAPFILE[*]}
+}
+
+log() {
+       echo limit.sh: "$*" >&3
+       echo limit.sh: "$*" >&2
+}
+
 MW_INCLUDE_STDERR=
+MW_USE_LOG_PIPE=
 MW_CPU_LIMIT=0
 MW_CGROUP=
 MW_MEM_LIMIT=0
@@ -19,6 +52,10 @@ eval "$2"
 if [ -n "$MW_INCLUDE_STDERR" ]; then
        exec 2>&1
 fi
+if [ -z "$MW_USE_LOG_PIPE" ]; then
+       # Open a dummy log FD
+       exec 3>/dev/null
+fi
 
 if [ "$MW_CPU_LIMIT" -gt 0 ]; then
        ulimit -t "$MW_CPU_LIMIT"
@@ -27,9 +64,11 @@ if [ "$MW_MEM_LIMIT" -gt 0 ]; then
        if [ -n "$MW_CGROUP" ]; then
                # Create cgroup
                if ! mkdir -m 0700 "$MW_CGROUP"/$$; then
-                       echo "limit.sh: failed to create the cgroup." 1>&2
-                       exit 1
+                       log "failed to create the cgroup."
+                       MW_CGROUP=""
                fi
+       fi
+       if [ -n "$MW_CGROUP" ]; then
                echo $$ > "$MW_CGROUP"/$$/tasks
                if [ -n "$MW_CGROUP_NOTIFY" ]; then
                        echo "1" > "$MW_CGROUP"/$$/notify_on_release
@@ -48,43 +87,16 @@ if [ "$MW_FILE_SIZE_LIMIT" -gt 0 ]; then
        ulimit -f "$MW_FILE_SIZE_LIMIT"
 fi
 if [ "$MW_WALL_CLOCK_LIMIT" -gt 0 -a -x "/usr/bin/timeout" ]; then
-       /usr/bin/timeout $MW_WALL_CLOCK_LIMIT /bin/bash -c "$1"
+       /usr/bin/timeout $MW_WALL_CLOCK_LIMIT /bin/bash -c "$1" 3>&-
        STATUS="$?"
        if [ "$STATUS" == 124 ]; then
-               echo "limit.sh: timed out." 1>&2
+               log "timed out executing command \"$1\""
        fi
 else
-       eval "$1"
+       eval "$1" 3>&-
        STATUS="$?"
 fi
 
-# Clean up cgroup
-cleanup() {
-       # First we have to move the current task into a "garbage" group, otherwise
-       # the cgroup will not be empty, and attempting to remove it will fail with
-       # "Device or resource busy"
-       if [ -w "$MW_CGROUP"/tasks ]; then
-               GARBAGE="$MW_CGROUP"
-       else
-               GARBAGE="$MW_CGROUP"/garbage-"$USER"
-               if [ ! -e "$GARBAGE" ]; then
-                       mkdir -m 0700 "$GARBAGE"
-               fi
-       fi
-       echo $BASHPID > "$GARBAGE"/tasks
-
-       # Suppress errors in case the cgroup has disappeared due to a release script
-       rmdir "$MW_CGROUP"/$$ 2>/dev/null
-}
-
-updateTaskCount() {
-       # There are lots of ways to count lines in a file in shell script, but this
-       # is one of the few that doesn't create another process, which would
-       # increase the returned number of tasks.
-       readarray < "$MW_CGROUP"/$$/tasks
-       NUM_TASKS=${#MAPFILE[*]}
-}
-
 if [ -n "$MW_CGROUP" ]; then
        updateTaskCount
 
@@ -97,7 +109,7 @@ if [ -n "$MW_CGROUP" ]; then
                                updateTaskCount
                        done
                        cleanup
-               ) >&/dev/null < /dev/null &
+               ) >&/dev/null < /dev/null 3>&- &
                disown -a
        else
                cleanup