fix: Properly synchronize slog sender termination #11052

gibson042 · 2025-02-26T00:16:04Z

Description

This was prompted by #10925 (comment) (calling out missing level data for kernel console slog entries), but more fundamentally fixes the interaction between cosmic-swingset, the kernel, and the telemetry system (and performs a few cleanups along the way).

Security Considerations

Security posture should not be affected.

Scaling Considerations

None.

Documentation Considerations

n/a

Testing Considerations

Manual confirmation per #10776:

slog excerpt

{"type":"syscall","crankNum":407,"vatID":"v12","deliveryNum":13,"syscallNum":19,"replay":false,"ksc":["subscribe","v12","kp140"],"vsc":["subscribe","p+12"],"time":1740527497.795959,"monotime":64.620102064}
{"type":"syscall-result","crankNum":407,"vatID":"v12","deliveryNum":13,"syscallNum":19,"replay":false,"ksr":["ok",null],"vsr":["ok",null],"time":1740527497.79604,"monotime":64.620182996}
{"type":"clist","crankNum":407,"mode":"drop","vatID":"v12","kobj":"kp139","vobj":"p-61","time":1740527497.79643,"monotime":64.620573542}
{"type":"syscall","crankNum":407,"vatID":"v12","deliveryNum":13,"syscallNum":20,"replay":false,"ksc":["resolve","v12",[["kp139",false,{"body":"#\"$0.Alleged: IST payment\"","slots":["ko113"]}]]],"vsc":["resolve",[["p-61",false,{"body":"#\"$0.Alleged: IST payment\"","slots":["o-60"]}]]],"time":1740527497.796508,"monotime":64.620651781}
{"type":"syscall-result","crankNum":407,"vatID":"v12","deliveryNum":13,"syscallNum":20,"replay":false,"ksr":["ok",null],"vsr":["ok",null],"time":1740527497.796697,"monotime":64.62084073199999}
{"type":"syscall","crankNum":407,"vatID":"v12","deliveryNum":13,"syscallNum":21,"replay":false,"ksc":["vatstoreSet","v12","idCounters","{\"exportID\":23,\"collectionID\":14,\"promiseID\":13}"],"vsc":["vatstoreSet","idCounters","{\"exportID\":23,\"collectionID\":14,\"promiseID\":13}"],"time":1740527497.796941,"monotime":64.621084505}
{"type":"syscall-result","crankNum":407,"vatID":"v12","deliveryNum":13,"syscallNum":21,"replay":false,"ksr":["ok",null],"vsr":["ok",null],"time":1740527497.796998,"monotime":64.621141273}
{"type":"syscall","crankNum":407,"vatID":"v12","deliveryNum":13,"syscallNum":22,"replay":false,"ksc":["vatstoreSet","v12","vc.12.|schemata","{\"body\":\"#{\\\"keyShape\\\":{\\\"#tag\\\":\\\"match:scalar\\\",\\\"payload\\\":\\\"#undefined\\\"},\\\"label\\\":\\\"activeZCFSeats\\\"}\",\"slots\":[]}"],"vsc":["vatstoreSet","vc.12.|schemata","{\"body\":\"#{\\\"keyShape\\\":{\\\"#tag\\\":\\\"match:scalar\\\",\\\"payload\\\":\\\"#undefined\\\"},\\\"label\\\":\\\"activeZCFSeats\\\"}\",\"slots\":[]}"],"time":1740527497.797194,"monotime":64.621337016}
{"type":"syscall-result","crankNum":407,"vatID":"v12","deliveryNum":13,"syscallNum":22,"replay":false,"ksr":["ok",null],"vsr":["ok",null],"time":1740527497.797243,"monotime":64.62138665}
{"type":"syscall","crankNum":407,"vatID":"v12","deliveryNum":13,"syscallNum":23,"replay":false,"ksc":["vatstoreSet","v12","vc.13.|schemata","{\"body\":\"#{\\\"keyShape\\\":{\\\"#tag\\\":\\\"match:scalar\\\",\\\"payload\\\":\\\"#undefined\\\"},\\\"label\\\":\\\"zcfSeatToSeatHandle\\\"}\",\"slots\":[]}"],"vsc":["vatstoreSet","vc.13.|schemata","{\"body\":\"#{\\\"keyShape\\\":{\\\"#tag\\\":\\\"match:scalar\\\",\\\"payload\\\":\\\"#undefined\\\"},\\\"label\\\":\\\"zcfSeatToSeatHandle\\\"}\",\"slots\":[]}"],"time":1740527497.797417,"monotime":64.621560356}
{"type":"syscall-result","crankNum":407,"vatID":"v12","deliveryNum":13,"syscallNum":23,"replay":false,"ksr":["ok",null],"vsr":["ok",null],"time":1740527497.797454,"monotime":64.621596915}
{"type":"deliver-result","crankNum":407,"vatID":"v12","deliveryNum":13,"replay":false,"dr":["ok",null,{"meterType":"xs-meter-34","currentHeapCount":392885,"compute":143185,"allocate":46268416,"timestamps":[1740527497.788211,1740527497.788585,1740527497.789082,1740527497.789307,1740527497.789815,1740527497.790001,1740527497.790369,1740527497.790651,1740527497.790798,1740527497.7912,1740527497.791383,1740527497.791439,1740527497.791629,1740527497.791687,1740527497.791946,1740527497.791994,1740527497.7922,1740527497.79224,1740527497.792447,1740527497.792476,1740527497.792649,1740527497.792704,1740527497.792904,1740527497.793317,1740527497.793441,1740527497.793488,1740527497.793621,1740527497.793654,1740527497.793815,1740527497.793846,1740527497.794009,1740527497.794043,1740527497.794202,1740527497.794229,1740527497.794441,1740527497.794554,1740527497.794991,1740527497.795274,1740527497.795742,1740527497.795778,1740527497.796088,1740527497.796216,1740527497.79675,1740527497.796844,1740527497.797045,1740527497.79708,1740527497.797288,1740527497.797317,1740527497.797483,1740527497.797602]}],"time":1740527497.797708,"monotime":64.621851681}
{"type":"terminate","vatID":"v12","shouldReject":false,"info":{"body":"#\"payment retrieved\"","slots":[]},"time":1740527497.798019,"monotime":64.622162789}
{"type":"console","source":"kernel","level":"log","args":["kernel terminating vat v12 (failure=false)"],"time":1740527497.798286,"monotime":64.622429777}
{"type":"crank-finish","crankNum":407,"crankhash":"086f84650ada36d845ee2079ea0dfe6e6e08d6a587f6be46868e75eee0690a6b","activityhash":"ede8ca0d16de82e6eb8748dcfe475d71e908f334bdc7d564867f77384c6d0798","time":1740527497.80501,"monotime":64.629155006}

