Add logging to ArchivePurger service, task + Scheduler class & modify CronArchive so scheduled Task logs are displayed. #7602

diosmosis · 2015-04-01T01:48:53Z

This pull request modifies CronArchive so scheduled task logging output displays in core:archive output, and adds logging to ArchivePurger + other classes.

We display scheduled task output in the core:archive process by going through the Request class instead of climulti:request.

Example scheduled task output:

INFO CoreConsole[2015-04-01 01:33:19] ---------------------------
INFO CoreConsole[2015-04-01 01:33:19] SCHEDULED TASKS
INFO CoreConsole[2015-04-01 01:33:19] Starting Scheduled tasks... 
INFO CoreAdminHome[2015-04-01 01:33:19] Scheduler: executing task Piwik\Plugins\CoreAdminHome\Tasks.purgeOutdatedArchives...
INFO CoreAdminHome[2015-04-01 01:33:19] Purging archives in 96 archive tables.
INFO CoreAdminHome[2015-04-01 01:33:19] No outdated archives found in archive numeric table for 2005-01-15.
INFO CoreAdminHome[2015-04-01 01:33:19] Purged 0 range archive rows from archive_numeric_2005_01 & archive_blob_2005_01.
INFO CoreAdminHome[2015-04-01 01:33:19] No outdated archives found in archive numeric table for 2006-01-15.
INFO CoreAdminHome[2015-04-01 01:33:19] Purged 0 range archive rows from archive_numeric_2006_01 & archive_blob_2006_01.
INFO CoreAdminHome[2015-04-01 01:33:19] No outdated archives found in archive numeric table for 2007-01-15.
INFO CoreAdminHome[2015-04-01 01:33:19] Scheduler: finished executing task Piwik\Plugins\CoreAdminHome\Tasks.purgeOutdatedArchives. Time elapsed: 0.114s
INFO CoreConsole[2015-04-01 01:33:19] done
INFO CoreConsole[2015-04-01 01:33:19] ---------------------------

Refs #7181

…heduled tasks + Scheduler, modify CronArchive to run scheduled tasks within same process as core:archive so logs are visible in core:archive output.

… in comment header].

diosmosis · 2015-04-01T20:19:42Z

Remembered the CronArchive method is used within tracker, need to revise how tracker runs scheduled tasks.

mattab · 2015-04-01T21:56:12Z

the CronArchive method is used within tracker

I'm wondering, do we have a test case for this? if not, it would be useful to add one 👍

tsteur · 2015-04-07T04:43:20Z

core/Archive/ArchivePurger.php

        }
+        return $deletedCount;


Do you mind adding an integration test for this? Would be nice to have a test for this. Not only for the return value but also whether it actually deletes the archives.

Modified the existing ArchivePurgerTest to test for deleted row counts.

tsteur · 2015-04-07T04:49:56Z

Nice! Do those kinda changes affect performance in any way?

…cheduled tasks through tracker including test that ensures tracker won't fail if scheduled tasks fail, allow tests to override container config by setting a property in the testing environment file, and properly use TestingEnvironment in RequestCommand.

… logic in ArchivePurger.

… logs at INFO level.

…rger doesn't log anything unless verbose output is requested.

diosmosis · 2015-04-08T23:39:45Z

@tsteur Re: performance, I tested using a dump of demo2's DB (which admittedly wouldn't have too much to purge) and there was no discernible difference w/ logging added.

…getting superuser token auth.

…ommand for tests.

diosmosis · 2015-04-09T04:49:18Z

Ready for another review, and then possibly merge. Now includes system test to ensure scheduled tasks are run via tracker correctly and w/o failing the tracker.

Conflicts: core/CronArchive.php

Conflicts: tests/UI/expected-ui-screenshots

mnapoli · 2015-04-16T04:01:11Z

I have checked out the branch and given it a try, the amount of output when running the scheduled tasks is quite high. For example:

INFO CoreAdminHome[2015-04-16 03:56:52] Scheduler: finished executing task Piwik\Plugins\CoreAdminHome\Tasks.purgeOutdatedArchives. Time elapsed: 0.219s
INFO CoreAdminHome[2015-04-16 03:56:52] Scheduler: executing task Piwik\Plugins\ExamplePlugin\Tasks.myTaskWithParam_anystring...
INFO CoreAdminHome[2015-04-16 03:56:52] Scheduler: finished executing task Piwik\Plugins\ExamplePlugin\Tasks.myTaskWithParam_anystring. Time elapsed: 0.000s
INFO CoreAdminHome[2015-04-16 03:56:52] Scheduler: executing task Piwik\Plugins\ExamplePlugin\Tasks.myTask...
INFO CoreAdminHome[2015-04-16 03:56:52] Scheduler: finished executing task Piwik\Plugins\ExamplePlugin\Tasks.myTask. Time elapsed: 0.000s
INFO CoreAdminHome[2015-04-16 03:56:52] Scheduler: executing task Piwik\Plugins\ExamplePlugin\Tasks.myTask...
INFO CoreAdminHome[2015-04-16 03:56:52] Scheduler: finished executing task Piwik\Plugins\ExamplePlugin\Tasks.myTask. Time elapsed: 0.000s
INFO CoreAdminHome[2015-04-16 03:56:52] Scheduler: executing task Piwik\Plugins\ExamplePlugin\Tasks.myTask...
INFO CoreAdminHome[2015-04-16 03:56:52] Scheduler: finished executing task Piwik\Plugins\ExamplePlugin\Tasks.myTask. Time elapsed: 0.000s
INFO CoreAdminHome[2015-04-16 03:56:52] Scheduler: executing task Piwik\Plugins\ExamplePlugin\Tasks.myTask...
INFO CoreAdminHome[2015-04-16 03:56:52] Scheduler: finished executing task Piwik\Plugins\ExamplePlugin\Tasks.myTask. Time elapsed: 0.000s
INFO CoreAdminHome[2015-04-16 03:56:52] Scheduler: executing task Piwik\Plugins\ExamplePlugin\Tasks.myTaskWithParam_anystring...
INFO CoreAdminHome[2015-04-16 03:56:52] Scheduler: finished executing task Piwik\Plugins\ExamplePlugin\Tasks.myTaskWithParam_anystring. Time elapsed: 0.000s
[...]
INFO CoreAdminHome[2015-04-16 03:58:37] done
Piwik\Plugins\CoreAdminHome\Tasks.purgeOutdatedArchives - Time elapsed: 0.219s
Piwik\Plugins\ExamplePlugin\Tasks.myTaskWithParam_anystring - Time elapsed: 0.000s
Piwik\Plugins\ExamplePlugin\Tasks.myTask - Time elapsed: 0.000s
Piwik\Plugins\ExamplePlugin\Tasks.myTask - Time elapsed: 0.000s
Piwik\Plugins\ExamplePlugin\Tasks.myTask - Time elapsed: 0.000s
Piwik\Plugins\ExamplePlugin\Tasks.myTask - Time elapsed: 0.000s
Piwik\Plugins\ExamplePlugin\Tasks.myTaskWithParam_anystring - Time elapsed: 0.000s
Piwik\Plugins\ScheduledReports\API.sendReport_1 - Time elapsed: 103.436s
Piwik\Plugins\CustomAlerts\Tasks.runAlertsDaily_16 - Time elapsed: 0.119s
Piwik\Plugins\CustomAlerts\Tasks.runAlertsWeekly_16 - Time elapsed: 0.002s
Piwik\Plugins\CustomAlerts\Tasks.runAlertsMonthly_16 - Time elapsed: 0.003s
Piwik\Plugins\TrafficMonitor\Tasks.doCacheTotalActionsNbFromRawData - Time elapsed: 0.962s
Piwik\Plugins\CoreAdminHome\Tasks.purgeInvalidatedArchives - Time elapsed: 0.002s
Piwik\Plugins\PrivacyManager\Tasks.deleteReportData - Time elapsed: 0.004s
Piwik\Plugins\PrivacyManager\Tasks.deleteLogData - Time elapsed: 0.001s
Piwik\Plugins\CorePluginsAdmin\Tasks.clearAllCacheEntries - Time elapsed: 0.001s
Piwik\Plugins\CorePluginsAdmin\Tasks.sendNotificationIfUpdatesAvailable - Time elapsed: 0.001s
Piwik\Plugins\CoreAdminHome\Tasks.optimizeArchiveTable - Time elapsed: 0.028s
Piwik\Plugins\ExamplePlugin\Tasks.myTask - Time elapsed: 0.000s
Piwik\Plugins\UserCountry\GeoIPAutoUpdater.update - Time elapsed: 0.011s
Piwik\Plugins\CoreUpdater\Tasks.sendNotificationIfUpdateAvailable - Time elapsed: 0.001s

