T3.4: Uses Logs and Debugging

Purpose

The Business Rule Log provides a comprehensive history of all routing rule and decision rule executions across the production. This log is invaluable for understanding why messages routed to specific destinations or why certain business decisions were made.

Log Entry Contents

Each entry in the Business Rule Log represents one rule execution, showing when the rule executed, which component invoked it, which rule set was used, and what result the rule returned. For routing rules, the result shows the list of target configuration names the message was routed to. For decision rules, it shows the decision values returned. This historical record allows you to investigate routing behavior without reproducing the original message flow.

Navigation to Visual Trace

The log provides direct navigation to the associated message session. Each rule log entry includes a link to the session where the rule executed. Clicking this link opens Visual Trace for that session, showing the rule execution in context with all related messages. This integration between Business Rule Log and Visual Trace makes it easy to understand not just what decision was made, but what message triggered the decision and what processing occurred afterward.

Search Capabilities

Search capabilities within the Business Rule Log allow filtering by time range and component name. When investigating routing issues for a specific component, you can filter to show only rule executions for that component's routing engine. Time range filtering is useful when you know when the problem occurred and want to examine rule executions during that period.

Detailed Analysis in Visual Trace

For detailed rule execution analysis, the Visual Trace provides the most comprehensive view. Within Visual Trace, rule executions appear as numbered green icons. Clicking these icons displays the Reason field, which contains detailed execution information including which specific rule in the set matched and which when clause triggered. This level of detail is essential for debugging complex routing rules with multiple when clauses and conditional logic.

Troubleshooting Value

The Business Rule Log is particularly valuable when troubleshooting scenarios where messages aren't routing as expected. By examining the log, you can verify that the routing rule actually executed (if no log entry exists, the component may not be configured correctly), confirm which targets were selected, and identify patterns in routing decisions over time.

Central Repository

The Event Log is the central repository for all production events, providing comprehensive visibility into errors, warnings, informational messages, and developer trace statements. Understanding the event type hierarchy and how to effectively search the log is essential for production troubleshooting.

Error Events

Error events represent integration failures that require immediate attention. These include message processing errors, external system connectivity failures, transformation errors, and component crashes. When troubleshooting production issues, the Event Log filtered to show only Errors provides a focused view of problems requiring resolution. Each error entry includes the error message text, stack trace (when available), source component, and timestamp. This information typically points directly to the root cause.

Warning Events

Warning events indicate non-critical issues that don't halt processing but may signal problems. Common warnings include TCP connection disconnects (which may be normal during connection recycling), inactivity timeouts, retry attempts, and deprecated feature usage. While warnings don't require immediate action like errors, they often signal degrading conditions that may lead to failures if unaddressed. For example, increasing frequency of connection warnings may indicate network instability.

Info Events

Info events provide operational context without indicating problems. These include component start/stop events, configuration changes, manual operator actions, and normal processing milestones. Info events are valuable for understanding production timeline and correlating operational changes with issues. For example, if errors began after a specific time, checking Info events for that timeframe may reveal a configuration change or component restart that triggered the problems.

Trace Events

Trace events are developer-generated debugging messages created using $$$TRACE macros or similar logging statements in custom components. These events only appear in the log if the component's "Log Trace Events" setting is enabled. By default, this setting is disabled to prevent log clutter in production environments. When debugging custom component logic, enable Log Trace Events for the specific component, reproduce the issue, then examine Trace events to see detailed execution flow. Remember to disable Log Trace Events after debugging to prevent performance impact from excessive logging.

Assert Events

Assert events represent assertions in code, typically used during development to verify assumptions. Like Trace events, these are primarily relevant during development and debugging rather than normal production operation.

Context-Aware Filtering

When navigating to the Event Log from the Production Configuration page with a specific component selected, the log automatically filters to show only events for that component. This context-aware filtering accelerates troubleshooting by eliminating noise from unrelated components. However, be aware that this filtering persists even when navigating directly to the Event Log from other pages. Always check the Source Config Name filter to ensure you're viewing the intended scope of events.

Filter Capabilities

The Event Log search interface provides powerful filtering capabilities that must be used effectively to find relevant events in potentially large logs. Understanding how filters work and interact is critical for efficient troubleshooting.

Source Config Name Filter

The Source Config Name filter restricts events to those generated by a specific production component. The dropdown lists all current production components plus any historical components that generated logged events. This filter is particularly useful when troubleshooting component-specific issues. When investigating a Business Operation's connectivity problems, filtering to that operation's name shows only its errors and warnings, eliminating events from other components.

