Context Logging not in Sequential order

[HariKrishna598]

Created the basic Http Trigger in Node Js 18 LTS Azure Functions using VS Code.

module.exports = async function (context) {
    context.log('JavaScript HTTP trigger function processed a request.');

    context.log.info({ a: 'first object', b: { q: 'test 1' } });
    context.log.info({ a: 'second object', b: { q: 'test 2' } });
    context.log.info({ a: 'third object', b: { q: 'test 3' } });
  
    context.log.info(JSON.stringify({ a: 'first string', b: { q: 'test 1' } }));
    context.log.info(JSON.stringify({ a: 'second string', b: { q: 'test 2' } }));
    context.log.info(JSON.stringify({ a: 'third string', b: { q: 'test 3' } }));
  
    context.log.info('first simple string');
    context.log.info('second simple string');
    context.log.info('third simple string');
    const responseMessage = "Hello Krishna, This Http Triggered Function executed successfully."

    context.res = {
        // status: 200, /* Defaults to 200 */
        body: responseMessage
    };
}

The way I have written my log statements are not coming in the terminal with the same order when I run my function.

Is it the behavior of Context.Log() or am I missing something?

[ejizba]

@RohitRanjanMS do you know if this is unique to Node.js or does it happen for most languages? I'm wondering if this is just a known limitation of some part of the functions runtime.

[RohitRanjanMS]

Most of these are processed asynchronously, so the sequence is not guarantee.

@ejizba , @HariKrishna598

[ejizba]

Closing as by-design/upstream per Rohit's response. Attempting to get these in order would likely be more work than it was worth and probably have other negative side effects to things like performance.

[oshihirii]

How does anyone log information in their function code?

I tried using Pino, but the logs don't show up in live production environment (ie when calling live function endpoint), they only show up in local development environment (when calling local function endpoint).

There seem to be quite a few issues/comments/forum posts on this topic:

Azure/azure-functions-host#9238

https://stackoverflow.com/questions/75716633/azure-function-context-log-not-logging-properly-not-synchronous

geoffrich/svelte-adapter-azure-swa#114

Azure/azure-functions-host#9657

#172 (comment)

[ejizba]

Yeah the host team is actively working on this. I can't predict when it'll be fixed, but things are definitely looking a lot better than my original comment in July when I thought this would never happen. I'll reopen this issue to track from a Node.js perspective, but again the work is on the host team which we (the Node.js side of things) don't control

I'm not super familiar with Pino. If you need help with that, please file a new issue with sample code/repro steps as I don't think it's super related to the "out of order" logging

[oshihirii]

@eliaslopezgt - thanks for your update.

I basically just need any logging functionality that works as expected, ie in a synchronous manner.

I feel like this is fundamental and important functionality in any application.

But maybe I am missing something? Because others don't seem to be treating it as a critical issue?

I don't understand how anyone could confidently be running an app where things can't be logged for troubleshooting etc.

Again, maybe I am missing something in my approach, so apologies if that is the case.

But what would you be using for logging at the moment in an Azure Function app?

How would you be developing if you couldn't context.log('here's an important value i want to check or write to the logs')?

The reason I tried Pino is that I just wanted to get something to work, but as mentioned, when using Pino I can see the logs in the local environment, but not in the live environment.

[ejizba]

This definitely annoys me too, but you're correct we haven't heard many people report this as a critical problem. My guess is that the issue is easy to repro in small sample apps, but not as big a deal in larger more realistic apps. For example, once you have enough traffic, you're going to have missing logs due to sampling. Also, once your logic is complex enough your invocation will naturally have mini-delays that will flush the logs and cause them to be roughly in-order. Lastly, the reason the logs are out-of-order is to improve performance, and most people view performance as more critical than super precise log ordering. Anyways, I'm just guessing here and the host team is already working on this so it's a bit of a moot point now.

The only time I'm aware of missing logs is at the end of an invocation (other than sampling, which is by-design). If these logs are super important, one workaround you can use is to add a tiny delay before finishing execution to ensure the logs are flushed. You can also use a post-invocation hook (in package version v4.1.0+) to add this delay to all functions at once (sample code here). I'm consistently seeing all logs with just a 50ms delay, so if that doesn't work for you it's a sign you're not properly awaiting some async code.

[oshihirii]

I am still getting the same behavior - logs are printing in an incorrect order or not at all.

There is a possibly related comment here stating that it has been fixed:

Azure/azure-functions-host#9238 (comment)

But I am running in local environment and it does not seem to be fixed.

Possibly related merged pull request is here too:

Azure/azure-functions-host#9657

Environment information and steps to reproduce are below.

Windows 11.

$ az --version
azure-cli                         2.59.0

core                              2.59.0
telemetry                          1.1.0

Dependencies:
msal                              1.27.0
azure-mgmt-resource             23.1.0b2

Python location 'C:\Program Files\Microsoft SDKs\Azure\CLI2\python.exe'
Extensions directory 'C:\Users\<my-name>\.azure\cliextensions'

Python (Windows) 3.11.8 (tags/v3.11.8:db85d51, Feb  6 2024, 22:03:32) [MSC v.1937 64 bit (AMD64)]

Legal docs and information: aka.ms/AzureCliLegal


Your CLI is up-to-date.


$ func --version
4.0.5611

$ node --version
v20.12.0

$ npm --version
10.5.0

package.json:

{
  "name": "",
  "version": "1.0.0",
  "description": "",
  "type": "module",
  "main": "src/functions/*.js",
  "scripts": {
    "start": "func start",
    "test": "echo \"No tests yet...\""
  },
  "dependencies": {
    "@azure/functions": "^4.0.0",
    "@azure/msal-node": "^2.7.0",
    "axios": "^1.6.8",
    "date-fns": "^3.6.0",
    "date-fns-tz": "^3.1.3",
    "pino": "^8.20.0"
  },
  "devDependencies": {
    "azure-functions-core-tools": "^4.x",
    "eslint": "^8.57.0",
    "eslint-config-standard": "^17.1.0",
    "eslint-plugin-import": "^2.29.1",
    "eslint-plugin-n": "^16.6.2",
    "eslint-plugin-promise": "^6.1.1"
  }
}

My Azure Function code:

import { app } from '@azure/functions';

app.http('<my-function-name>POSTHttpTriggerFunction', {
    methods: ['POST'],
    authLevel: 'function',
    handler: async (request, context) => {

        const requestData = await request.json();
        
        context.log(`SUCCESS - here is the request.url:  ${request.url}`); 
        context.log(`here is the payload you sent in your POST request test`);
        context.log(requestData);
    }
});

My Request:

curl -X POST http://localhost:7071/api/<my-function-name>POSTHttpTriggerFunction \
-H "Content-Type: application/json" \
-H "x-functions-key: function-key-here" \
-d '{
"my_key_01": "my value 01",
"my_key_02": "my value 02"
}'

Logs:

They seem to shows in whatever order they want or not at all.

Not showing at all example:

[2024-04-19T08:29:29.202Z] SUCCESS - here is the request.url:  http://localhost:7071/api/<my-function-name>POSTHttpTriggerFunction

Incorrect order example:

[2024-04-19T08:30:14.101Z] here is the payload you sent in your POST request test
[2024-04-19T08:30:14.101Z] { my_key_01: 'my value 01', my_key_02: 'my value 02' }
[2024-04-19T08:30:14.101Z] SUCCESS - here is the request.url:  http://localhost:7071/api/<my-function-name>POSTHttpTriggerFunction

And another example where the function is executed before one of the statements is logged:

[2024-04-19T08:31:28.923Z] SUCCESS - here is the request.url:  http://localhost:7071/api/<my-function-name>POSTHttpTriggerFunction
[2024-04-19T08:31:28.923Z] here is the payload you sent in your POST request test
[2024-04-19T08:31:28.924Z] Executed 'Functions.<my-function-name>POSTHttpTriggerFunction' (Succeeded, Id=***, Duration=3ms)
[2024-04-19T08:31:28.923Z] { my_key_01: 'my value 01', my_key_02: 'my value 02' }

UPDATE:

If i change this DEFAULT setting in local.settings.json:

"AzureWebJobsFeatureFlags": "EnableWorkerIndexing",

to this:

"AzureWebJobsFeatureFlags": "EnableOrderedInvocationMessages",

then the log statements seem to show in the correct order.

However I do not know what that setting means and if changing it the way I have will have any undesired effects?

[ejizba]

Updating the setting is the correct way to get the fix:

"AzureWebJobsFeatureFlags": "EnableOrderedInvocationMessages"

The fix is being slowly rolled out to ensure it doesn't cause any regressions and it will be a while before "EnableOrderedInvocationMessages" is on-by-default. By contrast, "EnableWorkerIndexing" has been on-by-default for a while now, but if people are on older versions of core tools they might still need it (you'll know if you need it, the app won't even run). For the record, you can have both set if you do "EnableOrderedInvocationMessages,EnableWorkerIndexing".

[peter-mskeng]

This may not be a critical runtime issue, but it is a significant nuisance for developing code and troubleshooting bugs, and makes Azure Functions less developer-friendly.

To be clear, the fix is to add EnableOrderedInvocationMessages to your comma-delimited list of feature flags in the AzureWebJobsFeatureFlags setting.

So something like this:

"AzureWebJobsFeatureFlags": "EnableWorkerIndexing",

becomes like this:

"AzureWebJobsFeatureFlags": "EnableWorkerIndexing,EnableOrderedInvocationMessages",