Bookmarks: cron.php getting stuck running CrawlJob
Describe the bug
Every 12 hours, when cron.php attempts to run CrawlJob, it gets stuck. Subsequent cron jobs will not run until it completes, so I get messages in Basic Settings -> Background jobs to the effect of "cron has not run in 10 hours, something looks wrong". Upon noticing that cron.php is stuck, I manually kill the php7 process, and cron.php runs normally at the next scheduled time and continues to do so for 12 more hours.
To Reproduce
Steps to reproduce the behavior:
- Set up cron to run cron.php every 5 minutes
- Upgrade to Bookmarks 4.1.0 (Not really sure when the issue started, took me a while to figure out it was related to the Bookmarks App.)
- Wait for cron.php to execute CrawlJob (I don't know why it does not run every 5 minutes, but in oc_jobs, last_checked == last_run == reserved_at == the last time cron.php ran and is now stuck.
- See error
Expected behavior
cron.php should run CrawlJob to completion, or report an error and quit so that cron.php may run again in the future.
Screenshots
User http's crontab:
# crontab -l -u http
*/5 * * * * /usr/bin/php7 -f /usr/share/webapps/nextcloud/cron.php &> /dev/null
7-57/15 * * * * /usr/bin/php7 /usr/share/webapps/nextcloud/occ preview:pre-generate &> /dev/null
CrawlJob entry in oc_jobs:
$ mysql -uxxxxxxxx -pxxxxxxxx -D nextcloud -e 'select * from oc_jobs where reserved_at > 0;'
+-------+---------------------------------------+----------+------------+--------------+-------------+--------------------+
| id | class | argument | last_run | last_checked | reserved_at | execution_duration |
+-------+---------------------------------------+----------+------------+--------------+-------------+--------------------+
| 13377 | OCA\Bookmarks\BackgroundJobs\CrawlJob | null | 1618222913 | 1618222913 | 1618222913 | 0 |
+-------+---------------------------------------+----------+------------+--------------+-------------+--------------------+
Desktop (please complete the following information):
- OS: Arch Linux
- Browser: Firefox
- Version: 87
Server (please complete the following information):
- OS: Arch Linux
- HTTP server: nginx-mainline 1.19.9-1
- Database: mariadb 10.5.9-1
- PHP version: php7 7.4.16-1
- Nextcloud version: 20.0.8
- Bookmarks app version: 4.1.0
- Activated Nextcloud Apps: [the output of running
$ sudo -u www-data php occ app:listin your command line]
```
runuser -u http -- php7 /usr/share/webapps/nextcloud/occ app:list
Enabled:
- accessibility: 1.6.0
- activity: 2.13.4
- announcementcenter: 4.0.1
- apporder: 0.12.0
- bookmarks: 4.1.0
- bruteforcesettings: 2.1.0
- calendar: 2.2.0
- carnet: 0.23.8
- cloud_federation_api: 1.3.0
- cms_pico: 1.0.15
- comments: 1.10.0
- contacts: 3.5.1
- contactsinteraction: 1.1.0
- cookbook: 0.8.4
- dashboard: 7.0.0
- dav: 1.16.2
- federatedfilesharing: 1.10.2
- federation: 1.10.1
- files: 1.15.0
- files_markdown: 2.3.3
- files_pdfviewer: 2.0.1
- files_rightclick: 0.17.0
- files_sharing: 1.12.2
- files_texteditor: 2.14.0
- files_trashbin: 1.10.1
- files_versions: 1.13.0
- files_videoplayer: 1.9.0
- firstrunwizard: 2.9.0
- logreader: 2.5.0
- lookup_server_connector: 1.8.0
- nextcloud_announcements: 1.9.0
- notes: 4.0.4
- notifications: 2.8.0
- oauth2: 1.8.0
- password_policy: 1.10.1
- passwords: 2021.4.0
- phonetrack: 0.6.7
- photos: 1.2.3
- previewgenerator: 3.1.1
- privacy: 1.4.0
- provisioning_api: 1.10.0
- recommendations: 0.8.0
- serverinfo: 1.10.0
- settings: 1.2.0
- sharebymail: 1.10.0
- spreed: 10.0.6
- support: 1.3.0
- survey_client: 1.8.0
- systemtags: 1.10.0
- tasks: 0.13.6
- text: 3.1.0
- theming: 1.11.0
- twofactor_backupcodes: 1.9.0
- unsplash: 1.2.2
- updatenotification: 1.10.0
- user_status: 1.0.1
- viewer: 1.4.0
- weather: 1.7.5
- weather_status: 1.0.0
- workflowengine: 2.2.0
Disabled: - admin_audit
- dicomviewer
- encryption
- files_external
- user_ldap
```
- Nextcloud configuration: [the output of running
sudo -u www-data php occ config:list system]
- Nextcloud configuration: [the output of running
# runuser -u http -- php7 /usr/share/webapps/nextcloud/occ config:list system
{
"system": {
"instanceid": "***REMOVED SENSITIVE VALUE***",
"passwordsalt": "***REMOVED SENSITIVE VALUE***",
"secret": "***REMOVED SENSITIVE VALUE***",
"trusted_domains": [
"monster.bostrom.org",
"gremlin.homelinux.org"
],
"datadirectory": "***REMOVED SENSITIVE VALUE***",
"defaultapp": "apporder",
"overwrite.cli.url": "***REMOVED SENSITIVE VALUE***",
"dbtype": "mysql",
"version": "20.0.8.1",
"logtimezone": "UTC",
"log_rotate_size": 16777216,
"loglevel": 0,
"memcache.local": "\\OC\\Memcache\\APCu",
"asset-pipeline.enabled": false,
"session_lifetime": 21600,
"session_keepalive": true,
"installed": true,
"theme": "",
"maintenance": false,
"htaccess.RewriteBase": "\/nextcloud",
"mail_smtpmode": "smtp",
"mail_smtpauthtype": "LOGIN",
"mail_smtpsecure": "ssl",
"mail_from_address": "***REMOVED SENSITIVE VALUE***",
"mail_domain": "***REMOVED SENSITIVE VALUE***",
"mail_smtphost": "***REMOVED SENSITIVE VALUE***",
"mail_smtpport": "465",
"mail_smtpauth": 1,
"mail_smtpname": "***REMOVED SENSITIVE VALUE***",
"mail_smtppassword": "***REMOVED SENSITIVE VALUE***",
"enable_previews": true,
"preview_max_x": 1024,
"preview_max_y": 1024,
"dbname": "***REMOVED SENSITIVE VALUE***",
"dbhost": "***REMOVED SENSITIVE VALUE***",
"dbuser": "***REMOVED SENSITIVE VALUE***",
"dbpassword": "***REMOVED SENSITIVE VALUE***",
"has_rebuilt_cache": true,
"mysql.utf8mb4": true,
"encryption.legacy_format_support": false,
"encryption.key_storage_migrated": false,
"trashbin_retention_obligation": "auto, 180"
}
}
- Nextcloud external user backend: none
Additional context
Add any other context about the problem here.
Web server error log
N/A
Nextcloud log (nextcloud/data/nextcloud.log)
I've not noticed any messages in nextcloud.log related to CrawlJob. It rolls over too fast due to all the OCP\SabrePluginEvent info messages generated.
Browser log
N/A
donb9000
All 34 comments
Mh. This is strange. Does the process run at max CPU? Or does it idle?
marcelklehr
on 12 Apr 2021
Mh. This is strange. Does the process run at max CPU? Or does it idle?
It seems to be blocked and does not accumulate CPU time.
donb9000
on 12 Apr 2021
3. Wait for cron.php to execute CrawlJob (I don't know why it does not run every 5 minutes, but in oc_jobs, last_checked == last_run == reserved_at == the last time cron.php ran and is now stuck.https://github.com/nextcloud/bookmarks/blob/bbc32b67e6a5792074a4130a04b5526fcd563064/lib/BackgroundJobs/CrawlJob.php#L22
CrawlJob is set to run every 30 minutes. If there is something wrong with CrawlJob, the log entries may be found by executing
cat /path/to/your/data/nextcloud.log | grep CrawlJob.
And it's service classes.
cat /path/to/your/data/nextcloud.log | grep CrawlService
cat /path/to/your/data/nextcloud.log | grep BookmarkPreviewer
HouraisanNEET
on 13 Apr 2021
It could be that there's a bookmark to a URL that doesn't respond or takes a long time or simply serves a large file (think GBs), which will be downloaded. I've added some sanity checks so there's no surprises when downloading things: 68cdf45
marcelklehr
on 13 Apr 2021
3. Wait for cron.php to execute CrawlJob (I don't know why it does not run every 5 minutes, but in oc_jobs, last_checked == last_run == reserved_at == the last time cron.php ran and is now stuck.CrawlJob is set to run every 30 minutes. If there is something wrong with CrawlJob, the log entries may be found by executing
cat /path/to/your/data/nextcloud.log | grep CrawlJob.
And it's service class.
cat /path/to/your/data/nextcloud.log | grep CrawlService
cat /path/to/your/data/nextcloud.log | grep BookmarkPreviewer
Here is the output:
# ag CrawlJob nextcloud.log*
nextcloud.log.1
3699:{"reqId":"GWxgQhObLcWpfTBXpOgt","level":0,"time":"2021-04-13T10:25:02+00:00","remoteAddr":"","user":"--","app":"cron","method":"","url":"--","message":"Run OCA\\Bookmarks\\BackgroundJobs\\CrawlJob job with ID 13377","userAgent":"--","version":"20.0.8.1"}
# ag CrawlService nextcloud.log*
# ag BookmarkPreviewer nextcloud.log*
#
It could be that there's a bookmark to a URL that doesn't respond or takes a long time or simply serves a large file (think GBs), which will be downloaded. I've added some sanity checks so there's no surprises when downloading things: 68cdf45
How would I go about finding the "bad" URL if that is the case? I have 300+ bookmarks (I know, not a lot by some standards :-) ) but trying them one by one would get tedious.
Is there some way to run the CrawlJob on demand (via occ maybe) in debug mode and report each URL as it is checked?
donb9000
on 13 Apr 2021
Also, is it an issue that the reserved_at field has a value when the CrawlJob would otherwise have run?
None of the other jobs have a value greater than zero, and I did notice one job briefly have a reserved_at value, but it was quickly reset before cron.php ended.
I could set reserved_at to zero before the next cron.php cycle to see what happens if you think that would be useful.
$mysql -uxxxxxx -pxxxxxx -D nextcloud -e 'select * from oc_jobs where reserved_at > 0;'
+-------+---------------------------------------+----------+------------+--------------+-------------+--------------------+
| id | class | argument | last_run | last_checked | reserved_at | execution_duration |
+-------+---------------------------------------+----------+------------+--------------+-------------+--------------------+
| 13377 | OCA\Bookmarks\BackgroundJobs\CrawlJob | null | 1618309502 | 1618309502 | 1618309502 | 0 |
+-------+---------------------------------------+----------+------------+--------------+-------------+--------------------+
How would I go about finding the "bad" URL if that is the case? I have 300+ bookmarks (I know, not a lot by some standards :-) ) but trying them one by one would get tedious.
Maybe share your bookmarks? But NC users care about privacy so I am not sure.
Also, is it an issue that the reserved_at field has a value when the CrawlJob would otherwise have run?
None of the other jobs have a value greater than zero, and I did notice one job briefly have a reserved_at value, but it was quickly reset before cron.php ended.
I could set reserved_at to zero before the next cron.php cycle to see what happens if you think that would be useful.
According the output, you got it again. If it's greater than 0, it's inactive, and reset is required.
Would you consider testing the patch 68cdf45? Make sure your bookmarks have a backup first.
https://raw.githubusercontent.com/nextcloud/bookmarks/68cdf453f7d7e86f5883e5422cef059bd5a606b1/lib/Service/CrawlService.php
Replace your CrawlService.php with it and see if the issue is fixed.
HouraisanNEET
on 14 Apr 2021
Replace your CrawlService.php with it and see if the issue is fixed.
Sadly this won't work, as there have been other changes to the file in this repo that require a database migration as well as changing other files. Perhaps applying only the patch works, though.
marcelklehr
on 14 Apr 2021
Also, is it an issue that the reserved_at field has a value when the CrawlJob would otherwise have run?
According the output, you got it again. If it's greater than 0, it's inactive, and reset is required.
I set reserved_at to zero, and cron.php got stuck again at the next 5 minute cycle. Additionally, I think CrawlJob is getting stuck very early in its task because there are still no logs reported by any of the supporting classes. Just the one log entry indicating that it was started.
# ag CrawlJob nextcloud.log*
nextcloud.log
30:{"reqId":"uw8pdVa1LzXYyKW5VhFC","level":0,"time":"2021-04-14T10:15:03+00:00","remoteAddr":"","user":"--","app":"cron","method":"","url":"--","message":"Run OCA\\Bookmarks\\BackgroundJobs\\CrawlJob job with ID 13377","userAgent":"--","version":"20.0.8.1"}
nextcloud.log.1
24720:{"reqId":"pXm7COFQ4hZSj2nmC7Mf","level":0,"time":"2021-04-13T22:30:02+00:00","remoteAddr":"","user":"--","app":"cron","method":"","url":"--","message":"Run OCA\\Bookmarks\\BackgroundJobs\\CrawlJob job with ID 13377","userAgent":"--","version":"20.0.8.1"}
# ag CrawlService nextcloud.log*
# ag BookmarkPreviewer nextcloud.log*
#
Would you consider testing the patch 68cdf45? Make sure your bookmarks have a backup first.
Sure, I'll try that later today.
donb9000
on 14 Apr 2021
OK, I tried the patch. No change. I set reserved_at to zero and made the following edits:
# diff -u ./CrawlService.php.orig /usr/share/webapps/nextcloud/apps/bookmarks/lib/Service/CrawlService.php
--- ./CrawlService.php.orig 2021-04-14 08:36:57.657757234 -0400
+++ /usr/share/webapps/nextcloud/apps/bookmarks/lib/Service/CrawlService.php 2021-04-14 08:49:13.125852098 -0400
@@ -26,6 +26,10 @@
use OCP\Lock\LockedException;
class CrawlService {
+ public const MAX_BODY_LENGTH = 92160; // 90 MiB
+ public const CONNECT_TIMEOUT = 10;
+ public const READ_TIMEOUT = 10;
+
/**
* @var BookmarkMapper
*/
@@ -74,7 +78,7 @@
*/
public function crawl(Bookmark $bookmark): void {
try {
- $client = new Client();
+ $client = new Client(['connect_timeout' => self::CONNECT_TIMEOUT, 'read_timeout' => self::READ_TIMEOUT]);
/** @var Response $resp */
$resp = $client->get($bookmark->getUrl());
$available = $resp ? $resp->getStatusCode() !== 404 : false;
@@ -94,7 +98,7 @@
private function archiveFile(Bookmark $bookmark, Response $resp) :void {
$contentType = $resp->getHeader('Content-type')[0];
- if ((bool)preg_match('#text/html#i', $contentType) === false && $bookmark->getArchivedFile() === null) {
+ if ((bool)preg_match('#text/html#i', $contentType) === false && $bookmark->getArchivedFile() === null && (int)$resp->getHeader('Content-length')[0] < self::MAX_BODY_LENGTH) {
try {
$userFolder = $this->rootFolder->getUserFolder($bookmark->getUserId());
$folderPath = $this->getArchivePath($bookmark, $userFolder);
When the CrawlJob ran at 8:55am, these were the results:
-->mysql -uxxxxxx -pxxxxxx -D nextcloud -e 'select * from oc_jobs where id = 13377;'
+-------+---------------------------------------+----------+------------+--------------+-------------+--------------------+
| id | class | argument | last_run | last_checked | reserved_at | execution_duration |
+-------+---------------------------------------+----------+------------+--------------+-------------+--------------------+
| 13377 | OCA\Bookmarks\BackgroundJobs\CrawlJob | null | 1618404901 | 1618404901 | 1618404901 | 0 |
+-------+---------------------------------------+----------+------------+--------------+-------------+--------------------+
monster:~/nextcloud_admin (dbostrom)
-->date -d '@1618404901'
Wed Apr 14 08:55:01 EDT 2021
# ag CrawlJob nextcloud.log*
nextcloud.log
10173:{"reqId":"z4umti5K4NPUbbjFrhod","level":0,"time":"2021-04-14T12:55:01+00:00","remoteAddr":"","user":"--","app":"cron","method":"","url":"--","message":"Run OCA\\Bookmarks\\BackgroundJobs\\CrawlJob job with ID 13377","userAgent":"--","version":"20.0.8.1"}
nextcloud.log.1
30:{"reqId":"uw8pdVa1LzXYyKW5VhFC","level":0,"time":"2021-04-14T10:15:03+00:00","remoteAddr":"","user":"--","app":"cron","method":"","url":"--","message":"Run OCA\\Bookmarks\\BackgroundJobs\\CrawlJob job with ID 13377","userAgent":"--","version":"20.0.8.1"}
# ag CrawlService nextcloud.log*
# ag BookmarkPreviewer nextcloud.log*
cron.php is still stuck at 9:07am with no further messages in the log.
I am assuming at this point that the job is getting stuck in initialization somewhere due to a possible mis-configuration on my part or a corrupt database table. FYI, I do have the following in apcu.ini. The enable_cli bit was added on the recommendation of some documentation I read recently as referred to by a post indicating that strange things may happen in occ if enable_cli was not enabled. (Sorry, I don't have the forum link)
$ cat apcu.ini
extension=apcu.so
apc.enabled=1
apc.shm_size=32M
apc.ttl=7200
apc.enable_cli=1
One other thing, would it be possible for you to supply me with a debug log statement that dumps the $bookmark argument to the crawl() function in CrawlService.php (or any more appropriate place you think is better)? This way I can get a definitive answer on whether or not any bookmarks are being checked. Sorry, I am not a PHP programmer nor am I familiar with the Nextcloud API, or I would do this part myself.
donb9000
on 14 Apr 2021
For the record, here is the documentation link recommending enable_cli be set to 1.
donb9000
on 14 Apr 2021
a debug log statement that dumps the $bookmark argument to the crawl() function
Sure!
Before this line:
https://github.com/nextcloud/bookmarks/blob/bbc32b67e6/lib/Service/CrawlService.php#L76
insert the following line:
$this->logger->warning('Crawling '.$bookmark->getUrl());
marcelklehr
on 14 Apr 2021
@marcelklehr Thank you for that bit of code. I added it to CrawlService.php and it turns out that one bookmark is processed, or maybe more accurately, one has started processing and apparently never finished. I did click on that link from the bookmarks app page in Nextcloud, and the link is not broken or dead. A page was returned.
-->mysql -uxxxxxx -pxxxxxx -D nextcloud -e 'select * from oc_jobs where id = 13377;'
+-------+---------------------------------------+----------+------------+--------------+-------------+--------------------+
| id | class | argument | last_run | last_checked | reserved_at | execution_duration |
+-------+---------------------------------------+----------+------------+--------------+-------------+--------------------+
| 13377 | OCA\Bookmarks\BackgroundJobs\CrawlJob | null | 1618409101 | 1618409101 | 1618409101 | 0 |
+-------+---------------------------------------+----------+------------+--------------+-------------+--------------------+
The very last line of the following output shows the new log message with the URL that I clicked on.
# ag CrawlJob nextcloud.log*; ag CrawlService nextcloud.log*; ag BookmarkPreviewer nextcloud.log*; ag Crawling nextcloud.log*
nextcloud.log
10173:{"reqId":"z4umti5K4NPUbbjFrhod","level":0,"time":"2021-04-14T12:55:01+00:00","remoteAddr":"","user":"--","app":"cron","method":"","url":"--","message":"Run OCA\\Bookmarks\\BackgroundJobs\\CrawlJob job with ID 13377","userAgent":"--","version":"20.0.8.1"}
18568:{"reqId":"sVTNbZjZRUjSdFzIcAN9","level":0,"time":"2021-04-14T14:05:01+00:00","remoteAddr":"","user":"--","app":"cron","method":"","url":"--","message":"Run OCA\\Bookmarks\\BackgroundJobs\\CrawlJob job with ID 13377","userAgent":"--","version":"20.0.8.1"}
nextcloud.log.1
30:{"reqId":"uw8pdVa1LzXYyKW5VhFC","level":0,"time":"2021-04-14T10:15:03+00:00","remoteAddr":"","user":"--","app":"cron","method":"","url":"--","message":"Run OCA\\Bookmarks\\BackgroundJobs\\CrawlJob job with ID 13377","userAgent":"--","version":"20.0.8.1"}
nextcloud.log
18569:{"reqId":"sVTNbZjZRUjSdFzIcAN9","level":2,"time":"2021-04-14T14:05:01+00:00","remoteAddr":"","user":"--","app":"bookmarks","method":"","url":"--","message":"Crawling https://www.homedepot.com/p/Westinghouse-WGen9500DF-12-500-9-500-Watt-Dual-Fuel-Portable-Generator-with-Remote-Start-and-Transfer-Switch-Outlet-for-Home-Backup-WGen9500DF/310741071","userAgent":"--","version":"20.0.8.1"}
Again, at this point cron.php just sits there until I kill it.
donb9000
on 14 Apr 2021
If you have some time, you could join the chat over here: https://gitter.im/nextcloud-bookmarks/community then we can debug a bit :)
marcelklehr
on 14 Apr 2021
I am actually working (from home) right now :-) So I'm gonna have to pass on the chat. But if you want me to add more log/debug statements to the code, I will be happy to do that when I get the time later today. I was thinking one just before the if ($available) and one after the if's closing brace. Maybe one at the end of the crawl() function as well...
donb9000
on 14 Apr 2021
I've added more log messages to the crawl() function like so:
# diff -u CrawlService.php.orig /usr/share/webapps/nextcloud/apps/bookmarks/lib/Service/CrawlService.php
--- CrawlService.php.orig 2021-04-14 08:36:57.657757234 -0400
+++ /usr/share/webapps/nextcloud/apps/bookmarks/lib/Service/CrawlService.php 2021-04-14 11:53:09.376161460 -0400
@@ -26,6 +26,10 @@
use OCP\Lock\LockedException;
class CrawlService {
+ public const MAX_BODY_LENGTH = 92160; // 90 MiB
+ public const CONNECT_TIMEOUT = 10;
+ public const READ_TIMEOUT = 10;
+
/**
* @var BookmarkMapper
*/
@@ -73,8 +77,9 @@
* @throws UrlParseError
*/
public function crawl(Bookmark $bookmark): void {
+ $this->logger->warning('Crawling '.$bookmark->getUrl());
try {
- $client = new Client();
+ $client = new Client(['connect_timeout' => self::CONNECT_TIMEOUT, 'read_timeout' => self::READ_TIMEOUT]);
/** @var Response $resp */
$resp = $client->get($bookmark->getUrl());
$available = $resp ? $resp->getStatusCode() !== 404 : false;
@@ -83,18 +88,22 @@
}
if ($available) {
+ $this->logger->warning('Crawl Preview '.$bookmark->getUrl());
$this->archiveFile($bookmark, $resp);
$this->bookmarkPreviewer->getImage($bookmark);
$this->faviconPreviewer->getImage($bookmark);
+ $this->logger->warning('Done Crawl Preview '.$bookmark->getUrl());
}
+ $this->logger->warning('Crawl Cleanup '.$bookmark->getUrl());
$bookmark->markPreviewCreated();
$bookmark->setAvailable($available);
$this->bookmarkMapper->update($bookmark);
+ $this->logger->warning('Done Crawling '.$bookmark->getUrl());
}
private function archiveFile(Bookmark $bookmark, Response $resp) :void {
$contentType = $resp->getHeader('Content-type')[0];
- if ((bool)preg_match('#text/html#i', $contentType) === false && $bookmark->getArchivedFile() === null) {
+ if ((bool)preg_match('#text/html#i', $contentType) === false && $bookmark->getArchivedFile() === null && (int)$resp->getHeader('Content-length')[0] < self::MAX_BODY_LENGTH) {
try {
$userFolder = $this->rootFolder->getUserFolder($bookmark->getUserId());
$folderPath = $this->getArchivePath($bookmark, $userFolder);
Again, no messages after the initial URL message of "Crawling"
# ag crawl nextcloud.log.1
3858:{"reqId":"9V2ndAfGuyT065qnmYxF","level":0,"time":"2021-04-14T15:35:02+00:00","remoteAddr":"","user":"--","app":"cron","method":"","url":"--","message":"Run OCA\\Bookmarks\\BackgroundJobs\\CrawlJob job with ID 13377","userAgent":"--","version":"20.0.8.1"}
3859:{"reqId":"9V2ndAfGuyT065qnmYxF","level":2,"time":"2021-04-14T15:35:02+00:00","remoteAddr":"","user":"--","app":"bookmarks","method":"","url":"--","message":"Crawling https://www.homedepot.com/p/Westinghouse-WGen9500DF-12-500-9-500-Watt-Dual-Fuel-Portable-Generator-with-Remote-Start-and-Transfer-Switch-Outlet-for-Home-Backup-WGen9500DF/310741071","userAgent":"--","version":"20.0.8.1"}
28295:{"reqId":"x9Bg7Po1tZbEKdwA2V0G","level":0,"time":"2021-04-14T16:10:01+00:00","remoteAddr":"","user":"--","app":"cron","method":"","url":"--","message":"Run OCA\\Bookmarks\\BackgroundJobs\\CrawlJob job with ID 13377","userAgent":"--","version":"20.0.8.1"}
28296:{"reqId":"x9Bg7Po1tZbEKdwA2V0G","level":2,"time":"2021-04-14T16:10:01+00:00","remoteAddr":"","user":"--","app":"bookmarks","method":"","url":"--","message":"Crawling https://www.homedepot.com/p/Westinghouse-WGen9500DF-12-500-9-500-Watt-Dual-Fuel-Portable-Generator-with-Remote-Start-and-Transfer-Switch-Outlet-for-Home-Backup-WGen9500DF/310741071","userAgent":"--","version":"20.0.8.1"}
Since neither Crawl Preview nor Crawl Cleanup appeared in the log, I have to assume that something in the try block is blocked... Maybe $client is having trouble with this particular URL? As I've mentioned, I have directly cut and pasted that URL into Firefox, and got a valid page back... As I know nothing about Guzzle, I'm out of ideas.
Please let me know if you have any more ideas that I can try.
donb9000
on 14 Apr 2021
Well this is interesting. Since I mentioned previews in the last post, I went looking at my bookmarks config in the Admin section. There I found this:
Then I checked the database which shows the value as empty:
MariaDB [nextcloud]> select * from oc_appconfig where appid = 'bookmarks' and configkey = 'previews.screenly.url';
+-----------+-----------------------+-------------+
| appid | configkey | configvalue |
+-----------+-----------------------+-------------+
| bookmarks | previews.screenly.url | |
+-----------+-----------------------+-------------+
Then I grepped through the bookmarks app code and found references to a few different URLs for screeenly:
src/components/ViewAdmin.vue
55: <h3>{{ t('bookmarks', 'Screeenly') }}</h3>
59: 'You can either sign up for free at screeenly.com or setup your own server.'
64: <label>{{ t('bookmarks', 'Screeenly API URL') }}
68: placeholder="https://screeenly.example.com/api/v1/fullsize"
72: <label>{{ t('bookmarks', 'Screeenly API key') }}
lib/Service/Previewers/ScreeenlyBookmarkPreviewer.php
20:class ScreeenlyBookmarkPreviewer implements IBookmarkPreviewer {
55: $this->apiUrl = $config->getAppValue('bookmarks', 'previews.screenly.url', 'http://screeenly.com/api/v1/fullsize');
lib/Settings/AdminSettings.php
41: 'previews.screenly.url' => $this->config->getAppValue('bookmarks', 'previews.screenly.url', 'https://secure.screeenly.com/api/v1/fullsize'),
Apparently I was under the impression that if I left that field blank, I would get an appropriate URL by default. I do have an API Key registered.
So, my question is: Do I need to fill in the previews.screenly.url item in the Admin setup, or should I be getting the correct URL by default? If I should be filling it in myself, then which is the correct URL from above? Certainly it's not the placeholder URL, so will ether of the other two (HTTP, or HTTPS) work? I would rather use the HTTPS URL if given the choice.
donb9000
on 14 Apr 2021
Again added more debug to crawl(). Note the Crawling 2, Crawling 3, and Crawling 4 messages in the try block:
public function crawl(Bookmark $bookmark): void {
$this->logger->warning('Crawling '.$bookmark->getUrl());
try {
$client = new Client(['connect_timeout' => self::CONNECT_TIMEOUT, 'read_timeout' => self::READ_TIMEOUT]
$this->logger->warning('Crawling 2 '.$bookmark->getUrl());
/** @var Response $resp */
$resp = $client->get($bookmark->getUrl());
$this->logger->warning('Crawling 3 '.$bookmark->getUrl());
$available = $resp ? $resp->getStatusCode() !== 404 : false;
$this->logger->warning('Crawling 4 '.$bookmark->getUrl());
} catch (Exception $e) {
$available = false;
}
if ($available) {
$this->logger->warning('Crawl Preview '.$bookmark->getUrl());
$this->archiveFile($bookmark, $resp);
$this->bookmarkPreviewer->getImage($bookmark);
$this->faviconPreviewer->getImage($bookmark);
$this->logger->warning('Done Crawl Preview '.$bookmark->getUrl());
}
$this->logger->warning('Crawl Cleanup '.$bookmark->getUrl());
$bookmark->markPreviewCreated();
$bookmark->setAvailable($available);
$this->bookmarkMapper->update($bookmark);
$this->logger->warning('Done Crawling '.$bookmark->getUrl());
}
The last cron.php never got to Crawling 3...
# ag crawl nextcloud.log
10389:{"reqId":"X9HtaZqt8hiO6f9G7Ywr","level":0,"time":"2021-04-14T20:30:01+00:00","remoteAddr":"","user":"--","app":"cron","method":"","url":"--","message":"Run OCA\\Bookmarks\\BackgroundJobs\\CrawlJob job with ID 13377","userAgent":"--","version":"20.0.8.1"}
10390:{"reqId":"X9HtaZqt8hiO6f9G7Ywr","level":2,"time":"2021-04-14T20:30:01+00:00","remoteAddr":"","user":"--","app":"bookmarks","method":"","url":"--","message":"Crawling https://www.homedepot.com/p/Westinghouse-WGen9500DF-12-500-9-500-Watt-Dual-Fuel-Portable-Generator-with-Remote-Start-and-Transfer-Switch-Outlet-for-Home-Backup-WGen9500DF/310741071","userAgent":"--","version":"20.0.8.1"}
10391:{"reqId":"X9HtaZqt8hiO6f9G7Ywr","level":2,"time":"2021-04-14T20:30:01+00:00","remoteAddr":"","user":"--","app":"bookmarks","method":"","url":"--","message":"Crawling 2 https://www.homedepot.com/p/Westinghouse-WGen9500DF-12-500-9-500-Watt-Dual-Fuel-Portable-Generator-with-Remote-Start-and-Transfer-Switch-Outlet-for-Home-Backup-WGen9500DF/310741071","userAgent":"--","version":"20.0.8.1"}
Looks like GuzzleHttp is stuck trying to retrieve that URL...
That homedepot.com URL is not the first URL in the table, and it's last_preview date is non-zero (1607037002). It does have the oldest last_preview date, so maybe that's the reason.
donb9000
on 14 Apr 2021
Can you add a typo in that URL's domain, or set it's last_preview date to today, or simply delete it? That way we can find out if the URL is the problem or something else.
marcelklehr
on 16 Apr 2021
Sure, happy to.
-->mysql -uxxx -pxxx -D nextcloud -e 'update oc_jobs set reserved_at = 0 where id = 13377;'
monster:~ (dbostrom)
-->mysql -uxxx -pxxx -D nextcloud -e 'update oc_bookmarks set last_preview = 1618518602 where id = 444;'
monster:~ (dbostrom)
-->mysql -uxxx -pxxx -D nextcloud -e 'select * from oc_jobs where id = 13377;'
+-------+---------------------------------------+----------+------------+--------------+-------------+--------------------+
| id | class | argument | last_run | last_checked | reserved_at | execution_duration |
+-------+---------------------------------------+----------+------------+--------------+-------------+--------------------+
| 13377 | OCA\Bookmarks\BackgroundJobs\CrawlJob | null | 1618518602 | 1618518602 | 0 | 0 |
+-------+---------------------------------------+----------+------------+--------------+-------------+--------------------+
monster:~ (dbostrom)
-->mysql -uxxx -pxxx -D nextcloud -e 'select id, last_preview, url from oc_bookmarks where id = 444;'
+-----+--------------+--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| id | last_preview | url |
+-----+--------------+--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| 444 | 1618518602 | https://www.homedepot.com/p/Westinghouse-WGen9500DF-12-500-9-500-Watt-Dual-Fuel-Portable-Generator-with-Remote-Start-and-Transfer-Switch-Outlet-for-Home-Backup-WGen9500DF/310741071 |
+-----+--------------+--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
I killed the stuck cron.php. We'll see what happens.
donb9000
on 16 Apr 2021
Well, it appears that particular URL is a problem. The latest cron.php did quite a bit more work...
-->mysql -uxxx -pxxx -D nextcloud -e 'select * from oc_jobs where id = 13377;'
+-------+---------------------------------------+----------+------------+--------------+-------------+--------------------+
| id | class | argument | last_run | last_checked | reserved_at | execution_duration |
+-------+---------------------------------------+----------+------------+--------------+-------------+--------------------+
| 13377 | OCA\Bookmarks\BackgroundJobs\CrawlJob | null | 1618527905 | 1618528201 | 0 | 76 |
+-------+---------------------------------------+----------+------------+--------------+-------------+--------------------+
I won't post all the debug logs from the work that was done, but this is the first time that execution_duration has been anything other than zero, and reserved_at is also reset as it should be.
donb9000
on 16 Apr 2021
Does this result indicate a bug in the URL fetching code (Guzzle)?
donb9000
on 16 Apr 2021
It means at the very least, that URL is peculiar, somehow. Could you curl -vv it and post the results here (homedepot blocks europe, apparently, theh)?
$ curl -vvv "https://www.homedepot.com/p/Westinghouse-WGen9500DF-12-500-9-500-Watt-Dual-Fuel-Portable-Generator-with-Remote-Start-and-Transfer-Switch-Outlet-for-Home-Backup-WGen9500DF/310741071"
OK. I ran the the above including &> homedepot.curl.txt to capture curl's output to stderr.
homedepot.curl.txt
donb9000
on 18 Apr 2021
Thanks that's very helpful. First, the server wants to use HTTP 2 and it also doesn't send a content-length header. After perusing the interweb for a while, I came across a possible solution:
Change this line: https://github.com/nextcloud/bookmarks/blob/master/lib/Service/CrawlService.php#L85
To look like this:
$client = new Client(['connect_timeout' => self::CONNECT_TIMEOUT, 'read_timeout' => self::READ_TIMEOUT, 'version' => 1]);
This will force Guzzle to use HTTP v1
marcelklehr
on 18 Apr 2021
I made the code change and set the following in oc_bookmarks
-->mysql -uxxx -pxxx -D nextcloud -e 'update oc_bookmarks set last_preview = 1607191200 where id = 444;'
-->mysql -uxxx -pxxx -D nextcloud -e 'select id, last_preview, url from oc_bookmarks where id = 444;'
+-----+--------------+--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| id | last_preview | url |
+-----+--------------+--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| 444 | 1607191200 | https://www.homedepot.com/p/Westinghouse-WGen9500DF-12-500-9-500-Watt-Dual-Fuel-Portable-Generator-with-Remote-Start-and-Transfer-Switch-Outlet-for-Home-Backup-WGen9500DF/310741071 |
+-----+--------------+--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
-->date -d '@1607191200'
Sat Dec 5 13:00:00 EST 2020
That last_preview date is close to the original date for this URL when things were stuck. I assume there is some minimum time between previews, measured in days perhaps?
Now waiting for CrawlJob.php to run again.
donb9000
on 18 Apr 2021
Looks like cron.php is stuck again.
For the record, here is the line in CrawlService.php that I modified:
# ag 'new client' CrawlService.php
82: $client = new Client(['connect_timeout' => self::CONNECT_TIMEOUT, 'read_timeout' => self::READ_TIMEOUT, 'version' => 1]);
So, I guess there is nothing else to do except remove that one link so Guzzle doesn't get stuck again?
donb9000
on 3 May 2021
Sorry for the delay. I've been tinkering with the CrawlJob the last few days, investigating different problems and trying different things. I've discovered that there's also a normal 'timeout' option, which may work for you in this case as well:
$client = new Client(['timeout' => 10, 'connect_timeout' => self::CONNECT_TIMEOUT, 'read_timeout' => self::READ_TIMEOUT, 'version' => 1]);
No worries, I know you are busy. I'll give the new timeout option a try.
donb9000
on 3 May 2021
That seems to have helped. The CrawlJob is no longer stuck processing the homedepot.com link.
I set the last_preview date to Dec 2020 again and waited for the job to run
-->mysql -uxxx -pxxx -D nextcloud -e 'update oc_bookmarks set last_preview = 1607191200 where id = 444;'
-->mysql -uxxx -pxxx -D nextcloud -e 'select id, last_preview, url from oc_bookmarks where id = 444;'
+-----+--------------+--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| id | last_preview | url |
+-----+--------------+--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| 444 | 1607191200 | https://www.homedepot.com/p/Westinghouse-WGen9500DF-12-500-9-500-Watt-Dual-Fuel-Portable-Generator-with-Remote-Start-and-Transfer-Switch-Outlet-for-Home-Backup-WGen9500DF/310741071 |
+-----+--------------+--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
After remembering that the CrawlJob only runs once every 30 minutes, it seemed to wait for the 10 second timeout and then give up on that link.
-->mysql -uxxx -pxxx -D nextcloud -e 'select * from oc_jobs where id = 13377;'
+-------+---------------------------------------+----------+------------+--------------+-------------+--------------------+
| id | class | argument | last_run | last_checked | reserved_at | execution_duration |
+-------+---------------------------------------+----------+------------+--------------+-------------+--------------------+
| 13377 | OCA\Bookmarks\BackgroundJobs\CrawlJob | null | 1620476402 | 1620476402 | 0 | 10 |
+-------+---------------------------------------+----------+------------+--------------+-------------+--------------------+
The last_preview time was updated in oc_bookmarks even though it failed to read the link. I don't know if this is intentional or not. But it will probably keep the CrawlJob from repeatedly trying the link that doesn't work...
-->mysql -uxxx -pxxx -D nextcloud -e 'select id, last_preview, url from oc_bookmarks where id = 444;'
+-----+--------------+--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| id | last_preview | url |
+-----+--------------+--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| 444 | 1620476412 | https://www.homedepot.com/p/Westinghouse-WGen9500DF-12-500-9-500-Watt-Dual-Fuel-Portable-Generator-with-Remote-Start-and-Transfer-Switch-Outlet-for-Home-Backup-WGen9500DF/310741071 |
+-----+--------------+--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
For the record, here is the change that I made:
diff -u CrawlService.php.20210508 CrawlService.php
--- CrawlService.php.20210508 2021-04-18 15:36:17.766813565 -0400
+++ CrawlService.php 2021-05-08 08:04:21.004765011 -0400
@@ -79,7 +79,7 @@
public function crawl(Bookmark $bookmark): void {
$this->logger->warning('Crawling '.$bookmark->getUrl());
try {
- $client = new Client(['connect_timeout' => self::CONNECT_TIMEOUT, 'read_timeout' => self::READ_TIMEOUT, 'version' => 1]);
+ $client = new Client(['timeout' => 10, 'connect_timeout' => self::CONNECT_TIMEOUT, 'read_timeout' => self::READ_TIMEOUT, 'version' => 1]);
/** @var Response $resp */
$resp = $client->get($bookmark->getUrl());
$available = $resp ? $resp->getStatusCode() !== 404 : false;
Awesome! The fix is already in, then :)
see https://github.com/nextcloud/bookmarks/blob/master/lib/Service/CrawlService.php#L94
marcelklehr
on 8 May 2021
Related issues
bspire
路
4Comments
sunjam
路
4Comments
marcelklehr
路
4Comments
kc853
路
3Comments
ifuchs
路
4Comments