Azure-functions-host: Logging within a ILogger.BeginScope section fails on deployed apps.

[leftler]

Investigative information

• Timestamp: 2017-07-13T17:07:05.436
• Function App name: functionapp20170713114256
• Function name(s) (as appropriate): HttpTiggerCSharpScript
• Invocation ID: 32761606-1768-4ddf-a897-503d8fc09126
• Region: South Central US

Repro steps

Create a new HttpResponseTrigger and use the following body

using System.Net;
using Microsoft.Extensions.Logging;

public static HttpResponseMessage Run(HttpRequestMessage req, ILogger log)
{
    log.LogInformation("C# HTTP trigger function processed a request.");

    using (log.BeginScope("SomeScope"))
    {
        log.LogInformation("Information in a scope.");
    }
    return req.CreateResponse(HttpStatusCode.OK, "This should have not gotten this far.");
}

Expected behavior

To run and provide a status 200 response with two log messages in the log.

Actual behavior

Returned a status 500 response with the message

{
  "id": "e1f4cc1d-c6a5-43e3-87aa-b9040511cfea",
  "requestId": "2602d5b4-d6c6-48c4-a729-41b00adfed0a",
  "statusCode": 500,
  "errorCode": 0,
  "messsage": "Exception while executing function: Functions.HttpTriggerCSharpScript -> Exception has been thrown by the target of an invocation. -> An error occurred while writing to logger(s). -> Object reference not set to an instance of an object."
}

Related information

• This error does not happen if running from in the cli in visual studio, it only happens to published functions.
• This happens for both .csx files and compiled functions from a .dll
• I have seen this happen on a HttpTrigger and a TimerTrigger, I have not tested other types of triggers.
• This happens with both synchronous and asynchronous methods.

Text from the Logs in the monitor blade

