[cartservice] Support for Logs

[Kielek]

Changes

cartservice - Support for Logs

Merge Requirements

For new features contributions please make sure you have completed the following
essential items:

• CHANGELOG.md updated to document new feature additions
• Appropriate documentation updates in the docs [demo/cartservice] Add support for logs opentelemetry.io#3213
• [ ] Appropriate Helm chart updates in the helm-charts N/A OTEL_EXPORTER_OTLP_ENDPOINT seems to be correctly defined

Test

Tested with

      logging/detailed:
        verbosity: detailed

exporter

results

2023-08-31 08:44:00 2023-08-31T06:44:00.968Z    info    ResourceLog #0
2023-08-31 08:44:00 Resource SchemaURL: 
2023-08-31 08:44:00 Resource attributes:
2023-08-31 08:44:00      -> container.id: Str(6a3c4515b4fbe1ab4771d0adb9cb3665f1d666159e7e866c20678f155ce703fd)
2023-08-31 08:44:00      -> service.name: Str(cartservice)
2023-08-31 08:44:00      -> service.namespace: Str(opentelemetry-demo)
2023-08-31 08:44:00      -> telemetry.sdk.name: Str(opentelemetry)
2023-08-31 08:44:00      -> telemetry.sdk.language: Str(dotnet)
2023-08-31 08:44:00      -> telemetry.sdk.version: Str(1.5.1)
2023-08-31 08:44:00 ScopeLogs #0
2023-08-31 08:44:00 ScopeLogs SchemaURL: 
2023-08-31 08:44:00 InstrumentationScope  
2023-08-31 08:44:00 LogRecord #0
2023-08-31 08:44:00 ObservedTimestamp: 2023-08-31 06:43:57.6214683 +0000 UTC
2023-08-31 08:44:00 Timestamp: 2023-08-31 06:43:57.6214683 +0000 UTC
2023-08-31 08:44:00 SeverityText: Information
2023-08-31 08:44:00 SeverityNumber: Info(9)
2023-08-31 08:44:00 Body: Str(GetCartAsync called with userId={userId})
2023-08-31 08:44:00 Attributes:
2023-08-31 08:44:00      -> dotnet.ilogger.category: Str(cartservice.cartstore.RedisCartStore)
2023-08-31 08:44:00      -> userId: Str()
2023-08-31 08:44:00 Trace ID: 9b710a958184b678bad2a14074d8609f
2023-08-31 08:44:00 Span ID: 8c777227bd361502
2023-08-31 08:44:00 Flags: 1
2023-08-31 08:44:00 LogRecord #1
2023-08-31 08:44:00 ObservedTimestamp: 2023-08-31 06:43:57.9846331 +0000 UTC
2023-08-31 08:44:00 Timestamp: 2023-08-31 06:43:57.9846331 +0000 UTC
2023-08-31 08:44:00 SeverityText: Information
2023-08-31 08:44:00 SeverityNumber: Info(9)
2023-08-31 08:44:00 Body: Str(AddItemAsync called with userId={userId}, productId={productId}, quantity={quantity})
2023-08-31 08:44:00 Attributes:
2023-08-31 08:44:00      -> dotnet.ilogger.category: Str(cartservice.cartstore.RedisCartStore)
2023-08-31 08:44:00      -> userId: Str(c2f3228a-47c9-11ee-a680-0242ac130017)
2023-08-31 08:44:00      -> productId: Str(0PUK6V6EV0)
2023-08-31 08:44:00      -> quantity: Int(5)
2023-08-31 08:44:00 Trace ID: a2b543a8426c0086d859da713b2c4142
2023-08-31 08:44:00 Span ID: f75fb3f4e0dce525
2023-08-31 08:44:00 Flags: 1
2023-08-31 08:44:00 LogRecord #2
2023-08-31 08:44:00 ObservedTimestamp: 2023-08-31 06:43:57.9868343 +0000 UTC
2023-08-31 08:44:00 Timestamp: 2023-08-31 06:43:57.9868343 +0000 UTC
2023-08-31 08:44:00 SeverityText: Information
2023-08-31 08:44:00 SeverityNumber: Info(9)
2023-08-31 08:44:00 Body: Str(GetCartAsync called with userId={userId})
2023-08-31 08:44:00 Attributes:
2023-08-31 08:44:00      -> dotnet.ilogger.category: Str(cartservice.cartstore.RedisCartStore)
2023-08-31 08:44:00      -> userId: Str(c2f3228a-47c9-11ee-a680-0242ac130017)
2023-08-31 08:44:00 Trace ID: a2b543a8426c0086d859da713b2c4142
2023-08-31 08:44:00 Span ID: 4403e536ea338790
2023-08-31 08:44:00 Flags: 1
2023-08-31 08:44:00 LogRecord #3
2023-08-31 08:44:00 ObservedTimestamp: 2023-08-31 06:43:57.9924853 +0000 UTC
2023-08-31 08:44:00 Timestamp: 2023-08-31 06:43:57.9924853 +0000 UTC
2023-08-31 08:44:00 SeverityText: Information
2023-08-31 08:44:00 SeverityNumber: Info(9)
2023-08-31 08:44:00 Body: Str(GetCartAsync called with userId={userId})
2023-08-31 08:44:00 Attributes:
2023-08-31 08:44:00      -> dotnet.ilogger.category: Str(cartservice.cartstore.RedisCartStore)
2023-08-31 08:44:00      -> userId: Str(c2f3228a-47c9-11ee-a680-0242ac130017)
2023-08-31 08:44:00 Trace ID: d72365feb5d51e09f9fd81361a7ea0ac
2023-08-31 08:44:00 Span ID: 153a4822112ee125
2023-08-31 08:44:00 Flags: 1
2023-08-31 08:44:00 LogRecord #4
2023-08-31 08:44:00 ObservedTimestamp: 2023-08-31 06:43:58.0067877 +0000 UTC
2023-08-31 08:44:00 Timestamp: 2023-08-31 06:43:58.0067877 +0000 UTC
2023-08-31 08:44:00 SeverityText: Information
2023-08-31 08:44:00 SeverityNumber: Info(9)
2023-08-31 08:44:00 Body: Str(EmptyCartAsync called with userId={userId})
2023-08-31 08:44:00 Attributes:
2023-08-31 08:44:00      -> dotnet.ilogger.category: Str(cartservice.cartstore.RedisCartStore)
2023-08-31 08:44:00      -> userId: Str(c2f3228a-47c9-11ee-a680-0242ac130017)
2023-08-31 08:44:00 Trace ID: d72365feb5d51e09f9fd81361a7ea0ac
2023-08-31 08:44:00 Span ID: 84ef9b9e5643a8b3
2023-08-31 08:44:00 Flags: 1
2023-08-31 08:44:00 LogRecord #5
2023-08-31 08:44:00 ObservedTimestamp: 2023-08-31 06:43:59.9838842 +0000 UTC
2023-08-31 08:44:00 Timestamp: 2023-08-31 06:43:59.9838842 +0000 UTC
2023-08-31 08:44:00 SeverityText: Information
2023-08-31 08:44:00 SeverityNumber: Info(9)
2023-08-31 08:44:00 Body: Str(GetCartAsync called with userId={userId})
2023-08-31 08:44:00 Attributes:
2023-08-31 08:44:00      -> dotnet.ilogger.category: Str(cartservice.cartstore.RedisCartStore)
2023-08-31 08:44:00      -> userId: Str()
2023-08-31 08:44:00 Trace ID: c0c63ea46c9945a4c4dcb6d128fec101
2023-08-31 08:44:00 Span ID: ab73929ed2fd2905
2023-08-31 08:44:00 Flags: 1
2023-08-31 08:44:00     {"kind": "exporter", "data_type": "logs", "name": "logging/detailed"}

