Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

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

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

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

smk0621 opened this issue Sep 19, 2016 · 5 comments
Labels
core ffi JRuby 1.7.x JRuby 9000
Milestone
JRuby 9.1.6.0

Comments

@smk0621
Copy link
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
Copy link
Member

headius commented Sep 19, 2016

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

@headius
Copy link
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
Copy link
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
Copy link
Contributor Author

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
Copy link
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
This was referenced Sep 20, 2016
Closed
Closed
headius added a commit that referenced this issue Sep 20, 2016
@headius
Move Solaris flock struct to ffi platform files. #4162
01030ab
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
core ffi JRuby 1.7.x JRuby 9000
Projects
None yet
Milestone
JRuby 9.1.6.0
Development

No branches or pull requests
2 participants
@headius @smk0621