Introduce a generic gRPC span sink #386

sdboyer-stripe · 2018-02-15T19:02:12Z

Summary

This introduces a generic gRPC sink for spans.

Motivation

It'll allow us to use, say, Falconer as a sink target. And arbitrary "other things" (as yet undefined) that may want to be span sinks.

Test plan

Automated end-to-end tests of service creation and ingesting a span.

Rollout/monitoring/revert plan

Strictly an addition, so no changes are required for rollouts.

sdboyer-stripe · 2018-02-15T20:32:07Z

Just looking for preliminary feedback right now, while i iterate. Note that this and maybe this are the only two files to really even look at.

cory-stripe · 2018-02-16T02:23:22Z

sinks/grpsink/grpc.go

+)
+
+// GRPCStreamingSpanSink is a sink that streams spans to a configurable target
+// service over gRPC. The sink is only tied to the grpc_sink.proto defintion of


sdboyer-stripe · 2018-02-16T03:27:28Z

One thing i've not quite been able to figure out - my go generate directive creates an import with the wrong path in it. i've manually fixed it, but this is obviously suboptimal for the future, and i'm not fully sure how to make it generate the way i'd prefer. i can keep poking at it and get it eventually, but if anyone more familiar with protobuf has a suggestion, it'd be welcome 😄

sdboyer-stripe · 2018-02-21T02:43:39Z

OK, finally fixed those silly errors, tests now passing.

r? @stripe/observability

asf-stripe

Nice start! I have a few comments / questions about structure (:

asf-stripe · 2018-02-21T13:42:51Z

sinks/grpsink/grpc_stream.go

+
+// Name returns this sink's name.
+func (gs *GRPCStreamingSpanSink) Name() string {
+	return gs.name


Hm, we use the Name a ton in metric tags, which means that every grpc sink gets its own timeseries; I guess this is one of those blessing/curse things, but we should definitely think through if we want to time things by grpc sink implementation, or by sink target (currently, we measure only by sink implementation)

My thought was that it seems unlikely that the grpc sink gets used directly - instead, i can imagine e.g. a very lightweight falconer sink that just wraps this one. That way we'd still have stability on this property, even though it isn't hardwired into the struct.

Alternatively, we could enforce that things work that way by dropping the Name() method entirely, ,causing GRPCStreamingSpanSink to not fulfill the interface anymore, and requiring some other struct (e.g. falconer) to embed it in order to have it actually be useful. That smacks of inheritance, but not so much that it wouldn't be idiomatic.

So, alternative: what if the expectation is that a value in a configuration file is what sets the actual name, here?

asf-stripe · 2018-02-21T13:44:16Z

sinks/grpsink/grpc_stream.go

+	if err != nil {
+		gs.log.WithError(err).WithFields(logrus.Fields{
+			"name": gs.name,
+		}).Warn("Error streaming traces to gRPC server")


Increment an error counter here or track a metric right away?

Why are we doing log.WithError.Warn instead of log.WithError.Error? The latter would automatically get us a Sentry event.

asf-stripe · 2018-02-21T13:45:38Z

sinks/grpsink/grpc_stream.go

+
+func (gs *GRPCStreamingSpanSink) Start(cl *trace.Client) error {
+	// TODO this API is experimental - perhaps we shouldn't use it yet
+	if !gs.grpcConn.WaitForStateChange(context.TODO(), connectivity.Ready) {


Hrm, maybe we should pass a ctx arg into Start methods too.

i definitely think we should, but i didn't want to expand scope on this PR to modifying the interface.

asf-stripe · 2018-02-21T13:45:54Z

sinks/grpsink/grpc_stream.go

+}
+
+// Ingest takes in a span and streams it over gRPC to the connected server.
+func (gs *GRPCStreamingSpanSink) Ingest(ssfSpan *ssf.SSFSpan) error {


We definitely ought to start passing a ctx into Ingest.

💯 💯 💯

asf-stripe · 2018-02-21T13:47:25Z

sinks/grpsink/grpc_stream.go

+	}
+
+	// TODO validation of span, e.g. time bounds like in datadog span sink?
+	err := gs.stream.Send(ssfSpan)


How does this deal with disconnections? Will sending to a dead socket re-establish the connection? (A cursory glance at the grpc docs didn't tell me)

i don't know yet. there's a whole lot of connection handling things that i just haven't explored.

This question, at least, is one that we can explore via tests.

asf-stripe · 2018-02-21T13:56:38Z

sinks/grpsink/grpc_stream.go

+	}
+
+	// TODO How do we allow grpc.CallOption to be injected in here?
+	// TODO Setting this up here (probably) means one stream per lifecycle of this object. Is that the right design?


I think that TODO sums it up: We don't restart veneur all that often, and Start gets called only on startup; if the connection should drop, does that mean we have no way of re-establishing?

i shall investigate 😄

sdboyer-stripe · 2018-02-21T16:51:17Z

(testing)

r? @aditya-stripe

sdboyer-stripe · 2018-02-28T02:34:30Z

Had to fix the CHANGELOG, it adds the 4.0.0 section at the top. Maybe this isn't ideal, but we can sort that out...

Anyway, this is actually ready for review - @asf-stripe ? The only two files that ACTUALLY need review are sinks/grpsink/grpc_stream.go and sinks/grpsink/grpc_stream_test.go.

sdboyer-stripe · 2018-02-28T02:35:13Z

Note that we've elected NOT to expose config controls in this PR, so this code isn't actually reachable yet by users. (Maybe that means it's premature to add it to the CHANGELOG...?)

sdboyer-stripe · 2018-02-28T03:19:30Z

Uuuugh, so, we've got some potentially flaky tests here - a lot of dependence on sleep timings, because there's not really good ways of peeking into internal grpc state. Not actually sure how avoidable this is going to be on shared infra like Travis... 😢

asf-stripe · 2018-02-28T10:48:31Z

Agh also, unrelated note: I realized why this is not building in our internal CI: You have to make that branch in the stripe/veneur instead of your fork /:

asf-stripe

Hm, yeah, I don't love the tests either, and I'm somewhat confused around what locks do and don't. I think since this code takes the lock at a bunch of times and does not super easy to grok things with it, maybe this can be structured in a different way? (Is there a reasonable way to have a single goroutine manage the connection?)

asf-stripe · 2018-02-28T10:50:32Z

sinks/grpsink/grpc_stream_test.go

+
+	err = sink.Ingest(testSpan)
+	// This should be enough to make it through loopback TCP. Bump up if flaky.
+	time.Sleep(time.Millisecond)


wow, yeah, I really don't love this; can this maybe notify a channel or invoke a callback or something instead of appending to that spans array?

i have some WIP locally that i'd abandoned, but it at least achieves that bit. that's easy enough to pull up 👍

asf-stripe · 2018-02-28T10:51:57Z

sinks/grpsink/grpc_stream_test.go

+	assert.Equal(t, testSpan, mock.firstSpan())
+	require.Equal(t, mock.spanCount(), 1)
+
+	srv.Stop()


hm (recalling our vc before), did it not work to close the connection out-of-band?

i spent a bit trying to make it work, but it ended up being even more complicated wrt adding more icky timing dependencies. then, i looked at the actual implementation of Server.Stop(), and saw that the first really effectual action it takes is just closing the listener. So i decided that testing this directly wasn't worth the extra trouble. (sorry, forgot to mention it in issue comments!)

asf-stripe · 2018-02-28T10:53:07Z

sinks/grpsink/grpc_stream_test.go

+	cf()
+
+	require.Equal(t, connectivity.Ready, sink.grpcConn.GetState())
+	time.Sleep(5 * time.Millisecond)


same for the ingestion channel suggestion above

asf-stripe · 2018-02-28T10:53:38Z

sinks/grpsink/grpc_stream_test.go

+// channel, but this test ensures we handle it properly in the event that it
+// does. It can be flaky, though (it's too dependent on sleep timings), so
+// it's disabled, but preserved for future debugging purposes.
+func testClientIdleRecovery(t *testing.T) {


is it intentional that this function doesn't get invoked?

Yes, per the comment above it

asf-stripe · 2018-02-28T10:54:27Z

sinks/sinks.go

@@ -56,6 +56,11 @@ const MetricKeySpanFlushDuration = "sink.span_flush_total_duration_ns"
 // place to do this.
 const MetricKeyTotalSpansFlushed = "sink.spans_flushed_total"

+// MetricKeyTotalSpansDropped  should be emitted as a counter by a SpanSink
+// if possible. Tagged with `sink:sink.Name()`. The `Flush` function is a great
+// place to do this.


I think this doc comment doesn't quite answer the thing I most hoped it would: What concrete thing does that metric indicate? (:

i was following the pattern from above :) i'll flesh it out.

asf-stripe · 2018-02-28T11:10:31Z

sinks/grpsink/grpc_stream.go

+					logrus.ErrorKey: err,
+				}).Error("Failed to set up a new stream after gRPC channel recovered")
+				time.Sleep(1 * time.Second)
+				gs.streamMut.Unlock()


it it necessary to hold the lock while sleeping there?

Also, wonder if instead of sleeping this can use WaitForStateChange with a longer timeout instead.

Ah no, those can be switched around - unlock before sleep.

We don't want another WaitForStateChange() here, though, because we shouldn't expect to see one. The state change is in the underlying channel state, not the stream - and being here means that the channel is already back in READY state. If we were to wait again, it might be for a long time - until the next network event disrupts the connection.

asf-stripe · 2018-02-28T11:13:54Z

sinks/grpsink/grpc_stream.go

+	if err := protocol.ValidateTrace(ssfSpan); err != nil {
+		return err
+	}
+	// TODO(sdboyer) validation of span, e.g. time bounds like in datadog sink?


what do you mean by that TODO? (ValidateTrace should take care of identifying only trace spans...)

veneur/sinks/datadog/datadog.go

Lines 334 to 342 in a634bb6

if ssfSpan.StartTimestamp < tooEarly {

tags["type"] = "tooEarly"

}

if ssfSpan.StartTimestamp > tooLate {

tags["type"] = "tooLate"

}

if timeErr != "" {

samples.Add(ssf.Count("worker.trace.sink.timestamp_error", 1, tags))

}

asf-stripe · 2018-02-28T11:16:35Z

sinks/grpsink/grpc_stream.go

+	return err
+}
+
+// Flush reports metrics about the number of failed and successful


doc comment sentence breaks off (:

asf-stripe · 2018-02-28T11:17:06Z

sinks/grpsink/grpc_stream.go

+		sinks.MetricKeyTotalSpansDropped,
+		float32(atomic.LoadUint32(&gs.errCount)),
+		map[string]string{"sink": gs.Name()},
+	))


you can pass varargs to samples.Add - probably easier to skim that way

asf-stripe · 2018-02-28T11:17:45Z

sinks/grpsink/grpc_stream.go

+		map[string]string{"sink": gs.Name()},
+	))
+
+	metrics.Report(gs.traceClient, samples)


I've been doing defer metrics.Report(gs.traceClient, samples) throughout the code - guess this is fine too (:

yeah this is just my thing about defers again :)

sdboyer-stripe · 2018-03-01T01:58:09Z

(Is there a reasonable way to have a single goroutine manage the connection?)

There really isn't, unfortunately. We need a self-contained bundle of logic where its sole job is watching the state of the underlying channel in the background, then recreating the stream when it comes back into a good state. That's what's difficult here - while gRPC handles keeping the "channel" (basically, the connection) working automatically, we still have to keep our stream working, as it dies whenever the connection itself has a problem.

Gotta have its own goroutine for that. Or at least, i haven't been able to figure out an alternative that isn't more complicated.

sdboyer-stripe · 2018-03-01T02:00:31Z

i've added some more commits that should remove the test flakiness entirely (no more sleeps to get timings right) - about 200 or so successful runs in a row on my laptop. (we'll see how it fares in CI, ofc).

Also simplified a few things, and added a bit more in the way of explanatory documentation. i think this should be pretty much ready.

asf-stripe

No final judgment yet! The tests look good (\o/ yay less raciness), I have found a few nits though (:

asf-stripe · 2018-03-01T13:49:37Z

sinks/grpsink/grpc_stream.go

 				continue
 			}
+			// CAS inside the mutex means that it's impossible for for the same


