Connect to localhost fails on 0.35

[christopherraa]

After the version bump and update of hiredis in 0.35 there is an issue where Redis::Fast is unable to connect to localhost:6379. On the other hand 127.0.0.1:6379 works without fail. This behaviour isn't seen on all hosts though. Example I used to reproduce this on one of the problematic hosts:

# Works fine, outputs nothing
perl -e 'use Redis::Fast; Redis::Fast->new(server => "127.0.0.1:6379")->keys("*");'

# Fails to connect, spits out error
perl -e 'use Redis::Fast; Redis::Fast->new(server => "localhost:6379")->keys("*");'
Could not connect to Redis server at localhost:6379 at [TRUNCATED].../local/lib/perl5/x86_64-linux/Redis/Fast.pm line 246.

On hosts where this is a problem version 0.34 works without failing, but version 0.35 fails on connect to localhost every time.

I don't quite know how to proceed in debugging this. What I have checked is that the system can resolve localhost just fine, and redis-cli also connects to the server just fine on both localhost and 127.0.0.1.

[shogo82148]

set the REDIS_DEBUG environment value, and then please show me the whole of log.

[christopherraa]

Connection string that does not work:

$ REDIS_DEBUG=1 perl -e 'use Redis::Fast; Redis::Fast->new(server => "localhost:6379")->keys("*");'

[28726][1711][lib/Redis/Fast.xs:373:Redis__Fast_connect]: start
[28726][1711][lib/Redis/Fast.xs:292:__build_sock]: start
[28726][1711][lib/Redis/Fast.xs:119:AddWrite]: flags = 2
[28726][1711][lib/Redis/Fast.xs:199:wait_for_event]: set WRITE, write_timeout = -1.000000
[28726][1711][lib/Redis/Fast.xs:210:wait_for_event]: select start, timeout is -1.000000
[28726][1711][lib/Redis/Fast.xs:217:wait_for_event]: poll returns 1
[28726][1711][lib/Redis/Fast.xs:237:wait_for_event]: ready to write
[28726][1711][lib/Redis/Fast.xs:269:Redis__Fast_connect_cb]: connected status = -1
[28726][1711][lib/Redis/Fast.xs:244:wait_for_event]: exception: POLLERR
Could not connect to Redis server at localhost:6379 at [TRUNCATED].../local/lib/perl5/x86_64-linux/Redis/Fast.pm line 246.
[28726][1711][lib/Redis/Fast.xs:1162:XS_Redis__Fast_DESTROY]: start
[28726][1711][lib/Redis/Fast.xs:1171:XS_Redis__Fast_DESTROY]: free hostname
[28726][1711][lib/Redis/Fast.xs:1183:XS_Redis__Fast_DESTROY]: free error
[28726][1711][lib/Redis/Fast.xs:1189:XS_Redis__Fast_DESTROY]: free on_connect
[28726][1711][lib/Redis/Fast.xs:1201:XS_Redis__Fast_DESTROY]: free data
[28726][1711][lib/Redis/Fast.xs:1212:XS_Redis__Fast_DESTROY]: finish

Connection string that works:

$ REDIS_DEBUG=1 perl -e 'use Redis::Fast; Redis::Fast->new(server => "127.0.0.1:6379")->keys("*");'

