Test suite hangs w/ redis 4.0.2

[kentfredric]

I'm having trouble packaging Redis 1.991 for downstream, partly because the tests randomly hang without any clear indication of what is going wrong.

The number of tests that run before they start hanging varies semi-randomly, and eventually you're left with a redis-server thread blocking on a futex() call.

An example output looks like:

t/00-compile.t ......... ok   
t/01-basic.t ........... ok     
t/02-responses.t ....... ok    
t/03-pubsub.t .......... 2/?     # child is ready to test, signal parent to kill our server
    # parent killed pub/sub redis server, signal child to proceed
    # now, check wait_for_messages(), should die...
    # parent waiting for child 22160...
t/03-pubsub.t .......... 3/?     # CHILD: reconnected (with a 10s timeout)
    # CHILD: is ready to test, signal parent to restart our server
    # PARENT: killed pub/sub redis server, signal child to proceed
    # CHILD: launch wait_for_messages(2), with reconnect...
    # CHILD: reconnected (with a 10s timeout)
    # PARENT: has relaunched the server...
    # CHILD: after 2 sec, nothing yet, retrying
    # CHILD: launch wait_for_messages(2), with reconnect...
    # CHILD: after 2 sec, nothing yet, retrying
    # CHILD: launch wait_for_messages(2), with reconnect...
    # PARENT: waiting for child 22165...
    # CHILD: child received the message
t/03-pubsub.t .......... ok   
t/04-pipeline.t ........ ok    
t/05-nonblock.t ........ ok   
t/06-on-connect.t ...... ok   
t/07-reconnect.t ....... 1/?     # Sleeping 11 seconds, waiting for Redis to timeout...
t/07-reconnect.t ....... 12/?     # waiting for sleep command
t/07-reconnect.t ....... ok    
t/08-unix-socket.t ..... skipped: Define ENV TEST_REDIS_SERVER_SOCK_PATH to test UNIX socket support
t/10-tie-list.t ........ ok   
t/11-timeout.t ......... ok   
t/20-tie-hash.t ........ 1/? 

But if I nuke t/20*, then it will probably hang in t/30* , but simply starting over might make how far it progresses different.

I haven't yet tested with older redis versions, partly because I'm not actually sure which circumstances replicate the failure yet.

[kentfredric]

Here's a verbose output. It looks like its hanging at perl exit() ( which is probably why if I SIGKILL the redis-server instead of the test, the test passes )

