jruby
jruby copied to clipboard
Published
20 hours ago •
jruby
jruby
Newly unreliable getsockopt tests
I'm working on upgrading JRuby in Debian from 9.4.6.0 to 9.4.8.0, and I noticed jruby/test_socket now fails intermittently on amd64, which wasn't happening with the previous version:
$ jruby -I. test/jruby/test_socket.rb
Note: test/org/jruby/test/AlternativelyLoaded.java uses or overrides a deprecated API.
Note: Recompile with -Xlint:deprecation for details.
Note: Some input files use unchecked or unsafe operations.
Note: Recompile with -Xlint:unchecked for details.
/usr/lib/ruby/gems/3.1.0/gems/power_assert-2.0.1/lib/power_assert.rb:8: warning: tracing (e.g. set_trace_func) will not capture all events without --debug flag
/usr/lib/ruby/gems/3.1.0/gems/power_assert-2.0.1/lib/power_assert.rb:8: warning: tracing (e.g. set_trace_func) will not capture all events without --debug flag
Loaded suite test/jruby/test_socket
Started
..warning: thread "Ruby-0-Thread-3: test/jruby/test_socket.rb:678" terminated with exception (report_on_exception is true):
IOError: stream closed in another thread
accept at org/jruby/ext/socket/RubyTCPServer.java:153
test_server_close_interrupts_pending_accepts at test/jruby/test_socket.rb:679
..................F
===============================================================================
Failure: test_tcp_info(SocketTest):
Exception raised:
Errno::EINVAL(<Invalid argument - Unknown error -1>)
org/jruby/ext/socket/RubyBasicSocket.java:463:in `getsockopt'
test/jruby/test_socket.rb:58:in `block in test_tcp_info'
/usr/lib/ruby/gems/3.1.0/gems/test-unit-3.5.3/lib/test/unit/assertions.rb:693:in `block in assert_nothing_raised'
/usr/lib/ruby/gems/3.1.0/gems/test-unit-3.5.3/lib/test/unit/assertions.rb:1826:in `_wrap_assertion'
/usr/lib/ruby/gems/3.1.0/gems/test-unit-3.5.3/lib/test/unit/assertions.rb:684:in `assert_nothing_raised'
test/jruby/test_socket.rb:49:in `test_tcp_info'
/usr/lib/ruby/gems/3.1.0/gems/test-unit-3.5.3/lib/test/unit/testcase.rb:871:in `run_test'
/usr/lib/ruby/gems/3.1.0/gems/test-unit-3.5.3/lib/test/unit/testcase.rb:566:in `block in run'
/usr/lib/ruby/gems/3.1.0/gems/test-unit-3.5.3/lib/test/unit/fixture.rb:276:in `block in create_fixtures_runner'
/usr/lib/ruby/gems/3.1.0/gems/test-unit-3.5.3/lib/test/unit/fixture.rb:276:in `block in create_fixtures_runner'
/usr/lib/ruby/gems/3.1.0/gems/test-unit-3.5.3/lib/test/unit/fixture.rb:257:in `run_fixture'
/usr/lib/ruby/gems/3.1.0/gems/test-unit-3.5.3/lib/test/unit/fixture.rb:292:in `run_setup'
/usr/lib/ruby/gems/3.1.0/gems/test-unit-3.5.3/lib/test/unit/testcase.rb:564:in `block in run'
org/jruby/RubyKernel.java:1423:in `catch'
org/jruby/RubyKernel.java:1418:in `catch'
/usr/lib/ruby/gems/3.1.0/gems/test-unit-3.5.3/lib/test/unit/testcase.rb:563:in `run'
/usr/lib/ruby/gems/3.1.0/gems/test-unit-3.5.3/lib/test/unit/testsuite.rb:124:in `run_test'
/usr/lib/ruby/gems/3.1.0/gems/test-unit-3.5.3/lib/test/unit/testsuite.rb:53:in `run'
/usr/lib/ruby/gems/3.1.0/gems/test-unit-3.5.3/lib/test/unit/testsuite.rb:124:in `run_test'
/usr/lib/ruby/gems/3.1.0/gems/test-unit-3.5.3/lib/test/unit/testsuite.rb:53:in `run'
/usr/lib/ruby/gems/3.1.0/gems/test-unit-3.5.3/lib/test/unit/ui/testrunnermediator.rb:67:in `run_suite'
/usr/lib/ruby/gems/3.1.0/gems/test-unit-3.5.3/lib/test/unit/ui/testrunnermediator.rb:45:in `block in run'
/usr/lib/ruby/gems/3.1.0/gems/test-unit-3.5.3/lib/test/unit/ui/testrunnermediator.rb:102:in `with_listener'
/usr/lib/ruby/gems/3.1.0/gems/test-unit-3.5.3/lib/test/unit/ui/testrunnermediator.rb:41:in `block in run'
org/jruby/RubyKernel.java:1423:in `catch'
org/jruby/RubyKernel.java:1418:in `catch'
/usr/lib/ruby/gems/3.1.0/gems/test-unit-3.5.3/lib/test/unit/ui/testrunnermediator.rb:39:in `run'
/usr/lib/ruby/gems/3.1.0/gems/test-unit-3.5.3/lib/test/unit/ui/testrunner.rb:40:in `start_mediator'
/usr/lib/ruby/gems/3.1.0/gems/test-unit-3.5.3/lib/test/unit/ui/testrunner.rb:25:in `start'
/usr/lib/ruby/gems/3.1.0/gems/test-unit-3.5.3/lib/test/unit/ui/testrunnerutilities.rb:24:in `run'
/usr/lib/ruby/gems/3.1.0/gems/test-unit-3.5.3/lib/test/unit/autorunner.rb:458:in `block in run'
/usr/lib/ruby/gems/3.1.0/gems/test-unit-3.5.3/lib/test/unit/autorunner.rb:514:in `change_work_directory'
/usr/lib/ruby/gems/3.1.0/gems/test-unit-3.5.3/lib/test/unit/autorunner.rb:457:in `run'
/usr/lib/ruby/gems/3.1.0/gems/test-unit-3.5.3/lib/test/unit/autorunner.rb:66:in `run'
/usr/lib/ruby/gems/3.1.0/gems/test-unit-3.5.3/lib/test/unit.rb:518:in `block in <main>'
test/jruby/test_socket.rb:49:in `test_tcp_info'
46:
47: if RbConfig::CONFIG['target_os'] == 'linux'
48: def test_tcp_info
=> 49: assert_nothing_raised do
50: server = TCPServer.new(nil, 7789)
51: begin
52: t = Thread.new do
org/jruby/RubyKernel.java:1423:in `catch'
org/jruby/RubyKernel.java:1418:in `catch'
org/jruby/RubyKernel.java:1423:in `catch'
org/jruby/RubyKernel.java:1418:in `catch'
===============================================================================
..warning: thread "Ruby-0-Thread-7: test/jruby/test_socket.rb:307" terminated with exception (report_on_exception is true):
IOError: closed stream
accept at org/jruby/ext/socket/RubyTCPServer.java:153
test_tcp_socket_errors at test/jruby/test_socket.rb:307
E
===============================================================================
Error: test_tcp_socket_get_keep_cnt(SocketTest): Errno::EINVAL: Invalid argument - Unknown error -1
org/jruby/ext/socket/RubyBasicSocket.java:463:in `getsockopt'
test/jruby/test_socket.rb:197:in `test_tcp_socket_get_keep_cnt'
194:
195: def test_tcp_socket_get_keep_cnt
196: socket = Socket.new(Socket::AF_INET, Socket::SOCK_STREAM, 0)
=> 197: assert_instance_of(Integer, socket.getsockopt(Socket::SOL_TCP, Socket::TCP_KEEPCNT).int)
198: ensure
199: socket.close
200: end
org/jruby/RubyKernel.java:1423:in `catch'
org/jruby/RubyKernel.java:1418:in `catch'
org/jruby/RubyKernel.java:1423:in `catch'
org/jruby/RubyKernel.java:1418:in `catch'
===============================================================================
E
===============================================================================
Error: test_tcp_socket_get_keep_idle(SocketTest): Errno::EINVAL: Invalid argument - Unknown error -1
org/jruby/ext/socket/RubyBasicSocket.java:463:in `getsockopt'
test/jruby/test_socket.rb:183:in `test_tcp_socket_get_keep_idle'
180: if RbConfig::CONFIG['target_os'] == 'linux'
181: def test_tcp_socket_get_keep_idle
182: socket = Socket.new(Socket::AF_INET, Socket::SOCK_STREAM, 0)
=> 183: assert_instance_of(Integer, socket.getsockopt(Socket::SOL_TCP, Socket::TCP_KEEPIDLE).int)
184: ensure
185: socket.close
186: end
org/jruby/RubyKernel.java:1423:in `catch'
org/jruby/RubyKernel.java:1418:in `catch'
org/jruby/RubyKernel.java:1423:in `catch'
org/jruby/RubyKernel.java:1418:in `catch'
===============================================================================
E
===============================================================================
Error: test_tcp_socket_get_keep_intvl(SocketTest): Errno::EINVAL: Invalid argument - Unknown error -1
org/jruby/ext/socket/RubyBasicSocket.java:463:in `getsockopt'
test/jruby/test_socket.rb:190:in `test_tcp_socket_get_keep_intvl'
187:
188: def test_tcp_socket_get_keep_intvl
189: socket = Socket.new(Socket::AF_INET, Socket::SOCK_STREAM, 0)
=> 190: assert_instance_of(Integer, socket.getsockopt(Socket::SOL_TCP, Socket::TCP_KEEPINTVL).int)
191: ensure
192: socket.close
193: end
org/jruby/RubyKernel.java:1423:in `catch'
org/jruby/RubyKernel.java:1418:in `catch'
org/jruby/RubyKernel.java:1423:in `catch'
org/jruby/RubyKernel.java:1418:in `catch'
===============================================================================
...........................
Finished in 0.61878 seconds.
-------------------------------------------------------------------------------
53 tests, 94 assertions, 1 failures, 3 errors, 0 pendings, 0 omissions, 0 notifications
92.4528% passed
-------------------------------------------------------------------------------
85.65 tests/s, 151.91 assertions/s
It may be a coincidence but the set of test cases failure here is the exact same as #8041, although a different error message TypeError vs Errno::EINVAL.
The JVM being used is 17.0.12.
Using the tcp_info.rb example shared in the context of an previous issue, I can reproduce this in another container image, docker.io/jruby:9.4.8.0. The result alternates like so:
root@2f9c3fdcdf7e:/# jruby tcp_info.rb
TCP_INFO => true
Errno::EINVAL: Invalid argument - Unknown error -1
getsockopt at org/jruby/ext/socket/RubyBasicSocket.java:463
<main> at tcp_info.rb:10
root@2f9c3fdcdf7e:/# jruby tcp_info.rb
TCP_INFO => true
"\x01\x00\x00\x00\x00\x00\x00\x01\x00k\x03\x00\x00\x00\x00\x00\xFF\x7F\x00\x00\x18\x02\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x04\x00\x00\x00\x00\x00\x00\x00\x04\x00\x00\x00\x04\x00\x00\x00\xF0\xFF\x00\x00\xC8\xFF\x00\x00\x95W\x00\x00\xCA+\x00\x00\xFF\xFF\xFF\x7F\n\x00\x00\x00\xC8\xFF\x00\x00\x03\x00\x00\x00\x00\x00\x00\x00\xC8\xFF\x00\x00\x00\x00\x00\x00/\xFF\xBD\x01\x00\x00\x00\x00\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\x01\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x02\x00\x00\x00\x01\x00\x00\x00\x00\x00\x00\x00\x95W\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x01\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\xFF\xFF\x00\x00
The host machine runs Debian 12 bookworm running kernel 6.1.99 on amd64 hardware (Intel Skylake CPU).
Testing on the same host, with the same base container (docker.io/ubuntu:20.04) but using MRI Ruby (ruby 2.7.0p0 (2019-12-25 revision 647ee6f091) [x86_64-linux-gnu]), then the test works consistently, no EINVAL errors.
Sorry for delay getting to this one...
I only see two PRs in 9.4.8.0 that might be remotely related: https://github.com/jruby/jruby/pull/8294 and https://github.com/jruby/jruby/pull/8255
As expected in the tcp_info.rb example, it does not fail for me on OS X. However it also seems ok for me inside a Docker container on the same machine (macos host on aarch64):
[] jruby $ docker run -it --rm jruby:9 jruby -v
jruby 9.4.8.0 (3.1.4) 2024-07-02 4d41e55a67 OpenJDK 64-Bit Server VM 25.422-b05 on 1.8.0_422-b05 +jit [aarch64-linux]
[] jruby $ docker run -v $PWD:/opt/example -it --rm jruby:9 bash
root@4d9e9af45989:/# jruby /opt/example/tcp_info.rb
TCP_INFO => true
"\x01\x00\x00\x00\x00\x05w\x01xW\x03\x00\x00\x00\x00\x00\xC0\x7F\x00\x00\x18\x02\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x02\x00\x00\x00\x00\x00\x00\x00\x02\x00\x00\x00\x02\x00\x00\x00\xFF\xFF\x00\x00\x00\x82\x00\x00\xD0H\x00\x00h$\x00\x00\xFF\xFF\xFF\x7F\n\x00\x00\x00\xCB\xFF\x00\x00\x03\x00\x00\x00\x00\x00\x00\x00\x00\x82\x00\x00\x00\x00\x00\x00\xD0n\x17\x02\x00\x00\x00\x00\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\x01\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x02\x00\x00\x00\x01\x00\x00\x00\x00\x00\x00\x00\xD0H\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x01\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x80\xFF\x00\x00\x00\x82\x00\x00\x00\x00\x00\x00"
root@4d9e9af45989:/# jruby /opt/example/tcp_info.rb
TCP_INFO => true
"\x01\x00\x00\x00\x00\x05w\x01H_\x03\x00\x00\x00\x00\x00\xC0\x7F\x00\x00\x18\x02\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x01\x00\x00\x00\x00\x00\x00\x00\x01\x00\x00\x00\x01\x00\x00\x00\xFF\xFF\x00\x00\x00\x82\x00\x00\xD1N\x00\x00h'\x00\x00\xFF\xFF\xFF\x7F\n\x00\x00\x00\xCB\xFF\x00\x00\x03\x00\x00\x00\x00\x00\x00\x00\x00\x82\x00\x00\x00\x00\x00\x00T\xA5\xEE\x01\x00\x00\x00\x00\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\x01\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x02\x00\x00\x00\x01\x00\x00\x00\x00\x00\x00\x00\xD1N\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x01\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x80\xFF\x00\x00\x00\x82\x00\x00\x00\x00\x00\x00"
root@4d9e9af45989:/#
This output is similar (but not identical) to CRuby in the same container:
root@4d9e9af45989:/# ruby /opt/example/tcp_info.rb
TCP_INFO => true
"\x01\x00\x00\x00\x00\x05w\x01`[\x03\x00\x00\x00\x00\x00\xC0\x7F\x00\x00\x18\x02\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\xFF\xFF\x00\x00\x00\x82\x00\x006L\x00\x00\e&\x00\x00\xFF\xFF\xFF\x7F\n\x00\x00\x00\xCB\xFF\x00\x00\x03\x00\x00\x00\x00\x00\x00\x00\x00\x82\x00\x00\x00\x00\x00\x00{\x8E\xFF\x01\x00\x00\x00\x00\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\x01\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x02\x00\x00\x00\x01\x00\x00\x00\x00\x00\x00\x006L\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x01\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x80\xFF\x00\x00\x00\x82\x00\x00\x00\x00\x00\x00"
I would like to reproduce this, so if you have any suggestions let me know. In the meantime, could you get a longer stack trace by passing -Xbacktrace.style=full to JRuby?
