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… ?


(T.) #7

I think Im running into this issue too. None of my Transitions are working but it seems that hits are being recorded but when its time to display this information on Transitions everything just freezes and it loads forever.

I’m running on shared server for what its work I don’t expect it to be fast but I’ve left Transitions loading for over an hour and nothing.