Matomo: 'Visits Overview' not updating while `Visits in Real-time` works fine (Matomo 4)

Created on 10 Nov 2020  路  33Comments  路  Source: matomo-org/matomo

Hi,

I'm having some issues with my matomo server since updating to the 4.0.0-rc1 beta. I'm using a crontab to automatically archive my matomo reports. However, the Visits Overview statistics are not updated anymore. The Visits in Real-time does work as intended and shows recent visits. All the system checks succeed and I'm not sure what to look at. I tried deleting the tmp directory but it didn't resolve anything.

Manually executing the archive command does not show new API requests. Are there some steps I can take to resolve this issue?

root@c3e43c5fd0ff:/var/www/html# ./console core:archive
INFO [2020-11-10 18:42:53] 335  ---------------------------
INFO [2020-11-10 18:42:53] 335  INIT
INFO [2020-11-10 18:42:53] 335  Running Matomo 4.0.0-rc1 as Super User
INFO [2020-11-10 18:42:53] 335  ---------------------------
INFO [2020-11-10 18:42:53] 335  NOTES
INFO [2020-11-10 18:42:53] 335  - Async process archiving supported, using CliMulti.
INFO [2020-11-10 18:42:53] 335  - Reports for today will be processed at most every 10 seconds. You can change this value in Matomo UI > Settings > General Settings.
INFO [2020-11-10 18:42:53] 335  - Archiving was last executed without error 8 min 27s ago
INFO [2020-11-10 18:42:53] 335  ---------------------------
INFO [2020-11-10 18:42:53] 335  START
INFO [2020-11-10 18:42:53] 335  Starting Matomo reports archiving...
INFO [2020-11-10 18:42:53] 335  Start processing archives for site 1.
INFO [2020-11-10 18:42:53] 335  Finished archiving for site 1, 0 API requests, Time elapsed: 0.002s [1 / 2 done]
INFO [2020-11-10 18:42:53] 335  Start processing archives for site 4.
INFO [2020-11-10 18:42:53] 335  Finished archiving for site 4, 0 API requests, Time elapsed: 0.002s [2 / 2 done]
INFO [2020-11-10 18:42:53] 335  Done archiving!
INFO [2020-11-10 18:42:53] 335  ---------------------------
INFO [2020-11-10 18:42:53] 335  SUMMARY
INFO [2020-11-10 18:42:53] 335  Processed 0 archives.
INFO [2020-11-10 18:42:53] 335  Total API requests: 0
INFO [2020-11-10 18:42:53] 335  done: 0 req, 96 ms, no error
INFO [2020-11-10 18:42:53] 335  Time elapsed: 0.097s
INFO [2020-11-10 18:42:53] 335  ---------------------------
INFO [2020-11-10 18:42:53] 335  SCHEDULED TASKS
INFO [2020-11-10 18:42:53] 335  Starting Scheduled tasks...
INFO [2020-11-10 18:42:53] 335  done
INFO [2020-11-10 18:42:53] 335  ---------------------------

matomo_system_check.txt

Thank you,
Pepijn Boers

Bug not-in-changelog
Source
picture PepijnBoers

Most helpful comment

I see the issue, it's due to the previous entries still existing. We need to remove status = 1 AND ts_started IS NULL invalidation entries in an update.

@cadeyrn if you run this SQL it should unblock the archiving:

DELETE FROM matomo_archive_invalidations WHERE status = 1 AND ts_started IS NULL

cc @tsteur (will remove in an update)

picture diosmosis on 17 Nov 2020
👍2

All 33 comments

Thanks for creating this issue and sorry for the trouble @PepijnBoers

Could you maybe run this MySQL query and send us the output?

select `status`, count(*) from matomo_archive_invalidations group by `status`

just created https://github.com/matomo-org/matomo/pull/16690 to add more information to system check so this won't be needed next time.

@diosmosis do you have any idea on this? My theory is that maybe some invalidation is stuck in progress and it won't trigger any new invalidations maybe? Wonder if we should change DataAccess\Model::isInvalidationsScheduledForSite() to add a condition where status = 0?

tsteur picture tsteur on 10 Nov 2020 
mysql> select `status`, count(*) from matomo_archive_invalidations group by `status`;
+--------+----------+
| status | count(*) |
+--------+----------+
|      1 |        2 |
+--------+----------+
1 row in set (0.00 sec)
PepijnBoers picture PepijnBoers on 10 Nov 2020

