timeout'd waiting for outcomes

[dmaretskyi]

I'm trying to get a test to run using the js sdk and a generic docker builder. It seems like the test result isn't getting reported back to the daemon.

testground version
Testground
Git commit: 58ab9a21

@testground/sdk 0.1.3

const { invokeMap } = require('@testground/sdk')

invokeMap({
  quickstart: async (env) => {
    env.recordMessage('Hello World!')
  }
})

FROM node:12.16.1-alpine3.11

WORKDIR /usr/src/app

COPY plan/package.json ./
RUN npm install

COPY plan/main.js /usr/src/app/

CMD ["node", "main.js"]

Logs

testground run single --plan=signal \
                        --testcase=quickstart \
                        --runner=local:docker \
                        --builder=docker:generic \
                        --instances=1 \
                        --wait

May 12 11:53:14.771298  INFO    created a synthetic composition file for this job; all instances will run under singleton group "single"
May 12 11:53:14.771356  INFO    using home directory: /Users/dmaretskyi/testground
May 12 11:53:14.771622  INFO    .env.toml loaded from: /Users/dmaretskyi/testground/.env.toml
May 12 11:53:14.771631  INFO    testground client initialized   {"addr": "http://localhost:8042"}

>>> Result:

May 12 11:53:15.153357  INFO    run is queued with ID: chf2havrirfoe1kn8gcg

>>> Server output:

May 12 11:53:15.177220  INFO    performing build for groups     {"plan": "signal", "groups": ["single"], "builder": "docker:generic"}
Step 1/6 : FROM node:12.16.1-alpine3.11
 ---> be7c0ffeb20b
Step 2/6 : WORKDIR /usr/src/app
 ---> Using cache
 ---> 99aaa987d7d0
Step 3/6 : COPY plan/package.json ./
 ---> Using cache
 ---> 4391e8eb776b
Step 4/6 : RUN npm install
 ---> Using cache
 ---> 0abcb7675ea3
Step 5/6 : COPY plan/main.js /usr/src/app/
 ---> Using cache
 ---> 8e378e9ca26d
Step 6/6 : CMD ["node", "main.js"]
 ---> Using cache
 ---> 23e829eb63d3
 ---> 23e829eb63d3
