roachtest: ssh_problem failed

[cockroach-teamcity]

roachtest.ssh_problem failed with artifacts on master @ 1b1c8da55be48c174b7b370b305f42622546209f:

test schemachange/random-load failed due to test artifacts and logs in: /artifacts/schemachange/random-load/run_1
(test_impl.go:291).Fatal: output in run_125153.622625054_n1_workload_run_schemachange: ./workload run schemachange --verbose=1 --tolerate-errors=false  --histograms=perf/stats.json --max-ops 5000 --concurrency 20 --txn-log /mnt/data1/cockroach/transactions.json returned: SSH_PROBLEM: exit status 255

Parameters: ROACHTEST_cloud=gce , ROACHTEST_cpu=4 , ROACHTEST_encrypted=false , ROACHTEST_fs=ext4 , ROACHTEST_localSSD=true , ROACHTEST_ssd=0

Help

See: roachtest README

See: How To Investigate (internal)

/cc @cockroachdb/test-eng

This test on roachdash | Improve this report!

Jira issue: CRDB-20896

[cockroach-teamcity]

roachtest.ssh_problem failed with artifacts on master @ 0c1c3e7777b28a30ebe41428fb173f0156e8968c:

test schemachange/random-load failed due to test artifacts and logs in: /artifacts/schemachange/random-load/run_1
(test_impl.go:291).Fatal: output in run_133500.318499865_n1_workload_run_schemachange: ./workload run schemachange --verbose=1 --tolerate-errors=false  --histograms=perf/stats.json --max-ops 5000 --concurrency 20 --txn-log /mnt/data1/cockroach/transactions.json returned: SSH_PROBLEM: exit status 255

Parameters: ROACHTEST_cloud=gce , ROACHTEST_cpu=4 , ROACHTEST_encrypted=false , ROACHTEST_fs=ext4 , ROACHTEST_localSSD=true , ROACHTEST_ssd=0

Help

See: roachtest README

See: How To Investigate (internal)

This test on roachdash | Improve this report!

[cockroach-teamcity]

roachtest.ssh_problem failed with artifacts on master @ 2d926e68000df659f282d4e4477329867b9a3323:

test schemachange/random-load failed due to test artifacts and logs in: /artifacts/schemachange/random-load/run_1
(test_impl.go:291).Fatal: output in run_140012.557459920_n1_workload_run_schemachange: ./workload run schemachange --verbose=1 --tolerate-errors=false  --histograms=perf/stats.json --max-ops 5000 --concurrency 20 --txn-log /mnt/data1/cockroach/transactions.json returned: SSH_PROBLEM: exit status 255
(test_impl.go:314).Errorf: test timed out (0s)

Parameters: ROACHTEST_cloud=gce , ROACHTEST_cpu=4 , ROACHTEST_encrypted=false , ROACHTEST_fs=ext4 , ROACHTEST_localSSD=true , ROACHTEST_ssd=0

Help

See: roachtest README

See: How To Investigate (internal)

This test on roachdash | Improve this report!

[renatolabs]

Some notes about the failure above:

Error classifiction

The failure was classified as an SSH flake but, in reality, the test timed out. You can see it in the message above, as well as by checking the test logs: the workload ran for 10 hours.

To consider (cc @smg260):

• Improve the test timed out message to properly report time spent in the test. This could be done by reusing the default timeout [1] or (even better) displaying the actual duration (for example, by exposing duration [2]).
• Improving SSH-flake detection. It seems that when the test runner intentionally stops processes started by roachprod, there's a chance we'll get a 255 error. There's probably a better way to deal with this. One quick and dirty, short term solution would be to not mark a failure an SSH-flake if one of the errors indicates that the test timed out.

[1] https://github.com/cockroachdb/cockroach/blob/master/pkg/cmd/roachtest/test_runner.go#L877
[2] https://github.com/cockroachdb/cockroach/blob/master/pkg/cmd/roachtest/test_impl.go#L373-L375

---

Actual test failure (workload timeout)

The workload ran for 10h and never finished. We're passing --max-ops 5000, so it technically should terminate when we reach that number of operations (+ the number of concurrent workers which in this case is 20).

The logs generated by the workload are fairly large (280MB). If we grep for a field in the JSON printed when a worker performs its random number of ops, I think we are able to get a count of the actual number of schema change ops the workload ran:

% rg expectedExecErrors run_140012.557459920_n1_workload_run_schemachange.log | wc -l
    5643

This looks suspicious to me. This number shouldn't be > 5019 (5000 maxOps + enough ops for the remaining 19 workers to realize they should stop after maxOps is reached).

@fqazi Thoughts? Anything to be done here?

[fqazi]

Let me dig into this, it looks like we are some how kept generating ops, which is super weird.

[fqazi]

@renatolabs It looks like we ran into an infinite loop inside randParentColumnForFkRelation. I'll get a patch out for it shortly

[smg260]

Thanks @renatolabs .

Improve the test timed out message to properly report time spent in the test. This could be done by reusing the default timeout [1] or (even better) displaying the actual duration (for example, by exposing duration [2]).

test.log shows the correct actual timeout of 10h (this is the default, and incidentally quite high)

23:59:09 test_runner.go:936: test timed out after 10h0m0s; check __stacks.log and CRDB logs for goroutine dumps

The 0s you see is reported at the time we finally call t.Errorf and it uses the timeout in the TestSpec, which defaults to 0. This should probably use the actual timeout as in the above print.

Improving SSH-flake detection. It seems that when the test runner intentionally stops processes started by roachprod, there's a chance we'll get a 255 error. There's probably a better way to deal with this. One quick and dirty, short term solution would be to not mark a failure an SSH-flake if one of the errors indicates that the test timed out.

Agreed. However this is a symptom of us delaying the call to t.Errorf on timeout until teardown as completed [1], [2]. When the nodes are stopped, the long running ssh command will fail, resulting in a 255 exit code, and the subsequent reporting of that error - but since we delayed reporting the real cause (timeout), this error becomes the primary and gets reported as such. We could certainly look at prioritising the time out error.

[1] - https://github.com/cockroachdb/cockroach/blob/master/pkg/cmd/roachtest/test_runner.go#L933
[2] - https://github.com/cockroachdb/cockroach/blob/master/pkg/cmd/roachtest/test_runner.go#L1051

[fqazi]

There is a secondary bug here inside cockroache's DROP SCHEMA implementation too, which makes this worse. I'll band-aid the infinite loop first since a faster failure is better here.