Will invalidate archived reports for today in site ID = xxx - multiple times for the same site ID archive during cron job

Support & Bugs
1

Hello,

I have situation where one or two sites are being parsed multiple times during console archive cronjob. Take a look at log below. I had to kill archive job because of this. Does anyone have any idea how to solve it? Previously I had some issues with task being killed by memory usage and later by FastCGI settings on IIS server. I’ve switched to PHP 7.2 x64 (previously it was x86) raised memory limit levels and timeout values too.

I’m running Matomo 4.0.0 stable version. Thanks

INFO [2020-11-24 12:19:41] 38820 Start processing archives for site 118.
INFO [2020-11-24 12:19:43] 38820 Archived website id 118, period = day, date = 2020-11-24, segment = ‘’, 6 visits found. Time elapsed: 1.980s
INFO [2020-11-24 12:19:43] 38820 Archived website id 118, period = day, date = 2020-11-23, segment = ‘’, 168 visits found. Time elapsed: 1.985s
INFO [2020-11-24 12:19:45] 38820 Archived website id 118, period = week, date = 2020-11-23, segment = ‘’, 174 visits found. Time elapsed: 2.385s
INFO [2020-11-24 12:19:59] 38820 Archived website id 118, period = month, date = 2020-11-01, segment = ‘’, 3468 visits found. Time elapsed: 13.849s
INFO [2020-11-24 12:41:06] 38820 Archived website id 118, period = year, date = 2020-01-01, segment = ‘’, 52944 visits found. Time elapsed: 1267.061s
INFO [2020-11-24 12:41:06] 38820 Will invalidate archived reports for today in site ID = 118’s timezone (2020-11-24 00:00:00).
INFO [2020-11-24 12:41:08] 38820 Archived website id 118, period = day, date = 2020-11-24, segment = ‘’, 6 visits found. Time elapsed: 1.204s
INFO [2020-11-24 12:41:10] 38820 Archived website id 118, period = week, date = 2020-11-23, segment = ‘’, 174 visits found. Time elapsed: 2.029s
INFO [2020-11-24 12:41:21] 38820 Archived website id 118, period = month, date = 2020-11-01, segment = ‘’, 3468 visits found. Time elapsed: 11.452s
INFO [2020-11-24 12:56:46] 38820 Archived website id 118, period = year, date = 2020-01-01, segment = ‘’, 52944 visits found. Time elapsed: 924.398s
INFO [2020-11-24 12:56:46] 38820 Will invalidate archived reports for today in site ID = 118’s timezone (2020-11-24 00:00:00).
INFO [2020-11-24 12:56:47] 38820 Archived website id 118, period = day, date = 2020-11-24, segment = ‘’, 6 visits found. Time elapsed: 1.213s
INFO [2020-11-24 12:56:49] 38820 Archived website id 118, period = week, date = 2020-11-23, segment = ‘’, 174 visits found. Time elapsed: 2.078s
INFO [2020-11-24 12:57:01] 38820 Archived website id 118, period = month, date = 2020-11-01, segment = ‘’, 3468 visits found. Time elapsed: 11.621s
INFO [2020-11-24 13:12:26] 38820 Archived website id 118, period = year, date = 2020-01-01, segment = ‘’, 52944 visits found. Time elapsed: 925.198s
INFO [2020-11-24 13:12:26] 38820 Will invalidate archived reports for today in site ID = 118’s timezone (2020-11-24 00:00:00).
INFO [2020-11-24 13:12:27] 38820 Archived website id 118, period = day, date = 2020-11-24, segment = ‘’, 6 visits found. Time elapsed: 1.203s
INFO [2020-11-24 13:12:29] 38820 Archived website id 118, period = week, date = 2020-11-23, segment = ‘’, 174 visits found. Time elapsed: 2.046s
INFO [2020-11-24 13:12:41] 38820 Archived website id 118, period = month, date = 2020-11-01, segment = ‘’, 3468 visits found. Time elapsed: 11.402s
INFO [2020-11-24 13:28:05] 38820 Archived website id 118, period = year, date = 2020-01-01, segment = ‘’, 52944 visits found. Time elapsed: 924.566s
INFO [2020-11-24 13:28:05] 38820 Will invalidate archived reports for today in site ID = 118’s timezone (2020-11-24 00:00:00).
INFO [2020-11-24 13:28:07] 38820 Archived website id 118, period = day, date = 2020-11-24, segment = ‘’, 6 visits found. Time elapsed: 1.235s
INFO [2020-11-24 13:28:09] 38820 Archived website id 118, period = week, date = 2020-11-23, segment = ‘’, 174 visits found. Time elapsed: 2.062s
INFO [2020-11-24 13:28:20] 38820 Archived website id 118, period = month, date = 2020-11-01, segment = ‘’, 3468 visits found. Time elapsed: 11.463s
INFO [2020-11-24 13:43:42] 38820 Archived website id 118, period = year, date = 2020-01-01, segment = ‘’, 52944 visits found. Time elapsed: 921.392s
INFO [2020-11-24 13:43:42] 38820 Will invalidate archived reports for today in site ID = 118’s timezone (2020-11-24 00:00:00).
INFO [2020-11-24 13:43:44] 38820 Archived website id 118, period = day, date = 2020-11-24, segment = ‘’, 6 visits found. Time elapsed: 1.513s
INFO [2020-11-24 13:43:47] 38820 Archived website id 118, period = week, date = 2020-11-23, segment = ‘’, 174 visits found. Time elapsed: 2.984s
INFO [2020-11-24 13:43:59] 38820 Archived website id 118, period = month, date = 2020-11-01, segment = ‘’, 3468 visits found. Time elapsed: 12.013s
INFO [2020-11-24 13:59:29] 38820 Archived website id 118, period = year, date = 2020-01-01, segment = ‘’, 52944 visits found. Time elapsed: 930.101s
INFO [2020-11-24 13:59:29] 38820 Will invalidate archived reports for today in site ID = 118’s timezone (2020-11-24 00:00:00).
INFO [2020-11-24 13:59:30] 38820 Archived website id 118, period = day, date = 2020-11-24, segment = ‘’, 6 visits found. Time elapsed: 1.214s
INFO [2020-11-24 13:59:32] 38820 Archived website id 118, period = week, date = 2020-11-23, segment = ‘’, 174 visits found. Time elapsed: 1.995s
INFO [2020-11-24 13:59:44] 38820 Archived website id 118, period = month, date = 2020-11-01, segment = ‘’, 3468 visits found. Time elapsed: 11.274s
INFO [2020-11-24 14:15:11] 38820 Archived website id 118, period = year, date = 2020-01-01, segment = ‘’, 52944 visits found. Time elapsed: 927.303s
INFO [2020-11-24 14:15:11] 38820 Will invalidate archived reports for today in site ID = 118’s timezone (2020-11-24 00:00:00).
INFO [2020-11-24 14:15:12] 38820 Archived website id 118, period = day, date = 2020-11-24, segment = ‘’, 6 visits found. Time elapsed: 1.170s
INFO [2020-11-24 14:15:14] 38820 Archived website id 118, period = week, date = 2020-11-23, segment = ‘’, 174 visits found. Time elapsed: 2.084s
INFO [2020-11-24 14:15:26] 38820 Archived website id 118, period = month, date = 2020-11-01, segment = ‘’, 3468 visits found. Time elapsed: 11.412s
INFO [2020-11-24 14:30:47] 38820 Archived website id 118, period = year, date = 2020-01-01, segment = ‘’, 52944 visits found. Time elapsed: 921.252s
INFO [2020-11-24 14:30:47] 38820 Will invalidate archived reports for today in site ID = 118’s timezone (2020-11-24 00:00:00).
INFO [2020-11-24 14:30:48] 38820 Archived website id 118, period = day, date = 2020-11-24, segment = ‘’, 6 visits found. Time elapsed: 1.224s
INFO [2020-11-24 14:30:50] 38820 Archived website id 118, period = week, date = 2020-11-23, segment = ‘’, 174 visits found. Time elapsed: 2.090s
INFO [2020-11-24 14:31:02] 38820 Archived website id 118, period = month, date = 2020-11-01, segment = ‘’, 3468 visits found. Time elapsed: 11.817s
INFO [2020-11-24 14:46:23] 38820 Archived website id 118, period = year, date = 2020-01-01, segment = ‘’, 52944 visits found. Time elapsed: 920.299s
INFO [2020-11-24 14:46:23] 38820 Will invalidate archived reports for today in site ID = 118’s timezone (2020-11-24 00:00:00).
INFO [2020-11-24 14:46:24] 38820 Archived website id 118, period = day, date = 2020-11-24, segment = ‘’, 6 visits found. Time elapsed: 1.151s
INFO [2020-11-24 14:46:26] 38820 Archived website id 118, period = week, date = 2020-11-23, segment = ‘’, 174 visits found. Time elapsed: 2.084s
INFO [2020-11-24 14:46:38] 38820 Archived website id 118, period = month, date = 2020-11-01, segment = ‘’, 3468 visits found. Time elapsed: 11.580s
INFO [2020-11-24 15:01:58] 38820 Archived website id 118, period = year, date = 2020-01-01, segment = ‘’, 52944 visits found. Time elapsed: 920.105s
INFO [2020-11-24 15:01:58] 38820 Will invalidate archived reports for today in site ID = 118’s timezone (2020-11-24 00:00:00).
INFO [2020-11-24 15:01:59] 38820 Archived website id 118, period = day, date = 2020-11-24, segment = ‘’, 6 visits found. Time elapsed: 1.221s
INFO [2020-11-24 15:02:01] 38820 Archived website id 118, period = week, date = 2020-11-23, segment = ‘’, 174 visits found. Time elapsed: 2.101s
INFO [2020-11-24 15:02:13] 38820 Archived website id 118, period = month, date = 2020-11-01, segment = ‘’, 3468 visits found. Time elapsed: 11.536s
INFO [2020-11-24 15:17:29] 38820 Archived website id 118, period = year, date = 2020-01-01, segment = ‘’, 52944 visits found. Time elapsed: 916.378s
INFO [2020-11-24 15:17:29] 38820 Will invalidate archived reports for today in site ID = 118’s timezone (2020-11-24 00:00:00).
INFO [2020-11-24 15:17:30] 38820 Archived website id 118, period = day, date = 2020-11-24, segment = ‘’, 6 visits found. Time elapsed: 1.208s
INFO [2020-11-24 15:17:33] 38820 Archived website id 118, period = week, date = 2020-11-23, segment = ‘’, 174 visits found. Time elapsed: 2.070s
INFO [2020-11-24 15:17:44] 38820 Archived website id 118, period = month, date = 2020-11-01, segment = ‘’, 3468 visits found. Time elapsed: 11.391s
INFO [2020-11-24 15:33:03] 38820 Archived website id 118, period = year, date = 2020-01-01, segment = ‘’, 52944 visits found. Time elapsed: 919.355s
INFO [2020-11-24 15:33:03] 38820 Will invalidate archived reports for today in site ID = 118’s timezone (2020-11-24 00:00:00).
INFO [2020-11-24 15:33:05] 38820 Archived website id 118, period = day, date = 2020-11-24, segment = ‘’, 6 visits found. Time elapsed: 1.251s
INFO [2020-11-24 15:33:07] 38820 Archived website id 118, period = week, date = 2020-11-23, segment = ‘’, 174 visits found. Time elapsed: 2.033s
INFO [2020-11-24 15:33:18] 38820 Archived website id 118, period = month, date = 2020-11-01, segment = ‘’, 3468 visits found. Time elapsed: 11.360s
INFO [2020-11-24 15:48:39] 38820 Archived website id 118, period = year, date = 2020-01-01, segment = ‘’, 52944 visits found. Time elapsed: 920.550s
INFO [2020-11-24 15:48:39] 38820 Will invalidate archived reports for today in site ID = 118’s timezone (2020-11-24 00:00:00).
INFO [2020-11-24 15:48:40] 38820 Archived website id 118, period = day, date = 2020-11-24, segment = ‘’, 6 visits found. Time elapsed: 1.219s
INFO [2020-11-24 15:48:42] 38820 Archived website id 118, period = week, date = 2020-11-23, segment = ‘’, 174 visits found. Time elapsed: 2.048s
INFO [2020-11-24 15:48:54] 38820 Archived website id 118, period = month, date = 2020-11-01, segment = ‘’, 3468 visits found. Time elapsed: 11.347s
INFO [2020-11-24 16:04:24] 38820 Archived website id 118, period = year, date = 2020-01-01, segment = ‘’, 52944 visits found. Time elapsed: 930.518s
INFO [2020-11-24 16:04:24] 38820 Will invalidate archived reports for today in site ID = 118’s timezone (2020-11-24 00:00:00).
INFO [2020-11-24 16:04:25] 38820 Archived website id 118, period = day, date = 2020-11-24, segment = ‘’, 6 visits found. Time elapsed: 1.226s
INFO [2020-11-24 16:04:27] 38820 Archived website id 118, period = week, date = 2020-11-23, segment = ‘’, 174 visits found. Time elapsed: 2.036s
INFO [2020-11-24 16:04:39] 38820 Archived website id 118, period = month, date = 2020-11-01, segment = ‘’, 3468 visits found. Time elapsed: 11.514s
INFO [2020-11-24 16:20:03] 38820 Archived website id 118, period = year, date = 2020-01-01, segment = ‘’, 52944 visits found. Time elapsed: 924.318s
INFO [2020-11-24 16:20:03] 38820 Will invalidate archived reports for today in site ID = 118’s timezone (2020-11-24 00:00:00).
INFO [2020-11-24 16:20:05] 38820 Archived website id 118, period = day, date = 2020-11-24, segment = ‘’, 6 visits found. Time elapsed: 1.262s
INFO [2020-11-24 16:20:07] 38820 Archived website id 118, period = week, date = 2020-11-23, segment = ‘’, 174 visits found. Time elapsed: 2.139s
INFO [2020-11-24 16:20:19] 38820 Archived website id 118, period = month, date = 2020-11-01, segment = ‘’, 3468 visits found. Time elapsed: 11.995s
INFO [2020-11-24 16:35:44] 38820 Archived website id 118, period = year, date = 2020-01-01, segment = ‘’, 52944 visits found. Time elapsed: 925.404s
INFO [2020-11-24 16:35:44] 38820 Will invalidate archived reports for today in site ID = 118’s timezone (2020-11-24 00:00:00).
INFO [2020-11-24 16:35:46] 38820 Archived website id 118, period = day, date = 2020-11-24, segment = ‘’, 6 visits found. Time elapsed: 1.255s
INFO [2020-11-24 16:35:48] 38820 Archived website id 118, period = week, date = 2020-11-23, segment = ‘’, 174 visits found. Time elapsed: 2.077s
INFO [2020-11-24 16:35:59] 38820 Archived website id 118, period = month, date = 2020-11-01, segment = ‘’, 3468 visits found. Time elapsed: 11.409s
INFO [2020-11-24 16:51:20] 38820 Archived website id 118, period = year, date = 2020-01-01, segment = ‘’, 52944 visits found. Time elapsed: 920.418s
INFO [2020-11-24 16:51:20] 38820 Will invalidate archived reports for today in site ID = 118’s timezone (2020-11-24 00:00:00).
INFO [2020-11-24 16:51:21] 38820 Archived website id 118, period = day, date = 2020-11-24, segment = ‘’, 6 visits found. Time elapsed: 1.216s
INFO [2020-11-24 16:51:23] 38820 Archived website id 118, period = week, date = 2020-11-23, segment = ‘’, 174 visits found. Time elapsed: 2.034s
INFO [2020-11-24 16:51:35] 38820 Archived website id 118, period = month, date = 2020-11-01, segment = ‘’, 3468 visits found. Time elapsed: 11.409s
INFO [2020-11-24 17:07:09] 38820 Archived website id 118, period = year, date = 2020-01-01, segment = ‘’, 52944 visits found. Time elapsed: 934.039s
INFO [2020-11-24 17:07:09] 38820 Will invalidate archived reports for today in site ID = 118’s timezone (2020-11-24 00:00:00).
INFO [2020-11-24 17:07:10] 38820 Archived website id 118, period = day, date = 2020-11-24, segment = ‘’, 6 visits found. Time elapsed: 1.593s
INFO [2020-11-24 17:07:12] 38820 Archived website id 118, period = week, date = 2020-11-23, segment = ‘’, 174 visits found. Time elapsed: 2.052s
INFO [2020-11-24 17:07:24] 38820 Archived website id 118, period = month, date = 2020-11-01, segment = ‘’, 3468 visits found. Time elapsed: 11.723s

