[Discussion] Need a better way to hook into the logging framework provided by webjobs.

[bakatz]

Fair warning: this is going to be fairly long winded and I hope this is the right place to post this.

Problem: my application is comprised of an API component and a background processing component which uses WebJobs. All parts of the app use Serilog in order to send diagnostic messages to an elasticsearch cluster. I want each webjob's logs to appear in both the dashboard and in the elasticsearch cluster.

There are four possible solutions to this problem that I explored, none of which ended up working out completely for me:

1. Implement a custom Serilog Sink to handle pushing logs to webjobs, and implement a "passthru" TraceWriter which should be added to the JobHostConfiguration before initialization. Basically this was an attempt to "trick" WebJobs into recognizing that logging is happening and to send said logs to the dashboard. This is, IMO, the cleaner option overall as I would theoretically be able to just inject an ILogger instance everywhere and have logs magically appear where they need to be, but unfortunately when I implemented this, it seemed like all logs that my webjob sent (i.e. explicit ILogger.Information() calls) were being ignored, while runtime-generated logs such as exception messages worked fine and were logged to the dashboard. So this option didn't work at all for me.

2. Attempt to enable Console, Trace, File, etc. logging in Serilog in hopes of getting WebJobs to pick up one of them and send the logs to the dashboard. This didn't work despite some StackOverflow posts saying it would. :)

3. Implement a custom TraceWriter that has a serilog dependency. This actually worked and allowed logs to be stored in both the webjobs dashboard and the elasticsearch cluster. However, it's a messy solution because I had to call Serilog's internal message parser to generate a log that the dashboard would be able to display (it doesn't understand serilog's message templates). It's additionally messy because certain shared code needed both an ILogger dependency and an optional TraceWriter dependency for the case when the shared code is being invoked from the WebJobs runtime. I considered just using the TraceWriter that I wrote everywhere to avoid multiple logging dependencies, but that seemed a bit odd as I figured pieces of my application unrelated to WebJobs shouldn't have a WebJobs dependency

4. Use the built in TextWriter dependency injection stuff. This wasn't ideal for the same reason Add tests for dashboard #3 wasn't ideal, and it was less flexible because TextWriter only exposes a WriteLine method and I want to be able to log errors, warnings, etc. differently.

So that said, is there a recommended approach for logging to external data sources and the dashboard at once? If webjobs just listened for Trace messages and wrote those to the dashboard, this would be a lot easier because I could simply turn on Trace logging and ElasticSearch logging in my Serilog configuration and be done with it, but it seems like this doesn't work / no longer works as of the latest stable WebJobs version.

Thanks!

[aaronhoffman]

For those interested, I believe this is were the TextWriter instance, that will eventually be passed to the WebJob function, is created: https://github.com/Azure/azure-webjobs-sdk/blob/master/src/Microsoft.Azure.WebJobs.Host/Executors/FunctionExecutor.cs#L210

(if you follow the functionOutputTextWriter, it's wrapped in a CompositeTraceWriter and eventually ends up in the parameters variable here: https://github.com/Azure/azure-webjobs-sdk/blob/master/src/Microsoft.Azure.WebJobs.Host/Executors/FunctionExecutor.cs#L235 )

And I believe outputDefinition is an instance of BlobFunctionOutputDefinition (looks like the most likely implementation?) https://github.com/Azure/azure-webjobs-sdk/blob/master/src/Microsoft.Azure.WebJobs.Host/Loggers/BlobFunctionOutputDefinition.cs#L43

Which would mean that the actual TextWriter instance is created here: (follow the UpdateOutputLogCommand.Create(blob) method) https://github.com/Azure/azure-webjobs-sdk/blob/master/src/Microsoft.Azure.WebJobs.Host/Loggers/UpdateOutputLogCommand.cs#L37

If I understand that class correctly, it flushes that TextWriter to the Storage account configured via the JobHostConfiguration.

Unfortunately, I don't see a way to shim into that operation. I have a couple thoughts on potential workarounds:

1. Within the WebJob function call, inject the provided TextWriter instance into your DI framework (perhaps also wrap behind an interface), then after it's injected into your DI framework, resolve the services/controllers you want to interact with. Not a great solution... (you would likely no longer need/use the JobHostConfiguration.JobActivator if you are today)

2. Perhaps create an Azure Function with a Storage Blob Trigger to read the Azure WebJob logs and write to a different location https://docs.microsoft.com/en-us/azure/azure-functions/functions-bindings-storage-blob Also not ideal as this requires knowledge about how the WebJob log messages are stored, and the message format could change in the future.

[bakatz]

@aaronhoffman yep, approach #2 was what I was going to go with next. However, for the time being, I just gave up on using the webjobs dashboard for any kind of logging. Instead, I wrote a base job class that has Serilog as a dependency. In this class, I have an Execute() method which basically just tried to execute a lambda function (I.e. the job to be run) and logs the begining, end, exceptions generated by the job along with the correlationid so that I can inspect the logs later by finding the correlationid in the webjobs dashboard first, then going to Kibana and searching for the same guid.

This isn't ideal but it works for now.

[snboisen]

This should be doable now that WebJobs is finally using Microsoft.Extensions.Logging and ILogger?

[fabiocav]

@snboisen yes, this is planned and will be part of the 3.0 work.