Invalid memory address or nil pointer dereference

[joostlawerman]

What platforms are affected?

linux

What architectures are affected?

amd64

What SpiceDB version are you using?

v1.45.4

Steps to Reproduce

Not sure, we are running spicedb in a docker container (3 instances per environment). Randomly one of the 3 instances crashes, one per +- two weeks. It is happening for some months now.

Expected Result

No unexpected crashes/ panics, should be running stable.

Actual Result

We get the following log, which seems to be a memory corruption of some sort.

Sep 24 05:54:51 panic: runtime error: invalid memory address or nil pointer dereference
Sep 24 05:54:51 [signal SIGSEGV: segmentation violation code=0x1 addr=0x0 pc=0x48b5e5]
Sep 24 05:54:51 goroutine 28 [running]:
google.golang.org/protobuf/encoding/protowire.AppendString(...)
    google.golang.org/protobuf/encoding/protowire/wire.go:479
google.golang.org/protobuf/internal/impl.appendStringValidateUTF8(...)
    google.golang.org/protobuf/internal/impl/codec_gen.go:5045 +0x91
google.golang.org/protobuf/internal/impl.(*MessageInfo).initOneofFieldCoders.func4(...)
    google.golang.org/protobuf/internal/impl/codec_field.go:96 +0x5d
google.golang.org/protobuf/internal/impl.appendMessageInfo(...)
    google.golang.org/protobuf/internal/impl/encode.go:215 +0x403
google.golang.org/protobuf/internal/impl.(*MessageInfo).marshalAppendPointer(...)
    google.golang.org/protobuf/internal/impl/codec_field.go:168 +0xa5
google.golang.org/protobuf/proto.Marshal(...)
    google.golang.org/protobuf/proto/encode.go:111 +0x50
go.opentelemetry.io/otel/exporters/otlp/otlptrace/otlptracehttp.(*client).UploadTraces(...)
    go.opentelemetry.io/otel/exporters/otlp/otlptrace/otlptracehttp/client.go:134 +0xb3
go.opentelemetry.io/otel/exporters/otlp/otlptrace.(*Exporter).ExportSpans(...)
    go.opentelemetry.io/otel/exporters/otlp/otlptrace/exporter.go:36 +0x63
go.opentelemetry.io/otel/sdk/trace.(*batchSpanProcessor).exportSpans(...)
    go.opentelemetry.io/otel/sdk/trace/batch_span_processor.go:365 +0x437
go.opentelemetry.io/otel/sdk/trace.(*batchSpanProcessor).processQueue(...)
    go.opentelemetry.io/otel/sdk/trace/batch_span_processor.go:394 +0x38c
go.opentelemetry.io/otel/sdk/trace.NewBatchSpanProcessor.func2()
    go.opentelemetry.io/otel/sdk/trace/batch_span_processor.go:145 +0x51
created by go.opentelemetry.io/otel/sdk/trace.NewBatchSpanProcessor in goroutine 1
    go.opentelemetry.io/otel/sdk/trace/batch_span_processor.go:143 +0x565
Sep 24 05:54:51 spicedb serve failed

Found the following issues that might be related:

• build: build failure on gotip-darwin-amd64-longtest golang/go#73024
• [Bug] Go agent data race and random crashes during concurrent validation. apache/skywalking#13363
• Service crash caused by encoding golang/protobuf#1627

[tstirrat15]

We also got a report of this on Discord:

https://cdn.discordapp.com/attachments/844600078948630559/1421065745130979339/stitched_log.png?ex=68d7ae1b&is=68d65c9b&hm=b385a3535ac534c1578d0995b919607c4ccd1b3e494bd3bf5c8a02059ffbba8d&

Things we know so far:

• This happens on both v1.45.3 and v1.45.4 (which included an otel library version bump)
  and with both oteltracehttp and oteltracegrpc
• It's also happening on both the vtproto and non-vtproto marshalling codepaths, and both involve AppendString
• One codepath includes a SpiceDB proto object; the other does not appear to.

Some things that might be happening:

• There's a bug in protobuf-go where nilable input isn't being checked as such
• There's a bug in the otel library where the marshalling logic defined for one of its protos is incorrect
• There's a bug in our usage of the otel library where we're either failing to set a field that's implicitly required or passing a nil value where we shouldn't

My current guess is that it's somewhere in the otel library; that's made slightly less likely by the fact that we had a version bump between 1.45.3 and 1.45.4 and nothing changed (though the relevant code may have just been stable across those versions).

[tstirrat15]

This was also reported back in July: https://discord.com/channels/844600078504951838/1392131382108749876/1392132151633379390

That was SpiceDB v1.44.0 and we were on v1.27.0 of the otel trace library on that version.

This issue seems to be pretty deep: golang/protobuf#1319 (comment)

[joostlawerman]

Somewhere in June/ July we have seen the first crashes, so yes ~ v1.44.0 seems plausible. Looked at some of the related issues, but they lack any way of consistently reproducing which is frustrating.

[miparnisari]

@joostlawerman if we had the schema and the call that was attempted prior to this panic, we could narrow this down more easily. Could you run your SpiceDB server with --grpc-log-requests-enabled?

[miparnisari]

@joostlawerman if you could also share your server settings/flags, that will be helpful too. 😄

[tstirrat15]

We got a report from a user that even with OTEL flags disabled, they're still experiencing crashes. They also pointed to this line in a stack trace they pulled:

https://github.com/authzed/spicedb/blob/v1.45.1/internal/services/v1/bulkcheck.go#L183

[joostlawerman]

I can add some details next week (after 27 October) currently not able to due to a holiday.

[miparnisari]

We've investigated this report and while we haven't found the exact root cause, we have found that one panic is triggered when doing multiple concurrent calls of BulkCheck API, when the with_tracing flag is turned on.

For now, and until we find the actual root cause, we recommend not setting this flag, neither in BulkCheck nor Check APIs.

@joostlawerman i haven't been able to reproduce the panic log that you shared, but could you try the recommendation above and let us know if you still see the panic?

[joostlawerman]

I have seen this error latest this morning, even more frequently the last 2 weeks, consistently every 3 days on all 3 running instances. Running currently on version: 1.46.0

So we use spicedb without any direct flags. We run it in the authzed/spicedb docker container with an custom script executing spicedb serve.

Here are the spicedb related environment variables:

SPICEDB_DATASTORE_ENGINE: mysql
SPICEDB_LOG_FORMAT: json
SPICEDB_LOG_LEVEL: info
SPICEDB_OTEL_PROVIDER: otlphttp
SPICEDB_OTEL_SAMPLE_RATIO: 1.0
SPICEDB_OTEL_TRACE_PROPAGATOR: w3c

We use the BulkCheck API for almost all our checks. I we also have the with_tracing flag but it is always defined as false. I will remove the flag entirely and check if it does anything.