Something about spam handling can result in hung PHP-FPM processes, which eventually take down PHP.

MattWilcox commented 1 month ago

Describe the bug

This one took hours to track down, and I'm not sure where to look beyond that it seems to be Formie and spam submission related bug of some sort.

We have been hitting issues on a server where PHP has stopped processing all websites hosted on the server - so all websites become white-screens, unresponsive. PHP-FPM has to be restarted to restore sites on the server.

Because nothing obvious was in any logs, we used a simple PHP function to get a window into what's happening on the PHP-FPM process level:

<?php print_r(fpm_get_status()); ?>

What was showing up was numerous stuck processes where the State was Getting request information and never closing. They were always POST methods, and were always on the same website. Making an strace on any of the stuck process IDs showed it stuck on a Read operation:

sudo strace -p 268093
strace: Process 268093 attached
read(5,

We then went lookiing in the logs for that website, and discovered what appear to be spam submissions throwing various errors in Formie - most obvious in the web.log file, but also some making it into the formie.log file. Stuff like Invalid numeric value and Unable to verify your data submission or General error: 1525 Incorrect DATETIME value: '' The SQL being executed was: or Unsupported operand types: string + int.

All forms on the site have Recaptcha integration turned on and working. The site with the problem has been working for some time (months) and other than having some Craft updates installed, nothing has changed on it. So... seems likely to be some sort of spam bot hitting the site now.

To attempt to confirm these stuck processes were actually Formie related (because you can't tell just from the PHP-FPM report) we disabled Formie and left the site running with it disabled for 30 minutes. During that time, we did not get any stuck PHP processes. After re-enabling Formie, we got another stuck process within a few minutes.

I have no idea how to help you on this, but I've attached the logs we have. I've tried to marry up the stuck-processes' timestamps to the logs (our logs are BST, so converting from UNIX to that does seem to work) - but we don't retain a record of the stuck processes because we don't know about them unless we're looking at that PHP function output from up there ^. Nothing seems to get recorded, presumably because a "stuck process" isn't an error that can be logged.

I do not know enough (even close) about the guts of PHP and Craft/Formie, but if I had to guess - it's as though something in how the spam submission is handled causes a failure to send any response to the HTTP requester - which leaves the PHP process open forever, which then causes our PHP-FPM pool to run out of available processes, which then causes all sites to become unresponsive.

formie-2024-09-12.log

web-2024-09-12.log

Steps to reproduce

See above.

Form settings

Multi-page form: Yes
Submission Method: Ajax
Client-side Validation: Yes
Custom Form Templates: Yes

Craft CMS version

4.12.2

Plugin version

2.1.29

Multi-site?

Yes

Additional context

PHP version	8.1.29
OS version	Linux 6.9.8-orbstack-00170-g7b4100b7ced4
Database driver & version	MariaDB 10.3.39
Image driver & version	Imagick 3.7.0 (ImageMagick 6.9.11-60)
Craft edition & version	Craft Pro 4.12.2
Yii version	2.0.51
Twig version	v3.14.0
Guzzle version	7.9.2

Blitz	4.23.0
Blitz Recommendations	2.2.1
CKEditor	3.9.0
Consume	1.0.12
Feed Me	5.7.0
Formie	2.1.29
Google Maps	4.5.2
Hyper	1.2.2
Image Resizer	3.0.12
Imager X	4.4.1
Maps	4.0.8
Minify	4.0.1
Navigation	2.1.1
Neo	4.2.12
Retour	4.1.19
SEO	4.1.3
Sprig	2.13.0
Vite	4.0.10

MattWilcox commented 1 month ago

Yeah, something's trying to hack around with forms...

                (
                    [pid] => 270986
                    [state] => Idle
                    [start-time] => 1726148783
                    [start-since] => 49
                    [requests] => 112
                    [request-duration] => 450846
                    [request-method] => GET
                    [request-uri] => /index.php
                    [query-string] => category=health-and-wellbeing&date=022024*DBMS_PIPE.RECEIVE_MESSAGE(CHR(99)%7C%7CCHR(99)%7C%7CCHR(99)%2C15)&keyword=the
                    [request-length] => 0
                    [user] => -
                    [script] => /websites/fit/web/index.php
                    [last-request-cpu] => 93.158193016458
                    [last-request-memory] => 48234496
                )

MattWilcox commented 1 month ago

We have also spotted in the logs something a little more alarming, as it looks as though there's malformed data in the siteId parameter, and I don't see why a front-end form would need to be posting that back to the CMS.

  "yourName": {
    "firstName":"CpjJwWHV",
    "lastName":"CpjJwWHV"
  }
},
"handle":"testForm",
"redirect":"2e123dce749316d67afbce8e561073e142518e08dff44a4770119e832c0ea00fhttps://REDACTED.com/contact/thank-you-for-getting-in-touch?query=http%3A//www.example.com",
"siteId":"-5) OR 65=(SELECT 65 FROM PG_SLEEP(15))--",
"submitAction":"submit"
}

