CycleServer supports logging events to an event log (or audit log). The API is based on the standard Log4j logger. Events are just records with a type of Event.

Getting a logger takes a single line. In Java, you get an instance of com.cyclecomputing.apex.event.Logger, typically in a class variable:

private static class Logger logger = Logger.getLogger(Your.class);

This is intentionally identical to the canonical Log4j usage, except for the Logger class imported at the top.

In Python, this uses the standard application.logger plugin:

from application import logger

Note

Examples in this document are given in Python. They typically work the same in Java except for language differences like the lack of keywork arguments.

The normal trace, debug, info, warn and error methods work unchanged, and levels at info and above generate Entry records in addition to the normal logfile output. When events are generated from the logger, they get the following attributes set:

Attribute Value
Message The first argument to the logger
Detail The exception and stack trace, if the second argument is given
Level Set to info, warning, or error (note: not warn!)
Priority Set to low
Module Set to the name of the logger, as it appears in the logfile

You can add your own attributes to the event with the context parameter:

logger.info("Created new user %s" % user_name, context={"AffectedUser": user_name, "Category": "auth"})

In addition, calls that accept a context accept shortcuts for category, priority, and primary:

logger.info("Created new user %s" % user_name, category="auth", context={"AffectedUser": user_name})

Besides the context included in a given call, the events get the current thread’s context included as well.

Specifying Context

Each logger operates in a context specific to the current thread. The current context specifies the attributes added to every event generated on that thread, for the length of that unit of work. The system sets some attributes automatically based on how that unit of work was invoked:

Attribute Value
EntryPoint What called this code (a URL, a timer name, a command name, etc)
User The authenticated user that invoked the action (or undefined if anonymous or system)

You can add any custom attributes to the context at any point:

logger.add({"CustomAttribute": "Value"})

This also supports the same shortcuts:

logger.add(category="config")

The add() call is additive, so you can call it later after you have identified more context attributes. The context is implemented as a stack, meaning you can use this in a loop as long as you pair logger.add with logger.remove:

for item in list:
  logger.add({"ItemId": item.id})
  # do the processing here
  logger.info("Processed item %s" % item.id)
  logger.remove()

The entire context stack is removed when the unit of work ends, so there is no need to “cleanup” by calling logger.remove. It is only used above because otherwise we could end up with a very large stack.

In the example above, there might only be a single event logged with the ItemId context attribute. In that case, it might be simpler to call the log method with the context argument:

for item in list:
  # do the processing here
  logger.info("Processed item %s" % item.id, context={"ItemId": item.id})

Which works better depends on the situation.

Logging Levels

The logging API uses the same levels as Log4j. These are the recommended purposes:

fatal: not used
This is turned into error in the event log, though it is still logged as FATAL in Log4j for backwards compatibility.
error: something went wrong
This means the operation was not successful. It may or may not be important (that would be a matter for priority), but it didn’t work.
warning: something might be wrong
This means that the operation took longer than expected, did not fully run properly, or encountered a situation it did not expect.
It could also indicate a recurring error, if we keep a cache of which operations failed recently and use that to downgrade failure events to warning.
info: things are great, and the user would care
This is for general notification of successful, high-level user-oriented operations.
It is very important this not be too “spammy” because it shows up in the user interface.
debug: no one is interested in this unless they are debugging the software
This is for developers, admins, or anyone who reads logfiles. It is intended for data that should be captured in the logs in case of a problem.
Having the corresponding source code handy may be helpful for understanding the messages.
trace: no one will ever see this unless they ask for it
This is for tracing a problem down that couldn’t be resolved with the existing logging at debug.
It is helpful for determing why code branched in a certain way that’s not obvious (for instance, an early-out to avoid an operation).
This is typically pointless without the corresponding source code.

Note

With this API, we changed the default logging level to DEBUG. Most messages that were INFO should be changed to DEBUG, and many of those at DEBUG should be changed to TRACE.

Regardless of the logging level, the messages logged should be compact and filled with dynamic data. Logging a completely static message is nearly always a bad idea, because there are very few things that have no data associated with them.

Handling Errors

Some events take a while to complete, particularly those that represent an interaction with a remote system. They also run the risk of failure. The logger API has a set of methods to make it easier to handle those cases:

logger.begin("to download the Internet")
# begin recursive curl here, which can use the logger as needed
logger.succeeded("Downloaded the entire Internet--it must be 1991")

