@githubyouser opened this Issue on October 1st 2021

I've been experiencing an issue with Matomo core:archive scheduled cron jobs throwing "Got invalid response from API request: The response was empty" errors ever since I upgraded to Matomo 4.4.1. Not all of the API requests fail, only a few, and there doesn't seem to be any pattern to which ones fail.

My scheduled cron task sends me an email with errors every single time the cron job runs (hourly), until I have ~800 emails from the past few weeks. More details.
Strangely, if I run the exact same command manually via SSH, it will always complete successfully without any errors.

The Error Message

Your scheduled task "matomo" on site _____:

php /home/public/stats/matomo/console core:archive
--url=https://www.matomo.matomo/stats/matomo/ >/dev/null

completed at 2021-08-23 18:03:39 UTC after 3 minutes, 6 seconds and
produced the following output:

ERROR [2021-08-23 18:01:03] 29023  Got invalid response from API request:
?module=API&method=CoreAdminHome.archiveReports&idSite=3&period=day&date=2021-08-23&format=json&trigger=archivephp.
The response was empty. This usually means a server error. A solution to
this error is generally to increase the value of 'memory_limit' in your
php.ini file.  For more information and the error message please check in
your PHP CLI error log file. As this core:archive command triggers PHP
processes over the CLI, you can find where PHP CLI logs are stored by
running this command: php -i | grep error_log
ERROR [2021-08-23 18:01:03] 29023  Error unserializing the following
response from
?module=API&method=CoreAdminHome.archiveReports&idSite=3&period=day&date=2021-08-23&format=json&trigger=archivephp:
''

Obviously, I've tried raising the memory limit, but I'm quite sure that's not the real issue, and it didn't make the errors go away.
I've tried debugging further, but neither PHP nor Matomo will log any meaningful errors to shed any more light on the issue. A full summary of what I've tried already and additional info can be found at the Matomo forums: (https://forum.matomo.org/t/uncaught-exception-matomo-core-cronarchive-php-599-got-invalid-response-from-api-request/42849)
Downgrading to Matomo 4.3.1 temporarily solved the problem for me, so I'm stuck using an old version of Matomo until this issue can be resolved. I will be happy to provide any additional details/logs if they would be helpful.

Your Environment

Matomo version: 4.4.1
MySQL version: 10.5.8-MariaDB-1:10.5.8+maria~bionic
PHP version: 7.4.21
Server Operating System: FreeBSD

@tsteur commented on October 3rd 2021 Member

refs https://github.com/matomo-org/matomo/issues/13180

@githubyouser Sorry about the trouble. I've had a look through the linked forum post. I think I didn't see any PHP error logs. Any chance you could check them or enable them?

Also could you paste a copy of the system report here see https://matomo.org/faq/troubleshooting/how-do-i-find-and-copy-the-system-check-in-matomo-on-premise/ ?

@githubyouser commented on October 4th 2021

Thanks, @tsteur. I have enabled PHP logs, but unfortunately, nothing seems to show up relating to my issue. This is all I've got for the past month or so from Matomo. (The 4.3.1 error is from when I downgraded to see if that fixed the problem.)

[19-Aug-2021 21:59:36 UTC] ERROR Piwik\ExceptionHandler[2021-08-19 21:59:36 UTC] [64e4f] Uncaught exception: /home/public/stats/matomo/plugins/CorePluginsAdmin/Controller.php(577): Could not verify the security token on this form. [Query: ?module=CorePluginsAdmin&action=activate&pluginName=DBStats&nonce=d7ad89924d11a540ec5ffaa3f78db0c2&redirectTo=referrer&referrer=https%3A%2F%2Fwww.admin.mrgreekgeek.com%2Fstats%2Fmatomo%2Findex.php%3Fmodule%3DCorePluginsAdmin%26action%3Dplugins%26idSite%3D1%26period%3Dday%26date%3Dyesterday%26activated%3D, CLI mode: 0]

[19-Aug-2021 21:59:36 UTC] Error in Matomo: Could not verify the security token on this form.
[25-Aug-2021 02:46:20 UTC] Error in Matomo (tracker): Invalid idSite: '0'
[26-Aug-2021 13:18:24 UTC] Error in Matomo (tracker): Invalid idSite: '0'

[17-Sep-2021 16:23:14 UTC] Error in Matomo (tracker): Invalid idSite: '0'

[28-Sep-2021 22:06:05 UTC] Error in Matomo: Your Matomo codebase is running the old version 4.3.1 and we have detected that your Matomo Database has already been upgraded to the newer version 4.4.1. Maybe your Matomo administrators are currently finishing the upgrade process. Please try again in a few minutes. If you still have this issue please contact your Matomo administrator for assistance. 

[04-Oct-2021 00:04:03 UTC] Error in Matomo (tracker): Invalid idSite: '0'
[04-Oct-2021 00:05:09 UTC] Error in Matomo (tracker): Invalid idSite: '0'

Let me get my 4.4.1 installation running again here, (I left it in place so I can quickly switch back to it) and I'll get a system report for you shortly. Thanks for looking into this!

EDIT: Here's the system check: matomo_system_check.txt

@githubyouser commented on October 7th 2021

@tsteur If you need any further information, please don't hesitate to ask.

@tsteur commented on October 7th 2021 Member

Thanks for this @githubyouser It's hard to say what could cause this since it works when executing manually. Is it maybe using a different PHP binary when it's running from the cronjob? Maybe that one has a different php ini? Maybe it helps in the cronjob to define the path to the php binary that you are using when executing it manually. Might make no difference but trying to understand what could be different when executing in cronjob and when manually.

Could you maybe remove the cronjob for few hours and then execute it manually to see if you can then reproduce it maybe?

@githubyouser commented on October 8th 2021

Thanks @tsteur. I double-checked, and the the path to the PHP binaries is the same. They're also using the same php ini.

I removed the cron job and waited a few hours, then ran the archive job manually via SSH, but the task finished in 198 seconds with no errors.

Interestingly, my cron job did run once without an error this morning! But I have no idea why, or what the difference was.
2021-10-08 11:02:09 | Scheduled task "matomo" completed after 1 minute, 47 seconds.

@tsteur commented on October 10th 2021 Member

@githubyouser thanks for this update. It's hard to say what's happening there without knowing the system in & out etc. Is there maybe some way that cronjobs are terminated after a while? Possible that it now completed some tasks and next time the cron ran a bit faster and wasn't terminated early. Generally, this looks like a server configuration issue as it works fine when running it manually. I would recommend you look if there are any restrictions for cronjobs. Unfortunately I'm not an expert but maybe you can also check with your hoster etc?

@githubyouser commented on October 11th 2021

Thanks for continuing to pursue this with me, @tsteur. I just asked my host about this, and linked to this issue so they can take a look into it.

In the mean time, is there any way I can have Matomo put out some more useful debug information? Maybe inject some logging code somewhere to give more precise error messages about what is actually going wrong behind the scenes?
Also, I see that Matomo 4.5.0 has been released. Shall I upgrade, or would it be better to get this issue resolved first?

@tsteur commented on October 11th 2021 Member

It's up to you whether you want to upgrade. I would probably recommend as there's always a small chance that it will fix something. Although I don't think it will in this case as it does look like a server configuration issue.

Regarding additional logging or so I'm not 100% sure but I would definitely wait first regarding what your hoster says.

@githubyouser commented on October 11th 2021

@tsteur here's what my host says:

"If Matomo says there were 4 problems or 6 problems or whatever, then it should be able to tell you what they are. A program that exits unsuccessfully without producing a diagnostic error is a broken program.

If Matomo can provide useful feedback about some actual problem, we'll be happy to help you look into it."

@tsteur commented on October 12th 2021 Member

thanks for this @githubyouser

Did you maybe ask them if there are any kind of restrictions on cronjobs or so? Like a time limit?

If there was a logic that simply aborts/kills the process that is being executed, then there wouldn't be much we can log. Currently I don't really think there's actually a problem in Matomo as it seems to work fine when you execute it manually. However, it doesn't seem to work when it runs as a cronjob so there must be some difference.

The error message in Matomo says The response was empty. This usually means a server error.. Basically, something might be simply aborting the request/command. In that case there wouldn't be much we can do.

Sorry for all this and lots of forth and back and you being in the middle! It be great to check with them generally if there's any kind of restrictions on the cronjobs (like a time limit) or anything that would explain this.

@githubyouser commented on October 12th 2021

I'm pretty sure there's no time limit on cron jobs, as the tasks do eventually finish, it's just that a few of the API calls are empty for some reason.

INFO [2021-10-12 02:04:17] 23012  Done archiving!
INFO [2021-10-12 02:04:17] 23012  ---------------------------
INFO [2021-10-12 02:04:17] 23012  SUMMARY
INFO [2021-10-12 02:04:17] 23012  Processed 28 archives.
INFO [2021-10-12 02:04:17] 23012  Total API requests: 32
INFO [2021-10-12 02:04:17] 23012  done: 32 req, 218785 ms, 8 errors.
INFO [2021-10-12 02:04:17] 23012  Time elapsed: 218.785s
INFO [2021-10-12 02:04:17] 23012  ---------------------------

My host is convinced that it's not their problem, (and said so very emphatically) while you seem to think that it is server-side, so I don't know what to do next! :/ I'll try upgrading in the morning, and if that doesn't work, is there any way we can try to ask Matomo for more debugging info?

@githubyouser commented on October 12th 2021

Here's the most recent log from today. As I look closely at it, it seems that all of the requests that are failing are for today's data. Could it be because there's not enough data to process? Some of my sites are very low traffic, and it's possible that they don't have any traffic to report for today.

matomo.txt

@tsteur commented on October 13th 2021 Member

Could you try running below command and see if that prints anything?

./console climulti:request -q --superuser "module=API&method=CoreAdminHome.archiveReports&idSite=3&period=week&date=today&format=json&pid=e548fdf6c3b06f2a669d973af6ff0759f74e43b1279ce193a2052427218aea4f660&runid=2382"
@githubyouser commented on October 13th 2021

@tsteur do you want this run from a cronjob or just from my SSH commandline?

@githubyouser commented on October 13th 2021

I ran it from the command line and got the following response:
{"idarchives":["27813"],"nb_visits":"6"}

@tsteur commented on October 13th 2021 Member

I meant the command line. I see that works. It could be interesting to run it on the crontab too to see if there's any kind of difference. Maybe crontab could run this in say 1-2 hours? I wouldn't run it again right away as it might not give us the result we're after as the reports might not be regenerated

@githubyouser commented on October 13th 2021

Here's the response from the cronjob: {"idarchives":["28176"],"nb_visits":"6"}

@tsteur commented on October 15th 2021 Member

Thanks for this @githubyouser

Could you try to edit your config/config.ini.php and add below content:

[log]
log_writers[] = "file"
log_level = DEBUG

This will set the logging to file. You can then later check in $matomoDir/tmp/logs/matomo.log if any kind of error or information was logged. You will then eventually want to remove these lines again from the config.

There might be also some other logs like the one below which might be expected.
image

I don't know if you can modify your PHP ini settings but you'll also want to check that log_errors=On is configured. Otherwise the PHP logs might not show anything.

@githubyouser commented on October 16th 2021

Thanks, @tsteur I've enabled DEBUG for Matomo logs and PHP logs are enabled as well.
A few hours later I've already got ~9MB of Matomo DEBUG logs. Is there anything in particular I should be looking for? I'm not finding any that start with ERROR, only DEBUG or INFO entries.

@githubyouser commented on October 19th 2021

@tsteur I'm not seeing any Matomo errors show up in the PHP log. :(
The tasks do seem to be completing more often without errors though! Just today there were a couple of times when the cron job shows Archiving was last executed without error 57 min 16s ago (it runs every hour). So that's hopeful, but still doesn't tell me what the actual issue might be.

@tsteur commented on October 20th 2021 Member

@githubyouser it might be otherwise good if you could pause the cronjob again for a day and then run it again manually. This should then definitely confirm there is something terminating a process when it's run as cronjob.

It's a bit of wild guessing but what might be also worth a try could be to use --concurrent-requests-per-website=1 option for the core:archive command. It might not do anything but it can be worth a try.

Otherwise I'm not an expert in Linux. I wonder if there's any kind of logging possible when a process gets suddenly terminated.

@githubyouser commented on October 21st 2021

@tsteur I paused the cron job for several hours yesterday, and then ran it with the --concurrent-requests-per-website=1 option, but I'm still getting the same errors. I'll pause it again today for a few hours, and then run it manually via SSH to see if anything different happens.

@githubyouser commented on October 21st 2021

And I just now realized as I look through the logs since enabling the cron job again that I'm now getting a new error message! Could the concurrent-requests option have triggered that, @tsteur? Or maybe that's just a fluke from letting it go several hours without archiving.

INFO [2021-10-20 23:04:11] 22951  Error: Got invalid response from API
request:
?module=API&method=CoreAdminHome.archiveReports&idSite=4&period=month&date=2021-10-01&format=json&trigger=archivephp.
Response was 'echo: write error on stdout '
INFO [2021-10-20 23:04:11] 22951  Error: Error unserializing the following
response from
?module=API&method=CoreAdminHome.archiveReports&idSite=4&period=month&date=2021-10-01&format=json&trigger=archivephp:
'echo: write error on stdout '
INFO [2021-10-20 23:04:11] 22951  Error: Got invalid response from API
request:
?module=API&method=CoreAdminHome.archiveReports&idSite=6&period=week&date=2021-10-18&format=json&trigger=archivephp.
The response was empty. This usually means a server error. A solution to
this error is generally to increase the value of 'memory_limit' in your
php.ini file.  For more information and the error message please check in
your PHP CLI error log file. As this core:archive command triggers PHP
processes over the CLI, you can find where PHP CLI logs are stored by
running this command: php -i | grep error_log

EDIT: It looks like that particular error has showed up every few days for the past month or two, but it was always mixed in with the others, and I just never noticed it before.

@tsteur commented on October 21st 2021 Member

Great we're now having some error message there. 'echo: write error on stdout ' I did a quick search about this but couldn't find anything.

I found one place where such an error came up in a code for awk.

Could you try executing this command? ps x 2>/dev/null | awk '! /defunct/ {print $1}' 2>/dev/null

If that causes the issue, there may be a chance actually that there might be an improvement in the already released 4.6.0 beta 1 that would no longer use that command when using --concurrent-requests-per-website=1

@githubyouser commented on October 22nd 2021

OK, @tsteur I ran the archive command manually several hours after I paused the cron job, but it completed with no errors.
When I ran ps x 2>/dev/null | awk '! /defunct/ {print $1}' 2>/dev/null I got the following output:

PID
37181
37206
41795
@tsteur commented on October 22nd 2021 Member

Thanks. This looks as expected.

I have one suspicion. Are you familiar with changing files on the server?

If so, could you change the file in core/CliMulti/Process.php. There you would need to change these 4 lines https://github.com/matomo-org/matomo/blob/4.5.0/core/CliMulti/Process.php#L247-L251 to look like this:

    private static function awkExistsAndRunsCorrectly()
    {
        return false;
    }
@githubyouser commented on October 22nd 2021

:sparkles::sparkles: That seems to have done the trick!! The command has run without error via cron for the past 2 hours. I'll definitely keep an eye on it yet, and make sure it's not just a temporary reprieve. 😃 Thanks SO much, @tsteur for helping me work through this!

@tsteur commented on October 25th 2021 Member

@githubyouser I'll reopen it if that's alright just to fully understand a bit more what's happening.

Do you mind testing a few more things for us?

If you change the return false; to return true;, does it still work?

@githubyouser commented on October 26th 2021

@tsteur When I change it to return true; the errors start again immediately.

Powered by GitHub Issue Mirror