Problems with usageStats. Metrics not updated. v2-4-6, files not moved

retostauffer · August 9, 2015, 8:17am

Dear community.

I am struggling since a few hours with the usageStats. I installed ojs 2-4-6 from scratch. What we are doing special: we are currently migrating an old journal from an arbitrary system used for 15 years. I could figure out most things - all the inserts are good. However, I can’t figure out how the metrics really work. I read tons of forum entries but still in troubles.

What I am already considering:

base_url in config.inc.php is correct, fits the entries in the usage (base_url: http://jstatsoft.uibk.ac.at, usageLog example (for a file in this case): http://jstatsoft.uibk.ac.at/index.php/jss/article/download/v064i02/v64i02.pdf`
usageStats/usageEventLogs and usageStats/stage have rwx permissions
cronjob (cd /var/www/html && php tools/runScheduledTasks.php plugins/generic/usageStats/scheduledTasks.xml) is running.

My current problems
OJS (v 2.4.6) seems to create proper log-entries in the usageEventLogs directory for (i) volume views, (ii) issue vuews, and (iii) file downloads. However, only the issue views seems to be updated in the metrics table.

We are using the custom names (pub-id::publisher-id/original_file_name) for file downloads/galleys. Might this be a problem for the Stats/Metrics plugin?
Why are issue views logged, but the rest not?
We migrated an old journal from a complete arbitrary software manually (with full submission path) into OJS: maybe I’ve forgotten to set a specific flag in a database table which tells OJS that this specific file should be tracked?

Furthermore …

the cronjob works if and only if I move the files manually from usageEventLogs to stage. Seems that the script dont want to move the files. As I am always testing on a live version my log-files are never older than 1 day. Are they moved lagged based on the modification date or something?

Thanks in advance!
I was spending a lot of time to fix it, but could not find it. More or less reverse-engineered the whole database relations to be able to migrate into OJS as I expected it :).

Thank you very much!
Reto

beghelli · August 18, 2015, 11:28pm

Hi @retostauffer,

For automatic staging the log files, use scheduledTasksAutoStage.xml file.

If you are using the Acron plugin, there is no need to configure a cron job.

Make sure permissions are ok for all folders under usageStats.

And the last one, for now, can you send me some processing log files (not the stats log files, the stats processing log ones) that can be found in your files_dir folder, under scheduledTaskLogs? Please, send the most recent ones, they should start with Usagestatisticsfileloadertask, ending with the date.

Regards,
Bruno

retostauffer · September 10, 2015, 9:48am

Hy Bruno,

thank you very much for your help and sorry for my late response. Directory permissions double checked, they should all be correct (owned by the apache user, rwx permissions granted).

Good to know that a cron-job is not necessary, however, at the moment I am running a cron-job as well but nothing happens with the usageStats files (scheduledTasksAutoStage.xml tested).

The scheduler seems to run as it should without processing any files. scheduledTaskLogs contains a bunch of log files (also current files, seems to work). All log files just contain three lines. An example shown below, latest file:

http://jstatsoft.uibk.ac.at
[2015-09-10 09:35:21] [Notice] Task process started.
[2015-09-10 09:35:21] [Notice] Task process stopped.

So no files processed, even if there are usage_event files in the usageEventLogs directory:

.
./stage
./archive
./archive/usage_events_20150809.log
./reject
./processing
./usageEventLogs
./usageEventLogs/usage_events_20150811.log
./usageEventLogs/usage_events_20150812.log
...... 
./usageEventLogs/usage_events_20150910.log

The one file in the archive was processed when I was testing a few weeks ago before I wrote my forum question. At that time I was able to run it once manually - but no idea how or why . As the php script tools/runScheduledTasks.php does not produce any output it is hard for me to track the problem. Maybe you do have another hint?

Thank you very much for your help!

All best,
Reto

beghelli · September 10, 2015, 12:50pm

@retostauffer,

Depending on your server configuration, the apache user might not be the one running PHP. An easy way to know for sure which user is running PHP is to create a simple PHP script executing whoami command and access it using your browser.

Also, the PHP tool runScheduledTasks will run under the user that’s calling it. And it is almost certain that’s not the apache one right? So again, the process will not be able to move the files.

Try checking those things and tell me later the result.

Cheers,
Bruno

retostauffer · September 10, 2015, 1:11pm

