We are trying to use the Ubercart Products Recommender (6.x-2.0-alpha1) working, and when running the recommender from the recommender admin interface, and then executing run.sh from the shell, we are getting status=failure and the following message:

Command evaluation error. See script log for details. Error: Sourced file: inline evaluation of: ``app.runRecommender(); //uc_rec_i2i;'' : Method Invocation app.runRecommender : at Line: 1 : in file: inline evaluation of: ``app.runRecommender(); //uc_rec_i2i;'' : app .runRecommender ( ) Target exception: java.lang.NullPointerException

I've done a lot of searching but don't seem to be getting any clues on the source of the issue. Hoping that someone with more knowledge in this area can point me in the right direction.

Thanks

Comments

shotokai’s picture

shotokai commented

To try and figure things out a bit better I installed the history recommender as well. Can't get that to work either. Here is the shell output when running run.sh 

# sh run.sh
Feb 10, 2012 6:50:39 PM org.drupal.project.async_command.AbstractDrupalApp handleCLI
INFO: DrupalApp VERSION: 6_1_2
Feb 10, 2012 6:50:39 PM org.drupal.project.async_command.AbstractDrupalApp handleCommandSettings
INFO: Set configuration file as: config.properties
Feb 10, 2012 6:50:39 PM org.drupal.project.async_command.AbstractDrupalApp getDefaultSettingsPhpFile
INFO: Jar file location: /var/www/vhosts/licmotorsports.com/httpdocs/sites/all/modules/recommender/recommender.jar
Feb 10, 2012 6:50:39 PM org.drupal.project.async_command.AbstractDrupalApp runApp
INFO: Total commands to be executed: 1
Feb 10, 2012 6:50:39 PM org.drupal.project.async_command.AbstractDrupalApp runApp
INFO: Running async_command: runRecommender(); //history_rec
Feb 10, 2012 6:50:39 PM org.drupal.project.recommender.RecommenderApp$AlgorithmImpl run
INFO: Initializing data model, similarity and recommender.
Feb 10, 2012 6:50:39 PM org.drupal.project.recommender.RecommenderApp$AlgorithmImpl initDataModel
INFO: Initializing data model.
log4j:WARN No appenders could be found for logger (org.apache.mahout.cf.taste.impl.model.jdbc.AbstractJDBCDataModel).
log4j:WARN Please initialize the log4j system properly.
log4j:WARN See http://logging.apache.org/log4j/1.2/faq.html#noconfig for more info.
Feb 10, 2012 6:50:39 PM org.drupal.project.recommender.RecommenderApp$AlgorithmImpl initDataModel
INFO: Switching to MEMORY mode. Load all data from database into memory first.
Feb 10, 2012 6:50:39 PM org.drupal.project.recommender.RecommenderApp$AlgorithmImpl run
INFO: Using similarity class: org.apache.mahout.cf.taste.impl.similarity.LogLikelihoodSimilarity
Feb 10, 2012 6:50:39 PM org.drupal.project.recommender.RecommenderApp$AlgorithmImpl run
INFO: Using recommender class: org.apache.mahout.cf.taste.impl.recommender.GenericBooleanPrefItemBasedRecommender
Feb 10, 2012 6:50:39 PM org.drupal.project.recommender.RecommenderApp$AlgorithmImpl run
INFO: Computing and saving similarity data.
Feb 10, 2012 6:50:39 PM org.drupal.project.async_command.AbstractDrupalApp runCommand
SEVERE: Cannot execute the command: runRecommender(); //history_rec
org.drupal.project.async_command.EvaluationFailureException: Sourced file: inline evaluation of: ``app.runRecommender(); //history_rec;'' : Method Invocation app.runRecommender : at Line: 1 : in file: inline evaluation of: ``app.runRecommender(); //history_rec;'' : app .runRecommender ( ) 

Target exception: java.lang.NullPointerException

        at org.drupal.project.async_command.AbstractDrupalApp.runCommand(AbstractDrupalApp.java:125)
        at org.drupal.project.async_command.AbstractDrupalApp.runApp(AbstractDrupalApp.java:90)
        at org.drupal.project.async_command.AbstractDrupalApp.handleCommandExecutables(AbstractDrupalApp.java:397)
        at org.drupal.project.async_command.AbstractDrupalApp.handleCLI(AbstractDrupalApp.java:366)
        at org.drupal.project.recommender.RecommenderApp.main(RecommenderApp.java:660)
