Stand alone logger provider for Microsoft.Extensions.Logging that uses ECS to log directly to Elasticsearch #85

sgryphon · 2020-06-03T09:29:25Z

Component donated from https://github.com/sgryphon/essential-logging
Re-licensed as Apache 2 (contributer agreement signed).
Once merged, I will deprecate from the other repository and refer here.
Also once merged I can update the pull request with the usage example to refer to the project directly.

apmmachine · 2020-06-03T09:32:33Z

💚 Build Succeeded

Expand to view the summary

Build stats

Build Cause: [Pull request #85 updated]
Start Time: 2020-07-14T08:48:34.304+0000
Duration: 13 min 13 sec

Test stats 🧪

Test	Results
Failed	0
Passed	50
Skipped	4
Total	54

Mpdreamz

Some initial surface nitpicks, can you also reformat the code. Our .editorconfig should dictate tabs if you use visual studio/rider/omnisharp.

Did you want to port the test project as part of this PR or do you intend to follow up?

Again thank you for this! 👍

src/Elastic.CommonSchema.LoggerProvider/build.ps1

src/Elastic.CommonSchema.LoggerProvider/Elastic.CommonSchema.LoggerProvider.csproj

src/Elastic.CommonSchema.LoggerProvider/.config/dotnet-tools.json

src/Elastic.CommonSchema.LoggerProvider/Elastic.CommonSchema.LoggerProvider.csproj

sgryphon · 2020-06-03T12:29:09Z

Did you want to port the test project as part of this PR or do you intend to follow up?

I don't have a unit test project (I did have for my Framework System.Diagnostics trace listener libraries, but haven't ported them across to Core Extensions.Logging ... it is on my todo list)

I'll do a separate PR for the example / how to use.

sgryphon · 2020-06-04T07:35:52Z

The Jenkins build (Windows) had failed on the signing. I updated the project to use the shared properties which should fix this.

Mpdreamz

Thanks for the updates, CI is happy. I added a few more notes

@gregkalapos @russcam I would love another pass over by atleast one of you!

src/Elastic.CommonSchema.LoggerProvider/ConnectionPoolType.cs

src/Elastic.CommonSchema.LoggerProvider/ElasticsearchDataProcessor.cs

sgryphon · 2020-06-08T06:01:22Z

This is approved, but I don't have permission to merge.

From the code review, the only open question is whether to change the namespace, e.g. Elastic.Extensions.Logging or Elasticsearch.Extensions.Logging (if you want Elasticsearch in there)?

sgryphon · 2020-06-08T06:43:06Z

I decided to change the namespace to "Elasticsearch.Extensions.Logging", which has the Elasticsearch name in there (where it is writing to directly) and reflects it is for Extensions.Logging.

russcam

I've had a first pass through and left some initial comments

russcam · 2020-06-18T05:02:59Z

src/Elasticsearch.Extensions.Logging/ElasticsearchDataProcessor.cs

+
+			var index = string.Format(_options.Index, indexTime);
+
+			var id = Guid.NewGuid().ToString();


If the id for a document is auto-generated, it'd be better to not send an id and rely on Elasticsearch to generate one. This is faster in Elasticsearch because it does not need to check if a document already exists with a given id.

russcam · 2020-06-18T05:04:10Z

src/Elasticsearch.Extensions.Logging/ElasticsearchDataProcessor.cs

+			var id = Guid.NewGuid().ToString();
+
+			var localClient = _lowLevelClient;
+			var response = localClient.Index<StringResponse>(index, id, PostData.Serializable(logEvent));


Should a failed API call be handled or logged?

russcam · 2020-06-18T05:06:48Z

src/Elasticsearch.Extensions.Logging/ElasticsearchDataProcessor.cs

+		{
+			try
+			{
+				foreach (var logEvent in _messageQueue.GetConsumingEnumerable()) PostEvent(logEvent);


Using the bulk API to send a batch of events in one request would be preferable to sending individual log events.

src/Elasticsearch.Extensions.Logging/ElasticsearchLogger.cs

gregkalapos

Awesome work @sgryphon - thank you for doing this!

I went through the whole thing, I added some things I noticed, overall I feel this is very good!

One thing I'd like to rant about here is the Tracing part of ecs (I work on the Elastic APM Agent, so that's close to me :) )

