New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

ILogger Log method is missing constraints? #1630

Closed
kamil-mrzyglod opened this Issue Jun 27, 2017 · 6 comments

Comments

Projects
None yet
3 participants
@kamil-mrzyglod

kamil-mrzyglod commented Jun 27, 2017

Hi,

today I was playing a bit with ILogger interface and Log method. Unfortunately I found an issue which makes it difficult to use.

I believe this problem is caused by the fact, that Log method from Microsoft.Azure.WebJobs.Logging.ApplicationInsights casts TState parameter to IEnumerable<KeyValuePair<string, object>> which is not constrained in any way. If I pass any other type, Log method just returns without logging any data.

I hope I'm not duplicating this issue, if this is intended, there's a gap in the documentation.

Repro steps

  1. Create following function(HTTP trigger):
using System.Net;

public static async Task<HttpResponseMessage> Run(HttpRequestMessage req, ILogger log)
{
    var state = new State { TimeStamp = DateTime.Now };
    log.Log(LogLevel.Trace, 0, state, null, (s, ex) => {
        return $"Action happened at {s.TimeStamp} with ID {s.Id}";
    });

    return req.CreateResponse(HttpStatusCode.OK, "Hello!");
}

public class State {
    public string Id => Guid.NewGuid().ToString();
    public DateTime TimeStamp {get; set;}
}
  1. Try to call it

Expected behavior

In logs I should see something similar to Action happened at 6/27/2017 9:26:37 AM with ID 7dfc65cd-2418-4eb1-95c9-fdd6637dfec6

Actual behavior

The message is not logged

Known workarounds

I can use IEnumerable<KeyValuePair<>> type to encapsulate my TState in it:

using System.Net;
 
public static async Task<HttpResponseMessage> Run(HttpRequestMessage req, ILogger log)
{
    var state = new List<KeyValuePair<string, object>>() { new KeyValuePair<string, object>("data", new State { TimeStamp = DateTime.Now }) };
 
    log.Log(LogLevel.Trace, 0, state, null, (s, ex) => {
        return $"Action happened at {((State)s[0].Value).TimeStamp} with ID {((State)s[0].Value).Id}";
    });
 
    return req.CreateResponse(HttpStatusCode.OK, "Hello!");
}
 
public class State {
    public string Id => Guid.NewGuid().ToString();
    public DateTime TimeStamp {get; set;}
}

Best regards,
Kamil

@brettsam

This comment has been minimized.

Show comment
Hide comment
@brettsam

brettsam Jun 27, 2017

Member

This was fixed with this PR, but hasn't yet rolled out to production: Azure/azure-webjobs-sdk#1174. Now, the logger will check and if you have a string that we can write out as a message, we will, regardless of what the state object is. If the state object is an IEnumerable<KeyValuePair<>>, you'll get those values added to your App Insights properties, but otherwise, you'll just get the string directly.

For your scenario, though, your best approach is to use the built-in ILogger extensions: log.LogTrace("Action happened at {timeStamp} with Id {id}", s.TimeStamp, s.Id). This is easier to remember, takes care of converting this into an dictionary for you, and enables structured logging (i.e. you can directly query for timeStamp and id from App Insights).

This is explained briefly here: https://github.com/Azure/azure-webjobs-sdk-script/wiki/ILogger#structured-logging.

Member

brettsam commented Jun 27, 2017

This was fixed with this PR, but hasn't yet rolled out to production: Azure/azure-webjobs-sdk#1174. Now, the logger will check and if you have a string that we can write out as a message, we will, regardless of what the state object is. If the state object is an IEnumerable<KeyValuePair<>>, you'll get those values added to your App Insights properties, but otherwise, you'll just get the string directly.

For your scenario, though, your best approach is to use the built-in ILogger extensions: log.LogTrace("Action happened at {timeStamp} with Id {id}", s.TimeStamp, s.Id). This is easier to remember, takes care of converting this into an dictionary for you, and enables structured logging (i.e. you can directly query for timeStamp and id from App Insights).

This is explained briefly here: https://github.com/Azure/azure-webjobs-sdk-script/wiki/ILogger#structured-logging.

@kamil-mrzyglod

This comment has been minimized.

Show comment
Hide comment
@kamil-mrzyglod

kamil-mrzyglod Jun 28, 2017