Caused by: Sourced file: inline evaluation of: ``app.runRecommender(); //history_rec;'' : Method Invocation app.runRecommender : at Line: 1 : in file: inline evaluation of: ``app.runRecommender(); //history_rec;'' : app .runRecommender ( ) 

Target exception: java.lang.NullPointerException

        at bsh.BSHMethodInvocation.eval(Unknown Source)
        at bsh.BSHPrimaryExpression.eval(Unknown Source)
        at bsh.BSHPrimaryExpression.eval(Unknown Source)
        at bsh.Interpreter.eval(Unknown Source)
        at bsh.Interpreter.eval(Unknown Source)
        at bsh.Interpreter.eval(Unknown Source)
        at org.drupal.project.async_command.AbstractDrupalApp.runCommand(AbstractDrupalApp.java:121)
        ... 4 more

Any guidance greatly appreciated!

danithaca’s picture

danithaca commented

Have you modified run.sh? If so, please post it as well.
Also, you might delete all records in the {async_command} table before try to run it again.
Let me know if you still experience this problem.

shotokai’s picture

shotokai commented

Dan - thanks for your help!

The only modification to run.sh is that I uncommented CONFIG_FILE in async_command/run.sh:

# this is an example of run.sh.
# If you are under Linux/Mac, just create a new run.sh following the example here.
# If you are under Windows, please create a run.bat by following the example here.

# specify the location and filename of config.properties file. Default is the working directory
# if the file is not under the working directory, please use '-c $CONFIG_FILE' option when executing the Java program.
CONFIG_FILE=config.properties

# please make sure you have java installed.
command -v java >/dev/null || { echo "Cannot find java program. Please install Java first and make sure the executable is under PATH."; exit 1;}

# config CLASSPATH: add all jar files under lib.
CLASSPATH="${CLASSPATH}:$(find "lib" -name "*.jar" | tr '\n' ':')"



# execute the command, find config.properties in working directory
java -cp $CLASSPATH org.drupal.project.async_command.DefaultDrupalApp

# or, execute the command, find config.properties specified by CONFIG_FILE
#java -cp $CLASSPATH org.drupal.project.async_command.DefaultDrupalApp -c $CONFIG_FILE

# or, read the help of DefaultDrupalApp
#java -cp $CLASSPATH org.drupal.project.async_command.DefaultDrupalApp -h

Before uncommenting that line it was reading my database name incorrectly (placing a / before the name) and was unable to connect.

I've tried flushing that table but still the same output at the shell. Thanks again.

danithaca’s picture

danithaca commented
Status: Active » Needs work

I'm make considerable changes to the code these days. I'll give it a thorough test once it's done.

danithaca’s picture

danithaca commented
Status: Needs work » Needs review

Please try 6.x-3.0-alpha4. The problem seems to be fixed.

It's a little strange that I see this problem too on my other development machine. But when I restart that machine, the problem goes away. I suspect this is some java class loading problem.

superfedya’s picture

superfedya commented
Version: 6.x-3.0-alpha3 » 6.x-3.0-alpha4

After re-installation of the alpha4 it doesn't works...

Command evaluation error. See script log for details. Error: Sourced file: inline evaluation of: ``app.runRecommender();'' : Method Invocation app.runRecommender : at Line: 1 : in file: inline evaluation of: ``app.runRecommender();'' : app .runRecommender ( ) Target exception: java.lang.NullPointerException 