Would it be better to remove the finished executing ... kind of messages? E.g. only say executing task … and not say when it's finished (because it will be obvious from the output).

Or else get rid of the summary at the end (which only displays the time elapsed) and show the time elapsed when printing finished executing task ...?

Except that 👍 for merge.

mnapoli · 2015-04-16T04:02:32Z

plugins/CoreAdminHome/Commands/PurgeOldArchiveData.php

+        $logger = null;
+        if ($output->getVerbosity() <= OutputInterface::VERBOSITY_NORMAL) {
+            $logger = new NullLogger();
+        }


Why this? The -q flag should automatically set the error level at "error".

During normal output (in addition to when -q is used), we don't want the ArchivePurger logs to output in this command, but we want it to appear in scheduled task output.

Ah yes I think we discussed that in slack! Could you maybe add a comment to explain it?

Added a comment.

diosmosis · 2015-04-16T04:06:29Z

Or else get rid of the summary at the end (which only displays the time elapsed) and show the time elapsed when printing finished executing task ...?

You're right, don't need the summary anymore, will remove it.

…ed or rows deleted. For debugging, users can append -v to core:archive and email it to us.

Add logging to ArchivePurger service, task + Scheduler class & modify CronArchive so scheduled Task logs are displayed.

…ullLogger.

mattab · 2015-04-19T23:50:20Z

only say executing task … and not say when it's finished (because it will be obvious from the output).

it looks like the output was not simplfied as much as possible so created follow up issue #7705

diosmosis added 2 commits March 31, 2015 18:37

Refs #7181, add logging to ArchivePurger service + archive purging sc…

b70727f

…heduled tasks + Scheduler, modify CronArchive to run scheduled tasks within same process as core:archive so logs are visible in core:archive output.

Merge branch 'master' into archive_purger_logs

bed3509

diosmosis added the Enhancement For new feature suggestions that enhance Matomo's capabilities or add a new report, new API etc. label Apr 1, 2015

diosmosis added this to the Piwik 2.13.0 milestone Apr 1, 2015

diosmosis added 3 commits April 1, 2015 12:36

Update log importer submodule [for better W3C log whitespace handling…

b2b4f35

… in comment header].

Merge branch 'master' into archive_purger_logs

a30632f

Fixing build.

e18f570

diosmosis added the Pull Request WIP Indicates the current pull request is still work in progress and not ready yet for a review. label Apr 1, 2015

tsteur reviewed Apr 7, 2015
View reviewed changes

diosmosis added 5 commits April 7, 2015 14:17

Merge branch 'master' into archive_purger_logs

5b82ed2

Rename PurgerTest to ArchivePurgerTest and add tests for row counting…

3ffd6f8

… logic in ArchivePurger.

Clean up purge-old-archive-data command output now that ArchivePurger…

875414c

… logs at INFO level.

Use NullLogger in core:purge-old-archive-data by default so ArchivePu…

9e529ae

