Async function is not executed (awaited) in one AWS Lambda function but is in another

user_3281427 0
Viewed 576

Consider the following MailService:

export class MailService {
    private transporter?: nodemailer.Transporter;

    async sendMail(opts: {
        from: string,
        to: string,
        subject: string,
        template?: string,
        context?: any,
        bcc?: string,
        html?: string
    }) {
        console.log(`About to send an email to ${opts.to}...`);

        this.getTransporter();
        console.log("Generating email content...");
        let htmlToSend = "Default message."
        if (opts.template) {
            const htmlData = await fs.readFile(path.resolve(__dirname, process.env.EMAIL_TEMPLATES_DIR + opts.template), { encoding: 'utf-8' });
            const htmlBuffer = Buffer.from(htmlData);
            const template = handlebars.compile(htmlBuffer.toString());
            htmlToSend = template(opts.context);
        }
        if (opts.html) {
            htmlToSend = opts.html
        }

        const mailOptions = {
            from: opts.from,
            to: opts.to,
            subject: opts.subject,
            html: htmlToSend
        };
        console.log(htmlToSend);
        console.log("Sending...");   

        // Here, lambda just terminates silently
        const sentMessageInfo = await this.transporter.sendMail(mailOptions);
        // This log is never displayed:
        console.log("Done.", sentMessageInfo);
        return sentMessageInfo;
    }

    /* Creates a mail transporter if needed */
    private getTransporter() {...}
}

Then in my express endpoints, I am using the service like this:

app.post("/subscriptions/new", async (req, res) => {
    // Check if this Customer already exists before creating it
    let customer = await stripeService.getExistingCustomer(req.body.email);

    const returningCustomer = customer !== null;

    if (returningCustomer) {
        console.log("Customer(s) with same email address already exist(s).", customer);
    }
    else {
        customer = await stripeService.createCustomer({
            name: req.body.name,
            email: req.body.email,
            phone: req.body.phone,
            source: req.body.stripeSource,
            preferred_locales: ['fr-FR'],
            metadata: {
                ...
            }
        });
        console.log("New Customer created", customer);
    }

    // Serve a success page
    const filePath = path.resolve(process.env.STATIC_DIR + "/success.html");
    res.sendFile(filePath);

    // Send notifications to My Company and the Customer using nodemailer
    const mailService = new MailService();

    if (customer && returningCustomer) {
        console.warn("This is a returning customer. Sending the returning customer email.", returningCustomer);
        await mailService.sendMail({
            from: "'The Guy' <no-reply@mydomain.com>",
            to: customer.email as string,
            bcc: "order@mydomain.com",
            subject: "Merci pour votre confiance",
            template: "returning-customer.handlebars",
            context: {
                customer,
                subscription: req.body,
                orderItems: req.body.orderItems.split('\n'),
                futureDeliveries: Scheduler.getFutureDeliveries({
                    frequencyStr: req.body.frequency,
                    targetWeekDay: Scheduler.getWeekDayFromDropLocation(req.body.dropLocation)
                })
            }
        });
        console.log("Returning customer email sent.");
    }
    else {
        if (customer) {
            await mailService.sendMail({
                from: "'The Guy' <no-reply@mydomain.com>",
                to: customer.email as string,
                bcc: "order@mydomain.com",
                subject: "Merci pour votre confiance !",
                template: "new-customer.handlebars",
                context: {
                    customer,
                    subscription: req.body,
                    orderItems: req.body.orderItems.split('\n'),
                    futureDeliveries: Scheduler.getFutureDeliveries({
                        frequencyStr: req.body.frequency,
                        targetWeekDay: Scheduler.getWeekDayFromDropLocation(req.body.dropLocation)
                    })
                }
            });
            console.log("The confirmation email has been sent to the new customer", customer.email);
        }
    }
})

Everything runs fine locally.

Here is my functions definition from serverless.yml:

functions:
  my-api:
    handler: handler.handler
    events:
      - http:
          path: /
          method: GET
          cors: true
      - http:
          path: /{proxy+}
          method: ANY
          cors: true
  cronjobs:
    handler: handler.sendDeliveryReminders
    events:
      # every day at 03:00 PM
      - schedule: cron(0 15 * * ? *)

And finally my handlers:

const serverlessExpress = require('@vendia/serverless-express');
const app = require('./src/server.js');

// This doesn't await for every async call to complete before terminating the lambda invocation
exports.handler = serverlessExpress({
  app: app.app
});

// This is awaiting everything as expected
exports.sendDeliveryReminders = require('./src/cronjobs.js').sendDeliveryReminders;

Sending emails is done both in the API endpoints (handler.handler) and the cronjobs (handler.sendDeliveryReminders). However, only the latter works.

When trying to send an email from an API endpoint (with the exact same parameters as those working in the cronjobs), the lambda function stops at the sendMail call (EDIT: or even a few instructions before! It can fail as soon as it hits the await fs.readFile in MailService.sendMail):

// Here, lambda just terminates silently
const sentMessageInfo = await this.transporter.sendMail(mailOptions);
// This log is never displayed:
console.log("Done.", sentMessageInfo);

It's as if await this.transporter.sendMail(mailOptions) is never really awaited, even though it is called within an async function and should have something inside to await for (I assume the implementation of Nodemailer is correct).

Here is a log from CloudWatch:

2021-03-02T11:08:10.409+01:00   START RequestId: 0c455857-ab09-4547-b861-038e91f666b7 Version: $LATEST

2021-03-02T11:08:10.724+01:00   2021-03-02T10:08:10.724Z 0c455857-ab09-4547-b861-038e91f666b7 WARN This is a returning customer. Sending the returning customer email. true

2021-03-02T11:08:10.727+01:00   2021-03-02T10:08:10.726Z 0c455857-ab09-4547-b861-038e91f666b7 INFO About to send an email to me@mydomain.com...

2021-03-02T11:08:10.727+01:00   2021-03-02T10:08:10.727Z 0c455857-ab09-4547-b861-038e91f666b7 INFO Creating the mail transporter...

2021-03-02T11:08:10.728+01:00   2021-03-02T10:08:10.728Z 0c455857-ab09-4547-b861-038e91f666b7 INFO Generating email content...

2021-03-02T11:08:10.735+01:00   2021-03-02T10:08:10.734Z 0c455857-ab09-4547-b861-038e91f666b7 INFO SERVERLESS_ENTERPRISE {"c":true,"b":"H4sIAAAAAAAAA7VXbU/bSBD+K5F1J7Vq7Oz63anQHUcD9IAeImmLWtBpbY8Tg+M1a5skoPz3m7WdVwJXKpUvODvPzM7OzD6z86hwEQ/jVOkqeZKrbAhpobSVPBjBmH0BkcdcyohGcLWIx5AXbJzhik50qhJDJfqAki5xu5RojmF+Q5iAuxJxH0OpGJiW5VqOynziqaZlOqrv2lLTBY9Gtm37jrQ8ywDRhWBpzoJCbtpWMjZLOEMrj40/gxqVq3nG0me95BkIJk18YuMavmZWjcp0YR+PIopBXIF2HcekljwOpOELoObMYVnvqXQN6mousQ3Twh3QzwOeFjAt5CnQjwBeExapX+EpuBbx/Ui1PZeoJtFD1XMBVNf0Qz80dM91PMRPB8sdLjgv9qhqEwMIuEx1HMulDIDSwKChB44dRdSg+vtzJjDne9QnxPEiUwdXd0ww3/cxzwmEe0SZY37YMN+Rh+cC+1PV04Sbi6E8QFomSVthWZbEwXo2x3EguA+qz4JbzIyKCLkjiPs4gN2YOtXDhTSEe1xZuPuMWQSpizWWxY37vMQ82m0l4OOsLKCJA5vkWsLGfsiUpeiiTIu6aFZSLeUh3OQa1TWdaHQNDMM6UFCqE4yRuiY7gzEXs378IG1Ropvbos85yHw/Xikiz6+UrmMQ3TBdt32ljIBlA16wBJepY1uGY5NmWWrJVYtSh+pyFWsURFpjLc9zXBsXmRBs9lcZRZhLKaCObrjzbRfOQQRYQxji2hmqGbZDXcda4uQlYHEK4nNWh0X3LI0S03GIbq8C+jE/4EnYl/dS6UYsyWElSjGHKRZ3es/rgjjgGGO0tNqkzAs+7m+WaCNTMQ3qdpLWFbardQNy+Npi2am92uK30/1Brz/YBu4LKWQi7aK33drb7rImup5Mq+kYlmVY3UX9dl/pzEu1ViNeqLgaIFNwC6tLunmGSX7xev7fMHH5S1hsa5NTPjwSvMyalHYw4p064p1XRhQt9QsBbNyYktzWIUaH6J3vTaKvDWbYzGcO3rfQjGzHtUwaBa5LQ+J6GJBtm730/jxhRcTFGC0mcVpOd0D2RTBC8dR+kiIU1mmsrj/eSF3Hy2Z7uvsc8FAAOk+JQT3sJpb9FHeQldgDlO/INGMkMkkUV8pHbG7Jm4u3rUvgqfx/LngAec5F68+Wrlnk6PjhSkEmyTOoGEe3iGSbqhngTzRWInnjl1VxU4osjj/kZz6TANuS33GYQE1itk6rBXEnYfN5+xe5Y9Kd7tTLa+44m+5cywfDPZbiWm/AmhmyAiZspo2KIlsi/qcfGo77bYHt8xIp9om9hXgn81WSivdWCuq6Ay/R3xpgPwgk01b3cZ2CtlBZXCHuInIb2+KmgE35BeTVGSqQf5OYNNgEfOBj7BDnAqJ4+oKdvmwzyy7+RH9DU4MpBBX5Z7G25DuNjdkDT2UkscS3vVxR1w++uda0e9hC0xDCdSv+TUB57+TyA+8dTqzJ3s79mvclMsYZEx1ZDN1FGbTeEfx7VquXcckB1Kam7Xi2R7BqNrDHmPBzVkie6Dxmgk9n7+bKE8QZFCMu3T3/p2pLa+KfYOMtA4dcTJjAuODHomesyfHNIParuaOrnPGHOElYx9JI680lpe9bp5L7WlPX/tc237b28T0IX8E/iYsOPmfwndF6c3I8ODttt5L4FlpHENzyt62DkeBj6Liuhs9KQzc16uqtPouYiBs16aIQXKy6WPXzkFV0ubZyUCaZiIuNtd40gEw23/qu7ZKcIelUhbpLiDUc3FbDwFKehhmPqxB08tLPAxFXyLyTwkQ+PlcP7dfUJpYja25ucc9S9EneJnwyf47lmnGXjm7op+Dvr7eTky+fZocfljo1IHAc5nmWp3rUjVQzAKq6JLJV1zEcwCccWNSXg1pS4gi5ohBTMzVDmpLNp48zDPYN2lZGuwqtOfgZBCOWxrlsdzDNBLqKPTdEnsXSkU5LZYxbUeITMazbLKkD85qRCkeZhFejzLyervDz++NyvGnG0IYkmzn2mOdFWrd2ySN5gbmBhjoayOKC3dNOUNU0huIPZNU42WvCjqces/x3kwzlaqO9EZCj3mDjmNibCJn/wJTq0B+YUnV9c0rVLTq/XjSi6vTfr+fz/wBK6eZbDhAAAA==","origin":"sls-agent"}

2021-03-02T11:08:10.735+01:00   END RequestId: 0c455857-ab09-4547-b861-038e91f666b7

2021-03-02T11:08:10.735+01:00   REPORT RequestId: 0c455857-ab09-4547-b861-038e91f666b7 Duration: 321.58 ms Billed Duration: 322 ms Memory Size: 1024 MB Max Memory Used: 120 MB

2021-03-02T11:08:10.965+01:00   START RequestId: 9d5a4391-6568-4d80-976b-d88a5f946d41 Version: $LATEST

2021-03-02T11:08:10.973+01:00   2021-03-02T10:08:10.973Z 9d5a4391-6568-4d80-976b-d88a5f946d41 INFO SERVERLESS_ENTERPRISE {"c":true,"b":"H4sIAAAAAAAAA7VXbU/jOBD+K1V0H3a1JLUTx3G6QjqOK+zewgrR7osW0Mp1nDaQxsFJoAX1v9846TuFO1ZavpDOPB6PZ8bPjB8tpZNhklkdq0gLmw9lVlp7ViFGcsy/Sl0kyuiQg0BaJmNZlHycg8RFLraRZyO3j1EHsQ5GThh4PwCm5W0FuI8RwMLI58QLsU19ymwSMWSHAR3YEWPcj0NCI4KN5WkuAV1qnhVclGbTPSvn01RxsPI496ffoAq7yHn2rJcql5obE5/5uIGvmbXjKlvYh6Posp/UoJ3HoaE5jsyil0DNmaOq2dPquA5jGCMX7IOXhyor5aQ0ZwAvhHxNUMz6Go99ETCGfNvjBNvEF8JmnhvanvAxinzMORWAn/SXO5wrVe6DfeRJJBm3fU/EwvdpwBCnmNFgIL1YovD9GdeQ8X0vChiNEA+CmASc4fc9yHIqo31kzSA7fFjsyMJzYf212mmCrfTQHCCr0nTP4nmeJmI9l+NEaDWQ9oCLG8iLDQizo9R3iZC7MU2ihwttJO9AsnD3GbMAshcynidz91UFeaR7llDjvCrlPA78vnBSPh5E3FqqzqusbEpmpXUyFcnrwsGu4yIHr4HlsAmUrOx7iJG9pjuVY6WnveTB2IKiItuqL4U0+X68tHRRXFqdwEOBSwnau7RGkud9VfIUxDigvhfQhdisMlLfR8RFRgo1KnXWYKmLSOiCkGvNp39VcQy5NAovCAmZbbtwJrWAGoIQN85gh1DCiBf4S6C5BTzJpP6SN3FxQ9+hfuiHLvVWEf1YHKo06plraXVinhZypcogiRlUd3anmoo4VBBkq+OtNqmKUo17mzU619mQB3s7S+sLtst1A3L02mrZuXq1xR8nB/1ur78NPNBGyXXWAW87jbedZVF0Qo8wRgLP9z2/syjgziudeanYGsQLJdcATApu5OqWbp7hvjh/Pf1vmPj+W2hsa5MTNTzWqsrnKW1DxNtNxNuvjChY6pVa8vHclCG3NvLayG1fzBN95XGP8gEPsI8jEoP7PsGxgD4RIRYOGN222c3uzlJexkqPwWKaZNVkB+RAixGoJ/RJikDZpLG+/3AlXbjSAQ1d9hzwSEtwHiMPM99FnvsUd5hX0ASsC6CaMTCZYYpL6yN0t/TN+dvWd6ky8/9MKyGLQunWny3X8dHxh4dLC6ikyGVNOa5f003dDeAnGKuAveELSAfkGdA4/DCfxdQAaGC+kyiVDYvRuUDfGthstveb3CFspzvE23QnwGzDnSszL9xBKa41B6iZIS/lPZ86o7LMl4j/aog++bHA9lQFHPvE3kK9k/lqTc17qwX2ugMv0d8a4EAIw7TNdV6joC1UntSI2xjdJFRfl3JTfy6L+gw1aHCdEiw2AX+rMXSIMy3jZPKCnZ7pM8s2/mT9xkpHTqSoyT9PnCXfOXzMH1RmIgklvu3lirr+59C1troLPTSLZLRuZXAtcNU9KK5V96j/835/537z8RIY45TrtimGzqIMWu8Q/D27qpsrwwGYYkIDGKEQVM0G9gMk/IyXhifaj7lWk+m7mfUEcSrLkTLuHnf7m9pfIOMtA0dK33MNYYGPRctY08PMoA/qV0fHOlUPSZrytu+g1pvvGL9vnRjqa00Y/UnJ29YBzIPymxx8Sso2jDOOR1tvPn3on57stdLkRraOpbhRb1uHI63Gss2YgxziucTBzG31eMx1Ml9mXNRa6VUTq38e8Zot1ySHVZrrpNyQdSdC5qb3Nldtl+YUOKeu011KKGFxUz8GFvq1Qfo1pQfVxucXs7zjGexpLguMxF8SI/Nus9E1/iz++XZz/+nr5+nR38s1DUAEAQ9hBrNDzGKbCIlthmJqs8ALJExo0scD8wxLK3ggrhiCOMTxjCnTW3rwRikMQ1qGWuBoZQVDXGTKmSDSvJ5ylWTlqRQjniWFaWhykmvwFrpqBEwK1WH8fuXzCJ4lqaqfJbPmpQSfF1cLbq0fLBdXs9m/B3GCfOAOAAA=","origin":"sls-agent"}

2021-03-02T11:08:10.974+01:00   END RequestId: 9d5a4391-6568-4d80-976b-d88a5f946d41

2021-03-02T11:08:10.974+01:00   REPORT RequestId: 9d5a4391-6568-4d80-976b-d88a5f946d41 Duration: 5.36 ms Billed Duration: 6 ms Memory Size: 1024 MB Max Memory Used: 120 MB

2021-03-02T11:09:29.926+01:00   START RequestId: 6c5cadaf-b14f-4669-834d-46fbeabdc561 Version: $LATEST

2021-03-02T11:09:29.970+01:00   2021-03-02T10:09:29.970Z 6c5cadaf-b14f-4669-834d-46fbeabdc561 INFO <body> <h1>Welcome back John Doe</h1> </body>

2021-03-02T11:09:29.970+01:00   2021-03-02T10:09:29.970Z 6c5cadaf-b14f-4669-834d-46fbeabdc561 INFO Sending...

2021-03-02T11:09:30.012+01:00   2021-03-02T10:09:30.012Z 6c5cadaf-b14f-4669-834d-46fbeabdc561 INFO SERVERLESS_ENTERPRISE {"c":true,"b":"H4sIAAAAAAAAA7VX227bOBD9FUPYhxa1ZFKkbi4CbNZ10m7jIojdC5oEC0qibMWSqFBSYifwv+9Q8j1OdlOgfjE1czgczgzPkI+akPE4zrSuViSFzsY8K7W2VgQTnrJvXBaxUDpkIJCWccqLkqU5SExkYh0RHZkjjLrI65qe4XnoJ8Akv60A9ykEmB1YAQtZpPuYRjq1bU93CQ1hFPmc+WFg2VhZnucc0KVkWcGCUi3a1nI2TwQDK49Lf0YNqtCLnGXPeilyLpky8YWlDXzLrB5V2co+bEWWo7gGHdwOqbfDs/AlULPnsGrW1LrUMUxCPYJhAXCzJ7KSz0q1CXAj4K+Jippf4yPX84LQd3UzcgDFfZgZUV+nzKGIUtuhlsLPRusVLoQoj7BuI8IRDz3dQgxx03EQM30c+haxkEUtRN+fMwkpP8LcdaPAcW2KLGQ65P0Q0pzw8AhpC0gPGxcH0vBcXH+teJpoCzlWG8iqJGlrLM+TONhOZhoHUvhc91kwhcTogFArcnkXB/wwpsn0eKUN+R1IVu4+YxZA+krG8njpvqggj3ZbC0SaVyVfxoHdF0bCUj9k2lp1UWVlUzMbrZGJkN8UBjYNExl4C8zHTaB4pd9DjPQt3YCnQs6H8YOyhZFJ91VfC67y/XilyaK40roOsTEh2GxfaRPO8pEoWQJi7HjY8hBditUsJbUsYppEgaFGucwarE2IjSwQMinZ/K8qiiCXNRwjy1nsu3DOZQA1BCFunMEGtalLiWOtgeoUsDjj8mvexIU41LAx5NxzrA3sU9ETSThU51LrRiwp+EaVQRIzqO7sTjQV0RMQZDhvm0WqohTpcLdGlzod8qDvZ2l7wn657kBOXlstB2dvlvjj7HjUH472gcdSKZnMuuBtt/G2uy6Krkeo61KHQNKs7qqAu6905qViaxAvlFwDUCmY8s0p3d3DfXHxev7fMfHjt9DY3iJnYnwqRZUvU9qBiHeaiHdeGVGwNCwlZ+nSlCK3DiIdZHYul4m+JozYzGcOnKCQRrbjWhRHgeviELme79r7NvvZ3XnCykjIFCwmcVbNDkCOZTAB9cx+kiJQNmmszz8cSdNE1LE9030OeCI5OI8Rwa5lIqCEJ7heXkET0C6BalJgMsUUV9on6G7Jm4u3rR9cZOr/XIqAF4WQrT9bpmGh048PVxpQSZHzmnJMCyH4rLsBfIKxCtgbRpAykGdA4/ChhsVcAWxHjeMwUWLsUstya4G8VbDFov2b3KHuQXco3XXHxuaOO9fqwnAHpbjVHKBmxqzk92xuTMoyXyP+qyEi++cKOxQVcOwTeyv1QearNTXvbSbo2w68RH9bgOMgUExbn8dtCtpD5XGNuI3QNLblTcl39Re8qPdQg/ybhOJgF/BBpNAhziWP4tkLdoaqz6zb+JP5OzMNPuNBTf55bKz5zmApexCZiiSU+L6XG+r6n5eurdl96KFZyMNtK/5N2OufVPaN6J9Mxfjo4HrL+yUwxoDJjiqG7qoMWu8Q/J6d1c+F4gBsY3DIgxMOVbOD/QgJP2el4onOYy7FbP5uoT1BDHg5Ecrd0/5oV/sLZLxn4ETIeyYhLDBYtYwtPdwZ5HH97OhqA/EQJwnrWAZqvfmB8fvWmaK+1sy1/7Hp29Yx3Af5d+5/jsuORRyD2K03nz+OBmftVhJPeeuUB1PxttWbSJHyjusayKDEpAZ2zdaQRUzGy2nKRSmF3DSx+vOE1Wy5JelVSS7jckfWnwU8V723OWqHNAPgnLpODymhhINp/RhY6bcu0q8pPag2tjyY5R3LYE11WOBK/DVWMnKbTW7wl+Dv79P7z9++zE8+rOc0gMBxmOdZnu5hF5pzwLHuosjWXYc43PQsbmFfvcOSCl6IG4agBjWIMqV6yxDeKIViSE1RC2ytrOASF6pypk0pZGEu4qwc8GDCsrhQDY3PcgneQlcNgUmhOpTfr3wewbMkEfWzZNG8lGB4eb3i1vrBcnm9WPwLOY4lEuEOAAA=","origin":"sls-agent"}

2021-03-02T11:09:30.015+01:00   END RequestId: 6c5cadaf-b14f-4669-834d-46fbeabdc561

2021-03-02T11:09:30.015+01:00   REPORT RequestId: 6c5cadaf-b14f-4669-834d-46fbeabdc561 Duration: 86.16 ms Billed Duration: 87 ms Memory Size: 1024 MB Max Memory Used: 120 MB

Any idea why this would work in some lambda functions and not others? Another mystery (at least for me) is why the execution of the handler spans over multiple Lambda invokations (cfr. the logs)...

FYI, I'm using "nodemailer": "^6.4.18" and "@types/nodemailer": "^6.4.0"

nodemailer aws-lambda serverless-framework typescript express
2 Answers

I think what's happening is:

  1. Your handler gets to res.sendFile(filePath) (which is asynchronous and will send the response when it succeeds).
  2. Node starts sending the file
  3. Since the above is asynchronous, node also keeps on running your other instructions.
  4. Eventually the file is sent, so the response is gone. This is where lambda is shut down. It could happen at any point in time after res.sendFile(), from instantly to after the email is sent.

The straightforward solution is to move res.sendFile to the bottom of your handler.

If you want to serve the next page as soon as possible and you can't afford to wait until the email is sent, you can push an event to a queue (for example, to SQS) and then trigger a lambda that sends emails from SQS. This gets you into distributed territory, though, so not always simple.

user_20290970

Your sendMail does not return a Promise, then await keyword will not work as your expectation. The function will be finished before the sendMail process finish.

On the local side, I guess you use serverless-offline plugin to test your function. Then, the function will not "finished", it just responds -> Different behavior with Lambda environment.

If this.transporter is an instance of Nodemailler's Transporter, then .sendMail function is a callback function. You have to convert it to a new function that returns a Promise or just wrap it into a new Promise like this:

const sentMessageInfo = await new Promise((resolve, reject) => {
  this.transporter.sendMail(mailOptions, (error, info) => {
    if (error) {
      return reject(error);
    }
    return resolve(info);
  })
});
user_51963940
Related