refs #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/ ?

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

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

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?

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.

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

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?

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.

@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."

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.

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?

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

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"

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

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

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

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

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.

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.

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.

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

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

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

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.

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

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

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;
    }

✨✨ 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!

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

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

Thanks for this.

There's something wrong in that case potentially with our detection of whether Cli Async Archiving is supported or not.

@githubyouser as the change you made that makes the archiving work would be overwritten with the next update, you want as a workaround create a file config/config.php and paste below content in there:

<?php

return [

    'observers.global' => DI\add(array(
        array('CliMulti.supportsAsync', DI\value(function (&$supportsAsync) {
            $supportsAsync = false;
        })),
    ))
];

This way it should always work for you also when you update to a newer Matomo version.

I will update the name of the title to eventually offer a config option to force disable async archiving.

Interesting would be also to think further why async support was not detect correctly or whether maybe the issue is with something else. The question where is the error 'echo: write error on stdout ' coming from.

Thanks, @tsteur. I created the config.php file according to your instructions, so hopefully we won't have any more trouble with it! :) If there's any further troubleshooting I can help with on my installation, please let me know. I'll be happy to help make Matomo better and less buggy!