Add Failed state

[srogovtsev]

I use Serilog.Timings to log the outbound HTTP calls and those can be completed, abandoned and failed (at least, for us): the difference between "completed" and "failed" is the one between successful and unsuccessful HTTP status code.

So what I would like to have is the ability to

1. have different outcomes in the log ("completed" and "failed")
2. differentiate them by the log level

All of this can be (quite easily, but a bit messily) achieved by adding an overload to Complete accepting log level and outcome, or if we want more "graceful" solution - by adding another method very similar to Complete.

I can do a PR for whichever solution you prefer.

[nblumhardt]

Hi @srogovtsev - thanks for the note. In the current design, abandoned and failed are intended to be the same thing, since abandonment can happen during unwinding due to an exception, etc.

To record the status code, can you use the overload of Complete() that attaches it as a property? https://github.com/nblumhardt/serilog-timings/blob/dev/src/SerilogTimings/Operation.cs#L140

[srogovtsev]

I tried to solve this within the current paradigm and found myself in a bind: abandoned state doesn't capture a property, completed state doesn't differentiate by log level.

Let me show a simplified code; this is a part of a generic DelegatingHandler I want to use to capture all outbound HTTP requests. First let's do it without timings:

protected override async Task<HttpResponseMessage> SendAsync(HttpRequestMessage request, CancellationToken cancellationToken)
{
  try
  {
    var response = await base.SendAsync(request, cancellationToken);
    _logger.Write(response.IsSuccessStatusCode ? _successLevel : _errorLevel,
      "{HttpMethod} {RequestUri} {StatusCode}",
      request.Method, request.RequestUri, (int) response .StatusCode);
    return response;
  }
  catch(Exception e) //I know about exception filters, let's skip it for now
  {
    _logger.Write(_errorLevel, e,
      "{HttpMethod} {RequestUri}: {Message}",
      request.Method, request.RequestUri, e.Message);
  }
}

So far, so good. Now, the same with the timings:

using(var op = _logger
  .OperationAt(_successLevel, _errorLevel)
  .Begin("{HttpMethod} {RequestUri}", request.Method, request.RequestUri))
{
  var response = await base.SendAsync(request, cancellationToken);
  op.Complete("StatusCode", (int) response .StatusCode)
  return response;
}

In this way, whichever response I get, it always gets logged with _successLevel, which is inconvenient. Another approach:

using(var op = _logger
  .OperationAt(_successLevel, _errorLevel)
  .Begin("{HttpMethod} {RequestUri}", request.Method, request.RequestUri))
{
  var response = await base.SendAsync(request, cancellationToken);
  if (response.IsSuccessStatusCode)
    op.Complete("StatusCode", (int) response .StatusCode);
  return response;
}

Now I have unsuccessful requests logged with _errorLevel (good), but I don't get the status codes with them (baad!). Actually, the same bothered me with the case of exception: I can't log the exception (or other info) with the abandonment.

Of course, I can do that by adding another log entry (that's the way I'm doing it now), but then I have to look at two lines to know what happens.

So maybe this can be solved in another way: by allowing to explicitly abandon the operation and pass some properties and information to it:

using(var op = _logger
  .OperationAt(_successLevel, _errorLevel)
  .Begin("{HttpMethod} {RequestUri}", request.Method, request.RequestUri))
{
  try
  {
    var response = await base.SendAsync(request, cancellationToken);
    if (response.IsSuccessStatusCode)
      op.Complete("StatusCode", (int) response .StatusCode);
    else
      op.Abandon("StatusCode", (int) response .StatusCode);
    return response;
  }
  catch (Exception e)
  {
    op.Abandon(e); //can easily be moved to exception filter as well
  }
}

I think I can draft a PR for this as well.

(of course, all of this can also benefit from multiple property enrichment, but that is addressed in #8)

[nblumhardt]

Ah, interesting - thanks for all of the details!

An explicit Abandon() seems like a reasonable addition; but, taking a swing at AddProperty() from #8 would cover more cases, including this one. I think we just stalled over there due to a lack of time. What do you think about picking that one up?

As far as I can tell, it should be a fairly simple case of making Operation._logger mutable and using ForContext() in the implementation of AddProperty(), but I could be missing some subtleties.

[srogovtsev]

I will try picking up AddProperty either today or tomorrow, I like the idea. The only thing that is missing is logging the exception, but that can be remedied by adding similar SetException.

[srogovtsev]

Can you please merge #26, as my VS does the same upgrade too, and I prefer to have my PR clean from such changes?

[nblumhardt]

Done, thanks @srogovtsev 👍

[nblumhardt]

Is this now satisfactorily covered by #30? Thanks!

[srogovtsev]

I think with #31 and #32 (they make more sense in this order) it will be covered completely.

[nblumhardt]

Great - thanks for all the effort on it, I'll PR a master branch build and make a release once it's been out in the wild a little longer.

[srogovtsev]

I wonder what you mean by "out in the wild"... Do you have some pre-release package build?

[nblumhardt]

Odd - looks like pre-release package publishing is broken. I'll have a look shortly - the dev branch builds should be published to NuGet.