Re-think the logger API and internal propagation between shared core and SDK #465

slinkydeveloper · 2024-12-09T09:49:06Z

This API brings API changes, mostly around naming, to the logger internal api. It also renames a publicly exposed logger interface, now named LoggerTransport (reflecting names used in other known JS libraries).

slinkydeveloper · 2024-12-10T11:45:10Z

This is a final example of the new logs:

[restate] [2024-12-10T11:43:51.601Z] INFO:  Listening on 9080...
[restate] [2024-12-10T11:43:51.602Z] WARN:  Accepting requests without validating request signatures; handler access must be restricted
[restate] [2024-12-10T11:43:59.884Z] DEBUG:  Start invocation
[restate] [greeter/greet][inv_17rpyk2iRhDJ2tPathULARLGgJ69lc5nPj][2024-12-10T11:43:59.885Z] INFO:  Starting invocation.
[restate] [greeter/greet][inv_17rpyk2iRhDJ2tPathULARLGgJ69lc5nPj][2024-12-10T11:43:59.889Z] DEBUG:  Executing 'Awakeable'
[restate] [greeter/greet][inv_17rpyk2iRhDJ2tPathULARLGgJ69lc5nPj][2024-12-10T11:43:59.890Z] INFO:  curl -X POST http://localhost:8080/restate/awakeables/prom_1GzI2ITrgrlYBk7BiG3mChq_miA0vBYVRAAAAAQ/resolve --json '"Guardiani"'
[restate] [greeter/greet][inv_17rpyk2iRhDJ2tPathULARLGgJ69lc5nPj][2024-12-10T11:43:59.891Z] DEBUG:  Executing 'Sleep for 1733831049.89s'
[restate] [greeter/greet][inv_17rpyk2iRhDJ2tPathULARLGgJ69lc5nPj][2024-12-10T11:44:09.902Z] WARN:  Invocation completed with an error.
 TimeoutError: Timeout occurred
    at LazyPromise.executor (/home/slinkydeveloper/projects/work/sdk-typescript/packages/restate-sdk/src/context_impl.ts:661:35)
    at process.processTicksAndRejections (node:internal/process/task_queues:105:5)
    at async Object.greet (/home/slinkydeveloper/projects/work/sdk-typescript/packages/restate-sdk-examples/src/greeter.ts:26:31)
    at async HandlerWrapper.invoke (/home/slinkydeveloper/projects/work/sdk-typescript/packages/restate-sdk/src/types/rpc.ts:492:26) {
  code: 408,
  [cause]: undefined
}
[restate] [greeter/greet][inv_17rpyk2iRhDJ2tPathULARLGgJ69lc5nPj][2024-12-10T11:44:09.918Z] DEBUG:  Writing invocation result failure value
[restate] [greeter/greet][inv_17rpyk2iRhDJ2tPathULARLGgJ69lc5nPj][2024-12-10T11:44:09.918Z] DEBUG:  End of the invocation

The DEBUG ones come from the shared core, everything else comes from the SDK

slinkydeveloper · 2024-12-10T11:51:19Z

Improved formatting

[restate][2024-12-10T11:49:13.009Z] INFO: Listening on 9080...
[restate][2024-12-10T11:49:13.011Z] WARN: Accepting requests without validating request signatures; handler access must be restricted
[restate][2024-12-10T11:49:18.979Z] DEBUG: Start invocation
[restate][2024-12-10T11:49:18.980Z][greeter/greet][inv_17slXLwGcVIE4J4GswxK5qdBPyRQX63kWZ] INFO: Starting invocation.
[restate][2024-12-10T11:49:18.983Z][greeter/greet][inv_17slXLwGcVIE4J4GswxK5qdBPyRQX63kWZ] DEBUG: Executing 'Awakeable'
[restate][2024-12-10T11:49:18.983Z][greeter/greet][inv_17slXLwGcVIE4J4GswxK5qdBPyRQX63kWZ] INFO: curl -X POST http://localhost:8080/restate/awakeables/prom_1NBzarU8v3FYBk7Bm-eaoZEFBrdrsr1CbAAAAAQ/resolve --json '"Guardiani"'
[restate][2024-12-10T11:49:18.984Z][greeter/greet][inv_17slXLwGcVIE4J4GswxK5qdBPyRQX63kWZ] DEBUG: Executing 'Sleep for 1733831368.984s'
[restate][2024-12-10T11:49:29.002Z][greeter/greet][inv_17slXLwGcVIE4J4GswxK5qdBPyRQX63kWZ] WARN: Invocation completed with an error.
 TimeoutError: Timeout occurred
    at LazyPromise.executor (/home/slinkydeveloper/projects/work/sdk-typescript/packages/restate-sdk/src/context_impl.ts:661:35)
    at process.processTicksAndRejections (node:internal/process/task_queues:105:5)
    at async Object.greet (/home/slinkydeveloper/projects/work/sdk-typescript/packages/restate-sdk-examples/src/greeter.ts:26:31)
    at async HandlerWrapper.invoke (/home/slinkydeveloper/projects/work/sdk-typescript/packages/restate-sdk/src/types/rpc.ts:492:26) {
  code: 408,
  [cause]: undefined
}
[restate][2024-12-10T11:49:29.015Z][greeter/greet][inv_17slXLwGcVIE4J4GswxK5qdBPyRQX63kWZ] DEBUG: Writing invocation result failure value
[restate][2024-12-10T11:49:29.016Z][greeter/greet][inv_17slXLwGcVIE4J4GswxK5qdBPyRQX63kWZ] DEBUG: End of the invocation
[restate][2024-12-10T11:49:32.906Z] DEBUG: Start invocation
[restate][2024-12-10T11:49:32.907Z][greeter/greet][inv_16tISe3rmLZ80Bi6SZcG7szC831LLXf3CF] INFO: Starting invocation.
[restate][2024-12-10T11:49:32.907Z][greeter/greet][inv_16tISe3rmLZ80Bi6SZcG7szC831LLXf3CF] DEBUG: Executing 'Awakeable'
[restate][2024-12-10T11:49:32.908Z][greeter/greet][inv_16tISe3rmLZ80Bi6SZcG7szC831LLXf3CF] INFO: curl -X POST http://localhost:8080/restate/awakeables/prom_1qunteHhCeEsBk7BnMGTAMq6qiIJUT8MTAAAAAQ/resolve --json '"Guardiani"'
[restate][2024-12-10T11:49:32.908Z][greeter/greet][inv_16tISe3rmLZ80Bi6SZcG7szC831LLXf3CF] DEBUG: Executing 'Sleep for 1733831382.908s'
[restate][2024-12-10T11:49:42.924Z][greeter/greet][inv_16tISe3rmLZ80Bi6SZcG7szC831LLXf3CF] WARN: Invocation completed with an error.
 TimeoutError: Timeout occurred
    at LazyPromise.executor (/home/slinkydeveloper/projects/work/sdk-typescript/packages/restate-sdk/src/context_impl.ts:661:35)
    at process.processTicksAndRejections (node:internal/process/task_queues:105:5)
    at async Object.greet (/home/slinkydeveloper/projects/work/sdk-typescript/packages/restate-sdk-examples/src/greeter.ts:26:31)
    at async HandlerWrapper.invoke (/home/slinkydeveloper/projects/work/sdk-typescript/packages/restate-sdk/src/types/rpc.ts:492:26) {
  code: 408,
  [cause]: undefined
}
[restate][2024-12-10T11:49:42.925Z][greeter/greet][inv_16tISe3rmLZ80Bi6SZcG7szC831LLXf3CF] DEBUG: Writing invocation result failure value
[restate][2024-12-10T11:49:42.925Z][greeter/greet][inv_16tISe3rmLZ80Bi6SZcG7szC831LLXf3CF] DEBUG: End of the invocation

mupperton · 2024-12-10T11:59:26Z

Just curious

[restate][2024-12-10T11:49:32.908Z][greeter/greet][inv_16tISe3rmLZ80Bi6SZcG7szC831LLXf3CF] INFO: curl -X POST http://localhost:8080/restate/awakeables/prom_1qunteHhCeEsBk7BnMGTAMq6qiIJUT8MTAAAAAQ/resolve --json '"Guardiani"'