t/00-compile.t ......... 
1..4
ok 1 - Redis.pm loaded ok
ok 2 - Redis/Hash.pm loaded ok
ok 3 - Redis/List.pm loaded ok
ok 4 - Redis/Sentinel.pm loaded ok
ok
t/01-basic.t ........... 
ok 1 - Got an unconnected object
ok 2 - ping doesn't work yet
ok 3 - ping works after connection
ok 4 - connected to our test redis-server
ok 5 - ping
ok 6 - set foo => bar
ok 7 - setnx foo => bar fails
ok 8 - get foo = bar
ok 9 - set foo => ""
ok 10 - get foo = ""
ok 11 - set foo => baz
ok 12 - get foo = baz
ok 13 - assume $eur is wide character
ok 14 - accepts only binary data, thus crashes on strings with characters > 255
ok 15 - .. and crashes on syswrite call
ok 16 - .. and does not write actual data
ok 17 - set test-undef
ok 18 - exists undef
ok 19 - set with value size 10000 ok
ok 20 - ... and get was ok to
ok 21 - set with value size 100000 ok
ok 22 - ... and get was ok to
ok 23 - set with value size 500000 ok
ok 24 - ... and get was ok to
ok 25 - set with value size 1000000 ok
ok 26 - ... and get was ok to
ok 27 - set with value size 2500000 ok
ok 28 - ... and get was ok to
ok 29 - exists non-existant
ok 30 - get non-existant
ok 31 - key-next = 0
ok 32 - key-left
ok 33 - mget
ok 34 - set key-0
ok 35 - exists key-0
ok 36 - get key-0
ok 37 - incr
ok 38 - decr
ok 39 - set key-1
ok 40 - exists key-1
ok 41 - get key-1
ok 42 - incr
ok 43 - decr
ok 44 - set key-2
ok 45 - exists key-2
ok 46 - get key-2
ok 47 - incr
ok 48 - decr
ok 49 - set key-3
ok 50 - exists key-3
ok 51 - get key-3
ok 52 - incr
ok 53 - decr
ok 54 - key-next
ok 55 - test-incrby
ok 56 - test-decry
ok 57 - incrby 3
ok 58 - decrby 7
ok 59 - incrby 3
ok 60 - decrby 7
ok 61 - incrby 3
ok 62 - decrby 7
ok 63 - del key-next
ok 64 - del key-left
ok 65 - del non-existing
ok 66 - type
ok 67 - key-*
ok 68 - keys
ok 69 - randomkey
ok 70 - rename
ok 71 - exists test-renamed
ok 72 - rename to existing key
ok 73 - dbsize
ok 74 - Error responses throw exception
ok 75 - rpush
ok 76 - rpush
ok 77 - rpush
ok 78 - lpush
ok 79 - lpush
ok 80 - type
ok 81 - llen
ok 82 - lrange
ok 83 - ltrim
ok 84 - llen after ltrim
ok 85 - lindex
ok 86 - lindex
ok 87 - lset
ok 88 - verified
ok 89 - lrem
ok 90 - llen after lrem
ok 91 - lpop
ok 92 - rpop
ok 93 - sadd
ok 94 - sadd
ok 95 - scard
ok 96 - sismember
ok 97 - type is set
ok 98 - srem
ok 99 - srem again
ok 100 - scard
ok 101 - sinter
ok 102 - sinterstore
ok 103 - cardinality of intersection
ok 104 - sdiff
ok 105 - sdiffstore
ok 106 - cardinality of diff
ok 107 - sunion
ok 108 - sunionstore
ok 109 - cardinality of union
ok 110 - srandmember result is defined
ok 111
ok 112 - spop result is defined
ok 113
ok 114 - new cardinality of union
ok 115 - smembers
ok 116 - repeated smove depleted source
ok 117 - repeated smove populated destination
ok 118 - smembers
ok 119
ok 120
ok 121
ok 122
ok 123
ok 124
ok 125
ok 126
ok 127
ok 128
ok 129
ok 130
ok 131
ok 132
ok 133
ok 134
ok 135
ok 136
ok 137
ok 138
ok 139
ok 140
ok 141
ok 142
ok 143
ok 144
ok 145
ok 146
ok 147
ok 148
ok 149
ok 150
ok 151
ok 152
ok 153
ok 154
ok 155
ok 156
ok 157
ok 158
ok 159
ok 160
ok 161
ok 162
ok 163
ok 164
ok 165
ok 166
ok 167
ok 168
ok 169
ok 170
ok 171
ok 172
ok 173 - select
ok 174 - select
ok 175 - move
ok 176 - gone
ok 177 - select
ok 178 - exists
ok 179 - flushdb
ok 180 - empty
ok 181 - put 1
ok 182 - put 2
ok 183 - put 3
ok 184 - put 4
ok 185 - llen
ok 186 - sort
ok 187 - sort DESC
ok 188 - save
ok 189 - bgsave
ok 190 - lastsave
ok 191 - info
ok 192 - '... yields a hash' isa 'HASH'
ok 193 - ... nonempty
ok 194 - ... with no comments in the keys
ok 195 - ... with no blank lines in the keys
ok 196 - ping() is true
ok 197 - quit
ok 198 - quit again, ok
ok 199 - ... but after quit() returns false
ok 200 - shutdown() once is ok
ok 201 - ... twice also lives, but returns false
ok 202 - ping() will be false after shutdown()
ok 203 - Failed connection throws exception
1..203
ok
t/02-responses.t ....... 
ok 1 - connected to our test redis-server
ok 2 - Error response detected
ok 3 - Text response ok
ok 4 - Integer response ok
ok 5 - Size+payload response ok
ok 6 - Zero-size+payload response ok
ok 7 - Negative-size+payload response ok
ok 8 - Simple multi-bulk response ok
ok 9 - Nested multi-bulk response ok
ok 10 - Read a NIL multi-bulk response
ok 11 - Nested errors must usually throw exceptions
ok 12 - Nested errors must be collected in collect-errors mode
1..12
ok
t/03-pubsub.t .......... 
# Subtest: basics
    ok 1 - connected to our test redis-server (pub)
    ok 2 - connected to our test redis-server (sub)
    ok 3 - No subscribers to 'aa' topic
    ok 4 - Delivered to 1 subscriber of topic 'aa'
    ok 5 - subscribing processes pending queued commands
    ok 6 - ... yep, got the expected 1 message
    ok 7 - ... for the expected topic, 'aa'
    ok 8 - Delivered to 1 subscriber of topic 'aa'
    ok 9 - ... yep, got the expected 1 message
    ok 10 - ... for the expected topic, 'aa', with two handlers
    ok 11 - Delivered to 1 subscriber of topic 'aa'
    ok 12 - ... received message while processing psubscribe(), two handlers
    ok 13 - Delivered to 2 subscriber of topic 'aa'
    ok 14 - ... yep, got the expected 2 messages
    ok 15 - ... for the expected subs, 'aa' and 'a*', three handlers total
    ok 16 - Delivered to 1 subscriber of topic 'aaa'
    ok 17 - ... yep, got the expected 1 message
    ok 18 - ... for the expected sub, 'a*'
    ok 19 - Current subscriber has 4 subscriptions active
    ok 20 - ... the publisher has none
    ok 21 - No match to our subscriptions, unsubscribe doesn't change active count
    ok 22 - unsubscribe ok, active count is still 4, another handler is alive
    ok 23 - unsubscribe done, active count is now 3, both handlers are done
    ok 24 - ... yep, got the expected 1 message
    ok 25 - ... for the expected key, 'a*'
    ok 26 - unsubscribe with topic wildcard failed, active count is now 3
    ok 27 - ... yep, got the expected 1 message
    ok 28 - ... for the expected key, 'a*'
    ok 29 - unsubscribe with 'bb' ok, active count is now 2
    ok 30 - punsubscribe with 'a*' ok, active count is now 1
    ok 31 - Publish to 'aa' now gives 0 deliveries
    ok 32 - ... yep, no messages delivered
    ok 33 - ... and an empty messages recorded set
    ok 34 - Still some pending subcriptions active
    ok 35 - .. still an error to try PING while in SUBSCRIBE mode
    ok 36 - .. still an error to try INFO while in SUBSCRIBE mode
    ok 37 - .. still an error to try KEYS while in SUBSCRIBE mode
    ok 38 - .. still an error to try DBSIZE while in SUBSCRIBE mode
    ok 39 - .. still an error to try SHUTDOWN while in SUBSCRIBE mode
    ok 40 - ... but none anymore
    ok 41 - Other commands ok after we leave subscriber_mode
    1..41
