Zipkin Receiver: default timestamp #1068

chris-smith-zocdoc · 2020-06-03T05:18:22Z

Fixes #954

#954 is being caused from the conversion of OC -> Internal -> OC span types.

OC technically allows nil times because its a pointer, but docs state

// This field is semantically required. When not set on receive -
// receiver should set it to the value of end_time field if it was
// set. Or to the current time if neither was set. It is important to
// keep end_time > start_time for consistency.
//
// This field is required.
StartTime *timestamp.Timestamp

So this pr changes the zipkin receiver to set the start/end timestamps if they're not set on receive

chris-smith-zocdoc · 2020-06-03T05:20:13Z

exporter/zipkinexporter/zipkin.go

@@ -123,7 +123,7 @@ func (ze *zipkinExporter) PushTraceData(_ context.Context, td consumerdata.Trace

 	body, err := ze.serializer.Serialize(tbatch)
 	if err != nil {
-		return len(td.Spans), err
+		return len(td.Spans), consumererror.Permanent(err)


I changed the serialization failure to a permanent error because it had caused an infinite loop in the retry processor otherwise. Is there any reason we'd want to retry on a serialization error?

I can't think of any reason to retry them

dmitryax

What is the value of spans with no timestamps? Is there a particular reason to have them in zipkin?

Btw we will need to remove the OC part from the zipkin -> OC -> internal translation later on. So we need to think how to represent such spans in internal data structure if cannot discard them.

dmitryax · 2020-06-03T07:26:56Z

exporter/zipkinexporter/zipkin.go

@@ -123,7 +123,7 @@ func (ze *zipkinExporter) PushTraceData(_ context.Context, td consumerdata.Trace

 	body, err := ze.serializer.Serialize(tbatch)
 	if err != nil {
-		return len(td.Spans), err
+		return len(td.Spans), consumererror.Permanent(err)


I can't think of any reason to retry them

owais · 2020-06-03T09:22:20Z

translator/trace/zipkin/zipkinv1_to_protospan.go

+		now := internal.TimeToTimestamp(time.Now())
+		span.StartTime = now
+		span.EndTime = now
+	}


I'm not sure about this but I don't know what the right thing to do is. Addin/modifying data like this just to make serialize happy doesn't sound that great to me. This mean backends will show misleading information to users.

Alternatively, we could just drop such spans as a validation step in the zipkin receiver and log messages but we can't do that as zipkin spec allows for the possibility of not having timestamps. Is there a way we can serialize it differently without adding fake timestamps?

If there is no other viable solution, we should at least add an attribute to the span that represents that the timestamps are fake and shouldn't be trusted. Also, can we may be use more obvious fake value for timestamp like unix epoch or something?

Zipkin spec on this:

Epoch microseconds of the start of this span, possibly absent if incomplete. For example, 1502787600000000 corresponds to 2017-08-15 09:00 UTC This value should be set directly by instrumentation, using the most precise value possible. For example, gettimeofday or multiplying epoch millis by 1000. There are three known edge-cases where this could be reported absent. A span was allocated but never started (ex not yet received a timestamp) The span’s start event was lost Data about a completed span (ex tags) were sent after the fact

A span was allocated but never started (ex not yet received a timestamp)

If this was the only edge-case, we could just drop the span as it didn't actually represent a real operation but we have two more scenarios that can result in spans without timestamps so we can't just drop.

It looks like setting a static timestamp that is obviously fake along with a well-known attribute that says the timestamps were injected by Otel collector as a workaround is probably our best bet. Does Jaeger proto allow having empty timestamps? If so, an OTLP>Jaeger/Zipkin translator should probably set the timestamp to nil again when it encounters this tag on a span. One concern with setting a very old timestamp is that it might affect some backends in an unexpected way. For example, some backend might drop the span very soon if it stores only recent data and by span operation timestamps instead of ingestion timestamp.

I'm not familiar with Jaeger, will need someone else to weigh in on that

It looks like setting a static timestamp that is obviously fake along with a well-known attribute that says the timestamps were injected by Otel collector as a workaround is probably our best bet. Does Jaeger proto allow having empty timestamps? If so, an OTLP>Jaeger/Zipkin translator should probably set the timestamp to nil again when it encounters this tag on a span. One concern with setting a very old timestamp is that it might affect some backends in an unexpected way. For example, some backend might drop the span very soon if it stores only recent data and by span operation timestamps instead of ingestion timestamp.

I agree with this approach. We can set a fake current timestamp along with an attribute identifying this workaround and use it in Jaeger/zipkin exporters to reconstruct null timestamps.

That sounds like a zipkin convention. We should probably have an otel convention about such tags. May be otel.zipkin.missingTimestamp or otel.zipkin.missingFields with value being comma separated list of field names? May be we should have otel collector specific conventions for behavior like this. Perhaps prefix with otelcol or something?

We can set a fake current timestamp

Why current timestamp? Can we do zero time? Like 0 seconds since unix epoch? I'm afraid if we use current time and the span get exported using something other than zipkin, it might be very misleading to users when seeing the span in a tracing backend. "zero time" will at least raise some eye brows.

@owais , 0 timestamps look cleaner, but if I understood your concern right it doesn't look like the best way:

One concern with setting a very old timestamp is that it might affect some backends in an unexpected way. For example, some backend might drop the span very soon if it stores only recent data and by span operation timestamps instead of ingestion timestamp.

IMO still dropping spans with 0 timestamp looks like the best way to handle it in otel-collector. @chris-smith-zocdoc could you please let us know if the spans with no timestamps are actually visible in the backend that you use or they needed for aggregation purposes?

IMO still dropping spans with 0 timestamp looks like the best way to handle it in otel-collector

I disagree. Throwing away data seems suboptimal.

Through coincidence they actually end up as a zero timestamp right now, but after the translation from OC -> internal -> OC for the zipkin export, the timestamp is becoming invalid and causing the serialization issue.

could you please let us know if the spans with no timestamps are actually visible in the backend that you use or they needed for aggregation purposes?

Yes they're visible. We have two backends, one is zipkin the other is honeycomb.

The data in these spans are just events and annotations, sent after the original span. This appears to be a common behavior in the zipkin libraries we're using for javascript and scala.

[ { "traceId": "404059d49fac24fc", "id": "404059d49fac24ff", "annotations": [ { "timestamp": 1589292979495000, "value": "zipkin-js.flush" } ], "tags": { "response_size_bytes": "9622" } } ]

In zipkin the data is merged into the original span.

In honeycomb these end up as a second event in their system. I've considered building a buffer/merge processor (similar to tail sampling) to do the merge in OTel before sending it to them.

Agree that throwing away the spans does not sound correct for people who might be using zipkin end to end (or even some parts of it) since it is a valid zipkin use case. I still have concerns about zero'ed timestamps causing backends to drop spans too soon. May be backends can use the tag we inject to detect this edge-case but not sure we can expect all backends to do this especially since it is not part of the otel spec. I guess adding current timestamp for both start and end is the safest choice here even though it's not very optimal for backends other than zipkin.

Sounds good. Let's stick with the current timestamp.

Also @owais had a good point about about the attribute name. We probably should not use a name that looks like zipkin convention. @owais, what about otel.zipkin.absentField.startTime?

chris-smith-zocdoc · 2020-06-03T13:16:02Z

What is the value of spans with no timestamps? Is there a particular reason to have them in zipkin?

Yes there is value in keeping them, @owais covered the cases where this can occur.

In my environment I believe I was running into case 3 "Data about a completed span (ex tags) were sent after the fact"

dmitryax · 2020-06-05T23:01:21Z

Please fix linter issues

linux-foundation-easycla · 2020-06-08T14:08:08Z

The committers are authorized under a signed CLA.

✅ Chris Smith (edc1c82, af7a2d5, 0da8861)

…h is removed on the export

codecov · 2020-06-08T14:34:54Z

Codecov Report

Merging #1068 into master will decrease coverage by 0.00%.
The diff coverage is 97.82%.

@@            Coverage Diff             @@
##           master    #1068      +/-   ##
==========================================
- Coverage   86.34%   86.33%   -0.01%     
==========================================
  Files         198      198              
  Lines       14159    14187      +28     
==========================================
+ Hits        12226    12249      +23     
- Misses       1477     1481       +4     
- Partials      456      457       +1

Impacted Files	Coverage Δ
exporter/zipkinexporter/zipkin.go	`78.18% <0.00%> (ø)`
...ceiver/internal/scraper/cpuscraper/cpu_metadata.go	`100.00% <100.00%> (ø)`
...eceiver/internal/scraper/cpuscraper/cpu_scraper.go	`88.23% <100.00%> (ø)`
...r/internal/scraper/cpuscraper/cpu_scraper_linux.go	`100.00% <100.00%> (ø)`
receiver/hostmetricsreceiver/internal/testutils.go	`88.46% <100.00%> (-11.54%)`	⬇️
receiver/zipkinreceiver/trace_receiver.go	`70.29% <100.00%> (+0.09%)`	⬆️
translator/trace/zipkin/protospan_to_zipkinv1.go	`88.23% <100.00%> (+0.21%)`	⬆️
translator/trace/zipkin/zipkinv1_to_protospan.go	`83.96% <100.00%> (+1.00%)`	⬆️
internal/internal.go	`78.94% <0.00%> (-10.53%)`	⬇️
translator/internaldata/resource_to_oc.go	`76.47% <0.00%> (ø)`

Continue to review full report at Codecov.

Legend - Click here to learn more
Δ = absolute <relative> (impact), ø = not affected, ? = missing data
Powered by Codecov. Last update caadbbc...c3f6252. Read the comment docs.

dmitryax

LGTM

Fixes open-telemetry#954 open-telemetry#954 is being caused from the conversion of OC -> Internal -> OC span types. OC technically allows nil times because its a pointer, but [docs state](https://github.com/census-instrumentation/opencensus-proto/blob/master/src/opencensus/proto/trace/v1/trace.proto#L125-L135) ```go // This field is semantically required. When not set on receive - // receiver should set it to the value of end_time field if it was // set. Or to the current time if neither was set. It is important to // keep end_time > start_time for consistency. // // This field is required. StartTime *timestamp.Timestamp ``` So this pr changes the zipkin receiver to set the start/end timestamps if they're not set on receive

…y#1068)

chris-smith-zocdoc requested review from bogdandrutu, dmitryax, flands, owais, pjanotti, rghetia, songy23 and tigrannajaryan as code owners June 3, 2020 05:18

chris-smith-zocdoc commented Jun 3, 2020

View reviewed changes

dmitryax reviewed Jun 3, 2020

View reviewed changes

dmitryax self-assigned this Jun 3, 2020

owais reviewed Jun 3, 2020

View reviewed changes

chris-smith-zocdoc mentioned this pull request Jun 3, 2020

Upstream Sync Zocdoc/opentelemetry-collector#1

Merged

chris-smith-zocdoc added 3 commits June 8, 2020 10:27

If the starttime is unset, default to the current time

edc1c82

When zipkin receiver infers the span starttime, add an attribute whic…

af7a2d5

…h is removed on the export

Fix lint

0da8861

chris-smith-zocdoc force-pushed the cs_954_pt2 branch from e033b2a to 0da8861 Compare June 8, 2020 14:28

rename attribute to otel.zipkin.absentField.startTime

c3f6252

dmitryax approved these changes Jun 9, 2020

View reviewed changes

tigrannajaryan merged commit 746db76 into open-telemetry:master Jun 11, 2020

chris-smith-zocdoc deleted the cs_954_pt2 branch June 12, 2020 14:05

nebffa mentioned this pull request Sep 7, 2020

Default timestamps for splunkhecexporter open-telemetry/opentelemetry-collector-contrib#965

Closed

Troels51 pushed a commit to Troels51/opentelemetry-collector that referenced this pull request Jul 5, 2024

Improvement: span_id should not break strict aliasing. (open-telemetr…

69fdf67

…y#1068)

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Zipkin Receiver: default timestamp #1068

Zipkin Receiver: default timestamp #1068

chris-smith-zocdoc commented Jun 3, 2020

chris-smith-zocdoc Jun 3, 2020

dmitryax Jun 3, 2020

dmitryax left a comment •

edited

Loading

dmitryax Jun 3, 2020

owais Jun 3, 2020

owais Jun 3, 2020

owais Jun 3, 2020 •

edited

Loading

chris-smith-zocdoc Jun 3, 2020

dmitryax Jun 3, 2020

owais Jun 5, 2020 •

edited

Loading

dmitryax Jun 5, 2020 •

edited

Loading

chris-smith-zocdoc Jun 6, 2020

owais Jun 8, 2020

dmitryax Jun 8, 2020

chris-smith-zocdoc commented Jun 3, 2020

dmitryax commented Jun 5, 2020

linux-foundation-easycla bot commented Jun 8, 2020 •

edited

Loading

codecov bot commented Jun 8, 2020 •

edited

Loading

dmitryax left a comment

Zipkin Receiver: default timestamp #1068

Zipkin Receiver: default timestamp #1068

Conversation

chris-smith-zocdoc commented Jun 3, 2020

Choose a reason for hiding this comment

Choose a reason for hiding this comment

dmitryax left a comment • 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

owais Jun 3, 2020 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

owais Jun 5, 2020 • edited Loading

Choose a reason for hiding this comment

dmitryax Jun 5, 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

chris-smith-zocdoc commented Jun 3, 2020

dmitryax commented Jun 5, 2020

linux-foundation-easycla bot commented Jun 8, 2020 • edited Loading

codecov bot commented Jun 8, 2020 • edited Loading

Codecov Report

dmitryax left a comment

Choose a reason for hiding this comment

dmitryax left a comment •

edited

Loading

owais Jun 3, 2020 •

edited

Loading

owais Jun 5, 2020 •

edited

Loading

dmitryax Jun 5, 2020 •

edited

Loading

linux-foundation-easycla bot commented Jun 8, 2020 •

edited

Loading

codecov bot commented Jun 8, 2020 •

edited

Loading