panic: protocol bug, message handled out of order (valkey-go client)

[dineshd30]

Observed a panic when using the valkey-go client:

panic: protocol bug, message handled out of order
goroutine 12268 [running]:
github.com/valkey-io/valkey-go.(*pipe)._backgroundRead(0xc00029c000)
/go/pkg/mod/github.com/valkey-io/valkey-go@v1.0.64/pipe.go:575 +0xd18
github.com/valkey-io/valkey-go.(*pipe)._background(0xc00029c000)
/go/pkg/mod/github.com/valkey-io/valkey-go@v1.0.64/pipe.go:378 +0xa6
created by github.com/valkey-io/valkey-go.(*pipe).background in goroutine 12246
/go/pkg/mod/github.com/valkey-io/valkey-go@v1.0.64/pipe.go:346 +0x7c

Lambda runtime log:

{
  "time": "2025-09-17T17:27:53.054Z",
  "type": "platform.report",
  "record":
    {
      "requestId": "2a68caef-902f-4f7d-bfc1-2f656b7c9a2f",
      "metrics":
        {
          "durationMs": 7.925,
          "billedDurationMs": 8,
          "memorySizeMB": 128,
          "maxMemoryUsedMB": 46,
        },
      "status": "error",
      "errorType": "Runtime.ExitError",
    },
}

Environment
Runtime: AWS Lambda Go v1.25
Valkey Server version: v8.1
valkey-go package version: v1.0.64
Go version: v1.25
OS/Platform: x86_64

[rueian]

Is it easy to reproduce? I tried a bit with AWS Lambda Go and Valkey 8.1 elasticache cluster, but I couldn't reproduce the issue. Would you be willing to help with a custom build of valkey-io to identify the protocol bug?

A custom build would be logging out commands and responses like this:

diff --git a/pipe.go b/pipe.go
index 307705b..3f1365a 100644
--- a/pipe.go
+++ b/pipe.go
@@ -7,6 +7,7 @@ import (
 	"errors"
 	"fmt"
 	"io"
+	"log"
 	"net"
 	"os"
 	"regexp"
@@ -456,6 +457,7 @@ func (p *pipe) _backgroundWrite() (err error) {
 			}
 			if p.w.Buffered() != 0 {
 				if err = p.w.Flush(); err != nil {
+					log.Println("background write err", err)
 					break
 				}
 			}
@@ -478,6 +480,7 @@ func (p *pipe) _backgroundWrite() (err error) {
 		}
 		for _, cmd := range multi {
 			err = writeCmd(p.w, cmd.Commands())
+			log.Println("background write", strings.Join(cmd.Commands(), " "), err)
 			if cmd.IsUnsub() { // See https://github.com/redis/rueidis/pull/691
 				err = writeCmd(p.w, cmds.PingCmd.Commands())
 			}
@@ -522,6 +525,7 @@ func (p *pipe) _backgroundRead() (err error) {
 		if msg, err = readNextMessage(p.r); err != nil {
 			return
 		}
+		log.Println("background read", msg.String(), err)
 		if msg.typ == '>' || (r2ps && len(msg.values()) != 0 && msg.values()[0].string() != "pong") {
 			if prply, unsub = p.handlePush(msg.values()); !prply {
 				continue
@@ -896,6 +900,7 @@ func (p *pipe) Version() int {
 }
 
 func (p *pipe) AZ() string {
+	log.Println("getting AZ info", p.info)
 	infoAvailabilityZone := p.info["availability_zone"]
 	return infoAvailabilityZone.string()
 }
@@ -1272,8 +1277,10 @@ func (p *pipe) syncDo(dl time.Time, dlOk bool, cmd Completed) (resp RedisResult)
 
 	var msg RedisMessage
 	err := flushCmd(p.w, cmd.Commands())
+	log.Println("syncDo write", strings.Join(cmd.Commands(), " "), err)
 	if err == nil {
 		msg, err = syncRead(p.r)
+		log.Println("syncDo read", msg.String(), err)
 	}
 	if err != nil {
 		if dlOk && errors.Is(err, os.ErrDeadlineExceeded) {
@@ -1318,14 +1325,17 @@ process:
 	var msg RedisMessage
 	for _, cmd := range multi {
 		_ = writeCmd(p.w, cmd.Commands())
+		log.Println("syncDoMulti write", strings.Join(cmd.Commands(), " "))
 	}
 	if err = p.w.Flush(); err != nil {
+		log.Println("syncDoMulti write err", err)
 		goto abort
 	}
 	for i := 0; i < len(resp); i++ {
 		if msg, err = syncRead(p.r); err != nil {
 			goto abort
 		}
+		log.Println("syncDoMulti read", msg.String(), err)
 		resp[i] = newResult(msg, err)
 	}
 	return
@@ -1347,6 +1357,7 @@ next:
 		return m, err
 	}
 	if m.typ == '>' {
+		log.Println("syncRead ignore >", m)
 		goto next
 	}
 	return m, nil

[dineshd30]

Its happening intermittently, Its definitely not easy to reproduce.

[dineshd30]

What would be the impact of DisableAutoPipelining=true? Can it fix this one?

[dineshd30]

Is it easy to reproduce? I tried a bit with AWS Lambda Go and Valkey 8.1 elasticache cluster, but I couldn't reproduce the issue. Would you be willing to help with a custom build of valkey-io to identify the protocol bug?

A custom build would be logging out commands and responses like this:

diff --git a/pipe.go b/pipe.go
index 307705b..3f1365a 100644
--- a/pipe.go
+++ b/pipe.go
@@ -7,6 +7,7 @@ import (
"errors"
"fmt"
"io"

• "log"
  "net"
  "os"
  "regexp"
  @@ -456,6 +457,7 @@ func (p *pipe) _backgroundWrite() (err error) {
  }
  if p.w.Buffered() != 0 {
  if err = p.w.Flush(); err != nil {

• 			log.Println("background write err", err)
  			break
  		}
  	}
  

@@ -478,6 +480,7 @@ func (p *pipe) _backgroundWrite() (err error) {
}
for _, cmd := range multi {
err = writeCmd(p.w, cmd.Commands())

• 	log.Println("background write", strings.Join(cmd.Commands(), " "), err)
  	if cmd.IsUnsub() { // See https://github.com/redis/rueidis/pull/691
  		err = writeCmd(p.w, cmds.PingCmd.Commands())
  	}
  

@@ -522,6 +525,7 @@ func (p *pipe) _backgroundRead() (err error) {
if msg, err = readNextMessage(p.r); err != nil {
return
}

• log.Println("background read", msg.String(), err)
  if msg.typ == '>' || (r2ps && len(msg.values()) != 0 && msg.values()[0].string() != "pong") {
  	if prply, unsub = p.handlePush(msg.values()); !prply {
  		continue
  

@@ -896,6 +900,7 @@ func (p *pipe) Version() int {
}

func (p *pipe) AZ() string {

• log.Println("getting AZ info", p.info)
  infoAvailabilityZone := p.info["availability_zone"]
  return infoAvailabilityZone.string()
  }
  @@ -1272,8 +1277,10 @@ func (p *pipe) syncDo(dl time.Time, dlOk bool, cmd Completed) (resp RedisResult)

  var msg RedisMessage
  err := flushCmd(p.w, cmd.Commands())

• log.Println("syncDo write", strings.Join(cmd.Commands(), " "), err)
  if err == nil {
  msg, err = syncRead(p.r)

• log.Println("syncDo read", msg.String(), err)
  

  }
  if err != nil {
  if dlOk && errors.Is(err, os.ErrDeadlineExceeded) {
  @@ -1318,14 +1325,17 @@ process:
  var msg RedisMessage
  for _, cmd := range multi {
  _ = writeCmd(p.w, cmd.Commands())

• log.Println("syncDoMulti write", strings.Join(cmd.Commands(), " "))
  

  }
  if err = p.w.Flush(); err != nil {

• log.Println("syncDoMulti write err", err)
  goto abort
  

  }
  for i := 0; i < len(resp); i++ {
  if msg, err = syncRead(p.r); err != nil {
  goto abort
  }

• log.Println("syncDoMulti read", msg.String(), err)
  resp[i] = newResult(msg, err)
  

  }
  return
  @@ -1347,6 +1357,7 @@ next:
  return m, err
  }
  if m.typ == '>' {

• log.Println("syncRead ignore >", m)
  goto next
  

  }
  return m, nil

Sorry, forgot to mention that I am using serverless elasticache for valkey engine 8.1

[rueian]

Unfortunately, I couldn't reproduce it with serverless elasticache either. This is the lambda I was trying:

package main

import (
	"context"
	"crypto/tls"
	"log"
	"os"
	"sync"

	"github.com/aws/aws-lambda-go/lambda"
	"github.com/valkey-io/valkey-go"
)

var client valkey.Client

func init() {
	var err error
	client, err = valkey.NewClient(valkey.ClientOption{
		InitAddress:           []string{os.Getenv("REDIS_ADDRESS")},
		DisableCache:          true,
		TLSConfig:             &tls.Config{},
		EnableReplicaAZInfo:   true,
	})
	if err != nil {
		panic(err)
	}
}

func hello(ctx context.Context) (int64, error) {
	var wg sync.WaitGroup
	for i := 0; i < 3; i++ {
		wg.Add(1)
		go func() {
			client.Do(ctx, client.B().Get().Key("counter").Build())
			wg.Done()
		}()
	}
	ret, err := client.Do(ctx, client.B().Incr().Key("counter").Build()).AsInt64()
	wg.Wait()
	return ret, err
}

func main() {
	lambda.Start(hello)
}

Is there any hint for reproducing the issue? Like, what does your workload look like?

[dineshd30]

This issue occurs intermittently and does not impact our business functionality, but it does result in Lambda system errors.

During our last test, where the Lambda was run continuously for 3 hours, we observed this panic happening twice. As shown in the graphs below, this Lambda handles a high workload.

I also disabled auto pipelining using the following configuration, but it had no effect:

	clientOptions := valkey.ClientOption{
		InitAddress:           []string{address},
		DisableCache:          true,
		DisableAutoPipelining: true,
	}

For now, we are relying on panic recovery to prevent system errors until hopefully the underlying issue is resolved.

[rueian]

Hi @dineshd30, DisableAutoPipelining: true should reduce the problem surface and help us find the root cause. Please keep it. Do you use .ToPipe() when constructing a command? Or do you use .Receive() for receiving pubsub?

Could you also add a ClientOption.Dialer.KeepAlive=-1 setting, which will disable the background PING goroutines, to see if the problem persists?

[dineshd30]

@rueian We are not using .ToPine() in the command builder. Instead, we call .Do(ctx, builderCommand). Our use case here is exclusively for caching key values.

I will give ClientOption.Dialer.KeepAlive = -1a try. We currently execute a PING command immediately after creating the Valkey client (but before actually using it) to ensure the connection to the cache is established properly. If I disable keep-alive, will this affect the PING command executed during the Lambda’s init phase?

Another concern is that disabling keep alive may require opening more connections, since we will no longer be reusing existing connections from the pool.

[rueian]

If I disable keep-alive, will this affect the PING command executed during the Lambda’s init phase?

It won’t affect that, and actually, your initial PING is not necessary since NewClient essentially does that for you.

Another concern is that disabling keep alive may require opening more connections, since we will no longer be reusing existing connections from the pool.

Don't worry. Disabling the option won’t stop reusing connections in the pool.

[rueian]

Hi @dineshd30, did ClientOption.Dialer.KeepAlive=-1 work?

[dineshd30]

Hi @dineshd30, did ClientOption.Dialer.KeepAlive=-1 work?

Hi @rueian, it’s working, no protocol bug panics so far.

Quick check: is it safe to set ClientOption.Dialer.KeepAlive = -1 in prod? My understanding is that a negative value disables TCP keepalives entirely. Previously we had a positive interval, so the client sent probes after that period; with -1, it wouldn’t probe at all. Is that correct? Is there any downside of not probing for long time?

[rueian]

Hi @dineshd30,

it wouldn’t probe at all. Is that correct?

That's correct. The only downside of this is that you have a higher chance of finding your connection being dropped after you use it. While probing the connection periodically can lower the chance.