Scans stalling

  • Resolved keysnparrots

    (@keysnparrots)


    8 years, 11 months ago

    More background in this Reddit post, but let’s start fresh here.

    I have three WordPress sites on DreamHost with the free version of WordFence installed. Since Tuesday (2017-05-02), none of them will complete a scan. This coincides approximately with installation of the WordPress 4.7.4 update and WordFence 6.3.7 and 6.3.8 updates. Scans stall at different points each time.

    I first investigated through DreamHost support and they told me my processes are being killed for high memory usage; i.e. not CPU usage and not for running too long. I don’t know if that’s the only issue involved.

    In my PHP error log, I’m seeing errors like this during scans:

    [Thu May 04 13:21:40 2017] [error] [client [server IP]] Premature end of script headers: php70.cgi, referer: https://[my domain].com/wp-admin/admin-ajax.php?action=wordfence_doScan&isFork=1&cronKey=46d6271345c2507b55ff100
[Thu May 04 13:22:31 2017] [error] [client [server IP]] Premature end of script headers: php70.cgi, referer: https://[my domain].com/wp-admin/admin-ajax.php?action=wordfence_doScan&isFork=1&cronKey=2df0e08f78e3c3704c0a7fa0
[Thu May 04 13:22:31 2017] [error] [client [server IP]] Premature end of script headers: php70.cgi, referer: https://[my domain].com/wp-admin/admin-ajax.php?action=wordfence_doScan&isFork=1&cronKey=5da542ff7de5c210203950f6

    All three of those errors occurred during one scan. The scan didn’t stall until after the third error occurred.

    In case it’s relevant, Sucuri scans and UpdraftPlus backups are succeeding on all three sites.

    The sites are running on PHP 7. I’ve tried both CGI and FastCGI.

    I’ve tried enabling the low resource scanning option. These options are disabled, as recommended by wfasa:

    • Scan files outside your WordPress installation
    • Scan images, binary, and other files as if they were executable
    • Enable HIGH SENSITIVITY scanning (may give false positives)

    Below are the last few lines (most recent at top) of the activity log for a scan I attempted just now. Note that the scan doesn’t always stall at the same stage.

    
