RedisClient::ProtocolError: Unknown sigil type: "\r"

[erikkessler1]

I have a pubsub connection that will will intermittently hit a RedisClient::ProtocolError:

RedisClient::ProtocolError: Unknown sigil type: "\r"

This seems to have started with just recently with version 0.22.0.

From patching the rescue RedisClient::RESP3::UnknownType in RedisClient::RubyConnection#read to print the current @io object and waiting for the error to happen, it looks like the @io object is the following state:

#<RedisClient::RubyConnection::BufferedIO:0x00007f0f842ed700
 @blocking_reads=false,
 @buffer=">3\r\n$7\r\nmessage\r\n$19\r\nnotify:entity_event\r\n$0\r\n\r\n",
 @chunk_size=4096,
 @offset=7,
 @read_timeout=5,
 @write_timeout=5>

I haven't been able to reproduce the error deterministically, unfortunately, but this is roughly what I've used to reproduce it in a production application:

pubsub.call(:subscribe, *channels)
p pubsub.next_event(1) while true
# wait for error

[byroot]

Thanks for the report, this is very likely caused by the recent changes in redis-client, I'll look into it tomorrow.

[casperisfine]

I forgot to ask if you could share the full backtrace.

[casperisfine]

I'd also need to know if you connect with a UNIX socket, regular TCP, or SSL.

[casperisfine]

@erikkessler1 I tried the repro by crafting specific responses but couldn't figure it out. I still made a tentative fix in #191, I'd appreciate if you could try it in your app and report back whether it fixes the issue.

[erikkessler1]

Unfortunately, it looks like it still happens with that fix. The connection is SSL and here is the backtrace:

gems/redis-client-0.22.0/lib/redis_client/ruby_connection/resp3.rb:141:in `parse'
gems/redis-client-0.22.0/lib/redis_client/ruby_connection/resp3.rb:50:in `load'
gems/redis-client-0.22.0/lib/redis_client/ruby_connection.rb:98:in `block in read'
gems/redis-client-0.22.0/lib/redis_client/ruby_connection/buffered_io.rb:114:in `with_timeout'
gems/redis-client-0.22.0/lib/redis_client/ruby_connection.rb:94:in `read`
gems/redis-client-0.22.0/lib/redis_client.rb:513:in `next_event'
<application-code>

This is the error with the patch and state of @io after the error:

#<RedisClient::RESP3::UnknownType: Unknown sigil type: "t">

#<RedisClient::RubyConnection::BufferedIO:0x00007f8a7e9abef0
 @blocking_reads=false,
 @buffer=">3\r\n$7\r\nmessage\r\n$25\r\nnotify:email_notification\r\n$0\r\n\r\n>3\r\n$7\r\nmessage\r\n$25\r\nnotify:email_notification\r\n$0\r\n\r\n",
 @chunk_size=4096,
 @io=#<OpenSSL::SSL::SSLSocket:0x00007f8a75405a68>,
 @offset=99,
 @read_timeout=5,
 @write_timeout=5>

[byroot]

Thank you. SSL socket changes a lot of things. Can you share your Ruby and openssl gem version, as well as OpenSSL::OPENSSL_LIBRARY_VERSION?

[casperisfine]

I think I got a repro using SSL:

/Users/byroot/src/github.com/redis-rb/redis-client/lib/redis_client/ruby_connection.rb:101:in `rescue in read': Unknown sigil type: "\n" (rediss://127.0.0.1:26379) (RedisClient::ProtocolError)
	from /Users/byroot/src/github.com/redis-rb/redis-client/lib/redis_client/ruby_connection.rb:94:in `read'
	from /Users/byroot/src/github.com/redis-rb/redis-client/lib/redis_client.rb:513:in `next_event'
	from test/sub.rb:29:in `block (2 levels) in <main>'
	from <internal:numeric>:237:in `times'
	from test/sub.rb:28:in `block in <main>'
	from <internal:kernel>:187:in `loop'
	from test/sub.rb:24:in `<main>'

[erikkessler1]

Here are my OpenSSL versions:

OpenSSL::VERSION
#=> "3.2.0"
OpenSSL::OPENSSL_LIBRARY_VERSION
#=> "OpenSSL 1.1.1w  11 Sep 2023"

[casperisfine]

Alright, I figured the root cause.

With a regular socket read_nonblock(10, buffer, exception: false) doesn't clear the buffer if there's nothing to read.

But with SSLSocket, the buffer is always cleared. that's what cause the issue.

[erikkessler1]

Awesome, great find! 🎉

[casperisfine]

@erikkessler1 could you try #193 ? I just want to make sure I fixed the same bug you are experiencing (we never know).

[erikkessler1]

After running things with that patch for 15 minutes I haven't seen the error again (usually would have seen it every few minutes), so I'd say that was the issue. Thank you for the quick fix!

[byroot]

Welcome.

I need to fix a few things on CI and will try to write a test for this (tricky) and I'll cut a release soon.

[casperisfine]

0.22.1 is out.

[casperisfine]

Upstream PR: ruby/openssl#739