from

2024-09-12 14:46:23 [web.ERROR] [yii\web\HttpException:400] Request has invalid param siteId {"trace":["#0 /websites/fit/vendor/verbb/formie/src/controllers/SubmissionsController.php(1125): verbb\\formie\\controllers\\SubmissionsController->_getTypedParam()","#1 /websites/fit/vendor/verbb/formie/src/controllers/SubmissionsController.php(467): verbb\\formie\\controllers\\SubmissionsController->_populateSubmission()","#2 [internal function]: verbb\\formie\\controllers\\SubmissionsController->actionSubmit()","#3 /websites/fit/vendor/yiisoft/yii2/base/InlineAction.php(57): call_user_func_array()","#4 /websites/fit/vendor/yiisoft/yii2/base/Controller.php(178): yii\\base\\InlineAction->runWithParams()","#5 /websites/fit/vendor/yiisoft/yii2/base/Module.php(552): yii\\base\\Controller->runAction()","#6 /websites/fit/vendor/craftcms/cms/src/web/Application.php(341): yii\\base\\Module->runAction()","#7 /websites/fit/vendor/craftcms/cms/src/web/Application.php(640): craft\\web\\Application->runAction()","#8 /websites/fit/vendor/craftcms/cms/src/web/Application.php(303): craft\\web\\Application->_processActionRequest()","#9 /websites/fit/vendor/yiisoft/yii2/base/Application.php(384): craft\\web\\Application->handleRequest()","#10 /websites/fit/web/index.php(12): yii\\base\\Application->run()","#11 {main}"],"memory":11551264,"exception":"[object] (yii\\web\\BadRequestHttpException(code: 0): Request has invalid param siteId at /websites/fit/vendor/verbb/formie/src/controllers/SubmissionsController.php:1254)"} 
2024-09-12 14:46:23 [web.WARNING] [application] Request context: {"environment":"production","sessionId":"r04c2c6a2hpji40odfvb9up4em","vars":{"_GET":{"query":"http://www.example.com"},"_POST":{"CRAFT_CSRF_TOKEN":"••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••","action":"formie/submissions/submit","fields":{"areYouHappyToReceiveOurENews":"1","message":"555","topic":"General enquiry","yourEmail":"testing@example.com","yourName":{"firstName":"CpjJwWHV","lastName":"CpjJwWHV"}},"handle":"testForm","redirect":"2e123dce749316d67afbce8e561073e142518e08dff44a4770119e832c0ea00fhttps://redactedproject.com/contact/thank-you-for-getting-in-touch?query=http%3A//www.example.com","siteId":"-5) OR 65=(SELECT 65 FROM PG_SLEEP(15))--","submitAction":"submit"},"_FILES":[],"_COOKIE":{"CraftSessionId":"r04c2c6a2hpji40odfvb9up4em","cookie_consent_level":"{\"strictly-necessary\":true,\"functionality\":false,\"tracking\":false,\"targeting\":false}","CRAFT_CSRF_TOKEN":"••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••"},"_SESSION":{"b549066c37441b91622fcf5426f4479f__flash":{"formie.246564:error":-1,"formie.4537:submitted":-1},"formie:246564:pageId":2339,"formie.246564:error":"<p>Couldn’t save submission due to errors.</p>","formie.4537:submitted":true},"_SERVER":{"USER":"www-data","HOME":"/var/www","HTTP_USER_AGENT":"Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/108.0.0.0 Safari/537.36","HTTP_REFERER":"https://redactedproject.com/","SSL_PROTOCOL":"TLSv1.3","HTTP_HOST":"redactedproject.com","REMOTE_PORT":"60067","QUERY_STRING":"query=http://www.example.com","CONTENT_LENGTH":"1467","HTTP_X_REQUESTED_WITH":"XMLHttpRequest","HTTP_COOKIE":"CraftSessionId=r04c2c6a2hpji40odfvb9up4em; cookie_consent_level=%7B%22strictly-necessary%22%3Atrue%2C%22functionality%22%3Afalse%2C%22tracking%22%3Afalse%2C%22targeting%22%3Afalse%7D; CRAFT_CSRF_TOKEN=ee73c03bb96025129bb0e0617132b405d9e62f9a6517e837b6732c7db4077bd2a%3A2%3A%7Bi%3A0%3Bs%3A16%3A%22CRAFT_CSRF_TOKEN%22%3Bi%3A1%3Bs%3A40%3A%22khGyCL6AMXmWR3SNpR5y3zYkcs7kxcjEDIamKHWi%22%3B%7D","SERVER_PORT":"443","REQUEST_URI":"/contact?query=http://www.example.com","HTTP_X_FORWARDED_FOR":"5.252.177.33","HTTP_ACCEPT":"text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8","HTTPS":"on","DOCUMENT_URI":"/index.php","SERVER_NAME":"redactedproject.com","GATEWAY_INTERFACE":"CGI/1.1","HTTP_X_FORWARDED_PROTO":"https","HTTP_CONTENT_LENGTH":"1467","SSL_CIPHER":"TLS_AES_128_GCM_SHA256","REMOTE_USER":"","REMOTE_HOST":"5.252.177.33","PATH_INFO":"","HTTP_CONTENT_TYPE":"multipart/form-data; boundary=----------YWJkMTQzNDcw","SCRIPT_NAME":"/index.php","SCRIPT_FILENAME":"/websites/fit/web/index.php","SERVER_PROTOCOL":"HTTP/1.1","CONTENT_TYPE":"multipart/form-data; boundary=----------YWJkMTQzNDcw","REQUEST_SCHEME":"https","REMOTE_ADDR":"5.252.177.33","HTTP_X_FORWARDED_HOST":"redactedproject.com","REQUEST_METHOD":"POST","REMOTE_IDENT":"","AUTH_TYPE":"","HTTP_ACCEPT_ENCODING":"gzip,deflate,br","DOCUMENT_ROOT":"/websites/fit/web","SERVER_SOFTWARE":"Caddy/v2.8.4","FCGI_ROLE":"RESPONDER","PHP_SELF":"/index.php","REQUEST_TIME_FLOAT":1726148783.667547,"REQUEST_TIME":1726148783,"SYSTEM_IS_LIVE":"true","CRAFT_ENVIRONMENT":"production","CP_TRIGGER":"secretadmin","SYSTEM_NAME":"Fields in Trust","PRIMARY_SITE_NAME":"Fields in Trust PRIMARY","PRIMARY_SITE_URL":"https://redactedproject.com","PRIMARY_SITE_WEB_ROOT":"/websites/fit/web","USE_QUEUE_DAEMON":"true","BLUEPRINT_SITE_NAME":"Fields in Trust Blueprint","BLUEPRINT_SITE_URL":"https://fit-bp.ddev.site","CRAFT_APP_ID":"CraftCMS--d803acdb-12e1-447e-9545-3e9e2628ceca","CRAFT_SECURITY_KEY":"••••••••••••••••••••••••••••••••","PATH_TO_CWEBP":"/usr/bin/cwebp","LICENSE_KEY_BLITZ":"••••••••••••••••••••••••","LICENSE_KEY_IMAGERX":"••••••••••••••••••••••••","LICENSE_KEY_NAVIGATION":"••••••••••••••••••••••••","LICENSE_KEY_SEOMATIC":"••••••••••••••••••••••••","LICENSE_KEY_HYPER":"••••••••••••••••••••••••","LICENSE_KEY_GOOGLEMAPS":"••••••••••••••••••••••••","LICENSE_KEY_FORMIE":"•••••••••••••••••••••••••••••","LICENSE_KEY_CONSUME":"•••••••••••••••••••••••••••••","LICENSE_KEY_NEO":"•••••••••••••••••••••••••••••","LICENSE_RETOUR":"0N2W-VWIJ-YN3A-4TCS-MUTQ-QY9C","BLITZ_CACHE_ENABLED":"true","SSI_ENABLED":"true","SERVER_TYPE":"caddy","GOOGLEMAPS_BROWSERKEY":"AIzaSyAzrpH095sTD9nckAjxe99wFcneRWKV4a4","GOOGLEMAPS_SERVERKEY":"AIzaSyDiHyT5DatAMjzmSBiWhIwae4vDlO--bxg","CRAFT_DB_DRIVER":"mysql","CRAFT_DB_SERVER":"127.0.0.1","CRAFT_DB_PORT":"3306","CRAFT_DB_DATABASE":"fit","CRAFT_DB_SCHEMA":"public","CRAFT_DB_TABLE_PREFIX":"","CRAFT_DB_USER":"fit","CRAFT_DB_PASSWORD":"••••••••••••••••••••••••","TEST_TO_EMAIL_ADDRESS":"gareth@REDACTED.co.uk","SYSTEM_EMAIL_ADDRESS":"website@redactedproject.com","SYSTEM_REPLY_TO_ADDRESS":"website@redactedproject.com","SYSTEM_SENDER_NAME":"Fields in Trust","SYSTEM_HTML_EMAIL_TEMPLATE":"_emails/notifications","SYSTEM_TRANSPORT_TYPE":"SMTP","SMTP_HOST":"in-v3.mailjet.com","SMTP_PORT":"465","SMTP_USERNAME":"7f077d336c83a417eed9b23bc5a318a7","SMTP_PASSWORD":"••••••••••••••••••••••••••••••••","SYSTEM_USE_AUTH":"true","SYSTEM_ENCRYPTION_METHOD":"ssl","CRAFT_WEB_URL":"https://redactedproject.com","CRAFT_WEB_ROOT":"/websites/fit/web","MAILHOG_SMTP_HOSTNAME":"127.0.0.1","MAILHOG_SMTP_PORT":"1025","SAGE_API_BASE":"http://fit.loriacrm.com/sdata/crmj/sagecrm2/-/","SAGE_API_USER":"REDACTED","SAGE_API_PASSWORD":"••••••••••","WORK_FOR_YOU_ENDPOINT":"https://www.REDACTED.com/api/","WORK_FOR_YOU_USER":"REDACTED","WORK_FOR_YOU_KEY":"••••••••••••••••••••••••"}}}

