[PATCH 3 of 3 V2] lock: allow to configure when the lock messages are displayed

[Boris Feld]

# HG changeset patch
# User Boris Feld <boris.feld at octobus.net>
# Date 1512005999 18000
#      Wed Nov 29 20:39:59 2017 -0500
# Node ID b727ac51b2e57c1ae65eb8d33264609cf92c15ac
# Parent  25564a60ab9e4446256a2bde0af18186f6094755
# EXP-Topic lock-message
# Available At https://bitbucket.org/octobus/mercurial-devel/
#              hg pull https://bitbucket.org/octobus/mercurial-devel/ -r b727ac51b2e5
lock: allow to configure when the lock messages are displayed

We add a new 'ui.timeout.warn' config to set a grace period before we display
lock related warning:

    waiting for lock on PATH held by PROCESS

The config is based on 'ui.timeout' and expresses a number of seconds before
the warning is displayed. Negative values disable the warning altogether.

The messages go to the debug output to help people trouble-shooting deadlocks.

diff --git a/mercurial/configitems.py b/mercurial/configitems.py
--- a/mercurial/configitems.py
+++ b/mercurial/configitems.py
@@ -985,6 +985,9 @@ coreconfigitem('ui', 'textwidth',
 coreconfigitem('ui', 'timeout',
     default='600',
 )
+coreconfigitem('ui', 'timeout.warn',
+    default=0,
+)
 coreconfigitem('ui', 'traceback',
     default=False,
 )
diff --git a/mercurial/help/config.txt b/mercurial/help/config.txt
--- a/mercurial/help/config.txt
+++ b/mercurial/help/config.txt
@@ -2215,6 +2215,10 @@ User interface controls.
     The timeout used when a lock is held (in seconds), a negative value
     means no timeout. (default: 600)
 
+``timeout.warn``
+    Time (in seconds) before a warning is printed about held lock. A negative
+    value means no warning. (default: 0)
+
 ``traceback``
     Mercurial always prints a traceback when an unknown exception
     occurs. Setting this to True will make Mercurial print a traceback
diff --git a/mercurial/localrepo.py b/mercurial/localrepo.py
--- a/mercurial/localrepo.py
+++ b/mercurial/localrepo.py
@@ -1592,10 +1592,12 @@ class localrepository(object):
             parentlock = encoding.environ.get(parentenvvar)
 
         timeout = 0
+        warntimeout = 0
         if wait:
             timeout = self.ui.configint("ui", "timeout")
+            warntimeout = self.ui.configint("ui", "timeout.warn")
 
-        l = lockmod.trylock(self.ui, vfs, lockname, timeout,
+        l = lockmod.trylock(self.ui, vfs, lockname, timeout, warntimeout,
                             releasefn=releasefn,
                             acquirefn=acquirefn, desc=desc,
                             inheritchecker=inheritchecker,
diff --git a/mercurial/lock.py b/mercurial/lock.py
--- a/mercurial/lock.py
+++ b/mercurial/lock.py
@@ -41,11 +41,11 @@ def _getlockprefix():
                 raise
     return result
 
-def trylock(ui, vfs, lockname, timeout, *args, **kwargs):
+def trylock(ui, vfs, lockname, timeout, warntimeout, *args, **kwargs):
     """return an acquired lock or raise an a LockHeld exception
 
-    This function is responsible to issue warnings about the held lock while
-    trying to acquires it."""
+    This function is responsible to issue warnings and or debug messages about
+    the held lock while trying to acquires it."""
 
     def printwarning(printer, locker):
         """issue the usual "waiting on lock" message through any channel"""
@@ -60,9 +60,12 @@ def trylock(ui, vfs, lockname, timeout, 
 
     l = lock(vfs, lockname, 0, *args, dolock=False, **kwargs)
 
+    debugidx = 0 if (warntimeout and timeout) else -1
     warningidx = 0
     if not timeout:
         warningidx = -1
+    elif warntimeout:
+        warningidx = warntimeout
 
     delay = 0
     while True:
@@ -70,6 +73,8 @@ def trylock(ui, vfs, lockname, timeout, 
             l._trylock()
             break
         except error.LockHeld as inst:
+            if delay == debugidx:
+                printwarning(ui.debug, inst.locker)
             if delay == warningidx:
                 printwarning(ui.warn, inst.locker)
             if timeout <= delay:
@@ -80,7 +85,10 @@ def trylock(ui, vfs, lockname, timeout, 
 
     l.delay = delay
     if l.delay:
-        ui.warn(_("got lock after %s seconds\n") % l.delay)
+        if 0 <= warningidx <= l.delay:
+            ui.warn(_("got lock after %s seconds\n") % l.delay)
+        else:
+            ui.debug("got lock after %s seconds\n" % l.delay)
     if l.acquirefn:
         l.acquirefn()
     return l
diff --git a/tests/test-lock-badness.t b/tests/test-lock-badness.t
--- a/tests/test-lock-badness.t
+++ b/tests/test-lock-badness.t
@@ -57,14 +57,77 @@ One process waiting for another
   $ echo b > b/b
   $ hg -R b ci -A -m b --config hooks.precommit="python:`pwd`/hooks.py:sleepone" > stdout &
   $ hg -R b up -q --config hooks.pre-update="python:`pwd`/hooks.py:sleephalf" \
-  > > preup 2>&1
+  > > preup-stdout 2>preup-stderr
   $ wait
-  $ cat preup
+  $ cat preup-stdout
+  $ cat preup-stderr
   waiting for lock on working directory of b held by process '*' on host '*' (glob)
   got lock after * seconds (glob)
   $ cat stdout
   adding b
 
+On processs waiting on another, warning after a long time.
+
+  $ echo b > b/c
+  $ hg -R b ci -A -m b --config hooks.precommit="python:`pwd`/hooks.py:sleepone" > stdout &
+  $ hg -R b up -q --config hooks.pre-update="python:`pwd`/hooks.py:sleephalf" \
+  > --config ui.timeout.warn=250 \
+  > > preup-stdout 2>preup-stderr
+  $ wait
+  $ cat preup-stdout
+  $ cat preup-stderr
+  $ cat stdout
+  adding c
+
+On processs waiting on another, warning disabled.
+
+  $ echo b > b/d
+  $ hg -R b ci -A -m b --config hooks.precommit="python:`pwd`/hooks.py:sleepone" > stdout &
+  $ hg -R b up -q --config hooks.pre-update="python:`pwd`/hooks.py:sleephalf" \
+  > --config ui.timeout.warn=-1 \
+  > > preup-stdout 2>preup-stderr
+  $ wait
+  $ cat preup-stdout
+  $ cat preup-stderr
+  $ cat stdout
+  adding d
+
+check we still print debug output
+
+On processs waiting on another, warning after a long time (debug output on)
+
+  $ echo b > b/e
+  $ hg -R b ci -A -m b --config hooks.precommit="python:`pwd`/hooks.py:sleepone" > stdout &
+  $ hg -R b up --config hooks.pre-update="python:`pwd`/hooks.py:sleephalf" \
+  > --config ui.timeout.warn=250 --debug\
+  > > preup-stdout 2>preup-stderr
+  $ wait
+  $ cat preup-stdout
+  calling hook pre-update: hghook_pre-update.sleephalf
+  waiting for lock on working directory of b held by process '*' on host '*' (glob)
+  got lock after * seconds (glob)
+  0 files updated, 0 files merged, 0 files removed, 0 files unresolved
+  $ cat preup-stderr
+  $ cat stdout
+  adding e
+
+On processs waiting on another, warning disabled, (debug output on)
+
+  $ echo b > b/f
+  $ hg -R b ci -A -m b --config hooks.precommit="python:`pwd`/hooks.py:sleepone" > stdout &
+  $ hg -R b up --config hooks.pre-update="python:`pwd`/hooks.py:sleephalf" \
+  > --config ui.timeout.warn=-1 --debug\
+  > > preup-stdout 2>preup-stderr
+  $ wait
+  $ cat preup-stdout
+  calling hook pre-update: hghook_pre-update.sleephalf
+  waiting for lock on working directory of b held by process '*' on host '*' (glob)
+  got lock after * seconds (glob)
+  0 files updated, 0 files merged, 0 files removed, 0 files unresolved
+  $ cat preup-stderr
+  $ cat stdout
+  adding f
+
 Pushing to a local read-only repo that can't be locked
 
   $ chmod 100 a/.hg/store