Not reporting data for timerange weeks but single days are working

[chgarling]

Hi there,

we are running Matomo 3.8.1 under Debian 8.11 with PHP-FPM (php-5.6.40) and experienced the following problem more than once:

Data is collected with a Matomo tracking URL as usual, the archive cronjobs runs every hour. Reports for single days are working fine, but if we select the complete week as timerange, the report is empty.

After invalidating and recalculating the broken timerange, everything is fine.

[tsteur]

Hard to say what is happening there. Have you made any config changes to your config/config.ini.php manually? Which ones?

[bab-mkedziora]

Hard to say what is happening there. Have you made any config changes to your config/config.ini.php manually? Which ones?

Below our config file.
`[database]
host = "XXXXX"
username = "XXXXX"
password = "XXXXX"
dbname = "XXXXX"
tables_prefix = "XXXXX"

[log]
log_only_when_cli = 1
logger_error[] = "file"
logger_exception[] = "file"
logger_message[] = "file"
logger_api_call[] = "file"
log_writers[] = "file"
log_level = WARN
logger_file_path = "/var/log/piwik/piwik.log"

[General]
enable_auto_update = 0
show_update_notification_to_superusers_only = 1
noreply_email_address = [email protected]
anonymous_user_enable_use_segments_API = 0
default_language = "de"
session_save_handler = "dbtable"
login_cookie_expire = 7200
datatable_archiving_maximum_rows_custom_variables = 5000
datatable_archiving_maximum_rows_subtable_custom_variables = 5000
datatable_archiving_maximum_rows_actions = 50000
datatable_archiving_maximum_rows_subtable_actions = 50000
datatable_archiving_maximum_rows_events = 5000
assume_secure_protocol = 1
datatable_archiving_maximum_rows_referers = 5000
datatable_archiving_maximum_rows_subtable_referers = 5000
force_ssl_login = 1
force_ssl = 1
cookie_expire = 7200
proxy_client_headers[] = "HTTP_X_FORWARDED_FOR"
proxy_ips[] = "127.0.0.1"
proxy_ips[] = "192.168.x.x/24"
salt = "xxxxxxxxxxxxx"
trusted_hosts[] = "xxxxxxxxxx"
trusted_hosts[] = "xxxxxxxxx"
trusted_hosts[] = "localhost"
trusted_hosts[] = "xxxxxxxxxx"

[Tracker]
cookie_name = "xxxxxxxx"
scheduled_tasks_min_interval = 1800
ip_address_mask_length = 2
ip_address_pre_mask_length = 0

[mail]
username = ""
password = ""

[Plugins]
Plugins[] = "CorePluginsAdmin"
Plugins[] = "CoreAdminHome"
Plugins[] = "CoreHome"
Plugins[] = "WebsiteMeasurable"
Plugins[] = "Diagnostics"
Plugins[] = "CoreVisualizations"
Plugins[] = "Proxy"
Plugins[] = "API"
Plugins[] = "Widgetize"
Plugins[] = "Transitions"
Plugins[] = "LanguagesManager"
Plugins[] = "Actions"
Plugins[] = "Dashboard"
Plugins[] = "MultiSites"
Plugins[] = "Referrers"
Plugins[] = "UserLanguage"
Plugins[] = "DevicesDetection"
Plugins[] = "Goals"
Plugins[] = "Ecommerce"
Plugins[] = "SEO"
Plugins[] = "Events"
Plugins[] = "UserCountry"
Plugins[] = "VisitsSummary"
Plugins[] = "VisitFrequency"
Plugins[] = "VisitTime"
Plugins[] = "VisitorInterest"
Plugins[] = "Monolog"
Plugins[] = "Login"
Plugins[] = "UsersManager"
Plugins[] = "SitesManager"
Plugins[] = "Installation"
Plugins[] = "CoreUpdater"
Plugins[] = "CoreConsole"
Plugins[] = "ScheduledReports"
Plugins[] = "UserCountryMap"
Plugins[] = "Live"
Plugins[] = "CustomVariables"
Plugins[] = "PrivacyManager"
Plugins[] = "ImageGraph"
Plugins[] = "Annotations"
Plugins[] = "MobileMessaging"
Plugins[] = "Overlay"
Plugins[] = "SegmentEditor"
Plugins[] = "Morpheus"
Plugins[] = "Contents"
Plugins[] = "BulkTracking"
Plugins[] = "Resolution"
Plugins[] = "DevicePlugins"
Plugins[] = "Heartbeat"
Plugins[] = "Intl"
Plugins[] = "Marketplace"
Plugins[] = "ProfessionalServices"
Plugins[] = "UserId"
Plugins[] = "CustomPiwikJs"
Plugins[] = "DBStats"
Plugins[] = "MobileAppMeasurable"
Plugins[] = "SecurityInfo"
Plugins[] = "HeatmapSessionRecording"
Plugins[] = "CustomReports"
Plugins[] = "SearchEngineKeywordsPerformance"
Plugins[] = "AbTesting"
Plugins[] = "WhiteLabel"
Plugins[] = "MediaAnalytics"
Plugins[] = "ActivityLog"
Plugins[] = "FormAnalytics"
Plugins[] = "RollUpReporting"
Plugins[] = "UsersFlow"
Plugins[] = "MultiChannelConversionAttribution"
Plugins[] = "Funnels"
Plugins[] = "LoginSaml"
Plugins[] = "WooCommerceAnalytics"

[PluginsInstalled]
PluginsInstalled[] = "Login"
PluginsInstalled[] = "CoreAdminHome"
PluginsInstalled[] = "UsersManager"
PluginsInstalled[] = "SitesManager"
PluginsInstalled[] = "Installation"
PluginsInstalled[] = "CorePluginsAdmin"
PluginsInstalled[] = "CoreHome"
PluginsInstalled[] = "CoreVisualizations"
PluginsInstalled[] = "Proxy"
PluginsInstalled[] = "API"
PluginsInstalled[] = "ExamplePlugin"
PluginsInstalled[] = "Widgetize"
PluginsInstalled[] = "Transitions"
PluginsInstalled[] = "LanguagesManager"
PluginsInstalled[] = "Actions"
PluginsInstalled[] = "Dashboard"
PluginsInstalled[] = "MultiSites"
PluginsInstalled[] = "Referrers"
PluginsInstalled[] = "DevicesDetection"
PluginsInstalled[] = "Goals"
PluginsInstalled[] = "SEO"
PluginsInstalled[] = "Events"
PluginsInstalled[] = "UserCountry"
PluginsInstalled[] = "VisitsSummary"
PluginsInstalled[] = "VisitFrequency"
PluginsInstalled[] = "VisitTime"
PluginsInstalled[] = "VisitorInterest"
PluginsInstalled[] = "ExampleAPI"
PluginsInstalled[] = "Provider"
PluginsInstalled[] = "Feedback"
PluginsInstalled[] = "CoreUpdater"
PluginsInstalled[] = "CoreConsole"
PluginsInstalled[] = "ScheduledReports"
PluginsInstalled[] = "UserCountryMap"
PluginsInstalled[] = "Live"
PluginsInstalled[] = "CustomVariables"
PluginsInstalled[] = "PrivacyManager"
PluginsInstalled[] = "ImageGraph"
PluginsInstalled[] = "Annotations"
PluginsInstalled[] = "MobileMessaging"
PluginsInstalled[] = "Overlay"
PluginsInstalled[] = "SegmentEditor"
PluginsInstalled[] = "Insights"
PluginsInstalled[] = "Morpheus"
PluginsInstalled[] = "Contents"
PluginsInstalled[] = "DBStats"
PluginsInstalled[] = "BulkTracking"
PluginsInstalled[] = "Resolution"
PluginsInstalled[] = "DevicePlugins"
PluginsInstalled[] = "Ecommerce"
PluginsInstalled[] = "UserLanguage"
PluginsInstalled[] = "Monolog"
PluginsInstalled[] = "WebsiteMeasurable"
PluginsInstalled[] = "Diagnostics"
PluginsInstalled[] = "Intl"
PluginsInstalled[] = "MobileAppMeasurable"
PluginsInstalled[] = "Heartbeat"
PluginsInstalled[] = "UserId"
PluginsInstalled[] = "ProfessionalServices"
PluginsInstalled[] = "CustomPiwikJs"
PluginsInstalled[] = "Marketplace"
PluginsInstalled[] = "SecurityInfo"
PluginsInstalled[] = "HeatmapSessionRecording"
PluginsInstalled[] = "CustomReports"
PluginsInstalled[] = "SearchEngineKeywordsPerformance"
PluginsInstalled[] = "AbTesting"
PluginsInstalled[] = "WhiteLabel"
PluginsInstalled[] = "MediaAnalytics"
PluginsInstalled[] = "ActivityLog"
PluginsInstalled[] = "FormAnalytics"
PluginsInstalled[] = "RollUpReporting"
PluginsInstalled[] = "UsersFlow"
PluginsInstalled[] = "MultiChannelConversionAttribution"
PluginsInstalled[] = "Funnels"
PluginsInstalled[] = "LoginSaml"
PluginsInstalled[] = "WooCommerceAnalytics"

[HeatmapSessionRecording]
add_tracking_code_only_when_needed = 1
session_recording_sample_limits = "50,100,250,500,1000,2000,5000"

[CustomReports]
datatable_archiving_maximum_rows_custom_reports = 500
datatable_archiving_maximum_rows_subtable_custom_reports = 500
custom_reports_validate_report_content_all_websites = 1
custom_reports_always_show_unique_visitors = 0

[MediaAnalytics]
media_analytics_exclude_query_parameters = "enablejsapi,player_id"
datatable_archiving_maximum_rows_media = 1000
datatable_archiving_maximum_rows_subtable_media = 1000

[UsersFlow]
UsersFlow_num_max_steps = 10
UsersFlow_num_max_rows_in_actions = 100
UsersFlow_num_max_links_per_interaction = 5000

[MultiChannelConversionAttribution]
default_day_prior_to_conversion = 30
available_days_prior_to_conversion = "7,30,60,90"

[Funnels]
funnels_num_max_rows_in_actions = 100
funnels_num_max_rows_in_referrers = 50
funnels_num_max_rows_populate_at_once = 60000
`