To fill those fields we typically have another package which depends on the .NET APM Agent, here you used Activity. I feel the Elasticsearch.Extensions.Logging package should not depend on the APM Agent, so using Activity is totally reasonable. Plus in case there is no APM Agent in the app, then indeed we should use Activity.

But a couple of things:

We have a feature in Kibana which lets you jump from APM Traces to Logs and vice versa, and that feature works based on Trace.Id.
The Elastic APM Agent works with W3C TraceContext based ids - Activity has 2 id formats, the hierarchical (that's still the default) ones and W3C (the one which the Elastic APM Agent also uses)
If the APM Agent is present in an App, it'll always check if there is a W3C TraceId already created and for that it uses Activity.Currernt,
- if yes, it'll reuse it, so that's good, all log and APM trace correlation will work perfectly
- if not (because the old hierarchical format is used), then it'll create one and it'll also create an Activity with a W3C id format, forcing Activity to use the new id format. Now, unfortunately in this case the Trace.Id will change (meaning we'll set Trace.Id based on the hierarchical id until the APM transaction is started and then after the APM transaction starts it'll be a new W3C based id). This is a bit unfortunate, but in the readme here we already suggest using W3C format, so I'd say that's just something we will live with.
The Transaction.Id is not used at the moment by any Kibana or APM feature for log correlation. I feel we won't be able to populate that based on Activity, I think for that we'll need the APM Agent, I added a specific comment about this below.

src/Elasticsearch.Extensions.Logging/Elasticsearch.Extensions.Logging.csproj

src/Elasticsearch.Extensions.Logging/ElasticsearchLoggerOptions.cs

gregkalapos · 2020-07-03T10:21:27Z

src/Elasticsearch.Extensions.Logging/ElasticsearchDataProcessor.cs

+			var id = Guid.NewGuid().ToString();
+
+			var localClient = _lowLevelClient;
+			var response = localClient.Index<StringResponse>(index, id, PostData.Serializable(logEvent));


nit: var response unused, unless we handle it as @russcam suggests :)

Suggested change

var response = localClient.Index<StringResponse>(index, id, PostData.Serializable(logEvent));

localClient.Index<StringResponse>(index, id, PostData.Serializable(logEvent));

gregkalapos · 2020-07-03T10:55:54Z

src/Elasticsearch.Extensions.Logging/ElasticsearchLogger.cs

