[tracing] Structured logging based on Span events #8583

pujagani · 2020-07-29T05:35:53Z

Description

The changes are related to issue #6694. Current implementation has structured logging in place, the changes provide additional context to the logs by encapsulating the information from span and events to logs by primarily logging events. This is the first iteration to make changes beginning with logging HTTP calls and database calls.

Changes below include:

Add logging for events at INFO level as JSON in LoggingOptions.
Update in event attribute datatypes to add arrays for String, Long, Double and Boolean.
Standardise error events to match OpenTelemetry specification https://github.com/open-telemetry/opentelemetry-specification/blob/master/specification/trace/semantic_conventions/exceptions.md.
Instrument SpanWrappedHTTPHandler and TracedHTTPClient with events for logging.
Instrument HandleSession, ReverseProxyHandler, JDBCBackedSessionMap and RedisBackedSessionMap with events for logging.
Instrument DockerSessionFactory and DriverServiceSessionFactory with events for logging.
Instrument LocalNode, LocalSessionMap, LocalDistributor. ProtocolConverter and GridStatusHandler with events for logging.

Motivation and Context

Span events can have attributes which can store all possible information for a particular operation. Leveraging the events, this information can be added to logs to provide rich contextual information in logs. This makes the debugging process easier. Rather than having multiple log statements for a single operation, event can be used to capture all possible context (including high-cardinality values) and used in logging.

Types of changes

Bug fix (non-breaking change which fixes an issue)
New feature (non-breaking change which adds functionality)
Breaking change (fix or feature that would cause existing functionality to change)

Checklist

I have read the contributing document.
My change requires a change to the documentation.
I have updated the documentation accordingly.
I have added tests to cover my changes.
All new and existing tests passed.

…ging.

…ackedSession map and RedisBackedSessionMap. Additional changes include: - Disabling pretty printng in LoggingOptions for event JSON.

shs96c · 2020-08-03T10:00:20Z

java/client/src/org/openqa/selenium/remote/tracing/AttributeKey.java

+  SESSION_CAPABILITIES("session.capabilities"),
+  SESSION_URI("session.uri"),
+
+  DATABASE_STATEMENT ("db.statement"),


These seems specific to the JDBC classes, and probably shouldn't be in the common keys.

These are based on OpenTelemetry specification for databases and it is applicable to all SQL and NoSQL client calls.

java/client/src/org/openqa/selenium/remote/tracing/AttributeKey.java

shs96c · 2020-08-03T10:01:19Z

java/client/src/org/openqa/selenium/remote/tracing/AttributeKey.java