ok 1 - basics
# Subtest: zero_topic
    ok 1 - Delivered to 1 subscriber of topic '0'
    ok 2 - ... yep, got the expected 1 message
    ok 3 - ... for the expected topic, '0'
    1..3
ok 2 - zero_topic
# Subtest: server is killed while waiting for subscribe
    ok 1 - connected to our test redis-server (sync parent)
    # child is ready to test, signal parent to kill our server
    ok 2 - pub/sub redis server killed
    # parent killed pub/sub redis server, signal child to proceed
    # parent waiting for child 25904...
    # now, check wait_for_messages(), should die...
    ok 1 - properly died with EOF
    ok 3 - wait_for_messages() properly detects a server that dies
    1..3
ok 3 - server is killed while waiting for subscribe
# Subtest: server is restarted while waiting for subscribe
    ok 1 - PARENT: connected to our test redis-server (sync parent)
    # CHILD: reconnected (with a 10s timeout)
    # CHILD: is ready to test, signal parent to restart our server
    ok 2 - PARENT: pub/sub redis server killed
    # PARENT: killed pub/sub redis server, signal child to proceed
    # CHILD: launch wait_for_messages(2), with reconnect...
    # CHILD: reconnected (with a 10s timeout)
    # PARENT: has relaunched the server...
    # CHILD: after 2 sec, nothing yet, retrying
    # CHILD: launch wait_for_messages(2), with reconnect...
    # CHILD: after 2 sec, nothing yet, retrying
    # CHILD: launch wait_for_messages(2), with reconnect...
    ok 3 - PARENT: published and the child is subscribed
    # PARENT: waiting for child 25909...
    # CHILD: child received the message
    ok 1 - CHILD: the message is what we want
    ok 4 - PARENT: child has properly quit after wait_for_messages()
    ok 5 - PARENT: pub/sub redis server killed
    1..5
ok 4 - server is restarted while waiting for subscribe
1..4
ok
t/04-pipeline.t ........ 
ok 1 - connected to our test redis-server
ok 2 - single-command pipeline
ok 3 - pipeline with embedded error
ok 4 - keys in pipelined mode
ok 5 - info in pipelined mode
ok 6 - pipeline with multi-bulk reply
ok 7 - large pipeline
# Subtest: synchronous request with pending pipeline
    ok 1 - queue a request
    ok 2 - queue another request
    ok 3 - synchronous request has expected return
    ok 4 - synchronous request processes pending ones
    1..4