[Kielek]

Closed/Reopened to fix build checks after force push.

[mviitane]

The log body shouldn't only include the attribute names, but also the values?
2023-08-31 08:44:00 Body: Str(AddItemAsync called with userId={userId}, productId={productId}, quantity={quantity})

This is valid for all log lines, also
Now listening on: {address}

[Kielek]

The log body shouldn't only include the attribute names, but also the values? 2023-08-31 08:44:00 Body: Str(AddItemAsync called with userId={userId}, productId={productId}, quantity={quantity})

This is valid for all log lines, also Now listening on: {address}

I do not fully understand this comment. Values/attributes are also available

2023-08-31 08:44:00 Body: Str(AddItemAsync called with userId={userId}, productId={productId}, quantity={quantity})
2023-08-31 08:44:00 Attributes:
2023-08-31 08:44:00      -> dotnet.ilogger.category: Str(cartservice.cartstore.RedisCartStore)
2023-08-31 08:44:00      -> userId: Str(c2f3228a-47c9-11ee-a680-0242ac130017)
2023-08-31 08:44:00      -> productId: Str(0PUK6V6EV0)
2023-08-31 08:44:00      -> quantity: Int(5)

[mviitane]

I do not fully understand this comment. Values/attributes are also available

I'd expect the log body also include the userId. For example,
AddItemAsync called with userId=c2f3228a instead of
AddItemAsync called with userId={userId}

Other examples of the logs we already have from Java and Python services:
Targeted ad request received for [accessories]
Recommendation service started, listening on port 9001

[Kielek]

@mviitane,
Lets focus on Recommendation service started, listening on port 9001 entry.

which in fact does not have any attributes

2023-08-30 15:12:16 Body: Str(Recommendation service started, listening on port 9001)
2023-08-30 15:12:16 Attributes:
2023-08-30 15:12:16      -> otelSpanID: Str(0)
2023-08-30 15:12:16      -> otelTraceID: Str(0)
2023-08-30 15:12:16      -> otelTraceSampled: Bool(false)
2023-08-30 15:12:16      -> otelServiceName: Str(recommendationservice)

It is due to how python implements this code
logger.info(f'Recommendation service started, listening on port {port}'). f at the beginning means that it has to be formatted and any kind of log structure is lost.

.NET code
_logger.LogInformation("AddItemAsync called with userId={userId}, productId={productId}, quantity={quantity}", userId, productId, quantity);

It means that we are passing attributes to the logger instead of creating the final string. Decision is left for the logger how to make it. Log structure is preserved.

It can be changed and the log can be flattered by _logger.LogInformation($"AddItemAsync called with userId={userId}, productId={productId}, quantity={quantity}"); ($ sign forces formatting) but it leads to CA2554compilation information.

I would keep it as it is for .NET. The question is, if we should change other behaviors.

[mviitane]

Thanks @Kielek for the good explanation! It still feels a bit strange and new to me to print the attributes kind of twice in the log body, but I’m OK keeping it as it seems best practice.

[julianocosta89]

LGTM