@brettsam Does it mean that I'll be able to use Log method in a way I presented? From the test case in the PR I see that indeed it allows me to pass a string, but what about a custom type?

If passing a custom type is not a case(since it will be casted to IEnumerable<KeyValuePair<>>), wouldn't it make sense to actually introduce a constraint on TState type?

kamil-mrzyglod commented Jun 28, 2017

@brettsam Does it mean that I'll be able to use Log method in a way I presented? From the test case in the PR I see that indeed it allows me to pass a string, but what about a custom type?

If passing a custom type is not a case(since it will be casted to IEnumerable<KeyValuePair<>>), wouldn't it make sense to actually introduce a constraint on TState type?

@brettsam

This comment has been minimized.

Show comment
Hide comment
@brettsam

brettsam Jun 28, 2017

Member

You'll be able to log with what you have, but it doesn't get you much. Your state will be ignored and we'll log the string. What did you want to happen when you pass in that type? All of the registered loggers need to know how to handle it.

As for the constraint: we don't own that interface; it's part of the Microsoft.Extensions.Logging. I do see your point, but I believe the goal was to make it as open as possible -- you just need Loggers that know how to handle the TState. Some may do something special; some may ignore it. You're not the only one with this question -- see this related issue for BeginScope: aspnet/Logging#454, which also has an unconstrained TState. It does look like some loggers take advantage of the openness, which is why they haven't constrained it.

Member

brettsam commented Jun 28, 2017

You'll be able to log with what you have, but it doesn't get you much. Your state will be ignored and we'll log the string. What did you want to happen when you pass in that type? All of the registered loggers need to know how to handle it.

As for the constraint: we don't own that interface; it's part of the Microsoft.Extensions.Logging. I do see your point, but I believe the goal was to make it as open as possible -- you just need Loggers that know how to handle the TState. Some may do something special; some may ignore it. You're not the only one with this question -- see this related issue for BeginScope: aspnet/Logging#454, which also has an unconstrained TState. It does look like some loggers take advantage of the openness, which is why they haven't constrained it.

@kamil-mrzyglod

This comment has been minimized.

Show comment
Hide comment
@kamil-mrzyglod

kamil-mrzyglod Jun 28, 2017

What I expected from this method was to actually use my formatter and take advantage of passed state(possibly combine it with an exception and transform a string if needed). Due to current shape it's a bit confusing. On the other hand I see the point, that Log is not documented in favor of extension methods like LogInformation.

Anyway thanks for clarifying this!

kamil-mrzyglod commented Jun 28, 2017

What I expected from this method was to actually use my formatter and take advantage of passed state(possibly combine it with an exception and transform a string if needed). Due to current shape it's a bit confusing. On the other hand I see the point, that Log is not documented in favor of extension methods like LogInformation.

Anyway thanks for clarifying this!

@brettsam

This comment has been minimized.

Show comment
Hide comment
@brettsam

brettsam Jun 28, 2017

Member

Oh, of course! Let me rephrase -- yes, your formatter will be called with your state. We won't do anything special with that state, though -- we just pass it straight to your formatter. That will happen here: https://github.com/Azure/azure-webjobs-sdk/blob/dev/src/Microsoft.Azure.WebJobs.Logging.ApplicationInsights/ApplicationInsightsLogger.cs#L31

Using an extension like LogInformation/Trace/etc should get you a little more value. If you use structured logging, we'll be able to log your TimeStamp and Id as queryable columns in App Insights (as well as your string).

Member

brettsam commented Jun 28, 2017

Oh, of course! Let me rephrase -- yes, your formatter will be called with your state. We won't do anything special with that state, though -- we just pass it straight to your formatter. That will happen here: https://github.com/Azure/azure-webjobs-sdk/blob/dev/src/Microsoft.Azure.WebJobs.Logging.ApplicationInsights/ApplicationInsightsLogger.cs#L31

Using an extension like LogInformation/Trace/etc should get you a little more value. If you use structured logging, we'll be able to log your TimeStamp and Id as queryable columns in App Insights (as well as your string).

@christopheranderson

This comment has been minimized.

Show comment
Hide comment
@christopheranderson

christopheranderson Jul 8, 2017

Member

Closing since this looks resolved.

Member

christopheranderson commented Jul 8, 2017

Closing since this looks resolved.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment