Javascript promise console.logs does not print first time around AWS Lambda

I've got a NodeJS AWS lambda that essentially fetches all accounts in an AWS Organisation and checks if those accounts exist in a DynamoDB table. Scroll to the end for the code.

1. The lambda handler calls fetchAllAccounts() which fetches all accounts in the organisation.
2. Those accounts are iterated upon and for each of them checkIfAccountExists is called.
3. In checkIfAccountExists the DynamoDB is called to check if the account exists.

When i test this code the console.log statements in the .then() do no print the first test after deployment.

The output that I get after the 1st test is as follows:

Response  null    Function Logs  START RequestId: ef026aa8-614a-4007-ad8b-af3bd53b77e7 Version: $LATEST  2021-03-20T02:35:25.150Z    ef026aa8-614a-4007-ad8b-af3bd53b77e7    INFO    fetching all accounts in the organization  2021-03-20T02:35:26.519Z    ef026aa8-614a-4007-ad8b-af3bd53b77e7    INFO    {"Accounts":[{"Id":"3453453453","Arn":"arn:aws:organizations::45345345345:account/o-kbtt45j25z/453453453","Email":"asdasdasd@yahoo.co.in","Name":"rtrtrtrtrt","Status":"ACTIVE","JoinedMethod":"INVITED","JoinedTimestamp":"2021-02-02T08:12:42.064Z"},{"Id":"34534534676","Arn":"arn:aws:organizations::21241241241:account/o-kbtt45j25z/345345345","Email":"xydakjlkjalsadss@gmail.com","Name":"shared-services","Status":"ACTIVE","JoinedMethod":"CREATED","JoinedTimestamp":"2021-02-02T08:24:06.130Z"},{"Id":"4356545335","Arn":"arn:aws:organizations::456342324565:account/o-kbtt45j25z/3456545635","Email":"xydakjlkjalsadalskjdkjas@gmail.com","Name":"app1","Status":"ACTIVE","JoinedMethod":"CREATED","JoinedTimestamp":"2021-02-03T04:42:59.464Z"},{"Id":"281178849017","Arn":"arn:aws:organizations::940498014228:account/o-kbtt45j25z/281178849017","Email":"aa.xydakjlkjalsa.sdsd.sec@gmail.com","Name":"security","Status":"ACTIVE","JoinedMethod":"CREATED","JoinedTimestamp":"2021-02-02T08:12:48.667Z"},{"Id":"499240802577","Arn":"arn:aws:organizations::940498014228:account/o-kbtt45j25z/499240802577","Email":"lz.siddhesh.jog.la@gmail.com","Name":"log-archive","Status":"ACTIVE","JoinedMethod":"CREATED","JoinedTimestamp":"2021-02-02T08:18:25.011Z"}]}  2021-03-20T02:35:26.556Z    ef026aa8-614a-4007-ad8b-af3bd53b77e7    INFO    Check if data exists for account: 940498014228  2021-03-20T02:35:26.556Z    ef026aa8-614a-4007-ad8b-af3bd53b77e7    INFO    sending Param: SSOParamSetData  2021-03-20T02:35:26.617Z    ef026aa8-614a-4007-ad8b-af3bd53b77e7    INFO    Check if data exists for account: 407710725534  2021-03-20T02:35:26.617Z    ef026aa8-614a-4007-ad8b-af3bd53b77e7    INFO    sending Param: SSOParamSetData  2021-03-20T02:35:26.638Z    ef026aa8-614a-4007-ad8b-af3bd53b77e7    INFO    Check if data exists for account: 621020887292  2021-03-20T02:35:26.638Z    ef026aa8-614a-4007-ad8b-af3bd53b77e7    INFO    sending Param: SSOParamSetData  2021-03-20T02:35:26.678Z    ef026aa8-614a-4007-ad8b-af3bd53b77e7    INFO    Check if data exists for account: 281178849017  2021-03-20T02:35:26.716Z    ef026aa8-614a-4007-ad8b-af3bd53b77e7    INFO    sending Param: SSOParamSetData  2021-03-20T02:35:26.718Z    ef026aa8-614a-4007-ad8b-af3bd53b77e7    INFO    Check if data exists for account: 499240802577  2021-03-20T02:35:26.718Z    ef026aa8-614a-4007-ad8b-af3bd53b77e7    INFO    sending Param: SSOParamSetData  END RequestId: ef026aa8-614a-4007-ad8b-af3bd53b77e7  REPORT RequestId: ef026aa8-614a-4007-ad8b-af3bd53b77e7  Duration: 1648.82 ms    Billed Duration: 1649 ms    Memory Size: 128 MB Max Memory Used: 88 MB  Init Duration: 380.49 ms    Request ID  ef026aa8-614a-4007-ad8b-af3bd53b77e7  

When I run the test the second time (or any number of times subsequently) I get the following output on the console:

Response  null    Function Logs  INFO    Logging after the call  2021-03-20T02:38:09.237Z    89dc4156-303e-45ce-b4d7-2ac89ae870c2    INFO    Logging after the call  2021-03-20T02:38:09.699Z    89dc4156-303e-45ce-b4d7-2ac89ae870c2    INFO    dbRow: {"Item":{"accountName":{"S":"app1"},"linkingDone":{"BOOL":false},"paramSetsCreated":{"BOOL":false},"accountId":{"S":"621020887292"}}}  2021-03-20T02:38:09.717Z    89dc4156-303e-45ce-b4d7-2ac89ae870c2    INFO    Done  2021-03-20T02:38:09.738Z    89dc4156-303e-45ce-b4d7-2ac89ae870c2    INFO    dbRow: {"Item":{"accountName":{"S":"log-archive"},"linkingDone":{"BOOL":false},"paramSetsCreated":{"BOOL":false},"accountId":{"S":"499240802577"}}}  2021-03-20T02:38:09.738Z    89dc4156-303e-45ce-b4d7-2ac89ae870c2    INFO    Done  2021-03-20T02:38:09.738Z    89dc4156-303e-45ce-b4d7-2ac89ae870c2    INFO    dbRow: {"Item":{"accountName":{"S":"shared-services"},"linkingDone":{"BOOL":false},"paramSetsCreated":{"BOOL":false},"accountId":{"S":"407710725534"}}}  2021-03-20T02:38:09.757Z    89dc4156-303e-45ce-b4d7-2ac89ae870c2    INFO    Done  2021-03-20T02:38:09.758Z    89dc4156-303e-45ce-b4d7-2ac89ae870c2    INFO    dbRow: {"Item":{"accountName":{"S":"rtrtrtrtrt"},"linkingDone":{"BOOL":false},"paramSetsCreated":{"BOOL":false},"accountId":{"S":"940498014228"}}}  2021-03-20T02:38:09.758Z    89dc4156-303e-45ce-b4d7-2ac89ae870c2    INFO    Done  2021-03-20T02:38:09.758Z    89dc4156-303e-45ce-b4d7-2ac89ae870c2    INFO    dbRow: {"Item":{"accountName":{"S":"security"},"linkingDone":{"BOOL":false},"paramSetsCreated":{"BOOL":false},"accountId":{"S":"281178849017"}}}  2021-03-20T02:38:09.777Z    89dc4156-303e-45ce-b4d7-2ac89ae870c2    INFO    Done  2021-03-20T02:38:10.324Z    89dc4156-303e-45ce-b4d7-2ac89ae870c2    INFO    {"Accounts":[{"Id":"298379758239785","Arn":"arn:aws:organizations::567457372727:account/o-kbtt45j25z/4546357388","Email":"kjkjkjlkqoqowjh@yahoo.co.in","Name":"rtrtrtrtrt","Status":"ACTIVE","JoinedMethod":"INVITED","JoinedTimestamp":"2021-02-02T08:12:42.064Z"},{"Id":"67567567567","Arn":"arn:aws:organizations::4574577277:account/o-kbtt45j25z/407710725534","Email":"lskfjlksjdlfkjsdf@gmail.com","Name":"shared-services","Status":"ACTIVE","JoinedMethod":"CREATED","JoinedTimestamp":"2021-02-02T08:24:06.130Z"},{"Id":"234234234234","Arn":"arn:aws:organizations::940498014228:account/o-kbtt45j25z/23423423423423","Email":"rtrtrtrtrtrtrtr@gmail.com","Name":"app1","Status":"ACTIVE","JoinedMethod":"CREATED","JoinedTimestamp":"2021-02-03T04:42:59.464Z"},{"Id":"281178849017","Arn":"arn:aws:organizations::940498014228:account/o-kbtt45j25z/281178849017","Email":"lz.23982lknkjfkj.eere.sec@gmail.com","Name":"security","Status":"ACTIVE","JoinedMethod":"CREATED","JoinedTimestamp":"2021-02-02T08:12:48.667Z"},{"Id":"499240802577","Arn":"arn:aws:organizations::940498014228:account/o-kbtt45j25z/499240802577","Email":"t.kejltelrkt.333.la@gmail.com","Name":"log-archive","Status":"ACTIVE","JoinedMethod":"CREATED","JoinedTimestamp":"2021-02-02T08:18:25.011Z"}]}  2021-03-20T02:38:10.324Z    89dc4156-303e-45ce-b4d7-2ac89ae870c2    INFO    Check if data exists for account: 940498014228  2021-03-20T02:38:10.324Z    89dc4156-303e-45ce-b4d7-2ac89ae870c2    INFO    sending Param: SSOParamSetData  2021-03-20T02:38:10.326Z    89dc4156-303e-45ce-b4d7-2ac89ae870c2    INFO    Check if data exists for account: 407710725534  2021-03-20T02:38:10.326Z    89dc4156-303e-45ce-b4d7-2ac89ae870c2    INFO    sending Param: SSOParamSetData  2021-03-20T02:38:10.328Z    89dc4156-303e-45ce-b4d7-2ac89ae870c2    INFO    Check if data exists for account: 621020887292  2021-03-20T02:38:10.328Z    89dc4156-303e-45ce-b4d7-2ac89ae870c2    INFO    sending Param: SSOParamSetData  2021-03-20T02:38:10.378Z    89dc4156-303e-45ce-b4d7-2ac89ae870c2    INFO    Check if data exists for account: 281178849017  2021-03-20T02:38:10.378Z    89dc4156-303e-45ce-b4d7-2ac89ae870c2    INFO    sending Param: SSOParamSetData  2021-03-20T02:38:10.379Z    89dc4156-303e-45ce-b4d7-2ac89ae870c2    INFO    Check if data exists for account: 499240802577  2021-03-20T02:38:10.379Z    89dc4156-303e-45ce-b4d7-2ac89ae870c2    INFO    sending Param: SSOParamSetData  END RequestId: 89dc4156-303e-45ce-b4d7-2ac89ae870c2  REPORT RequestId: 89dc4156-303e-45ce-b4d7-2ac89ae870c2  Duration: 1243.88 ms    Billed Duration: 1244 ms    Memory Size: 128 MB Max Memory Used: 90 MB    Request ID  89dc4156-303e-45ce-b4d7-2ac89ae870c2  

