Logger: Errno::EINVAL: Invalid argument with JRuby 9.x in Solaris #4162

Closed
smk0621 opened this Issue Sep 19, 2016 · 5 comments

Projects

None yet

2 participants

@smk0621
Contributor
smk0621 commented Sep 19, 2016

Environment

  • jruby 9.1.2.0 (2.3.0) 2016-05-26 7357c8f Java HotSpot(TM) 64-Bit Server VM 25.60-b23 on 1.8.0_60-b27 +jit [solaris-sparcv9]
  • SunOS s11 5.11 11.3 sun4v sparc sun4v

Our Rails4 App in Solaris cannot started because we need create log file.
And we test the follow codes alone:

require 'logger'

logger = Logger.new("/work/log.txt", 5, 1024)
logger.info("A" * 1024)
logger.info("B" * 1024)

Expected Behavior

  • Create 'log.txt' with 'B' and 'log.txt.1' with 'A'.*

Actual Behavior

  • Only create a empty file 'log.txt' without any characters in it and raise the follows error:
Errno::EINVAL: Invalid argument - /work/log.txt
           flock at org/jruby/RubyFile.java:335
  create_logfile at /work/jruby-9.1.2.0/lib/ruby/stdlib/logger.rb:712
    open_logfile at /work/jruby-9.1.2.0/lib/ruby/stdlib/logger.rb:705
         set_dev at /work/jruby-9.1.2.0/lib/ruby/stdlib/logger.rb:695
      initialize at /work/jruby-9.1.2.0/lib/ruby/stdlib/logger.rb:635
      initialize at /work/jruby-9.1.2.0/lib/ruby/stdlib/logger.rb:353
           <top> at /work/test_logger.rb:3
  • Then we test it with JRuby 1.7.26 and Ruby 2.1, they are OK.
  • And we test it with JRuby 9.0.0.0, it raise another error:
AsmRuntime.java:40:in `newUnsatisifiedLinkError': java.lang.UnsatisfiedLinkError: unknown
        from null:-1:in `flock'
        from BaseNativePOSIX.java:527:in `flock'
        from CheckedPOSIX.java:416:in `flock'
        from LazyPOSIX.java:412:in `flock'
        from PosixShim.java:177:in `flock'
        from OpenFile.java:2488:in `run'
        from OpenFile.java:2485:in `run'
        from RubyThread.java:1358:in `executeTask'
        from OpenFile.java:2485:in `threadFlock'
        from RubyFile.java:298:in `flock'
        from RubyFile$INVOKER$i$1$0$flock.gen:-1:in `call'
        from CachingCallSite.java:313:in `cacheAndCall'
        from CachingCallSite.java:163:in `call'
        from InterpreterEngine.java:289:in `processCall'
        from StartupInterpreterEngine.java:77:in `interpret'
        from InterpreterEngine.java:82:in `interpret'
        from MixedModeIRMethod.java:198:in `INTERPRET_METHOD'
        from MixedModeIRMethod.java:184:in `call'
        from DynamicMethod.java:201:in `call'
        from CachingCallSite.java:313:in `cacheAndCall'
        from CachingCallSite.java:163:in `call'
        from InterpreterEngine.java:289:in `processCall'
        from StartupInterpreterEngine.java:77:in `interpret'
        from InterpreterEngine.java:82:in `interpret'
        from MixedModeIRMethod.java:198:in `INTERPRET_METHOD'
        from MixedModeIRMethod.java:184:in `call'
        from DynamicMethod.java:201:in `call'
        from CachingCallSite.java:313:in `cacheAndCall'
        from CachingCallSite.java:163:in `call'
        from InterpreterEngine.java:289:in `processCall'
        from StartupInterpreterEngine.java:77:in `interpret'
        from MixedModeIRMethod.java:128:in `INTERPRET_METHOD'
        from MixedModeIRMethod.java:114:in `call'
        from CachingCallSite.java:273:in `cacheAndCall'
        from CachingCallSite.java:79:in `callBlock'
        from CachingCallSite.java:83:in `call'
        from RubyClass.java:881:in `newInstance'
        from RubyClass$INVOKER$i$newInstance.gen:-1:in `call'
        from CachingCallSite.java:273:in `cacheAndCall'
        from CachingCallSite.java:79:in `callBlock'
        from CachingCallSite.java:83:in `call'
        from CallBase.java:419:in `interpret'
        from InterpreterEngine.java:321:in `processCall'
        from StartupInterpreterEngine.java:77:in `interpret'
        from InterpreterEngine.java:94:in `interpret'
        from MixedModeIRMethod.java:268:in `INTERPRET_METHOD'
        from MixedModeIRMethod.java:254:in `call'
        from CachingCallSite.java:363:in `cacheAndCall'
        from CachingCallSite.java:237:in `callBlock'
        from CachingCallSite.java:241:in `call'
        from RubyClass.java:874:in `newInstance'
        from RubyClass$INVOKER$i$newInstance.gen:-1:in `call'
        from JavaMethod.java:345:in `call'
        from CachingCallSite.java:353:in `cacheAndCall'
        from CachingCallSite.java:227:in `call'
        from /work/test_logger.rb:-1:in `invokeOther5:new'
        from /work/test_logger.rb:3:in `RUBY$script'
        from MethodHandle.java:627:in `invokeWithArguments'
        from Compiler.java:111:in `load'
        from Ruby.java:821:in `runScript'
        from Ruby.java:813:in `runScript'
        from Ruby.java:751:in `runNormally'
        from Ruby.java:573:in `runFromMain'
        from Main.java:403:in `doRunFromMain'
        from Main.java:298:in `internalRun'
        from Main.java:225:in `run'
        from Main.java:197:in `main'

