Skip to content
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

Closed
averymd opened this issue Dec 17, 2014 · 42 comments
Closed

Scheduled email reports not sending in 2.9.1 #6868

averymd opened this issue Dec 17, 2014 · 42 comments
Labels
Bug For errors / faults / flaws / inconsistencies etc. Major Indicates the severity or impact or benefit of an issue is much higher than normal but not critical. worksforme The issue cannot be reproduced and things work as intended.
Milestone

Comments

@averymd
Copy link

averymd commented Dec 17, 2014

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.

@mattab mattab added the Bug For errors / faults / flaws / inconsistencies etc. label Dec 17, 2014
@mattab mattab added this to the Piwik 2.11.0 milestone Dec 17, 2014
@mattab
Copy link
Member

mattab commented Dec 17, 2014

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.

@averymd
Copy link
Author

averymd commented Dec 18, 2014

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.

2014-12-18 taskstimetable

@mattab
Copy link
Member

mattab commented Jan 6, 2015

@mnapoli maybe you will have some idea about this bug when looking at the scheduled task code?

@mnapoli
Copy link
Contributor

mnapoli commented Jan 6, 2015

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

@mattab
Copy link
Member

mattab commented Jan 6, 2015

@mnapoli if you want to debug the issue maybe @averymd would be happy to send you the server access?

If anyone else experiences the issue, please let us know in the comments. in the meantime, i'm moving out of 2.11.0.

@mattab mattab modified the milestones: Short term, Piwik 2.11.0 Jan 6, 2015
@averymd
Copy link
Author

averymd commented Jan 17, 2015

@mnapoli What's a good way to get you the info you need, if you're willing?

@leonardise
Copy link

Hi all
I'm experiencing the same issue on Piwik 2.9.1, PHP 5.5.6, Red Hat Enterprise Linux Server release 6.6 (Santiago) automatic email reports is not working though manually emails is working well.
Is there any way to debug or workaround this behaviour?
Thank you

@averymd
Copy link
Author

averymd commented Jan 30, 2015

I'm on 2.10.0 now, and the issue persists. @leonardise, I haven't found a workaround yet.

@averymd
Copy link
Author

averymd commented Feb 4, 2015

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.

@mnapoli
Copy link
Contributor

mnapoli commented Feb 4, 2015

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 America/New York).

The server's timezone is PST, and the schedule is compared to the server's timezone.

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.

@tsteur
Copy link
Member

tsteur commented Feb 4, 2015

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.

@averymd
Copy link
Author

averymd commented Feb 4, 2015

I'll get you credentials within a couple of hours.

@leonardise
Copy link

Hi @averymd
I see that the only task that has been correctly rescheduled is the GeoIpAutoUpdater, but I don't know where I can check if any of these really ran. I found no logs in Apache error and access files.
Could you give me any hint?

@averymd
Copy link
Author

averymd commented Feb 5, 2015

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.

@mattab mattab modified the milestones: Piwik 2.11.0, Short term Feb 6, 2015
@mattab mattab added the Major Indicates the severity or impact or benefit of an issue is much higher than normal but not critical. label Feb 6, 2015
@mnapoli
Copy link
Contributor

mnapoli commented Feb 8, 2015

@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 cd to Piwik's directory. I noticed that there is no log file using sudo (should be tmp/logs/piwik.log), could you maybe enable logging? To do this, add this config to your config.ini.php:

