Having trouble getting Recommender API to work at all. I'm using fivestar_rec to test that basic functionality is working. After setting config, running drupal crop, and executing run.sh, I'm presented with the following error:

Nov 11, 2011 1:32:52 PM org.drupal.project.async_command.CommandLineLauncher launch
INFO: DrupalApp VERSION: 7_1_1
Nov 11, 2011 1:32:52 PM org.drupal.project.async_command.CommandLineLauncher handleSettings
INFO: Set configuration file as: /home/msepjobs/public_html/sites/all/modules/recommender/../async_command/config.properties
Nov 11, 2011 1:32:52 PM org.drupal.project.async_command.DrupalConnection testConnection
INFO: Database connection successful: MySQL5.0.92-community
Nov 11, 2011 1:32:52 PM org.drupal.project.async_command.GenericDrupalApp runSerial
INFO: Total number of commands to run: 1
Nov 11, 2011 1:32:52 PM org.drupal.project.async_command.GenericDrupalApp runSerial
INFO: Executing command: RunRecommender
Nov 11, 2011 1:32:52 PM org.drupal.project.recommender.RunRecommender processTable
INFO: Using {recommender_preference_staging} table. Loading data.
Nov 11, 2011 1:32:52 PM org.drupal.project.recommender.RunRecommender$AlgorithmImpl run
INFO: Initializing data model, similarity and recommender.
Nov 11, 2011 1:32:52 PM org.drupal.project.recommender.RunRecommender$AlgorithmImpl initDataModel
INFO: Initializing data model.
Nov 11, 2011 1:32:52 PM org.drupal.project.recommender.RunRecommender$AlgorithmImpl initDataModel
INFO: Switching to MEMORY mode. Load all data from database into memory first.
Nov 11, 2011 1:32:52 PM org.slf4j.impl.JCLLoggerAdapter info
INFO: Loading new JDBC delegate data...
Nov 11, 2011 1:32:52 PM org.slf4j.impl.JCLLoggerAdapter info
INFO: Processed 2 users
Nov 11, 2011 1:32:52 PM org.slf4j.impl.JCLLoggerAdapter info
INFO: New data loaded.
Nov 11, 2011 1:32:52 PM org.drupal.project.recommender.RunRecommender$AlgorithmImpl run
INFO: Using similarity class: org.apache.mahout.cf.taste.impl.similarity.PearsonCorrelationSimilarity
Nov 11, 2011 1:32:52 PM org.drupal.project.recommender.RunRecommender$AlgorithmImpl run
INFO: Using recommender class: org.apache.mahout.cf.taste.impl.recommender.GenericItemBasedRecommender
Nov 11, 2011 1:32:52 PM org.drupal.project.recommender.RunRecommender$AlgorithmImpl run
INFO: Computing and saving similarity data.
Nov 11, 2011 1:32:52 PM org.drupal.project.recommender.RunRecommender$AlgorithmImpl genericComputeSave
INFO: Start computing recommendation and saving results.
Nov 11, 2011 1:32:52 PM org.drupal.project.recommender.RunRecommender$AlgorithmImpl genericComputeSave
INFO: Computing done. Waiting for data to be saved to database. Records#: 0
Nov 11, 2011 1:32:52 PM org.drupal.project.recommender.RunRecommender$AlgorithmImpl genericComputeSave
INFO: Done saving data.
Nov 11, 2011 1:32:52 PM org.drupal.project.recommender.RunRecommender$AlgorithmImpl run
INFO: Computing and saving prediction data.
Exception in thread "main" java.lang.NullPointerException
	at org.drupal.project.recommender.RunRecommender$AlgorithmImpl.genericComputeSave(RunRecommender.java:457)
	at org.drupal.project.recommender.RunRecommender$AlgorithmImpl.computeSavePrediction(RunRecommender.java:528)
	at org.drupal.project.recommender.RunRecommender$AlgorithmImpl.run(RunRecommender.java:552)
	at org.drupal.project.recommender.RunRecommender.run(RunRecommender.java:277)
	at org.drupal.project.async_command.GenericDrupalApp.runSerial(GenericDrupalApp.java:184)
	at org.drupal.project.async_command.GenericDrupalApp.run(GenericDrupalApp.java:157)
	at org.drupal.project.async_command.CommandLineLauncher.handleExecutables(CommandLineLauncher.java:95)
	at org.drupal.project.async_command.CommandLineLauncher.launch(CommandLineLauncher.java:63)
	at org.drupal.project.recommender.RecommenderApp.main(RecommenderApp.java:26)

Any idea what could be causing this?

Comments

danithaca’s picture

danithaca commented

In run.sh, use the following "java" command:

java -ea -Djava.util.logging.config.file=/home/daniel/logging.properties -cp $CLASSPATH org.drupal.project.recommender.RecommenderApp

logging.properties is like this:

############################################################
#  	Default Logging Configuration File
#
# You can use a different file by specifying a filename
# with the java.util.logging.config.file system property.  
# For example java -Djava.util.logging.config.file=myfile
############################################################

############################################################
#  	Global properties
############################################################

# "handlers" specifies a comma separated list of log Handler 
# classes.  These handlers will be installed during VM startup.
# Note that these classes must be on the system classpath.
# By default we only configure a ConsoleHandler, which will only
# show messages at the INFO and above levels.
handlers= java.util.logging.ConsoleHandler

# To also add the FileHandler, use the following line instead.
#handlers= java.util.logging.FileHandler, java.util.logging.ConsoleHandler

# Default global logging level.
# This specifies which kinds of events are logged across
# all loggers.  For any given facility this global level
# can be overriden by a facility specific level
# Note that the ConsoleHandler also has a separate level
# setting to limit messages printed to the console.
.level = FINEST

############################################################
# Handler specific properties.
# Describes specific configuration info for Handlers.
############################################################

# default file output is in user's home directory.
java.util.logging.FileHandler.pattern = %h/java%u.log
java.util.logging.FileHandler.limit = 50000
java.util.logging.FileHandler.count = 1
java.util.logging.FileHandler.formatter = java.util.logging.XMLFormatter

# Limit the message that are printed on the console to INFO and above.
java.util.logging.ConsoleHandler.level = FINEST
java.util.logging.ConsoleHandler.formatter = java.util.logging.SimpleFormatter


############################################################
# Facility specific properties.
# Provides extra control for each logger.
############################################################

# For example, set the com.xyz.foo logger to only log SEVERE
# messages:
org.drupal.project.async_command.level = FINEST

Use this to turn on all the debugging info, and then I'll take a look.

grasmash’s picture

grasmash commented

Thanks for helping out. I d/led the file and ran the command (with the -c flag). The output is:

Nov 11, 2011 3:17:16 PM org.drupal.project.async_command.CommandLineLauncher launch
INFO: DrupalApp VERSION: 7_2_5
Nov 11, 2011 3:17:16 PM org.drupal.project.async_command.CommandLineLauncher handleSettings
INFO: Set configuration file as: ../../../../sites/all/modules/async_command/config.properties
Nov 11, 2011 3:17:16 PM org.drupal.project.async_command.GenericDrupalApp <init>
FINE: Constructor called for GenericDrupalApp
Nov 11, 2011 3:17:16 PM org.drupal.project.async_command.DrupalConnection testConnection
INFO: Database connection successful: MySQL5.0.92-community
Nov 11, 2011 3:17:16 PM org.drupal.project.async_command.DrupalConnection retrievePendingCommandRecord
FINEST: Retrieving pending commands for recommender
Nov 11, 2011 3:17:16 PM org.drupal.project.async_command.DrupalConnection d
FINE: SELECT * FROM async_command WHERE app='recommender' AND (status IS NULL OR status='PEND')
Nov 11, 2011 3:17:16 PM org.drupal.project.async_command.GenericDrupalApp runSerial
INFO: Total number of commands to run: 0
Nov 11, 2011 3:17:16 PM org.drupal.project.async_command.GenericDrupalApp runSerial
FINE: Sorting commands.
Nov 11, 2011 3:17:16 PM org.drupal.project.async_command.GenericDrupalApp run
INFO: Shutdown parallel executor.
Nov 11, 2011 3:17:16 PM org.drupal.project.async_command.GenericDrupalApp run
INFO: Running the DrupalApp is accomplished.
Nov 11, 2011 3:17:16 PM org.drupal.project.async_command.CommandLineLauncher launch
INFO: Mission accomplished.
msepjobs@msepjobs.com [~/public_html/sites/all/modules/recommender]# ./run.sh
Nov 11, 2011 3:18:36 PM org.drupal.project.async_command.CommandLineLauncher launch
INFO: DrupalApp VERSION: 7_2_5
Nov 11, 2011 3:18:36 PM org.drupal.project.async_command.CommandLineLauncher handleSettings
INFO: Set configuration file as: ../../../../sites/all/modules/async_command/config.properties
Nov 11, 2011 3:18:36 PM org.drupal.project.async_command.GenericDrupalApp <init>
FINE: Constructor called for GenericDrupalApp
Nov 11, 2011 3:18:36 PM org.drupal.project.async_command.DrupalConnection testConnection
INFO: Database connection successful: MySQL5.0.92-community
Nov 11, 2011 3:18:36 PM org.drupal.project.async_command.DrupalConnection retrievePendingCommandRecord
FINEST: Retrieving pending commands for recommender
Nov 11, 2011 3:18:36 PM org.drupal.project.async_command.DrupalConnection d
FINE: SELECT * FROM async_command WHERE app='recommender' AND (status IS NULL OR status='PEND')
Nov 11, 2011 3:18:36 PM org.drupal.project.async_command.GenericDrupalApp runSerial
INFO: Total number of commands to run: 1
Nov 11, 2011 3:18:36 PM org.drupal.project.async_command.GenericDrupalApp runSerial
FINE: Sorting commands.
Nov 11, 2011 3:18:36 PM org.drupal.project.async_command.DrupalConnection d
FINE: SELECT params FROM recommender_app WHERE id=?
Nov 11, 2011 3:18:36 PM org.drupal.project.async_command.GenericDrupalApp runSerial
INFO: Executing command: RunRecommender
Nov 11, 2011 3:18:36 PM org.drupal.project.recommender.RunRecommender processTable
INFO: Using {recommender_preference_staging} table. Loading data.
Nov 11, 2011 3:18:36 PM org.drupal.project.async_command.DrupalConnection update
FINEST: SQL UPDATE: DELETE FROM {recommender_preference_staging}
Nov 11, 2011 3:18:36 PM org.drupal.project.async_command.DrupalConnection d
FINE: DELETE FROM recommender_preference_staging
Nov 11, 2011 3:18:37 PM org.drupal.project.async_command.DrupalConnection d
FINE: SELECT uid, entity_id, AVG(value) AS value, MAX(timestamp) AS timestamp FROM votingapi_vote WHERE entity_type='node' AND value_type='percent' AND tag='vote' AND uid>0 GROUP BY uid, entity_id
Nov 11, 2011 3:18:37 PM org.drupal.project.async_command.DrupalConnection batch
FINEST: SQL BATCH: INSERT INTO {recommender_preference_staging}(source_eid, target_eid, score, updated) VALUES(?, ?, ?, ?)
Nov 11, 2011 3:18:37 PM org.drupal.project.async_command.DrupalConnection batch
FINEST: Number of rows in batch: 3
Nov 11, 2011 3:18:37 PM org.drupal.project.async_command.DrupalConnection d
FINE: INSERT INTO recommender_preference_staging(source_eid, target_eid, score, updated) VALUES(?, ?, ?, ?)
Nov 11, 2011 3:18:37 PM org.drupal.project.async_command.DrupalConnection batch
FINEST: Batch processing all.
Nov 11, 2011 3:18:37 PM org.drupal.project.async_command.DrupalConnection d
FINE: recommender_preference_staging
Nov 11, 2011 3:18:37 PM org.drupal.project.recommender.RunRecommender$AlgorithmImpl run
INFO: Initializing data model, similarity and recommender.
Nov 11, 2011 3:18:37 PM org.drupal.project.recommender.RunRecommender$AlgorithmImpl initDataModel
INFO: Initializing data model.
Nov 11, 2011 3:18:37 PM org.slf4j.impl.JCLLoggerAdapter debug
FINE: Creating AbstractJDBCModel...
Nov 11, 2011 3:18:37 PM org.slf4j.impl.JCLLoggerAdapter debug
FINE: preferenceTable: recommender_preference_staging
Nov 11, 2011 3:18:37 PM org.slf4j.impl.JCLLoggerAdapter debug
FINE: userIDColumn: source_eid
Nov 11, 2011 3:18:37 PM org.slf4j.impl.JCLLoggerAdapter debug
FINE: itemIDColumn: target_eid
Nov 11, 2011 3:18:37 PM org.slf4j.impl.JCLLoggerAdapter debug
FINE: preferenceColumn: score
Nov 11, 2011 3:18:37 PM org.slf4j.impl.JCLLoggerAdapter debug
FINE: dataSource: org.apache.mahout.cf.taste.impl.model.jdbc.ConnectionPoolDataSource@665b9efd
Nov 11, 2011 3:18:37 PM org.slf4j.impl.JCLLoggerAdapter debug
FINE: getUserSQL: SELECT DISTINCT source_eid, target_eid, score FROM recommender_preference_staging WHERE source_eid=? ORDER BY target_eid
Nov 11, 2011 3:18:37 PM org.slf4j.impl.JCLLoggerAdapter debug
FINE: getAllUsersSQL: SELECT DISTINCT source_eid, target_eid, score FROM recommender_preference_staging ORDER BY source_eid, target_eid
Nov 11, 2011 3:18:37 PM org.slf4j.impl.JCLLoggerAdapter debug
FINE: getPreferenceSQL: SELECT score FROM recommender_preference_staging WHERE source_eid=? AND target_eid=?
Nov 11, 2011 3:18:37 PM org.slf4j.impl.JCLLoggerAdapter debug
FINE: getNumItemsSQL: SELECT COUNT(DISTINCT target_eid) FROM recommender_preference_staging
Nov 11, 2011 3:18:37 PM org.slf4j.impl.JCLLoggerAdapter debug
FINE: getNumUsersSQL: SELECT COUNT(DISTINCT source_eid) FROM recommender_preference_staging
Nov 11, 2011 3:18:37 PM org.slf4j.impl.JCLLoggerAdapter debug
FINE: setPreferenceSQL: INSERT INTO recommender_preference_staging(source_eid,target_eid,score) VALUES (?,?,?) ON DUPLICATE KEY UPDATE score=?
Nov 11, 2011 3:18:37 PM org.slf4j.impl.JCLLoggerAdapter debug
FINE: removePreferenceSQL: DELETE FROM recommender_preference_staging WHERE source_eid=? AND target_eid=?
Nov 11, 2011 3:18:37 PM org.slf4j.impl.JCLLoggerAdapter debug
FINE: getUsersSQL: SELECT DISTINCT source_eid FROM recommender_preference_staging ORDER BY source_eid
Nov 11, 2011 3:18:37 PM org.slf4j.impl.JCLLoggerAdapter debug
FINE: getItemsSQL: SELECT DISTINCT target_eid FROM recommender_preference_staging ORDER BY target_eid
Nov 11, 2011 3:18:37 PM org.slf4j.impl.JCLLoggerAdapter debug
FINE: getPrefsForItemSQL: SELECT DISTINCT source_eid, target_eid, score FROM recommender_preference_staging WHERE target_eid=? ORDER BY source_eid
Nov 11, 2011 3:18:37 PM org.slf4j.impl.JCLLoggerAdapter debug
FINE: getNumPreferenceForItemSQL: SELECT COUNT(1) FROM recommender_preference_staging WHERE target_eid=?
Nov 11, 2011 3:18:37 PM org.slf4j.impl.JCLLoggerAdapter debug
FINE: getNumPreferenceForItemsSQL: SELECT COUNT(1) FROM recommender_preference_staging tp1 JOIN recommender_preference_staging tp2 USING (source_eid) WHERE tp1.target_eid=? and tp2.target_eid=?
Nov 11, 2011 3:18:37 PM org.slf4j.impl.JCLLoggerAdapter debug
FINE: getMaxPreferenceSQL: SELECT MAX(score) FROM recommender_preference_staging
Nov 11, 2011 3:18:37 PM org.slf4j.impl.JCLLoggerAdapter debug
FINE: getMinPreferenceSQL: SELECT MIN(score) FROM recommender_preference_staging
Nov 11, 2011 3:18:37 PM org.slf4j.impl.JCLLoggerAdapter debug
FINE: Retrieving number of users in model
Nov 11, 2011 3:18:37 PM org.slf4j.impl.JCLLoggerAdapter debug
FINE: Executing SQL query: SELECT COUNT(DISTINCT source_eid) FROM recommender_preference_staging
Nov 11, 2011 3:18:37 PM org.slf4j.impl.JCLLoggerAdapter debug
FINE: Retrieving number of items in model
Nov 11, 2011 3:18:37 PM org.slf4j.impl.JCLLoggerAdapter debug
FINE: Executing SQL query: SELECT COUNT(DISTINCT target_eid) FROM recommender_preference_staging
Nov 11, 2011 3:18:37 PM org.drupal.project.recommender.RunRecommender$AlgorithmImpl initDataModel
INFO: Switching to MEMORY mode. Load all data from database into memory first.
Nov 11, 2011 3:18:37 PM org.slf4j.impl.JCLLoggerAdapter info
INFO: Loading new JDBC delegate data...
Nov 11, 2011 3:18:37 PM org.slf4j.impl.JCLLoggerAdapter debug
FINE: Exporting all data
Nov 11, 2011 3:18:37 PM org.slf4j.impl.JCLLoggerAdapter debug
FINE: Executing SQL query: SELECT DISTINCT source_eid, target_eid, score FROM recommender_preference_staging ORDER BY source_eid, target_eid
Nov 11, 2011 3:18:37 PM org.slf4j.impl.JCLLoggerAdapter info
INFO: Processed 2 users
Nov 11, 2011 3:18:37 PM org.slf4j.impl.JCLLoggerAdapter info
INFO: New data loaded.
Nov 11, 2011 3:18:37 PM org.drupal.project.recommender.RunRecommender$AlgorithmImpl run
INFO: Using similarity class: org.apache.mahout.cf.taste.impl.similarity.PearsonCorrelationSimilarity
Nov 11, 2011 3:18:37 PM org.drupal.project.recommender.RunRecommender$AlgorithmImpl run
INFO: Using recommender class: org.apache.mahout.cf.taste.impl.recommender.GenericItemBasedRecommender
Nov 11, 2011 3:18:37 PM org.drupal.project.recommender.RunRecommender$AlgorithmImpl run
INFO: Computing and saving similarity data.
Nov 11, 2011 3:18:37 PM org.drupal.project.async_command.DrupalConnection d
FINE: SELECT max(updated) FROM recommender_similarity
Nov 11, 2011 3:18:37 PM org.drupal.project.async_command.GenericDrupalApp handleException
SEVERE: System error or programming bug.
java.lang.NullPointerException
	at org.drupal.project.recommender.RunRecommender$AlgorithmImpl.genericComputeSave(RunRecommender.java:458)
	at org.drupal.project.recommender.RunRecommender$AlgorithmImpl.computeSaveSimilarity(RunRecommender.java:528)
	at org.drupal.project.recommender.RunRecommender$AlgorithmImpl.run(RunRecommender.java:554)
	at org.drupal.project.recommender.RunRecommender.run(RunRecommender.java:278)
	at org.drupal.project.async_command.GenericDrupalApp.runSerial(GenericDrupalApp.java:245)
	at org.drupal.project.async_command.GenericDrupalApp.run(GenericDrupalApp.java:179)
	at org.drupal.project.async_command.CommandLineLauncher.handleExecutables(CommandLineLauncher.java:103)
	at org.drupal.project.async_command.CommandLineLauncher.launch(CommandLineLauncher.java:64)
	at org.drupal.project.recommender.RecommenderApp.main(RecommenderApp.java:26)
Nov 11, 2011 3:18:37 PM org.drupal.project.async_command.GenericDrupalApp runSerial
INFO: Command finished running with status: INTR
Nov 11, 2011 3:18:37 PM org.drupal.project.async_command.DrupalConnection update
FINEST: SQL UPDATE: UPDATE {async_command} SET output=?, id1=?, id2=?, number1=?, number2=?, number3=?, number4=?, string1=?, string2=?, status=?, control=?, message=?, weight=?, start=?, end=?, checkpoint=?, progress=? WHERE id=?
Nov 11, 2011 3:18:37 PM org.drupal.project.async_command.DrupalConnection d
FINE: UPDATE async_command SET output=?, id1=?, id2=?, number1=?, number2=?, number3=?, number4=?, string1=?, string2=?, status=?, control=?, message=?, weight=?, start=?, end=?, checkpoint=?, progress=? WHERE id=?
Nov 11, 2011 3:18:37 PM org.drupal.project.async_command.GenericDrupalApp run
INFO: Shutdown parallel executor.
Nov 11, 2011 3:18:37 PM org.drupal.project.async_command.GenericDrupalApp run
INFO: Running the DrupalApp is accomplished.
Nov 11, 2011 3:18:37 PM org.drupal.project.async_command.CommandLineLauncher launch
INFO: Mission accomplished.
danithaca’s picture

danithaca commented
Version: 7.x-4.0-alpha3 » 7.x-4.0-alpha4
Status: Active » Fixed

thanks for the report. confirmed as bug, and fixed in 7.x-4.0-alpha4.

Status: Fixed » Closed (fixed)

Automatically closed -- issue fixed for 2 weeks with no activity.