Logging

No web server would be complete without a robust logging system. With Caliper, we’ve added a few helpers to the powerful built-in logging module, and the result is an easy-to-use and feature-rich logging suite. This will work out of the box when you run your server with q2 run, but can be customized in a variety of ways.

Structure

Because this is based on the builtin Python logging module, there is a lot of information in the python logging documentation.

In addition, there are several pieces you should be familiar with in Caliper itself. When you invoke an entrypoint from the command line interface such as q2 run, a logger is instantiated. In Python, when logger is created, it takes a configuration to determine whether the output is sent to stdout, a file, or a series of files. In Caliper, we provide a configuration at q2_sdk.core.default_logging.conf that will be used by default. This streams data to stdout and stderr in the following format:

%(asctime)s.%(msecs)03d %(name)-15s %(levelname)-8s %(message)s

For instance:

2017-10-06T14:29:26.342 q2_sdk.general  INFO     Starting Server on port 1980

The benefit of this approach is you have less to configure to start getting work done. There’s only one place to look for all the logs your server is generating: stdout in the terminal running the server.

However, this server is likely to have multiple requests coming in simultaneously, which could lead to a confusing log with multiple calls interwoven. To address this, Q2RequestHandlers (the class from which extensions inherit) generate a unique GUID for each request. Log lines written from RequestHandlers have the following format:

%(asctime)s.%(msecs)03d %(name)-15s %(guid)s %(levelname)-8s %(message)s

For instance:

2017-10-06T14:38:41.678 extension.inspect 4309e017c72f4b31bc6a5cc05213c9b1 INFO     Info message

You can see two pieces that differ here. The %(name) piece resolves the name of the endpoint, while the %(guid) is filled in with a value that will remain the same for the duration of the request. Other traffic can be handled in the interim of a long call, but you can splice the history of the request back together at a later time using the GUID.

Writing Logs

To output a log line during the runtime of your server, simply add the following to your extension:

self.logger.info('Message')

That’s it!

• info can be either info, debug, error, or warning. More on logging levels below.

• Message can be anything that you would put into a Python print() statement: strings, integers, variables referencing values of these types, etc.

Levels

It is often convenient to take advantage of distinct levels of logging, as the logging needs of a local debug session are likely different than those of deployed production servers. Fortunately, Python (and by extension, Caliper) makes this very simple to use. By default, entrypoints will run with logging level INFO, but swapping to another level is as easy as adding a --logging-level LEVEL (-l LEVEL for short) to the end of the command. For instance:

q2 run -l DEBUG

It is also possible to set this value with the environment variable Q2SDK_LOGGING_LEVEL:

Q2SDK_LOGGING_LEVEL=DEBUG q2 run

Note

In production, logs will be run at log level INFO

You can also temporarily change the logging level at runtime by hitting the /logging endpoint.

Summary Line

One of the most powerful features we have for troubleshooting in Caliper is our summary log implementation. This feature allows you to log key pieces of information, allowing for faster troubleshooting and root cause analysis.

By default, summary logs capture essential details such as the HQ session identifier, the user’s login name, the customer key (for multitenant extensions), and other key identifiers that can be used to quickly trace errors.

Unlike standard logs that are captured at the INFO level, summary logs are captured at the SUMMARY level. This unique log level makes it easy to sift through and find summary lines, providing a quick snapshot of critical information needed for troubleshooting.

When Would You Need To Expand Summary Logs?

If you constantly need to track the same information for debugging, summary logs are the perfect solution. You can customize the summary log entries to include additional key data points beyond the default values captured.

For example, you may want to log the HQ authentication token and logon audit ID along with the default values. This can easily be done by overriding the default summary log behavior using the override_summary_log property in your code. Here’s an example:

@property
def override_summary_log(self):
    summary_dict = {
        'HQ_Auth_Token': self.online_session.hq_auth_token,
        'Audit_ID': self.online_session.logon_audit_id,
    }
    return summary_dict

How Is This Applied?

When an error occurs and we need to grab more details, we first search for the summary line in the logs:

2024-03-11T16:11:37.119 extension.MyAuditExtension SUMMARY  Q2     047ca815802e45cf91bcc07675ad07af summary line: status_code='200' HQ_ID='55bi4n2davpkereg2uacnabp' login_name='retail0' customer_key='1234'

• The HQ_ID helps us quickly locate logs related to HQ calls during failures.

• The login_name is used to quickly identify the end user tied to the session.

• The customer_key is especially useful in multitenant environments, as it helps identify the stack or environment the extension is running in.

You will notice a guid next to the summary line: string, which pertains to the SDK session. This value will be captured for every log line regardless of the log level, and is essential for tracking requests from when the user clicks and interacts with the SDK extension.

By customizing the override_summary_log method, you can include any additional relevant data that will assist with troubleshooting.

For a guided experience, check out our Online Banking Logging Tutorial.

Log Replay

To reduce log clutter, especially when using debug-level logging, we’ve introduced a log replay feature that allows you to capture relevant logs without overwhelming you with unnecessary details. It allows you to minimize log noise generated by lower levels while still providing detailed logs when a critical error, like a 500 Internal Server Error, occurs. When such an error is triggered, the system captures all log entries in a buffer and replays them from the start of the request to help you understand the entire flow that led to the error.

By default, this functionality is enabled to monitor 500 errors, but it can be customized to replay logs for other events as well.

Note

This functionality is currently enabled in production via our Q2SDK_ENABLE_LOG_REPLAY environment variable (more details can be found in our Configuration guide), where logs are solely captured at the INFO level.

How Does It Work?

When a 500 error is detected, all logs associated with that request are stored in a buffer and then replayed to provide complete context. This is incredibly useful for troubleshooting, especially when you need to trace the sequence of events that led to the failure.

Here’s an example of how this is embedded in the code:

if self.get_status() == 500:
    self.logger.replay_buffer()

The structure of the logs when log replay is enabled would look similar to the following:

2025-03-11T18:23:40.411 extension.OnlineExtSS INFO     Q2     b542dcb1ca7847d29c6028ec8e52622c Transition: routing to 'default'
2025-03-11T18:23:40.411 extension.OnlineExtSS REPLAY   Q2     b542dcb1ca7847d29c6028ec8e52622c ↹↹↹↹↹ Start Log Replay ↹↹↹↹↹
    All logs from the previous failed request will be replayed, regardless of log level
    RequestId: b542dcb1ca7847d29c6028ec8e52622c
    Start: 2025-03-11 18:23:40.409964
    End: 2025-03-11 18:23:40.411322
2025-03-11T18:23:40.411 extension.OnlineExtSS REPLAY   Q2     b542dcb1ca7847d29c6028ec8e52622c BODY: b'<<GroupID>1</GroupID>
...
Any additional logs within the request are captured
...
2025-03-11T18:23:40.412 extension.OnlineExtSS REPLAY   Q2     b542dcb1ca7847d29c6028ec8e52622c Transition: routing to 'default'
2025-03-11T18:23:40.412 extension.OnlineExtSS REPLAY   Q2     b542dcb1ca7847d29c6028ec8e52622c ↹↹↹↹↹ End Log Replay ↹↹↹↹↹
2025-03-11T18:23:40.427 tornado.access  INFO     200 b542dcb1ca7847d29c6028ec8e52622c POST /OnlineExtSS (::1) 18.79ms
2025-03-11T18:23:40.427 extension.OnlineExtSS SUMMARY  Q2     b542dcb1ca7847d29c6028ec8e52622c summary line: status_code='200' HQ_ID='jne54unzrdbwrcwi1r1ru5dl'

This default behavior helps to reduce the noise of logs generated at other levels, by allowing you to maintain your logs at the INFO level and only invoke lower level logs when needed. With this feature, you have the flexibility to trigger log replay for various events as needed.

Customizing Log Replay

You can manually trigger log replay for specific scenarios. For instance, if you have a try-except block where an exception is raised, you might want to replay the logs up to that point. This can be easily done using the self.logger.replay_buffer() function.

Here’s an example:

try:     # Some operation that may cause an error
    result = await self.perform_critical_operation()
except CriticalOperationError:     # Log replay triggered when an error occurs
    self.logger.replay_buffer()
    return ERROR_OCCURRED

In this case, the replay_buffer() function would capture all logs that occurred before the exception, helping you understand the context of the error.

Filtering

Perhaps there are lines you do not want printed to your logs or, alternatively, you would like a cleansed version to appear. In each of these cases, log filtering is the tool for the job. Filters can be set on a per-extension basis or globally, giving you total flexibility in your logging. Let’s look at an example:

Consider the line:

self.logger.info("Here's my social security number: 123-45-6789")

What if you need to mask the social security number to appear as ‘xxx-xx-6789’ in your logs? This is one of our built-in filters that live in q2_sdk.core.q2_logging.filters, called TaxIDFilter. It looks like this:

class TaxIDFilter(BaseMaskingFilter):
    r"""
    Masks Social Security Numbers

    The RegEx is a bit gross, but it's faster than splitting it into two,
    and since this is called on every log line, speed matters here.

    Here's a breakdown:

    123-45-6789
    \d{3}-?\d{2}-\d{4}

    12-3456789
    \d{2}-\d{3}\d{4}

    It's the last 4 (\d{4}) that matter so we can print them later. So we wrap
    them in a () to capture them. The | is an OR, and ? is optional so we can
    have 123456789 also match.
    """

    PATTERN = re.compile(r'\b(?:\d{3}-?\d{2}-?|\d{2}-\d{3})(\d{4})\b')

    def _mask(self, inp: str):
        inp = re.sub(self.PATTERN, r'xxx-xx-\1', inp)
        return inp

When a log record is passed into that _mask method, the Filter object has two purposes. First, if it returns False, the line will be completely hidden from output. Secondly, if the record.msg is altered and then the method returns True, the altered record.msg is the one displayed. That’s how we accomplish the masking.

In our example, we’ve identified what Filter we want to use, so let’s look at how to hook it up. As mentioned above, there are two options, global and extension-specific.

This will affect all log lines from all extensions. This is as simple as populating the list GLOBAL_LOGGING_FILTERS in your settings file with a reference to the Filter.:

from q2_sdk.core.q2_logging import filters
GLOBAL_LOGGING_FILTERS = [filters.TaxIDFilter()]

Note

TaxIDFilter is already on by default, it is shown here for demonstration purposes.

This will only apply the filter to specific extensions. To configure your filters this way, take advantage of the self.LOGGING_FILTERS static attribute on Q2RequestHandler. You can set this in the class area of your extension’s Q2RequestHandler:

from q2_sdk.core.q2_logging import filters
...

class MyExtensionHandler(q2_sdk.core.web.Q2RequestHandler):

    LOGGING_FILTERS = [filters.TaxIDFilter()]

    def __init__(self, application, request, **kwargs):
        """
        If you need variables visible through the lifetime of this request,
        feel free to add them in this function
        """
        super().__init__(application, request, **kwargs)

You are welcome to write your own Filters as well. Follow the pattern of the classes in q2_sdk.core.q2_logging.filters, ensuring you inherit from q2_sdk.core.q2_logging.filters.BaseMaskingFilter. Define whatever _mask method you would like and reference your new filter either globally or per-extension. Happy logging!

Accessing Datacenter Logs

Note

Datacenter logs are all written in UTC time, while local logs are written in whatever your machine’s local time is.

Note

To pull logs for a particular service:

• Your company must be entitled for a particular service (to get entitled create a support ticket on q2developer.com)

• You must have self service access (which you can receive either from your company’s q2developer admin or by making a support ticket on q2developer.com)

• You need to enable Two-factor Authentication. You can setup Two-factor Authentication here: https://www.q2developer.com/settings/security

After your SDK service is running in Staging or Production, you can pull those logs from the left-hand menu item under “Self Service” called “Logs”.

You can pull aggregated logs using the Caliper Deployment Manager (CDM)

• Staging

• Production

Find your service under Nomad tab on the left, then expand and click one of the buttons under “Get Job Logs”

Overrides

The Q2 team provides sane defaults for the various customizable logging components, but here’s how to customize your own overrides.

• Custom Log configuration

  • Create a logging configuration file in the format of q2_sdk.core.default_logging.conf.

  • In your settings file, set LOGGING_CONF to your custom logging configuration file.

  • For more options of what can be contained in this file, refer to the python dictConfig documentation.

Generating HAR logs

HAR (HTTP Archive File) is a log format specialized in tracking browser network requests, making it an excellent tool to troubleshoot UI issues. We can save the session data in a file with the .har extension using the following steps in Chrome:

• Access the website. Open developer tools

• Open out the Network tab. Check the Preserve log and Disable cache boxes.

• Right Click on the request that you want to debug, right click and select Save all as HAR with content.

• Save the file locally.

The .har file generated has data in JSON format.

Warning

HAR files contain sensitive data such as passwords, recording of downloaded pages, cookie contents etc. It is therefore advised to delete all such sensitive data before forwarding the data to external parties.