Fixed ticket 208, added more logging in GitServe and Scm backend.

src/IDF/Plugin/SyncGit/Serve.php

@@ -98,6 +98,7 @@ class IDF_Plugin_SyncGit_Serve
             $this->setGitExport($relpath, $fullpath);
         }
         $new_cmd = sprintf("%s '%s'", $verb, $fullpath);
+        Pluf_Log::info(array('IDF_Plugin_Git_Serve::serve', $username, $cmd, $new_cmd));
         return $new_cmd;
     }
 
@@ -199,8 +200,11 @@ class IDF_Plugin_SyncGit_Serve
                      Pluf::f('git_path', 'git').' --git-dir=%s init', escapeshellarg($fullpath)), 
              $out, $res);
         if ($res != 0) {
+            Pluf_Log::error(array('IDF_Plugin_Git_Serve::initRepository', $res, $fullpath));
             throw new Exception(sprintf('Init repository error, exit status %d.', $res));
         }
+        Pluf_Log::info(array('IDF_Plugin_Git_Serve::initRepository', 'success', $fullpath));
+
     }
 
     /**

src/IDF/Scm.php

@@ -87,6 +87,42 @@ class IDF_Scm
         return call_user_func(array($scms[$scm], 'factory'), $project);
     }
 
+    /**
+     * Run exec and log some information.
+     *
+     * @param $caller Calling method
+     * @param $cmd Command to run
+     * @param &$out Array of output
+     * @param &$return Return value
+     * @return string Last line of the command
+     */
+    public static function exec($caller, $cmd, &$out=null, &$return=null)
+    {
+        Pluf_Log::stime('timer');
+        $ret = exec($cmd, $out, $return);
+        Pluf_Log::perf(array($caller, $cmd, Pluf_Log::etime('timer', 'total_exec')));
+        Pluf_Log::debug(array($caller, $cmd, $out));
+        Pluf_Log::inc('exec_calls');
+        return $ret;
+    }
+
+    /**
+     * Run shell_exec and log some information.
+     *
+     * @param $caller Calling method
+     * @param $cmd Command to run
+     * @return string The output
+     */
+    public static function shell_exec($caller, $cmd)
+    {
+        Pluf_Log::stime('timer');
+        $ret = shell_exec($cmd);
+        Pluf_Log::perf(array($caller, $cmd, Pluf_Log::etime('timer', 'total_exec')));
+        Pluf_Log::debug(array($caller, $cmd, $ret));
+        Pluf_Log::inc('exec_calls');
+        return $ret;
+    }
+
     /**
      * Return the size of the repository in bytes.
      *

src/IDF/Scm/Git.php

@@ -48,7 +48,9 @@ class IDF_Scm_Git extends IDF_Scm
         }
         $cmd = Pluf::f('idf_exec_cmd_prefix', '').'du -skD '
             .escapeshellarg($this->repo);
-        $out = explode(' ', shell_exec($cmd), 2);
+        $out = explode(' ', 
+                       self::shell_exec('IDF_Scm_Git::getRepositorySize', $cmd),
+                       2);
         return (int) $out[0]*1024;
     }
 
@@ -70,7 +72,8 @@ class IDF_Scm_Git extends IDF_Scm
         $cmd = Pluf::f('idf_exec_cmd_prefix', '')
             .sprintf('GIT_DIR=%s '.Pluf::f('git_path', 'git').' branch', 
                      escapeshellarg($this->repo));
-        exec($cmd, $out, $return);
+        self::exec('IDF_Scm_Git::getBranches', 
+                   $cmd, $out, $return);
         if ($return != 0) {
             throw new IDF_Scm_Exception(sprintf($this->error_tpl,
                                                 $cmd, $return, 
@@ -125,11 +128,10 @@ class IDF_Scm_Git extends IDF_Scm
             .sprintf('GIT_DIR=%s %s tag',
                      escapeshellarg($this->repo),
                      Pluf::f('git_path', 'git'));
-         exec($cmd, $out, $return);
+        self::exec('IDF_Scm_Git::getTags', $cmd, $out, $return);
         if (0 != $return) {
             throw new IDF_Scm_Exception(sprintf($this->error_tpl,
-                                                 $cmd,
+                                                $cmd, $return,
-                                                 $return,
                                                 implode("\n", $out)));
         }
         $res = array();
@@ -310,7 +312,7 @@ class IDF_Scm_Git extends IDF_Scm
                        escapeshellarg($hash));
         $ret = 0; $out = array();
         $cmd = Pluf::f('idf_exec_cmd_prefix', '').$cmd;
-        exec($cmd, $out, $ret);
+        self::exec('IDF_Scm_Git::testHash', $cmd, $out, $ret);
         if ($ret != 0) return false;
         return trim($out[0]);
     }
@@ -334,7 +336,7 @@ class IDF_Scm_Git extends IDF_Scm
                      escapeshellarg($tree), escapeshellarg($folder));
         $out = array();
         $res = array();
-        exec($cmd, $out);
+        self::exec('IDF_Scm_Git::getTreeInfo', $cmd, $out);
         foreach ($out as $line) {
             list($perm, $type, $hash, $size, $file) = preg_split('/ |\t/', $line, 5, PREG_SPLIT_NO_EMPTY);
             $res[] = (object) array('perm' => $perm, 'type' => $type, 
@@ -359,7 +361,7 @@ class IDF_Scm_Git extends IDF_Scm
                        escapeshellarg($commit));
         $out = array();
         $cmd = Pluf::f('idf_exec_cmd_prefix', '').$cmd;
-        exec($cmd, $out);
+        self::exec('IDF_Scm_Git::getPathInfo', $cmd, $out);
         foreach ($out as $line) {
             list($perm, $type, $hash, $size, $file) = preg_split('/ |\t/', $line, 5, PREG_SPLIT_NO_EMPTY);
             if ($totest == $file) {
@@ -379,7 +381,8 @@ class IDF_Scm_Git extends IDF_Scm
                        'GIT_DIR=%s '.Pluf::f('git_path', 'git').' cat-file blob %s',
                        escapeshellarg($this->repo), 
                        escapeshellarg($def->hash));
-        return ($cmd_only) ? $cmd : shell_exec($cmd);
+        return ($cmd_only) 
+            ? $cmd : self::shell_exec('IDF_Scm_Git::getFile', $cmd);
     }
 
     /**
@@ -404,7 +407,7 @@ class IDF_Scm_Git extends IDF_Scm
         }
         $out = array();
         $cmd = Pluf::f('idf_exec_cmd_prefix', '').$cmd;
-        exec($cmd, $out, $ret);
+        self::exec('IDF_Scm_Git::getCommit', $cmd, $out, $ret);
         if ($ret != 0 or count($out) == 0) {
             return false;
         }
@@ -445,7 +448,7 @@ class IDF_Scm_Git extends IDF_Scm
                        escapeshellarg($commit));
         $out = array();
         $cmd = Pluf::f('idf_exec_cmd_prefix', '').$cmd;
-        exec($cmd, $out);
+        self::exec('IDF_Scm_Git::isCommitLarge', $cmd, $out);
         $affected = count($out) - 2;
         $added = 0;
         $removed = 0;
@@ -478,7 +481,7 @@ class IDF_Scm_Git extends IDF_Scm
                        escapeshellarg($commit));
         $out = array();
         $cmd = Pluf::f('idf_exec_cmd_prefix', '').$cmd;
-        exec($cmd, $out);
+        self::exec('IDF_Scm_Git::getChangeLog', $cmd, $out);
         return self::parseLog($out);
     }
 
@@ -636,7 +639,8 @@ class IDF_Scm_Git extends IDF_Scm
                      escapeshellarg($this->repo));
         $skip = 0;
         $res = array();
-        exec(sprintf($cmd, $skip), $rawlog);
+        self::exec('IDF_Scm_Git::appendBlobInfoCache',
+                   sprintf($cmd, $skip), $rawlog);
         while (count($rawlog) and count($blobs)) {
             $rawlog = implode("\n", array_reverse($rawlog));
             foreach ($blobs as $blob => $idx) {
@@ -665,7 +669,8 @@ class IDF_Scm_Git extends IDF_Scm
                 }
                 break;
             }
-            exec(sprintf($cmd, $skip), $rawlog);
+            self::exec('IDF_Scm_Git::appendBlobInfoCache',
+                       sprintf($cmd, $skip), $rawlog);
         }
         $this->cacheBlobInfo($res);
         return $res;
@@ -683,7 +688,8 @@ class IDF_Scm_Git extends IDF_Scm
             .sprintf('GIT_DIR=%s '.Pluf::f('git_path', 'git').' log --raw --abbrev=40 --pretty=oneline -500 --skip=%%s',
                      escapeshellarg($this->repo));
         $skip = 0;
-        exec(sprintf($cmd, $skip), $rawlog);
+        self::exec('IDF_Scm_Git::buildBlobInfoCache',
+                   sprintf($cmd, $skip), $rawlog);
         while (count($rawlog)) {
             $commit = '';
             $data = array();
@@ -701,7 +707,8 @@ class IDF_Scm_Git extends IDF_Scm
             $this->cacheBlobInfo($data);
             $rawlog = array();
             $skip += 500;
-            exec(sprintf($cmd, $skip), $rawlog);
+            self::exec('IDF_Scm_Git::buildBlobInfoCache',
+                       sprintf($cmd, $skip), $rawlog);
         }
     }
 

src/IDF/Scm/Mercurial.php

@@ -37,7 +37,10 @@ class IDF_Scm_Mercurial extends IDF_Scm
     {
         $cmd = Pluf::f('idf_exec_cmd_prefix', '').'du -skD '
             .escapeshellarg($this->repo);
-        $out = explode(' ', shell_exec($cmd), 2);
+        $out = explode(' ', 
+                       self::shell_exec('IDF_Scm_Mercurial::getRepositorySize',
+                                        $cmd), 
+                       2);
         return (int) $out[0]*1024;
     }
 
@@ -90,7 +93,7 @@ class IDF_Scm_Mercurial extends IDF_Scm
                        escapeshellarg($this->repo),
                        escapeshellarg($rev));
         $cmd = Pluf::f('idf_exec_cmd_prefix', '').$cmd;
-        exec($cmd, $out, $ret);
+        self::exec('IDF_Scm_Mercurial::isValidRevision', $cmd, $out, $ret);
         return ($ret == 0) && (count($out) > 0);
     }
 
@@ -109,7 +112,7 @@ class IDF_Scm_Mercurial extends IDF_Scm
         $ret = 0; 
         $out = array();
         $cmd = Pluf::f('idf_exec_cmd_prefix', '').$cmd;
-        exec($cmd, $out, $ret);
+        self::exec('IDF_Scm_Mercurial::testHash', $cmd, $out, $ret);
         return ($ret != 0) ? false : 'commit'; 
     }
 
@@ -153,7 +156,7 @@ class IDF_Scm_Mercurial extends IDF_Scm
         $out = array();
         $res = array();
         $cmd = Pluf::f('idf_exec_cmd_prefix', '').$cmd;
-        exec($cmd, $out);
+        self::exec('IDF_Scm_Mercurial::getTreeInfo', $cmd, $out);
         $tmp_hack = array();
         while (null !== ($line = array_pop($out))) {
             list($hash, $perm, $exec, $file) = preg_split('/ |\t/', $line, 4);
@@ -202,7 +205,7 @@ class IDF_Scm_Mercurial extends IDF_Scm
         $cmd = sprintf($cmd_tmpl, escapeshellarg($this->repo), $commit); 
         $out = array();
         $cmd = Pluf::f('idf_exec_cmd_prefix', '').$cmd;
-        exec($cmd, $out);
+        self::exec('IDF_Scm_Mercurial::getPathInfo', $cmd, $out);
         $tmp_hack = array();
         while (null !== ($line = array_pop($out))) {
             list($hash, $perm, $exec, $file) = preg_split('/ |\t/', $line, 4);
@@ -254,7 +257,8 @@ class IDF_Scm_Mercurial extends IDF_Scm
                        escapeshellarg($def->commit), 
                        escapeshellarg($this->repo.'/'.$def->fullpath));
         $cmd = Pluf::f('idf_exec_cmd_prefix', '').$cmd;
-        return ($cmd_only) ? $cmd : shell_exec($cmd);
+        return ($cmd_only) ? 
+            $cmd : self::shell_exec('IDF_Scm_Mercurial::getFile', $cmd);
     }
 
     /**
@@ -271,7 +275,7 @@ class IDF_Scm_Mercurial extends IDF_Scm
         $cmd = sprintf(Pluf::f('hg_path', 'hg').' branches -R %s', 
                        escapeshellarg($this->repo));
         $cmd = Pluf::f('idf_exec_cmd_prefix', '').$cmd;
-        exec($cmd, $out);
+        self::exec('IDF_Scm_Mercurial::getBranches', $cmd, $out);
         $res = array();
         foreach ($out as $b) {
             preg_match('/(\S+).*\S+:(\S+)/', $b, $match);
@@ -295,7 +299,7 @@ class IDF_Scm_Mercurial extends IDF_Scm
         $cmd = sprintf(Pluf::f('hg_path', 'hg').' tags -R %s', 
                        escapeshellarg($this->repo));
         $cmd = Pluf::f('idf_exec_cmd_prefix', '').$cmd;
-        exec($cmd, $out);
+        self::exec('IDF_Scm_Mercurial::getTags', $cmd, $out);
         $res = array();
         foreach ($out as $b) {
             preg_match('/(\S+).*\S+:(\S+)/', $b, $match);
@@ -335,7 +339,7 @@ class IDF_Scm_Mercurial extends IDF_Scm
                        escapeshellarg($commit), escapeshellarg($this->repo));
         $out = array();
         $cmd = Pluf::f('idf_exec_cmd_prefix', '').$cmd;
-        exec($cmd, $out);
+        self::exec('IDF_Scm_Mercurial::getCommit', $cmd, $out);
         $log = array();
         $change = array();
         $inchange = false;
@@ -377,7 +381,7 @@ class IDF_Scm_Mercurial extends IDF_Scm
         $cmd = sprintf(Pluf::f('hg_path', 'hg').' log -R %s -l%s ', escapeshellarg($this->repo), $n, $commit);
         $out = array();
         $cmd = Pluf::f('idf_exec_cmd_prefix', '').$cmd;
-        exec($cmd, $out);
+        self::exec('IDF_Scm_Mercurial::getChangeLog', $cmd, $out);
         return self::parseLog($out, 6);
     }
 

src/IDF/Scm/Svn.php

@@ -58,7 +58,7 @@ class IDF_Scm_Svn extends IDF_Scm
         }
         $cmd = Pluf::f('idf_exec_cmd_prefix', '').'du -skD '
             .escapeshellarg(substr($this->repo, 7));
-        $out = explode(' ', shell_exec($cmd), 2);
+        $out = explode(' ', self::shell_exec('IDF_Scm_Svn::getRepositorySize', $cmd), 2);
         return (int) $out[0]*1024;
     }
 
@@ -147,7 +147,7 @@ class IDF_Scm_Svn extends IDF_Scm
                        escapeshellarg($this->repo),
                        escapeshellarg($rev));
         $cmd = Pluf::f('idf_exec_cmd_prefix', '').$cmd;
-        exec($cmd, $out, $ret);
+        self::exec('IDF_Scm_Svn::isValidRevision', $cmd, $out, $ret);
         return (0 == $ret);
     }
 
@@ -172,7 +172,7 @@ class IDF_Scm_Svn extends IDF_Scm
                        escapeshellarg($this->repo.'/'.self::smartEncode($path)),
                        escapeshellarg($rev));
         $cmd = Pluf::f('idf_exec_cmd_prefix', '').$cmd;
-        $xmlInfo = shell_exec($cmd);
+        $xmlInfo = self::shell_exec('IDF_Scm_Svn::testHash', $cmd);
 
         // If exception is thrown, return false
         try {
@@ -199,7 +199,7 @@ class IDF_Scm_Svn extends IDF_Scm
                        escapeshellarg($this->repo.'/'.self::smartEncode($folder)),
                        escapeshellarg($commit));
         $cmd = Pluf::f('idf_exec_cmd_prefix', '').$cmd;
-        $xml = simplexml_load_string(shell_exec($cmd));
+        $xml = simplexml_load_string(self::shell_exec('IDF_Scm_Svn::getTree', $cmd));
         $res = array();
         $folder = (strlen($folder) and ($folder != '/')) ? $folder.'/' : '';
         foreach ($xml->list->entry as $entry) {
@@ -241,7 +241,7 @@ class IDF_Scm_Svn extends IDF_Scm
                        escapeshellarg($this->repo),
                        escapeshellarg($rev));
         $cmd = Pluf::f('idf_exec_cmd_prefix', '').$cmd;
-        $xml = simplexml_load_string(shell_exec($cmd));
+        $xml = simplexml_load_string(self::shell_exec('IDF_Scm_Svn::getCommitMessage', $cmd));
         $this->cache['commitmess'][$rev] = (string) $xml->logentry->msg;
         return $this->cache['commitmess'][$rev];
     }
@@ -257,7 +257,7 @@ class IDF_Scm_Svn extends IDF_Scm
                        escapeshellarg($this->repo.'/'.self::smartEncode($filename)),
                        escapeshellarg($rev));
         $cmd = Pluf::f('idf_exec_cmd_prefix', '').$cmd;
-        $xml = simplexml_load_string(shell_exec($cmd));
+        $xml = simplexml_load_string(self::shell_exec('IDF_Scm_Svn::getPathInfo', $cmd));
         if (!isset($xml->entry)) {
             return false;
         }
@@ -284,7 +284,8 @@ class IDF_Scm_Svn extends IDF_Scm
                        escapeshellarg($this->repo.'/'.self::smartEncode($def->fullpath)),
                        escapeshellarg($def->rev));
         $cmd = Pluf::f('idf_exec_cmd_prefix', '').$cmd;
-        return ($cmd_only) ? $cmd : shell_exec($cmd);
+        return ($cmd_only) ? 
+            $cmd : self::shell_exec('IDF_Scm_Svn::getFile', $cmd);
     }
 
     /**
@@ -303,7 +304,7 @@ class IDF_Scm_Svn extends IDF_Scm
                        escapeshellarg($this->password),
                        escapeshellarg($this->repo.'/branches'));
         $cmd = Pluf::f('idf_exec_cmd_prefix', '').$cmd;
-        exec($cmd, $out, $ret);
+        self::exec('IDF_Scm_Svn::getBranches', $cmd, $out, $ret);
         if ($ret == 0) {
             foreach ($out as $entry) {
                 if (substr(trim($entry), -1) == '/') {
@@ -318,7 +319,7 @@ class IDF_Scm_Svn extends IDF_Scm
                        escapeshellarg($this->password),
                        escapeshellarg($this->repo.'/trunk'));
         $cmd = Pluf::f('idf_exec_cmd_prefix', '').$cmd;
-        exec($cmd, $out, $ret);
+        self::exec('IDF_Scm_Svn::getBranches', $cmd, $out, $ret);
         if ($ret == 0) {
             $res = array('trunk' => 'trunk') + $res;
         }
@@ -342,7 +343,7 @@ class IDF_Scm_Svn extends IDF_Scm
                        escapeshellarg($this->password),
                        escapeshellarg($this->repo.'/tags'));
         $cmd = Pluf::f('idf_exec_cmd_prefix', '').$cmd;
-        exec($cmd, $out, $ret);
+        self::exec('IDF_Scm_Svn::getTags', $cmd, $out, $ret);
         if ($ret == 0) {
             foreach ($out as $entry) {
                 if (substr(trim($entry), -1) == '/') {
@@ -401,7 +402,7 @@ class IDF_Scm_Svn extends IDF_Scm
                        escapeshellarg($this->repo),
                        escapeshellarg($commit));
         $cmd = Pluf::f('idf_exec_cmd_prefix', '').$cmd;
-        $xmlRes = shell_exec($cmd);
+        $xmlRes = self::shell_exec('IDF_Scm_Svn::getCommit', $cmd);
         $xml = simplexml_load_string($xmlRes);
         $res['author'] = (string) $xml->logentry->author;
         $res['date'] = gmdate('Y-m-d H:i:s', strtotime((string) $xml->logentry->date));
@@ -430,7 +431,7 @@ class IDF_Scm_Svn extends IDF_Scm
                        escapeshellarg($commit),
                        escapeshellarg($repo));
         $cmd = Pluf::f('idf_exec_cmd_prefix', '').$cmd;
-        $out = shell_exec($cmd);
+        $out = self::shell_exec('IDF_Scm_Svn::isCommitLarge', $cmd);
         $lines = preg_split("/\015\012|\015|\012/", $out);
         return (count($lines) > 100);
     }
@@ -444,7 +445,7 @@ class IDF_Scm_Svn extends IDF_Scm
                        escapeshellarg($this->password),
                        escapeshellarg($this->repo));
         $cmd = Pluf::f('idf_exec_cmd_prefix', '').$cmd;
-        return shell_exec($cmd);
+        return self::shell_exec('IDF_Scm_Svn::getDiff', $cmd);
     }
 
 
@@ -470,7 +471,7 @@ class IDF_Scm_Svn extends IDF_Scm
                        escapeshellarg($this->repo),
                        escapeshellarg($branch));
         $cmd = Pluf::f('idf_exec_cmd_prefix', '').$cmd;
-        $xmlRes = shell_exec($cmd);
+        $xmlRes = self::shell_exec('IDF_Scm_Svn::getChangeLog', $cmd);
         $xml = simplexml_load_string($xmlRes);
         foreach ($xml->logentry as $entry) {
             $log = array();
@@ -502,7 +503,7 @@ class IDF_Scm_Svn extends IDF_Scm
                        escapeshellarg($this->repo.'/'.self::smartEncode($path)),
                        escapeshellarg($rev));
         $cmd = Pluf::f('idf_exec_cmd_prefix', '').$cmd;
-        $xmlProps = shell_exec($cmd);
+        $xmlProps = self::shell_exec('IDF_Scm_Svn::getProperties', $cmd);
         $props = simplexml_load_string($xmlProps);
 
         // No properties, returns an empty array
@@ -538,7 +539,7 @@ class IDF_Scm_Svn extends IDF_Scm
                        escapeshellarg($this->repo.'/'.self::smartEncode($path)),
                        escapeshellarg($rev));
         $cmd = Pluf::f('idf_exec_cmd_prefix', '').$cmd;
-        $xmlProp = shell_exec($cmd);
+        $xmlProp = self::shell_exec('IDF_Scm_Svn::getProperty', $cmd);
         $prop = simplexml_load_string($xmlProp);
 
         return (string) $prop->target->property;
@@ -561,7 +562,7 @@ class IDF_Scm_Svn extends IDF_Scm
                        escapeshellarg($this->repo),
                        escapeshellarg($rev));
         $cmd = Pluf::f('idf_exec_cmd_prefix', '').$cmd;
-        $xmlInfo = shell_exec($cmd);
+        $xmlInfo = self::shell_exec('IDF_Scm_Svn::getLastCommit', $cmd);
 
         $xml = simplexml_load_string($xmlInfo);
         return (string) $xml->entry->commit['revision'];