We found that if we delete 3 lines in /jruby-9.1.2.0/lib/ruby/stdlib/logger.rb, it's OK too.

712  logdev.flock(File::LOCK_EX)
715  logdev.flock(File::LOCK_UN)
755  lock.flock(File::LOCK_EX) # inter-process locking. will be unlocked at closing file

And we test the same codes with JRuby 9.1.2.0 in RedHat Enterprise 7.2, it's OK.
It seems that this is a JRuby bug in Solaris.

@headius
Member
headius commented Sep 19, 2016

flock on Solaris does have some problems. I'll look at this a bit.

@headius
Member
headius commented Sep 19, 2016

Could you please start up your app with env var JRUBY_OPTS='-Xbacktrace.style=full' please? The logic in JRuby should be using JVM file locking rather than native flock logic on Solaris, and I'd expect it to work. A full trace will have all Ruby and Java line numbers so I can see where it's actually failing.

@headius
Member
headius commented Sep 19, 2016

I have managed to reproduce this on my Solaris VM:

$ bin/jruby -rlogger -e "Logger.new('/export/home/headius/blah.txt')"
Errno::EINVAL: Invalid argument - /export/home/headius/blah.txt
           flock at org/jruby/RubyFile.java:337
  create_logfile at /export/home/headius/jruby/lib/ruby/stdlib/logger.rb:712
    open_logfile at /export/home/headius/jruby/lib/ruby/stdlib/logger.rb:705
         set_dev at /export/home/headius/jruby/lib/ruby/stdlib/logger.rb:695
      initialize at /export/home/headius/jruby/lib/ruby/stdlib/logger.rb:635
      initialize at /export/home/headius/jruby/lib/ruby/stdlib/logger.rb:353
          <main> at -e:1
@smk0621
Contributor
smk0621 commented Sep 20, 2016 edited

@headius We set the JRUBY_OPTS='-Xbacktrace.style=full',
and the full trace is