2

Hello!
I also updated to version 4 today, and noticed that my server received a heavy load, which reached 25% …
The reason turned out to be a task in the crown that was executed in a looped mode for many hours :frowning:

1 Like
3

Hi, sorry this issue is affecting you. Would someone experiencing the issue be able to post the output of the core:archive command with the -vvv flag? Eg, ./console core:archive -vvv.

4

It looks like this was yesterday problem so far. It could be related to multiple errors which I was facing and finally I decided to take a look at them. They where mostly related to memory usage and timeouts on various levels.

Currently after PHP upgrading to x64 version archive process is creating php-cgi.exe process with 25% cpu usage (probably related to 4 cores on system which process is using one of them at 100%) and about 3.3-3.4GB of RAM. With timeout values changed to much higher levels archive process is not being killed and can run for long time. Today I didn’t noticed any issues and forcing site with ID 118 is resulting with:

INFO [2020-11-25 07:47:39] 49504  Running Matomo 4.0.0 as Super User
INFO [2020-11-25 07:47:39] 49504  ---------------------------
INFO [2020-11-25 07:47:39] 49504  NOTES
INFO [2020-11-25 07:47:39] 49504  - Async process archiving not supported, using curl requests.
INFO [2020-11-25 07:47:39] 49504  - Reports for today will be processed at most every 1 seconds. You can change this value in Matomo UI > Settings > General Settings.
INFO [2020-11-25 07:47:39] 49504  - Archiving was last executed without error 14s ago
INFO [2020-11-25 07:47:39] 49504  - Will process 1 websites (--force-idsites)
INFO [2020-11-25 07:47:39] 49504  - Will process specified sites: 118
INFO [2020-11-25 07:47:39] 49504  ---------------------------
INFO [2020-11-25 07:47:39] 49504  START
INFO [2020-11-25 07:47:39] 49504  Starting Matomo reports archiving...
DEBUG [2020-11-25 07:47:39] 49504  Applying queued rearchiving...
INFO [2020-11-25 07:47:39] 49504  Start processing archives for site 118.
DEBUG [2020-11-25 07:47:39] 49504  Invalidations currently exist for idSite 118, skipping invalidating for now...
DEBUG [2020-11-25 07:47:39] 49504  No next invalidated archive.
INFO [2020-11-25 07:47:39] 49504  Finished archiving for site 118, 0 API requests, Time elapsed: 0.003s [1 / 1 done]
DEBUG [2020-11-25 07:47:39] 49504  No more sites left to archive, stopping.
INFO [2020-11-25 07:47:39] 49504  Done archiving!
INFO [2020-11-25 07:47:39] 49504  ---------------------------
INFO [2020-11-25 07:47:39] 49504  SUMMARY
INFO [2020-11-25 07:47:39] 49504  Processed 0 archives.
INFO [2020-11-25 07:47:39] 49504  Total API requests: 0
INFO [2020-11-25 07:47:39] 49504  done: 0 req, 21 ms, no error
INFO [2020-11-25 07:47:39] 49504  Time elapsed: 0.022s
INFO [2020-11-25 07:47:39] 49504  ---------------------------
INFO [2020-11-25 07:47:39] 49504  SCHEDULED TASKS
DEBUG [2020-11-25 07:47:39] 49504  28 scheduled tasks loaded
INFO [2020-11-25 07:47:39] 49504  Starting Scheduled tasks...
DEBUG [2020-11-25 07:47:39] 49504  Executing tasks with priority 0:
DEBUG [2020-11-25 07:47:39] 49504  Executing tasks with priority 1:
DEBUG [2020-11-25 07:47:39] 49504  Executing tasks with priority 2:
DEBUG [2020-11-25 07:47:39] 49504  Executing tasks with priority 3:
DEBUG [2020-11-25 07:47:39] 49504  Executing tasks with priority 4:
DEBUG [2020-11-25 07:47:39] 49504  Executing tasks with priority 5:
DEBUG [2020-11-25 07:47:39] 49504  Executing tasks with priority 6:
DEBUG [2020-11-25 07:47:39] 49504  Executing tasks with priority 7:
DEBUG [2020-11-25 07:47:39] 49504  Executing tasks with priority 8:
DEBUG [2020-11-25 07:47:39] 49504  Executing tasks with priority 9:
DEBUG [2020-11-25 07:47:39] 49504  Executing tasks with priority 10:
DEBUG [2020-11-25 07:47:39] 49504  Executing tasks with priority 11:
DEBUG [2020-11-25 07:47:39] 49504  Executing tasks with priority 12:
INFO [2020-11-25 07:47:39] 49504  done
INFO [2020-11-25 07:47:39] 49504  ---------------------------
5

