Instrumentation and Logging in Event-Reflexive Programming

<< First | < Prev

The previous two posts in this series have introduced the idea of event-reflexive programming, and started to investigate a little into its properties, and design decisions about creating a system using it in terms of ordering considerations and ways to invoke individual actions.

I said this story would continue chronologically, following the history of this idea through various systems I've encountered or built using it. So far we have an ISP provisioning system, and an IRC bot. Quite different in size, scope and semantics, they did however have some common features. The one I want to talk about today is the debugging logging and instrumentation part.

At the ISP, every top-level provisioning action was identified by its name, a plain string, and a named set of arguments, the value of each argument also a string. This made it trivially simple to encode the action over a simple TCP socket we had at the time (this being years before the explosion of YAML and JSON-driven systems, and before, even, the peak of the XML craze). While it wasn't strictly required, it turned out that keeping this property for all of the inner reflexive events as well made logging very simple. The logging was also aware of the nesting level of the event-reflexive core, allowing it to print simple logs showing the full tree-shaped nature of the events as they took place. I forget all the inner details of the logging format, but a hypothetical example could look something like:

Action 'add_user': reseller=foo username=a-new-user product=shiney
+- Action(1) 'make_user_config': reseller=foo username=a-new-user product=shiney
+- Action(1) 'make_user_homedir': reseller=foo username=a-new-user product=shiney
|  +- Action(2) 'copy_skeleton': reseller=foo username=a-new-user product=shiney
...

It wasn't too long before I started finding this logging system simply not powerful enough. At least in the "leaf" events, these often actually did useful things - performed LDAP reads or writes, interacted with the filesystem, talked to various 3rd-party systems, and so on. The logging system then gained the ability to write these as well.

While most logging/debugging systems we have currently use a simple linear scale of "verboseness", the logged items in our logging system were tagged with any of a wide set of possible categories. The set of categories in effect at any time was given by an environment variable. For example, to log just the reads and writes to the LDAP directory, and the attributes of a write, one could set:

DEBUG_INSTRUMENT_FLAGS=LDAPr,LDAPw,LDAPwa

This becomes a much more powerful logging system because it allows the programmer/operator to choose not simply the level of verbosity of the logging, but to more finely-tune where in the code the logging is more detailed. A few current logging systems also possess this ability now.

The full power of our instrumentation system here, however, was that it was integrated with the rest of the event-reflexive core. This meant that it could peek into the action names and parameters, and test the values of them. These values could then be used to set or change the logging flags. A particularly powerful example could be:

A=add_user,reseller=foo,product=gold{LDAPw,LDAPwa};reseller=bar,user=frank{IMAP}

In this example, we are interested in logging the LDAP writes and attributes contained by them that happens during any attempt to add a new user to the foo reseller, for their gold product (perhaps because we are investigating some issue with this one), or separately, any IMAP-related activity that the bar user called frank performs. Because these are interpreted by the core of the event-reflexive system, they can apply fully recursively; applying to any nested inner action performed as part of the ultimate add_user action, for example.

Being strings, these tests could also be performed using regexps, though I never got around to implementing that test as part of this code, so they remained only simple string equality tests. However, even this far gets us an enormous amount of expressive power very simply, and virtually for free in the main body of action-handling code in the plugins, because almost all of it exists only once, at the very core. However, much of its power has come exactly because of the limited expressiveness of the individual arguments, being simple strings.

Over in my IRC bot, meanwhile, many of the arguments and return values being passed around between the named events were application-level objects expressing such concepts as IRC users, channels, and so on. These objects made it convenient to write the code powerful in the action handlers, but limited the ability of the event-reflexive core to introspect into them, to provide such abilities as detailed debug logging similar to that seen above for the ISP provisioning system.

This leads to my third question about event-reflexivity:

To what extent should the arguments of event-reflexive calls be understood and interpreted by the event-reflexive system itself, above simply passing them on to invoked action handlers? Do such abilities as powerfully flexible instrumentation logging justify limiting the expressiveness of the parameters that may be passed?

Next >