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.

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

Silently fallback to WEBrick or panic: failed to coerce org.slf4j.helpers.NOPLoggerFactory to ch.qos.logback.core.Context #20

Closed
arloan opened this issue Jul 15, 2018 · 10 comments

Comments

@arloan
Copy link

arloan commented Jul 15, 2018

rackup -s Fishwife causes load exception:

stone$ rackup -s Fishwife
SLF4J: Failed to load class "org.slf4j.impl.StaticLoggerBinder".
SLF4J: Defaulting to no-operation (NOP) logger implementation
SLF4J: See http://www.slf4j.org/codes.html#StaticLoggerBinder for further details.
Bundler::GemRequireError: There was an error while trying to load the gem 'rjack-logback'.
Gem Load Error is: failed to coerce org.slf4j.helpers.NOPLoggerFactory to ch.qos.logback.core.Context
Backtrace for gem load error is:
/Users/stone/.rbenv/versions/jruby-9.1.17.0/lib/ruby/gems/shared/gems/rjack-logback-1.9.0-java/lib/rjack-logback.rb:191:in `initialize'
/Users/stone/.rbenv/versions/jruby-9.1.17.0/lib/ruby/gems/shared/gems/rjack-logback-1.9.0-java/lib/rjack-logback.rb:200:in `<module:AppenderUtil>'
/Users/stone/.rbenv/versions/jruby-9.1.17.0/lib/ruby/gems/shared/gems/rjack-logback-1.9.0-java/lib/rjack-logback.rb:199:in `<module:Logback>'
/Users/stone/.rbenv/versions/jruby-9.1.17.0/lib/ruby/gems/shared/gems/rjack-logback-1.9.0-java/lib/rjack-logback.rb:79:in `<module:RJack>'
/Users/stone/.rbenv/versions/jruby-9.1.17.0/lib/ruby/gems/shared/gems/rjack-logback-1.9.0-java/lib/rjack-logback.rb:20:in `<main>'
org/jruby/RubyKernel.java:956:in `require'
/Users/stone/.rbenv/versions/jruby-9.1.17.0/lib/ruby/gems/shared/gems/bundler-1.16.2/lib/bundler/runtime.rb:1:in `block in (root)'
org/jruby/RubyArray.java:1735:in `each'
/Users/stone/.rbenv/versions/jruby-9.1.17.0/lib/ruby/gems/shared/gems/bundler-1.16.2/lib/bundler/runtime.rb:81:in `block in require'
org/jruby/RubyArray.java:1735:in `each'
/Users/stone/.rbenv/versions/jruby-9.1.17.0/lib/ruby/gems/shared/gems/bundler-1.16.2/lib/bundler/runtime.rb:76:in `require'
/Users/stone/.rbenv/versions/jruby-9.1.17.0/lib/ruby/gems/shared/gems/bundler-1.16.2/lib/bundler/runtime.rb:65:in `require'
/Users/stone/.rbenv/versions/jruby-9.1.17.0/lib/ruby/gems/shared/gems/bundler-1.16.2/lib/bundler.rb:114:in `block in require'
org/jruby/RubyBasicObject.java:1691:in `instance_eval'
/Users/stone/RubymineProjects/AutoReimbursement/mas/config.ru:8:in `new_from_string'
/Users/stone/.rbenv/versions/jruby-9.1.17.0/lib/ruby/gems/shared/gems/rack-2.0.5/lib/rack/builder.rb:55:in `<eval>'
org/jruby/RubyKernel.java:995:in `eval'
/Users/stone/RubymineProjects/AutoReimbursement/mas/config.ru:1:in `new_from_string'
/Users/stone/.rbenv/versions/jruby-9.1.17.0/lib/ruby/gems/shared/gems/rack-2.0.5/lib/rack/builder.rb:49:in `new_from_string'
/Users/stone/.rbenv/versions/jruby-9.1.17.0/lib/ruby/gems/shared/gems/rack-2.0.5/lib/rack/builder.rb:40:in `parse_file'
/Users/stone/.rbenv/versions/jruby-9.1.17.0/lib/ruby/gems/shared/gems/rack-2.0.5/lib/rack/server.rb:319:in `build_app_and_options_from_config'
/Users/stone/.rbenv/versions/jruby-9.1.17.0/lib/ruby/gems/shared/gems/rack-2.0.5/lib/rack/server.rb:219:in `app'
/Users/stone/.rbenv/versions/jruby-9.1.17.0/lib/ruby/gems/shared/gems/rack-2.0.5/lib/rack/server.rb:354:in `wrapped_app'
/Users/stone/.rbenv/versions/jruby-9.1.17.0/lib/ruby/gems/shared/gems/rack-2.0.5/lib/rack/server.rb:283:in `start'
/Users/stone/.rbenv/versions/jruby-9.1.17.0/lib/ruby/gems/shared/gems/rack-2.0.5/lib/rack/server.rb:148:in `<main>'
org/jruby/RubyKernel.java:974:in `load'
/usr/local/bin/rackup:23:in `<main>'
Bundler Error Backtrace:

                   block in require at /Users/stone/.rbenv/versions/jruby-9.1.17.0/lib/ruby/gems/shared/gems/bundler-1.16.2/lib/bundler/runtime.rb:84
                               each at org/jruby/RubyArray.java:1735
                   block in require at /Users/stone/.rbenv/versions/jruby-9.1.17.0/lib/ruby/gems/shared/gems/bundler-1.16.2/lib/bundler/runtime.rb:76
                               each at org/jruby/RubyArray.java:1735
                            require at /Users/stone/.rbenv/versions/jruby-9.1.17.0/lib/ruby/gems/shared/gems/bundler-1.16.2/lib/bundler/runtime.rb:65
                            require at /Users/stone/.rbenv/versions/jruby-9.1.17.0/lib/ruby/gems/shared/gems/bundler-1.16.2/lib/bundler.rb:114
           block in new_from_string at /Users/stone/RubymineProjects/AutoReimbursement/mas/config.ru:8
                      instance_eval at org/jruby/RubyBasicObject.java:1691
                         initialize at /Users/stone/.rbenv/versions/jruby-9.1.17.0/lib/ruby/gems/shared/gems/rack-2.0.5/lib/rack/builder.rb:55
                             <eval> at /Users/stone/RubymineProjects/AutoReimbursement/mas/config.ru:1
                               eval at org/jruby/RubyKernel.java:995
                    new_from_string at /Users/stone/.rbenv/versions/jruby-9.1.17.0/lib/ruby/gems/shared/gems/rack-2.0.5/lib/rack/builder.rb:49
                         parse_file at /Users/stone/.rbenv/versions/jruby-9.1.17.0/lib/ruby/gems/shared/gems/rack-2.0.5/lib/rack/builder.rb:40
  build_app_and_options_from_config at /Users/stone/.rbenv/versions/jruby-9.1.17.0/lib/ruby/gems/shared/gems/rack-2.0.5/lib/rack/server.rb:319
                                app at /Users/stone/.rbenv/versions/jruby-9.1.17.0/lib/ruby/gems/shared/gems/rack-2.0.5/lib/rack/server.rb:219
                        wrapped_app at /Users/stone/.rbenv/versions/jruby-9.1.17.0/lib/ruby/gems/shared/gems/rack-2.0.5/lib/rack/server.rb:354
                              start at /Users/stone/.rbenv/versions/jruby-9.1.17.0/lib/ruby/gems/shared/gems/rack-2.0.5/lib/rack/server.rb:283
                              start at /Users/stone/.rbenv/versions/jruby-9.1.17.0/lib/ruby/gems/shared/gems/rack-2.0.5/lib/rack/server.rb:148
                             <main> at /Users/stone/.rbenv/versions/jruby-9.1.17.0/lib/ruby/gems/shared/gems/rack-2.0.5/bin/rackup:4
                               load at org/jruby/RubyKernel.java:974
                             <main> at /usr/local/bin/rackup:23

While simple run fishwife, the app starts with rack default handler WEBrick:

stone$ fishwife
307  [main] INFO  org.eclipse.jetty.util.log - Logging initialized @4406ms to org.eclipse.jetty.util.log.Slf4jLog 
[2018-07-15 10:33:00] INFO  WEBrick 1.3.1
[2018-07-15 10:33:00] INFO  ruby 2.3.3 (2018-04-20) [java]
[2018-07-15 10:33:00] INFO  WEBrick::HTTPServer#start: pid=91462 port=3001

jruby 9.1.7.0 @ macos 10.12.6

stone$ java -version
java version "1.8.0_131"
Java(TM) SE Runtime Environment (build 1.8.0_131-b11)
Java HotSpot(TM) 64-Bit Server VM (build 25.131-b11, mixed mode)

config.ru:

#\ -p 3001
# encoding: utf-8

APP_ROOTDIR = File.expand_path(File.dirname(__FILE__))
$: << File.join(APP_ROOTDIR, 'lib')

require 'bundler/setup'
Bundler.require(:default)

require 'common/app_const'

class AppConst
  AppName = 'mas'
end

if defined? Fishwife
  RJack::Logback.config_console( :stderr => true, :thread => true )
end

AppConfig.setup(AppConst::AppName, APP_ROOTDIR, File.join(APP_ROOTDIR, 'config'))
MAIN_CONFIG = AppConfig.get_config
COMMON_CONFIG = AppConfig.get_config 'common'

DB = Sequel::connect(COMMON_CONFIG['db.conn'])

require 'app'

$stdout.sync = true unless $stdout.isatty
$stderr.sync = true unless $stderr.isatty

begin
  run Cuba
ensure
  DB.disconnect
end

Gemfile:

source 'https://rubygems.org'

gem 'appconf'
gem 'cuba'
# gem 'cuba-sendfile' # this gem does not work any more
gem 'rack-protection', :require => 'rack/protection'
gem 'cuba-sugar', :require => false
gem 'faraday'
gem 'faraday_middleware'
gem 'sequel'

gem 'jruby-jars', '9.1.17.0', :require => false # newest 9.2.0.0 has a bug that .war does not load for error: 'no such file to load -- bundler/shared_helpers'
gem 'jruby-openssl', :platforms => :jruby
gem 'jdbc-sqlite3', :require => false, :platforms => :jruby
gem 'fishwife', :platforms => :jruby
gem 'rjack-logback', :platforms => :jruby

install_if -> { not defined? JRUBY_VERSION } do
  gem 'sqlite3'
  gem 'openssl'
  gem 'thin'
end

Gemfile.lock:

GEM
  remote: https://rubygems.org/
  specs:
    appconf (0.1.0)
    cuba (3.9.2)
      rack (>= 1.6.0)
    cuba-sugar (0.3.1)
      cuba (~> 3.3)
      json (~> 1.7)
      rack_csrf (~> 2.4)
    daemons (1.2.6)
    eventmachine (1.2.7)
    eventmachine (1.2.7-java)
    faraday (0.15.2)
      multipart-post (>= 1.2, < 3)
    faraday_middleware (0.12.2)
      faraday (>= 0.7.4, < 1.0)
    fishwife (1.10.0-java)
      rack (>= 1.6.4, < 2.1)
      rjack-jetty (>= 9.2.11, < 9.5)
      rjack-slf4j (~> 1.7.2)
    jdbc-sqlite3 (3.20.1)
    jruby-jars (9.1.17.0)
    jruby-openssl (0.10.1-java)
    json (1.8.6)
    json (1.8.6-java)
    multipart-post (2.0.0)
    openssl (2.1.0)
    rack (2.0.5)
    rack-protection (2.0.3)
      rack
    rack_csrf (2.6.0)
      rack (>= 1.1.0)
    rjack-jetty (9.4.6.0-java)
    rjack-logback (1.9.0-java)
      rjack-slf4j (~> 1.7.16)
    rjack-slf4j (1.7.25.0-java)
    sequel (5.9.0)
    sqlite3 (1.3.13)
    thin (1.7.2)
      daemons (~> 1.0, >= 1.0.9)
      eventmachine (~> 1.0, >= 1.0.4)
      rack (>= 1, < 3)

PLATFORMS
  java
  ruby

DEPENDENCIES
  appconf
  cuba
  cuba-sugar
  faraday
  faraday_middleware
  fishwife
  jdbc-sqlite3
  jruby-jars (= 9.1.17.0)
  jruby-openssl
  openssl
  rack-protection
  rjack-logback
  sequel
  sqlite3
  thin

BUNDLED WITH
   1.16.2

If I remove 'gem rjack-logback' from Gemfile, and remove RJack::Logback.config_console( :stderr => true, :thread => true ) call from config.ru, then rackup command will freeze on loading.

stone$ rackup -s Fishwife
SLF4J: Failed to load class "org.slf4j.impl.StaticLoggerBinder".
SLF4J: Defaulting to no-operation (NOP) logger implementation
SLF4J: See http://www.slf4j.org/codes.html#StaticLoggerBinder for further details.

---> loading process freezed here

In this case, use fishwife instead, app runs with rack handler fallback to WEBrick, simply the same case with gem rjack-logback included with Gemfile.

@arloan
Copy link
Author

arloan commented Jul 15, 2018

Further: mizuno works fine both with rackup command or mizuno command directly.

@dekellum
Copy link
Owner

I don't think mizuno sets up logging in any similar way. I can't reproduce this, yet. I upgraded to jruby 9.1.17. My best guess is that somewhere your are loading an incompatible version of SLF4J jar prior to fishwife trying to load rjack-logback gem and rjack-slf4j (packaging its own version of that jar.) There may have been later releases of these that are incompatible with, ahead of the rjack-logback/slf4j versions?

Does your loading jruby-jars end up doing that? Why do you need that?

@dekellum
Copy link
Owner

Please provide a minimal, self contained, reproducible case. For example, you could start with the fishwife (source tree) example/config.ru and modify until it fails in the same way.

@arloan
Copy link
Author

arloan commented Jul 18, 2018

@dekellum
I used 2 files to re-pro this problem, Gemfile & config.ru:

Gemfile:

source 'https://rubygems.org'

gem 'cuba'

gem 'fishwife', :platforms => :jruby
gem 'rjack-logback', :platforms => :jruby

config.ru:

require 'bundler/setup'
Bundler.require(:default)

if defined?(Fishwife) && defined?(RJack::Logback)
  RJack::Logback.config_console( :stderr => true, :thread => true )
end

Cuba.define do
	on root do
		res.write '<h1>Hello, world!</h1>'
	end
end

run Cuba

Generated Gemfile.lock with bundler:

GEM
  remote: https://rubygems.org/
  specs:
    cuba (3.9.2)
      rack (>= 1.6.0)
    fishwife (1.10.0-java)
      rack (>= 1.6.4, < 2.1)
      rjack-jetty (>= 9.2.11, < 9.5)
      rjack-slf4j (~> 1.7.2)
    rack (2.0.5)
    rjack-jetty (9.4.6.0-java)
    rjack-logback (1.9.0-java)
      rjack-slf4j (~> 1.7.16)
    rjack-slf4j (1.7.25.0-java)

PLATFORMS
  java

DEPENDENCIES
  cuba
  fishwife
  rjack-logback

BUNDLED WITH
   1.16.2

Behavior:

  • fishwife commands falls back to WEBrick silently.
  • rackup or rackup -s Fishwife produces load error exactly as my first post above.

If I remove rjack-logback gem from Gemfile, then the behavior changes as:

  • rackup or fishwife falls back to WEBrick silently.
  • rackup -s Fishwife freezes after these lines below:
stone$ rackup -s Fishwife
SLF4J: Failed to load class "org.slf4j.impl.StaticLoggerBinder".
SLF4J: Defaulting to no-operation (NOP) logger implementation
SLF4J: See http://www.slf4j.org/codes.html#StaticLoggerBinder for further details.

Environment:

bogon: ~/tmp/fishwife.test ]
stone$ jruby -v
jruby 9.1.17.0 (2.3.3) 2018-04-20 d8b1ff9 Java HotSpot(TM) 64-Bit Server VM 25.131-b11 on 1.8.0_131-b11 +jit [darwin-x86_64]
bogon: ~/tmp/fishwife.test ]
stone$ java -version
java version "1.8.0_131"
Java(TM) SE Runtime Environment (build 1.8.0_131-b11)
Java HotSpot(TM) 64-Bit Server VM (build 25.131-b11, mixed mode)
bogon: ~/tmp/fishwife.test ]
stone$ 

@ macOS 10.12.6

@dekellum
Copy link
Owner

dekellum commented Jul 18, 2018

When you say "freezes", is your server just running but without console logging (given logging setup failed)? In your original report:

Gem Load Error is: failed to coerce org.slf4j.helpers.NOPLoggerFactory to ch.qos.logback.core.Context

Isn't reproduced in your minimized case?

I'm not familiar with cuba gem, can your factor that out as well, and still repro (e.g. simple rack app)?

Also you might try jruby -S bundle exec fishwife config.ru (just to be certain of env) and removing the bundler/setup and Bundler.require from your config.ru?

@arloan
Copy link
Author

arloan commented Jul 19, 2018

@dekellum

I tested again with dead simple Gemfile/config.ru, and the result is exactly same as in my previous post, while I do found a mistake I wrote. When I said 'freeze', the server actually worked, I was misled because every other rack handler will report the ip-address and/or port it listens on, while fishwife doesn't output anything like that. I'll repeat the result here for clear reading, and with additional test result of bundle exec case (removing the bundler/setup and Bundler.require):

  1. with rjack-logback gem:
  • rackup or rackup -s Fishwife produces load error on gem 'rjack-logback'
  • fishwife falls back to WEBrick
  • jruby -S bundle exec fishwife config.ru (without the bundler/setup and Bundler.require) falls back to WEBrick
  1. without rjack-logback gem:
  • rackup or fishwife comes up with WEBrick
  • rackup -s Fishwife: works (with NOP logger implementation, though)
  • jruby -S bundle exec fishwife config.ru (without the bundler/setup and Bundler.require) falls back to WEBrick

Gemfile:

source 'https://rubygems.org'

gem 'fishwife', :platforms => :jruby
gem 'rjack-logback', :platforms => :jruby

config.ru

require 'bundler/setup'
Bundler.require(:default)

if defined?(Fishwife) && defined?(RJack::Logback)
  RJack::Logback.config_console( :stderr => true, :thread => true )
end

run proc { |env| [200, {}, ['<h1>hello, world!</h1>'] ] }

Gemfile.lock (produced with gem 'rjack-logback')

GEM
  remote: https://rubygems.org/
  specs:
    fishwife (1.10.0-java)
      rack (>= 1.6.4, < 2.1)
      rjack-jetty (>= 9.2.11, < 9.5)
      rjack-slf4j (~> 1.7.2)
    rack (2.0.5)
    rjack-jetty (9.4.6.0-java)
    rjack-logback (1.9.0-java)
      rjack-slf4j (~> 1.7.16)
    rjack-slf4j (1.7.25.0-java)

PLATFORMS
  java

DEPENDENCIES
  fishwife
  rjack-logback

BUNDLED WITH
   1.16.2

Gemfile.lock (without gem 'rjack-logback')

GEM
  remote: https://rubygems.org/
  specs:
    fishwife (1.10.0-java)
      rack (>= 1.6.4, < 2.1)
      rjack-jetty (>= 9.2.11, < 9.5)
      rjack-slf4j (~> 1.7.2)
    rack (2.0.5)
    rjack-jetty (9.4.6.0-java)
    rjack-slf4j (1.7.25.0-java)

PLATFORMS
  java

DEPENDENCIES
  fishwife

BUNDLED WITH
   1.16.2

@dekellum
Copy link
Owner

OK, I'm able to reproduce both of the two issues you are seeing. Firstly regarding WEBrick being run from the fishwife command: It appears that somewhere >= rack 2.0 it has become necessary to use the -s Fishwife (or --server) flag on the fishwife command line to get Fishwife to actually load. Note this can also be added to the config.ru, as the following initial line:

#\ -s Fishwife

Alternatively if you add a dependency for rack ~> 1.6.4 (currently resolves to 1.6.10) then that flag is not required. I'm not sure what has changed (last I looked, rack hasn't maintained a changelog) and testing with rack 2 has been limited here. It would be desirable to fix that in a way that continues to support rack 1.6.

Regarding the other logging initialization issue when using rackup, rjack-logback needs to be loaded and configured before the first log line is written (during jetty startup). That is a feature of the fact that the SLF4J output impl. binding happens in the java classpath. Modifying your config.ru, while still preserving its ability to run on MRI ruby:

if RUBY_PLATFORM =~ /java/
  require 'rjack-logback'
  RJack::Logback.config_console( :stderr => true, :thread => true )
end

run proc { |env| [200, {}, ['<h1>hello, world!</h1>'] ] }

This works with jruby -S bundle exec rackup -s Fishwife.

So there are workarounds for both issues and some potential fixes can be made to make it harder to encounter these in the first place.

dekellum added a commit that referenced this issue Jul 19, 2018
Previously this was relying on in-place mutation which is no longer
supported in rack 2.0

github: #20
@dekellum
Copy link
Owner

ffcfe5c fixes the need for fishwife -s Fishwife with rack 2.x.

@arloan
Copy link
Author

arloan commented Jul 20, 2018

confirmed. thank u very much.

@arloan arloan closed this as completed Jul 20, 2018
@dekellum
Copy link
Owner

released to rubygems as fishwife 1.10.1

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

2 participants