Open
Description
Describe the bug
We are using Actions Runner Controller and maintain our own runner images.
We were using gha-runner-scale-set-controller-0.10.0 & gha-runner-scale-set-0.10.0 since couple of months. Then, suddenly (first observed on 30th of May), workflow job logs from linux runner scale sets were not streamed to the UI anymore. The logs are however visible after job completion.
The image had been built and deployed on 21th of May.
This problem does not happen with windows runner scale sets nor with VM runners.
To Reproduce
Steps to reproduce the behavior:
- install gha-runner-scale-set-controller-0.11.0 to an AKS
- install gha-runner-scale-set-0.11.0 to an AKS using a ubuntu jammy base image with runner version 2.325.0
- Run a workflow job and observe how logs are not streamed to the github UI during the job execution. Logs are however available after job completion.
Expected behavior
Logs should be streamed in the UI during job execution
Runner Version and Platform
2.325.0
Linux
What's not working?
Job Log Output
Runner and Worker's Diagnostic Logs
A snippet from runner diagnostic logs:
[2025-06-04 06:09:10Z INFO JobDispatcher] Job request 0 for plan 6aa8a6fb-2032-4b2f-997a-c4a5898e64fa job bdedc8de-e57a-5dee-b0f8-7dc24a4b0aaa received.
[2025-06-04 06:09:10Z INFO JobDispatcher] Start dispatcher for one time used runner.
[2025-06-04 06:09:10Z INFO MessageListener] Received job status event. JobState: Busy
[2025-06-04 06:09:10Z INFO MessageListener] _getMessagesTokenSource is already disposed.
[2025-06-04 06:09:10Z INFO Terminal] WRITE LINE: 2025-06-04 06:09:10Z: Running job: build
[2025-06-04 06:09:10Z INFO JobDispatcher] Start renew job request 0 for job bdedc8de-e57a-5dee-b0f8-7dc24a4b0aaa.
[2025-06-04 06:09:10Z INFO Runner] One time used runner received job message.
[2025-06-04 06:09:11Z INFO JobDispatcher] Successfully renew job bdedc8de-e57a-5dee-b0f8-7dc24a4b0aaa, job is valid till 4.6.2025 6.19.11
[2025-06-04 06:09:11Z INFO HostContext] Well known directory 'Bin': '/actions-runner/bin'
[2025-06-04 06:09:11Z INFO ProcessInvokerWrapper] Starting process:
[2025-06-04 06:09:11Z INFO ProcessInvokerWrapper] File name: '/actions-runner/bin/Runner.Worker'
[2025-06-04 06:09:11Z INFO ProcessInvokerWrapper] Arguments: 'spawnclient 150 153'
[2025-06-04 06:09:11Z INFO ProcessInvokerWrapper] Working directory: '/actions-runner/bin'
[2025-06-04 06:09:11Z INFO ProcessInvokerWrapper] Require exit code zero: 'False'
[2025-06-04 06:09:11Z INFO ProcessInvokerWrapper] Encoding web name: ; code page: ''
[2025-06-04 06:09:11Z INFO ProcessInvokerWrapper] Force kill process on cancellation: 'True'
[2025-06-04 06:09:11Z INFO ProcessInvokerWrapper] Redirected STDIN: 'False'
[2025-06-04 06:09:11Z INFO ProcessInvokerWrapper] Persist current code page: 'False'
[2025-06-04 06:09:11Z INFO ProcessInvokerWrapper] Keep redirected STDIN open: 'False'
[2025-06-04 06:09:11Z INFO ProcessInvokerWrapper] High priority process: 'True'
[2025-06-04 06:09:11Z INFO ProcessInvokerWrapper] Process started with process id 33, waiting for process exit.
[2025-06-04 06:09:11Z INFO JobDispatcher] Send job request message to worker for job bdedc8de-e57a-5dee-b0f8-7dc24a4b0aaa.
[2025-06-04 06:09:11Z INFO ProcessChannel] Sending message of length 21561, with hash '7bcfcdb11a6c01b318a3c318e39a31ec22e48727f588c8548da3e1d8be6b2257'
[2025-06-04 06:09:11Z INFO JobNotification] Entering JobStarted Notification
[2025-06-04 06:09:11Z INFO JobNotification] Entering StartMonitor
[2025-06-04 06:09:12Z INFO ConfigurationStore] HasCredentials()
[2025-06-04 06:09:12Z INFO ConfigurationStore] stored True
[2025-06-04 06:09:12Z INFO CredentialManager] GetCredentialProvider
[2025-06-04 06:09:12Z INFO CredentialManager] Creating type OAuth
[2025-06-04 06:09:12Z INFO CredentialManager] Creating credential type: OAuth
[2025-06-04 06:09:12Z INFO RSAFileKeyManager] Loading RSA key parameters from file /actions-runner/.credentials_rsaparams
A snippet from worker diagnostic logs:
[2025-06-04 06:09:11Z INFO ProcessInvokerWrapper] Process started with process id 47, waiting for process exit.
[2025-06-04 06:09:11Z INFO Worker] Listening for cancel message from the channel.
[2025-06-04 06:09:11Z INFO Worker] Waiting for the job to complete or for a cancel message from the channel.
[2025-06-04 06:09:12Z INFO JobServerQueue] Try to upload 1 log files or attachments, success rate: 1/1.
[2025-06-04 06:09:12Z INFO JobServerQueue] Got a step log file to send to results service.
[2025-06-04 06:09:12Z INFO JobServerQueue] Starting upload of step log file to results service ResultsLog, /actions-runner/_diag/blocks/6aa8a6fb-2032-4b2f-997a-c4a5898e64fa_dac89eda-1e37-4f73-ba8b-02f489482686.1
[2025-06-04 06:09:13Z INFO ResultServer] Successfully started websocket client.
[2025-06-04 06:09:13Z INFO JobServerQueue] Try to append 1 batches web console lines for record 'bdedc8de-e57a-5dee-b0f8-7dc24a4b0aaa', success rate: 1/1.
[2025-06-04 06:09:13Z INFO JobServerQueue] Try to append 1 batches web console lines for record 'dac89eda-1e37-4f73-ba8b-02f489482686', success rate: 1/1.
[2025-06-04 06:09:13Z INFO JobServerQueue] Try to append 5 batches web console lines for record 'e51e78b9-4019-4dd0-8302-262ea585677c', success rate: 5/5.
[2025-06-04 06:09:13Z ERR GitHubActionsService] POST request to https://results-receiver.actions.githubusercontent.com/twirp/github.actions.results.api.v1.WorkflowStepUpdateService/WorkflowStepsUpdate failed. HTTP Status: BadRequest
[2025-06-04 06:09:13Z INFO JobServerQueue] Catch exception during update steps, skip update Results.
[2025-06-04 06:09:13Z ERR JobServerQueue] System.Exception: Failed to mark StepsUpdateRequest upload as complete, status code: BadRequest, ok: False, timestamp: 2025-06-04T06:09:12.653Z
at GitHub.Services.Results.Client.ResultsHttpClient.SendRequest[R](Uri uri, CancellationToken cancellationToken, R request, String timestamp)
at GitHub.Services.Results.Client.ResultsHttpClient.UpdateWorkflowStepsAsync(Guid planId, IEnumerable`1 records, CancellationToken cancellationToken)
at GitHub.Runner.Common.JobServerQueue.ProcessTimelinesUpdateQueueAsync(Boolean runOnce)
[2025-06-04 06:09:13Z INFO JobServerQueue] Job timeline record has been updated for the first time.
[2025-06-04 06:09:13Z INFO JobServerQueue] Try to append 2 batches web console lines for record 'e51e78b9-4019-4dd0-8302-262ea585677c', success rate: 2/2.
[2025-06-04 06:09:13Z INFO JobServerQueue] Tried to upload 1 file(s) to results, success rate: 1/1.
[2025-06-04 06:09:21Z INFO HostContext] Well known directory 'Bin': '/actions-runner/bin'
[2025-06-04 06:09:21Z INFO HostContext] Well known directory 'Root': '/actions-runner'
[2025-06-04 06:09:21Z INFO HostContext] Well known directory 'Work': '/actions-runner/_work'
[2025-06-04 06:09:31Z INFO HostContext] Well known directory 'Bin': '/actions-runner/bin'
[2025-06-04 06:09:31Z INFO HostContext] Well known directory 'Root': '/actions-runner'
[2025-06-04 06:09:31Z INFO HostContext] Well known directory 'Work': '/actions-runner/_work'
[2025-06-04 06:09:41Z INFO HostContext] Well known directory 'Bin': '/actions-runner/bin'
[2025-06-04 06:09:41Z INFO HostContext] Well known directory 'Root': '/actions-runner'
[2025-06-04 06:09:41Z INFO HostContext] Well known directory 'Work': '/actions-runner/_work'
[2025-06-04 06:09:41Z INFO ProcessInvokerWrapper] STDOUT/STDERR stream read finished.
[2025-06-04 06:09:41Z INFO ProcessInvokerWrapper] STDOUT/STDERR stream read finished.
[2025-06-04 06:09:41Z INFO ProcessInvokerWrapper] Finished process 47 with exit code 0, and elapsed time 00:00:30.0039405.