Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

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

Closed
PepijnBoers opened this issue Nov 10, 2020 · 33 comments
Closed
Assignees
Labels
Bug For errors / faults / flaws / inconsistencies etc. not-in-changelog For issues or pull requests that should not be included in our release changelog on matomo.org.
Milestone

Comments

@PepijnBoers
Copy link

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

@tsteur
Copy link
Member

tsteur commented Nov 10, 2020

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 #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 tsteur added the Bug For errors / faults / flaws / inconsistencies etc. label Nov 10, 2020
@tsteur tsteur added this to the 4.0.0-RC milestone Nov 10, 2020
@PepijnBoers
Copy link
Author

PepijnBoers commented Nov 10, 2020

mysql> select `status`, count(*) from matomo_archive_invalidations group by `status`;
+--------+----------+
| status | count(*) |
+--------+----------+
|      1 |        2 |
+--------+----------+
1 row in set (0.00 sec)

@tsteur
Copy link
Member

tsteur commented Nov 10, 2020

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

@cadeyrn
Copy link

cadeyrn commented Nov 10, 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.

@tsteur
Copy link
Member

tsteur commented Nov 10, 2020

Thanks @cadeyrn very appreciated

@diosmosis
Copy link
Member

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

@diosmosis
Copy link
Member

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

@cadeyrn
Copy link

cadeyrn commented Nov 11, 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  ---------------------------

@tsteur
Copy link
Member

tsteur commented Nov 11, 2020

fyi there's another report in #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.

@cadeyrn
Copy link

cadeyrn commented Nov 11, 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.

@tsteur
Copy link
Member

tsteur commented Nov 12, 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

@timscha
Copy link

timscha commented Nov 12, 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.

@cadeyrn
Copy link

cadeyrn commented Nov 12, 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.

@timscha
Copy link

timscha commented Nov 12, 2020

Bildschirmfoto 2020-11-12 um 09 11 07

Ehm, my Matomo installation said something different. :)

@evilham
Copy link

evilham commented Nov 16, 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)

@tsteur
Copy link
Member

tsteur commented Nov 16, 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

@timscha
Copy link

timscha commented Nov 16, 2020

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

@cadeyrn
Copy link

cadeyrn commented Nov 16, 2020

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

same here, the issue is still present.

@tsteur
Copy link
Member

tsteur commented Nov 16, 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

@cadeyrn
Copy link

cadeyrn commented Nov 16, 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?

@diosmosis
Copy link
Member

@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).

@cadeyrn
Copy link

cadeyrn commented Nov 16, 2020

Result:

Bildschirmfoto 2020-11-17 um 00 46 27

@diosmosis
Copy link
Member

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

@diosmosis
Copy link
Member

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)

@tsteur
Copy link
Member

tsteur commented Nov 17, 2020

makes sense 👍

@timscha
Copy link

timscha commented Nov 17, 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!

@cadeyrn
Copy link

cadeyrn commented Nov 17, 2020

works for me as well, thank you!

@tsteur
Copy link
Member

tsteur commented Nov 18, 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.

@diosmosis
Copy link
Member

@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.

@tsteur
Copy link
Member

tsteur commented Nov 18, 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

@diosmosis
Copy link
Member

👍

@evilham
Copy link

evilham commented Nov 18, 2020

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

@tsteur
Copy link
Member

tsteur commented Nov 18, 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 tsteur closed this as completed Nov 18, 2020
@mattab mattab added the not-in-changelog For issues or pull requests that should not be included in our release changelog on matomo.org. label Nov 23, 2020
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Bug For errors / faults / flaws / inconsistencies etc. not-in-changelog For issues or pull requests that should not be included in our release changelog on matomo.org.
Projects
None yet
Development

No branches or pull requests

7 participants