[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.

@mattab
Copy link
Member

mattab commented Feb 9, 2015

fyi: this bug is also experienced by other Enterprise clients

@averymd
Copy link
Author

averymd commented Feb 10, 2015

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:

INFO CoreConsole[2015-02-03 01:08:24] SCHEDULED TASKS
INFO CoreConsole[2015-02-03 01:08:24] Starting Scheduled tasks...
INFO CoreConsole[2015-02-03 01:08:26] task,output
Piwik\Plugins\UserCountry\GeoIPAutoUpdater.update,Time elapsed: 0.446s
INFO CoreConsole[2015-02-03 01:08:26] done
INFO CoreConsole[2015-02-03 01:08:26] --------------------------- 

or like:

INFO CoreConsole[2015-02-03 03:07:23] SCHEDULED TASKS
INFO CoreConsole[2015-02-03 03:07:23] Starting Scheduled tasks...
INFO CoreConsole[2015-02-03 03:07:26]  No task to run
INFO CoreConsole[2015-02-03 03:07:26] done
INFO CoreConsole[2015-02-03 03:07:26] ---------------------------

every hour.

When I turned on Piwik logging (thank you, @mnapoli!), I found my issue: the LOAD DATA INFILE commands were silently failing during the archive process due to missing permissions. I didn't read the source code surrounding the check for the LOAD DATA commands too closely, but it looks like the system check is only verifying that that command exists, not that the database user has access to use it.

I didn't see a way in config.ini.php to switch to LOAD DATA LOCAL INFILE, which, according to my host's documentation, should have cleared up the issue.

Instead, I set enable_load_data_infile = 0 in my config.ini.php, dropped my January and February archive tables, and ran the archive command. Voila, emails are sending again, and my missing data is back.

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 LOAD DATA INFILE?

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.

@mattab
Copy link
Member

mattab commented Feb 10, 2015

the System check for LOAD DATA INFILE inserts data using the command using the DB user in the cconfig file, so it should have detected the issue with it. But even if it does not work then Piwik will fallback to inserting each record one by one, which still works (although slower).

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..
@quba maybe we can access other client's server experiencing this issue?
or maybe someone experiencing the issue of not receiving email reports could give us access to servers via email?

@averymd
Copy link
Author

averymd commented Feb 10, 2015

It was definitely still trying to do LOAD DATA INFILE until I set the flag in config.ini.php. My logs were full of:

INFO Actions[2015-02-08 23:56:15] LOAD DATA INFILE failed... Error was: SQLSTATE [28000]:
Invalid authorization specification: 1045 Access denied for user '<dbusername>'@'%' (using password: YES)[28000]

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 LOAD DATA INFILE errors.

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.

@mattab
Copy link
Member

mattab commented Feb 10, 2015

Instead, I set enable_load_data_infile = 0 in my config.ini.php, dropped my January and February archive tables, and ran the archive command. Voila, emails are sending again, and my missing data is back.

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!

@averymd
Copy link
Author

averymd commented Feb 10, 2015

Will do. I'll post back tonight on the results.

@mattab
Copy link
Member

mattab commented Feb 11, 2015

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)

@averymd
Copy link
Author

averymd commented Feb 11, 2015

I removed the enable_load_data_infile = 0 line from my config. The system check page once again shows a green mark for being able to use INFILE.

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.

@mattab
Copy link
Member

mattab commented Feb 11, 2015

Should I open a bug for the fact that INFILE is thought available despite permission problems?

👍

@mattab
Copy link
Member

mattab commented Feb 11, 2015

I think we're back at square one in replicating this on my system.

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?

@mnapoli
Copy link
Contributor

mnapoli commented Feb 11, 2015

So if I try to sum things up:

  • email reports where not sent, rescheduled to the next day around 1-2h before it was supposed to run
  • the cron output looks fine, no error in archiving or scheduled tasks appear
  • you enable log, see LOAD DATA INFILE errors during the archiving (it should have then fallback to using INSERT instead…)
  • you set enable_load_data_infile = 0 and drop archive tables, then the archiving runs OK and emails are sent
  • then, to test, you remove enable_load_data_infile = 0
  • LOAD DATA INFILE errors again, but email reports are still being sent!

@mnapoli
Copy link
Contributor

mnapoli commented Feb 11, 2015

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 Daily class schedule: rescheduling the task always gets the next day (date('j', $currentTime) + 1). Should we change that? I'm not sure because the next day is indeed the correct time for the "next scheduled time"…

And why would superuser access fail? Is it related to the LOAD DATA INFILE warnings?

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?

@mnapoli
Copy link
Contributor

mnapoli commented Feb 12, 2015

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 core:archive command to a file (e.g. see here)? I will not change anything on your server myself.

@averymd
Copy link
Author

averymd commented Feb 12, 2015

Cron output should now be logged to /home/piwikstats/logs/piwik-cron.log. I've also fixed the SSH accounts permission problems with access to that home directory. My cron task is setup in my host's control panel, rather than the system cron, so you won't be able to tweak that, but I created a piwik-folks-info.txt file into your user's home directory that has the command being run.

@mnapoli
Copy link
Contributor

mnapoli commented Feb 12, 2015

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.

@mnapoli
Copy link
Contributor

mnapoli commented Feb 12, 2015

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 /path/to/piwik/tmp/, a user permission problem probably? Have you changed something in your setup recently, or is there a chance it was like this all along?