ok 8 - synchronous request with pending pipeline
# Subtest: transaction with error and pipeline
    ok 1 - multi started
    ok 2 - queued
    ok 3 - queued
    ok 4 - queued
    ok 5 - set
    ok 6 - bad rpush value should be undef
    ok 7 - bad rpush should give an error
    ok 8 - get should work
    1..8
ok 9 - transaction with error and pipeline
# Subtest: transaction with error and no pipeline
    ok 1 - multi
    ok 2 - transactional SET
    ok 3 - transactional bad RPUSH
    ok 4 - transactional GET
    ok 5 - synchronous EXEC dies for intervening error
    1..5
ok 10 - transaction with error and no pipeline
# Subtest: wait_one_response
    ok 1 - after first wait_one_response(), first callback called
    ok 2 - ... but not the second one
    ok 3 - after second wait_one_response(), first callback was not called again
    ok 4 - ... but the second one was called
    ok 5 - after final wait_all_responses(), first callback was called again
    ok 6 - ... the second one was also called
    ok 7 - after final wait_one_response(), first callback was not called again
    ok 8 - ... nor was the second one
    1..8
ok 11 - wait_one_response
1..11
ok
t/05-nonblock.t ........ 
# Subtest: non-block TCP
    ok 1 - connected to our test redis-server via TCP
    ok 2 - Nothing to read, didn't block
    1..2
ok 1 - non-block TCP
# Subtest: non-block UNIX
    1..0 # SKIP Define ENV TEST_REDIS_SERVER_SOCK_PATH to test UNIX socket support
ok 2 # skip Define ENV TEST_REDIS_SERVER_SOCK_PATH to test UNIX socket support
1..2
ok
t/06-on-connect.t ...... 
# Subtest: on_connect
    ok 1 - connected to our test redis-server
    ok 2 - ... on_connect code was run
    ok 3 - new connection is up and running
    ok 4 - ... on_connect code was run again
    ok 5 - new connection with reconnect enabled
    ok 6 - ... on_connect code one again perfect
    ok 7 - ... on_connect code works after reconnect also
    1..7
ok 1 - on_connect
1..1
ok
t/07-reconnect.t ....... 
# Subtest: Command without connection, no reconnect
    ok 1 - connected to our test redis-server
    ok 2 - close connection to the server
    ok 3 - send ping without reconnect
    1..3
ok 1 - Command without connection, no reconnect
# Subtest: Command without connection or timeout, with database change, with reconnect
    ok 1 - connected to our test redis-server
    ok 2 - send command with reconnect
    ok 3 - send command with reconnect
    ok 4 - close connection to the server
    ok 5 - reconnect with read errors before write
    1..5
ok 2 - Command without connection or timeout, with database change, with reconnect
# Subtest: Reconnection discards pending commands
    ok 1 - connected to our test redis-server
    ok 2 - evilly close connection to the server
    ok 3 - send command with reconnect
    ok 4 - pending command discarded on reconnect
    1..4
ok 3 - Reconnection discards pending commands
# Subtest: Conservative Reconnection dies on pending commands
    ok 1 - connected to our test redis-server
    ok 2 - evilly close connection to the server
    ok 3 - send command with reconnect and conservative_reconnect should raise an exception
    ok 4 - pending command never arrived
    1..4
ok 4 - Conservative Reconnection dies on pending commands
# Subtest: INFO commands with extra logic triggers reconnect
    ok 1 - connected to our test redis-server
    ok 2 - close connection to the server
    ok 3 - reconnect on INFO command
    1..3
ok 5 - INFO commands with extra logic triggers reconnect
# Subtest: KEYS commands with extra logic triggers reconnect
    ok 1 - connected to our test redis-server
    ok 2 - delete all keys
    ok 3 - set known key
    ok 4 - close connection to the server
    ok 5 - reconnect on KEYS command
    1..5
ok 6 - KEYS commands with extra logic triggers reconnect
# Subtest: Bad commands don't trigger reconnect
    ok 1 - connected to our test redis-server
    ok 2 - Bad commands still die
    ok 3 - ... and don't trigger a reconnect
    1..3
ok 7 - Bad commands don't trigger reconnect
# Subtest: Reconnect code clears sockect ASAP
    ok 1 - connected to our test redis-server
    # Sleeping 11 seconds, waiting for Redis to timeout...
    ok 2 - Quit doesn't die if we are already disconnected
    1..2
ok 8 - Reconnect code clears sockect ASAP
# Subtest: Reconnect gives up after timeout
    ok 1 - connected to our test redis-server
    ok 2 - Eventually it gives up and dies
    ok 3 - ... minimum value for the reconnect reached
    1..3