The beginning of the event is marked with the logger.begin call, which does not log anything. Instead, it captures both the message and the time it was called. When logger.succeeded is called, it logs the message given to logger.succeeded (with Duration set to the elapsed time) and clears the captured information. However, if logger.succeeded is not called, and an exception is thrown instead, CycleServer automatically logs an error-level event with Message set to “Failed ” plus the begin message, Detail set to the stack trace, Duration set to the elapsed time, and any context given to the logger.begin call (eg, with the context keyword).

Note

The automatic message on failure indicates why the begin message should always begin with an infinitive (ie, “to verb something”).

This gives you two features for little work: capturing how long a process took, and automatically handling exceptions.

If you want to handle the exception yourself, you can get the same behavior by including this line:

logger.failed("Could not download the entire Internet at this time", exception)

This sets Duration and clears the last message.

Warning

Currently, nesting begin calls will not work as expected, and is not supported.

Attributes

Some attributes are added automatically if you use the logger API:

ActivityId
A unique value that identifies the sequence of events that occur on a
single thread.
Detail
Extended or supplemental information, such as an exception trace.
EntryPoint
The method by which this operation was initiated (such as a URL, a
timer, etc).
Id
The unique identifier of this event.
Level
The notification level (one of info, warning, or error).
Message
A summary or description of the event.
Module
The unit of code that generated this event (such as a class, plugin,
etc).
OperationId
A unique value that identifies an operation performed by a user.
Primary
True if this event should be flagged as a summary for the operation.
True by default except after a resume call.
Priority
The importance of this event (low, medium or high).
Time
The time this event happened or started at.
User
The name of the user who performed this operation, or undefined if
done by the system.

In addition, there are other attributes with standard meanings that are not added automatically:

ActivityId
A unique value that identifies the sequence of events that occur on a
single thread.
Category
One of several predefined ways to classify this event.
Comments
The reason for performing this operation, if given by the user.
Detail
Extended or supplemental information, such as an exception trace.
Duration
How long this event took to complete (optional).
EntryPoint
The method by which this operation was initiated (such as a URL, a
timer, etc).
Id
The unique identifier of this event.
Level
The notification level (one of info, warning, or error).
Message
A summary or description of the event.
Module
The unit of code that generated this event (such as a class, plugin,
etc).
OperationId
A unique value that identifies an operation performed by a user.
Primary
True if this event should be flagged as a summary for the operation.
True by default except after a resume call.
Priority
The importance of this event (low, medium or high).
Time
The time this event happened or started at.
User
The name of the user who performed this operation, or undefined if
done by the system.

Categories

The primary way that events are classified is by the Category attribute. This attribute must be set by the programmer generating the event. If none is set, it defaults to system. The following list is comprehensive, and one should be used from this list.

monitor
Indicates data was gathered from an external system, either by regularly polling or by receiving messages.
command
Indicates an action taken on an external system, such as holding a job or restarting a service.
config
Indicates a change made to configuration values for an external system, such as the maximum number of running jobs or a user’s quota on a filer.
settings
Indicates a change to a value for the CycleServer platform, such as adding a new external system to monitor or
updating rules applied when jobs are submitted.
auth
Indicates a change to authentication and authorization settings, such as a user, group or role being modified.
system
Indicates an internal operation has run, such as applying retirement rules or a backup completing.
notice
Indicates a notification of some condition, such as an alert firing, a job finishing, or a new version of software ready for download.

Resuming Operations

Normally, an operation lasts the length of the scope of one unit of work–a request, a task, a timer, etc. But if your request spawns background tasks, or stores data to be later processed, then the operation initiated by a request (on the primary thread) logically spans several units of work. In that case, you can resume from an earlier operation so that your new events are tagged with the same operation ID as earlier events. This will make them be associated together in the user interface.

You can get this behavior with the logger.resume method:

# on a background or second thread
my_custom_id = lookup_item_to_process()
logger.resume("MyCustomId === %s" % expressions.quote(my_custom_id))

This will find the most recent primary event where MyCustomId matches the value you supply. This means you must log at least one event in advance with MyCustomId set in the context:

# on the primary thread
logger.info("Processing %s" % the_current_id, context={"MyCustomId": the_current_id})
# now create background tasks or store somewhere a background polling thread will find this item

When you resume on another thread, the events are tagged with the same operation id as the events on the primary thread, as well as the same user. They are not tagged with Primary set to true, because they are assumed to be processing one of several parts of the operation. You can override this if the message you are generating should be treated as indicative of the overall operation:

# on a background thread
logger.info("Fully processed %s" % my_custom_id, context={"Primary": True})

Or the equivalent:

# on a background thread
logger.info("Fully processed %s" % my_custom_id, primary=True)