@averymd
Copy link
Author

averymd commented Feb 13, 2015

Yup, there was a permission problem. When I opened up access to your user, I managed to mangle permissions to the tmp directory. It's corrected now. Sorry for the mixup!

@mnapoli
Copy link
Contributor

mnapoli commented Feb 15, 2015

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.

@diosmosis
Copy link
Member

I don't know why scheduled tasks are run as a web request, but maybe ./console core:run-scheduled-tasks -vvv might provide some useful info?

@mnapoli
Copy link
Contributor

mnapoli commented Feb 15, 2015

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.

@tsteur
Copy link
Member

tsteur commented Feb 15, 2015

Do simulate the same behaviour as during archiving I would maybe rather execute the scheduled tasks separately via climulti:request module=API&method=CoreAdminHome.runScheduledTasks&format=csv&convertToUnicode=0&token_auth=... if possible and set the logging to verbose to a file in config for that test. Should be ok for a minute or so.

Does this Piwik installation have multiple super users defined?

@mnapoli
Copy link
Contributor

mnapoli commented Feb 15, 2015

I gave it a try with verbose options (climulti:request -vv), here was the output:

DEBUG SitesManager[2015-02-15 23:25:28] Db::fetchAll() executing SQL: SELECT idsite FROM piwik_site
No data available

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.

@tsteur
Copy link
Member

tsteur commented Feb 15, 2015

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

@mnapoli
Copy link
Contributor

mnapoli commented Feb 16, 2015

Running the command twice yields the same result.

I have added log statements in the scheduler (see the commit above).

Also, running the climulti:request command with logging at DEBUG enabled yields this in piwik.log:

DEBUG Piwik\Db[2015-02-16 00:56:51] Db::fetchAll() executing SQL: SELECT DATABASE()
DEBUG Piwik\Db[2015-02-16 00:56:51] Db::fetchAll() executing SQL: SELECT option_value, option_name FROM `piwik_option` WHERE autoload = 1
DEBUG Piwik\Db[2015-02-16 00:56:51] Db::fetchOne() executing SQL: SELECT option_value FROM `piwik_option` WHERE option_name = ?
DEBUG Piwik\Plugin\Manager[2015-02-16 00:56:51] 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-16 00:56:51] Db::fetchAll() executing SQL: SELECT idsite FROM piwik_site
DEBUG SitesManager[2015-02-16 00:56:51] Db::fetchAll() executing SQL: SELECT idsite FROM piwik_site
DEBUG LanguagesManager[2015-02-16 00:56:51] Db::fetchOne() executing SQL: SELECT language FROM piwik_user_language WHERE login = ?
DEBUG SitesManager[2015-02-16 00:56:51] Db::fetchAll() executing SQL: SELECT idsite FROM piwik_site
DEBUG CoreAdminHome[2015-02-16 00:56:51] Db::fetchOne() executing SQL: SELECT option_value FROM `piwik_option` WHERE option_name = ?
DEBUG UserCountry[2015-02-16 00:56:52] Db::fetchOne() executing SQL: SELECT option_value FROM `piwik_option` WHERE option_name = ?
DEBUG ScheduledReports[2015-02-16 00:56:52] Db::fetchAll() executing SQL: SELECT report.*
                                                                FROM piwik_report AS `report`
                                                                        JOIN piwik_site
                                                                        USING (idsite)
                                                                WHERE deleted = 0

@mnapoli
Copy link
Contributor

mnapoli commented Feb 16, 2015

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).

@mnapoli
Copy link
Contributor

mnapoli commented Feb 16, 2015

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 :)

@mnapoli mnapoli closed this as completed Feb 16, 2015
@mnapoli mnapoli added the worksforme The issue cannot be reproduced and things work as intended. label Feb 16, 2015
@mnapoli
Copy link
Contributor

mnapoli commented Feb 16, 2015

For the record for the latest archiving in your server @averymd:

  • the email reports where sent
  • scheduled tasks have been correctly executed and rescheduled
  • logging was as expected in both logs

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.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Bug For errors / faults / flaws / inconsistencies etc. Major Indicates the severity or impact or benefit of an issue is much higher than normal but not critical. worksforme The issue cannot be reproduced and things work as intended.
Projects
None yet
Development

No branches or pull requests

6 participants