Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Introduce ctx.console to provide logging utilities #233

Merged
merged 5 commits into from
Jan 29, 2024

Conversation

slinkydeveloper
Copy link
Contributor

@slinkydeveloper slinkydeveloper commented Jan 18, 2024

Fix #187.

In this PR:

This is a sample output with RESTATE_DEBUG_LOGGING=OFF:

[restate] [2024-01-18T13:16:49.534Z] INFO: Listening on 9080...
[restate] [greeter/logger][nZ7YpdY6EikAY0ct5vCfa6bXwZZCc6sxw][2024-01-18T13:16:51.566Z] LOG:  HEEEELLLLOOOOO! Hello Pete! at the 30th time
[restate] [greeter/logger][WgTjvH6v2vkAY0ct5vCcE6XVnm_Y-8fMw][2024-01-18T13:16:51.627Z] LOG:  HEEEELLLLOOOOO! delayed Hello Pete! at the 30th time

(those log lines come from the example)

This is sample output with RESTATE_DEBUG_LOGGING=INVOKE:

[restate] [2024-01-18T13:18:07.478Z] INFO: Listening on 9080...
[restate] [greeter/greet][Xpt9SZI6-EYAY0cuMIweYu6AVBdKlP8qg][2024-01-18T13:18:07.687Z] DEBUG: Invoking function.
[restate] [counter/count][mgOR55f4niYAY0cuMVKfGaXzAZTDJDMQA][2024-01-18T13:18:07.704Z] DEBUG: Invoking function.
[restate] [counter/count][mgOR55f4niYAY0cuMVKfGaXzAZTDJDMQA][2024-01-18T13:18:07.706Z] DEBUG: Function completed successfully.
[restate] [greeter/greet][Xpt9SZI6-EYAY0cuMIweYu6AVBdKlP8qg][2024-01-18T13:18:07.750Z] DEBUG: Function completed successfully.
[restate] [greeter/logger][pf8TPYty3WMAY0cuMWHewq3wafCGye4mA][2024-01-18T13:18:07.795Z] DEBUG: Invoking function.
[restate] [greeter/logger][pf8TPYty3WMAY0cuMWHewq3wafCGye4mA][2024-01-18T13:18:07.795Z] LOG:  HEEEELLLLOOOOO! Hello Pete! at the 31th time
[restate] [greeter/logger][pf8TPYty3WMAY0cuMWHewq3wafCGye4mA][2024-01-18T13:18:07.796Z] DEBUG: Function completed successfully.
[restate] [greeter/logger][_NUHCUeoF1wAY0cuMWHfXGYFt-oxrw-Hg][2024-01-18T13:18:07.860Z] DEBUG: Invoking function.
[restate] [greeter/logger][_NUHCUeoF1wAY0cuMWHfXGYFt-oxrw-Hg][2024-01-18T13:18:07.860Z] LOG:  HEEEELLLLOOOOO! delayed Hello Pete! at the 31th time
[restate] [greeter/logger][_NUHCUeoF1wAY0cuMWHfXGYFt-oxrw-Hg][2024-01-18T13:18:07.860Z] DEBUG: Function completed successfully.

This is the sample output with RESTATE_DEBUG_LOGGING=JOURNAL:

[restate] [2024-01-18T13:18:44.998Z] INFO: Listening on 9080...
[restate] [greeter/greet][Hyxp3qilSPMAY0cuVaucBepjVnz-4Snng][2024-01-18T13:18:45.095Z] DEBUG: Invoking function.
[restate] [greeter/greet][Hyxp3qilSPMAY0cuVaucBepjVnz-4Snng][2024-01-18T13:18:45.099Z] DEBUG: Adding message to journal and sending to Restate ; InvokeEntryMessage
[restate] [greeter/greet][Hyxp3qilSPMAY0cuVaucBepjVnz-4Snng][2024-01-18T13:18:45.100Z] DEBUG: Scheduling suspension in 30000 ms
[restate] [counter/count][mgOR55f4niYAY0cuVdwcZmGyLi3zLWe6Q][2024-01-18T13:18:45.125Z] DEBUG: Invoking function.
[restate] [counter/count][mgOR55f4niYAY0cuVdwcZmGyLi3zLWe6Q][2024-01-18T13:18:45.126Z] DEBUG: Adding message to journal and sending to Restate ; GetStateEntryMessage
[restate] [counter/count][mgOR55f4niYAY0cuVdwcZmGyLi3zLWe6Q][2024-01-18T13:18:45.127Z] DEBUG: Adding message to journal and sending to Restate ; SetStateEntryMessage
[restate] [counter/count][mgOR55f4niYAY0cuVdwcZmGyLi3zLWe6Q][2024-01-18T13:18:45.130Z] DEBUG: Journaled and sent output message ; OutputStreamEntryMessage
[restate] [counter/count][mgOR55f4niYAY0cuVdwcZmGyLi3zLWe6Q][2024-01-18T13:18:45.130Z] DEBUG: Function completed successfully.
[restate] [greeter/greet][Hyxp3qilSPMAY0cuVaucBepjVnz-4Snng][2024-01-18T13:18:45.179Z] DEBUG: Received completion message from Restate, adding to journal. ; CompletionMessage
[restate] [greeter/greet][Hyxp3qilSPMAY0cuVaucBepjVnz-4Snng][2024-01-18T13:18:45.183Z] DEBUG: Adding message to journal and sending to Restate ; BackgroundInvokeEntryMessage
[restate] [greeter/greet][Hyxp3qilSPMAY0cuVaucBepjVnz-4Snng][2024-01-18T13:18:45.184Z] DEBUG: Adding message to journal and sending to Restate ; BackgroundInvokeEntryMessage
[restate] [greeter/greet][Hyxp3qilSPMAY0cuVaucBepjVnz-4Snng][2024-01-18T13:18:45.185Z] DEBUG: Journaled and sent output message ; OutputStreamEntryMessage
[restate] [greeter/greet][Hyxp3qilSPMAY0cuVaucBepjVnz-4Snng][2024-01-18T13:18:45.185Z] DEBUG: Function completed successfully.
[restate] [greeter/logger][L-sAQHC6hNUAY0cuVfDduG_27xzzoCYlg][2024-01-18T13:18:45.230Z] DEBUG: Invoking function.
[restate] [greeter/logger][L-sAQHC6hNUAY0cuVfDduG_27xzzoCYlg][2024-01-18T13:18:45.230Z] LOG:  HEEEELLLLOOOOO! Hello Pete! at the 32th time
[restate] [greeter/logger][L-sAQHC6hNUAY0cuVfDduG_27xzzoCYlg][2024-01-18T13:18:45.230Z] DEBUG: Journaled and sent output message ; OutputStreamEntryMessage
[restate] [greeter/logger][L-sAQHC6hNUAY0cuVfDduG_27xzzoCYlg][2024-01-18T13:18:45.230Z] DEBUG: Function completed successfully.
[restate] [greeter/logger][HdYwrvq8LMoAY0cuVfDdlawW9sTA4l9lw][2024-01-18T13:18:45.292Z] DEBUG: Invoking function.
[restate] [greeter/logger][HdYwrvq8LMoAY0cuVfDdlawW9sTA4l9lw][2024-01-18T13:18:45.292Z] LOG:  HEEEELLLLOOOOO! delayed Hello Pete! at the 32th time
[restate] [greeter/logger][HdYwrvq8LMoAY0cuVfDdlawW9sTA4l9lw][2024-01-18T13:18:45.292Z] DEBUG: Journaled and sent output message ; OutputStreamEntryMessage
[restate] [greeter/logger][HdYwrvq8LMoAY0cuVfDdlawW9sTA4l9lw][2024-01-18T13:18:45.292Z] DEBUG: Function completed successfully.

This is the sample output with RESTATE_DEBUG_LOGGING=JOURNAL_VERBOSE:

[restate] [2024-01-18T13:19:19.031Z] INFO: Listening on 9080...
[restate] [greeter/greet][eR_orTibcnYAY0cudt6dF6VNTkCdjXcSw][2024-01-18T13:19:19.102Z] DEBUG: Invoking function.
[restate] [greeter/greet][eR_orTibcnYAY0cudt6dF6VNTkCdjXcSw][2024-01-18T13:19:19.106Z] DEBUG: Adding message to journal and sending to Restate ; InvokeEntryMessage : {"serviceName":"counter","methodName":"count","parameter":{"type":"Buffer","data":[10,4,80,101,116,101,168,6,4]}}
[restate] [greeter/greet][eR_orTibcnYAY0cudt6dF6VNTkCdjXcSw][2024-01-18T13:19:19.107Z] DEBUG: Scheduling suspension in 30000 ms
[restate] [counter/count][mgOR55f4niYAY0cudxHdi6-8oo6zq4n_g][2024-01-18T13:19:19.132Z] DEBUG: Invoking function.
[restate] [counter/count][mgOR55f4niYAY0cudxHdi6-8oo6zq4n_g][2024-01-18T13:19:19.134Z] DEBUG: Adding message to journal and sending to Restate ; GetStateEntryMessage : {"key":{"type":"Buffer","data":[115,101,101,110]},"value":{"type":"Buffer","data":[51,50]}}
[restate] [counter/count][mgOR55f4niYAY0cudxHdi6-8oo6zq4n_g][2024-01-18T13:19:19.135Z] DEBUG: Adding message to journal and sending to Restate ; SetStateEntryMessage : {"key":{"type":"Buffer","data":[115,101,101,110]},"value":{"type":"Buffer","data":[51,51]}}
[restate] [counter/count][mgOR55f4niYAY0cudxHdi6-8oo6zq4n_g][2024-01-18T13:19:19.136Z] DEBUG: Journaled and sent output message ; OutputStreamEntryMessage : {"value":{"type":"Buffer","data":[10,9,17,0,0,0,0,0,0,64,64]}}
[restate] [counter/count][mgOR55f4niYAY0cudxHdi6-8oo6zq4n_g][2024-01-18T13:19:19.137Z] DEBUG: Function completed successfully.
[restate] [greeter/greet][eR_orTibcnYAY0cudt6dF6VNTkCdjXcSw][2024-01-18T13:19:19.184Z] DEBUG: Received completion message from Restate, adding to journal. ; CompletionMessage : {"entryIndex":1,"value":{"type":"Buffer","data":[10,9,17,0,0,0,0,0,0,64,64]}}
[restate] [greeter/greet][eR_orTibcnYAY0cudt6dF6VNTkCdjXcSw][2024-01-18T13:19:19.188Z] DEBUG: Adding message to journal and sending to Restate ; BackgroundInvokeEntryMessage : {"serviceName":"greeter","methodName":"logger","parameter":{"type":"Buffer","data":[10,28,72,101,108,108,111,32,80,101,116,101,33,32,97,116,32,116,104,101,32,51,51,116,104,32,116,105,109,101,168,6,4]},"invokeTime":0}
[restate] [greeter/greet][eR_orTibcnYAY0cudt6dF6VNTkCdjXcSw][2024-01-18T13:19:19.189Z] DEBUG: Adding message to journal and sending to Restate ; BackgroundInvokeEntryMessage : {"serviceName":"greeter","methodName":"logger","parameter":{"type":"Buffer","data":[10,36,100,101,108,97,121,101,100,32,72,101,108,108,111,32,80,101,116,101,33,32,97,116,32,116,104,101,32,51,51,116,104,32,116,105,109,101,168,6,4]},"invokeTime":1705583959289}
[restate] [greeter/greet][eR_orTibcnYAY0cudt6dF6VNTkCdjXcSw][2024-01-18T13:19:19.190Z] DEBUG: Journaled and sent output message ; OutputStreamEntryMessage : {"value":{"type":"Buffer","data":[10,30,26,28,72,101,108,108,111,32,80,101,116,101,33,32,97,116,32,116,104,101,32,51,51,116,104,32,116,105,109,101]}}
[restate] [greeter/greet][eR_orTibcnYAY0cudt6dF6VNTkCdjXcSw][2024-01-18T13:19:19.190Z] DEBUG: Function completed successfully.
[restate] [greeter/logger][uAMyavelSA8AY0cudyYcdKnGQaqXHQdoA][2024-01-18T13:19:19.235Z] DEBUG: Invoking function.
[restate] [greeter/logger][uAMyavelSA8AY0cudyYcdKnGQaqXHQdoA][2024-01-18T13:19:19.236Z] LOG:  HEEEELLLLOOOOO! Hello Pete! at the 33th time
[restate] [greeter/logger][uAMyavelSA8AY0cudyYcdKnGQaqXHQdoA][2024-01-18T13:19:19.236Z] DEBUG: Journaled and sent output message ; OutputStreamEntryMessage : {"value":{"type":"Buffer","data":[]}}
[restate] [greeter/logger][uAMyavelSA8AY0cudyYcdKnGQaqXHQdoA][2024-01-18T13:19:19.236Z] DEBUG: Function completed successfully.
[restate] [greeter/logger][xjnqqU9I6JwAY0cudyYcFi9KT5JiOis_g][2024-01-18T13:19:19.296Z] DEBUG: Invoking function.
[restate] [greeter/logger][xjnqqU9I6JwAY0cudyYcFi9KT5JiOis_g][2024-01-18T13:19:19.296Z] LOG:  HEEEELLLLOOOOO! delayed Hello Pete! at the 33th time
[restate] [greeter/logger][xjnqqU9I6JwAY0cudyYcFi9KT5JiOis_g][2024-01-18T13:19:19.296Z] DEBUG: Journaled and sent output message ; OutputStreamEntryMessage : {"value":{"type":"Buffer","data":[]}}
[restate] [greeter/logger][xjnqqU9I6JwAY0cudyYcFi9KT5JiOis_g][2024-01-18T13:19:19.296Z] DEBUG: Function completed successfully.