Hy Bruno

Thanks for the tip, but the apache user is the one which handles the webserver requests (also checked php whoami - it’s the apache user). The usageEventLogs and written by apache as well, the permissions are given to the apache, and therefore this should not be the problem.

-rw-r--r--. 1 apache apache   642 Sep 10 14:22 usage_events_20150910.log

Permissions granted. But the eventStats seem not to be moved. As I remember they should be moved into the stage directory and then be archived in the archive dir. Just to check myself: copy one file manually with the correct user - no permission probs.

> whoami
apache
> cp usageEventLogs/usage_events_20150910.log stage/
> ls -l stage/
-rw-r--r--. 1 apache apache 642 Sep 10 15:07 usage_events_20150910.log

Do you maybe know where in the php code this should be done? Maybe I have to dive into these classes and see what happens when runScheduledTasks.php is called.

Thanks for your support,
Reto

beghelli · September 10, 2015, 1:32pm

@retostauffer,

Try testing with a file that’s not your current day one. If you move the current day file, the system will have no file to log the stats and will create another one. Then you will have two files for the same day, and the system will not be able to merge them.

With that said, can you check your PHP error log for any error related to this?

Thanks,
Bruno

ctgraham · September 10, 2015, 2:23pm

@retostauffer, to walk through this in the code, see:

github.com

pkp/ojs/blob/ojs-stable-2_4_6/plugins/generic/usageStats/UsageStatsLoader.inc.php#L106


	/**
	 * @see FileLoader::getName()
	 */
	function getName() {
		return __('plugins.generic.usageStats.usageStatsLoaderName');
	}

	/**
	 * @see FileLoader::executeActions()
	 */
	function executeActions() {
		$plugin =& $this->_plugin;
		if (!$plugin->getEnabled()) {
			$this->addExecutionLogEntry(__('plugins.generic.usageStats.pluginDisabled'), SCHEDULED_TASK_MESSAGE_TYPE_WARNING);
			return true;
		}
		// It's possible that the processing directory has files that
		// were being processed but the php process was stopped before
		// finishing the processing, or there may be a concurrent process running.
		// Warn the user if this is the case.
		$processingDirFiles = glob($this->getProcessingPath() . DIRECTORY_SEPARATOR . '*');

Particularly as it calls:

github.com

pkp/ojs/blob/ojs-stable-2_4_6/plugins/generic/usageStats/UsageStatsLoader.inc.php#L243


		}
	}

	//
	// Protected methods.
	//
	/**
	 * Auto stage usage stats log files, also moving files that
	 * might be in processing folder to stage folder.
	 */ 
	function autoStage() {
		$plugin = $this->_plugin;

		// Copy all log files to stage directory, except the current day one.
		$fileMgr = new FileManager();
		$logFiles = array();
		$logsDirFiles =  glob($plugin->getUsageEventLogsPath() . DIRECTORY_SEPARATOR . '*');

		// It's possible that the processing directory has files that
		// were being processed but the php process was stopped before
		// finishing the processing. Just copy them to the stage directory too.

retostauffer · September 21, 2015, 7:57am

Thank you very much guys!

… maybe just “my fault”, but I tried to find the source of the error (see below). Was doing some reverse-engineering on the task scheduler. The description in lib/pkp/dtd/scheduledTasks.dtd gave me the hint I needed.

By default, plugins/generic/usageStats/scheduledTasksAutoStage.xml is set to be executed every 24 hours (hour=“24”). However, seems that my system has had a problem with it - maybe because there is no hour 24? For testing, I just set the frequency to and all worked as expected. I’ve now set the frequency to (if I understood it correctly, the tool should now be executed once an hour at around minute 0, if we have visitors).

[2015-09-21 07:39:38] [Notice] Task process started.
[2015-09-21 07:39:39] [Notice] File [...]/ojs/usageStats/processing/usage_events_20150917.log was processed and archived.
...
[2015-09-21 07:39:39] [Notice] Task process stopped.

Why didn’t it work before?

I tired to find out where the problem came from. Two ideas:

Idea number 1:
As we are in the development mode (and just some test-visitors) I never got a visitor at the specified time and the task was therefore never triggered.

Idea number 2:
There is a problem (on our system) with the specification of hour=“24”. What I found in OJS (but nowhere on the system as an error log: maybe a problem with my php.ini error logging level): ScheduledTaskTool.inc.php::parseTask() returned the following error on the $task variable:

ojs2 has produced an error
  Message: CAUGHT EXCEPTION: Object of class XMLNode could not be converted to string
  In file: /mnt/data/www-devel/html/lib/pkp/classes/cliTool/ScheduledTaskTool.inc.php
  At line: 89
  Stacktrace: 
  Server info:
   OS: Linux
   PHP Version: 5.4.16
   Apache Version: N/A
   DB Driver: mysql
   DB server version: 5.5.37-MariaDB-wsrep<br/>
ojs2 has produced an error
  Message: CAUGHT EXCEPTION: Object of class XMLNode could not be converted to string
  In file: /mnt/data/www-devel/html/lib/pkp/classes/cliTool/ScheduledTaskTool.inc.php
  At line: 89
  Stacktrace: 
  Server info:
   OS: Linux
   PHP Version: 5.4.16
   Apache Version: N/A
   DB Driver: mysql
   DB server version: 5.5.37-MariaDB-wsrep

Why an error and not a message like “sorry, wrong time to do the task?”. I did not dig deeper in all the pkplib classes, but is it possible that the specification hour=24 is not a good default option (OJS 2.4.6)?

However, seems that the AutoStage is now running, just have to check if the download counter will work, as we made some major modifications on the file names :).

