Add an optional protocol log to git SSH workflows

Summary:
Ref T8093. Support dumping the protocol bytes to a side channel logfile, as a precursor to parsing the protocol and rewriting protocol frames to virtualize refs.

The protocol itself is mostly ASCII text so the raw protocol bytes are pretty comprehensible.

Test Plan:
{F6363221}

{F6363222}

Reviewers: amckinley

Reviewed By: amckinley

Maniphest Tasks: T8093

Differential Revision: https://secure.phabricator.com/D20380

src/__phutil_library_map__.php

@@ -4284,6 +4284,7 @@ phutil_register_library_map(array(
     'PhabricatorProjectsSearchEngineExtension' => 'applications/project/engineextension/PhabricatorProjectsSearchEngineExtension.php',
     'PhabricatorProjectsWatchersSearchEngineAttachment' => 'applications/project/engineextension/PhabricatorProjectsWatchersSearchEngineAttachment.php',
     'PhabricatorPronounSetting' => 'applications/settings/setting/PhabricatorPronounSetting.php',
+    'PhabricatorProtocolLog' => 'infrastructure/log/PhabricatorProtocolLog.php',
     'PhabricatorPygmentSetupCheck' => 'applications/config/check/PhabricatorPygmentSetupCheck.php',
     'PhabricatorQuery' => 'infrastructure/query/PhabricatorQuery.php',
     'PhabricatorQueryConstraint' => 'infrastructure/query/constraint/PhabricatorQueryConstraint.php',
@@ -10491,6 +10492,7 @@ phutil_register_library_map(array(
     'PhabricatorProjectsSearchEngineExtension' => 'PhabricatorSearchEngineExtension',
     'PhabricatorProjectsWatchersSearchEngineAttachment' => 'PhabricatorSearchEngineAttachment',
     'PhabricatorPronounSetting' => 'PhabricatorSelectSetting',
+    'PhabricatorProtocolLog' => 'Phobject',
     'PhabricatorPygmentSetupCheck' => 'PhabricatorSetupCheck',
     'PhabricatorQuery' => 'Phobject',
     'PhabricatorQueryConstraint' => 'Phobject',

src/applications/diffusion/ssh/DiffusionGitReceivePackSSHWorkflow.php

@@ -28,7 +28,8 @@ final class DiffusionGitReceivePackSSHWorkflow extends DiffusionGitSSHWorkflow {
       ->setRepository($repository)
       ->setLog($this);
 
-    if ($this->shouldProxy()) {
+    $is_proxy = $this->shouldProxy();
+    if ($is_proxy) {
       $command = $this->getProxyCommand(true);
       $did_write = false;
 
@@ -51,6 +52,12 @@ final class DiffusionGitReceivePackSSHWorkflow extends DiffusionGitSSHWorkflow {
       }
     }
 
+    $log = $this->newProtocolLog($is_proxy);
+    if ($log) {
+      $this->setProtocolLog($log);
+      $log->didStartSession($command);
+    }
+
     $caught = null;
     try {
       $err = $this->executeRepositoryCommand($command);
@@ -58,6 +65,10 @@ final class DiffusionGitReceivePackSSHWorkflow extends DiffusionGitSSHWorkflow {
       $caught = $ex;
     }
 
+    if ($log) {
+      $log->didEndSession();
+    }
+
     // We've committed the write (or rejected it), so we can release the lock
     // without waiting for the client to receive the acknowledgement.
     if ($did_write) {

src/applications/diffusion/ssh/DiffusionGitSSHWorkflow.php

@@ -5,6 +5,7 @@ abstract class DiffusionGitSSHWorkflow
   implements DiffusionRepositoryClusterEngineLogInterface {
 
   private $engineLogProperties = array();
+  private $protocolLog;
 
   protected function writeError($message) {
     // Git assumes we'll add our own newlines.
@@ -55,4 +56,54 @@ abstract class DiffusionGitSSHWorkflow
         $repository->getVersionControlSystem()));
   }
 
+  protected function newPassthruCommand() {
+    return parent::newPassthruCommand()
+      ->setWillWriteCallback(array($this, 'willWriteMessageCallback'))
+      ->setWillReadCallback(array($this, 'willReadMessageCallback'));
+  }
+
+  protected function newProtocolLog($is_proxy) {
+    if ($is_proxy) {
+      return null;
+    }
+
+    // While developing, do this to write a full protocol log to disk:
+    //
+    // return new PhabricatorProtocolLog('/tmp/git-protocol.log');
+
+    return null;
+  }
+
+  protected function getProtocolLog() {
+    return $this->protocolLog;
+  }
+
+  protected function setProtocolLog(PhabricatorProtocolLog $log) {
+    $this->protocolLog = $log;
+  }
+
+  public function willWriteMessageCallback(
+    PhabricatorSSHPassthruCommand $command,
+    $message) {
+
+    $log = $this->getProtocolLog();
+    if ($log) {
+      $log->didWriteBytes($message);
+    }
+
+    return $message;
+  }
+
+  public function willReadMessageCallback(
+    PhabricatorSSHPassthruCommand $command,
+    $message) {
+
+    $log = $this->getProtocolLog();
+    if ($log) {
+      $log->didReadBytes($message);
+    }
+
+    return $message;
+  }
+
 }

src/applications/diffusion/ssh/DiffusionGitUploadPackSSHWorkflow.php

@@ -54,11 +54,21 @@ final class DiffusionGitUploadPackSSHWorkflow extends DiffusionGitSSHWorkflow {
     $future = id(new ExecFuture('%C', $command))
       ->setEnv($this->getEnvironment());
 
+    $log = $this->newProtocolLog($is_proxy);
+    if ($log) {
+      $this->setProtocolLog($log);
+      $log->didStartSession($command);
+    }
+
     $err = $this->newPassthruCommand()
       ->setIOChannel($this->getIOChannel())
       ->setCommandChannelFromExecFuture($future)
       ->execute();
 
+    if ($log) {
+      $log->didEndSession();
+    }
+
     if ($err) {
       $pull_event
         ->setResultType(PhabricatorRepositoryPullEvent::RESULT_ERROR)

src/infrastructure/log/PhabricatorProtocolLog.php

@@ -0,0 +1,193 @@
+<?php
+
+final class PhabricatorProtocolLog
+  extends Phobject {
+
+  private $logfile;
+  private $mode;
+  private $buffer = array();
+
+  public function __construct($logfile) {
+    $this->logfile = $logfile;
+  }
+
+  public function didStartSession($session_name) {
+    $this->setMode('!');
+    $this->buffer[] = $session_name;
+    $this->flush();
+  }
+
+  public function didEndSession() {
+    $this->setMode('_');
+    $this->buffer[] = pht('<End of Session>');
+    $this->flush();
+  }
+
+  public function didWriteBytes($bytes) {
+    if (!strlen($bytes)) {
+      return;
+    }
+
+    $this->setMode('>');
+    $this->buffer[] = $bytes;
+  }
+
+  public function didReadBytes($bytes) {
+    if (!strlen($bytes)) {
+      return;
+    }
+
+    $this->setMode('<');
+    $this->buffer[] = $bytes;
+  }
+
+  private function setMode($mode) {
+    if ($this->mode === $mode) {
+      return $this;
+    }
+
+    if ($this->mode !== null) {
+      $this->flush();
+    }
+
+    $this->mode = $mode;
+
+    return $this;
+  }
+
+  private function flush() {
+    $mode = $this->mode;
+    $bytes = $this->buffer;
+
+    $this->mode = null;
+    $this->buffer = array();
+
+    $bytes = implode('', $bytes);
+
+    if (strlen($bytes)) {
+      $this->writeBytes($mode, $bytes);
+    }
+  }
+
+  private function writeBytes($mode, $bytes) {
+    $header = $mode;
+    $len = strlen($bytes);
+
+    $out = array();
+    switch ($mode) {
+      case '<':
+        $out[] = pht('%s Write [%s bytes]', $header, new PhutilNumber($len));
+        break;
+      case '>':
+        $out[] = pht('%s Read [%s bytes]', $header, new PhutilNumber($len));
+        break;
+      default:
+        $out[] = pht(
+          '%s %s',
+          $header,
+          $this->escapeBytes($bytes));
+        break;
+    }
+
+    switch ($mode) {
+      case '<':
+      case '>':
+        $out[] = $this->renderBytes($header, $bytes);
+        break;
+    }
+
+    $out = implode("\n", $out)."\n\n";
+
+    $this->writeMessage($out);
+  }
+
+  private function renderBytes($header, $bytes) {
+    $bytes_per_line = 48;
+    $bytes_per_chunk = 4;
+
+    // Compute the width of the "bytes" display section, which looks like
+    // this:
+    //
+    // >  00112233 44556677  abcdefgh
+    //    ^^^^^^^^^^^^^^^^^
+    //
+    // We need to figure this out so we can align the plain text in the far
+    // right column appropriately.
+
+    // The character width of the "bytes" part of a full display line. If
+    // we're rendering 48 bytes per line, we'll need 96 characters, since
+    // each byte is printed as a 2-character hexadecimal code.
+    $display_bytes = ($bytes_per_line * 2);
+
+    // The character width of the number of spaces in between the "bytes"
+    // chunks. If we're rendering 12 chunks per line, we'll put 11 spaces
+    // in between them to separate them.
+    $display_spaces = (($bytes_per_line / $bytes_per_chunk) - 1);
+
+    $pad_bytes = $display_bytes + $display_spaces;
+
+    // When the protocol is plaintext, try to break it on newlines so it's
+    // easier to read.
+    $pos = 0;
+    $lines = array();
+    while (true) {
+      $next_break = strpos($bytes, "\n", $pos);
+      if ($next_break === false) {
+        $len = strlen($bytes) - $pos;
+      } else {
+        $len = ($next_break - $pos) + 1;
+      }
+      $len = min($bytes_per_line, $len);
+
+      $next_bytes = substr($bytes, $pos, $len);
+
+      $chunk_parts = array();
+      foreach (str_split($next_bytes, $bytes_per_chunk) as $chunk) {
+        $chunk_display = '';
+        for ($ii = 0; $ii < strlen($chunk); $ii++) {
+          $chunk_display .= sprintf('%02x', ord($chunk[$ii]));
+        }
+        $chunk_parts[] = $chunk_display;
+      }
+      $chunk_parts = implode(' ', $chunk_parts);
+
+      $chunk_parts = str_pad($chunk_parts, $pad_bytes, ' ');
+
+
+      $lines[] = $header.'  '.$chunk_parts.'  '.$this->escapeBytes($next_bytes);
+
+      $pos += $len;
+
+      if ($pos >= strlen($bytes)) {
+        break;
+      }
+    }
+
+    $lines = implode("\n", $lines);
+
+    return $lines;
+  }
+
+  private function escapeBytes($bytes) {
+    $result = '';
+    for ($ii = 0; $ii < strlen($bytes); $ii++) {
+      $c = $bytes[$ii];
+      $o = ord($c);
+
+      if ($o >= 0x20 && $o <= 0x7F) {
+        $result .= $c;
+      } else {
+        $result .= '.';
+      }
+    }
+    return $result;
+  }
+
+  private function writeMessage($message) {
+    $f = fopen($this->logfile, 'a');
+    fwrite($f, $message);
+    fflush($f);
+    fclose($f);
+  }
+
+}