Thanks a lot @PepijnBoers I think that confirms my theory @diosmosis ? Maybe the one in "progress" failed and was never cleaned up?

tsteur picture tsteur on 10 Nov 2020

For the record: I have the same issue since 4.0.0-rc1. My output for the command above:

+--------+----------+
| status | count(*) |
+--------+----------+
|      1 |        5 |
+--------+----------+

Let me know if you need some additional information.

cadeyrn picture cadeyrn on 10 Nov 2020

Thanks @cadeyrn very appreciated

tsteur picture tsteur on 10 Nov 2020

Hi @cadeyrn would you be able to run ./console core:archive -vvv and share the output?

diosmosis picture diosmosis on 11 Nov 2020

@tsteur that sounds like a possibility, debug logs would be helpful I think. I'll add the status = 0 check in a new PR.

diosmosis picture diosmosis on 11 Nov 2020

Hi @cadeyrn would you be able to run ./console core:archive -vvv and share the output?

INFO [2020-11-11 07:55:21] 4846  ---------------------------
INFO [2020-11-11 07:55:21] 4846  INIT
INFO [2020-11-11 07:55:21] 4846  Running Matomo 4.0.0-rc1 as Super User
INFO [2020-11-11 07:55:21] 4846  ---------------------------
INFO [2020-11-11 07:55:21] 4846  NOTES
INFO [2020-11-11 07:55:21] 4846  - Async process archiving not supported, using curl requests.
INFO [2020-11-11 07:55:21] 4846  - Reports for today will be processed at most every 3600 seconds. You can change this value in Matomo UI > Settings > General Settings.
INFO [2020-11-11 07:55:21] 4846  - Archiving was last executed without error 54 min 28s ago
INFO [2020-11-11 07:55:26] 4846  ---------------------------
INFO [2020-11-11 07:55:26] 4846  START
INFO [2020-11-11 07:55:26] 4846  Starting Matomo reports archiving...
INFO [2020-11-11 07:55:31] 4846  Start processing archives for site 3.
DEBUG [2020-11-11 07:55:31] 4846  Invalidations currently exist for idSite 3, skipping invalidating for now...
DEBUG [2020-11-11 07:55:31] 4846  No next invalidated archive.
INFO [2020-11-11 07:55:31] 4846  Finished archiving for site 3, 0 API requests, Time elapsed: 0.003s [1 / 8 done]
INFO [2020-11-11 07:55:36] 4846  Start processing archives for site 5.
DEBUG [2020-11-11 07:55:36] 4846  Checking for queued invalidations...
DEBUG [2020-11-11 07:55:36] 4846    Today archive can be skipped due to no visits for idSite = 5, skipping invalidation...
DEBUG [2020-11-11 07:55:36] 4846    Yesterday archive can be skipped due to no visits for idSite = 5, skipping invalidation...
DEBUG [2020-11-11 07:55:36] 4846  Done invalidating
DEBUG [2020-11-11 07:55:36] 4846  No next invalidated archive.
INFO [2020-11-11 07:55:36] 4846  Finished archiving for site 5, 0 API requests, Time elapsed: 0.035s [2 / 8 done]
INFO [2020-11-11 07:55:41] 4846  Start processing archives for site 7.
DEBUG [2020-11-11 07:55:41] 4846  Invalidations currently exist for idSite 7, skipping invalidating for now...
DEBUG [2020-11-11 07:55:41] 4846  No next invalidated archive.
INFO [2020-11-11 07:55:41] 4846  Finished archiving for site 7, 0 API requests, Time elapsed: 0.001s [3 / 8 done]
INFO [2020-11-11 07:55:46] 4846  Start processing archives for site 8.
DEBUG [2020-11-11 07:55:46] 4846  Invalidations currently exist for idSite 8, skipping invalidating for now...
DEBUG [2020-11-11 07:55:46] 4846  No next invalidated archive.
INFO [2020-11-11 07:55:46] 4846  Finished archiving for site 8, 0 API requests, Time elapsed: 0.002s [4 / 8 done]
INFO [2020-11-11 07:55:51] 4846  Start processing archives for site 11.
DEBUG [2020-11-11 07:55:51] 4846  Invalidations currently exist for idSite 11, skipping invalidating for now...
DEBUG [2020-11-11 07:55:51] 4846  No next invalidated archive.
INFO [2020-11-11 07:55:51] 4846  Finished archiving for site 11, 0 API requests, Time elapsed: 0.001s [5 / 8 done]
INFO [2020-11-11 07:55:56] 4846  Start processing archives for site 12.
DEBUG [2020-11-11 07:55:56] 4846  Invalidations currently exist for idSite 12, skipping invalidating for now...
DEBUG [2020-11-11 07:55:56] 4846  No next invalidated archive.
INFO [2020-11-11 07:55:56] 4846  Finished archiving for site 12, 0 API requests, Time elapsed: 0.001s [6 / 8 done]
INFO [2020-11-11 07:56:01] 4846  Start processing archives for site 13.
DEBUG [2020-11-11 07:56:01] 4846  Invalidations currently exist for idSite 13, skipping invalidating for now...
DEBUG [2020-11-11 07:56:01] 4846  No next invalidated archive.
INFO [2020-11-11 07:56:01] 4846  Finished archiving for site 13, 0 API requests, Time elapsed: 0.001s [7 / 8 done]
INFO [2020-11-11 07:56:06] 4846  Start processing archives for site 18.
DEBUG [2020-11-11 07:56:06] 4846  Checking for queued invalidations...
INFO [2020-11-11 07:56:06] 4846    Will invalidate archived reports for today in site ID = 18's timezone (2020-11-11 00:00:00).
INFO [2020-11-11 07:56:06] 4846  LOAD DATA INFILE failed... Error was: 
  Try #1: LOAD DATA INFILE : SQLSTATE[28000]: Invalid authorization specification: 1045 Access denied for user 'd02849e2'@'%' (using password: YES)[28000],
  Try #2: LOAD DATA LOCAL INFILE : SQLSTATE[42000]: Syntax error or access violation: 1148 The used command is not allowed with this MySQL version[42000]