Errno::EINVAL: Invalid argument - /work/log.txt
        getStackTrace at java/lang/Thread.java:1552
     getBacktraceData at org/jruby/runtime/backtrace/TraceType.java:246
         getBacktrace at org/jruby/runtime/backtrace/TraceType.java:47
     prepareBacktrace at org/jruby/RubyException.java:236
             preRaise at org/jruby/exceptions/RaiseException.java:214
             preRaise at org/jruby/exceptions/RaiseException.java:181
               <init> at org/jruby/exceptions/RaiseException.java:111
    newRaiseException at org/jruby/Ruby.java:4175
      newErrnoFromInt at org/jruby/Ruby.java:3869
    newErrnoFromErrno at org/jruby/Ruby.java:3879
                flock at org/jruby/RubyFile.java:335
         cacheAndCall at org/jruby/runtime/callsite/CachingCallSite.java:313
                 call at org/jruby/runtime/callsite/CachingCallSite.java:163
          processCall at org/jruby/ir/interpreter/InterpreterEngine.java:316
            interpret at org/jruby/ir/interpreter/StartupInterpreterEngine.java:77
            interpret at org/jruby/ir/interpreter/InterpreterEngine.java:86
     INTERPRET_METHOD at org/jruby/internal/runtime/methods/MixedModeIRMethod.java:179
       create_logfile at /work/jruby-9.1.2.0/lib/ruby/stdlib/logger.rb:712
                 call at org/jruby/internal/runtime/methods/MixedModeIRMethod.java:165
                 call at org/jruby/internal/runtime/methods/DynamicMethod.java:197
         cacheAndCall at org/jruby/runtime/callsite/CachingCallSite.java:313
                 call at org/jruby/runtime/callsite/CachingCallSite.java:163
          processCall at org/jruby/ir/interpreter/InterpreterEngine.java:316
            interpret at org/jruby/ir/interpreter/StartupInterpreterEngine.java:77
            interpret at org/jruby/ir/interpreter/InterpreterEngine.java:86
     INTERPRET_METHOD at org/jruby/internal/runtime/methods/MixedModeIRMethod.java:179
         open_logfile at /work/jruby-9.1.2.0/lib/ruby/stdlib/logger.rb:705
                 call at org/jruby/internal/runtime/methods/MixedModeIRMethod.java:165
                 call at org/jruby/internal/runtime/methods/DynamicMethod.java:197
         cacheAndCall at org/jruby/runtime/callsite/CachingCallSite.java:313
                 call at org/jruby/runtime/callsite/CachingCallSite.java:163
          processCall at org/jruby/ir/interpreter/InterpreterEngine.java:316
            interpret at org/jruby/ir/interpreter/StartupInterpreterEngine.java:77
            interpret at org/jruby/ir/interpreter/InterpreterEngine.java:86
     INTERPRET_METHOD at org/jruby/internal/runtime/methods/MixedModeIRMethod.java:179
              set_dev at /work/jruby-9.1.2.0/lib/ruby/stdlib/logger.rb:695
                 call at org/jruby/internal/runtime/methods/MixedModeIRMethod.java:165
                 call at org/jruby/internal/runtime/methods/DynamicMethod.java:197
         cacheAndCall at org/jruby/runtime/callsite/CachingCallSite.java:313
                 call at org/jruby/runtime/callsite/CachingCallSite.java:163
          processCall at org/jruby/ir/interpreter/InterpreterEngine.java:316
            interpret at org/jruby/ir/interpreter/StartupInterpreterEngine.java:77
     INTERPRET_METHOD at org/jruby/internal/runtime/methods/MixedModeIRMethod.java:109
           initialize at /work/jruby-9.1.2.0/lib/ruby/stdlib/logger.rb:635
                 call at org/jruby/internal/runtime/methods/MixedModeIRMethod.java:95
         cacheAndCall at org/jruby/runtime/callsite/CachingCallSite.java:273
            callBlock at org/jruby/runtime/callsite/CachingCallSite.java:79
                 call at org/jruby/runtime/callsite/CachingCallSite.java:83
          newInstance at org/jruby/RubyClass.java:904
         cacheAndCall at org/jruby/runtime/callsite/CachingCallSite.java:273
            callBlock at org/jruby/runtime/callsite/CachingCallSite.java:79
                 call at org/jruby/runtime/callsite/CachingCallSite.java:83
            interpret at org/jruby/ir/instructions/CallBase.java:423
          processCall at org/jruby/ir/interpreter/InterpreterEngine.java:348
            interpret at org/jruby/ir/interpreter/StartupInterpreterEngine.java:77
            interpret at org/jruby/ir/interpreter/InterpreterEngine.java:98
     INTERPRET_METHOD at org/jruby/internal/runtime/methods/MixedModeIRMethod.java:249
           initialize at /work/jruby-9.1.2.0/lib/ruby/stdlib/logger.rb:353
                 call at org/jruby/internal/runtime/methods/MixedModeIRMethod.java:235
         cacheAndCall at org/jruby/runtime/callsite/CachingCallSite.java:363
            callBlock at org/jruby/runtime/callsite/CachingCallSite.java:237
                 call at org/jruby/runtime/callsite/CachingCallSite.java:241
          newInstance at org/jruby/RubyClass.java:897
                 call at org/jruby/internal/runtime/methods/DynamicMethod.java:213
         cacheAndCall at org/jruby/runtime/callsite/CachingCallSite.java:353
                 call at org/jruby/runtime/callsite/CachingCallSite.java:227
                <top> at /work/test_logger.rb:3
  invokeWithArguments at java/lang/invoke/MethodHandle.java:627
                 load at org/jruby/ir/Compiler.java:111
            runScript at org/jruby/Ruby.java:833
            runScript at org/jruby/Ruby.java:825
          runNormally at org/jruby/Ruby.java:760
          runFromMain at org/jruby/Ruby.java:579
        doRunFromMain at org/jruby/Main.java:425
          internalRun at org/jruby/Main.java:313
                  run at org/jruby/Main.java:242
                 main at org/jruby/Main.java:204
@headius headius closed this in f8da225 Sep 20, 2016
@headius
Member
headius commented Sep 20, 2016

I have pushed a fix to master that reimplements File#flock using FFI on Solaris. It appears to work, and it passes the basic flock specs.

I will start a snapshot build for http://ci.jruby.org. You should be able to test it once you see an up-to-date build there.

Please let us know if it works!

@headius headius added this to the JRuby 9.1.6.0 milestone Sep 20, 2016
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment