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

Jump to bottom

Got empty response from API request without any logging information #18889

Open
dieisraels opened this issue Mar 7, 2022 · 3 comments
Open

Got empty response from API request without any logging information #18889

dieisraels opened this issue Mar 7, 2022 · 3 comments
Labels
Potential Bug Something that might be a bug, but needs validation and confirmation it can be reproduced.
Milestone
For Prioritization

Comments

@dieisraels
Copy link

The archiving process occasionally has empty API response over and over again:

DEBUG [2022-03-04 17:03:19] 18494  Running command: /opt/plesk/php/8.0/bin/php -q -d memory_limit=12G -d error_log=/var/www/vhosts/***/logs/error_log_cli /var/www/vhosts/***/httpdocs/console climulti:request -q --matomo-domain='***' --superuser 'module=API&method=CoreAdminHome.archiveReports&idSite=1&period=week&date=2022-02-28&format=json&segment=pageUrl%3D%40%25252FCCBT%25252F%2CpageUrl%3D%40.CCBT%25252F%2CpageUrl%3D%40%25252FCCBT.%2CpageUrl%3D%40.CCBT.&trigger=archivephp&skipArchiveSegmentToday=1&pid=519c9642b824b4c1f01b1c5d2a33c5b24fe128fd97750556ce40c6fb72cf004aa8af8d1b10d51a77eaac7826f68372c8d5800&runid=18494'  > /var/www/vhosts/***/httpdocs/tmp/climulti/519c9642b824b4c1f01b1c5d2a33c5b24fe128fd97750556ce40c6fb72cf004aa8af8d1b10d51a77eaac7826f68372c8d5800.output 2>&1 &
DEBUG [2022-03-04 17:03:19] 18494  Running command: /opt/plesk/php/8.0/bin/php -q -d memory_limit=12G -d error_log=/var/www/vhosts/***/logs/error_log_cli /var/www/vhosts/***/httpdocs/console climulti:request -q --matomo-domain='***' --superuser 'module=API&method=CoreAdminHome.archiveReports&idSite=1&period=week&date=2022-02-28&format=json&segment=pageUrl%3D%40%25252FCUVS%25252F%2CpageUrl%3D%40.CUVS%25252F%2CpageUrl%3D%40%25252FCUVS.%2CpageUrl%3D%40.CUVS.&trigger=archivephp&skipArchiveSegmentToday=1&pid=caa2a4b7c6775526600af6138cdc52dc3231cf778c5445ab26fc1de2584cf4b0981fe3d3d45d1281612643447c593ca102601&runid=18494'  > /var/www/vhosts/***/httpdocs/tmp/climulti/caa2a4b7c6775526600af6138cdc52dc3231cf778c5445ab26fc1de2584cf4b0981fe3d3d45d1281612643447c593ca102601.output 2>&1 &
DEBUG [2022-03-04 17:03:19] 18494  Running command: /opt/plesk/php/8.0/bin/php -q -d memory_limit=12G -d error_log=/var/www/vhosts/***/logs/error_log_cli /var/www/vhosts/***/httpdocs/console climulti:request -q --matomo-domain='***' --superuser 'module=API&method=CoreAdminHome.archiveReports&idSite=1&period=week&date=2022-02-28&format=json&segment=pageUrl%3D%40%25252FFCB%25252F%2CpageUrl%3D%40.FCB%25252F%2CpageUrl%3D%40%25252FFCB.%2CpageUrl%3D%40.FCB.%2CpageUrl%3D%40%25252FPCB%25252F%2CpageUrl%3D%40.PCB%25252F%2CpageUrl%3D%40%25252FPCB.%2CpageUrl%3D%40.PCB.&trigger=archivephp&skipArchiveSegmentToday=1&pid=973b2bfe6f7adb381fa8c0b9fb6dc345df462e6a3507d288bf7b791038920e7411e977a9078d8895eb59e7e046f0e9956a692&runid=18494'  > /var/www/vhosts/***/httpdocs/tmp/climulti/973b2bfe6f7adb381fa8c0b9fb6dc345df462e6a3507d288bf7b791038920e7411e977a9078d8895eb59e7e046f0e9956a692.output 2>&1 &
DEBUG [2022-03-04 17:03:19] 18494  Running command: /opt/plesk/php/8.0/bin/php -q -d memory_limit=12G -d error_log=/var/www/vhosts/***/logs/error_log_cli /var/www/vhosts/***/httpdocs/console climulti:request -q --matomo-domain='***' --superuser 'module=API&method=CoreAdminHome.archiveReports&idSite=1&period=week&date=2022-02-28&format=json&segment=pageUrl%3D%40%25252FNAV%25252F%2CpageUrl%3D%40.NAV%25252F%2CpageUrl%3D%40%25252FNAV.%2CpageUrl%3D%40.NAV.&trigger=archivephp&skipArchiveSegmentToday=1&pid=d839fce085bd2b21b51811ffd0046a42c324004cdde946ce4b15391fca6577509413de85e697019e171ce2374981a9747d303&runid=18494'  > /var/www/vhosts/***/httpdocs/tmp/climulti/d839fce085bd2b21b51811ffd0046a42c324004cdde946ce4b15391fca6577509413de85e697019e171ce2374981a9747d303.output 2>&1 &
DEBUG [2022-03-04 17:03:19] 18494  Running command: /opt/plesk/php/8.0/bin/php -q -d memory_limit=12G -d error_log=/var/www/vhosts/***/logs/error_log_cli /var/www/vhosts/***/httpdocs/console climulti:request -q --matomo-domain='***' --superuser 'module=API&method=CoreAdminHome.archiveReports&idSite=1&period=week&date=2022-02-28&format=json&segment=pageUrl%3D%40%25252FTR%25252F%2CpageUrl%3D%40.TR%25252F%2CpageUrl%3D%40%25252FTR.%2CpageUrl%3D%40.TR.&trigger=archivephp&skipArchiveSegmentToday=1&pid=6da6ebbc4fa3656ac1d71073ceb82e27b12f37522bcf3738e01f83e499d39d0c536d4f55753e1ada26f06a66b15f34df6b084&runid=18494'  > /var/www/vhosts/***/httpdocs/tmp/climulti/6da6ebbc4fa3656ac1d71073ceb82e27b12f37522bcf3738e01f83e499d39d0c536d4f55753e1ada26f06a66b15f34df6b084.output 2>&1 &
DEBUG [2022-03-04 17:03:19] 18494  Running command: /opt/plesk/php/8.0/bin/php -q -d memory_limit=12G -d error_log=/var/www/vhosts/***/logs/error_log_cli /var/www/vhosts/***/httpdocs/console climulti:request -q --matomo-domain='***' --superuser 'module=API&method=CoreAdminHome.archiveReports&idSite=1&period=week&date=2022-02-28&format=json&segment=pageUrl%3D%40%25252FCARS%25252F%2CpageUrl%3D%40.CARS%25252F%2CpageUrl%3D%40%25252FCARS.%2CpageUrl%3D%40.CARS.&trigger=archivephp&skipArchiveSegmentToday=1&pid=36ee011f21d20d3de3ea1ff719a38077c96baa326cdca66fbcca62f3f33220b695ff90262a24399f108fcf914c7cbfd66e735&runid=18494'  > /var/www/vhosts/***/httpdocs/tmp/climulti/36ee011f21d20d3de3ea1ff719a38077c96baa326cdca66fbcca62f3f33220b695ff90262a24399f108fcf914c7cbfd66e735.output 2>&1 &
INFO [2022-03-04 17:03:31] 18494  Archived website id 1, period = week, date = 2022-02-28, segment = 'pageUrl=@%2FCCBT%2F,pageUrl=@.CCBT%2F,pageUrl=@%2FCCBT.,pageUrl=@.CCBT.', 46 visits found. Time elapsed: 12.514s
INFO [2022-03-04 17:03:31] 18494  ''
INFO [2022-03-04 17:03:31] 18494  ''
INFO [2022-03-04 17:03:31] 18494  Archived website id 1, period = week, date = 2022-02-28, segment = 'pageUrl=@%2FNAV%2F,pageUrl=@.NAV%2F,pageUrl=@%2FNAV.,pageUrl=@.NAV.', 153 visits found. Time elapsed: 12.515s
INFO [2022-03-04 17:03:31] 18494  Archived website id 1, period = week, date = 2022-02-28, segment = 'pageUrl=@%2FTR%2F,pageUrl=@.TR%2F,pageUrl=@%2FTR.,pageUrl=@.TR.', 127 visits found. Time elapsed: 12.515s
INFO [2022-03-04 17:03:31] 18494  Archived website id 1, period = week, date = 2022-02-28, segment = 'pageUrl=@%2FCARS%2F,pageUrl=@.CARS%2F,pageUrl=@%2FCARS.,pageUrl=@.CARS.', 96 visits found. Time elapsed: 12.515s

The cron process outputs the following error message in that case:

ERROR [2022-03-04 17:03:31] 18494  Got invalid response from API request: ?module=API&method=CoreAdminHome.archiveReports&idSite=1&period=week&date=2022-02-28&format=json&segment=pageUrl%3D%40%25252FCUVS%25252F%2CpageUrl%3D%40.CUVS%25252F%2CpageUrl%3D%40%25252FCUVS.%2CpageUrl%3D%40.CUVS.&trigger=archivephp&skipArchiveSegmentToday=1. 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 [2022-03-04 17:03:31] 18494  Error unserializing the following response from ?module=API&method=CoreAdminHome.archiveReports&idSite=1&period=week&date=2022-02-28&format=json&segment=pageUrl%3D%40%25252FCUVS%25252F%2CpageUrl%3D%40.CUVS%25252F%2CpageUrl%3D%40%25252FCUVS.%2CpageUrl%3D%40.CUVS.&trigger=archivephp&skipArchiveSegmentToday=1: ''
ERROR [2022-03-04 17:03:31] 18494  Got invalid response from API request: ?module=API&method=CoreAdminHome.archiveReports&idSite=1&period=week&date=2022-02-28&format=json&segment=pageUrl%3D%40%25252FFCB%25252F%2CpageUrl%3D%40.FCB%25252F%2CpageUrl%3D%40%25252FFCB.%2CpageUrl%3D%40.FCB.%2CpageUrl%3D%40%25252FPCB%25252F%2CpageUrl%3D%40.PCB%25252F%2CpageUrl%3D%40%25252FPCB.%2CpageUrl%3D%40.PCB.&trigger=archivephp&skipArchiveSegmentToday=1. 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 [2022-03-04 17:03:31] 18494  Error unserializing the following response from ?module=API&method=CoreAdminHome.archiveReports&idSite=1&period=week&date=2022-02-28&format=json&segment=pageUrl%3D%40%25252FFCB%25252F%2CpageUrl%3D%40.FCB%25252F%2CpageUrl%3D%40%25252FFCB.%2CpageUrl%3D%40.FCB.%2CpageUrl%3D%40%25252FPCB%25252F%2CpageUrl%3D%40.PCB%25252F%2CpageUrl%3D%40%25252FPCB.%2CpageUrl%3D%40.PCB.&trigger=archivephp&skipArchiveSegmentToday=1: ''

