ERR Protocol error: too big inline request (Redis::CommandError)

[Jakanapes]

Redis 5.3.3
Ruby 3.1.3
Rails 7.0.4.2
redis gem 5.0.6
resque gem 2.4.0

Just upgraded the redis/resque gems and their dependencies and am getting this intermittent error ERROR -- : ERR Protocol error: too big inline request (Redis::CommandError)

The backtrace is not super helpful

E, [2023-03-14T14:41:13.543261 #44489] ERROR -- : ERR Protocol error: too big inline request (Redis::CommandError)
.....shared/bundle/ruby/3.1.0/gems/redis-5.0.6/lib/redis/subscribe.rb:52:in `subscription'
.....shared/bundle/ruby/3.1.0/gems/redis-5.0.6/lib/redis/subscribe.rb:17:in `subscribe'
.....shared/bundle/ruby/3.1.0/gems/redis-5.0.6/lib/redis.rb:188:in `_subscription'
.....shared/bundle/ruby/3.1.0/gems/redis-5.0.6/lib/redis/commands/pubsub.rb:17:in `subscribe'
.....shared/bundle/ruby/3.1.0/gems/actioncable-7.0.4.2/lib/action_cable/subscription_adapter/redis.rb:83:in `block in listen'
.....shared/bundle/ruby/3.1.0/gems/redis-client-0.12.1/lib/redis_client.rb:645:in `ensure_connected'
.....shared/bundle/ruby/3.1.0/gems/redis-5.0.6/lib/redis/client.rb:104:in `disable_reconnection'
.....shared/bundle/ruby/3.1.0/gems/redis-5.0.6/lib/redis.rb:79:in `without_reconnect'
.....shared/bundle/ruby/3.1.0/gems/actioncable-7.0.4.2/lib/action_cable/subscription_adapter/redis.rb:80:in `listen'
.....shared/bundle/ruby/3.1.0/gems/actioncable-7.0.4.2/lib/action_cable/subscription_adapter/redis.rb:154:in `block in ensure_listener_running'

seems to indicate that action_cable is involved, but we use it a lot and having trouble tracking it down. I can't reproduce it and it appears on calls that don't trigger any actioncable actions.

The error is generated in redis, which has not changed, but looking at the gem difference, the error being raised in subscribe.rb is new. Am I looking at something that was happening all along, but was being swallowed by earlier versions of the redis gem?

[byroot]

So this error is thrown by the server here: https://github.com/redis/redis/blob/2dd5c3a180a9892c339b66f76cc203f8b0f6fe5a/src/networking.c#L2112-L2115

And that constant is defined as 64kB:

#define PROTO_INLINE_MAX_SIZE   (1024*64)

So this seem to suggest that somehow the client sends more than 64kB of data without a single newline, that is very fishy.

But somehow that error rings a bell, it feels like I researched this before.

[Jakanapes]

What would be sending inline, though? Looking at the ActionCable source, it's calling publish in Redis::Commands::Pubsub, I believe. We're trying to eliminate possible causes so we're tracking any AC broadcast messages over 64k, but they don't correspond to the redis protocol errors because they bubble up in a separate thread from the AC listener. Neither AC nor Redis versions have changed, just the redis gem getting bumped up from 4.1.0

[byroot]

What would be sending inline, though?

Yeah, I don't know, it could be an overly long channel name on something like that. It will be hard to debug without a repro.

I'm not sure what you setup look like, but if you have that flexibility I'd try to add some logging in there

redis-rb/lib/redis/subscribe.rb

Line 49 in e4f5299

call_v([start, *channels])

to see what can of command is emitted and whether you can figure out a smaller repro?

[Jakanapes]

So looking at the backtrace, the line in actioncable that ends up at call_v is here

https://github.com/rails/rails/blob/7-0-stable/actioncable/lib/action_cable/subscription_adapter/redis.rb#L92

and it's explicitly sending _action_cable_internal, which is sent all the way through to call_v in the *channels params. Am I reading the code correctly there that the events pulled from client.next_event are a direct result of the call_v command?

I can try to add some logging there, but if that's the case, I don't see how it could be anything other than the hardcoded channel, let along a 64k long channel name

[byroot]

Hum, you're right.

[Jakanapes]

actioncable sets the message callback of the Subscription class to

                on.message do |chan, message|
                  broadcast(chan, message)
                end

If I'm reading it right, this block under call_v

      while event = @client.next_event(timeout)
        if event.is_a?(::RedisClient::CommandError)
          raise Client::ERROR_MAPPING.fetch(event.class), event.message
        end

        type, *rest = event
        if callback = sub.callbacks[type]
          callback.call(*rest)
        end
        break if type == stop && rest.last == 0
      end

is blocking while loop in its own thread? So it's likely that it subscribes to the channel, then waits for incoming messages.
Eventually, it gets a message, calls the callback which attempts to broadcast it on the channel, and that is what triggers to the "too big" error, which it picks up on the next loop?

If that's the case, though, we've attempted sending large messages through to trigger the exception with no luck

[byroot]

Note that it could be a total red herring. When googling for that error, you can see lots of these being resolved in various ways on the server side.

Given that you say the issue started when you upgraded, it makes sense to assume the client doesn't something wrong, but that wrong thing may not be to send a packet too big.

just the redis gem getting bumped up from 4.1.0

Have you tried the latest 4.x? Mostly to try to pinpoint when the issue might have been introduced.

Another good thing to try would be to enable the hiredis bindings, see if that changes anything. That could help track the source of the issue.

[Jakanapes]

That is a concern, that since the exception being raised is new in this version, that it's something that could have been happening all along and was either being swallowed or surfaced as another error that we haven't noticed is no longer happening.

[1] pry(main)> Redis::Connection.drivers
=> [RedisClient::HiredisConnection]

we're already using the hiredis-client gem.

Is there a way to see if the AC redis instance is using inline? I thought resp was what was always used?

[byroot]

we're already using the hiredis-client gem.

Then the opposite, try to disable it. It's really just a basic bisection to try to narrow down where the bug could be.

Is there a way to see if the AC redis instance is using inline?

I'm not sure what you are referring to by inline.

[byroot]

Oh wait, Hum, another thing, is there SSL into the mix? I cant remember nor find where I saw that too big inline request before, but I wonder if it wasn't a client trying to connect to an unsecured server using SSL, and the SSL handshake paquets were tripping the server.

Just a wild guess though.

[Jakanapes]

It does look like the gem uses RESP2

      def config(**kwargs)
        super(protocol: 2, **kwargs)
      end

The error itself says "inline request" and the comments on the method in the redis source say
"Like processMultibulkBuffer(), but for the inline protocol instead of RESP"
https://github.com/redis/redis/blob/2dd5c3a180a9892c339b66f76cc203f8b0f6fe5a/src/networking.c#L2094-L2117

however, it seems like every client in existence uses resp.

I'll have to check on the SSL issue, but if that was the case, I'd expect it to happen on every message, no?

[byroot]

Oh wait, this is an intermittent issue?

[byroot]

however, it seems like every client in existence uses resp.

Yeah, I have no idea what "inline protocol" is supposed to be never heard of it, and I can confirm that redis-rb uses RESP2.

Is there a proxy or something between the client and Redis? Or anything else that isn't just a raw standalone redis-server?

[Jakanapes]

Oh wait, this is an intermittent issue?

Oh yes, intermittent and extremely elusive. We've had 0 luck in recreating it on purpose. We see the error 6-8 times a day among thousands and thousands of requests. No other issues we can tell on straight redis calls for caching and resque use, just something with action cable.

We use consul to manage the url, but ATM we only have a single redis server in production.

[byroot]

Hum, that is extremely intriguing. I'll try to find some time to review if it's possible that on 4.x that error was swallowed or retried. That could explain it, e.g. a pre-existing issue with your server, and now we're just reporting it.