Automatic Filter Population

An important characteristic of Source Config Name filtering is automatic population when navigating from the Production Configuration page. If you select a component in the production and click to view its Log tab, the Event Log opens with Source Config Name pre-set to that component. This accelerates troubleshooting but can be confusing if you forget the filter is active. You may navigate to the Event Log expecting to see all events but see only one component's events due to persistent filtering from a previous navigation.

Time Range Filtering

Time range filtering uses StartTime and EndTime parameters to show only events within a specific window. This is essential when investigating incidents that occurred at known times. For example, if an external system was unavailable from 2:00 PM to 2:15 PM, setting the time range to that window shows only events during the outage, making it easy to identify which messages failed and which components were affected.

Event Type Filtering

Event type filtering allows selecting specific severities: Error, Warning, Info, Trace, Assert, or All. For initial troubleshooting, filtering to Errors provides a focused view of problems. For comprehensive investigation, All shows the complete event timeline including errors in context with warnings and info messages. This context often reveals that what appears as a sudden error was actually preceded by warning signs visible in the full event stream.

Reset Button Importance

The Reset button is critically important because Event Log filters persist between page visits. If you set Source Config Name to MyOperation and return to the Event Log later (even in a different browser session if cookies persist), the filter remains active. This can lead to confusion where you expect to see all events but see only one component's events. Always check active filters when the Event Log displays fewer events than expected, and use Reset to clear all filters and view the complete log.

Search Results Display

Search results display with the most recent events first by default, which is appropriate for most troubleshooting scenarios where you're investigating recent issues. Each event row shows timestamp, source component, event type, and abbreviated event text. Clicking an event row displays full details including complete error messages and stack traces.

Multi-Component Troubleshooting

For complex troubleshooting scenarios involving multiple components, consider searching without Source Config Name filtering but with appropriate time range filtering. This reveals interaction patterns between components and helps identify cascading failures where an error in one component triggers failures in downstream components.

Setting Overview

The Log Trace Events setting provides granular control over trace-level logging for individual production components. Understanding when and how to use this setting is important for effective debugging without impacting production performance.

How It Works

Log Trace Events is a component-level setting found in the Additional Settings section of each Business Service, Business Process, and Business Operation. When enabled, trace statements within the component's code generate entries in the Event Log. When disabled, trace statements execute but no log entries are created. This allows developers to include detailed trace logging in code that can be activated on-demand without requiring code changes.

Default Setting Rationale

The setting defaults to disabled for good reason. Trace logging can generate significant volumes of log entries, especially in high-throughput components. In production environments, this log volume can impact performance (due to I/O overhead of writing log entries) and make it difficult to find relevant error and warning messages among trace output. Therefore, trace logging should remain disabled during normal operation.

When to Enable

Enable Log Trace Events when actively debugging component behavior, especially for custom-developed components. When investigating why a Business Process isn't making expected routing decisions or why a transformation isn't mapping data correctly, enable tracing for that specific component, reproduce the issue, then examine the Trace events in the Event Log. The trace output shows execution flow, variable values, and decision points within the code.

Post-Debugging Cleanup

After debugging is complete and the issue is resolved, remember to disable Log Trace Events. Leaving tracing enabled indefinitely degrades performance and clutters the Event Log. In production environments, establish a policy of reviewing enabled trace settings periodically to ensure components aren't inadvertently left in trace mode.

Selective Enabling

For HealthConnect installations with many components, selectively enabling tracing for only the component under investigation minimizes performance impact. You can enable tracing for a Business Process while leaving it disabled for the Business Services and Business Operations it communicates with. This focused approach provides necessary debugging information without system-wide logging overhead.

Other Event Types

The Log Trace Events setting applies only to trace-level events. Error, Warning, and Info events always log regardless of this setting. This ensures critical events are never lost even when tracing is disabled.

Audit Capabilities Overview

InterSystems IRIS includes comprehensive auditing capabilities that automatically track specific production events in the Audit Database. Understanding which events are audited and how to access audit information is important for compliance, security, and troubleshooting.

The Ensemble (now HealthConnect/Interoperability) components generate five primary auditable event types. The event names retain the "Ensemble" prefix for historical compatibility, even though the product is now called HealthConnect or Interoperability.

EnsembleMessageResend

