floodcontrol can incorrectly fail a submission
While investigating a client complaint, I found multiple log entries like this:
Aug 23 15:43:19 [warning] floodcontrol: 45.130.83.84 FAIL Register [0], filled in 0 seconds
They were mostly followed by a PASS some time later, presumably from a resubmission.
I did a test on a contribution page and got the same result, which appeared after the Stripe "pre-authorizing your card" sweetalert-styled message.
Interestingly, here's the Civi log for my failure, followed by the relevant Apache logs, with timestamps:
Civi:
Aug 23 16:10:59 [warning] floodcontrol: 24.191.15.235 FAIL Main [0], filled in 0 seconds
Apache:
mysite.org:443 24.191.15.235 - - [23/Aug/2022:16:10:17 -0400] "GET /civicrm/asset/builder?an=civicrmStripe.js&ap=Pc5LCgJBDATQu/RaO3vPEpAYgmboT%2BhkZhTx7vYguAvFKyrvZBSPdEkIGw2Efd8RuLcmHNkKeShbL2UN7Y07FT2O3Md9WrkhuIY4ApUye7opj3rm1aNXBHmGNJ9%2BAo%2BhJgiL/931l%2BXF0ylVrRIvk/kKmRVlOoamp42cp4v0%2BQI%3D&ad=41298c39868eebc490ab2e8f27b786a8 HTTP/1.1" 200 8020 "-" "Mozilla/5.0 (X11; Linux x86_64; rv:103.0) Gecko/20100101 Firefox/103.0"
mysite.org:443 24.191.15.235 - - [23/Aug/2022:16:10:17 -0400] "GET /civicrm/asset/builder?an=crm-l10n.js&ap=XczLCsIwEEDRfxlcBuuzi%2B5EFFwoirgryJgMNTJJSh5oEf/duLCI23vgPkFqBdVIgLaSk6KVQc0bu0NDUEWfSADe8LF3bWrDyuKFSfXA7O4LJh8XKTqlg9EhIH/ZU3DJS1qivNLSqTyEFMrmQPZ8OoIAdhL5U/sgt5QPDYWfqDDSxrYprp03GLMYUxdK1UXXZY7a/PE4V%2BMsdX0ZjMVkOhvOS3i9AQ%3D%3D&ad=2e4f9c19a4f21221b1129aa38126bdfc HTTP/1.1" 200 2970 "-" "Mozilla/5.0 (X11; Linux x86_64; rv:103.0) Gecko/20100101 Firefox/103.0"
mysite.org:443 24.191.15.235 - - [23/Aug/2022:16:10:57 -0400] "POST /civicrm/ajax/rest HTTP/1.1" 200 5683 "https://mysite.org/civicrm/contribute/transact?reset=1&id=4&action=preview" "Mozilla/5.0 (X11; Linux x86_64; rv:103.0) Gecko/20100101 Firefox/103.0"
mysite.org:443 24.191.15.235 - - [23/Aug/2022:16:10:59 -0400] "POST /civicrm/contribute/transact HTTP/1.1" 200 23252 "https://mysite.org/civicrm/contribute/transact?reset=1&id=4&action=preview" "Mozilla/5.0 (X11; Linux x86_64; rv:103.0) Gecko/20100101 Firefox/103.0"
mysite.org:443 54.187.205.235 - - [23/Aug/2022:16:10:59 -0400] "POST /civicrm/payment/ipn/4 HTTP/1.1" 200 5440 "-" "Stripe/1.0 (+https://stripe.com/docs/webhooks)"
I think this is because buildForm()
is generally called on post-process (see the flowchart on https://docs.civicrm.org/dev/en/latest/framework/quickform/). I'm guessing that the cached time (when the page is first loaded) is getting written to a second time on submission.