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

fix: Properly synchronize slog sender termination #11052

Open
wants to merge 10 commits into
base: master
Choose a base branch
from

Conversation

gibson042
Copy link
Member

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:

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.).

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

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

Deploying agoric-sdk with  Cloudflare Pages  Cloudflare Pages

Latest commit: 80be157
Status: ✅  Deploy successful!
Preview URL: https://dfd80380.agoric-sdk.pages.dev
Branch Preview URL: https://gibson-10925-followup.agoric-sdk.pages.dev

View logs

Copy link
Member

@mhofman mhofman left a comment

Choose a reason for hiding this comment

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

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

* @returns {F} the wrapped method
*/
wrap(method, impl) {
const wrappedMethods = /** @type {typeof methods} */ (
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 Methods instead of typeof methods?

Copy link
Member Author

Choose a reason for hiding this comment

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

To allow for the increased specificity.

Comment on lines +89 to +92
const waitForDrain = await written;
if (waitForDrain) {
await new Promise(resolve => stream.once('drain', resolve));
}
Copy link
Member

Choose a reason for hiding this comment

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

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

Comment on lines 110 to 111
// @ts-expect-error calling a possibly missing method
stream.close?.();
if (stream.end) {
await new Promise(resolve => stream.end(() => resolve(undefined)));
}
Copy link
Member

Choose a reason for hiding this comment

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

close is only present on the fs WriteStream, whereas end also exists on the stdout stream, which we don't want to end. Is there any reason to change this one?

Copy link
Member Author

@gibson042 gibson042 Feb 28, 2025

Choose a reason for hiding this comment

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

I tried that in an early iteration and close wasn't final enough, though I don't remember the details. I'm updating to exempt process.stdout from this handling.

@mhofman mhofman added the force:integration Force integration tests to run on PR label Feb 28, 2025
@gibson042
Copy link
Member Author

@mhofman back to you

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
force:integration Force integration tests to run on PR
Projects
None yet
Development

Successfully merging this pull request may close these issues.

2 participants