EnsembleMessageResend events are created whenever an operator uses the Message Viewer to resend one or more messages. This audit trail records who resent messages, when the resend occurred, which messages were resent, and whether standard resend, edit and resend, or new target resend was used. This is particularly important for compliance environments where message reprocessing must be tracked and justified. If resent messages trigger actions in external systems (lab orders, medication administration records), the audit trail provides evidence of what was done and by whom.

EnsembleViewContents

EnsembleViewContents events track when operators view message content through the Management Portal. In healthcare environments handling PHI (Protected Health Information), this audit trail demonstrates compliance with privacy regulations by recording who accessed patient data and when. Not all message viewing generates audit events; only actions that display the actual message content trigger auditing.

EnsembleModifyConfiguration

EnsembleModifyConfiguration events record changes to component settings within the production. When an operator modifies a Business Operation's IP address, enables Archive I/O, or changes any component setting, an audit event captures the change, who made it, and when. This audit trail is invaluable when troubleshooting configuration-related issues, as it allows correlating problems with recent configuration changes.

EnsembleModifyDefaultSettings

EnsembleModifyDefaultSettings events specifically track changes to System Default Settings, which are configuration defaults that apply across productions. These settings have production-wide impact, so changes are separately audited to ensure visibility into system-level configuration modifications.

EnsembleStartStop

EnsembleStartStop events record production start and stop actions. This audit trail shows who started or stopped the production and when, which is critical for understanding production availability and correlating outages with operator actions versus system failures. If a production was stopped during a time when it should have been processing messages, the audit event identifies who stopped it.

Audit Event Properties

All audit events include the username of the person who performed the action, the timestamp, and event-specific details. Audit data is stored in the InterSystems Audit Database, separate from the production database, ensuring audit trail integrity. Audit events cannot be modified or deleted through normal interfaces, providing tamper-resistant accountability.

Viewing Audit Events

To view audit events, access the Audit Database through the Management Portal System Administration menu. The audit interface allows searching by event type, date range, user, and other criteria. When investigating production issues, checking audit events often reveals that configuration changes or message resends correlate with problem onset.

Integration Overview

The integration between the Business Rule Log and Visual Trace provides comprehensive visibility into routing rule and decision rule execution. Understanding how to access and interpret rule execution details is essential for debugging complex routing scenarios.

Green Numbered Icons

In Visual Trace, rule executions appear as distinctive green icons with numbers inside. The number indicates the sequence of rule executions within the session—the first rule execution is numbered 1, the second is 2, and so on. This numbering makes it easy to identify multiple rule executions in sessions where messages pass through several routing engines or where a single routing engine is invoked multiple times.

The Reason Field

Clicking a green rule execution icon displays detailed information in the details panel below the trace. The most important field is Reason, which contains the complete execution path through the rule. The Reason field specifies which rule set was used (important when multiple routing engines exist in the production), which specific rule within the set matched, and which when clause within that rule triggered.

For example, a Reason might state: "Executed rule 'ADT_Routing', matched rule 'Route to Registration', selected when clause 'Patient is inpatient' based on condition PV1:2.1='I'". This level of detail makes it immediately clear why the message routed to specific destinations and what data values drove the decision.

Rule Execution Results

The rule execution details also show the result returned by the rule. For routing rules, this is the list of target configuration names the message was sent to. For decision rules, it's the decision value or values returned. Comparing the expected targets against the actual targets shown in the rule execution helps identify configuration mismatches or unexpected data values.

Visual Trace Context

Visual Trace rule execution details complement the Business Rule Log by providing execution information in the context of the complete message flow. While the Business Rule Log shows all rule executions in a searchable list, Visual Trace shows each execution in relation to the messages that triggered it and the messages it generated. This context is invaluable for understanding complex routing scenarios where multiple components and rules interact.

Troubleshooting Workflow

When troubleshooting routing issues, the workflow is typically: identify the problem message in Message Viewer, open its Visual Trace, locate the rule execution icon, examine the Reason field to understand what decision was made and why, and compare against expectations. If the rule didn't execute at all (no green icon appears), the problem is likely in component configuration or message routing before the rule engine. If the rule executed but selected unexpected targets, the Reason field shows which when clause matched, allowing you to verify the routing rule logic against actual message data.

Complementary Tools

The combination of Business Rule Log for historical analysis and Visual Trace for detailed execution context provides comprehensive rule debugging capabilities.