Hi, there is a possible fix here: https://github.com/matomo-org/matomo/pull/16796/files

Would you be able to make this change and see if it helps?

1 Like
6

Result after changes:

.....console core:archive --force-idsites=118 -vvv
INFO [2020-11-25 08:53:49] 55984  ---------------------------
INFO [2020-11-25 08:53:49] 55984  INIT
INFO [2020-11-25 08:53:49] 55984  Running Matomo 4.0.0 as Super User
INFO [2020-11-25 08:53:49] 55984  ---------------------------
INFO [2020-11-25 08:53:49] 55984  NOTES
INFO [2020-11-25 08:53:49] 55984  - Async process archiving not supported, using curl requests.
INFO [2020-11-25 08:53:49] 55984  - Reports for today will be processed at most every 1 seconds. You can change this value in Matomo UI > Settings > General Settings.
INFO [2020-11-25 08:53:49] 55984  - Archiving was last executed without error 1 hours 6 min ago
INFO [2020-11-25 08:53:49] 55984  - Will process 1 websites (--force-idsites)
INFO [2020-11-25 08:53:49] 55984  - Will process specified sites: 118
INFO [2020-11-25 08:53:49] 55984  ---------------------------
INFO [2020-11-25 08:53:49] 55984  START
INFO [2020-11-25 08:53:49] 55984  Starting Matomo reports archiving...
DEBUG [2020-11-25 08:53:49] 55984  Applying queued rearchiving...
INFO [2020-11-25 08:53:49] 55984  Start processing archives for site 118.
DEBUG [2020-11-25 08:53:49] 55984  Checking for queued invalidations...
DEBUG [2020-11-25 08:53:49] 55984    Found usable archive for date range 2020-11-24 for site 118, skipping invalidation for now.
DEBUG [2020-11-25 08:53:49] 55984    Found usable archive for date range 2020-11-22 for site 118, skipping invalidation for now.
INFO [2020-11-25 08:53:49] 55984    Will invalidate archived reports for today in site ID = 118's timezone (2020-11-25 00:00:00).
INFO [2020-11-25 08:53:49] 55984    Will invalidate archived reports for yesterday in site ID = 118's timezone (2020-11-24 00:00:00).
DEBUG [2020-11-25 08:53:49] 55984    Invalidating custom date range (previous7) for site 118
DEBUG [2020-11-25 08:53:49] 55984  Done invalidating
DEBUG [2020-11-25 08:53:49] 55984  Processing invalidation: [idinvalidation = 2822, idsite = 118, period = day(2020-11-25 - 2020-11-25), name = done].
DEBUG [2020-11-25 08:53:49] 55984  Processing invalidation: [idinvalidation = 2826, idsite = 118, period = day(2020-11-24 - 2020-11-24), name = done].
DEBUG [2020-11-25 08:53:49] 55984  Found archive with intersecting period with others in concurrent batch, skipping until next batch: [idinvalidation = 2827, idsite = 118, period = week(2020-11-23 - 2020-11-29), name = done]
DEBUG [2020-11-25 08:53:49] 55984  Found archive with intersecting period with others in concurrent batch, skipping until next batch: [idinvalidation = 2823, idsite = 118, period = week(2020-11-23 - 2020-11-29), name = done]
DEBUG [2020-11-25 08:53:49] 55984  Found archive with intersecting period with others in concurrent batch, skipping until next batch: [idinvalidation = 2828, idsite = 118, period = month(2020-11-01 - 2020-11-30), name = done]
DEBUG [2020-11-25 08:53:49] 55984  Found archive with intersecting period with others in concurrent batch, skipping until next batch: [idinvalidation = 2824, idsite = 118, period = month(2020-11-01 - 2020-11-30), name = done]
DEBUG [2020-11-25 08:53:49] 55984  Found duplicate invalidated archive (same archive currently in progress), ignoring: [idinvalidation = 2829, idsite = 118, period = year(2020-01-01 - 2020-12-31), name = done]
DEBUG [2020-11-25 08:53:49] 55984  Found duplicate invalidated archive (same archive currently in progress), ignoring: [idinvalidation = 2825, idsite = 118, period = year(2020-01-01 - 2020-12-31), name = done]
DEBUG [2020-11-25 08:53:49] 55984  No next invalidated archive.
DEBUG [2020-11-25 08:53:49] 55984  Starting archiving for ?module=API&method=CoreAdminHome.archiveReports&idSite=118&period=day&date=2020-11-25&format=json&trigger=archivephp
DEBUG [2020-11-25 08:53:49] 55984  Starting archiving for ?module=API&method=CoreAdminHome.archiveReports&idSite=118&period=day&date=2020-11-24&format=json&trigger=archivephp
DEBUG [2020-11-25 08:53:49] 55984  Execute HTTP API request: https://MATMOURL/?module=API&method=CoreAdminHome.archiveReports&idSite=118&period=day&date=2020-11-25&format=json&trigger=archivephp&
DEBUG [2020-11-25 08:53:51] 55984  Execute HTTP API request: https://MATMOURL/?module=API&method=CoreAdminHome.archiveReports&idSite=118&period=day&date=2020-11-24&format=json&trigger=archivephp&
INFO [2020-11-25 08:53:59] 55984  Archived website id 118, period = day, date = 2020-11-25, segment = '', 3 visits found. Time elapsed: 9.823s
INFO [2020-11-25 08:53:59] 55984  Archived website id 118, period = day, date = 2020-11-24, segment = '', 171 visits found. Time elapsed: 9.841s
DEBUG [2020-11-25 08:53:59] 55984  Processing invalidation: [idinvalidation = 2827, idsite = 118, period = week(2020-11-23 - 2020-11-29), name = done].
DEBUG [2020-11-25 08:53:59] 55984  Found duplicate invalidated archive 177004, ignoring: [idinvalidation = 2823, idsite = 118, period = week(2020-11-23 - 2020-11-29), name = done]
DEBUG [2020-11-25 08:53:59] 55984  Found archive with intersecting period with others in concurrent batch, skipping until next batch: [idinvalidation = 2828, idsite = 118, period = month(2020-11-01 - 2020-11-30), name = done]
DEBUG [2020-11-25 08:53:59] 55984  Found archive with intersecting period with others in concurrent batch, skipping until next batch: [idinvalidation = 2824, idsite = 118, period = month(2020-11-01 - 2020-11-30), name = done]
DEBUG [2020-11-25 08:53:59] 55984  No next invalidated archive.
DEBUG [2020-11-25 08:53:59] 55984  Starting archiving for ?module=API&method=CoreAdminHome.archiveReports&idSite=118&period=week&date=2020-11-23&format=json&trigger=archivephp
DEBUG [2020-11-25 08:53:59] 55984  Execute HTTP API request: https://MATMOURL/?module=API&method=CoreAdminHome.archiveReports&idSite=118&period=week&date=2020-11-23&format=json&trigger=archivephp&
INFO [2020-11-25 08:54:02] 55984  Archived website id 118, period = week, date = 2020-11-23, segment = '', 342 visits found. Time elapsed: 3.257s
DEBUG [2020-11-25 08:54:02] 55984  Processing invalidation: [idinvalidation = 2828, idsite = 118, period = month(2020-11-01 - 2020-11-30), name = done].
DEBUG [2020-11-25 08:54:02] 55984  Found duplicate invalidated archive 177007, ignoring: [idinvalidation = 2824, idsite = 118, period = month(2020-11-01 - 2020-11-30), name = done]
DEBUG [2020-11-25 08:54:02] 55984  No next invalidated archive.
DEBUG [2020-11-25 08:54:02] 55984  Starting archiving for ?module=API&method=CoreAdminHome.archiveReports&idSite=118&period=month&date=2020-11-01&format=json&trigger=archivephp
DEBUG [2020-11-25 08:54:02] 55984  Execute HTTP API request: https://MATMOURL/?module=API&method=CoreAdminHome.archiveReports&idSite=118&period=month&date=2020-11-01&format=json&trigger=archivephp&
INFO [2020-11-25 08:54:16] 55984  Archived website id 118, period = month, date = 2020-11-01, segment = '', 3636 visits found. Time elapsed: 13.907s
DEBUG [2020-11-25 08:54:16] 55984  No next invalidated archive.
INFO [2020-11-25 08:54:16] 55984  Finished archiving for site 118, 4 API requests, Time elapsed: 27.581s [1 / 1 done]
DEBUG [2020-11-25 08:54:16] 55984  No more sites left to archive, stopping.
INFO [2020-11-25 08:54:16] 55984  Done archiving!
INFO [2020-11-25 08:54:16] 55984  ---------------------------
INFO [2020-11-25 08:54:16] 55984  SUMMARY
INFO [2020-11-25 08:54:16] 55984  Processed 4 archives.
INFO [2020-11-25 08:54:16] 55984  Total API requests: 4
INFO [2020-11-25 08:54:16] 55984  done: 4 req, 27598 ms, no error
INFO [2020-11-25 08:54:16] 55984  Time elapsed: 27.598s
INFO [2020-11-25 08:54:16] 55984  ---------------------------
INFO [2020-11-25 08:54:16] 55984  SCHEDULED TASKS
DEBUG [2020-11-25 08:54:17] 55984  28 scheduled tasks loaded
INFO [2020-11-25 08:54:17] 55984  Starting Scheduled tasks...
DEBUG [2020-11-25 08:54:17] 55984  Executing tasks with priority 0:
DEBUG [2020-11-25 08:54:17] 55984  Executing tasks with priority 1:
DEBUG [2020-11-25 08:54:17] 55984  Executing tasks with priority 2:
DEBUG [2020-11-25 08:54:17] 55984  Executing tasks with priority 3:
DEBUG [2020-11-25 08:54:17] 55984  Executing tasks with priority 4:
DEBUG [2020-11-25 08:54:17] 55984  Executing tasks with priority 5:
DEBUG [2020-11-25 08:54:17] 55984  Executing tasks with priority 6:
DEBUG [2020-11-25 08:54:17] 55984  Task Piwik\Plugins\CustomJsTracker\Tasks.updateTracker is scheduled to run again for 2020-11-25.
INFO [2020-11-25 08:54:17] 55984  Scheduler: executing task Piwik\Plugins\CustomJsTracker\Tasks.updateTracker...
INFO [2020-11-25 08:54:17] 55984  Scheduler: finished. Time elapsed: 0.019s
DEBUG [2020-11-25 08:54:17] 55984  Executing tasks with priority 7:
DEBUG [2020-11-25 08:54:17] 55984  Executing tasks with priority 8:
DEBUG [2020-11-25 08:54:17] 55984  Executing tasks with priority 9:
DEBUG [2020-11-25 08:54:17] 55984  Task Piwik\Plugins\PrivacyManager\Tasks.deleteLogData is scheduled to run again for 2020-11-25.
INFO [2020-11-25 08:54:17] 55984  Scheduler: executing task Piwik\Plugins\PrivacyManager\Tasks.deleteLogData...
INFO [2020-11-25 08:54:17] 55984  Scheduler: finished. Time elapsed: 0.002s
DEBUG [2020-11-25 08:54:17] 55984  Task Piwik\Plugins\PrivacyManager\Tasks.anonymizePastData is scheduled to run again for 2020-11-25.
INFO [2020-11-25 08:54:17] 55984  Scheduler: executing task Piwik\Plugins\PrivacyManager\Tasks.anonymizePastData...
INFO [2020-11-25 08:54:17] 55984  Scheduler: finished. Time elapsed: 0.001s
DEBUG [2020-11-25 08:54:17] 55984  Executing tasks with priority 10:
DEBUG [2020-11-25 08:54:17] 55984  Executing tasks with priority 11:
DEBUG [2020-11-25 08:54:17] 55984  Executing tasks with priority 12:
INFO [2020-11-25 08:54:17] 55984  done
INFO [2020-11-25 08:54:17] 55984  ---------------------------
7

