util/tracing: panic in LogFields - runtime error: index out of range

[couchand]

https://sentry.io/cockroach-labs/cockroachdb/issues/552506410/

*log.safeError: stopper.go:175: runtime.errorString: runtime error: index out of range
  File "github.com/cockroachdb/cockroach/pkg/util/tracing/tracer_span.go", line 358, in LogFields
  File "github.com/cockroachdb/cockroach/pkg/util/log/trace.go", line 131, in eventInternal
  File "github.com/cockroachdb/cockroach/pkg/util/log/structured.go", line 153, in addStructured
  File "github.com/cockroachdb/cockroach/pkg/util/log/log.go", line 55, in logDepth
  File "github.com/cockroachdb/cockroach/pkg/util/log/log.go", line 98, in Warningf
...
(7 additional frame(s) were not displayed)

stopper.go:175: runtime.errorString: runtime error: index out of range

[knz]

Sentry issue: COCKROACHDB-G1

[andreimatei]

I've got no idea what's going on here. The line that panics is the Printf in

	if len(fields) == 1 && fields[0].Key() == "event" {
			s.netTr.LazyPrintf("%s", fields[0].Value())
		} 

I'm at a loss about how that can generate an index out of range, given that we just checked the length. The .Value() function also doesn't seem to be using any indexes.
And the caller is sp.LogFields(otlog.String("event", msg)), so there's no funny business there.

@RaduBerinde , do you happen to see anything here?

[tbg]

Use after finish?

On Wed, Jun 13, 2018, 7:37 PM Andrei Matei ***@***.***> wrote: I've got no idea what's going on here. The line that panics is the Printf in if len(fields) == 1 && fields[0].Key() == "event" { s.netTr.LazyPrintf("%s", fields[0].Value()) } I'm at a loss about how that can generate an index out of range, given that we just checked the length. The .Value() function also doesn't seem to be using any indexes. And the caller is sp.LogFields(otlog.String("event", msg)), so there's no funny business there. @RaduBerinde <https://github.com/RaduBerinde> , do you happen to see anything here? — You are receiving this because you are subscribed to this thread. Reply to this email directly, view it on GitHub <#25389 (comment)>, or mute the thread <https://github.com/notifications/unsubscribe-auth/AE135CNoOGg1TzsHB_8g-7bi6XuegAjdks5t8U3egaJpZM4T44FB> .

--

…

-- Tobias

[andreimatei]

"Use after finish" of what exactly?

[RaduBerinde]

My guess is that for whatever reason we're not seeing the top stack frames. The error is probably coming from inside net/trace where it is documented that crashes in that code are likely the result of use-after-free. See #26500 for another example of the same panic happening inside net/trace.

[andreimatei]

Thanks. Ah, stupid sentry was hiding entries from the stack trace that was pasted here; interesting both at the top and the bottom. With this I can look again.

  File "github.com/cockroachdb/cockroach/vendor/golang.org/x/net/trace/trace.go", line 772, in addEvent
  File "github.com/cockroachdb/cockroach/vendor/golang.org/x/net/trace/trace.go", line 801, in LazyPrintf
  File "github.com/cockroachdb/cockroach/pkg/util/tracing/tracer_span.go", line 358, in LogFields
  File "github.com/cockroachdb/cockroach/pkg/util/log/trace.go", line 131, in eventInternal
  File "github.com/cockroachdb/cockroach/pkg/util/log/structured.go", line 153, in addStructured
  File "github.com/cockroachdb/cockroach/pkg/util/log/log.go", line 55, in logDepth
  File "github.com/cockroachdb/cockroach/pkg/util/log/log.go", line 98, in Warningf
  File "github.com/cockroachdb/cockroach/pkg/server/server.go", line 1462, in 2
  File "github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go", line 192, in func1

[solongordon]

Sentry issue: COCKROACHDB-H2

[andreimatei]

Two of the 3 sentry reports here did not belong and have not been fixed. Moved them to the new #26715.