Flush lower level logs to console

[zirkelc]

#3142 (reply in thread)

[boring-cyborg]

Thanks a lot for your first contribution! Please check out our contributing guidelines and don't hesitate to ask whatever you need.
In the meantime, check out the #typescript channel on our Powertools for AWS Lambda Discord: Invite link

[sonarqubecloud]

Quality Gate passed

Issues
4 New issues
0 Accepted issues

Measures
0 Security Hotspots
0.0% Coverage on New Code
17.6% Duplication on New Code

See analysis details on SonarCloud

[github-actions]

No acknowledgement section found. Please make sure you used the template to open a PR and didn't remove the acknowledgment section. Check the template here: https://github.com/aws-powertools/powertools-lambda-typescript/blob/develop/.github/PULL_REQUEST_TEMPLATE.md#acknowledgment

[github-actions]

No related issues found. Please ensure there is an open issue related to this change to avoid significant delays or closure.

[leandrodamascena]

Just adding a comment here to get notifications about this PR! Whatever is decided here might make sense, we implemented it in Python and dotnet too.

btw, thanks for submitting the PR @zirkelc! Let's wait to hear from @dreamorosi.

[zirkelc]

Sorry, I actually wanted to open the PR in my forked repo to get a diff to share with @dreamorosi in #3142 (comment)

Since it's already open, I will leave it open so we can add comments in code.

[dreamorosi]

Hi @zirkelc, thanks you for the PR.

I have a deadline for this year's re:Invent set for Wednesday afternoon. I'm planning on reviewing your PR by Thursday morning at the latest.

[zirkelc]

Hey @dreamorosi take your time, I just wanted to share it with you to get your opinion

[dreamorosi]

This can work in theory but in practice I don't see Powertools relying on this value to uniquely identify requests.

This value could be undefined in Lambda in rare occasions and would not exist at all outside of it, i.e. in testing environments or other compute platforms. It's true that we target primarily Lambda so this is not an immediate concern when it comes to other platforms, but introducing a requirement on this environment variable means now customers have to set it in their tests or CI, which is why for example the Tracer utility disables itself when running outside of Lambda.

Overall, for this type of thing I would instead relying on something that follows a similar principle but more robust, like AsyncLocalStorage. With this being a language feature, we wouldn't have to worry about where Logger is running and context would be guaranteed at the process level.

[dreamorosi]

This is something I also touched upon in the original discussion, but for the sake of the review I'll include it here as well.

Having an unbounded buffer is a risk as you could run out of memory depending on how much and what you're logging.

For your specific use case this might not be a problem since you might know with relative certainty what you're logging and how much resources you're assigning to your Lambda functions, however from a library perspective this is a dangerous assumption to make.

If we were to implement this feature, we'd most likely want to set a max size for the buffer with a sensible default and an option to configure it. Depending on the performance impact of doing this, we might also want to consider calculating the size of each log and allow customers to set a max size in kb/mb for the buffer rather than a number of buffered logs, since the latter might have less meaning. Alternatively, or additionally, we might also want to consider implementing a sliding window mechanism that deletes older logs as newer are added and the buffer reaches the limit.

This above is the main reason why we haven't implemented the feature, as it requires some design and discussion.

[zirkelc]

Yes, I agree! I think byte size and/or count limit should be implemented.

Since we store the stringified JSON (see comment on printLog/formatLog), we could easily calculate the UTF-8 byte size of each item and maintain a total byte size of the buffer. When a new log is added to the buffer and the total size exceeds the max allowed size, the buffer should drop the first N items until the total size is again below threshold.

[dreamorosi]

If I understand this change correctly, we're bypassing the creation of an object, including all the attributes when passing a string message only.

If this is the case I don't think we would ever make this change, since the main value proposition of this logger is to emit JSON structured logs with keys, context, and all the other features.

[zirkelc]

I probably should have explained this change more thoroughly.
When saving logs into the buffer instead of emiting them to stdout, we cannot save the original object in the buffer because this object might be mutated later on in the Lambda function:

const user = { name: 'John' };
logger.debug('User', { user } );
user.name = 'Jane';

So I added a new function formatLog which is identical to printLog but doesn't emit to stdout:

powertools-lambda-typescript/packages/logger/src/Logger.ts

Lines 856 to 864 in e6d0db9

	private formatLog(log: LogItem): string {
	log.prepareForPrint();
	return JSON.stringify(
	log.getAttributes(),
	this.getJsonReplacer(),
	this.logIndentation
	);
	}

I use this function to serialise the log object into JSON and save it to the buffer:

powertools-lambda-typescript/packages/logger/src/Logger.ts

Lines 907 to 913 in e6d0db9

	const context = this.#context[xRayTraceId] ?? [];
	context.push([
	logLevel,
	this.formatLog(
	this.createAndPopulateLogItem(logLevel, input, extraInput)
	),
	]);

Then when we flush the log, since we already have a JSON string we only need to print it to stdout:

powertools-lambda-typescript/packages/logger/src/Logger.ts

Lines 884 to 887 in e6d0db9

	if (this.#context[xRayTraceId]) {
	for (const contextItem of this.#context[xRayTraceId]) {
	this.printLog(...contextItem);
	}

[dreamorosi]

I see - makes sense, I missed this.

Thank you for explaining it.

[zirkelc]

@dreamorosi do you want me to continue working on this or would like to start a RFC first? I think you also mentioned you wait for feedback from the Lambda for something related to this.

As a sidenote: in one of my projects, I implemented this feature manually by creating a “CustomLogger” class that extends the Logger and overrides the logging functions. Since processLogItem and printLog are private, I had to work around this and override each debug/info/warn/error method instead. Would you consider making these protected so we can go the way of subclassing Logger to add custom features like this?

[dreamorosi]

@dreamorosi do you want me to continue working on this or would like to start a RFC first? I think you also mentioned you wait for feedback from the Lambda for something related to this.

Thanks for bringing this up.

Given that there are still some fundamental questions about the implementation I think a small RFC would be better. This is also because we'll want to design the feature in a way that can be adopted by all versions of Powertools for AWS, and not just this one.

Since I expect there will be some moderate discussion and we'll have to make some tests that don't necessarily require an implementation, I think having this discussion in an RFC that we, and other versions, can then use as implementation guide would be best.

If possible, and you're interested in championing this effort, I'd suggest to open a new discussion under RFCs and follow the template¹, which will inform the subsequent discussion. After that, based on our process, once we reach an agreement we can start the implementation. Just to manage expectations, almost the entire team will be traveling in the US for re:Invent next week, and many (including me) are taking PTO the week afterwards. We'll do our best to engage with the RFC in a timely manner but there will be some delays.

Regarding the discussion with the AWS Lambda team, that is still ongoing but I don't expect to see any meaningful development soon. I think the most pragmatic way forward would be to implement this feature in a way that allows customers to buffer logs and then flush the buffer manually. Then later on, if Lambda decides to make some hook available to improve on this by allowing us to flush when certain conditions happen, we'll add that.

If anything, having a design document / RFC and a clearly defined use case will help the discussion with that team, so I'd say let's move forward without waiting on this.

As a sidenote: in one of my projects, I implemented this feature manually by creating a “CustomLogger” class that extends the Logger and overrides the logging functions. Since processLogItem and printLog are private, I had to work around this and override each debug/info/warn/error method instead. Would you consider making these protected so we can go the way of subclassing Logger to add custom features like this?

Yes, we can do this right away.

If you could open an issue, we can try to land this change in the next release.

---

Footnotes

1. I'm in the process of moving RFCs to Discussions as they were previously in Issues & I expect the PR to get merged tomorrow. You can however already see the template with the different sections in the PR or by trying to open a new issue using that category, if you want to get a sense of what should be in the RFC. ↩

[zirkelc]

@dreamorosi sounds like a good plan forward! I'd be happy to start the RFC!

Thank you for your support so far and have a good time at re:Invent!

[dreamorosi]

@dreamorosi sounds like a good plan forward! I'd be happy to start the RFC!

Thank you for your support so far and have a good time at re:Invent!

Thank you!

FYI the RFC template in discussions is now live, you should see it if you try to open a new discussion using the RFC category.

For the time being, would it be ok to close this PR? We can always reopen it, in case we want to reprise working on it instead of starting a new branch.

[zirkelc]

Yes, of course, I wanted to close this PR anyway. I'll start the RFC in the next few days/weeks.