large increase in claim expired tasks on Firefox CI cluster around the start of October, 2023

[bhearsum]

As shown in https://sql.telemetry.mozilla.org/queries/95924/source?p_date=2023-03-01#236915.

The first small bump appears to be October 5th, followed by a much larger bump on October 10th. It drops a bit after that (but not back to normal levels), and then hits a new peak on November 8th.

[bhearsum]

https://bugzilla.mozilla.org/show_bug.cgi?id=1859204 was filed about this as well.

[bhearsum]

One thing I wondered was whether this was spot termination related. Here's an example of where this seems to have happened on a bitbar machine, which might disprove that?

provisionerId: proj-autophone
workerType: gecko-t-bitbar-gw-perf-a51
taskQueueId: proj-autophone/gecko-t-bitbar-gw-perf-a51
schedulerId: gecko-level-3
projectId: none
taskGroupId: f8jCP1KrSwKLNBdCfvLRVg
dependencies:
  - F9DsHj7jS0C2V0CzLyAFbA
  - FGME-1ZhR6ypEZHtJYFIgw
  - GizFup4qRx29HhWmDGXdHA
  - JvnukrsZTou0hotu606M0A
  - VzxY2QkvSXajQxzK1cJiAQ
  - cWGy4YtxQkGNtz0X1N4ATQ
  - dSJjH8_kRUSk1xLmr3W1dA
requires: all-completed
routes:
  - tc-treeherder.v2.autoland.9591bcc532c4599dba688d3555c6a0135139c39a
priority: low
retries: 5
created: '2023-10-09T16:54:53.829Z'
deadline: '2023-10-10T16:54:53.829Z'
expires: '2024-10-08T16:54:53.829Z'
scopes:
  - project:releng:services/tooltool/api/download/public
  - project:releng:services/tooltool/api/download/internal
  - secrets:get:project/perftest/gecko/level-3/perftest-login
