Integration Test #250
Workflow file for this run
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
| name: Integration Test | |
| on: | |
| workflow_dispatch: | |
| inputs: | |
| os: | |
| description: "Platform to test" | |
| required: true | |
| type: choice | |
| options: | |
| - all | |
| - windows-latest | |
| - ubuntu-latest | |
| - macos-latest | |
| jobs: | |
| build: | |
| permissions: | |
| contents: read | |
| uses: ./.github/workflows/build.yml | |
| with: | |
| os_list: "${{ inputs.os == 'all' && '[''windows-latest'',''ubuntu-latest'',''macos-latest'']' || format('[{0}{1}{0}]', '''', inputs.os) }}" | |
| cache: true | |
| build-integration-test: | |
| permissions: | |
| contents: read | |
| strategy: | |
| fail-fast: false | |
| matrix: | |
| os: ${{ fromJson(inputs.os == 'all' && '[''windows-latest'',''ubuntu-latest'',''macos-latest'']' || format('[{0}{1}{0}]', '''', inputs.os)) }} | |
| runs-on: ${{ matrix.os }} | |
| steps: | |
| - name: Checkout code | |
| uses: actions/checkout@v5 | |
| with: | |
| ref: ${{ github.ref }} | |
| fetch-depth: 0 | |
| - name: Cache integration test build output | |
| id: cache-build | |
| uses: actions/cache@v5 | |
| with: | |
| path: ./dist | |
| key: build-it-${{ matrix.os }}-go1.25.0-${{ hashFiles('**/*.go', 'go.sum', 'go.mod') }} | |
| - name: Setup go | |
| if: steps.cache-build.outputs.cache-hit != 'true' | |
| uses: actions/setup-go@v6 | |
| with: | |
| go-version: "1.25.0" | |
| cache: true | |
| - name: Build integration test binary | |
| if: steps.cache-build.outputs.cache-hit != 'true' | |
| shell: pwsh | |
| id: build | |
| run: ./scripts/build_integration_test.ps1 | % { "binary_path=$_" } >> $env:GITHUB_OUTPUT | |
| - name: Upload integration test binary | |
| uses: actions/upload-artifact@v6 | |
| with: | |
| name: it-${{ matrix.os }} | |
| path: ${{ steps.build.outputs.binary_path || './dist/*' }} | |
| set-matrix: | |
| permissions: | |
| contents: read | |
| runs-on: ubuntu-latest | |
| outputs: | |
| matrix: ${{ steps.gen.outputs.matrix }} | |
| steps: | |
| - name: Build test matrix include | |
| id: gen | |
| shell: pwsh | |
| env: | |
| OS_INPUT: ${{ inputs.os }} | |
| ORG_ID: ${{ vars.IT_ORG_ID }} | |
| run: | | |
| $winSuccess = @' | |
| "[Net.ServicePointManager]::SecurityProtocol = [Net.SecurityProtocolType]::Tls12 | |
| $PS_Results = New-Object -TypeName psobject | |
| # Start of typed powershell | |
| $PS_Results | Add-Member -MemberType NoteProperty -Name \"error\" -Value \"\" | |
| $PS_Results | Add-Member -MemberType NoteProperty -Name \"output\" -Value \"hello world`n\" | |
| # Post results back to Rewst | |
| $postData = $PS_Results | ConvertTo-Json | |
| Invoke-RestMethod -Method \"Post\" -Uri $post_url -Body $postData -ContentType \"application/json\"" | |
| '@ | |
| $winFailure = @' | |
| "[Net.ServicePointManager]::SecurityProtocol = [Net.SecurityProtocolType]::Tls12 | |
| $PS_Results = New-Object -TypeName psobject | |
| # Start of typed powershell | |
| throw \"this is a test error\" | |
| # Post results back to Rewst | |
| $postData = $PS_Results | ConvertTo-Json | |
| Invoke-RestMethod -Method \"Post\" -Uri $post_url -Body $postData -ContentType \"application/json\"" | |
| '@ | |
| $orgId = $env:ORG_ID | |
| # Output-flood scripts for the bounded-output scenario (sc-106105). | |
| # Deliberately quote-free and backslash-free so they survive the trip | |
| # through the trigger's JSON-quoted commands field unchanged, and | |
| # byte-exact so the produced counts the agent reports are predictable: | |
| # verbose 200 MiB to stdout, then a clean exit | |
| # verbose_stderr a short stdout line, then 200 MiB to stderr | |
| # verbose_hang 200 MiB to stdout, then a hang past the timeout | |
| # All three write 200 MiB - three orders of magnitude past the ceiling | |
| # the scenario configures - so the RSS ceiling asserted while they run | |
| # is far below what buffering the output whole would cost. | |
| $winVerbose = '"$chunk = [string]::new([char]120, 1048576); 1..200 | ForEach-Object { $chunk }"' | |
| $winVerboseStderr = '"Write-Output keep-stdout; $chunk = [string]::new([char]101, 1048576); 1..200 | ForEach-Object { [Console]::Error.Write($chunk) }"' | |
| $winVerboseHang = '"$chunk = [string]::new([char]120, 1048576); 1..200 | ForEach-Object { $chunk }; Start-Sleep -Seconds 60"' | |
| $unixVerbose = '"yes x | head -c 209715200"' | |
| $unixVerboseStderr = '"echo keep-stdout; yes e | head -c 209715200 >&2"' | |
| $unixVerboseHang = '"yes x | head -c 209715200; sleep 60"' | |
| $entries = @( | |
| [ordered]@{ | |
| os = 'ubuntu-latest' | |
| binary = 'rewst_agent_config.linux.bin' | |
| it_binary = 'rewst_agent_config.linux.it.bin' | |
| config_dir = '/etc/rewst_remote_agent' | |
| log_file = "/etc/rewst_remote_agent/$orgId/rewst_agent.log" | |
| service = "rewst_remote_agent_$orgId" | |
| success_commands = '"echo \"hello world\""' | |
| failure_commands = '"exit 1"' | |
| timeout_commands = '"sleep 30"' | |
| sweep_commands = '"sleep 180"' | |
| verbose_commands = $unixVerbose | |
| verbose_stderr_commands = $unixVerboseStderr | |
| verbose_hang_commands = $unixVerboseHang | |
| success_patterns = "Command completed`nSending postback`nPostback sent" | |
| no_auto_updates_extra = '' | |
| uninstall_paths = "/etc/rewst_remote_agent/$orgId`n/usr/local/bin/rewst_remote_agent/$orgId`n/tmp/rewst_remote_agent/scripts/$orgId" | |
| service_user = 'rewst-it-svc' | |
| service_username_arg = 'rewst-it-svc' | |
| service_identity = 'rewst-it-svc' | |
| }, | |
| [ordered]@{ | |
| os = 'windows-latest' | |
| binary = 'rewst_agent_config.win.exe' | |
| it_binary = 'rewst_agent_config.win.it.exe' | |
| config_dir = 'C:\ProgramData\RewstRemoteAgent' | |
| log_file = "C:\ProgramData\RewstRemoteAgent\$orgId\rewst_agent.log" | |
| service = "RewstRemoteAgent_$orgId" | |
| success_commands = $winSuccess | |
| failure_commands = $winFailure | |
| timeout_commands = '"Start-Sleep -Seconds 30"' | |
| sweep_commands = '"Start-Sleep -Seconds 180"' | |
| verbose_commands = $winVerbose | |
| verbose_stderr_commands = $winVerboseStderr | |
| verbose_hang_commands = $winVerboseHang | |
| success_patterns = "Command completed`nSending postback`nPostback already sent" | |
| no_auto_updates_extra = '--disable-agent-postback' | |
| uninstall_paths = "C:\ProgramData\RewstRemoteAgent\$orgId`nC:\Program Files\RewstRemoteAgent\$orgId`nC:\RewstRemoteAgent\scripts\$orgId" | |
| service_user = 'rewst-it-svc' | |
| service_username_arg = '.\rewst-it-svc' | |
| service_identity = '.\rewst-it-svc' | |
| }, | |
| [ordered]@{ | |
| os = 'macos-latest' | |
| binary = 'rewst_agent_config.mac-os.bin' | |
| it_binary = 'rewst_agent_config.mac-os.it.bin' | |
| config_dir = '/Library/Application Support/rewst_remote_agent' | |
| log_file = "/Library/Application Support/rewst_remote_agent/$orgId/rewst_agent.log" | |
| service = "io.rewst.remote_agent_$orgId" | |
| success_commands = '"echo \"hello world\""' | |
| failure_commands = '"exit 1"' | |
| timeout_commands = '"sleep 30"' | |
| sweep_commands = '"sleep 180"' | |
| verbose_commands = $unixVerbose | |
| verbose_stderr_commands = $unixVerboseStderr | |
| verbose_hang_commands = $unixVerboseHang | |
| success_patterns = "Command completed`nSending postback`nPostback sent" | |
| no_auto_updates_extra = '' | |
| uninstall_paths = "/Library/Application Support/rewst_remote_agent/$orgId`n/usr/local/bin/rewst_remote_agent/$orgId`n`$env:TMPDIR/rewst_remote_agent/scripts/$orgId" | |
| service_user = 'rewst-it-svc' | |
| service_username_arg = 'rewst-it-svc' | |
| service_identity = 'rewst-it-svc' | |
| } | |
| ) | |
| if ($env:OS_INPUT -ne 'all') { | |
| $entries = @($entries | Where-Object { $_.os -eq $env:OS_INPUT }) | |
| } | |
| $payload = @{ include = $entries } | |
| $json = ConvertTo-Json -InputObject $payload -Depth 10 -Compress | |
| Write-Output $json | |
| "matrix=$json" >> $env:GITHUB_OUTPUT | |
| test: | |
| permissions: | |
| contents: read | |
| env: | |
| GITHUB_TOKEN: ${{ secrets.GITHUB_TOKEN }} | |
| needs: [build, build-integration-test, set-matrix] | |
| strategy: | |
| fail-fast: false | |
| matrix: ${{ fromJson(needs.set-matrix.outputs.matrix) }} | |
| runs-on: ${{ matrix.os }} | |
| steps: | |
| - name: Checkout code | |
| uses: actions/checkout@v5 | |
| - name: Inject PowerShell profile noise | |
| if: matrix.os == 'windows-latest' | |
| id: inject_profile_noise | |
| uses: ./.github/actions/inject-profile-noise | |
| - name: Install agent | |
| id: install_agent | |
| uses: ./.github/actions/install-agent | |
| with: | |
| os: ${{ matrix.os }} | |
| binary: ${{ matrix.binary }} | |
| it_binary: ${{ matrix.it_binary }} | |
| config_url: ${{ vars.IT_CONFIG_URL }} | |
| config_secret: ${{ secrets.IT_CONFIG_SECRET }} | |
| org_id: ${{ vars.IT_ORG_ID }} | |
| github_token: ${{ secrets.GITHUB_TOKEN }} | |
| - name: Check install output for profile noise | |
| if: matrix.os == 'windows-latest' | |
| uses: ./.github/actions/check-profile-noise | |
| with: | |
| install_output_path: ${{ steps.install_agent.outputs.install_output_path }} | |
| noise: ${{ steps.inject_profile_noise.outputs.noise }} | |
| - name: Check service | |
| uses: ./.github/actions/check-service | |
| with: | |
| service: ${{ matrix.service }} | |
| - name: Validate config and get device id | |
| id: config | |
| uses: ./.github/actions/validate-config | |
| with: | |
| config_dir: ${{ matrix.config_dir }} | |
| org_id: ${{ vars.IT_ORG_ID }} | |
| - name: Check subscribed messages log for topic and QoS | |
| uses: ./.github/actions/assert-log-contains | |
| with: | |
| log_file: ${{ matrix.log_file }} | |
| patterns: Subscribed to messages | |
| subscribed_topic_qos: "true" | |
| wait_seconds: "10" | |
| - name: Send success command | |
| uses: ./.github/actions/send-command | |
| with: | |
| trigger_url: ${{ vars.IT_SEND_COMMAND_TRIGGER_URL }} | |
| device_id: ${{ steps.config.outputs.device_id }} | |
| commands: ${{ matrix.success_commands }} | |
| - name: Check logs for successful command | |
| uses: ./.github/actions/assert-log-contains | |
| with: | |
| log_file: ${{ matrix.log_file }} | |
| patterns: ${{ matrix.success_patterns }} | |
| - name: Send failing command | |
| uses: ./.github/actions/send-command | |
| with: | |
| trigger_url: ${{ vars.IT_SEND_COMMAND_TRIGGER_URL }} | |
| device_id: ${{ steps.config.outputs.device_id }} | |
| commands: ${{ matrix.failure_commands }} | |
| - name: Check logs for error handling | |
| uses: ./.github/actions/assert-log-contains | |
| with: | |
| log_file: ${{ matrix.log_file }} | |
| patterns: Command failed | |
| wait_seconds: "15" | |
| - name: Install integration test binary (old version) | |
| uses: ./.github/actions/run-agent | |
| with: | |
| binary: ${{ matrix.it_binary }} | |
| args: --update --org-id ${{ vars.IT_ORG_ID }} --github-token ${{ secrets.GITHUB_TOKEN }} | |
| - name: Wait for auto updater to trigger and update | |
| uses: ./.github/actions/wait-for-log-line | |
| with: | |
| log_file: ${{ matrix.log_file }} | |
| pattern: Updating agent | |
| - name: Verify auto update completed | |
| uses: ./.github/actions/verify-auto-update | |
| with: | |
| log_file: ${{ matrix.log_file }} | |
| - name: Update logging level to debug | |
| uses: ./.github/actions/run-agent | |
| with: | |
| binary: ${{ matrix.binary }} | |
| args: --update --org-id ${{ vars.IT_ORG_ID }} --logging-level debug --github-token ${{ secrets.GITHUB_TOKEN }} | |
| - name: Send test command (debug) | |
| uses: ./.github/actions/send-command | |
| with: | |
| trigger_url: ${{ vars.IT_SEND_COMMAND_TRIGGER_URL }} | |
| device_id: ${{ steps.config.outputs.device_id }} | |
| commands: ${{ matrix.success_commands }} | |
| - name: Check logs for debug level | |
| uses: ./.github/actions/assert-log-contains | |
| with: | |
| log_file: ${{ matrix.log_file }} | |
| patterns: DEBUG | |
| - name: Stop service | |
| uses: ./.github/actions/stop-service | |
| with: | |
| service: ${{ matrix.service }} | |
| - name: Delete log file | |
| uses: ./.github/actions/delete-log | |
| with: | |
| log_file: ${{ matrix.log_file }} | |
| - name: Update agent (no auto updates) | |
| uses: ./.github/actions/run-agent | |
| with: | |
| binary: ${{ matrix.binary }} | |
| args: --update --org-id ${{ vars.IT_ORG_ID }} --no-auto-updates ${{ matrix.no_auto_updates_extra }} --github-token ${{ secrets.GITHUB_TOKEN }} | |
| - name: Check logs for no auto updater | |
| uses: ./.github/actions/assert-log-missing | |
| with: | |
| log_file: ${{ matrix.log_file }} | |
| pattern: Starting auto updater | |
| wait_for_file_seconds: "30" | |
| - name: Send test command (windows postback verification) | |
| if: matrix.os == 'windows-latest' | |
| uses: ./.github/actions/send-command | |
| with: | |
| trigger_url: ${{ vars.IT_SEND_COMMAND_TRIGGER_URL }} | |
| device_id: ${{ steps.config.outputs.device_id }} | |
| commands: ${{ matrix.success_commands }} | |
| - name: Check logs for command received (windows) | |
| if: matrix.os == 'windows-latest' | |
| uses: ./.github/actions/assert-log-contains | |
| with: | |
| log_file: ${{ matrix.log_file }} | |
| patterns: Command completed | |
| - name: Check logs absent postback (windows) | |
| if: matrix.os == 'windows-latest' | |
| uses: ./.github/actions/assert-log-missing | |
| with: | |
| log_file: ${{ matrix.log_file }} | |
| pattern: Postback already sent | |
| - name: Update agent with syslog | |
| uses: ./.github/actions/run-agent | |
| with: | |
| binary: ${{ matrix.binary }} | |
| args: --update --org-id ${{ vars.IT_ORG_ID }} --syslog --github-token ${{ secrets.GITHUB_TOKEN }} | |
| - name: Send test command (syslog) | |
| uses: ./.github/actions/send-command | |
| with: | |
| trigger_url: ${{ vars.IT_SEND_COMMAND_TRIGGER_URL }} | |
| device_id: ${{ steps.config.outputs.device_id }} | |
| commands: ${{ matrix.success_commands }} | |
| - name: Check syslog for command completed | |
| uses: ./.github/actions/assert-syslog-contains | |
| with: | |
| service: ${{ matrix.service }} | |
| pattern: Command completed | |
| # ---- MQTT reconnection scenario ---- | |
| # Force a transient broker outage and verify the agent tears down, backs | |
| # off, resubscribes, and resumes command delivery exactly once. Counts are | |
| # captured up front and compared as deltas because the log already contains | |
| # "Subscribed to messages"/"Command completed" lines from earlier cycles | |
| # (the service has restarted several times by now and the log is not reset | |
| # while the service holds it open). | |
| - name: Capture reconnect baseline counts | |
| id: reconnect_baseline | |
| shell: pwsh | |
| env: | |
| LOG_FILE: ${{ matrix.log_file }} | |
| run: | | |
| $content = Get-Content $env:LOG_FILE -Raw | |
| $subscribed = ([regex]::Matches($content, [regex]::Escape("Subscribed to messages"))).Count | |
| $completed = ([regex]::Matches($content, [regex]::Escape("Command completed"))).Count | |
| "subscribed=$subscribed" >> $env:GITHUB_OUTPUT | |
| "completed=$completed" >> $env:GITHUB_OUTPUT | |
| Write-Output "Baseline counts -> subscribed=$subscribed completed=$completed" | |
| - name: Disrupt broker connection | |
| uses: ./.github/actions/disrupt-connection | |
| with: | |
| mode: block | |
| host: ${{ steps.config.outputs.azure_iot_hub_host }} | |
| - name: Wait for connection lost detection | |
| uses: ./.github/actions/wait-for-log-line | |
| with: | |
| log_file: ${{ matrix.log_file }} | |
| pattern: Connection lost | |
| max_attempts: "60" | |
| interval_seconds: "2" | |
| - name: Assert connection lost and reconnect/backoff activity | |
| uses: ./.github/actions/assert-log-contains | |
| with: | |
| log_file: ${{ matrix.log_file }} | |
| patterns: | | |
| Connection lost | |
| Reconnecting in | |
| Reconnecting... | |
| wait_seconds: "10" | |
| - name: Restore broker connection | |
| if: always() | |
| uses: ./.github/actions/disrupt-connection | |
| with: | |
| mode: restore | |
| host: ${{ steps.config.outputs.azure_iot_hub_host }} | |
| - name: Wait for fresh subscription after reconnect | |
| shell: pwsh | |
| env: | |
| LOG_FILE: ${{ matrix.log_file }} | |
| BASELINE: ${{ steps.reconnect_baseline.outputs.subscribed }} | |
| run: | | |
| $baseline = [int]$env:BASELINE | |
| for ($i = 1; $i -le 60; $i++) { | |
| $content = Get-Content $env:LOG_FILE -Raw -ErrorAction SilentlyContinue | |
| $count = if ($content) { ([regex]::Matches($content, [regex]::Escape("Subscribed to messages"))).Count } else { 0 } | |
| if ($count -gt $baseline) { | |
| Write-Output "Agent resubscribed after reconnect (count $count > baseline $baseline) after ~$($i * 2)s" | |
| exit 0 | |
| } | |
| Start-Sleep -Seconds 2 | |
| } | |
| Write-Error "Agent did not resubscribe after reconnect (subscribed count stayed at $baseline)" | |
| exit 1 | |
| - name: Send command after reconnect | |
| uses: ./.github/actions/send-command | |
| with: | |
| trigger_url: ${{ vars.IT_SEND_COMMAND_TRIGGER_URL }} | |
| device_id: ${{ steps.config.outputs.device_id }} | |
| commands: ${{ matrix.success_commands }} | |
| - name: Assert command executed exactly once after reconnect | |
| shell: pwsh | |
| env: | |
| LOG_FILE: ${{ matrix.log_file }} | |
| BASELINE: ${{ steps.reconnect_baseline.outputs.completed }} | |
| run: | | |
| $baseline = [int]$env:BASELINE | |
| $observed = $baseline | |
| # Wait for the post-reconnect command to complete. | |
| for ($i = 1; $i -le 30; $i++) { | |
| Start-Sleep -Seconds 2 | |
| $content = Get-Content $env:LOG_FILE -Raw -ErrorAction SilentlyContinue | |
| $observed = if ($content) { ([regex]::Matches($content, [regex]::Escape("Command completed"))).Count } else { 0 } | |
| if ($observed -gt $baseline) { break } | |
| } | |
| if (($observed - $baseline) -lt 1) { | |
| Write-Error "Post-reconnect command never completed (count stayed at $baseline)" | |
| exit 1 | |
| } | |
| # Allow a brief window for any duplicate delivery to surface, then | |
| # require the delta to be exactly one - guarding against re-delivery of | |
| # the buffered message on a non-clean reconnected session. | |
| Start-Sleep -Seconds 10 | |
| $content = Get-Content $env:LOG_FILE -Raw | |
| $final = ([regex]::Matches($content, [regex]::Escape("Command completed"))).Count | |
| $delta = $final - $baseline | |
| Write-Output "Post-reconnect 'Command completed' delta: $delta (baseline $baseline, final $final)" | |
| if ($delta -ne 1) { | |
| Write-Error "Expected exactly one post-reconnect 'Command completed', got $delta (duplicate delivery?)" | |
| exit 1 | |
| } | |
| Write-Output "Confirmed exactly one post-reconnect command execution" | |
| # ---- Withheld-SUBACK scenario (sc-106107) ---- | |
| # The reconnection scenario above severs the connection, which keepalive | |
| # detects and the agent handles as an ordinary reconnect. This one covers | |
| # the harder case it cannot reach: a broker that stays alive - completing | |
| # the TLS handshake, answering CONNECT with CONNACK, and answering every | |
| # PINGREQ - while never sending SUBACK. That is what Azure IoT Hub does when | |
| # it throttles a device, and what a middlebox that half-opens a connection | |
| # produces. Before the fix it left the agent connected but never subscribed, | |
| # silently running no commands and unable to honor a stop; now the subscribe | |
| # wait is bounded and stop-interruptible, so the agent fails cleanly, backs | |
| # off, and recovers on a later cycle once the broker starts acknowledging. | |
| # Counts are compared as deltas because the log already carries lines from | |
| # earlier cycles. | |
| - name: Capture SUBACK-withheld baseline counts | |
| id: suback_baseline | |
| shell: pwsh | |
| env: | |
| LOG_FILE: ${{ matrix.log_file }} | |
| run: | | |
| $content = Get-Content $env:LOG_FILE -Raw -ErrorAction SilentlyContinue | |
| function Get-PatternCount($text, $needle) { | |
| if ($text) { ([regex]::Matches($text, [regex]::Escape($needle))).Count } else { 0 } | |
| } | |
| $subscribed = Get-PatternCount $content "Subscribed to messages" | |
| $timedOut = Get-PatternCount $content "Failed to subscribe: timed out waiting for broker acknowledgement" | |
| $backoffs = Get-PatternCount $content "Reconnecting in" | |
| "subscribed=$subscribed" >> $env:GITHUB_OUTPUT | |
| "timed_out=$timedOut" >> $env:GITHUB_OUTPUT | |
| "backoffs=$backoffs" >> $env:GITHUB_OUTPUT | |
| Write-Output "Baseline -> subscribed=$subscribed timed_out=$timedOut backoffs=$backoffs" | |
| # Read off a logged path rather than re-deriving the platform path; see the | |
| # fuller note on the bounded-output scenario's copy of this step. | |
| - name: Resolve the scripts directory (SUBACK scenario) | |
| id: suback_scripts_dir | |
| shell: pwsh | |
| env: | |
| LOG_FILE: ${{ matrix.log_file }} | |
| run: | | |
| $content = Get-Content $env:LOG_FILE -Raw -ErrorAction SilentlyContinue | |
| $found = if ($content) { [regex]::Matches($content, 'Command saved to[^\r\n]*path=(?<p>\S+)') } else { @() } | |
| if ($found.Count -eq 0) { | |
| Write-Error "No 'Command saved to' line in the log; cannot resolve the scripts directory" | |
| exit 1 | |
| } | |
| $dir = Split-Path -Parent $found[$found.Count - 1].Groups['p'].Value.Trim('"') | |
| "path=$dir" >> $env:GITHUB_OUTPUT | |
| Write-Output "Scripts directory: $dir" | |
| - name: Snapshot temp script files before the withheld-SUBACK scenario | |
| uses: ./.github/actions/assert-no-orphaned-scripts | |
| with: | |
| mode: snapshot | |
| scripts_dir: ${{ steps.suback_scripts_dir.outputs.path }} | |
| - name: Start stub broker withholding SUBACK | |
| id: stub_broker | |
| uses: ./.github/actions/stub-broker | |
| with: | |
| mode: start | |
| - name: Point agent at the stub broker | |
| id: stub_host | |
| uses: ./.github/actions/set-broker-host | |
| with: | |
| config_dir: ${{ matrix.config_dir }} | |
| org_id: ${{ vars.IT_ORG_ID }} | |
| host: ${{ steps.stub_broker.outputs.host }} | |
| # --update restarts the service, so the rewritten broker host takes effect. | |
| # The short subscribe timeout keeps each wedged cycle to ~10s so several | |
| # backoff slots are observable inside the job. | |
| - name: Restart agent against the stub broker | |
| uses: ./.github/actions/run-agent | |
| with: | |
| binary: ${{ matrix.binary }} | |
| args: --update --org-id ${{ vars.IT_ORG_ID }} --mqtt-subscribe-timeout-seconds 10 --github-token ${{ secrets.GITHUB_TOKEN }} | |
| - name: Assert bounded subscribe failure and growing backoff | |
| id: assert_suback_withheld | |
| shell: pwsh | |
| env: | |
| LOG_FILE: ${{ matrix.log_file }} | |
| BASE_TIMED_OUT: ${{ steps.suback_baseline.outputs.timed_out }} | |
| BASE_BACKOFFS: ${{ steps.suback_baseline.outputs.backoffs }} | |
| BASE_SUBSCRIBED: ${{ steps.suback_baseline.outputs.subscribed }} | |
| run: | | |
| $baseTimedOut = [int]$env:BASE_TIMED_OUT | |
| $baseBackoffs = [int]$env:BASE_BACKOFFS | |
| $baseSubscribed = [int]$env:BASE_SUBSCRIBED | |
| $needle = "Failed to subscribe: timed out waiting for broker acknowledgement" | |
| # Two wedged cycles plus their backoff waits take roughly 10+2+10+4s. | |
| $content = "" | |
| for ($i = 1; $i -le 60; $i++) { | |
| $content = Get-Content $env:LOG_FILE -Raw -ErrorAction SilentlyContinue | |
| $timedOut = if ($content) { ([regex]::Matches($content, [regex]::Escape($needle))).Count } else { 0 } | |
| $backoffs = if ($content) { ([regex]::Matches($content, [regex]::Escape("Reconnecting in"))).Count } else { 0 } | |
| if (($timedOut - $baseTimedOut) -ge 2 -and ($backoffs - $baseBackoffs) -ge 2) { break } | |
| Start-Sleep -Seconds 2 | |
| } | |
| $timedOut = if ($content) { ([regex]::Matches($content, [regex]::Escape($needle))).Count } else { 0 } | |
| if (($timedOut - $baseTimedOut) -lt 2) { | |
| Write-Error "Expected at least two bounded subscribe timeouts, got $($timedOut - $baseTimedOut)" | |
| exit 1 | |
| } | |
| Write-Output "Bounded subscribe timeouts observed: $($timedOut - $baseTimedOut)" | |
| # The agent must not have subscribed: a withheld SUBACK means no | |
| # subscription, and a "Subscribed to messages" line here would mean the | |
| # stub broker is not the broker the agent reached. | |
| $subscribed = ([regex]::Matches($content, [regex]::Escape("Subscribed to messages"))).Count | |
| if ($subscribed -ne $baseSubscribed) { | |
| Write-Error "Agent reported a subscription against a broker that withholds SUBACK" | |
| exit 1 | |
| } | |
| # The backoff must not be cleared by a timed-out subscribe: a throttling | |
| # broker needs progressively longer waits, not a tight reconnect loop. | |
| # Go renders a duration as concatenated unit components ("4.1s", | |
| # "1m4s"), so each component is summed rather than parsed as one number. | |
| function ConvertTo-Seconds([string]$value) { | |
| $total = 0.0 | |
| foreach ($m in [regex]::Matches($value, '(?<n>[0-9.]+)(?<u>ms|us|ns|h|m|s)')) { | |
| $n = [double]$m.Groups['n'].Value | |
| switch ($m.Groups['u'].Value) { | |
| 'ns' { $total += $n / 1e9 } | |
| 'us' { $total += $n / 1e6 } | |
| 'ms' { $total += $n / 1e3 } | |
| 's' { $total += $n } | |
| 'm' { $total += $n * 60 } | |
| 'h' { $total += $n * 3600 } | |
| } | |
| } | |
| return $total | |
| } | |
| $waits = [regex]::Matches($content, 'Reconnecting in: timeout=(?<t>[0-9.a-z]+)') | | |
| ForEach-Object { ConvertTo-Seconds $_.Groups['t'].Value } | |
| $new = @($waits | Select-Object -Skip $baseBackoffs) | |
| if ($new.Count -lt 2) { | |
| Write-Error "Expected at least two reconnect waits after the subscribe timeouts, got $($new.Count)" | |
| exit 1 | |
| } | |
| Write-Output "Reconnect waits after the subscribe timeouts: $($new -join ', ')" | |
| if ($new[1] -le $new[0]) { | |
| Write-Error "Reconnect backoff did not grow ($($new[0]) then $($new[1])); a timed-out subscribe must not clear it" | |
| exit 1 | |
| } | |
| Write-Output "Confirmed the reconnect backoff grows after a withheld SUBACK" | |
| # What the agent actually did against the stub is only visible in its own | |
| # log, and the assertion above deliberately reads counts rather than lines. | |
| # Dumping the tail on failure makes a fixture problem (never reached the | |
| # broker at all) distinguishable from a real regression (reached it and | |
| # blocked) without re-running the job. | |
| - name: Dump agent log on withheld-SUBACK failure | |
| if: failure() && steps.assert_suback_withheld.outcome == 'failure' | |
| shell: pwsh | |
| env: | |
| LOG_FILE: ${{ matrix.log_file }} | |
| run: | | |
| Write-Output "---- last 100 lines of $($env:LOG_FILE) ----" | |
| Get-Content $env:LOG_FILE -Tail 100 -ErrorAction SilentlyContinue | |
| # The original defect made this impossible: with the cycle parked in | |
| # token.Wait() the stop signal was never reached, the platform waited out | |
| # its stop deadline (30s on the Windows SCM) and force-killed the process. | |
| - name: Assert the service stops promptly while wedged on the stub broker | |
| shell: pwsh | |
| env: | |
| LOG_FILE: ${{ matrix.log_file }} | |
| SERVICE: ${{ matrix.service }} | |
| run: | | |
| function Get-StopCount { | |
| $content = Get-Content $env:LOG_FILE -Raw -ErrorAction SilentlyContinue | |
| if ($content) { ([regex]::Matches($content, [regex]::Escape("Service stopped"))).Count } else { 0 } | |
| } | |
| # Counted here rather than reusing the scenario-wide baseline: the | |
| # --update that pointed the agent at the stub broker restarts the | |
| # service, and that restart logs its own "Service stopped". Measured | |
| # against the older baseline the delta was already satisfied before this | |
| # stop was even issued, so the assertion "passed" in 0.2s without | |
| # observing the stop it exists to test. | |
| $before = Get-StopCount | |
| Write-Output "Service stopped lines before issuing the stop: $before" | |
| $sw = [System.Diagnostics.Stopwatch]::StartNew() | |
| if ($IsWindows) { | |
| sc.exe stop $env:SERVICE | Out-Null | |
| } elseif ($IsLinux) { | |
| sudo systemctl stop $env:SERVICE | |
| } else { | |
| # Bare label, not a "system/<label>" service target. launchctl's | |
| # `stop` is a legacy subcommand that resolves a label in the current | |
| # domain, so the target form is taken as a literal label, matches | |
| # nothing, and exits 3 (ESRCH) without ever signalling the agent. | |
| # This mirrors what the agent's own darwinService.Stop does. `stop` | |
| # leaves the job loaded, so the later start-service can run it again. | |
| sudo launchctl stop $env:SERVICE | |
| } | |
| # launchctl exits non-zero in situations that are not failures here - | |
| # the repo's own stop-service action already guards it with `|| true` - | |
| # and the pwsh shell ends by exiting with $LASTEXITCODE, which failed | |
| # this step on macOS even after the assertion below had passed. Report | |
| # the code and clear it; whether the stop was honored is decided by the | |
| # agent's log, not by the service manager's exit status. | |
| Write-Output "Stop command exit code: $LASTEXITCODE" | |
| $global:LASTEXITCODE = 0 | |
| # A clean exit runs the agent's deferred teardown, whose last act is the | |
| # "Service stopped" line; a force-kill past the stop deadline never | |
| # produces one. | |
| $stopped = $false | |
| while ($sw.Elapsed.TotalSeconds -lt 30) { | |
| if ((Get-StopCount) -gt $before) { $stopped = $true; break } | |
| Start-Sleep -Milliseconds 500 | |
| } | |
| $sw.Stop() | |
| if (-not $stopped) { | |
| # Both halves matter when this fails: the agent log says whether the | |
| # stop was received and ignored, and the service manager says whether | |
| # it was ever delivered. | |
| Write-Output "---- last 60 lines of the agent log ----" | |
| Get-Content $env:LOG_FILE -Tail 60 -ErrorAction SilentlyContinue | |
| Write-Output "---- service manager state ----" | |
| if ($IsWindows) { | |
| sc.exe query $env:SERVICE | |
| } elseif ($IsLinux) { | |
| sudo systemctl status $env:SERVICE --no-pager | |
| } else { | |
| # print, unlike stop, is a modern subcommand and does take the | |
| # system/<label> service target. | |
| sudo launchctl print "system/$($env:SERVICE)" | |
| } | |
| $global:LASTEXITCODE = 0 | |
| Write-Error "Service did not log a clean stop within 30s while wedged on a withholding broker" | |
| exit 1 | |
| } | |
| Write-Output "Service stopped cleanly after $([math]::Round($sw.Elapsed.TotalSeconds, 1))s while wedged" | |
| exit 0 | |
| - name: Assert no orphaned scripts after the wedged stop | |
| uses: ./.github/actions/assert-no-orphaned-scripts | |
| with: | |
| mode: assert | |
| scripts_dir: ${{ steps.suback_scripts_dir.outputs.path }} | |
| - name: Restart the service against the still-withholding broker | |
| uses: ./.github/actions/start-service | |
| with: | |
| service: ${{ matrix.service }} | |
| - name: Wait for the agent to wedge on the stub broker again | |
| uses: ./.github/actions/wait-for-log-line | |
| with: | |
| log_file: ${{ matrix.log_file }} | |
| pattern: "Failed to subscribe: timed out waiting for broker acknowledgement" | |
| max_attempts: "60" | |
| interval_seconds: "2" | |
| # Flipped on the live connection - the stub re-reads its mode per packet - | |
| # so recovery is the agent's own next reconnect cycle, not a restart. | |
| - name: Switch stub broker to acknowledge SUBACK | |
| uses: ./.github/actions/stub-broker | |
| with: | |
| mode: ack | |
| - name: Assert the agent recovers on a later cycle | |
| shell: pwsh | |
| env: | |
| LOG_FILE: ${{ matrix.log_file }} | |
| BASELINE: ${{ steps.suback_baseline.outputs.subscribed }} | |
| run: | | |
| $baseline = [int]$env:BASELINE | |
| for ($i = 1; $i -le 60; $i++) { | |
| $content = Get-Content $env:LOG_FILE -Raw -ErrorAction SilentlyContinue | |
| $count = if ($content) { ([regex]::Matches($content, [regex]::Escape("Subscribed to messages"))).Count } else { 0 } | |
| if ($count -gt $baseline) { | |
| Write-Output "Agent subscribed on a later cycle once SUBACK arrived (count $count > baseline $baseline) after ~$($i * 2)s" | |
| exit 0 | |
| } | |
| Start-Sleep -Seconds 2 | |
| } | |
| Write-Error "Agent never subscribed after the stub broker started acknowledging" | |
| exit 1 | |
| - name: Restore the real broker host | |
| if: always() && steps.stub_host.outputs.previous_host != '' | |
| uses: ./.github/actions/set-broker-host | |
| with: | |
| config_dir: ${{ matrix.config_dir }} | |
| org_id: ${{ vars.IT_ORG_ID }} | |
| host: ${{ steps.stub_host.outputs.previous_host }} | |
| - name: Stop stub broker | |
| if: always() | |
| uses: ./.github/actions/stub-broker | |
| with: | |
| mode: stop | |
| - name: Restart agent against the real broker | |
| if: always() && steps.stub_host.outputs.previous_host != '' | |
| uses: ./.github/actions/run-agent | |
| with: | |
| binary: ${{ matrix.binary }} | |
| args: --update --org-id ${{ vars.IT_ORG_ID }} --mqtt-subscribe-timeout-seconds 30 --github-token ${{ secrets.GITHUB_TOKEN }} | |
| - name: Wait for resubscription to the real broker | |
| if: always() && steps.stub_host.outputs.previous_host != '' | |
| uses: ./.github/actions/wait-for-log-line | |
| with: | |
| log_file: ${{ matrix.log_file }} | |
| pattern: Subscribed to messages | |
| max_attempts: "60" | |
| interval_seconds: "2" | |
| # ---- Per-command execution timeout scenario (sc-103835) ---- | |
| # Configure a short per-command timeout, dispatch a script that sleeps well | |
| # beyond it, and confirm the agent kills the command (logging a timeout) and | |
| # that a subsequent ordinary command still completes - i.e. the worker pool | |
| # recovered instead of staying wedged. Counts are compared as deltas because | |
| # the log already carries lines from earlier cycles. | |
| - name: Enable short command timeout | |
| uses: ./.github/actions/run-agent | |
| with: | |
| binary: ${{ matrix.binary }} | |
| args: --update --org-id ${{ vars.IT_ORG_ID }} --command-timeout-seconds 5 --github-token ${{ secrets.GITHUB_TOKEN }} | |
| - name: Wait for fresh subscription after timeout update | |
| uses: ./.github/actions/wait-for-log-line | |
| with: | |
| log_file: ${{ matrix.log_file }} | |
| pattern: Subscribed to messages | |
| max_attempts: "60" | |
| interval_seconds: "2" | |
| - name: Capture command-timeout baseline counts | |
| id: timeout_baseline | |
| shell: pwsh | |
| env: | |
| LOG_FILE: ${{ matrix.log_file }} | |
| run: | | |
| $content = Get-Content $env:LOG_FILE -Raw -ErrorAction SilentlyContinue | |
| $timedOut = if ($content) { ([regex]::Matches($content, [regex]::Escape("Command timed out"))).Count } else { 0 } | |
| $completed = if ($content) { ([regex]::Matches($content, [regex]::Escape("Command completed"))).Count } else { 0 } | |
| "timed_out=$timedOut" >> $env:GITHUB_OUTPUT | |
| "completed=$completed" >> $env:GITHUB_OUTPUT | |
| Write-Output "Baseline counts -> timed_out=$timedOut completed=$completed" | |
| - name: Send hanging command | |
| uses: ./.github/actions/send-command | |
| with: | |
| trigger_url: ${{ vars.IT_SEND_COMMAND_TRIGGER_URL }} | |
| device_id: ${{ steps.config.outputs.device_id }} | |
| commands: ${{ matrix.timeout_commands }} | |
| - name: Assert hanging command was killed by the timeout | |
| shell: pwsh | |
| env: | |
| LOG_FILE: ${{ matrix.log_file }} | |
| BASELINE: ${{ steps.timeout_baseline.outputs.timed_out }} | |
| run: | | |
| $baseline = [int]$env:BASELINE | |
| for ($i = 1; $i -le 30; $i++) { | |
| Start-Sleep -Seconds 2 | |
| $content = Get-Content $env:LOG_FILE -Raw -ErrorAction SilentlyContinue | |
| $count = if ($content) { ([regex]::Matches($content, [regex]::Escape("Command timed out"))).Count } else { 0 } | |
| if ($count -gt $baseline) { | |
| Write-Output "Command timed out as expected (count $count > baseline $baseline) after ~$($i * 2)s" | |
| exit 0 | |
| } | |
| } | |
| Write-Error "Hanging command was not killed by the per-command timeout (count stayed at $baseline)" | |
| exit 1 | |
| - name: Send command after timeout | |
| uses: ./.github/actions/send-command | |
| with: | |
| trigger_url: ${{ vars.IT_SEND_COMMAND_TRIGGER_URL }} | |
| device_id: ${{ steps.config.outputs.device_id }} | |
| commands: ${{ matrix.success_commands }} | |
| - name: Assert worker pool recovered after timeout | |
| shell: pwsh | |
| env: | |
| LOG_FILE: ${{ matrix.log_file }} | |
| BASELINE: ${{ steps.timeout_baseline.outputs.completed }} | |
| run: | | |
| $baseline = [int]$env:BASELINE | |
| for ($i = 1; $i -le 30; $i++) { | |
| Start-Sleep -Seconds 2 | |
| $content = Get-Content $env:LOG_FILE -Raw -ErrorAction SilentlyContinue | |
| $count = if ($content) { ([regex]::Matches($content, [regex]::Escape("Command completed"))).Count } else { 0 } | |
| if ($count -gt $baseline) { | |
| Write-Output "Worker pool recovered; a later command completed (count $count > baseline $baseline)" | |
| exit 0 | |
| } | |
| } | |
| Write-Error "Worker pool did not process a command after the timeout (count stayed at $baseline)" | |
| exit 1 | |
| # ---- SAS token proactive renewal scenario (sc-103969) ---- | |
| # The integration test binary is built with a short SAS token lifetime | |
| # (sasTokenLifetimeOverrideStr=90s), so the agent must proactively | |
| # reconnect with a freshly minted token a safety margin BEFORE the token | |
| # expires rather than being forcibly disconnected by the broker on expiry. | |
| # Install the IT binary with auto-updates disabled so it stays the running | |
| # service (otherwise the 30s auto-updater would swap it for the real | |
| # release before renewal fires), then confirm: the renewal fires (distinct | |
| # Info log), the agent re-subscribes with the fresh token, and it is | |
| # graceful - no Error "Connection lost" is produced. Deltas are compared | |
| # because earlier cycles already left "Subscribed to messages"/"Connection | |
| # lost" lines in the log. | |
| - name: Install IT binary with short SAS token lifetime | |
| uses: ./.github/actions/run-agent | |
| with: | |
| binary: ${{ matrix.it_binary }} | |
| args: --update --org-id ${{ vars.IT_ORG_ID }} --no-auto-updates ${{ matrix.no_auto_updates_extra }} --github-token ${{ secrets.GITHUB_TOKEN }} | |
| - name: Wait for fresh subscription after SAS lifetime update | |
| uses: ./.github/actions/wait-for-log-line | |
| with: | |
| log_file: ${{ matrix.log_file }} | |
| pattern: Subscribed to messages | |
| max_attempts: "60" | |
| interval_seconds: "2" | |
| - name: Capture SAS renewal baseline counts | |
| id: sas_renewal_baseline | |
| shell: pwsh | |
| env: | |
| LOG_FILE: ${{ matrix.log_file }} | |
| run: | | |
| $content = Get-Content $env:LOG_FILE -Raw -ErrorAction SilentlyContinue | |
| $renewed = if ($content) { ([regex]::Matches($content, [regex]::Escape("Renewing SAS token before expiry"))).Count } else { 0 } | |
| $subscribed = if ($content) { ([regex]::Matches($content, [regex]::Escape("Subscribed to messages"))).Count } else { 0 } | |
| $lost = if ($content) { ([regex]::Matches($content, [regex]::Escape("Connection lost"))).Count } else { 0 } | |
| $completed = if ($content) { ([regex]::Matches($content, [regex]::Escape("Command completed"))).Count } else { 0 } | |
| "renewed=$renewed" >> $env:GITHUB_OUTPUT | |
| "subscribed=$subscribed" >> $env:GITHUB_OUTPUT | |
| "lost=$lost" >> $env:GITHUB_OUTPUT | |
| "completed=$completed" >> $env:GITHUB_OUTPUT | |
| Write-Output "Baseline counts -> renewed=$renewed subscribed=$subscribed lost=$lost completed=$completed" | |
| - name: Wait for proactive SAS token renewal | |
| uses: ./.github/actions/wait-for-log-line | |
| with: | |
| log_file: ${{ matrix.log_file }} | |
| pattern: Renewing SAS token before expiry | |
| max_attempts: "60" | |
| interval_seconds: "2" | |
| - name: Assert SAS token renewed and agent resubscribed with fresh token | |
| shell: pwsh | |
| env: | |
| LOG_FILE: ${{ matrix.log_file }} | |
| RENEWED_BASELINE: ${{ steps.sas_renewal_baseline.outputs.renewed }} | |
| SUBSCRIBED_BASELINE: ${{ steps.sas_renewal_baseline.outputs.subscribed }} | |
| run: | | |
| $renewedBaseline = [int]$env:RENEWED_BASELINE | |
| $subscribedBaseline = [int]$env:SUBSCRIBED_BASELINE | |
| for ($i = 1; $i -le 60; $i++) { | |
| $content = Get-Content $env:LOG_FILE -Raw -ErrorAction SilentlyContinue | |
| $renewed = if ($content) { ([regex]::Matches($content, [regex]::Escape("Renewing SAS token before expiry"))).Count } else { 0 } | |
| $subscribed = if ($content) { ([regex]::Matches($content, [regex]::Escape("Subscribed to messages"))).Count } else { 0 } | |
| if (($renewed -gt $renewedBaseline) -and ($subscribed -gt $subscribedBaseline)) { | |
| Write-Output "SAS token renewed (count $renewed > baseline $renewedBaseline) and agent resubscribed (count $subscribed > baseline $subscribedBaseline) after ~$($i * 2)s" | |
| exit 0 | |
| } | |
| Start-Sleep -Seconds 2 | |
| } | |
| Write-Error "Proactive SAS renewal did not fire and resubscribe (renewed stayed <= $renewedBaseline or subscribed stayed <= $subscribedBaseline)" | |
| exit 1 | |
| - name: Assert SAS renewal was graceful (no forced disconnect) | |
| shell: pwsh | |
| env: | |
| LOG_FILE: ${{ matrix.log_file }} | |
| LOST_BASELINE: ${{ steps.sas_renewal_baseline.outputs.lost }} | |
| run: | | |
| $baseline = [int]$env:LOST_BASELINE | |
| $content = Get-Content $env:LOG_FILE -Raw | |
| $lost = ([regex]::Matches($content, [regex]::Escape("Connection lost"))).Count | |
| if ($lost -gt $baseline) { | |
| Write-Error "SAS renewal was not graceful: 'Connection lost' count rose from $baseline to $lost (token expired before renewal fired?)" | |
| exit 1 | |
| } | |
| Write-Output "Confirmed graceful renewal: no new 'Connection lost' (count stayed at $baseline)" | |
| - name: Send command after SAS renewal | |
| uses: ./.github/actions/send-command | |
| with: | |
| trigger_url: ${{ vars.IT_SEND_COMMAND_TRIGGER_URL }} | |
| device_id: ${{ steps.config.outputs.device_id }} | |
| commands: ${{ matrix.success_commands }} | |
| - name: Assert command delivery continues after SAS renewal | |
| shell: pwsh | |
| env: | |
| LOG_FILE: ${{ matrix.log_file }} | |
| BASELINE: ${{ steps.sas_renewal_baseline.outputs.completed }} | |
| run: | | |
| $baseline = [int]$env:BASELINE | |
| for ($i = 1; $i -le 30; $i++) { | |
| Start-Sleep -Seconds 2 | |
| $content = Get-Content $env:LOG_FILE -Raw -ErrorAction SilentlyContinue | |
| $count = if ($content) { ([regex]::Matches($content, [regex]::Escape("Command completed"))).Count } else { 0 } | |
| if ($count -gt $baseline) { | |
| Write-Output "Command delivery continues after renewal (count $count > baseline $baseline)" | |
| exit 0 | |
| } | |
| } | |
| Write-Error "No command completed after SAS renewal (count stayed at $baseline)" | |
| exit 1 | |
| # ---- Bounded command output scenario (sc-106105) ---- | |
| # A command's stdout and stderr used to be buffered whole in memory, so the | |
| # agent's heap tracked however much a script decided to write and a verbose | |
| # one could OOM-kill the service. Configure a deliberately small ceiling, | |
| # flood it by three orders of magnitude, and assert the two properties that | |
| # matter: the agent's RSS stays near the ceiling instead of near the output | |
| # size, and the discarded output is reported rather than silently dropped. | |
| # | |
| # The release binary is installed first with the per-command timeout raised | |
| # well past the floods' runtime, because the earlier timeout scenario left a | |
| # 5s deadline in the config that would kill these commands mid-write, and | |
| # the SAS scenario left the IT binary running with a 90s token lifetime | |
| # whose reconnect would cancel them. --logging-level is deliberately not | |
| # passed: it resets to the default (Info), which keeps the Warn under test | |
| # visible while leaving the debug handler that dumps whole command outputs | |
| # into the log switched off. --disable-agent-postback is likewise not | |
| # passed (unlike the sweep scenario) so the truncated result actually | |
| # traverses the postback path on every platform. | |
| # | |
| # Coverage note: these steps assert on the agent log, which is where the | |
| # byte counts are observable on the endpoint. The same counts are what the | |
| # postback carries as truncated/output_bytes_produced/output_bytes_kept - | |
| # both come from one value computed once per command - but the postback body | |
| # is never logged, so confirming the workflow's received payload stays a | |
| # Rewst-side QA step. | |
| - name: Resolve the scripts directory | |
| id: scripts_dir | |
| shell: pwsh | |
| env: | |
| LOG_FILE: ${{ matrix.log_file }} | |
| run: | | |
| # Read the directory off a "Command saved to" line rather than | |
| # re-deriving the platform path: the service's temp directory is not the | |
| # runner's, notably root's private TMPDIR on macOS. Many earlier | |
| # scenarios have already logged one. | |
| $content = Get-Content $env:LOG_FILE -Raw -ErrorAction SilentlyContinue | |
| $found = if ($content) { [regex]::Matches($content, 'Command saved to[^\r\n]*path=(?<p>\S+)') } else { @() } | |
| if ($found.Count -eq 0) { | |
| Write-Error "No 'Command saved to' line in the log; cannot resolve the scripts directory" | |
| exit 1 | |
| } | |
| $path = $found[$found.Count - 1].Groups['p'].Value.Trim('"') | |
| $dir = Split-Path -Parent $path | |
| "path=$dir" >> $env:GITHUB_OUTPUT | |
| Write-Output "Scripts directory: $dir" | |
| - name: Snapshot temp script files before the output floods | |
| uses: ./.github/actions/assert-no-orphaned-scripts | |
| with: | |
| mode: snapshot | |
| scripts_dir: ${{ steps.scripts_dir.outputs.path }} | |
| # Captured before the update below restarts the service: the restart's own | |
| # "Subscribed to messages" line must land after this snapshot for the delta | |
| # wait to mean anything. | |
| - name: Capture bounded-output baseline counts | |
| id: output_baseline | |
| shell: pwsh | |
| env: | |
| LOG_FILE: ${{ matrix.log_file }} | |
| run: | | |
| $content = Get-Content $env:LOG_FILE -Raw -ErrorAction SilentlyContinue | |
| $subscribed = if ($content) { ([regex]::Matches($content, [regex]::Escape("Subscribed to messages"))).Count } else { 0 } | |
| $truncated = if ($content) { ([regex]::Matches($content, [regex]::Escape("Command output truncated"))).Count } else { 0 } | |
| $completed = if ($content) { ([regex]::Matches($content, [regex]::Escape("Command completed"))).Count } else { 0 } | |
| "subscribed=$subscribed" >> $env:GITHUB_OUTPUT | |
| "truncated=$truncated" >> $env:GITHUB_OUTPUT | |
| "completed=$completed" >> $env:GITHUB_OUTPUT | |
| Write-Output "Baseline counts -> subscribed=$subscribed truncated=$truncated completed=$completed" | |
| - name: Configure a small output ceiling | |
| uses: ./.github/actions/run-agent | |
| with: | |
| binary: ${{ matrix.binary }} | |
| args: --update --org-id ${{ vars.IT_ORG_ID }} --no-auto-updates --max-output-bytes 262144 --command-timeout-seconds 600 --github-token ${{ secrets.GITHUB_TOKEN }} | |
| - name: Assert a non-positive output ceiling is rejected | |
| shell: pwsh | |
| env: | |
| BINARY: ${{ matrix.binary }} | |
| ORG_ID: ${{ vars.IT_ORG_ID }} | |
| run: | | |
| # The bound must not be disablable by configuration: a non-positive | |
| # value is refused outright rather than accepted as "no limit" (a | |
| # hand-edited config falls back to the documented default instead). | |
| foreach ($value in @('0', '-1')) { | |
| if ($IsWindows) { | |
| $out = & "./dist/$env:BINARY" --update --org-id $env:ORG_ID --max-output-bytes $value 2>&1 | Out-String | |
| } else { | |
| $out = & sudo "./dist/$env:BINARY" --update --org-id $env:ORG_ID --max-output-bytes $value 2>&1 | Out-String | |
| } | |
| $code = $LASTEXITCODE | |
| if ($code -eq 0) { | |
| Write-Output $out | |
| Write-Error "--max-output-bytes $value was accepted (exit 0); the bound must not be disablable" | |
| exit 1 | |
| } | |
| if ($out -notmatch 'invalid max-output-bytes: must be a positive integer') { | |
| Write-Output $out | |
| Write-Error "--max-output-bytes $value was rejected without the expected validation message" | |
| exit 1 | |
| } | |
| Write-Output "OK: --max-output-bytes $value rejected (exit $code) with the expected message" | |
| } | |
| # Explicit success: the runner appends "exit $LASTEXITCODE" to pwsh | |
| # steps, and the last thing this step ran was a deliberately failing | |
| # agent invocation, so falling off the end would report that failure as | |
| # the step's own. | |
| exit 0 | |
| - name: Wait for fresh subscription after the output ceiling update | |
| shell: pwsh | |
| env: | |
| LOG_FILE: ${{ matrix.log_file }} | |
| BASELINE: ${{ steps.output_baseline.outputs.subscribed }} | |
| run: | | |
| # A delta, not a bare match: the log already carries many "Subscribed to | |
| # messages" lines, so only a new one proves the restarted agent is | |
| # connected with the new ceiling in effect. | |
| $baseline = [int]$env:BASELINE | |
| for ($i = 1; $i -le 60; $i++) { | |
| $content = Get-Content $env:LOG_FILE -Raw -ErrorAction SilentlyContinue | |
| $count = if ($content) { ([regex]::Matches($content, [regex]::Escape("Subscribed to messages"))).Count } else { 0 } | |
| if ($count -gt $baseline) { | |
| Write-Output "Agent subscribed with the new output ceiling (count $count > baseline $baseline) after ~$($i * 2)s" | |
| exit 0 | |
| } | |
| Start-Sleep -Seconds 2 | |
| } | |
| Write-Error "Agent did not subscribe after the output ceiling update (count stayed at $baseline)" | |
| exit 1 | |
| - name: Send stdout flood command | |
| uses: ./.github/actions/send-command | |
| with: | |
| trigger_url: ${{ vars.IT_SEND_COMMAND_TRIGGER_URL }} | |
| device_id: ${{ steps.config.outputs.device_id }} | |
| commands: ${{ matrix.verbose_commands }} | |
| - name: Assert the stdout flood was bounded | |
| uses: ./.github/actions/assert-output-bounded | |
| with: | |
| service: ${{ matrix.service }} | |
| log_file: ${{ matrix.log_file }} | |
| baseline_truncations: ${{ steps.output_baseline.outputs.truncated }} | |
| expected_ceiling_bytes: "262144" | |
| # At least the whole ceiling, since stdout alone floods it. The upper | |
| # bound carries 4 KiB of headroom rather than being exact because the | |
| # shell contributes a preamble of its own that is not this scenario's to | |
| # control - on Windows the run deliberately injects a | |
| # PROFILE_NOISE_<guid> marker into the all-users PowerShell profile, | |
| # which every agent-spawned PowerShell echoes. What the bound has to | |
| # catch is a stream that was not capped at all, and that would land | |
| # near the 200 MiB produced, not a few bytes over. | |
| min_kept_bytes: "262144" | |
| max_kept_bytes: "266240" | |
| min_produced_bytes: "209715200" | |
| max_rss_mb: "250" | |
| - name: Assert the flooding command still succeeded | |
| shell: pwsh | |
| env: | |
| LOG_FILE: ${{ matrix.log_file }} | |
| BASELINE: ${{ steps.output_baseline.outputs.completed }} | |
| run: | | |
| # Being verbose is not a failure: the command runs to completion with the | |
| # excess discarded, so it reports "Command completed", not "Command | |
| # failed" or "Command timed out". | |
| $baseline = [int]$env:BASELINE | |
| for ($i = 1; $i -le 30; $i++) { | |
| $content = Get-Content $env:LOG_FILE -Raw -ErrorAction SilentlyContinue | |
| $count = if ($content) { ([regex]::Matches($content, [regex]::Escape("Command completed"))).Count } else { 0 } | |
| if ($count -gt $baseline) { | |
| Write-Output "Flooding command completed normally (count $count > baseline $baseline)" | |
| exit 0 | |
| } | |
| Start-Sleep -Seconds 2 | |
| } | |
| Write-Error "The flooding command never completed (count stayed at $baseline): it was killed for being verbose" | |
| exit 1 | |
| - name: Capture small-output baseline counts | |
| id: small_output_baseline | |
| shell: pwsh | |
| env: | |
| LOG_FILE: ${{ matrix.log_file }} | |
| run: | | |
| $content = Get-Content $env:LOG_FILE -Raw -ErrorAction SilentlyContinue | |
| $truncated = if ($content) { ([regex]::Matches($content, [regex]::Escape("Command output truncated"))).Count } else { 0 } | |
| $completed = if ($content) { ([regex]::Matches($content, [regex]::Escape("Command completed"))).Count } else { 0 } | |
| "truncated=$truncated" >> $env:GITHUB_OUTPUT | |
| "completed=$completed" >> $env:GITHUB_OUTPUT | |
| Write-Output "Baseline counts -> truncated=$truncated completed=$completed" | |
| - name: Send ordinary command after the flood | |
| uses: ./.github/actions/send-command | |
| with: | |
| trigger_url: ${{ vars.IT_SEND_COMMAND_TRIGGER_URL }} | |
| device_id: ${{ steps.config.outputs.device_id }} | |
| commands: ${{ matrix.success_commands }} | |
| - name: Assert output below the ceiling is untouched and the worker recovered | |
| shell: pwsh | |
| env: | |
| LOG_FILE: ${{ matrix.log_file }} | |
| COMPLETED_BASELINE: ${{ steps.small_output_baseline.outputs.completed }} | |
| TRUNCATED_BASELINE: ${{ steps.small_output_baseline.outputs.truncated }} | |
| run: | | |
| # Two things at once: the worker the flood used was released (a later | |
| # command completes), and a command whose output fits under the ceiling | |
| # is not flagged - the bound only engages on the output that exceeds it. | |
| $completedBaseline = [int]$env:COMPLETED_BASELINE | |
| $truncatedBaseline = [int]$env:TRUNCATED_BASELINE | |
| $completed = $completedBaseline | |
| for ($i = 1; $i -le 30; $i++) { | |
| Start-Sleep -Seconds 2 | |
| $content = Get-Content $env:LOG_FILE -Raw -ErrorAction SilentlyContinue | |
| $completed = if ($content) { ([regex]::Matches($content, [regex]::Escape("Command completed"))).Count } else { 0 } | |
| if ($completed -gt $completedBaseline) { break } | |
| } | |
| if ($completed -le $completedBaseline) { | |
| Write-Error "No command completed after the flood (count stayed at $completedBaseline): the worker was not released" | |
| exit 1 | |
| } | |
| Write-Output "Worker released; a later command completed (count $completed > baseline $completedBaseline)" | |
| $content = Get-Content $env:LOG_FILE -Raw | |
| $truncated = ([regex]::Matches($content, [regex]::Escape("Command output truncated"))).Count | |
| if ($truncated -ne $truncatedBaseline) { | |
| Write-Error "A small-output command was flagged as truncated (count rose from $truncatedBaseline to $truncated)" | |
| exit 1 | |
| } | |
| Write-Output "Confirmed small-output command was not truncated (count stayed at $truncatedBaseline)" | |
| - name: Capture stderr-flood baseline counts | |
| id: stderr_flood_baseline | |
| shell: pwsh | |
| env: | |
| LOG_FILE: ${{ matrix.log_file }} | |
| run: | | |
| $content = Get-Content $env:LOG_FILE -Raw -ErrorAction SilentlyContinue | |
| $truncated = if ($content) { ([regex]::Matches($content, [regex]::Escape("Command output truncated"))).Count } else { 0 } | |
| "truncated=$truncated" >> $env:GITHUB_OUTPUT | |
| Write-Output "Baseline counts -> truncated=$truncated" | |
| - name: Send stderr flood command | |
| uses: ./.github/actions/send-command | |
| with: | |
| trigger_url: ${{ vars.IT_SEND_COMMAND_TRIGGER_URL }} | |
| device_id: ${{ steps.config.outputs.device_id }} | |
| commands: ${{ matrix.verbose_stderr_commands }} | |
| - name: Assert stderr is bounded independently of stdout | |
| uses: ./.github/actions/assert-output-bounded | |
| with: | |
| service: ${{ matrix.service }} | |
| log_file: ${{ matrix.log_file }} | |
| baseline_truncations: ${{ steps.stderr_flood_baseline.outputs.truncated }} | |
| expected_ceiling_bytes: "262144" | |
| # Above the ceiling on purpose: the script floods stderr to its full | |
| # ceiling AND writes a short stdout line, so the kept total can only | |
| # exceed the ceiling if the two streams have separate budgets. A shared | |
| # budget would cap the total at 262144 and starve one of them. The upper | |
| # bound has the same 4 KiB of headroom as the stdout flood, for the same | |
| # reason: the stdout side carries the shell's preamble as well as the | |
| # scenario's own line. | |
| min_kept_bytes: "262145" | |
| max_kept_bytes: "266240" | |
| min_produced_bytes: "209715200" | |
| max_rss_mb: "250" | |
| # Captured before the update below restarts the service, for the same | |
| # reason as the bounded-output baseline. | |
| - name: Capture timeout-composition baseline counts | |
| id: compose_baseline | |
| shell: pwsh | |
| env: | |
| LOG_FILE: ${{ matrix.log_file }} | |
| run: | | |
| $content = Get-Content $env:LOG_FILE -Raw -ErrorAction SilentlyContinue | |
| $subscribed = if ($content) { ([regex]::Matches($content, [regex]::Escape("Subscribed to messages"))).Count } else { 0 } | |
| $truncated = if ($content) { ([regex]::Matches($content, [regex]::Escape("Command output truncated"))).Count } else { 0 } | |
| $timedOut = if ($content) { ([regex]::Matches($content, [regex]::Escape("Command timed out"))).Count } else { 0 } | |
| $completed = if ($content) { ([regex]::Matches($content, [regex]::Escape("Command completed"))).Count } else { 0 } | |
| "subscribed=$subscribed" >> $env:GITHUB_OUTPUT | |
| "truncated=$truncated" >> $env:GITHUB_OUTPUT | |
| "timed_out=$timedOut" >> $env:GITHUB_OUTPUT | |
| "completed=$completed" >> $env:GITHUB_OUTPUT | |
| Write-Output "Baseline counts -> subscribed=$subscribed truncated=$truncated timed_out=$timedOut completed=$completed" | |
| - name: Shorten the command timeout for the composition check | |
| uses: ./.github/actions/run-agent | |
| with: | |
| binary: ${{ matrix.binary }} | |
| args: --update --org-id ${{ vars.IT_ORG_ID }} --no-auto-updates --max-output-bytes 262144 --command-timeout-seconds 30 --github-token ${{ secrets.GITHUB_TOKEN }} | |
| - name: Wait for fresh subscription after the timeout update | |
| shell: pwsh | |
| env: | |
| LOG_FILE: ${{ matrix.log_file }} | |
| BASELINE: ${{ steps.compose_baseline.outputs.subscribed }} | |
| run: | | |
| $baseline = [int]$env:BASELINE | |
| for ($i = 1; $i -le 60; $i++) { | |
| $content = Get-Content $env:LOG_FILE -Raw -ErrorAction SilentlyContinue | |
| $count = if ($content) { ([regex]::Matches($content, [regex]::Escape("Subscribed to messages"))).Count } else { 0 } | |
| if ($count -gt $baseline) { | |
| Write-Output "Agent subscribed with the short timeout (count $count > baseline $baseline) after ~$($i * 2)s" | |
| exit 0 | |
| } | |
| Start-Sleep -Seconds 2 | |
| } | |
| Write-Error "Agent did not subscribe after the timeout update (count stayed at $baseline)" | |
| exit 1 | |
| - name: Send verbose command that then hangs | |
| uses: ./.github/actions/send-command | |
| with: | |
| trigger_url: ${{ vars.IT_SEND_COMMAND_TRIGGER_URL }} | |
| device_id: ${{ steps.config.outputs.device_id }} | |
| commands: ${{ matrix.verbose_hang_commands }} | |
| - name: Assert the hanging command's output was still bounded | |
| uses: ./.github/actions/assert-output-bounded | |
| with: | |
| service: ${{ matrix.service }} | |
| log_file: ${{ matrix.log_file }} | |
| baseline_truncations: ${{ steps.compose_baseline.outputs.truncated }} | |
| expected_ceiling_bytes: "262144" | |
| # Same headroom as the other floods: stdout fills the ceiling on its | |
| # own, and anything the shell adds on either stream is incidental. | |
| min_kept_bytes: "262144" | |
| max_kept_bytes: "266240" | |
| # Lower than the flood's full 200 MiB: the command is killed at its | |
| # deadline, so only the volume written before the kill is counted. | |
| min_produced_bytes: "104857600" | |
| max_rss_mb: "250" | |
| # The warning lands once the deadline kills the process group, and | |
| # cmd.WaitDelay can hold Run for up to 10s more after that. | |
| max_attempts: "120" | |
| - name: Assert the hanging command also timed out and released its worker | |
| shell: pwsh | |
| env: | |
| LOG_FILE: ${{ matrix.log_file }} | |
| TIMED_OUT_BASELINE: ${{ steps.compose_baseline.outputs.timed_out }} | |
| run: | | |
| # The two bounds compose: the same command is reported as truncated | |
| # (asserted above) and as timed out, neither masking the other. | |
| $baseline = [int]$env:TIMED_OUT_BASELINE | |
| for ($i = 1; $i -le 30; $i++) { | |
| $content = Get-Content $env:LOG_FILE -Raw -ErrorAction SilentlyContinue | |
| $count = if ($content) { ([regex]::Matches($content, [regex]::Escape("Command timed out"))).Count } else { 0 } | |
| if ($count -gt $baseline) { | |
| Write-Output "Verbose hanging command was killed by the timeout (count $count > baseline $baseline) after ~$($i * 2)s" | |
| exit 0 | |
| } | |
| Start-Sleep -Seconds 2 | |
| } | |
| Write-Error "Verbose hanging command was not killed by the per-command timeout (count stayed at $baseline)" | |
| exit 1 | |
| - name: Send command after the verbose timeout | |
| uses: ./.github/actions/send-command | |
| with: | |
| trigger_url: ${{ vars.IT_SEND_COMMAND_TRIGGER_URL }} | |
| device_id: ${{ steps.config.outputs.device_id }} | |
| commands: ${{ matrix.success_commands }} | |
| - name: Assert the worker recovered after the verbose timeout | |
| shell: pwsh | |
| env: | |
| LOG_FILE: ${{ matrix.log_file }} | |
| BASELINE: ${{ steps.compose_baseline.outputs.completed }} | |
| run: | | |
| $baseline = [int]$env:BASELINE | |
| for ($i = 1; $i -le 30; $i++) { | |
| Start-Sleep -Seconds 2 | |
| $content = Get-Content $env:LOG_FILE -Raw -ErrorAction SilentlyContinue | |
| $count = if ($content) { ([regex]::Matches($content, [regex]::Escape("Command completed"))).Count } else { 0 } | |
| if ($count -gt $baseline) { | |
| Write-Output "Worker recovered after the verbose timeout (count $count > baseline $baseline)" | |
| exit 0 | |
| } | |
| } | |
| Write-Error "No command completed after the verbose timeout (count stayed at $baseline)" | |
| exit 1 | |
| - name: Assert the output floods left no orphaned script files | |
| uses: ./.github/actions/assert-no-orphaned-scripts | |
| with: | |
| mode: assert | |
| scripts_dir: ${{ steps.scripts_dir.outputs.path }} | |
| # ---- Stale script file sweep scenario (sc-103967) ---- | |
| # A command interrupted by an abrupt kill (force-stop, OOM kill, power | |
| # loss) never runs its deferred temp-file cleanup, so its script file is | |
| # stranded in the scripts directory and nothing used to reclaim it. Verify | |
| # the startup sweep now does: force-kill the service mid-command to strand | |
| # a real script file, age it (plus a control set) into the months-old | |
| # debris a long-lived install accumulates, restart, and confirm only the | |
| # agent's own stale files are removed. | |
| # | |
| # The release binary is reinstalled first, with auto-updates off and the | |
| # per-command timeout raised well past the command's runtime, so nothing | |
| # ends the command before the kill lands - not the 5s timeout from the | |
| # earlier scenario, the 30s auto-updater, or the IT binary's 90s SAS | |
| # lifetime. Each of those tears the command down gracefully, and graceful | |
| # teardown DOES run the cleanup, leaving no stranded file to sweep. | |
| - name: Capture sweep scenario baseline counts | |
| id: sweep_baseline | |
| shell: pwsh | |
| env: | |
| LOG_FILE: ${{ matrix.log_file }} | |
| run: | | |
| $content = Get-Content $env:LOG_FILE -Raw -ErrorAction SilentlyContinue | |
| $subscribed = if ($content) { ([regex]::Matches($content, [regex]::Escape("Subscribed to messages"))).Count } else { 0 } | |
| $saved = if ($content) { ([regex]::Matches($content, [regex]::Escape("Command saved to"))).Count } else { 0 } | |
| "subscribed=$subscribed" >> $env:GITHUB_OUTPUT | |
| "saved=$saved" >> $env:GITHUB_OUTPUT | |
| Write-Output "Baseline counts -> subscribed=$subscribed saved=$saved" | |
| - name: Install release binary for the sweep scenario | |
| uses: ./.github/actions/run-agent | |
| with: | |
| binary: ${{ matrix.binary }} | |
| args: --update --org-id ${{ vars.IT_ORG_ID }} --no-auto-updates ${{ matrix.no_auto_updates_extra }} --command-timeout-seconds 600 --github-token ${{ secrets.GITHUB_TOKEN }} | |
| - name: Wait for fresh subscription before the sweep scenario | |
| shell: pwsh | |
| env: | |
| LOG_FILE: ${{ matrix.log_file }} | |
| BASELINE: ${{ steps.sweep_baseline.outputs.subscribed }} | |
| run: | | |
| # A delta, not a bare match: the log already carries many "Subscribed to | |
| # messages" lines from earlier scenarios, so only a new one proves the | |
| # restarted agent is connected and ready to receive the command. | |
| $baseline = [int]$env:BASELINE | |
| for ($i = 1; $i -le 60; $i++) { | |
| $content = Get-Content $env:LOG_FILE -Raw -ErrorAction SilentlyContinue | |
| $count = if ($content) { ([regex]::Matches($content, [regex]::Escape("Subscribed to messages"))).Count } else { 0 } | |
| if ($count -gt $baseline) { | |
| Write-Output "Agent subscribed after the sweep-scenario install (count $count > baseline $baseline) after ~$($i * 2)s" | |
| exit 0 | |
| } | |
| Start-Sleep -Seconds 2 | |
| } | |
| Write-Error "Agent did not subscribe after the sweep-scenario install (count stayed at $baseline)" | |
| exit 1 | |
| - name: Send long-running command | |
| uses: ./.github/actions/send-command | |
| with: | |
| trigger_url: ${{ vars.IT_SEND_COMMAND_TRIGGER_URL }} | |
| device_id: ${{ steps.config.outputs.device_id }} | |
| commands: ${{ matrix.sweep_commands }} | |
| - name: Capture the in-flight script file path | |
| id: inflight_script | |
| shell: pwsh | |
| env: | |
| LOG_FILE: ${{ matrix.log_file }} | |
| BASELINE: ${{ steps.sweep_baseline.outputs.saved }} | |
| run: | | |
| # The agent logs the temp file it wrote the command to, so read the path | |
| # (and the scripts directory) straight from the log instead of | |
| # re-deriving the platform path - the service's temp directory is not | |
| # the runner's, notably root's private TMPDIR on macOS. | |
| $baseline = [int]$env:BASELINE | |
| for ($i = 1; $i -le 30; $i++) { | |
| $content = Get-Content $env:LOG_FILE -Raw -ErrorAction SilentlyContinue | |
| $found = if ($content) { [regex]::Matches($content, 'Command saved to[^\r\n]*path=(?<p>\S+)') } else { @() } | |
| if ($found.Count -gt $baseline) { | |
| $path = $found[$found.Count - 1].Groups['p'].Value.Trim('"') | |
| $dir = Split-Path -Parent $path | |
| "path=$path" >> $env:GITHUB_OUTPUT | |
| "scripts_dir=$dir" >> $env:GITHUB_OUTPUT | |
| Write-Output "In-flight script file: $path (scripts directory $dir)" | |
| exit 0 | |
| } | |
| Start-Sleep -Seconds 2 | |
| } | |
| Write-Error "Agent never logged a script file for the long-running command (count stayed at $baseline)" | |
| exit 1 | |
| - name: Force-kill the agent mid-command | |
| uses: ./.github/actions/kill-service | |
| with: | |
| service: ${{ matrix.service }} | |
| - name: Age the stranded script file and seed sweep control files | |
| uses: ./.github/actions/script-sweep-fixture | |
| with: | |
| mode: seed | |
| scripts_dir: ${{ steps.inflight_script.outputs.scripts_dir }} | |
| orphan_path: ${{ steps.inflight_script.outputs.path }} | |
| - name: Capture sweep log baseline count | |
| id: sweep_log_baseline | |
| shell: pwsh | |
| env: | |
| LOG_FILE: ${{ matrix.log_file }} | |
| run: | | |
| $content = Get-Content $env:LOG_FILE -Raw -ErrorAction SilentlyContinue | |
| $swept = if ($content) { ([regex]::Matches($content, [regex]::Escape("Swept stale script files"))).Count } else { 0 } | |
| "swept=$swept" >> $env:GITHUB_OUTPUT | |
| Write-Output "Baseline counts -> swept=$swept" | |
| - name: Restart agent to trigger the startup sweep | |
| uses: ./.github/actions/run-agent | |
| with: | |
| binary: ${{ matrix.binary }} | |
| args: --update --org-id ${{ vars.IT_ORG_ID }} --no-auto-updates ${{ matrix.no_auto_updates_extra }} --github-token ${{ secrets.GITHUB_TOKEN }} | |
| - name: Wait for and assert the startup sweep was logged | |
| shell: pwsh | |
| env: | |
| LOG_FILE: ${{ matrix.log_file }} | |
| BASELINE: ${{ steps.sweep_log_baseline.outputs.swept }} | |
| run: | | |
| $baseline = [int]$env:BASELINE | |
| for ($i = 1; $i -le 60; $i++) { | |
| $content = Get-Content $env:LOG_FILE -Raw -ErrorAction SilentlyContinue | |
| $swept = if ($content) { ([regex]::Matches($content, [regex]::Escape("Swept stale script files"))).Count } else { 0 } | |
| if ($swept -gt $baseline) { | |
| Write-Output "Startup sweep logged (count $swept > baseline $baseline) after ~$($i * 2)s" | |
| exit 0 | |
| } | |
| Start-Sleep -Seconds 2 | |
| } | |
| Write-Error "Startup sweep was never logged (count stayed at $baseline)" | |
| exit 1 | |
| - name: Assert stale script files swept and live files untouched | |
| uses: ./.github/actions/script-sweep-fixture | |
| with: | |
| mode: assert | |
| scripts_dir: ${{ steps.inflight_script.outputs.scripts_dir }} | |
| orphan_path: ${{ steps.inflight_script.outputs.path }} | |
| # ---- Downloaded installer sweep scenario (sc-106111) ---- | |
| # Every auto-update downloads a full agent binary and executes it as the | |
| # installer. The installer is spawned detached and the process that could | |
| # delete it afterwards is the one the installer replaces, so the download | |
| # path cannot clean up after itself and nothing else used to - one | |
| # orphaned binary accumulated per update for the lifetime of the install, | |
| # until the volume filled and took future updates and command execution | |
| # with it. Verify the startup sweep now reclaims them. | |
| # | |
| # The fixture is planted rather than produced by a real update cycle: the | |
| # sweep is what this ticket changed, and the download side (where the file | |
| # lands, under what name) is covered by unit tests that assert the two | |
| # halves share one pattern constant. Ageing is the only simulated part, so | |
| # the production 24h threshold stays in play with no test-only override. | |
| # | |
| # Only the org's own updates directory is asserted here. The sweep also | |
| # covers the legacy shared temp directory that older agents downloaded | |
| # into, but that is the *service account's* temp directory - notably root's | |
| # private TMPDIR on macOS, not the runner's - so a fixture planted from | |
| # the runner would land somewhere the service never reads. That half is | |
| # covered by TestExecute_SweepsStaleInstallerFilesOnStartup, which runs | |
| # Execute in-process and can see its own temp directory. | |
| - name: Seed the installer sweep fixture | |
| uses: ./.github/actions/installer-sweep-fixture | |
| with: | |
| mode: seed | |
| updates_dir: ${{ matrix.config_dir }}/${{ vars.IT_ORG_ID }}/updates | |
| - name: Capture installer sweep log baseline count | |
| id: installer_sweep_baseline | |
| shell: pwsh | |
| env: | |
| LOG_FILE: ${{ matrix.log_file }} | |
| run: | | |
| $content = Get-Content $env:LOG_FILE -Raw -ErrorAction SilentlyContinue | |
| $swept = if ($content) { ([regex]::Matches($content, [regex]::Escape("Swept stale installer files"))).Count } else { 0 } | |
| "swept=$swept" >> $env:GITHUB_OUTPUT | |
| Write-Output "Baseline counts -> swept=$swept" | |
| - name: Restart agent to trigger the installer sweep | |
| uses: ./.github/actions/run-agent | |
| with: | |
| binary: ${{ matrix.binary }} | |
| args: --update --org-id ${{ vars.IT_ORG_ID }} --no-auto-updates ${{ matrix.no_auto_updates_extra }} --github-token ${{ secrets.GITHUB_TOKEN }} | |
| - name: Wait for and assert the installer sweep was logged | |
| shell: pwsh | |
| env: | |
| LOG_FILE: ${{ matrix.log_file }} | |
| BASELINE: ${{ steps.installer_sweep_baseline.outputs.swept }} | |
| run: | | |
| $baseline = [int]$env:BASELINE | |
| for ($i = 1; $i -le 60; $i++) { | |
| $content = Get-Content $env:LOG_FILE -Raw -ErrorAction SilentlyContinue | |
| $swept = if ($content) { ([regex]::Matches($content, [regex]::Escape("Swept stale installer files"))).Count } else { 0 } | |
| if ($swept -gt $baseline) { | |
| Write-Output "Installer sweep logged (count $swept > baseline $baseline) after ~$($i * 2)s" | |
| exit 0 | |
| } | |
| Start-Sleep -Seconds 2 | |
| } | |
| Write-Output "---- last 40 log lines ----" | |
| Get-Content $env:LOG_FILE -Tail 40 -ErrorAction SilentlyContinue | |
| Write-Error "Installer sweep was never logged (count stayed at $baseline)" | |
| exit 1 | |
| - name: Assert stale installers swept and live files untouched | |
| uses: ./.github/actions/installer-sweep-fixture | |
| with: | |
| mode: assert | |
| updates_dir: ${{ matrix.config_dir }}/${{ vars.IT_ORG_ID }}/updates | |
| # ---- Capped and jittered auto-update retry scenario (sc-106110) ---- | |
| # The auto-update retry delay was base * (1 << attempt) with no ceiling and | |
| # no jitter. Unjittered, every agent that failed against the release | |
| # endpoint at the same moment retried at the same instants, so an outage or | |
| # rate limit was sustained by the fleet trying to recover from it; uncapped, | |
| # a large retry count overflowed the shift into a negative duration, which | |
| # made the wait return immediately and spun the loop against the endpoint. | |
| # | |
| # A GitHub outage is not something CI can arrange and an unroutable address | |
| # produces connection errors rather than the HTTP failure the ticket | |
| # describes, so the agent is pointed at the test/stubrelease fixture through | |
| # the override file the integration build honors. The fixture fails every | |
| # request until it is flipped, which puts the agent into retryWithBackoff | |
| # with the shortened build knobs - base 2s, 6 retries, 30s check interval, | |
| # so the cap is a quarter of that interval (7.5s) - and makes a full | |
| # schedule observable in under a minute. | |
| # | |
| # Fleet-wide de-synchronization needs many agents and is covered by unit | |
| # tests over the schedule itself. What one endpoint can show, and what these | |
| # steps assert, is that every slot is strictly positive, bounded by the cap, | |
| # varies rather than repeating, and is never served back to back. | |
| - name: Start stub release endpoint (failing) | |
| id: stub_release | |
| uses: ./.github/actions/stub-release | |
| with: | |
| mode: start | |
| - name: Capture auto-update retry baseline counts | |
| id: retry_baseline | |
| shell: pwsh | |
| env: | |
| LOG_FILE: ${{ matrix.log_file }} | |
| run: | | |
| $content = Get-Content $env:LOG_FILE -Raw -ErrorAction SilentlyContinue | |
| $retrying = if ($content) { ([regex]::Matches($content, [regex]::Escape("Retrying update"))).Count } else { 0 } | |
| $succeeded = if ($content) { ([regex]::Matches($content, [regex]::Escape("Update succeeded on retry"))).Count } else { 0 } | |
| "retrying=$retrying" >> $env:GITHUB_OUTPUT | |
| "succeeded=$succeeded" >> $env:GITHUB_OUTPUT | |
| Write-Output "Baseline counts -> retrying=$retrying succeeded=$succeeded" | |
| # Written before the install, because the updater reads the override when a | |
| # service cycle constructs it - a file written afterwards would not be seen | |
| # until the next restart, and the agent would spend the scenario updating | |
| # itself from the real releases API instead. | |
| - name: Point the agent at the stub release endpoint | |
| uses: ./.github/actions/set-release-url | |
| with: | |
| mode: set | |
| config_dir: ${{ matrix.config_dir }} | |
| org_id: ${{ vars.IT_ORG_ID }} | |
| url: ${{ steps.stub_release.outputs.url }} | |
| - name: Install integration test binary with auto-updates on | |
| uses: ./.github/actions/run-agent | |
| with: | |
| binary: ${{ matrix.it_binary }} | |
| args: --update --org-id ${{ vars.IT_ORG_ID }} --github-token ${{ secrets.GITHUB_TOKEN }} | |
| - name: Wait for the update retry schedule to run | |
| shell: pwsh | |
| env: | |
| LOG_FILE: ${{ matrix.log_file }} | |
| BASELINE: ${{ steps.retry_baseline.outputs.retrying }} | |
| run: | | |
| # The first check fires 30s after the service starts, then the schedule | |
| # is roughly 2s, 4s, 7.5s, 7.5s... Four new lines put two slots at the | |
| # ceiling, which is what the jitter assertion below needs to tell a | |
| # jittered schedule from one that is merely capped, and still leave two | |
| # more slots (~15s) for the recovery flip to land in, so the flip cannot | |
| # race the end of the retry budget. | |
| $baseline = [int]$env:BASELINE | |
| for ($i = 1; $i -le 150; $i++) { | |
| $content = Get-Content $env:LOG_FILE -Raw -ErrorAction SilentlyContinue | |
| $count = if ($content) { ([regex]::Matches($content, [regex]::Escape("Retrying update"))).Count } else { 0 } | |
| if (($count - $baseline) -ge 4) { | |
| Write-Output "Observed $($count - $baseline) update retries after ~${i}s" | |
| exit 0 | |
| } | |
| Start-Sleep -Seconds 1 | |
| } | |
| Write-Error "The agent never retried the update against the failing release endpoint" | |
| exit 1 | |
| # Flipped mid-sequence - the fixture re-reads its mode per request - so the | |
| # recovery is the agent's own next retry, not a restart. | |
| - name: Serve a valid release payload mid-sequence | |
| uses: ./.github/actions/stub-release | |
| with: | |
| mode: ok | |
| - name: Assert the update succeeds on a retry | |
| shell: pwsh | |
| env: | |
| LOG_FILE: ${{ matrix.log_file }} | |
| BASELINE: ${{ steps.retry_baseline.outputs.succeeded }} | |
| run: | | |
| # The fixture serves the running agent's own version as tag_name, so a | |
| # recovered check ends at "No updates available" and the retry is seen | |
| # succeeding without downloading or executing anything - the recovery is | |
| # what is under test here, not the installer. | |
| $baseline = [int]$env:BASELINE | |
| for ($i = 1; $i -le 60; $i++) { | |
| $content = Get-Content $env:LOG_FILE -Raw -ErrorAction SilentlyContinue | |
| $count = if ($content) { ([regex]::Matches($content, [regex]::Escape("Update succeeded on retry"))).Count } else { 0 } | |
| if ($count -gt $baseline) { | |
| Write-Output "Update succeeded on a retry after ~$($i * 2)s (count $count > baseline $baseline)" | |
| exit 0 | |
| } | |
| Start-Sleep -Seconds 2 | |
| } | |
| # Separates a real regression from a flip that landed after the budget | |
| # was already spent, which would leave the next check succeeding on its | |
| # first try and logging no retry at all. | |
| $content = Get-Content $env:LOG_FILE -Raw -ErrorAction SilentlyContinue | |
| if ($content -and $content.Contains("All retries exhausted")) { | |
| Write-Output "Note: the log records an exhausted retry budget; the recovery flip may have landed after the last slot" | |
| } | |
| Write-Output "---- last 40 log lines ----" | |
| Get-Content $env:LOG_FILE -Tail 40 -ErrorAction SilentlyContinue | |
| Write-Error "The agent never logged a successful update retry after the endpoint recovered" | |
| exit 1 | |
| - name: Assert the retry schedule is capped, jittered and never immediate | |
| shell: pwsh | |
| env: | |
| LOG_FILE: ${{ matrix.log_file }} | |
| BASELINE: ${{ steps.retry_baseline.outputs.retrying }} | |
| run: | | |
| # The cap the integration build lands on: a quarter of its 30s check | |
| # interval, which is below the absolute 1h ceiling a released build uses. | |
| $cap = 7.5 | |
| $baseline = [int]$env:BASELINE | |
| $failures = @() | |
| function ConvertTo-Seconds([string]$value) { | |
| # Go renders a duration as concatenated unit components ("4.1s", | |
| # "1m4s"), and a negative one with a leading '-'. The sign is read | |
| # separately because the overflow this scenario guards against | |
| # produced exactly that negative value, and summing the components | |
| # alone would report it as positive. | |
| $sign = if ($value.StartsWith('-')) { -1.0 } else { 1.0 } | |
| $total = 0.0 | |
| foreach ($m in [regex]::Matches($value, '(?<n>[0-9.]+)(?<u>ms|us|ns|h|m|s)')) { | |
| $n = [double]$m.Groups['n'].Value | |
| switch ($m.Groups['u'].Value) { | |
| 'ns' { $total += $n / 1e9 } | |
| 'us' { $total += $n / 1e6 } | |
| 'ms' { $total += $n / 1e3 } | |
| 's' { $total += $n } | |
| 'm' { $total += $n * 60 } | |
| 'h' { $total += $n * 3600 } | |
| } | |
| } | |
| return $sign * $total | |
| } | |
| $lines = @(Get-Content $env:LOG_FILE -ErrorAction SilentlyContinue | | |
| Where-Object { $_ -match 'Retrying update' } | | |
| Select-Object -Skip $baseline) | |
| $slots = @() | |
| foreach ($line in $lines) { | |
| # hclog writes "<timestamp> [INFO] agent_smith: Retrying update: attempt=N backoff=D". | |
| # The timestamp is a fixed-width local time followed by its offset, so | |
| # the first 23 characters parse without worrying about the offset form. | |
| $m = [regex]::Match($line, '^(?<ts>\S{23}).*Retrying update: attempt=(?<attempt>\d+) backoff=(?<backoff>\S+)') | |
| if (-not $m.Success) { | |
| $failures += "could not parse a retry line: $line" | |
| continue | |
| } | |
| $stamp = $null | |
| try { | |
| $stamp = [datetime]::ParseExact( | |
| $m.Groups['ts'].Value, | |
| 'yyyy-MM-ddTHH:mm:ss.fff', | |
| [Globalization.CultureInfo]::InvariantCulture) | |
| } catch { | |
| $failures += "could not parse the timestamp of: $line" | |
| } | |
| $slots += [pscustomobject]@{ | |
| Attempt = [int]$m.Groups['attempt'].Value | |
| Backoff = ConvertTo-Seconds $m.Groups['backoff'].Value | |
| Time = $stamp | |
| } | |
| } | |
| if ($slots.Count -lt 3) { | |
| Write-Error "Expected at least three retry slots to inspect, got $($slots.Count)" | |
| exit 1 | |
| } | |
| # The timestamp table the ticket asks for: every slot, what it waited, | |
| # and how long actually elapsed before the next one arrived. | |
| Write-Output "---- observed update retry schedule ----" | |
| for ($i = 0; $i -lt $slots.Count; $i++) { | |
| $gap = '' | |
| if ($i -lt $slots.Count - 1 -and $slots[$i].Time -and $slots[$i + 1].Time) { | |
| $gap = [math]::Round(($slots[$i + 1].Time - $slots[$i].Time).TotalSeconds, 3) | |
| } | |
| Write-Output ("attempt={0} backoff={1}s elapsed_to_next={2}" -f $slots[$i].Attempt, [math]::Round($slots[$i].Backoff, 3), $gap) | |
| } | |
| foreach ($slot in $slots) { | |
| # A zero or negative slot is the overflow busy-spin: time.After fires | |
| # immediately and the loop issues requests as fast as it can. | |
| if ($slot.Backoff -le 0) { | |
| $failures += "attempt $($slot.Attempt): backoff $($slot.Backoff)s is not strictly positive" | |
| } | |
| # The tolerance covers the millisecond rendering, not the cap itself. | |
| if ($slot.Backoff -gt ($cap + 0.05)) { | |
| $failures += "attempt $($slot.Attempt): backoff $($slot.Backoff)s exceeds the ${cap}s cap" | |
| } | |
| } | |
| # Jitter: a fixed schedule repeats the same values bit for bit. | |
| $distinct = @($slots | ForEach-Object { [math]::Round($_.Backoff, 3) } | Select-Object -Unique) | |
| if ($distinct.Count -lt 2) { | |
| $failures += "every retry slot was $($distinct -join ', ')s - the schedule is not jittered" | |
| } | |
| # Distinct values alone are weak evidence, because the doubling produces | |
| # distinct values on its own until it reaches the ceiling. The slots that | |
| # do reach it are the discriminator: an unjittered schedule pins every | |
| # one of them to exactly the cap, while jitter spreads them across the | |
| # band below it. Skipped when the sequence was cut short by the recovery | |
| # flip before two slots got that far. | |
| $nearCap = @($slots | Where-Object { $_.Backoff -ge ($cap * 0.75) }) | |
| if ($nearCap.Count -ge 2) { | |
| $distinctNearCap = @($nearCap | ForEach-Object { [math]::Round($_.Backoff, 3) } | Select-Object -Unique) | |
| if ($distinctNearCap.Count -lt 2) { | |
| $failures += "the capped slots all measured $($distinctNearCap -join ', ')s - the jitter is not being applied" | |
| } | |
| } | |
| # Growth: the schedule still doubles up to the cap rather than being flat. | |
| $maxBackoff = ($slots | Measure-Object -Property Backoff -Maximum).Maximum | |
| if ($maxBackoff -le $slots[0].Backoff) { | |
| $failures += "the schedule never grew (first $($slots[0].Backoff)s, largest ${maxBackoff}s)" | |
| } | |
| # Spacing: consecutive slots of one sequence must be separated by at | |
| # least the wait that was logged. Pairs that are not consecutive attempts | |
| # belong to different retry sequences and are skipped. | |
| for ($i = 0; $i -lt $slots.Count - 1; $i++) { | |
| if ($slots[$i + 1].Attempt -ne $slots[$i].Attempt + 1) { continue } | |
| if (-not $slots[$i].Time -or -not $slots[$i + 1].Time) { continue } | |
| $gap = ($slots[$i + 1].Time - $slots[$i].Time).TotalSeconds | |
| if ($gap -lt 1) { | |
| $failures += "attempts $($slots[$i].Attempt) and $($slots[$i + 1].Attempt) arrived ${gap}s apart - back to back" | |
| } | |
| if ($gap -lt ($slots[$i].Backoff * 0.8)) { | |
| $failures += "attempt $($slots[$i].Attempt) logged a $($slots[$i].Backoff)s backoff but the next retry came after ${gap}s" | |
| } | |
| } | |
| if ($failures.Count -gt 0) { | |
| $failures | ForEach-Object { Write-Output "FAIL: $_" } | |
| Write-Error "the update retry schedule is not capped, jittered and spaced as expected" | |
| exit 1 | |
| } | |
| Write-Output "Retry schedule bounded by ${cap}s, jittered across $($distinct.Count) distinct values, and never served back to back" | |
| exit 0 | |
| - name: Fail the release endpoint again for the stop check | |
| uses: ./.github/actions/stub-release | |
| with: | |
| mode: fail | |
| - name: Capture stop-during-backoff baseline counts | |
| id: retry_stop_baseline | |
| shell: pwsh | |
| env: | |
| LOG_FILE: ${{ matrix.log_file }} | |
| run: | | |
| $content = Get-Content $env:LOG_FILE -Raw -ErrorAction SilentlyContinue | |
| $retrying = if ($content) { ([regex]::Matches($content, [regex]::Escape("Retrying update"))).Count } else { 0 } | |
| $stopped = if ($content) { ([regex]::Matches($content, [regex]::Escape("Auto updater stopped"))).Count } else { 0 } | |
| "retrying=$retrying" >> $env:GITHUB_OUTPUT | |
| "stopped=$stopped" >> $env:GITHUB_OUTPUT | |
| Write-Output "Baseline counts -> retrying=$retrying stopped=$stopped" | |
| - name: Wait for a fresh backoff to be entered | |
| shell: pwsh | |
| env: | |
| LOG_FILE: ${{ matrix.log_file }} | |
| BASELINE: ${{ steps.retry_stop_baseline.outputs.retrying }} | |
| run: | | |
| $baseline = [int]$env:BASELINE | |
| for ($i = 1; $i -le 90; $i++) { | |
| $content = Get-Content $env:LOG_FILE -Raw -ErrorAction SilentlyContinue | |
| $count = if ($content) { ([regex]::Matches($content, [regex]::Escape("Retrying update"))).Count } else { 0 } | |
| if ($count -gt $baseline) { | |
| Write-Output "Agent is in a retry backoff again after ~${i}s" | |
| exit 0 | |
| } | |
| Start-Sleep -Seconds 1 | |
| } | |
| Write-Error "The agent never entered a retry backoff after the endpoint was failed again" | |
| exit 1 | |
| - name: Assert a service stop during a backoff is prompt | |
| shell: pwsh | |
| env: | |
| LOG_FILE: ${{ matrix.log_file }} | |
| SERVICE: ${{ matrix.service }} | |
| BASELINE: ${{ steps.retry_stop_baseline.outputs.stopped }} | |
| run: | | |
| # The agent has just entered a backoff with most of its 6-slot budget | |
| # left (~30s of waiting at the 7.5s cap). A stop that has to wait out | |
| # the pending slot - or worse, the whole budget - delays every caller of | |
| # Stop(): the installer, an upgrade, and an uninstall. | |
| $baseline = [int]$env:BASELINE | |
| $sw = [System.Diagnostics.Stopwatch]::StartNew() | |
| if ($IsWindows) { | |
| sc.exe stop $env:SERVICE | Out-Null | |
| } elseif ($IsLinux) { | |
| sudo systemctl stop $env:SERVICE | |
| } else { | |
| # Bare label, not "system/<label>": stop is a legacy launchctl | |
| # subcommand that resolves a label in the current domain, and a | |
| # service-target form is read as a literal label that matches nothing. | |
| sudo launchctl stop $env:SERVICE | |
| } | |
| # The service managers disagree about exit status for a stop that was | |
| # delivered; the verdict here comes from the agent's own log. | |
| $global:LASTEXITCODE = 0 | |
| for ($i = 1; $i -le 60; $i++) { | |
| $content = Get-Content $env:LOG_FILE -Raw -ErrorAction SilentlyContinue | |
| $count = if ($content) { ([regex]::Matches($content, [regex]::Escape("Auto updater stopped"))).Count } else { 0 } | |
| if ($count -gt $baseline) { | |
| $sw.Stop() | |
| $elapsed = [math]::Round($sw.Elapsed.TotalSeconds, 1) | |
| if ($sw.Elapsed.TotalSeconds -gt 20) { | |
| Write-Error "The auto updater stopped only after ${elapsed}s, long enough to have waited out its retry schedule" | |
| exit 1 | |
| } | |
| Write-Output "Auto updater stopped ${elapsed}s after the stop was issued, mid-backoff" | |
| exit 0 | |
| } | |
| Start-Sleep -Milliseconds 500 | |
| } | |
| $sw.Stop() | |
| Write-Output "---- last 40 log lines ----" | |
| Get-Content $env:LOG_FILE -Tail 40 -ErrorAction SilentlyContinue | |
| Write-Error "The auto updater never logged a stop after the service was stopped mid-backoff" | |
| exit 1 | |
| # The restore steps run under always() so a failed assertion above cannot | |
| # leave the rest of the job running an agent that points at a stub release | |
| # endpoint (or leave the service stopped for the scenarios that follow). | |
| - name: Capture restore baseline counts | |
| if: always() | |
| id: retry_restore_baseline | |
| shell: pwsh | |
| env: | |
| LOG_FILE: ${{ matrix.log_file }} | |
| run: | | |
| $content = Get-Content $env:LOG_FILE -Raw -ErrorAction SilentlyContinue | |
| $subscribed = if ($content) { ([regex]::Matches($content, [regex]::Escape("Subscribed to messages"))).Count } else { 0 } | |
| "subscribed=$subscribed" >> $env:GITHUB_OUTPUT | |
| Write-Output "Baseline counts -> subscribed=$subscribed" | |
| - name: Clear the release url override | |
| if: always() | |
| uses: ./.github/actions/set-release-url | |
| with: | |
| mode: clear | |
| config_dir: ${{ matrix.config_dir }} | |
| org_id: ${{ vars.IT_ORG_ID }} | |
| - name: Stop stub release endpoint | |
| if: always() | |
| uses: ./.github/actions/stub-release | |
| with: | |
| mode: stop | |
| - name: Reinstall the release binary after the retry scenario | |
| if: always() | |
| uses: ./.github/actions/run-agent | |
| with: | |
| binary: ${{ matrix.binary }} | |
| args: --update --org-id ${{ vars.IT_ORG_ID }} --no-auto-updates ${{ matrix.no_auto_updates_extra }} --github-token ${{ secrets.GITHUB_TOKEN }} | |
| - name: Wait for resubscription after the retry scenario | |
| if: always() | |
| shell: pwsh | |
| env: | |
| LOG_FILE: ${{ matrix.log_file }} | |
| BASELINE: ${{ steps.retry_restore_baseline.outputs.subscribed }} | |
| run: | | |
| $baseline = [int]$env:BASELINE | |
| for ($i = 1; $i -le 60; $i++) { | |
| $content = Get-Content $env:LOG_FILE -Raw -ErrorAction SilentlyContinue | |
| $count = if ($content) { ([regex]::Matches($content, [regex]::Escape("Subscribed to messages"))).Count } else { 0 } | |
| if ($count -gt $baseline) { | |
| Write-Output "Agent resubscribed after the retry scenario (count $count > baseline $baseline) after ~$($i * 2)s" | |
| exit 0 | |
| } | |
| Start-Sleep -Seconds 2 | |
| } | |
| Write-Error "Agent never resubscribed after the retry scenario" | |
| exit 1 | |
| # ---- Wedged Windows service stop scenario (sc-106108) ---- | |
| # windowsService.Stop() polled the service state every 250ms in an | |
| # unbounded loop, so a service that never reached Stopped hung its caller | |
| # forever - and every caller is blocking: the unattended auto-updater, the | |
| # installer, and uninstall. The symptom was a device that went offline | |
| # during a routine update with no error logged anywhere. | |
| # | |
| # The wedge is produced by pointing the agent's own service registration at | |
| # the test/wedgedservice fixture, which accepts the stop control, reports | |
| # StopPending, and never stops (see the action for why killing or | |
| # suspending the agent will not do). The installed agent executable and | |
| # config file are left alone, so they can be hashed before and after to | |
| # prove an aborted update did not touch them. | |
| # | |
| # Windows only: the Unix service implementations have no such polling loop. | |
| - name: Capture installed file hashes before the wedge | |
| if: matrix.os == 'windows-latest' | |
| id: wedge_hashes | |
| shell: pwsh | |
| env: | |
| ORG_ID: ${{ vars.IT_ORG_ID }} | |
| CONFIG_DIR: ${{ matrix.config_dir }} | |
| run: | | |
| $ErrorActionPreference = 'Stop' | |
| $exe = Join-Path $env:PROGRAMFILES "RewstRemoteAgent\$($env:ORG_ID)\agent_smith.win.exe" | |
| $config = Join-Path $env:CONFIG_DIR "$($env:ORG_ID)\config.json" | |
| foreach ($path in @($exe, $config)) { | |
| if (-not (Test-Path $path)) { throw "expected installed file is missing: $path" } | |
| } | |
| $exeHash = (Get-FileHash -Path $exe -Algorithm SHA256).Hash | |
| $configHash = (Get-FileHash -Path $config -Algorithm SHA256).Hash | |
| "exe_path=$exe" >> $env:GITHUB_OUTPUT | |
| "config_path=$config" >> $env:GITHUB_OUTPUT | |
| "exe_hash=$exeHash" >> $env:GITHUB_OUTPUT | |
| "config_hash=$configHash" >> $env:GITHUB_OUTPUT | |
| Write-Output "agent executable $exe sha256=$exeHash" | |
| Write-Output "config file $config sha256=$configHash" | |
| - name: Wedge the agent service in StopPending | |
| if: matrix.os == 'windows-latest' | |
| uses: ./.github/actions/wedged-service | |
| with: | |
| mode: wedge | |
| service: ${{ matrix.service }} | |
| - name: Assert the update aborts on a wedged stop | |
| if: matrix.os == 'windows-latest' | |
| shell: pwsh | |
| env: | |
| IT_BINARY: ${{ matrix.it_binary }} | |
| ORG_ID: ${{ vars.IT_ORG_ID }} | |
| GH_TOKEN: ${{ secrets.GITHUB_TOKEN }} | |
| run: | | |
| # The integration binary is the invoker because its stop deadline is | |
| # overridden to 25s (see scripts/build_integration_test.ps1). The | |
| # released default is five minutes; that the constant is what governs a | |
| # production build is covered by unit tests rather than by keeping a | |
| # runner idle for five minutes here. | |
| $sw = [System.Diagnostics.Stopwatch]::StartNew() | |
| $out = & "./dist/$($env:IT_BINARY)" --update --org-id $env:ORG_ID ` | |
| --github-token $env:GH_TOKEN 2>&1 | Out-String | |
| $sw.Stop() | |
| # The updater reports an aborted update through its log, not its exit | |
| # status, and this step's verdict comes from the log below. | |
| $global:LASTEXITCODE = 0 | |
| $elapsed = [math]::Round($sw.Elapsed.TotalSeconds, 1) | |
| Write-Output "---- updater output after ${elapsed}s ----" | |
| Write-Output $out | |
| $failures = @() | |
| # Returning at all is the headline: before the fix this call never came | |
| # back. The floor proves it waited out its deadline rather than failing | |
| # fast for an unrelated reason; the ceiling is far above the 25s | |
| # deadline yet far below an unbounded hang. | |
| if ($sw.Elapsed.TotalSeconds -lt 20) { | |
| $failures += "update returned after ${elapsed}s, before its 25s stop deadline could elapse" | |
| } | |
| if ($sw.Elapsed.TotalSeconds -gt 180) { | |
| $failures += "update took ${elapsed}s, far past its 25s stop deadline" | |
| } | |
| # The log has to name the service, the deadline and the last observed | |
| # state, since that is the only account of why an unattended update | |
| # aborted. | |
| foreach ($needle in @( | |
| 'Failed to stop service', | |
| 'did not stop within', | |
| 'last observed state StopPending', | |
| 'Update aborted; existing installation left untouched' | |
| )) { | |
| if (-not $out.Contains($needle)) { $failures += "missing from the log: '$needle'" } | |
| } | |
| # And it must not have carried on as if the stop had succeeded. | |
| foreach ($absent in @( | |
| 'Configuration successfully updated', | |
| 'Agent installed to', | |
| 'Service started' | |
| )) { | |
| if ($out.Contains($absent)) { $failures += "update proceeded past the failed stop: '$absent'" } | |
| } | |
| if ($failures.Count -gt 0) { | |
| $failures | ForEach-Object { Write-Output "FAIL: $_" } | |
| Write-Error "the update did not abort cleanly on a wedged stop" | |
| exit 1 | |
| } | |
| Write-Output "Update aborted on the wedged stop after ${elapsed}s, as expected" | |
| exit 0 | |
| - name: Assert the aborted update left the installation untouched | |
| if: matrix.os == 'windows-latest' | |
| shell: pwsh | |
| env: | |
| EXE_PATH: ${{ steps.wedge_hashes.outputs.exe_path }} | |
| CONFIG_PATH: ${{ steps.wedge_hashes.outputs.config_path }} | |
| EXE_HASH: ${{ steps.wedge_hashes.outputs.exe_hash }} | |
| CONFIG_HASH: ${{ steps.wedge_hashes.outputs.config_hash }} | |
| run: | | |
| # The whole point of aborting: the wedged process may still hold the | |
| # executable open, so a half-written binary or a rewritten config would | |
| # leave the endpoint unrecoverable without hands on it. | |
| $ErrorActionPreference = 'Stop' | |
| $failures = @() | |
| foreach ($pair in @( | |
| @{ Path = $env:EXE_PATH; Expected = $env:EXE_HASH; Label = 'agent executable' }, | |
| @{ Path = $env:CONFIG_PATH; Expected = $env:CONFIG_HASH; Label = 'config file' } | |
| )) { | |
| if (-not (Test-Path $pair.Path)) { | |
| $failures += "$($pair.Label) was removed: $($pair.Path)" | |
| continue | |
| } | |
| $actual = (Get-FileHash -Path $pair.Path -Algorithm SHA256).Hash | |
| if ($actual -ne $pair.Expected) { | |
| $failures += "$($pair.Label) changed: $($pair.Expected) -> $actual" | |
| } else { | |
| Write-Output "$($pair.Label) unchanged (sha256=$actual)" | |
| } | |
| } | |
| if ($failures.Count -gt 0) { | |
| $failures | ForEach-Object { Write-Output "FAIL: $_" } | |
| Write-Error "the aborted update modified the installation" | |
| exit 1 | |
| } | |
| exit 0 | |
| # The failed stop above left the service in StopPending, and the agent | |
| # treats only Running as active - so an uninstall issued now would skip the | |
| # stop entirely instead of exercising it. Start a fresh wedged run so the | |
| # uninstall meets a Running service, as an operator would. | |
| - name: Re-wedge the service for the uninstall check | |
| if: matrix.os == 'windows-latest' | |
| uses: ./.github/actions/wedged-service | |
| with: | |
| mode: rewedge | |
| service: ${{ matrix.service }} | |
| - name: Assert the uninstall aborts on a wedged stop | |
| if: matrix.os == 'windows-latest' | |
| shell: pwsh | |
| env: | |
| IT_BINARY: ${{ matrix.it_binary }} | |
| ORG_ID: ${{ vars.IT_ORG_ID }} | |
| SERVICE: ${{ matrix.service }} | |
| EXE_PATH: ${{ steps.wedge_hashes.outputs.exe_path }} | |
| CONFIG_PATH: ${{ steps.wedge_hashes.outputs.config_path }} | |
| EXE_HASH: ${{ steps.wedge_hashes.outputs.exe_hash }} | |
| CONFIG_HASH: ${{ steps.wedge_hashes.outputs.config_hash }} | |
| UNINSTALL_PATHS: ${{ matrix.uninstall_paths }} | |
| run: | | |
| $sw = [System.Diagnostics.Stopwatch]::StartNew() | |
| $out = & "./dist/$($env:IT_BINARY)" --uninstall --org-id $env:ORG_ID 2>&1 | Out-String | |
| $sw.Stop() | |
| $global:LASTEXITCODE = 0 | |
| $elapsed = [math]::Round($sw.Elapsed.TotalSeconds, 1) | |
| Write-Output "---- uninstaller output after ${elapsed}s ----" | |
| Write-Output $out | |
| $failures = @() | |
| if ($sw.Elapsed.TotalSeconds -lt 20) { | |
| $failures += "uninstall returned after ${elapsed}s, before its 25s stop deadline could elapse" | |
| } | |
| if ($sw.Elapsed.TotalSeconds -gt 180) { | |
| $failures += "uninstall took ${elapsed}s, far past its 25s stop deadline" | |
| } | |
| foreach ($needle in @( | |
| 'Failed to stop service', | |
| 'did not stop within', | |
| 'Uninstall aborted; nothing was removed' | |
| )) { | |
| if (-not $out.Contains($needle)) { $failures += "missing from the log: '$needle'" } | |
| } | |
| foreach ($absent in @('Service deleted', 'Directory deleted')) { | |
| if ($out.Contains($absent)) { $failures += "uninstall proceeded past the failed stop: '$absent'" } | |
| } | |
| # Fully intact or fully removed, never mixed: the registration, the | |
| # installed directories, and both hashed files must all still be there. | |
| if (-not (Get-Service -Name $env:SERVICE -ErrorAction SilentlyContinue)) { | |
| $failures += "service registration $($env:SERVICE) was deleted" | |
| } | |
| foreach ($path in ($env:UNINSTALL_PATHS -split "`n" | ForEach-Object { $_.Trim() } | | |
| Where-Object { $_ })) { | |
| if (-not (Test-Path $path)) { $failures += "installed directory was removed: $path" } | |
| } | |
| foreach ($pair in @( | |
| @{ Path = $env:EXE_PATH; Expected = $env:EXE_HASH; Label = 'agent executable' }, | |
| @{ Path = $env:CONFIG_PATH; Expected = $env:CONFIG_HASH; Label = 'config file' } | |
| )) { | |
| if (-not (Test-Path $pair.Path)) { | |
| $failures += "$($pair.Label) was removed: $($pair.Path)" | |
| } elseif ((Get-FileHash -Path $pair.Path -Algorithm SHA256).Hash -ne $pair.Expected) { | |
| $failures += "$($pair.Label) changed during the aborted uninstall" | |
| } | |
| } | |
| if ($failures.Count -gt 0) { | |
| $failures | ForEach-Object { Write-Output "FAIL: $_" } | |
| Write-Error "the uninstall did not abort cleanly on a wedged stop" | |
| exit 1 | |
| } | |
| Write-Output "Uninstall aborted on the wedged stop after ${elapsed}s with nothing removed" | |
| exit 0 | |
| # Captured before the restore restarts the real agent, so the delta below | |
| # can only come from the recovered service. | |
| - name: Capture recovery baseline counts | |
| if: matrix.os == 'windows-latest' | |
| id: wedge_recovery_baseline | |
| shell: pwsh | |
| env: | |
| LOG_FILE: ${{ matrix.log_file }} | |
| run: | | |
| $content = Get-Content $env:LOG_FILE -Raw -ErrorAction SilentlyContinue | |
| $subscribed = if ($content) { ([regex]::Matches($content, [regex]::Escape("Subscribed to messages"))).Count } else { 0 } | |
| "subscribed=$subscribed" >> $env:GITHUB_OUTPUT | |
| Write-Output "Baseline counts -> subscribed=$subscribed" | |
| # always(): a failed assertion above must not leave the runner's service | |
| # registration pointing at the fixture, or the rest of the job (and the | |
| # final uninstall) would be testing the fixture instead of the agent. | |
| - name: Restore the agent service after the wedge | |
| if: always() && matrix.os == 'windows-latest' | |
| uses: ./.github/actions/wedged-service | |
| with: | |
| mode: restore | |
| service: ${{ matrix.service }} | |
| - name: Assert the recovered endpoint comes back online | |
| if: matrix.os == 'windows-latest' | |
| shell: pwsh | |
| env: | |
| LOG_FILE: ${{ matrix.log_file }} | |
| BASELINE: ${{ steps.wedge_recovery_baseline.outputs.subscribed }} | |
| run: | | |
| $baseline = [int]$env:BASELINE | |
| for ($i = 1; $i -le 60; $i++) { | |
| $content = Get-Content $env:LOG_FILE -Raw -ErrorAction SilentlyContinue | |
| $count = if ($content) { ([regex]::Matches($content, [regex]::Escape("Subscribed to messages"))).Count } else { 0 } | |
| if ($count -gt $baseline) { | |
| Write-Output "Recovered agent subscribed again (count $count > baseline $baseline) after ~$($i * 2)s" | |
| exit 0 | |
| } | |
| Start-Sleep -Seconds 2 | |
| } | |
| Write-Error "Recovered agent never resubscribed (count stayed at $baseline)" | |
| exit 1 | |
| - name: Assert a subsequent update succeeds after recovery | |
| if: matrix.os == 'windows-latest' | |
| shell: pwsh | |
| env: | |
| BINARY: ${{ matrix.binary }} | |
| ORG_ID: ${{ vars.IT_ORG_ID }} | |
| GH_TOKEN: ${{ secrets.GITHUB_TOKEN }} | |
| NO_AUTO_UPDATES_EXTRA: ${{ matrix.no_auto_updates_extra }} | |
| run: | | |
| # The bound must only catch a wedge: once the endpoint is recovered, an | |
| # ordinary update stops the service, replaces the binary and starts it | |
| # again with no behavioral change. | |
| $out = & "./dist/$($env:BINARY)" --update --org-id $env:ORG_ID --no-auto-updates ` | |
| $env:NO_AUTO_UPDATES_EXTRA --github-token $env:GH_TOKEN 2>&1 | Out-String | |
| $global:LASTEXITCODE = 0 | |
| Write-Output $out | |
| $failures = @() | |
| foreach ($needle in @('Agent installed to', 'Service started')) { | |
| if (-not $out.Contains($needle)) { $failures += "missing from the log: '$needle'" } | |
| } | |
| if ($out.Contains('Failed to stop service')) { | |
| $failures += "a healthy stop was reported as a failure" | |
| } | |
| if ($failures.Count -gt 0) { | |
| $failures | ForEach-Object { Write-Output "FAIL: $_" } | |
| Write-Error "the post-recovery update did not complete normally" | |
| exit 1 | |
| } | |
| Write-Output "Post-recovery update completed normally" | |
| exit 0 | |
| - name: Uninstall agent | |
| uses: ./.github/actions/run-agent | |
| with: | |
| binary: ${{ matrix.binary }} | |
| args: --uninstall --org-id ${{ vars.IT_ORG_ID }} | |
| - name: Check deleted directories | |
| uses: ./.github/actions/assert-uninstalled | |
| with: | |
| paths: ${{ matrix.uninstall_paths }} | |
| test-service-user: | |
| permissions: | |
| contents: read | |
| env: | |
| GITHUB_TOKEN: ${{ secrets.GITHUB_TOKEN }} | |
| needs: [build, build-integration-test, set-matrix] | |
| strategy: | |
| fail-fast: false | |
| matrix: ${{ fromJson(needs.set-matrix.outputs.matrix) }} | |
| runs-on: ${{ matrix.os }} | |
| steps: | |
| - name: Checkout code | |
| uses: actions/checkout@v5 | |
| - name: Provision service account | |
| id: provision | |
| uses: ./.github/actions/provision-service-user | |
| with: | |
| username: ${{ matrix.service_user }} | |
| - name: Install agent as service account | |
| uses: ./.github/actions/install-agent | |
| with: | |
| os: ${{ matrix.os }} | |
| binary: ${{ matrix.binary }} | |
| it_binary: ${{ matrix.it_binary }} | |
| config_url: ${{ vars.IT_CONFIG_URL }} | |
| config_secret: ${{ secrets.IT_CONFIG_SECRET }} | |
| org_id: ${{ vars.IT_ORG_ID }} | |
| github_token: ${{ secrets.GITHUB_TOKEN }} | |
| service_username: ${{ matrix.service_username_arg }} | |
| service_password: ${{ steps.provision.outputs.password }} | |
| - name: Assert service runs as account (config flow) | |
| uses: ./.github/actions/assert-service-identity | |
| with: | |
| service: ${{ matrix.service }} | |
| expected_identity: ${{ matrix.service_identity }} | |
| - name: Validate config and get device id | |
| uses: ./.github/actions/validate-config | |
| with: | |
| config_dir: ${{ matrix.config_dir }} | |
| org_id: ${{ vars.IT_ORG_ID }} | |
| - name: Assert password absent from config (config flow) | |
| uses: ./.github/actions/assert-config-secret-absent | |
| with: | |
| config_dir: ${{ matrix.config_dir }} | |
| org_id: ${{ vars.IT_ORG_ID }} | |
| secret: ${{ steps.provision.outputs.password }} | |
| - name: Re-register service via update flow (Unix) | |
| if: runner.os != 'Windows' | |
| shell: bash | |
| env: | |
| ORG_ID: ${{ vars.IT_ORG_ID }} | |
| GH_TOKEN: ${{ secrets.GITHUB_TOKEN }} | |
| SERVICE_USERNAME: ${{ matrix.service_username_arg }} | |
| run: | | |
| sudo "./dist/${{ matrix.binary }}" \ | |
| --update \ | |
| --org-id "$ORG_ID" \ | |
| --github-token "$GH_TOKEN" \ | |
| --service-username "$SERVICE_USERNAME" | |
| - name: Re-register service via update flow (Windows) | |
| if: runner.os == 'Windows' | |
| shell: pwsh | |
| env: | |
| ORG_ID: ${{ vars.IT_ORG_ID }} | |
| GH_TOKEN: ${{ secrets.GITHUB_TOKEN }} | |
| SERVICE_USERNAME: ${{ matrix.service_username_arg }} | |
| SERVICE_PASSWORD: ${{ steps.provision.outputs.password }} | |
| run: | | |
| & "./dist/${{ matrix.binary }}" ` | |
| --update ` | |
| --org-id $env:ORG_ID ` | |
| --github-token $env:GH_TOKEN ` | |
| --service-username $env:SERVICE_USERNAME ` | |
| --service-password $env:SERVICE_PASSWORD | |
| - name: Assert service runs as account (update flow) | |
| uses: ./.github/actions/assert-service-identity | |
| with: | |
| service: ${{ matrix.service }} | |
| expected_identity: ${{ matrix.service_identity }} | |
| - name: Assert password absent from config (update flow) | |
| uses: ./.github/actions/assert-config-secret-absent | |
| with: | |
| config_dir: ${{ matrix.config_dir }} | |
| org_id: ${{ vars.IT_ORG_ID }} | |
| secret: ${{ steps.provision.outputs.password }} | |
| - name: Uninstall agent | |
| uses: ./.github/actions/run-agent | |
| with: | |
| binary: ${{ matrix.binary }} | |
| args: --uninstall --org-id ${{ vars.IT_ORG_ID }} | |
| - name: Check deleted directories | |
| uses: ./.github/actions/assert-uninstalled | |
| with: | |
| paths: ${{ matrix.uninstall_paths }} | |
| - name: Remove service account | |
| if: always() | |
| uses: ./.github/actions/remove-service-user | |
| with: | |
| username: ${{ matrix.service_user }} |