@blankse opened this Pull Request on June 28th 2018 Contributor

In the core:archive command I get following message for every site:

Got invalid response from API request: ...
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

After looking in the code I found following solution.

The sub commands are executed in the background with the & sign.
The output file doesn't exists when it is looking for content.

@mattab commented on June 28th 2018 Member

Hi @blankse
Thanks for the PR.
Could you please post the output of core:archive after you make the change? Do you get some useful information then?

(in theory the message would be displayed when there was an empty response so it shouldn't hide information. and it's on purpose to run in the background so we could run multiple at once)

@blankse commented on June 29th 2018 Contributor

Hi @mattab

Before:

INFO [2018-06-29 07:50:27] 18974  - tracking data found for website id 212 since 2018-06-29 06:50:29 UTC (since the last successful archiving)
INFO [2018-06-29 07:50:27] 18974  Will pre-process for website id = 212, period = day, date = last2
INFO [2018-06-29 07:50:27] 18974  - pre-processing all visits
ERROR [2018-06-29 07:50:28] 18974  Got invalid response from API request: ?module=API&method=API.get&idSite=212&period=day&date=last2&format=php&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 [2018-06-29 07:50:28] 18974  Empty or invalid response '' for website id 212, Time elapsed: 0.133s, skipping

After:

INFO [2018-06-29 06:43:45] 14678  - tracking data found for website id 212 since 2018-06-29 00:21:12 UTC (since the last successful archiving)
INFO [2018-06-29 06:43:45] 14678  Will pre-process for website id = 212, period = day, date = last2
INFO [2018-06-29 06:43:45] 14678  - pre-processing all visits
INFO [2018-06-29 06:43:46] 14678  Archived website id = 212, period = day, 0 segments, 8 visits in last 2 days, 1 visits today, Time elapsed: 0.637s
INFO [2018-06-29 06:43:46] 14678  Will pre-process for website id = 212, period = week, date = last2
INFO [2018-06-29 06:43:46] 14678  - pre-processing all visits
INFO [2018-06-29 06:43:47] 14678  Archived website id = 212, period = week, 0 segments, 82 visits in last 2 weeks, 28 visits this week, Time elapsed: 1.422s
INFO [2018-06-29 06:43:47] 14678  Will pre-process for website id = 212, period = month, date = last2
INFO [2018-06-29 06:43:47] 14678  - pre-processing all visits
INFO [2018-06-29 06:43:49] 14678  Archived website id = 212, period = month, 0 segments, 119 visits in last 2 months, 119 visits this month, Time elapsed: 1.715s
INFO [2018-06-29 06:43:49] 14678  Will pre-process for website id = 212, period = year, date = last2
INFO [2018-06-29 06:43:49] 14678  - pre-processing all visits
INFO [2018-06-29 06:43:51] 14678  Archived website id = 212, period = year, 0 segments, 2046 visits in last 2 years, 640 visits this year, Time elapsed: 1.462s
INFO [2018-06-29 06:43:51] 14678  Will pre-process for website id = 212, period = range, date = previous7
INFO [2018-06-29 06:43:51] 14678  - pre-processing all visits
INFO [2018-06-29 06:43:52] 14678  Archived website id = 212, period = range, 0 segments, 43 visits in previous 7 ranges, 43 visits this range, Time elapsed: 1.123s
INFO [2018-06-29 06:43:52] 14678  Archived website id = 212, 5 API requests, Time elapsed: 6.363s [148/327 done]

(in theory the message would be displayed when there was an empty response so it shouldn't hide information. and it's on purpose to run in the background so we could run multiple at once)

But than we don't know if the sub command is successfull. We have empty reports because of memory limit errors. When the commands should be async, it should be a mechanism, which look with a timeout after the contents in the tmp files.

@mattab commented on July 2nd 2018 Member

We have empty reports because of memory limit errors. When the commands should be async, it should be a mechanism, which look with a timeout after the contents in the tmp files.

This is how it's supposed to work already, the code is in core/CliMulti.php

Maybe something didn't work in your case but in theory it should work fine?

@blankse commented on July 4th 2018 Contributor

@mattab I looked deeper.

The Proccess creates a *.pid File with the PID. This PID is generated by the CliMulti class and is passed to the command in the query argument.

I think the command ignore this PID. So the PID is not in the RunningProcesses List and the process instantly finished.

How is this PID query argument working?

@blankse commented on July 4th 2018 Contributor

@mattab I found it. The RequestCommand writes the getmypid() in the file and remove it at the end of the process.

We get running processes over ps ex but not the own...
So I change the isSupported function.

@diosmosis commented on July 8th 2018 Member

Hi @blankse thanks for updating the PR!

I looked at the code and I'm not sure if this is the cause of your issue. RequestCommand doesn't receive a pid, but the name of the pid file (see https://github.com/matomo-org/matomo/blob/3.x-dev/core/CliMulti.php#L311). RequestCommand will check if the file exists & is not empty, so it doesn't execute ps there.

Can you confirm that the RequestCommand command exits immediately after starting?

@blankse commented on July 10th 2018 Contributor

@diosmosis The CliMulti class create a empty pid file and give the name with the query to the RequestCommand.

The RequestCommand writes its PID in this file:
https://github.com/matomo-org/matomo/blob/3.x-dev/core/CliMulti/RequestCommand.php#L66
https://github.com/matomo-org/matomo/blob/3.x-dev/core/CliMulti/Process.php#L96

The CliMulti check this file (Empty = not started, Full and in the proccess list = started, Full and not in the proccess list = finished)
https://github.com/matomo-org/matomo/blob/3.x-dev/core/CliMulti.php#L386
https://github.com/matomo-org/matomo/blob/3.x-dev/core/CliMulti/Process.php#L101

My system can not load the own proccesses. So it thinks the RequestCommand is immediately
finished.

@diosmosis commented on July 10th 2018 Member

@blankse If RequestCommand writes the PID to the file, then I would expect CliMulti would read the contents successfully. Or are you saying that when RequestCommand writes getmypid(), the file is still blank?

Btw, what system are you running matomo on? Maybe I can try and reproduce.

@blankse commented on July 10th 2018 Contributor

@diosmosis The RequestCommand can write its PID in the file. CliMulti can read this PID successfully. But in the ProcessList (which is loaded with ps ex) this PID is not present.
https://github.com/matomo-org/matomo/blob/3.x-dev/core/CliMulti/Process.php#L248

It is a managed hosting with Linux Gentoo.

@tsteur commented on July 10th 2018 Member

I haven't tested it but by the looks it makes sense 👍

@diosmosis commented on July 11th 2018 Member

@tsteur But CliMulti executes ps and RequestCommand runs in a separate process, so it shouldn't matter if ps doesn't return getmypid(). If ps doesn't return child processes then that is an issue, but the test for that in isSupported() in this PR would need to be different. Or am I misunderstanding?

@tsteur commented on July 11th 2018 Member

To me it just sounds good that when the process doesn't find its own pid in the list of processes, something is likely wrong/ not supported. I presume in general that ps would not return any of the process in the user's case. Neither this process, nor any child process etc as it might be restricted by the hoster?

@diosmosis commented on July 11th 2018 Member

A reasonable hypothesis. But adding this check might create confusion later on as it suggests the parent process needs to know the child process' PID. I believe this problem merits further investigation. It would be good to know the root cause.

But then @blankse may not have time to dig any deeper so there may not be an opportunity to look further.

@diosmosis commented on July 12th 2018 Member

Given @tsteur's approval will merge this, thanks for the PR and thanks for debugging this yourself, @blankse!

This Pull Request was closed on July 12th 2018
Powered by GitHub Issue Mirror