+
+		private void WriteName(StringBuilder stringBuilder, string name)
+		{
+			foreach (var c in name.Cast<char>())


nit: Is this .Cast<char>() needed 🤔?

Suggested change

foreach (var c in name.Cast<char>())

foreach (var c in name)

gregkalapos · 2020-07-03T10:56:23Z

src/Elasticsearch.Extensions.Logging/ElasticsearchLogger.cs

+
+		private void WriteValue(StringBuilder stringBuilder, string value)
+		{
+			foreach (var c in value.Cast<char>())


Some as above.

Suggested change

foreach (var c in value.Cast<char>())

foreach (var c in value)

gregkalapos · 2020-07-03T12:35:27Z

src/Elasticsearch.Extensions.Logging/ElasticsearchLogger.cs

+		private Regex _w3CFormat = new Regex(@"^[abcdef]{2}-[\dabcdef]{32}-([\dabcdef]{16})-[\dabcdef]{2}$",
+			RegexOptions.Compiled);


nit: seems to be unused.

Suggested change

private Regex _w3CFormat = new Regex(@"^[abcdef]{2}-[\dabcdef]{32}-([\dabcdef]{16})-[\dabcdef]{2}$",

RegexOptions.Compiled);

gregkalapos · 2020-07-03T12:49:43Z

src/Elasticsearch.Extensions.Logging/ElasticsearchLogger.cs

+using System.Diagnostics;
+using System.Linq;
+using System.Text;
+using System.Text.RegularExpressions;


In case private Regex _w3CFormat is removed this can also be removed.

gregkalapos · 2020-07-03T15:19:42Z

src/Elasticsearch.Extensions.Logging/ElasticsearchLogger.cs

+				// Unique identifier of the transaction.
+				// A transaction is the highest level of work measured within a service, such as a request to a server.
+				var spanId = ExtractW3cSpanIdFromActivityId(activity.Id);
+				logEvent.Transaction = new Transaction() { Id = spanId ?? activity.Id };


I think setting Transaction.Id to Activity.Current.Id or to SpanId in case it's in W3C format is not correct. As the definition of transaction in ecs says (which is in the comment above) "transaction is the highest level of work measured within a service". The thinking behind this is that if you filter based on transaction.id you'll see all logs for the given transaction e.g. for a given incoming HTTP request (from the point when it hits the request pipeline until the response is sent back) in a single service. The scope of SpanId or Activity.Id is smaller - it'd be something like an outgoing HTTP request or a database call - but each activity will have its own id, so if we use those, then the filtering based on Transaction.Id will be very different, you'll only see logs for a given span (or activity), but not for the whole transaction.

In Elastic APM we have the definition of a transaction which is not the same as a span - Activity fits more the definition of the span.

We have tracing integration with Serilog and NLog with the Elastic APM Agent (meaning we fill the 2 ecs tracing fields (Trace.Id and Transaction.Id) based on ids generated by the APM Agent) and in that case we set Transaction.Id to the real transaction id - which is the same for all spans within a single service.

Overall I'm afraid it'd be impossible to get a transaction.id just based on Activity here and I feel it'd be best to not fill Transaction.Id here. We could reiterate on this later, but for now I think it'd be better to just not set it to something which would be technically incorrect. So my suggestion is that we should remove setting the logEvent.Transaction part.

Happy to discuss this further, let me know if someone has different opinion.

gregkalapos · 2020-07-03T15:42:46Z

src/Elasticsearch.Extensions.Logging/ElasticsearchLogger.cs

+
+		private string? ExtractW3cSpanIdFromActivityId(string activityId)
+		{
+			if (activityId.Length != 2 + 32 + 16 + 2 + 3) return null;


Probably an edge case, but I think a non-W3C activityId can also be 2 + 32 + 16 + 2 + 3 long.

An idea: if it's not W3C then it's probably the hierarchical id and that always starts with |, so a check like this would also catch that:

if (activityId[0] == '|' || activityId.Length != 2 + 32 + 16 + 2 + 3) return null;

… so the project name is set correctly

….cs, and 8 more files...

… and 11 more files...

…dency

Mpdreamz · 2020-07-14T08:37:50Z

@russcam @gregkalapos discussed this over zoom and decided to merge this as is and follow up with smaller PR's to get this ready for release.

For now the new project is marked as non pack-able to prevent a release.

I will open a new ticket to keep track of the work needed.

…m master

Mpdreamz · 2020-07-14T11:34:34Z

Thanks again for your hard work on this @sgryphon!

Mpdreamz requested changes Jun 3, 2020

View reviewed changes

Mpdreamz added enhancement New feature or request v1.6.0 labels Jun 3, 2020

sgryphon requested a review from Mpdreamz June 4, 2020 07:17

Mpdreamz approved these changes Jun 4, 2020

View reviewed changes

sgryphon requested a review from Mpdreamz June 7, 2020 00:01

russcam reviewed Jun 18, 2020

View reviewed changes

gregkalapos reviewed Jul 3, 2020

View reviewed changes

gregkalapos mentioned this pull request Jul 3, 2020

APM ILoggerProvider Implementation elastic/apm-agent-dotnet#894

Closed

sgryphon added 16 commits July 14, 2020 10:32

Skeleton elasticsearch

b7ed897

Add elasticsearch readme, and processor blocking queue skeleton

24a98df

Add reference to low level elasticsearch client and basic log event

415cd31

Basic example - something appears in kibana!

2a0591d

Get field names correct

7c32bdd

Test out some nested fields

775f015

Stick elasticsearch data into the queue

a5335eb

Add a whole bunch of system values

72158f2

Add error (exception) data

c1d2fab

Include semantic field values from TState and from scopes

773b291

Add some options to turn sections off, and also to add fixed tags.

47afa37

Add custom fields for message template and scopes

5b6f0bf

Format bytes and datetimes

3c993bb

Handling list / enumerable and dictionary

f49cdfa

Additional cleanup

5d70734

Documentation and a few minor tweaks.

3f94221

sgryphon added 21 commits July 14, 2020 10:32

More documentation tweaks

8b0975b

More doco tweaks.

458f076

Use official ECS

409b8ac

Reorder example, to compare with new messages

2c3f6a3

Add ECS version to event; Add trace, principal to example

90731db

Add back in custom properties for template, scopes

6952ed9

Add special handling for trace (TraceId) and transaction (RequestId)

2e9c632

Bug fix for null value formatting

0f47bb6

Clean up support of correlation identifiers

e12ba75

Clean up correlation identifiers

144e0a9

Update sample output for trace/transaction

d5873d1

Use current activity trace and span (not request values)

22453ea

Readme cleanup; also move docker-compose file to meaningful directory…

623c890

… so the project name is set correctly

Update Elastic.CommonSchema.LoggerProvider.csproj, ConnectionPoolType…

691e4ac

….cs, and 8 more files...

Update dotnet-tools.json, Elastic.CommonSchema.LoggerProvider.csproj,…

7f82cb5

… and 11 more files...

Add looger provider to main solution file and change to project depen…

ef7abc7

…dency

Move source code to root folder

82290a9

Run code cleanup in Rider, to pick up project styles

8f9fe2a

Code review fixes

00c67b0

Add reference to share properties, including signing to fix build

33f400a

Change namespace to include Elasticsearch

9a55fa7

Mpdreamz force-pushed the feature/migrate-loggerprovider branch from e2d0f82 to 9a55fa7 Compare July 14, 2020 08:32

Mark Elasticsearch.Extensions.Logging as non packable for now

fca473d

update csproj and sln to reflect the changed in project structure fro…

a415da6

…m master

Mpdreamz merged commit 764253b into elastic:master Jul 14, 2020

Mpdreamz mentioned this pull request Jul 14, 2020

[meta] Elasticsearch.Extensions.Logging GA #95

Closed

14 tasks

gregkalapos mentioned this pull request Jul 14, 2020

Remove sending Transaction.Id in Elasticsearch.Extensions.Logging #96

Merged

Mpdreamz mentioned this pull request Jul 21, 2020

Several improvements to Elasticsearch.Ext.Logging #97

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Stand alone logger provider for Microsoft.Extensions.Logging that uses ECS to log directly to Elasticsearch #85

Stand alone logger provider for Microsoft.Extensions.Logging that uses ECS to log directly to Elasticsearch #85

sgryphon commented Jun 3, 2020

apmmachine commented Jun 3, 2020 •

edited

Loading

Build stats

Test stats 🧪

Mpdreamz left a comment

sgryphon commented Jun 3, 2020

sgryphon commented Jun 4, 2020

Mpdreamz left a comment

sgryphon commented Jun 8, 2020

sgryphon commented Jun 8, 2020

russcam left a comment

russcam Jun 18, 2020

russcam Jun 18, 2020

russcam Jun 18, 2020

gregkalapos left a comment

gregkalapos Jul 3, 2020

gregkalapos Jul 3, 2020

gregkalapos Jul 3, 2020

gregkalapos Jul 3, 2020

gregkalapos Jul 3, 2020

gregkalapos Jul 3, 2020

gregkalapos Jul 3, 2020

Mpdreamz commented Jul 14, 2020

Mpdreamz commented Jul 14, 2020


		var index = string.Format(_options.Index, indexTime);

		var id = Guid.NewGuid().ToString();

	var response = localClient.Index<StringResponse>(index, id, PostData.Serializable(logEvent));
	localClient.Index<StringResponse>(index, id, PostData.Serializable(logEvent));

	foreach (var c in value.Cast<char>())
	foreach (var c in value)

		private Regex _w3CFormat = new Regex(@"^[abcdef]{2}-[\dabcdef]{32}-([\dabcdef]{16})-[\dabcdef]{2}$",
		RegexOptions.Compiled);

Stand alone logger provider for Microsoft.Extensions.Logging that uses ECS to log directly to Elasticsearch #85

Stand alone logger provider for Microsoft.Extensions.Logging that uses ECS to log directly to Elasticsearch #85

Conversation

sgryphon commented Jun 3, 2020

apmmachine commented Jun 3, 2020 • edited Loading

💚 Build Succeeded

Build stats

Test stats 🧪

Mpdreamz left a comment

Choose a reason for hiding this comment

sgryphon commented Jun 3, 2020

sgryphon commented Jun 4, 2020

Mpdreamz left a comment

Choose a reason for hiding this comment

sgryphon commented Jun 8, 2020

sgryphon commented Jun 8, 2020

russcam left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

gregkalapos left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Mpdreamz commented Jul 14, 2020

Mpdreamz commented Jul 14, 2020

apmmachine commented Jun 3, 2020 •

edited

Loading