getappmap / appmap-agent-js

This project is deprecated. Please use https://github.com/getappmap/appmap-node/ to record Node.js applications.
Other
28 stars 8 forks source link

Generator return and throw methods mess up the callstack #203

Closed lachrist closed 1 year ago

lachrist commented 1 year ago

Currently, when running the agent on scanner, there is a good old begin/end event mismatch. These errors should be taken seriously because they indicate that an important assumption on the callstack was broken.

After inspection the errors I found out that the error is located in the technique that babel uses to implement async functions with generators:

The faulty helper:

// appmap-js/packages/scanner/built/src/ruleChecker.js:2:44
var __awaiter = (this && this.__awaiter) || function (thisArg, _arguments, P, generator) {
    function adopt(value) { return value instanceof P ? value : new P(function (resolve) { resolve(value); }); }
    return new (P || (P = Promise))(function (resolve, reject) {
        function fulfilled(value) { try { step(generator.next(value)); } catch (e) { reject(e); } }
        function rejected(value) { try { step(generator["throw"](value)); } catch (e) { reject(e); } }
        function step(result) { result.done ? resolve(result.value) : adopt(result.value).then(fulfilled, rejected); }
        step((generator = generator.apply(thisArg, _arguments || [])).next());
    });
};

The faulty generator:

// appmap-js/packages/scanner/built/src/rules/rpcWithoutCircuitBreaker.js:15:0
// The circuit breaker will be found in a descendant of the httpClientRequest.
function* descendants(httpClientRequest) {
    for (const candidate of new models_1.EventNavigator(httpClientRequest).descendants()) {
        yield candidate.event;
    }
}

Relevant part of the trace:

  {
    "type": "event",
    "session": "ips0tq4o",
    "site": "begin",
    "tab": 33,
    "time": 631.034,
    "group": 0,
    "payload": {
      "type": "apply",
      "function": "lhZRPLfeLWibCgzO9pPkxy0TbfmAG3v3YmdhLYhKYZE=|file:///Users/soft/Desktop/workspace/appmap-js/packages/scanner/built/src/ruleChecker.js:2:44",
      "this": {
        "type": "undefined",
        "print": "undefined"
      },
      "arguments": [
        {
          "type": "object",
          "print": "object",
          "index": 25,
          "constructor": "object",
          "specific": null
        },
        {
          "type": "undefined",
          "print": "undefined"
        },
        {
          "type": "undefined",
          "print": "undefined"
        },
        {
          "type": "function",
          "print": "function",
          "index": 34,
          "constructor": "function",
          "specific": null
        }
      ]
    }
  },
  {
    "type": "event",
    "session": "ips0tq4o",
    "site": "begin",
    "tab": 34,
    "time": 631.561,
    "group": 0,
    "payload": {
      "type": "apply",
      "function": "slgAnUX5j0ytZO9l7oSKMunVOShaRC42IkmEldNEsbE=|file:///Users/soft/Desktop/workspace/appmap-js/packages/scanner/built/src/rules/rpcWithoutCircuitBreaker.js:15:0",
      "this": {
        "type": "undefined",
        "print": "undefined"
      },
      "arguments": [
        {
          "type": "object",
          "print": "object",
          "index": 35,
          "constructor": "object",
          "specific": null
        }
      ]
    }
  },
  {
    "type": "event",
    "session": "ips0tq4o",
    "site": "before",
    "tab": 35,
    "time": 631.967,
    "group": 0,
    "payload": {
      "type": "yield",
      "iterator": {
        "type": "boolean",
        "print": "false"
      }
    }
  },
  {
    "type": "event",
    "session": "ips0tq4o",
    "site": "after",
    "tab": 35,
    "time": 632.091,
    "group": 0,
    "payload": {
      "type": "resume",
      "argument": {
        "type": "undefined",
        "print": "undefined"
      }
    }
  },
  {
    "type": "event",
    "session": "ips0tq4o",
    "site": "before",
    "tab": 36,
    "time": 632.147,
    "group": 0,
    "payload": {
      "type": "yield",
      "iterator": {
        "type": "boolean",
        "print": "false"
      }
    }
  },
  {
    "type": "event",
    "session": "ips0tq4o",
    "site": "after",
    "tab": 36,
    "time": 632.193,
    "group": 0,
    "payload": {
      "type": "resume",
      "argument": {
        "type": "undefined",
        "print": "undefined"
      }
    }
  },
  {
    "type": "event",
    "session": "ips0tq4o",
    "site": "before",
    "tab": 37,
    "time": 632.238,
    "group": 0,
    "payload": {
      "type": "yield",
      "iterator": {
        "type": "boolean",
        "print": "false"
      }
    }
  },
  {
    "type": "event",
    "session": "ips0tq4o",
    "site": "after",
    "tab": 37,
    "time": 632.282,
    "group": 0,
    "payload": {
      "type": "resume",
      "argument": {
        "type": "undefined",
        "print": "undefined"
      }
    }
  },
  {
    "type": "event",
    "session": "ips0tq4o",
    "site": "before",
    "tab": 38,
    "time": 632.327,
    "group": 0,
    "payload": {
      "type": "yield",
      "iterator": {
        "type": "boolean",
        "print": "false"
      }
    }
  },
  {
    "type": "event",
    "session": "ips0tq4o",
    "site": "after",
    "tab": 38,
    "time": 632.369,
    "group": 0,
    "payload": {
      "type": "resume",
      "argument": {
        "type": "undefined",
        "print": "undefined"
      }
    }
  },
  {
    "type": "event",
    "session": "ips0tq4o",
    "site": "before",
    "tab": 39,
    "time": 632.414,
    "group": 0,
    "payload": {
      "type": "yield",
      "iterator": {
        "type": "boolean",
        "print": "false"
      }
    }
  },
  {
    "type": "event",
    "session": "ips0tq4o",
    "site": "after",
    "tab": 39,
    "time": 632.456,
    "group": 0,
    "payload": {
      "type": "resume",
      "argument": {
        "type": "undefined",
        "print": "undefined"
      }
    }
  },
  {
    "type": "event",
    "session": "ips0tq4o",
    "site": "before",
    "tab": 40,
    "time": 632.501,
    "group": 0,
    "payload": {
      "type": "yield",
      "iterator": {
        "type": "boolean",
        "print": "false"
      }
    }
  },
  {
    "type": "event",
    "session": "ips0tq4o",
    "site": "end",
    "tab": 34,
    "time": 632.547,
    "group": 0,
    "payload": {
      "type": "return",
      "function": "slgAnUX5j0ytZO9l7oSKMunVOShaRC42IkmEldNEsbE=|file:///Users/soft/Desktop/workspace/appmap-js/packages/scanner/built/src/rules/rpcWithoutCircuitBreaker.js:15:0",
      "result": {
        "type": "undefined",
        "print": "undefined"
      }
    }
  },
  {
    "type": "event",
    "session": "ips0tq4o",
    "site": "end",
    "tab": 33,
    "time": 632.671,
    "group": 0,
    "payload": {
      "type": "return",
      "function": "lhZRPLfeLWibCgzO9pPkxy0TbfmAG3v3YmdhLYhKYZE=|file:///Users/soft/Desktop/workspace/appmap-js/packages/scanner/built/src/ruleChecker.js:2:44",
      "result": {
        "type": "object",
        "print": "object",
        "index": 36,
        "constructor": "object",
        "specific": null
      }
    }
  },

So the problem is that the event yield/40 is followed by return/34 and resume/40 is misssing. This messes up the callstack. This can happens when using Generator.prototype.return() or using Generator.prototype.return().

function* G () {
  try {
    for (const x of [1,2,3]) {
      console.log("resume", yield (console.log("yield", x), x));
    }
  } finally {
    console.log("finally");
  }
}

const g = G();
console.log("next", g.next());
console.log("return", g.return(123));
yield 1
next { value: 1, done: false }
finally
return { value: 123, done: true }

We should take these method into account to solve this issue.

brikelly commented 1 year ago

Hi @lachrist , is this issue in progress? If so, I will mark it as such on the board.

lachrist commented 1 year ago

Yes it is