Add build hang diagnostics on CI. (#34982)
* Add build hang diagnostics on CI. * Use sigkill.
This commit is contained in:
@@ -0,0 +1,99 @@
|
||||
// Copyright (c) 2026 The Brave Authors. All rights reserved.
|
||||
// This Source Code Form is subject to the terms of the Mozilla Public
|
||||
// License, v. 2.0. If a copy of the MPL was not distributed with this file,
|
||||
// You can obtain one at https://mozilla.org/MPL/2.0/.
|
||||
|
||||
import fs from 'node:fs'
|
||||
import os from 'node:os'
|
||||
import path from 'node:path'
|
||||
import { dumpBuildHangDiagnostics } from './buildDiagnostics.ts'
|
||||
import Log from './logging.js'
|
||||
|
||||
jest.mock('./logging.js', () => ({
|
||||
error: jest.fn(),
|
||||
}))
|
||||
|
||||
describe('dumpBuildHangDiagnostics', () => {
|
||||
let tempDir: string
|
||||
let consoleLogSpy: jest.SpyInstance
|
||||
|
||||
beforeEach(() => {
|
||||
tempDir = fs.mkdtempSync(path.join(os.tmpdir(), 'ci-diagnostics-'))
|
||||
consoleLogSpy = jest.spyOn(console, 'log').mockImplementation(() => {})
|
||||
jest.clearAllMocks()
|
||||
})
|
||||
|
||||
afterEach(() => {
|
||||
consoleLogSpy.mockRestore()
|
||||
jest.restoreAllMocks()
|
||||
fs.rmSync(tempDir, { recursive: true, force: true })
|
||||
})
|
||||
|
||||
it('logs the contents of an existing diagnostics file', () => {
|
||||
const diagPath = path.join(tempDir, 'siso.INFO')
|
||||
fs.writeFileSync(diagPath, 'first line\nsecond line\n', 'utf8')
|
||||
|
||||
dumpBuildHangDiagnostics(tempDir)
|
||||
|
||||
expect(consoleLogSpy).toHaveBeenCalledWith(`--- tail of ${diagPath} ---`)
|
||||
expect(consoleLogSpy).toHaveBeenCalledWith('first line\nsecond line\n')
|
||||
expect(Log.error).not.toHaveBeenCalled()
|
||||
})
|
||||
|
||||
it('reads a redirected diagnostics file when the local file is missing', () => {
|
||||
const redirectedTarget = path.join(tempDir, 'redirect-target.INFO')
|
||||
const redirectedMarker = path.join(tempDir, 'siso.exe.INFO.redirected')
|
||||
fs.writeFileSync(redirectedTarget, 'redirected output\n', 'utf8')
|
||||
fs.writeFileSync(redirectedMarker, `${redirectedTarget}\n`, 'utf8')
|
||||
|
||||
dumpBuildHangDiagnostics(tempDir)
|
||||
|
||||
expect(consoleLogSpy).toHaveBeenCalledWith(
|
||||
`--- tail of ${redirectedTarget} ---`,
|
||||
)
|
||||
expect(consoleLogSpy).toHaveBeenCalledWith('redirected output\n')
|
||||
expect(Log.error).not.toHaveBeenCalled()
|
||||
})
|
||||
|
||||
it('logs an error when a redirected target does not exist', () => {
|
||||
const redirectedTarget = path.join(tempDir, 'missing.INFO')
|
||||
const redirectedMarker = path.join(tempDir, 'siso_output.redirected')
|
||||
fs.writeFileSync(redirectedMarker, redirectedTarget, 'utf8')
|
||||
|
||||
dumpBuildHangDiagnostics(tempDir)
|
||||
|
||||
expect(Log.error).toHaveBeenCalledWith(
|
||||
`Redirected file ${redirectedTarget} does not exist`,
|
||||
)
|
||||
expect(consoleLogSpy).not.toHaveBeenCalled()
|
||||
})
|
||||
|
||||
it('logs read errors without throwing', () => {
|
||||
const diagPath = path.join(tempDir, 'siso.INFO')
|
||||
fs.writeFileSync(diagPath, 'content that will not be read', 'utf8')
|
||||
|
||||
const realFs = jest.requireActual('node:fs') as typeof import('node:fs')
|
||||
jest.spyOn(fs, 'openSync').mockImplementation((...args) => {
|
||||
if (args[0] === diagPath) {
|
||||
throw new Error('open failed')
|
||||
}
|
||||
return realFs.openSync(...args)
|
||||
})
|
||||
|
||||
dumpBuildHangDiagnostics(tempDir)
|
||||
|
||||
expect(consoleLogSpy).toHaveBeenCalledWith(`--- tail of ${diagPath} ---`)
|
||||
expect(Log.error).toHaveBeenCalledWith('open failed')
|
||||
})
|
||||
|
||||
it('prints only the final complete lines for oversized files', () => {
|
||||
const diagPath = path.join(tempDir, 'siso.INFO')
|
||||
const content = `${'a'.repeat(130 * 1024)}\nkept line 1\nkept line 2\n`
|
||||
fs.writeFileSync(diagPath, content, 'utf8')
|
||||
|
||||
dumpBuildHangDiagnostics(tempDir)
|
||||
|
||||
expect(consoleLogSpy).toHaveBeenCalledWith('kept line 1\nkept line 2\n')
|
||||
expect(Log.error).not.toHaveBeenCalled()
|
||||
})
|
||||
})
|
||||
@@ -0,0 +1,71 @@
|
||||
// Copyright (c) 2026 The Brave Authors. All rights reserved.
|
||||
// This Source Code Form is subject to the terms of the Mozilla Public
|
||||
// License, v. 2.0. If a copy of the MPL was not distributed with this file,
|
||||
// You can obtain one at https://mozilla.org/MPL/2.0/.
|
||||
|
||||
import fs from 'node:fs'
|
||||
import path from 'node:path'
|
||||
import Log from './logging.js'
|
||||
|
||||
const kReadFileTailLimitBytes = 128 * 1024
|
||||
|
||||
/**
|
||||
* Dumps the hanged build diagnostics for a build.
|
||||
* @param {string} outputDir
|
||||
*/
|
||||
export function dumpBuildHangDiagnostics(outputDir: string) {
|
||||
const relativePaths = ['siso.INFO', 'siso.exe.INFO', 'siso_output']
|
||||
for (const rel of relativePaths) {
|
||||
let filePath = path.join(outputDir, rel)
|
||||
if (!fs.existsSync(filePath)) {
|
||||
const filePathRedirected = path.join(outputDir, rel + '.redirected')
|
||||
if (fs.existsSync(filePathRedirected)) {
|
||||
// read the redirected file and get the path
|
||||
const redirectedContent = fs.readFileSync(filePathRedirected, 'utf8')
|
||||
const redirectedPath = redirectedContent.trim()
|
||||
if (fs.existsSync(redirectedPath)) {
|
||||
filePath = redirectedPath
|
||||
} else {
|
||||
Log.error(`Redirected file ${redirectedPath} does not exist`)
|
||||
continue
|
||||
}
|
||||
} else {
|
||||
continue
|
||||
}
|
||||
}
|
||||
console.log(`--- tail of ${filePath} ---`)
|
||||
try {
|
||||
console.log(readFileTailUtf8Sync(filePath, kReadFileTailLimitBytes))
|
||||
} catch (err) {
|
||||
Log.error(err instanceof Error ? err.message : String(err))
|
||||
}
|
||||
}
|
||||
}
|
||||
|
||||
/**
|
||||
* Reads only the last `maxBytes` bytes from a file.
|
||||
*/
|
||||
function readFileTailUtf8Sync(filePath: string, maxBytes: number): string {
|
||||
const fd = fs.openSync(filePath, 'r')
|
||||
try {
|
||||
const size = fs.fstatSync(fd).size
|
||||
if (size === 0) {
|
||||
return ''
|
||||
}
|
||||
const toRead = Math.min(maxBytes, size)
|
||||
const buf = Buffer.alloc(toRead)
|
||||
fs.readSync(fd, buf, 0, toRead, size - toRead)
|
||||
// May start mid-sequence for UTF-8; Node replaces invalid bytes at slice
|
||||
// edge.
|
||||
let str = buf.toString('utf8')
|
||||
if (toRead < size) {
|
||||
const nl = str.indexOf('\n')
|
||||
if (nl !== -1) {
|
||||
str = str.slice(nl + 1)
|
||||
}
|
||||
}
|
||||
return str
|
||||
} finally {
|
||||
fs.closeSync(fd)
|
||||
}
|
||||
}
|
||||
@@ -18,6 +18,7 @@ import ActionGuard from './actionGuard.js'
|
||||
import { GitPatcher } from './gitPatcher.js'
|
||||
import { getBuildArgs } from './buildArgs.ts'
|
||||
import { isCI, isTeamcity } from './ciDetect.ts'
|
||||
import { dumpBuildHangDiagnostics } from './buildDiagnostics.ts'
|
||||
|
||||
// Do not limit the number of listeners to avoid warnings from EventEmitter.
|
||||
process.setMaxListeners(0)
|
||||
@@ -228,13 +229,22 @@ const util = {
|
||||
args = [],
|
||||
options = /** @type {Record<string, any>} */ ({}),
|
||||
) => {
|
||||
let { continueOnFail, verbose, onStdErrLine, onStdOutLine, ...cmdOptions } =
|
||||
options
|
||||
let {
|
||||
continueOnFail,
|
||||
verbose,
|
||||
onSpawn,
|
||||
onStdErrLine,
|
||||
onStdOutLine,
|
||||
...cmdOptions
|
||||
} = options
|
||||
if (verbose !== false) {
|
||||
Log.command(cmdOptions.cwd, cmd, args)
|
||||
}
|
||||
return new Promise((resolve, reject) => {
|
||||
const prog = spawn(...normalizeCommand(cmd, args), cmdOptions)
|
||||
if (onSpawn) {
|
||||
onSpawn(prog)
|
||||
}
|
||||
const signalsToForward = ['SIGINT', 'SIGTERM', 'SIGQUIT', 'SIGHUP']
|
||||
const signalHandler = (s) => {
|
||||
prog.kill(s)
|
||||
@@ -708,11 +718,14 @@ const util = {
|
||||
// Collect build statistics into this variable to display in a separate TC
|
||||
// block.
|
||||
let buildStats = ''
|
||||
// Updated on every autoninja log line when CI pipes output (idle watchdog).
|
||||
let lastBuildLogTime = Date.now()
|
||||
|
||||
// Parse output to display the build progress on Teamcity.
|
||||
if (isTeamcity) {
|
||||
let lastStatusTime = Date.now()
|
||||
options.onStdOutLine = (line) => {
|
||||
lastBuildLogTime = Date.now()
|
||||
if (
|
||||
buildStats
|
||||
|| /^(RBE Stats:|metric\s+count|build finished)\s+/.test(line)
|
||||
@@ -732,6 +745,14 @@ const util = {
|
||||
}
|
||||
options.onStdErrLine = options.onStdOutLine
|
||||
options.stdio = 'pipe'
|
||||
} else if (isCI) {
|
||||
const onLine = (line) => {
|
||||
lastBuildLogTime = Date.now()
|
||||
console.log(line)
|
||||
}
|
||||
options.onStdOutLine = onLine
|
||||
options.onStdErrLine = onLine
|
||||
options.stdio = 'pipe'
|
||||
}
|
||||
|
||||
// Enable to allow error post-processing after autoninja/siso failure.
|
||||
@@ -743,6 +764,14 @@ const util = {
|
||||
fs.unlinkSync(sisoOutputFile)
|
||||
}
|
||||
|
||||
let buildIdleWatchdogInterval = null
|
||||
const clearBuildIdleWatchdog = () => {
|
||||
if (buildIdleWatchdogInterval) {
|
||||
clearInterval(buildIdleWatchdogInterval)
|
||||
buildIdleWatchdogInterval = null
|
||||
}
|
||||
}
|
||||
|
||||
const buildGuard = new ActionGuard(path.join(outputDir, 'build.guard'))
|
||||
try {
|
||||
if (
|
||||
@@ -755,9 +784,36 @@ const util = {
|
||||
await util.runAsync('gn', ['clean', outputDir], options)
|
||||
}
|
||||
buildGuard.markStarted()
|
||||
await util.runAsync('autoninja', ninjaOpts, options)
|
||||
|
||||
let buildProcess = null
|
||||
const autoninjaOptions = {
|
||||
...options,
|
||||
onSpawn: (prog) => {
|
||||
buildProcess = prog
|
||||
},
|
||||
}
|
||||
|
||||
if (isCI) {
|
||||
const idleTimeoutMs = 90 * 60 * 1000 // 90 minutes
|
||||
lastBuildLogTime = Date.now()
|
||||
buildIdleWatchdogInterval = setInterval(() => {
|
||||
if (Date.now() - lastBuildLogTime <= idleTimeoutMs) {
|
||||
return
|
||||
}
|
||||
clearBuildIdleWatchdog()
|
||||
Log.error(
|
||||
`Build aborted: no autoninja output for ${idleTimeoutMs / 1000}s `,
|
||||
)
|
||||
dumpBuildHangDiagnostics(outputDir)
|
||||
util.killProcessTree(buildProcess)
|
||||
}, 10 * 1000)
|
||||
}
|
||||
|
||||
await util.runAsync('autoninja', ninjaOpts, autoninjaOptions)
|
||||
clearBuildIdleWatchdog()
|
||||
buildGuard.markFinished()
|
||||
} catch (e) {
|
||||
clearBuildIdleWatchdog()
|
||||
// Display siso_output on CI after a build failure.
|
||||
if (isCI && fs.existsSync(sisoOutputFile)) {
|
||||
const sisoOutput = fs.readFileSync(sisoOutputFile, 'utf8')
|
||||
@@ -1029,6 +1085,29 @@ const util = {
|
||||
config.defaultOptions,
|
||||
)
|
||||
},
|
||||
|
||||
/**
|
||||
* Stop a process and its descendants. On Windows, `child.kill()` often only
|
||||
* affects `cmd.exe`; `taskkill /T` tears down the full tree.
|
||||
* @param {import('node:child_process').ChildProcess | null} child
|
||||
*/
|
||||
killProcessTree: (child) => {
|
||||
if (!child?.pid) {
|
||||
return
|
||||
}
|
||||
if (process.platform === 'win32') {
|
||||
spawnSync('taskkill', ['/PID', String(child.pid), '/T', '/F'], {
|
||||
stdio: 'ignore',
|
||||
windowsHide: true,
|
||||
})
|
||||
return
|
||||
}
|
||||
try {
|
||||
child.kill('SIGKILL')
|
||||
} catch {
|
||||
// Process may already have exited.
|
||||
}
|
||||
},
|
||||
}
|
||||
|
||||
export default util
|
||||
|
||||
Reference in New Issue
Block a user