Merge pull request #323 from Distributive-Network/Xmader/feat/WtfPM

Detect hanging timers with the WTFPythonMonkey tool & Fix bugs found by WTFPythonMonkey

Author: philippedistributive

include/PyEventLoop.hh

@@ -12,6 +12,7 @@
 #define PythonMonkey_PyEventLoop_
 
 #include <Python.h>
+#include <jsapi.h>
 #include <vector>
 #include <utility>
 #include <atomic>
@@ -35,7 +36,7 @@ public:
   public:
     explicit AsyncHandle(PyObject *handle) : _handle(handle) {};
     AsyncHandle(const AsyncHandle &old) = delete; // forbid copy-initialization
-    AsyncHandle(AsyncHandle &&old) : _handle(std::exchange(old._handle, nullptr)), _refed(old._refed.exchange(false)) {}; // clear the moved-from object
+    AsyncHandle(AsyncHandle &&old) : _handle(std::exchange(old._handle, nullptr)), _refed(old._refed.exchange(false)), _debugInfo(std::exchange(old._debugInfo, nullptr)) {}; // clear the moved-from object
     ~AsyncHandle() {
       if (Py_IsInitialized()) { // the Python runtime has already been finalized when `_timeoutIdMap` is cleared at exit
         Py_XDECREF(_handle);
@@ -126,9 +127,27 @@ public:
         PyEventLoop::_locker->decCounter();
       }
     }
+
+    /**
+     * @brief Set the debug info object for WTFPythonMonkey tool
+     */
+    inline void setDebugInfo(PyObject *obj) {
+      _debugInfo = obj;
+    }
+    inline PyObject *getDebugInfo() {
+      return _debugInfo;
+    }
+
+    /**
+     * @brief Get an iterator for the `AsyncHandle`s of all timers
+     */
+    static inline auto &getAllTimers() {
+      return _timeoutIdMap;
+    }
   protected:
     PyObject *_handle;
     std::atomic_bool _refed = false;
+    PyObject *_debugInfo = nullptr;
   };
 
   /**

python/pythonmonkey/builtin_modules/internal-binding.d.ts

@@ -32,6 +32,8 @@ declare function internalBinding(namespace: "utils"): {
   getProxyDetails<T extends object>(proxy: T): undefined | [target: T, handler: ProxyHandler<T>];
 };
 
+declare type TimerDebugInfo = object;
+
 declare function internalBinding(namespace: "timers"): {
   /**
    * internal binding helper for the `setTimeout`/`setInterval` global functions
@@ -41,7 +43,7 @@ declare function internalBinding(namespace: "timers"): {
    * @param repeat The call is to `setInterval` if true
    * @return timeoutId
    */
-  enqueueWithDelay(handler: Function, delaySeconds: number, repeat: boolean): number;
+  enqueueWithDelay(handler: Function, delaySeconds: number, repeat: boolean, debugInfo?: TimerDebugInfo): number;
 
   /**
    * internal binding helper for the `clearTimeout` global function
@@ -62,6 +64,16 @@ declare function internalBinding(namespace: "timers"): {
    * internal binding helper for unref'ing the timer
    */
   timerRemoveRef(timeoutId: number): void;
+
+  /**
+   * Retrieve debug info inside the timer for the WTFPythonMonkey tool
+   */
+  getDebugInfo(timeoutId: number): TimerDebugInfo;
+
+  /**
+   * Retrieve the debug info for all timers that are still ref'ed
+   */
+  getAllRefedTimersDebugInfo(): TimerDebugInfo[];
 };
 
 export = internalBinding;

python/pythonmonkey/builtin_modules/timers.js

@@ -96,7 +96,7 @@ class Timeout
 }
 
 /**
- * Normalize the arguments to `setTimeout` or `setInterval`
+ * Normalize the arguments to `setTimeout`,`setImmediate` or `setInterval`
  * @param {Function | string} handler
  * @param {number} delayMs timeout milliseconds
  * @param {any[]} additionalArgs additional arguments to be passed to the `handler`
@@ -123,7 +123,19 @@ function _normalizeTimerArgs(handler, delayMs, additionalArgs)
     delayMs = 0; // as spec-ed
   const delaySeconds = delayMs / 1000; // convert ms to s
 
-  return { boundHandler, delaySeconds };
+  // Populate debug information for the WTFPythonMonkey tool
+  const stacks = new Error().stack.split('\n');
+  const timerType = stacks[1]?.match(/^set(Timeout|Immediate|Interval)/)?.[0]; // `setTimeout@...`/`setImmediate@...`/`setInterval@...` is on the second line of stack trace
+  const debugInfo = {
+    type: timerType, // "setTimeout", "setImmediate", or "setInterval"
+    fn: handler,
+    args: additionalArgs,
+    startTime: new Date(),
+    delaySeconds,
+    stack: stacks.slice(2).join('\n'), // remove the first line `_normalizeTimerArgs@...` and the second line `setTimeout/setImmediate/setInterval@...`
+  };
+
+  return { boundHandler, delaySeconds, debugInfo };
 }
 
 /**
@@ -137,8 +149,8 @@ function _normalizeTimerArgs(handler, delayMs, additionalArgs)
  */
 function setTimeout(handler, delayMs = 0, ...args) 
 {
-  const { boundHandler, delaySeconds } = _normalizeTimerArgs(handler, delayMs, args);
-  return new Timeout(enqueueWithDelay(boundHandler, delaySeconds, false));
+  const { boundHandler, delaySeconds, debugInfo } = _normalizeTimerArgs(handler, delayMs, args);
+  return new Timeout(enqueueWithDelay(boundHandler, delaySeconds, false, debugInfo));
 }
 
 /**
@@ -157,6 +169,29 @@ function clearTimeout(timeoutId)
   return cancelByTimeoutId(Number(timeoutId));
 }
 
+/**
+ * Implement the `setImmediate` global function  
+ * **NON-STANDARD**, for Node.js compatibility only.
+ * @see https://developer.mozilla.org/en-US/docs/Web/API/Window/setImmediate and
+ * @see https://nodejs.org/en/learn/asynchronous-work/understanding-setimmediate
+ * @param {Function | string} handler
+ * @param {any[]} args additional arguments to be passed to the `handler`
+ */
+function setImmediate(handler, ...args)
+{
+  // setImmediate is equal to setTimeout with a 0ms delay
+  const { boundHandler, debugInfo } = _normalizeTimerArgs(handler, 0, args);
+  return new Timeout(enqueueWithDelay(boundHandler, 0, false, debugInfo));
+}
+
+/**
+ * Implement the `clearImmediate` global function  
+ * **NON-STANDARD**, for Node.js compatibility only.
+ * @alias to `clearTimeout`
+ * @see https://developer.mozilla.org/en-US/docs/Web/API/Window/clearImmediate
+ */
+const clearImmediate = clearTimeout;
+
 /**
  * Implement the `setInterval` global function
  * @see https://developer.mozilla.org/en-US/docs/Web/API/setInterval and
@@ -168,8 +203,8 @@ function clearTimeout(timeoutId)
  */
 function setInterval(handler, delayMs = 0, ...args) 
 {
-  const { boundHandler, delaySeconds } = _normalizeTimerArgs(handler, delayMs, args);
-  return new Timeout(enqueueWithDelay(boundHandler, delaySeconds, true));
+  const { boundHandler, delaySeconds, debugInfo } = _normalizeTimerArgs(handler, delayMs, args);
+  return new Timeout(enqueueWithDelay(boundHandler, delaySeconds, true, debugInfo));
 }
 
 /**
@@ -181,19 +216,27 @@ const clearInterval = clearTimeout;
 
 // expose the `Timeout` class
 setTimeout.Timeout = Timeout;
+setImmediate.Timeout = Timeout;
 setInterval.Timeout = Timeout;
 
 if (!globalThis.setTimeout)
   globalThis.setTimeout = setTimeout;
 if (!globalThis.clearTimeout)
   globalThis.clearTimeout = clearTimeout;
 
+if (!globalThis.setImmediate)
+  globalThis.setImmediate = setImmediate;
+if (!globalThis.clearImmediate)
+  globalThis.clearImmediate = clearImmediate;
+
 if (!globalThis.setInterval)
   globalThis.setInterval = setInterval;
 if (!globalThis.clearInterval)
   globalThis.clearInterval = clearInterval;
 
 exports.setTimeout = setTimeout;
 exports.clearTimeout = clearTimeout;
+exports.setImmediate = setImmediate;
+exports.clearImmediate = clearImmediate;
 exports.setInterval = setInterval;
 exports.clearInterval = clearInterval;

python/pythonmonkey/cli/pmjs.py

@@ -11,7 +11,7 @@
 import readline
 import asyncio
 import pythonmonkey as pm
-from pythonmonkey.lib import pmdb
+from pythonmonkey.lib import pmdb, wtfpm
 
 globalThis = pm.eval("globalThis")
 evalOpts = {'filename': __file__, 'fromPythonFrame': True, 'strict': False}  # type: pm.EvalOptions
@@ -296,6 +296,7 @@ def usage():
   -v, --version        print PythonMonkey version
   --use-strict         evaluate -e, -p, and REPL code in strict mode
   --inspect            enable pmdb, a gdb-like JavaScript debugger interface
+  --wtf                enable WTFPythonMonkey, a tool that can detect hanging timers when Ctrl-C is hit
 
 Environment variables:
 TZ                            specify the timezone configuration
@@ -333,14 +334,15 @@ def main():
 
   try:
     opts, args = getopt.getopt(sys.argv[1:], "hie:p:r:v", ["help", "eval=", "print=",
-                               "require=", "version", "interactive", "use-strict", "inspect"])
+                               "require=", "version", "interactive", "use-strict", "inspect", "wtf"])
   except getopt.GetoptError as err:
     # print help information and exit:
     print(err)  # will print something like "option -a not recognized"
     usage()
     sys.exit(2)
   output = None
   verbose = False
+  enableWTF = False
   for o, a in opts:
     if o in ("-v", "--version"):
       print(pm.__version__)
@@ -369,6 +371,8 @@ async def runEvalPrint():
       globalThis.require(a)
     elif o in ("--inspect"):
       pmdb.enable()
+    elif o in ("--wtf"):
+      enableWTF = True
     else:
       assert False, "unhandled option"
 
@@ -377,7 +381,12 @@ async def runJS():
       globalInitModule.patchGlobalRequire()
       pm.runProgramModule(args[0], args, requirePath)
       await pm.wait()  # blocks until all asynchronous calls finish
-    asyncio.run(runJS())
+    try:
+      asyncio.run(runJS())
+    except KeyboardInterrupt:
+      print()  # silently going to end the program instead of printing out the Python traceback
+      if enableWTF:
+        wtfpm.printTimersDebugInfo()
   elif (enterRepl or forceRepl):
     async def runREPL():
       globalInitModule.initReplLibs()

python/pythonmonkey/lib/wtfpm.py

@@ -0,0 +1,42 @@
+# @file     WTFPythonMonkey - A tool that detects any hanging setTimeout/setInterval timers when Ctrl-C is hit
+# @author   Tom Tang <[email protected]>
+# @date     April 2024
+# @copyright Copyright (c) 2024 Distributive Corp.
+
+import pythonmonkey as pm
+
+
+def printTimersDebugInfo():
+  pm.eval("""(require) => {
+    const internalBinding = require('internal-binding');
+    const { getAllRefedTimersDebugInfo: getDebugInfo } = internalBinding('timers');
+    console.log(getDebugInfo())
+    console.log(new Date())
+  }""")(pm.createRequire(__file__))
+
+
+class WTF:
+  """
+  WTFPythonMonkey to use as a Python context manager (`with`-statement)
+
+  Usage:
+    ```py
+    from pythonmonkey.lib.wtfpm import WTF
+
+    with WTF():
+      # the main entry point for the program utilizes PythonMonkey event-loop
+      asyncio.run(pythonmonkey_main())
+    ```
+  """
+
+  def __enter__(self):
+    pass
+
+  def __exit__(self, errType, errValue, traceback):
+    if errType is None:  # no exception
+      return
+    elif issubclass(errType, KeyboardInterrupt):  # except KeyboardInterrupt:
+      printTimersDebugInfo()
+      return True  # exception suppressed
+    else:  # other exceptions
+      return False

src/PyEventLoop.cc

@@ -38,13 +38,16 @@ static PyObject *timerJobWrapper(PyObject *jobFn, PyObject *args) {
   PyEventLoop::AsyncHandle::id_t handleId = PyLong_AsLong(PyTuple_GetItem(args, 1));
   double delaySeconds = PyFloat_AsDouble(PyTuple_GetItem(args, 2));
   bool repeat = (bool)PyLong_AsLong(PyTuple_GetItem(args, 3));
-  auto handle = PyEventLoop::AsyncHandle::fromId(handleId);
 
   PyObject *ret = PyObject_CallObject(jobFn, NULL); // jobFn()
   Py_XDECREF(ret); // don't care about its return value
 
   PyObject *errType, *errValue, *traceback; // we can't call any Python code unless the error indicator is clear
   PyErr_Fetch(&errType, &errValue, &traceback);
+  // Making sure a `AsyncHandle::fromId` call is close to its `handle`'s use.
+  // We need to ensure the memory block doesn't move for reallocation before we can use the pointer,
+  // as we could have multiple new `setTimeout` calls to expand the `_timeoutIdMap` vector while running the job function in parallel.
+  auto handle = PyEventLoop::AsyncHandle::fromId(handleId);
   if (repeat && !handle->cancelled()) {
     _enqueueWithDelay(_loop, handleId, jobFn, delaySeconds, repeat);
   } else {
@@ -119,6 +122,7 @@ PyEventLoop::Future PyEventLoop::ensureFuture(PyObject *awaitable) {
   Py_DECREF(args);
   Py_DECREF(kwargs);
 
+  Py_INCREF(futureObj); // needs to be kept alive as `PyEventLoop::Future` will decrease the reference count in its destructor
   return PyEventLoop::Future(futureObj);
 }
 

src/internalBinding/timers.cc

@@ -8,9 +8,12 @@
 
 #include "include/internalBinding.hh"
 #include "include/pyTypeFactory.hh"
+#include "include/jsTypeFactory.hh"
 #include "include/PyEventLoop.hh"
+#include "include/setSpiderMonkeyException.hh"
 
 #include <jsapi.h>
+#include <js/Array.h>
 
 using AsyncHandle = PyEventLoop::AsyncHandle;
 
@@ -24,6 +27,7 @@ static bool enqueueWithDelay(JSContext *cx, unsigned argc, JS::Value *vp) {
   JS::HandleValue jobArgVal = args.get(0);
   double delaySeconds = args.get(1).toNumber();
   bool repeat = args.get(2).toBoolean();
+  JS::HandleValue debugInfo = args.get(3);
 
   // Convert to a Python function
   JS::RootedValue jobArg(cx, jobArgVal);
@@ -34,6 +38,10 @@ static bool enqueueWithDelay(JSContext *cx, unsigned argc, JS::Value *vp) {
   PyEventLoop::AsyncHandle::id_t handleId = loop.enqueueWithDelay(job, delaySeconds, repeat);
   Py_DECREF(job);
 
+  // Set debug info for the WTFPythonMonkey tool
+  auto handle = PyEventLoop::AsyncHandle::fromId(handleId);
+  handle->setDebugInfo(pyTypeFactory(cx, debugInfo));
+
   // Return the `timeoutID` to use in `clearTimeout`
   args.rval().setNumber(handleId);
   return true;
@@ -95,11 +103,45 @@ static bool timerRemoveRef(JSContext *cx, unsigned argc, JS::Value *vp) {
   return true;
 }
 
+static bool getDebugInfo(JSContext *cx, unsigned argc, JS::Value *vp) {
+  JS::CallArgs args = JS::CallArgsFromVp(argc, vp);
+  double timeoutID = args.get(0).toNumber();
+
+  // Retrieve the AsyncHandle by `timeoutID`
+  AsyncHandle *handle = AsyncHandle::fromId((uint32_t)timeoutID);
+  if (!handle) return false; // error no such timeoutID
+
+  JS::Value debugInfo = jsTypeFactory(cx, handle->getDebugInfo());
+  args.rval().set(debugInfo);
+  return true;
+}
+
+static bool getAllRefedTimersDebugInfo(JSContext *cx, unsigned argc, JS::Value *vp) {
+  JS::CallArgs args = JS::CallArgsFromVp(argc, vp);
+
+  JS::RootedVector<JS::Value> results(cx);
+  for (AsyncHandle &timer: AsyncHandle::getAllTimers()) {
+    if (!timer.hasRef()) continue; // we only need ref'ed timers
+
+    JS::Value debugInfo = jsTypeFactory(cx, timer.getDebugInfo());
+    if (!results.append(debugInfo)) {
+      // out of memory
+      setSpiderMonkeyException(cx);
+      return false;
+    }
+  }
+
+  args.rval().setObjectOrNull(JS::NewArrayObject(cx, results));
+  return true;
+}
+
 JSFunctionSpec InternalBinding::timers[] = {
   JS_FN("enqueueWithDelay", enqueueWithDelay, /* nargs */ 2, 0),
   JS_FN("cancelByTimeoutId", cancelByTimeoutId, 1, 0),
   JS_FN("timerHasRef", timerHasRef, 1, 0),
   JS_FN("timerAddRef", timerAddRef, 1, 0),
   JS_FN("timerRemoveRef", timerRemoveRef, 1, 0),
+  JS_FN("getDebugInfo", getDebugInfo, 1, 0),
+  JS_FN("getAllRefedTimersDebugInfo", getAllRefedTimersDebugInfo, 1, 0),
   JS_FS_END
 };