miiiinor nit: for for

asf-stripe · 2018-03-01T13:54:03Z

sinks/grpsink/state_helper_test19.go

+	t.Helper()
+
+	first, current := seq[0], sink.grpcConn.GetState()
+	if !assert.ObjectsAreEqual(first, current) {


this smells super strongly like it wants to be require.Equal (:

comment added - it doesn't use require.Equal because then the use of t.Helper() above would be pointless, because those libraries haven't yet been updated to use t.Helper().

asf-stripe · 2018-03-01T13:54:30Z

sinks/grpsink/state_helper_test19.go

+	waitThroughStateSequence(t, sink, dur, seq[:len(seq)-1]...)
+
+	last, current := seq[len(seq)-1], sink.grpcConn.GetState()
+	if !assert.ObjectsAreEqual(last, current) {


ditto for require.Equal

asf-stripe · 2018-03-01T13:56:08Z

sinks/grpsink/state_helper_test19.go

+		switch state {
+		case connectivity.Ready:
+			// Spin on the internal state marker that indicates the stream state is bad
+			for !atomic.CompareAndSwapUint32(&sink.bad, 0, 0) {


shouldn't this check that the context timeout has been exceeded too? (Otherwise it'll spin forever/until the test timeout)

(now done, but github didn't notice)

Needed for some (experimental) features currently accessed in grpsink. Plus, might as well upgrade anyway.

This is a rudimentary but effective test of the sink's essential behavior.

All of my efforts at simulating failure modes thus far have either resulted in deadlocks, or error messages. Honestly not sure how one is supposed to simulate a failure, even after looking at grpc's own tests in this area.

This logic handles adaptive stream recreation on a background goroutine, which operates by keeping tabs on the underlying gRPC connection state machine.

This now simulates a server shutdown effectively, demonstrating the automated stream reconstruction capabilities of the sink's background goroutine.

We now handle idle connections correctly, in the very remote case that they should occur.

This should obviate the possibility of flaky failures in these tests. Hopefully. 200 test runs in a row without a failure, so here's hoping.

Previous code wasn't treating io.EOF as a special value in the way that gRPC expects it to be. This simplifies the error handling a bit, as well as alllowing us to continue to log potentially interesting non-EOF errors after the first error has been seen on a given stream instance.

Avoid a possible, albeit highly unlikely, spinlock.

Separating this call into its own method helps clarify its role on the critical path, as well as the relationship to the state machine manager.

asf-stripe

\o/

sdboyer-stripe · 2018-03-01T15:13:52Z

WEEEEE!!!

sdboyer-stripe force-pushed the grpc-sink branch from a0a17cd to 538d136 Compare February 15, 2018 20:22

cory-stripe reviewed Feb 16, 2018

View reviewed changes

sdboyer-stripe force-pushed the grpc-sink branch from 9e12bc0 to a7f54b0 Compare February 20, 2018 21:41

asf-stripe reviewed Feb 21, 2018

View reviewed changes

sdboyer-stripe force-pushed the grpc-sink branch 2 times, most recently from f0be0df to b36a560 Compare February 28, 2018 02:33

sdboyer-stripe assigned asf-stripe Feb 28, 2018

asf-stripe suggested changes Feb 28, 2018

View reviewed changes

stripe-ci assigned sdboyer-stripe and unassigned asf-stripe Feb 28, 2018

sdboyer-stripe force-pushed the grpc-sink branch from 89175a1 to 283ab27 Compare March 1, 2018 02:03

asf-stripe reviewed Mar 1, 2018

View reviewed changes

sdboyer-stripe added 7 commits March 1, 2018 09:49

First pass on generic gRPC sink

ab23913

Update grpc to latest

8cd2b21

Needed for some (experimental) features currently accessed in grpsink. Plus, might as well upgrade anyway.

Update generators with new grpsink path

e642e47

Update Gopkg.lock hash inputs

37c6dad

Rename and touch up files

9a436da

Add basic end-to-end test of gRPC sink

19352c6

This is a rudimentary but effective test of the sink's essential behavior.

Fix typos and update CHANGELOG

c886915

sdboyer-stripe added 17 commits March 1, 2018 09:49

gofmt over vendor

888681e

Fix generate.go to use correct import path prefix

e645380

Fix silly data race in test mock

40a0b02

Work towards automated grpc stream healing

cd158a6

All of my efforts at simulating failure modes thus far have either resulted in deadlocks, or error messages. Honestly not sure how one is supposed to simulate a failure, even after looking at grpc's own tests in this area.

Fix gRPC stream adaptive recovery logic

d978464

This logic handles adaptive stream recreation on a background goroutine, which operates by keeping tabs on the underlying gRPC connection state machine.

Fix gRPC sink stream test

0bfd1c7

This now simulates a server shutdown effectively, demonstrating the automated stream reconstruction capabilities of the sink's background goroutine.

Update grpc-go to v1.10.0

518e0a0

Final fixes to the gRPC state machine manager

f65b1e3

We now handle idle connections correctly, in the very remote case that they should occur.

Fix CHANGELOG for next release

b5a3b0d

Ugh the inputs-digest in Gopkg.lock

d77742e

Disable flaky idling timeouts test

2977c3d

Address issues with state machine manager

93934b0

Excise all use of sleep timings in tests

73a3f59

This should obviate the possibility of flaky failures in these tests. Hopefully. 200 test runs in a row without a failure, so here's hoping.

Comment improvements

d8e722a

Comment and improve gRPC sink helper test methods

430214c

Avoid a possible, albeit highly unlikely, spinlock.

Put span sink send into its own method for clarity

6b34cb3

Separating this call into its own method helps clarify its role on the critical path, as well as the relationship to the state machine manager.

sdboyer-stripe force-pushed the grpc-sink branch from fcab67d to 6b34cb3 Compare March 1, 2018 14:52

Fix comment typo

0da14f3

asf-stripe approved these changes Mar 1, 2018

View reviewed changes

stripe-ci added the approved label Mar 1, 2018

sdboyer-stripe merged commit a76347d into stripe:master Mar 1, 2018

sdboyer-stripe mentioned this pull request Mar 5, 2018

Common tags on sinks: overwrite or not? #404

Open

	if ssfSpan.StartTimestamp < tooEarly {
	tags["type"] = "tooEarly"
	}
	if ssfSpan.StartTimestamp > tooLate {
	tags["type"] = "tooLate"
	}
	if timeErr != "" {
	samples.Add(ssf.Count("worker.trace.sink.timestamp_error", 1, tags))
	}

Introduce a generic gRPC span sink #386

Introduce a generic gRPC span sink #386

Conversation

sdboyer-stripe commented Feb 15, 2018 • edited Loading

Summary

Motivation

Test plan

Rollout/monitoring/revert plan

sdboyer-stripe commented Feb 15, 2018

Choose a reason for hiding this comment

sdboyer-stripe commented Feb 16, 2018

sdboyer-stripe commented Feb 21, 2018 • edited by aditya-stripe Loading

asf-stripe 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

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

sdboyer-stripe commented Feb 21, 2018

sdboyer-stripe commented Feb 28, 2018

sdboyer-stripe commented Feb 28, 2018

sdboyer-stripe commented Feb 28, 2018

asf-stripe commented Feb 28, 2018

asf-stripe 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

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

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

sdboyer-stripe commented Mar 1, 2018

sdboyer-stripe commented Mar 1, 2018

asf-stripe 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

asf-stripe left a comment

Choose a reason for hiding this comment

sdboyer-stripe commented Mar 1, 2018

sdboyer-stripe commented Feb 15, 2018 •

edited

Loading

sdboyer-stripe commented Feb 21, 2018 •

edited by aditya-stripe

Loading