…rger doesn't log anything unless verbose output is requested.

diosmosis added 3 commits April 8, 2015 16:42

Merge branch 'master' into archive_purger_logs

f71c869

Don't execute CronArchive constructor just to execute it's logic for …

debaf15

…getting superuser token auth.

Allow ArchivePurger to be set in constructor of PurgeOldArchiveData c…

009b41a

…ommand for tests.

diosmosis added Needs Review PRs that need a code review and removed Pull Request WIP Indicates the current pull request is still work in progress and not ready yet for a review. labels Apr 9, 2015

diosmosis added 2 commits April 15, 2015 19:26

Merge branch 'master' into archive_purger_logs

a265627

Conflicts: core/CronArchive.php

Merge branch 'master' into archive_purger_logs

444ce0e

Conflicts: tests/UI/expected-ui-screenshots

mnapoli reviewed Apr 16, 2015
View reviewed changes

diosmosis added 3 commits April 15, 2015 21:46

Merge branch 'master' into archive_purger_logs

f0fabe5

Only log in INFO level in ArchivePurger service if archives were purg…

1af927d

…ed or rows deleted. For debugging, users can append -v to core:archive and email it to us.

Tweak output of task finished log in Scheduler.

8ad51e4

mnapoli added a commit that referenced this pull request Apr 17, 2015

Merge pull request #7602 from piwik/archive_purger_logs

b4ac2e8

Add logging to ArchivePurger service, task + Scheduler class & modify CronArchive so scheduled Task logs are displayed.

mnapoli merged commit b4ac2e8 into master Apr 17, 2015

mnapoli deleted the archive_purger_logs branch April 17, 2015 00:48

diosmosis removed the Needs Review PRs that need a code review label Apr 17, 2015

diosmosis pushed a commit that referenced this pull request Apr 17, 2015

Refs #7602, add comment in PurgeOldArchiveData.php regarding use of N…

3899b9a

…ullLogger.

mattab mentioned this pull request Apr 19, 2015

Simplify scheduled task output in console command #7705

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Add logging to ArchivePurger service, task + Scheduler class & modify CronArchive so scheduled Task logs are displayed. #7602

Add logging to ArchivePurger service, task + Scheduler class & modify CronArchive so scheduled Task logs are displayed. #7602

diosmosis commented Apr 1, 2015

diosmosis commented Apr 1, 2015

mattab commented Apr 1, 2015

tsteur Apr 7, 2015

diosmosis Apr 8, 2015

tsteur commented Apr 7, 2015

diosmosis commented Apr 8, 2015

diosmosis commented Apr 9, 2015

mnapoli commented Apr 16, 2015

mnapoli Apr 16, 2015

diosmosis Apr 16, 2015

mnapoli Apr 16, 2015

diosmosis Apr 17, 2015

diosmosis commented Apr 16, 2015

mattab commented Apr 19, 2015

Add logging to ArchivePurger service, task + Scheduler class & modify CronArchive so scheduled Task logs are displayed. #7602

Add logging to ArchivePurger service, task + Scheduler class & modify CronArchive so scheduled Task logs are displayed. #7602

Conversation

diosmosis commented Apr 1, 2015

diosmosis commented Apr 1, 2015

mattab commented Apr 1, 2015

tsteur Apr 7, 2015

Choose a reason for hiding this comment

diosmosis Apr 8, 2015

Choose a reason for hiding this comment

tsteur commented Apr 7, 2015

diosmosis commented Apr 8, 2015

diosmosis commented Apr 9, 2015

mnapoli commented Apr 16, 2015

mnapoli Apr 16, 2015

Choose a reason for hiding this comment

diosmosis Apr 16, 2015

Choose a reason for hiding this comment

mnapoli Apr 16, 2015

Choose a reason for hiding this comment

diosmosis Apr 17, 2015

Choose a reason for hiding this comment

diosmosis commented Apr 16, 2015

mattab commented Apr 19, 2015