Get inserted log entry Id as return in MSSqlServerSink

[asiridissa]

Hi,

I have a requirement to store some other meta data related to the log in some other tables related with the original log entry and a correlated id which I generated.

ex: Action 'Event creation' will have log entry 1 and has a correlation Id 1. Action 'Event participant add' will log entry 2 and fill some other tables with participant details using correlation Id 1 and log entry 2's Id.

I have configured MSSqlServerSink with identity "Id" column in the log table. Is it possible to get the 'Id' of inserted log entry as soon as it inserted in to table?

[asiridissa]

I used triggers for this.

[sandersonsuprtek]

How would one use triggers? I can find zero documentation on how to do this. The bottom line is if I can't get back the id, then I will probably not be able to use this sink. So it is a big deal to me. Should not be closed without something more than the above to go on.

[ckadluba]

A Serilog sink has no way of returning anything when it writes logs to a target because (except for the audit mode) Serilog operates like this.

1. Collect log events created with single Log() calls in an internal buffer
2. In the background: write a batch of logs from the buffer to the target (the SQL table in this case)

The sink does not have a way of returning any IDs to your program because you do not call it to write the logs. Serilog calls it and it is happening asynchronous in the background.

Even if the sink would let you register e.g. a callback which is called every time it writes a batch would not help. The MSSQL sink writes a batch using SQL bulk insert. With this operation it does not get back any IDs from the database.

So the solution used by @asiridissa seems to be the most reasonable choice. Create an insert trigger on the log table on SQL server to retrieve and process the IDs of the inserted log records.

There is plenty of documentation from Microsoft about how to do that. And also other sources with good examples about that. https://www.mssqltips.com/sqlservertip/5909/sql-server-trigger-example/

[jonorossi]

You could do it the other way. Log to Serilog with GUID request/correlation ID as a property (could be injected via an enricher), then configure the MSSQL sink to store that ID property in a custom table column (via AdditionalColumns) which can easily be joined to other table.

[sandersonsuprtek]

Sorry but I do not see how to actually do either. The Correlation ID is not meant to change as I understand it. Normally, it's a static request header value. And it must be added to header. But I am in a server side business method. As for the database trigger, EF does not support database triggers. So how would I get the EF code to receive the trigger's return value? Again, the point is to get the id of the inserted Log record back to the UI to tell the user the error id. Not to be critical but if you all want developer to use these tools then they have to be practical with examples. My gripe with Serilog and its sinks is lack of examples and help.

[ckadluba]

Help us understand your requirement in detail. What do you need to do with those IDs in your code?

[sandersonsuprtek]

An example. An exception occurs and is handled and the code will call the Serilog logger via the static class. catch (Exception ex) { var logId = Log.Error(ex, "An error occurred."); response.LogId = id; } Then the UI can receive the response object and give the user a message telling them the id of the Log database record.

However, I realize the above is not how Serilog and the SQL sink really work in terms of timing. I am just saying what would be the best for my situation.

[asiridissa]

How would one use triggers? I can find zero documentation on how to do this. The bottom line is if I can't get back the id, then I will probably not be able to use this sink. So it is a big deal to me. Should not be closed without something more than the above to go on.

My requirement was just to store some additional information with the log entry. I managed to fulfil that by using triggers. That's why I closed this thread. Expecting a return will cause to loose the advantage of asynchronous batch sinks as @ckadluba says. If you want to shaw an ID to the user in real time, then using your own generated ID is a possible solution as @jonorossi says.

[sandersonsuprtek]

Ok, regarding the generated value. I use an enricher to add additional info. So I added this to it: logEvent.AddPropertyIfAbsent(new LogEventProperty("LogEventGuid", new ScalarValue(Guid.NewGuid()))); and I created a sql column called LogEventGuid as a uniqueidentifier in the log table and that worked in terms of saving the guid.

However, I do not see how to get the generated guid value out of the enricher context to my business layer code invoking the logger.

I could not figure out how to do this https://github.com/serilog/serilog/issues/1015 when calling, say, Log.Error.

[jonorossi]

You'll want to do it the other way around. Log the correlation ID fetched from somewhere else just like you'd add the current thread, process or host name.

See https://github.com/ekmsystems/serilog-enrichers-correlation-id for inspiration on how it can be done with ASP.NET Core.

[sandersonsuprtek]

But that uses http headers and all this is occurring server side. I want to invoke logging and get some id and then return it. So it cant be header related as the code is not web layer. And in fact my business layer code is used by a windows service too. It is shared and must work there too. So web and service use same business layer code that logs.

[jonorossi]

As I said, inspiration. Serilog has various way to log additional properties from various places. Serilog's ForContext is probably the easiest but least transparent.

None of this is unique to the SQL Server sink or this GitHub issue. I recommend you do some reading of the Serilog docs and check out some similar questions on StackOverflow.

[ckadluba]

@sandersonsuprtek It the approach outlined by @jonorossi an option for you?

Also I'd like to add one remark according to your comment about lack of samples and documentation in Serilog. There is a samples directory in the source of this sink and also in a lot of other sinks. The documentation of this sink, other sinks and on the serilog website has code snippets and samples about various topics. Additionally you will find a lot of information about Serilog on the web e.g. on stackoverflow. Last but not least Serilog and all of it's sinks are open source and as a programmer you have the neccessary resources to find out everything you need to know. Most of the code also is quite simple - no rocket science here. :)

[sandersonsuprtek]

As for documentation. I am been developing for 30 years and have used dozens of tools. Been using .NET since 2003. If I am honest, then I have to tell you the Serilog and it Sinks are poorly documented and sampled compared to most tools. I feel that way based upon experience. I know you disagree. But, I would hope you would want to know what real developers truly think.

As for my approach, I thought it was working. Well, it is IF I use the debugger and step through the code. But, without the debugger slowing things down, it does NOT work. It being adding a row to the log table.

To repeat, the below works if I step through it with the VS debugger. A row gets inserted in log SQL table. Without the debugger, a row never shows up in the table despite the code running. (I am getting a guid back to UI but there is no row matching the guid. That confirms the catch block is running though,)

Program.cs

Log.Logger = new LoggerConfiguration() .ReadFrom.Configuration(configuration) .Enrich.FromLogContext() //.Enrich.WithCaller() .CreateLogger();

Business class

    catch (Exception ex)
    {
        response.AddException(ex);

        var value = Guid.NewGuid();
        using (LogContext.PushProperty("LogEventGuid", value))
        {
            Log.Error(ex, $"{nameof(ModifyObject)}");
            response.LogEventGuid = value;
        }
    }

    return response;

[jonorossi]

See the Troubleshooting section of this sink's readme.

You are missing Log.CloseAndFlush before shutting down your program. When running with the debugger I assume you are stepping through so you are allowing the async background logging to occur.

CloseAndFlush is also in the Serilog base library's Getting Started example.

[sandersonsuprtek]

I thought CloseAndFlush was to be used as follows in Program.cs. That's how I have used it for over year. Are you saying each call to a Log method such as Error needs CloseAndFlush as well?

I do not want to shutdown. I want it to insert while it is running.

Log.Logger = new LoggerConfiguration() .ReadFrom.Configuration(configuration) .Enrich.FromLogContext() //.Enrich.WithCaller() .CreateLogger();

    try
    {
        Log.Information("Starting web host");
        CreateHostBuilder(args, configuration).Build().Run();
        return 0;
    }
    catch (Exception ex)
    {
        Log.Fatal(ex, "Host terminated unexpectedly");
        return 1;
    }
    finally
    {
        Log.CloseAndFlush();
    }

[jonorossi]

I thought CloseAndFlush was to be used as follows in Program.cs. That's how I have used it for over year.

I can only provide assistance based on code you provide, you didn't have it in your last comment.

Are you saying each call to a Log method such as Error needs CloseAndFlush as well?

No, as I said "before shutting down your program".

I do not want to shutdown. I want it to insert while it is running.

Then there should be no problem. As per the readme of this sink, it's based on Serilog's Serilog.Sinks.PeriodicBatching library, you are likely checking the table too quickly:

This is a "periodic batching sink." The sink will queue a certain number of log events before they're actually written to SQL Server as a bulk insert operation. There is also a timeout period so that the batch is always written even if it has not been filled. By default, the batch size is 50 rows and the timeout is 5 seconds. You can change these through by setting the MSSqlServerSinkOptions.BatchPostingLimit and MSSqlServerSinkOptions.BatchPeriod arguments. (https://github.com/serilog-mssql/serilog-sinks-mssqlserver#basic-arguments)

[sandersonsuprtek]

The row never appears. I ran the code yesterday and today, still no inserted row.

So if I use.Enrich.FromLogContext() in Program.cs and then use

        var value = Guid.NewGuid();
        using (LogContext.PushProperty("LogEventGuid", value))
        {
            Log.Error(ex, $"{nameof(ModifyObject)}");
        }

how can it be failing?

Note there is a custom column in table named LogEventGuid (already created) that gets the guid value when using the debuuger. Specified in appsettings.json. as follows:

          "additionalColumns": [
          {
            "ColumnName": "LogEventGuid",
            "DataType": "uniqueidentifier",
            "AllowNull": false
          }
        ],

[ckadluba]

@sandersonsuprtek Please activate selflog as documented in the README under Troubleshooting and check the debug output for exceptions.

[sandersonsuprtek]

Thank you. I figured it out finally and it is working now. It was System.Data.NoNullAllowedException. Column needed to allow nulls of course.

[ckadluba]

You're welcome. I'm glad we could help. ☺️