Submit method in the FormController is executed twice.

[geertjanknapen1]

Bug description

So I have set up forms using the Statamic routing, but with a custom MailJob. Now it seems that the FormController's submit method is executed twice even though there is only one request, causing me to have duplicate emails being sent out.

This did seem like a front-end issue, but with some pointers from Erin in the Discord, we've basically ruled that out.

So I'm turning to the help of the Github issues, since I've got no clue anymore. Now this might full-well be user error, but I don't see where that user error would be. So any pointers are appreciated.

After testing with Postman, like below, and adding logging directly in the Statamic FormController, I see these logs appearing. (Yes the log entries are older but I can still reproduce it.)

[2024-12-20 19:39:03] local.INFO: Statamic/FormController submit method ran 
[2024-12-20 19:39:03] local.INFO: Statamic/FormController submit method ran 

Since there is only one request, it seems to me there should only be one log entry, but that is not the case.

I'm submitting the form through AJAX, which looks as follows;

$.ajax({
    url: formHtmlElement.action,
    type: 'POST',
    data: formData,
    processData: false,
    contentType: false,
})
    .done(response => {
        if (response.success) {
            let confirmationRow = $('#confirmation-row');
            let formRow = $('#form-row');
            let formButton = $('.form-ajax-submit');

            confirmationRow.removeClass('d-none');
            formRow.addClass('d-none');
            formButton.addClass('d-none');

            $('html, body').stop(true,true).animate({
                scrollTop: (confirmationRow.offset().top - 20)
            }, 500, 'linear');

            // forms.enableSubmit(e);
        }
    })
    .fail(response => {
        form.trigger('form.fail');
        if (response.status === 404) {
            console.log(response.responseJSON.message);

            formErrorSpan.html(failureMessage);
            formErrorSpan.show();
        } else {
            $.each(response.responseJSON.error, function (formFieldName, validationErrorText) {
                let formField = form.find('[name=' + formFieldName + ']');
                let formFieldValidationSpan = form.find('span.' + formFieldName);

                formFieldValidationSpan.html(validationErrorText);
                formFieldValidationSpan.show();
                formField.addClass('is-invalid');
            });
        }

        forms.enableSubmit(e);
    });

We do have a custom MailJob, which looks as follows, but it does not seem like this has anything to do with the root-cause of the issue since the jobs run AFTER the submit method in FormController was executed.

class MailJob implements ShouldQueue
{
    use Dispatchable;
    use InteractsWithQueue;
    use Queueable;
    use SerializesModels;
    use MailSanitizerTrait;
    use JsonFailable;

    /**
     * The number of times the job may be attempted.
     *
     * @var int
     */
    public $tries = 5;

    /**
     * if the task takes longer than this, fail it
     *
     * @var int // in seconds
     */
    public $timeout = 180;

    /**
     * If this task fails, wait 60 seconds before attempting again
     *
     * @var int // in seconds
     */
    public $backoff = 90;

    public $submission;
    public $site;
    public $emailConfiguration;
    private IContentService $contentService;
    private IEmailStatisticsService $emailStatisticsService;

    private const EXTERNAL_NAMESPACE = 'App\\Mail\\External\\';
    private const INTERNAL_NAMESPACE = 'App\\Mail\\Internal\\';

    public function __construct(Submission $submission, Site $site, $config)
    {
        $this->submission = $submission;
        $this->site = $site;
        $this->emailConfiguration = $config;
        $this->contentService = app(IContentService::class);
        $this->emailStatisticsService = app(IEmailStatisticsService::class);

        // Statamic does not allow to set a queue for the forms in config, so we tell the job to run on the 'every_minute' queue in the constructor of the job itself.
        $this->onQueue('every_minute');
    }