Exception while executing function: Functions.HttpTriggerCSharpScript
Microsoft.Azure.WebJobs.Host.FunctionInvocationException : Exception while executing function: Functions.HttpTriggerCSharpScript ---> System.Reflection.TargetInvocationException : Exception has been thrown by the target of an invocation. ---> System.AggregateException : An error occurred while writing to logger(s). ---> Object reference not set to an instance of an object.
   at Microsoft.Extensions.Logging.Logger.Log[TState](LogLevel logLevel,EventId eventId,TState state,Exception exception,Func`3 formatter)
   at Microsoft.Extensions.Logging.LoggerExtensions.LogInformation(ILogger logger,String message,Object[] args)
   at Submission#0.Run(HttpRequestMessage req,ILogger log) at D:\home\site\wwwroot\HttpTriggerCSharpScript\run.csx : 10
---> (Inner Exception #0) System.NullReferenceException : Object reference not set to an instance of an object.
   at Microsoft.Azure.WebJobs.Script.Diagnostics.DictionaryLoggerScope.GetMergedStateDictionary() at C:\azure-webjobs-sdk-script\src\WebJobs.Script\Diagnostics\DictionaryLoggerScope.cs : 47
   at Microsoft.Azure.WebJobs.Script.Diagnostics.FileLogger.GetFunctionName() at C:\azure-webjobs-sdk-script\src\WebJobs.Script\Diagnostics\FileLogger.cs : 71
   at Microsoft.Azure.WebJobs.Script.Diagnostics.FileLogger.Log[TState](LogLevel logLevel,EventId eventId,TState state,Exception exception,Func`3 formatter) at C:\azure-webjobs-sdk-script\src\WebJobs.Script\Diagnostics\FileLogger.cs : 67
   at Microsoft.Extensions.Logging.Logger.Log[TState](LogLevel logLevel,EventId eventId,TState state,Exception exception,Func`3 formatter)<---

   End of inner exception
   at System.RuntimeMethodHandle.InvokeMethod(Object target,Object[] arguments,Signature sig,Boolean constructor)
   at System.Reflection.RuntimeMethodInfo.UnsafeInvokeInternal(Object obj,Object[] parameters,Object[] arguments)
   at System.Reflection.RuntimeMethodInfo.Invoke(Object obj,BindingFla…

[brettsam]

What did you want to happen with a string scope? The FileLogger likely isn't handling non-dictionary scope values correctly, which we can fix. But we'd need to decide what we need to do when we see a string as a scope.

[leftler]

I just expected consistent behavior between a app running on the cli from the visual studio debugger and a deployed app. When run from visual studio no error is thrown.

[JeffN825]

any update? the DictionaryLoggerScope is clearly not functional in the api

[brettsam]

We can fix it to not throw (and if you use a Dictionary<string, object>, it won't throw today), but I want to check to see what you guys think we should do with a string passed to BeginScope.

For background -- we use BeginScope within the host to pass function details throughout the logging pipeline. We add key/value pairs to the scope and pull out 'special' properties that we apply to the App Insights logs.

If you did something like BeginScope("SomeScope"), we'd likely just ignore it as we're not sure what to do without a key/value pair.

What would you expect from logging a string as a scope like this? i.e. -- where would "SomeScope" appear in an App Insights trace?

For example, if you do something like:

using (log.BeginScope(new Dictionary<string, object>
{
   ["MyScopeProperty"] = "SpecialScopeValue"
})
{
    log.LogInformation("Information in a scope.");
}

We should be attaching the MyScopeProperty : SpecialScopeValue as a part of any log made inside that using -- it would appear in the customDimensions in App Insights.

[jnevins-gcm]

I would agree properties in the dictionary should be attached to the log entries as custom properties. Also, treating single values passed to BeginScope (non IDictionarys) should be treated as a single entry dictionary which relies on the ToString of the object (so something like state.GetType.Value = state.ToString()) to determine what properties to attach.

[jnevins-gcm]

any idea when this might be implemented? it's a long term blocker for us to not have these properties

[brettsam]

Is there a reason that you cannot use dictionary here? That'd unblock you today.

You'd want the Type of the state to be the key, and the ToString() to be the value?

So for:

using (log.BeginScope("SomeScope"))
{
    log.LogInformation("Information in a scope.");
}

You'd want (note we disambiguate custom properties by prefixing 'prop__'): prop_String : SomeScope? That seems do-able, if I'm understanding correctly.

Another thing that I've just realized is that we don't handle using (logger.BeginScope("{MyKey}", "SomeScope")) { } like we should. I've filed https://github.com/Azure/azure-webjobs-sdk/issues/1264 to fix that.

[jnevins-gcm]

Using an IDictionary works to prevent the exception, thanks, but I don't see my custom properties on the trace in app insights

[brettsam]

Shoot, you're right! I thought I had a test for this but I don't. Yes, I will work to get these issues fixed up for the next release, likely released in a few weeks.

If you want to attach your own custom properties to traces today, you can still use the structured logging approach here: https://github.com/Azure/azure-webjobs-sdk-script/wiki/ILogger#structured-logging. If you have a lot of logs that you want to attach the same scope values to, it'll be a little more verbose, but it should get you the end-result you want today. Then when this is fixed and deployed, you can switch to using the scope. If you want some guidance on that temporary workaround, let me know and I can help.

[jnevins-gcm]

Thanks. Though I don't really understand your description of how structured logging works in that page. Can you clarify please?

[brettsam]

Sure, if you write a log like:

logger.LogInformation("Ran job {jobId} with results {resultCount}", "abc", 5);

You'll get a trace in App Insights that effectively runs String.Format() like you'd expect to generate the trace message. But ILogger actually splits out the replacement keys and values so we can log it separately as well. So you'd end up with custom dimensions attached to that trace in App Insights like:

customDimensions: {
  "prop__jobId": "abc",
  "prop__resultCount": 5
}

You can then write queries against those custom dimensions. This gives a good explanation of how ILogger uses the format strings and values: https://docs.microsoft.com/en-us/aspnet/core/fundamentals/logging#log-message-format-string

[jnevins-gcm]

Cool thanks

[jnevins-gcm]

Can you please add documentation on how this will work? And when it will be merged in and released? Thanks

[arichiardi]

I have a similar but unrelated issue, in which I am using bunyan in order to emit JSON objects to stdout from my functions.

The host seems to always prepend the timestamp though, effectively nullifying my attempt to have structured logging.

Is there a simple way to make sure my JSON is saved/outputted undisturbed?