TheRacetrack / racetrack

An opinionated framework for deploying, managing, and serving application workloads
https://theracetrack.github.io/racetrack/
Apache License 2.0
28 stars 5 forks source link

Race condition in Async job call #449

Closed iszulcdeepsense closed 2 months ago

iszulcdeepsense commented 2 months ago
t=2024-04-15T10:51:47+0000 lvl=eror msg="Async Job Call request error" requestId=7e590a18-69b6-4896-a851-9c7659d958a4 taskId=845c728d-cb69-4394-8b78-e7566cc71819 jobName=windows12 jobVersion=0.0.1 host=windows12-v-0-0-1 path=/pub/job/windows12/0.0.1/api/v1/perform error="connection broken to a target job (job may have died): Post \"http://windows12-v-0-0-1/pub/job/windows12/0.0.1/api/v1/perform\": EOF"
t=2024-04-15T10:51:47+0000 lvl=info msg="Request: Poll async task" requestId=e2efe653-31dc-4a32-bcd0-28ce8ab64517 taskId=845c728d-cb69-4394-8b78-e7566cc71819 path=/pub/async/task/845c728d-cb69-4394-8b78-e7566cc71819/poll method=GET
t=2024-04-15T10:51:47+0000 lvl=info msg="Async job call crashed, retrying..." requestId=7e590a18-69b6-4896-a851-9c7659d958a4 taskId=845c728d-cb69-4394-8b78-e7566cc71819
t=2024-04-15T10:51:47+0000 lvl=info msg="Retrying async job call" requestId=7e590a18-69b6-4896-a851-9c7659d958a4 taskId=845c728d-cb69-4394-8b78-e7566cc71819 errorMessage="connection broken to a target job (job may have died): Post \"http://windows12-v-0-0-1/pub/job/windows12/0.0.1/api/v1/perform\": EOF" jobName=windows12 jobVersion=0.0.1 jobPath=/api/v1/perform attempts=2 replicaAddr=127.0.0.1:37469
Response 500 for http://127.0.0.1:37469/pub/async/task/845c728d-cb69-4394-8b78-e7566cc71819/poll: {"attempts":1,"duration":"99.374µs","ended_at":"2024-04-15T10:51:47.08618076Z","error":"connection broken to a target job (job may have died): Post \"http://windows12-v-0-0-1/pub/job/windows12/0.0.1/api/v1/perform\": EOF","http_method":"POST","job_name":"windows12","job_path":"/api/v1/perform","job_version":"0.0.1","started_at":"2024-04-15T10:51:47.086081385Z","status":"failed","task_id":"845c728d-cb69-4394-8b78-e7566cc71819"}
t=2024-04-15T10:51:47+0000 lvl=info msg="Async Job Call task has ended successfully" requestId=7e590a18-69b6-4896-a851-9c7659d958a4 taskId=845c728d-cb69-4394-8b78-e7566cc71819 duration=320.[214](https://github.com/TheRacetrack/racetrack/actions/runs/8687829022/job/23822149203#step:6:215)µs jobName=windows12 jobVersion=0.0.1 jobPath=/pub/job/windows12/0.0.1/api/v1/perform statusCode=200
Server 127.0.0.1:37469 closed
--- FAIL: TestRetryCrashedJobCall (0.00s)
    async_test.go:92: 
            Error Trace:    /home/runner/work/racetrack/racetrack/pub/async_test.go:92
            Error:          Not equal: 
                            expected: 500
                            actual  : 200
            Test:           TestRetryCrashedJobCall
            Messages:       job result should return status 200
    async_test.go:93: 
            Error Trace:    /home/runner/work/racetrack/racetrack/pub/async_test.go:93
            Error:          Not equal: 
                            expected: <nil>(<nil>)
                            actual  : int(42)
            Test:           TestRetryCrashedJobCall
            Messages:       result data should be included in the job response
t=2024-04-15T10:51:47+0000 lvl=dbug msg="Config values" config="{LogLevel:debug ListenPort:7205 ForwardToProtocol:http GitVersion: LifecycleUrl:http://127.0.0.1:7202/lifecycle AuthRequired:true AuthDebug:false LifecycleToken: RequestTracingHeader:X-Request-Tracing-Id CallerNameHeader:X-Caller-Name OpenTelemetryEndpoint: RemoteGatewayMode:false RemoteGatewayToken: ServiceName:pub StructuredLogging:false ReplicaDiscoveryHostname: AsyncMaxAttempts:2 AsyncTaskRetryInterval:10}"
t=2024-04-15T10:51:47+0000 lvl=info msg="Request: new Async Job Call" requestId=d0aa7653-3b7c-40a1-a0c1-0a777a0e1fd7 method=POST path=/pub/async/new/job/adder/latest/api/v1/perform
t=2024-04-15T10:51:47+0000 lvl=info msg="Async Job Call task created" requestId=d0aa7653-3b7c-40a1-a0c1-0a777a0e1fd7 taskId=0e590243-f462-41e8-8704-42230a89c600 jobVersion=0.0.1 jobPath=/api/v1/perform caller=bob jobName=adder
Server 127.0.0.1:41317 closed
t=2024-04-15T10:51:47+0000 lvl=info msg="Request: Poll async task" taskId=0e590243-f462-41e8-8704-42230a89c600 requestId=4dd91d88-94cd-4943-8bd9-d9c69e21ca74 path=/pub/async/task/0e590243-f462-41e8-8704-42230a89c600/poll method=GET
t=2024-04-15T10:51:47+0000 lvl=info msg="Task is gone in a supposed Pub replica, retrying" taskId=0e590243-f462-41e8-8704-42230a89c600 requestId=4dd91d88-94cd-4943-8bd9-d9c69e21ca74 pubInstance=127.0.0.1:41317
t=2024-04-15T10:51:47+0000 lvl=info msg="Retrying async job call" taskId=0e590243-f462-41e8-8704-42230a89c600 requestId=4dd91d88-94cd-4943-8bd9-d9c69e21ca74 jobName=adder jobVersion=0.0.1 jobPath=/api/v1/perform attempts=2 replicaAddr=127.0.0.1:41317 errorMessage=
t=2024-04-15T10:51:47+0000 lvl=info msg="Async Job Call task has ended successfully" requestId=d0aa7653-3b7c-40a1-a0c1-0a777a0e1fd7 taskId=0e590243-f462-41e8-8704-42230a89c600 statusCode=200 duration=1.[220](https://github.com/TheRacetrack/racetrack/actions/runs/8687829022/job/23822149203#step:6:221)224ms jobName=adder jobVersion=0.0.1 jobPath=/pub/job/adder/0.0.1/api/v1/perform
t=2024-04-15T10:51:47+0000 lvl=info msg="Async Job Call task has ended successfully" taskId=0e590243-f462-41e8-8704-4[223](https://github.com/TheRacetrack/racetrack/actions/runs/8687829022/job/23822149203#step:6:224)0a89c600 requestId=4dd91d88-94cd-4943-8bd9-d9c69e21ca74 jobName=adder jobVersion=0.0.1 jobPath=/pub/job/adder/0.0.1/api/v1/perform statusCode=200 duration=88.386832ms
Server 127.0.0.1:41317 closed
[GIN] 2024/04/15 - 10:51:47 | 200 |      25.377µs |                 | GET      "/pub/job/name-123/latest/api/v1/perform"
[GIN] 2024/04/15 - 10:51:47 | 200 |       5.039µs |                 | GET      "/pub/job/name-123/0.0.1/"
[GIN] 2024/04/15 - 10:51:47 | 200 |       4.328µs |                 | GET      "/pub/job/name-123/0.0.2"
FAIL
FAIL    github.com/TheRacetrack/racetrack/pub   0.019s
FAIL

https://github.com/TheRacetrack/racetrack/actions/runs/8687829022/job/23822149203