payload:
  env:
    LANG: en_US.UTF-8
    PYTHON: python3
    NEED_XVFB: 'false'
    MOZ_FETCHES: >-
      [{"artifact": "public/build/browsertime.tar.zst", "extract": true, "task":
      "cWGy4YtxQkGNtz0X1N4ATQ"}, {"artifact": "public/build/fix-stacks.tar.zst",
      "extract": true, "task": "dSJjH8_kRUSk1xLmr3W1dA"}, {"artifact":
      "public/build/geckodriver.tar.gz", "extract": true, "task":
      "F9DsHj7jS0C2V0CzLyAFbA"}, {"artifact":
      "public/build/minidump-stackwalk.tar.zst", "extract": true, "task":
      "FGME-1ZhR6ypEZHtJYFIgw"}, {"artifact": "public/build/node.tar.zst",
      "extract": true, "task": "GizFup4qRx29HhWmDGXdHA"}, {"artifact":
      "public/ffmpeg-4.4.1-i686-static.tar.xz", "extract": true, "task":
      "JvnukrsZTou0hotu606M0A"}]
    MOZ_NODE_PATH: /usr/local/bin/node
    MOZ_NO_REMOTE: '1'
    MOZ_SCM_LEVEL: '3'
    GECKO_HEAD_REV: 9591bcc532c4599dba688d3555c6a0135139c39a
    MOZHARNESS_URL: >-
      https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/VzxY2QkvSXajQxzK1cJiAQ/artifacts/public/build/mozharness.zip
    MOZ_AUTOMATION: '1'
    MOZ_FETCHES_DIR: fetches
    SCCACHE_DISABLE: '1'
    MOZHARNESS_CONFIG: raptor/android_hw_config.py
    MOZHARNESS_SCRIPT: raptor_script.py
    MOZILLA_BUILD_URL: >-
      https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/VzxY2QkvSXajQxzK1cJiAQ/artifacts/public/build/geckoview_example.apk
    XPCOM_DEBUG_BREAK: warn
    GECKO_HEAD_REPOSITORY: https://hg.mozilla.org/integration/autoland
    MOZ_HIDE_RESULTS_TABLE: '1'
    NO_FAIL_ON_TEST_ERRORS: '1'
    EXTRA_MOZHARNESS_CONFIG: >-
      {"installer_url":
      "https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/VzxY2QkvSXajQxzK1cJiAQ/artifacts/public/build/geckoview_example.apk",
      "test_packages_url":
      "https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/VzxY2QkvSXajQxzK1cJiAQ/artifacts/public/build/en-US/target.test_packages.json"}
    TASKCLUSTER_WORKER_TYPE: t-bitbar-gw-perf-a51
  mounts:
    - file: test-linux.sh
      content:
        url: >-
          https://hg.mozilla.org/integration/autoland/raw-file/9591bcc532c4599dba688d3555c6a0135139c39a/taskcluster/scripts/tester/test-linux.sh
    - file: ./run-task
      content:
        url: >-
          http://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/f8jCP1KrSwKLNBdCfvLRVg/artifacts/public/run-task
    - file: ./fetch-content
      content:
        url: >-
          http://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/f8jCP1KrSwKLNBdCfvLRVg/artifacts/public/fetch-content
  command:
    - - chmod
      - +x
      - run-task
    - - ./run-task
      - '--user'
      - root
      - '--group'
      - root
      - '--'
      - /builds/taskcluster/script.py
      - bash
      - ./test-linux.sh
      - '--cfg'
      - mozharness/configs/raptor/android_hw_config.py
      - '--browsertime-no-ffwindowrecorder'
      - '--conditioned-profile=settled'
      - '--chimera'
      - '--disable-fission'
      - '--device-name=a51'
      - '--browsertime-video'
      - '--browsertime-visualmetrics'
      - '--app=geckoview'
      - '--activity=org.mozilla.geckoview_example.GeckoViewActivity'
      - '--binary-path=org.mozilla.geckoview_example'
      - '--test=google-maps'
      - '--project=autoland'
      - '--browsertime-browsertimejs'
      - $MOZ_FETCHES_DIR/browsertime/node_modules/browsertime/bin/browsertime.js
      - '--browsertime-node'
      - $MOZ_FETCHES_DIR/node/bin/node
      - '--browsertime-geckodriver'
      - $MOZ_FETCHES_DIR/geckodriver
      - '--browsertime-chromedriver'
      - $MOZ_FETCHES_DIR/{}chromedriver
      - '--browsertime-ffmpeg'
      - $MOZ_FETCHES_DIR/ffmpeg-4.4.1-i686-static/ffmpeg
      - '--download-symbols'
      - ondemand
  features:
    taskclusterProxy: true
  artifacts:
    - name: public/test/
      path: artifacts/public
      type: directory
      expires: '2024-10-08T16:54:53.829Z'
    - name: public/logs/
      path: workspace/logs
      type: directory
      expires: '2024-10-08T16:54:53.829Z'
    - name: public/test_info/
      path: workspace/build/blobber_upload_dir
      type: directory
      expires: '2024-10-08T16:54:53.829Z'
  maxRunTime: 3600
  onExitStatus:
    retry:
      - 4
      - 137