ok 9 - Reconnect gives up after timeout
# Subtest: Reconnect during transaction
    ok 1 - spawn redis on port 34167
    ok 2 - connected to our test redis-server
    ok 3 - start transacion
    ok 4 - set first key
    ok 5 - respawn redis on port 34167
    ok 6 - set second key
    ok 7 - key "reconnect_1" should not exist
    ok 8 - key "reconnect_2" should not exist
    1..8
ok 10 - Reconnect during transaction
# Subtest: Reconnect works after WATCH + MULTI + EXEC
    ok 1 - spawn redis on port 32963
    ok 2 - connected to our test redis-server
    ok 3 - set watch key
    ok 4 - start watching key
    ok 5 - start transacion
    ok 6 - set key
    ok 7 - execute transaction
    ok 8 - respawn redis on port 32963
    ok 9 - setting key should not fail
    1..9
ok 11 - Reconnect works after WATCH + MULTI + EXEC
# Subtest: Reconnect works after WATCH + MULTI + DISCARD
    ok 1 - spawn redis on port 45367
    ok 2 - connected to our test redis-server
    ok 3 - set watch key
    ok 4 - start watching key
    ok 5 - start transacion
    ok 6 - set key
    ok 7 - dscard transaction
    ok 8 - respawn redis on port 45367
    ok 9 - setting second key should not fail
    1..9
ok 12 - Reconnect works after WATCH + MULTI + DISCARD
# Subtest: Reconnection by read timeout discards pending commands
    ok 1 - connected to our test redis-server
    ok 2 - set foo bar
    ok 3 - sleep command is timeout
    # waiting for sleep command
    ok 4 - the value of key foo is bar
    1..4
ok 13 - Reconnection by read timeout discards pending commands
1..13
ok
t/08-unix-socket.t ..... 
1..0 # SKIP Define ENV TEST_REDIS_SERVER_SOCK_PATH to test UNIX socket support
skipped: Define ENV TEST_REDIS_SERVER_SOCK_PATH to test UNIX socket support
t/10-tie-list.t ........ 
ok 1 - tied to our test redis-server
ok 2 - pinged fine
ok 3 - An object of class 'Redis::List' isa 'Redis::List'
# Subtest: direct access
    ok 1 - empty list ok
    ok 2 - Set multiple values ok
    ok 3 - Set single value ok
    ok 4 - get single value ok
    ok 5 - ... even with post/pre-increments
    1..5
ok 4 - direct access
# Subtest: list functions
    ok 1 - shift ok
    ok 2 - ... expected value
    ok 3 - ... resulting list as expected
    ok 4 - push ok
    ok 5 - ... resulting list as expected
    ok 6 - pop ok
    ok 7 - ... expected value
    ok 8 - ... resulting list as expected
    ok 9 - unshift ok
    ok 10 - ... resulting list as expected
    ok 11 - splice ok
    ok 12 - ... resulting list as expected
    ok 13 - ... original list as expected
    1..13
ok 5 - list functions
ok 6 - empty list ok
1..6
ok
t/11-timeout.t ......... 
# Subtest: server replies quickly enough
    ok 1
    ok 2 - the code didn't died, as expected
    1..2
ok 1 - server replies quickly enough
# Subtest: server doesn't replies quickly enough
    ok 1
    ok 2 - the code died as expected
    1..2
ok 2 - server doesn't replies quickly enough
# Subtest: server doesn't respond at connection (cnx_timeout)
    ok 1 # skip This subtest is failing on some platforms
    ok 2 # skip This subtest is failing on some platforms
    ok 3 # skip This subtest is failing on some platforms
    ok 4 # skip This subtest is failing on some platforms
    1..4
ok 3 - server doesn't respond at connection (cnx_timeout)
1..3
ok
t/20-tie-hash.t ........ 
ok 1 - tied to our test redis-server
ok 2 - pinged fine
ok 3 - An object of class 'Redis::Hash' isa 'Redis::Hash'
# Subtest: direct access
    ok 1 - empty list ok
    ok 2 - Set multiple values ok
    ok 3 - Set single value ok
    ok 4 - get single value ok
    ok 5 - ... even with post/pre-increments
    1..5
ok 4 - direct access
# Subtest: hash functions
    ok 1 - keys ok
    ok 2 - ... resulting list as expected
    ok 3 - values ok
    ok 4 - ... resulting list as expected
    ok 5 - reverse() worked
    1..5
ok 5 - hash functions
ok 6 - empty list ok
1..6

[kentfredric]

Amusingly, if you set REDIS_DEBUG=1 ... tests stop failing :(