0 hits reported incorrectly

[Andarist]

I'm debugging this recording:
https://app.replay.io/recording/21594023-f9ae-4787-912c-c391a68304aa

and I've noticed that sometimes I'm not able to step into certain functions. Take a look at this loom:
https://www.loom.com/share/9628264e684a4d0eb66e5176296972e5

Notice how I've wanted to step into reportImplicitAny but I was taken out of this frame, to the point after the call to the reportImplicitAny's caller.

One additional thing I've noticed here is that 0 hits are reported on the line containing that reportImplicitAny

This is clearly incorrect as I was paused at this line of code.

[Andarist]

On the same recording I can also observe this weird situation:

Notice how node.dotDotDotToken is undefined and the condition for the if statement is this:

node.dotDotDotToken && !ts.isBindingPattern(node.name) && !isTypeAssignableTo(getReducedType(getTypeOfSymbol(node.symbol)), anyReadonlyArrayType)

There is no way this has been really evaluated as a truth value and yet I've entered this conditional block. I'm also pretty sure that ts.Diagnostics.A_rest_parameter_must_be_of_an_array_type has not been raised here as the source file that is being type-checked doesn't have any spread/rest in it and tsc exits without any errors.

[jasonLaster]

@Andarist left a comment in the replay that the outer IF is returning falsey for all 24 branches. How did you get to 60024?

[Andarist]

@jasonLaster this is how: https://app.replay.io/recording/cf835ced-5001-469b-8111-90c4522bb64d . Just go to the very last hit at 60022 and click "Step in" twice or thrice

[kannanvijayan]

One additional thing I've noticed here is that 0 hits are reported on the line containing that reportImplicitAny

The bit of the conditional on line 60022 that never hits is the ts.getObjectFlags(type) & 131072 expression. So I'm with @jasonLaster : the bug is the fact that it's stopping at the call, not that it's not stepping into the call.

Small-stepping through the debug also demonstrates this: the debugger enters the getObjectFlags, then the next breakpoint (the within the conditional) appears to be at the call to reportImplicitAny, and the next step returns you to the caller of the function.

That last breakpoint before returning to the caller maybe corresponds to a "IFNE" (jump if false) bytecode instruction to skip the loop conditional. There would need to be one after the "AND 131072" operation to implement short-circuiting.

Then I thought about it more and figured that the last instruction before returning to the might actually be a "RET" instruction embedded inside the conditional code, since a failure of any of the terms in the conditional leads to the end of the function.

Either way, what I think might be happening is this: the IFNE/RET instruction we land at right before returning is not classified as part of the conditional. If we land on it, we map that to a minified code location that corresponds to "after the conditional", which presents as "before the call". The inner "if" is not mapped because a smart enough bytecode compiler converts it into a single conditional with the inner expression being &&-ed to the outer expression, and so at execution time it looks like one big conditional.

I'm hoping to maybe replicate this in a reduced test case with conditionals.

[Andarist]

I'm afraid that this might not be the correct diagnosis here. This whole debugging session has started from the fact that TS was not able to infer a parameter type and raised an implicit any error.

index.ts:71:16 - error TS7006: Parameter '_ctx' implicitly has an 'any' type.

So it makes sense that reportImplicitAny would have been called in here, but according to Replay it wasn't:

Of course, this doesn't yet prove anything as the error could have been somehow raised by any other function in tsc. However, if I add a log within reportImplicitAny and just run the whole thing with regular node then the call is being "reported":

And the reported call stack looks exactly like the one on this loom: https://www.loom.com/share/9628264e684a4d0eb66e5176296972e5

Error
    at reportImplicitAny (/Users/mateuszburzynski/Desktop/xstate-types-debug/node_modules/typescript/lib/tsc.js:53821:25)
    at widenTypeForVariableLikeDeclaration (/Users/mateuszburzynski/Desktop/xstate-types-debug/node_modules/typescript/lib/tsc.js:44249:21)
    at getWidenedTypeForVariableLikeDeclaration (/Users/mateuszburzynski/Desktop/xstate-types-debug/node_modules/typescript/lib/tsc.js:44226:20)
    at assignParameterType (/Users/mateuszburzynski/Desktop/xstate-types-debug/node_modules/typescript/lib/tsc.js:61873:38)
    at assignNonContextualParameterTypes (/Users/mateuszburzynski/Desktop/xstate-types-debug/node_modules/typescript/lib/tsc.js:61866:17)
    at contextuallyCheckFunctionExpressionOrObjectLiteralMethod (/Users/mateuszburzynski/Desktop/xstate-types-debug/node_modules/typescript/lib/tsc.js:62247:29)
    at checkFunctionExpressionOrObjectLiteralMethod (/Users/mateuszburzynski/Desktop/xstate-types-debug/node_modules/typescript/lib/tsc.js:62223:13)
    at checkExpressionWorker (/Users/mateuszburzynski/Desktop/xstate-types-debug/node_modules/typescript/lib/tsc.js:63758:28)
    at checkExpression (/Users/mateuszburzynski/Desktop/xstate-types-debug/node_modules/typescript/lib/tsc.js:63662:38)
    at checkExpressionForMutableLocation (/Users/mateuszburzynski/Desktop/xstate-types-debug/node_modules/typescript/lib/tsc.js:63463:24)

[kannanvijayan]

Thanks for the detailed info! It's interesting that the stack trace you have has reportImplicitAny as a direct child of widenTypeForVariableLikeDeclaration. What happened to the frame for reportErrorsFromWidening? I noted that there did exist a direct call to reportImplicitAny from widenTypeForVariableLikeDeclaration, but it shows as hitting zero times.

Thanks, I'm convinced by your argument that there's more going on than just a mapping issue here.

I looked at reportImplicitAny and there were zero hits to it anywhere in the recording. That suggests a more fundamental replay execution mismatch issue that's not being picked up.

[Andarist]

Thanks, I'm convinced by your argument that there's more going on than just a mapping issue here.

Actually - you might be way more correct than me. In a rush, I've assumed that those call stacks were the same. They are slightly different though! Very close to each other but different.

It turns out that reportImplicitAny can get called from this widenTypeForVariableLikeDeclaration at least twice (once directly and once indirectly by reportErrorsFromWidening):

And in here, we are actually hitting the direct call and not that indirect one that is misbehaving.

[kannanvijayan]

Yeah, I saw that before I posted. However, if you hover of the line-numbers on that line it's reporting the line as having 0 hits. Either way, there is a codepath that's not getting picked up.

This is a wild guess but maybe some types of frame entries that are not getting picked up by the replay-process instrumentation.

[kannanvijayan]

@Andarist would it be possible to get the materials needed to repro this locally?

[jasonLaster]

hmm... I wonder if part of this is that there are multiple breakable locations on that line. You should both enable column breakpoints via app.features.columnBreakpoints this should help you see other hits on that line.

[Andarist]

@kannanvijayan sorry for the late reply but I've finally extracted the repro case for this. You can find it here: https://github.com/Andarist/replay-stopped-at-0-hits-line/tree/323f80789d6a20691c52b05b1ee33a3b065a1056 . I think the info in the README and in the Loom recording is enough but if anything is still unclear - just let me know.

[kannanvijayan]

@Andarist thanks that's fantastic! I've been hacking away at internal analysis tooling to lets us inspect our logs better this last week or so. I'm actually heading on vacation for the next week, but others will be looking at it in the meantime and I'll be getting back to it as soon as I'm back.

Appreciate the effort in getting a repro testcase. That's very well prepared!

[Andarist]

I have one additional recording suffering from a very similar problem here:
https://app.replay.io/recording/3a809b96-483f-4749-964d-ded8a45b4eb3

I've also noticed something very similar today while stepping out of functions and I think this all might be the same issue.

I think what happens here (at least on this new replay and while stepping out of a function) is that we always get to the last statement of a particular function. But that statement might be from a random location really if we have if statements etc.

Consider this:

function foo(a) {
  if (a) {
    callSmth()
  }
}

If I make a step on the if (a) line then I'm just brought to the callSmth() as this is the last statement here

[jasonLaster]

cc @bhackett1024

[hbenl]

It seems that "0 hits" may actually be correct and we're sometimes getting wrong locations for the stack frames: in the initial recording the debugger should never step to the reportImplicitAny() call in reportErrorsFromWidening() because it's in the body of an if statement with a condition that is always falsy.
I've created RecordReplay/backend#3288 for looking into the frame locations.

[Andarist]

This would probably highly relate to my observation from the previous post (just making sure that you have not missed it by accident). Wrong frame locations could explain both problems.

[jasonLaster]

@hbenl removed from our current sprint since it is blocked on RecordReplay/backend#3288

[Andarist]

I've been hit by this again and got quite confused. It looks like I'm being paused at this line:

but that is just because this is the very last statement of this function. In fact - none of those cases were matched and thus I'm like "at the very end" of this function now but the UI is obviously presenting a confusing information

[gideonred]

This ticket has been moved to RUN-307