metadata:
  name: >-
    test-android-hw-a51-11-0-aarch64-shippable-qr/opt-browsertime-tp6m-geckoview-google-maps-nofis
  owner: gijskruitbosch@gmail.com
  source: >-
    https://hg.mozilla.org/integration/autoland/file/9591bcc532c4599dba688d3555c6a0135139c39a/taskcluster/ci/test
  description: >-
    Raptor (browsertime) tp6 page-load tests on android without fission enabled
    on Geckoview on google-maps ([Treeherder
    job](https://treeherder.mozilla.org/#/jobs?repo=autoland&revision=9591bcc532c4599dba688d3555c6a0135139c39a&selectedTaskRun=N7XTxYS6QMWGPfE8RnufjQ))
tags:
  os: linux-bitbar
  kind: test
  label: >-
    test-android-hw-a51-11-0-aarch64-shippable-qr/opt-browsertime-tp6m-geckoview-google-maps-nofis
  retrigger: 'true'
  test-type: raptor
  createdForUser: gijskruitbosch@gmail.com
  worker-implementation: generic-worker
extra:
  index:
    rank: 0
  suite: raptor
  chunks:
    total: 1
    current: 1
  parent: f8jCP1KrSwKLNBdCfvLRVg
  treeherder:
    tier: 2
    symbol: gmaps
    jobKind: test
    machine:
      platform: android-hw-a51-11-0-aarch64-shippable-qr
    groupName: Browsertime tests on Firefox without fission enabled
    collection:
      opt: true
    groupSymbol: Btime-nofis
  test-setting:
    _hash: 60fe8a61eec7
    build:
      type: opt
      shippable: true
    runtime:
      geckoview-no-fission: true
    platform:
      os:
        name: android
        version: '11.0'
      arch: aarch64
      device: a51
  treeherder-platform: android-hw-a51-11-0-aarch64-shippable-qr/opt

https://firefox-ci-tc.services.mozilla.com/tasks/N7XTxYS6QMWGPfE8RnufjQ/runs/0

Scheduled: 2023-10-09T18:23:25.515Z
Started: 2023-10-09T19:27:53.034Z
Resolved: 2023-10-09T19:47:53.348Z

No artifacts on the task.

[bhearsum]

An example on mac hardware as well: https://firefox-ci-tc.services.mozilla.com/tasks/Tc1jvjw8TxyEEyIm-EiKTg/runs/0

[bhearsum]

Also an example from a scriptworker: https://firefox-ci-tc.services.mozilla.com/tasks/e2hdjT8bR6-fnAkzjmNkNg/runs/0

[lotas]

We were able to trace in logs, both on the worker side, and services side that the issue is that somewhere between the services and the worker.

There are plenty of 502 coming from load balancer, which clearly explains why queue service sent a response, but it never reached client (worker)

[lotas]

Checking backend_connection_closed_before_data_sent_to_client

GCP docs say:

The backend unexpectedly closed its connection to the load balancer before the response was proxied to the client. This can happen if the load balancer is sending traffic to another entity. The other entity might be a third-party load balancer that has a TCP timeout that is shorter than the external Application Load Balancer's 10-minute (600-second) timeout. The third-party load balancer might be running on a VM instance. Manually setting the TCP timeout (keepalive) on the target service to greater than 600 seconds might resolve the issue.

[lotas]

Chain of calls looks like this:

1. client
2. GLB
3. k8s-ingress
4. iprepd-nginx (k8s service)
5. k8s service
6. pod (application)

and by looking at the logs at both ends we get: lots of 502 in 1. client, everything is 200 on the 6.pod application logs
which leads to assumption that 4. iprepd-nginx is a likely place of failure here

[lotas]

so load balancer keeps connection up to 10min

nodejs seems to have a default of 5min: https://github.com/nodejs/node/blob/v18.16.0/lib/_http_server.js#L447

and iprepd-nginx seems to have 2min

[lotas]

We still haven't figured out what was the root cause for that increase.
Since then we have "fixed" the services side and made sure that there are no unwanted 502s disrupting operations, and it was quite stable in past weeks.
However, claim expires are still happening, and investigation should be continued on the workers side and the tasks themselves.

We already established last year that some of the factors might be:

• tasks dying with OOM errors, and worker has no chance to report back the status
• worker and worker-runner interaction, where worker-runner might request machine shutdown during successful claimWork call

[lotas]

Here's the actual stand:

@bhearsum should we close this one? We got rid of 502s on the services side and the ones on the worker side are being partially covered in other tickets (like #6318)

[bhearsum]

I'm happy to close this now, yeah. Thank you for all your work here!

[lotas]

Thanks! Let's close it then