Skip to content

Investigate flaky test-http-server-request-timeouts-mixed #43465

Closed as not planned
#45722
Closed as not planned
Investigate flaky test-http-server-request-timeouts-mixed#43465
#45722
Labels
flaky-testIssues and PRs involving tests that fail intermittently in CI.staleIssues and PRs marked stale due to inactivity and scheduled for automatic closure.

Description

@F3n67u
F3n67u
opened on Jun 18, 2022

Test

test-http-server-request-timeouts-mixed

Platform

macos

Console output

not ok 1173 parallel/test-http-server-request-timeouts-mixed
  ---
  duration_ms: 3.244
  severity: fail
  exitcode: 1
  stack: |-
    node:assert:399
        throw err;
        ^
    
    AssertionError [ERR_ASSERTION]: The expression evaluated to a falsy value:
    
      assert(request2.completed)
    
        at Timeout._onTimeout (/Users/iojs/build/workspace/node-test-commit-osx/nodes/osx11-x64/test/parallel/test-http-server-request-timeouts-mixed.js:106:5)
        at listOnTimeout (node:internal/timers:564:17)
        at process.processTimers (node:internal/timers:507:7) {
      generatedMessage: true,
      code: 'ERR_ASSERTION',
      actual: false,
      expected: true,
      operator: '=='
    }
    
    Node.js v19.0.0-pre
  ...

Build links

Failed PR

10 (nodejs/node#43329, nodejs/node#43380, nodejs/node#43366, nodejs/node#43455, nodejs/node#43190, nodejs/node#43176, nodejs/node#43374, nodejs/node#43363, nodejs/node#43417, nodejs/node#43216)

Appeared

test-orka-macos11-x64-1, test-nearform-macos10.15-x64-3, test-orka-macos10.15-x64-2, test-nearform-macos10.15-x64-1, test-orka-macos11-x64-2

First CI

https://ci.nodejs.org/job/node-test-pull-request/44587/

Last CI

https://ci.nodejs.org/job/node-test-pull-request/44664/

Example

https://ci.nodejs.org/job/node-test-commit-osx/nodes=osx11-x64/45608/console

Additional information

Build links info is from CI Reliability 2022-06-18

This test was introduced on 2022-05-03: #42893

This test starts flaky from 2022-05-04: nodejs/reliability#271

Query all flaky dates: https://github.com/nodejs/reliability/issues?q=is%3Aissue+is%3Aopen+test-http-server-request-timeouts-mixed

cc @ShogunPanda(Test author) @lpinca(Reviewer, I saw you mention the flaky possibility in pr comment)

Activity

  1. F3n67u
    added
    flaky-testIssues and PRs involving tests that fail intermittently in CI.
    on Jun 18, 2022

  2. lpinca commented on Jun 18, 2022

    @lpinca
    lpinca
    on Jun 18, 2022
    Member

    It seems this only occurs on macOS but I am not able to reproduce locally on macOS 12.4.

  3. mcollina commented on Jun 18, 2022

    @mcollina
    mcollina
    on Jun 18, 2022
    SponsorMember

    @ShogunPanda could d you take a look?

  4. ShogunPanda commented on Jun 18, 2022

    @ShogunPanda
    ShogunPanda
    on Jun 18, 2022
    Contributor

    Yup, I will take a look on Monday!

  5. F3n67u commented on Jun 18, 2022

    @F3n67u
    F3n67u
    on Jun 18, 2022
    ContributorAuthor

    It seems this only occurs on macOS but I am not able to reproduce locally on macOS 12.4.

    Yes, I also tried to reproduce on my local MacOS 12.4 but never reproduced.

  6. ShogunPanda
    added a commit that references this issue on Jun 28, 2022

    test: mark test-http-server-request-timeouts-mixed flaky on macOS

    bc5f9e1
  7. targos
    added a commit that references this issue on Jul 12, 2022

    test: mark test-http-server-request-timeouts-mixed flaky on macOS

    7c6f548
  8. targos
    added a commit that references this issue on Jul 31, 2022

    test: mark test-http-server-request-timeouts-mixed flaky on macOS

    a3a2a9e

  9. nicksia-vgw commented on Aug 5, 2022

    @nicksia-vgw
    nicksia-vgw
    on Aug 5, 2022
    Contributor

    I was able to repro on Mac 12.4:

    === release test-http-server-request-timeouts-mixed ===                       
Path: parallel/test-http-server-request-timeouts-mixed
node:assert:400
    throw err;
    ^

AssertionError [ERR_ASSERTION]: The expression evaluated to a falsy value:

  assert(request2.completed)

    at Timeout._onTimeout (/Users/nicksia/Documents/git/node/test/parallel/test-http-server-request-timeouts-mixed.js:107:5)
    at listOnTimeout (node:internal/timers:564:17)
    at process.processTimers (node:internal/timers:507:7) {
  generatedMessage: true,
  code: 'ERR_ASSERTION',
  actual: false,
  expected: true,
  operator: '=='
}

    Let me know if there's anything I can do to help, even if it's just being a lab rat :)

  10. ShogunPanda commented on Aug 5, 2022

    @ShogunPanda
    ShogunPanda
    on Aug 5, 2022
    Contributor

    Thanks sir! Do you mind sharing which machine (hardware I mean) were you running on and all the relevant environment information (like if you were on battery or if your machine was overloaded and so forth)

  11. nicksia-vgw commented on Aug 5, 2022

    @nicksia-vgw
    nicksia-vgw
    on Aug 5, 2022
    Contributor

    Sure thing - here's a screenshot of my system details:
    image

    My machine was plugged into the wall.

    Test was running in CLion's integrated terminal.

    I'd say "low-medium" utilisation, had Postgres running in a Docker image and a IDE/Browser open (about 20% CPU usage and 20GB memory used).

    Update: Fails even with request2 isolated.

  12. nicksia-vgw commented on Aug 5, 2022

    @nicksia-vgw
    nicksia-vgw
    on Aug 5, 2022
    Contributor

    Here's some awfully crude dumps (sorry!), printing out the value of request2.completed every 100ms with setInterval.

    Failed Run:

    @[101ms] request2.completed: undefined
