runScheduledTasks.php fails in OJS 3.0.1 (Call to undefined method ScheduledTaskTool::ScheduledTaskTool())

Greetings @bozana,

I have performed clean upgrade. All files except configuration file, file store folder and public folder were removed and than OJS 3.0.1 installed. I will copy .dat file in plugins/generic/usageStats and the results. Thanks.

As for stats data, they all are stored in usageEvent logs. They are processed by command, noted in Ubuntu cron, every 2 hours. Some of logs are then moved to /reject directory and others in the archive/ but all data are recorded in the database. I will check database once more and share with several lines.

If there is a need you can check link for the article, where stats data are not displayed. In articles, published before the upgrade, all is ok. The psychological distress and psychic phenomena in cancer patients during palliative care | Psychosomatic Medicine and General Practice

Hi @bozana,

I have found rows from metrics table that are associated with this new article. submission id of the article is 13, its corresponds, for example, for this 2 rows:

# load_id, context_id, pkp_section_id, assoc_object_type, assoc_object_id, submission_id, representation_id, assoc_type, assoc_id, day, month, file_type, country_id, region, city, metric_type, metric
'usage_events_20161203.log', '1', NULL, NULL, NULL, '13', NULL, '256', '1', '20161203', '201612', NULL, NULL, NULL, NULL, 'ojs::counter', '119'
'usage_events_20161203.log', '1', NULL, NULL, NULL, '13', NULL, '259', '1', '20161203', '201612', NULL, NULL, NULL, NULL, 'ojs::counter', '24'

For comparing here are 2 other rows from old articles, which data are normally displayed after upgrade:

# load_id, context_id, pkp_section_id, assoc_object_type, assoc_object_id, submission_id, representation_id, assoc_type, assoc_id, day, month, file_type, country_id, region, city, metric_type, metric
'usage_events_20161202.log', '1', '5', '259', '1', '8', '6', '515', '27', '20161202', '201612', '2', NULL, NULL, NULL, 'ojs::counter', '1'
'usage_events_20161202.log', '1', '5', '259', '1', '8', '7', '515', '28', '20161202', '201612', '2', NULL, NULL, NULL, 'ojs::counter', '2'

After quick look can be seen some difference, for example in new article there aren`t any data in columns:
pkp_section_id, assoc_object_type, and many others. Furthermore I see only 2 rows associated with this submission id, but them must to be much more. So I think the problem is in absent of counting views for that specific article. Maybe this plugin requires deactivation/activation after update for “seeing” new content?

Hi @Vitaliy

Hmmm
 Those entries with submission_id = 13 are a little bit strange: they have assoc_type = 259 and assoc_type = 256 which means that those are actually entries for issue (259) with assoc_id = 1 and journal (256) with assoc_id = 1 i.e. those are access counts on the issue 1 and journal 1 page. But in that case they should have submission_id = NULL. And it is all right that section_id and other columns are NULL.
For that submission 13 there should be an entry with assoc_type = 1048585 and assoc_id = 13 in the metrics table.

Hmmm
 Yes, it seems that the data in not in the database. Eventually the log files are not processed correctly, at least not for that submission. Maybe first to check if the access to that article is logged correctly i.e. do you see the article URL https://e-medjournal.com/index.php/psp/article/view/13 in your recent statistics log files, that are processed i.e. either in archive/ or reject/ folder? Maybe they are in reject/ folder (which would probably mean that they are not processed successfully and thus data not inserted into the table metrics)?

I accessed the article today, so the log file usage_events_20161208.log should be processed tomorrow and if everything goes well, it will be moved to archive/ and data inserted into the metrics table. – The log files are processed and rotated daily. It could however end in the reject/ folder – then we should analyze why i.e. what went wrong


Best,
Bozana

Hi @bozana,

I haven`t seen any new records in metrics table for “problematic” article. Checked plugin logs, here several from localhost:

127.0.0.1 administrative 1 "2016-12-08 00:27:05" http://e-medjournal.com/index.php/psp/article/view/1 200 "Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:50.0) Gecko/20100101 Firefox/50.0"

127.0.0.1 - - "2016-12-08 20:04:37" http://e-medjournal.com/index.php/psp/article/download/11/10/54 200 "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/55.0.2883.75 Safari/537.36"

Here line, that is associated with new article (without ip for privacy reasons):

xxxxxxxxxx - - "2016-12-04 22:01:51" http://e-medjournal.com/index.php/psp/article/download/13/14/53 200 "Mozilla/5.0 (Windows NT 10.0; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/54.0.2840.99 Safari/537.36"

and another one from other page:

xxxxxxxxx - - "2016-12-04 23:10:10" http://e-medjournal.com/index.php/psp/index 200 "Mozilla/5.0 (Windows NT 10.0; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/54.0.2840.99 Safari/537.36"

There is no logs that contain https://e-medjournal.com/index.php/psp/article/view/13 or every other number at the end, except 1. As it can be seen, it counts not exactly views but downloads of html or xml. There minimum 3 records in logs associated with downloads of xml or html of problematic article. As I can see they are not recorded in database.

From where those logs are come from? from apache logs? If yes, maybe there is a reason for looking in apache logs, associated with this article?

It should to be also noted that I use ubuntu cron for processing those logs. The command runs every 2 hours. https://pkp.sfu.ca/ojs/docs/userguide/2.3.3/systemAdministartionScheduledTasks.html. The reason why I use cron is that I had problems with acron plugin. You can see this info here: OJS3: issues with usage statistics plugin with php7.0 - #10 by Vitaliy. I had similar problems month ago geo ip plugin wasn`t working because of conflict with php-geoip module (I simply deleted it in that case and all started to work) and stats data wasn’t recording because of problems with acron plugin.

As for geo ip plugin - it started to work perfectly after copying dat file into plugin/generic/usageStats directory. I simply downloaded it in the wrong place after clean upgrade.

Hi @bozana,

Additionally checked apache logs. There are very big number of views, associated with new article. And they are normally recorded: “/index.php/psp/article/view/13/15”

Hi @Vitaliy

Hmmm
 strange. The usage statistics plugin is using its own log files (and not apache log files), if the option “Create log files” in the plugin settings is on – that probably is, because you see the log files. Thus we do not have to look into apache log files.
The plugin “Usage event” produces an event if an user access the article page, for example. This plugin is surely enabled in your installation? – otherwise there would be no other entries in the usage stats log files


Where, in which folder, did you find the log file that contains this entry:
xxxxxxxxxx - - "2016-12-04 22:01:51" http://e-medjournal.com/index.php/psp/article/download/13/14/53 200 "Mozilla/5.0 (Windows NT 10.0; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/54.0.2840.99 Safari/537.36" ?
Is there an entry in you DB table metrics with that load_Id (= the log file name)?

Do the log files contain any “https://” URL? Are there other “http://” URLs of that article in the log files, e.g. http://e-medjournal.com/index.php/psp/article/view/13?

