Ejecución impredecible de código asíncrono en Lambda node.js

Nov 05 2020

No puedo entender cómo usar código asíncrono en Lambda. Los resultados son desconcertantes, construyamos 2 funciones:

const sendToFirehoseAsync = async (param) => {
    console.log(param);
    const promise = new Promise(function(resolve, reject) {

        var params = {
            DeliveryStreamName: 'TestStream', 
            Records: [{ Data: 'test data' }]
        };
        console.log('params', params);

        firehose.putRecordBatch(params, function (err, data) {
            if (err) console.log(err, err.stack); // an error occurred
            else console.log('Firehose Successful',  data);           //         successful response
        });
    });
    return promise;
}

y

const sendToFirehoseSync = (param) => {
    console.log(param);

    var params = {
        DeliveryStreamName: 'TestStream', 
        Records: [{ Data: 'test data' }]
    };
    console.log('params', params);

    firehose.putRecordBatch(params, function (err, data) {
        if (err) console.log(err, err.stack); // an error occurred
        else console.log('Firehose Successful',  data);           //         successful response
    });  
}

¡Ahora vamos a ejecutarlos y ver qué pasa!

Ejecutar la función Async: funciona bien.

exports.handler = async (event) => {
    let res = await sendToFirehoseAsync('test1');
    return res;
}

    2020-11-05T20:19:16.146+13:00   START RequestId: e4c505ea-1717-4998-ad0d-a42434f0a0c1 Version: $LATEST
    2020-11-05T20:19:16.148+13:00   2020-11-05T07:19:16.147Z e4c505ea-1717-4998-ad0d-a42434f0a0c1 INFO test1
    2020-11-05T20:19:16.149+13:00   2020-11-05T07:19:16.149Z e4c505ea-1717-4998-ad0d-a42434f0a0c1 INFO params { DeliveryStreamName: 'TestStream', Records: [ { Data: 'test data' } ] }
    2020-11-05T07:19:16.245Z    e4c505ea-1717-4998-ad0d-a42434f0a0c1    INFO    Firehose Successful {
        FailedPutCount: 0,
        Encrypted: false,
        ....

Sin embargo, si llamo a la función dos veces con await (ver más abajo), obtengo exactamente la misma respuesta (es decir, no veo el archivo console.log para la prueba 2, etc. ¿Es como si la segunda llamada nunca sucediera?) ¿Qué está pasando? Supuse awaitque detendría la ejecución hasta que se resolviera la primera función y luego continuaría. Claramente no.

let res = await sendToFirehoseAsync('test1');
res = await sendToFirehoseAsync('test2');
return res;

Ahora ejecutemos algunos más seguidos:

console.log('async call 1');
await sendToFirehoseAsync('test1');

console.log('async call 2');
await sendToFirehoseAsync('test2');

console.log('sync call 1');
let resp1 = await sendToFirehoseSync('1');

console.log('sync call 2');
let resp2 = await sendToFirehoseSync('2');

console.log('after sync calls');

2020-11-05T20:35:28.465+13:00   2020-11-05T07:35:28.464Z 5a9e551f-ecc6-4f18-8af4-a11b1b29d835 INFO async call 1
2020-11-05T20:35:28.465+13:00   2020-11-05T07:35:28.465Z 5a9e551f-ecc6-4f18-8af4-a11b1b29d835 INFO test1
2020-11-05T20:35:28.467+13:00   2020-11-05T07:35:28.467Z 5a9e551f-ecc6-4f18-8af4-a11b1b29d835 INFO params { DeliveryStreamName: 'TestStream', Records: [ { Data: 'test data' } ] }
2020-11-05T20:35:28.577+13:00   2020-11-05T07:35:28.577Z 5a9e551f-ecc6-4f18-8af4-a11b1b29d835 INFO Firehose Successful { FailedPutCount: 0, Encrypted: false, RequestResponses: [ { RecordId: '4v+6H3T3koBggYYvdu/U6fg4h0C8m4taPVYznfYT4fIAWmm9XKu4/9F9jEgjdZFE02IsNgYs0/ORGzz1l2udEzCJUN1dRR1YCHSi/jiLI/DHGpTkoyN89VUG0jGzNlAERgUNCIwxXlCYww/l2HSGjK8++f+qmRj7sTCY/J4/QlV2sqhcXSlJjKhkK+A+Ib7w2+WwdZ5gliF64fSP9qkQSpeSutOh68o6' } ] }
2020-11-05T20:35:28.580+13:00   END RequestId: 5a9e551f-ecc6-4f18-8af4-a11b1b29d835

Nuevamente, solo se obtiene 1 resultado. ¡¿El resto está perdido ?!

Y obtengo el mismo resultado con 2 llamadas asincrónicas, seguidas de 2 llamadas sincronizadas y una más por si acaso.

console.log('async call 1');
await sendToFirehoseAsync('test1');

console.log('async call 2');
await sendToFirehoseAsync('test2');

console.log('sync call 1');
let resp1 = await sendToFirehoseSync('1');

console.log('sync call 2');
let resp2 = await sendToFirehoseSync('2');

console.log('after sync calls');


const promise = new Promise(function(resolve, reject) {

    var params = {
        DeliveryStreamName: 'TestStream', 
        Records: [{ Data: 'test data 2' }]
    };
    console.log('params', params);

    firehose.putRecordBatch(params, function (err, data) {
        if (err) console.log(err, err.stack); // an error occurred
        else console.log('Firehose Successful',  data);           //         successful response
    });
});

return promise;  

Sin embargo ... Si vuelvo a ejecutar el último ejemplo pero comento las 2 llamadas asíncronas, obtengo algo diferente ...

console.log('sync call 1');
let resp1 = await sendToFirehoseSync('1');

console.log('sync call 2');
let resp2 = await sendToFirehoseSync('2');

console.log('after sync calls');


const promise = new Promise(function(resolve, reject) {

    var params = {
        DeliveryStreamName: 'TestStream', 
        Records: [{ Data: 'test data 2' }]
    };
    console.log('params', params);

    firehose.putRecordBatch(params, function (err, data) {
        if (err) console.log(err, err.stack); // an error occurred
        else console.log('Firehose Successful',  data);           //         successful response
    });
});

return promise;

2020-11-05T20:42:08.713+13:00
2020-11-05T07:42:08.713Z    333feae9-f306-409c-89c8-1707e0547ba3    INFO    sync call 1
2020-11-05T07:42:08.713Z 333feae9-f306-409c-89c8-1707e0547ba3 INFO sync call 1
2020-11-05T20:42:08.713+13:00   2020-11-05T07:42:08.713Z 333feae9-f306-409c-89c8-1707e0547ba3 INFO 1
2020-11-05T20:42:08.715+13:00   2020-11-05T07:42:08.715Z 333feae9-f306-409c-89c8-1707e0547ba3 INFO params { DeliveryStreamName: 'TestStream', Records: [ { Data: 'test data' } ] }
2020-11-05T20:42:08.760+13:00   2020-11-05T07:42:08.760Z 333feae9-f306-409c-89c8-1707e0547ba3 INFO after sync calls
2020-11-05T20:42:08.760+13:00   2020-11-05T07:42:08.760Z 333feae9-f306-409c-89c8-1707e0547ba3 INFO params { DeliveryStreamName: 'TestStream', Records: [ { Data: 'test data 2' } ] }
2020-11-05T20:42:08.808+13:00   2020-11-05T07:42:08.807Z 333feae9-f306-409c-89c8-1707e0547ba3 INFO Firehose Successful { FailedPutCount: 0, Encrypted: false, RequestResponses: [ { RecordId: 'iWeCDK6kukfkLfh/1mg791g3sIVpDC1hNNokJuTGFJJaLBNd1TvvCiWHV4z2iiWS3hOvu9OmKVnUofCPbr5uewKPAQBdiCJp9iVIzTakcL5bb4CkyOZKxzLX4NOxTP94Z0j64KgssWo10z7jEhDoevF8NTMZR+tUlhHmYtEGcQq2YViwwXhpYX8MP4yvS5xSRo+sjJXEcyoty+Pvt1UFWGelEKIygtnO' } ] }
2020-11-05T20:42:08.865+13:00   2020-11-05T07:42:08.865Z 333feae9-f306-409c-89c8-1707e0547ba3 INFO Firehose Successful { FailedPutCount: 0, Encrypted: false, RequestResponses: [ { RecordId: 's5loZTT8d4J0fhSjnJli0LzOzljnvgvC99AvdSeqkj/j9xp5RnjstL5UxQXm5t+uyEbSSe21XZxwaUU/D7XVsCzpJ6F5nlnzsOZBLd6vyaF3bc2lSUo2DM2u9dGetJPMahC1b0rO+GXod91sC9XumS8QWIVePcww2DH0IM46RuoLEVVR3/kgcnvhIm/UU67JuvZkFTCAP/jss0VwVUY2vmzfdvw4mJT4' } ] }
2020-11-05T20:42:08.867+13:00   END RequestId: 333feae9-f306-409c-89c8-1707e0547ba3

El único patrón que puedo ver es el regreso. La función asincrónica tiene un retorno. ¿Eso quizás causa que regrese todo el lambda, no solo la función? Espero que este (desafortunadamente) largo experimento sea útil y que alguien pueda arrojar algo de luz sobre cómo funciona. Salud.

** Añadiendo Resolve & Reject **

console.log('before');
await sendToFirehosePromise('thing');
console.log('after');

....

async function sendToFirehosePromise(record) {
    var params = {
        DeliveryStreamName: 'TestStream', 
        Records: [{ Data: 'test data' }]
    };
    
    const promise =  new Promise((resolve, reject) => {
        firehose.putRecordBatch(params, (err, data) => {
            if (err) return reject(err);
            return resolve(data);
        });
    });       
    return promise;
}

Respuestas

1 404 Nov 05 2020 at 10:51

Reduzcamos todo lo posible a llamadas asíncronas puras de una lambda:

function f(p) {
    console.log(p);
    return new Promise(res => res('result ' + p));
}

exports.handler = async () => {
    let res = await f(1);
    console.log(res);
    res = await f(2);
    console.log(res);
    res = await f(3);
    console.log(res);
}

Huellas dactilares:

2020-11-05T10:40:25.298Z    bd564d91-480f-4dcd-8134-1481fa59a946    INFO    1
2020-11-05T10:40:25.298Z    bd564d91-480f-4dcd-8134-1481fa59a946    INFO    result 1
2020-11-05T10:40:25.298Z    bd564d91-480f-4dcd-8134-1481fa59a946    INFO    2
2020-11-05T10:40:25.298Z    bd564d91-480f-4dcd-8134-1481fa59a946    INFO    result 2
2020-11-05T10:40:25.298Z    bd564d91-480f-4dcd-8134-1481fa59a946    INFO    3
2020-11-05T10:40:25.299Z    bd564d91-480f-4dcd-8134-1481fa59a946    INFO    result 3

Ahora compáralo con el tuyo. En primer lugar esta firma es incorrecta (o al menos innecesaria): const sendToFirehoseAsync = async (param). Async solo es necesario si espera algo. Si no está esperando, y no lo está, no necesita marcarlo como asíncrono. Una función asincrónica puede esperar cualquier cosa que devuelva una promesa. Si su función devuelve una promesa y no espera nada, no la marque como asincrónica.

Ahora a la parte en la que estás mezclando promesas y asincrónicas innecesariamente.

async function sendToFirehosePromise(record) {
    var params = {
        DeliveryStreamName: 'TestStream', 
        Records: [{ Data: 'test data' }]
    };
    
    const promise =  new Promise((resolve, reject) => {
        firehose.putRecordBatch(params, (err, data) => {
            if (err) return reject(err);
            return resolve(data);
        });
    });       
    return promise;
}

Si está intentando usar async, use async. Todas las llamadas de AWS SDK devuelven un tipo de AWS.Request. Ese tipo contiene un promise()método. Puede esperar esa promesa en lugar de utilizar la notación de promesa real.

async function sendToFirehosePromise(record) {
    var params = {
        DeliveryStreamName: 'TestStream', 
        Records: [{ Data: 'test data' }]
    };
    return await firehose.putRecordBatch(params).promise();
}

Ese es un uso adecuado de async / await con el SDK en lugar de convertirlo en promesas personalizadas. Ahora en tu controlador puedes esperar esa función tantas veces como quieras y siempre funcionará.