GetMessage long poll does not wake for JobStarted messages

[jmgilman]

Summary

Using github.com/actions/scaleset v0.4.0 against GitHub.com, we consistently observe JobStarted only on the request immediately after the current GetMessage request expires.

A controlled A/B test changed only the client-visible poll boundary from the normal approximately 50 seconds to 5 seconds. The delay between the event's runnerAssignTime and the JobStarted callback fell from 50.531 seconds to 5.402 seconds.

This suggests that an in-flight long poll does not wake when a JobStarted lifecycle message becomes available. The next request receives the message immediately.

Environment

• github.com/actions/scaleset: v0.4.0
• GitHub: GitHub.com
• Controller: custom Go autoscaler using listener.New
• Actions Runner: 2.335.1
• Incus: 7.0.1
• Capacity mode: one already-connected idle runner
• HTTP proxy: none on the controller
• Client session remained stable; no refresh or reconnect occurred

The same normal-poll behavior was independently reproduced in another hosting provider with Actions Runner 2.336.0.

Expected behavior

The v0.4.0 README documents GetMessage long polling as:

1. Return immediately if messages are available.
2. Otherwise, block for up to approximately 50 seconds.
3. Return HTTP 202 / (nil, nil) if no message arrives.

Based on that, a JobStarted message that becomes available during an active request should wake the request.

Actual behavior

The request active after job assignment remains blocked until its poll boundary and returns empty. The immediately following request returns JobStarted in less than a second.

Changing only the request boundary from approximately 50 seconds to 5 seconds changes the observed delivery delay.

Controlled A/B results

Both samples used:

• the same physical host;
• the same scale set;
• the same VM image;
• the same controller binary;
• the same workflow;
• an already-connected idle runner.

Measurement	Normal polling	Five-second diagnostic polling
Empty/intentional poll duration	50.113s	5.001s
runnerAssignTime to callback	50.531s	5.402s
Next poll to JobStarted response	149.6ms	133.5ms
Callback to downstream processing	5.70ms	5.05ms
User-visible wait	47.840s	2.089s

Baseline timeline

16:37:32.444015751Z  JobStarted.runnerAssignTime
16:37:32.617459289Z  GetMessage starts, lastMessageID=100000046
16:38:22.730698388Z  Request completes empty after 50.113239099s
16:38:22.730764231Z  Next GetMessage starts, same lastMessageID
16:38:22.880324308Z  Next request returns message 100000047
16:38:22.975129060Z  JobStarted callback begins

The event's runnerAssignTime preceded the request start by approximately 173ms, but that request remained blocked for its entire 50-second boundary.

Five-second canary timeline

16:39:53.077064531Z  JobStarted.runnerAssignTime
16:39:53.242071399Z  GetMessage starts, lastMessageID=100000049
16:39:58.243320342Z  Intentional deadline after 5.001248943s
16:39:58.243472249Z  Next GetMessage starts, same lastMessageID
16:39:58.376986238Z  Next request returns message 100000050
16:39:58.478991631Z  JobStarted callback begins

Here, runnerAssignTime preceded the request start by approximately 150ms. Again, the active request did not return JobStarted. The next request received it in 133.5ms.

Additional observations

• JobAssigned messages were received normally.
• The same lastMessageID was retained across each empty/expired request.
• DeleteMessage occurred before the application callback, as expected.
• There was no token refresh, session recreation, or controller reconnect.
• Shortening the poll boundary did not change downstream processing time.

Thank you.

[crohr]

I observed the same thing as well.