Do you see something weird?

Best Regards

[tsteur]

Can't find anything suspicious here. Do you maybe see any information in the php error/webserver logs or maybe you even write the archive cron output to a log file and something is in there?

Eg be interesting to see if the archiving job maybe fails sometimes randomly with some memory error or so. I would recommend to write the output of the archiving to a log file like this:

* * * * ... console core:archive .. >> log file 2>&1

[daylicron]

@tsteur
We're running ,,multithreaded archiving" via:
for ((n=0;n<6;n++)); do (${PHP_BIN} ${ARCHIVE_BIN} ${ARCHIVE_OPTS} >> ${LOG_FILE} 2>&1 &); done

Two Logs of 27.02.2019, when this error occured again, contain the following messages:
WARNING [2019-02-27 13:00:01] 20269  Matomo_Path/core/Filesystem.php(425): Warning - filesize(): stat failed for Matomo_Path/tmp/climulti/archive.sharedsiteids.pid - Matomo 3.8.1 - Please report this message in the Matomo forums: https://forum.matomo.org (please do a search first as it might have been reported already)
[...]
Error: error or warning logs detected, exit 1

INFO [2019-02-27 22:00:02] 7381  Starting Matomo reports archiving...
WARNING [2019-02-27 22:00:02] 7385  Matomo_Path/core/Filesystem.php(425): Warning - filesize(): stat failed for Matomo_Path/tmp/climulti/archive.sharedsiteids.pid - Matomo 3.8.1 - Please report this message in the Matomo forums: https://forum.matomo.org (please do a search first as it might have been reported already)
[...]
Error: error or warning logs detected, exit 1

