Skip to content
This repository has been archived by the owner on Jan 19, 2022. It is now read-only.

null pointer exception in Mondrian #151

Closed
hwchen opened this issue Oct 2, 2018 · 11 comments
Closed

null pointer exception in Mondrian #151

hwchen opened this issue Oct 2, 2018 · 11 comments
Assignees
@jspeis @hwchen

Comments

@hwchen
Copy link

hwchen commented Oct 2, 2018

Ipeds completions cube developed a null pointer exception when drilling down on University dimension.

Trace was unhelpful, only noting that a null pointer exception occurred during generation of the sql query. (Unfortunately, I lost the exact trace, but it wasn't that helpful).

Flushing Mondrian fixed the problem.
@jspeis
Copy link
Member

jspeis commented Oct 3, 2018

@hwchen can you share a link that replicates the issue or the link to a query where the issues originally occured?

@hwchen
Copy link
Author

hwchen commented Oct 3, 2018

@jspeis unfortunately I don't know if the issue is replicable.

Before flush, this query reliably gave an error:
https://canon-api.datausa.io/cubes/ipeds_completions/aggregate.csv?drilldown%5B%5D=%5BYear%5D.%5BYear%5D.%5BYear%5D&drilldown%5B%5D=%5BUniversity%5D.%5BUniversity%5D.%5BUniversity%5D&measures%5B%5D=Completions&debug=false&parents=false&nonempty=false&distinct=false&sparse=false

@jspeis
Copy link
Member

jspeis commented Oct 4, 2018

@hwchen would you be able to check the journalctl logs for both the cube and site services? (hopefully one of them would have logged the underlying error)

@hwchen
Copy link
Author

hwchen commented Oct 4, 2018

from canon site logs, here's the trace:

Oct 04 05:43:44 canon npm[359951]: Cube Error 400 Bad Request
Oct 04 05:43:44 canon npm[359951]: { error:
Oct 04 05:43:44 canon npm[359951]:    [ 'root cause: java.lang.NullPointerException: ',
Oct 04 05:43:44 canon npm[359951]:      'mondrian/olap4j/MondrianOlap4jConnection.java:858:in `createException\'',
Oct 04 05:43:44 canon npm[359951]:      'mondrian/olap4j/MondrianOlap4jStatement.java:423:in `executeOlapQueryInternal\'',
Oct 04 05:43:44 canon npm[359951]:      'mondrian/olap4j/MondrianOlap4jPreparedStatement.java:72:in `executeQuery\'',
Oct 04 05:43:44 canon npm[359951]:      'mondrian/olap4j/MondrianOlap4jPreparedStatement.java:42:in `executeQuery\'',
Oct 04 05:43:44 canon npm[359951]:      'java/lang/reflect/Method.java:498:in `invoke\'',
Oct 04 05:43:44 canon npm[359951]:      'org/jruby/javasupport/JavaMethod.java:438:in `invokeDirectWithExceptionHandling\'',
Oct 04 05:43:44 canon npm[359951]:      'org/jruby/javasupport/JavaMethod.java:302:in `invokeDirect\'',
Oct 04 05:43:44 canon npm[359951]:      'home/deploy/$_dot_rvm/gems/jruby_minus_9_dot_1_dot_13_dot_0/gems/mondrian_minus_olap_minus_0_dot_8_dot_0/lib/mondrian/olap//home/deploy/.rvm/gems/jruby-9.1.13.0/gems/mondrian-olap-0.8.0/lib/mondrian/olap/connection.rb:80:in `invokeOther3:executeQuery\'',
Oct 04 05:43:44 canon npm[359951]:      'home/deploy/$_dot_rvm/gems/jruby_minus_9_dot_1_dot_13_dot_0/gems/mondrian_minus_olap_minus_0_dot_8_dot_0/lib/mondrian/olap//home/deploy/.rvm/gems/jruby-9.1.13.0/gems/mondrian-olap-0.8.0/lib/mondrian/olap/connection.rb:80:in `block in execute\'',
Oct 04 05:43:44 canon npm[359951]:      'home/deploy/$_dot_rvm/gems/jruby_minus_9_dot_1_dot_13_dot_0/gems/mondrian_minus_olap_minus_0_dot_8_dot_0/lib/mondrian/olap//home/deploy/.rvm/gems/jruby-9.1.13.0/gems/mondrian-olap-0.8.0/lib/mondrian/olap/error.rb:19:in `wrap_native_exception\'',
Oct 04 05:43:44 canon npm[359951]:      'home/deploy/$_dot_rvm/gems/jruby_minus_9_dot_1_dot_13_dot_0/gems/mondrian_minus_olap_minus_0_dot_8_dot_0/lib/mondrian/olap//home/deploy/.rvm/gems/jruby-9.1.13.0/gems/mondrian-olap-0.8.0/lib/mondrian/olap/connection.rb:77:in `invokeOther6:wrap_native_exception\'',
Oct 04 05:43:44 canon npm[359951]:      'home/deploy/$_dot_rvm/gems/jruby_minus_9_dot_1_dot_13_dot_0/gems/mondrian_minus_olap_minus_0_dot_8_dot_0/lib/mondrian/olap//home/deploy/.rvm/gems/jruby-9.1.13.0/gems/mondrian-olap-0.8.0/lib/mondrian/olap/connection.rb:77:in `execute\'',
Oct 04 05:43:44 canon npm[359951]:      'home/deploy/$_dot_rvm/gems/jruby_minus_9_dot_1_dot_13_dot_0/gems/mondrian_minus_rest_minus_1_dot_0_dot_0_minus_java/lib/mondrian_rest//home/deploy/.rvm/gems/jruby-9.1.13.0/gems/mondrian-rest-1.0.0-java/lib/mondrian_rest/api_helpers.rb:45:in `invokeOther5:execute\'',
Oct 04 05:43:44 canon npm[359951]:      'home/deploy/$_dot_rvm/gems/jruby_minus_9_dot_1_dot_13_dot_0/gems/mondrian_minus_rest_minus_1_dot_0_dot_0_minus_java/lib/mondrian_rest//home/deploy/.rvm/gems/jruby-9.1.13.0/gems/mondrian-rest-1.0.0-java/lib/mondrian_rest/api_helpers.rb:45:in `mdx\'',
Oct 04 05:43:44 canon npm[359951]:      'home/deploy/$_dot_rvm/gems/jruby_minus_9_dot_1_dot_13_dot_0/gems/mondrian_minus_rest_minus_1_dot_0_dot_0_minus_java/lib/mondrian_rest//home/deploy/.rvm/gems/jruby-9.1.13.0/gems/mondrian-rest-1.0.0-java/lib/mondrian_rest/api_helpers.rb:60:in `invokeOther6:mdx\'',
Oct 04 05:43:44 canon npm[359951]:      'home/deploy/$_dot_rvm/gems/jruby_minus_9_dot_1_dot_13_dot_0/gems/mondrian_minus_rest_minus_1_dot_0_dot_0_minus_java/lib/mondrian_rest//home/deploy/.rvm/gems/jruby-9.1.13.0/gems/mondrian-rest-1.0.0-java/lib/mondrian_rest/api_helpers.rb:60:in `run_from_params\'',
Oct 04 05:43:44 canon npm[359951]:      'home/deploy/$_dot_rvm/gems/jruby_minus_9_dot_1_dot_13_dot_0/gems/mondrian_minus_rest_minus_1_dot_0_dot_0_minus_java/lib/mondrian_rest//home/deploy/.rvm/gems/jruby-9.1.13.0/gems/mondrian-rest-1.0.0-java/lib/mondrian_rest/api.rb:152:in `invokeOther1:run_from_params\'',
Oct 04 05:43:44 canon npm[359951]:      'home/deploy/$_dot_rvm/gems/jruby_minus_9_dot_1_dot_13_dot_0/gems/mondrian_minus_rest_minus_1_dot_0_dot_0_minus_java/lib/mondrian_rest//home/deploy/.rvm/gems/jruby-9.1.13.0/gems/mondrian-rest-1.0.0-java/lib/mondrian_rest/api.rb:152:in `block in Api\'',
Oct 04 05:43:44 canon npm[359951]:      'org/jruby/RubyProc.java:289:in `call\'',
Oct 04 05:43:44 canon npm[359951]:      'org/jruby/RubyMethod.java:111:in `call\'',
Oct 04 05:43:44 canon npm[359951]:      'org/jruby/RubyMethod$INVOKER$i$call.gen:-1:in `call\'',
Oct 04 05:43:44 canon npm[359951]:      'home/deploy/$_dot_rvm/gems/jruby_minus_9_dot_1_dot_13_dot_0/gems/grape_minus_1_dot_0_dot_2/lib/grape//home/deploy/.rvm/gems/jruby-9.1.13.0/gems/grape-1.0.2/lib/grape/endpoint.rb:57:in `invokeOther1:call\'',
Oct 04 05:43:44 canon npm[359951]:      'home/deploy/$_dot_rvm/gems/jruby_minus_9_dot_1_dot_13_dot_0/gems/grape_minus_1_dot_0_dot_2/lib/grape//home/deploy/.rvm/gems/jruby-9.1.13.0/gems/grape-1.0.2/lib/grape/endpoint.rb:57:in `block in generate_api_method\'',
Oct 04 05:43:44 canon npm[359951]:      'home/deploy/$_dot_rvm/gems/jruby_minus_9_dot_1_dot_13_dot_0/gems/activesupport_minus_5_dot_1_dot_6/lib/active_support//home/deploy/.rvm/gems/jruby-9.1.13.0/gems/activesupport-5.1.6/lib/active_support/notifications.rb:168:in `instrument\'',
Oct 04 05:43:44 canon npm[359951]:      'home/deploy/$_dot_rvm/gems/jruby_minus_9_dot_1_dot_13_dot_0/gems/grape_minus_1_dot_0_dot_2/lib/grape//home/deploy/.rvm/gems/jruby-9.1.13.0/gems/grape-1.0.2/lib/grape/endpoint.rb:56:in `invokeOther6:instrument\'',
Oct 04 05:43:44 canon npm[359951]:      'home/deploy/$_dot_rvm/gems/jruby_minus_9_dot_1_dot_13_dot_0/gems/grape_minus_1_dot_0_dot_2/lib/grape//home/deploy/.rvm/gems/jruby-9.1.13.0/gems/grape-1.0.2/lib/grape/endpoint.rb:56:in `block in generate_api_method\'',
Oct 04 05:43:44 canon npm[359951]:      'org/jruby/RubyProc.java:289:in `call\'',
Oct 04 05:43:44 canon npm[359951]:      'org/jruby/RubyProc.java:273:in `call19\'',
Oct 04 05:43:44 canon npm[359951]:      'org/jruby/RubyProc$INVOKER$i$0$0$call19.gen:-1:in `call\'',
Oct 04 05:43:44 canon npm[359951]:      'home/deploy/$_dot_rvm/gems/jruby_minus_9_dot_1_dot_13_dot_0/gems/grape_minus_1_dot_0_dot_2/lib/grape//home/deploy/.rvm/gems/jruby-9.1.13.0/gems/grape-1.0.2/lib/grape/endpoint.rb:262:in `invokeOther47:call\'',
Oct 04 05:43:44 canon npm[359951]:      'home/deploy/$_dot_rvm/gems/jruby_minus_9_dot_1_dot_13_dot_0/gems/grape_minus_1_dot_0_dot_2/lib/grape//home/deploy/.rvm/gems/jruby-9.1.13.0/gems/grape-1.0.2/lib/grape/endpoint.rb:262:in `block in run\'',
Oct 04 05:43:44 canon npm[359951]:      'home/deploy/$_dot_rvm/gems/jruby_minus_9_dot_1_dot_13_dot_0/gems/activesupport_minus_5_dot_1_dot_6/lib/active_support//home/deploy/.rvm/gems/jruby-9.1.13.0/gems/activesupport-5.1.6/lib/active_support/notifications.rb:168:in `instrument\'',
Oct 04 05:43:44 canon npm[359951]:      'home/deploy/$_dot_rvm/gems/jruby_minus_9_dot_1_dot_13_dot_0/gems/grape_minus_1_dot_0_dot_2/lib/grape//home/deploy/.rvm/gems/jruby-9.1.13.0/gems/grape-1.0.2/lib/grape/endpoint.rb:243:in `invokeOther69:instrument\'',
Oct 04 05:43:44 canon npm[359951]:      'home/deploy/$_dot_rvm/gems/jruby_minus_9_dot_1_dot_13_dot_0/gems/grape_minus_1_dot_0_dot_2/lib/grape//home/deploy/.rvm/gems/jruby-9.1.13.0/gems/grape-1.0.2/lib/grape/endpoint.rb:243:in `run\'',
Oct 04 05:43:44 canon npm[359951]:      'home/deploy/$_dot_rvm/gems/jruby_minus_9_dot_1_dot_13_dot_0/gems/grape_minus_1_dot_0_dot_2/lib/grape//home/deploy/.rvm/gems/jruby-9.1.13.0/gems/grape-1.0.2/lib/grape/endpoint.rb:313:in `invokeOther1:run\'',
Oct 04 05:43:44 canon npm[359951]:      'home/deploy/$_dot_rvm/gems/jruby_minus_9_dot_1_dot_13_dot_0/gems/grape_minus_1_dot_0_dot_2/lib/grape//home/deploy/.rvm/gems/jruby-9.1.13.0/gems/grape-1.0.2/lib/grape/endpoint.rb:313:in `block in build_stack\'',
Oct 04 05:43:44 canon npm[359951]:      'org/jruby/RubyProc.java:289:in `call\'',
Oct 04 05:43:44 canon npm[359951]:      'org/jruby/RubyProc.java:273:in `call19\'',
Oct 04 05:43:44 canon npm[359951]:      'org/jruby/RubyProc$INVOKER$i$0$0$call19.gen:-1:in `call\'',
Oct 04 05:43:44 canon npm[359951]:      'home/deploy/$_dot_rvm/gems/jruby_minus_9_dot_1_dot_13_dot_0/gems/grape_minus_1_dot_0_dot_2/lib/grape/middleware//home/deploy/.rvm/gems/jruby-9.1.13.0/gems/grape-1.0.2/lib/grape/middleware/base.rb:31:in `invokeOther4:call\'',
Oct 04 05:43:44 canon npm[359951]:      'home/deploy/$_dot_rvm/gems/jruby_minus_9_dot_1_dot_13_dot_0/gems/grape_minus_1_dot_0_dot_2/lib/grape/middleware//home/deploy/.rvm/gems/jruby-9.1.13.0/gems/grape-1.0.2/lib/grape/middleware/base.rb:31:in `call!\'',
Oct 04 05:43:44 canon npm[359951]:      'home/deploy/$_dot_rvm/gems/jruby_minus_9_dot_1_dot_13_dot_0/gems/grape_minus_1_dot_0_dot_2/lib/grape/middleware//home/deploy/.rvm/gems/jruby-9.1.13.0/gems/grape-1.0.2/lib/grape/middleware/base.rb:24:in `invokeOther1:call!\'',
Oct 04 05:43:44 canon npm[359951]:      'home/deploy/$_dot_rvm/gems/jruby_minus_9_dot_1_dot_13_dot_0/gems/grape_minus_1_dot_0_dot_2/lib/grape/middleware//home/deploy/.rvm/gems/jruby-9.1.13.0/gems/grape-1.0.2/lib/grape/middleware/base.rb:24:in `call\'',
Oct 04 05:43:44 canon npm[359951]:      'home/deploy/$_dot_rvm/gems/jruby_minus_9_dot_1_dot_13_dot_0/gems/grape_minus_1_dot_0_dot_2/lib/grape/middleware//home/deploy/.rvm/gems/jruby-9.1.13.0/gems/grape-1.0.2/lib/grape/middleware/base.rb:31:in `invokeOther4:call\'',
Oct 04 05:43:44 canon npm[359951]:      'home/deploy/$_dot_rvm/gems/jruby_minus_9_dot_1_dot_13_dot_0/gems/grape_minus_1_dot_0_dot_2/lib/grape/middleware//home/deploy/.rvm/gems/jruby-9.1.13.0/gems/grape-1.0.2/lib/grape/middleware/base.rb:31:in `call!\'',
Oct 04 05:43:44 canon npm[359951]:      'home/deploy/$_dot_rvm/gems/jruby_minus_9_dot_1_dot_13_dot_0/gems/grape_minus_1_dot_0_dot_2/lib/grape/middleware//home/deploy/.rvm/gems/jruby-9.1.13.0/gems/grape-1.0.2/lib/grape/middleware/base.rb:24:in `invokeOther1:call!\'',
Oct 04 05:43:44 canon npm[359951]:      'home/deploy/$_dot_rvm/gems/jruby_minus_9_dot_1_dot_13_dot_0/gems/grape_minus_1_dot_0_dot_2/lib/grape/middleware//home/deploy/.rvm/gems/jruby-9.1.13.0/gems/grape-1.0.2/lib/grape/middleware/base.rb:24:in `call\'',
Oct 04 05:43:44 canon npm[359951]:      'home/deploy/$_dot_rvm/gems/jruby_minus_9_dot_1_dot_13_dot_0/gems/grape_minus_1_dot_0_dot_2/lib/grape/middleware//home/deploy/.rvm/gems/jruby-9.1.13.0/gems/grape-1.0.2/lib/grape/middleware/error.rb:37:in `invokeOther2:call\'',
Oct 04 05:43:44 canon npm[359951]:      'home/deploy/$_dot_rvm/gems/jruby_minus_9_dot_1_dot_13_dot_0/gems/grape_minus_1_dot_0_dot_2/lib/grape/middleware//home/deploy/.rvm/gems/jruby-9.1.13.0/gems/grape-1.0.2/lib/grape/middleware/error.rb:37:in `block in call!\'',
Oct 04 05:43:44 canon npm[359951]:      'org/jruby/RubyContinuation.java:107:in `enter\'',
Oct 04 05:43:44 canon npm[359951]:      'org/jruby/RubyKernel.java:1121:in `rbCatch19Common\'',
Oct 04 05:43:44 canon npm[359951]:      'org/jruby/RubyKernel.java:1114:in `catch\'',
Oct 04 05:43:44 canon npm[359951]:      'org/jruby/RubyKernel$INVOKER$s$rbCatch19.gen:-1:in `call\'',
Oct 04 05:43:44 canon npm[359951]:      'home/deploy/$_dot_rvm/gems/jruby_minus_9_dot_1_dot_13_dot_0/gems/grape_minus_1_dot_0_dot_2/lib/grape/middleware//home/deploy/.rvm/gems/jruby-9.1.13.0/gems/grape-1.0.2/lib/grape/middleware/error.rb:36:in `invokeOther8:catch\'',
Oct 04 05:43:44 canon npm[359951]:      'home/deploy/$_dot_rvm/gems/jruby_minus_9_dot_1_dot_13_dot_0/gems/grape_minus_1_dot_0_dot_2/lib/grape/middleware//home/deploy/.rvm/gems/jruby-9.1.13.0/gems/grape-1.0.2/lib/grape/middleware/error.rb:36:in `call!\'',
Oct 04 05:43:44 canon npm[359951]:      'home/deploy/$_dot_rvm/gems/jruby_minus_9_dot_1_dot_13_dot_0/gems/grape_minus_1_dot_0_dot_2/lib/grape/middleware//home/deploy/.rvm/gems/jruby-9.1.13.0/gems/grape-1.0.2/lib/grape/middleware/base.rb:24:in `invokeOther1:call!\'',
Oct 04 05:43:44 canon npm[359951]:      'home/deploy/$_dot_rvm/gems/jruby_minus_9_dot_1_dot_13_dot_0/gems/grape_minus_1_dot_0_dot_2/lib/grape/middleware//home/deploy/.rvm/gems/jruby-9.1.13.0/gems/grape-1.0.2/lib/grape/middleware/base.rb:24:in `call\'',
Oct 04 05:43:44 canon npm[359951]:      'home/deploy/$_dot_rvm/gems/jruby_minus_9_dot_1_dot_13_dot_0/gems/rack_minus_2_dot_0_dot_4/lib/rack//home/deploy/.rvm/gems/jruby-9.1.13.0/gems/rack-2.0.4/lib/rack/head.rb:12:in `invokeOther5:call\'',
Oct 04 05:43:44 canon npm[359951]:      'home/deploy/$_dot_rvm/gems/jruby_minus_9_dot_1_dot_13_dot_0/gems/rack_minus_2_dot_0_dot_4/lib/rack//home/deploy/.rvm/gems/jruby-9.1.13.0/gems/rack-2.0.4/lib/rack/head.rb:12:in `call\'',
Oct 04 05:43:44 canon npm[359951]:      'home/deploy/$_dot_rvm/gems/jruby_minus_9_dot_1_dot_13_dot_0/gems/grape_minus_1_dot_0_dot_2/lib/grape//home/deploy/.rvm/gems/jruby-9.1.13.0/gems/grape-1.0.2/lib/grape/endpoint.rb:227:in `invokeOther3:call\'',
Oct 04 05:43:44 canon npm[359951]:      'home/deploy/$_dot_rvm/gems/jruby_minus_9_dot_1_dot_13_dot_0/gems/grape_minus_1_dot_0_dot_2/lib/grape//home/deploy/.rvm/gems/jruby-9.1.13.0/gems/grape-1.0.2/lib/grape/endpoint.rb:227:in `call!\'',
Oct 04 05:43:44 canon npm[359951]:      'home/deploy/$_dot_rvm/gems/jruby_minus_9_dot_1_dot_13_dot_0/gems/grape_minus_1_dot_0_dot_2/lib/grape//home/deploy/.rvm/gems/jruby-9.1.13.0/gems/grape-1.0.2/lib/grape/endpoint.rb:221:in `invokeOther2:call!\'',
Oct 04 05:43:44 canon npm[359951]:      'home/deploy/$_dot_rvm/gems/jruby_minus_9_dot_1_dot_13_dot_0/gems/grape_minus_1_dot_0_dot_2/lib/grape//home/deploy/.rvm/gems/jruby-9.1.13.0/gems/grape-1.0.2/lib/grape/endpoint.rb:221:in `call\'',
Oct 04 05:43:44 canon npm[359951]:      'home/deploy/$_dot_rvm/gems/jruby_minus_9_dot_1_dot_13_dot_0/gems/grape_minus_1_dot_0_dot_2/lib/grape/router//home/deploy/.rvm/gems/jruby-9.1.13.0/gems/grape-1.0.2/lib/grape/router/route.rb:72:in `invokeOther1:call\'',
Oct 04 05:43:44 canon npm[359951]:      'home/deploy/$_dot_rvm/gems/jruby_minus_9_dot_1_dot_13_dot_0/gems/grape_minus_1_dot_0_dot_2/lib/grape/router//home/deploy/.rvm/gems/jruby-9.1.13.0/gems/grape-1.0.2/lib/grape/router/route.rb:72:in `exec\'',
Oct 04 05:43:44 canon npm[359951]:      'home/deploy/$_dot_rvm/gems/jruby_minus_9_dot_1_dot_13_dot_0/gems/grape_minus_1_dot_0_dot_2/lib/grape//home/deploy/.rvm/gems/jruby-9.1.13.0/gems/grape-1.0.2/lib/grape/router.rb:121:in `invokeOther4:exec\'',
Oct 04 05:43:44 canon npm[359951]:      'home/deploy/$_dot_rvm/gems/jruby_minus_9_dot_1_dot_13_dot_0/gems/grape_minus_1_dot_0_dot_2/lib/grape//home/deploy/.rvm/gems/jruby-9.1.13.0/gems/grape-1.0.2/lib/grape/router.rb:121:in `process_route\'',
Oct 04 05:43:44 canon npm[359951]:      'home/deploy/$_dot_rvm/gems/jruby_minus_9_dot_1_dot_13_dot_0/gems/grape_minus_1_dot_0_dot_2/lib/grape//home/deploy/.rvm/gems/jruby-9.1.13.0/gems/grape-1.0.2/lib/grape/router.rb:74:in `invokeOther1:process_route\'',
Oct 04 05:43:44 canon npm[359951]:      'home/deploy/$_dot_rvm/gems/jruby_minus_9_dot_1_dot_13_dot_0/gems/grape_minus_1_dot_0_dot_2/lib/grape//home/deploy/.rvm/gems/jruby-9.1.13.0/gems/grape-1.0.2/lib/grape/router.rb:74:in `block in identity\'',
Oct 04 05:43:44 canon npm[359951]:      'home/deploy/$_dot_rvm/gems/jruby_minus_9_dot_1_dot_13_dot_0/gems/grape_minus_1_dot_0_dot_2/lib/grape//home/deploy/.rvm/gems/jruby-9.1.13.0/gems/grape-1.0.2/lib/grape/router.rb:93:in `transaction\'',
Oct 04 05:43:44 canon npm[359951]:      'home/deploy/$_dot_rvm/gems/jruby_minus_9_dot_1_dot_13_dot_0/gems/grape_minus_1_dot_0_dot_2/lib/grape//home/deploy/.rvm/gems/jruby-9.1.13.0/gems/grape-1.0.2/lib/grape/router.rb:72:in `invokeOther3:transaction\'',
Oct 04 05:43:44 canon npm[359951]:      'home/deploy/$_dot_rvm/gems/jruby_minus_9_dot_1_dot_13_dot_0/gems/grape_minus_1_dot_0_dot_2/lib/grape//home/deploy/.rvm/gems/jruby-9.1.13.0/gems/grape-1.0.2/lib/grape/router.rb:72:in `identity\'',
Oct 04 05:43:44 canon npm[359951]:      'home/deploy/$_dot_rvm/gems/jruby_minus_9_dot_1_dot_13_dot_0/gems/grape_minus_1_dot_0_dot_2/lib/grape//home/deploy/.rvm/gems/jruby-9.1.13.0/gems/grape-1.0.2/lib/grape/router.rb:57:in `invokeOther0:identity\'',
Oct 04 05:43:44 canon npm[359951]:      'home/deploy/$_dot_rvm/gems/jruby_minus_9_dot_1_dot_13_dot_0/gems/grape_minus_1_dot_0_dot_2/lib/grape//home/deploy/.rvm/gems/jruby-9.1.13.0/gems/grape-1.0.2/lib/grape/router.rb:57:in `block in call\'',
Oct 04 05:43:44 canon npm[359951]:      'home/deploy/$_dot_rvm/gems/jruby_minus_9_dot_1_dot_13_dot_0/gems/grape_minus_1_dot_0_dot_2/lib/grape//home/deploy/.rvm/gems/jruby-9.1.13.0/gems/grape-1.0.2/lib/grape/router.rb:137:in `with_optimization\'',
Oct 04 05:43:44 canon npm[359951]:      'home/deploy/$_dot_rvm/gems/jruby_minus_9_dot_1_dot_13_dot_0/gems/grape_minus_1_dot_0_dot_2/lib/grape//home/deploy/.rvm/gems/jruby-9.1.13.0/gems/grape-1.0.2/lib/grape/router.rb:56:in `invokeOther3:with_optimization\'',
Oct 04 05:43:44 canon npm[359951]:      'home/deploy/$_dot_rvm/gems/jruby_minus_9_dot_1_dot_13_dot_0/gems/grape_minus_1_dot_0_dot_2/lib/grape//home/deploy/.rvm/gems/jruby-9.1.13.0/gems/grape-1.0.2/lib/grape/router.rb:56:in `call\'',
Oct 04 05:43:44 canon npm[359951]:      'home/deploy/$_dot_rvm/gems/jruby_minus_9_dot_1_dot_13_dot_0/gems/grape_minus_1_dot_0_dot_2/lib/grape//home/deploy/.rvm/gems/jruby-9.1.13.0/gems/grape-1.0.2/lib/grape/api.rb:119:in `invokeOther1:call\'',
Oct 04 05:43:44 canon npm[359951]:      'home/deploy/$_dot_rvm/gems/jruby_minus_9_dot_1_dot_13_dot_0/gems/grape_minus_1_dot_0_dot_2/lib/grape//home/deploy/.rvm/gems/jruby-9.1.13.0/gems/grape-1.0.2/lib/grape/api.rb:119:in `call\'',
Oct 04 05:43:44 canon npm[359951]:      'home/deploy/$_dot_rvm/gems/jruby_minus_9_dot_1_dot_13_dot_0/gems/grape_minus_1_dot_0_dot_2/lib/grape//home/deploy/.rvm/gems/jruby-9.1.13.0/gems/grape-1.0.2/lib/grape/api.rb:45:in `invokeOther1:call\'',
Oct 04 05:43:44 canon npm[359951]:      'home/deploy/$_dot_rvm/gems/jruby_minus_9_dot_1_dot_13_dot_0/gems/grape_minus_1_dot_0_dot_2/lib/grape//home/deploy/.rvm/gems/jruby-9.1.13.0/gems/grape-1.0.2/lib/grape/api.rb:45:in `call!\'',
Oct 04 05:43:44 canon npm[359951]:      'home/deploy/$_dot_rvm/gems/jruby_minus_9_dot_1_dot_13_dot_0/gems/grape_minus_1_dot_0_dot_2/lib/grape//home/deploy/.rvm/gems/jruby-9.1.13.0/gems/grape-1.0.2/lib/grape/api.rb:40:in `invokeOther4:call!\'',
Oct 04 05:43:44 canon npm[359951]:      'home/deploy/$_dot_rvm/gems/jruby_minus_9_dot_1_dot_13_dot_0/gems/grape_minus_1_dot_0_dot_2/lib/grape//home/deploy/.rvm/gems/jruby-9.1.13.0/gems/grape-1.0.2/lib/grape/api.rb:40:in `call\'',
Oct 04 05:43:44 canon npm[359951]:      'home/deploy/$_dot_rvm/gems/jruby_minus_9_dot_1_dot_13_dot_0/gems/rack_minus_2_dot_0_dot_4/lib/rack//home/deploy/.rvm/gems/jruby-9.1.13.0/gems/rack-2.0.4/lib/rack/common_logger.rb:33:in `invokeOther3:call\'',
Oct 04 05:43:44 canon npm[359951]:      'home/deploy/$_dot_rvm/gems/jruby_minus_9_dot_1_dot_13_dot_0/gems/rack_minus_2_dot_0_dot_4/lib/rack//home/deploy/.rvm/gems/jruby-9.1.13.0/gems/rack-2.0.4/lib/rack/common_logger.rb:33:in `call\'',
Oct 04 05:43:44 canon npm[359951]:      'home/deploy/$_dot_rvm/gems/jruby_minus_9_dot_1_dot_13_dot_0/gems/rack_minus_cors_minus_0_dot_4_dot_1/lib/rack//home/deploy/.rvm/gems/jruby-9.1.13.0/gems/rack-cors-0.4.1/lib/rack/cors.rb:81:in `invokeOther50:call\'',
Oct 04 05:43:44 canon npm[359951]:      'home/deploy/$_dot_rvm/gems/jruby_minus_9_dot_1_dot_13_dot_0/gems/rack_minus_cors_minus_0_dot_4_dot_1/lib/rack//home/deploy/.rvm/gems/jruby-9.1.13.0/gems/rack-cors-0.4.1/lib/rack/cors.rb:81:in `call\'',
Oct 04 05:43:44 canon npm[359951]:      'home/deploy/$_dot_rvm/gems/jruby_minus_9_dot_1_dot_13_dot_0/gems/rack_minus_2_dot_0_dot_4/lib/rack//home/deploy/.rvm/gems/jruby-9.1.13.0/gems/rack-2.0.4/lib/rack/config.rb:17:in `invokeOther3:call\'',
Oct 04 05:43:44 canon npm[359951]:      'home/deploy/$_dot_rvm/gems/jruby_minus_9_dot_1_dot_13_dot_0/gems/rack_minus_2_dot_0_dot_4/lib/rack//home/deploy/.rvm/gems/jruby-9.1.13.0/gems/rack-2.0.4/lib/rack/config.rb:17:in `call\'',
Oct 04 05:43:44 canon npm[359951]:      'home/deploy/$_dot_rvm/gems/jruby_minus_9_dot_1_dot_13_dot_0/gems/puma_minus_3_dot_8_dot_2_minus_java/lib/puma//home/deploy/.rvm/gems/jruby-9.1.13.0/gems/puma-3.8.2-java/lib/puma/configuration.rb:224:in `invokeOther3:call\'',
Oct 04 05:43:44 canon npm[359951]:      'home/deploy/$_dot_rvm/gems/jruby_minus_9_dot_1_dot_13_dot_0/gems/puma_minus_3_dot_8_dot_2_minus_java/lib/puma//home/deploy/.rvm/gems/jruby-9.1.13.0/gems/puma-3.8.2-java/lib/puma/configuration.rb:224:in `call\'',
Oct 04 05:43:44 canon npm[359951]:      'home/deploy/$_dot_rvm/gems/jruby_minus_9_dot_1_dot_13_dot_0/gems/puma_minus_3_dot_8_dot_2_minus_java/lib/puma//home/deploy/.rvm/gems/jruby-9.1.13.0/gems/puma-3.8.2-java/lib/puma/server.rb:600:in `invokeOther54:call\'',
Oct 04 05:43:44 canon npm[359951]:      'home/deploy/$_dot_rvm/gems/jruby_minus_9_dot_1_dot_13_dot_0/gems/puma_minus_3_dot_8_dot_2_minus_java/lib/puma//home/deploy/.rvm/gems/jruby-9.1.13.0/gems/puma-3.8.2-java/lib/puma/server.rb:600:in `handle_request\'',
Oct 04 05:43:44 canon npm[359951]:      'home/deploy/$_dot_rvm/gems/jruby_minus_9_dot_1_dot_13_dot_0/gems/puma_minus_3_dot_8_dot_2_minus_java/lib/puma//home/deploy/.rvm/gems/jruby-9.1.13.0/gems/puma-3.8.2-java/lib/puma/server.rb:435:in `invokeOther4:handle_request\'',
Oct 04 05:43:44 canon npm[359951]:      'home/deploy/$_dot_rvm/gems/jruby_minus_9_dot_1_dot_13_dot_0/gems/puma_minus_3_dot_8_dot_2_minus_java/lib/puma//home/deploy/.rvm/gems/jruby-9.1.13.0/gems/puma-3.8.2-java/lib/puma/server.rb:435:in `process_client\'',
Oct 04 05:43:44 canon npm[359951]:      'home/deploy/$_dot_rvm/gems/jruby_minus_9_dot_1_dot_13_dot_0/gems/puma_minus_3_dot_8_dot_2_minus_java/lib/puma//home/deploy/.rvm/gems/jruby-9.1.13.0/gems/puma-3.8.2-java/lib/puma/server.rb:299:in `invokeOther17:process_client\'',
Oct 04 05:43:44 canon npm[359951]:      'home/deploy/$_dot_rvm/gems/jruby_minus_9_dot_1_dot_13_dot_0/gems/puma_minus_3_dot_8_dot_2_minus_java/lib/puma//home/deploy/.rvm/gems/jruby-9.1.13.0/gems/puma-3.8.2-java/lib/puma/server.rb:299:in `block in run\'',
Oct 04 05:43:44 canon npm[359951]:      'org/jruby/RubyProc.java:289:in `call\'',
Oct 04 05:43:44 canon npm[359951]:      'org/jruby/RubyProc.java:273:in `call19\'',
Oct 04 05:43:44 canon npm[359951]:      ... 6 more items ] }

@jspeis
Copy link
Member

jspeis commented Oct 4, 2018

Looks like some sort of internal Mondrian error? sigh

@hwchen are there any other errors in the log around the same spots as these?

@hwchen
Copy link
Author

hwchen commented Oct 4, 2018

The api and site logs differ a bit, possibly because of caching. So it's a little hard to line them up.

The other error that happens reliably is this, and this will go away with flushing or just retrying sometimes.

Oct 03 21:52:19 canon npm[359951]: Cube Error 400 Bad Request
Oct 03 21:52:19 canon npm[359951]: { error:
Oct 03 21:52:19 canon npm[359951]:    [ 'root cause: mondrian.olap.MondrianException: Mondrian Error:Internal error: Query required more than 12 iterations',
Oct 03 21:52:19 canon npm[359951]:      'root cause:   mondrian.resource.MondrianResource$_Def0.ex(MondrianResource.java:984)',
Oct 03 21:52:19 canon npm[359951]:      'root cause:   mondrian.olap.Util.newInternal(Util.java:2403)',
Oct 03 21:52:19 canon npm[359951]:      'root cause:   mondrian.rolap.RolapResult.executeBody(RolapResult.java:1047)',
Oct 03 21:52:19 canon npm[359951]:      'root cause:   mondrian.rolap.RolapResult.<init>(RolapResult.java:504)',
Oct 03 21:52:19 canon npm[359951]:      'root cause:   mondrian.rolap.RolapConnection.executeInternal(RolapConnection.java:672)',
Oct 03 21:52:19 canon npm[359951]:      'root cause:   mondrian.rolap.RolapConnection.access$000(RolapConnection.java:52)',
Oct 03 21:52:19 canon npm[359951]:      'root cause:   mondrian.rolap.RolapConnection$1.call(RolapConnection.java:623)',
Oct 03 21:52:19 canon npm[359951]:      'root cause:   mondrian.rolap.RolapConnection$1.call(RolapConnection.java:621)',
Oct 03 21:52:19 canon npm[359951]:      'root cause:   java.util.concurrent.FutureTask.run(FutureTask.java:266)',
Oct 03 21:52:19 canon npm[359951]:      'root cause:   java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)',

@jspeis
Copy link
Member

jspeis commented Oct 4, 2018

@hwchen perhaps we can try making sure mondrian is getting passed these settings?

https://help.pentaho.com/Documentation/5.3/0P0/100/050/010/040

not sure if it will make a difference but maybe?

@hwchen
Copy link
Author

hwchen commented Oct 4, 2018

Weird, can't seem to find a University query associated with the Null pointer exception. I wonder if something else triggered an error in Mondrian, and then the the null pointer exception started showing up somewhere else?

Anyways, here's the log for the cube, searching for Null with context of 30 lines:

deploy@canon:~$ sudo journalctl -u datausa-cube --lines 1000000 | ag Null -C 30
Sep 25 16:11:19 canon datausa-acs_bundle[3240]: 3978400288 [Ruby-0-Thread-4853@puma 002: /home/deploy/.rvm/gems/jruby-9.1.13.0/gems/puma-3.8.2-java/lib/puma/server.rb:352] DEBUG mondrian.sql  - 279778: , exec 8 ms
Sep 25 16:11:19 canon datausa-acs_bundle[3240]: 3978400288 [Ruby-0-Thread-4853@puma 002: /home/deploy/.rvm/gems/jruby-9.1.13.0/gems/puma-3.8.2-java/lib/puma/server.rb:352] DEBUG mondrian.sql  - 279778: , exec+fetch 8 ms, 1 rows
Sep 25 16:11:19 canon datausa-acs_bundle[3240]: 3978400288 [Ruby-0-Thread-4853@puma 002: /home/deploy/.rvm/gems/jruby-9.1.13.0/gems/puma-3.8.2-java/lib/puma/server.rb:352] DEBUG mondrian.sql  - 279778: , exec+fetch 8 ms, 1 rows
Sep 25 16:11:19 canon datausa-acs_bundle[3240]: 71.232.34.173 - - [25/Sep/2018:20:11:19 +0000] "GET /cubes/acs_ygh_health_care_coverage_overall_5/aggregate?drilldown%5B%5D=%5BKaiser+Health+Coverage%5D.%5BKaiser+Coverage%5D&drilldown%5B%5D=%5BYear%5D.%5BYear%5D&cut%5B%5D=%7B%5BYear%5D.%5BYear%5D.%5BYear%5D.%26%5B2016%5D%2C%5BYear%5D.%5BYear%5D.%5BYear%5D.%26%5B2015%5D%7D&measures%5B%5D=Health+Insurance&nonempty=true&distinct=false&parents=false&debug=false&sparse=true HTTP/1.0" 200 1374 152.4006
Sep 25 16:12:21 canon datausa-acs_bundle[3240]: 71.232.34.173 - - [25/Sep/2018:20:12:21 +0000] "GET /cubes/acs_ygpsar_poverty_by_sex_age_race_5/aggregate?drilldown%5B%5D=%5BPoverty+Status%5D.%5BPoverty+Status%5D&drilldown%5B%5D=%5BYear%5D.%5BYear%5D&cut%5B%5D=%7B%5BYear%5D.%5BYear%5D.%5BYear%5D.%26%5B2016%5D%2C%5BYear%5D.%5BYear%5D.%5BYear%5D.%26%5B2015%5D%7D&measures%5B%5D=Population+in+Poverty+by+Gender%2C+Age%2C+and+Race&nonempty=true&distinct=false&parents=false&debug=false&sparse=true HTTP/1.0" 400 19528 306.9224
Sep 25 16:12:33 canon datausa-acs_bundle[3240]: 71.232.34.173 - - [25/Sep/2018:20:12:33 +0000] "GET /cubes/acs_ygpsar_poverty_by_sex_age_race_5/aggregate?drilldown%5B%5D=%5BPoverty+Status%5D.%5BPoverty+Status%5D&drilldown%5B%5D=%5BYear%5D.%5BYear%5D&drilldown%5B%5D=%5BGeography%5D.%5BNation%5D.%5BNation%5D&cut%5B%5D=%7B%5BYear%5D.%5BYear%5D.%5BYear%5D.%26%5B2016%5D%7D&cut%5B%5D=%7B%5BGeography%5D.%5BNation%5D.%5BNation%5D.%26%5B01000US%5D%7D&measures%5B%5D=Population+in+Poverty+by+Gender%2C+Age%2C+and+Race&nonempty=true&distinct=false&parents=false&debug=false&sparse=true HTTP/1.0" 400 19528 316.4974
Sep 25 16:12:40 canon datausa-acs_bundle[3240]: 71.232.34.173 - - [25/Sep/2018:20:12:40 +0000] "GET /cubes/acs_ygpsar_poverty_by_sex_age_race_5/aggregate?drilldown%5B%5D=%5BRace%5D.%5BRace%5D&drilldown%5B%5D=%5BYear%5D.%5BYear%5D&drilldown%5B%5D=%5BPoverty+Status%5D.%5BPoverty+Status%5D&cut%5B%5D=%7B%5BPoverty+Status%5D.%5BPoverty+Status%5D.%5BPoverty+Status%5D.%26%5B0%5D%7D&cut%5B%5D=%7B%5BYear%5D.%5BYear%5D.%5BYear%5D.%26%5B2016%5D%7D&measures%5B%5D=Population+in+Poverty+by+Gender%2C+Age%2C+and+Race&measures%5B%5D=Population+in+Poverty+by+Gender%2C+Age%2C+and+Race+Moe&nonempty=true&distinct=false&parents=false&debug=false&sparse=true HTTP/1.0" 400 19528 313.3053
Sep 25 16:12:43 canon datausa-acs_bundle[3240]: 3978483451 [mondrian.rolap.RolapResultShepherd$executor_17] DEBUG mondrian.mdx  - 31385973: exec: 300792 ms
Sep 25 16:12:43 canon datausa-acs_bundle[3240]: 71.232.34.173 - - [25/Sep/2018:20:12:43 +0000] "GET /cubes/acs_ygpsar_poverty_by_sex_age_race_5/aggregate?drilldown%5B%5D=%5BAge%5D.%5BAge%5D&drilldown%5B%5D=%5BSex%5D.%5BSex%5D&drilldown%5B%5D=%5BYear%5D.%5BYear%5D&drilldown%5B%5D=%5BPoverty+Status%5D.%5BPoverty+Status%5D&cut%5B%5D=%7B%5BPoverty+Status%5D.%5BPoverty+Status%5D.%5BPoverty+Status%5D.%26%5B0%5D%7D&cut%5B%5D=%7B%5BYear%5D.%5BYear%5D.%5BYear%5D.%26%5B2016%5D%7D&measures%5B%5D=Population+in+Poverty+by+Gender%2C+Age%2C+and+Race&nonempty=true&distinct=false&parents=false&debug=false&sparse=true HTTP/1.0" 400 19528 324.1163
Sep 25 16:12:43 canon datausa-acs_bundle[3240]: 3978483451 [mondrian.rolap.RolapResultShepherd$executor_17] DEBUG mondrian.mdx  - 31385973: exec: 300792 ms
Sep 25 16:12:43 canon datausa-acs_bundle[3240]: 3978483451 [mondrian.rolap.RolapResultShepherd$executor_20] DEBUG mondrian.mdx  - 31385966: exec: 303204 ms
Sep 25 16:12:43 canon datausa-acs_bundle[3240]: 3978483451 [mondrian.rolap.RolapResultShepherd$executor_20] DEBUG mondrian.mdx  - 31385966: exec: 303204 ms
Sep 25 16:12:43 canon datausa-acs_bundle[3240]: 3978483459 [mondrian.rolap.RolapResultShepherd$executor_12] DEBUG mondrian.mdx  - 31385771: exec: 310532 ms
Sep 25 16:12:43 canon datausa-acs_bundle[3240]: 3978483459 [mondrian.rolap.RolapResultShepherd$executor_12] DEBUG mondrian.mdx  - 31385771: exec: 310532 ms
Sep 25 16:14:14 canon datausa-acs_bundle[3240]: I, [2018-09-25T20:14:14.788403 #3240]  INFO -- : Executing MDX query SELECT NON EMPTY {[Measures].[Diabetes Monitoring], [Measures].[Diabetes Monitoring CI High]} ON COLUMNS,
Sep 25 16:14:14 canon datausa-acs_bundle[3240]: NON EMPTY [Geography].[County].[State].Members * [Year].[Year].[Year].Members ON ROWS
Sep 25 16:14:14 canon datausa-acs_bundle[3240]: FROM [county_health_ranking]
Sep 25 16:14:14 canon datausa-acs_bundle[3240]: 3978575189 [mondrian.rolap.RolapResultShepherd$executor_5] DEBUG mondrian.mdx  - 31427071: select NON EMPTY {[Measures].[Diabetes Monitoring], [Measures].[Diabetes Monitoring CI High]} ON COLUMNS,
Sep 25 16:14:14 canon datausa-acs_bundle[3240]:   NON EMPTY ([Geography].[County].[State].Members * [Year].[Year].Members) ON ROWS
Sep 25 16:14:14 canon datausa-acs_bundle[3240]: from [county_health_ranking]
Sep 25 16:14:14 canon datausa-acs_bundle[3240]: 3978575189 [mondrian.rolap.RolapResultShepherd$executor_5] DEBUG mondrian.mdx  - 31427071: select NON EMPTY {[Measures].[Diabetes Monitoring], [Measures].[Diabetes Monitoring CI High]} ON COLUMNS,
Sep 25 16:14:14 canon datausa-acs_bundle[3240]:   NON EMPTY ([Geography].[County].[State].Members * [Year].[Year].Members) ON ROWS
Sep 25 16:14:14 canon datausa-acs_bundle[3240]: from [county_health_ranking]
Sep 25 16:14:14 canon datausa-acs_bundle[3240]: 3978575195 [mondrian.rolap.RolapResultShepherd$executor_5] DEBUG mondrian.mdx  - 31427071: exec: 6 ms
Sep 25 16:14:14 canon datausa-acs_bundle[3240]: 3978575195 [mondrian.rolap.RolapResultShepherd$executor_5] DEBUG mondrian.mdx  - 31427071: exec: 6 ms
Sep 25 16:14:14 canon datausa-acs_bundle[3240]: 190.13.139.25 - - [25/Sep/2018:20:14:14 +0000] "GET /cubes/county_health_ranking/aggregate?drilldown%5B%5D=%5BGeography%5D.%5BCounty%5D.%5BState%5D&drilldown%5B%5D=%5BYear%5D.%5BYear%5D&measures%5B%5D=Diabetes+Monitoring&measures%5B%5D=Diabetes+Monitoring+CI+High&nonempty=true&distinct=false&parents=false&debug=false&sparse=true HTTP/1.0" 200 11 0.1283
Sep 25 16:15:35 canon datausa-acs_bundle[3240]: 3978655462 [mondrian.rolap.agg.SegmentCacheManager$sqlExecutor_92] DEBUG mondrian.sql  - 278997: , exec 470727 ms
Sep 25 16:15:35 canon datausa-acs_bundle[3240]: 3978655462 [mondrian.rolap.agg.SegmentCacheManager$sqlExecutor_92] DEBUG mondrian.sql  - 278997: , exec 470727 ms
Sep 25 16:15:36 canon datausa-acs_bundle[3240]: 3978656832 [mondrian.rolap.agg.SegmentCacheManager$sqlExecutor_92] DEBUG mondrian.sql  - 278997: , exec+fetch 474158 ms, 13 rows
Sep 25 16:15:36 canon datausa-acs_bundle[3240]: 3978656832 [mondrian.rolap.agg.SegmentCacheManager$sqlExecutor_92] DEBUG mondrian.sql  - 278997: , exec+fetch 474158 ms, 13 rows
Sep 25 16:15:36 canon datausa-acs_bundle[3240]: java.lang.NullPointerException
Sep 25 16:15:36 canon datausa-acs_bundle[3240]: java.lang.NullPointerException
Sep 25 16:15:36 canon datausa-acs_bundle[3240]: java.lang.NullPointerException
Sep 25 16:15:36 canon datausa-acs_bundle[3240]: java.lang.NullPointerException
Sep 25 16:15:36 canon datausa-acs_bundle[3240]: java.lang.NullPointerException
Sep 25 16:15:36 canon datausa-acs_bundle[3240]: java.lang.NullPointerException
Sep 25 16:15:36 canon datausa-acs_bundle[3240]: java.lang.NullPointerException
Sep 25 16:15:36 canon datausa-acs_bundle[3240]: java.lang.NullPointerException
Sep 25 16:15:36 canon datausa-acs_bundle[3240]: java.lang.NullPointerException
Sep 25 16:18:02 canon datausa-acs_bundle[3240]: 3978802743 [mondrian.rolap.agg.SegmentCacheManager$sqlExecutor_41] DEBUG mondrian.sql  - 278910: , exec 635907 ms
Sep 25 16:18:02 canon datausa-acs_bundle[3240]: 3978802743 [mondrian.rolap.agg.SegmentCacheManager$sqlExecutor_41] DEBUG mondrian.sql  - 278910: , exec 635907 ms
Sep 25 16:18:02 canon datausa-acs_bundle[3240]: java.lang.NullPointerException3978803140 [mondrian.rolap.agg.SegmentCacheManager$sqlExecutor_41] DEBUG mondrian.sql  - 278910: , exec+fetch 636610 ms, 2 rows
Sep 25 16:18:02 canon datausa-acs_bundle[3240]: 3978803140 [mondrian.rolap.agg.SegmentCacheManager$sqlExecutor_41] DEBUG mondrian.sql  - 278910: , exec+fetch 636610 ms, 2 rows
Sep 25 16:18:02 canon datausa-acs_bundle[3240]: java.lang.NullPointerException
Sep 25 16:18:02 canon datausa-acs_bundle[3240]: java.lang.NullPointerException
Sep 25 16:18:02 canon datausa-acs_bundle[3240]: java.lang.NullPointerException
Sep 25 16:18:02 canon datausa-acs_bundle[3240]: java.lang.NullPointerException
Sep 25 16:18:02 canon datausa-acs_bundle[3240]: java.lang.NullPointerException
Sep 25 16:18:02 canon datausa-acs_bundle[3240]: java.lang.NullPointerException
Sep 25 16:18:02 canon datausa-acs_bundle[3240]: java.lang.NullPointerException
Sep 25 16:18:02 canon datausa-acs_bundle[3240]: java.lang.NullPointerException
Sep 25 16:18:02 canon datausa-acs_bundle[3240]: 3978803298 [mondrian.rolap.RolapResultShepherd$executor_18] DEBUG mondrian.mdx  - 31382141: exec: 642376 ms
Sep 25 16:18:02 canon datausa-acs_bundle[3240]: 3978803298 [mondrian.rolap.RolapResultShepherd$executor_18] DEBUG mondrian.mdx  - 31382141: exec: 642376 ms
Sep 25 16:18:17 canon datausa-acs_bundle[3240]: 3978817901 [mondrian.rolap.agg.SegmentCacheManager$sqlExecutor_14] DEBUG mondrian.sql  - 278998: , exec 635017 ms
Sep 25 16:18:17 canon datausa-acs_bundle[3240]: 3978817901 [mondrian.rolap.agg.SegmentCacheManager$sqlExecutor_14] DEBUG mondrian.sql  - 278998: , exec 635017 ms
Sep 25 16:18:17 canon datausa-acs_bundle[3240]: 3978818206 [mondrian.rolap.agg.SegmentCacheManager$sqlExecutor_14] DEBUG mondrian.sql  - 278998: , exec+fetch 635528 ms, 2 rows
Sep 25 16:18:17 canon datausa-acs_bundle[3240]: 3978818206 [mondrian.rolap.agg.SegmentCacheManager$sqlExecutor_14] DEBUG mondrian.sql  - 278998: , exec+fetch 635528 ms, 2 rows
Sep 25 16:18:17 canon datausa-acs_bundle[3240]: java.lang.NullPointerException
Sep 25 16:18:17 canon datausa-acs_bundle[3240]: java.lang.NullPointerException
Sep 25 16:18:17 canon datausa-acs_bundle[3240]: java.lang.NullPointerException
Sep 25 16:18:17 canon datausa-acs_bundle[3240]: java.lang.NullPointerException
Sep 25 16:18:17 canon datausa-acs_bundle[3240]: java.lang.NullPointerException
Sep 25 16:18:17 canon datausa-acs_bundle[3240]: java.lang.NullPointerException
Sep 25 16:18:17 canon datausa-acs_bundle[3240]: java.lang.NullPointerException
Sep 25 16:18:17 canon datausa-acs_bundle[3240]: java.lang.NullPointerException
Sep 25 16:18:17 canon datausa-acs_bundle[3240]: java.lang.NullPointerException
Sep 25 16:18:21 canon datausa-acs_bundle[3240]: 3978822349 [mondrian.rolap.agg.SegmentCacheManager$sqlExecutor_68] DEBUG mondrian.sql  - 278988: , exec 641647 ms
Sep 25 16:18:21 canon datausa-acs_bundle[3240]: 3978822349 [mondrian.rolap.agg.SegmentCacheManager$sqlExecutor_68] DEBUG mondrian.sql  - 278988: , exec 641647 ms
Sep 25 16:18:22 canon datausa-acs_bundle[3240]: java.lang.NullPointerException3978823336 [mondrian.rolap.agg.SegmentCacheManager$sqlExecutor_68] DEBUG mondrian.sql  - 278988: , exec+fetch 643082 ms, 10 rows
Sep 25 16:18:22 canon datausa-acs_bundle[3240]: 3978823336 [mondrian.rolap.agg.SegmentCacheManager$sqlExecutor_68] DEBUG mondrian.sql  - 278988: , exec+fetch 643082 ms, 10 rows
Sep 25 16:18:22 canon datausa-acs_bundle[3240]: java.lang.NullPointerException
Sep 25 16:18:22 canon datausa-acs_bundle[3240]: java.lang.NullPointerException
Sep 25 16:18:22 canon datausa-acs_bundle[3240]: java.lang.NullPointerException
Sep 25 16:18:22 canon datausa-acs_bundle[3240]: java.lang.NullPointerException
Sep 25 16:18:22 canon datausa-acs_bundle[3240]: java.lang.NullPointerException
Sep 25 16:18:22 canon datausa-acs_bundle[3240]: java.lang.NullPointerException
Sep 25 16:18:22 canon datausa-acs_bundle[3240]: java.lang.NullPointerException
Sep 25 16:18:22 canon datausa-acs_bundle[3240]: java.lang.NullPointerException
Sep 25 16:18:22 canon datausa-acs_bundle[3240]: java.lang.NullPointerException
Sep 25 16:18:22 canon datausa-acs_bundle[3240]: java.lang.NullPointerException
Sep 25 16:18:22 canon datausa-acs_bundle[3240]: java.lang.NullPointerException
Sep 25 16:18:22 canon datausa-acs_bundle[3240]: java.lang.NullPointerException
Sep 25 16:18:22 canon datausa-acs_bundle[3240]: java.lang.NullPointerException
Sep 25 16:18:22 canon datausa-acs_bundle[3240]: java.lang.NullPointerException
Sep 25 16:18:22 canon datausa-acs_bundle[3240]: java.lang.NullPointerException
Sep 25 16:18:22 canon datausa-acs_bundle[3240]: java.lang.NullPointerException
Sep 25 16:18:22 canon datausa-acs_bundle[3240]: java.lang.NullPointerException
Sep 25 16:18:35 canon datausa-acs_bundle[3240]: 3978836321 [mondrian.rolap.agg.SegmentCacheManager$sqlExecutor_7] DEBUG mondrian.sql  - 278987: , exec 655870 ms
Sep 25 16:18:35 canon datausa-acs_bundle[3240]: 3978836321 [mondrian.rolap.agg.SegmentCacheManager$sqlExecutor_7] DEBUG mondrian.sql  - 278987: , exec 655870 ms
Sep 25 16:18:36 canon datausa-acs_bundle[3240]: 3978836680 [mondrian.rolap.agg.SegmentCacheManager$sqlExecutor_7] DEBUG mondrian.sql  - 278987: , exec+fetch 656426 ms, 1 rows
Sep 25 16:18:36 canon datausa-acs_bundle[3240]: java.lang.NullPointerException3978836680 [mondrian.rolap.agg.SegmentCacheManager$sqlExecutor_7] DEBUG mondrian.sql  - 278987: , exec+fetch 656426 ms, 1 rows
Sep 25 16:18:36 canon datausa-acs_bundle[3240]: java.lang.NullPointerException
Sep 25 16:18:36 canon datausa-acs_bundle[3240]: java.lang.NullPointerException
Sep 25 16:18:36 canon datausa-acs_bundle[3240]: java.lang.NullPointerException
Sep 25 16:18:36 canon datausa-acs_bundle[3240]: java.lang.NullPointerException
Sep 25 16:18:36 canon datausa-acs_bundle[3240]: java.lang.NullPointerException
Sep 25 16:18:36 canon datausa-acs_bundle[3240]: java.lang.NullPointerException
Sep 25 16:18:36 canon datausa-acs_bundle[3240]: java.lang.NullPointerException
Sep 25 16:18:36 canon datausa-acs_bundle[3240]: java.lang.NullPointerException
Sep 25 16:22:36 canon datausa-acs_bundle[3240]: I, [2018-09-25T20:22:36.606537 #3240]  INFO -- : Executing MDX query SELECT NON EMPTY {[Measures].[Average Age], [Measures].[Average Age Appx MOE]} ON COLUMNS,
Sep 25 16:22:36 canon datausa-acs_bundle[3240]: NON EMPTY FILTER([Geography].[Geography].[State].Members * [Year].[Year].[Year].Members, [Measures].[Average Age] > 0) ON ROWS
Sep 25 16:22:36 canon datausa-acs_bundle[3240]: FROM [pums_5]
Sep 25 16:22:36 canon datausa-acs_bundle[3240]: 3979076986 [mondrian.rolap.RolapResultShepherd$executor_13] DEBUG mondrian.mdx  - 31427134: select NON EMPTY {[Measures].[Average Age], [Measures].[Average Age Appx MOE]} ON COLUMNS,
Sep 25 16:22:36 canon datausa-acs_bundle[3240]:   NON EMPTY Filter(([Geography].[State].Members * [Year].[Year].Members), ([Measures].[Average Age] > 0)) ON ROWS
Sep 25 16:22:36 canon datausa-acs_bundle[3240]: from [pums_5]
Sep 25 16:22:36 canon datausa-acs_bundle[3240]: 3979076986 [mondrian.rolap.RolapResultShepherd$executor_13] DEBUG mondrian.mdx  - 31427134: select NON EMPTY {[Measures].[Average Age], [Measures].[Average Age Appx MOE]} ON COLUMNS,
Sep 25 16:22:36 canon datausa-acs_bundle[3240]:   NON EMPTY Filter(([Geography].[State].Members * [Year].[Year].Members), ([Measures].[Average Age] > 0)) ON ROWS
Sep 25 16:22:36 canon datausa-acs_bundle[3240]: from [pums_5]
Sep 25 16:22:36 canon datausa-acs_bundle[3240]: 3979077000 [mondrian.rolap.RolapResultShepherd$executor_13] DEBUG mondrian.mdx  - 31427134: exec: 14 ms
Sep 25 16:22:36 canon datausa-acs_bundle[3240]: 3979077000 [mondrian.rolap.RolapResultShepherd$executor_13] DEBUG mondrian.mdx  - 31427134: exec: 14 ms
Sep 25 16:22:36 canon datausa-acs_bundle[3240]: 190.13.139.25 - - [25/Sep/2018:20:22:36 +0000] "GET /cubes/pums_5/aggregate?drilldown%5B%5D=%5BGeography%5D.%5BState%5D&drilldown%5B%5D=%5BYear%5D.%5BYear%5D&measures%5B%5D=Average+Age&measures%5B%5D=Average+Age+Appx+MOE&filter%5B%5D=Average+Age+%3E+0&nonempty=true&distinct=false&parents=true&debug=false&sparse=true HTTP/1.0" 200 40646 0.0696
Sep 25 16:30:31 canon datausa-acs_bundle[3240]: I, [2018-09-25T20:30:31.948588 #3240]  INFO -- : Executing MDX query SELECT NON EMPTY {[Measures].[Diabetes Monitoring], [Measures].[Diabetes Monitoring CI High]} ON COLUMNS,
Sep 25 16:30:31 canon datausa-acs_bundle[3240]: NON EMPTY [Geography].[State].[State].Members * [Year].[Year].[Year].Members ON ROWS
Sep 25 16:30:31 canon datausa-acs_bundle[3240]: FROM [county_health_ranking]
Sep 25 16:30:31 canon datausa-acs_bundle[3240]: 3979552326 [mondrian.rolap.RolapResultShepherd$executor_14] DEBUG mondrian.mdx  - 31427634: select NON EMPTY {[Measures].[Diabetes Monitoring], [Measures].[Diabetes Monitoring CI High]} ON COLUMNS,
Sep 25 16:30:31 canon datausa-acs_bundle[3240]:   NON EMPTY ([Geography].[State].[State].Members * [Year].[Year].Members) ON ROWS
Sep 25 16:30:31 canon datausa-acs_bundle[3240]: from [county_health_ranking]
Sep 25 16:30:31 canon datausa-acs_bundle[3240]: 3979552326 [mondrian.rolap.RolapResultShepherd$executor_14] DEBUG mondrian.mdx  - 31427634: select NON EMPTY {[Measures].[Diabetes Monitoring], [Measures].[Diabetes Monitoring CI High]} ON COLUMNS,
Sep 25 16:30:31 canon datausa-acs_bundle[3240]:   NON EMPTY ([Geography].[State].[State].Members * [Year].[Year].Members) ON ROWS
Sep 25 16:30:31 canon datausa-acs_bundle[3240]: from [county_health_ranking]
Sep 25 16:30:31 canon datausa-acs_bundle[3240]: 3979552369 [mondrian.rolap.agg.SegmentCacheManager$sqlExecutor_24] DEBUG mondrian.sql  - 279779: Segment.load: executing sql [
Sep 25 16:30:31 canon datausa-acs_bundle[3240]: select
Sep 25 16:30:31 canon datausa-acs_bundle[3240]:     "states"."geoid" as "c0",
Sep 25 16:30:31 canon datausa-acs_bundle[3240]:     avg("county_health_ranking"."mea_county_cihigh::Diabetes monitoring") as "m0",
Sep 25 16:30:31 canon datausa-acs_bundle[3240]:     avg("county_health_ranking"."mea_county_value::Diabetes monitoring") as "m1",
Sep 25 16:30:31 canon datausa-acs_bundle[3240]:     avg("county_health_ranking"."mea_state_cihigh::Diabetes monitoring") as "m2",
Sep 25 16:30:31 canon datausa-acs_bundle[3240]:     avg("county_health_ranking"."mea_state_value::Diabetes monitoring") as "m3"
Sep 25 16:30:31 canon datausa-acs_bundle[3240]: from
Sep 25 16:30:31 canon datausa-acs_bundle[3240]:     "shapes2017"."states" as "states",
--
Sep 26 14:36:01 canon datausa-acs_bundle[3240]: 96.89.227.150 - - [26/Sep/2018:18:36:01 +0000] "GET /cubes/pums_1/aggregate?drilldown%5B%5D=%5BPUMS+Degree+Field%5D.%5BCIP2%5D&drilldown%5B%5D=%5BPUMS+Occupation%5D.%5BDetailed+Occupation%5D&drilldown%5B%5D=%5BYear%5D.%5BYear%5D&drilldown%5B%5D=%5BEmployment+Time+Status%5D.%5BEmployment+Time+Status%5D&cut%5B%5D=%7B%5BEmployment+Time+Status%5D.%5BEmployment+Time+Status%5D.%5BEmployment+Time+Status%5D.%26%5B1%5D%7D&cut%5B%5D=%7B%5BYear%5D.%5BYear%5D.%5BYear%5D.%26%5B2016%5D%7D&measures%5B%5D=Total+Population&measures%5B%5D=Record+Count&measures%5B%5D=Average+Wage&filter%5B%5D=Record+Count+%3E%3D+5&nonempty=true&distinct=false&parents=false&debug=false&sparse=true HTTP/1.0" 200 1776517 4.7108
Sep 26 14:36:52 canon datausa-acs_bundle[3240]: 96.89.227.150 - - [26/Sep/2018:18:36:52 +0000] "GET /cubes/acs_ygpsar_poverty_by_sex_age_race_5/aggregate?drilldown%5B%5D=%5BRace%5D.%5BRace%5D&drilldown%5B%5D=%5BYear%5D.%5BYear%5D&drilldown%5B%5D=%5BPoverty+Status%5D.%5BPoverty+Status%5D&cut%5B%5D=%7B%5BPoverty+Status%5D.%5BPoverty+Status%5D.%5BPoverty+Status%5D.%26%5B0%5D%7D&cut%5B%5D=%7B%5BYear%5D.%5BYear%5D.%5BYear%5D.%26%5B2016%5D%7D&measures%5B%5D=Population+in+Poverty+by+Gender%2C+Age%2C+and+Race&measures%5B%5D=Population+in+Poverty+by+Gender%2C+Age%2C+and+Race+Moe&nonempty=true&distinct=false&parents=false&debug=false&sparse=true HTTP/1.0" 400 19528 310.9003
Sep 26 14:36:53 canon datausa-acs_bundle[3240]: 4059133997 [mondrian.rolap.RolapResultShepherd$executor_10] DEBUG mondrian.mdx  - 32442651: exec: 300527 ms
Sep 26 14:36:53 canon datausa-acs_bundle[3240]: 4059133997 [mondrian.rolap.RolapResultShepherd$executor_10] DEBUG mondrian.mdx  - 32442651: exec: 300527 ms
Sep 26 14:36:53 canon datausa-acs_bundle[3240]: 96.89.227.150 - - [26/Sep/2018:18:36:53 +0000] "GET /cubes/acs_ygpsar_poverty_by_sex_age_race_5/aggregate?drilldown%5B%5D=%5BRace%5D.%5BRace%5D&drilldown%5B%5D=%5BYear%5D.%5BYear%5D&drilldown%5B%5D=%5BPoverty+Status%5D.%5BPoverty+Status%5D&cut%5B%5D=%7B%5BPoverty+Status%5D.%5BPoverty+Status%5D.%5BPoverty+Status%5D.%26%5B0%5D%7D&cut%5B%5D=%7B%5BYear%5D.%5BYear%5D.%5BYear%5D.%26%5B2016%5D%7D&measures%5B%5D=Population+in+Poverty+by+Gender%2C+Age%2C+and+Race&measures%5B%5D=Population+in+Poverty+by+Gender%2C+Age%2C+and+Race+Moe&nonempty=true&distinct=false&parents=false&debug=false&sparse=true HTTP/1.0" 400 19528 303.8386
Sep 26 14:36:53 canon datausa-acs_bundle[3240]: 96.89.227.150 - - [26/Sep/2018:18:36:53 +0000] "GET /cubes/acs_ygpsar_poverty_by_sex_age_race_5/aggregate?drilldown%5B%5D=%5BAge%5D.%5BAge%5D&drilldown%5B%5D=%5BSex%5D.%5BSex%5D&drilldown%5B%5D=%5BYear%5D.%5BYear%5D&drilldown%5B%5D=%5BPoverty+Status%5D.%5BPoverty+Status%5D&cut%5B%5D=%7B%5BPoverty+Status%5D.%5BPoverty+Status%5D.%5BPoverty+Status%5D.%26%5B0%5D%7D&cut%5B%5D=%7B%5BYear%5D.%5BYear%5D.%5BYear%5D.%26%5B2016%5D%7D&measures%5B%5D=Population+in+Poverty+by+Gender%2C+Age%2C+and+Race&nonempty=true&distinct=false&parents=false&debug=false&sparse=true HTTP/1.0" 400 19528 303.9920
Sep 26 14:36:54 canon datausa-acs_bundle[3240]: 96.89.227.150 - - [26/Sep/2018:18:36:54 +0000] "GET /cubes/acs_ygpsar_poverty_by_sex_age_race_5/aggregate?drilldown%5B%5D=%5BAge%5D.%5BAge%5D&drilldown%5B%5D=%5BSex%5D.%5BSex%5D&drilldown%5B%5D=%5BYear%5D.%5BYear%5D&drilldown%5B%5D=%5BPoverty+Status%5D.%5BPoverty+Status%5D&cut%5B%5D=%7B%5BPoverty+Status%5D.%5BPoverty+Status%5D.%5BPoverty+Status%5D.%26%5B0%5D%7D&cut%5B%5D=%7B%5BYear%5D.%5BYear%5D.%5BYear%5D.%26%5B2016%5D%7D&measures%5B%5D=Population+in+Poverty+by+Gender%2C+Age%2C+and+Race&nonempty=true&distinct=false&parents=false&debug=false&sparse=true HTTP/1.0" 400 19528 312.7799
Sep 26 14:36:57 canon datausa-acs_bundle[3240]: 96.89.227.150 - - [26/Sep/2018:18:36:57 +0000] "GET /cubes/acs_ygpsar_poverty_by_sex_age_race_5/aggregate?drilldown%5B%5D=%5BPoverty+Status%5D.%5BPoverty+Status%5D&drilldown%5B%5D=%5BYear%5D.%5BYear%5D&cut%5B%5D=%7B%5BYear%5D.%5BYear%5D.%5BYear%5D.%26%5B2016%5D%2C%5BYear%5D.%5BYear%5D.%5BYear%5D.%26%5B2015%5D%7D&measures%5B%5D=Population+in+Poverty+by+Gender%2C+Age%2C+and+Race&nonempty=true&distinct=false&parents=false&debug=false&sparse=true HTTP/1.0" 400 19528 308.1553
Sep 26 14:36:58 canon datausa-acs_bundle[3240]: 4059138998 [mondrian.rolap.RolapResultShepherd$executor_11] DEBUG mondrian.mdx  - 32442697: exec: 305030 ms
Sep 26 14:36:58 canon datausa-acs_bundle[3240]: 4059138998 [mondrian.rolap.RolapResultShepherd$executor_11] DEBUG mondrian.mdx  - 32442697: exec: 305030 ms
Sep 26 14:36:58 canon datausa-acs_bundle[3240]: 4059138998 [mondrian.rolap.RolapResultShepherd$executor_8] DEBUG mondrian.mdx  - 32442783: exec: 300218 ms
Sep 26 14:36:58 canon datausa-acs_bundle[3240]: 4059138998 [mondrian.rolap.RolapResultShepherd$executor_8] DEBUG mondrian.mdx  - 32442783: exec: 300218 ms
Sep 26 14:36:58 canon datausa-acs_bundle[3240]: 4059138998 [mondrian.rolap.RolapResultShepherd$executor_14] DEBUG mondrian.mdx  - 32442703: exec: 304546 ms
Sep 26 14:36:58 canon datausa-acs_bundle[3240]: 4059138998 [mondrian.rolap.RolapResultShepherd$executor_14] DEBUG mondrian.mdx  - 32442703: exec: 304546 ms
Sep 26 14:36:58 canon datausa-acs_bundle[3240]: 4059138998 [mondrian.rolap.RolapResultShepherd$executor_12] DEBUG mondrian.mdx  - 32442777: exec: 300721 ms
Sep 26 14:36:58 canon datausa-acs_bundle[3240]: 4059138998 [mondrian.rolap.RolapResultShepherd$executor_12] DEBUG mondrian.mdx  - 32442777: exec: 300721 ms
Sep 26 14:36:58 canon datausa-acs_bundle[3240]: 96.89.227.150 - - [26/Sep/2018:18:36:58 +0000] "GET /cubes/acs_ygpsar_poverty_by_sex_age_race_5/aggregate?drilldown%5B%5D=%5BRace%5D.%5BRace%5D&drilldown%5B%5D=%5BYear%5D.%5BYear%5D&drilldown%5B%5D=%5BPoverty+Status%5D.%5BPoverty+Status%5D&cut%5B%5D=%7B%5BPoverty+Status%5D.%5BPoverty+Status%5D.%5BPoverty+Status%5D.%26%5B0%5D%7D&cut%5B%5D=%7B%5BYear%5D.%5BYear%5D.%5BYear%5D.%26%5B2016%5D%7D&measures%5B%5D=Population+in+Poverty+by+Gender%2C+Age%2C+and+Race&measures%5B%5D=Population+in+Poverty+by+Gender%2C+Age%2C+and+Race+Moe&nonempty=true&distinct=false&parents=false&debug=false&sparse=true HTTP/1.0" 400 19528 305.2710
Sep 26 14:36:58 canon datausa-acs_bundle[3240]: 96.89.227.150 - - [26/Sep/2018:18:36:58 +0000] "GET /cubes/acs_ygpsar_poverty_by_sex_age_race_5/aggregate?drilldown%5B%5D=%5BAge%5D.%5BAge%5D&drilldown%5B%5D=%5BSex%5D.%5BSex%5D&drilldown%5B%5D=%5BYear%5D.%5BYear%5D&drilldown%5B%5D=%5BPoverty+Status%5D.%5BPoverty+Status%5D&cut%5B%5D=%7B%5BPoverty+Status%5D.%5BPoverty+Status%5D.%5BPoverty+Status%5D.%26%5B0%5D%7D&cut%5B%5D=%7B%5BYear%5D.%5BYear%5D.%5BYear%5D.%26%5B2016%5D%7D&measures%5B%5D=Population+in+Poverty+by+Gender%2C+Age%2C+and+Race&nonempty=true&distinct=false&parents=false&debug=false&sparse=true HTTP/1.0" 400 19528 305.4615
Sep 26 14:36:59 canon datausa-acs_bundle[3240]: 96.89.227.150 - - [26/Sep/2018:18:36:59 +0000] "GET /cubes/acs_ygpsar_poverty_by_sex_age_race_5/aggregate?drilldown%5B%5D=%5BPoverty+Status%5D.%5BPoverty+Status%5D&drilldown%5B%5D=%5BYear%5D.%5BYear%5D&cut%5B%5D=%7B%5BYear%5D.%5BYear%5D.%5BYear%5D.%26%5B2016%5D%2C%5BYear%5D.%5BYear%5D.%5BYear%5D.%26%5B2015%5D%7D&measures%5B%5D=Population+in+Poverty+by+Gender%2C+Age%2C+and+Race&nonempty=true&distinct=false&parents=false&debug=false&sparse=true HTTP/1.0" 400 19528 318.0395
Sep 26 14:37:00 canon datausa-acs_bundle[3240]: 4059140998 [mondrian.rolap.RolapResultShepherd$executor_20] DEBUG mondrian.mdx  - 32442756: exec: 303677 ms
Sep 26 14:37:00 canon datausa-acs_bundle[3240]: 4059140998 [mondrian.rolap.RolapResultShepherd$executor_20] DEBUG mondrian.mdx  - 32442756: exec: 303677 ms
Sep 26 14:37:00 canon datausa-acs_bundle[3240]: 4059140998 [mondrian.rolap.RolapResultShepherd$executor_5] DEBUG mondrian.mdx  - 32442789: exec: 301294 ms
Sep 26 14:37:00 canon datausa-acs_bundle[3240]: 4059140998 [mondrian.rolap.RolapResultShepherd$executor_5] DEBUG mondrian.mdx  - 32442789: exec: 301294 ms
Sep 26 14:37:00 canon datausa-acs_bundle[3240]: 4059140998 [mondrian.rolap.RolapResultShepherd$executor_6] DEBUG mondrian.mdx  - 32442792: exec: 300880 ms
Sep 26 14:37:00 canon datausa-acs_bundle[3240]: 4059140998 [mondrian.rolap.RolapResultShepherd$executor_6] DEBUG mondrian.mdx  - 32442792: exec: 300880 ms
Sep 26 14:37:00 canon datausa-acs_bundle[3240]: 96.89.227.150 - - [26/Sep/2018:18:37:00 +0000] "GET /cubes/acs_ygpsar_poverty_by_sex_age_race_5/aggregate?drilldown%5B%5D=%5BPoverty+Status%5D.%5BPoverty+Status%5D&drilldown%5B%5D=%5BYear%5D.%5BYear%5D&cut%5B%5D=%7B%5BYear%5D.%5BYear%5D.%5BYear%5D.%26%5B2016%5D%2C%5BYear%5D.%5BYear%5D.%5BYear%5D.%26%5B2015%5D%7D&measures%5B%5D=Population+in+Poverty+by+Gender%2C+Age%2C+and+Race&nonempty=true&distinct=false&parents=false&debug=false&sparse=true HTTP/1.0" 400 19528 307.6466
Sep 26 14:39:19 canon datausa-acs_bundle[3240]: 4059280010 [mondrian.rolap.agg.SegmentCacheManager$sqlExecutor_100] DEBUG mondrian.sql  - 289855: , exec 446357 ms
Sep 26 14:39:19 canon datausa-acs_bundle[3240]: 4059280010 [mondrian.rolap.agg.SegmentCacheManager$sqlExecutor_100] DEBUG mondrian.sql  - 289855: , exec 446357 ms
Sep 26 14:39:19 canon datausa-acs_bundle[3240]: 4059280367 [mondrian.rolap.agg.SegmentCacheManager$sqlExecutor_100] DEBUG mondrian.sql  - 289855: , exec+fetch 446894 ms, 13 rows
Sep 26 14:39:19 canon datausa-acs_bundle[3240]: 4059280367 [mondrian.rolap.agg.SegmentCacheManager$sqlExecutor_100] DEBUG mondrian.sql  - 289855: , exec+fetch 446894 ms, 13 rows
Sep 26 14:39:20 canon datausa-acs_bundle[3240]: java.lang.NullPointerException
Sep 26 14:39:20 canon datausa-acs_bundle[3240]: java.lang.NullPointerException
Sep 26 14:39:20 canon datausa-acs_bundle[3240]: java.lang.NullPointerException
Sep 26 14:39:20 canon datausa-acs_bundle[3240]: java.lang.NullPointerException
Sep 26 14:39:20 canon datausa-acs_bundle[3240]: java.lang.NullPointerException
Sep 26 14:39:20 canon datausa-acs_bundle[3240]: java.lang.NullPointerException
Sep 26 14:39:20 canon datausa-acs_bundle[3240]: java.lang.NullPointerException
Sep 26 14:39:20 canon datausa-acs_bundle[3240]: java.lang.NullPointerException
Sep 26 14:39:20 canon datausa-acs_bundle[3240]: java.lang.NullPointerException
Sep 26 14:39:36 canon datausa-acs_bundle[3240]: 4059296720 [mondrian.rolap.agg.SegmentCacheManager$sqlExecutor_86] DEBUG mondrian.sql  - 289856: , exec 463017 ms
Sep 26 14:39:36 canon datausa-acs_bundle[3240]: 4059296720 [mondrian.rolap.agg.SegmentCacheManager$sqlExecutor_86] DEBUG mondrian.sql  - 289856: , exec 463017 ms
Sep 26 14:39:36 canon datausa-acs_bundle[3240]: 4059297139 [mondrian.rolap.agg.SegmentCacheManager$sqlExecutor_86] DEBUG mondrian.sql  - 289856: , exec+fetch 463666 ms, 2 rows
Sep 26 14:39:36 canon datausa-acs_bundle[3240]: java.lang.NullPointerException4059297139 [mondrian.rolap.agg.SegmentCacheManager$sqlExecutor_86] DEBUG mondrian.sql  - 289856: , exec+fetch 463666 ms, 2 rows
Sep 26 14:39:36 canon datausa-acs_bundle[3240]: java.lang.NullPointerException
Sep 26 14:39:36 canon datausa-acs_bundle[3240]: java.lang.NullPointerException
Sep 26 14:39:36 canon datausa-acs_bundle[3240]: java.lang.NullPointerException
Sep 26 14:39:36 canon datausa-acs_bundle[3240]: java.lang.NullPointerException
Sep 26 14:39:36 canon datausa-acs_bundle[3240]: java.lang.NullPointerException
Sep 26 14:39:36 canon datausa-acs_bundle[3240]: java.lang.NullPointerException
Sep 26 14:39:36 canon datausa-acs_bundle[3240]: java.lang.NullPointerException
Sep 26 14:39:36 canon datausa-acs_bundle[3240]: java.lang.NullPointerException
Sep 26 14:40:01 canon datausa-acs_bundle[3240]: 4059322083 [mondrian.rolap.agg.SegmentCacheManager$sqlExecutor_54] DEBUG mondrian.sql  - 289850: , exec 489429 ms
Sep 26 14:40:01 canon datausa-acs_bundle[3240]: 4059322083 [mondrian.rolap.agg.SegmentCacheManager$sqlExecutor_54] DEBUG mondrian.sql  - 289850: , exec 489429 ms
Sep 26 14:40:02 canon datausa-acs_bundle[3240]: java.lang.NullPointerException4059322846 [mondrian.rolap.agg.SegmentCacheManager$sqlExecutor_54] DEBUG mondrian.sql  - 289850: , exec+fetch 490744 ms, 1 rows
Sep 26 14:40:02 canon datausa-acs_bundle[3240]: 4059322846 [mondrian.rolap.agg.SegmentCacheManager$sqlExecutor_54] DEBUG mondrian.sql  - 289850: , exec+fetch 490744 ms, 1 rows
Sep 26 14:40:02 canon datausa-acs_bundle[3240]: java.lang.NullPointerException
Sep 26 14:40:02 canon datausa-acs_bundle[3240]: java.lang.NullPointerException
Sep 26 14:40:02 canon datausa-acs_bundle[3240]: java.lang.NullPointerException
Sep 26 14:40:02 canon datausa-acs_bundle[3240]: java.lang.NullPointerException
Sep 26 14:40:02 canon datausa-acs_bundle[3240]: java.lang.NullPointerException
Sep 26 14:40:02 canon datausa-acs_bundle[3240]: java.lang.NullPointerException
Sep 26 14:40:02 canon datausa-acs_bundle[3240]: java.lang.NullPointerException
Sep 26 14:40:02 canon datausa-acs_bundle[3240]: java.lang.NullPointerException
Sep 26 14:40:02 canon datausa-acs_bundle[3240]: java.lang.NullPointerException
Sep 26 14:40:02 canon datausa-acs_bundle[3240]: java.lang.NullPointerException
Sep 26 14:40:02 canon datausa-acs_bundle[3240]: java.lang.NullPointerException
Sep 26 14:40:02 canon datausa-acs_bundle[3240]: java.lang.NullPointerException
Sep 26 14:40:02 canon datausa-acs_bundle[3240]: java.lang.NullPointerException
Sep 26 14:40:02 canon datausa-acs_bundle[3240]: java.lang.NullPointerException
Sep 26 14:40:02 canon datausa-acs_bundle[3240]: java.lang.NullPointerException
Sep 26 14:40:02 canon datausa-acs_bundle[3240]: java.lang.NullPointerException
Sep 26 14:40:02 canon datausa-acs_bundle[3240]: java.lang.NullPointerException
Sep 26 14:40:07 canon datausa-acs_bundle[3240]: 4059327904 [mondrian.rolap.agg.SegmentCacheManager$sqlExecutor_73] DEBUG mondrian.sql  - 289849: , exec 495432 ms
Sep 26 14:40:07 canon datausa-acs_bundle[3240]: 4059327904 [mondrian.rolap.agg.SegmentCacheManager$sqlExecutor_73] DEBUG mondrian.sql  - 289849: , exec 495432 ms
Sep 26 14:40:08 canon datausa-acs_bundle[3240]: java.lang.NullPointerException
Sep 26 14:40:08 canon datausa-acs_bundle[3240]: java.lang.NullPointerException
Sep 26 14:40:08 canon datausa-acs_bundle[3240]: 4059328701 [mondrian.rolap.agg.SegmentCacheManager$sqlExecutor_73] DEBUG mondrian.sql  - 289849: , exec+fetch 496599 ms, 10 rows
Sep 26 14:40:08 canon datausa-acs_bundle[3240]: 4059328701 [mondrian.rolap.agg.SegmentCacheManager$sqlExecutor_73] DEBUG mondrian.sql  - 289849: , exec+fetch 496599 ms, 10 rows
Sep 26 14:40:08 canon datausa-acs_bundle[3240]: java.lang.NullPointerException
Sep 26 14:40:08 canon datausa-acs_bundle[3240]: java.lang.NullPointerException
Sep 26 14:40:08 canon datausa-acs_bundle[3240]: java.lang.NullPointerException
Sep 26 14:40:08 canon datausa-acs_bundle[3240]: java.lang.NullPointerException
Sep 26 14:40:08 canon datausa-acs_bundle[3240]: java.lang.NullPointerException
Sep 26 14:40:08 canon datausa-acs_bundle[3240]: java.lang.NullPointerException
Sep 26 14:40:08 canon datausa-acs_bundle[3240]: java.lang.NullPointerException
Sep 26 14:40:08 canon datausa-acs_bundle[3240]: java.lang.NullPointerException
Sep 26 14:40:08 canon datausa-acs_bundle[3240]: java.lang.NullPointerException
Sep 26 14:40:08 canon datausa-acs_bundle[3240]: java.lang.NullPointerException
Sep 26 14:40:08 canon datausa-acs_bundle[3240]: java.lang.NullPointerException
Sep 26 14:40:08 canon datausa-acs_bundle[3240]: java.lang.NullPointerException
Sep 26 14:40:08 canon datausa-acs_bundle[3240]: java.lang.NullPointerException
Sep 26 14:40:08 canon datausa-acs_bundle[3240]: java.lang.NullPointerException
Sep 26 14:40:08 canon datausa-acs_bundle[3240]: java.lang.NullPointerException
Sep 26 14:40:08 canon datausa-acs_bundle[3240]: java.lang.NullPointerException
Sep 26 14:40:08 canon datausa-acs_bundle[3240]: 4059328712 [mondrian.rolap.RolapResultShepherd$executor_15] DEBUG mondrian.mdx  - 32442602: exec: 496616 ms
Sep 26 14:40:08 canon datausa-acs_bundle[3240]: 4059328712 [mondrian.rolap.RolapResultShepherd$executor_15] DEBUG mondrian.mdx  - 32442602: exec: 496616 ms
Sep 26 14:44:06 canon datausa-acs_bundle[3240]: I, [2018-09-26T18:44:06.609546 #3240]  INFO -- : Executing MDX query SELECT NON EMPTY {[Measures].[Average Age], [Measures].[Average Age Appx MOE]} ON COLUMNS,
Sep 26 14:44:06 canon datausa-acs_bundle[3240]: NON EMPTY [Geography].[Geography].[PUMA].Members * [Year].[Year].[Year].Members ON ROWS
Sep 26 14:44:06 canon datausa-acs_bundle[3240]: FROM [pums_5]
Sep 26 14:44:06 canon datausa-acs_bundle[3240]: 4059566991 [mondrian.rolap.RolapResultShepherd$executor_3] DEBUG mondrian.mdx  - 32475908: select NON EMPTY {[Measures].[Average Age], [Measures].[Average Age Appx MOE]} ON COLUMNS,
Sep 26 14:44:06 canon datausa-acs_bundle[3240]:   NON EMPTY ([Geography].[PUMA].Members * [Year].[Year].Members) ON ROWS
Sep 26 14:44:06 canon datausa-acs_bundle[3240]: from [pums_5]
Sep 26 14:44:06 canon datausa-acs_bundle[3240]: 4059566991 [mondrian.rolap.RolapResultShepherd$executor_3] DEBUG mondrian.mdx  - 32475908: select NON EMPTY {[Measures].[Average Age], [Measures].[Average Age Appx MOE]} ON COLUMNS,
Sep 26 14:44:06 canon datausa-acs_bundle[3240]:   NON EMPTY ([Geography].[PUMA].Members * [Year].[Year].Members) ON ROWS
Sep 26 14:44:06 canon datausa-acs_bundle[3240]: from [pums_5]
Sep 26 14:44:06 canon datausa-acs_bundle[3240]: 4059567007 [mondrian.rolap.RolapResultShepherd$executor_3] DEBUG mondrian.sql  - 290967: SqlMemberSource.getLevelMemberCount: executing sql [
Sep 26 14:44:06 canon datausa-acs_bundle[3240]: select
Sep 26 14:44:06 canon datausa-acs_bundle[3240]:     count(*) as "c0"
Sep 26 14:44:06 canon datausa-acs_bundle[3240]: from
Sep 26 14:44:06 canon datausa-acs_bundle[3240]:     (select distinct
Sep 26 14:44:06 canon datausa-acs_bundle[3240]:     "pumas"."geoid" as "c0"
Sep 26 14:44:06 canon datausa-acs_bundle[3240]: from
Sep 26 14:44:06 canon datausa-acs_bundle[3240]:     "shapes2017"."pumas" as "pumas") as "init"]
Sep 26 14:44:06 canon datausa-acs_bundle[3240]: 4059567007 [mondrian.rolap.RolapResultShepherd$executor_3] DEBUG mondrian.sql  - 290967: SqlMemberSource.getLevelMemberCount: executing sql [
Sep 26 14:44:06 canon datausa-acs_bundle[3240]: select
Sep 26 14:44:06 canon datausa-acs_bundle[3240]:     count(*) as "c0"
Sep 26 14:44:06 canon datausa-acs_bundle[3240]: from
Sep 26 14:44:06 canon datausa-acs_bundle[3240]:     (select distinct
Sep 26 14:44:06 canon datausa-acs_bundle[3240]:     "pumas"."geoid" as "c0"
Sep 26 14:44:06 canon datausa-acs_bundle[3240]: from
Sep 26 14:44:06 canon datausa-acs_bundle[3240]:     "shapes2017"."pumas" as "pumas") as "init"]
Sep 26 14:44:06 canon datausa-acs_bundle[3240]: 4059567034 [mondrian.rolap.RolapResultShepherd$executor_3] DEBUG mondrian.sql  - 290967: , exec 6 ms
Sep 26 14:44:06 canon datausa-acs_bundle[3240]: 4059567034 [mondrian.rolap.RolapResultShepherd$executor_3] DEBUG mondrian.sql  - 290967: , exec 6 ms
Sep 26 14:44:06 canon datausa-acs_bundle[3240]: 4059567034 [mondrian.rolap.RolapResultShepherd$executor_3] DEBUG mondrian.sql  - 290967: , exec+fetch 27 ms, 1 rows

@hwchen
Copy link
Author

hwchen commented Oct 4, 2018

Interestingly, the errors that canon reports are only from October 3 onwards.

@jspeis
Copy link
Member

jspeis commented Oct 10, 2018

@hwchen check this out pentaho/mondrian#1038 -- I think that's might be the same issue we're seeing. I wonder if there's a way we can try to apply that patch

@jspeis
Copy link
Member

jspeis commented Oct 22, 2018

going to close this out as it seems the NullPointerException has not recurred!

@jspeis jspeis closed this as completed Oct 22, 2018
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees

@jspeis jspeis

@hwchen hwchen

Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@jspeis @hwchen