As is evident the log statements related to the promise resolution seem misplaced?

This sequence repeats every time i deploy.

Why do the logs not show up the first time around and why are they misplaced from then on (or are they misplaced at all )?

I have provided the code below. Version: Node.js 14.x. I have randmonly redacted the console output to remove account and email information. Rest assured this is not a data issue.

const AWS  = require('aws-sdk');  AWS.config.update({ region:'us-east-1' });  const organization = new AWS.Organizations();  const ddb = new AWS.DynamoDB({region: 'ap-southeast-2'});    exports.handler = async (event, context, callback) => {      const response = await fetchAllAccount();      console.log(JSON.stringify(response));      response.Accounts.forEach(acc => checkIfAccountExists(acc));        };    function fetchAllAccount(){      console.log("fetching all accounts in the organization");      const params = {};      return organization.listAccounts(params).promise();  }    function checkIfAccountExists(acc){      console.log("Check if data exists for account: " + acc.Id);      const params = {          Key: {              accountId:  {                  S: acc.Id              }          },          TableName: "SSOParamSetData"      }      console.log("sending Param: " + params.TableName);      getDatafromDB(params).then((dbRow) => {          console.log("dbRow: " + JSON.stringify(dbRow))              console.log("Done");      });            setTimeout(function() {console.log("Logging after the call");}, 5000);  }    function getDatafromDB(params){      return ddb.getItem(params).promise();  }  

https://stackoverflow.com/questions/66717777/javascript-promise-console-logs-does-not-print-first-time-around-aws-lambda March 20, 2021 at 10:47AM