INFO [2020-11-11 07:56:06] 4846  LOAD DATA INFILE failed... Error was: 
  Try #1: LOAD DATA INFILE : SQLSTATE[28000]: Invalid authorization specification: 1045 Access denied for user 'd02849e2'@'%' (using password: YES)[28000],
  Try #2: LOAD DATA LOCAL INFILE : SQLSTATE[42000]: Syntax error or access violation: 1148 The used command is not allowed with this MySQL version[42000]
DEBUG [2020-11-11 07:56:06] 4846    Found existing valid archive for yesterday, skipping invalidation...
DEBUG [2020-11-11 07:56:06] 4846  Done invalidating
DEBUG [2020-11-11 07:56:06] 4846  Processing invalidation: [idinvalidation = 34033, idsite = 18, period = day(2020-11-11 - 2020-11-11), name = done].
DEBUG [2020-11-11 07:56:06] 4846  Found archive with intersecting period with others in concurrent batch, skipping until next batch: [idinvalidation = 34034, idsite = 18, period = week(2020-11-09 - 2020-11-15), name = done]
DEBUG [2020-11-11 07:56:06] 4846  Found archive with intersecting period with others in concurrent batch, skipping until next batch: [idinvalidation = 34035, idsite = 18, period = month(2020-11-01 - 2020-11-30), name = done]
DEBUG [2020-11-11 07:56:06] 4846  Found archive with intersecting period with others in concurrent batch, skipping until next batch: [idinvalidation = 34036, idsite = 18, period = year(2020-01-01 - 2020-12-31), name = done]
DEBUG [2020-11-11 07:56:06] 4846  No next invalidated archive.
DEBUG [2020-11-11 07:56:06] 4846  Starting archiving for ?module=API&method=CoreAdminHome.archiveReports&idSite=18&period=day&date=2020-11-11&format=json&trigger=archivephp
DEBUG [2020-11-11 07:56:06] 4846  Execute HTTP API request: https://analytics.agenedia.com/?module=API&method=CoreAdminHome.archiveReports&idSite=18&period=day&date=2020-11-11&format=json&trigger=archivephp&
INFO [2020-11-11 07:56:07] 4846  Archived website id 18, period = day, date = 2020-11-11, segment = '', 68 visits found. Time elapsed: 0.953s
DEBUG [2020-11-11 07:56:07] 4846  Invalidations currently exist for idSite 18, skipping invalidating for now...
DEBUG [2020-11-11 07:56:07] 4846  Processing invalidation: [idinvalidation = 34034, idsite = 18, period = week(2020-11-09 - 2020-11-15), name = done].
DEBUG [2020-11-11 07:56:07] 4846  Found archive with intersecting period with others in concurrent batch, skipping until next batch: [idinvalidation = 34035, idsite = 18, period = month(2020-11-01 - 2020-11-30), name = done]
DEBUG [2020-11-11 07:56:07] 4846  Found archive with intersecting period with others in concurrent batch, skipping until next batch: [idinvalidation = 34036, idsite = 18, period = year(2020-01-01 - 2020-12-31), name = done]
DEBUG [2020-11-11 07:56:07] 4846  No next invalidated archive.
DEBUG [2020-11-11 07:56:07] 4846  Starting archiving for ?module=API&method=CoreAdminHome.archiveReports&idSite=18&period=week&date=2020-11-09&format=json&trigger=archivephp
DEBUG [2020-11-11 07:56:07] 4846  Execute HTTP API request: https://analytics.agenedia.com/?module=API&method=CoreAdminHome.archiveReports&idSite=18&period=week&date=2020-11-09&format=json&trigger=archivephp&
INFO [2020-11-11 07:56:07] 4846  Archived website id 18, period = week, date = 2020-11-09, segment = '', 950 visits found. Time elapsed: 0.618s
DEBUG [2020-11-11 07:56:07] 4846  Invalidations currently exist for idSite 18, skipping invalidating for now...
DEBUG [2020-11-11 07:56:07] 4846  Processing invalidation: [idinvalidation = 34035, idsite = 18, period = month(2020-11-01 - 2020-11-30), name = done].
DEBUG [2020-11-11 07:56:07] 4846  Found archive with intersecting period with others in concurrent batch, skipping until next batch: [idinvalidation = 34036, idsite = 18, period = year(2020-01-01 - 2020-12-31), name = done]
DEBUG [2020-11-11 07:56:07] 4846  No next invalidated archive.
DEBUG [2020-11-11 07:56:07] 4846  Starting archiving for ?module=API&method=CoreAdminHome.archiveReports&idSite=18&period=month&date=2020-11-01&format=json&trigger=archivephp
DEBUG [2020-11-11 07:56:07] 4846  Execute HTTP API request: https://analytics.agenedia.com/?module=API&method=CoreAdminHome.archiveReports&idSite=18&period=month&date=2020-11-01&format=json&trigger=archivephp&
INFO [2020-11-11 07:56:09] 4846  Archived website id 18, period = month, date = 2020-11-01, segment = '', 4931 visits found. Time elapsed: 1.413s
DEBUG [2020-11-11 07:56:09] 4846  Invalidations currently exist for idSite 18, skipping invalidating for now...
DEBUG [2020-11-11 07:56:09] 4846  Processing invalidation: [idinvalidation = 34036, idsite = 18, period = year(2020-01-01 - 2020-12-31), name = done].
DEBUG [2020-11-11 07:56:09] 4846  No next invalidated archive.
DEBUG [2020-11-11 07:56:09] 4846  Starting archiving for ?module=API&method=CoreAdminHome.archiveReports&idSite=18&period=year&date=2020-01-01&format=json&trigger=archivephp
DEBUG [2020-11-11 07:56:09] 4846  Execute HTTP API request: https://analytics.agenedia.com/?module=API&method=CoreAdminHome.archiveReports&idSite=18&period=year&date=2020-01-01&format=json&trigger=archivephp&
INFO [2020-11-11 07:56:11] 4846  Archived website id 18, period = year, date = 2020-01-01, segment = '', 163661 visits found. Time elapsed: 2.394s
DEBUG [2020-11-11 07:56:11] 4846  Checking for queued invalidations...
DEBUG [2020-11-11 07:56:11] 4846    Found existing valid archive for today, skipping invalidation...
DEBUG [2020-11-11 07:56:11] 4846    Found existing valid archive for yesterday, skipping invalidation...
DEBUG [2020-11-11 07:56:11] 4846  Done invalidating
DEBUG [2020-11-11 07:56:11] 4846  No next invalidated archive.
INFO [2020-11-11 07:56:11] 4846  Finished archiving for site 18, 4 API requests, Time elapsed: 5.513s [8 / 8 done]
DEBUG [2020-11-11 07:56:16] 4846  No more sites left to archive, stopping.
INFO [2020-11-11 07:56:16] 4846  Done archiving!
INFO [2020-11-11 07:56:16] 4846  ---------------------------
INFO [2020-11-11 07:56:16] 4846  SUMMARY
INFO [2020-11-11 07:56:16] 4846  Processed 4 archives.
INFO [2020-11-11 07:56:16] 4846  Total API requests: 4
INFO [2020-11-11 07:56:16] 4846  done: 4 req, 50016 ms, no error
INFO [2020-11-11 07:56:16] 4846  Time elapsed: 50.016s
INFO [2020-11-11 07:56:16] 4846  ---------------------------
INFO [2020-11-11 07:56:16] 4846  SCHEDULED TASKS
DEBUG [2020-11-11 07:56:16] 4846  26 scheduled tasks loaded
INFO [2020-11-11 07:56:16] 4846  Starting Scheduled tasks... 
DEBUG [2020-11-11 07:56:16] 4846  Executing tasks with priority 0:
DEBUG [2020-11-11 07:56:16] 4846  Executing tasks with priority 1:
DEBUG [2020-11-11 07:56:16] 4846  Executing tasks with priority 2:
DEBUG [2020-11-11 07:56:16] 4846  Executing tasks with priority 3:
DEBUG [2020-11-11 07:56:16] 4846  Executing tasks with priority 4:
DEBUG [2020-11-11 07:56:16] 4846  Executing tasks with priority 5:
DEBUG [2020-11-11 07:56:16] 4846  Executing tasks with priority 6:
DEBUG [2020-11-11 07:56:16] 4846  Task Piwik\Plugins\CustomJsTracker\Tasks.updateTracker is scheduled to run again for 2020-11-11.
INFO [2020-11-11 07:56:16] 4846  Scheduler: executing task Piwik\Plugins\CustomJsTracker\Tasks.updateTracker...
INFO [2020-11-11 07:56:16] 4846  Scheduler: finished. Time elapsed: 0.010s
DEBUG [2020-11-11 07:56:16] 4846  Task Piwik\Plugins\TagManager\Tasks.regenerateReleasedContainers is scheduled to run again for 2020-11-11.
INFO [2020-11-11 07:56:16] 4846  Scheduler: executing task Piwik\Plugins\TagManager\Tasks.regenerateReleasedContainers...
INFO [2020-11-11 07:56:16] 4846  Scheduler: finished. Time elapsed: 0.006s
DEBUG [2020-11-11 07:56:16] 4846  Executing tasks with priority 7:
DEBUG [2020-11-11 07:56:16] 4846  Executing tasks with priority 8:
DEBUG [2020-11-11 07:56:16] 4846  Executing tasks with priority 9:
DEBUG [2020-11-11 07:56:16] 4846  Task Piwik\Plugins\PrivacyManager\Tasks.deleteLogData is scheduled to run again for 2020-11-11.
INFO [2020-11-11 07:56:16] 4846  Scheduler: executing task Piwik\Plugins\PrivacyManager\Tasks.deleteLogData...
INFO [2020-11-11 07:56:16] 4846  Scheduler: finished. Time elapsed: 0.000s
DEBUG [2020-11-11 07:56:16] 4846  Task Piwik\Plugins\PrivacyManager\Tasks.anonymizePastData is scheduled to run again for 2020-11-11.
INFO [2020-11-11 07:56:16] 4846  Scheduler: executing task Piwik\Plugins\PrivacyManager\Tasks.anonymizePastData...
INFO [2020-11-11 07:56:16] 4846  Scheduler: finished. Time elapsed: 0.001s
DEBUG [2020-11-11 07:56:16] 4846  Executing tasks with priority 10:
DEBUG [2020-11-11 07:56:16] 4846  Executing tasks with priority 11:
DEBUG [2020-11-11 07:56:16] 4846  Executing tasks with priority 12:
INFO [2020-11-11 07:56:16] 4846  done
INFO [2020-11-11 07:56:16] 4846  ---------------------------
cadeyrn picture cadeyrn on 11 Nov 2020

fyi there's another report in https://github.com/matomo-org/matomo/issues/16703

@diosmosis might be good to also check if there could be any reason why it fails to remove the invalidation in the first place and why the status = 1 persists. Maybe it's all due to failed archives but maybe there could be also other reasons?

@PepijnBoers @cadeyrn @timscha any chance you maybe noticed some DB errors like "server gone away"? (you would likely only notice this if you have the full logs of archiving runs or so). If you don't know out of the box all good and feel free to ignore.

tsteur picture tsteur on 11 Nov 2020

Maybe it's all due to failed archives but maybe there could be also other reasons?

When I first noticed the issue I tried to manually execute the cron script and indeed I noticed an error in the archiving process. It was caused by the automatic update of the GeoLite2 city database. The URL (without an API key) was no longer working and caused an exception. I changed the URL after that. Maybe that error caused the failure?

any chance you maybe noticed some DB errors like "server gone away"? (you would likely only notice this if you have the full logs of archiving runs or so).

Unfortunately I don't know of such errors. I only noticed the LOAD DATA INFILE failed error in my log above.

cadeyrn picture cadeyrn on 11 Nov 2020

fyi We'll soon release RC3 which should resume the archiving again. We'll still need to check if we can further prevent this from happening in the first place

tsteur picture tsteur on 12 Nov 2020