Jun 5, 2012 1:07:42 AM org.drupal.project.async_command.AbstractDrupalApp handleCLI
INFO: DrupalApp VERSION: 6_1_2
Jun 5, 2012 1:07:42 AM org.drupal.project.async_command.AbstractDrupalApp getDefaultSettingsPhpFile
INFO: Jar file location: /var/www/mysite.com/sites/all/modules/recommender/recommender.jar
Jun 5, 2012 1:07:42 AM org.drupal.project.async_command.AbstractDrupalApp runApp
INFO: Total commands to be executed: 2
Jun 5, 2012 1:07:42 AM org.drupal.project.async_command.AbstractDrupalApp runApp
INFO: Running async_command: runRecommender()
Jun 5, 2012 1:07:42 AM org.drupal.project.recommender.RecommenderApp$AlgorithmImpl run
INFO: Initializing data model, similarity and recommender.
Jun 5, 2012 1:07:42 AM org.drupal.project.recommender.RecommenderApp$AlgorithmImpl initDataModel
INFO: Initializing data model.
Jun 5, 2012 1:07:42 AM org.drupal.project.recommender.RecommenderApp$AlgorithmImpl initDataModel
INFO: Switching to MEMORY mode. Load all data from database into memory first.
Jun 5, 2012 1:07:42 AM org.slf4j.impl.JCLLoggerAdapter info
INFO: Loading new JDBC delegate data...
Jun 5, 2012 1:07:42 AM org.slf4j.impl.JCLLoggerAdapter info
INFO: New data loaded.
Jun 5, 2012 1:07:42 AM org.drupal.project.recommender.RecommenderApp$AlgorithmImpl run
INFO: Using similarity class: org.apache.mahout.cf.taste.impl.similarity.LogLikelihoodSimilarity
Jun 5, 2012 1:07:42 AM org.drupal.project.recommender.RecommenderApp$AlgorithmImpl run
INFO: Using recommender class: org.apache.mahout.cf.taste.impl.recommender.GenericBooleanPrefItemBasedRecommender
Jun 5, 2012 1:07:42 AM org.drupal.project.recommender.RecommenderApp$AlgorithmImpl run
INFO: Computing and saving similarity data.
Jun 5, 2012 1:07:42 AM org.drupal.project.async_command.AbstractDrupalApp runCommand
SEVERE: Cannot execute the command: runRecommender()
org.drupal.project.async_command.EvaluationFailureException: Sourced file: inline evaluation of: ``app.runRecommender();'' : Method Invocation app.runRecommender : at Line: 1 : in file: inline evaluation of: ``app.runRecommender();'' : app .runRecommender ( )

Target exception: java.lang.NullPointerException

        at org.drupal.project.async_command.AbstractDrupalApp.runCommand(AbstractDrupalApp.java:125)
        at org.drupal.project.async_command.AbstractDrupalApp.runApp(AbstractDrupalApp.java:90)
        at org.drupal.project.async_command.AbstractDrupalApp.handleCommandExecutables(AbstractDrupalApp.java:397)
        at org.drupal.project.async_command.AbstractDrupalApp.handleCLI(AbstractDrupalApp.java:366)
        at org.drupal.project.recommender.RecommenderApp.main(RecommenderApp.java:660)
Caused by: Sourced file: inline evaluation of: ``app.runRecommender();'' : Method Invocation app.runRecommender : at Line: 1 : in file: inline evaluation of: ``app.runRecommender();'' : app .runRecommender ( )

Target exception: java.lang.NullPointerException

        at bsh.BSHMethodInvocation.eval(Unknown Source)
        at bsh.BSHPrimaryExpression.eval(Unknown Source)
        at bsh.BSHPrimaryExpression.eval(Unknown Source)
        at bsh.Interpreter.eval(Unknown Source)
        at bsh.Interpreter.eval(Unknown Source)
        at bsh.Interpreter.eval(Unknown Source)
        at org.drupal.project.async_command.AbstractDrupalApp.runCommand(AbstractDrupalApp.java:121)
        ... 4 more
