redis / redis-rb

A Ruby client library for Redis
MIT License
3.98k stars 1.03k forks source link

Mitigate long running job for truffleruby in CI by workaround #1292

Closed supercaracal closed 2 months ago

supercaracal commented 2 months ago

This is just a workaround. I'm not understanding the root cause, sorry. I'd say that it's a pain in the neck because we are made to wait to fail the job with meaningless timeout every time.

byroot commented 2 months ago

I'd rather have it fail than hide the failure.

supercaracal commented 2 months ago

I've simplified it.

byroot commented 2 months ago

It's interesting, it looks like it succeed but then get stuck on exit? Weird.

supercaracal commented 2 months ago

When I tried the test in my local machine, it was reproduced. It seems that there were three processes for the test and they were waiting for some kind of lock.

kasuga@W010097262:~$ ps aux | grep rub[y]
kasuga     24776  199  9.9 4348724 794524 pts/4  Sl+  10:05   0:24 /home/kasuga/vcs/redis-rb/.bundle/truffleruby/3.2.2.24.0.0.2/bin/rake test:redis
kasuga     24858  0.0  0.0   2804  1120 pts/4    S+   10:05   0:00 sh -c /home/kasuga/.rbenv/versions/truffleruby-24.0.2/bin/truffleruby -w -I"lib:test:lib" /home/kasuga/vcs/redis-rb/.bundle/truffleruby/3.2.2.24.0.0.2/gems/rake-13.2.1/lib/rake/rake_test_loader.rb "test/redis/bitpos_test.rb" "test/redis/blocking_commands_test.rb" "test/redis/client_test.rb" "test/redis/commands_on_geo_test.rb" "test/redis/commands_on_hashes_test.rb" "test/redis/commands_on_hyper_log_log_test.rb" "test/redis/commands_on_lists_test.rb" "test/redis/commands_on_sets_test.rb" "test/redis/commands_on_sorted_sets_test.rb" "test/redis/commands_on_streams_test.rb" "test/redis/commands_on_strings_test.rb" "test/redis/commands_on_value_types_test.rb" "test/redis/connection_handling_test.rb" "test/redis/connection_test.rb" "test/redis/encoding_test.rb" "test/redis/error_replies_test.rb" "test/redis/fork_safety_test.rb" "test/redis/helper_test.rb" "test/redis/internals_test.rb" "test/redis/persistence_control_commands_test.rb" "test/redis/pipelining_commands_test.rb" "test/redis/publish_subscribe_test.rb" "test/redis/remote_server_control_commands_test.rb" "test/redis/scanning_test.rb" "test/redis/scripting_test.rb" "test/redis/sorting_test.rb" "test/redis/ssl_test.rb" "test/redis/thread_safety_test.rb" "test/redis/transactions_test.rb" "test/redis/unknown_commands_test.rb" "test/redis/url_param_test.rb"
kasuga     24859  605 10.2 5386460 817088 pts/4  Rl+  10:05   0:57 /home/kasuga/.rbenv/versions/truffleruby-24.0.2/bin/truffleruby -w -Ilib:test:lib /home/kasuga/vcs/redis-rb/.bundle/truffleruby/3.2.2.24.0.0.2/gems/rake-13.2.1/lib/rake/rake_test_loader.rb test/redis/bitpos_test.rb test/redis/blocking_commands_test.rb test/redis/client_test.rb test/redis/commands_on_geo_test.rb test/redis/commands_on_hashes_test.rb test/redis/commands_on_hyper_log_log_test.rb test/redis/commands_on_lists_test.rb test/redis/commands_on_sets_test.rb test/redis/commands_on_sorted_sets_test.rb test/redis/commands_on_streams_test.rb test/redis/commands_on_strings_test.rb test/redis/commands_on_value_types_test.rb test/redis/connection_handling_test.rb test/redis/connection_test.rb test/redis/encoding_test.rb test/redis/error_replies_test.rb test/redis/fork_safety_test.rb test/redis/helper_test.rb test/redis/internals_test.rb test/redis/persistence_control_commands_test.rb test/redis/pipelining_commands_test.rb test/redis/publish_subscribe_test.rb test/redis/remote_server_control_commands_test.rb test/redis/scanning_test.rb test/redis/scripting_test.rb test/redis/sorting_test.rb test/redis/ssl_test.rb test/redis/thread_safety_test.rb test/redis/transactions_test.rb test/redis/unknown_commands_test.rb test/redis/url_param_test.rb