./console core:archive -vvv
INFO [2020-11-25 10:47:04] 18521 ---------------------------
INFO [2020-11-25 10:47:04] 18521 INIT
INFO [2020-11-25 10:47:04] 18521 Running Matomo 4.0.0 as Super User
INFO [2020-11-25 10:47:04] 18521 ---------------------------
INFO [2020-11-25 10:47:04] 18521 NOTES
INFO [2020-11-25 10:47:04] 18521 - Async process archiving supported, using CliMulti.
INFO [2020-11-25 10:47:04] 18521 - Reports for today will be processed at most every 900 seconds. You can change this value in Matomo UI > Settings > General Settings.
INFO [2020-11-25 10:47:04] 18521 - Archiving was last executed without error 1 min 54s ago
INFO [2020-11-25 10:47:04] 18521 ---------------------------
INFO [2020-11-25 10:47:04] 18521 START
INFO [2020-11-25 10:47:04] 18521 Starting Matomo reports archiving…
DEBUG [2020-11-25 10:47:04] 18521 Applying queued rearchiving…
INFO [2020-11-25 10:47:04] 18521 Start processing archives for site 1.
DEBUG [2020-11-25 10:47:04] 18521 Checking for queued invalidations…
DEBUG [2020-11-25 10:47:04] 18521 Found existing valid archive for today, skipping invalidation…
DEBUG [2020-11-25 10:47:04] 18521 Yesterday archive can be skipped due to no visits for idSite = 1, skipping invalidation…
DEBUG [2020-11-25 10:47:04] 18521 Invalidating custom date range (last7) for site 1
DEBUG [2020-11-25 10:47:04] 18521 Done invalidating
DEBUG [2020-11-25 10:47:04] 18521 No next invalidated archive.
INFO [2020-11-25 10:47:04] 18521 Finished archiving for site 1, 0 API requests, Time elapsed: 0.020s [1 / 3 done]
INFO [2020-11-25 10:47:04] 18521 Start processing archives for site 4.
DEBUG [2020-11-25 10:47:04] 18521 Checking for queued invalidations…
DEBUG [2020-11-25 10:47:04] 18521 Found existing valid archive for today, skipping invalidation…
DEBUG [2020-11-25 10:47:04] 18521 Yesterday archive can be skipped due to no visits for idSite = 4, skipping invalidation…
DEBUG [2020-11-25 10:47:04] 18521 Done invalidating
DEBUG [2020-11-25 10:47:04] 18521 No next invalidated archive.
INFO [2020-11-25 10:47:04] 18521 Finished archiving for site 4, 0 API requests, Time elapsed: 0.004s [2 / 3 done]
INFO [2020-11-25 10:47:04] 18521 Start processing archives for site 15.
DEBUG [2020-11-25 10:47:04] 18521 Checking for queued invalidations…
DEBUG [2020-11-25 10:47:04] 18521 Found existing valid archive for today, skipping invalidation…
DEBUG [2020-11-25 10:47:04] 18521 Yesterday archive can be skipped due to no visits for idSite = 15, skipping invalidation…
DEBUG [2020-11-25 10:47:04] 18521 Done invalidating
DEBUG [2020-11-25 10:47:04] 18521 No next invalidated archive.
INFO [2020-11-25 10:47:04] 18521 Finished archiving for site 15, 0 API requests, Time elapsed: 0.004s [3 / 3 done]
DEBUG [2020-11-25 10:47:04] 18521 No more sites left to archive, stopping.
INFO [2020-11-25 10:47:04] 18521 Done archiving!
INFO [2020-11-25 10:47:04] 18521 ---------------------------
INFO [2020-11-25 10:47:04] 18521 SUMMARY
INFO [2020-11-25 10:47:04] 18521 Processed 0 archives.
INFO [2020-11-25 10:47:04] 18521 Total API requests: 0
INFO [2020-11-25 10:47:04] 18521 done: 0 req, 152 ms, no error
INFO [2020-11-25 10:47:04] 18521 Time elapsed: 0.152s
INFO [2020-11-25 10:47:04] 18521 ---------------------------
INFO [2020-11-25 10:47:04] 18521 SCHEDULED TASKS
DEBUG [2020-11-25 10:47:04] 18521 26 scheduled tasks loaded
INFO [2020-11-25 10:47:04] 18521 Starting Scheduled tasks…
DEBUG [2020-11-25 10:47:04] 18521 Executing tasks with priority 0:
DEBUG [2020-11-25 10:47:04] 18521 Executing tasks with priority 1:
DEBUG [2020-11-25 10:47:04] 18521 Executing tasks with priority 2:
DEBUG [2020-11-25 10:47:04] 18521 Executing tasks with priority 3:
DEBUG [2020-11-25 10:47:04] 18521 Executing tasks with priority 4:
DEBUG [2020-11-25 10:47:04] 18521 Executing tasks with priority 5:
DEBUG [2020-11-25 10:47:04] 18521 Executing tasks with priority 6:
DEBUG [2020-11-25 10:47:04] 18521 Executing tasks with priority 7:
DEBUG [2020-11-25 10:47:04] 18521 Executing tasks with priority 8:
DEBUG [2020-11-25 10:47:04] 18521 Executing tasks with priority 9:
DEBUG [2020-11-25 10:47:04] 18521 Executing tasks with priority 10:
DEBUG [2020-11-25 10:47:04] 18521 Executing tasks with priority 11:
DEBUG [2020-11-25 10:47:04] 18521 Executing tasks with priority 12:
INFO [2020-11-25 10:47:04] 18521 done
INFO [2020-11-25 10:47:04] 18521 ---------------------------