I have increased the log level of Matomo to DEBUG, but there are no log entries for the API requests. I explicitly redirect the PHP error logging to a file. I have additionally checked the logging of PHP errors on the CLI this way and it works. However, the archiving process does not write errors to the PHP log.

It does not always abort the same API requests. At a later time the segmet could be processed.

What are my options for further error analysis? What could be reasons for API requests aborting?

Your Environment

  • Matomo-Version: 4.7.1
  • MySQL-Version: 10.5.15-MariaDB
  • PHP-Version: 8.0.16
  • Server Operating System: CentOS Linux release 7.9.2009 (Core)
@dieisraels dieisraels added the Potential Bug Something that might be a bug, but needs validation and confirmation it can be reproduced. label Mar 7, 2022
@sgiehl
Copy link
Member

sgiehl commented Mar 7, 2022

Hi @dieisraels. Sorry to hear you are having issues with the archiving.
Those segments on page urls are known to be a bit memory and time consuming, especially when they are not using an exact match.
Are you using some custom configuration for [General] enable_segments_cache or enable_segments_subquery_cache?

@dieisraels
Copy link
Author

No, I have not made any customizations to the above settings. I have made the following (possibly relevant) changes in the [Generic] section:

enabled_periods_UI = "day,week,month,year"
browser_archiving_disabled_enforce = 1
minimum_memory_limit_when_archiving = 4096
force_ssl = 1
datatable_archiving_maximum_rows_subtable_referrers = 500
datatable_archiving_maximum_rows_actions = 1000
datatable_archiving_maximum_rows_subtable_actions = 500
datatable_archiving_maximum_rows_events = 1000
datatable_archiving_maximum_rows_subtable_events = 100

@DBX12
Copy link

DBX12 commented Mar 23, 2022

However, the archiving process does not write errors to the PHP log.
That is something I can confirm. My instance (4.8.0 on php 8.0.13) also does not log into the error log file. Running error_log("Test") creates the log file and writes the log line "Test" to it.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
Potential Bug Something that might be a bug, but needs validation and confirmation it can be reproduced.
Projects
None yet
Milestone
For Prioritization
Development

No branches or pull requests
4 participants
@dieisraels @sgiehl @DBX12 @innocraft-automation