+
+package org.openqa.selenium.remote.tracing;
+
+public enum AttributeKey {


It's likely that we can't know all the possible keys in advance. An enum is a poor choice given this constraint, so it may be better to use an interface

+1 , it is not possible to know keys in advance. AttributeKey enum is to store keys which are used repeatedly and which are part of OpenTelemetry specification, all attribute key do not need to be part of the enum. Do you still suggest to use an interface instead?

shs96c · 2020-08-03T10:02:16Z

java/client/src/org/openqa/selenium/remote/tracing/EventAttribute.java

+    return new EventAttributeValue(value);
+  }
+
+  public static EventAttributeValue setValue(Long[] value) {


Prefer primitive types.

OpenTelemetry APIs for array attributes accepts boxes types so stuck to that.

java/client/src/org/openqa/selenium/remote/tracing/EventAttribute.java

java/client/test/org/openqa/selenium/remote/tracing/opentelemetry/TracerTest.java

shs96c · 2020-08-03T10:12:07Z

java/server/src/org/openqa/selenium/grid/log/LoggingOptions.java

+                  attributeValue = value.getDoubleArrayValue();
+                  break;
+                case BOOLEAN_ARRAY:
+                  attributeValue = value.getBooleanArrayValue();


This case statement makes me twitch. It's long, and it looks like a prime candidate to accidentally forget to extend if we add a new value type. At the least, I'd suggest making Attributes be aware of how to serialise itself to JSON, so you can do a map.put("attributes", event.getAttributes)

I understand the concern expressed. However, the OpenTelemetry Attributes class stores a String key and AttributeValue value and in order to get the actual value from AttributeValue, it offers series of methods of based on the AttributeValue.Type. So this is the only way I am seeing to creating the attributeMap from Events, unless we extend Event. I will try and see how this can be made better.

Initially I considered extending either the Event or Attributes to add a method for Json serialisation of the attributes. After looking into the OTel classes, the Attributes implementation AutoValue_Attributes_ArrayBackedAttributes is final and cannot be extended. Same is applicable for Events implementation AutoValue_TimedEvent_RawTimedEvent. So we might be stuck with the switch case. Any suggestions on this front?

shs96c · 2020-08-03T10:12:30Z

java/server/src/org/openqa/selenium/grid/log/LoggingOptions.java

+            Map<String, Object> attributeMap = new HashMap<>();
+            attributes.forEach((key, value) -> {
+              Object attributeValue = null;
+              switch (value.getType()) {


Missed a default case

This is the exhaustive list of all the datatypes for event attributes, so any value that is passed will match one of the cases, hence no default case.

java/server/src/org/openqa/selenium/grid/log/LoggingOptions.java

shs96c · 2020-08-03T10:13:29Z

java/server/src/org/openqa/selenium/grid/log/LoggingOptions.java

+    StringBuilder text = new StringBuilder();
+    try (JsonOutput json = JSON.newOutput(text).setPrettyPrint(false)) {
+      json.write(map);
+      text.append('\n');


👀 Uhhh... Why? The logger will output everything on one line for us.

If I passed the Json String as it is, it was pretty printing the Json, so this was added to disable the pretty printing and have the event log in one line.

AutomatedTester

Looks good to me but will wait for @shs96c to have a look

…tory with event logs. - Alphabetize EventAttributeValue Type enum - Alphabetize switch case in openTelemetrySpan - Breakdown TracerTest into multiple test methods for Span event testing - Add vargs to EventAttributeValue for array value types

…y enum method getKey()

…StatusHandler, LocalSessionMap and ProtocolConverter.

AutomatedTester · 2020-08-14T12:51:58Z

I believe all comments have been addressed and will be merging on Tuesday morning if there are no further review comments.

@shs96c @diemol

diemol · 2020-08-17T23:14:01Z

Just a heads up, this PR touches some files that this #8513 one is also changing. I'd recommend merging the other one first and then solving the conflicts here afterwards.

pujagani · 2020-08-18T11:25:57Z

Verified that the changes in #8513 have not impacted the changes here. It is working as intended. @AutomatedTester

pujagani added 4 commits July 23, 2020 18:52

[tracing] Update tracing.txt for Opentelemetry 0.6.0 version bump

a4eeb89

Merge remote-tracking branch 'upstream/trunk' into structured_logging

ddab8cc

[tracing] Add array value to span event attribute. Add span event log…

22cd1a5

…ging.

[tracing] Add events to SpanHTTPHandler. Add events to TracedHTTPClient.

58571f2

pujagani marked this pull request as draft July 29, 2020 05:53

[tracing] Add log events to HandleSession, ReverseProxyHandler, JDBCB…

1751513

…ackedSession map and RedisBackedSessionMap. Additional changes include: - Disabling pretty printng in LoggingOptions for event JSON.

pujagani marked this pull request as ready for review July 30, 2020 11:15

pujagani changed the title ~~[tracing] WIP - Structured logging based on Span events~~ [tracing] Structured logging based on Span events Jul 30, 2020

Merge branch 'trunk' into structured_logging

3cae257

shs96c requested changes Aug 3, 2020

View reviewed changes

AutomatedTester approved these changes Aug 3, 2020

View reviewed changes

pujagani and others added 6 commits August 4, 2020 14:34

Merge branch 'trunk' into structured_logging

36bd973

[tracing] Remove AttributeKey enum method toString(). Add AttributeKe…

bc501a6

…y enum method getKey()

[tracing] Instrument event logs for LocalDistributor, LocalNode, Grid…

9eeffee

…StatusHandler, LocalSessionMap and ProtocolConverter.

Merge branch 'trunk' into structured_logging

3faa8f4

Merge branch 'trunk' into structured_logging

c9087b6

diemol and others added 3 commits August 18, 2020 08:53

Merge branch 'trunk' into structured_logging

f812799

Merge branch 'trunk' into structured_logging

58dd106

[tracing] Fix indentation and conflict in JdbcBackedSessionMap [skip ci]

1db2566

AutomatedTester merged commit 738dd0e into SeleniumHQ:trunk Aug 18, 2020

AutomatedTester mentioned this pull request Aug 21, 2020

Support structured logging on stdout #6694

Closed

pujagani mentioned this pull request Sep 22, 2020

Request Level Logging for next version of Sel4 #8625

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

[tracing] Structured logging based on Span events #8583

[tracing] Structured logging based on Span events #8583

pujagani commented Jul 29, 2020 •

edited

Loading

shs96c Aug 3, 2020

pujagani Aug 3, 2020

shs96c Aug 3, 2020

pujagani Aug 3, 2020

shs96c Aug 3, 2020

pujagani Aug 3, 2020 •

edited

Loading

shs96c Aug 3, 2020

pujagani Aug 4, 2020 •

edited

Loading

pujagani Aug 4, 2020 •

edited

Loading

shs96c Aug 3, 2020

pujagani Aug 3, 2020

shs96c Aug 3, 2020

pujagani Aug 3, 2020

AutomatedTester left a comment •

edited

Loading

AutomatedTester commented Aug 14, 2020

diemol commented Aug 17, 2020

pujagani commented Aug 18, 2020


		package org.openqa.selenium.remote.tracing;

		public enum AttributeKey {

[tracing] Structured logging based on Span events #8583

[tracing] Structured logging based on Span events #8583

Conversation

pujagani commented Jul 29, 2020 • edited Loading

Description

Motivation and Context

Types of changes

Checklist

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

pujagani Aug 3, 2020 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

pujagani Aug 4, 2020 • edited Loading

Choose a reason for hiding this comment

pujagani Aug 4, 2020 • edited Loading

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

AutomatedTester left a comment • edited Loading

Choose a reason for hiding this comment

AutomatedTester commented Aug 14, 2020

diemol commented Aug 17, 2020

pujagani commented Aug 18, 2020

pujagani commented Jul 29, 2020 •

edited

Loading

pujagani Aug 3, 2020 •

edited

Loading

pujagani Aug 4, 2020 •

edited

Loading

pujagani Aug 4, 2020 •

edited

Loading

AutomatedTester left a comment •

edited

Loading