From 94257a258b181a674b93b90785af9921e62795a9 Mon Sep 17 00:00:00 2001 From: Mark Thomas Date: Tue, 23 Apr 2019 02:45:38 -0700 Subject: [PATCH] blackbox: clean up blackbox logging and log more during rage Summary: Clean up some of the calls to `ui.log` and how they appear in blackbox logging. * Make the names of the events consistently use `snake_case`. * For watchman, only log once for each watchman command. Include whether or not it failed. * Unify `fsmonitor` logging under the `fsmonitor` event. * Omit the second argument when it is empty - it is optional and does nothing when empty. * Increase the number of blackbox lines included in rage to 100. Reviewed By: quark-zju Differential Revision: D14949868 fbshipit-source-id: a9aa8251e71ae7ca556c08116f8f7c61ff472218 --- edenscm/hgext/clienttelemetry.py | 6 ++-- edenscm/hgext/clindex.pyx | 2 +- edenscm/hgext/errorredirect.py | 2 +- .../hgext/extlib/watchmanclient/__init__.py | 23 ++++++------ edenscm/hgext/fsmonitor/__init__.py | 30 ++++++---------- edenscm/hgext/fsmonitor/fsmonitorutil.py | 14 ++++++++ edenscm/hgext/fsmonitor/state.py | 36 ++++++++----------- edenscm/hgext/morecolors.py | 2 +- edenscm/hgext/rage.py | 2 +- edenscm/hgext/rebase.py | 8 ++--- edenscm/hgext/remotefilelog/shallowutil.py | 4 +-- edenscm/hgext/sparse.py | 2 +- edenscm/mercurial/dirstate.py | 2 +- edenscm/mercurial/dispatch.py | 12 +++---- edenscm/mercurial/localrepo.py | 2 +- edenscm/mercurial/merge.py | 6 ++-- edenscm/mercurial/treedirstate.py | 2 +- edenscm/mercurial/visibility.py | 2 +- tests/test-amend-hiddenoverride.t | 2 +- tests/test-blackbox.t | 2 +- tests/test-checkoutidentifier-commitinfo.t | 22 ++++++------ tests/test-checkoutidentifier-dirstateinfo.t | 24 ++++++------- tests/test-fb-hgext-errorredirect.t | 4 +-- tests/test-fb-hgext-sampling.t | 16 ++++----- tests/test-fsmonitor-blackbox.t | 10 +++--- tests/test-fsmonitor-bumpclock.t | 10 +++--- tests/test-fsmonitor-filemerge.t | 14 ++++---- 27 files changed, 126 insertions(+), 135 deletions(-) create mode 100644 edenscm/hgext/fsmonitor/fsmonitorutil.py diff --git a/edenscm/hgext/clienttelemetry.py b/edenscm/hgext/clienttelemetry.py index 2e75223739..7fa76b4ca1 100644 --- a/edenscm/hgext/clienttelemetry.py +++ b/edenscm/hgext/clienttelemetry.py @@ -48,7 +48,7 @@ def correlator(ui): global _correlator if _correlator is None: _correlator = util.makerandomidentifier() - ui.log("clienttelemetry", "", client_correlator=_correlator) + ui.log("clienttelemetry", client_correlator=_correlator) return _correlator @@ -59,7 +59,7 @@ _clienttelemetrydata = {} def _clienttelemetry(repo, proto, args): """Handle received client telemetry""" logargs = {"client_%s" % key: value for key, value in args.items()} - repo.ui.log("clienttelemetry", "", **logargs) + repo.ui.log("clienttelemetry", **logargs) # Make them available to other extensions repo.clienttelemetry = logargs return socket.gethostname() @@ -94,7 +94,7 @@ def _peersetup(ui, peer): logargs = {name: f(ui) for name, f in _clienttelemetryfuncs.items()} logargs.update(_clienttelemetrydata) peername = peer._call("clienttelemetry", **logargs) - ui.log("clienttelemetry", "", server_realhostname=peername) + ui.log("clienttelemetry", server_realhostname=peername) ann = ui.configbool("clienttelemetry", "announceremotehostname", None) if ann is None: ann = not ui.plain() and ui._isatty(ui.ferr) diff --git a/edenscm/hgext/clindex.pyx b/edenscm/hgext/clindex.pyx index e08a3e96a7..14dad9f411 100644 --- a/edenscm/hgext/clindex.pyx +++ b/edenscm/hgext/clindex.pyx @@ -426,7 +426,7 @@ def reposetup(ui, repo): try: # Record nodemap lag. - ui.log("nodemap_lag", "", nodemap_lag=repo.changelog.nodemap.lag) + ui.log("nodemap_lag", nodemap_lag=repo.changelog.nodemap.lag) except AttributeError: pass diff --git a/edenscm/hgext/errorredirect.py b/edenscm/hgext/errorredirect.py index 7f62f16000..b42c404d46 100644 --- a/edenscm/hgext/errorredirect.py +++ b/edenscm/hgext/errorredirect.py @@ -50,7 +50,7 @@ def _handlecommandexception(orig, ui): trace = traceback.format_exc() # let blackbox log it (if it is configured to do so) - ui.log("commandexception", "%s\n%s\n", warning, trace) + ui.log("command_exception", "%s\n%s\n", warning, trace) exctype = sys.exc_info()[0] exctypename = "None" if exctype is None else exctype.__name__ ui.log( diff --git a/edenscm/hgext/extlib/watchmanclient/__init__.py b/edenscm/hgext/extlib/watchmanclient/__init__.py index 09aae1d940..e0b81e8199 100644 --- a/edenscm/hgext/extlib/watchmanclient/__init__.py +++ b/edenscm/hgext/extlib/watchmanclient/__init__.py @@ -115,13 +115,8 @@ class client(object): def _command(self, *args): watchmanargs = (args[0], self._resolved_root) + args[1:] - self._ui.log( - "watchman-command", - "watchman command %r started with timeout = %s", - watchmanargs, - self._timeout, - ) try: + starttime = util.timer() if self._watchmanclient is None: self._firsttime = False self._watchmanclient = pywatchman.client( @@ -133,12 +128,19 @@ class client(object): ) result = self._watchmanclient.query(*watchmanargs) self._ui.log( - "watchman-command", "watchman command %r completed", watchmanargs + "watchman", + "command %r completed in %0.2f seconds", + watchmanargs, + util.timer() - starttime, ) return result except pywatchman.CommandError as ex: if "unable to resolve root" in ex.msg: + self._ui.log( + "watchman", "command %r failed - unable to resolve root", args + ) raise WatchmanNoRoot(self._resolved_root, ex.msg) + self._ui.log("watchman", "command %r failed - %s", watchmanargs, ex.msg) raise Unavailable(ex.msg) except pywatchman.SocketConnectError as ex: # If fsmonitor.sockpath was specified in the configuration, we will @@ -151,6 +153,7 @@ class client(object): if not self._ui.config("fsmonitor", "sockpath") or self._sockpath is None: # Either sockpath wasn't configured, or we already tried clearing # it out, so let's propagate this error. + self._ui.log("watchman", "command %r failed - %s", watchmanargs, ex) raise Unavailable(str(ex)) # Recurse and retry the command, and hopefully it will # start the server this time. @@ -158,6 +161,7 @@ class client(object): self._watchmanclient = None return self._command(*args) except pywatchman.WatchmanError as ex: + self._ui.log("watchman", "command %r failed - %s", watchmanargs, ex) raise Unavailable(str(ex)) @util.timefunction("watchmanquery", 0, "_ui") @@ -170,7 +174,7 @@ class client(object): # Ideally we wouldn't let this happen, but if it does happen, # record it in the log and retry the command. self._ui.log( - "watchman-command", + "watchman", "UseAfterFork detected, re-establish a client connection", ) self._watchmanclient = None @@ -286,9 +290,8 @@ class state_update(object): metadata.update(self.metadata) client.command(cmd, {"name": self.name, "metadata": metadata}) return True - except Exception as e: + except Exception: # Swallow any errors; fire and forget - self.repo.ui.log("watchman", "Exception %s while running %s\n", e, cmd) return False diff --git a/edenscm/hgext/fsmonitor/__init__.py b/edenscm/hgext/fsmonitor/__init__.py index 4e6d2dd312..a049286a44 100644 --- a/edenscm/hgext/fsmonitor/__init__.py +++ b/edenscm/hgext/fsmonitor/__init__.py @@ -169,7 +169,7 @@ from edenscm.mercurial import ( ) from edenscm.mercurial.i18n import _ -from . import state +from . import fsmonitorutil, state from ..extlib import pywatchman, watchmanclient @@ -205,11 +205,11 @@ def _handleunavailable(ui, state, ex): ui.warn(str(ex) + "\n") if ex.invalidate: state.invalidate(reason="exception") - ui.log("fsmonitor", "Watchman unavailable: %s\n", ex.msg) - ui.log("fsmonitor_status", "", fsmonitor_status="unavailable") + ui.log("fsmonitor", "watchman unavailable: %s\n", ex.msg) + ui.log("fsmonitor_status", fsmonitor_status="unavailable") else: - ui.log("fsmonitor", "Watchman exception: %s\n", ex) - ui.log("fsmonitor_status", "", fsmonitor_status="exception") + ui.log("fsmonitor", "watchman exception: %s\n", ex) + ui.log("fsmonitor_status", fsmonitor_status="exception") def _hashignore(ignore): @@ -381,9 +381,7 @@ def overridewalk(orig, self, match, unknown, ignored, full=True): nonnormalset = self._map.nonnormalsetfiltered(dirfilter) else: nonnormalset = self._map.nonnormalset - self._ui.log( - "fsmonitor", "clock = %r len(nonnormal) = %d" % (clock, len(nonnormalset)) - ) + self._ui.log("fsmonitor", "clock=%r len(nonnormal)=%d" % (clock, len(nonnormalset))) copymap = self._map.copymap getkind = stat.S_IFMT @@ -457,13 +455,13 @@ def overridewalk(orig, self, match, unknown, ignored, full=True): notefiles = [] if fresh_instance: - self._ui.log("fsmonitor_status", "", fsmonitor_status="fresh") + self._ui.log("fsmonitor_status", fsmonitor_status="fresh") else: - self._ui.log("fsmonitor_status", "", fsmonitor_status="normal") - if "fsmonitor_details" in getattr(self._ui, "track", ()): + self._ui.log("fsmonitor_status", fsmonitor_status="normal") + if "fsmonitor" in getattr(self._ui, "track", ()): filelist = [e["name"] for e in result["files"]] self._ui.log( - "fsmonitor_details", "watchman returned %s" % _reprshort(filelist) + "fsmonitor", "watchman returned %s" % fsmonitorutil.reprshort(filelist) ) state.setwatchmanchangedfilecount(len(result["files"])) @@ -1031,11 +1029,3 @@ def debugrefreshwatchmanclock(ui, repo): ui.status(_("updating watchman clock from %r to %r\n") % (ds.getclock(), clock)) ds.setclock(clock) ds.write(tr) - - -def _reprshort(filelist, limit=20): - """Like repr(filelist). But truncate it if it is too long""" - if len(filelist) <= limit: - return repr(filelist) - else: - return "%r and %s more entries" % (filelist[:limit], len(filelist) - limit) diff --git a/edenscm/hgext/fsmonitor/fsmonitorutil.py b/edenscm/hgext/fsmonitor/fsmonitorutil.py new file mode 100644 index 0000000000..bced65226a --- /dev/null +++ b/edenscm/hgext/fsmonitor/fsmonitorutil.py @@ -0,0 +1,14 @@ +# util.py - fsmonitor utilities +# +# Copyright 2013-2019 Facebook, Inc. +# +# This software may be used and distributed according to the terms of the +# GNU General Public License version 2 or any later version. + + +def reprshort(filelist, limit=20): + """Like repr(filelist). But truncate it if it is too long""" + if len(filelist) <= limit: + return repr(filelist) + else: + return "%r and %s more entries" % (filelist[:limit], len(filelist) - limit) diff --git a/edenscm/hgext/fsmonitor/state.py b/edenscm/hgext/fsmonitor/state.py index 76771360cf..242d7de1c7 100644 --- a/edenscm/hgext/fsmonitor/state.py +++ b/edenscm/hgext/fsmonitor/state.py @@ -15,6 +15,8 @@ import struct from edenscm.mercurial import pathutil, util from edenscm.mercurial.i18n import _ +from . import fsmonitorutil + _version = 4 _versionformat = ">I" @@ -111,13 +113,10 @@ class state(object): finally: file.close() - if "fsmonitor_details" in getattr(self._ui, "track", ()): - from . import _reprshort - - self._ui.log( - "fsmonitor_details", - "clock, notefiles = %r, %s" % (clock, _reprshort(notefiles)), - ) + self._ui.log( + "fsmonitor", + "get clock=%r notefiles=%s" % (clock, fsmonitorutil.reprshort(notefiles)), + ) return clock, ignorehash, notefiles @@ -135,13 +134,10 @@ class state(object): self._ignorelist = ignorelist def set(self, clock, ignorehash, notefiles): - if "fsmonitor_details" in getattr(self._ui, "track", ()): - from . import _reprshort - - self._ui.log( - "fsmonitor_details", - "set clock, notefiles = %r, %s" % (clock, _reprshort(notefiles)), - ) + self._ui.log( + "fsmonitor", + "set clock=%r notefiles=%s" % (clock, fsmonitorutil.reprshort(notefiles)), + ) if self._usetreestate: ds = self._repo.dirstate @@ -197,23 +193,19 @@ class state(object): except OSError as inst: if inst.errno != errno.ENOENT: raise - if "fsmonitor_details" in getattr(self._ui, "track", ()): - self._ui.log("fsmonitor_details", "fsmonitor state invalidated") + self._ui.log("fsmonitor", "state invalidated") def setlastclock(self, clock): - if "fsmonitor_details" in getattr(self._ui, "track", ()): - self._ui.log("fsmonitor_details", "setlastclock: %r" % clock) + self._ui.log("fsmonitor", "setlastclock %r" % clock) self._lastclock = clock def setlastisfresh(self, isfresh): - if "fsmonitor_details" in getattr(self._ui, "track", ()): - self._ui.log("fsmonitor_details", "setlastisfresh: %r" % isfresh) + self._ui.log("fsmonitor", "setlastisfresh %r" % isfresh) self._lastisfresh = isfresh def setwatchmanchangedfilecount(self, filecount): self._lastchangedfilecount = filecount def getlastclock(self): - if "fsmonitor_details" in getattr(self._ui, "track", ()): - self._ui.log("fsmonitor_details", "getlastclock: %r" % self._lastclock) + self._ui.log("fsmonitor", "getlastclock %r" % self._lastclock) return self._lastclock diff --git a/edenscm/hgext/morecolors.py b/edenscm/hgext/morecolors.py index 879f439a75..ce005d7dbe 100644 --- a/edenscm/hgext/morecolors.py +++ b/edenscm/hgext/morecolors.py @@ -46,7 +46,7 @@ def _writeerr(orig, self, *args, **opts): def _handlecommandexception(orig, ui): trace = traceback.format_exc() - ui.log("commandexception", "%s\n", trace) + ui.log("command_exception", "%s\n", trace) ui.write_err(_colorizetraceback(ui, trace)) return True # do not re-raise the exception diff --git a/edenscm/hgext/rage.py b/edenscm/hgext/rage.py index 8f5fde5403..f95f797eab 100644 --- a/edenscm/hgext/rage.py +++ b/edenscm/hgext/rage.py @@ -299,7 +299,7 @@ def _makerage(ui, repo, **opts): 'first 20 lines of "hg status"', lambda: "\n".join(hgcmd("status").splitlines()[:20]), ), - ("hg blackbox -l60", lambda: hgcmd("blackbox", limit=60)), + ("hg blackbox -l100", lambda: hgcmd("blackbox", limit=100)), ("hg summary", lambda: hgcmd("summary")), ("hg debugprocesstree", lambda: hgcmd("debugprocesstree")), ("hg config (local)", lambda: "\n".join(localconfig(ui))), diff --git a/edenscm/hgext/rebase.py b/edenscm/hgext/rebase.py index d2a1d18204..0df2281081 100644 --- a/edenscm/hgext/rebase.py +++ b/edenscm/hgext/rebase.py @@ -445,7 +445,6 @@ class rebaseruntime(object): # a rebase may run multiple updates, so that value might be not be accurate. repo.ui.log( "rebase_size", - "", rebase_commitcount=commitcount, rebase_distance=distance - commitcount, ) @@ -462,9 +461,7 @@ class rebaseruntime(object): else: self.wctx = self.repo[None] self.repo.ui.debug("rebasing on disk\n") - self.repo.ui.log( - "rebase", "", rebase_imm_used=str(self.wctx.isinmemory()).lower() - ) + self.repo.ui.log("rebase", rebase_imm_used=str(self.wctx.isinmemory()).lower()) def _performrebase(self, tr): self._assignworkingcopy() @@ -585,7 +582,6 @@ class rebaseruntime(object): ) ui.log( "rebase", - "", rebase_imm_new_restart=str(True).lower(), rebase_imm_restart=str(True).lower(), ) @@ -1249,7 +1245,7 @@ def _definedestmap( destmap = {r: destrev for r in rebaseset} # {srcrev: destrev} rbsrt.rebasingwcp = destmap is not None and repo["."].rev() in destmap - ui.log("rebase", "", rebase_rebasing_wcp=rbsrt.rebasingwcp) + ui.log("rebase", rebase_rebasing_wcp=rbsrt.rebasingwcp) if rbsrt.inmemory and rbsrt.rebasingwcp: # Require a clean working copy if rebasing the current commit, as the # last step of the rebase is an update. diff --git a/edenscm/hgext/remotefilelog/shallowutil.py b/edenscm/hgext/remotefilelog/shallowutil.py index 56b85c7834..2050b25099 100644 --- a/edenscm/hgext/remotefilelog/shallowutil.py +++ b/edenscm/hgext/remotefilelog/shallowutil.py @@ -152,8 +152,8 @@ def prefixkeys(dict, prefix): def reportpackmetrics(ui, prefix, *stores): dicts = [s.getmetrics() for s in stores] - dict = prefixkeys(sumdicts(*dicts), prefix + "_") - ui.log(prefix + "_packsizes", "", **dict) + data = prefixkeys(sumdicts(*dicts), prefix + "_") + ui.log(prefix + "_packsizes", **data) def _parsepackmeta(metabuf): diff --git a/edenscm/hgext/sparse.py b/edenscm/hgext/sparse.py index d28c21bda2..8ccbb7779b 100644 --- a/edenscm/hgext/sparse.py +++ b/edenscm/hgext/sparse.py @@ -447,7 +447,7 @@ def _trackdirstatesizes(runcommand, lui, repo, *args): # Treestate and treedirstate. dirstatesize = len(dirstate._map) if dirstatesize is not None: - lui.log("dirstate_size", "", dirstate_size=dirstatesize) + lui.log("dirstate_size", dirstate_size=dirstatesize) if ( repo.ui.configbool("sparse", "largecheckouthint") and dirstatesize >= repo.ui.configint("sparse", "largecheckoutcount") diff --git a/edenscm/mercurial/dirstate.py b/edenscm/mercurial/dirstate.py index d947688d41..3877095431 100644 --- a/edenscm/mercurial/dirstate.py +++ b/edenscm/mercurial/dirstate.py @@ -1400,7 +1400,7 @@ class dirstate(object): prefix + "wdirparent1": parents[0], prefix + "wdirparent2": parents[1], } - ui.log("dirstate_info", "", **data) + ui.log("dirstate_info", **data) class dirstatemap(object): diff --git a/edenscm/mercurial/dispatch.py b/edenscm/mercurial/dispatch.py index cc82c3c4a8..e0f9d6644a 100644 --- a/edenscm/mercurial/dispatch.py +++ b/edenscm/mercurial/dispatch.py @@ -401,11 +401,7 @@ def dispatch(req): def logatexit(): ui = req.ui if ui.logmeasuredtimes: - ui.log( - "measuredtimes", - "measured times", - **pycompat.strkwargs(ui._measuredtimes) - ) + ui.log("measuredtimes", **pycompat.strkwargs(ui._measuredtimes)) if ui.metrics.stats: # Re-arrange metrics so "a_b_c", "a_b_d", "a_c" becomes # {'a': {'b': {'c': ..., 'd': ...}, 'c': ...} @@ -467,7 +463,7 @@ def dispatch(req): duration = util.timer() - starttime req.ui.flush() req.ui.log( - "commandfinish", + "command_finish", "%s exited %d after %0.2f seconds\n", msg, ret or 0, @@ -895,7 +891,7 @@ class cmdalias(object): raise error.Abort(self.badalias, hint=hint) ui.log( - "commandalias", "alias '%s' expands to '%s'\n", self.name, self.definition + "command_alias", "alias '%s' expands to '%s'\n", self.name, self.definition ) if util.safehasattr(self, "shell"): return self.fn(ui, *args, **opts) @@ -1452,7 +1448,7 @@ def handlecommandexception(ui): this function returns False, ignored otherwise. """ warning = _exceptionwarning(ui) - ui.log("commandexception", "%s\n%s\n", warning, traceback.format_exc()) + ui.log("command_exception", "%s\n%s\n", warning, traceback.format_exc()) ui.warn(warning) return False # re-raise the exception diff --git a/edenscm/mercurial/localrepo.py b/edenscm/mercurial/localrepo.py index db4cf3b15a..82e4eafb90 100644 --- a/edenscm/mercurial/localrepo.py +++ b/edenscm/mercurial/localrepo.py @@ -2337,7 +2337,7 @@ class localrepository(object): ) mutation.recordentries(self, [entry], skipexisting=False) tr.close() - self.ui.log("commit_info", "", node=hex(n), author=user, **ctx.loginfo()) + self.ui.log("commit_info", node=hex(n), author=user, **ctx.loginfo()) return n finally: if tr: diff --git a/edenscm/mercurial/merge.py b/edenscm/mercurial/merge.py index 959a68eeda..4a30357247 100644 --- a/edenscm/mercurial/merge.py +++ b/edenscm/mercurial/merge.py @@ -533,7 +533,7 @@ class mergestate(object): else: actx = None self._repo.ui.log( - "merge-resolve", "resolving %s, preresolve = %s", dfile, preresolve + "merge_resolve", "resolving %s, preresolve = %s", dfile, preresolve ) fcd = self._filectxorabsent(hash, wctx, dfile) fco = self._filectxorabsent(onode, octx, ofile) @@ -1945,7 +1945,7 @@ def _logupdatedistance(ui, repo, node, branchmerge): try: distance = len(repo.revs("(%s %% .) + (. %% %s)", node, node)) - repo.ui.log("update_size", "", update_distance=distance) + repo.ui.log("update_size", update_distance=distance) except Exception: # error may happen like: RepoLookupError: unknown revision '-1' pass @@ -2293,7 +2293,7 @@ def update( repo.hook("update", parent1=xp1, parent2=xp2, error=stats[3]) # Log the number of files updated. - repo.ui.log("update_size", "", update_filecount=sum(stats)) + repo.ui.log("update_size", update_filecount=sum(stats)) return stats diff --git a/edenscm/mercurial/treedirstate.py b/edenscm/mercurial/treedirstate.py index 9769ed227d..c32d9cad94 100644 --- a/edenscm/mercurial/treedirstate.py +++ b/edenscm/mercurial/treedirstate.py @@ -424,7 +424,7 @@ class treedirstatemap(object): repackthreshold = max(self._packedsize * repackfactor, minrepackthreshold) if self._rmap.storeoffset() > repackthreshold: self._ui.note(_("auto-repacking treedirstate\n")) - self._ui.log("treedirstate_repacking", "", treedirstate_repacking=True) + self._ui.log("treedirstate_repacking", treedirstate_repacking=True) self._repacked = True self._treeid = None self._gc() diff --git a/edenscm/mercurial/visibility.py b/edenscm/mercurial/visibility.py index e7c645855a..46a45f9a60 100644 --- a/edenscm/mercurial/visibility.py +++ b/edenscm/mercurial/visibility.py @@ -72,7 +72,7 @@ class visibleheads(object): raise self.heads = _convertfromobsolete(repo) self.dirty = True - ui.log("visibility", "", visibility_headcount=len(self.heads)) + ui.log("visibility", visibility_headcount=len(self.heads)) def _write(self, fp): fp.write("%s\n" % FORMAT_VERSION) diff --git a/tests/test-amend-hiddenoverride.t b/tests/test-amend-hiddenoverride.t index b3d1c2c6d8..6cd16d0da5 100644 --- a/tests/test-amend-hiddenoverride.t +++ b/tests/test-amend-hiddenoverride.t @@ -5,7 +5,7 @@ > [experimental] > evolution = all > [blackbox] - > track = command, commandfinish, commandexception, + > track = command, command_finish, command_exception, > pinnednodes > EOF diff --git a/tests/test-blackbox.t b/tests/test-blackbox.t index 4373346d49..8511207d32 100644 --- a/tests/test-blackbox.t +++ b/tests/test-blackbox.t @@ -317,7 +317,7 @@ blackbox should work if repo.ui.log is not called (issue5518) $ cat >> $HGRCPATH << EOF > [blackbox] - > track = commandexception + > track = command_exception > [extensions] > raise=$TESTTMP/raise.py > EOF diff --git a/tests/test-checkoutidentifier-commitinfo.t b/tests/test-checkoutidentifier-commitinfo.t index 533dbae192..74eeb6731c 100644 --- a/tests/test-checkoutidentifier-commitinfo.t +++ b/tests/test-checkoutidentifier-commitinfo.t @@ -9,7 +9,7 @@ Commit and Amend $ echo base > base $ hg commit -Am base adding base - commit_info: (author=test checkoutidentifier= node=d20a80d4def38df63a4b330b7fb688f3d4cae1e3) + commit_info (author=test checkoutidentifier= node=d20a80d4def38df63a4b330b7fb688f3d4cae1e3) $ hg debugcheckoutidentifier 0000000000000000 @@ -18,20 +18,20 @@ Commit and Amend $ hg debugcheckoutidentifier 0000000000000000 $ hg commit -m 1 - commit_info: (author=test checkoutidentifier=0000000000000000 node=f0161ad23099c690115006c21e96f780f5d740b6) + commit_info (author=test checkoutidentifier=0000000000000000 node=f0161ad23099c690115006c21e96f780f5d740b6) $ hg debugcheckoutidentifier 0000000000000001 $ echo 1b > 1 $ hg amend -m 1b - commit_info: (author=test checkoutidentifier=0000000000000001 mutation=amend node=edbfe685c913f3cec015588dbc0f1e03f5146d80 predecessors=f0161ad23099c690115006c21e96f780f5d740b6) + commit_info (author=test checkoutidentifier=0000000000000001 mutation=amend node=edbfe685c913f3cec015588dbc0f1e03f5146d80 predecessors=f0161ad23099c690115006c21e96f780f5d740b6) $ hg debugcheckoutidentifier 0000000000000002 $ echo 2 > 2 $ hg commit -Am 2 adding 2 - commit_info: (author=test checkoutidentifier=0000000000000002 node=155c3fe008ceed8a313cbb9358999d850a57a06f) + commit_info (author=test checkoutidentifier=0000000000000002 node=155c3fe008ceed8a313cbb9358999d850a57a06f) Absorb $ hg debugcheckoutidentifier @@ -51,8 +51,8 @@ Absorb 2 changesets affected 155c3fe 2 edbfe68 1b - commit_info: (author=test checkoutidentifier=0000000000000003 node=f84ddfee68927d4ebfe4344520adb71ccb173c4f) - commit_info: (author=test checkoutidentifier=0000000000000003 node=e911dd548c90906d9f6733aa1612274865a7dfd2) + commit_info (author=test checkoutidentifier=0000000000000003 node=f84ddfee68927d4ebfe4344520adb71ccb173c4f) + commit_info (author=test checkoutidentifier=0000000000000003 node=e911dd548c90906d9f6733aa1612274865a7dfd2) 2 of 2 chunks applied Rebase with conflict resolution @@ -64,13 +64,13 @@ Rebase with conflict resolution $ echo 2z > 2 $ hg commit -Am 2z adding 2 - commit_info: (author=test checkoutidentifier=0000000000000005 node=78930e916793ff11b38f4f89f92221c180f922a3) + commit_info (author=test checkoutidentifier=0000000000000005 node=78930e916793ff11b38f4f89f92221c180f922a3) $ hg debugcheckoutidentifier 0000000000000006 $ echo 3 > 3 $ hg commit -Am 3 adding 3 - commit_info: (author=test checkoutidentifier=0000000000000006 node=27fd2733660ce0233ef4603cebe6328681aa598d) + commit_info (author=test checkoutidentifier=0000000000000006 node=27fd2733660ce0233ef4603cebe6328681aa598d) $ hg debugcheckoutidentifier 0000000000000007 $ hg rebase -s 6 -d 5 @@ -89,15 +89,15 @@ Rebase with conflict resolution 0000000000000008 $ hg rebase --continue rebasing 6:78930e916793 "2z" - commit_info: (author=test checkoutidentifier=0000000000000008 mutation=rebase node=2a9f3f40eebf9d189f51eeba40f6d45935255c3e predecessors=78930e916793ff11b38f4f89f92221c180f922a3) + commit_info (author=test checkoutidentifier=0000000000000008 mutation=rebase node=2a9f3f40eebf9d189f51eeba40f6d45935255c3e predecessors=78930e916793ff11b38f4f89f92221c180f922a3) rebasing 7:27fd2733660c "3" (tip) - commit_info: (author=test checkoutidentifier=0000000000000009 mutation=rebase node=b42c49c8c650d6040d4a4003a30c82e1cde21c50 predecessors=27fd2733660ce0233ef4603cebe6328681aa598d) + commit_info (author=test checkoutidentifier=0000000000000009 mutation=rebase node=b42c49c8c650d6040d4a4003a30c82e1cde21c50 predecessors=27fd2733660ce0233ef4603cebe6328681aa598d) $ hg debugcheckoutidentifier 0000000000000010 Fold has no checkoutidentifier, but does log other commit info $ hg fold --from ".~2" - commit_info: (author=test mutation=fold node=39938ad744a3c4695743296607b5786b8e1437c6 predecessors=e911dd548c90906d9f6733aa1612274865a7dfd2 2a9f3f40eebf9d189f51eeba40f6d45935255c3e b42c49c8c650d6040d4a4003a30c82e1cde21c50) + commit_info (author=test mutation=fold node=39938ad744a3c4695743296607b5786b8e1437c6 predecessors=e911dd548c90906d9f6733aa1612274865a7dfd2 2a9f3f40eebf9d189f51eeba40f6d45935255c3e b42c49c8c650d6040d4a4003a30c82e1cde21c50) 3 changesets folded 1 files updated, 0 files merged, 0 files removed, 0 files unresolved $ hg debugcheckoutidentifier diff --git a/tests/test-checkoutidentifier-dirstateinfo.t b/tests/test-checkoutidentifier-dirstateinfo.t index acb9ef6ae7..6854a6320c 100644 --- a/tests/test-checkoutidentifier-dirstateinfo.t +++ b/tests/test-checkoutidentifier-dirstateinfo.t @@ -7,25 +7,25 @@ $ echo base > base $ hg commit -Am base - dirstate_info: (precheckoutidentifier= prewdirparent1= prewdirparent2=) + dirstate_info (precheckoutidentifier= prewdirparent1= prewdirparent2=) adding base - dirstate_info: (postcheckoutidentifier=0000000000000000 postwdirparent1=d20a80d4def38df63a4b330b7fb688f3d4cae1e3 postwdirparent2=) + dirstate_info (postcheckoutidentifier=0000000000000000 postwdirparent1=d20a80d4def38df63a4b330b7fb688f3d4cae1e3 postwdirparent2=) $ hg debugcheckoutidentifier - dirstate_info: (precheckoutidentifier=0000000000000000 prewdirparent1=d20a80d4def38df63a4b330b7fb688f3d4cae1e3 prewdirparent2=) + dirstate_info (precheckoutidentifier=0000000000000000 prewdirparent1=d20a80d4def38df63a4b330b7fb688f3d4cae1e3 prewdirparent2=) 0000000000000000 - dirstate_info: (postcheckoutidentifier=0000000000000000 postwdirparent1=d20a80d4def38df63a4b330b7fb688f3d4cae1e3 postwdirparent2=) + dirstate_info (postcheckoutidentifier=0000000000000000 postwdirparent1=d20a80d4def38df63a4b330b7fb688f3d4cae1e3 postwdirparent2=) $ echo 1 > 1 $ hg commit -Am 1 - dirstate_info: (precheckoutidentifier=0000000000000000 prewdirparent1=d20a80d4def38df63a4b330b7fb688f3d4cae1e3 prewdirparent2=) + dirstate_info (precheckoutidentifier=0000000000000000 prewdirparent1=d20a80d4def38df63a4b330b7fb688f3d4cae1e3 prewdirparent2=) adding 1 - dirstate_info: (postcheckoutidentifier=0000000000000001 postwdirparent1=f0161ad23099c690115006c21e96f780f5d740b6 postwdirparent2=) + dirstate_info (postcheckoutidentifier=0000000000000001 postwdirparent1=f0161ad23099c690115006c21e96f780f5d740b6 postwdirparent2=) $ hg debugcheckoutidentifier - dirstate_info: (precheckoutidentifier=0000000000000001 prewdirparent1=f0161ad23099c690115006c21e96f780f5d740b6 prewdirparent2=) + dirstate_info (precheckoutidentifier=0000000000000001 prewdirparent1=f0161ad23099c690115006c21e96f780f5d740b6 prewdirparent2=) 0000000000000001 - dirstate_info: (postcheckoutidentifier=0000000000000001 postwdirparent1=f0161ad23099c690115006c21e96f780f5d740b6 postwdirparent2=) + dirstate_info (postcheckoutidentifier=0000000000000001 postwdirparent1=f0161ad23099c690115006c21e96f780f5d740b6 postwdirparent2=) An extension which makes the log command slow $ cat > $TESTTMP/slowlog.py < $TESTTMP/log.out & $ sleep 1 $ hg prev - dirstate_info: (precheckoutidentifier=0000000000000001 prewdirparent1=f0161ad23099c690115006c21e96f780f5d740b6 prewdirparent2=) + dirstate_info (precheckoutidentifier=0000000000000001 prewdirparent1=f0161ad23099c690115006c21e96f780f5d740b6 prewdirparent2=) 0 files updated, 0 files merged, 1 files removed, 0 files unresolved [d20a80] base - dirstate_info: (postcheckoutidentifier=0000000000000002 postwdirparent1=d20a80d4def38df63a4b330b7fb688f3d4cae1e3 postwdirparent2=) + dirstate_info (postcheckoutidentifier=0000000000000002 postwdirparent1=d20a80d4def38df63a4b330b7fb688f3d4cae1e3 postwdirparent2=) $ wait $ cat $TESTTMP/log.out - dirstate_info: (precheckoutidentifier=0000000000000001 prewdirparent1=f0161ad23099c690115006c21e96f780f5d740b6 prewdirparent2=) + dirstate_info (precheckoutidentifier=0000000000000001 prewdirparent1=f0161ad23099c690115006c21e96f780f5d740b6 prewdirparent2=) f0161ad23099c690115006c21e96f780f5d740b6 - dirstate_info: (postcheckoutidentifier=0000000000000001 postwdirparent1=f0161ad23099c690115006c21e96f780f5d740b6 postwdirparent2=) + dirstate_info (postcheckoutidentifier=0000000000000001 postwdirparent1=f0161ad23099c690115006c21e96f780f5d740b6 postwdirparent2=) diff --git a/tests/test-fb-hgext-errorredirect.t b/tests/test-fb-hgext-errorredirect.t index a6d8e6c83f..44d84edd71 100644 --- a/tests/test-fb-hgext-errorredirect.t +++ b/tests/test-fb-hgext-errorredirect.t @@ -58,7 +58,7 @@ Traces are logged in blackbox > [extensions] > blackbox= > [blackbox] - > track = command, commandexception + > track = command, command_exception > logsource = 1 > EOF @@ -70,5 +70,5 @@ Traces are logged in blackbox $ hg blackbox -l 12 | grep '\[command' * @0000000000000000000000000000000000000000 (*) [command]> blackbox -l 2 (glob) * @0000000000000000000000000000000000000000 (*) [command]> crash* (glob) - * @0000000000000000000000000000000000000000 (*) [commandexception]> * (glob) + * @0000000000000000000000000000000000000000 (*) [command_exception]> * (glob) * @0000000000000000000000000000000000000000 (*) [command]> blackbox -l 12 (glob) diff --git a/tests/test-fb-hgext-sampling.t b/tests/test-fb-hgext-sampling.t index 6757b32715..ce7de3fc34 100644 --- a/tests/test-fb-hgext-sampling.t +++ b/tests/test-fb-hgext-sampling.t @@ -71,18 +71,18 @@ Do a couple of commits. We expect to log two messages per call to repo.commit. ... assert len(parsedrecord["data"]) == 4 ... elif parsedrecord['category'] == 'measuredtimes': ... print('atexit_measured: ', repr(sorted(parsedrecord['data']))) - atexit_measured: [u'atexit_measured', u'command_duration', u'dirstatewalk_time', u'metrics_type', u'msg', u'stdio_blocked'] (no-fsmonitor !) - atexit_measured: [u'atexit_measured', u'command_duration', u'fsmonitorwalk_time', u'metrics_type', u'msg', u'stdio_blocked'] (fsmonitor !) + atexit_measured: [u'atexit_measured', u'command_duration', u'dirstatewalk_time', u'metrics_type', u'stdio_blocked'] (no-fsmonitor !) + atexit_measured: [u'atexit_measured', u'command_duration', u'fsmonitorwalk_time', u'metrics_type', u'stdio_blocked'] (fsmonitor !) match filter commit_table message string commit_table - atexit_measured: [u'atexit_measured', u'command_duration', u'dirstatewalk_time', u'metrics_type', u'msg', u'stdio_blocked'] (no-fsmonitor !) - atexit_measured: [u'atexit_measured', u'command_duration', u'dirstatewalk_time', u'metrics_type', u'msg', u'stdio_blocked'] (no-fsmonitor !) - atexit_measured: [u'atexit_measured', u'command_duration', u'fsmonitorwalk_time', u'metrics_type', u'msg', u'stdio_blocked', u'watchmanquery_time'] (fsmonitor !) - atexit_measured: [u'atexit_measured', u'command_duration', u'fsmonitorwalk_time', u'metrics_type', u'msg', u'stdio_blocked'] (fsmonitor !) + atexit_measured: [u'atexit_measured', u'command_duration', u'dirstatewalk_time', u'metrics_type', u'stdio_blocked'] (no-fsmonitor !) + atexit_measured: [u'atexit_measured', u'command_duration', u'dirstatewalk_time', u'metrics_type', u'stdio_blocked'] (no-fsmonitor !) + atexit_measured: [u'atexit_measured', u'command_duration', u'fsmonitorwalk_time', u'metrics_type', u'stdio_blocked', u'watchmanquery_time'] (fsmonitor !) + atexit_measured: [u'atexit_measured', u'command_duration', u'fsmonitorwalk_time', u'metrics_type', u'stdio_blocked'] (fsmonitor !) match filter commit_table message string commit_table - atexit_measured: [u'atexit_measured', u'command_duration', u'dirstatewalk_time', u'metrics_type', u'msg', u'stdio_blocked'] (no-fsmonitor !) - atexit_measured: [u'atexit_measured', u'command_duration', u'fsmonitorwalk_time', u'metrics_type', u'msg', u'stdio_blocked', u'watchmanquery_time'] (fsmonitor !) + atexit_measured: [u'atexit_measured', u'command_duration', u'dirstatewalk_time', u'metrics_type', u'stdio_blocked'] (no-fsmonitor !) + atexit_measured: [u'atexit_measured', u'command_duration', u'fsmonitorwalk_time', u'metrics_type', u'stdio_blocked', u'watchmanquery_time'] (fsmonitor !) Test topdir logging: $ setconfig sampling.logtopdir=True diff --git a/tests/test-fsmonitor-blackbox.t b/tests/test-fsmonitor-blackbox.t index d95cb7aa20..91b2376785 100644 --- a/tests/test-fsmonitor-blackbox.t +++ b/tests/test-fsmonitor-blackbox.t @@ -2,7 +2,7 @@ $ newrepo $ enable blackbox - $ setconfig blackbox.track=fsmonitor_details + $ setconfig blackbox.track=fsmonitor $ hg status $ touch x $ hg status @@ -38,7 +38,7 @@ $ grep returned .hg/blackbox.log *> watchman returned ['x'] (glob) *> watchman returned [*] and 5 more entries (glob) - $ grep 'set clock, notefiles' .hg/blackbox.log - *> set clock, notefiles = '*', [] (glob) - *> set clock, notefiles = '*', ['x'] (glob) - *> set clock, notefiles = '*', [*] and 6 more entries (glob) + $ grep 'set clock' .hg/blackbox.log + *> set clock='*' notefiles=[] (glob) + *> set clock='*' notefiles=['x'] (glob) + *> set clock='*' notefiles=[*] and 6 more entries (glob) diff --git a/tests/test-fsmonitor-bumpclock.t b/tests/test-fsmonitor-bumpclock.t index d358328ce1..3dce5fca7a 100644 --- a/tests/test-fsmonitor-bumpclock.t +++ b/tests/test-fsmonitor-bumpclock.t @@ -30,12 +30,12 @@ many files: $ hg status $ hg blackbox | sed "s/^[^>]*> //;s/c:[0-9][0-9:]*/c:x/" - clock = 'c:x' len(nonnormal) = 0 - setlastclock: 'c:x' - setlastisfresh: False + clock='c:x' len(nonnormal)=0 + setlastclock 'c:x' + setlastisfresh False watchman returned ['a', 'b', 'c', 'd', 'e', 'f'] - getlastclock: 'c:x' - set clock, notefiles = 'c:x', [] + getlastclock 'c:x' + set clock='c:x' notefiles=[] status exited 0 after 0.00 seconds The watchman clock remains unchanged. Watchman still returns 4 files, which diff --git a/tests/test-fsmonitor-filemerge.t b/tests/test-fsmonitor-filemerge.t index 9d57bd697a..940d859ac1 100644 --- a/tests/test-fsmonitor-filemerge.t +++ b/tests/test-fsmonitor-filemerge.t @@ -13,7 +13,7 @@ > EOS $ enable blackbox fsmonitor rebase hgevents - $ setconfig blackbox.track=merge-resolve,watchman-command + $ setconfig blackbox.track=merge_resolve,watchman blackbox.logsource=true $ hg rebase -s B -d C --tool=false rebasing 1:65f3e88a53bc "B" (B) @@ -24,12 +24,12 @@ [1] $ hg blackbox -l 100 | egrep '(watchman.*state.*completed|resolving)' | python $RUNTESTDIR/sortdictfilter.py - *> watchman command ('state-enter', '$TESTTMP/repo1', {'metadata': {'distance': 3, 'merge': False, 'partial': False, 'rev': '0000000000000000000000000000000000000000', 'status': 'ok'}, 'name': 'hg.update'}) completed (glob) - *> watchman command ('state-leave', '$TESTTMP/repo1', {'metadata': {'distance': 3, 'merge': False, 'partial': False, 'rev': '2e2f27616b65209eecd4710c454df0f678f271d9', 'status': 'ok'}, 'name': 'hg.update'}) completed (glob) - *> watchman command ('state-enter', '$TESTTMP/repo1', {'metadata': {'distance': 3, 'merge': True, 'partial': False, 'rev': '2e2f27616b65209eecd4710c454df0f678f271d9', 'status': 'ok'}, 'name': 'hg.update'}) completed (glob) + *> command ('state-enter', '$TESTTMP/repo1', {'metadata': {'distance': 3, 'merge': False, 'partial': False, 'rev': '0000000000000000000000000000000000000000', 'status': 'ok'}, 'name': 'hg.update'}) completed in 0.00 seconds (glob) + *> command ('state-leave', '$TESTTMP/repo1', {'metadata': {'distance': 3, 'merge': False, 'partial': False, 'rev': '2e2f27616b65209eecd4710c454df0f678f271d9', 'status': 'ok'}, 'name': 'hg.update'}) completed in 0.00 seconds (glob) + *> command ('state-enter', '$TESTTMP/repo1', {'metadata': {'distance': 3, 'merge': True, 'partial': False, 'rev': '2e2f27616b65209eecd4710c454df0f678f271d9', 'status': 'ok'}, 'name': 'hg.update'}) completed in 0.00 seconds (glob) *> resolving 2, preresolve = True (glob) *> resolving A, preresolve = True (glob) *> resolving 2, preresolve = False (glob) - *> watchman command ('state-enter', '$TESTTMP/repo1', {'metadata': {'path': '2'}, 'name': 'hg.filemerge'}) completed (glob) - *> watchman command ('state-leave', '$TESTTMP/repo1', {'metadata': {'path': '2'}, 'name': 'hg.filemerge'}) completed (glob) - *> watchman command ('state-leave', '$TESTTMP/repo1', {'metadata': {'distance': 3, 'merge': True, 'partial': False, 'rev': '65f3e88a53bc0f5183deea0cdbc46738777ec005', 'status': 'ok'}, 'name': 'hg.update'}) completed (glob) + *> command ('state-enter', '$TESTTMP/repo1', {'metadata': {'path': '2'}, 'name': 'hg.filemerge'}) completed in 0.00 seconds (glob) + *> command ('state-leave', '$TESTTMP/repo1', {'metadata': {'path': '2'}, 'name': 'hg.filemerge'}) completed in 0.00 seconds (glob) + *> command ('state-leave', '$TESTTMP/repo1', {'metadata': {'distance': 3, 'merge': True, 'partial': False, 'rev': '65f3e88a53bc0f5183deea0cdbc46738777ec005', 'status': 'ok'}, 'name': 'hg.update'}) completed in 0.00 seconds (glob)