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

NPE when printing a variable in a view #4641

Closed
alaz opened this issue Jun 1, 2017 · 7 comments
Closed

NPE when printing a variable in a view #4641

alaz opened this issue Jun 1, 2017 · 7 comments

Comments

@alaz
Copy link

alaz commented Jun 1, 2017

Environment

  • JRuby: 9.1.9 and 9.1.10. Reverting to 9.1.8 fixes the problem
  • Operating system and platform: official Docker images
  • Application/framework version: Rails 5.0.3
  • Environment variables:
JRUBY_OPTS=--server  -Xjit.threshold=5 -Xjit.max=16384 -Xcompile.invokedynamic=false
JAVA_OPTS=-Xms1G -Xmx1G -XX:ReservedCodeCacheSize=128M -XX:+UseCodeCacheFlushing -Duser.timezone=GMT -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/logs -Dcom.sun.management.jmxremote -Dcom.sun.management.jmxremote.ssl=false -Dcom.sun.management.jmxremote.authenticate=false -Dorg.apache.camel.jmx.serviceUrlPath=\"/jmxrmi\" -Dcom.sun.management.jmxremote.port=9073

Behavior

MRI and 9.1.8 show the template fine. 9.1.9 and 9.1.10 genrate a NPE:

I, [2017-06-01T15:53:49.906088 #1]  INFO -- : Write fragment views/pictures/asides/57ed3a75622e73832
132713ad509003d (1.1ms)
I, [2017-06-01T15:53:50.039642 #1]  INFO -- :   Rendered collection of admin/stream/pictures/_pictur
e.html.erb [50 times] (132.5ms)
I, [2017-06-01T15:53:50.043756 #1]  INFO -- :   Rendered admin/stream/pictures/hosted.html.erb withi
n layouts/admin (500.7ms)
I, [2017-06-01T15:53:50.044603 #1]  INFO -- : Completed 500 Internal Server Error in 536ms (ActiveRe
cord: 81.4ms)
F, [2017-06-01T15:53:50.046648 #1] FATAL -- :   
F, [2017-06-01T15:53:50.046784 #1] FATAL -- : ActionView::Template::Error (ExecutionException waiting for value: java.lang.NullPointerException):
F, [2017-06-01T15:53:50.047148 #1] FATAL -- :     32:           <%= @pagination_fine %>
    33:         </nav>
    34: 
    35:         <div class="row">
    36:           <%= render collection: @pictures, partial: 'picture', layout: 'col', cached: true 
%>
    37:         </div>
    38: 
F, [2017-06-01T15:53:50.047267 #1] FATAL -- :   
F, [2017-06-01T15:53:50.047405 #1] FATAL -- : app/views/admin/stream/pictures/hosted.html.erb:35:in `_app_views_admin_stream_pictures_hosted_html_erb___884846157_2150'

Sorry I failed to build a minimal example. Please tell me what options I should use to create a stack trace.

@kares
Copy link
Member

kares commented Jun 2, 2017

seems like its coming from an executor (ExecutionException will be AS's Concurrent::Future error wrapper)
thus I wonder if the ActionView::Template::Error get a cause or simply just an error message here ...

you could try -Xbacktrace.style=raw -Xcli.debug=true but I am not sure it will be logged since it might be coming from a native part, in which case I would try to setup Concurrent Ruby's logger for more details ...

@alaz
Copy link
Author

alaz commented Jun 2, 2017

Thank you @kares. New information, but not too much:

Exception `Spymemcached::Error' at java/lang/Thread.java:1556 - ExecutionException waiting for value: java.lang.NullPointerException
Exception `ActionView::Template::Error' at java/lang/Thread.java:1556 - ExecutionException waiting for value: java.lang.NullPointerException
Exception `ActionView::Template::Error' at java/lang/Thread.java:1556 - ExecutionException waiting for value: java.lang.NullPointerException
Exception `ActionView::Template::Error' at java/lang/Thread.java:1556 - ExecutionException waiting for value: java.lang.NullPointerException
Exception `ActionView::Template::Error' at java/lang/Thread.java:1556 - ExecutionException waiting for value: java.lang.NullPointerException
Exception `ActionView::Template::Error' at java/lang/Thread.java:1556 - ExecutionException waiting for value: java.lang.NullPointerException
Exception `ActionView::Template::Error' at java/lang/Thread.java:1556 - ExecutionException waiting for value: java.lang.NullPointerException
Exception `NoMethodError' at java/lang/Thread.java:1556 - undefined method `join' for nil:NilClass
Did you mean?  JSON

@kares
Copy link
Member

kares commented Jun 2, 2017

@alaz thanks, this time we were right its smt about native ext ... and actually this time not in JRuby
wonder what changed with JRuby that would cause it to be exhibit, are you on latest spymemcached gem?

@alaz
Copy link
Author

alaz commented Jun 2, 2017

Gemfile.lock fragment:

    spymemcached.jruby (1.0.16-java)
    spymemcached_store (1.0.2-java)
      spymemcached.jruby

@headius
Copy link
Member

headius commented Jun 13, 2017

If it's easy for you to reproduce, could you perhaps bisect JRuby between 9.1.8.0 and 9.1.9.0 and see what we changed?

We might get better stack traces with -d or -w or -Xbacktrace.style=full passed to JRuby.

Without a local reproduction it will be a bit tricky to sort out, but it shouldn't be too tough to find the issue if you bisect.

@alaz
Copy link
Author

alaz commented Jun 13, 2017

Result:

$ git bisect good
64c7ea04829a77cf5eac2f368bb3e0131ac37646 is the first bad commit
commit 64c7ea04829a77cf5eac2f368bb3e0131ac37646
Author: Charles Oliver Nutter <headius@headius.com>
Date:   Thu Mar 9 13:22:22 2017 -0600

    Accept nil proc in Marshal.load. Fixes #4526.

:040000 040000 4dd9dec886f356a0cb17dd5625b67f20b911d31d ab4b13eb8d7f776a929a83969867e891df47c575 M	core

Log:

# bad: [28aa8305faf98a9170366200598060ab2d9d4f6d] Update for 9.1.9.
# good: [90fc7ab0191bb8fba8e152ff4c7ffc19debb448f] Update version for 9.1.8.0
git bisect start '9.1.9.0' '9.1.8.0'
# bad: [c47fef80589387d984d18b8cf4ba8d5aeb147721] Add tag as thread.rb/jar is not a yet a provided feature on JRuby
git bisect bad c47fef80589387d984d18b8cf4ba8d5aeb147721
# bad: [b6e06de99ab64c9b7d98aae8397e60d137ef9250] Implement pgroup for spawn and untag working specs.
git bisect bad b6e06de99ab64c9b7d98aae8397e60d137ef9250
# bad: [8f44866212f18b90ea21c2467015125efe4782cf] Naughty bytecode.  Should invoke it as a static and not an instance method...
git bisect bad 8f44866212f18b90ea21c2467015125efe4782cf
# good: [1d61432ca87601d19681cb1291ac36d915b3f1d4] More complicated logic to follow if last argument is named hash or just a plain hash. Improved name reporting to match exact strings in MRI a little closer Removed tags which now pass.
git bisect good 1d61432ca87601d19681cb1291ac36d915b3f1d4
# bad: [bafb4f5a04f7f8ced72a7552f42c97fd9dd4d9cc] Check pseudo-errno for error rather than real errno. Fixes #4527.
git bisect bad bafb4f5a04f7f8ced72a7552f42c97fd9dd4d9cc
# bad: [64c7ea04829a77cf5eac2f368bb3e0131ac37646] Accept nil proc in Marshal.load. Fixes #4526.
git bisect bad 64c7ea04829a77cf5eac2f368bb3e0131ac37646
# good: [0c749ca88da7c40fbef45a5af9a01423367745c3] Update launchers to fix #4519.
git bisect good 0c749ca88da7c40fbef45a5af9a01423367745c3
# first bad commit: [64c7ea04829a77cf5eac2f368bb3e0131ac37646] Accept nil proc in Marshal.load. Fixes #4526.

@enebo
Copy link
Member

enebo commented Jun 13, 2017

@alaz ah excellent. That commit stopped null checking and if we look here:

https://github.com/ThoughtWorksStudios/spymemcached.jruby/blob/master/ext/spymemcached_adapter/SpymemcachedAdapter.java#L50

Boom. I will add a null check to the constructor and convert it to a nil if present so we don't break this.

@enebo enebo closed this as completed in b132a18 Jun 13, 2017
@enebo enebo added this to the JRuby 9.1.11.0 milestone Jun 13, 2017
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

No branches or pull requests

4 participants