Context Logging not in Sequential order about azure-functions-nodejs-library HOT 11 OPEN

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.

from azure-functions-nodejs-library.

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",

from azure-functions-nodejs-library.

@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.

from azure-functions-nodejs-library.

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?

from azure-functions-nodejs-library.

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",

Worked for me:

• windows 10
• net 8
• azure function isolated

from azure-functions-nodejs-library.

@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.

from azure-functions-nodejs-library.

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

@ejizba , @HariKrishna598

from azure-functions-nodejs-library.

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.

from azure-functions-nodejs-library.

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)

from azure-functions-nodejs-library.

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

from azure-functions-nodejs-library.

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".

from azure-functions-nodejs-library.