Again, thank you very much for the tips and hints, and sorry for the long post.

All best,
Reto

beghelli · September 21, 2015, 4:42pm

Hi @retostauffer,

You’re right, the 24 value doesn’t make sense. But the strange thing is that your task should be running even with that value, since the code has a cut off that will be used to run the task if the last run is older than a day (in the case of the hour setting).

I’ve created an issue to solve the scheduled tasks files problem: Plugins scheduled tasks files hour setting are using a non existing hour · Issue #760 · pkp/pkp-lib · GitHub

Thanks for debugging it.

Cheers,
Bruno

retostauffer · September 28, 2015, 8:56am

Dear OJS team

Still struggling with the UsageStats and did some more re-engineering. As soon as the files are landing in my stage folder everything looks fine. However, autoStage does not work. What I found out today:

In “plugins/generic/usageStats/UsageStatsLoader.inc.php” there is the swtich/case statement:

  $arg = current($args);

  switch ($arg) {
     case 'autoStage':
        if ($plugin->getSetting(0, 'createLogFiles')) {
           $this->_autoStage = true;
        }
        break;
     case 'externalLogFiles':
        $this->_externalLogFiles = true;
        break;
  }

… however, $this->autoStage is empty as the array $args is completely empty. Based on this the method $this->autoStage(); will never be called. Manipulated the $args array ($args = array(“autoStage”);_) and all worked fine. Seems that this property is not set properly in my installation. Trying to isolate the problem lead me to the file lib/pkp/classes/cliTool/ScheduledTaskTool.inc.php (called by tools/runScheduledTasks.php and its xml file).
At the end it is executing the required tool by calling the method executeTask where $args are an input argument. However, $args is already empty.

Have I forgotten to set some Option somewhere calling the system that autoStage should be used?

All best and thank you for any advice in advance,
Reto

beghelli · September 28, 2015, 1:54pm

@retostauffer,

Are you using the acron plugin or manually starting your processing task?

If you’re manually starting it, you should use this command line:

php tools/runScheduledTasks.php plugins/generic/usageStats/scheduledTasksAutoStage.xml

Let me know if that works.

Cheers,
Bruno

retostauffer · October 9, 2015, 8:28am

@beghelli,

Ok, had time to check this stuff again. Since yesterday the Acron plugin is disabled anyways (see: OJS page stalls - awesome delays ). Neither

php tools/runScheduledTasks.php plugins/generic/usageStats/scheduledTasksAutoStage.xml

nor

php tools/runScheduledTasks.php plugins/generic/usageStats/scheduledTasks.xml

were doing what should be done. However, I now enabled my fix again adding the line

$args = array("autoStage");

In plugins/generic/usageStats/UsageStatsLoader.inc.php and enabled my system-cronjob again. Now calling /scheduledTasks.xml is auto-staging and doing all the metrics as expected.

I’m very sorry not to find the “major” purpose for this issue, however, I hope that - for my application - this fix solved the problems.

All best,
Reto