spanner: "OVERKILLED java.lang.IllegalStateException: refCount dropped below zero" warning

[skuruppu]

I have seen a few reports of warning messages polluting error logs.

Environment details

1. Specify the API at the beginning of the title. For example, "BigQuery: ...").
   Spanner
2. OS type and version: Linux but version unknown
3. Java version: Unknown
4. spanner version(s): 1.43.0

Steps to reproduce

I haven't reproduced this yet but I suspect this happens when an error occurs during ResumableStreamIterator.computeNext(). The trace span is ended with TraceUtil.endSpanWithFailure(span, e) but then when the stream iterator is closed, the code attempts to end the span again.

Stack trace

WARNING: <span:26a180bf406e2db9, parent:4479af252f884e07, trace:842cc1d5df736326, mask:ffffffff98000080, name:CloudSpannerOperation.ExecuteStreamingQuery>: OVERKILLED
java.lang.IllegalStateException: refCount dropped below zero
	at com.google.tracing.TraceContext.unRef(TraceContext.java:799)
	at com.google.perftools.opencensus.trace.SpanImpl.end(SpanImpl.java:237)
	at io.opencensus.trace.Span.end(Span.java:244)
	at com.google.cloud.spanner.AbstractResultSet$ResumableStreamIterator.close(AbstractResultSet.java:850)
	at com.google.cloud.spanner.AbstractResultSet$GrpcValueIterator.close(AbstractResultSet.java:285)
	at com.google.cloud.spanner.AbstractResultSet$GrpcResultSet.close(AbstractResultSet.java:133)
	at com.google.cloud.spanner.AbstractResultSet$GrpcResultSet.yieldError(AbstractResultSet.java:144)
	at com.google.cloud.spanner.AbstractResultSet$GrpcResultSet.next(AbstractResultSet.java:121)
	at com.google.cloud.spanner.ForwardingResultSet.next(ForwardingResultSet.java:47)
	at com.google.cloud.spanner.SessionPool$AutoClosingReadContext$1.internalNext(SessionPool.java:151)
	at com.google.cloud.spanner.SessionPool$AutoClosingReadContext$1.next(SessionPool.java:141)

[mayurkale22]

In case of OpenCensus implementation, we have a safety check in place to handle end of span call multiple times. You might see "Calling end() on an ended Span." log when calling end more than once.

See: https://github.com/census-instrumentation/opencensus-java/blob/eea371c3c1cdaa7f73004e5ca369cb6128d80abc/impl_core/src/main/java/io/opencensus/implcore/trace/RecordEventsSpanImpl.java#L373-L376

[skuruppu]

Thanks @mayurkale22. That's what I suspected. I'm trying to reproduce this with the ResumableStreamIteratorTest but I can end the span as many times as I want and it doesn't seem to be an issue.

So it's not so much that the span is ended many times. It's more that the span has gone out of scope by the time end() is called. I haven't yet figured out how to recreate this situation.

Adding @dinooliva to see if he has any thoughts.

[skuruppu]

Also adding @olavloite to see if he has any ideas.

[mayurkale22]

So it's not so much that the span is ended many times. It's more that the span has gone out of scope by the time end() is called.

AFAIK a default Span will be used (which does nothing) if no Span is associated with the current Context/Scope. I would not worry about out of scope scenario.

Looking at the implementation (com.google.perftools.opencensus.trace.SpanImpl), reference (refCount) is increased only when the Span is created and decreased when the span is ended. The refCount is dropping below means there are more number of ended span than started, which also indicates spanner instrumentation is calling end() on an ended Span.

One of the suspect is this, there is a call TraceUtil.endSpanWithFailure(span, e) which calls span.end() and a second end() is getting called in the finally block. For this case, I would not end the span in endSpanWithFailure and let the finally block take care of it.

java-spanner/google-cloud-spanner/src/main/java/com/google/cloud/spanner/DatabaseClientImpl.java

Lines 68 to 73 in 1178958

	} catch (RuntimeException e) {
	TraceUtil.endSpanWithFailure(span, e);
	throw e;
	} finally {
	span.end(TraceUtil.END_SPAN_OPTIONS);
	}

This is my initial assessment. WDYT?

[skuruppu]

Yup I agree with you @mayurkale22. I thought that was the issue and was going to replace some of the TraceUtil.endSpanWithFailure() calls with span.setStatus() calls then allow the finally and/or close to end the span once.

But when I tried out this idea with the ResumableStreamIteratorTest by calling end() a few times, I don't get this refcount warning. Maybe I'm not running the tests in a similar environment to those people that reported the issue.

[olavloite]

See https://github.com/mayurkale22/java-spanner/pull/1 for a small test framework for checking whether we are or are not 'overkilling' spans.

[mayurkale22]

Test framework looks great, I have integrated with my PR with some checks on all the started span and their ended status. Two things I observed:

1. CloudSpanner.ReadWriteTransaction span doesn't end after transactionRunner call. See: https://github.com/googleapis/java-spanner/pull/75/files#diff-711d9312cd4ab6691f226f63f857fd54R197. I am not sure what is expected behavior, should we close the span in finally block?

2. CloudSpannerOperation.ExecuteStreamingQuery span getting ended twice in case of singleUse().executeQuery due to this, I think stream is not closed properly in case of GrpcResultSet. @olavloite thoughts?

[olavloite]

Test framework looks great, I have integrated with my PR with some checks on all the started span and their ended status. Two things I observed:

1. CloudSpanner.ReadWriteTransaction span doesn't end after transactionRunner call. See: https://github.com/googleapis/java-spanner/pull/75/files#diff-711d9312cd4ab6691f226f63f857fd54R197. I am not sure what is expected behavior, should we close the span in finally block?
2. CloudSpannerOperation.ExecuteStreamingQuery span getting ended twice in case of singleUse().executeQuery due to this, I think stream is not closed properly in case of GrpcResultSet. @olavloite thoughts?

Ad 1: I would say we should end the span in the finally block of this method:

java-spanner/google-cloud-spanner/src/main/java/com/google/cloud/spanner/TransactionRunnerImpl.java

Lines 290 to 305 in 8d84b53

	public <T> T run(TransactionCallable<T> callable) {
	try (Scope s = tracer.withSpan(span)) {
	if (blockNestedTxn) {
	SessionImpl.hasPendingTransaction.set(Boolean.TRUE);
	}
	return runInternal(callable);
	} catch (RuntimeException e) {
	TraceUtil.endSpanWithFailure(span, e);
	throw e;
	} finally {
	// Remove threadLocal rather than set to FALSE to avoid a possible memory leak.
	// We also do this unconditionally in case a user has modified the flag when the transaction
	// was running.
	SessionImpl.hasPendingTransaction.remove();
	}
	}

Ad 2: The problem is not that stream is not closed properly, it is because it is closed twice. The problem is that the fact that the stream is closed is not recorded, so it is closed twice and the span is ended twice.

The reason that the span in 2 is closed twice, is that single use read contexts will automatically close the result set once all rows have been consumed. This happens here. The result set is then closed a second time when the try-with-resources block ends.

Closing a result set multiple times should not have any side effects. I think the solution in this case should be to set stream = null; here. That way, the span and the stream are not ended/closed more than once.

[mayurkale22]

Thanks for the suggestion, I made the change 10d5ffc. I think things look good now.