The ownership and directory permission are correct:

ls -alh matomo_path/tmp/
total 416K
drwxr-xr-x  10 www-data www-data 4.0K Jan 31 09:13 .
drwxr-x---  12 www-data www-data 4.0K Feb  7 16:40 ..
drwxr-x---   2 www-data www-data 4.0K Mar  5 15:01 assets
drwxr-x---   3 www-data www-data 4.0K Jan 30 14:30 cache
drwxr-x---   2 www-data www-data 4.0K Mar  5 15:01 climulti
-rw-r--r--   1 www-data www-data  545 Jan 30 14:24 .htaccess
-rw-r--r--   1 www-data www-data   20 Mar  5 15:01 index.htm
-rw-r--r--   1 www-data www-data   20 Mar  5 15:01 index.php
drwxr-x---   3 www-data www-data 4.0K Feb 20 12:25 latest
drwxr-x---   2 www-data www-data 4.0K Jan 30 14:30 logs
drwxr-x---   2 www-data www-data 4.0K Jan 31 09:13 sessions
drwxr-x---   2 www-data www-data 368K Mar  4 01:11 tcpdf
drwxr-x--- 110 www-data www-data 4.0K Mar  5 10:18 templates_c

ls -alh matomo_path/tmp/climulti/
total 16K
drwxr-x---  2 www-data www-data 4.0K Mar  5 15:01 .
drwxr-xr-x 10 www-data www-data 4.0K Jan 31 09:13 ..
-rw-r--r--  1 www-data www-data   20 Mar  5 15:01 index.htm
-rw-r--r--  1 www-data www-data   20 Mar  5 15:01 index.php

Neither the webserver or php error logs contain any error messages on that day.

Those messages occured in https://forum.matomo.org/t/archive-problem-after-upgrade/11738/13 too, but have never been resolved.

[tsteur]

for ((n=0;n<6;n++)); do (${PHP_BIN} ${ARCHIVE_BIN} ${ARCHIVE_OPTS} >> ${LOG_FILE} 2>&1 &); done
can you maybe at a sleep n before executing each archive to start them each with a slight delay? possible it runs into some random race conditions starting them all the very same time

[daylicron]

can you maybe at a sleep n before executing each archive to start them each with a slight delay?

Sure, we'll try this. I added sleep 1

[tsteur]

You may need to use something like sleep $n depending how it is executed. Not sure but if it does in the end like sleep 1 &then they will be executed again all at the same time but 1s delayed

[daylicron]

I changed it to:

for ((n=0;n<<%= @number_workers %>;n++)); do (${PHP_BIN} ${ARCHIVE_BIN} ${ARCHIVE_OPTS} >> ${LOG_FILE} 2>&1 &); sleep 1; done

According to the log it seems that this is working correctly:

INFO [2019-03-08 08:00:02] 21742  INIT
INFO [2019-03-08 08:00:02] 21742  Running Matomo 3.8.1 as Super User
[...]
INFO [2019-03-08 08:00:03] 21833  INIT
INFO [2019-03-08 08:00:03] 21833  Running Matomo 3.8.1 as Super User
[...]
INFO [2019-03-08 08:00:04] 21956  INIT
INFO [2019-03-08 08:00:04] 21956  Running Matomo 3.8.1 as Super User
[...]
INFO [2019-03-08 08:00:05] 22033  INIT
INFO [2019-03-08 08:00:05] 22033  Running Matomo 3.8.1 as Super User
[...]

Every job ist starting 1 second delayed.
Before it was like this:

INFO [2019-02-26 08:00:01] 9635  INIT
INFO [2019-02-26 08:00:01] 9635  Running Matomo 3.8.1 as Super User
[...]
INFO [2019-02-26 08:00:01] 9633  INIT
INFO [2019-02-26 08:00:01] 9633  Running Matomo 3.8.1 as Super User
[...]
INFO [2019-02-26 08:00:01] 9627  INIT
INFO [2019-02-26 08:00:01] 9627  Running Matomo 3.8.1 as Super User
[...]
INFO [2019-02-26 08:00:01] 9638  INIT
INFO [2019-02-26 08:00:01] 9638  Running Matomo 3.8.1 as Super User
[...]

4 jobs in 1 second.

Not sure but if it does in the end like sleep 1 &then they will be executed again all at the same time but 1s delayed

If I understand this correctly then this is exactly what I've done. In addition I assume you're saying that there should only be 1 archiving process at a time? We had this before: The problem is that we're running some Matomo instances where the archive process takes with only one process like 8 hours.

Then I found your comment and used this.

[tsteur]

In addition I assume you're saying that there should only be 1 archiving process at a time

It's fine to have multiple at a time, I would just start them with a little delay (the sleep) to avoid any race conditions.

[daylicron]

This issue occured again on 08.03.2019 and 10.03.2019. On both days the same and only siteid was affected. A very interesting thing is: the archive process is running every hour between 1 am and 23 pm. The delay between the archive processes does not apply to the run at 1 am but to every other archive process running during a day. I'd really like to know why this happens.

As a very first guess I assume it's because of UTC 0 am. So I edited my cron file so that the first archive run a day runs at 2 am. In addition I increased the sleep 1 to sleep 5.

I'll check tomorrow if the delay is applied during the first archive run.

[tsteur]

Cheers for letting us know and giving it a try 👍

[daylicron]

A new update:
Running the first archive process at 2 am helped a little bit. Only 2 archive processes were started at the same time. I checked if there is any other cronjob or something, but I couldn't find anything. Checking the logs from the last days, the delay is only working properly after 3 am. I don't have any clue why. That's why I changed the starting time to 3 am. In addition I changed the command to:
for ((n=0;n<<%= @number_workers %>;n++)); do sleep 2; (${PHP_BIN} ${ARCHIVE_BIN} ${ARCHIVE_OPTS} >> ${LOG_FILE} 2>&1 &); sleep 2; done

The main problem occured again yesterday. The same and only siteid as mentioned in my comment before was affected. That's why I would rather see this issue around this siteid and not with the multithreading. I just have no idea how to debug the problem regarding the siteid.

I already checked the MySQL max connections. 300 are set and only 24 have been used so far.

[daylicron]

SiteNote:
We faced another Problem. We had to invalidate several days this month and reporcess them. Our customer then noticed the following for the affected site:

• Timeperiod 04.03.2019-10.03.2019: 217.593 Visitors
• Timeperiod 04.03.2019-9.03.2019 (1 day less!): 256.218 Visitors

During this month we switched from https://matomo.org/faq/how-to/faq_73/

DELETE FROM matomo_archive_numeric_Y, matomo_archive_blob_Y WHERE idsite = X;
/console core:archive --force-idsites=X --force-all-periods=315576000 --force-date-last-n=1000 --url='matomo_url'

to https://matomo.org/faq/how-to/faq_155/

console core:invalidate-report-data --dates=2012-01-01,2011-10-15 --sites=1,3,5
then waiting for auto archive

I assume there are some problems with core:invalidate-report-data and/or waiting for auto archive run as documented. That's why I used the previous way, deleting data from the whole month and run manual archive. We'll see if this changes anything.

[tsteur]

Thanks for letting us know again 👍 curious to see the results

[daylicron]

Here I'm back again, providing my results:
My idea in my previos comment didn't work out unfortunately. One day after the clean reprocessed start, we faced our issue again.

After that only one idea was left: switching back to single threaded archiving. And well, the issue has not been occuring anymore since that day (14.03.2019).

In addition, using the multithreading we noticed something else. The weekly report scheduled in Matomo is send multiple times.
(Keep in mind that this log time is UTC)

INFO [2019-03-26 00:43:44] 24534  - pre-processing all visits
INFO [2019-03-26 00:44:30] 26245  Deleted 51415 rows in archive tables (numeric + blob) for 2019-03-15.
INFO [2019-03-26 00:44:30] 25441  Deleted 100694 rows in archive tables (numeric + blob) for 2019-03-15.
INFO [2019-03-26 00:44:30] 24159  Deleted 97719 rows in archive tables (numeric + blob) for 2019-03-15.
INFO [2019-03-26 00:44:30] 24975  Deleted 198960 rows in archive tables (numeric + blob) for 2019-03-15.
INFO [2019-03-26 00:44:30] 26245  Scheduler: finished. Time elapsed: 232.267s
INFO [2019-03-26 00:44:30] 26245  Scheduler: executing task Piwik\Plugins\Login\Tasks.cleanupBruteForceLogs...
INFO [2019-03-26 00:44:30] 26245  Scheduler: finished. Time elapsed: 0.001s
INFO [2019-03-26 00:44:30] 26245  Scheduler: executing task Piwik\Plugins\UsersManager\Tasks.setUserDefaultReportPreference...
INFO [2019-03-26 00:44:30] 24159  Scheduler: finished. Time elapsed: 227.000s
INFO [2019-03-26 00:44:30] 25441  Scheduler: finished. Time elapsed: 226.099s
INFO [2019-03-26 00:44:30] 24975  Scheduler: finished. Time elapsed: 225.662s
INFO [2019-03-26 00:44:30] 26245  Scheduler: finished. Time elapsed: 0.008s
INFO [2019-03-26 00:44:30] 24159  Scheduler: executing task Piwik\Plugins\Login\Tasks.cleanupBruteForceLogs...
INFO [2019-03-26 00:44:30] 24159  Scheduler: finished. Time elapsed: 0.016s
INFO [2019-03-26 00:44:30] 26245  Scheduler: executing task Piwik\Plugins\ScheduledReports\API.sendReport_8...
INFO [2019-03-26 00:44:30] 24975  Scheduler: executing task Piwik\Plugins\Login\Tasks.cleanupBruteForceLogs...
INFO [2019-03-26 00:44:30] 25441  Scheduler: executing task Piwik\Plugins\Login\Tasks.cleanupBruteForceLogs...
INFO [2019-03-26 00:44:30] 24975  Scheduler: finished. Time elapsed: 0.002s
INFO [2019-03-26 00:44:30] 24159  Scheduler: executing task Piwik\Plugins\UsersManager\Tasks.setUserDefaultReportPreference...
INFO [2019-03-26 00:44:30] 24975  Scheduler: executing task Piwik\Plugins\UsersManager\Tasks.setUserDefaultReportPreference...
INFO [2019-03-26 00:44:30] 25441  Scheduler: finished. Time elapsed: 0.003s
INFO [2019-03-26 00:44:30] 25441  Scheduler: executing task Piwik\Plugins\UsersManager\Tasks.setUserDefaultReportPreference...
INFO [2019-03-26 00:44:30] 24975  Scheduler: finished. Time elapsed: 0.011s
INFO [2019-03-26 00:44:30] 24975  Scheduler: executing task Piwik\Plugins\ScheduledReports\API.sendReport_8...
INFO [2019-03-26 00:44:30] 24159  Scheduler: finished. Time elapsed: 0.014s
INFO [2019-03-26 00:44:30] 24159  Scheduler: executing task Piwik\Plugins\ScheduledReports\API.sendReport_8...
INFO [2019-03-26 00:44:30] 25441  Scheduler: finished. Time elapsed: 0.012s
INFO [2019-03-26 00:44:30] 25441  Scheduler: executing task Piwik\Plugins\ScheduledReports\API.sendReport_8...
sendmail: warning: inet_protocols: disabling IPv6 name/address support: Address family not supported by protocol
sendmail: warning: inet_protocols: disabling IPv6 name/address support: Address family not supported by protocol
postdrop: warning: inet_protocols: disabling IPv6 name/address support: Address family not supported by protocol
postdrop: warning: inet_protocols: disabling IPv6 name/address support: Address family not supported by protocol
sendmail: warning: inet_protocols: disabling IPv6 name/address support: Address family not supported by protocol
postdrop: warning: inet_protocols: disabling IPv6 name/address support: Address family not supported by protocol
INFO [2019-03-26 00:44:30] 26245  Scheduler: finished. Time elapsed: 0.364s
INFO [2019-03-26 00:44:30] 24159  Scheduler: finished. Time elapsed: 0.355s
INFO [2019-03-26 00:44:30] 26245  Scheduler: executing task Piwik\Plugins\CustomPiwikJs\Tasks.updateTracker...
INFO [2019-03-26 00:44:30] 24159  Scheduler: executing task Piwik\Plugins\CustomPiwikJs\Tasks.updateTracker...
INFO [2019-03-26 00:44:30] 26245  Scheduler: finished. Time elapsed: 0.004s
INFO [2019-03-26 00:44:30] 24159  Scheduler: finished. Time elapsed: 0.003s
INFO [2019-03-26 00:44:30] 26245  Scheduler: executing task Piwik\Plugins\CoreAdminHome\Tasks.purgeInvalidatedArchives...
INFO [2019-03-26 00:44:30] 24159  Scheduler: executing task Piwik\Plugins\CoreAdminHome\Tasks.purgeInvalidatedArchives...
INFO [2019-03-26 00:44:30] 24975  Scheduler: finished. Time elapsed: 0.365s
sendmail: warning: inet_protocols: disabling IPv6 name/address support: Address family not supported by protocol
INFO [2019-03-26 00:44:30] 24975  Scheduler: executing task Piwik\Plugins\CustomPiwikJs\Tasks.updateTracker...
postdrop: warning: inet_protocols: disabling IPv6 name/address support: Address family not supported by protocol
INFO [2019-03-26 00:44:30] 24975  Scheduler: finished. Time elapsed: 0.004s
INFO [2019-03-26 00:44:30] 24975  Scheduler: executing task Piwik\Plugins\CoreAdminHome\Tasks.purgeInvalidatedArchives...
INFO [2019-03-26 00:44:30] 25441  Scheduler: finished. Time elapsed: 0.399s
INFO [2019-03-26 00:44:30] 25441  Scheduler: executing task Piwik\Plugins\CustomPiwikJs\Tasks.updateTracker...
INFO [2019-03-26 00:44:30] 25441  Scheduler: finished. Time elapsed: 0.004s
INFO [2019-03-26 00:44:30] 25441  Scheduler: executing task Piwik\Plugins\CoreAdminHome\Tasks.purgeInvalidatedArchives...
INFO [2019-03-26 00:44:33] 24534  Archived website id = 3, period = week, 0 segments, 47952656 visits in last 98 weeks, 185098 visits this week, Time elapsed: 49.049s
INFO [2019-03-26 00:44:33] 24534  - skipping archiving for period 'month' because processing the period 'week' is already in progress.
INFO [2019-03-26 00:44:33] 24534  Archived website id = 3, 2 API requests, Time elapsed: 243.376s [183/183 done]
INFO [2019-03-26 00:44:33] 24534  Done archiving!
INFO [2019-03-26 00:44:33] 24534  ---------------------------
INFO [2019-03-26 00:44:33] 24534  SUMMARY
INFO [2019-03-26 00:44:33] 24534  Total visits for today across archived websites: 15257
INFO [2019-03-26 00:44:33] 24534  Archived today's reports for 31 websites
INFO [2019-03-26 00:44:33] 24534  Archived week/month/year for 31 websites
INFO [2019-03-26 00:44:33] 24534  Skipped 153 websites
INFO [2019-03-26 00:44:33] 24534  - 10 skipped because no new visit since the last script execution
INFO [2019-03-26 00:44:33] 24534  - 0 skipped because existing daily reports are less than 3600 seconds old
INFO [2019-03-26 00:44:33] 24534  - 0 skipped because existing week/month/year periods reports are less than 3600 seconds old
INFO [2019-03-26 00:44:33] 24534  Total API requests: 122
INFO [2019-03-26 00:44:33] 24534  done: 31/183 17%, 15257 vtoday, 31 wtoday, 31 wperiods, 122 req, 859227 ms, no error
INFO [2019-03-26 00:44:33] 24534  Time elapsed: 859.227s
INFO [2019-03-26 00:44:33] 24534  ---------------------------
INFO [2019-03-26 00:44:33] 24534  SCHEDULED TASKS
INFO [2019-03-26 00:44:33] 24534  Starting Scheduled tasks... 
INFO [2019-03-26 00:44:33] 24534  Scheduler: executing task Piwik\Plugins\CoreAdminHome\Tasks.purgeOutdatedArchives...
INFO [2019-03-26 00:44:33] 24534  Purging archives in 266 archive tables.
INFO [2019-03-26 00:44:34] 24534  Scheduler: finished. Time elapsed: 0.593s
INFO [2019-03-26 00:44:34] 24534  Scheduler: executing task Piwik\Plugins\Login\Tasks.cleanupBruteForceLogs...
INFO [2019-03-26 00:44:34] 24534  Scheduler: finished. Time elapsed: 0.001s
INFO [2019-03-26 00:44:34] 24534  Scheduler: executing task Piwik\Plugins\UsersManager\Tasks.setUserDefaultReportPreference...
INFO [2019-03-26 00:44:34] 24534  Scheduler: finished. Time elapsed: 0.007s
INFO [2019-03-26 00:44:34] 24534  Scheduler: executing task Piwik\Plugins\ScheduledReports\API.sendReport_8...
WARNING [2019-03-26 00:44:34] 24534  Preventing the same scheduled report from being sent again (report #8 for period "Monday, 25. März 2019")
INFO [2019-03-26 00:44:34] 24534  Scheduler: finished. Time elapsed: 0.211s
INFO [2019-03-26 00:44:34] 24534  Scheduler: executing task Piwik\Plugins\CustomPiwikJs\Tasks.updateTracker...
INFO [2019-03-26 00:44:34] 24534  Scheduler: finished. Time elapsed: 0.003s

I received four e-mails this night at 01:44:30 am. As you can see in the log output I provided above

INFO [2019-03-26 00:44:30] 26245  Scheduler: executing task Piwik\Plugins\UsersManager\Tasks.setUserDefaultReportPreference...
INFO [2019-03-26 00:44:30] 24159  Scheduler: finished. Time elapsed: 227.000s
INFO [2019-03-26 00:44:30] 25441  Scheduler: finished. Time elapsed: 226.099s
INFO [2019-03-26 00:44:30] 24975  Scheduler: finished. Time elapsed: 225.662s
INFO [2019-03-26 00:44:30] 26245  Scheduler: finished. Time elapsed: 0.008s

There are four jobs finishing at 01:44:30 am, although I don't really get the time elapsed there.

Later on, matomot tries to prevent another report to be sent:

INFO [2019-03-26 00:44:34] 24534  Scheduler: executing task Piwik\Plugins\UsersManager\Tasks.setUserDefaultReportPreference...
INFO [2019-03-26 00:44:34] 24534  Scheduler: finished. Time elapsed: 0.007s
INFO [2019-03-26 00:44:34] 24534  Scheduler: executing task Piwik\Plugins\ScheduledReports\API.sendReport_8...
WARNING [2019-03-26 00:44:34] 24534  Preventing the same scheduled report from being sent again (report #8 for period "Monday, 25. März 2019")

I really would like to get this multithreading issue fixed, as it's a huge speedup for archiving lots of websites.

[tsteur]

Hi there, sorry to get back to you so late. What happens if you start the archivers with a delay of one minute? Of course it's not best solution and doesn't fix the actual issue, just curious if it works.
Do you know if it always runs the scheduled tasks at the same time / whether you always receive the report multiple times?

[Littlericket]

Hi @tsteur, actually we are facing the exact same issue. We have archiving on, every */15 minutes. No race conditions, archiving is done in about 2 minutes. Unfortunatly I have to mask the values.

INFO [2019-04-26 12:45:27] 31619 Archived website id = 1, period = day, 0 segments, 62676 visits in last 2 days, 20969 visits today, Time elapsed: 22.870s

[tsteur]

@Littlericket can you confirm it basically never happens that two archivers run at the same time? Does any data appear for week when you don't search? Are there more than 500 different page urls recorded (you would see this in the pagination when you don't search like "1-10 of 500")?

[Littlericket]

Hi @tsteur, thanks for you reply. Yes I can confirm that there is never a chance running two archivers at the same time. We have a lock if one is running and check if the lock is present before starting another one.

There's data for the week, but we're not having more than 500 urls recorded. We're at 208 for the given week. I haven't read that theres a minimum of URLs needed for archiving in this ticket here tho...

[daylicron]

Sorry for replying late, I've been quite busy.

What's working for us is running a script every hour, that starts one archiving process which runs across every website. In the very beginning we used a lockfile too, but removed when we heard about the multi processing. This results in all customers but one finsh in one hour, meaning there is never a second archive process running in parallel. The archiving for the mentioned customer can take longer then one hour, so there is a chance that a second archive process is running in parallel. But we never faced the previous issue anymore since we rolled back to single archive processing.

So, regarding the specific customer, having a second process running in parallel which is started with a delay of one hour and occuring only 3-4 times a day is working fine.

[tsteur]

@mattab or @diosmosis do any of you have an idea how this could happen?

Not quite sure how this happens.

@daylicron @Littlericket @chgarling do any of you know if you have configured

• any custom settings in config/config.ini.php
• or configured any "aggregated report data" or "old raw data" deletion in "Admin => Privacy => Anonymize Data"?

[daylicron]

@tsteur

@daylicron @Littlericket @chgarling do any of you know if you have configured
any custom settings in config/config.ini.php

The config.php from us (daylicron, chgarling) has been provided in in the comment by bab-mkedziora.

or configured any "aggregated report data" or "old raw data" deletion in "Admin => Privacy => Anonymize Data"?

Yes indeed, we configured deletion of raw data after 180 days. We don't delete old reports. This matomo instance was affected very often by this issue, meaning sometimes every day.

I have to add, that I know of to other matomo instances where we don't delete the raw data but which were affected by the same issue too. The issue occured there only 1 to 2 times. Since we rolled back to single threaded archiving, the issue hasn't occured there anymore.

I would consider this something to start at. I'm curious what @Littlericket is going to report.

[Littlericket]

@tsteur

@daylicron @Littlericket @chgarling do any of you know if you have configured

• any custom settings in config/config.ini.php
• or configured any "aggregated report data" or "old raw data" deletion in "Admin => Privacy => Anonymize Data"?

We don't have any custom settings except a proxy and another cors domain but we have "old raw data" deletion set to 90 Days. Old aggregated report data deletion is disabled.

[mattab]

Maybe related to #14379 although this is probably a different issue?

[Littlericket]

@mattab thanks for the reply.

I've executed your second query over every table we have. We have no duplicates. We dont have a day with 0 visits in the graph...

[daylicron]

Currently we don't have them as well:

mysql> select count(*) as count, GROUP_CONCAT(name), idarchive, date1, date2 as names from piwik_archive_numeric_2019_01 where name like 'done%' group by idarchive having count > 1;
Empty set (0.03 sec)

mysql> select count(*) as count, GROUP_CONCAT(name), idarchive, date1, date2 as names from piwik_archive_numeric_2019_02 where name like 'done%' group by idarchive having count > 1;
Empty set (0.02 sec)

mysql> select count(*) as count, GROUP_CONCAT(name), idarchive, date1, date2 as names from piwik_archive_numeric_2019_03 where name like 'done%' group by idarchive having count > 1;
Empty set (0.03 sec)

mysql> select count(*) as count, GROUP_CONCAT(name), idarchive, date1, date2 as names from piwik_archive_numeric_2019_04 where name like 'done%' group by idarchive having count > 1;
Empty set (0.01 sec)

mysql> select count(*) as count, GROUP_CONCAT(name), idarchive, date1, date2 as names from piwik_archive_numeric_2019_05 where name like 'done%' group by idarchive having count > 1;
Empty set (0.01 sec)

mysql> select count(*) as count, GROUP_CONCAT(name), idarchive, date1, date2 as names from piwik_archive_numeric_2019_06 where name like 'done%' group by idarchive having count > 1;
Empty set (0.01 sec)

But since we moved back to singlethreaded archiving, we don't have this problem anymore. So I'll try to repoduce this in a testsetup and check this again.

[mattab]

noticed on the demo we have the same problem with some of the weekly reports appearing as zeros while days/months/years are all working.
eg. https://demo.matomo.org/index.php?module=CoreHome&action=index&date=today&period=week&idSite=62#?idSite=62&period=week&date=today&category=General_Visitors&subcategory=General_Overview

[castigaro]

The problem has also been with us since we upgraded from 3.10 to 3.12. The error occurs with all weeks, with which the transition from one month to the next month is, e.g. in the week of 30 September - 6 October or 26 August - 01 September etc. If the Monday is a 1. e.g. 01. July. to 07. July the error does not occur.

[tsteur]

@mattab @diosmosis maybe any idea how this could happen? @mattab have you seen this maybe somewhere as well?

[diosmosis]

This would mean the archives are failing to finish, correct? Maybe we can check whether the archives even exist for those dates or if they are finished with DONE_ERROR?

[tsteur]

Be good to know maybe. As there seems to be a pattern I wonder if it is somehow timezone related or so. Wouldn't expect 0 visits then though but instead only partial result.

If anyone can give us access to their DB and matomo instance that be great: hello at matomo.org is our email.

[mattab]

Yes, seen this happen several times as well (although I had not noticed it only occurred on weeks overlapping two months). It happens randomly. This was a much bigger issue months ago and now it happens a lot less (in recent Matomo releases). It's still visible for example on the demo: https://demo.matomo.org/index.php?module=CoreHome&action=index&date=today&period=week&idSite=62#?idSite=62&period=week&date=today&segment=&category=General_Visitors&subcategory=General_Overview

2 weeks are missing data and overlap 2 months (Select 52 in the row limit selector):

[castigaro]

The problems only occurred after I re-processed the reports with Version 3.12. Under 3.10 everything was ok.
After moving the installation to a new server in the week before the move I was missing the data of 2 days. I thought through a re-process they would reappear. Instead, the gaps were created in the weeks I mentioned. Hope I can create the missing weekly reports again somehow without this gaps.

[mattab]

Yes, seen this happen several times as well (although I had not noticed it only occurred on weeks overlapping two months). It happens randomly.

Fyi: a separate issue was created for this particular bug in #15363

[mattab]

Thanks for reporting this issue.
Unfortunately we're unable to reproduce the problem.
If anyone is reading this and has seen this behaviour, please leave a comment and a screenshot (and ideally how you managed to reproduce).
Thanks!