Logging Noise Seen from Resource Processor

[martinpeck]

When running an AppInsights query such as this...

traces
| where cloud_RoleName == "runner.py"
| where message !startswith "Retrying due to transient client"
| where message !startswith "No sessions for this process"
| where not (message startswith "Unable to find image" and strlen(message)<170)
| where severityLevel >1
| order by timestamp desc

... a number of messages that are simply [stderr] are reported...

Specifically, this query will return all such logs:

traces
| where cloud_RoleName == "runner.py"
| where message == "[stderr]"

This appears to be related to code in runner.py and logging.py within the resource processor.

We need to avoid this noise and, at the same time, make sure this noise doesn't mean we're dropping other more important logs.

[martinpeck]

Is shell_output_logger ever supposed to log to AppInsights?
The name suggests it shouldn't.

[tamirkamara]

When addressing this just need to also account for local development and us using direct console view (like docker logs) on the vm.

[stuartleeks]

I'm seeing a lot of noise from the Retrying due to transient client... error

I just ran this query:

traces
| where message startswith "Retrying due to transient client side error HTTPsConnectionPool(host='westus-0.in"
| summarize count() by bin(timestamp, 1s)
| render timechart 

And get the following output showing a flurry of instances roughly every 15 minutes

It's not a great experience when you're digging into the logs to troubleshoot an issue!

[marrobi]

At present:

    logger.log(logging_level, prefix_item)
    logger.log(logging_level, console_output)

This means [stderr] prefix appears as its own entry.

Will look at changing to:

    logger.log(logging_level, f"{prefix_item} {console_output}")

Also default log level is INFO, some packages are outputting too much info at the INFO level, such as service bus, going to look at changing the default to `WARN' when not debugging. Ideally this would be configurable.