test-chg: stabilize the log checking

The "worker process exited" line have been making the CI flaky for a long time.
Lets sort this out.

tests/test-chg.t

@@ -1,572 +1,575 b''
 #require chg
 
 Scale the timeout for the chg-server to the test timeout scaling.
 This is done to reduce the flakiness of this test on heavy load.
 
   $ CHGTIMEOUT=`expr $HGTEST_TIMEOUT / 6`
   $ export CHGTIMEOUT
 
   $ mkdir log
   $ cp $HGRCPATH $HGRCPATH.unconfigured
   $ cat <<'EOF' >> $HGRCPATH
   > [cmdserver]
   > log = $TESTTMP/log/server.log
   > max-log-files = 1
   > max-log-size = 10 kB
   > EOF
   $ cp $HGRCPATH $HGRCPATH.orig
 
   $ filterlog () {
   >   sed -e 's!^[0-9/]* [0-9:]* ([0-9]*)>!YYYY/MM/DD HH:MM:SS (PID)>!' \
   >       -e 's!\(setprocname\|received fds\|setenv\): .*!\1: ...!' \
   >       -e 's!\(confighash\|mtimehash\) = [0-9a-f]*!\1 = ...!g' \
   >       -e 's!\(in \)[0-9.]*s\b!\1 ...s!g' \
   >       -e 's!\(pid\)=[0-9]*!\1=...!g' \
   >       -e 's!\(/server-\)[0-9a-f]*!\1...!g'
   > }
 
 init repo
 
   $ chg init foo
   $ cd foo
 
 ill-formed config
 
   $ chg status
   $ echo '=brokenconfig' >> $HGRCPATH
   $ chg status
   config error at * =brokenconfig (glob)
   [30]
 
   $ cp $HGRCPATH.orig $HGRCPATH
 
 long socket path
 
   $ sockpath=$TESTTMP/this/path/should/be/longer/than/one-hundred-and-seven/characters/where/107/is/the/typical/size/limit/of/unix-domain-socket
   $ mkdir -p $sockpath
   $ bakchgsockname=$CHGSOCKNAME
   $ CHGSOCKNAME=$sockpath/server
   $ export CHGSOCKNAME
   $ chg root
   $TESTTMP/foo
   $ rm -rf $sockpath
   $ CHGSOCKNAME=$bakchgsockname
   $ export CHGSOCKNAME
 
   $ cd ..
 
 editor
 ------
 
   $ cat >> pushbuffer.py <<EOF
   > def reposetup(ui, repo):
   >     repo.ui.pushbuffer(subproc=True)
   > EOF
 
   $ chg init editor
   $ cd editor
 
 by default, system() should be redirected to the client:
 
   $ touch foo
   $ CHGDEBUG= HGEDITOR=cat chg ci -Am channeled --edit 2>&1 \
   > | grep -E "HG:|run 'cat"
   chg: debug: * run 'cat "*"' at '$TESTTMP/editor' (glob)
   HG: Enter commit message.  Lines beginning with 'HG:' are removed.
   HG: Leave message empty to abort commit.
   HG: --
   HG: user: test
   HG: branch 'default'
   HG: added foo
 
 but no redirection should be made if output is captured:
 
   $ touch bar
   $ CHGDEBUG= HGEDITOR=cat chg ci -Am bufferred --edit \
   > --config extensions.pushbuffer="$TESTTMP/pushbuffer.py" 2>&1 \
   > | grep -E "HG:|run 'cat"
   [1]
 
 check that commit commands succeeded:
 
   $ hg log -T '{rev}:{desc}\n'
   1:bufferred
   0:channeled
 
   $ cd ..
 
 pager
 -----
 
   $ cat >> fakepager.py <<EOF
   > import sys
   > for line in sys.stdin:
   >     sys.stdout.write('paged! %r\n' % line)
   > EOF
 
 enable pager extension globally, but spawns the master server with no tty:
 
   $ chg init pager
   $ cd pager
   $ cat >> $HGRCPATH <<EOF
   > [extensions]
   > pager =
   > [pager]
   > pager = "$PYTHON" $TESTTMP/fakepager.py
   > EOF
   $ chg version > /dev/null
   $ touch foo
   $ chg ci -qAm foo
 
 pager should be enabled if the attached client has a tty:
 
   $ chg log -l1 -q --config ui.formatted=True
   paged! '0:1f7b0de80e11\n'
   $ chg log -l1 -q --config ui.formatted=False
   0:1f7b0de80e11
 
 chg waits for pager if runcommand raises
 
   $ cat > $TESTTMP/crash.py <<EOF
   > from mercurial import registrar
   > cmdtable = {}
   > command = registrar.command(cmdtable)
   > @command(b'crash')
   > def pagercrash(ui, repo, *pats, **opts):
   >     ui.write(b'going to crash\n')
   >     raise Exception('.')
   > EOF
 
   $ cat > $TESTTMP/fakepager.py <<EOF
   > import sys
   > import time
   > for line in iter(sys.stdin.readline, ''):
   >     if 'crash' in line: # only interested in lines containing 'crash'
   >         # if chg exits when pager is sleeping (incorrectly), the output
   >         # will be captured by the next test case
   >         time.sleep(1)
   >         sys.stdout.write('crash-pager: %s' % line)
   > EOF
 
   $ cat >> .hg/hgrc <<EOF
   > [extensions]
   > crash = $TESTTMP/crash.py
   > EOF
 
   $ chg crash --pager=on --config ui.formatted=True 2>/dev/null
   crash-pager: going to crash
   [255]
 
 no stdout data should be printed after pager quits, and the buffered data
 should never persist (issue6207)
 
 "killed!" may be printed if terminated by SIGPIPE, which isn't important
 in this test.
 
   $ cat > $TESTTMP/bulkwrite.py <<'EOF'
   > import time
   > from mercurial import error, registrar
   > cmdtable = {}
   > command = registrar.command(cmdtable)
   > @command(b'bulkwrite')
   > def bulkwrite(ui, repo, *pats, **opts):
   >     ui.write(b'going to write massive data\n')
   >     ui.flush()
   >     t = time.time()
   >     while time.time() - t < 2:
   >         ui.write(b'x' * 1023 + b'\n')  # will be interrupted by SIGPIPE
   >     raise error.Abort(b"write() doesn't block")
   > EOF
 
   $ cat > $TESTTMP/fakepager.py <<'EOF'
   > import sys
   > import time
   > sys.stdout.write('paged! %r\n' % sys.stdin.readline())
   > time.sleep(1)  # new data will be written
   > EOF
 
   $ cat >> .hg/hgrc <<EOF
   > [extensions]
   > bulkwrite = $TESTTMP/bulkwrite.py
   > EOF
 
   $ chg bulkwrite --pager=on --color no --config ui.formatted=True
   paged! 'going to write massive data\n'
   killed! (?)
   [255]
 
   $ chg bulkwrite --pager=on --color no --config ui.formatted=True
   paged! 'going to write massive data\n'
   killed! (?)
   [255]
 
   $ cd ..
 
 missing stdio
 -------------
 
   $ CHGDEBUG=1 chg version -q 0<&-
   chg: debug: * stdio fds are missing (glob)
   chg: debug: * execute original hg (glob)
   Mercurial Distributed SCM * (glob)
 
 server lifecycle
 ----------------
 
 chg server should be restarted on code change, and old server will shut down
 automatically. In this test, we use the following time parameters:
 
  - "sleep 1" to make mtime different
  - "sleep 2" to notice mtime change (polling interval is 1 sec)
 
 set up repository with an extension:
 
   $ chg init extreload
   $ cd extreload
   $ touch dummyext.py
   $ cat <<EOF >> .hg/hgrc
   > [extensions]
   > dummyext = dummyext.py
   > EOF
 
 isolate socket directory for stable result:
 
   $ OLDCHGSOCKNAME=$CHGSOCKNAME
   $ mkdir chgsock
   $ CHGSOCKNAME=`pwd`/chgsock/server
 
 warm up server:
 
   $ CHGDEBUG= chg log 2>&1 | grep -E 'instruction|start'
   chg: debug: * start cmdserver at $TESTTMP/extreload/chgsock/server.* (glob)
 
 new server should be started if extension modified:
 
   $ sleep 1
   $ touch dummyext.py
   $ CHGDEBUG= chg log 2>&1 | grep -E 'instruction|start'
   chg: debug: * instruction: unlink $TESTTMP/extreload/chgsock/server-* (glob)
   chg: debug: * instruction: reconnect (glob)
   chg: debug: * start cmdserver at $TESTTMP/extreload/chgsock/server.* (glob)
 
 old server will shut down, while new server should still be reachable:
 
   $ sleep 2
   $ CHGDEBUG= chg log 2>&1 | (grep -E 'instruction|start' || true)
 
 socket file should never be unlinked by old server:
 (simulates unowned socket by updating mtime, which makes sure server exits
 at polling cycle)
 
   $ ls chgsock/server-*
   chgsock/server-* (glob)
   $ touch chgsock/server-*
   $ sleep 2
   $ ls chgsock/server-*
   chgsock/server-* (glob)
 
 since no server is reachable from socket file, new server should be started:
 (this test makes sure that old server shut down automatically)
 
   $ CHGDEBUG= chg log 2>&1 | grep -E 'instruction|start'
   chg: debug: * start cmdserver at $TESTTMP/extreload/chgsock/server.* (glob)
 
 shut down servers and restore environment:
 
   $ rm -R chgsock
   $ sleep 2
   $ CHGSOCKNAME=$OLDCHGSOCKNAME
   $ cd ..
 
 check that server events are recorded:
 
   $ ls log
   server.log
   server.log.1
 
 print only the last 10 lines, since we aren't sure how many records are
 preserved (since setprocname isn't available on py3 and pure version,
 the 10th-most-recent line is different when using py3):
 
-  $ cat log/server.log.1 log/server.log | tail -10 | filterlog
+(the "worker process exited" line is matched independently as it order is unstable with the "exiting" line, the worker might exit before the server decide to exit).
+
+  $ cat log/server.log.1 log/server.log | tail -10 | grep -v "worker process exited" | filterlog
   YYYY/MM/DD HH:MM:SS (PID)> confighash = ... mtimehash = ... (no-setprocname !)
   YYYY/MM/DD HH:MM:SS (PID)> forked worker process (pid=...)
   YYYY/MM/DD HH:MM:SS (PID)> setprocname: ... (setprocname !)
   YYYY/MM/DD HH:MM:SS (PID)> received fds: ...
   YYYY/MM/DD HH:MM:SS (PID)> chdir to '$TESTTMP/extreload'
   YYYY/MM/DD HH:MM:SS (PID)> setumask 18
   YYYY/MM/DD HH:MM:SS (PID)> setenv: ...
   YYYY/MM/DD HH:MM:SS (PID)> confighash = ... mtimehash = ...
   YYYY/MM/DD HH:MM:SS (PID)> validate: []
+  YYYY/MM/DD HH:MM:SS (PID)> $TESTTMP/extreload/chgsock/server-... is not owned, exiting.
+  $ cat log/server.log.1 log/server.log | tail -10 | grep "worker process exited" | filterlog
   YYYY/MM/DD HH:MM:SS (PID)> worker process exited (pid=...)
-  YYYY/MM/DD HH:MM:SS (PID)> $TESTTMP/extreload/chgsock/server-... is not owned, exiting.
 
 global data mutated by schems
 -----------------------------
 
   $ hg init schemes
   $ cd schemes
 
 initial state
 
   $ cat > .hg/hgrc <<'EOF'
   > [extensions]
   > schemes =
   > [schemes]
   > foo = https://foo.example.org/
   > EOF
   $ hg debugexpandscheme foo://expanded
   https://foo.example.org/expanded
   $ hg debugexpandscheme bar://unexpanded
   bar://unexpanded
 
 add bar
 
   $ cat > .hg/hgrc <<'EOF'
   > [extensions]
   > schemes =
   > [schemes]
   > foo = https://foo.example.org/
   > bar = https://bar.example.org/
   > EOF
   $ hg debugexpandscheme foo://expanded
   https://foo.example.org/expanded
   $ hg debugexpandscheme bar://expanded
   https://bar.example.org/expanded
 
 remove foo
 
   $ cat > .hg/hgrc <<'EOF'
   > [extensions]
   > schemes =
   > [schemes]
   > bar = https://bar.example.org/
   > EOF
   $ hg debugexpandscheme foo://unexpanded
   foo://unexpanded
   $ hg debugexpandscheme bar://expanded
   https://bar.example.org/expanded
 
   $ cd ..
 
 repository cache
 ----------------
 
   $ cp $HGRCPATH.unconfigured $HGRCPATH
   $ cat <<'EOF' >> $HGRCPATH
   > [cmdserver]
   > log = $TESTTMP/log/server-cached.log
   > max-repo-cache = 1
   > track-log = command, repocache
   > EOF
 
 isolate socket directory for stable result:
 
   $ OLDCHGSOCKNAME=$CHGSOCKNAME
   $ mkdir chgsock
   $ CHGSOCKNAME=`pwd`/chgsock/server
 
 create empty repo and cache it:
 
   $ hg init cached
   $ hg id -R cached
   000000000000 tip
   $ sleep 1
 
 modify repo (and cache will be invalidated):
 
   $ touch cached/a
   $ hg ci -R cached -Am 'add a'
   adding a
   $ sleep 1
 
 read cached repo:
 
   $ hg log -R cached
   changeset:   0:ac82d8b1f7c4
   tag:         tip
   user:        test
   date:        Thu Jan 01 00:00:00 1970 +0000
   summary:     add a
   
   $ sleep 1
 
 discard cached from LRU cache:
 
   $ hg clone cached cached2
   updating to branch default
   1 files updated, 0 files merged, 0 files removed, 0 files unresolved
   $ hg id -R cached2
   ac82d8b1f7c4 tip
   $ sleep 1
 
 read uncached repo:
 
   $ hg log -R cached
   changeset:   0:ac82d8b1f7c4
   tag:         tip
   user:        test
   date:        Thu Jan 01 00:00:00 1970 +0000
   summary:     add a
   
   $ sleep 1
 
 shut down servers and restore environment:
 
   $ rm -R chgsock
   $ sleep 2
   $ CHGSOCKNAME=$OLDCHGSOCKNAME
 
 check server log:
 
   $ cat log/server-cached.log | filterlog
   YYYY/MM/DD HH:MM:SS (PID)> init cached
   YYYY/MM/DD HH:MM:SS (PID)> id -R cached
   YYYY/MM/DD HH:MM:SS (PID)> loaded repo into cache: $TESTTMP/cached (in  ...s)
   YYYY/MM/DD HH:MM:SS (PID)> repo from cache: $TESTTMP/cached
   YYYY/MM/DD HH:MM:SS (PID)> ci -R cached -Am 'add a'
   YYYY/MM/DD HH:MM:SS (PID)> loaded repo into cache: $TESTTMP/cached (in  ...s)
   YYYY/MM/DD HH:MM:SS (PID)> repo from cache: $TESTTMP/cached
   YYYY/MM/DD HH:MM:SS (PID)> log -R cached
   YYYY/MM/DD HH:MM:SS (PID)> loaded repo into cache: $TESTTMP/cached (in  ...s)
   YYYY/MM/DD HH:MM:SS (PID)> clone cached cached2
   YYYY/MM/DD HH:MM:SS (PID)> id -R cached2
   YYYY/MM/DD HH:MM:SS (PID)> loaded repo into cache: $TESTTMP/cached2 (in  ...s)
   YYYY/MM/DD HH:MM:SS (PID)> log -R cached
   YYYY/MM/DD HH:MM:SS (PID)> loaded repo into cache: $TESTTMP/cached (in  ...s)
 
 Test that -R is interpreted relative to --cwd.
 
   $ hg init repo1
   $ mkdir -p a/b
   $ hg init a/b/repo2
   $ printf "[alias]\ntest=repo1\n" >> repo1/.hg/hgrc
   $ printf "[alias]\ntest=repo2\n" >> a/b/repo2/.hg/hgrc
   $ cd a
   $ chg --cwd .. -R repo1 show alias.test
   repo1
   $ chg --cwd . -R b/repo2 show alias.test
   repo2
   $ cd ..
 
 Test that chg works (sets to the user's actual LC_CTYPE) even when python
 "coerces" the locale (py3.7+)
 
   $ cat > $TESTTMP/debugenv.py <<EOF
   > from mercurial import encoding
   > from mercurial import registrar
   > cmdtable = {}
   > command = registrar.command(cmdtable)
   > @command(b'debugenv', [], b'', norepo=True)
   > def debugenv(ui):
   >     for k in [b'LC_ALL', b'LC_CTYPE', b'LANG']:
   >         v = encoding.environ.get(k)
   >         if v is not None:
   >             ui.write(b'%s=%s\n' % (k, encoding.environ[k]))
   > EOF
 (hg keeps python's modified LC_CTYPE, chg doesn't)
   $ (unset LC_ALL; unset LANG; LC_CTYPE= "$CHGHG" \
   >    --config extensions.debugenv=$TESTTMP/debugenv.py debugenv)
   LC_CTYPE=C.UTF-8 (py37 !)
   LC_CTYPE= (no-py37 !)
   $ (unset LC_ALL; unset LANG; LC_CTYPE= chg \
   >    --config extensions.debugenv=$TESTTMP/debugenv.py debugenv)
   LC_CTYPE=
   $ (unset LC_ALL; unset LANG; LC_CTYPE=unsupported_value chg \
   >    --config extensions.debugenv=$TESTTMP/debugenv.py debugenv)
   *cannot change locale* (glob) (?)
   LC_CTYPE=unsupported_value
   $ (unset LC_ALL; unset LANG; LC_CTYPE= chg \
   >    --config extensions.debugenv=$TESTTMP/debugenv.py debugenv)
   LC_CTYPE=
   $ LANG= LC_ALL= LC_CTYPE= chg \
   >    --config extensions.debugenv=$TESTTMP/debugenv.py debugenv
   LC_ALL=
   LC_CTYPE=
   LANG=
 
 Profiling isn't permanently enabled or carried over between chg invocations that
 share the same server
   $ cp $HGRCPATH.orig $HGRCPATH
   $ hg init $TESTTMP/profiling
   $ cd $TESTTMP/profiling
   $ filteredchg() {
   >   CHGDEBUG=1 chg "$@" 2>&1 | sed -rn 's_^No samples recorded.*$_Sample count: 0_; /Sample count/p; /start cmdserver/p'
   > }
   $ newchg() {
   >   chg --kill-chg-daemon
   >   filteredchg "$@" | grep -E -v 'start cmdserver' || true
   > }
 (--profile isn't permanently on just because it was specified when chg was
 started)
   $ newchg log -r . --profile
   Sample count: * (glob)
   $ filteredchg log -r .
 (enabling profiling via config works, even on the first chg command that starts
 a cmdserver)
   $ cat >> $HGRCPATH <<EOF
   > [profiling]
   > type=stat
   > enabled=1
   > EOF
   $ newchg log -r .
   Sample count: * (glob)
   $ filteredchg log -r .
   Sample count: * (glob)
 (test that we aren't accumulating more and more samples each run)
   $ cat > $TESTTMP/debugsleep.py <<EOF
   > import time
   > from mercurial import registrar
   > cmdtable = {}
   > command = registrar.command(cmdtable)
   > @command(b'debugsleep', [], b'', norepo=True)
   > def debugsleep(ui):
   >   start = time.time()
   >   x = 0
   >   while time.time() < start + 0.5:
   >     time.sleep(.1)
   >     x += 1
   >   ui.status(b'%d debugsleep iterations in %.03fs\n' % (x, time.time() - start))
   > EOF
   $ cat >> $HGRCPATH <<EOF
   > [extensions]
   > debugsleep = $TESTTMP/debugsleep.py
   > EOF
   $ newchg debugsleep > run_1
   $ filteredchg debugsleep > run_2
   $ filteredchg debugsleep > run_3
   $ filteredchg debugsleep > run_4
 FIXME: Run 4 should not be >3x Run 1's number of samples.
   $ "$PYTHON" <<EOF
   > r1 = int(open("run_1", "r").read().split()[-1])
   > r4 = int(open("run_4", "r").read().split()[-1])
   > print("Run 1: %d samples\nRun 4: %d samples\nRun 4 > 3 * Run 1: %s" %
   >       (r1, r4, r4 > (r1 * 3)))
   > EOF
   Run 1: * samples (glob)
   Run 4: * samples (glob)
   Run 4 > 3 * Run 1: False
 (Disabling with --no-profile on the commandline still works, but isn't permanent)
   $ newchg log -r . --no-profile
   $ filteredchg log -r .
   Sample count: * (glob)
   $ filteredchg log -r . --no-profile
   $ filteredchg log -r .
   Sample count: * (glob)
 
 chg setting CHGHG itself
 ------------------------
 
 If CHGHG is not set, chg will set it before spawning the command server.
   $ hg --kill-chg-daemon
   $ HG=$CHGHG CHGHG= CHGDEBUG= hg debugshell -c \
   >   'ui.write(b"CHGHG=%s\n" % ui.environ.get(b"CHGHG"))' 2>&1 \
   >   | grep -E 'CHGHG|start cmdserver'
   chg: debug: * start cmdserver at * (glob)
   CHGHG=/*/install/bin/hg (glob)
 
 Running the same command a second time shouldn't spawn a new command server.
   $ HG=$CHGHG CHGHG= CHGDEBUG= hg debugshell -c \
   >   'ui.write(b"CHGHG=%s\n" % ui.environ.get(b"CHGHG"))' 2>&1 \
   >   | grep -E 'CHGHG|start cmdserver'
   CHGHG=/*/install/bin/hg (glob)