This appears to be showing the resolving of an awakeable and the value it is being resolved with?

What else is going to be shown this way? Like, ctx.serviceClient calls and their payload?

Can there be a way to opt-out of exposing the values/payloads in logs if they could be sensitive?

slinkydeveloper · 2024-12-10T13:13:28Z

This appears to be showing the resolving of an awakeable and the value it is being resolved with?
What else is going to be shown this way? Like, ctx.serviceClient calls and their payload?
Can there be a way to opt-out of exposing the values/payloads in logs if they could be sensitive?

This is not from the SDK, this is a manual console log statement in the code: https://github.com/restatedev/sdk-typescript/blob/main/packages/restate-sdk-examples/src/greeter.ts#L20

mupperton · 2024-12-10T13:36:19Z

This is not from the SDK, this is a manual console log statement in the code: https://github.com/restatedev/sdk-typescript/blob/main/packages/restate-sdk-examples/src/greeter.ts#L20

Ahh! All good then

So what's this about:

DEBUG: Executing 'Sleep for 1733831382.908s'

That's like 55 years lol

Accidental overwrite, but the reply from @slinkydeveloper is:

That's like 55 years lol

Uhhhhhhh that's a good catch, thanks! That's duration since epoch :D

slinkydeveloper · 2024-12-13T16:30:53Z

This one is now ready to merge, pending re-generating the VM and fixing the conflict

…h the logger facade. Introduce a Logger interface, extending the Console interface, that will be used within the sdk by the shared core.

…are correctly propagated and they use the context aware logger created when the invocation starts.

slinkydeveloper added 5 commits December 16, 2024 14:44

Re-think the logging API, clearly separating the logger transport wit…

b56e19b

…h the logger facade. Introduce a Logger interface, extending the Console interface, that will be used within the sdk by the shared core.

Proper fix for log propagation from shared core to SDK. Now the logs …

224124d

…are correctly propagated and they use the context aware logger created when the invocation starts.

Remove unnecessary data structure

38e28fe

Improve logging formatting

14d18a9

Improve formatting of sleep durations

244189e

slinkydeveloper force-pushed the issues/457 branch from 82da95c to 85638a0 Compare December 16, 2024 13:49

Update again

2fba236

slinkydeveloper force-pushed the issues/457 branch from 85638a0 to 2fba236 Compare December 16, 2024 13:54

slinkydeveloper merged commit 189153b into restatedev:main Dec 16, 2024
2 checks passed

slinkydeveloper deleted the issues/457 branch December 16, 2024 14:01

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Uh oh!

Re-think the logger API and internal propagation between shared core and SDK #465

Re-think the logger API and internal propagation between shared core and SDK #465

Uh oh!

slinkydeveloper commented Dec 9, 2024

Uh oh!

slinkydeveloper commented Dec 10, 2024

Uh oh!

slinkydeveloper commented Dec 10, 2024

Uh oh!

mupperton commented Dec 10, 2024

Uh oh!

slinkydeveloper commented Dec 10, 2024

Uh oh!

mupperton commented Dec 10, 2024 •

edited

Loading

Uh oh!

slinkydeveloper commented Dec 13, 2024

Uh oh!

Uh oh!

Uh oh!

Re-think the logger API and internal propagation between shared core and SDK #465

Re-think the logger API and internal propagation between shared core and SDK #465

Uh oh!

Conversation

slinkydeveloper commented Dec 9, 2024

Uh oh!

slinkydeveloper commented Dec 10, 2024

Uh oh!

slinkydeveloper commented Dec 10, 2024

Uh oh!

mupperton commented Dec 10, 2024

Uh oh!

slinkydeveloper commented Dec 10, 2024

Uh oh!

mupperton commented Dec 10, 2024 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

slinkydeveloper commented Dec 13, 2024

Uh oh!

Uh oh!

Uh oh!

mupperton commented Dec 10, 2024 •

edited

Loading