redis-rb/redis-client

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

Closed this issue · 15 comments

erikkessler1 commented

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 commented

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

casperisfine commented

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

casperisfine commented

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

casperisfine commented

@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 commented

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 commented

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 commented

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 commented

Here are my OpenSSL versions:

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

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.

  • 🎉2
erikkessler1 commented

Awesome, great find! 🎉

casperisfine commented

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

erikkessler1 commented

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 commented

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.

  • 👍1
casperisfine commented

0.22.1 is out.

  • 👍2
  • ❤️1