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

feat: Workflow logger improvements #1117

Merged
merged 5 commits into from
May 17, 2023

Conversation

bergundy
Copy link
Member

Example:

import * as workflow from '@temporalio/workflow';

export async function myWorkflow(): Promise<void> {
  workflow.log.info('hello from my workflow', { key: 'value' });
}

@bergundy bergundy requested review from lorensr and mjameswh May 12, 2023 18:20
*
* See the documentation for `WorkerOptions`, `defaultSinks`, and `Runtime` for more information.
*/
export const log = loggerSinks.defaultWorkerLogger;
Copy link
Contributor

Choose a reason for hiding this comment

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

I'm thinking that maybe we should clone arguments (ie. JSON.parse(JSON.stringify(args))) on Workflow side (before they get captured by the sink plumbing). I got bitten once because an object that was being passed to a sink was being modified afterward (but in the same WFT), so the sink would receive the object in its modified state rather than the object in the state it was at the moment the sink was called in code...

Copy link
Contributor

Choose a reason for hiding this comment

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

For similar reason, wondering if we should maybe capture the real time at the moment log was called...

Copy link
Contributor

Choose a reason for hiding this comment

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

For now, I suggest we simply mark this as experimental. Let's get this in as is, and we'll see later if either of my previous concern turns out to be justified.

Copy link
Member Author

Choose a reason for hiding this comment

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

I wouldn't want to impose JSON serializability here, postMessage accepts a wider variety of types.

Copy link
Member

Choose a reason for hiding this comment

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

Why not just use this which is mentioned in the linked docs? https://developer.mozilla.org/en-US/docs/Web/API/Web_Workers_API/Structured_clone_algorithm

I think the point James makes seems pretty important

Copy link
Member Author

Choose a reason for hiding this comment

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

I agree that the point is important, I’ll look into it

Copy link
Member Author

Choose a reason for hiding this comment

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

All good points @mjameswh , thanks

/**
* Default workflow logger.
* This logger is replay-aware and will omit log messages on workflow replay.
* The messages emitted by this logger are funnelled to the worker's `defaultSinks`, which are installed by default.
Copy link
Contributor

Choose a reason for hiding this comment

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

Suggested change
* The messages emitted by this logger are funnelled to the worker's `defaultSinks`, which are installed by default.
* The messages emitted by this logger are funnelled to the worker's {@link defaultSinks}, which are installed by default.

Copy link
Member Author

Choose a reason for hiding this comment

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

I'll try that and see if it gets linked properly, defaultSinks is in a different package.

* {@link https://nodejs.org/api/worker_threads.html#worker_threads_port_postmessage_value_transferlist | postMessage}
* API.
*
* `defaultSinks` accepts a user logger and defaults to the `Runtime`'s logger.
Copy link
Contributor

Choose a reason for hiding this comment

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

Suggested change
* `defaultSinks` accepts a user logger and defaults to the `Runtime`'s logger.
* `defaultSinks` accepts a user logger and defaults to the {@link RuntimeOptions.logger | `Runtime`'s logger}.

Comment on lines +1269 to +1270
*
* See the documentation for `WorkerOptions`, `defaultSinks`, and `Runtime` for more information.
Copy link
Contributor

Choose a reason for hiding this comment

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

Suggested change
*
* See the documentation for `WorkerOptions`, `defaultSinks`, and `Runtime` for more information.

prefer linking above, when the terms are used. didn't see a place for {@link WorkerOptions.sinks}

@@ -3,6 +3,8 @@ import { AsyncLocalStorage } from 'node:async_hooks';
import vm from 'node:vm';
import * as internals from '@temporalio/workflow/lib/worker-interface';
import { IllegalStateError } from '@temporalio/common';
import { getTimeOfDay } from '@temporalio/core-bridge';
Copy link
Contributor

Choose a reason for hiding this comment

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

I know this is not new, but any reason why getting nano time through core was preferred over process.hrtime?

Copy link
Member Author

Choose a reason for hiding this comment

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

We need to compare timestamps of logs emitted by Core and Lang when buffering Core logs so they can be emitted in order.

Copy link
Member Author

Choose a reason for hiding this comment

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

From the hrtime docs:

These times are relative to an arbitrary time in the past, and not related to the time of day and therefore not subject to clock drift. The primary use is for measuring performance between intervals:

We need time of day in nanosecond resolution.

@bergundy
Copy link
Member Author

I'm merging this and opening a new PR to call structuredClone on every sink call.

@bergundy bergundy merged commit 14189f1 into temporalio:main May 17, 2023
23 checks passed
@bergundy bergundy deleted the lazy-sinks-logger branch May 17, 2023 20:58
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.

None yet

4 participants