ReportStream Internal Error Monitoring

[JohnNKing]

Story

As an Intermediary engineer, so that I can notify CA about any errors that occur, I need a way to identify NBS error that occur during intermediary processing within ReportStream.

Pre-conditions

• [x] We've been given access to RS staging and have been provided with training.
• [x] Automated alerting is not mandatory for this story.

Acceptance Criteria

• [x] If processing of a message fails in ReportStream, that failure can be identified via a query.
• [x] If a message fails to be delivered, that can be identified via a query.
• [x] Only ETOR-specific errors are identified via these queries.

Tasks

Engineering

• [x] Create a query that will filter only ETOR-specific log errors
  • [x] Evaluate if possible to filter only ETOR logs
  • [x] If not possible, what do we need to add this functionality?
• [x] Document the failure scenarios we want to test: done here
• [x] Make sure we have sample messages in the repo to test those scenarios PR here
• [x] Test with different failure scenarios
• [x] Determine if it's easy to generate automated alerts based on what we can access today. (No, we cannot at present)

AC Queries

• If processing of a message fails in ReportStream, that failure can be identified via a query. There are different queries depending on where the error happens
• If a message fails to be delivered, that can be identified via a query.

  customEvents
  | where name == "ITEM_NOT_ROUTED"
  | where tostring(customDimensions.topic) == 'etor-ti'

• Only ETOR-specific errors are identified via these queries.

  customEvents
  | where tostring(customDimensions.topic) == 'etor-ti'

  Though this topic is not availble for all log entries. It depends on where the log was generated

Definition of Done

• [x] Documentation tasks completed
  • [x] Documentation and diagrams created or updated
  • [x] Implementation guide (/ig folder)
  • [x] ADRs (/adr folder)
  • [x] Main README.md
  • [x] Other READMEs in the repo
  • [x] If applicable, update the ReportStream Setup section in README.md
  • [x] Threat model updated
  • [x] API documentation updated
• [x] Code quality tasks completed
  • [x] Code refactored for clarity and no design/technical debt
  • [x] Adhere to separation of concerns; code is not tightly coupled, especially to 3rd party dependencies
  • [x] Code is reviewed or developed by pair; 1 approval is needed but consider requiring an outside-the-pair reviewer
  • [x] Code quality checks passed
• [x] Security & Privacy tasks completed
  • [x] Security & privacy gates passed
• [x] Testing tasks completed
  • [x] Load tests passed
  • [x] Unit test coverage of our code >= 90%
• [x] Build & Deploy tasks completed
  • [x] Build process updated
  • [x] API(s) are versioned
  • [x] Feature toggles created and/or deleted. Document the feature toggle
  • [x] Source code is merged to the main branch

Research Questions

• Optional: Any initial questions for research

Decisions

• Optional: Any decisions we've made while working on this story

Notes

• Optional: Any reference material or thoughts we may need for later reference

[JohnNKing]

Blocked waiting on access and a meeting to show us the process

[JohnNKing]

Discussing RS proposal today

[basiliskus]

We now have access to RS logs in staging and production. We'll evaluate if possible to create alerts for error logs

[basiliskus]

RS is actively working in adding log parameters that will allow us to query the logs filtering by topic, sender, receiver, etc. Here's the PR: https://github.com/CDCgov/prime-reportstream/pull/15263

[basiliskus]

Currently RS doesn't have the permissions required to create the log alerts and queries. They will look into getting access

[basiliskus]

I'll mark this story as blocked while RS works on that PR and the ability to create alerts

[basiliskus]

RS PR has been merged. Removing the blocked label

[basiliskus]

Here's a KQL query to filter by the etor-ti topic, now that the capability has been added to RS:

traces
| extend customDimensionsParsed = parse_json(customDimensions)
| where customDimensionsParsed.TOPIC == '"etor-ti"'

[basiliskus]

Here's a first version of a KQL query to select and unpack the fields we care about

traces
| project timestamp, message, customDimensions, appId
| extend 
    messageParsed = parse_json(message),
    customDimensionsParsed = parse_json(customDimensions)
