@chgarling opened this Issue on February 21st 2019

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 commented on February 21st 2019 Member

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

@bab-mkedziora commented on February 25th 2019

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 = xxxx@xxxx.xxx
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 commented on February 26th 2019 Member

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 commented on March 5th 2019

@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 commented on March 7th 2019 Member

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 commented on March 7th 2019

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 commented on March 7th 2019 Member

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 commented on March 8th 2019

I changed it to:

for ((n=0;n<<%= <a class='mention' href='https://github.com/number_workers'>@number_workers</a> %>;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 commented on March 8th 2019 Member

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 commented on March 11th 2019

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 commented on March 11th 2019 Member

Cheers for letting us know and giving it a try 👍

@daylicron commented on March 12th 2019

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<<%= <a class='mention' href='https://github.com/number_workers'>@number_workers</a> %>;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 commented on March 13th 2019

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 commented on March 13th 2019 Member

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

Powered by GitHub Issue Mirror