engram-design commented 1 month ago

Yeah, something is clearly hammering your site with POST requests to Formie, and while error-handling is catching most of these (we're pretty strict about what a submission accepts, and its fields). These are direct HTTP POST requests rather than submissions from the front end, which is why they can send some messed up values our way.

I'm not sure where the responsibility lies with regard to rate-limiting these sorts of things, whether that's Formie, Craft or on your server. I suppose with Formie, we can at least add some handling there. There is a "Limit Submissions" setting for forms, but that's not able to be set less than daily. It's not really designed for rate-limiting either.

As for why a submission is even holding up the PHP process, that's possibly beyond be expertise without getting my hands on it. It could be the logging process that's holding things up for example. Craft holds in-memory log data until a request has ended and it's flushed to disk. It could be the case that there's just so much activity that it's always being written to, and a lock can't be gained.

Not to worry about those values, that's the reason we have a _getTypedParam() function to protect against these bad values. In the instance of siteId, we won't accept anything other than an ID, so this sort of bad value is caught very early on at the start of the submission process.

And I've seen these things before, they're penetration tests, so someone or something is doing automated tests on your site for vulnerabilities.

So, I suppose my recommendation is to first check if your client is doing security tests (it's happened before when clients don't give developers a heads-up first!), look into rate-checking the actions/formie/submissions/submit endpoint.

MattWilcox commented 1 month ago

Thanks Josh... yeah, this is somewhat beyond my own knowledge and skillset tbh too, no idea how you'd rate limit anything - and I can't even get to marry up these requests with IPs to try banning them as things stand.

Good to know the values in there aren't anything to worry about. We're on the latest OS everything and latest Craft everything, so hopefully they won't actually get anywhere - but just the attempts are enough to be taking PHP down at the moment, so it's still "an issue" for us :/

engram-design commented 1 month ago

I'll do a bit of quick research (and hassle the Craft crew) if their better brains have any ideas! Might be worth pinging some people on Discord if thay've done similar things...

MattWilcox commented 1 month ago

In case anyone else ever gets this sort of thing:

A partial solution to at least help avoid the server going down was to edit the PHP-FPM pool such that no PHP process can live longer than X amount of time, and to increase the allowed number of processes from the default.

/etc/php/8.x/fpm/pool.d/www.conf

Uncomment the request_terminate_timeout line and set it to however many seconds seems reasonable to kill a process if it goes beyond.
Change the pm.max_children = 5 to whatever you feel should be reasonable.

Also of note, the server never appeared to be "stressed" and the load / memory use never seemed anything other than low. The issue was the exhausting of PHP-FPM processes and not excessive load.

We are currently getting CloudFlare set up in front of the site in hopes it will detect the abuse and kerb it - though I don't like having to rely on third party services for this really.

verbb / formie