From e53af95c9301ca092ffa1f7de022beb24d60ea52 Mon Sep 17 00:00:00 2001 From: Tim Starling Date: Tue, 22 Oct 2013 12:16:14 +1100 Subject: [PATCH] Improve logging for wfShellExec() and ignore missing cgroup 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 | 151 ++++++++++++++++++++++++++++++----- includes/limit.sh | 78 ++++++++++-------- 2 files changed, 177 insertions(+), 52 deletions(-) diff --git a/includes/GlobalFunctions.php b/includes/GlobalFunctions.php index d8e6b367b9..de1ebcdc52 100644 --- a/includes/GlobalFunctions.php +++ b/includes/GlobalFunctions.php @@ -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; } /** diff --git a/includes/limit.sh b/includes/limit.sh index 2a1545b64e..82197b53ca 100644 --- a/includes/limit.sh +++ b/includes/limit.sh @@ -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 -- 2.20.1