@[201ms] request2.completed: undefined
@[303ms] request2.completed: undefined
request2 client created.
request2.client.write()
@[413ms] request2.completed: false
<snip>
@[2840ms] request2.completed: false
node:assert:400
    throw err;
    ^

AssertionError [ERR_ASSERTION]: The expression evaluated to a falsy value:

  assert(request2.completed)

    at Timeout._onTimeout (/Users/nicksia/Documents/git/node/test/parallel/test-http-server-request-timeouts-mixed.js:81:5)
    at listOnTimeout (node:internal/timers:564:17)
    at process.processTimers (node:internal/timers:507:7) {
  generatedMessage: true,
  code: 'ERR_ASSERTION',
  actual: false,
  expected: true,
  operator: '=='
}

Node.js v19.0.0-pre

    Passing Run

    @[102ms] request2.completed: undefined
@[203ms] request2.completed: undefined
@[304ms] request2.completed: undefined
request2 client created.
request2.client.write()
@[412ms] request2.completed: false
<snip>
@[2439ms] request2.completed: false
@[2540ms] request2.completed: true
<snip>
@[6481ms] request2.completed: true
Closing server.

    My passing runs are close to 2500ms after client is created, when the headersTimeout * 1.2 + connectionsCheckingInterval on my platform is 2900ms.

    Could it be that the check is just too early on slow/burdened systems?

    Update: I'm getting a bunch of runs around the 3000ms mark when I remove assert(request2.completed):

    @[3039ms] request2.completed: true

  13. nicksia-vgw commented on Aug 8, 2022

    @nicksia-vgw
    nicksia-vgw
    on Aug 8, 2022
    Contributor

    The times don't quite match up, which is causing this issue.

    headersTimeout: 2000ms
    requestTimeout: 4000ms
    connectionsCheckingInterval: 500ms

    Request 2 is started at headersTimeout * 0.2, or 400ms.
    Headers time out 2000ms after that.
    Completion of Request 2 is checked at at headersTimeout * 1.2 + connectionsCheckingInterval, or 2900ms.

    Timeline
    @[400ms]: Request 2 client created and first write sent.
    @[2400ms]: Headers are timed out.
    @[2900ms]: Request 2 completion is checked (which is intended to depend on Request 2 expiring via headersTimeout, as seen in the comment - assert(request2.response.startsWith(responseTimeout)); // It is expired due to headersTimeout.

    The problem is that the connectionsCheckingInterval is slightly too high. The connection checking interval could tick just after 2400ms, and then just after 2900ms.

    Example

    @[2424ms] request2.completed: false
checking connection timeout
@[2525ms] request2.completed: false
@[2625ms] request2.completed: false
@[2727ms] request2.completed: false
@[2828ms] request2.completed: false
node:assert:400
    throw err;
    ^

AssertionError [ERR_ASSERTION]: The expression evaluated to a falsy value:

  assert(request2.completed)

    at Timeout._onTimeout (/Users/nicksia/Documents/git/node/test/parallel/test-http-server-request-timeouts-mixed.js:108:5)
    at listOnTimeout (node:internal/timers:564:17)
    at process.processTimers (node:internal/timers:507:7) {
  generatedMessage: true,
  code: 'ERR_ASSERTION',
  actual: false,
  expected: true,
  operator: '=='
}

    The fix is to ensure connection checking interval is less than 500ms, and to decouple the check timeout from connection checking interval.

    I'll put up a fix for this shortly.

  14. 29 remaining items

  15. nodejs-github-bot
    added a commit that references this issue on Jan 9, 2025

    test: mark test-http-server-request-timeouts-mixed as flaky

    b8f6d84
  16. targos
    added a commit that references this issue on Jan 13, 2025

    test: mark test-http-server-request-timeouts-mixed as flaky

    2675c1d
  17. aduh95
    added a commit that references this issue on Jan 30, 2025

    test: mark test-http-server-request-timeouts-mixed as flaky

    cbbcaf9
  18. marco-ippolito
    added a commit that references this issue on Jan 30, 2025

    test: mark test-http-server-request-timeouts-mixed as flaky

    39d608f
  19. aduh95
    added 2 commits that reference this issue on Jan 31, 2025

    test: mark test-http-server-request-timeouts-mixed as flaky

    5942d86

    test: mark test-http-server-request-timeouts-mixed as flaky

    4844fa2
  20. mcollina
    added a commit that references this issue on Mar 13, 2025

    test: mark test-http-server-request-timeouts-mixed as flaky

    6e2e829

  21. github-actions commented on Jun 25, 2026

    @github-actions
    github-actionsbot
    on Jun 25, 2026 – with GitHub Actions
    Contributor

    This issue has been marked as stale due to 210 days of inactivity.
    It will be automatically closed in 30 days if no further activity occurs. If this is still relevant, please leave a comment or update it to keep it open.

  22. github-actions
    added
    staleIssues and PRs marked stale due to inactivity and scheduled for automatic closure.
    on Jun 25, 2026

  23. github-actions commented on Jul 26, 2026

    @github-actions
    github-actionsbot
    on Jul 26, 2026 – with GitHub Actions
    Contributor

    This issue has been automatically closed after 30 days of inactivity following its stale status (no activity for a total of 120 days).
    If this is still relevant, feel free to reopen it or leave a comment with additional details so we can continue the discussion.

  24. github-actions
    closed this as not plannedon Jul 26, 2026
  25. nodejs-github-bot
    added a commit that references this issue on Sep 30, 2026

    test: deflake http server mixed request timeouts

    76a5db6
  26. aduh95
    added 2 commits that reference this issue on Oct 3, 2026

    test: deflake http server mixed request timeouts

    873954c

    test: deflake http server mixed request timeouts

    a5ee59c
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

No one assigned

    Labels

    flaky-testIssues and PRs involving tests that fail intermittently in CI.staleIssues and PRs marked stale due to inactivity and scheduled for automatic closure.

    Type

    No type

    Projects

    No projects

      Milestone

      No milestone

      Relationships

      None yet

      Development

      No branches or pull requests

      Issue actions