[Warning] One or more build-args [PLAN_PATH] were not consumed
Successfully built 23e829eb63d3
Successfully tagged d04c24bddfc5:latest
May 12 11:53:15.505628  INFO    build completed {"default_tag": "d04c24bddfc5:latest", "took": "0s"}
May 12 11:53:15.542288  INFO    got docker image id     {"image_id": "23e829eb63d3"}
May 12 11:53:15.542346  INFO    tagging image   {"image_id": "23e829eb63d3", "tag": "signal:23e829eb63d3"}
May 12 11:53:15.549457  INFO    build succeeded {"plan": "signal", "groups": ["single"], "builder": "docker:generic", "artifact": "23e829eb63d3"}
May 12 11:53:15.549633  INFO    performing healthcheck on runner
May 12 11:53:15.643594  INFO    healthcheck: ok
May 12 11:53:15.643692  INFO    starting run    {"run_id": "chf2havrirfoe1kn8gcg", "plan": "signal", "case": "quickstart", "runner": "local:docker", "instances": 1}
May 12 11:53:15.696543  INFO    creating container      {"runner": "local:docker", "run_id": "chf2havrirfoe1kn8gcg", "name": "tg-signal-quickstart-chf2havrirfoe1kn8gcg-single-0"}
May 12 11:53:15.791658  INFO    starting containers     {"runner": "local:docker", "run_id": "chf2havrirfoe1kn8gcg", "count": 1}
May 12 11:53:15.791732  INFO    starting container      {"runner": "local:docker", "run_id": "chf2havrirfoe1kn8gcg", "id": "d26f3d080414d6031a424402e013a87afec652b7a00243dd0880b5fff9a917cc", "group": "single", "group_index": 0}
May 12 11:53:16.423779  INFO    Containers started, waiting for containers and outcome signals  {"runner": "local:docker", "run_id": "chf2havrirfoe1kn8gcg"}
May 12 11:53:16.423825  INFO    waiting for container   {"runner": "local:docker", "run_id": "chf2havrirfoe1kn8gcg", "id": "d26f3d080414d6031a424402e013a87afec652b7a00243dd0880b5fff9a917cc", "group": "single", "group_index": 0}
May 12 11:53:16.423786  INFO    attaching container     {"runner": "local:docker", "run_id": "chf2havrirfoe1kn8gcg", "id": "d26f3d080414d6031a424402e013a87afec652b7a00243dd0880b5fff9a917cc", "group": "single", "group_index": 0}
May 12 11:53:16.445060  INFO    0.6533s      OTHER << sidecar      >> May 12 11:53:16.441917    INFO    additional hosts        {"hosts": ""}
May 12 11:53:16.447239  INFO    0.6555s      OTHER << sidecar      >> May 12 11:53:16.445772    INFO    resolved route to host  {"host": "testground-redis", "ip": "192.18.0.3"}
May 12 11:53:16.447456  INFO    0.6557s      OTHER << sidecar      >> May 12 11:53:16.446894    INFO    resolved route to host  {"host": "testground-sync-service", "ip": "192.18.0.4"}
May 12 11:53:16.450035  INFO    0.6583s      OTHER << sidecar      >> May 12 11:53:16.448622    INFO    resolved route to host  {"host": "testground-influxdb", "ip": "192.18.0.5"}
May 12 11:53:16.460900  INFO    0.6691s      OTHER << sidecar      >> May 12 11:53:16.460801    INFO    successfully resolved route to host     {"container_id": "d26f3d080414d6031a424402e013a87afec652b7a00243dd0880b5fff9a917cc"}
May 12 11:53:16.468876  INFO    0.6771s      OTHER << sidecar      >> May 12 11:53:16.463493    INFO    external routing disabled
May 12 11:53:16.468992  INFO    0.6772s      OTHER << sidecar      >> May 12 11:53:16.463629    INFO    waiting for all networks to be ready    {"sidecar": true, "run_id": "chf2havrirfoe1kn8gcg"}
May 12 11:53:16.478862  INFO    0.6871s      OTHER << sidecar      >> May 12 11:53:16.477870    INFO    all networks ready      {"sidecar": true, "run_id": "chf2havrirfoe1kn8gcg"}
May 12 11:53:16.589601  INFO    0.7973s      START << single[000] (d26f3d) >> {"plan":"signal","case":"quickstart","run":"chf2havrirfoe1kn8gcg","outputs_path":"/outputs","instances":1,"group":"single","group_instances":1,"network":"16.2.0.0/16","start_time":"0001-01-01T00:00:00Z"}
May 12 11:53:16.591007  INFO    0.7993s    MESSAGE << single[000] (d26f3d) >> Hello World!
May 12 11:53:16.591206  INFO    0.7993s         OK << single[000] (d26f3d) >> 
May 12 11:53:16.591808  INFO    0.8003s    MESSAGE << single[000] (d26f3d) >> registerTestcaseResult: true
May 12 11:53:16.812204  INFO    container exited        {"runner": "local:docker", "run_id": "chf2havrirfoe1kn8gcg", "id": "d26f3d080414d6031a424402e013a87afec652b7a00243dd0880b5fff9a917cc", "group": "single", "group_index": 0, "status": 0}
May 12 11:53:16.812265  INFO    all containers are complete     {"runner": "local:docker", "run_id": "chf2havrirfoe1kn8gcg"}
May 12 11:54:01.814626  INFO    we timeout'd waiting for outcomes       {"runner": "local:docker", "run_id": "chf2havrirfoe1kn8gcg"}
May 12 11:54:01.816801  INFO    deleting containers     {"runner": "local:docker", "run_id": "chf2havrirfoe1kn8gcg", "ids": ["d26f3d080414d6031a424402e013a87afec652b7a00243dd0880b5fff9a917cc"]}
May 12 11:54:01.817162  INFO    deleting container      {"runner": "local:docker", "run_id": "chf2havrirfoe1kn8gcg", "id": "d26f3d080414d6031a424402e013a87afec652b7a00243dd0880b5fff9a917cc"}
May 12 11:54:01.817454  INFO    46.0251s INCOMPLETE << sidecar      >> 
May 12 11:54:02.016064  INFO    run completed   {"runner": "local:docker", "run_id": "chf2havrirfoe1kn8gcg", "err": null}
May 12 11:54:02.016461  INFO    run finished with outcome = failure (single:0/1)        {"run_id": "chf2havrirfoe1kn8gcg", "plan": "signal", "case": "quickstart", "runner": "local:docker", "instances": 1}

>>> Result:

May 12 11:54:05.719262  INFO    finished run with ID: chf2havrirfoe1kn8gcg
May 12 11:54:05.720510  INFO    result default[chf2havrirfoe1kn8gcg]: failure
run "default" failed