[495][1711][lib/Redis/Fast.xs:373:Redis__Fast_connect]: start
[495][1711][lib/Redis/Fast.xs:292:__build_sock]: start
[495][1711][lib/Redis/Fast.xs:119:AddWrite]: flags = 2
[495][1711][lib/Redis/Fast.xs:199:wait_for_event]: set WRITE, write_timeout = -1.000000
[495][1711][lib/Redis/Fast.xs:210:wait_for_event]: select start, timeout is -1.000000
[495][1711][lib/Redis/Fast.xs:217:wait_for_event]: poll returns 1
[495][1711][lib/Redis/Fast.xs:237:wait_for_event]: ready to write
[495][1711][lib/Redis/Fast.xs:269:Redis__Fast_connect_cb]: connected status = 0
[495][1711][lib/Redis/Fast.xs:126:DelWrite]: flags = 0
[495][1711][lib/Redis/Fast.xs:105:AddRead]: flags = 1
[495][1711][lib/Redis/Fast.xs:248:wait_for_event]: finish
[495][1711][lib/Redis/Fast.xs:365:__build_sock]: finish
[495][1711][lib/Redis/Fast.xs:423:Redis__Fast_reconnect]: start
[495][1711][lib/Redis/Fast.xs:431:Redis__Fast_reconnect]: finish
[495][1711][lib/Redis/Fast.xs:760:Redis__Fast_run_cmd]: start KEYS
[495][1711][lib/Redis/Fast.xs:762:Redis__Fast_run_cmd]: pid check: previous pid is 495, now 495
[495][1711][lib/Redis/Fast.xs:807:Redis__Fast_run_cmd]: send command in sync mode
[495][1711][lib/Redis/Fast.xs:119:AddWrite]: flags = 3
[495][1711][lib/Redis/Fast.xs:812:Redis__Fast_run_cmd]: waiting response
[495][1711][lib/Redis/Fast.xs:254:_wait_all_responses]: start
[495][1711][lib/Redis/Fast.xs:177:wait_for_event]: set READ and WRITE, compare read_timeout = -1.000000 and write_timeout = -1.000000
[495][1711][lib/Redis/Fast.xs:210:wait_for_event]: select start, timeout is -1.000000
[495][1711][lib/Redis/Fast.xs:217:wait_for_event]: poll returns 1
[495][1711][lib/Redis/Fast.xs:237:wait_for_event]: ready to write
[495][1711][lib/Redis/Fast.xs:126:DelWrite]: flags = 1
[495][1711][lib/Redis/Fast.xs:105:AddRead]: flags = 1
[495][1711][lib/Redis/Fast.xs:248:wait_for_event]: finish
[495][1711][lib/Redis/Fast.xs:195:wait_for_event]: set READ, read_timeout = -1.000000
[495][1711][lib/Redis/Fast.xs:210:wait_for_event]: select start, timeout is -1.000000
[495][1711][lib/Redis/Fast.xs:217:wait_for_event]: poll returns 1
[495][1711][lib/Redis/Fast.xs:233:wait_for_event]: ready to read
[495][1711][lib/Redis/Fast.xs:105:AddRead]: flags = 1
[495][1711][lib/Redis/Fast.xs:545:Redis__Fast_sync_reply_cb]: 0x5647448f4c80
[495][1711][lib/Redis/Fast.xs:562:Redis__Fast_sync_reply_cb]: finish
[495][1711][lib/Redis/Fast.xs:248:wait_for_event]: finish
[495][1711][lib/Redis/Fast.xs:262:_wait_all_responses]: finish
[495][1711][lib/Redis/Fast.xs:828:Redis__Fast_run_cmd]: finish KEYS
[495][1711][lib/Redis/Fast.xs:1162:XS_Redis__Fast_DESTROY]: start
[495][1711][lib/Redis/Fast.xs:1164:XS_Redis__Fast_DESTROY]: free ac
[495][1711][lib/Redis/Fast.xs:282:Redis__Fast_disconnect_cb]: disconnected status = 0
[495][1711][lib/Redis/Fast.xs:254:_wait_all_responses]: start
[495][1711][lib/Redis/Fast.xs:262:_wait_all_responses]: finish
[495][1711][lib/Redis/Fast.xs:1171:XS_Redis__Fast_DESTROY]: free hostname
[495][1711][lib/Redis/Fast.xs:1183:XS_Redis__Fast_DESTROY]: free error
[495][1711][lib/Redis/Fast.xs:1189:XS_Redis__Fast_DESTROY]: free on_connect
[495][1711][lib/Redis/Fast.xs:1201:XS_Redis__Fast_DESTROY]: free data
[495][1711][lib/Redis/Fast.xs:1212:XS_Redis__Fast_DESTROY]: finish

[shogo82148]

Hmm, I cannot reproduce it. Please more information, OS, the version of Perl, etc.

[christopherraa]

Ok, so I figured it out by running everything through strace and wading through the output. There I discovered that localhost was resolved to ::1 when running through Perl, but 127.0.0.1 when running other system applications such as ping etc. The redis server was only listening on 127.0.0.1. Once I configured the redis server to listen on ::1 as well both forms of connection string worked (127.0.0.1 and localhost).

Perhaps it would be useful if the output from the module listed what it actually tried to connect to (ie. what was resolved)? Something like the following output would have me see the issue immediately:

Could not connect to Redis server at localhost:6379 (::1:6379) at [TRUNCATED].../local/lib/perl5/x86_64-linux/Redis/Fast.pm line 246.

or

Could not connect to Redis server at ::1:6379 for connection string 'localhost:6379' at [TRUNCATED].../local/lib/perl5/x86_64-linux/Redis/Fast.pm line 246.

What do you think? That additional bit of information would definitly have saved me (and you) quite some time debugging.

[shogo82148]

It needs to apply some patches to hiredis. I want not to do that.

https://github.com/redis/hiredis/pull/1096 would be related, but we do not know why.

[christopherraa]

Thank you for taking the time to followin up on this, and for linking to the other issue. I'll go ahead and close this one now.

[oschwald]

We also ran into this when upgrading to 0.35. For us it is happening on Ubuntu 20.04 and 22.10 with Perl 5.36.0.

The underlying reason appears to be that we were connecting to localhost but the Redis server was bound to 127.0.0.1. In 0.35, localhost resolves to ::1, despite comments in hiredis code saying that IPv4 will be tried first if no preference is specified.

[christopherraa]

Based on the comment by @oschwald perhaps this issue is better reopened.