Upgrade Considerations

This fixes a late-discovered flaw in #10925 and would ideally be cherry-picked into agoric-upgrade-19, but if it doesn't make it in then we'll just be missing the kernel console level data until agoric-upgrade-20 (which is still acceptable).

Release verification should look for slog entries like the above (type "console", source "kernel", level "log"/"warn"/"error"/etc.).

cloudflare-workers-and-pages · 2025-02-26T15:02:20Z

Deploying agoric-sdk with Cloudflare Pages

Latest commit:	`6c6fba4`
Status:	✅ Deploy successful!
Preview URL:	https://aef1fe73.agoric-sdk.pages.dev
Branch Preview URL:	https://gibson-10925-followup.agoric-sdk.pages.dev

View logs

mhofman

A few nits and a request for change on the handling of stdout close.

packages/SwingSet/src/kernel/slogger.js

mhofman · 2025-02-28T01:40:08Z

packages/SwingSet/src/kernel/slogger.js

-     * @returns {F} the wrapped method
-     */
-    wrap(method, impl) {
+  const wrappedMethods = /** @type {typeof methods} */ (


Why not Methods instead of typeof methods?

To allow for the increased specificity.

I don't understand what increased specificity. Isn't typeof methods === Methods ?

mhofman · 2025-02-28T01:51:30Z

packages/internal/src/node/fs-stream.js

+    const waitForDrain = await written;
+    if (waitForDrain) {
+      await new Promise(resolve => stream.once('drain', resolve));
+    }


Yeah that's a little more respectful of the drain signal.

packages/internal/src/node/fs-stream.js

packages/telemetry/test/flight-recorder.test.js

gibson042 · 2025-02-28T18:21:06Z

@mhofman back to you

mergify · 2025-03-01T02:27:31Z

This pull request has been removed from the queue for the following reason: pull request manually updated.

The pull request #11052 has been manually updated

You should look at the reason for the failure and decide if the pull request needs to be fixed or if you want to requeue it.

If you want to requeue this pull request, you need to post a comment with the text: @mergifyio requeue

mergify · 2025-03-01T03:12:33Z

This pull request has been removed from the queue for the following reason: checks failed.

The merge conditions cannot be satisfied due to failing checks:

❌ integration-test-result
☑️ linear-history

You should look at the reason for the failure and decide if the pull request needs to be fixed or if you want to requeue it.

If you want to requeue this pull request, you need to post a comment with the text: @mergifyio requeue

gibson042 · 2025-03-01T06:09:34Z

@Mergifyio requeue

mergify · 2025-03-01T06:10:03Z

requeue

❌ This pull request head commit has not been previously disembarked from queue.

mergify · 2025-03-01T06:49:16Z

This pull request has been removed from the queue for the following reason: checks failed.

The merge conditions cannot be satisfied due to failing checks:

❌ integration-test-result
☑️ linear-history

You should look at the reason for the failure and decide if the pull request needs to be fixed or if you want to requeue it.

If you want to requeue this pull request, you need to post a comment with the text: @mergifyio requeue

mergify · 2025-03-01T17:12:41Z

This pull request has been removed from the queue for the following reason: checks failed.

The merge conditions cannot be satisfied due to failing checks:

❌ integration-test-result
☑️ linear-history

You should look at the reason for the failure and decide if the pull request needs to be fixed or if you want to requeue it.

If you want to requeue this pull request, you need to post a comment with the text: @mergifyio requeue

Ref #10925

…mWriter

…e end()

refs: #10925 ## Description This was prompted by #10925 (comment) (calling out missing `level` data for kernel console slog entries), but more fundamentally fixes the interaction between cosmic-swingset, the kernel, and the telemetry system (and performs a few cleanups along the way). ### Security Considerations Security posture should not be affected. ### Scaling Considerations None. ### Documentation Considerations n/a ### Testing Considerations Manual confirmation per #10776: <details><summary>slog excerpt</summary> ``` {"type":"syscall","crankNum":407,"vatID":"v12","deliveryNum":13,"syscallNum":19,"replay":false,"ksc":["subscribe","v12","kp140"],"vsc":["subscribe","p+12"],"time":1740527497.795959,"monotime":64.620102064} {"type":"syscall-result","crankNum":407,"vatID":"v12","deliveryNum":13,"syscallNum":19,"replay":false,"ksr":["ok",null],"vsr":["ok",null],"time":1740527497.79604,"monotime":64.620182996} {"type":"clist","crankNum":407,"mode":"drop","vatID":"v12","kobj":"kp139","vobj":"p-61","time":1740527497.79643,"monotime":64.620573542} {"type":"syscall","crankNum":407,"vatID":"v12","deliveryNum":13,"syscallNum":20,"replay":false,"ksc":["resolve","v12",[["kp139",false,{"body":"#\"$0.Alleged: IST payment\"","slots":["ko113"]}]]],"vsc":["resolve",[["p-61",false,{"body":"#\"$0.Alleged: IST payment\"","slots":["o-60"]}]]],"time":1740527497.796508,"monotime":64.620651781} {"type":"syscall-result","crankNum":407,"vatID":"v12","deliveryNum":13,"syscallNum":20,"replay":false,"ksr":["ok",null],"vsr":["ok",null],"time":1740527497.796697,"monotime":64.62084073199999} {"type":"syscall","crankNum":407,"vatID":"v12","deliveryNum":13,"syscallNum":21,"replay":false,"ksc":["vatstoreSet","v12","idCounters","{\"exportID\":23,\"collectionID\":14,\"promiseID\":13}"],"vsc":["vatstoreSet","idCounters","{\"exportID\":23,\"collectionID\":14,\"promiseID\":13}"],"time":1740527497.796941,"monotime":64.621084505} {"type":"syscall-result","crankNum":407,"vatID":"v12","deliveryNum":13,"syscallNum":21,"replay":false,"ksr":["ok",null],"vsr":["ok",null],"time":1740527497.796998,"monotime":64.621141273} {"type":"syscall","crankNum":407,"vatID":"v12","deliveryNum":13,"syscallNum":22,"replay":false,"ksc":["vatstoreSet","v12","vc.12.|schemata","{\"body\":\"#{\\\"keyShape\\\":{\\\"#tag\\\":\\\"match:scalar\\\",\\\"payload\\\":\\\"#undefined\\\"},\\\"label\\\":\\\"activeZCFSeats\\\"}\",\"slots\":[]}"],"vsc":["vatstoreSet","vc.12.|schemata","{\"body\":\"#{\\\"keyShape\\\":{\\\"#tag\\\":\\\"match:scalar\\\",\\\"payload\\\":\\\"#undefined\\\"},\\\"label\\\":\\\"activeZCFSeats\\\"}\",\"slots\":[]}"],"time":1740527497.797194,"monotime":64.621337016} {"type":"syscall-result","crankNum":407,"vatID":"v12","deliveryNum":13,"syscallNum":22,"replay":false,"ksr":["ok",null],"vsr":["ok",null],"time":1740527497.797243,"monotime":64.62138665} {"type":"syscall","crankNum":407,"vatID":"v12","deliveryNum":13,"syscallNum":23,"replay":false,"ksc":["vatstoreSet","v12","vc.13.|schemata","{\"body\":\"#{\\\"keyShape\\\":{\\\"#tag\\\":\\\"match:scalar\\\",\\\"payload\\\":\\\"#undefined\\\"},\\\"label\\\":\\\"zcfSeatToSeatHandle\\\"}\",\"slots\":[]}"],"vsc":["vatstoreSet","vc.13.|schemata","{\"body\":\"#{\\\"keyShape\\\":{\\\"#tag\\\":\\\"match:scalar\\\",\\\"payload\\\":\\\"#undefined\\\"},\\\"label\\\":\\\"zcfSeatToSeatHandle\\\"}\",\"slots\":[]}"],"time":1740527497.797417,"monotime":64.621560356} {"type":"syscall-result","crankNum":407,"vatID":"v12","deliveryNum":13,"syscallNum":23,"replay":false,"ksr":["ok",null],"vsr":["ok",null],"time":1740527497.797454,"monotime":64.621596915} {"type":"deliver-result","crankNum":407,"vatID":"v12","deliveryNum":13,"replay":false,"dr":["ok",null,{"meterType":"xs-meter-34","currentHeapCount":392885,"compute":143185,"allocate":46268416,"timestamps":[1740527497.788211,1740527497.788585,1740527497.789082,1740527497.789307,1740527497.789815,1740527497.790001,1740527497.790369,1740527497.790651,1740527497.790798,1740527497.7912,1740527497.791383,1740527497.791439,1740527497.791629,1740527497.791687,1740527497.791946,1740527497.791994,1740527497.7922,1740527497.79224,1740527497.792447,1740527497.792476,1740527497.792649,1740527497.792704,1740527497.792904,1740527497.793317,1740527497.793441,1740527497.793488,1740527497.793621,1740527497.793654,1740527497.793815,1740527497.793846,1740527497.794009,1740527497.794043,1740527497.794202,1740527497.794229,1740527497.794441,1740527497.794554,1740527497.794991,1740527497.795274,1740527497.795742,1740527497.795778,1740527497.796088,1740527497.796216,1740527497.79675,1740527497.796844,1740527497.797045,1740527497.79708,1740527497.797288,1740527497.797317,1740527497.797483,1740527497.797602]}],"time":1740527497.797708,"monotime":64.621851681} {"type":"terminate","vatID":"v12","shouldReject":false,"info":{"body":"#\"payment retrieved\"","slots":[]},"time":1740527497.798019,"monotime":64.622162789} {"type":"console","source":"kernel","level":"log","args":["kernel terminating vat v12 (failure=false)"],"time":1740527497.798286,"monotime":64.622429777} {"type":"crank-finish","crankNum":407,"crankhash":"086f84650ada36d845ee2079ea0dfe6e6e08d6a587f6be46868e75eee0690a6b","activityhash":"ede8ca0d16de82e6eb8748dcfe475d71e908f334bdc7d564867f77384c6d0798","time":1740527497.80501,"monotime":64.629155006} ``` </details> ### Upgrade Considerations This fixes a late-discovered flaw in #10925 and would ideally be cherry-picked into agoric-upgrade-19, but if it doesn't make it in then we'll just be missing the kernel console `level` data until agoric-upgrade-20 (which is still acceptable). Release verification should look for slog entries like the above (type "console", source "kernel", level "log"/"warn"/"error"/etc.).

### Description Cherrypicks the following changes: - #11065 - #11052 Using the following rebase-todo: ``` # PR #11065 Branch fix-cosmos-upgrade-to-agoric-labs-ibc-go-v6-3-1-alpha-agoric-3-11065- label base-fix-cosmos-upgrade-to-agoric-labs-ibc-go-v6-3-1-alpha-agoric-3-11065- pick 52fb6cf build(deps): use new version of ibc-go pick 3dbb1bc chore(golang): `go mod tidy` label pr-11065--fix-cosmos-upgrade-to-agoric-labs-ibc-go-v6-3-1-alpha-agoric-3-11065- reset base-fix-cosmos-upgrade-to-agoric-labs-ibc-go-v6-3-1-alpha-agoric-3-11065- merge -C ee18609 pr-11065--fix-cosmos-upgrade-to-agoric-labs-ibc-go-v6-3-1-alpha-agoric-3-11065- # fix(cosmos): upgrade to `agoric-labs/ibc-go` `v6.3.1-alpha.agoric.3` (#11065) # PR #11052 Branch fix-Properly-synchronize-slog-sender-termination-11052- label base-fix-Properly-synchronize-slog-sender-termination-11052- pick ec3c1a2 chore(SwingSet): Remove unused code and comments pick 9ab1630 fix(SwingSet): Include level in kernel console slog output pick fcfb944 refactor(SwingSet): Simplify makeFinishersKit into addSlogCallbacks pick d8a5947 refactor(SwingSet): Improve addSlogCallbacks parameter/variable names pick f83c01d fix: Properly synchronize slog sender termination pick 318269e chore(telemetry): Use more readable async patterns pick fa1f04a chore(SwingSet): Prefer type Callable over Function pick 117c766 fix(internal): Exempt process.stdout from being closed by makeFsStreamWriter pick 6c6fba4 refactor(internal): Prefer fs.WriteStream close() over stream.Writable end() label pr-11052--fix-Properly-synchronize-slog-sender-termination-11052- reset base-fix-Properly-synchronize-slog-sender-termination-11052- # fix: minted early tracking (#11066) merge -C 42d5764 pr-11052--fix-Properly-synchronize-slog-sender-termination-11052- # fix: Properly synchronize slog sender termination (#11052) ```

gibson042 requested review from mhofman, LuqiPan and mujahidkay February 26, 2025 00:16

gibson042 requested a review from a team as a code owner February 26, 2025 00:16

gibson042 requested a review from siarhei-agoric February 27, 2025 17:23

gibson042 mentioned this pull request Feb 27, 2025

feat(SwingSet): Echo kernel console output to the slog #10925

Merged

mhofman reviewed Feb 28, 2025

View reviewed changes

mhofman added the force:integration Force integration tests to run on PR label Feb 28, 2025

mhofman approved these changes Mar 1, 2025

View reviewed changes

gibson042 added the automerge:rebase Automatically rebase updates, then merge label Mar 1, 2025

gibson042 force-pushed the gibson-10925-followup branch from 80be157 to 93ae92c Compare March 1, 2025 02:26

gibson042 force-pushed the gibson-10925-followup branch from 93ae92c to fe7d415 Compare March 1, 2025 02:28

gibson042 force-pushed the gibson-10925-followup branch from fe7d415 to 45fd037 Compare March 1, 2025 06:03

gibson042 added automerge:rebase Automatically rebase updates, then merge force:integration Force integration tests to run on PR and removed force:integration Force integration tests to run on PR automerge:rebase Automatically rebase updates, then merge labels Mar 1, 2025

gibson042 added 5 commits March 1, 2025 21:20

chore(SwingSet): Remove unused code and comments

ec3c1a2

fix(SwingSet): Include level in kernel console slog output

9ab1630

Ref #10925

refactor(SwingSet): Simplify makeFinishersKit into addSlogCallbacks

fcfb944

refactor(SwingSet): Improve addSlogCallbacks parameter/variable names

d8a5947

fix: Properly synchronize slog sender termination

f83c01d

gibson042 added 4 commits March 1, 2025 21:20

chore(telemetry): Use more readable async patterns

318269e

chore(SwingSet): Prefer type Callable over Function

fa1f04a

fix(internal): Exempt process.stdout from being closed by makeFsStrea…

117c766

…mWriter

refactor(internal): Prefer fs.WriteStream close() over stream.Writabl…

6c6fba4

…e end()

gibson042 force-pushed the gibson-10925-followup branch from 45fd037 to 6c6fba4 Compare March 1, 2025 21:20

mergify bot merged commit 42d5764 into master Mar 1, 2025
84 checks passed

mergify bot deleted the gibson-10925-followup branch March 1, 2025 22:05

mujahidkay mentioned this pull request Mar 3, 2025

chore: u19 cherrypicks #11071

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

fix: Properly synchronize slog sender termination #11052

fix: Properly synchronize slog sender termination #11052

gibson042 commented Feb 26, 2025

cloudflare-workers-and-pages bot commented Feb 26, 2025 •

edited

Loading

mhofman left a comment

mhofman Feb 28, 2025

gibson042 Feb 28, 2025

mhofman Feb 28, 2025

mhofman Feb 28, 2025

gibson042 commented Feb 28, 2025

mergify bot commented Mar 1, 2025

mergify bot commented Mar 1, 2025

gibson042 commented Mar 1, 2025

mergify bot commented Mar 1, 2025

mergify bot commented Mar 1, 2025

mergify bot commented Mar 1, 2025

fix: Properly synchronize slog sender termination #11052

fix: Properly synchronize slog sender termination #11052

Conversation

gibson042 commented Feb 26, 2025

Description

Security Considerations

Scaling Considerations

Documentation Considerations

Testing Considerations

Upgrade Considerations

cloudflare-workers-and-pages bot commented Feb 26, 2025 • edited Loading

Deploying agoric-sdk with Cloudflare Pages

mhofman left a comment

Choose a reason for hiding this comment

mhofman Feb 28, 2025

Choose a reason for hiding this comment

gibson042 Feb 28, 2025

Choose a reason for hiding this comment

mhofman Feb 28, 2025

Choose a reason for hiding this comment

mhofman Feb 28, 2025

Choose a reason for hiding this comment

gibson042 commented Feb 28, 2025

mergify bot commented Mar 1, 2025

mergify bot commented Mar 1, 2025

gibson042 commented Mar 1, 2025

mergify bot commented Mar 1, 2025

❌ This pull request head commit has not been previously disembarked from queue.

mergify bot commented Mar 1, 2025

mergify bot commented Mar 1, 2025

cloudflare-workers-and-pages bot commented Feb 26, 2025 •

edited

Loading