@slinkydeveloper slinkydeveloper force-pushed the issues/187 branch 2 times, most recently from 5864729 to cda88c5 Compare January 18, 2024 13:13
@slinkydeveloper slinkydeveloper changed the title [WIP] Introduce ctx.console to provide logging utilities Introduce ctx.console to provide logging utilities Jan 18, 2024
…write out in the same format.

Also modified the debugInvokeMessage and debugJournalMessage which are now static methods accepting the console as parameter. We also by default set the RestateDebugLogLevel to INVOKE.
@gvdongen
Copy link
Contributor

LGTM, Also works locally for me. 👍
Unrelated to this PR: the JOURNAL_VERBOSE logging seems a bit pointless if most values are printed as buffers?

@slinkydeveloper
Copy link
Contributor Author

the JOURNAL_VERBOSE logging seems a bit pointless if most values are printed as buffers?

IMO it doesn't hurt to keep it around, perhaps it would be more useful if buffers are printed as hex or base64.

@gvdongen
Copy link
Contributor

the JOURNAL_VERBOSE logging seems a bit pointless if most values are printed as buffers?

IMO it doesn't hurt to keep it around, perhaps it would be more useful if buffers are printed as hex or base64.

We should definitely keep it around, but maybe indeed print in a human-parseable format. I can create another issue for this.

Copy link
Contributor

@StephanEwen StephanEwen left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Generally, I like this a lot, many good changes in here.

Most comments are inline, a few high-level comments below:

AWS Request ID

My main issue here is that the AWS Request ID seems a bit too hard-wired into the core classes. Maybe we can do this a bit more generic, like allowing to pass in an additional log fields (which would be a string populates as [AWS RequestId: ${context.awsRequestId}] by the Lambda handler.

Commit structure:

  • For the next PRs, I'd encourage to leave renaming of methods/variable out of the core commits) and have dedicated pre-processing or cleanup commits with renamings.

@@ -21,7 +21,7 @@ import {
import {
CompletablePromise,
makeFqServiceName,
printMessageAsJson,
formatMessageAsJson,
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Would be nice to have this in pre- or post-processing commits, not mixed into main logic commits.

src/invocation.ts Outdated Show resolved Hide resolved
src/logger.ts Outdated Show resolved Hide resolved
/* eslint-disable @typescript-eslint/no-explicit-any */
/* eslint-disable no-console */

export class LoggerContext {
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I was a bit confused by this name. I expected this initially to be a context like in log4j that is dynamically available in the methods that implement the logging logic. But this here is more a config object, used to construct the logger.

Maybe call it LoggerConfig ?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

For me this is really the logging context, because it adds contextual information to log events. LoggerConfig for me is more something like "where to write it" and "the format to use to write it".

The fact that is not dynamically available to logging methods now is an implementation detail of how I just generate the prefix when i create the logger. If we extend the logger with "custom formats", then surely we'll make this context available in the log method implementations.

src/state_machine.ts Outdated Show resolved Hide resolved
@@ -85,8 +97,8 @@ export class StateMachine<I, O> implements RestateStreamConsumer {
}

if (m.messageType === COMPLETION_MESSAGE_TYPE) {
rlog.debugJournalMessage(
this.invocation.logPrefix,
debugJournalMessage(
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think the original encapsulation was a bit nicer, where the debugJournalMessage was on the logger. Why was it necessary to remove that?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Because I wanted to remove the old rlog and rely on the new console logger, and I didn't want debugJournalMessage and debugInvocationMessage as those are concern of the internal state machine, and not of the public API. I can reintroduce a new class/interface for debugJournalMessage and debugInvocationMessage and wrap the logger created in the state machine.

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

It is not a big deal, was just wondering if there was a deeper reason why that changed.
The rlog was also just internal, and extended Concole to keep those concerns separate.

interface RestateInternalConsole extends Console {
  debugInvocationMessage(...): void;
  debugJournalMessage(...): void;
}

But if that isn't working out, one could probably also do this:
``´typescript
interface InternalLogMethods {
debugInvocationMessage(...): void;
debugJournalMessage(...): void;

}
export type RestateInternalConsole = Console & InternalLogMethods;

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Look at the last commit

src/restate_context.ts Outdated Show resolved Hide resolved
@slinkydeveloper slinkydeveloper merged commit 63017c8 into restatedev:main Jan 29, 2024
2 checks passed
@slinkydeveloper slinkydeveloper deleted the issues/187 branch January 29, 2024 15:35
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

Restate logging utilities
3 participants