Jun 5, 2012 1:07:42 AM org.drupal.project.async_command.AbstractDrupalApp runApp
INFO: Running async_command: runRecommender()
Jun 5, 2012 1:07:42 AM org.drupal.project.recommender.RecommenderApp processTable
INFO: Using {recommender_preference_staging} table. Loading data.
Jun 5, 2012 1:07:42 AM org.drupal.project.recommender.RecommenderApp$AlgorithmImpl run
INFO: Initializing data model, similarity and recommender.
Jun 5, 2012 1:07:42 AM org.drupal.project.recommender.RecommenderApp$AlgorithmImpl initDataModel
INFO: Initializing data model.
Jun 5, 2012 1:07:42 AM org.drupal.project.recommender.RecommenderApp$AlgorithmImpl initDataModel
INFO: Switching to MEMORY mode. Load all data from database into memory first.
Jun 5, 2012 1:07:42 AM org.slf4j.impl.JCLLoggerAdapter info
INFO: Loading new JDBC delegate data...
Jun 5, 2012 1:07:42 AM org.slf4j.impl.JCLLoggerAdapter info
INFO: New data loaded.
Jun 5, 2012 1:07:42 AM org.drupal.project.recommender.RecommenderApp$AlgorithmImpl run
INFO: Using similarity class: org.apache.mahout.cf.taste.impl.similarity.LogLikelihoodSimilarity
Jun 5, 2012 1:07:42 AM org.drupal.project.recommender.RecommenderApp$AlgorithmImpl run
INFO: Using recommender class: org.apache.mahout.cf.taste.impl.recommender.GenericBooleanPrefItemBasedRecommender
Jun 5, 2012 1:07:42 AM org.drupal.project.recommender.RecommenderApp$AlgorithmImpl run
INFO: Computing and saving similarity data.
Jun 5, 2012 1:07:42 AM org.drupal.project.async_command.AbstractDrupalApp runCommand
SEVERE: Cannot execute the command: runRecommender()
org.drupal.project.async_command.EvaluationFailureException: Sourced file: inline evaluation of: ``app.runRecommender();'' : Method Invocation app.runRecommender : at Line: 1 : in file: inline evaluation of: ``app.runRecommender();'' : app .runRecommender ( )

Target exception: java.lang.NullPointerException

        at org.drupal.project.async_command.AbstractDrupalApp.runCommand(AbstractDrupalApp.java:125)
        at org.drupal.project.async_command.AbstractDrupalApp.runApp(AbstractDrupalApp.java:90)
        at org.drupal.project.async_command.AbstractDrupalApp.handleCommandExecutables(AbstractDrupalApp.java:397)
        at org.drupal.project.async_command.AbstractDrupalApp.handleCLI(AbstractDrupalApp.java:366)
        at org.drupal.project.recommender.RecommenderApp.main(RecommenderApp.java:660)
Caused by: Sourced file: inline evaluation of: ``app.runRecommender();'' : Method Invocation app.runRecommender : at Line: 1 : in file: inline evaluation of: ``app.runRecommender();'' : app .runRecommender ( )

Target exception: java.lang.NullPointerException

        at bsh.BSHMethodInvocation.eval(Unknown Source)
        at bsh.BSHPrimaryExpression.eval(Unknown Source)
        at bsh.BSHPrimaryExpression.eval(Unknown Source)
        at bsh.Interpreter.eval(Unknown Source)
        at bsh.Interpreter.eval(Unknown Source)
        at bsh.Interpreter.eval(Unknown Source)
        at org.drupal.project.async_command.AbstractDrupalApp.runCommand(AbstractDrupalApp.java:121)
        ... 4 more

I removed Rec, Async and reinstalled it, same problem.
Ping me works fine (Ping successful.).

On the test site (same server) it works fine. So, it's database fault? How I can erase this module completely?

Thanks

superfedya’s picture

superfedya commented

It doesn't work even after install of Alpha 1.

upd. it works after update to Alpha 2.

Alpha 3 - works.

Alpha 4 - works.

So strange. maybe because for alpha 2 I use WinSCP and not FileZilla...

danithaca’s picture

danithaca commented
Status: Needs review » Fixed

It's a strange problem... My own experience is that sometimes Java stores old cache to old classes, and then even though you update the new classes on the hard drive won't clean up the cache in memory. But this is my own hypothesis. I'm not sure if it's the reason.

So I'd consider this issues as fixed. If you have other questions, feel free to reopen it.

neilnz’s picture

neilnz commented
Status: Fixed » Needs review

This is not fixed in alpha4, I had the exact same output as #1

Java:

java version "1.6.0_20"
OpenJDK Runtime Environment (IcedTea6 1.9.13) (6b20-1.9.13-0ubuntu1~10.04.1)
OpenJDK 64-Bit Server VM (build 19.0-b09, mixed mode)

run.sh from the recommender module (stock) and using the config.properties edited only for database settings.

I'm running the git tip of recommender 6.x-3.x and async_command 6.x-1.x.

It appears that the use of eval() is masking the actual source of the NullPointerException. I traced the actual cause of it down to this code in RecommenderApp.java:

// check database status.
String tableName = "{recommender_" + tableIdentifier + "}";
long pastMaxTimestamp = DrupalUtils.getLong(queryValue("SELECT max(updated) FROM " + tableName));
System.out.println(pastMaxTimestamp);
if (pastMaxTimestamp > updatedTimestamp) {
    logger.severe("Please reinstall Recommender API or manually remove all data from " + tableName + ". It has records with timestamp newer than the current timestamp");
    throw new DrupalRuntimeException("Internal database error. Please reinstall recommender module of your Drupal site.");
}

Running in a debugger, I noticed that tableName is set to "{recommender_prediction}". This table is empty on a new install. This means that DrupalUtils.getLong returns null. You can't store null in a primitive long, so it throws a NullPointerException that bubbles all the way back up and crashes the whole app.

Here's a possible solution that works for me, swapping the primitive long for Long, which can accept null:

--- a/src/org/drupal/project/recommender/RecommenderApp.java
+++ b/src/org/drupal/project/recommender/RecommenderApp.java
@@ -420,8 +420,8 @@ public class RecommenderApp extends AbstractDrupalApp {
         protected void genericComputeSave(EntityHandler handler, LongPrimitiveIterator entityIterator, int numEntity, String tableIdentifier, boolean rebuild) throws TasteExc
             // check database status.
             String tableName = "{recommender_" + tableIdentifier + "}";
-            long pastMaxTimestamp = DrupalUtils.getLong(queryValue("SELECT max(updated) FROM " + tableName));
-            if (pastMaxTimestamp > updatedTimestamp) {
+            Long pastMaxTimestamp = DrupalUtils.getLong(queryValue("SELECT max(updated) FROM " + tableName));
+            if (pastMaxTimestamp != null && pastMaxTimestamp > updatedTimestamp) {
                 logger.severe("Please reinstall Recommender API or manually remove all data from " + tableName + ". It has records with timestamp newer than the current times
                 throw new DrupalRuntimeException("Internal database error. Please reinstall recommender module of your Drupal site.");
             }

It now runs to completion and populates the table properly.

It looks like future (D7) versions of this work in a different way, so this fix is possibly not forward-portable.

An alternative quick fix for those having trouble is to insert a dummy row into recommender_similarity with an update timestamp to get up and running.

superfedya’s picture

superfedya commented
Priority: Normal » Critical

So, I just need to replace those 2 lines:

            long pastMaxTimestamp = DrupalUtils.getLong(queryValue("SELECT max(updated) FROM " + tableName));
            if (pastMaxTimestamp > updatedTimestamp) {

By:

            Long pastMaxTimestamp = DrupalUtils.getLong(queryValue("SELECT max(updated) FROM " + tableName));
            if (pastMaxTimestamp != null && pastMaxTimestamp > updatedTimestamp) {

Done and reinstalled Recommender. But still have same issue.

Command evaluation error. See script log for details. Error: Sourced file: inline evaluation of: ``app.runRecommender();'' : Method Invocation app.runRecommender : at Line: 1 : in file: inline evaluation of: ``app.runRecommender();'' : app .runRecommender ( ) Target exception: java.lang.NullPointerException

Too many problems with this module :( I uninstalled it and waiting to the next version.

An alternative quick fix for those having trouble is to insert a dummy row into recommender_similarity with an update timestamp to get up and running.

How I can do that?

Thanks

danithaca’s picture

danithaca commented
Issue summary: View changes

Release 6.x-3.x is not supported anymore. Please consider upgrading to 7.x-6.x release for D7.

danithaca’s picture

danithaca commented
Status: Needs review » Closed (won't fix)