Cronjob bug after Matomo 3.9.0 upgrade


(Tim) #1

Hello!

I’m upgraded my Matomo installation to 3.9.0. After that I received a warning regarding the cron, which was not setup. So I tried this cronjob:

php /var/www/matomo/htdocs/console core:archive --url=https://myURL/

And I received following output/error:

INFO [2019-03-19 16:32:07] 21075  ---------------------------
INFO [2019-03-19 16:32:07] 21075  INIT
INFO [2019-03-19 16:32:07] 21075  Running Matomo 3.9.0 as Super User
INFO [2019-03-19 16:32:07] 21075  ---------------------------
INFO [2019-03-19 16:32:07] 21075  NOTES
INFO [2019-03-19 16:32:07] 21075  - If you execute this script at least once per hour (or more often) in a crontab, you may disable 'Browser trigger archiving' in Matomo UI > Settings > General Settings.
INFO [2019-03-19 16:32:07] 21075    See the doc at: https://matomo.org/docs/setup-auto-archiving/
INFO [2019-03-19 16:32:07] 21075  - Reports for today will be processed at most every 150 seconds. You can change this value in Matomo UI > Settings > General Settings.
INFO [2019-03-19 16:32:07] 21075  - Reports for the current week/month/year will be requested at most every 3600 seconds.
INFO [2019-03-19 16:32:07] 21075  - Archiving was last executed without error 27 min 1s ago
INFO [2019-03-19 16:32:07] 21075  ---------------------------
INFO [2019-03-19 16:32:07] 21075  START
INFO [2019-03-19 16:32:07] 21075  Starting Matomo reports archiving...
INFO [2019-03-19 16:32:08] 21075  - tracking data found for website id 6 since 2019-03-19 16:05:06 UTC (since the last successful archiving)
INFO [2019-03-19 16:32:08] 21075  Will pre-process for website id = 6, period = day, date = last2
INFO [2019-03-19 16:32:08] 21075  - pre-processing all visits
WARNING [2019-03-19 16:32:08] 21075  /var/www/matomo/htdocs/core/Common.php(271): Notice - unserialize(): Error at offset 0 of 116819 bytes - Matomo 3.9.0 - 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 [2019-03-19 16:32:08] 21075  Empty or invalid response '[2019-03-19 16:32:08] piwik.DEBUG: Loaded plugins: CorePluginsAdmin, CoreAdminHome, CoreHome, WebsiteMeasurable, IntranetMeasurable, Diagnostics, CoreVisualizations, Proxy, API, Widgetize, Transitions, LanguagesManager, Actions, Dashboard, MultiSites, Referrers, UserLanguage, DevicesDetection, Goals, Ecommerce, SEO, Events, UserCountry, GeoIp2, VisitsSummary, VisitFrequency, VisitTime, VisitorInterest, ExampleAPI, RssWidget, Feedback, Monolog, Login, TwoFactorAuth, UsersManager, SitesManager, Installation, CoreUpdater, CoreConsole, ScheduledReports, UserCountryMap, Live, CustomVariables, PrivacyManager, ImageGraph, Annotations, MobileMessaging, Overlay, SegmentEditor, Insights, Morpheus, Contents, BulkTracking, Resolution, DevicePlugins, Heartbeat, Intl, Marketplace, ProfessionalServices, UserId, CustomPiwikJs, Provider, Bandwidth, MarketingCampaignsReporting [] {"class":"Piwik\\Plugin\\Manager","request_id":21162} [2019-03-19 16:32:08] piwik.DEBUG: /* trigger = CronArchive */     SELECT     count(distinct log_visit.idvisitor) AS `1`,     count(*) AS `2`,     sum(log_visit.visit_total_actions) AS `3`,     max(log_visit.visit_total_actions) AS `4`,     sum(log_visit.visit_total_time) AS `5`,     sum(case log_visit.visit_total_actions when 1 then 1 when 0 then 1 else 0 end) AS `6`,     sum(case log_visit.visit_goal_converted when 1 then 1 else 0 end) AS `7`,     count(distinct log_visit.user_id) AS `39`    FROM     piwik_log_visit AS log_visit    WHERE     log_visit.visit_last_action_time >= ?     AND log_visit.visit_last_action_time <= ?     AND log_visit.idsite IN (?) [] {"class":"VisitsSummary","request_id":21162} [2019-03-19 16:32:08] piwik.DEBUG: PluginsArchiver::callAggregateAllPlugins: Initializing archiving process for all plugins [visits = 25, visits converted = 0] ["callAggregateAllPlugins",25,"0"] {"class":"VisitsSummary","request_id":21162} [2019-03-19 16:32:08] piwik.DEBUG: PluginsArchiver::callAggregateAllPlugins: Archiving day reports for plugin 'Actions'. ["callAggregateAllPlugins","Actions"] {"class":"VisitsSummary","request_id":21162} [2019-03-19 16:32:08] piwik.DEBUG: /* trigger = CronArchive */     SELECT     log_action.name,                 log_action.type,                 log_action.idaction,                 log_action.url_prefix, count(distinct log_link_visit_action.idvisit) as `2`, count(distinct log_link_visit_action.idvisitor) as `1`, count(*) as `12`, sum(                         case when custom_float is null                             then 0                             else custom_float                         end                 ) / 1000 as `30`, sum(                     case when custom_float is null                         then 0                         else 1                     end                 ) as `31`, min(custom_float) / 1000 as `32`, max(custom_float) / 1000 as `33`, sum(                     case when bandwidth is null                         then 0                         else bandwidth                     end             ) as `1090`, sum(                 case when bandwidth is null                     then 0                     else 1                 end             ) as `1093`, min(bandwidth) as `1091`, max(bandwidth) as `1092`,                 CASE WHEN (MAX(log_link_visit_action.custom_var_v5) = 0                     AND log_link_visit_action.custom_var_k5 = '_pk_scount')                 THEN 1 ELSE 0 END                     AS `28`,                 SUM( CASE WHEN log_action_name_ref.type = 8                       THEN 1 ELSE 0 END)                     AS `29`    FROM     piwik_log_link_visit_action AS log_link_visit_action LEFT JOIN piwik_log_action AS log_action ON log_link_visit_action.%s = log_action.idaction LEFT JOIN piwik_log_action AS log_action_name_ref ON log_link_visit_action.idaction_name_ref = log_action_name_ref.idaction    WHERE     log_link_visit_action.server_time >= ?     AND log_link_visit_action.server_time <= ?     AND log_link_visit_action.idsite IN (?) AND log_link_visit_action.%s IS NOT NULL AND log_link_visit_action.idaction_event_category IS NULL    GROUP BY     log_link_visit_action.%s    ORDER BY     `12` DESC, name ASC [] {"class":"Actions","request_id":21162} [2019-03-19 16:32:08] piwik.DEBUG: /* trigger = CronArchive */     SELECT     log_action.name,                 log_action.type,                 log_action.idaction,                 log_action.url_prefix, count(distinct log_link_visit_action.idvisit) as `2`, count(distinct log_link_visit_action.idvisitor) as `1`, count(*) as `12`, sum(                         case when custom_float is null                             then 0                             else custom_float                         end                 ) / 1000 as `30`, sum(                     case when custom_float is null                         then 0                         else 1                     end                 ) as `31`, min(custom_float) / 1000 as `32`, max(custom_float) / 1000 as `33`, sum(                     case when bandwidth is null                         then 0                         else bandwidth                     end             ) as `1090`, sum(                 case when bandwidth is null                     then 0                     else 1                 end             ) as `1093`, min(bandwidth) as `1091`, max(bandwidth) as `1092`,                 CASE WHEN (MAX(log_link_visit_action.custom_var_v5) = 0                     AND log_link_visit_action.custom_var_k5 = '_pk_scount')                 THEN 1 ELSE 0 END                     AS `28`,                 SUM( CASE WHEN log_action_name_ref.type = 8                       THEN 1 ELSE 0 END)                     AS `29`    FROM     piwik_log_link_visit_action AS log_link_visit_action LEFT JOIN piwik_log_action AS log_action ON log_link_visit_action.%s = log_action.idaction LEFT JOIN piwik_log_action AS log_action_name_ref ON log_link_visit_action.idaction_name_ref = log_action_name_ref.idacti
INFO [2019-03-19 16:32:09] 21075  - no new tracking data for website id 9 since 2019-03-19 16:05:06 UTC (since the last successful archiving)
INFO [2019-03-19 16:32:09] 21075  Skipped website id 9 as archiving is not needed
INFO [2019-03-19 16:32:09] 21075  - no new tracking data for website id 12 since 2019-03-19 16:05:06 UTC (since the last successful archiving)
INFO [2019-03-19 16:32:09] 21075  Skipped website id 12 as archiving is not needed
INFO [2019-03-19 16:32:09] 21075  Done archiving!
INFO [2019-03-19 16:32:09] 21075  ---------------------------
INFO [2019-03-19 16:32:09] 21075  SUMMARY
INFO [2019-03-19 16:32:09] 21075  Total visits for today across archived websites: 0
INFO [2019-03-19 16:32:09] 21075  Archived today's reports for 0 websites
INFO [2019-03-19 16:32:09] 21075  Archived week/month/year for 0 websites
INFO [2019-03-19 16:32:09] 21075  Skipped 3 websites
INFO [2019-03-19 16:32:09] 21075  - 2 skipped because no new visit since the last script execution
INFO [2019-03-19 16:32:09] 21075  - 0 skipped because existing daily reports are less than 150 seconds old
INFO [2019-03-19 16:32:09] 21075  - 0 skipped because existing week/month/year periods reports are less than 3600 seconds old
INFO [2019-03-19 16:32:09] 21075  - 1 skipped because got an error while querying reporting API
INFO [2019-03-19 16:32:09] 21075  Total API requests: 0
INFO [2019-03-19 16:32:09] 21075  done: 0/3 0%, 0 vtoday, 0 wtoday, 0 wperiods, 0 req, 1120 ms, 1 errors.
INFO [2019-03-19 16:32:09] 21075  Time elapsed: 1.120s
INFO [2019-03-19 16:32:09] 21075  ---------------------------
INFO [2019-03-19 16:32:09] 21075  SCHEDULED TASKS
INFO [2019-03-19 16:32:09] 21075  Starting Scheduled tasks... 
INFO [2019-03-19 16:32:09] 21075  done
INFO [2019-03-19 16:32:09] 21075  ---------------------------
INFO [2019-03-19 16:32:09] 21075  ---------------------------
INFO [2019-03-19 16:32:09] 21075  SUMMARY OF ERRORS
INFO [2019-03-19 16:32:09] 21075  Error: Empty or invalid response '[2019-03-19 16:32:08] piwik.DEBUG: Loaded plugins: CorePluginsAdmin, CoreAdminHome, CoreHome, WebsiteMeasurable, IntranetMeasurable, Diagnostics, CoreVisualizations, Proxy, API, Widgetize, Transitions, LanguagesManager, Actions, Dashboard, MultiSites, Referrers, UserLanguage, DevicesDetection, Goals, Ecommerce, SEO, Events, UserCountry, GeoIp2, VisitsSummary, VisitFrequency, VisitTime, VisitorInterest, ExampleAPI, RssWidget, Feedback, Monolog, Login, TwoFactorAuth, UsersManager, SitesManager, Installation, CoreUpdater, CoreConsole, ScheduledReports, UserCountryMap, Live, CustomVariables, PrivacyManager, ImageGraph, Annotations, MobileMessaging, Overlay, SegmentEditor, Insights, Morpheus, Contents, BulkTracking, Resolution, DevicePlugins, Heartbeat, Intl, Marketplace, ProfessionalServices, UserId, CustomPiwikJs, Provider, Bandwidth, MarketingCampaignsReporting [] {"class":"Piwik\\Plugin\\Manager","request_id":21162} [2019-03-19 16:32:08] piwik.DEBUG: /* trigger = CronArchive */     SELECT     count(distinct log_visit.idvisitor) AS `1`,     count(*) AS `2`,     sum(log_visit.visit_total_actions) AS `3`,     max(log_visit.visit_total_actions) AS `4`,     sum(log_visit.visit_total_time) AS `5`,     sum(case log_visit.visit_total_actions when 1 then 1 when 0 then 1 else 0 end) AS `6`,     sum(case log_visit.visit_goal_converted when 1 then 1 else 0 end) AS `7`,     count(distinct log_visit.user_id) AS `39`    FROM     piwik_log_visit AS log_visit    WHERE     log_visit.visit_last_action_time >= ?     AND log_visit.visit_last_action_time <= ?     AND log_visit.idsite IN (?) [] {"class":"VisitsSummary","request_id":21162} [2019-03-19 16:32:08] piwik.DEBUG: PluginsArchiver::callAggregateAllPlugins: Initializing archiving process for all plugins [visits = 25, visits converted = 0] ["callAggregateAllPlugins",25,"0"] {"class":"VisitsSummary","request_id":21162} [2019-03-19 16:32:08] piwik.DEBUG: PluginsArchiver::callAggregateAllPlugins: Archiving day reports for plugin 'Actions'. ["callAggregateAllPlugins","Actions"] {"class":"VisitsSummary","request_id":21162} [2019-03-19 16:32:08] piwik.DEBUG: /* trigger = CronArchive */     SELECT     log_action.name,                 log_action.type,                 log_action.idaction,                 log_action.url_prefix, count(distinct log_link_visit_action.idvisit) as `2`, count(distinct log_link_visit_action.idvisitor) as `1`, count(*) as `12`, sum(                         case when custom_float is null                             then 0                             else custom_float                         end                 ) / 1000 as `30`, sum(                     case when custom_float is null                         then 0                         else 1                     end                 ) as `31`, min(custom_float) / 1000 as `32`, max(custom_float) / 1000 as `33`, sum(                     case when bandwidth is null                         then 0                         else bandwidth                     end             ) as `1090`, sum(                 case when bandwidth is null                     then 0                     else 1                 end             ) as `1093`, min(bandwidth) as `1091`, max(bandwidth) as `1092`,                 CASE WHEN (MAX(log_link_visit_action.custom_var_v5) = 0                     AND log_link_visit_action.custom_var_k5 = '_pk_scount')                 THEN 1 ELSE 0 END                     AS `28`,                 SUM( CASE WHEN log_action_name_ref.type = 8                       THEN 1 ELSE 0 END)                     AS `29`    FROM     piwik_log_link_visit_action AS log_link_visit_action LEFT JOIN piwik_log_action AS log_action ON log_link_visit_action.%s = log_action.idaction LEFT JOIN piwik_log_action AS log_action_name_ref ON log_link_visit_action.idaction_name_ref = log_action_name_ref.idaction    WHERE     log_link_visit_action.server_time >= ?     AND log_link_visit_action.server_time <= ?     AND log_link_visit_action.idsite IN (?) AND log_link_visit_action.%s IS NOT NULL AND log_link_visit_action.idaction_event_category IS NULL    GROUP BY     log_link_visit_action.%s    ORDER BY     `12` DESC, name ASC [] {"class":"Actions","request_id":21162} [2019-03-19 16:32:08] piwik.DEBUG: /* trigger = CronArchive */     SELECT     log_action.name,                 log_action.type,                 log_action.idaction,                 log_action.url_prefix, count(distinct log_link_visit_action.idvisit) as `2`, count(distinct log_link_visit_action.idvisitor) as `1`, count(*) as `12`, sum(                         case when custom_float is null                             then 0                             else custom_float                         end                 ) / 1000 as `30`, sum(                     case when custom_float is null                         then 0                         else 1                     end                 ) as `31`, min(custom_float) / 1000 as `32`, max(custom_float) / 1000 as `33`, sum(                     case when bandwidth is null                         then 0                         else bandwidth                     end             ) as `1090`, sum(                 case when bandwidth is null                     then 0                     else 1                 end             ) as `1093`, min(bandwidth) as `1091`, max(bandwidth) as `1092`,                 CASE WHEN (MAX(log_link_visit_action.custom_var_v5) = 0                     AND log_link_visit_action.custom_var_k5 = '_pk_scount')                 THEN 1 ELSE 0 END                     AS `28`,                 SUM( CASE WHEN log_action_name_ref.type = 8                       THEN 1 ELSE 0 END)                     AS `29`    FROM     piwik_log_link_visit_action AS log_link_visit_action LEFT JOIN piwik_log_action AS log_action ON log_link_visit_action.%s = log_action.idaction LEFT JOIN piwik_log_action AS log_action_name_ref ON log_link_visit_action.idaction_name_ref = log_action_name_ref.idacti
ERROR [2019-03-19 16:32:09] 21075  1 total errors during this script execution, please investigate and try and fix these errors.


                                                                                                 
  [Exception]                                                                                    
  1 total errors during this script execution, please investigate and try and fix these errors.

(Victor Williams) #2

Same thing for me. For the time being I’ve disabled cronjobs. Unfortunately I didn’t create a snapshot before our upgrade (lack of sleep/coffee), so we’re stuck with this issue until a fix is available.


(Tim) #3

Same for me. All previous upgrades worked so smoothy for me that I thought I can do it without any backup. :frowning:


(Lukas Winkler) #4

Hi,

You can find more info about this bug here:

If you are in a hurry, there is also a hack that fixes the bug temporarily until a real fix is found soon.


(Tim) #5

Thank you @Lukas. Good to know that more people are affected and its a knowing problem.


#6

Did the update today, got this error, too. Why does the Matomo team dont stop this update, when alot of people reporting feature breaking bugs… ?