An unawaited promise in a deployed Forge function waits for the next thaw, fires milliseconds before the next handler, and its log is lost

A deployed Forge function does not wait for a promise it left unawaited. If another invocation lands on the same warm container, the pending callback runs. Where its log goes depends on when it came due.

Overdue when the container thaws, it runs milliseconds before the new handler starts and its log line is lost. Due while a later handler is still executing, it fires on schedule and the line lands, under its own already returned invocation id. If no invocation lands there, nothing shows it ever ran.

All of that except the last sentence is measured below. The last one rests on staff and on the thread that started this.

That thread is 98554. A KVS query in a scheduled trigger hung with no result and no error until every promise was awaited.

BoZhang: “With Lambda, the Node.js execution environment is ‘frozen’ once the handler returns; it doesn’t wait for all event loop to be empty. If a subsequent invocation comes along for the same Lambda instance, then the execution environment will be ‘unfrozen’, and the execution of unfinished promises will continue.”

That is the half about work that waits for a thaw.

The docs section he linked, Delayed code execution, is two short paragraphs around a code sample and states only the other half. “The latest Forge runtime might keep executing the code after the function returns”, with a setTimeout wrapping a fetch as the example. Nothing about a freeze.

In January he said the page could be made clearer about not leaving promises unawaited. Today it reads the same as when I pulled it on 26 August. Frozen, freeze, unawaited and Lambda are not on it. Hence a probe.

The probe

One handler body, exported behind a webtrigger and a scheduled trigger. The unawaited timer fires 1500 ms after entry. The awaited 300 ms sleep is the control. If the control does not log, that run is discarded.

const sleep = (ms) => new Promise((r) => setTimeout(r, ms));

globalThis.g36boot = globalThis.g36boot || Math.random().toString(36).slice(2, 8);
async function body(label) {
  const run = Math.random().toString(36).slice(2, 8);
  const t0 = Date.now();
  const lateAgo = globalThis.g36lateAt ? `${Date.now() - globalThis.g36lateAt}ms` : 'none';
  console.log(`G36 ${label} START run=${run} boot=${globalThis.g36boot} prevLate=${globalThis.g36late || 'none'} lateAgo=${lateAgo}`);
  sleep(1500).then(() => {
    globalThis.g36late = run;
    globalThis.g36lateAt = Date.now();
    console.log(`G36 ${label} UNAWAITED-LATE run=${run} fired +${Date.now() - t0}ms`);
  });
  await sleep(300);
  console.log(`G36 ${label} AWAITED-CONTROL run=${run} done +${Date.now() - t0}ms`);
  return run;
}

export const web = async () => ({ statusCode: 200, body: `G36 web run=${await body('web')}` });
export const sched = async () => { await body('sched'); };

Three detectors for one callback. Its own console.log. A module-level variable it writes, read back by the following invocation as prevLate. And a timestamp it records, reported by the following invocation as lateAgo, the time between the callback firing and that next handler starting.

Module scope survives on a warm container. boot says whether one was reused.

lateAgo settles the timing. A few milliseconds means the callback fired on thaw, right ahead of the new handler. Something close to the gap between invocations minus 1500 ms means it fired in a window after the return, before any freeze.

What came back

nodejs22.x, development environment, five curls to the deployed webtrigger this morning. Gaps of six seconds, six, sixty, six.

07:22:36.363Z G36 web START run=eb8wco boot=w7e4ia prevLate=none lateAgo=none
07:22:36.663Z G36 web AWAITED-CONTROL run=eb8wco done +300ms
07:22:42.203Z G36 web START run=6rz4d4 boot=w7e4ia prevLate=eb8wco lateAgo=2ms
07:22:42.504Z G36 web AWAITED-CONTROL run=6rz4d4 done +301ms
07:22:48.043Z G36 web START run=2p6rpu boot=w7e4ia prevLate=6rz4d4 lateAgo=73ms
07:22:48.344Z G36 web AWAITED-CONTROL run=2p6rpu done +301ms
07:23:48.893Z G36 web START run=9d69j6 boot=w7e4ia prevLate=2p6rpu lateAgo=3ms
07:23:49.192Z G36 web AWAITED-CONTROL run=9d69j6 done +299ms
07:23:54.729Z G36 web START run=f14p15 boot=w7e4ia prevLate=9d69j6 lateAgo=1ms
07:23:55.029Z G36 web AWAITED-CONTROL run=f14p15 done +300ms

Five controls, five logged. Zero UNAWAITED-LATE lines. Every warm START carries the previous run’s id. The callback ran.

And lateAgo is 1 to 73 ms on all four, including the call that came a full minute after the one before it. A timer due 1.2 s after the return fired 60 s later, a few milliseconds ahead of the next handler. The container was frozen in between.

Its own log line did not reach forge logs on any of the four. Not under its own id, not under the next one.

That is the thaw case. Stack the calls closer and a different thing happens. Three more curls on the same container, 1.2 s and 0.75 s apart:

07:28:18.644Z G36 web START run=fvgds4 boot=w7e4ia prevLate=f14p15 lateAgo=176ms
07:28:18.945Z G36 web AWAITED-CONTROL run=fvgds4 done +301ms
07:28:19.853Z G36 web START run=ackqgx boot=w7e4ia prevLate=f14p15 lateAgo=1385ms
07:28:20.145Z G36 web UNAWAITED-LATE run=fvgds4 fired +1501ms
07:28:20.153Z G36 web AWAITED-CONTROL run=ackqgx done +300ms
07:28:20.607Z G36 web START run=zz7clb boot=w7e4ia prevLate=fvgds4 lateAgo=462ms
07:28:20.907Z G36 web AWAITED-CONTROL run=zz7clb done +300ms
07:31:04.807Z G36 web START run=vgizj3 boot=w7e4ia prevLate=zz7clb lateAgo=3ms

ackqgx started with prevLate=f14p15, so fvgds4’s timer had not fired yet. It came due 292 ms into ackqgx, while that handler sat in its awaited sleep, and it fired on time. The line landed in forge logs, tagged with fvgds4’s id.

Then zz7clb returned before ackqgx’s timer was due, the container froze, and that timer waited for the next thaw at 07:31. No line for it anywhere.

One rule covers both. The callback runs whenever the container is awake and the timer is due. Awake because a handler is running, the line logs. Woken by the next invocation with the timer overdue, the line is lost.

The zero looked like a drop at first. The staff quote primes you for exactly that. Read only the log and you get the wrong claim, and the log is the only detector most apps have.

The scheduled run is from 13 September, on the deploy that still carried the trigger and before the lateAgo marker existed. Same probe file otherwise, fiveMinute interval:

17:27:33.865Z G36 sched START run=n4naxh boot=nu46s3 prevLate=none
17:27:34.165Z G36 sched AWAITED-CONTROL run=n4naxh done +300ms
17:32:32.985Z G36 sched START run=2o3q3n boot=nu46s3 prevLate=n4naxh
17:32:33.284Z G36 sched AWAITED-CONTROL run=2o3q3n done +300ms

Same container, five minutes apart. The first firing’s timer had run by the time the second one started. Nothing about “nobody downstream awaits a scheduled trigger” makes it more exposed than a webtrigger. What decides whether the promise ever runs is whether another invocation reaches that container first.

Under the tunnel

Same body, same URL, forge tunnel -e development, two curls five seconds apart. The tunnel console, which does not feed forge logs and stamps lines in local time, so 10:25 here is 07:25Z:

10:25:01.409  G36 web START run=vj6pa4 boot=4327as prevLate=none lateAgo=none
10:25:01.710  G36 web AWAITED-CONTROL run=vj6pa4 done +303ms
10:25:02.911  G36 web UNAWAITED-LATE run=vj6pa4 fired +1504ms
10:25:07.138  G36 web START run=zvqqdm boot=4327as prevLate=vj6pa4 lateAgo=4226ms
10:25:07.439  G36 web AWAITED-CONTROL run=zvqqdm done +301ms
10:25:08.638  G36 web UNAWAITED-LATE run=zvqqdm fired +1501ms

The late line appears, under its own id, 1.2 s after the handler returned. lateAgo on the second call is 4226 ms. The real clock. Nothing froze. That is why the code in 98554 worked under the tunnel and failed on each of the several versions the developer deployed.

One thing before you try this. After the tunnel exits, the deployed webtrigger in that environment answered 424 Failed Dependency for me, with nothing in forge logs. It was back to 200 within three minutes (424 at 07:25:23Z, 200 at 07:28:18Z).

Why it passes testing

Deployed to a dev site you click, the container thaws, the previous click’s callback runs, and the feature looks fine for as long as you keep clicking. In production a trigger fires once an hour on whichever container it gets. There may be no next invocation on that one.

That is 98554.

Await it or return it. Several of them, collect them with await Promise.allSettled([...]). Work you do not want the handler to wait for goes on the async events queue, and queue.push is a promise too.

Not measured

The callback wrote memory and a timestamp. Whether an unawaited KVS write or fetch completes on thaw the same way was not checked. If you have a scoped side effect that you have watched land late, I would like to see the log.

A container reclaimed with the promise still pending cannot be shown by a probe. That half rests on the staff statement and on what 98554’s asker saw.

Only a webtrigger and a scheduled trigger ran the probe. No resolver, product trigger or async-events consumer was wired to it. Only nodejs22.x. Only the development environment. Only one timer, due 1.2 s after a 300 ms handler. Absence of the late line was checked in the forge logs CLI and nowhere else.

One more thing from the scheduled run, unrelated to promises. The docs say a trigger is “scheduled to start shortly after it is created, about 5 minutes after app deployment”. Mine first fired seven to nine minutes after the deploy, depending on which of two deploys a couple of minutes apart you count from.

A missing first firing is not a broken trigger.

You’re absolutely right!

The unawaited promises in Forge functions can continue into the next invocation, and that might be much later. And because the logs are tied to invocations, those sent after the result has been returned might be lost as well.

I’ve clarified both points in https://developer.atlassian.com/platform/forge/function-reference/nodejs-runtime/. Hope it helps developers in the future!

But again, please don’t try to run code after your function returns. It almost certainly won’t do what you want.

Thanks @AlexeyKotlyarov, that’s exactly the clarification I was after. The warning block on the runtime page now says what the probe measured, and the tenant isolation line is the part I hadn’t thought about. Marking this as the solution.