Nightly statechannels build is failing (8th Feb).

[geoknee]

The e2e-test job failed twice in a row, suggesting this is a genuine issue and not a flicker.

Originally posted by @geoknee in #31 (comment)

[andrewgordstewart]

The CI passed on c5103c4, and first failed on 5134ffd.

The commits in statechannels behind the latest releases are statechannels/statechannels@25cda975d and statechannels/statechannels@a0dfe8615, respectively. For easy comparison, here's their diff: statechannels/statechannels@25cda97...a0dfe86.

[andrewgordstewart]

Note: The e2e tests pass locally for me.

In fact, if you look at the e2e test artifacts, you'll see:

1. Things generally seem to work (test logs)

If you compare these logs to working logs, you see that the tests run through their natural course. They just time out after 60 seconds, I think.

2. The servers are still running

203 ----------
Current Memory: 1782 mB
Max Memory:     2441 mB
USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
root      1357  0.1  0.0 895108 56956 pts/2    Rsl+ 23:19   0:00 node /opt/yarn-v1.22.4/bin/yarn.js test:e2e
root        78  0.0  0.0  17980  2992 pts/1    Ss+  23:19   0:00 bash bin/log_memory.sh e2e-stats
root      2400  0.0  0.0  36636  2840 pts/1    R+   23:22   0:00  \_ ps afu
70           7  0.0  0.0 190084 20172 pts/0    Ss+  23:19   0:00 postgres
root         1  0.0  0.0   1084     4 pts/0    Ss   23:19   0:00 /sbin/docker-init -- /bin/sh
root         6  0.0  0.0   4280   756 pts/0    S+   23:19   0:00 /bin/sh
root      2118  0.0  0.0   4284   708 pts/2    S+   23:22   0:00 /bin/sh -c yarn ts-node /root/project/packages/e2e-testing/src/payment-server.ts listen --useLedger true --logFile /tmp/e2e-test-with-ledger-without-chain.log --fundingStrategy Fake --amountOfWorkerThreads 0 --numAllocations 2
root      2119  0.5  0.0 893864 56396 pts/2    Sl+  23:22   0:00  \_ /usr/local/bin/node /opt/yarn-v1.22.4/bin/yarn.js ts-node /root/project/packages/e2e-testing/src/payment-server.ts listen --useLedger true --logFile /tmp/e2e-test-with-ledger-without-chain.log --fundingStrategy Fake --amountOfWorkerThreads 0 --numAllocations 2
root      2142  0.0  0.0   4284   740 pts/2    S+   23:22   0:00      \_ /bin/sh -c /root/project/node_modules/.bin/ts-node /root/project/packages/e2e-testing/src/payment-server.ts listen --useLedger true --logFile /tmp/e2e-test-with-ledger-without-chain.log --fundingStrategy Fake --amountOfWorkerThreads 0 --numAllocations 2
root      2143 26.3  0.5 25318688 378636 pts/2 Sl+  23:22   0:13          \_ /usr/local/bin/node /root/project/node_modules/.bin/ts-node /root/project/packages/e2e-testing/src/payment-server.ts listen --useLedger true --logFile /tmp/e2e-test-with-ledger-without-chain.log --fundingStrategy Fake --amountOfWorkerThreads 0 --numAllocations 2
root      2126  0.0  0.0   4284   716 pts/2    S+   23:22   0:00 /bin/sh -c yarn ts-node /root/project/packages/e2e-testing/src/receipt-server.ts listen --useLedger true --logFile /tmp/e2e-test-with-ledger-without-chain.log --fundingStrategy Fake --amountOfWorkerThreads 0 --numAllocations 2
root      2127  0.5  0.0 894104 56516 pts/2    Sl+  23:22   0:00  \_ /usr/local/bin/node /opt/yarn-v1.22.4/bin/yarn.js ts-node /root/project/packages/e2e-testing/src/receipt-server.ts listen --useLedger true --logFile /tmp/e2e-test-with-ledger-without-chain.log --fundingStrategy Fake --amountOfWorkerThreads 0 --numAllocations 2
root      2150  0.0  0.0   4284   720 pts/2    S+   23:22   0:00      \_ /bin/sh -c /root/project/node_modules/.bin/ts-node /root/project/packages/e2e-testing/src/receipt-server.ts listen --useLedger true --logFile /tmp/e2e-test-with-ledger-without-chain.log --fundingStrategy Fake --amountOfWorkerThreads 0 --numAllocations 2
root      2151 25.1  0.5 25311692 374080 pts/2 Sl+  23:22   0:13          \_ /usr/local/bin/node /root/project/node_modules/.bin/ts-node /root/project/packages/e2e-testing/src/receipt-server.ts listen --useLedger true --logFile /tmp/e2e-test-with-ledger-without-chain.log --fundingStrategy Fake --amountOfWorkerThreads 0 --numAllocations 2

See the e2e-stats artifact.

Just before the CI step finished, you can see that eg. the payment server is running with PID 2143:

root      2143 26.3  0.5 25318688 378636 pts/2 Sl+  23:22   0:13          \_ /usr/local/bin/node /root/project/node_modules/.bin/ts-node /root/project/packages/e2e-testing/src/payment-server.ts listen --useLedger true --logFile /tmp/e2e-test-with-ledger-without-chain.log --fundingStrategy Fake --amountOfWorkerThreads 0 --numAllocations 2

This is a child of PID 2118, which the circle logs complain is still running:

child process handle { pid: 2118, cmd: undefined, args: undefined }

What's interesting is, it complained about PID 1798 being open, which was successfully killed, between seconds 149 and 150.

Previous to that, it complained about PID 1444 being open, which was successfully killed between seconds 90 & 91.

Notice that 150 - 90 = 60, which is the jest timeout. This is consistent with:

Hypothesis

The afterEach promise does not resolve until

1. the jest test times out after 60 seconds
2. the beforeEach callback somehow coaxes the previous servers to die

Why do I believe this hypothesis?

Note that I killed the e2e test after 3 minutes.

I had to do this because without it, the jest test would not exit*.

* Normally, a jest test times out after 10 minutes with out output. But, I am logging open handles every 5 seconds, so there was output every 5 seconds. Circle eventually gave up after 5 hours. I wonder how much this cost...

[andrewgordstewart]

Resolved: 06c31f0