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
Scheduled email reports not sending in 2.9.1 #6868
Comments
Hi @averymd thanks for the report. maybe you can attach a screenshot of the tasksTimetable list? Also can you check that your server date is correct although it's likely not the issue. |
I confirmed that the server's date is correct, although I should note that its timezone is PST. As if I needed more timezones to deal with. Attached is a screenshot of the list after creating a new daily report that should have run within an hour (report 11) and running the archive script to get the table to update. Instead of scheduling itself for today, it scheduled for tomorrow. That might be by design for new reports, however. Report 10 is an existing daily report that never sends, and it should have sent within 15 minutes of that screenshot, but is already "bumped" to the next day. |
@mnapoli maybe you will have some idea about this bug when looking at the scheduled task code? |
@mattab I tried to have a look at this issue last week, but couldn't figure out something helpful. For the scheduler, for now I have only moved things around, and removed static methods. But I have touched the internals (yet) because that code is complex :( The only helpful thing I could imagine is to refactor the scheduler with advanced logging, e.g. log all the executions in database (or somewhere else?). That way we could create a plugin (or edit an existing one) that would show the run history of scheduled tasks (along with the future ones), allowing to debug problems more easily (not the first time we have problems with scheduled tasks). I was afraid it would be a bit overkill, what do you think @mattab? |
@mnapoli What's a good way to get you the info you need, if you're willing? |
Hi all |
I'm on 2.10.0 now, and the issue persists. @leonardise, I haven't found a workaround yet. |
As an update on this behavior: the only scheduled task I ever see being completed in my cron jobs (and I read all of them now) is the GeoIpAutoUpdater. None of the other tasks from the list I posted above ever run. I ran an experiment where I set a report to be delivered at a non-midnight time, like 19:00. I ran the cron archive command 10 minutes before 19:00. The task didn't execute (which I believe is correct behavior), but that triggered the task to roll forward into the next day. @leonardise, can you check and see if your system is behaving similarly? Am I correct in assuming the tasks should execute at the next archival after their scheduled time? I'm now wondering if all those report and archive purging tasks not running is leading to my issues with missing reports. |
Note to myself (still trying to understand how the scheduler works…): try to test in more details this part: https://github.com/piwik/piwik/blob/master/core/Scheduler/Schedule/Schedule.php#L128-L155 The schedule for sending reports is recorded with the site's timezone (so here The server's timezone is To be able to compare those 2 dates (schedule + current time) the scheduler "converts" the schedule time into the server timezone with the piece of code I linked above. Maybe this is this part that is buggy. |
Ideally, to fix this issue, anyone experiencing this issue would send us access to that Piwik installation if possible. We'd also need access to the files and maybe database if possible. If anyone is keen to do this please send details to hello (at) piwik.org. Otherwise it will be probably hard to fix this issue as it could be anything. |
I'll get you credentials within a couple of hours. |
Hi @averymd |
My understanding is that any task that runs will show up in the logs of the archive cron job. If the only thing you're seeing is the GeoIPAutoUpdater as well, then we might be in the same boat. I've sent the dev team credentials to my web and DB servers, but you may want to as well. In addition, what time zones are your websites and the server in? For instance, my websites are configured in piwik to be in EST time, but my server is in PST. |
@averymd I had a look but couldn't find anything interesting for now. I indeed saw that reports scheduled for a few hours from now where bumped to the next day… FYI in the credentials you sent I didn't have the permissions to [log]
log_writers[] = "file"
log_writers[] = "screen"
log_level = "INFO" Did you set up a cron job for running the tasks? Do you store the output of the cron job to a file to that I can have a look at that? Regarding the problem, I have the feeling that the task actually runs (in the code I see no way the task can be rescheduled without running first…). So then why would it do nothing, and also why is it rescheduled earlier than necessary… Though maybe I'm wrong, it's just where I am at now. |
fyi: this bug is also experienced by other Enterprise clients |
I've made quite a bit of headway with this. I realized that I was also suffering from the drastic increase in DB size reported on the forum, which led credence to the idea that those cleanup tasks weren't running. The end of my cron logs looked like:
or like:
every hour. When I turned on Piwik logging (thank you, @mnapoli!), I found my issue: the I didn't see a way in Instead, I set It seems to be that the fundamental issue is that no errors showed up in my cron logs, despite INFO-level logging showing there. Is it also an issue that DB permissions aren't checked for Let me know if you want me to fix your accesses to my server so you can investigate more. I'm happy to do so. |
the System check for I don't understand how this could have resolved your issue with the email reports... thoughts? we would need access to a Piwik server where the issue can be reproduced.. |
It was definitely still trying to do
Could the execution of scheduled tasks have been aborted due to these errors? If so, I don't know why the GeoIPAutoUpdater continued to run, although maybe it was also causing an error that stopped later tasks from running. There wasn't a way to map the entries in the log file to the steps in the archival process, but the only errors there were the As I went through my cron logs before I fixed this, I noticed that GeoIPAutoUpdater was running most hours of the day, instead of weekly or monthly, as the task suggests it should. That said, there were none of the log messages the task should have been writing to the log file (example). Not sure if that's a clue. Unfortunately (for diagnosis purposes), things are running very smoothly again on my system, so it's probably no longer useful for reproducing and diagnosing the issue. Maybe @leonardise or the enterprise client can help. |
Do you mind maybe trying to set back the setting to 1 and maybe the email reports will still send? if they don't send then it would indicate an issue with the LOAD DATA INFILE and it would help the research! |
Will do. I'll post back tonight on the results. |
Ok thanks, we look forward to your feedback. If anyone else listening experiences the bug please get in touch by email as we need your help to fix it before 2.11.0 (matt att piwik.org) |
I removed the The archive and report cleanup scheduled tasks ran when they should, but my logs are again full of LOAD DATA INFILE errors for Actions, Referrers, and AdvancedCampaignReporting for each time period being processed. I was tailing the logs as the archive ran, and no INFILE-related errors showed while the scheduled tasks were checked. My scheduled email reports did send at the correct time. So the INFILE problem is probably unrelated. Should I open a bug for the fact that INFILE is thought available despite permission problems? One thing I noticed: editing an existing report's time in the UI didn't reschedule its task, as seen on the TasksTimetable (and verified in the "TaskScheduler.timetable" option in the DB). I ran the archive command and I resaved the report again -- neither rescheduled the task. Only when it ran at the old time did its schedule adjust. I think we're back at square one in replicating this on my system. Hopefully one of the other folks with the issue will chime in. |
👍 |
if you can reproduce on your system, would it be possible to send us some SSH access so we can definitely investigate fully and fix it? |
So if I try to sum things up:
|
Summary of an idea suggested by @tsteur: If for whatever reason superuser access fails, the list of scheduled tasks will be empty. That means the timetable will be emptied (all scheduled tasks removed). Then on another run (e.g. 5 minutes later) the scheduled tasks are added again, but since they are "new" they are rescheduled (and not run). Now why would they be rescheduled for the next day (1day+1hour) instead of simply the next hour… (which means they will actually never run). It could be due to the implementation of the And why would superuser access fail? Is it related to the Or could it be that browser archiving is triggered, which means archiving can be run in the browser with the visitor's session. If the visitor is an anonymous user, or a user without super-user access, then scheduled tasks run without super-user and tasks are empty… That would also explain why it randomly works/doesn't work (because it depends how browser archiving is triggered…). @averymd could you check if you have browser archiving enabled? |
Just remembered you sent us access, I checked your config and browser archiving is correctly disabled… I couldn't find anything new in the logs (piwik + system), however I noticed the cronjob output is not logged to a file (so we can't check the archiving output). @averymd could you configure your crontab to log the output of the |
Cron output should now be logged to |
We'll let it run and see tomorrow, the first archiving logs are weird: they are not at a fixed time we can see 2 archiving overlapping and being run in parallel. I'm guessing it's just that you were re-configuring everything (was 9 feb.) and that it's not related to the problem here because at the end of the log the archiving seems to run correctly. Wait and see tomorrow. |
Since 5am yesterday the archiving fails every hour with this: INFO CoreConsole[2015-02-12 21:00:03] ---------------------------
INFO CoreConsole[2015-02-12 21:00:03] INIT
INFO CoreConsole[2015-02-12 21:00:03] Piwik is installed at: https://domain.com/index.php
INFO CoreConsole[2015-02-12 21:00:03] Running Piwik 2.10.0 as Super User
WARNING CoreConsole[2015-02-12 21:00:03] /path/to/piwik/core/CliMulti/Process.php(159): Warning - file_put_contents(/path/to/piwik/tmp/climulti/61c78519383e3948efc549040ded19546b5b8699bc949235a49e799a0ccf9b3e19d6243174b2f2361f6c636596e7b84c08e80.pid): failed to open stream: Permission denied - Piwik 2.10.0 - Please report this message in the Piwik forums: http://forum.piwik.org (please do a search first as it might have been reported already)
sh: /path/to/piwik/tmp/climulti/61c78519383e3948efc549040ded19546b5b8699bc949235a49e799a0ccf9b3e19d6243174b2f2361f6c636596e7b84c08e80.output: Permission denied
ERROR CoreConsole[2015-02-12 21:00:04] Got invalid response from API request: https://domain.com/index.php?module=API&method=API.getDefaultMetricTranslations&format=original&serialize=1&trigger=archivephp. The response was empty. This usually means a server error. This solution to this error is generally to increase the value of 'memory_limit' in your php.ini file. Please check your Web server Error Log file for more details.
ERROR CoreConsole[2015-02-12 21:00:04] The Piwik URL https://domain.com/index.php does not seem to be pointing to a Piwik server. Response was ''.
ERROR CoreConsole[2015-02-12 21:00:04] The Piwik URL https://domain.com/index.php does not seem to be pointing to a Piwik server. Response was ''.
[Exception]
The Piwik URL https://domain.com/index.php does not seem to be pointing to a Piwik server. Response was ''. It seems the process can't write to |
Yup, there was a permission problem. When I opened up access to your user, I managed to mangle permissions to the |
I had another deep look into the logs today and I have not found anything interesting. Cron output seems perfectly normal, but no scheduled reports are run… Piwik logs only contain warnings about LOAD DATA INFILE failing. Nginx/php-fpm error logs are empty. I also run the archiving in debug mode but no special information was logged for the scheduled tasks… It seems it runs through a web request: INFO CoreConsole[2015-02-15 02:36:21] ---------------------------
INFO CoreConsole[2015-02-15 02:36:21] SCHEDULED TASKS
INFO CoreConsole[2015-02-15 02:36:21] Starting Scheduled tasks...
DEBUG CoreConsole[2015-02-15 02:36:21] /usr/local/php54/bin/php -q /home/.../console climulti:request -q --piwik-domain='...' 'module=API&method=CoreAdminHome.runScheduledTasks&format=csv&convertToUnicode=0&token_auth=...'
INFO CoreConsole[2015-02-15 02:36:23] No task to run
INFO CoreConsole[2015-02-15 02:36:23] done
INFO CoreConsole[2015-02-15 02:36:23] --------------------------- @piwik/core-team Why are the scheduled tasks run through a web request and not directly in the same process? Because of that we lose verbose log info. |
I don't know why scheduled tasks are run as a web request, but maybe |
Good idea, I gave it a try here is the output: $ /usr/local/bin/php-5.4 ./console core:run-scheduled-tasks -vvv
DEBUG SitesManager[2015-02-15 05:54:33] Db::fetchAll() executing SQL: SELECT idsite FROM piwik_site
DEBUG CoreAdminHome[2015-02-15 05:54:33] Db::fetchAll() executing SQL: SELECT DATABASE()
DEBUG CoreAdminHome[2015-02-15 05:54:33] Db::fetchAll() executing SQL: SELECT option_value, option_name FROM `piwik_option` WHERE autoload = 1
DEBUG CoreAdminHome[2015-02-15 05:54:33] Db::fetchOne() executing SQL: SELECT option_value FROM `piwik_option` WHERE option_name = ?
DEBUG CoreAdminHome[2015-02-15 05:54:34] Loaded plugins: CorePluginsAdmin, CoreAdminHome, CoreHome, CoreVisualizations, Proxy, API, Widgetize, Transitions, LanguagesManager, Actions, Dashboard, MultiSites, Referrers, UserSettings, DevicesDetection, Goals, SEO, Events, UserCountry, VisitsSummary, VisitFrequency, VisitTime, VisitorInterest, Provider, Feedback, Login, UsersManager, SitesManager, Installation, CoreUpdater, CoreConsole, ScheduledReports, UserCountryMap, Live, CustomVariables, PrivacyManager, ImageGraph, Annotations, Overlay, Insights, LeftMenu, Morpheus, Contents, BulkTracking, Resolution, DevicePlugins, AdvancedCampaignReporting, DBStats, TasksTimetable
DEBUG SitesManager[2015-02-15 05:54:34] Db::fetchAll() executing SQL: SELECT idsite FROM piwik_site
DEBUG LanguagesManager[2015-02-15 05:54:34] Db::fetchOne() executing SQL: SELECT language FROM piwik_user_language WHERE login = ?
DEBUG UsersManager[2015-02-15 05:54:34] Db::query() executing SQL: INSERT INTO `piwik_option` (option_name, option_value, autoload) VALUES (?, ?, ?) ON DUPLICATE KEY UPDATE option_value = ?
DEBUG CoreAdminHome[2015-02-15 05:54:34] Db::fetchOne() executing SQL: SELECT option_value FROM `piwik_option` WHERE option_name = ?
DEBUG UserCountry[2015-02-15 05:54:34] Db::fetchOne() executing SQL: SELECT option_value FROM `piwik_option` WHERE option_name = ?
DEBUG ScheduledReports[2015-02-15 05:54:34] Db::fetchAll() executing SQL: SELECT report.*
FROM piwik_report AS `report`
JOIN piwik_site
USING (idsite)
WHERE deleted = 0
****************************
Scheduled Tasks executed
**************************** The last SQL request shows that scheduled reports are run, but it seems that's all the log info we can get… Monday I'll add additional logging statement to the scheduler. |
Do simulate the same behaviour as during archiving I would maybe rather execute the scheduled tasks separately via Does this Piwik installation have multiple super users defined? |
I gave it a try with verbose options (
I don't have the permissions to edit the config file to set debug logging, but even then I don't believe anything else will be logged since the API simply runs the scheduler and the scheduler doesn't have log statements. |
It might log only one entry as the option entry, which stores the execution time, has to be cleared before. Then the command has to be executed twice. Do you have super user permission? This plugin would allow you to edit it: https://github.com/piwik/plugin-PiwikDebugger |
Running the command twice yields the same result. I have added log statements in the scheduler (see the commit above). Also, running the
|
I have added log statements on the install, we'll see what is logged in the next day (right now I can only see no scheduled task is being run or rescheduled). |
I'll be closing this ticket as it seems that the scheduled reports are sent correctly from now on and we can't reproduce the bug. If you still have the problem, please let us know so that we reopen the bug :) |
For the record for the latest archiving in your server @averymd:
Cron output: INFO CoreConsole[2015-02-16 05:23:40] ---------------------------
INFO CoreConsole[2015-02-16 05:23:40] SCHEDULED TASKS
INFO CoreConsole[2015-02-16 05:23:40] Starting Scheduled tasks...
INFO CoreConsole[2015-02-16 05:25:33] task,output
Piwik\Plugins\ScheduledReports\API.sendReport_1,Time elapsed: 2.699s
Piwik\Plugins\ScheduledReports\API.sendReport_4,Time elapsed: 25.551s
Piwik\Plugins\ScheduledReports\API.sendReport_5,Time elapsed: 11.589s
Piwik\Plugins\ScheduledReports\API.sendReport_8,Time elapsed: 23.103s
Piwik\Plugins\ScheduledReports\API.sendReport_10,Time elapsed: 23.519s
Piwik\Plugins\ScheduledReports\API.sendReport_12,Time elapsed: 24.391s
INFO CoreConsole[2015-02-16 05:25:33] done
INFO CoreConsole[2015-02-16 05:25:33] --------------------------- Piwik log with additional log statements: INFO CoreAdminHome[2015-02-16 05:23:41] 18 tasks loaded
INFO CoreAdminHome[2015-02-16 05:23:41] Rescheduling Piwik\Plugins\ScheduledReports\API.sendReport_1
INFO CoreAdminHome[2015-02-16 05:23:41] Executing task Piwik\Plugins\ScheduledReports\API.sendReport_1
INFO CoreAdminHome[2015-02-16 05:23:44] Rescheduling Piwik\Plugins\ScheduledReports\API.sendReport_4
INFO CoreAdminHome[2015-02-16 05:23:44] Executing task Piwik\Plugins\ScheduledReports\API.sendReport_4
INFO CoreAdminHome[2015-02-16 05:24:10] Rescheduling Piwik\Plugins\ScheduledReports\API.sendReport_5
INFO CoreAdminHome[2015-02-16 05:24:10] Executing task Piwik\Plugins\ScheduledReports\API.sendReport_5
INFO CoreAdminHome[2015-02-16 05:24:21] Rescheduling Piwik\Plugins\ScheduledReports\API.sendReport_8
INFO CoreAdminHome[2015-02-16 05:24:21] Executing task Piwik\Plugins\ScheduledReports\API.sendReport_8
INFO CoreAdminHome[2015-02-16 05:24:45] Rescheduling Piwik\Plugins\ScheduledReports\API.sendReport_10
INFO CoreAdminHome[2015-02-16 05:24:45] Executing task Piwik\Plugins\ScheduledReports\API.sendReport_10
INFO CoreAdminHome[2015-02-16 05:25:08] Rescheduling Piwik\Plugins\ScheduledReports\API.sendReport_12
INFO CoreAdminHome[2015-02-16 05:25:08] Executing task Piwik\Plugins\ScheduledReports\API.sendReport_12 So all seems OK, no bug reproduced here. |
With the TasksTimetable plugin, I see that email reports are in the table, but always a day (or week, or month) ahead. As an example: if TasksTimetable reports the current date/time is Wednesday 03:00 UTC, my upcoming daily reports should be scheduled to send at Wednesday 05:00 UTC (all my websites are America/New York), but the next daily report is scheduled to go on Thursday at 05:00, as if the Wednesday task has already passed.
I've created new reports since 2.9.1, and they also always schedule too far in advance.
This has been happening since I upgraded to Piwik 2, so it's not new to 2.9.1, and this ticket is a continuation of #5289. I can send any report manually by email with no problems.
The text was updated successfully, but these errors were encountered: