java jruby-complete-9.3.4.0.jar org.jruby.Main -rjars/setup -S gem install --debug --backtrace msgpack -v 1.1.0 failed windos-latest environment only.

[hiroyuki-sato]

Hello, JRuby developers.

Environment Information

Provide at least:

• JRuby version (jruby -v) and command line (flags, JRUBY_OPTS, etc): 9.3.4.0
• Operating system and platform (e.g. uname -a): windows-latest in GitHub Actions.

Other relevant info you may wish to add: (Please see below)

Expected Behavior

java jruby-complete-9.3.4.0.jar org.jruby.Main -rjars/setup -S gem install --debug --backtrace msgpack -v 1.1.0 installed gem on windows-latest environment.

Actual Behavior

The following command failed with windows-latest in GitHub Actions. (I can't reprodude this behavior in my Windows 10 environment.)
ubuntu-latest and macOS-latest worked fine.

Does anyone advise me on how to investigate this issue?

java jruby-complete-9.3.4.0.jar org.jruby.Main -rjars/setup -S gem install --debug --backtrace msgpack -v 1.1.0

Reproduce steps.

• Fork https://github.com/hiroyuki-sato/embulk-ci-test/tree/b8b81865a687c43bd507b046007f2a9440c6ad83
• git push

2022-04-26T06:33:58.4480037Z Starting process 'command 'C:\hostedtoolcache\windows\Java_Zulu_jdk\8.0.332-9\x64\bin\java.exe''. Working directory: D:\a\embulk-ci-test\embulk-ci-test\build\gemContents Command: C:\hostedtoolcache\windows\Java_Zulu_jdk\8.0.332-9\x64\bin\java.exe -Dfile.encoding=windows-1252 -Duser.country=US -Duser.language=en -Duser.variant -cp C:\Users\runneradmin\.gradle\caches\modules-2\files-2.1\org.jruby\jruby-complete\9.3.4.0\7a6e380880c1868c542132651481e91db8ebe9a1\jruby-complete-9.3.4.0.jar org.jruby.Main -rjars/setup -S gem install --debug --backtrace msgpack -v 1.1.0
2022-04-26T06:33:58.4483570Z Successfully started process 'command 'C:\hostedtoolcache\windows\Java_Zulu_jdk\8.0.332-9\x64\bin\java.exe''
2022-04-26T06:34:03.0654776Z NOTE: Debugging mode prints all exceptions even when rescued
2022-04-26T06:34:03.4602050Z Exception `LoadError' at org/jruby/RubyKernel.java:1017 - no such file to load -- org/bouncycastle/bcutil-jdk15to18/1.68/bcutil-jdk15to18-1.68.jar
2022-04-26T06:34:03.4603038Z Exception `RuntimeError' at uri:classloader:/META-INF/jruby.home/lib/ruby/stdlib/jar_dependencies.rb:356 - 
2022-04-26T06:34:03.4603443Z 
2022-04-26T06:34:03.4603831Z 	you might need to reinstall the gem which depends on the missing jar or in case there is Jars.lock then resolve the jars with `lock_jars` command
2022-04-26T06:34:03.4604170Z 
2022-04-26T06:34:03.4604591Z no such file to load -- org/bouncycastle/bcutil-jdk15to18/1.68/bcutil-jdk15to18-1.68.jar (LoadError)
2022-04-26T06:34:06.7512434Z Exception `Errno::EACCES' at org/jruby/RubyIO.java:1227 - Permission denied - NUL
2022-04-26T06:34:06.8466933Z Exception `Errno::EACCES' at org/jruby/RubyIO.java:1227 - Permission denied - NUL
2022-04-26T06:34:06.8467388Z ERROR: While executing gem ... (Errno::EACCES)
2022-04-26T06:34:06.8467781Z Permission denied - NUL
2022-04-26T06:34:06.8468720Z 	org/jruby/RubyIO.java:1227:in `sysopen'
2022-04-26T06:34:06.8468983Z 	org/jruby/RubyFile.java:362:in `initialize'
2022-04-26T06:34:06.8469596Z 	org/jruby/RubyClass.java:909:in `new'
2022-04-26T06:34:06.8469862Z 	org/jruby/RubyIO.java:1146:in `open'
2022-04-26T06:34:06.8470470Z 	uri:classloader:/META-INF/jruby.home/lib/ruby/stdlib/rubygems/resolver.rb:176:in `output'
2022-04-26T06:34:06.8471049Z 	uri:classloader:/META-INF/jruby.home/lib/ruby/stdlib/rubygems/resolver/molinillo/lib/molinillo/modules/ui.rb:41:in `after_resolution'
2022-04-26T06:34:06.8472011Z 	uri:classloader:/META-INF/jruby.home/lib/ruby/stdlib/rubygems/resolver/molinillo/lib/molinillo/resolution.rb:232:in `end_resolution'
2022-04-26T06:34:06.8472779Z 	uri:classloader:/META-INF/jruby.home/lib/ruby/stdlib/rubygems/resolver/molinillo/lib/molinillo/resolution.rb:187:in `resolve'
2022-04-26T06:34:06.8473327Z 	uri:classloader:/META-INF/jruby.home/lib/ruby/stdlib/rubygems/resolver/molinillo/lib/molinillo/resolver.rb:43:in `resolve'
2022-04-26T06:34:06.8473828Z 	uri:classloader:/META-INF/jruby.home/lib/ruby/stdlib/rubygems/resolver.rb:190:in `resolve'
2022-04-26T06:34:06.8474300Z 	uri:classloader:/META-INF/jruby.home/lib/ruby/stdlib/rubygems/request_set.rb:411:in `resolve'
2022-04-26T06:34:06.8474985Z 	uri:classloader:/META-INF/jruby.home/lib/ruby/stdlib/rubygems/dependency_installer.rb:333:in `resolve_dependencies'
2022-04-26T06:34:06.8475635Z 	uri:classloader:/META-INF/jruby.home/lib/ruby/stdlib/rubygems/commands/install_command.rb:198:in `install_gem'
2022-04-26T06:34:06.8476124Z 	uri:classloader:/META-INF/jruby.home/lib/ruby/stdlib/rubygems/commands/install_command.rb:223:in `block in install_gems'
2022-04-26T06:34:06.8476453Z 	org/jruby/RubyArray.java:1865:in `each'
2022-04-26T06:34:06.8476869Z 	uri:classloader:/META-INF/jruby.home/lib/ruby/stdlib/rubygems/commands/install_command.rb:216:in `install_gems'
2022-04-26T06:34:06.8477334Z 	uri:classloader:/META-INF/jruby.home/lib/ruby/stdlib/rubygems/commands/install_command.rb:164:in `execute'
2022-04-26T06:34:06.8478085Z 	uri:classloader:/META-INF/jruby.home/lib/ruby/stdlib/rubygems/command.rb:323:in `invoke_with_build_args'
2022-04-26T06:34:06.8478619Z 	uri:classloader:/META-INF/jruby.home/lib/ruby/stdlib/rubygems/command_manager.rb:178:in `process_args'
2022-04-26T06:34:06.8479083Z 	uri:classloader:/META-INF/jruby.home/lib/ruby/stdlib/rubygems/command_manager.rb:147:in `run'
2022-04-26T06:34:06.8479495Z 	uri:classloader:/META-INF/jruby.home/lib/ruby/stdlib/rubygems/gem_runner.rb:53:in `run'
2022-04-26T06:34:06.8479906Z 	uri:classloader:/META-INF/jruby.home/bin/jgem:21:in `<main>'
2022-04-26T06:34:06.8480168Z 	org/jruby/RubyKernel.java:1052:in `load'
2022-04-26T06:34:06.8480717Z 	uri:classloader:/META-INF/jruby.home/bin/gem:4:in `<main>'
2022-04-26T06:34:06.8481624Z Exception `Gem::SystemExitException' at uri:classloader:/META-INF/jruby.home/lib/ruby/stdlib/rubygems/user_interaction.rb:365 - Exiting RubyGems with exit_code 1
2022-04-26T06:34:06.8481920Z 
2022-04-26T06:34:06.8482029Z FAILURE: Build failed with an exception.
2022-04-26T06:34:06.8482171Z 
2022-04-26T06:34:06.8482247Z * What went wrong:
2022-04-26T06:34:06.8482536Z Execution failed for task ':installDependencyGems'.
2022-04-26T06:34:06.8483011Z > Process 'command 'C:\hostedtoolcache\windows\Java_Zulu_jdk\8.0.332-9\x64\bin\java.exe'' finished with non-zero exit value 1
2022-04-26T06:34:06.8483251Z 
2022-04-26T06:34:06.8483318Z * Try:
2022-04-26T06:34:06.8483706Z Run with --stacktrace option to get the stack trace. Run with --debug option to get more log output. Run with --scan to get full insights.

[hiroyuki-sato]

It seems that File.open(IO::NULL, "w"){} raise the Exception on windows-latest in GitHub Actions.

uri:classloader:/META-INF/jruby.home/lib/ruby/stdlib/rubygems/resolver.rb:176:in `output'

173 include Molinillo::UI
174
175 def output
176 @output ||= debug? ? $stdout : File.open(IO::NULL, 'w')
177 end

https://github.com/hiroyuki-sato/embulk-ci-test/runs/6173635118?check_suite_focus=true#step:4:76

Starting process 'command 'C:\hostedtoolcache\windows\Java_Zulu_jdk\8.0.332-9\x64\bin\java.exe''. Working directory: D:\a\embulk-ci-test\embulk-ci-test\build\gemContents Command: C:\hostedtoolcache\windows\Java_Zulu_jdk\8.0.332-9\x64\bin\java.exe -Dfile.encoding=windows-1252 -Duser.country=US -Duser.language=en -Duser.variant -cp C:\Users\runneradmin\.gradle\caches\modules-2\files-2.1\org.jruby\jruby-complete\9.3.4.0\7a6e380880c1868c542132651481e91db8ebe9a1\jruby-complete-9.3.4.0.jar org.jruby.Main -e File.open(IO::NULL, :w.to_s){}
[76](https://github.com/hiroyuki-sato/embulk-ci-test/runs/6173635118?check_suite_focus=true#step:4:76)
Successfully started process 'command 'C:\hostedtoolcache\windows\Java_Zulu_jdk\8.0.332-9\x64\bin\java.exe''
[77](https://github.com/hiroyuki-sato/embulk-ci-test/runs/6173635118?check_suite_focus=true#step:4:77)
Errno::EACCES: Permission denied - NUL
[78](https://github.com/hiroyuki-sato/embulk-ci-test/runs/6173635118?check_suite_focus=true#step:4:78)
 sysopen at org/jruby/RubyIO.java:1227
[79](https://github.com/hiroyuki-sato/embulk-ci-test/runs/6173635118?check_suite_focus=true#step:4:79)
 initialize at org/jruby/RubyFile.java:362
[80](https://github.com/hiroyuki-sato/embulk-ci-test/runs/6173635118?check_suite_focus=true#step:4:80)
 new at org/jruby/RubyClass.java:909
[81](https://github.com/hiroyuki-sato/embulk-ci-test/runs/6173635118?check_suite_focus=true#step:4:81)
 open at org/jruby/RubyIO.java:1146
[82](https://github.com/hiroyuki-sato/embulk-ci-test/runs/6173635118?check_suite_focus=true#step:4:82)
 <main> at -e:1
[83](https://github.com/hiroyuki-sato/embulk-ci-test/runs/6173635118?check_suite_focus=true#step:4:83)

[hiroyuki-sato]

I'll close this issue within a few days. Because I think this issue is GitHub Actions specific.
Setting the environment variable "DEBUG_RESOLVER": "1" to avoid this issue. I found the following codes.

 15 ##
 16 # If the DEBUG_RESOLVER environment variable is set then debugging mode is
 17 # enabled for the resolver. This will display information about the state
 18 # of the resolver while a set of dependencies is being resolved.
 19
 20 DEBUG_RESOLVER = !ENV['DEBUG_RESOLVER'].nil?

179 def debug?
180 DEBUG_RESOLVER
181 end

[headius]

I think we should keep this open. The resolver debugging should not break on JRuby, but it appears there's a bug that causes us to raise an error when opening the NULL device for write.

[hiroyuki-sato]

Hello, @headius. Thank you for your comment. I keep this open.

I also tested the following code using CRuby on windows-latest in GitHub Actions.
It worked. Humm...

#!/usr/bin/env ruby

File.open(IO::NULL,'w'){}

https://github.com/hiroyuki-sato/embulk-ci-test/
cb32d1b91ea66a8f3701c1f11eed2d67735fed20

https://github.com/hiroyuki-sato/embulk-ci-test/runs/6185552371?check_suite_focus=true

[hiroyuki-sato]

I'll double-check later, but this issue is Zulu SDK-specific.

The difference is the distribution parameter only.

NG Case: https://github.com/hiroyuki-sato/embulk-ci-test/actions/runs/2233437492

name: Check
on: [ push, pull_request ]
jobs:
 check:
 runs-on: ${{ matrix.os }}
 # push: always run.
 # pull_request: run only when the PR is submitted from a forked repository, not within this repository.
 if: github.event_name == 'push' || github.event.pull_request.head.repo.full_name != github.repository
 strategy:
 fail-fast: false
 matrix:
 os:
 - ubuntu-latest
 - macOS-latest
 - windows-latest
 gradle_task:
 - "check"
 steps:
 - uses: actions/checkout@v2
 - name: Set up OpenJDK 8
 uses: actions/setup-java@v2
 with:
 java-version: 8
# distribution: "adopt"
 distribution: "zulu"
 - name: Check
 run: ./gradlew --debug ${{ matrix.gradle_task }}

OK Case: https://github.com/hiroyuki-sato/embulk-ci-test/actions/runs/2233515348

name: Check
on: [ push, pull_request ]
jobs:
 check:
 runs-on: ${{ matrix.os }}
 # push: always run.
 # pull_request: run only when the PR is submitted from a forked repository, not within this repository.
 if: github.event_name == 'push' || github.event.pull_request.head.repo.full_name != github.repository
 strategy:
 fail-fast: false
 matrix:
 os:
 - ubuntu-latest
 - macOS-latest
 - windows-latest
 gradle_task:
 - "check"
 steps:
 - uses: actions/checkout@v2
 - name: Set up OpenJDK 8
 uses: actions/setup-java@v2
 with:
 java-version: 8
 distribution: "adopt"
# distribution: "zulu"
 - name: Check
 run: ./gradlew --debug ${{ matrix.gradle_task }}

[headius]

Aha that is very interesting! I have some other issues with Zulu that I need to report, so I can add this to the list.

[hiroyuki-sato]

Hello, @headius. Thank you for your comment. I double-checked
https://github.com/hiroyuki-sato/embulk-ci-test/actions/runs/2236429457

Test code in build.gradle. (JRuby 9.3.4.0)

File.open(IO::NULL,'w'){}

SDK	Result	SDK version
Zulu	NG	8.0.332-9
Adopt	OK	8.0.322+6

2022-04-28T00:19:28.8311232Z 2022-04-28T00:19:28.823+0000 [ERROR] [system.err] Errno::EACCES: Permission denied - NUL
2022-04-28T00:19:28.8311956Z 2022-04-28T00:19:24.368+0000 [LIFECYCLE] [class org.gradle.internal.buildevents.TaskExecutionLogger] 
2022-04-28T00:19:28.8313085Z 2022-04-28T00:19:24.368+0000 [LIFECYCLE] [class org.gradle.internal.buildevents.TaskExecutionLogger] > Task :gemDebug
2022-04-28T00:19:28.8314835Z 2022-04-28T00:19:28.823+0000 [ERROR] [system.err] sysopen at org/jruby/RubyIO.java:1227
2022-04-28T00:19:28.8331302Z 2022-04-28T00:19:28.823+0000 [ERROR] [system.err] initialize at org/jruby/RubyFile.java:362
2022-04-28T00:19:28.8332237Z 2022-04-28T00:19:28.824+0000 [ERROR] [system.err] new at org/jruby/RubyClass.java:909
2022-04-28T00:19:28.8332927Z 2022-04-28T00:19:28.824+0000 [ERROR] [system.err] open at org/jruby/RubyIO.java:1146
2022-04-28T00:19:28.8333646Z 2022-04-28T00:19:28.826+0000 [ERROR] [system.err] <main> at -e:1
2022-04-28T00:19:28.9870562Z 2022-04-28T00:19:28.903+0000 [DEBUG] [org.gradle.process.internal.DefaultExecHandle] Changing state to: FAILED
2022-04-28T00:19:28.9969762Z 2022-04-28T00:19:28.935+0000 [ERROR] [org.gradle.internal.buildevents.BuildExceptionReporter] 
2022-04-28T00:19:28.9970878Z 2022-04-28T00:19:28.903+0000 [DEBUG] [org.gradle.process.internal.DefaultExecHandle] Process 'command 'C:\hostedtoolcache\windows\Java_Zulu_jdk\8.0.332-9\x64\bin\java.exe'' finished with exit value 1 (state: FAILED)

I can confirm the issue also exists using Adoptium 17.0.3_7 on Windows.

C:\tools>java -version
openjdk version "17.0.3" 2022-04-19
OpenJDK Runtime Environment Temurin-17.0.3+7 (build 17.0.3+7)
OpenJDK 64-Bit Server VM Temurin-17.0.3+7 (build 17.0.3+7, mixed mode, sharing)

C:\tools\jruby-9.3.4.0\bin\jirb
irb(main):001:0> File.open(IO::NULL, 'w')
Traceback (most recent call last):
 10: from C:/tools/jruby-9.3.4.0/bin/jirb:13:in `<main>'
 9: from org/jruby/RubyKernel.java:1237:in `catch'
 8: from org/jruby/RubyKernel.java:1237:in `catch'
 7: from org/jruby/RubyKernel.java:1507:in `loop'
 6: from org/jruby/RubyKernel.java:1091:in `eval'
 5: from (irb):1:in `evaluate'
 4: from org/jruby/RubyIO.java:1146:in `open'
 3: from org/jruby/RubyClass.java:909:in `new'
 2: from org/jruby/RubyFile.java:362:in `initialize'
 1: from org/jruby/RubyIO.java:1227:in `sysopen'
Errno::EACCES (Permission denied - NUL)
irb(main):002:0> exit()

[headius]

I can confirm the issue also exists using Adoptium 17.0.3_7 on Windows.

This may mean that some newer behavior from later JDKs was incorporated into the builds of Zulu 8, or it may mean this is not specific to Zulu after all.

I have reached out to the Zulu folks at Azul to help investigate this.

[sashaioffe]

Hi,
Looks like a known issue: https://bugs.openjdk.java.net/browse/JDK-8285445

Try to use command line option
-Djdk.io.File.enableADS=true