8

It looks like the problem is fixed, but I’m seeing another one I’ll look into as well.

9

Was it addressed to me? :slight_smile:
If it’s not a secret, what problem is still there?

10

That was a reply to Webio, in their logs I see it skipped processing the year archive. I think that might be a temporary issue that will resolve itself after some time has passed.

11

Thanks. I will try to keep an eye on it. So far it works correctly

12

Hi, I still have this Problem, even with Matomo 4.11.0 and php 7.4.

What could it be?

13

How many Matomo server do you have?
What is the CRON period?
Is the CRON active on only one single Matomo server?
Can you provide the Error log?

14

Hi Philippe,
we have 1 server with ca 50 sites.
the (php-Script) Cron is all 2 hours. This error even comes when executed once in console.

LOG:

INFO CoreAdminHome[2022-09-21 06:00:01 UTC] [d442e] ---------------------------
INFO CoreAdminHome[2022-09-21 06:00:01 UTC] [d442e] INIT
INFO CoreAdminHome[2022-09-21 06:00:01 UTC] [d442e] Running Matomo 4.11.0 as Super User
INFO CoreAdminHome[2022-09-21 06:00:01 UTC] [d442e] ---------------------------
INFO CoreAdminHome[2022-09-21 06:00:01 UTC] [d442e] NOTES
INFO CoreAdminHome[2022-09-21 06:00:01 UTC] [d442e] - Async process archiving not supported, using curl requests.
INFO CoreAdminHome[2022-09-21 06:00:01 UTC] [d442e] - Reports for today will be processed at most every 3600 seconds. You can change this value in Matomo UI > Settings > General Settings.
INFO CoreAdminHome[2022-09-21 06:00:01 UTC] [d442e] - Archiving was last executed without error 19 hours 55 min ago.
INFO CoreAdminHome[2022-09-21 06:00:06 UTC] [d442e] ---------------------------
INFO CoreAdminHome[2022-09-21 06:00:06 UTC] [d442e] START
INFO CoreAdminHome[2022-09-21 06:00:06 UTC] [d442e] Starting Matomo reports archiving…
INFO CoreAdminHome[2022-09-21 06:00:11 UTC] [d442e] Start processing archives for site 1.
INFO CoreAdminHome[2022-09-21 06:00:11 UTC] [d442e] Will invalidate archived reports for today in site ID = 1’s timezone (2022-09-21 00:00:00).
INFO CoreAdminHome[2022-09-21 06:00:11 UTC] [d442e] Will invalidate archived reports for yesterday in site ID = 1’s timezone (2022-09-20 00:00:00).
INFO CoreAdminHome[2022-09-21 06:00:11 UTC] [d442e] Archived website id 1, period = day, date = 2022-09-21, segment = ‘’, 17 visits found. Time elapsed: 0.350s
INFO CoreAdminHome[2022-09-21 06:00:11 UTC] [d442e] Archived website id 1, period = day, date = 2022-09-20, segment = ‘’, 279 visits found. Time elapsed: 0.351s
INFO CoreAdminHome[2022-09-21 06:00:11 UTC] [d442e] Archived website id 1, period = week, date = 2022-09-19, segment = ‘’, 558 visits found. Time elapsed: 0.195s
INFO CoreAdminHome[2022-09-21 06:00:12 UTC] [d442e] Archived website id 1, period = month, date = 2022-09-01, segment = ‘’, 4447 visits found. Time elapsed: 0.417s
INFO CoreAdminHome[2022-09-21 06:00:12 UTC] [d442e] Archived website id 1, period = year, date = 2022-01-01, segment = ‘’, 69829 visits found. Time elapsed: 0.678s
INFO CoreAdminHome[2022-09-21 06:00:12 UTC] [d442e] Finished archiving for site 1, 5 API requests, Time elapsed: 1.715s [1 / 55 done]
INFO CoreAdminHome[2022-09-21 06:00:17 UTC] [d442e] Start processing archives for site 2.
INFO CoreAdminHome[2022-09-21 06:00:17 UTC] [d442e] Will invalidate archived reports for today in site ID = 2’s timezone (2022-09-21 00:00:00).
INFO CoreAdminHome[2022-09-21 06:00:17 UTC] [d442e] Will invalidate archived reports for yesterday in site ID = 2’s timezone (2022-09-20 00:00:00).
INFO CoreAdminHome[2022-09-21 06:00:17 UTC] [d442e] Archived website id 2, period = day, date = 2022-09-21, segment = ‘’, 74 visits found. Time elapsed: 0.647s
INFO CoreAdminHome[2022-09-21 06:00:17 UTC] [d442e] Archived website id 2, period = day, date = 2022-09-20, segment = ‘’, 1270 visits found. Time elapsed: 0.648s
INFO CoreAdminHome[2022-09-21 06:00:17 UTC] [d442e] Archived website id 2, period = week, date = 2022-09-19, segment = ‘’, 2590 visits found. Time elapsed: 0.305s
INFO CoreAdminHome[2022-09-21 06:00:19 UTC] [d442e] Archived website id 2, period = month, date = 2022-09-01, segment = ‘’, 19092 visits found. Time elapsed: 1.057s
INFO CoreAdminHome[2022-09-21 06:00:20 UTC] [d442e] Archived website id 2, period = year, date = 2022-01-01, segment = ‘’, 225949 visits found. Time elapsed: 1.620s
INFO CoreAdminHome[2022-09-21 06:00:20 UTC] [d442e] Finished archiving for site 2, 5 API requests, Time elapsed: 3.677s [2 / 55 done]
INFO CoreAdminHome[2022-09-21 06:00:25 UTC] [d442e] Start processing archives for site 4.
INFO CoreAdminHome[2022-09-21 06:00:25 UTC] [d442e] Will invalidate archived reports for today in site ID = 4’s timezone (2022-09-21 00:00:00).
INFO CoreAdminHome[2022-09-21 06:00:25 UTC] [d442e] Will invalidate archived reports for yesterday in site ID = 4’s timezone (2022-09-20 00:00:00).
INFO CoreAdminHome[2022-09-21 06:00:25 UTC] [d442e] Archived website id 4, period = day, date = 2022-09-21, segment = ‘’, 8 visits found. Time elapsed: 0.222s
INFO CoreAdminHome[2022-09-21 06:00:25 UTC] [d442e] Archived website id 4, period = day, date = 2022-09-20, segment = ‘’, 105 visits found. Time elapsed: 0.223s
INFO CoreAdminHome[2022-09-21 06:00:25 UTC] [d442e] Archived website id 4, period = week, date = 2022-09-19, segment = ‘’, 196 visits found. Time elapsed: 0.186s
INFO CoreAdminHome[2022-09-21 06:00:25 UTC] [d442e] Archived website id 4, period = month, date = 2022-09-01, segment = ‘’, 1615 visits found. Time elapsed: 0.388s
INFO CoreAdminHome[2022-09-21 06:00:26 UTC] [d442e] Archived website id 4, period = year, date = 2022-01-01, segment = ‘’, 22496 visits found. Time elapsed: 0.706s
INFO CoreAdminHome[2022-09-21 06:00:26 UTC] [d442e] Finished archiving for site 4, 5 API requests, Time elapsed: 1.548s [3 / 55 done]

And so on …

Thanx

15

Sorry, I don’t see any problem in your log…

16

Hmm :wink:

There are various entries:

INFO CoreAdminHome[2022-09-21 06:00:11 UTC] [d442e] Will invalidate archived reports for today in site ID = 1’s timezone (2022-09-21 00:00:00).

Ah I see, it’s “timezone”.
It’s in the OP, too.
Thanx.

17

Archiving process has to invalidate the data of today.
Indeed, the data processing step first check which data must be compiled. If (reports) data are valid, they won’t be processed again. As the day of today is not finished, then the processed data of today are never valid… until tomorrow. So the archiving process must first invalidate the data of today…

18

Hi, great, thank you.