Add a "lock log" for debugging where locks are being held

Summary: Depends on D19173. Ref T13096. Adds an optional, disabled-by-default lock log to make it easier to figure out what is acquiring and holding locks.

Test Plan: Ran `bin/lock log --enable`, `--disable`, `--name`, etc. Saw sensible-looking output with log enabled and daemons restarted. Saw no additional output with log disabled and daemons restarted.

Maniphest Tasks: T13096

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

bin/lock

@@ -0,0 +1 @@
+../scripts/setup/manage_lock.php

resources/sql/autopatches/20180305.lock.01.locklog.sql

@@ -0,0 +1,9 @@
+CREATE TABLE {$NAMESPACE}_daemon.daemon_locklog (
+  id INT UNSIGNED NOT NULL AUTO_INCREMENT PRIMARY KEY,
+  lockName VARCHAR(64) NOT NULL COLLATE {$COLLATE_TEXT},
+  lockReleased INT UNSIGNED,
+  lockParameters LONGTEXT NOT NULL COLLATE {$COLLATE_TEXT},
+  lockContext LONGTEXT NOT NULL COLLATE {$COLLATE_TEXT},
+  dateCreated INT UNSIGNED NOT NULL,
+  dateModified INT UNSIGNED NOT NULL
+) ENGINE=InnoDB, COLLATE {$COLLATE_TEXT};

scripts/setup/manage_lock.php

@@ -0,0 +1,21 @@
+#!/usr/bin/env php
+<?php
+
+$root = dirname(dirname(dirname(__FILE__)));
+require_once $root.'/scripts/init/init-script.php';
+
+$args = new PhutilArgumentParser($argv);
+$args->setTagline(pht('manage locks'));
+$args->setSynopsis(<<<EOSYNOPSIS
+**lock** __command__ [__options__]
+  Manage locks.
+
+EOSYNOPSIS
+  );
+$args->parseStandardArguments();
+
+$workflows = id(new PhutilClassMapQuery())
+  ->setAncestorClass('PhabricatorLockManagementWorkflow')
+  ->execute();
+$workflows[] = new PhutilHelpArgumentWorkflow();
+$args->parseWorkflows($workflows);

src/__phutil_library_map__.php

@@ -2670,6 +2670,8 @@ phutil_register_library_map(array(
     'PhabricatorDaemonController' => 'applications/daemon/controller/PhabricatorDaemonController.php',
     'PhabricatorDaemonDAO' => 'applications/daemon/storage/PhabricatorDaemonDAO.php',
     'PhabricatorDaemonEventListener' => 'applications/daemon/event/PhabricatorDaemonEventListener.php',
+    'PhabricatorDaemonLockLog' => 'applications/daemon/storage/PhabricatorDaemonLockLog.php',
+    'PhabricatorDaemonLockLogGarbageCollector' => 'applications/daemon/garbagecollector/PhabricatorDaemonLockLogGarbageCollector.php',
     'PhabricatorDaemonLog' => 'applications/daemon/storage/PhabricatorDaemonLog.php',
     'PhabricatorDaemonLogEvent' => 'applications/daemon/storage/PhabricatorDaemonLogEvent.php',
     'PhabricatorDaemonLogEventGarbageCollector' => 'applications/daemon/garbagecollector/PhabricatorDaemonLogEventGarbageCollector.php',
@@ -3204,6 +3206,8 @@ phutil_register_library_map(array(
     'PhabricatorLocalTimeTestCase' => 'view/__tests__/PhabricatorLocalTimeTestCase.php',
     'PhabricatorLocaleScopeGuard' => 'infrastructure/internationalization/scope/PhabricatorLocaleScopeGuard.php',
     'PhabricatorLocaleScopeGuardTestCase' => 'infrastructure/internationalization/scope/__tests__/PhabricatorLocaleScopeGuardTestCase.php',
+    'PhabricatorLockLogManagementWorkflow' => 'applications/daemon/management/PhabricatorLockLogManagementWorkflow.php',
+    'PhabricatorLockManagementWorkflow' => 'applications/daemon/management/PhabricatorLockManagementWorkflow.php',
     'PhabricatorLogTriggerAction' => 'infrastructure/daemon/workers/action/PhabricatorLogTriggerAction.php',
     'PhabricatorLogoutController' => 'applications/auth/controller/PhabricatorLogoutController.php',
     'PhabricatorLunarPhasePolicyRule' => 'applications/policy/rule/PhabricatorLunarPhasePolicyRule.php',
@@ -8194,6 +8198,8 @@ phutil_register_library_map(array(
     'PhabricatorDaemonController' => 'PhabricatorController',
     'PhabricatorDaemonDAO' => 'PhabricatorLiskDAO',
     'PhabricatorDaemonEventListener' => 'PhabricatorEventListener',
+    'PhabricatorDaemonLockLog' => 'PhabricatorDaemonDAO',
+    'PhabricatorDaemonLockLogGarbageCollector' => 'PhabricatorGarbageCollector',
     'PhabricatorDaemonLog' => array(
       'PhabricatorDaemonDAO',
       'PhabricatorPolicyInterface',
@@ -8794,6 +8800,8 @@ phutil_register_library_map(array(
     'PhabricatorLocalTimeTestCase' => 'PhabricatorTestCase',
     'PhabricatorLocaleScopeGuard' => 'Phobject',
     'PhabricatorLocaleScopeGuardTestCase' => 'PhabricatorTestCase',
+    'PhabricatorLockLogManagementWorkflow' => 'PhabricatorLockManagementWorkflow',
+    'PhabricatorLockManagementWorkflow' => 'PhabricatorManagementWorkflow',
     'PhabricatorLogTriggerAction' => 'PhabricatorTriggerAction',
     'PhabricatorLogoutController' => 'PhabricatorAuthController',
     'PhabricatorLunarPhasePolicyRule' => 'PhabricatorPolicyRule',

src/applications/daemon/garbagecollector/PhabricatorDaemonLockLogGarbageCollector.php

@@ -0,0 +1,29 @@
+<?php
+
+final class PhabricatorDaemonLockLogGarbageCollector
+  extends PhabricatorGarbageCollector {
+
+  const COLLECTORCONST = 'daemon.lock-log';
+
+  public function getCollectorName() {
+    return pht('Lock Logs');
+  }
+
+  public function getDefaultRetentionPolicy() {
+    return 0;
+  }
+
+  protected function collectGarbage() {
+    $table = new PhabricatorDaemonLockLog();
+    $conn = $table->establishConnection('w');
+
+    queryfx(
+      $conn,
+      'DELETE FROM %T WHERE dateCreated < %d LIMIT 100',
+      $table->getTableName(),
+      $this->getGarbageEpoch());
+
+    return ($conn->getAffectedRows() == 100);
+  }
+
+}

src/applications/daemon/management/PhabricatorLockLogManagementWorkflow.php

@@ -0,0 +1,222 @@
+<?php
+
+final class PhabricatorLockLogManagementWorkflow
+  extends PhabricatorLockManagementWorkflow {
+
+  protected function didConstruct() {
+    $this
+      ->setName('log')
+      ->setSynopsis(pht('Enable, disable, or show the lock log.'))
+      ->setArguments(
+        array(
+          array(
+            'name' => 'enable',
+            'help' => pht('Enable the lock log.'),
+          ),
+          array(
+            'name' => 'disable',
+            'help' => pht('Disable the lock log.'),
+          ),
+          array(
+            'name' => 'name',
+            'param' => 'name',
+            'help' => pht('Review logs for a specific lock.'),
+          ),
+        ));
+  }
+
+  public function execute(PhutilArgumentParser $args) {
+    $is_enable = $args->getArg('enable');
+    $is_disable = $args->getArg('disable');
+
+    if ($is_enable && $is_disable) {
+      throw new PhutilArgumentUsageException(
+        pht(
+          'You can not both "--enable" and "--disable" the lock log.'));
+    }
+
+    $with_name = $args->getArg('name');
+
+    if ($is_enable || $is_disable) {
+      if (strlen($with_name)) {
+        throw new PhutilArgumentUsageException(
+          pht(
+            'You can not both "--enable" or "--disable" with search '.
+            'parameters like "--name".'));
+      }
+
+      $gc = new PhabricatorDaemonLockLogGarbageCollector();
+      $is_enabled = (bool)$gc->getRetentionPolicy();
+
+      $config_key = 'phd.garbage-collection';
+      $const = $gc->getCollectorConstant();
+      $value = PhabricatorEnv::getEnvConfig($config_key);
+
+      if ($is_disable) {
+        if (!$is_enabled) {
+          echo tsprintf(
+            "%s\n",
+            pht('Lock log is already disabled.'));
+          return 0;
+        }
+        echo tsprintf(
+          "%s\n",
+          pht('Disabling the lock log.'));
+
+        unset($value[$const]);
+      } else {
+        if ($is_enabled) {
+          echo tsprintf(
+            "%s\n",
+            pht('Lock log is already enabled.'));
+          return 0;
+        }
+        echo tsprintf(
+          "%s\n",
+          pht('Enabling the lock log.'));
+
+        $value[$const] = phutil_units('24 hours in seconds');
+      }
+
+      id(new PhabricatorConfigLocalSource())
+        ->setKeys(
+          array(
+            $config_key => $value,
+          ));
+
+      echo tsprintf(
+        "%s\n",
+        pht('Done.'));
+
+      echo tsprintf(
+        "%s\n",
+        pht('Restart daemons to apply changes.'));
+
+      return 0;
+    }
+
+    $table = new PhabricatorDaemonLockLog();
+    $conn = $table->establishConnection('r');
+
+    $parts = array();
+    if (strlen($with_name)) {
+      $parts[] = qsprintf(
+        $conn,
+        'lockName = %s',
+        $with_name);
+    }
+
+    if (!$parts) {
+      $constraint = '1 = 1';
+    } else {
+      $constraint = '('.implode(') AND (', $parts).')';
+    }
+
+    $logs = $table->loadAllWhere(
+      '%Q ORDER BY id DESC LIMIT 100',
+      $constraint);
+    $logs = array_reverse($logs);
+
+    if (!$logs) {
+      echo tsprintf(
+        "%s\n",
+        pht('No matching lock logs.'));
+      return 0;
+    }
+
+    $table = id(new PhutilConsoleTable())
+      ->setBorders(true)
+      ->addColumn(
+        'id',
+        array(
+          'title' => pht('Lock'),
+        ))
+      ->addColumn(
+        'name',
+        array(
+          'title' => pht('Name'),
+        ))
+      ->addColumn(
+        'acquired',
+        array(
+          'title' => pht('Acquired'),
+        ))
+      ->addColumn(
+        'released',
+        array(
+          'title' => pht('Released'),
+        ))
+      ->addColumn(
+        'held',
+        array(
+          'title' => pht('Held'),
+        ))
+      ->addColumn(
+        'parameters',
+        array(
+          'title' => pht('Parameters'),
+        ))
+      ->addColumn(
+        'context',
+        array(
+          'title' => pht('Context'),
+        ));
+
+    $viewer = $this->getViewer();
+
+    foreach ($logs as $log) {
+      $created = $log->getDateCreated();
+      $released = $log->getLockReleased();
+
+      if ($released) {
+        $held = '+'.($released - $created);
+      } else {
+        $held = null;
+      }
+
+      $created = phabricator_datetime($created, $viewer);
+      $released = phabricator_datetime($released, $viewer);
+
+      $parameters = $log->getLockParameters();
+      $context = $log->getLockContext();
+
+      $table->addRow(
+        array(
+          'id' => $log->getID(),
+          'name' => $log->getLockName(),
+          'acquired' => $created,
+          'released' => $released,
+          'held' => $held,
+          'parameters' => $this->flattenParameters($parameters),
+          'context' => $this->flattenParameters($context),
+        ));
+    }
+
+    $table->draw();
+
+    return 0;
+  }
+
+  private function flattenParameters(array $params, $keys = true) {
+    $flat = array();
+    foreach ($params as $key => $value) {
+      if (is_array($value)) {
+        $value = $this->flattenParameters($value, false);
+      }
+      if ($keys) {
+        $flat[] = "{$key}={$value}";
+      } else {
+        $flat[] = "{$value}";
+      }
+    }
+
+    if ($keys) {
+      $flat = implode(', ', $flat);
+    } else {
+      $flat = implode(' ', $flat);
+    }
+
+    return $flat;
+  }
+
+}

src/applications/daemon/management/PhabricatorLockManagementWorkflow.php

@@ -0,0 +1,4 @@
+<?php
+
+abstract class PhabricatorLockManagementWorkflow
+  extends PhabricatorManagementWorkflow {}

src/applications/daemon/storage/PhabricatorDaemonLockLog.php

@@ -0,0 +1,32 @@
+<?php
+
+final class PhabricatorDaemonLockLog
+  extends PhabricatorDaemonDAO {
+
+  protected $lockName;
+  protected $lockReleased;
+  protected $lockParameters = array();
+  protected $lockContext = array();
+
+  protected function getConfiguration() {
+    return array(
+      self::CONFIG_SERIALIZATION => array(
+        'lockParameters' => self::SERIALIZATION_JSON,
+        'lockContext' => self::SERIALIZATION_JSON,
+      ),
+      self::CONFIG_COLUMN_SCHEMA => array(
+        'lockName' => 'text64',
+        'lockReleased' => 'epoch?',
+      ),
+      self::CONFIG_KEY_SCHEMA => array(
+        'key_lock' => array(
+          'columns' => array('lockName'),
+        ),
+        'key_created' => array(
+          'columns' => array('dateCreated'),
+        ),
+      ),
+    ) + parent::getConfiguration();
+  }
+
+}

src/infrastructure/daemon/garbagecollector/PhabricatorGarbageCollector.php

@@ -100,8 +100,10 @@ abstract class PhabricatorGarbageCollector extends Phobject {
 
     // Hold a lock while performing collection to avoid racing other daemons
     // running the same collectors.
-    $lock_name = 'gc:'.$this->getCollectorConstant();
-    $lock = PhabricatorGlobalLock::newLock($lock_name);
+    $params = array(
+      'collector' => $this->getCollectorConstant(),
+    );
+    $lock = PhabricatorGlobalLock::newLock('gc', $params);
 
     try {
       $lock->lock(5);

src/infrastructure/storage/management/workflow/PhabricatorStorageManagementWorkflow.php

@@ -1163,12 +1163,16 @@ abstract class PhabricatorStorageManagementWorkflow
     // Although we're holding this lock on different databases so it could
     // have the same name on each as far as the database is concerned, the
     // locks would be the same within this process.
-    $ref_key = $api->getRef()->getRefKey();
-    $ref_hash = PhabricatorHash::digestForIndex($ref_key);
-    $lock_name = 'adjust('.$ref_hash.')';
+    $parameters = array(
+      'refKey' => $api->getRef()->getRefKey(),
+    );
 
-    return PhabricatorGlobalLock::newLock($lock_name)
+    // We disable logging for this lock because we may not have created the
+    // log table yet, or may need to adjust it.
+
+    return PhabricatorGlobalLock::newLock('adjust', $parameters)
       ->useSpecificConnection($api->getConn(null))
+      ->setDisableLogging(true)
       ->lock();
   }
 

src/infrastructure/util/PhabricatorGlobalLock.php

@@ -31,6 +31,8 @@ final class PhabricatorGlobalLock extends PhutilLock {
   private $parameters;
   private $conn;
   private $isExternalConnection = false;
+  private $log;
+  private $disableLogging;
 
   private static $pool = array();
 
@@ -95,6 +97,11 @@ final class PhabricatorGlobalLock extends PhutilLock {
     return $this;
   }
 
+  public function setDisableLogging($disable) {
+    $this->disableLogging = $disable;
+    return $this;
+  }
+
 
 /* -(  Implementation  )----------------------------------------------------- */
 
@@ -143,6 +150,24 @@ final class PhabricatorGlobalLock extends PhutilLock {
     $conn->rememberLock($lock_name);
 
     $this->conn = $conn;
+
+    if ($this->shouldLogLock()) {
+      global $argv;
+
+      $lock_context = array(
+        'pid' => getmypid(),
+        'host' => php_uname('n'),
+        'argv' => $argv,
+      );
+
+      $log = id(new PhabricatorDaemonLockLog())
+        ->setLockName($lock_name)
+        ->setLockParameters($this->parameters)
+        ->setLockContext($lock_context)
+        ->save();
+
+      $this->log = $log;
+    }
   }
 
   protected function doUnlock() {
@@ -175,6 +200,32 @@ final class PhabricatorGlobalLock extends PhutilLock {
       $conn->close();
       self::$pool[] = $conn;
     }
+
+    if ($this->log) {
+      $log = $this->log;
+      $this->log = null;
+
+      $conn = $log->establishConnection('w');
+      queryfx(
+        $conn,
+        'UPDATE %T SET lockReleased = UNIX_TIMESTAMP() WHERE id = %d',
+        $log->getTableName(),
+        $log->getID());
+    }
+  }
+
+  private function shouldLogLock() {
+    if ($this->disableLogging) {
+      return false;
+    }
+
+    $policy = id(new PhabricatorDaemonLockLogGarbageCollector())
+      ->getRetentionPolicy();
+    if (!$policy) {
+      return false;
+    }
+
+    return true;
   }
 
 }