| extend 
    mdc_span_id = messageParsed.mdc.span_id,
    mdc_trace_flags = messageParsed.mdc.trace_flags,
    mdc_trace_id = messageParsed.mdc.trace_id,
    message_content = messageParsed.message,
    message_thread = messageParsed.thread,
    message_timestamp = messageParsed.timestamp,
    message_level = messageParsed.level,
    message_logger = messageParsed.logger,
    customDimensions_ProcessId = customDimensionsParsed.ProcessId,
    customDimensions_Category = customDimensionsParsed.Category,
    customDimensions_HostInstanceId = customDimensionsParsed.HostInstanceId,
    customDimensions_LogLevel = customDimensionsParsed.LogLevel
| project 
    timestamp,
    appId,
    mdc_span_id,
    mdc_trace_flags,
    mdc_trace_id,
    message_content,
    message_thread,
    message_timestamp,
    message_level,
    message_logger,
    customDimensions_ProcessId,
    customDimensions_Category,
    customDimensions_HostInstanceId,
    customDimensions_LogLevel

[basiliskus]

Another query with extended fields found in customDimensions:

traces
| extend 
    messageParsed = parse_json(message),
    customDimensionsParsed = parse_json(customDimensions)
| extend 
    messageTimestamp = messageParsed.timestamp,
    messageLevel = messageParsed.level,
    messageContent = messageParsed.message,
    messageLogger = messageParsed.logger,
    messageMdc = messageParsed.mdc,
    messageThread = messageParsed.thread,
    customProcessId = customDimensionsParsed.ProcessId,
    customCategory = customDimensionsParsed.Category,
    customHostInstanceId = customDimensionsParsed.HostInstanceId,
    customLogLevel = customDimensionsParsed.LogLevel,
    customPipelineStepName = customDimensionsParsed.pipelineStepName,
    customParentReportId = customDimensionsParsed.parentReportId,
    customChildReportId = customDimensionsParsed.childReportId,
    customBLOB_URL = customDimensionsParsed.BLOB_URL,
    customBlobUrl = customDimensionsParsed.blobUrl,
    customCdProcessId = customDimensionsParsed.ProcessId,
    customSender = customDimensionsParsed.sender,
    customSubmittedReportIds = customDimensionsParsed.submittedReportIds,
    customCdTimestamp = customDimensionsParsed.timestamp,
    customTopic = customDimensionsParsed.topic,
    customTrackingId = customDimensionsParsed.trackingId
| project
    timestamp, 
    message, 
    customDimensions,
    messageTimestamp,
    messageLevel,
    messageContent,
    messageLogger,
    messageMdc,
    messageThread,
    customProcessId,
    customCategory,
    customHostInstanceId,
    customLogLevel,
    customPipelineStepName,
    customParentReportId,
    customChildReportId,
    customBLOB_URL,
    customBlobUrl,
    customCdProcessId,
    customSender,
    customSubmittedReportIds,
    customCdTimestamp,
    customTopic,
    customTrackingId
| where customTopic == "etor-ti"

[basiliskus]

Documented AppInsights KQL queries in RS: https://github.com/CDCgov/prime-reportstream/blob/master/prime-router/docs/observability/azure-events.md

[basiliskus]

After the most recent update in RS, this is how we can query logs by sender name:

customEvents
| where name == "REPORT_RECEIVED"
| extend params = parse_json(tostring(customDimensions.params))
| where params.senderName == "flexion.etor-service-sender"

By receiver name:

customEvents
| where name == "REPORT_SENT"
| extend params = parse_json(tostring(customDimensions.params))
| where params.receiverName == "la-phl.etor-nbs-orders"

[basiliskus]

It seems this is where the terraform resource should be added in RS: operations/app/terraform/modules/application_insights/

[basiliskus]

I'm documenting error scenarios in RS and the queries associated to troubleshooting here

[JohnNKing]

Just one thing I noticed in comparing REPORT_RECEIVED to REPORT_SENT on the etor-ti topic: there's a slight disparity that not routed outcomes and trace errors don't seem to account for.

Past month:

• 170 received
• 140 sent
• 23 not routed
• 4 errors
• 3 unaccounted for?

Looking at just Aug 13-15 (midnight-midnight UTC)

• 39 received
• 25 sent
• 10 not routed
• 3 errors
• I found the missing one: two arrived at 7:39 PM UTC on 8/13, but only one went out. No errors or not routed outcomes at that time.

[basiliskus]

I found the error for the message that arrived to RS on 7:39 PM UTC on 8/13: Unexpected scheme: null. To get the error you can use this query: `traces | where severityLevel > 1