    /**
     * Execute the job.
     *
     * @return bool
     *
     * @throws ReflectionException
     */
    public function handle(): bool
    {
        try {
            $formHandle = $this->submission->form->handle();
            $submissionData = $this->submission->toArray();
            $localeEnum = getLocaleEnum();

            // If this the submission does not pass the spam filter, fail the job silently.
            if (!$this->passesSpamCheck($formHandle, $submissionData)) {
                // If the submission does not pass the spam, delete the submission from Statamic as well (so we don't store useless submissions)
                $this->submission->delete();
                exit;
            }

            // Sanitize the question field for the contact form.
            if ($formHandle === Form::CONTACT_FORM->value) {
                $this->disableLinks($submissionData['question']);
            }

            // Get the email template for this form.
            $emailTemplate = $this->contentService->getCollectionEntryInLocale($formHandle, Collection::EMAIL_TEMPLATES,$localeEnum);

            // If email template is null, the mailing will fail, so save the form submission to Statamic anyway and log an error.
            if (is_null($emailTemplate)) {
                $this->submission->save();
                Log::channel(LogChannel::FAILED_FORM_MAILINGS->value)->error("No email template with slug: {$formHandle} found.");
                Log::channel(LogChannel::FAILED_FORM_MAILINGS->value)->info("Submission saved, but no email sent. Please check Statamic submissions", [
                    'submission' => $submissionData,
                ]);

                // return so the user see's the Form Confirmation regardless of whether the email was sent or not.
                exit;
            }

            // Statamic provides $config to the job, which contains the email configuration.
            // Per email defined in the form, a job is fired so just check which email is currently being used, and handle accordingly.
            if (Str::of($this->emailConfiguration['to'])->test("/\\{[^}]*\\}\\}/i")) {
                $fieldHandle = str_replace(['{', ' ', '}'], '', $this->emailConfiguration['to']);
                $email = $submissionData[$fieldHandle];
                $isExternal = true;
            } else {
                $email = $this->emailConfiguration['to'];
                $isExternal = false;
            }

            $mailable = $this->getMailableByFormHandle($formHandle, $emailTemplate, $isExternal);

             // Check if the 'before' method is present in the mailable and execute it before the email is sent.
             if (method_exists($mailable, 'before')) {
                 $mailable->before();
             }

             // Make sure to set the replyTo email address equal to the submitters email address in case of internal, and equal to reply_to in case of external.
             if (!$isExternal) {
                $mailable->replyTo($submissionData['email']);
             } else {
                 $mailable->replyTo($this->emailConfiguration['reply_to']);
             }

             // Sent the email
             Mail::to($email)->locale($localeEnum->value)->send($mailable);

             // If the email is external, we want to update the email statistics widget for this specific form.
             if ($isExternal) {
                 $this->emailStatisticsService->writeOrUpdateStatistic($formHandle, Carbon::now());
             }

             // Check if the 'cleanup' method is present in the mailable and execute it after the mail is sent. (Could be used to remove tmp attachments)
             if (method_exists($mailable, 'cleanup')) {
                 $mailable->cleanup();
             }

            return true;
        } catch (\Exception $e) {
            Log::error('Exception occurred when sending an email', [
                'exception' => $e,
                'message' => $e->getMessage(),
            ]);

            // Fail the job
            $this->fail($e);

            return false;
        }
    }

    /**
     * Returns the mailable based on the formHandle.
     *
     * @param string $formHandle
     * @param Entry $emailTemplate
     * @param bool $isExternal
     * @return Mailable|null
     */
    private function getMailableByFormHandle(string $formHandle, Entry $emailTemplate, bool $isExternal = false): Mailable|null
    {
        $submissionData = $this->submission->toArray();
        // For easy access to the formHandle in the mailable, add it to the submission data.
        $submissionData['formHandle'] = $formHandle;

        try {
            $sanitizedFormHandle = $this->getSanitizedFormHandle($formHandle);
            $className = ($isExternal)
                ? self::EXTERNAL_NAMESPACE . $sanitizedFormHandle . 'ExternalMailable'
                : self::INTERNAL_NAMESPACE . $sanitizedFormHandle . 'InternalMailable';

            return new $className($submissionData, $emailTemplate);
        } catch (\Exception $e) {
            Log::channel(LogChannel::FAILED_FORM_MAILINGS->value)->error('An exception occurred when trying to get the mailable based on the form handle', [
                'form_handle' => $formHandle,
                'submission_data' => $submissionData,
                'message' => $e->getMessage(),
                'exception' => $e,
            ]);

            return null;
        }
    }

    /**
     * Returns the formHandle as a proper classname (i.e. header_contact_form -> HeaderContactForm)
     *
     * @param string $formHandle
     * @return string
     */
    private function getSanitizedFormHandle(string $formHandle): string
    {
        return str_replace(' ', '', ucwords(str_replace('_', ' ', $formHandle)));
    }

    /**
     * Check if the current submission passes the spam filters.
     *
     * @param string $formHandle
     * @param array $submissionData
     * @return bool
     */
    private function passesSpamCheck(string $formHandle, array $submissionData): bool
    {
        if ($formHandle === Form::CONTACT_FORM->value) {
            // If the spam filter does not pass, fail the job silently.
            if (!spamFilter($submissionData['question'])) {
                return false;
            }
        }

        if ($formHandle === Form::HEADER_CONTACT->value) {
            // If the spam filter does not pass for these fields, fail the job silently.
            if (
                !spamFilter($submissionData['company_name']) ||
                !spamFilter($submissionData['first_name'], 1) ||
                !spamFilter($submissionData['last_name'], 1)
            ) {
                return false;
            }
        }

        return true;
    }
}

How to reproduce

Honestly, no clue.

I guess you can setup a form and try to post it using AJAX and see the same result.

Logs

No response

Environment

Environment
Application Name: myapp
Laravel Version: 11.36.1
PHP Version: 8.3.13
Composer Version: 2.8.2
Environment: local
Debug Mode: ENABLED
URL: myapp.test
Maintenance Mode: OFF
Timezone: UTC
Locale: en

Cache
Config: NOT CACHED
Events: NOT CACHED
Routes: NOT CACHED
Views: CACHED

Drivers
Broadcasting: null
Cache: file
Database: mysql
Logs: stack / daily
Mail: smtp
Queue: redis
Session: file

Statamic
Addons: 3
Sites: 2 (English, Dutch)
Stache Watcher: Disabled
Static Caching: half
Version: 5.44.0 PRO

Statamic Addons
spatie/statamic-responsive-images: 5.0.0
statamic-rad-pack/meilisearch: 3.3.0
withcandour/aardvark-seo: 5.0.0

Installation

Fresh statamic/statamic site via CLI

Additional details

No response

[duncanmcclean]

Are you able to replicate this on a fresh site?

[geertjanknapen1]

Not yet. Need to set up a new test site with the correct versions and such. Also have to copy all the helpers and customizations we did. Hopefully I get around to it this evening or tomorrow.

But I just tested Statamic's mail job (instead of our custom one) and still got four e-mails (instead of the expected two), so it seems to me it's not the Job being a problem.

[geertjanknapen1]

So I can't get it reproduced on a fresh site, even though it is the same code. There are no duplicate requests happening there, also not on the same version as running on the live site.

I did create a fresh site with a minimal install if you want to check it out, but I guess I will have to dig deeper.
Minimal example.zip

[geertjanknapen1]

Small update, I have come up with the following logging, which whould indicate my AJAX is posting multiple times.

[10:44:45] local.INFO: Posted to Statamic\FormController using AJAX.  <-- Initial AJAX call, correct
[10:44:45] local.INFO: FormController calling SendEmails::dispatch due to Illuminate\Routing\Controller::callAction  <-- SendMails dispatch byStatamic, correct but not queueing jobs?
[10:44:49] local.INFO: Posted to Statamic\FormController using AJAX.  <-- A second unexplainable AJAX call, incorrect.
[10:44:49] local.INFO: SendEmails called by Statamic\Forms\SendEmails::dispatch  <-- A second SendEmails dispatch by Statamic, incorrect (but kinda correct, because the first AJAX call did not queue jobs).
[10:44:49] local.INFO: MailJob added to queue by Statamic\Forms\SendEmails::Statamic\Forms\{closure}  <-- MailJob for email config 1, correct.
[10:44:49] local.INFO: MailJob added to queue by Statamic\Forms\SendEmails::Statamic\Forms\{closure}  <-- MailJob for email config 2, correct.
[10:44:49] local.INFO: FormController calling SendEmails::dispatch due to Illuminate\Routing\Controller::callAction <-- Huh?!
[10:44:49] local.INFO: SendEmails called by Statamic\Forms\SendEmails::dispatch  <--A third SendEmails dispatch byStatamic, incorrect (but is adding jobs to the queue this time??)
[10:44:49] local.INFO: MailJob added to queue by Statamic\Forms\SendEmails::Statamic\Forms\{closure}  <-- MailJob for email config 1, incorrect, is a duplicate.
[10:44:49] local.INFO: MailJob added to queue by Statamic\Forms\SendEmails::Statamic\Forms\{closure}  <-- MailJob for email config 2, incorrect, is a duplicate.

In the network tab, all is see is the following request. (To which I added a timestamp to make sure they are not grouped or anything by the DevTools). The open?op=... requests are from Laravel Debugbar.

---

Long story short, I am stumped.

[duncanmcclean]

Do you have any event listeners?

Queue: redis

How are you running your queue worker in production? With Redis as well? Are you using Laravel Horizon, or the default php artisan queue:work command?

[geertjanknapen1]

There is no event listeners regarding forms, so that'd be a no I guess.

Queue redis is used on my local environment, prod is using sync (just found that out, nice). But I observe the same behaviour on both environments.
But we run the queue worker using Supervisord with the following command php artisan queue:work --no-interaction --tries=3 --rest=1 --max-jobs=10 --queue=every_minute >> /usr/share/nginx/html/storage/logs/queue_monitor.log

[duncanmcclean]

Are you able to provide access to the site with the issue? You can either add me on GitHub (duncanmcclean) or send in a zip to [email protected].

[geertjanknapen1]

No need Duncan! We've solved the issue.

We had a middleware to set a default locale that was not ignoring Statamic's action routes.
Someone decided to check the $next($request) closure directly, without a ReflectionClass or anything, causing the closure to be executed in the if-statement check and after the middleware was done.

But it was not throwing errors or anything ofcourse so it proved to be a difficult little bugger to find.

So, definitely user error on our part, thanks for the suggestions and excelent help, as always!

[jasonvarga]

Thanks for the update!