[May 04 14:57:54:1493931474.041259:4:info] Entered fork()
[May 04 14:57:46:1493931466.689383:4:info] Got a true deserialized value back from 'wfsd_engine' with type: object
[May 04 14:57:44:1493931464.945533:4:info] Setting up scanRunning and starting scan
[May 04 14:57:44:1493931464.944940:4:info] Setting up error handling environment
[May 04 14:57:44:1493931464.944311:4:info] Requesting max memory
[May 04 14:57:44:1493931464.943762:4:info] Done become admin
[May 04 14:57:44:1493931464.943200:4:info] Scan authentication complete.
[May 04 14:57:44:1493931464.940837:4:info] Scan will run as admin user 'admin' with ID '1' sourced from: singlesite get_users() function
[May 04 14:57:44:1493931464.927877:4:info] Becoming admin for scan
[May 04 14:57:44:1493931464.918306:4:info] Checking saved cronkey against cronkey param
[May 04 14:57:44:1493931464.917639:4:info] Exploding stored cronkey
[May 04 14:57:44:1493931464.917062:4:info] Fetching stored cronkey for comparison.
[May 04 14:57:44:1493931464.916217:4:info] Checking cronkey
[May 04 14:57:44:1493931464.914976:4:info] Scan engine received request.
[May 04 14:57:42:1493931462.329106:4:info] Starting cron with normal ajax at URL https://[my domain].com/wp-admin/admin-ajax.php?action=wordfence_doScan&isFork=1&cronKey=6223f15a1682ba844f2a19ab
[May 04 14:57:42:1493931462.326767:4:info] Test result of scan start URL fetch: array ( 'headers' => Requests_Utility_CaseInsensitiveDictionary::__set_state(array( 'data' => array ( 'date' => 'Thu, 04 May 2017 20:57:40 GMT', 'server' => 'Apache', 'x-robots-tag' => 'noindex', 'x-content-type-options' => 'nosniff', 'expires' => 'Wed, 11 Jan 1984 05:00:00 GMT', 'cache-control' => 'no-cache, must-revalidate, max-age=0', 'x-frame-options' => 'SAMEORIGIN', 'set-cookie' => 'wfvt_2029678028=590b95c5804bc; expires=Thu, 04-May-2017 21:27:41 GMT; Max-Age=1800; path=/; HttpOnly', 'content-type' => 'text/html; charset=UTF-8', ), )), 'body' => 'WFSCANTESTOK', 'response' => array ( 'code' => 200, 'message' => 'OK', ), 'cookies' => array ( 0 => WP_Http_Cookie::__set_state(array( 'name' => 'wfvt_2029678028', 'value' => '590b95c5804bc', 'expires' => 1493933261, 'path' => '/', 'domain' => '[my domain].com',
[May 04 14:57:40:1493931460.411480:4:info] getMaxExecutionTime() returning half ini value: 15
[May 04 14:57:40:1493931460.410865:4:info] Got max_execution_time value from ini: 30
[May 04 14:57:40:1493931460.405907:4:info] Got value from wf config maxExecutionTime:
[May 04 14:57:40:1493931460.403036:4:info] Calling startScan(true)
[May 04 14:57:39:1493931459.963596:4:info] Entered fork()
[May 04 14:57:39:1493931459.962810:4:info] Calling fork() from wordfenceHash with maxExecTime: 15
[May 04 14:57:39:1493931459.949584:4:info] Scanning: /home/[username]/[my domain].com/wp-content/plugins/jetpack/modules/protect/protect-dashboard-widget.min.css (Mem:24.0M)
[May 04 14:57:39:1493931459.936184:4:info] Scanning: /home/[username]/[my domain].com/wp-content/plugins/jetpack/modules/protect/protect-dashboard-widget.css (Mem:24.0M)
[May 04 14:57:39:1493931459.924288:2:info] Analyzed 1200 files containing 17.91 MB of data so far
    • This topic was modified 8 years, 11 months ago by keysnparrots.
    • This topic was modified 8 years, 11 months ago by keysnparrots.
Viewing 15 replies - 1 through 15 (of 22 total)
1 2
  • Thread Starter keysnparrots

    (@keysnparrots)

    8 years, 11 months ago

    Sorry; that scan wasn’t finished. It came back after a while of looking like it wouldn’t. I’ll post an update when it finishes or has been stalled for longer.

    Thread Starter keysnparrots

    (@keysnparrots)

    8 years, 11 months ago

    Site #2 got further into an automatic scan starting at May 4 15:42 and then stalled. Next scan apparently never got started:

    [May 04 23:38:07:1493962687.689816:4:info] Entering start scan routine
[May 04 23:38:07:1493962687.686907:4:info] Scheduled time for day 6 hour 13 is: Saturday 6th of May 2017 07:49:04 PM
[May 04 23:38:07:1493962687.685035:4:info] Scheduled time for day 5 hour 13 is: Friday 5th of May 2017 07:45:04 PM
[May 04 23:38:07:1493962687.683201:4:info] Scheduled time for day 4 hour 13 is: Thursday 11th of May 2017 07:08:19 PM
[May 04 23:38:07:1493962687.681051:4:info] Scheduled time for day 3 hour 13 is: Wednesday 10th of May 2017 07:15:08 PM
[May 04 23:38:07:1493962687.679357:4:info] Scheduled time for day 2 hour 13 is: Tuesday 9th of May 2017 07:38:41 PM
[May 04 23:38:07:1493962687.674363:4:info] Scheduled time for day 1 hour 13 is: Monday 8th of May 2017 07:13:52 PM
[May 04 23:38:07:1493962687.672508:4:info] Scheduled time for day 0 hour 13 is: Sunday 7th of May 2017 07:13:48 PM
[May 04 23:38:07:1493962687.600397:1:info] Scheduled Wordfence scan starting at Thursday 4th of May 2017 11:38:07 PM
[May 04 15:55:29:1493934929.554643:4:info] Calling Wordfence API v2.23:https://noc1.wordfence.com/stats.json
[May 04 15:44:06:1493934246.793538:4:info] getMaxExecutionTime() returning half ini value: 15
[May 04 15:44:06:1493934246.792827:4:info] Got max_execution_time value from ini: 30
[May 04 15:44:06:1493934246.792146:4:info] Got value from wf config maxExecutionTime:
[May 04 15:44:06:1493934246.791050:4:info] Calling startScan(true)
[May 04 15:44:06:1493934246.445177:4:info] Entered fork()
[May 04 15:43:59:1493934239.438296:4:info] Got a true deserialized value back from 'wfsd_engine' with type: object
[May 04 15:43:59:1493934239.344506:4:info] Setting up scanRunning and starting scan
[May 04 15:43:59:1493934239.337951:4:info] Setting up error handling environment
[May 04 15:43:59:1493934239.337345:4:info] Requesting max memory
[May 04 15:43:59:1493934239.336842:4:info] Done become admin
[May 04 15:43:59:1493934239.336347:4:info] Scan authentication complete.
[May 04 15:43:59:1493934239.333983:4:info] Scan will run as admin user 'admin' with ID '1' sourced from: singlesite get_users() function
[May 04 15:43:59:1493934239.332205:4:info] Becoming admin for scan
[May 04 15:43:59:1493934239.330733:4:info] Checking saved cronkey against cronkey param
[May 04 15:43:59:1493934239.330225:4:info] Exploding stored cronkey
[May 04 15:43:59:1493934239.329364:4:info] Fetching stored cronkey for comparison.
[May 04 15:43:59:1493934239.328564:4:info] Checking cronkey
[May 04 15:43:59:1493934239.327629:4:info] Scan engine received request.
[May 04 15:43:58:1493934238.739355:4:info] Starting cron with normal ajax at URL https://[domain].com/wp-admin/admin-ajax.php?action=wordfence_doScan&isFork=1&cronKey=7152173f6004e00852c8ace5
[May 04 15:43:58:1493934238.736627:4:info] Test result of scan start URL fetch: array ( 'headers' => Requests_Utility_CaseInsensitiveDictionary::__set_state(array( 'data' => array ( 'date' => 'Thu, 04 May 2017 21:43:58 GMT', 'server' => 'Apache', 'x-robots-tag' => 'noindex', 'x-content-type-options' => 'nosniff', 'expires' => 'Wed, 11 Jan 1984 05:00:00 GMT', 'cache-control' => 'no-cache, must-revalidate, max-age=0', 'x-frame-options' => 'SAMEORIGIN', 'set-cookie' => 'wfvt_2029678028=590ba09e9bdf2; expires=Thu, 04-May-2017 22:13:58 GMT; Max-Age=1800; path=/; HttpOnly', 'content-type' => 'text/html; charset=UTF-8', ), )), 'body' => 'WFSCANTESTOK', 'response' => array ( 'code' => 200, 'message' => 'OK', ), 'cookies' => array ( 0 => WP_Http_Cookie::__set_state(array( 'name' => 'wfvt_2029678028', 'value' => '590ba09e9bdf2', 'expires' => 1493936038, 'path' => '/', 'domain' => '[domain].com',
[May 04 15:43:57:1493934237.839638:4:info] getMaxExecutionTime() returning half ini value: 15
[May 04 15:43:57:1493934237.838994:4:info] Got max_execution_time value from ini: 30
[May 04 15:43:57:1493934237.838232:4:info] Got value from wf config maxExecutionTime:
[May 04 15:43:57:1493934237.837642:4:info] Calling startScan(true)
[May 04 15:43:57:1493934237.531300:4:info] Entered fork()
[May 04 15:43:57:1493934237.530555:4:info] Calling fork() from wordfenceHash with maxExecTime: 15
[May 04 15:43:57:1493934237.368044:4:info] Scanning: /home/[user]/[domain].com/wp-content/plugins/updraftplus/vendor/rackspace/php-opencloud/lib/OpenCloud/ObjectStore/Constants/UrlType.php (Mem:42.0M)
[May 04 15:43:57:1493934237.275011:4:info] Scanning: /home/[user]/[domain].com/wp-content/plugins/updraftplus/vendor/rackspace/php-opencloud/lib/OpenCloud/ObjectStore/Constants/Header.php (Mem:42.0M)
[May 04 15:43:57:1493934237.260453:4:info] Scanning: /home/[user]/[domain].com/wp-content/plugins/updraftplus/vendor/rackspace/php-opencloud/lib/OpenCloud/ObjectStore/CDNService.php (Mem:42.0M)
[May 04 15:43:57:1493934237.243031:4:info] Scanning: /home/[user]/[domain].com/wp-content/plugins/updraftplus/vendor/rackspace/php-opencloud/lib/OpenCloud/ObjectStore/AbstractService.php (Mem:42.0M)
    • This reply was modified 8 years, 11 months ago by keysnparrots.
    Thread Starter keysnparrots

    (@keysnparrots)

    8 years, 11 months ago

    Site #3, same result as site #2:

    [May 05 00:05:43:1493964343.408327:4:info] Entering start scan routine
[May 05 00:05:43:1493964343.405593:4:info] Scheduled time for day 6 hour 12 is: Saturday 6th of May 2017 06:51:56 PM
[May 05 00:05:43:1493964343.403645:4:info] Scheduled time for day 5 hour 12 is: Friday 5th of May 2017 06:53:43 PM
[May 05 00:05:43:1493964343.401454:4:info] Scheduled time for day 4 hour 12 is: Thursday 11th of May 2017 06:06:14 PM
[May 05 00:05:43:1493964343.399080:4:info] Scheduled time for day 3 hour 12 is: Wednesday 10th of May 2017 06:21:26 PM
[May 05 00:05:43:1493964343.397008:4:info] Scheduled time for day 2 hour 12 is: Tuesday 9th of May 2017 06:33:03 PM
[May 05 00:05:43:1493964343.394955:4:info] Scheduled time for day 1 hour 12 is: Monday 8th of May 2017 06:02:59 PM
[May 05 00:05:43:1493964343.392868:4:info] Scheduled time for day 0 hour 12 is: Sunday 7th of May 2017 06:46:51 PM
[May 05 00:05:43:1493964343.332058:1:info] Scheduled Wordfence scan starting at Friday 5th of May 2017 12:05:43 AM
[May 04 16:22:50:1493936570.089317:4:info] Calling Wordfence API v2.23:https://noc1.wordfence.com/v2.23/?v=4.7.4&s=https%3A%2F%2F[domain].com&k=5afa5d03ba831832ae7ace4d82592a30ffb98cf2578df76993873ea49af68208aa7bc883a47f563ed8e20bcb972297116e6c9fee3ebea48b333043206e012bab8d39779cf6f87305a5f45431e84e619a&openssl=268439567&phpv=7.0.14&betaFeed=0&cacheType=disabled&action=get_known_vuln_pattern
[May 04 16:22:49:1493936569.617134:4:info] Calling Wordfence API v2.23:https://noc1.wordfence.com/v2.23/?v=4.7.4&s=https%3A%2F%2F[domain].com&k=5afa5d03ba831832ae7ace4d82592a30ffb98cf2578df76993873ea49af68208aa7bc883a47f563ed8e20bcb972297116e6c9fee3ebea48b333043206e012bab8d39779cf6f87305a5f45431e84e619a&openssl=268439567&phpv=7.0.14&betaFeed=0&cacheType=disabled&action=ping_api_key
[May 04 15:54:43:1493934883.779958:4:info] Calling Wordfence API v2.23:https://noc1.wordfence.com/v2.23/?v=4.7.4&s=https%3A%2F%2F[domain].com&k=5afa5d03ba831832ae7ace4d82592a30ffb98cf2578df76993873ea49af68208aa7bc883a47f563ed8e20bcb972297116e6c9fee3ebea48b333043206e012bab8d39779cf6f87305a5f45431e84e619a&openssl=268439567&phpv=7.0.14&betaFeed=0&cacheType=disabled&action=resolve_ips
[May 04 15:54:43:1493934883.258265:4:info] Calling Wordfence API v2.23:https://noc1.wordfence.com/stats.json
[May 04 15:49:06:1493934546.731256:4:info] Scanning: /home/[user]/[domain].com/wp-content/plugins/corporate-toolkit/shortcodes/shortcodes.php (Mem:12.0M)
[May 04 15:49:06:1493934546.715228:4:info] Scanning: /home/[user]/[domain].com/wp-content/plugins/corporate-toolkit/shortcodes/service.php (Mem:12.0M)
[May 04 15:49:06:1493934546.701655:4:info] Scanning: /home/[user]/[domain].com/wp-content/plugins/corporate-toolkit/shortcodes/sectiontitle.php (Mem:12.0M)
[May 04 15:49:06:1493934546.687930:4:info] Scanning: /home/[user]/[domain].com/wp-content/plugins/corporate-toolkit/shortcodes/projects.php (Mem:12.0M)
[May 04 15:49:06:1493934546.673804:4:info] Scanning: /home/[user]/[domain].com/wp-content/plugins/corporate-toolkit/shortcodes/products.php (Mem:12.0M)
[May 04 15:49:06:1493934546.660133:4:info] Scanning: /home/[user]/[domain].com/wp-content/plugins/corporate-toolkit/shortcodes/process_bar.php (Mem:12.0M)
[May 04 15:49:06:1493934546.646606:4:info] Scanning: /home/[user]/[domain].com/wp-content/plugins/corporate-toolkit/shortcodes/pricing.php (Mem:12.0M)
[May 04 15:49:06:1493934546.628558:4:info] Scanning: /home/[user]/[domain].com/wp-content/plugins/corporate-toolkit/shortcodes/pie_chart.php (Mem:12.0M)
[May 04 15:49:06:1493934546.614874:4:info] Scanning: /home/[user]/[domain].com/wp-content/plugins/corporate-toolkit/shortcodes/partner.php (Mem:12.0M)
    Thread Starter keysnparrots

    (@keysnparrots)

    8 years, 11 months ago

    I don’t know why, but my reply about site #1 has just disappeared after editing. Here it is again.

    Here’s the log from site #1, showing my attempt to start a manual scan that stalled, followed, apparently, by to scheduled scan attempts:

    [May 05 04:15:04:1493979304.094148:4:info] Entering start scan routine
[May 05 04:15:04:1493979304.090987:4:info] Scheduled time for day 6 hour 2 is: Saturday 6th of May 2017 08:46:28 AM
[May 05 04:15:04:1493979304.088705:4:info] Scheduled time for day 5 hour 2 is: Friday 12th of May 2017 08:50:10 AM
[May 05 04:15:04:1493979304.086154:4:info] Scheduled time for day 4 hour 2 is: Thursday 11th of May 2017 08:45:49 AM
[May 05 04:15:04:1493979304.075712:4:info] Scheduled time for day 3 hour 2 is: Wednesday 10th of May 2017 08:58:34 AM
[May 05 04:15:04:1493979304.072514:4:info] Scheduled time for day 2 hour 2 is: Tuesday 9th of May 2017 08:31:45 AM
[May 05 04:15:04:1493979304.070104:4:info] Scheduled time for day 1 hour 2 is: Monday 8th of May 2017 08:21:26 AM
[May 05 04:15:04:1493979304.067579:4:info] Scheduled time for day 0 hour 2 is: Sunday 7th of May 2017 08:38:19 AM
[May 05 04:15:04:1493979304.049105:1:info] Scheduled Wordfence scan starting at Friday 5th of May 2017 04:15:04 AM
[May 05 02:18:27:1493972307.146687:2:info] Scanned comment with Author: job posting sites Source IP: 196.52.84.75
[May 05 02:18:27:1493972307.137377:2:info] Done host key check.
[May 05 02:18:26:1493972306.614243:4:info] Calling Wordfence API v2.23:https://noc1.wordfence.com/v2.23/?v=4.7.4&s=https%3A%2F%2F[domain].com&k=116b60f8329ccb93aa9e0f7db78d7d74f30818921156ee74c0e494284b836e60472ce3d61353d93fb10280270edd63b7dda8cd7f6c8d2f32260544dc28c037b94fbcb0c11135721e591fec5f62109e2b&openssl=268439567&phpv=7.0.14&betaFeed=0&cacheType=disabled&action=check_host_keys
[May 05 02:18:26:1493972306.612528:2:info] Checking 2 host keys against Wordfence scanning servers.
[May 05 02:18:26:1493972306.533175:2:info] Scanning comment with Author: job posting sites Source IP: 196.52.84.75
[May 05 02:18:26:1493972306.528913:4:info] getMaxExecutionTime() returning half ini value: 300
[May 05 02:18:26:1493972306.528196:4:info] Got max_execution_time value from ini: 600
[May 05 02:18:26:1493972306.476810:4:info] Got value from wf config maxExecutionTime:
[May 04 19:45:02:1493948702.532967:4:info] Entering start scan routine
[May 04 19:45:02:1493948702.529766:4:info] Scheduled time for day 6 hour 4 is: Saturday 6th of May 2017 10:42:37 AM
[May 04 19:45:02:1493948702.527233:4:info] Scheduled time for day 5 hour 4 is: Friday 5th of May 2017 10:04:06 AM
[May 04 19:45:02:1493948702.524967:4:info] Scheduled time for day 4 hour 4 is: Thursday 11th of May 2017 10:39:15 AM
[May 04 19:45:02:1493948702.522688:4:info] Scheduled time for day 3 hour 4 is: Wednesday 10th of May 2017 10:24:34 AM
[May 04 19:45:02:1493948702.509694:4:info] Scheduled time for day 2 hour 4 is: Tuesday 9th of May 2017 10:10:00 AM
[May 04 19:45:02:1493948702.507316:4:info] Scheduled time for day 1 hour 4 is: Monday 8th of May 2017 10:09:43 AM
[May 04 19:45:02:1493948702.504727:4:info] Scheduled time for day 0 hour 4 is: Sunday 7th of May 2017 10:47:29 AM
[May 04 19:45:02:1493948702.418698:1:info] Scheduled Wordfence scan starting at Thursday 4th of May 2017 07:45:02 PM
[May 04 16:06:28:1493935588.614565:10:info] SUM_PAIDONLY:Checking if your site is on a domain blacklist is for paid members only
[May 04 16:06:26:1493935586.609102:10:info] SUM_PAIDONLY:Checking if your IP is generating spam is for paid members only
[May 04 16:06:24:1493935584.606685:10:info] SUM_PAIDONLY:Check if your site is being Spamvertized is for paid members only
[May 04 16:06:22:1493935582.603235:10:info] SUM_PAIDONLY:Remote scan of public facing site only available to paid members
[May 04 16:06:22:1493935582.598924:4:info] getMaxExecutionTime() returning half ini value: 300
[May 04 16:06:22:1493935582.598252:4:info] Got max_execution_time value from ini: 600
[May 04 16:06:22:1493935582.597710:4:info] Got value from wf config maxExecutionTime:
[May 04 16:06:22:1493935582.597146:10:info] SUM_PREP:Preparing a new scan.
[May 04 16:06:22:1493935582.594433:4:info] Setting up scanRunning and starting scan
[May 04 16:06:22:1493935582.593772:4:info] Setting up error handling environment
[May 04 16:06:22:1493935582.593137:4:info] Requesting max memory
[May 04 16:06:22:1493935582.592436:1:info] Using low resource scanning
[May 04 16:06:22:1493935582.590183:4:info] Checking if scan is already running
[May 04 16:06:22:1493935582.589609:4:info] Done become admin
[May 04 16:06:22:1493935582.588528:4:info] Scan authentication complete.
[May 04 16:06:22:1493935582.585972:4:info] Scan will run as admin user '[user]' with ID '2' sourced from: singlesite get_users() function
[May 04 16:06:22:1493935582.583302:4:info] Becoming admin for scan
[May 04 16:06:22:1493935582.581463:4:info] Checking saved cronkey against cronkey param
[May 04 16:06:22:1493935582.580591:4:info] Exploding stored cronkey
[May 04 16:06:22:1493935582.579688:4:info] Fetching stored cronkey for comparison.
[May 04 16:06:22:1493935582.578589:4:info] Checking cronkey
[May 04 16:06:22:1493935582.577320:4:info] Scan engine received request.
[May 04 16:06:18:1493935578.684993:4:info] Starting cron with normal ajax at URL https://[domain].com/wp-admin/admin-ajax.php?action=wordfence_doScan&isFork=0&cronKey=4bb0ec6543d3cff11b6887e
[May 04 16:06:18:1493935578.682553:4:info] Test result of scan start URL fetch: array ( 'headers' => Requests_Utility_CaseInsensitiveDictionary::__set_state(array( 'data' => array ( 'date' => 'Thu, 04 May 2017 22:06:11 GMT', 'server' => 'Apache', 'pragma' => 'no-cache', 'x-robots-tag' => 'noindex', 'x-content-type-options' => 'nosniff', 'expires' => 'Wed, 11 Jan 1984 05:00:00 GMT', 'cache-control' => 'no-cache, must-revalidate, max-age=0', 'x-frame-options' => 'SAMEORIGIN', 'set-cookie' => array ( 0 => 'PHPSESSID=yXn60nPYxUuR%2CK%2C861O8-1; path=/', 1 => 'wfvt_1247210739=590ba5d7973ee; expires=Thu, 04-May-2017 22:36:15 GMT; Max-Age=1800; path=/; HttpOnly', ), 'content-length' => '12', 'content-type' => 'text/html; charset=UTF-8', ), )), 'body' => 'WFSCANTESTOK', 'response' => array ( 'code' => 200, 'message' => 'OK', ), 'cookies' => array ( 0 => WP_Http_Cookie::__set_state(array(
[May 04 16:06:11:1493935571.516195:4:info] getMaxExecutionTime() returning half ini value: 300
[May 04 16:06:11:1493935571.515455:4:info] Got max_execution_time value from ini: 600
[May 04 16:06:11:1493935571.514934:4:info] Got value from wf config maxExecutionTime:
[May 04 16:06:11:1493935571.514147:4:info] Entering start scan routine
[May 04 16:06:11:1493935571.428434:4:info] Ajax request received to start scan.
    Thread Starter keysnparrots

    (@keysnparrots)

    8 years, 11 months ago

    PHP error log from site #3, covering from start of manual scan at May 4 15:48 to current end of WordFence activity log:

    [Thu May 04 14:49:24 2017] [error] [client 173.236.176.10] Premature end of script headers: admin-ajax.php, referer: https://[domain].com/wp-admin/admin-ajax.php?action=wordfence_doScan&isFork=0&cronKey=7b6e3d323e79697c14bfd6fe
[Thu May 04 14:49:35 2017] [error] [client 216.66.188.62] Premature end of script headers: admin-ajax.php, referer: https://[domain].com/wp-admin/admin.php?page=WordfenceScan
[Thu May 04 14:49:35 2017] [error] [client 216.66.188.62] Premature end of script headers: admin-ajax.php, referer: https://[domain].com/wp-admin/admin.php?page=WordfenceScan
[Thu May 04 14:49:35 2017] [error] [client 216.66.188.62] Premature end of script headers: admin-ajax.php, referer: https://[domain].com/wp-admin/admin.php?page=WordfenceScan
[Thu May 04 14:49:45 2017] [error] [client 216.66.188.62] Premature end of script headers: admin-ajax.php, referer: https://[domain].com/wp-admin/admin.php?page=WordfenceScan
[Thu May 04 14:49:45 2017] [error] [client 173.236.176.10] Premature end of script headers: index.php, referer: https://[domain].com/wp-admin/admin-ajax.php?action=wordfence_doScan&isFork=0&cronKey=7b6e3d323e79697c14bfd6fe
[Thu May 04 14:50:06 2017] [error] [client 216.66.188.62] Premature end of script headers: index.php, referer: https://[domain].com/wp-admin/admin.php?page=WordfenceScan
[Thu May 04 14:50:17 2017] [error] [client 216.66.188.62] Premature end of script headers: index.php, referer: https://[domain].com/wp-admin/admin.php?page=WordfenceScan
    wfalaa

    (@wfalaa)

    8 years, 11 months ago

    Hi keysnparrots,
    I’ve checked your reddit post along with all the scan activity logs you have attached in this thread, it’s a tricky one, especially after trying to upgrade PHP to version 7 and to disable some of the scan options to limit its activity as suggested by Asa, however, I have a couple of things to try:
    – It could be that (your theme + other installed plugins) combined together utilize a high amount of memory -almost near the limit set by your host- and during the scan process this limit is reached, to make sure if this is the case, you can try to disable other plugins installed and/or switch to a default WordPress theme -temporarily- then start a new scan and re-check this issue.
    – I wonder also what is the result for “Test your WordPress host’s available memory” in (Wordfence > Tools => Diagnostics) before/after disabling other plugins?

    You can also choose any of these three sites and send a diagnostics report from (Wordfence > Tools => Diagnostics => Send Report by Email) to “alaa [at] wordfence [dot] com”, I’ll take a look at this report, maybe there is something needs to be optimized out there.

    Thanks.

    Thread Starter keysnparrots

    (@keysnparrots)

    8 years, 11 months ago

    Thanks for responding.

    Here are the results of “Test your WordPress host’s available memory” on each site:

    Site 1:

    Wordfence Memory benchmarking utility version 6.3.8.
This utility tests if your WordPress host respects the maximum memory configured
in their php.ini file, or if they are using other methods to limit your access to memory.

--Starting test--
Current maximum memory configured in php.ini: 268435456
Current memory usage: 2.00M
Setting max memory to 90M.
Starting memory benchmark. Seeing an error after this line is not unusual. Read the error carefully
to determine how much memory your host allows. We have requested 90 megabytes.
<br />
<b>Fatal error</b>:  Allowed memory size of 94371840 bytes exhausted (tried to allocate 67108872 bytes) in <b>/home/[user]/[domain]/wp-content/plugins/wordfence/lib/wordfenceClass.php</b> on line <b>4388</b><br />
Error received: Cannot modify header information - headers already sent by (output started at /home/[user]/[domain]/wp-includes/functions.php:3720)

    Site 2:

    Wordfence Memory benchmarking utility version 6.3.8.
This utility tests if your WordPress host respects the maximum memory configured
in their php.ini file, or if they are using other methods to limit your access to memory.

--Starting test--
Current maximum memory configured in php.ini: 128M
Current memory usage: 28.00M
Setting max memory to 90M.
Starting memory benchmark. Seeing an error after this line is not unusual. Read the error carefully
to determine how much memory your host allows. We have requested 90 megabytes.
<br />
<b>Fatal error</b>:  Allowed memory size of 94371840 bytes exhausted (tried to allocate 67108872 bytes) in <b>/home/[user]/[domain]/wp-content/plugins/wordfence/lib/wordfenceClass.php</b> on line <b>4388</b><br />
Error received: Cannot modify header information - headers already sent by (output started at /home/[user]/[domain]/wp-content/plugins/wordfence/lib/wordfenceClass.php:4364)

    Site 3:

    Wordfence Memory benchmarking utility version 6.3.8.
This utility tests if your WordPress host respects the maximum memory configured
in their php.ini file, or if they are using other methods to limit your access to memory.

--Starting test--
Current maximum memory configured in php.ini: 256M
Current memory usage: 6.00M
Setting max memory to 90M.
Starting memory benchmark. Seeing an error after this line is not unusual. Read the error carefully
to determine how much memory your host allows. We have requested 90 megabytes.
<br />
<b>Fatal error</b>:  Allowed memory size of 94371840 bytes exhausted (tried to allocate 67108872 bytes) in <b>/home/[user]/[domain]/wp-content/plugins/wordfence/lib/wordfenceClass.php</b> on line <b>4388</b><br />
Error received: Cannot modify header information - headers already sent by (output started at /home/[user]/[domain]/wp-content/plugins/wordfence/lib/wordfenceClass.php:4364)

    I’ll focus on site 2 from here on, since it’s the smallest site (so, presumably, easiest to fit memory) and I’m pretty free to reconfigure it as necessary.

    I switched to the Twenty Seventeen theme and ran a scan, which still stalled. I’ll try disabling plugins next, and also send you a Diagnostics Report.

    wfalaa

    (@wfalaa)

    8 years, 10 months ago

    I’ve checked the diagnostics report, on this particular website you sent the report from, I suggest increasing the “WP_MEMORY_LIMIT” to something like 256MB, I can see it’s set to 40MB right now, increasing this value could help in resolving this issue.

    Also, I’ve a question regarding a plugin called “SSO” that is installed on your website as a “Must-Use WordPress Plugin”, I mean installed in “/wp-content/mu-plugins/” directory, any more information regarding this plugin please?

    Thanks.

    Thread Starter keysnparrots

    (@keysnparrots)

    8 years, 10 months ago

    I had no idea that WordPress had its own setting for memory limit. Increasing WP_MEMORY_LIMIT seems to have resolved the issue for site 2, but not the other two sites. I’m thinking that DreamHost’s process killer threshold might be just a little above 40M, so changing this setting allowed this site just enough breathing room.

    I never noticed the SSO plugin before. It’s apparently left over from before I moved this client’s site from BlueHost. Googling the authors shows that they work(ed) for BlueHost. I’m assuming this script automatically logs users in to WordPress when they login to their BlueHost control panel. I’ve removed the file. Here’s a copy of its contents:

    <?php
/**
Plugin Name: SSO
Author: Garth Mortensen, Mike Hansen
Version: 0.1
License: GPLv2 or later
License URI: http://www.gnu.org/licenses/gpl-2.0.html
*/

function sso_check () {
    if ( ! isset( $_GET['salt'] ) || ! isset( $_GET['nonce'] ) || ! isset( $_GET['user'] ) ) { sso_req_login(); }
    if ( sso_check_blocked() ) { sso_req_login(); }
    $nonce = esc_attr( $_GET['nonce'] );
    $salt = esc_attr( $_GET['salt'] );
    $user = esc_attr( $_GET['user'] );
    $bounce = esc_attr( $_GET['bounce'] );
    $hash = base64_encode( hash( 'sha256', $nonce . $salt, false ) );
    $hash = substr( $hash, 0, 64 );
    if ( get_transient( 'sso_token' ) == $hash ) {
        if ( is_email( $user ) ) {
            $user = get_user_by( 'email', $user );
        } else {
            $user = get_user_by( 'id', (int)$user );
        }
        if ( is_a( $user, 'WP_User' ) ) {
            wp_set_current_user( $user->ID, $user->user_login );
            wp_set_auth_cookie( $user->ID );
            do_action( 'wp_login', $user->user_login, $user );
            delete_transient( 'sso_token' );
            wp_safe_redirect( admin_url( $bounce ) );
        } else {
            sso_req_login();
        }
    } else {
        sso_add_failed_attempt();
        sso_req_login();
    }
    die();
}
add_action( 'wp_ajax_nopriv_sso-check', 'sso_check' );
add_action( 'wp_ajax_sso-check', 'sso_check' );

function sso_req_login() {
    wp_safe_redirect( wp_login_url() );
}

function sso_get_attempt_id() {
    return 'sso' . esc_url( $_SERVER['REMOTE_ADDR'] );
}

function sso_add_failed_attempt() {
    $attempts = get_transient( sso_get_attempt_id(), 0 );
    $attempts++;
    set_transient( sso_get_attempt_id(), $attempts, 300 );
}

function sso_check_blocked() {
    $attempts = get_transient( sso_get_attempt_id(), 0 );
    if ( $attempts > 4 ) {
        return true;
    }
    return false;
}

    One other thing I remember that I changed just before this problem started was configuring UpdraftPlus to do daily backups to DropBox. I’ll try reversing that configuration and see what happens.

    I’m really appreciating your help.

    Thread Starter keysnparrots

    (@keysnparrots)

    8 years, 10 months ago

    Reversing the UpdraftPlus configuration had no effect.

    wfalaa

    (@wfalaa)

    8 years, 10 months ago

    I’m glad you got the scan working fine on that website!

    May I have diagnostics reports as well for the other websites? you tried increasing “WP_MEMORY_LIMIT” on both sites but this doesn’t seem to work out, right?

    Thanks.

    Thread Starter keysnparrots

    (@keysnparrots)

    8 years, 10 months ago

    Looks like it’s still having problems on site 2. I looked at the site just now and found that it has been stalled in the middle of a scheduled scan for over two hours.

    I’ve sent you diagnostic reports from the other two sites. The site with the most extensions (though still not an unreasonable number) has been having issues with intermittent 404s and updates not finishing.

    Here are the most recent lines from site 2’s activity log:

    [May 10 13:49:50:1494445790.239938:10:info] SUM_KILLED:A request was received to kill the previous scan.
[May 10 13:49:50:1494445790.230561:1:info] Scan kill request received.
[May 10 13:44:38:1494445478.274001:4:info] Calling Wordfence API v2.23:https://noc1.wordfence.com/v2.23/?v=4.7.4&s=https%3A%2F%2F[domain]&k=6769e2b3427b64603769cfd38996a28ceab61873163cabd7c35042764ea129eb6d49ab65fd0f06ded0cf277f9678b60e1780dc9a0572189c7162ef85a6444cc4&openssl=268439567&phpv=7.0.14&betaFeed=0&cacheType=disabled&action=resolve_ips
[May 10 12:30:03:1494441003.029547:4:info] Calling Wordfence API v2.23:https://noc1.wordfence.com/v2.23/?v=4.7.4&s=https%3A%2F%2F[domain]&k=6769e2b3427b64603769cfd38996a28ceab61873163cabd7c35042764ea129eb6d49ab65fd0f06ded0cf277f9678b60e1780dc9a0572189c7162ef85a6444cc4&openssl=268439567&phpv=7.0.14&betaFeed=0&cacheType=disabled&action=get_net_bad_ips
[May 10 12:06:10:1494439570.098701:4:info] Calling Wordfence API v2.23:https://noc1.wordfence.com/v2.23/?v=4.7.4&s=https%3A%2F%2F[domain]&k=6769e2b3427b64603769cfd38996a28ceab61873163cabd7c35042764ea129eb6d49ab65fd0f06ded0cf277f9678b60e1780dc9a0572189c7162ef85a6444cc4&openssl=268439567&phpv=7.0.14&betaFeed=0&cacheType=disabled&action=resolve_ips
[May 10 10:29:31:1494433771.428288:4:info] Calling Wordfence API v2.23:https://noc1.wordfence.com/v2.23/?v=4.7.4&s=https%3A%2F%2F[domain]&k=6769e2b3427b64603769cfd38996a28ceab61873163cabd7c35042764ea129eb6d49ab65fd0f06ded0cf277f9678b60e1780dc9a0572189c7162ef85a6444cc4&openssl=268439567&phpv=7.0.14&betaFeed=0&cacheType=disabled&action=get_known_vuln_pattern
[May 10 10:29:30:1494433770.808739:4:info] Calling Wordfence API v2.23:https://noc1.wordfence.com/v2.23/?v=4.7.4&s=https%3A%2F%2F[domain]&k=6769e2b3427b64603769cfd38996a28ceab61873163cabd7c35042764ea129eb6d49ab65fd0f06ded0cf277f9678b60e1780dc9a0572189c7162ef85a6444cc4&openssl=268439567&phpv=7.0.14&betaFeed=0&cacheType=disabled&action=ping_api_key
[May 10 06:29:42:1494419382.575672:4:info] Calling Wordfence API v2.23:https://noc1.wordfence.com/v2.23/?v=4.7.4&s=https%3A%2F%2F[domain]&k=6769e2b3427b64603769cfd38996a28ceab61873163cabd7c35042764ea129eb6d49ab65fd0f06ded0cf277f9678b60e1780dc9a0572189c7162ef85a6444cc4&openssl=268439567&phpv=7.0.14&betaFeed=0&cacheType=disabled&action=get_net_bad_ips
[May 10 05:33:58:1494416038.835124:4:info] Calling Wordfence API v2.23:https://noc1.wordfence.com/v2.23/?v=4.7.4&s=https%3A%2F%2F[domain]&k=6769e2b3427b64603769cfd38996a28ceab61873163cabd7c35042764ea129eb6d49ab65fd0f06ded0cf277f9678b60e1780dc9a0572189c7162ef85a6444cc4&openssl=268439567&phpv=7.0.14&betaFeed=0&cacheType=disabled&action=resolve_ips
[May 10 05:33:58:1494416038.834732:4:info] Calling Wordfence API v2.23:https://noc1.wordfence.com/v2.23/?v=4.7.4&s=https%3A%2F%2F[domain]&k=6769e2b3427b64603769cfd38996a28ceab61873163cabd7c35042764ea129eb6d49ab65fd0f06ded0cf277f9678b60e1780dc9a0572189c7162ef85a6444cc4&openssl=268439567&phpv=7.0.14&betaFeed=0&cacheType=disabled&action=resolve_ips
[May 10 03:28:42:1494408522.202386:4:info] Calling Wordfence API v2.23:https://noc1.wordfence.com/v2.23/?v=4.7.4&s=https%3A%2F%2F[domain]&k=6769e2b3427b64603769cfd38996a28ceab61873163cabd7c35042764ea129eb6d49ab65fd0f06ded0cf277f9678b60e1780dc9a0572189c7162ef85a6444cc4&openssl=268439567&phpv=7.0.14&betaFeed=0&cacheType=disabled&action=get_net_bad_ips
[May 10 02:57:09:1494406629.571112:2:info] Scanned comment with Author: Google Source IP: 188.72.108.209
[May 10 02:57:09:1494406629.561751:2:info] Done host key check.
[May 10 02:57:09:1494406629.077580:4:info] Calling Wordfence API v2.23:https://noc1.wordfence.com/v2.23/?v=4.7.4&s=https%3A%2F%2F[domain]&k=6769e2b3427b64603769cfd38996a28ceab61873163cabd7c35042764ea129eb6d49ab65fd0f06ded0cf277f9678b60e1780dc9a0572189c7162ef85a6444cc4&openssl=268439567&phpv=7.0.14&betaFeed=0&cacheType=disabled&action=check_host_keys
    • This reply was modified 8 years, 10 months ago by keysnparrots.
    Thread Starter keysnparrots

    (@keysnparrots)

    8 years, 10 months ago

    Does “Scan process ended after forking” mean that the scan process died?

    Thread Starter keysnparrots

    (@keysnparrots)

    8 years, 10 months ago

    I’m really at a loss trying to figure out what’s going on here. Even after disabling all plugins on site 1, it won’t complete a scan.

    Watching top while scanning isn’t showing anything of interest either. CPU and memory use for the PHP process doing the scanning aren’t any higher than the other running PHP processes. Only the one process dies, so I know that either Dreamhost’s process killer doesn’t operate on the user’s total usage for all processes or it’s not the process killer that’s killing the scan. I don’t know which, and I’m having a hard time getting answers from Dreamhost support.

    Moderator Ipstenu (Mika Epstein)

    (@ipstenu)

    🏳️‍🌈 Advisor and Activist

    8 years, 10 months ago

    @keysnparrots – no promises but if you want to send me your DH ticket, I can try taking a look. mika.epstein@dreamhost.com if you don’t want to publicize it.

    Memory issues are insane to debug. If you’re on Shared DreamHost, you may be having an issue with someone else on the host. Or if you have multiple domains, one of the others may actually be the cause of a timeout.

Viewing 15 replies - 1 through 15 (of 22 total)
1 2

The topic ‘Scans stalling’ is closed to new replies.