Skip to content
Open
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
320 changes: 320 additions & 0 deletions build-tools/automation/scripts/CaptureLogcat.ps1
Original file line number Diff line number Diff line change
@@ -0,0 +1,320 @@
[CmdletBinding()]
param (
[Parameter(Mandatory = $true)]
[string] $Destination,
[Parameter(Mandatory = $true)]
[string] $DeviceOutput,
[string] $AdbPath = 'adb',
[int] $DeviceTimeoutSeconds = 10,
[int] $LogcatTimeoutSeconds = 45,
[int] $TerminationTimeoutSeconds = 2,
[int] $OutputDrainTimeoutSeconds = 5
)

$ErrorActionPreference = 'Stop'

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Same question here, should we introduce powershell? Or use inline bash in yaml?


function Write-CaptureWarning {
param (
[Parameter(Mandatory = $true)]
[string] $Message
)

$escapedMessage = $Message.Replace('%', '%AZP25').Replace("`r", '%0D').Replace("`n", '%0A')
Write-Host "##vso[task.logissue type=warning]$escapedMessage"
}

function Read-ProcessOutput {
param (
[Parameter(Mandatory = $true)]
[string] $Path
)

if (-not (Test-Path -LiteralPath $Path)) {
return ''
}

$content = Get-Content -LiteralPath $Path -Raw
if ($null -eq $content) {
return ''
}

return $content.TrimEnd()
}

function Get-OutputLength {
param (
[Parameter(Mandatory = $true)]
[string] $Path
)

if (-not (Test-Path -LiteralPath $Path)) {
return 0
}

return (Get-Item -LiteralPath $Path).Length
}

function Write-ProcessSummary {
param (
[Parameter(Mandatory = $true)]
[string] $Description,
[Parameter(Mandatory = $true)]
[PSCustomObject] $Result,
[Parameter(Mandatory = $true)]
[string] $OutputPath
)

$exitCode = if ($null -eq $Result.ExitCode) { 'none' } else { $Result.ExitCode }
$outputLength = Get-OutputLength -Path $OutputPath
Write-Host "$(Get-Date -AsUTC -Format 'yyyy-MM-ddTHH:mm:ssZ') finished $Description; elapsed=$($Result.ElapsedSeconds)s; exitCode=$exitCode; timedOut=$($Result.TimedOut); bytes=$outputLength"
}

function Wait-ForOutputDrain {
param (
[Parameter(Mandatory = $true)]
[Threading.Tasks.Task[]] $Tasks,
[Parameter(Mandatory = $true)]
[int] $TimeoutSeconds
)

$drainTask = [Threading.Tasks.Task]::WhenAll($Tasks)
try {
if (-not $drainTask.Wait([int] [TimeSpan]::FromSeconds($TimeoutSeconds).TotalMilliseconds)) {
return [PSCustomObject] @{
TimedOut = $true
Error = ''
}
}
} catch [AggregateException] {
$errorMessage = ($_.Exception.Flatten().InnerExceptions | ForEach-Object { $_.Message }) -join '; '
return [PSCustomObject] @{
TimedOut = $false
Error = $errorMessage
}
}

return [PSCustomObject] @{
TimedOut = $false
Error = ''
}
}

function Invoke-BoundedProcess {
param (
[Parameter(Mandatory = $true)]
[string] $FilePath,
[Parameter(Mandatory = $true)]
[string[]] $Arguments,
[Parameter(Mandatory = $true)]
[string] $StandardOutputPath,
[Parameter(Mandatory = $true)]
[string] $StandardErrorPath,
[Parameter(Mandatory = $true)]
[int] $TimeoutSeconds,
[Parameter(Mandatory = $true)]
[int] $TerminationTimeoutSeconds,
[Parameter(Mandatory = $true)]
[int] $OutputDrainTimeoutSeconds,
[hashtable] $EnvironmentVariables = @{}
)

$process = $null
$standardOutput = $null
$standardError = $null
$stopwatch = [Diagnostics.Stopwatch]::StartNew()
try {
$startInfo = [Diagnostics.ProcessStartInfo]::new()
$startInfo.FileName = $FilePath
$startInfo.UseShellExecute = $false
$startInfo.CreateNoWindow = $true
$startInfo.RedirectStandardOutput = $true
$startInfo.RedirectStandardError = $true
foreach ($argument in $Arguments) {
$startInfo.ArgumentList.Add($argument)
}
foreach ($name in $EnvironmentVariables.Keys) {
$startInfo.Environment[$name] = $EnvironmentVariables[$name]
}

$standardOutput = [IO.File]::Open($StandardOutputPath, [IO.FileMode]::Create, [IO.FileAccess]::Write, [IO.FileShare]::Read)
$standardError = [IO.File]::Open($StandardErrorPath, [IO.FileMode]::Create, [IO.FileAccess]::Write, [IO.FileShare]::Read)
$process = [Diagnostics.Process]::new()
$process.StartInfo = $startInfo
if (-not $process.Start()) {
throw "Failed to start '$FilePath'."
}

$standardOutputTask = $process.StandardOutput.BaseStream.CopyToAsync($standardOutput)
$standardErrorTask = $process.StandardError.BaseStream.CopyToAsync($standardError)

$exited = $process.WaitForExit([int] [TimeSpan]::FromSeconds($TimeoutSeconds).TotalMilliseconds)
$killError = ''
$terminationTimedOut = $false
if (-not $exited) {
try {
$process.Kill($true)
} catch [InvalidOperationException] {
# The process exited between the timeout and the kill request.
} catch {
$killError = $_.Exception.Message
}

$terminationTimedOut = -not $process.WaitForExit([int] [TimeSpan]::FromSeconds($TerminationTimeoutSeconds).TotalMilliseconds)
}

$outputDrain = Wait-ForOutputDrain `
Comment thread
simonrozsival marked this conversation as resolved.
-Tasks @($standardOutputTask, $standardErrorTask) `
-TimeoutSeconds $OutputDrainTimeoutSeconds
$stopwatch.Stop()
return [PSCustomObject] @{
ExitCode = if ($exited) { $process.ExitCode } else { $null }
TimedOut = -not $exited
TerminationTimedOut = $terminationTimedOut
KillError = $killError
OutputDrainTimedOut = $outputDrain.TimedOut
OutputDrainError = $outputDrain.Error
ElapsedSeconds = [Math]::Round($stopwatch.Elapsed.TotalSeconds, 1)
}
} finally {
$stopwatch.Stop()
if ($null -ne $standardOutput) {
$standardOutput.Dispose()
}
if ($null -ne $standardError) {
$standardError.Dispose()
}
if ($null -ne $process) {
$process.Dispose()
}
}
}

function Get-FailureDetails {
param (
[string] $StandardError,
[string] $KillError,
[bool] $TerminationTimedOut,
[bool] $OutputDrainTimedOut,
[string] $OutputDrainError
)

$details = @()
if (-not [string]::IsNullOrWhiteSpace($StandardError)) {
$details += "stderr: $StandardError"
}
if (-not [string]::IsNullOrWhiteSpace($KillError)) {
$details += "kill failed: $KillError"
}
if ($TerminationTimedOut) {
$details += "process did not exit within $TerminationTimeoutSeconds seconds after termination"
}
if ($OutputDrainTimedOut) {
$details += "output did not finish draining within $OutputDrainTimeoutSeconds seconds"
}
if (-not [string]::IsNullOrWhiteSpace($OutputDrainError)) {
$details += "output drain failed: $OutputDrainError"
}

if ($details.Count -eq 0) {
return ''
}

return '; ' + ($details -join '; ')
}

$temporaryPaths = @()

try {
$devicesErrorPath = [IO.Path]::GetTempFileName()
$logcatErrorPath = [IO.Path]::GetTempFileName()
$temporaryPaths = @($devicesErrorPath, $logcatErrorPath)

$destinationDirectory = Split-Path -Parent $Destination
if ([string]::IsNullOrEmpty($destinationDirectory)) {
$destinationDirectory = (Get-Location).Path
}
New-Item -ItemType Directory -Force -Path $destinationDirectory | Out-Null

Write-Host "$(Get-Date -AsUTC -Format 'yyyy-MM-ddTHH:mm:ssZ') starting adb devices"
$devicesResult = Invoke-BoundedProcess `
-FilePath $AdbPath `
-Arguments @('devices') `
-StandardOutputPath $DeviceOutput `
-StandardErrorPath $devicesErrorPath `
-TimeoutSeconds $DeviceTimeoutSeconds `
-TerminationTimeoutSeconds $TerminationTimeoutSeconds `
-OutputDrainTimeoutSeconds $OutputDrainTimeoutSeconds
Write-ProcessSummary -Description 'adb devices' -Result $devicesResult -OutputPath $DeviceOutput
$devicesOutput = Read-ProcessOutput -Path $DeviceOutput
$devicesError = Read-ProcessOutput -Path $devicesErrorPath

if (-not [string]::IsNullOrWhiteSpace($devicesOutput)) {
Write-Host $devicesOutput
}
if ($devicesResult.TimedOut) {
$details = Get-FailureDetails -StandardError $devicesError -KillError $devicesResult.KillError -TerminationTimedOut $devicesResult.TerminationTimedOut -OutputDrainTimedOut $devicesResult.OutputDrainTimedOut -OutputDrainError $devicesResult.OutputDrainError
Write-CaptureWarning "logcat capture skipped: adb devices timed out after $DeviceTimeoutSeconds seconds$details"
exit 0
}
if ($devicesResult.ExitCode -ne 0) {
$details = Get-FailureDetails -StandardError $devicesError -KillError '' -TerminationTimedOut $false -OutputDrainTimedOut $devicesResult.OutputDrainTimedOut -OutputDrainError $devicesResult.OutputDrainError
Write-CaptureWarning "logcat capture skipped: adb devices exited with code $($devicesResult.ExitCode)$details"
exit 0
}
if ($devicesResult.OutputDrainTimedOut -or -not [string]::IsNullOrWhiteSpace($devicesResult.OutputDrainError)) {
$details = Get-FailureDetails -StandardError $devicesError -KillError '' -TerminationTimedOut $false -OutputDrainTimedOut $devicesResult.OutputDrainTimedOut -OutputDrainError $devicesResult.OutputDrainError
Write-CaptureWarning "logcat capture skipped: adb devices output was incomplete$details"
exit 0
}
if (-not [string]::IsNullOrWhiteSpace($devicesError)) {
Write-Host $devicesError
}

$connectedDevice = $devicesOutput -split '\r?\n' | Where-Object { $_ -match '^\S+\s+device(?:\s|$)' } | Select-Object -First 1
if ($null -eq $connectedDevice) {
Write-Host 'logcat capture skipped: no connected device'
exit 0
}

Write-Host "$(Get-Date -AsUTC -Format 'yyyy-MM-ddTHH:mm:ssZ') starting adb logcat -d with ADB_TRACE=adb,shell"
$logcatResult = Invoke-BoundedProcess `
-FilePath $AdbPath `
-Arguments @('logcat', '-d') `
-StandardOutputPath $Destination `
-StandardErrorPath $logcatErrorPath `
-TimeoutSeconds $LogcatTimeoutSeconds `
-TerminationTimeoutSeconds $TerminationTimeoutSeconds `
-OutputDrainTimeoutSeconds $OutputDrainTimeoutSeconds `
-EnvironmentVariables @{ ADB_TRACE = 'adb,shell' }
Write-ProcessSummary -Description 'adb logcat -d' -Result $logcatResult -OutputPath $Destination
$logcatError = Read-ProcessOutput -Path $logcatErrorPath
if (-not [string]::IsNullOrWhiteSpace($logcatError)) {
Write-Host $logcatError
}

if ($logcatResult.TimedOut) {
$details = Get-FailureDetails -StandardError $logcatError -KillError $logcatResult.KillError -TerminationTimedOut $logcatResult.TerminationTimedOut -OutputDrainTimedOut $logcatResult.OutputDrainTimedOut -OutputDrainError $logcatResult.OutputDrainError
Write-CaptureWarning "logcat capture timed out after $LogcatTimeoutSeconds seconds; partial output was retained at $Destination$details"
exit 0
}
if ($logcatResult.ExitCode -ne 0) {
$details = Get-FailureDetails -StandardError $logcatError -KillError '' -TerminationTimedOut $false -OutputDrainTimedOut $logcatResult.OutputDrainTimedOut -OutputDrainError $logcatResult.OutputDrainError
Write-CaptureWarning "logcat capture exited with code $($logcatResult.ExitCode); partial output was retained at $Destination$details"
exit 0
}
if ($logcatResult.OutputDrainTimedOut -or -not [string]::IsNullOrWhiteSpace($logcatResult.OutputDrainError)) {
$details = Get-FailureDetails -StandardError $logcatError -KillError '' -TerminationTimedOut $false -OutputDrainTimedOut $logcatResult.OutputDrainTimedOut -OutputDrainError $logcatResult.OutputDrainError
Write-CaptureWarning "logcat capture output was incomplete; partial output was retained at $Destination$details"
exit 0
}

Write-Host "logcat capture completed: $Destination"
} catch {
Write-CaptureWarning "logcat capture failed: $($_.Exception.Message)"
} finally {
if ($temporaryPaths.Count -gt 0) {
Remove-Item -LiteralPath $temporaryPaths -Force -ErrorAction Ignore
}
}

exit 0
58 changes: 8 additions & 50 deletions build-tools/automation/yaml-templates/apk-instrumentation.yaml
Original file line number Diff line number Diff line change
Expand Up @@ -82,58 +82,16 @@ steps:
# earlier step failed or the job was canceled - in particular a failed -t:Install
# (which now fails the lane fast) or a hung/timed-out test run. Losing logcat in
# exactly those cases would defeat the diagnostics this template exists for; the
# capture is best-effort and time-bounded. See dotnet/android#11830.
- script: |
set -e
DEST="$(Build.StagingDirectory)/Test${{ parameters.configuration }}/${{ parameters.artifactFolder }}/"
mkdir -p "$DEST"
SECONDS=0
ADB_PID=""
trap 'if [ -n "$ADB_PID" ]; then
kill -KILL "$ADB_PID" 2>/dev/null || echo "adb client $ADB_PID already exited"
wait "$ADB_PID" 2>/dev/null || :
fi' EXIT
trap 'exit 130' INT
trap 'exit 143' TERM
run_adb() {
local OUTPUT="$1" STATUS=0
shift
echo "$(date -u '+%Y-%m-%dT%H:%M:%SZ') starting $*; elapsed=${SECONDS}s"
"$@" > "$OUTPUT" &
ADB_PID=$!
while kill -0 "$ADB_PID" 2>/dev/null; do
if [ "$SECONDS" -ge 45 ]; then
echo "capture deadline exceeded: $*; elapsed=${SECONDS}s; bytes=$(wc -c < "$OUTPUT")"
kill -KILL "$ADB_PID" 2>/dev/null || echo "adb client $ADB_PID already exited"
wait "$ADB_PID" 2>/dev/null || :
ADB_PID=""
return 124
fi
sleep 1
done
wait "$ADB_PID" || STATUS=$?
ADB_PID=""
echo "$* exited with code $STATUS; elapsed=${SECONDS}s; bytes=$(wc -c < "$OUTPUT")"
return "$STATUS"
}
ADB_STATUS=0
run_adb "$DEST/adb-devices-${{ parameters.testName }}.txt" adb devices || ADB_STATUS=$?
cat "$DEST/adb-devices-${{ parameters.testName }}.txt"
if [ "$ADB_STATUS" -ne 0 ]; then
exit "$ADB_STATUS"
fi
if awk 'NR > 1 && $2 == "device" { found=1 } END { exit !found }' "$DEST/adb-devices-${{ parameters.testName }}.txt"; then
run_adb "$DEST/logcat-${{ parameters.testName }}.txt" env ADB_TRACE=adb,shell adb logcat -d
else
echo "logcat capture skipped: no connected device"
fi
# capture is best-effort, internally time-bounded, and does not change the job
# status when diagnostics cannot be collected. See dotnet/android#11830 and
# dotnet/android#12704.
- powershell: |
$destinationDirectory = "$(Build.StagingDirectory)/Test${{ parameters.configuration }}/${{ parameters.artifactFolder }}"
& "${{ parameters.xaSourcePath }}/build-tools/automation/scripts/CaptureLogcat.ps1" `
-Destination "$destinationDirectory/logcat-${{ parameters.testName }}.txt" `
-DeviceOutput "$destinationDirectory/adb-devices-${{ parameters.testName }}.txt"
displayName: capture logcat ${{ parameters.testName }}
condition: always()
continueOnError: true
# Return failure before task cancellation so Azure can retry a hung capture.
# Allow two 45s attempts plus retry/startup overhead.
retryCountOnTaskFailure: 1
timeoutInMinutes: 2

- task: PublishTestResults@2
displayName: publish ${{ parameters.testName }} results
Expand Down