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

stack traces from xs-worker vats lack filenames, line numbers #2578

Closed
3 tasks done
dckc opened this issue Mar 4, 2021 · 15 comments · Fixed by #3776
Closed
3 tasks done

stack traces from xs-worker vats lack filenames, line numbers #2578

dckc opened this issue Mar 4, 2021 · 15 comments · Fixed by #3776
Assignees
Labels
bug Something isn't working xsnap the XS execution tool

Comments

@dckc
Copy link
Member

dckc commented Mar 4, 2021

What is the Problem Being Solved?

The moddable SDK supports 2 build modes, debug and production. xsnap uses production by default with an option for debug, which means we don't, by default, get things like line numbers in stack traces.

Description of the Design

  • yes, we want debug style stack traces
  • yes, we want $(CC) to optimize for execution speed
  • no, we don't want TCP connections to the debugger on exceptions
  • no, we don't want every exception to generate a printf

Security Considerations

The TCP connection to the debugger is certainly excess authority.

Test Plan

???

cc @phoddie @dtribble @erights @warner @kriskowal

@dckc dckc added the enhancement New feature or request label Mar 4, 2021
@phoddie
Copy link

phoddie commented Mar 4, 2021

we don't want TCP connections to the debugger on exceptions

The connection to the debugger is established on launch of the VM, not on an exception. If you don't want to use the debugger, disable it in xssnap.

The TCP connection to the debugger is certainly excess authority

How?

@dckc dckc added this to the infrastructure-phase milestone Mar 29, 2021
@dckc
Copy link
Member Author

dckc commented Mar 29, 2021

@warner @dtribble how important is this for infrastructure-phase? I conservatively added it to this milestone, but I think it's actually not critical.

@dckc
Copy link
Member Author

dckc commented May 2, 2021

Instrumentation would be handy but -DmxInstrument=1 seems to cause the compute meter to be 0 all the time.

@phoddie
Copy link

phoddie commented May 2, 2021

FWIW - instrumentation is a host feature, not strictly an xs feature. That means it needs to be implemented in the host for xsnap to be available there.

I just did a quick scan of the XS sources and didn't see any intersection between mxMetering and mxInstrument. Each of them does add/remove fields to sxMachine in xsAll.h. If there wasn't a full build after changing the setting, that might explain the result reported.

@dckc
Copy link
Member Author

dckc commented May 3, 2021

... If there wasn't a full build after changing the setting, that might explain the result reported.

ah. good point. I set mxInstrument in the makefile, which wouldn't automatically cause a rebuild.

@dckc
Copy link
Member Author

dckc commented May 6, 2021

In #3039 (comment) @warner writes:

Our current theory is some sort of [xsnap / XS] memory allocation bug, maybe during GC.

I was going to suggest getting a bytecode trace using mxTrace, but it would be huge and the relevant clues tend to be in the last page or so of it.

That reminded me of the circular buffer idea from logging discussion. Perhaps we should...

  • keep mxTrace turned on but just keep the last ~500 lines in a circular buffer?

I wonder how to access it externally and how that would interact with plans for a seccomp jail #2386 . Perhaps...

  • the circular buffer could be in a memmap memory region and other processes could look at the memmap backing file?

@Chris-Hibbert
Copy link
Contributor

The stacks I'm seeing under xs-worker look like this:

RemoteTypeError(error:liveSlots:v5#70003)#4 ERROR_NOTE: Rejection from: (Error#5) : 51 . 0
RemoteTypeError(error:liveSlots:v5#70003)#4 ERROR_NOTE: Rejection from: (Error#6) : 46 . 2
RemoteTypeError(error:liveSlots:v5#70003)#4 ERROR_NOTE: Sent as error:liveSlots:v4#70002
Error#5: Event: 48.3
Error: Event: 48.3
 at construct ()
 at Error ()
 at trackTurns ()
 at handle ()
 at ()
 at validate ()
 at ()
 at ()

I've gotten used to stack traces that show much more context. Here's an example (notice full path file names and line numbers):

RemoteError(error:liveSlots:v5#70001)#6 ERROR_NOTE: Rejection from: (Error#7) : 20 . 0
RemoteError(error:liveSlots:v5#70001)#6 ERROR_NOTE: Rejection from: (Error#8) : 2 . 1
RemoteError(error:liveSlots:v5#70001)#6 ERROR_NOTE: Sent as error:liveSlots:v6#70001
Nested 2 errors under RemoteError(error:liveSlots:v5#70001)#6
  Error#7: Event: 18.2
    at trackTurns (/Users/chrishibbert/agoric-sdk/packages/eventual-send/src/track-turns.js:48:24)
    at handle (/Users/chrishibbert/agoric-sdk/packages/eventual-send/src/index.js:420:27)
    at Function.applyMethod (/Users/chrishibbert/agoric-sdk/packages/eventual-send/src/index.js:336:14)
    at Proxy.eval (vat-v6/.../packages/eventual-send/src/E.js:38:49)
    at startRegistrar (vat-v6/.../packages/treasury/test/swingsetTests/governance/bootstrap.js:61:23)
    at Alleged: root.eval [as bootstrap] (vat-v6/.../packages/treasury/test/swingsetTests/governance/bootstrap.js:160:57)

@dckc dckc changed the title XS / xsnap build mode: debug? production? mix? stack traces from xs-worker vats lack filenames, line numbers Aug 18, 2021
@dckc dckc added bug Something isn't working and removed enhancement New feature or request labels Aug 18, 2021
@dckc
Copy link
Member Author

dckc commented Aug 19, 2021

eval interferes with source positions in XS

XS seems to provide file and line numbers normally, but not in eval, which we use in importBundle / Compartment shim

This code:

const e = () => { throw Error('lose'); };
const d = () => e();
const c = () => d();
const b = () => c();
const a = () => b();

try {
  a();
} catch (err) {
  print(err.stack);
}

when fed to xst gives:

Error: lose
 at e (/home/connolly/projects/moddable/examples/js/trace/debug.js:1)
 at d (/home/connolly/projects/moddable/examples/js/trace/debug.js:2)
 at c (/home/connolly/projects/moddable/examples/js/trace/debug.js:3)
 at b (/home/connolly/projects/moddable/examples/js/trace/debug.js:4)
 at a (/home/connolly/projects/moddable/examples/js/trace/debug.js:5)
 at (/home/connolly/projects/moddable/examples/js/trace/debug.js:8)

but wrapped in eval...

const code = `
const e = () => { throw Error('lose'); };
const d = () => e();
const c = () => d();
const b = () => c();
const a = () => b();
a
`;

const a = eval(code);

try {
  a();
} catch (err) {
  print(err.stack);
}

gives

Error: lose
 at e ()
 at d ()
 at c ()
 at b ()
 at a ()
 at (/home/connolly/projects/moddable/examples/js/trace/debug.js:13)

@erights
Copy link
Member

erights commented Aug 19, 2021

What about compartment.evaluate?

@kriskowal
Copy link
Member

The challenge for XS for either eval or compartment.evaluate is that there is no vessel to carry the file name. Line numbers are simpler, but meaningless without that file name. Browsers have dealt with this for aeons by looking at a sourceURL comment if they need to present a name. We prepare such comments in our bundles.

If that is not palatable, we could find another vessel for the file name. compartment.evaluate could take an options bag argument. The same treatment on eval would be weird but I assume possible.

@erights
Copy link
Member

erights commented Aug 19, 2021

Attn @phoddie , have we talked about this much?

@dckc
Copy link
Member Author

dckc commented Aug 19, 2021

What about compartment.evaluate?

Native compartments seem to lose even more info.

const code = `
const e = () => { throw Error('lose'); };
const d = () => e();
const c = () => d();
const b = () => c();
const a = () => b();

let result;
try {
  a();
} catch (err) {
  result = err.stack;
}
`;

const c = new Compartment();
const r = c.evaluate(code);
print(r);

gives

Error: lose
 at e ()
 at ()
 at evaluate ()
 at (/home/connolly/projects/moddable/examples/js/trace/debug2.js:17)

const code = `
const e = () => { throw Error('lose'); };
const d = () => e();
const c = () => d();
const b = () => c();
const a = () => b();
a
`;

const c = new Compartment();
const a = c.evaluate(code);

try {
  a();
} catch (err) {
  print(err.stack);
}

gives

Error: lose
 at e ()
 at (/home/connolly/projects/moddable/examples/js/trace/debug.js:14)

@phoddie
Copy link

phoddie commented Aug 19, 2021

@kriskowal describes the problem well. XS ignores the sourceURL. When we looked at doing that, it was ugly. Maybe we should look again.

I did expect eval to give line numbers. It turns out it does when xsbug is connected:

$ xst ~/test.js 
Error: lose
 at e (#0:2)
 at d (#0:3)
 at c (#0:4)
 at b (#0:5)
 at a (#0:6)
 at (/~/test.js:13)

The file name is given as #0 meaning this is the first eval of the session. It seems likely we could show line numbers even when xsbug isn't connected, but I didn't look.

@dckc
Copy link
Member Author

dckc commented Aug 19, 2021

Before we get too focused on eval, let's keep in mind that the overall goal is loading modules into a Compartment; preferably a native XS compartment.

Getting there involves addressing most / all of the issues below, so an expedient update to eval might be in order.

@phoddie
Copy link

phoddie commented Aug 19, 2021

let's keep in mind that the overall goal is loading modules into a Compartment; preferably a native XS compartment.

Agreed. That topic is already queued up for a call next week. Maybe best to wait for that to get in deeper than these (helpful!) notes.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Something isn't working xsnap the XS execution tool
Projects
None yet
Development

Successfully merging a pull request may close this issue.

5 participants