kasuga@W010097262:~$ sudo strace -p 24776
strace: Process 24776 attached
wait4(24858, ^Cstrace: Process 24776 detached
 <detached ...>

kasuga@W010097262:~$ sudo strace -p 24858
strace: Process 24858 attached
wait4(-1, ^Cstrace: Process 24858 detached
 <detached ...>

kasuga@W010097262:~$ sudo strace -p 24859
strace: Process 24859 attached
futex(0x7f1270002a54, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 0, NULL, FUTEX_BITSET_MATCH_ANY^Cstrace: Process 24859 detached
 <detached ...>

kasuga@W010097262:~$ sudo kill -9 24859
kasuga@W010097262:~$ ps aux | grep rub[y]
kasuga@W010097262:~$
Finished in 80.278015s, 6.7765 runs/s, 61.8974 assertions/s.

  1) Failure:
TestInternals#test_connection_timeout [test/redis/internals_test.rb:69]:
[Redis::CannotConnectError] exception expected, not
Class: <Redis::CommandError>
Message: <"DENIED Redis is running in protected mode because protected mode is enabled and no password is set for the default user. In this mode connections are only accepted from the loopback interface. If you want to connect from external computers to Redis you may adopt one of the following solutions: 1) Just disable protected mode sending the command 'CONFIG SET protected-mode no' from the loopback interface by connecting to Redis from the same host the server is running, however MAKE SURE Redis is not publicly accessible from internet if you do so. Use CONFIG REWRITE to make this change permanent. 2) Alternatively you can just disable the protected mode by editing the Redis configuration file, and setting the protected mode option to 'no', and then restarting the server. 3) If you started the server manually just for testing, restart it with the '--protected-mode no' option. 4) Set up an authentication password for the default user. NOTE: You only need to do one of the above things in order for the server to start accepting connections from the outside. (redis://10.255.255.254:6381/15)">
---Backtrace---
/home/kasuga/vcs/redis-rb/.bundle/truffleruby/3.2.2.24.0.0.2/gems/redis-client-0.22.2/lib/redis_client/connection_mixin.rb:71:in `call_pipelined'
/home/kasuga/vcs/redis-rb/.bundle/truffleruby/3.2.2.24.0.0.2/gems/redis-client-0.22.2/lib/redis_client.rb:771:in `block in connect'
/home/kasuga/vcs/redis-rb/.bundle/truffleruby/3.2.2.24.0.0.2/gems/redis-client-0.22.2/lib/redis_client/middlewares.rb:16:in `call'
/home/kasuga/vcs/redis-rb/.bundle/truffleruby/3.2.2.24.0.0.2/gems/redis-client-0.22.2/lib/redis_client.rb:770:in `connect'
/home/kasuga/vcs/redis-rb/.bundle/truffleruby/3.2.2.24.0.0.2/gems/redis-client-0.22.2/lib/redis_client.rb:732:in `raw_connection'
/home/kasuga/vcs/redis-rb/.bundle/truffleruby/3.2.2.24.0.0.2/gems/redis-client-0.22.2/lib/redis_client.rb:697:in `ensure_connected'
/home/kasuga/vcs/redis-rb/.bundle/truffleruby/3.2.2.24.0.0.2/gems/redis-client-0.22.2/lib/redis_client.rb:292:in `call_v'
/home/kasuga/vcs/redis-rb/lib/redis/client.rb:90:in `call_v'
/home/kasuga/vcs/redis-rb/lib/redis.rb:152:in `block in send_command'
/home/kasuga/.rbenv/versions/truffleruby-24.0.2/lib/mri/monitor.rb:218:in `mon_synchronize'
/home/kasuga/vcs/redis-rb/lib/redis.rb:151:in `send_command'
/home/kasuga/vcs/redis-rb/lib/redis/commands/connection.rb:21:in `ping'
/home/kasuga/vcs/redis-rb/test/redis/internals_test.rb:70:in `block in test_connection_timeout'
---------------

544 runs, 4833 assertions, 1 failures, 0 errors, 3 skips

You have skipped tests. Run with --verbose for details.
Killed
rake aborted!
Command failed with status (137)
/home/kasuga/vcs/redis-rb/.bundle/truffleruby/3.2.2.24.0.0.2/gems/rake-13.2.1/exe/rake:27:in `<top (required)>'
/home/kasuga/vcs/redis-rb/.bundle/truffleruby/3.2.2.24.0.0.2/gems/bundler-2.5.3/lib/bundler/cli/exec.rb:58:in `kernel_load'
/home/kasuga/vcs/redis-rb/.bundle/truffleruby/3.2.2.24.0.0.2/gems/bundler-2.5.3/lib/bundler/cli/exec.rb:23:in `run'
/home/kasuga/vcs/redis-rb/.bundle/truffleruby/3.2.2.24.0.0.2/gems/bundler-2.5.3/lib/bundler/cli.rb:451:in `exec'
/home/kasuga/vcs/redis-rb/.bundle/truffleruby/3.2.2.24.0.0.2/gems/bundler-2.5.3/lib/bundler/vendor/thor/lib/thor/command.rb:28:in `run'
/home/kasuga/vcs/redis-rb/.bundle/truffleruby/3.2.2.24.0.0.2/gems/bundler-2.5.3/lib/bundler/vendor/thor/lib/thor/invocation.rb:127:in `invoke_command'
/home/kasuga/vcs/redis-rb/.bundle/truffleruby/3.2.2.24.0.0.2/gems/bundler-2.5.3/lib/bundler/vendor/thor/lib/thor.rb:527:in `dispatch'
/home/kasuga/vcs/redis-rb/.bundle/truffleruby/3.2.2.24.0.0.2/gems/bundler-2.5.3/lib/bundler/cli.rb:34:in `dispatch'
/home/kasuga/vcs/redis-rb/.bundle/truffleruby/3.2.2.24.0.0.2/gems/bundler-2.5.3/lib/bundler/vendor/thor/lib/thor/base.rb:584:in `start'
/home/kasuga/vcs/redis-rb/.bundle/truffleruby/3.2.2.24.0.0.2/gems/bundler-2.5.3/lib/bundler/cli.rb:28:in `start'
/home/kasuga/vcs/redis-rb/.bundle/truffleruby/3.2.2.24.0.0.2/gems/bundler-2.5.3/exe/bundle:28:in `block in <top (required)>'
/home/kasuga/vcs/redis-rb/.bundle/truffleruby/3.2.2.24.0.0.2/gems/bundler-2.5.3/lib/bundler/friendly_errors.rb:117:in `with_friendly_errors'
/home/kasuga/vcs/redis-rb/.bundle/truffleruby/3.2.2.24.0.0.2/gems/bundler-2.5.3/exe/bundle:20:in `<top (required)>'
/home/kasuga/.rbenv/versions/truffleruby-24.0.2/bin/bundle:44:in `<main>'
Tasks: TOP => test:redis
(See full trace by running task with --trace)
supercaracal commented 2 months ago

I found the following test cases occur the weird behavior in TruffleRuby. https://github.com/redis/redis-rb/blob/6afa62b5a3a89c695158a88420e68d843016b30e/test/redis/ssl_test.rb#L15-L20 https://github.com/redis/redis-rb/blob/6afa62b5a3a89c695158a88420e68d843016b30e/test/redis/ssl_test.rb#L40-L45