Adding trace message logging in Azure WebJobs

When I noticed the arrival of the Web jobs SDK 2.0, I remembered an issue I had with logging traces in Web jobs. But before we come to that, let’s check out trace logging in general in a Web job.

Adding Trace messages to a Web job does not seems to be that hard. Just open the Visual Studio Web job template, create a new Web job and open the Function file.

There is already one function in the Web job template. Here, I just add several kinds of logging. Next to Trace logging, I make use of both the log.writeline() and the console.writeline() (because we are in a ‘kind of’ console app):

public class Functions
{
    // This function will get triggered/executed when a new message is written on an Azure Queue called 'queue'.
    public static void ProcessQueueMessage([QueueTrigger("queue")] string message, TextWriter log)
    {
        var ts = new TraceSource("Diagoutput");

        ts.TraceEvent(TraceEventType.Verbose, 1, $"ProcessQueueMessage verbose trace {message}");
        ts.TraceEvent(TraceEventType.Information, 1, $"ProcessQueueMessage info trace {message}");
        ts.TraceEvent(TraceEventType.Warning, 1, $"ProcessQueueMessage warn trace {message}");
        ts.TraceEvent(TraceEventType.Error, 1, $"ProcessQueueMessage err trace {message}");
        ts.TraceEvent(TraceEventType.Critical, 1, $"ProcessQueueMessage crit trace {message}");

        log.WriteLine($"ProcessQueueMessage log {message}");

        Console.WriteLine($"ProcessQueueMessage Console {message}");
        Console.Error.WriteLine($"ProcessQueueMessage Console Error {message}");
    }
}

Also, add the accompanying configuration so all trace events are logged to the console:

<configuration>
  ...
  <system.diagnostics>
    <trace autoflush="true" />
    <sources>
      <source name="Diagoutput" switchValue="Verbose">
        		<listeners>
          <add name="ConsoleTraceListener" />
        </listeners>
      </source>
    </sources>
    <sharedListeners>
      <add name="ConsoleTraceListener"
           type="System.Diagnostics.ConsoleTraceListener, System, Version=4.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089" />
    </sharedListeners>
  </system.diagnostics>
</configuration>

Deploy this to a Web App in the Azure cloud. But beware, we have to change some Web app settings:

wal01

 

We have to apply the connection strings settings in the Web App settings. (This makes it even possible to remove them from the app.config so the credentials can not be checked in by accident).

I highlighted the Always on selector too, because the logging contained this warning:

[03/06/2017 13:24:32 > ca71ed: SYS WARN]
'Always On' doesn't appear to be enabled for this Web App.
To ensure your continuous job doesn't stop running when the SCM host is idle for too long,
consider enabling 'Always On' in the configuration settings for your Web App.
Note: 'Always On' is available only in Basic, Standard and Premium modes.

Note: In my opinion, this ‘Always on’ option is not needed in this case. We are using triggered functions, we are not running a stateful job. So please check for non-triggered, missed, triggers after going idle. For simplicity of this blog, I keep the Web job ‘always on’.

Note 2: Using ‘Always on’ makes it pretty easy to use the remote debugger option in Visual Studio. Just add a breakpoint in the function and in the Server Explorer, look up your Web job in the App service by right-clicking the Web job and selecting Attach Debugger (after connection to your Azure subscription). Trigger your function and you are debugging.

Note 3: after running the remote bugger, be sure to turn off the remote bugging option in the WebApp settings again.

So if we deploy the Web job to a WebApp, we can check out the logging once the Web job is running. Just open the dashboard of the Web job using the Logs button (make sure you have selected the Web job):

wal03

Check out the logging of the job:

[03/06/2017 13:31:51 > ca71ed: SYS INFO] Status changed to Success
[03/06/2017 13:31:51 > ca71ed: SYS INFO] Status changed to Stopped
[03/06/2017 13:32:40 > ca71ed: SYS INFO] Detected WebJob file/s were updated, refreshing WebJob
[03/06/2017 13:32:40 > ca71ed: SYS INFO] Status changed to Starting
[03/06/2017 13:32:40 > ca71ed: SYS INFO] WebJob singleton setting is False
[03/06/2017 13:32:42 > ca71ed: SYS INFO] Run script 'WebJob1.exe' with script host - 'WindowsScriptHost'
[03/06/2017 13:32:42 > ca71ed: SYS INFO] Status changed to Running
[03/06/2017 13:32:43 > ca71ed: INFO] Found the following functions:
[03/06/2017 13:32:43 > ca71ed: INFO] WebJob1.Functions.ProcessQueueMessage
[03/06/2017 13:32:43 > ca71ed: INFO] Job host started

And as you see, the Web job has identified the function automatically.

We can invoke that function by hand or by posting a message in an Azure Storage Queue named ‘queue’ (You have to create the queue (only once) and the message yourself. Please check out the free Microsoft Storage explorer UPDATE A new version just arrived ).

To invoke it by hand, within the dashboard, invoke the function (you have to fill in a message yourself) and after the function is queued and executed (this can take a couple of seconds), check the logging of the function:

wal02

As you can see, only the “log.WriteLine()” is shown.

What has happened with all (the other) traces and messages? Well, let’s look at the logging at the level of the whole Web job:

wal04

All messages are shown. And that’s ok. But wait! That’s nog really ok, there is a limit to the number of lines shown here. Soon enough, a message like this will appear in the log:

...
[03/06/2017 14:07:35 > ca71ed: INFO]
ProcessQueueMessage Console 42
[03/06/2017 14:07:35 > ca71ed: WARN]
Reached maximum allowed output lines for this run,
to see all of the job's logs you can enable website application diagnostics

A simple way to circumvent this issue is to stretch the number of messages shown. In the WebApp, add an app setting named “WEBJOBS_HISTORY_SIZE” and give it a number (like 200, the default is 50). See how more recent logging messages are arriving again:

...
[03/06/2017 14:07:35 > ca71ed: WARN]
Reached maximum allowed output lines for this run,
to see all of the job's logs you can enable website application diagnostics
[03/06/2017 14:15:24 > ca71ed: SYS INFO]
WebJob is stopping due to website shutting down
[03/06/2017 14:15:24 > ca71ed: SYS INFO]
Status changed to Stopping
...

But this is only a reprieve. In the end, you will hit the next size limitation again.

So we need another way to trace our Web job….

And here comes the sad part. I was hoping to introduce Azure Application Insights. But whatever I tried, I could not get any trace into Application Insights. Yes, it’s still in investigation, I hope to tell you more about this in the near future.

But wait, there is another solution too!

Web App Monitoring

Microsoft Azure is growing up rapidly. New features arrive constantly. There is now another way to check out the logging of a Web job. A Web job is running inside a Web App (which is running inside an App Service Plan). And if we check out the many, many settings of a Web App, look under Monitoring, Diagnostics logs:

Here we can set up the logging on an application level. We can store to the filesystem and we can store to blobs. You can even set the minimum trace level for each kind of logging. Just fill in the settings and save them.

After that, go to the Log Stream and meanwhile, invoke a trigger (put a message on the queue):

Tada, we see the logging arrive almost instantly.

Note: The Application logging is used for the log stream and will turn itself off after twelve hours.

The blob storage will be filled with CSV files, each hour a new one:

Note: Keep in mind that the blob storage will not purge itself. Fortunately, blob storage is very cheap.

Conclusion

I would love to use StreamAnalytics for tracing my Web jobs. But this Web App monitoring is the next best thing to use.

Advertenties