@PepijnBoers @cadeyrn @timscha any chance you maybe noticed some DB errors like "server gone away"? (you would likely only notice this if you have the full logs of archiving runs or so). If you don't know out of the box all good and feel free to ignore.

No, MariaDB was fine. I'm using 10.5.7 at the moment.

@tsteur: Understand it correctly? RC3 should fixed it? I updated it a few minutes ago, had already some visitors, but no changes to the statistics and graphs.

timscha picture timscha on 12 Nov 2020

Understand it correctly? RC3 should fixed it? I updated it a few minutes ago

RC 3 is not yet released.

Okay, it has not yet arrived as update on my installation but I see RC 3 on the releases page.

edit: After the update to RC 3 arrived I can confirm what @timscha said: The issue is still present in RC 3.

cadeyrn picture cadeyrn on 12 Nov 2020
👍1

Bildschirmfoto 2020-11-12 um 09 11 07

Ehm, my Matomo installation said something different. :)

timscha picture timscha on 12 Nov 2020

\o chiming in from 4.0.0-RC3 because I just observed the same symptoms and can confirm the issue, maybe I can also help pinpoint the origin with some guidance.

Running core:archive -vvv also mentions that Invalidations currently exist for idSite X, skipping invalidating for now... and nothing happens afterwards for any site.

