Page MenuHomePhabricator

Deploy log tailing/filtering

Authored by dduvall on Oct 15 2015, 12:15 AM.
Referenced Files
Unknown Object (File)
Aug 16 2023, 8:02 PM
Unknown Object (File)
Aug 16 2023, 6:33 PM
Unknown Object (File)
Aug 16 2023, 4:13 PM
Unknown Object (File)
Aug 13 2023, 7:58 AM
Unknown Object (File)
Aug 9 2023, 12:16 PM
Unknown Object (File)
Aug 8 2023, 8:00 PM
Unknown Object (File)
Aug 5 2023, 5:49 PM
Unknown Object (File)
Aug 5 2023, 5:28 PM


Maniphest Tasks
T115137: (Re)implement logging output for scap targets
rMWTS2b3bc25baab0: Deploy log tailing/filtering
rMSCA2b3bc25baab0: Deploy log tailing/filtering
Patch without arc
git checkout -b D18 && curl -L | git apply

The main deploy application now sends all structured log output to a
file under scap/log/{git-tag}.log which the new deploy-log utility
can tail and filter using a given free-form expression. By default the
latter utility will periodically scan the scap/log directory for new
files and immediately begin tailing them. It can also be given an
explicit log file to parse via the --file option or the latest log
file by using --latest; in this case, it will simply filter the entire
file for matching records and exit.

Free-form log.Filter expressions are hopefully simple enough to grok
by most users and general enough to be used with later implementations
of iscap log multiplexing. See deploy-log -h or log.Filter for
expression examples.

Introduced a base main.DeployApplication class which sets up some of
the most commonly referenced attributes of the derived deploy classes,
including the root deploy directory, scap directory, and log directory.

Depends on D15. Resolves T115137

Test Plan

Tail behavior

  1. Run deploy-log {expr}.
  2. Run deploy in a separate terminal.
  3. Verify that deploy-log in the first terminal starts reading the new log file. It should say -- Opening log file: {file}.
  4. Verify that only log messages matching the given expression are output.

Latest log file behavior

  1. Run deploy.
  2. Run deploy-log -l {expr}
  3. Verify that only log messages from the latest log file matching the given expression are output.

Single log file behavior

  1. Run deploy a couple of times.
  2. Run deploy-log -f {log-file} {expr}.
  3. Verify that only log messages from the given log file matching the given expression are output.

Diff Detail

Lint Errors
Errorbin/deploy-log:16E402PEP8 E402
Errorscap/ E731
No Test Coverage

Event Timeline

dduvall retitled this revision from to Deploy log tailing/filtering.
dduvall updated this object.
dduvall edited the test plan for this revision. (Show Details)
dduvall added reviewers: thcipriani, mmodell, demon.

Removed redundant setting of self.root_dir in main.Deploy

Let me reiterate what I said to Dan in IRC, "holy shit deploy-log is really awesome."


This seems to blow up since the partial returned by using the expression: levelno > WARNING would be: lambda v: getattr(30, 'gt')(v)




currently must be an absolute directory which was unexpected from a usage perspective. Might be better to do:

os.path.join(os.getcwd(), self.arguments.file)
dduvall edited edge metadata.

Reimplemented log.Filter expression parsing using shlex instead of a regex (thanks, @thcipriani!) and fixed comparison operators (>, <, >=, <=).

dduvall marked an inline comment as done.

Fixed typo


ignore me, had the paths all messed up.

Fixed another typo, this time in the test plan

mmodell edited edge metadata.

Very cool stuff. Great work Dan!


I like this algorithm. Good thinking.

This revision is now accepted and ready to land.Oct 15 2015, 11:26 PM
mmodell requested changes to this revision.Oct 16 2015, 8:18 PM
mmodell edited edge metadata.

Found problems that were actually caused by D15 but I'm providing feedback here because the problems came up during testing of this patch.


This fails when there is an exception passed from the remote deploy-local via json, because the exception can't be serialized in a satisfactory format. We probably need to create our own stack trace (as a string or whatever...) and avoid passing it in the exc_info argument slot.


This fails when there is an exception in the record. Exceptions aren't serializable. You can pass default=callable(rec) to the dumps method, to override the default handling of non-serializable objects, however, when I do that, there is another problem on the other end when we reconstruct the logmessage from the serialized json (see above, line #119)

This revision now requires changes to proceed.Oct 16 2015, 8:18 PM

I spent a lot of time on this over the weekend, and simplified it some, but I still haven't managed to get the stack traces to carry through from deploy-local all the way through to deploy-log.

dduvall added inline comments.

Pre-formatting exc_info makes sense to me. Per our IRC discussion, we need to figure out how to properly deserialize/propagate this info on the consuming end.

dduvall edited edge metadata.

Added a failing test for handling of exc_info

dduvall edited edge metadata.

Added failing test for deserialization of exc_text


Just added a failing test for this.


Added a failing test for this as well.

Refactored log.JSONFormatter serialization to handle exceptions correctly by first formatting them as text.

Note: I'm working on revising this.


If we add this, it will ensure that unserializable objects won't throw exceptions here:

def serialize_obj(obj):
    if hasattr(obj, "getvalue"):
        return obj.getvalue()
    elif hasattr(obj, "__dict__"):
        return obj.__dict__
    return None
rec = record.__dict__.copy()
return json.dumps(rec, default=serialize_obj, skipkeys=True)

logrecord can actually contain arbitrary fields, and this doesn't account for any we decide to add. Maybe not a huge deal but @thcipriani and I were talking about surfacing important errors by including an "important" tag field in the log messages on the target machine, which would cause them to pass the filter on the main scap deploy(cli.application) console.


why is args marked unserializable? It needs to be serialized for parameterized log messages to work.

Now all the log entries print out just the format string without the data, for example:

19:48:39 [debian-jessie] %s on %s returned [%d]: %s
mmodell edited reviewers, added: dduvall; removed: mmodell.
mmodell marked 2 inline comments as done.
  • pass default=callback to handle unserializable objects passed to json.dumps
  • and do not exclude args from logmessage serialization, args is important!

Now tests pass and exceptions propogate! :)

Your changes look good to me, but my commits seem to have been clobbered by the new diff. Also, arc patch D18 is now super confused and tries to cherry-pick D15: Normalize structured logging data which results in an empty commit.


Arbitrary fields should still be included. See the _isvalid(field) method.


I was a bit worried about running into circular references there, but it looks like the JSON encoder actually takes care of that.

dduvall edited reviewers, added: mmodell; removed: dduvall.
mmodell edited edge metadata.


This revision is now accepted and ready to land.Oct 21 2015, 4:40 PM