Bug #21276: lib/controller/handler_test.go TestDiscoveryDocCache is racey - Arvados

Actions

Copy link

Bug #21276

closed

lib/controller/handler_test.go TestDiscoveryDocCache is racey

Added by Brett Smith 12 months ago. Updated 7 months ago.

Status:

Resolved

Priority:

Normal

Assigned To:

Tom Clegg

Category:

Tests

Target version:

Development 2024-01-03 sprint

Story points:

Release:

Arvados 3.0

Release relationship:

Auto

Description

time="2023-12-07T19:12:30Z" level=warning msg="error refreshing cache" error="HTTP status 400" path=/discovery/v1/apis/arvados/v1/rest

----------------------------------------------------------------------
FAIL: handler_test.go:100: HandlerSuite.TestDiscoveryDocCache

handler_test.go:257:
    // Only one attempt to re-fetch (holdReqs ensured the first
    // update took long enough for the last incoming request to
    // arrive)
    c.Check(countRailsReqs(), check.Equals, reqsBefore+1)
... obtained int = 10
... expected int = 11

Files

developer-run-tests-remainder-4162.log (924 KB) developer-run-tests-remainder-4162.log

Brett Smith, 12/08/2023 02:38 PM

Subtasks 1 (0 open — 1 closed)

Related issues

Actions

Copy link

Updated by Tom Clegg 11 months ago

Assigned To set to Tom Clegg
Status changed from New to In Progress

I repeated the test 100+ times without reproducing this error, then eventually got a similar failure a few lines down:

START: handler_test.go:100: HandlerSuite.TestDiscoveryDocCache
START: handler_test.go:49: HandlerSuite.SetUpTest
PASS: handler_test.go:49: HandlerSuite.SetUpTest        0.002s

{"level":"debug","msg":"interval is 0s, not running worker","time":"2023-12-18T16:35:12.145031309-05:00","worker":"trash sweep"}
{"level":"debug","msg":"interval is 0s, not running worker","time":"2023-12-18T16:35:12.145037610-05:00","worker":"container log sweep"}
WARN[0001] error refreshing cache                        error="HTTP status 400" path=/discovery/v1/apis/arvados/v1/rest
WARN[0001] error refreshing cache                        error="HTTP status 400" path=/discovery/v1/apis/arvados/v1/rest
handler_test.go:286:
    c.Check(countRailsReqs(), check.Equals, reqsBefore+5)
... obtained int = 18
... expected int = 17

START: handler_test.go:66: HandlerSuite.TearDownTest
PASS: handler_test.go:66: HandlerSuite.TearDownTest     0.000s

FAIL: handler_test.go:100: HandlerSuite.TestDiscoveryDocCache

Actions

Copy link

Updated by Tom Clegg 11 months ago

Target version changed from Future to Development 2024-01-03 sprint

21276-test-race @ 7737cf94d7f912f469a1ae7e808dbd2fb1eb6c8a -- developer-run-tests: #3976

Fixes two race bugs that caused the "number of requests" counter to occasionally miss some requests:

RequestDumps = append(RequestDumps, r) in arvadostest.Proxy needed to be protected with a mutex
Test case needed to wait for that append() statement to run in all of the outstanding reqs before counting RequestDumps

Actions

Copy link