Also: 

MariaDB [matomo]> select `status`, count(*) from matomo_archive_invalidations group by `status`;
+--------+----------+
| status | count(*) |
+--------+----------+
|      1 |        3 |
+--------+----------+
1 row in set (0.001 sec)
evilham picture evilham on 16 Nov 2020

Thanks @evilham there should be already a workaround in the latest RC or we might release also another RC today (possible only this next one today includes a fix)

@diosmosis if you could today look if there might be any other reasons this might stay on "status= 1" that be great or whether there's maybe something we can do when this happens (when the archive fails) etc. I don't know the details of how it all works right now but be good to check if there might be edge cases where it can be maybe prevented or something. Otherwise I suppose we can close this issue if there's nothing else we can do

tsteur picture tsteur on 16 Nov 2020

Unfortunately also RC4 does not fixed it for me. :(

timscha picture timscha on 16 Nov 2020

Unfortunately also RC4 does not fixed it for me. :(

same here, the issue is still present.

cadeyrn picture cadeyrn on 16 Nov 2020

Any chance you could launch the archiver again? It might need a second run but would have expected this to be fixed directly.

@diosmosis there might be still some issue

tsteur picture tsteur on 16 Nov 2020

Any chance you could launch the archiver again?

I already did this when I wrote my previous comment and now I did it again, but still with no success. Is there anything else I could check?

cadeyrn picture cadeyrn on 16 Nov 2020

@cadeyrn can you check the result of this query: SELECT * FROM matomo_archive_invalidations WHERE idsite = 3 AND status = 1 LIMIT 50 and post the result? I'll try and reproduce w/ similar data. (Note: if archiving is working for idsite 3 then substitute for an idsite that isn't working, I got 3 from your log output above).

diosmosis picture diosmosis on 16 Nov 2020

Result:

Bildschirmfoto 2020-11-17 um 00 46 27

cadeyrn picture cadeyrn on 17 Nov 2020

@cadeyrn just the one? Interesting, I'll see what I can find, thanks!

diosmosis picture diosmosis on 17 Nov 2020

I see the issue, it's due to the previous entries still existing. We need to remove status = 1 AND ts_started IS NULL invalidation entries in an update.

@cadeyrn if you run this SQL it should unblock the archiving:

DELETE FROM matomo_archive_invalidations WHERE status = 1 AND ts_started IS NULL

cc @tsteur (will remove in an update)

diosmosis picture diosmosis on 17 Nov 2020
👍2

makes sense 馃憤

tsteur picture tsteur on 17 Nov 2020

I tried it as well. Result of:
SELECT * FROM matomo_archive_invalidations WHERE idsite = 3 AND status = 1 LIMIT 50;

+----------------+-----------+------+--------+------------+------------+--------+---------------------+--------+--------+------------+
| idinvalidation | idarchive | name | idsite | date1      | date2      | period | ts_invalidated      | status | report | ts_started |
+----------------+-----------+------+--------+------------+------------+--------+---------------------+--------+--------+------------+
|            884 |      2052 | done |      3 | 2020-01-01 | 2020-12-31 |      4 | 2020-10-17 21:05:02 |      1 | NULL   | NULL       |
|            883 |      8423 | done |      3 | 2020-10-01 | 2020-10-31 |      3 | 2020-10-17 21:05:02 |      1 | NULL   | NULL       |
|            882 |      8447 | done |      3 | 2020-10-12 | 2020-10-18 |      2 | 2020-10-17 21:05:02 |      1 | NULL   | NULL       |
|            881 |      NULL | done |      3 | 2020-10-17 | 2020-10-17 |      1 | 2020-10-17 21:05:02 |      1 | NULL   | NULL       |
+----------------+-----------+------+--------+------------+------------+--------+---------------------+--------+--------+------------+

I tried the Deleted Query as well, now the statistics and graphs are working again.
Thank you!

timscha picture timscha on 17 Nov 2020

works for me as well, thank you!

cadeyrn picture cadeyrn on 17 Nov 2020

@diosmosis had a look at the code and can't think of a way this might be triggered except for some archiving is stopped or some fails in a different way.

Thought it might possible this error happened because under circumstances the mapping of $index in $urls and $archivesBeingQueried in https://github.com/matomo-org/matomo/blob/4.0.0-rc4/core/CronArchive.php#L482-L485 might be out of order but this can't really be the case.

could move this line to the beginning of the method to delete invalidations first but it shouldn't make any difference https://github.com/matomo-org/matomo/blob/4.0.0-rc4/core/CronArchive.php#L503

so maybe we could close this issue unless you have some ideas why this might happen maybe even if the archiving succeeds.

tsteur picture tsteur on 18 Nov 2020

@tsteur no idea how this might happen if archiving succeeds, but we could put in an extra check after launchArchivingFor or at the end of it that does SELECT COUNT(*) FROM matomo_invalidations WHERE status = 1 and idinvalidation IN (...) looking for invalidations that weren't deleted or reset, and if so log an error. What do you think? We could also do this after archiving a site is done just to check that every invalidation we saw and dealt with isn't still status = 1.

diosmosis picture diosmosis on 18 Nov 2020

@diosmosis we could do this maybe just for 2 months or so to verify the logic works? Then I'd maybe rather remove the overhead maybe once we know it works. Like we could put this logic in a public method in cronArchive, and add a test to DeprecatedMethodsTest that we expect this method to be removed in say 1st March 2021. This would be a reminder to remove this logic again

tsteur picture tsteur on 18 Nov 2020

馃憤

diosmosis picture diosmosis on 18 Nov 2020

Can confirm that 4.0.0-rc5 fixes the issue without manual SQL queries ^^.

evilham picture evilham on 18 Nov 2020

Great, I will close this issue for now. Should there still be an issue please let us know. Thanks for your help everyone!

tsteur picture tsteur on 18 Nov 2020
Was this page helpful?
0 / 5 - 0 ratings

Related issues

mattab picture mattab  路  5Comments
mattab picture mattab  路  4Comments
mattab picture mattab  路  4Comments
r621549 picture r621549  路  4Comments
jangrewe picture jangrewe  路  4Comments