How to properly log output of shell_exec("git pull") to logfile?

[bernhard]

Hello Community,

I'm building a module that runs a master cronjob every minute. This cron calls a PHP script that fires a hookable PW method, so I can use this cron from all of my modules to execute custom code:

<?php namespace ProcessWire;
chdir(dirname(__FILE__)); // file path
chdir("../../../"); // pw root folder
include("index.php");
/** @var RockTrigger $rt */
$rt = $modules->get('RockTrigger');
if(!$rt) return;
$rt->log("# ----- ".date("Y-m-d H:i:s")." -----", true);
$rt->log("# Running RockTrigger Master Cronjob");
$rt->masterCron();

In my other module I can hook the masterCron method:

$this->addHookAfter("RockTrigger::masterCron", function($event) {
  $rt = $event->object;
  $rt->log("# RockGit");
  
  $rt->log(shell_exec("git stash"));
  $rt->log(shell_exec("git submodule foreach 'git stash'"));
  $rt->log(shell_exec("git pull"));
  $rt->log(shell_exec("git submodule update --init --recursive"));
}

This works great. Almost ? 

The cronjob is setup to send me an email on error. My panel treats every output as ERROR and every cronjob without output as SUCCESS. The problem is, that I get this output in my error notification email:

From github.com:baumrock/xyz
   d36..a30  master     -> origin/master
Fetching submodule site/modules/xxx
From github.com:baumrock/xxx
   06d..641  master     -> origin/master

The logfile looks something like this:

# ----- 2020-07-06 21:00:01 -----
# Running RockTrigger Master Cronjob

# RockCI - 1 webhooks found
No local changes to save
No local changes to save
 1 file changed, 134 insertions(+), 23 deletions(-)

So it seems there is a part of the output in the logfile, but a part of the output is sent to STDOUT.

The log method looks like this:

  /**
   * Log data to logfiles
   * @return void
   */
  public function log($data, $newtask = false) {
    $last = $this->cronLogpath.self::lastlog;
    $day = $this->cronLogpath.date("\dN").".log";
    if($newtask) file_put_contents($last, "");

    $log = '';
    $log = $this->logString($data);

    // log to last-logfile
    file_put_contents($last, $log, FILE_APPEND);

    // log to day-logfile
    $fresh = $this->resetDayLog($day);
    if($newtask AND !$fresh) {
      // add some space
      $log = "\n\n$log";
    }
    file_put_contents($day, $log, FILE_APPEND);
  }

So the output is written (or should be written) to two logfiles: _last.log and d1.log (on monday). That's why I think something like git pull >> /foo/_last.log 2>&1 would not work (or is not what I want).

Any idas how I can reliably catch all the output of the commands via PHP and then write them to my logfiles as I want? Thx in advance!

[bernhard]

I have to add some important informations ? 

This is what I get in the console when doing "git pull"

me@vs1:/home/users/xxx/www/test# git pull
remote: Enumerating objects: 5, done.
remote: Counting objects: 100% (5/5), done.
remote: Compressing objects: 100% (2/2), done.
remote: Total 3 (delta 0), reused 0 (delta 0), pack-reused 0
Unpacking objects: 100% (3/3), done.
From github.com:baumrock/test
   624fe5e..e227704  master     -> origin/master
Updating 624fe5e..e227704
Fast-forward
 README.md | 1 +
 1 file changed, 1 insertion(+)

This is the output for git pull 2>&1

// cron.php
echo shell_exec("git pull 2>&1");

// output
me@vs1:/home/users/xxx/www/test# php cron.php 
From github.com:baumrock/test
   e227704..7b1b6f4  master     -> origin/master
Updating e227704..7b1b6f4
Fast-forward
 README.md | 1 +
 1 file changed, 1 insertion(+)

So, this is only a part of the original output!! And this when using git pull

// cron.php
echo shell_exec("git pull");

// output
me@vs1:/home/users/xxx/www/test# php cron.php 
remote: Enumerating objects: 5, done.
remote: Counting objects: 100% (5/5), done.
remote: Compressing objects: 100% (2/2), done.
remote: Total 3 (delta 0), reused 0 (delta 0), pack-reused 0
Unpacking objects: 100% (3/3), done.
From github.com:baumrock/test
   7b1b6f4..f106792  master     -> origin/master
Updating 7b1b6f4..f106792
Fast-forward
 README.md | 1 +
 1 file changed, 1 insertion(+)

That's the same output as using git pull, so shell_exec("git pull") should be what I need... But using this setup:

$out = shell_exec("git pull");
file_put_contents("cron.log", $out, FILE_APPEND);

I get this in the log:

Updating f106792..897d27c
Fast-forward
 README.md | 1 +
 1 file changed, 1 insertion(+)

And this in the console:

me@vs1:/home/users/xxx/www/test# php cron.php 
remote: Enumerating objects: 5, done.
remote: Counting objects: 100% (5/5), done.
remote: Compressing objects: 100% (2/2), done.
remote: Total 3 (delta 0), reused 0 (delta 0), pack-reused 0
Unpacking objects: 100% (3/3), done.
From github.com:baumrock/test
   f106792..897d27c  master     -> origin/master

I get the same result using this cron.php

ob_start();
echo shell_exec("git pull");
file_put_contents("cron.log", ob_get_clean(), FILE_APPEND);

I guess this post explains the problem better ? Why does the output get split? There's one part in the logfile and one part as direct output! Any ideas?