Did you use “https://” earlier too?
What is your “base_url” in the config.inc.php? Is “force_ssl = On” in your config.inc.php?
Do you have any base_url[ entries in config.inc.php commented?

Strange, strange
 :-\

Thanks!
Bozana

Hi @bozana,

I see enrties like xxxxxxxxxx - - "2016-12-04 22:01:51" http://e-medjournal.com/index.php/psp/article/download/13/14/53 200 "Mozilla/5.0 (Windows NT 10.0; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/54.0.2840.99 Safari/537.36" in the /archive folder an in the /reject folder. For example, there is identical entry from 9 Dec. This log file is in a archive folder. So this entry is processed. In the metrics table there is entries with load_id from this day. But they are not associated with any submission_id, representation_id etc.

Thera are not any entries in log file started from https:// . I did not see https earlier too. force_ssl is on. Base_url starts with “http://
” - is it the cause of problems?

Hi @Vitaliy

No, I think it should be fine – if all URLs in the log files are “http://” and base_url also “http://” this should be fine


Would it be possible for you to watch in real time if there will be a new entry in your current log file when you go to that article? You can do this like this: go to the usageStats/usageEventLogs/ on your server and then use this command line on the current log file: “trail -f usage_events_20161211.log”. Then go to that article 13 and you should see if there is a new entry there.
You can also access the article and then immediately see in the log file if there is a new entry.

Maybe there are two problems here, for some reason :frowning: – one that the usage is not logged and the other that the log file is not correctly processed :stuck_out_tongue:

Thanks!
Bozana

@bozana,

Yep, log entries are created normally. After checking all my views were counted as http://e-medjournal.com/index.php/psp/article/download/13/14/53
or as https://
 if change base url accordingly.

OK, thanks, then something is wrong only with log file processing. And unfortunately I am not sure why, especially, why just for this article :open_mouth: I’ll take a look in the code once again, if I can figure out something

Do you also see an entry in the log file if you just access the abstract page The psychological distress and psychic phenomena in cancer patients during palliative care | Psychosomatic Medicine and General Practice?

No, there are not any entries for viewing abstract nor for this, nor other articles.

Hi @Vitaliy

Could you please change this line in your installation: https://github.com/pkp/ojs/blob/master/plugins/generic/usageEvent/UsageEventPlugin.inc.php#L62
and enter get_template_vars('article'); instead of get_template_vars('publishedArticle'); and then test the access on the article abstract page and see/check if there will be an entry in the current usage stats log file?

Thanks!
Bozana

Hi,
Will check this latter this week.

Greetings @bozana,
I have already watched for statistic plugin work for about 2 weeks.
Apart from changes you requisted I have changed code for parsing logs in the plugin menu.
And finally the counter started to work. Obviously plugin misses a huge amount of views. Actually there only 3 views but I definitly know that there must be much more. I even asked friends to test it.

@bozana,

I have double checked, for now in log files I see even abstract views. All information certainly is recorded there. But in the metrics table only some of the logs are recorded.

Upon processing logs there are huge number of this errors:

PHP Warning: preg_match(): Delimiter must not be alphanumeric or backslash in .../lib/pkp/classes/core/PKPString.inc.php on line 342

and after:

PHP Fatal error:  Uncaught Error: Using $this when not in object context in .../lib/pkp/classes/i18n/PKPLocale.inc.php:111
Stack trace:
#0 .../lib/pkp/classes/i18n/PKPLocale.inc.php(731): PKPLocale::translate('common.openJour...', Array, 'en_US')
#1 .../lib/pkp/classes/scheduledTask/ScheduledTaskHelper.inc.php(175): __('common.openJour...')
#2 .../lib/pkp/classes/scheduledTask/ScheduledTaskHelper.inc.php(142): ScheduledTaskHelper->getMessage('/home/doc/Docum...')
#3 .../lib/pkp/classes/scheduledTask/ScheduledTask.inc.php(153): ScheduledTaskHelper->notifyExecutionResult('585f963c671af', 'Usage statistic...', false, '/home/doc/Docum...')
#4 .../lib/pkp/classes/cliTool/ScheduledTaskTool.inc.php(113): ScheduledTask->execute()
#5 .../lib/pkp/classes/cliTool/ScheduledTaskTool.inc.php(95): ScheduledT in .../lib/pkp/classes/i18n/PKPLocale.inc.php on line 111

I’ll escalate the error “Using $this when not in object context” to a GitHub Issue. There is a programming problem there and I’m not confident of the fix.

On the other hand, this indicates that your usage event logs were processed into metrics (or the processing was attempted), and the system was trying to notify you of the results of that processing. This notification probably included error messages which will help identity the problem.

You can find these notifications in your files_dir, under “scheduledTaskLogs”. Look for “Usagestatisticsfileloadertask-585f963c671af-*.log”

The error “Using $this when not in object context” is fixed here: