Debugging Github Actions timeout issue using Deno (Nodejs replacement)

README.md

I had a bug with golangci-lint that would time out on some Github Actions builds. In order to investigate the issue, I wrote this Deno script that would scrap all the logs and look for the memory used (we used golangci-lint with the -v flag which prints how much memory was being spent).

If you also use golangci-lint and have weird time out issues, turn on golangci-lint's -v mode and run this script.

brew install deno

Run it:

GITHUB_TOKEN=your-token deno run --allow-env --allow-net find_long_lint_jobs.ts

Example of output:

% deno run --allow-env --allow-net find_long_lint_jobs.ts
https://github.com/musicmash/auth/runs/1325955593 success (91 seconds): Memory: 69 samples, avg is 224.2MB, max is 274.4MB"
https://github.com/musicmash/auth/runs/1325955452 success (97 seconds): Memory: 62 samples, avg is 237.0MB, max is 341.1MB"
https://github.com/musicmash/auth/runs/1325934536 success (105 seconds): Memory: 74 samples, avg is 233.0MB, max is 275.3MB"
https://github.com/musicmash/auth/runs/1323969471 success (82 seconds): Memory: 58 samples, avg is 273.6MB, max is 341.1MB"
https://github.com/musicmash/auth/runs/1323958411 success (99 seconds): Memory: 83 samples, avg is 215.6MB, max is 274.5MB"
https://github.com/musicmash/auth/runs/1323942155 success (109 seconds): Memory: 69 samples, avg is 220.5MB, max is 275.2MB"
https://github.com/musicmash/auth/runs/1323931142 success (93 seconds): Memory: 69 samples, avg is 219.6MB, max is 275.0MB"
https://github.com/musicmash/auth/runs/1323876879 success (121 seconds): Memory: 73 samples, avg is 217.6MB, max is 274.4MB"
https://github.com/musicmash/auth/runs/1323856911 success (163 seconds): Memory: 86 samples, avg is 221.5MB, max is 274.2MB"
https://github.com/musicmash/auth/runs/1323845330 failure (89 seconds): Memory: 70 samples, avg is 220.2MB, max is 274.5MB"
https://github.com/musicmash/auth/runs/1323834258 failure (94 seconds): Memory: 80 samples, avg is 216.9MB, max is 274.7MB"

The script goes through all jobs/steps and tries to find a line that starts with Memory:. For example, this build log will match the penultimate line:

Run curl -sSfL https://raw.githubusercontent.com/golangci/golangci-lint/master/install.sh | sh -s -- -b $GITHUB_WORKSPACE v1.31.0
golangci/golangci-lint info checking GitHub for tag 'v1.31.0'
golangci/golangci-lint info found version: 1.31.0 for v1.31.0/linux/amd64
golangci/golangci-lint info installed /home/runner/work/auth/auth/golangci-lint
level=info msg="[config_reader] Config search paths: [./ /home/runner/work/auth/auth /home/runner/work/auth /home/runner/work /home/runner /home /]"
level=info msg="[config_reader] Used config file .golangci.yml"
level=info msg="[lintersdb] Active 49 linters: [asciicheck bodyclose deadcode depguard dogsled dupl errcheck exhaustive exportloopref funlen gci gochecknoglobals gochecknoinits gocognit goconst gocritic gocyclo goerr113 gofmt gofumpt goheader goimports gomodguard goprintffuncname gosec gosimple govet ineffassign interfacer lll maligned misspell nakedret nestif noctx nolintlint prealloc rowserrcheck scopelint sqlclosecheck staticcheck structcheck stylecheck typecheck unconvert unparam unused varcheck whitespace]"
level=info msg="[loader] Go packages loading at mode 575 (deps|files|imports|types_sizes|compiled_files|exports_file|name) took 317.12541ms"
level=info msg="[runner/filename_unadjuster] Pre-built 0 adjustments in 1.140603ms"
level=info msg="[linters context/goanalysis] analyzers took 10.9530131s with top 10 stages: buildir: 5.794236847s, the_only_name: 1.350337804s, unconvert: 498.548106ms, exhaustive: 450.786111ms, buildssa: 449.925301ms, dupl: 369.256997ms, inspect: 302.104764ms, ctrlflow: 201.60638ms, fact_deprecated: 200.789964ms, fact_purity: 138.768551ms"
level=info msg="[linters context/goanalysis] analyzers took 194.647582ms with top 10 stages: buildir: 187.696274ms, U1000: 6.951308ms"
level=warning msg="[runner/nolint] Found unknown linters in //nolint directives: funclen"
level=info msg="[runner] Issues before processing: 36, after processing: 0"
level=info msg="[runner] Processors filtering stat (out/in): path_prettifier: 36/36, exclude: 11/32, skip_files: 36/36, skip_dirs: 36/36, autogenerated_exclude: 32/36, exclude-rules: 11/11, nolint: 0/11, cgo: 36/36, filename_unadjuster: 36/36, identifier_marker: 32/32"
level=info msg="[runner] processing took 6.378909ms with stages: exclude: 3.614806ms, nolint: 930.801µs, identifier_marker: 736.801µs, path_prettifier: 507.801µs, autogenerated_exclude: 337.6µs, skip_dirs: 218.7µs, cgo: 20µs, filename_unadjuster: 7.4µs, max_same_issues: 1.1µs, max_from_linter: 500ns, uniq_by_line: 500ns, severity-rules: 500ns, diff: 400ns, source_code: 400ns, path_shortener: 400ns, max_per_file_from_linter: 400ns, exclude-rules: 300ns, sort_results: 300ns, skip_files: 200ns, path_prefixer: 0s"
level=info msg="[runner] linters took 6.429122689s with stages: goanalysis_metalinter: 6.146065577s, unused: 276.561403ms"
level=info msg="File cache stats: 27 entries of total size 23.1KiB"
level=info msg="Memory: 69 samples, avg is 224.2MB, max is 274.4MB"
level=info msg="Execution took 6.758112224s"

find_long_lint_jobs.ts

async function get(url: string) {
  let token = Deno.env.get("GITHUB_TOKEN");
  if (token == undefined) {
    console.log("GITHUB_TOKEN must be set");
    Deno.exit(1);
  }
  return await fetch(url, {
    headers: {
      Authorization: `Bearer ${token}`,
    },
    redirect: "follow",
  });
}

// https://developer.github.com/v3/actions/workflow-runs/#list-workflow-runs
let resp = await get(
  "https://api.github.com/repos/musicmash/auth/actions/runs"
);
let resp_json: { workflow_runs: [{ jobs_url: string }] } = await resp.json();

if (resp.status != 200) {
  console.log(resp);
  Deno.exit(1);
}

for (const workflow_run of resp_json.workflow_runs) {
  let jobs_resp: {
    // https://docs.github.com/en/rest/reference/actions#get-a-job-for-a-workflow-run
    jobs: [
      {
        name: string;
        started_at: string;
        completed_at: string;
        url: string;
        html_url: string;
        conclusion: string;
        id: string;
      }
    ];
  } = await get(workflow_run.jobs_url).then((x) => x.json());

  for (const job of jobs_resp.jobs) {
    // https://docs.github.com/en/rest/reference/actions#download-job-logs-for-a-workflow-run
    let log_resp = await get(job.url + "/logs");
    if (log_resp.body == null) {
      continue;
    }

    let log_str = "";
    let reader = log_resp.body.getReader();
    while (true) {
      let body = await reader.read();

      if (body == undefined) {
        continue;
      }

      if (body.done == true) {
        break;
      }

      if (body.value == undefined) {
        continue;
      }

      log_str += new TextDecoder("utf-8").decode(body.value);
    }

    let res = log_str.match(/Memory:.*$/gm);
    if (res == null) {
      continue;
    }
    log_str = res.join(" ");

    let result = {
      seconds:
        (new Date(job.completed_at).getTime() -
          new Date(job.started_at).getTime()) /
        1000,
      url: job.html_url,
      conclusion: job.conclusion,
      logs: log_str,
    };
    console.log(
      `${result.url} ${result.conclusion} (${result.seconds} seconds): ${result.logs}`
    );
  }
}