Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

sql/logictest: TestLogic failed #60824

Closed
cockroach-teamcity opened this issue Feb 20, 2021 · 71 comments · Fixed by #69024
Closed

sql/logictest: TestLogic failed #60824

cockroach-teamcity opened this issue Feb 20, 2021 · 71 comments · Fixed by #69024
Assignees
@jordanlewis
Labels
branch-master Failures and bugs on the master branch. C-test-failure Broken test (automatically or manually discovered). O-robot Originated from a bot.

Comments

@cockroach-teamcity
Copy link
Member

(sql/logictest).TestLogic failed on master@557346d5fc755db5f64d3e198e47be1f53a4d390:

=== RUN   TestLogic
    test_log_scope.go:73: test logs captured to: /go/src/github.com/cockroachdb/cockroach/artifacts/logTestLogic977178260
    test_log_scope.go:74: use -show-logs to present logs inline
=== CONT  TestLogic
    logic.go:3343: -- test log scope end --
test logs left over in: /go/src/github.com/cockroachdb/cockroach/artifacts/logTestLogic977178260
--- FAIL: TestLogic (958.82s)
=== RUN   TestLogic/5node-metadata/distsql_numtables
=== PAUSE TestLogic/5node-metadata/distsql_numtables
=== CONT  TestLogic/5node-metadata/distsql_numtables
=== CONT  TestLogic/5node-metadata/distsql_numtables
    logic.go:2559: 
        
        testdata/logic_test/distsql_numtables:21: 
        expected success, but found
        (XXUUU) cannot up-replicate to s2; missing gossiped StoreDescriptor
--- done: testdata/logic_test/distsql_numtables with config 5node-metadata: 4 tests, 1 failures
E210220 00:01:04.366080 12116468 sql/logictest/logic.go:3575  [-] 1008  pq: cannot up-replicate to s2; missing gossiped StoreDescriptor
    logic.go:3118: 
        testdata/logic_test/distsql_numtables:21: error while processing
    logic.go:3118: pq: cannot up-replicate to s2; missing gossiped StoreDescriptor
--- done: testdata/logic_test/merge_join_dist with config 5node-metadata: 12 tests, 0 failures
        --- FAIL: TestLogic/5node-metadata/distsql_numtables (1.66s)
=== RUN   TestLogic/5node-metadata
    --- FAIL: TestLogic/5node-metadata (0.00s)
More

Parameters:

  • GOFLAGS=-json
make stressrace TESTS=TestLogic PKG=./pkg/sql/logictest TESTTIMEOUT=5m STRESSFLAGS='-timeout 5m' 2>&1

Related:

See this test on roachdash
powered by pkg/cmd/internal/issues
@cockroach-teamcity cockroach-teamcity added branch-master Failures and bugs on the master branch. C-test-failure Broken test (automatically or manually discovered). O-robot Originated from a bot. labels Feb 20, 2021
@cockroach-teamcity
Copy link
Member Author

(sql/logictest).TestLogic failed on master@ab07ae1da6fe154eebc6c6847cca58b30184e14f:

=== RUN   TestLogic
    test_log_scope.go:73: test logs captured to: /go/src/github.com/cockroachdb/cockroach/artifacts/logTestLogic233649622
    test_log_scope.go:74: use -show-logs to present logs inline
=== CONT  TestLogic
    logic.go:3343: -- test log scope end --
test logs left over in: /go/src/github.com/cockroachdb/cockroach/artifacts/logTestLogic233649622
--- FAIL: TestLogic (740.75s)
=== RUN   TestLogic/5node-metadata/distsql_subquery
=== PAUSE TestLogic/5node-metadata/distsql_subquery
=== CONT  TestLogic/5node-metadata/distsql_subquery
=== CONT  TestLogic/5node-metadata/distsql_subquery
    logic.go:2559: 
        
        testdata/logic_test/distsql_subquery:18: 
        expected success, but found
        (XXUUU) while carrying out changes [{ADD_VOTER n2,s2}]: failed to connect to n2 at 127.0.0.1:43885: initial connection heartbeat failed: rpc error: code = Unavailable desc = connection error: desc = "transport: authentication handshake failed: context deadline exceeded"
        nodedialer.go:169: in dial()
--- done: testdata/logic_test/distsql_subquery with config 5node-metadata: 4 tests, 1 failures
E210222 19:54:48.567346 10789584 sql/logictest/logic.go:3575  [-] 1058  pq: while carrying out changes [{ADD_VOTER n2,s2}]: failed to connect to n2 at 127.0.0.1:43885: initial connection heartbeat failed: rpc error: code = Unavailable desc = connection error: desc = "transport: authentication handshake failed: context deadline exceeded"
    logic.go:3118: 
        testdata/logic_test/distsql_subquery:18: error while processing
    logic.go:3118: pq: while carrying out changes [{ADD_VOTER n2,s2}]: failed to connect to n2 at 127.0.0.1:43885: initial connection heartbeat failed: rpc error: code = Unavailable desc = connection error: desc = "transport: authentication handshake failed: context deadline exceeded"
        --- FAIL: TestLogic/5node-metadata/distsql_subquery (1.70s)
=== RUN   TestLogic/5node-metadata
    --- FAIL: TestLogic/5node-metadata (0.00s)
More

Parameters:

  • GOFLAGS=-json
make stressrace TESTS=TestLogic PKG=./pkg/sql/logictest TESTTIMEOUT=5m STRESSFLAGS='-timeout 5m' 2>&1

Related:

See this test on roachdash
powered by pkg/cmd/internal/issues

@yuzefovich
Copy link
Member

yuzefovich commented Feb 22, 2021 •
edited
Loading

The first report seems possibly related to #59340.

@cockroach-teamcity
Copy link
Member Author

(sql/logictest).TestLogic failed on master@bc98209ed36ec47675fe3d7a7d8201b4b77f89ba:

=== RUN   TestLogic
    test_log_scope.go:73: test logs captured to: /go/src/github.com/cockroachdb/cockroach/artifacts/logTestLogic516258408
    test_log_scope.go:74: use -show-logs to present logs inline
=== CONT  TestLogic
    logic.go:3343: -- test log scope end --
test logs left over in: /go/src/github.com/cockroachdb/cockroach/artifacts/logTestLogic516258408
--- FAIL: TestLogic (1031.64s)
=== RUN   TestLogic/fakedist-spec-planning/errors
=== PAUSE TestLogic/fakedist-spec-planning/errors
=== CONT  TestLogic/fakedist-spec-planning/errors
E210222 20:27:49.956148 10856322 jobs/adopt.go:117  [-] 7525  could not run claimed job 635552627370852353: job 635552627370852353: status changed to succeeded which is not resumable`
E210222 20:27:49.986725 10857012 jobs/adopt.go:117  [-] 7526  could not run claimed job 635552627323830273: job 635552627323830273: status changed to succeeded which is not resumable`
E210222 20:27:50.008918 10857561 jobs/adopt.go:117  [-] 7527  could not run claimed job 635552627463684097: job 635552627463684097: status changed to succeeded which is not resumable`
--- progress: testdata/logic_test/show_create_all_tables: 9 statements/queries
E210222 20:27:50.032915 10858483 jobs/adopt.go:117  [-] 7528  could not run claimed job 635552627347259393: job 635552627347259393: status changed to succeeded which is not resumable`
E210222 20:27:50.034966 10858482 jobs/adopt.go:117  [-] 7529  could not run claimed job 635552627423838209: job 635552627423838209: status changed to succeeded which is not resumable`
=== CONT  TestLogic/fakedist-spec-planning/errors
    logic.go:3122: 
        testdata/logic_test/errors:19: error while processing
    logic.go:3122: test was successful but validation upon completion failed: failed to test for descriptor JSON round-trip: pq: failed to connect to n3 at 127.0.0.1:34735: initial connection heartbeat failed: rpc error: code = Unavailable desc = connection error: desc = "transport: authentication handshake failed: context deadline exceeded"
--- done: testdata/logic_test/system with config fakedist-spec-planning: 65 tests, 0 failures
        --- FAIL: TestLogic/fakedist-spec-planning/errors (1.85s)
=== RUN   TestLogic/fakedist-spec-planning
    --- FAIL: TestLogic/fakedist-spec-planning (0.72s)
More

Parameters:

  • GOFLAGS=-json
make stressrace TESTS=TestLogic PKG=./pkg/sql/logictest TESTTIMEOUT=5m STRESSFLAGS='-timeout 5m' 2>&1

Related:

See this test on roachdash
powered by pkg/cmd/internal/issues

@cockroach-teamcity
Copy link
Member Author

(sql/logictest).TestLogic failed on master@5cd07e02c291d017bedd2a237956a62eb63dbcc9:

=== RUN   TestLogic
    test_log_scope.go:73: test logs captured to: /go/src/github.com/cockroachdb/cockroach/artifacts/logTestLogic237413412
    test_log_scope.go:74: use -show-logs to present logs inline
=== CONT  TestLogic
    logic.go:3351: -- test log scope end --
test logs left over in: /go/src/github.com/cockroachdb/cockroach/artifacts/logTestLogic237413412
--- FAIL: TestLogic (1294.75s)
=== RUN   TestLogic/fakedist-spec-planning/show_indexes
=== PAUSE TestLogic/fakedist-spec-planning/show_indexes
=== CONT  TestLogic/fakedist-spec-planning/show_indexes
E210225 01:17:46.717279 11401034 jobs/adopt.go:117  [-] 7559  could not run claimed job 636175865142411265: job 636175865142411265: status changed to succeeded which is not resumable`
E210225 01:17:46.734043 11401736 jobs/adopt.go:117  [-] 7560  could not run claimed job 636175865086050305: job 636175865086050305: status changed to succeeded which is not resumable`
E210225 01:17:46.739681 11402071 jobs/adopt.go:117  [-] 7561  could not run claimed job 636175865136676865: job 636175865136676865: status changed to succeeded which is not resumable`
E210225 01:17:46.756434 11402182 kv/kvclient/kvcoord/txn_interceptor_committer.go:449  [-] 7562  making txn commit explicit failed for "unnamed" meta={id=39096c6e pri=0.05947514 epo=0 ts=1614215866.731093780,0 min=1614215866.731093780,0 seq=2} lock=true stat=STAGING rts=1614215866.731093780,0 wto=false gul=1614215867.231093780,0 int=1 ifw=1: result is ambiguous (server shutdown)
=== CONT  TestLogic/fakedist-spec-planning/show_indexes
    testcluster.go:1439: failed to create a status client because of initial connection heartbeat failed: rpc error: code = Unavailable desc = connection error: desc = "transport: authentication handshake failed: context deadline exceeded"
        --- FAIL: TestLogic/fakedist-spec-planning/show_indexes (1.54s)
=== RUN   TestLogic/fakedist-spec-planning
    --- FAIL: TestLogic/fakedist-spec-planning (0.66s)
More

Parameters:

  • GOFLAGS=-json
make stressrace TESTS=TestLogic PKG=./pkg/sql/logictest TESTTIMEOUT=5m STRESSFLAGS='-timeout 5m' 2>&1

Related:

See this test on roachdash
powered by pkg/cmd/internal/issues

@RaduBerinde
Copy link
Member

Same failure like the one just above: https://teamcity.cockroachdb.com//viewLog.html?buildId=2716122&buildTypeId=Cockroach_MergeToMaster

@cockroach-teamcity
Copy link
Member Author

(sql/logictest).TestLogic failed on master@ac25d9f3511435c4e6962f71eb169fd6d7d0ef28:

=== RUN   TestLogic
    test_log_scope.go:73: test logs captured to: /go/src/github.com/cockroachdb/cockroach/artifacts/logTestLogic596100037
    test_log_scope.go:74: use -show-logs to present logs inline
=== CONT  TestLogic
    logic.go:3351: -- test log scope end --
test logs left over in: /go/src/github.com/cockroachdb/cockroach/artifacts/logTestLogic596100037
--- FAIL: TestLogic (752.70s)
=== RUN   TestLogic/5node/distsql_distinct_on
=== PAUSE TestLogic/5node/distsql_distinct_on
=== CONT  TestLogic/5node/distsql_distinct_on
=== CONT  TestLogic/5node/distsql_distinct_on
    logic.go:2567: 
        
        testdata/logic_test/distsql_distinct_on:40: 
        expected success, but found
        (XXUUU) while carrying out changes [{ADD_VOTER n2,s2}]: failed to connect to n2 at 127.0.0.1:44201: initial connection heartbeat failed: rpc error: code = Unavailable desc = connection error: desc = "transport: authentication handshake failed: context deadline exceeded"
        nodedialer.go:169: in dial()
--- done: testdata/logic_test/distsql_distinct_on with config 5node: 5 tests, 1 failures
E210226 02:36:17.364026 10710610 sql/logictest/logic.go:3583  [-] 7053  pq: while carrying out changes [{ADD_VOTER n2,s2}]: failed to connect to n2 at 127.0.0.1:44201: initial connection heartbeat failed: rpc error: code = Unavailable desc = connection error: desc = "transport: authentication handshake failed: context deadline exceeded"
    logic.go:3126: 
        testdata/logic_test/distsql_distinct_on:40: error while processing
    logic.go:3126: pq: while carrying out changes [{ADD_VOTER n2,s2}]: failed to connect to n2 at 127.0.0.1:44201: initial connection heartbeat failed: rpc error: code = Unavailable desc = connection error: desc = "transport: authentication handshake failed: context deadline exceeded"
        --- FAIL: TestLogic/5node/distsql_distinct_on (2.08s)
=== RUN   TestLogic/5node
    --- FAIL: TestLogic/5node (0.00s)
More

Parameters:

  • GOFLAGS=-json
make stressrace TESTS=TestLogic PKG=./pkg/sql/logictest TESTTIMEOUT=5m STRESSFLAGS='-timeout 5m' 2>&1

Related:

See this test on roachdash
powered by pkg/cmd/internal/issues

@cockroach-teamcity
Copy link
Member Author

(sql/logictest).TestLogic failed on master@dcc8ab04251aa954f086cd2b347cd1d1b976a312:

=== RUN   TestLogic
    test_log_scope.go:73: test logs captured to: /go/src/github.com/cockroachdb/cockroach/artifacts/logTestLogic228119198
    test_log_scope.go:74: use -show-logs to present logs inline
=== CONT  TestLogic
    logic.go:3351: -- test log scope end --
test logs left over in: /go/src/github.com/cockroachdb/cockroach/artifacts/logTestLogic228119198
--- FAIL: TestLogic (971.83s)
=== RUN   TestLogic/fakedist-spec-planning/txn_stats
=== PAUSE TestLogic/fakedist-spec-planning/txn_stats
=== CONT  TestLogic/fakedist-spec-planning/txn_stats
=== CONT  TestLogic/fakedist-spec-planning/txn_stats
    logic.go:3130: 
        testdata/logic_test/txn_stats:44: error while processing
    logic.go:3130: test was successful but validation upon completion failed: failed to test for descriptor JSON round-trip: pq: failed to connect to n2 at 127.0.0.1:33081: initial connection heartbeat failed: rpc error: code = Unavailable desc = connection error: desc = "transport: authentication handshake failed: context deadline exceeded"
        --- FAIL: TestLogic/fakedist-spec-planning/txn_stats (1.39s)
=== RUN   TestLogic/fakedist-spec-planning
    --- FAIL: TestLogic/fakedist-spec-planning (0.58s)
More

Parameters:

  • GOFLAGS=-json
make stressrace TESTS=TestLogic PKG=./pkg/sql/logictest TESTTIMEOUT=5m STRESSFLAGS='-timeout 5m' 2>&1

Related:

See this test on roachdash
powered by pkg/cmd/internal/issues

@cockroach-teamcity
Copy link
Member Author

(sql/logictest).TestLogic failed on master@6521a8e138c9838853f9502303faf99da69aad2d:

=== RUN   TestLogic
    test_log_scope.go:73: test logs captured to: /go/src/github.com/cockroachdb/cockroach/artifacts/logTestLogic409701549
    test_log_scope.go:74: use -show-logs to present logs inline
=== CONT  TestLogic
    logic.go:3351: -- test log scope end --
test logs left over in: /go/src/github.com/cockroachdb/cockroach/artifacts/logTestLogic409701549
--- FAIL: TestLogic (998.67s)
=== RUN   TestLogic/fakedist-spec-planning
    --- FAIL: TestLogic/fakedist-spec-planning (0.56s)
=== RUN   TestLogic/fakedist-spec-planning/alter_sequence
=== PAUSE TestLogic/fakedist-spec-planning/alter_sequence
=== CONT  TestLogic/fakedist-spec-planning/alter_sequence
--- done: testdata/logic_test/save_table with config fakedist-spec-planning: 21 tests, 0 failures
=== CONT  TestLogic/fakedist-spec-planning/alter_sequence
    testcluster.go:1439: failed to create a status client because of initial connection heartbeat failed: rpc error: code = Unavailable desc = connection error: desc = "transport: authentication handshake failed: context deadline exceeded"
        --- FAIL: TestLogic/fakedist-spec-planning/alter_sequence (1.43s)
More

Parameters:

  • GOFLAGS=-json
make stressrace TESTS=TestLogic PKG=./pkg/sql/logictest TESTTIMEOUT=5m STRESSFLAGS='-timeout 5m' 2>&1

Related:

See this test on roachdash
powered by pkg/cmd/internal/issues

@cockroach-teamcity
Copy link
Member Author

(sql/logictest).TestLogic failed on master@ae1e417e061cc1b869927959e8830e0e5cde2622:

=== RUN   TestLogic
    test_log_scope.go:73: test logs captured to: /go/src/github.com/cockroachdb/cockroach/artifacts/logTestLogic044184690
    test_log_scope.go:74: use -show-logs to present logs inline
=== CONT  TestLogic
    logic.go:3351: -- test log scope end --
test logs left over in: /go/src/github.com/cockroachdb/cockroach/artifacts/logTestLogic044184690
--- FAIL: TestLogic (988.19s)
=== RUN   TestLogic/fakedist-spec-planning/ordinality
=== PAUSE TestLogic/fakedist-spec-planning/ordinality
=== CONT  TestLogic/fakedist-spec-planning/ordinality
--- done: testdata/logic_test/partial_index with config fakedist-spec-planning: 316 tests, 0 failures
=== CONT  TestLogic/fakedist-spec-planning/ordinality
    logic.go:3130: 
        testdata/logic_test/ordinality:102: error while processing
    logic.go:3130: test was successful but validation upon completion failed: failed to test for descriptor JSON round-trip: pq: failed to connect to n2 at 127.0.0.1:43669: initial connection heartbeat failed: rpc error: code = Unavailable desc = connection error: desc = "transport: authentication handshake failed: context deadline exceeded"
E210302 05:25:10.426834 11625673 sql/stats/automatic_stats.go:302  [-] 1469  failed to refresh stats: node unavailable; try another peer
        --- FAIL: TestLogic/fakedist-spec-planning/ordinality (1.50s)
=== RUN   TestLogic/fakedist-spec-planning
    --- FAIL: TestLogic/fakedist-spec-planning (0.55s)
More

Parameters:

  • GOFLAGS=-json
make stressrace TESTS=TestLogic PKG=./pkg/sql/logictest TESTTIMEOUT=5m STRESSFLAGS='-timeout 5m' 2>&1

Related:

See this test on roachdash
powered by pkg/cmd/internal/issues

@cockroach-teamcity
Copy link
Member Author

(sql/logictest).TestLogic failed on master@f0c2d8a2f762ee33ca044ae86f46d06fc35682db:

=== RUN   TestLogic
    test_log_scope.go:73: test logs captured to: /go/src/github.com/cockroachdb/cockroach/artifacts/logTestLogic976886314
    test_log_scope.go:74: use -show-logs to present logs inline
=== CONT  TestLogic
    logic.go:3351: -- test log scope end --
test logs left over in: /go/src/github.com/cockroachdb/cockroach/artifacts/logTestLogic976886314
--- FAIL: TestLogic (949.79s)
=== RUN   TestLogic/fakedist-vec-off/inverted_join_geospatial
=== PAUSE TestLogic/fakedist-vec-off/inverted_join_geospatial
=== CONT  TestLogic/fakedist-vec-off/inverted_join_geospatial
--- done: testdata/logic_test/jobs with config fakedist-vec-off: 21 tests, 0 failures
--- done: testdata/logic_test/txn_retry with config fakedist-vec-off: 6 tests, 0 failures
--- done: testdata/logic_test/txn_as_of with config fakedist-vec-off: 72 tests, 0 failures
E210305 14:21:54.181701 5921621 jobs/adopt.go:260  [n1] 856  job 638594954554540033: adoption completed with error job 638594954554540033: could not mark as reverting: log-job: failed to send RPC: sending to all replicas failed; last error: node unavailable; try another peer: log-job: failed to send RPC: sending to all replicas failed; last error: node unavailable; try another peer
--- total progress: 75201 statements/queries
=== CONT  TestLogic/fakedist-vec-off/inverted_join_geospatial
    logic.go:2567: 
        
        testdata/logic_test/inverted_join_geospatial:33: SELECT lk, rk FROM ltable JOIN rtable@geom_index ON ST_Intersects(ltable.geom1, rtable.geom) ORDER BY (lk, rk)
        expected success, but found
        (XXUUU) failed to connect to n2 at 127.0.0.1:40659: initial connection heartbeat failed: rpc error: code = Unavailable desc = connection error: desc = "transport: authentication handshake failed: context deadline exceeded"
        nodedialer.go:169: in dial()
E210305 14:21:55.397713 5324437 sql/logictest/logic.go:3558  [-] 858  
E210305 14:21:55.397713 5324437 sql/logictest/logic.go:3558  [-] 858 +pq: failed to connect to n2 at 127.0.0.1:40659: initial connection heartbeat failed: rpc error: code = Unavailable desc = connection error: desc = "transport: authentication handshake failed: context deadline exceeded"
    logic.go:2300: 
         pq: failed to connect to n2 at 127.0.0.1:40659: initial connection heartbeat failed: rpc error: code = Unavailable desc = connection error: desc = "transport: authentication handshake failed: context deadline exceeded"
--- done: testdata/logic_test/inverted_join_geospatial with config fakedist-vec-off: 5 tests, 2 failures
E210305 14:21:55.398118 5324437 sql/logictest/logic.go:3583  [-] 859  testdata/logic_test/inverted_join_geospatial:45: too many errors encountered, skipping the rest of the input
    logic.go:3126: 
        testdata/logic_test/inverted_join_geospatial:45: error while processing
    logic.go:3126: testdata/logic_test/inverted_join_geospatial:45: too many errors encountered, skipping the rest of the input
--- progress: testdata/logic_test/join: 113 statements/queries
        --- FAIL: TestLogic/fakedist-vec-off/inverted_join_geospatial (1.41s)
=== RUN   TestLogic/fakedist-vec-off
    --- FAIL: TestLogic/fakedist-vec-off (0.54s)
More

Parameters:

  • GOFLAGS=-json
make stressrace TESTS=TestLogic PKG=./pkg/sql/logictest TESTTIMEOUT=5m STRESSFLAGS='-timeout 5m' 2>&1

Related:

See this test on roachdash
powered by pkg/cmd/internal/issues

@cockroach-teamcity
Copy link
Member Author

(sql/logictest).TestLogic failed on master@a69e6549a71f5a0e83eb13509001f4d7351050fb:

=== RUN   TestLogic
    test_log_scope.go:73: test logs captured to: /go/src/github.com/cockroachdb/cockroach/artifacts/logTestLogic150275333
    test_log_scope.go:74: use -show-logs to present logs inline
=== CONT  TestLogic
    logic.go:3351: -- test log scope end --
test logs left over in: /go/src/github.com/cockroachdb/cockroach/artifacts/logTestLogic150275333
--- FAIL: TestLogic (1873.11s)
=== RUN   TestLogic/fakedist-metadata/alter_primary_key/create_table_change_pk
=== CONT  TestLogic/fakedist-metadata/alter_primary_key/create_table_change_pk
    logic.go:2567: 
        
        testdata/logic_test/alter_primary_key:1332: 
        expected success, but found
        (42703) column "crdb_internal_id_shard_10" does not exist
        column_resolver.go:206: in NewUndefinedColumnError()
E210307 08:35:42.725685 7777196 sql/logictest/logic.go:3558  [-] 821  
E210307 08:35:42.725685 7777196 sql/logictest/logic.go:3558  [-] 821 +pq: column "crdb_internal_id_shard_10" does not exist
    logic.go:1844: 
         pq: column "crdb_internal_id_shard_10" does not exist
--- done: testdata/logic_test/alter_primary_key with config fakedist-metadata: 227 tests, 2 failures
--- progress: testdata/logic_test/alter_table: 300 statements/queries
--- total progress: 102482 statements/queries
            --- FAIL: TestLogic/fakedist-metadata/alter_primary_key/create_table_change_pk (2.55s)
=== RUN   TestLogic/fakedist-metadata/alter_primary_key
=== PAUSE TestLogic/fakedist-metadata/alter_primary_key
=== CONT  TestLogic/fakedist-metadata/alter_primary_key
--- progress: testdata/logic_test/alter_table: 68 statements/queries
E210307 08:35:34.903290 7753854 jobs/adopt.go:260  [n1] 806  job 639093095472267265: adoption completed with error validation of CHECK "i < 0:::INT8" failed on row: a=1, x=NULL, y=1.3, z=1.4, d=NULL, f=NULL, g=1, h=NULL, i=1
E210307 08:35:35.153586 7754777 jobs/adopt.go:260  [n1] 807  job 639093096392097793: adoption completed with error validation of CHECK "i < g" failed on row: a=1, x=NULL, y=1.3, z=1.4, d=NULL, f=NULL, g=1, h=NULL, i=1
        --- FAIL: TestLogic/fakedist-metadata/alter_primary_key (9.63s)
=== RUN   TestLogic/fakedist-metadata
    --- FAIL: TestLogic/fakedist-metadata (0.59s)
More

Parameters:

  • TAGS=
  • GOFLAGS=-parallel=2
make stressrace TESTS=TestLogic PKG=./pkg/sql/logictest TESTTIMEOUT=5m STRESSFLAGS='-timeout 5m' 2>&1

Related:

See this test on roachdash
powered by pkg/cmd/internal/issues

@jordanlewis
Copy link
Member 

     pq: column "crdb_internal_id_shard_10" does not exist

Hmmm... @ajwerner

@ajwerner
Copy link
Contributor

ajwerner commented Mar 8, 2021

Hmm indeed

@cockroach-teamcity cockroach-teamcity mentioned this issue Mar 8, 2021
Closed
@cockroach-teamcity
Copy link
Member Author

(sql/logictest).TestLogic failed on master@89c379950cb4ca77c5d25e45aac4008b1f1758d9:

=== RUN   TestLogic
    test_log_scope.go:73: test logs captured to: /go/src/github.com/cockroachdb/cockroach/artifacts/logTestLogic914265095
    test_log_scope.go:74: use -show-logs to present logs inline
=== CONT  TestLogic
    logic.go:3351: -- test log scope end --
test logs left over in: /go/src/github.com/cockroachdb/cockroach/artifacts/logTestLogic914265095
--- FAIL: TestLogic (752.85s)
=== RUN   TestLogic/fakedist-spec-planning/alter_primary_key/create_table_change_pk
=== CONT  TestLogic/fakedist-spec-planning/alter_primary_key/create_table_change_pk
    logic.go:2567: 
        
        testdata/logic_test/alter_primary_key:1332: 
        expected success, but found
        (42703) column "crdb_internal_id_shard_10" does not exist
        column_resolver.go:206: in NewUndefinedColumnError()
E210309 05:57:07.925464 10761106 sql/logictest/logic.go:3558  [-] 1191  
E210309 05:57:07.925464 10761106 sql/logictest/logic.go:3558  [-] 1191 +pq: column "crdb_internal_id_shard_10" does not exist
    logic.go:1844: 
         pq: column "crdb_internal_id_shard_10" does not exist
--- done: testdata/logic_test/alter_primary_key with config fakedist-spec-planning: 227 tests, 2 failures
--- done: testdata/logic_test/interleaved with config fakedist-spec-planning: 99 tests, 0 failures
            --- FAIL: TestLogic/fakedist-spec-planning/alter_primary_key/create_table_change_pk (4.71s)
=== RUN   TestLogic/fakedist-spec-planning/alter_primary_key
=== PAUSE TestLogic/fakedist-spec-planning/alter_primary_key
=== CONT  TestLogic/fakedist-spec-planning/alter_primary_key
--- progress: testdata/logic_test/alter_type: 86 statements/queries
        --- FAIL: TestLogic/fakedist-spec-planning/alter_primary_key (18.49s)
=== RUN   TestLogic/fakedist-spec-planning
    --- FAIL: TestLogic/fakedist-spec-planning (0.48s)
More

Parameters:

  • GOFLAGS=-json
make stressrace TESTS=TestLogic PKG=./pkg/sql/logictest TESTTIMEOUT=5m STRESSFLAGS='-timeout 5m' 2>&1

Related:

See this test on roachdash
powered by pkg/cmd/internal/issues

@andreimatei
Copy link
Contributor

seems to keep happening, and also on release-21.1
#61657

@andreimatei andreimatei mentioned this issue Mar 9, 2021
Merged
@cockroach-teamcity
Copy link
Member Author

(sql/logictest).TestLogic failed on master@dd87d114508b8b34230ae7da560ab053dd4f58ce:

=== RUN   TestLogic
    test_log_scope.go:73: test logs captured to: /go/src/github.com/cockroachdb/cockroach/artifacts/logTestLogic927282679
    test_log_scope.go:74: use -show-logs to present logs inline
=== CONT  TestLogic
    logic.go:3341: -- test log scope end --
test logs left over in: /go/src/github.com/cockroachdb/cockroach/artifacts/logTestLogic927282679
--- FAIL: TestLogic (754.47s)
=== RUN   TestLogic/5node/distsql_datetime
=== PAUSE TestLogic/5node/distsql_datetime
=== CONT  TestLogic/5node/distsql_datetime
=== CONT  TestLogic/5node/distsql_datetime
    logic.go:2557: 
        
        testdata/logic_test/distsql_datetime:3: 
        expected success, but found
        (XXUUU) while carrying out changes [{ADD_VOTER n3,s3}]: failed to connect to n3 at 127.0.0.1:44901: initial connection heartbeat failed: rpc error: code = Unavailable desc = connection error: desc = "transport: authentication handshake failed: context deadline exceeded"
        nodedialer.go:169: in dial()
--- done: testdata/logic_test/distsql_datetime with config 5node: 0 tests, 1 failures
E210309 21:22:34.947860 11118492 sql/logictest/logic.go:3573  [-] 1209  pq: while carrying out changes [{ADD_VOTER n3,s3}]: failed to connect to n3 at 127.0.0.1:44901: initial connection heartbeat failed: rpc error: code = Unavailable desc = connection error: desc = "transport: authentication handshake failed: context deadline exceeded"
    logic.go:3116: 
        testdata/logic_test/distsql_datetime:3: error while processing
    logic.go:3116: pq: while carrying out changes [{ADD_VOTER n3,s3}]: failed to connect to n3 at 127.0.0.1:44901: initial connection heartbeat failed: rpc error: code = Unavailable desc = connection error: desc = "transport: authentication handshake failed: context deadline exceeded"
        --- FAIL: TestLogic/5node/distsql_datetime (2.54s)
=== RUN   TestLogic/5node
    --- FAIL: TestLogic/5node (0.00s)
More

Parameters:

  • GOFLAGS=-json
make stressrace TESTS=TestLogic PKG=./pkg/sql/logictest TESTTIMEOUT=5m STRESSFLAGS='-timeout 5m' 2>&1

Related:

See this test on roachdash
powered by pkg/cmd/internal/issues

@cockroach-teamcity
Copy link
Member Author

(sql/logictest).TestLogic failed on master@3bae381e45397225ff926f3f8f60d52b70fdc661:

=== RUN   TestLogic
    test_log_scope.go:73: test logs captured to: /go/src/github.com/cockroachdb/cockroach/artifacts/logTestLogic961305549
    test_log_scope.go:74: use -show-logs to present logs inline
=== CONT  TestLogic
    logic.go:3341: -- test log scope end --
test logs left over in: /go/src/github.com/cockroachdb/cockroach/artifacts/logTestLogic961305549
--- FAIL: TestLogic (1554.07s)
=== RUN   TestLogic/local-vec-off/alter_primary_key/create_table_change_pk
E210310 09:07:38.128535 1719914 jobs/adopt.go:260  [n1] 190  job 639948744322187265: adoption completed with error could not parse "hello" as type int: strconv.ParseInt: parsing "hello": invalid syntax
E210310 09:07:38.542246 1721757 jobs/adopt.go:260  [n1] 191  job 639948745763160065: adoption completed with error could not parse "a\\01" as type bytes: bytea encoded value ends with incomplete escape sequence
--- progress: testdata/logic_test/alter_column_type: 115 statements/queries
E210310 09:07:38.790098 1722614 jobs/adopt.go:260  [n1] 192  job 639948746472423425: adoption completed with error integer out of range for type int2
--- done: testdata/logic_test/alter_column_type with config local-vec-off: 122 tests, 0 failures
--- total progress: 29593 statements/queries
=== CONT  TestLogic/local-vec-off/alter_primary_key/create_table_change_pk
    logic.go:2557: 
        
        testdata/logic_test/alter_primary_key:1332: 
        expected success, but found
        (42703) column "crdb_internal_id_shard_10" does not exist
        column_resolver.go:206: in NewUndefinedColumnError()
E210310 09:07:40.213479 1719775 sql/logictest/logic.go:3548  [-] 196  
E210310 09:07:40.213479 1719775 sql/logictest/logic.go:3548  [-] 196 +pq: column "crdb_internal_id_shard_10" does not exist
    logic.go:1834: 
         pq: column "crdb_internal_id_shard_10" does not exist
--- done: testdata/logic_test/alter_primary_key with config local-vec-off: 227 tests, 2 failures
            --- FAIL: TestLogic/local-vec-off/alter_primary_key/create_table_change_pk (2.22s)
=== RUN   TestLogic/local-vec-off/alter_primary_key
=== PAUSE TestLogic/local-vec-off/alter_primary_key
=== CONT  TestLogic/local-vec-off/alter_primary_key
        --- FAIL: TestLogic/local-vec-off/alter_primary_key (8.17s)
=== RUN   TestLogic/local-vec-off
    --- FAIL: TestLogic/local-vec-off (0.33s)
More

Parameters:

  • TAGS=
  • GOFLAGS=-parallel=2
make stressrace TESTS=TestLogic PKG=./pkg/sql/logictest TESTTIMEOUT=5m STRESSFLAGS='-timeout 5m' 2>&1

Related:

See this test on roachdash
powered by pkg/cmd/internal/issues

@adityamaru
Copy link
Contributor

@jordanlewis test-infra is seeing this and #61657 flake often on master and 21.1. Just wondering if someone is actively fixing this, or you recommend skipping some of these tests?

@jordanlewis
Copy link
Member

@ajwerner please advise. I think we could skip the create_table_change_pk test for now. I think we need to get to the bottom of this - it feels pretty new.

@ajwerner
Copy link
Contributor

Ack, turning my attention to it now. My best guess is it is #61345 as that's the only real thing that's touched this code that I can think of.

@ajwerner ajwerner mentioned this issue Mar 10, 2021
Closed
ajwerner added a commit to ajwerner/cockroach that referenced this issue Mar 10, 2021
@ajwerner
sql: stop mutating AST in AlterPrimaryKey
3a45eae 
The code in cockroachdb#61345 added a test that, under stress, nicely revealed a bug.
The bug is that we're mutating the AST in place and then, on retries, we hit
an error. The fix is to not mutate the AST.

I wish I had a more comprehensive testing strategy to ensure this didn't
happen. On some level, we could clone the AST when passing it to various DDL
plan node constructors. That's very defensive but also probably fine. Another
thing that would be cool would be to just assert that after planning the AST
did not change.

Touches cockroachdb#60824.

Release note: None
@ajwerner ajwerner mentioned this issue Mar 10, 2021
Merged
@cockroach-teamcity
Copy link
Member Author

sql/logictest.TestLogic failed with artifacts on master @ 4d987b3f0788c98fa358715b336a1c55e254ee50:

=== RUN   TestLogic
    test_log_scope.go:73: test logs captured to: /go/src/github.com/cockroachdb/cockroach/artifacts/logTestLogic879897068
    test_log_scope.go:74: use -show-logs to present logs inline
=== CONT  TestLogic
    logic.go:3312: -- test log scope end --
test logs left over in: /go/src/github.com/cockroachdb/cockroach/artifacts/logTestLogic879897068
--- FAIL: TestLogic (804.70s)
=== RUN   TestLogic/5node/merge_join_dist_vec
=== PAUSE TestLogic/5node/merge_join_dist_vec
=== CONT  TestLogic/5node/merge_join_dist_vec
=== CONT  TestLogic/5node/merge_join_dist_vec
    logic.go:2528: 
        
        testdata/logic_test/merge_join_dist_vec:23: 
        expected success, but found
        (XXUUU) while carrying out changes [{ADD_VOTER n2,s2}]: failed to connect to n2 at 127.0.0.1:39429: initial connection heartbeat failed: rpc error: code = Unavailable desc = timed out waiting for server handshake
        nodedialer.go:169: in dial()
--- done: testdata/logic_test/merge_join_dist_vec with config 5node: 6 tests, 1 failures
E210414 23:31:38.614575 11381253 sql/logictest/logic.go:3544  [-] 1242  pq: while carrying out changes [{ADD_VOTER n2,s2}]: failed to connect to n2 at 127.0.0.1:39429: initial connection heartbeat failed: rpc error: code = Unavailable desc = timed out waiting for server handshake
    logic.go:3087: 
        testdata/logic_test/merge_join_dist_vec:23: error while processing
    logic.go:3087: pq: while carrying out changes [{ADD_VOTER n2,s2}]: failed to connect to n2 at 127.0.0.1:39429: initial connection heartbeat failed: rpc error: code = Unavailable desc = timed out waiting for server handshake
        --- FAIL: TestLogic/5node/merge_join_dist_vec (2.25s)
=== RUN   TestLogic/5node
    --- FAIL: TestLogic/5node (0.00s)
Reproduce

To reproduce, try: 

make stressrace TESTS=TestLogic PKG=./pkg/sql/logictest TESTTIMEOUT=5m STRESSFLAGS='-timeout 5m' 2>&1

Parameters in this failure:

  • GOFLAGS=-json

Same failure on other branches

/cc @jordanlewis

This test on roachdash | Improve this report!

@cockroach-teamcity
Copy link
Member Author

sql/logictest.TestLogic failed with artifacts on master @ 660df848fcd8569392791f35b27ef5e849b35e2c:

=== RUN   TestLogic
    test_log_scope.go:73: test logs captured to: /go/src/github.com/cockroachdb/cockroach/artifacts/logTestLogic182394997
    test_log_scope.go:74: use -show-logs to present logs inline
=== CONT  TestLogic
    logic.go:3312: -- test log scope end --
test logs left over in: /go/src/github.com/cockroachdb/cockroach/artifacts/logTestLogic182394997
--- FAIL: TestLogic (761.93s)
=== RUN   TestLogic/fakedist-spec-planning/aggregate
=== PAUSE TestLogic/fakedist-spec-planning/aggregate
=== CONT  TestLogic/fakedist-spec-planning/aggregate
=== CONT  TestLogic/fakedist-spec-planning/aggregate
    testcluster.go:296: listen tcp 127.0.0.1:0: listen: address already in use
        --- FAIL: TestLogic/fakedist-spec-planning/aggregate (0.24s)
=== RUN   TestLogic/fakedist-spec-planning
    --- FAIL: TestLogic/fakedist-spec-planning (0.48s)
Reproduce

To reproduce, try: 

make stressrace TESTS=TestLogic PKG=./pkg/sql/logictest TESTTIMEOUT=5m STRESSFLAGS='-timeout 5m' 2>&1

Parameters in this failure:

  • GOFLAGS=-json

Same failure on other branches

/cc @jordanlewis

This test on roachdash | Improve this report!

@cockroach-teamcity
Copy link
Member Author

sql/logictest.TestLogic failed with artifacts on master @ bf6da8a40f6956bc88ee4a930ddc931f73dd5ce4:

=== CONT  TestLogic
    logic.go:3312: -- test log scope end --
test logs left over in: /go/src/github.com/cockroachdb/cockroach/artifacts/logTestLogic993746173
--- FAIL: TestLogic (1080.73s)
=== RUN   TestLogic/fakedist-spec-planning/target_names
=== PAUSE TestLogic/fakedist-spec-planning/target_names
=== CONT  TestLogic/fakedist-spec-planning/target_names
=== CONT  TestLogic/fakedist-spec-planning/target_names
    logic.go:2528: 
        
        testdata/logic_test/target_names:39: SELECT (pg_get_keywords()).word FROM t
        expected success, but found
        (XXUUU) failed to connect to n2 at 127.0.0.1:44747: initial connection heartbeat failed: rpc error: code = Unavailable desc = connection error: desc = "transport: authentication handshake failed: context deadline exceeded"
        nodedialer.go:169: in dial()
E210419 22:25:18.149024 11276971 sql/logictest/logic.go:3519  [-] 1169  
E210419 22:25:18.149024 11276971 sql/logictest/logic.go:3519  [-] 1169 +pq: failed to connect to n2 at 127.0.0.1:44747: initial connection heartbeat failed: rpc error: code = Unavailable desc = connection error: desc = "transport: authentication handshake failed: context deadline exceeded"
    logic.go:2261: 
         pq: failed to connect to n2 at 127.0.0.1:44747: initial connection heartbeat failed: rpc error: code = Unavailable desc = connection error: desc = "transport: authentication handshake failed: context deadline exceeded"
--- done: testdata/logic_test/target_names with config fakedist-spec-planning: 6 tests, 2 failures
E210419 22:25:18.149481 11276971 sql/logictest/logic.go:3544  [-] 1170  testdata/logic_test/target_names:44: too many errors encountered, skipping the rest of the input
    logic.go:3087: 
        testdata/logic_test/target_names:44: error while processing
    logic.go:3087: testdata/logic_test/target_names:44: too many errors encountered, skipping the rest of the input
        --- FAIL: TestLogic/fakedist-spec-planning/target_names (1.41s)
=== RUN   TestLogic/fakedist-spec-planning/cascade/OptDriven
=== CONT  TestLogic/fakedist-spec-planning/cascade/OptDriven
    logic.go:2528: 
        
        testdata/logic_test/cascade:15: SELECT * FROM child
        expected success, but found
        (XXUUU) failed to connect to n3 at 127.0.0.1:46129: initial connection heartbeat failed: rpc error: code = Unavailable desc = connection error: desc = "transport: authentication handshake failed: context deadline exceeded"
        nodedialer.go:169: in dial()
E210419 22:25:36.054415 12385639 sql/logictest/logic.go:3519  [-] 1198  
E210419 22:25:36.054415 12385639 sql/logictest/logic.go:3519  [-] 1198 +pq: failed to connect to n3 at 127.0.0.1:46129: initial connection heartbeat failed: rpc error: code = Unavailable desc = connection error: desc = "transport: authentication handshake failed: context deadline exceeded"
    logic.go:2261: 
         pq: failed to connect to n3 at 127.0.0.1:46129: initial connection heartbeat failed: rpc error: code = Unavailable desc = connection error: desc = "transport: authentication handshake failed: context deadline exceeded"
E210419 22:25:36.054706 12385639 sql/logictest/logic.go:3519  [-] 1199  
E210419 22:25:36.054706 12385639 sql/logictest/logic.go:3519  [-] 1199 +testdata/logic_test/cascade:23: too many errors encountered, skipping the rest of the input
    logic.go:1805: 
         testdata/logic_test/cascade:23: too many errors encountered, skipping the rest of the input
--- done: testdata/logic_test/cascade with config fakedist-spec-planning: 2 tests, 3 failures
--- done: testdata/logic_test/window with config fakedist-spec-planning: 397 tests, 0 failures
--- total progress: 131332 statements/queries
            --- FAIL: TestLogic/fakedist-spec-planning/cascade/OptDriven (0.68s)
=== RUN   TestLogic/fakedist-spec-planning/cascade
=== PAUSE TestLogic/fakedist-spec-planning/cascade
=== CONT  TestLogic/fakedist-spec-planning/cascade
        --- FAIL: TestLogic/fakedist-spec-planning/cascade (1.91s)
=== RUN   TestLogic/fakedist-spec-planning
    --- FAIL: TestLogic/fakedist-spec-planning (0.72s)
Reproduce

To reproduce, try: 

make stressrace TESTS=TestLogic PKG=./pkg/sql/logictest TESTTIMEOUT=5m STRESSFLAGS='-timeout 5m' 2>&1

Parameters in this failure:

  • GOFLAGS=-json

Same failure on other branches

/cc @jordanlewis

This test on roachdash | Improve this report!

@cockroach-teamcity
Copy link
Member Author

sql/logictest.TestLogic failed with artifacts on master @ 1c103726de6994b26706244144d3d9f7dd6b1f58:

=== RUN   TestLogic
    test_log_scope.go:73: test logs captured to: /go/src/github.com/cockroachdb/cockroach/artifacts/logTestLogic039425781
    test_log_scope.go:74: use -show-logs to present logs inline
=== CONT  TestLogic
    logic.go:3312: -- test log scope end --
test logs left over in: /go/src/github.com/cockroachdb/cockroach/artifacts/logTestLogic039425781
--- FAIL: TestLogic (987.15s)
=== RUN   TestLogic/fakedist-spec-planning
    --- FAIL: TestLogic/fakedist-spec-planning (0.58s)
=== RUN   TestLogic/fakedist-spec-planning/timestamp/timestamp_precision
=== CONT  TestLogic/fakedist-spec-planning/timestamp/timestamp_precision
    logic.go:2528: 
        
        testdata/logic_test/timestamp:100: SELECT * FROM timestamp_test ORDER BY id ASC
        expected success, but found
        (XXUUU) failed to connect to n3 at 127.0.0.1:40241: initial connection heartbeat failed: rpc error: code = Unavailable desc = connection error: desc = "transport: authentication handshake failed: context deadline exceeded"
        nodedialer.go:169: in dial()
E210419 22:59:32.858674 11450222 sql/logictest/logic.go:3519  [-] 1125  
E210419 22:59:32.858674 11450222 sql/logictest/logic.go:3519  [-] 1125 +pq: failed to connect to n3 at 127.0.0.1:40241: initial connection heartbeat failed: rpc error: code = Unavailable desc = connection error: desc = "transport: authentication handshake failed: context deadline exceeded"
    logic.go:2261: 
         pq: failed to connect to n3 at 127.0.0.1:40241: initial connection heartbeat failed: rpc error: code = Unavailable desc = connection error: desc = "transport: authentication handshake failed: context deadline exceeded"
E210419 22:59:32.859058 11450222 sql/logictest/logic.go:3519  [-] 1126  
E210419 22:59:32.859058 11450222 sql/logictest/logic.go:3519  [-] 1126 +testdata/logic_test/timestamp:111: too many errors encountered, skipping the rest of the input
    logic.go:1805: 
         testdata/logic_test/timestamp:111: too many errors encountered, skipping the rest of the input
--- done: testdata/logic_test/timestamp with config fakedist-spec-planning: 19 tests, 3 failures
            --- FAIL: TestLogic/fakedist-spec-planning/timestamp/timestamp_precision (0.50s)
=== RUN   TestLogic/fakedist-spec-planning/timestamp
=== PAUSE TestLogic/fakedist-spec-planning/timestamp
=== CONT  TestLogic/fakedist-spec-planning/timestamp
        --- FAIL: TestLogic/fakedist-spec-planning/timestamp (1.81s)
Reproduce

To reproduce, try: 

make stressrace TESTS=TestLogic PKG=./pkg/sql/logictest TESTTIMEOUT=5m STRESSFLAGS='-timeout 5m' 2>&1

Parameters in this failure:

  • GOFLAGS=-json

Same failure on other branches

/cc @jordanlewis

This test on roachdash | Improve this report!

@nvanbenschoten nvanbenschoten mentioned this issue Apr 20, 2021
Merged
@cockroach-teamcity
Copy link
Member Author

sql/logictest.TestLogic failed with artifacts on master @ bea4754bdf607ab050a72b7e2a3fe9dca0289d34:

=== RUN   TestLogic
    test_log_scope.go:73: test logs captured to: /go/src/github.com/cockroachdb/cockroach/artifacts/logTestLogic622773250
    test_log_scope.go:74: use -show-logs to present logs inline
=== CONT  TestLogic
    logic.go:3321: -- test log scope end --
test logs left over in: /go/src/github.com/cockroachdb/cockroach/artifacts/logTestLogic622773250
--- FAIL: TestLogic (1030.15s)
=== RUN   TestLogic/fakedist-spec-planning/computed
=== PAUSE TestLogic/fakedist-spec-planning/computed
=== CONT  TestLogic/fakedist-spec-planning/computed
--- done: testdata/logic_test/conditional with config fakedist-spec-planning: 9 tests, 0 failures
=== CONT  TestLogic/fakedist-spec-planning/computed
    logic.go:2537: 
        
        testdata/logic_test/computed:72: SELECT c FROM with_no_column_refs
        expected success, but found
        (XXUUU) failed to connect to n3 at 127.0.0.1:38231: initial connection heartbeat failed: rpc error: code = Unavailable desc = connection error: desc = "transport: authentication handshake failed: context deadline exceeded"
        nodedialer.go:169: in dial()
E210420 12:38:46.870038 11122369 sql/logictest/logic.go:3528  [-] 1172  
E210420 12:38:46.870038 11122369 sql/logictest/logic.go:3528  [-] 1172 +pq: failed to connect to n3 at 127.0.0.1:38231: initial connection heartbeat failed: rpc error: code = Unavailable desc = connection error: desc = "transport: authentication handshake failed: context deadline exceeded"
    logic.go:2270: 
         pq: failed to connect to n3 at 127.0.0.1:38231: initial connection heartbeat failed: rpc error: code = Unavailable desc = connection error: desc = "transport: authentication handshake failed: context deadline exceeded"
--- done: testdata/logic_test/computed with config fakedist-spec-planning: 14 tests, 2 failures
E210420 12:38:46.870229 11122369 sql/logictest/logic.go:3553  [-] 1173  testdata/logic_test/computed:78: too many errors encountered, skipping the rest of the input
    logic.go:3096: 
        testdata/logic_test/computed:78: error while processing
    logic.go:3096: testdata/logic_test/computed:78: too many errors encountered, skipping the rest of the input
E210420 12:38:46.872919 11957392 sql/stats/automatic_stats.go:302  [-] 1174  failed to refresh stats: node unavailable; try another peer
        --- FAIL: TestLogic/fakedist-spec-planning/computed (1.60s)
=== RUN   TestLogic/fakedist-spec-planning
    --- FAIL: TestLogic/fakedist-spec-planning (0.66s)
Reproduce

To reproduce, try: 

make stressrace TESTS=TestLogic PKG=./pkg/sql/logictest TESTTIMEOUT=5m STRESSFLAGS='-timeout 5m' 2>&1

Parameters in this failure:

  • GOFLAGS=-json

Same failure on other branches

/cc @jordanlewis

This test on roachdash | Improve this report!

@cockroach-teamcity
Copy link
Member Author

sql/logictest.TestLogic failed with artifacts on master @ b4766e0bdb491de6020d5d2acaa3d20f9c339176:

=== RUN   TestLogic
    test_log_scope.go:73: test logs captured to: /go/src/github.com/cockroachdb/cockroach/artifacts/logTestLogic692930075
    test_log_scope.go:74: use -show-logs to present logs inline
=== CONT  TestLogic
    logic.go:3350: -- test log scope end --
test logs left over in: /go/src/github.com/cockroachdb/cockroach/artifacts/logTestLogic692930075
--- FAIL: TestLogic (794.20s)
=== RUN   TestLogic/fakedist-vec-off/vectorize_unsupported
=== PAUSE TestLogic/fakedist-vec-off/vectorize_unsupported
=== CONT  TestLogic/fakedist-vec-off/vectorize_unsupported
--- done: testdata/logic_test/where with config fakedist-vec-off: 21 tests, 0 failures
--- done: testdata/logic_test/inverted_index with config fakedist-vec-off: 264 tests, 0 failures
=== CONT  TestLogic/fakedist-vec-off/vectorize_unsupported
    logic.go:2539: 
        
        testdata/logic_test/vectorize_unsupported:28: select (x/1) from t39417
        expected success, but found
        (XXUUU) failed to connect to n2 at 127.0.0.1:35759: initial connection heartbeat failed: rpc error: code = Unavailable desc = connection error: desc = "transport: authentication handshake failed: context deadline exceeded"
        nodedialer.go:169: in dial()
E210422 20:37:40.337643 5095761 sql/logictest/logic.go:3557  [-] 587  
E210422 20:37:40.337643 5095761 sql/logictest/logic.go:3557  [-] 587 +pq: failed to connect to n2 at 127.0.0.1:35759: initial connection heartbeat failed: rpc error: code = Unavailable desc = connection error: desc = "transport: authentication handshake failed: context deadline exceeded"
    logic.go:2272: 
         pq: failed to connect to n2 at 127.0.0.1:35759: initial connection heartbeat failed: rpc error: code = Unavailable desc = connection error: desc = "transport: authentication handshake failed: context deadline exceeded"
--- done: testdata/logic_test/vectorize_unsupported with config fakedist-vec-off: 6 tests, 2 failures
E210422 20:37:40.346935 5095761 sql/logictest/logic.go:3582  [-] 588  testdata/logic_test/vectorize_unsupported:33: too many errors encountered, skipping the rest of the input
    logic.go:3125: 
        testdata/logic_test/vectorize_unsupported:33: error while processing
    logic.go:3125: testdata/logic_test/vectorize_unsupported:33: too many errors encountered, skipping the rest of the input
        --- FAIL: TestLogic/fakedist-vec-off/vectorize_unsupported (1.83s)
=== RUN   TestLogic/fakedist-vec-off
    --- FAIL: TestLogic/fakedist-vec-off (0.60s)
Reproduce

To reproduce, try: 

make stressrace TESTS=TestLogic PKG=./pkg/sql/logictest TESTTIMEOUT=5m STRESSFLAGS='-timeout 5m' 2>&1

Parameters in this failure:

  • GOFLAGS=-json

Same failure on other branches

/cc @jordanlewis

This test on roachdash | Improve this report!

@cockroach-teamcity
Copy link
Member Author

sql/logictest.TestLogic failed with artifacts on master @ 924935cc8ee14ff0c6d23aedd2a12673bf864808:

=== RUN   TestLogic
    test_log_scope.go:73: test logs captured to: /go/src/github.com/cockroachdb/cockroach/artifacts/logTestLogic599276416
    test_log_scope.go:74: use -show-logs to present logs inline
=== CONT  TestLogic
    logic.go:3350: -- test log scope end --
test logs left over in: /go/src/github.com/cockroachdb/cockroach/artifacts/logTestLogic599276416
--- FAIL: TestLogic (816.45s)
=== RUN   TestLogic/fakedist/serial/serial_rowid
=== CONT  TestLogic/fakedist/serial/serial_rowid
    logic.go:2539: 
        
        testdata/logic_test/serial:31: SELECT count(DISTINCT a), count(DISTINCT b), count(DISTINCT c) FROM serial
        expected success, but found
        (XXUUU) failed to connect to n2 at 127.0.0.1:35655: initial connection heartbeat failed: rpc error: code = Unavailable desc = timed out waiting for server handshake
        nodedialer.go:169: in dial()
E210424 06:04:35.253726 4748781 sql/logictest/logic.go:3557  [-] 533  
E210424 06:04:35.253726 4748781 sql/logictest/logic.go:3557  [-] 533 +pq: failed to connect to n2 at 127.0.0.1:35655: initial connection heartbeat failed: rpc error: code = Unavailable desc = timed out waiting for server handshake
    logic.go:2272: 
         pq: failed to connect to n2 at 127.0.0.1:35655: initial connection heartbeat failed: rpc error: code = Unavailable desc = timed out waiting for server handshake
E210424 06:04:35.254062 4748781 sql/logictest/logic.go:3557  [-] 534  
E210424 06:04:35.254062 4748781 sql/logictest/logic.go:3557  [-] 534 +testdata/logic_test/serial:36: too many errors encountered, skipping the rest of the input
    logic.go:1816: 
         testdata/logic_test/serial:36: too many errors encountered, skipping the rest of the input
--- done: testdata/logic_test/serial with config fakedist: 5 tests, 3 failures
            --- FAIL: TestLogic/fakedist/serial/serial_rowid (0.31s)
=== RUN   TestLogic/fakedist/serial
=== PAUSE TestLogic/fakedist/serial
=== CONT  TestLogic/fakedist/serial
        --- FAIL: TestLogic/fakedist/serial (1.64s)
=== RUN   TestLogic/fakedist
    --- FAIL: TestLogic/fakedist (0.58s)
Reproduce

To reproduce, try: 

make stressrace TESTS=TestLogic PKG=./pkg/sql/logictest TESTTIMEOUT=5m STRESSFLAGS='-timeout 5m' 2>&1

Parameters in this failure:

  • GOFLAGS=-json

Same failure on other branches

/cc @jordanlewis

This test on roachdash | Improve this report!

@cockroach-teamcity

This comment has been minimized.

Sign in to view
@yuzefovich yuzefovich mentioned this issue Apr 26, 2021
Closed
@cockroach-teamcity
Copy link
Member Author

sql/logictest.TestLogic failed with artifacts on master @ 588d9d7ad7618784ee23a5e5f440a9d9d36bb0d5:

=== RUN   TestLogic/fakedist-disk/schema_change_in_txn/rollback_mutations
Reproduce

To reproduce, try: 

make stressrace TESTS=TestLogic PKG=./pkg/sql/logictest TESTTIMEOUT=5m STRESSFLAGS='-timeout 5m' 2>&1

Parameters in this failure:

  • GOFLAGS=-json

Same failure on other branches

/cc @jordanlewis

This test on roachdash | Improve this report!

@cockroach-teamcity
Copy link
Member Author

sql/logictest.TestLogic failed with artifacts on master @ 29305bfb08116f38e10ca090347eea170899b919:

=== RUN   TestLogic
    test_log_scope.go:73: test logs captured to: /go/src/github.com/cockroachdb/cockroach/artifacts/logTestLogic555034003
    test_log_scope.go:74: use -show-logs to present logs inline
=== CONT  TestLogic
    logic.go:3351: -- test log scope end --
test logs left over in: /go/src/github.com/cockroachdb/cockroach/artifacts/logTestLogic555034003
--- FAIL: TestLogic (817.89s)
=== RUN   TestLogic/fakedist/zigzag_join
=== PAUSE TestLogic/fakedist/zigzag_join
=== CONT  TestLogic/fakedist/zigzag_join
=== CONT  TestLogic/fakedist/zigzag_join
    logic.go:2540: 
        
        testdata/logic_test/zigzag_join:38: SELECT n,a,b FROM a WHERE a = 4 AND b = 1
        expected success, but found
        (XXUUU) failed to connect to n3 at 127.0.0.1:44899: initial connection heartbeat failed: rpc error: code = Unavailable desc = connection error: desc = "transport: authentication handshake failed: context deadline exceeded"
        nodedialer.go:169: in dial()
E210427 21:45:54.071236 3454388 sql/logictest/logic.go:3558  [-] 479  
E210427 21:45:54.071236 3454388 sql/logictest/logic.go:3558  [-] 479 +pq: failed to connect to n3 at 127.0.0.1:44899: initial connection heartbeat failed: rpc error: code = Unavailable desc = connection error: desc = "transport: authentication handshake failed: context deadline exceeded"
    logic.go:2273: 
         pq: failed to connect to n3 at 127.0.0.1:44899: initial connection heartbeat failed: rpc error: code = Unavailable desc = connection error: desc = "transport: authentication handshake failed: context deadline exceeded"
--- done: testdata/logic_test/zigzag_join with config fakedist: 8 tests, 2 failures
E210427 21:45:54.072134 3454388 sql/logictest/logic.go:3583  [-] 480  testdata/logic_test/zigzag_join:43: too many errors encountered, skipping the rest of the input
    logic.go:3126: 
        testdata/logic_test/zigzag_join:43: error while processing
    logic.go:3126: testdata/logic_test/zigzag_join:43: too many errors encountered, skipping the rest of the input
        --- FAIL: TestLogic/fakedist/zigzag_join (1.81s)
=== RUN   TestLogic/fakedist
    --- FAIL: TestLogic/fakedist (0.75s)
Reproduce

To reproduce, try: 

make stressrace TESTS=TestLogic PKG=./pkg/sql/logictest TESTTIMEOUT=5m STRESSFLAGS='-timeout 5m' 2>&1

Parameters in this failure:

  • GOFLAGS=-json

Same failure on other branches

/cc @jordanlewis

This test on roachdash | Improve this report!

@cockroach-teamcity
Copy link
Member Author

sql/logictest.TestLogic failed with artifacts on master @ f3286c1e1b8d2d44f0b5c92460c0d5acbfdd1610:

=== RUN   TestLogic
    test_log_scope.go:73: test logs captured to: /go/src/github.com/cockroachdb/cockroach/artifacts/logTestLogic036720330
    test_log_scope.go:74: use -show-logs to present logs inline
=== CONT  TestLogic
    logic.go:3351: -- test log scope end --
test logs left over in: /go/src/github.com/cockroachdb/cockroach/artifacts/logTestLogic036720330
--- FAIL: TestLogic (828.11s)
=== RUN   TestLogic/5node-metadata/distsql_numtables
=== PAUSE TestLogic/5node-metadata/distsql_numtables
=== CONT  TestLogic/5node-metadata/distsql_numtables
=== CONT  TestLogic/5node-metadata/distsql_numtables
    logic.go:2540: 
        
        testdata/logic_test/distsql_numtables:21: 
        expected success, but found
        (XXUUU) while carrying out changes [{ADD_VOTER n4,s4}]: failed to connect to n4 at 127.0.0.1:35873: initial connection heartbeat failed: rpc error: code = Unavailable desc = connection error: desc = "transport: authentication handshake failed: context deadline exceeded"
        nodedialer.go:169: in dial()
--- done: testdata/logic_test/distsql_numtables with config 5node-metadata: 4 tests, 1 failures
E210427 22:20:54.582791 12005955 sql/logictest/logic.go:3583  [-] 1219  pq: while carrying out changes [{ADD_VOTER n4,s4}]: failed to connect to n4 at 127.0.0.1:35873: initial connection heartbeat failed: rpc error: code = Unavailable desc = connection error: desc = "transport: authentication handshake failed: context deadline exceeded"
    logic.go:3126: 
        testdata/logic_test/distsql_numtables:21: error while processing
    logic.go:3126: pq: while carrying out changes [{ADD_VOTER n4,s4}]: failed to connect to n4 at 127.0.0.1:35873: initial connection heartbeat failed: rpc error: code = Unavailable desc = connection error: desc = "transport: authentication handshake failed: context deadline exceeded"
--- done: testdata/logic_test/contention_event with config 5node-metadata: 12 tests, 0 failures
--- total progress: 140737 statements/queries
        --- FAIL: TestLogic/5node-metadata/distsql_numtables (2.22s)
=== RUN   TestLogic/5node-metadata
    --- FAIL: TestLogic/5node-metadata (0.00s)
Reproduce

To reproduce, try: 

make stressrace TESTS=TestLogic PKG=./pkg/sql/logictest TESTTIMEOUT=5m STRESSFLAGS='-timeout 5m' 2>&1

Parameters in this failure:

  • GOFLAGS=-json

Same failure on other branches

/cc @jordanlewis

This test on roachdash | Improve this report!

@cockroach-teamcity

This comment has been minimized.

Sign in to view
@cockroach-teamcity
Copy link
Member Author

sql/logictest.TestLogic failed with artifacts on master @ 112d0c111c2e9bd54cd13d40ad353cc4b286016e:

=== RUN   TestLogic
    test_log_scope.go:73: test logs captured to: /go/src/github.com/cockroachdb/cockroach/artifacts/logTestLogic265796156
    test_log_scope.go:74: use -show-logs to present logs inline
=== CONT  TestLogic
    logic.go:3351: -- test log scope end --
test logs left over in: /go/src/github.com/cockroachdb/cockroach/artifacts/logTestLogic265796156
--- FAIL: TestLogic (1011.02s)
=== RUN   TestLogic/5node
    --- FAIL: TestLogic/5node (0.00s)
=== RUN   TestLogic/5node/distsql_distinct_on
=== PAUSE TestLogic/5node/distsql_distinct_on
=== CONT  TestLogic/5node/distsql_distinct_on
=== CONT  TestLogic/5node/distsql_distinct_on
    logic.go:2540: 
        
        testdata/logic_test/distsql_distinct_on:40: 
        expected success, but found
        (XXUUU) while carrying out changes [{ADD_VOTER n3,s3}]: failed to connect to n3 at 127.0.0.1:36903: initial connection heartbeat failed: rpc error: code = Unavailable desc = connection error: desc = "transport: authentication handshake failed: context deadline exceeded"
        nodedialer.go:169: in dial()
--- done: testdata/logic_test/distsql_distinct_on with config 5node: 5 tests, 1 failures
E210428 11:16:37.957233 13281632 sql/logictest/logic.go:3583  [-] 1274  pq: while carrying out changes [{ADD_VOTER n3,s3}]: failed to connect to n3 at 127.0.0.1:36903: initial connection heartbeat failed: rpc error: code = Unavailable desc = connection error: desc = "transport: authentication handshake failed: context deadline exceeded"
    logic.go:3126: 
        testdata/logic_test/distsql_distinct_on:40: error while processing
    logic.go:3126: pq: while carrying out changes [{ADD_VOTER n3,s3}]: failed to connect to n3 at 127.0.0.1:36903: initial connection heartbeat failed: rpc error: code = Unavailable desc = connection error: desc = "transport: authentication handshake failed: context deadline exceeded"
        --- FAIL: TestLogic/5node/distsql_distinct_on (2.22s)
Reproduce

To reproduce, try: 

make stressrace TESTS=TestLogic PKG=./pkg/sql/logictest TESTTIMEOUT=5m STRESSFLAGS='-timeout 5m' 2>&1

Parameters in this failure:

  • GOFLAGS=-json

Same failure on other branches

/cc @jordanlewis

This test on roachdash | Improve this report!

@cockroach-teamcity

This comment has been minimized.

Sign in to view
@cockroach-teamcity
Copy link
Member Author

sql/logictest.TestLogic failed with artifacts on master @ 852e22a2ad78b1a19bd4f504f7079274c0c95fe5:

=== RUN   TestLogic
    test_log_scope.go:73: test logs captured to: /go/src/github.com/cockroachdb/cockroach/artifacts/logTestLogic570632428
    test_log_scope.go:74: use -show-logs to present logs inline
=== CONT  TestLogic
    logic.go:3351: -- test log scope end --
test logs left over in: /go/src/github.com/cockroachdb/cockroach/artifacts/logTestLogic570632428
--- FAIL: TestLogic (1167.38s)
=== RUN   TestLogic/fakedist-spec-planning/poison_after_push
=== PAUSE TestLogic/fakedist-spec-planning/poison_after_push
=== CONT  TestLogic/fakedist-spec-planning/poison_after_push
--- progress: testdata/logic_test/fk: 252 statements/queries
--- done: testdata/logic_test/rename_constraint with config fakedist-spec-planning: 15 tests, 0 failures
=== CONT  TestLogic/fakedist-spec-planning/poison_after_push
    logic.go:2540: 
        
        testdata/logic_test/poison_after_push:35: SELECT * FROM t
        expected success, but found
        (XXUUU) failed to connect to n2 at 127.0.0.1:33935: initial connection heartbeat failed: rpc error: code = Unavailable desc = connection error: desc = "transport: authentication handshake failed: context deadline exceeded"
        nodedialer.go:169: in dial()
E210428 18:16:09.720477 11599440 sql/logictest/logic.go:3558  [-] 1206  
E210428 18:16:09.720477 11599440 sql/logictest/logic.go:3558  [-] 1206 +pq: failed to connect to n2 at 127.0.0.1:33935: initial connection heartbeat failed: rpc error: code = Unavailable desc = connection error: desc = "transport: authentication handshake failed: context deadline exceeded"
    logic.go:2273: 
         pq: failed to connect to n2 at 127.0.0.1:33935: initial connection heartbeat failed: rpc error: code = Unavailable desc = connection error: desc = "transport: authentication handshake failed: context deadline exceeded"
--- done: testdata/logic_test/poison_after_push with config fakedist-spec-planning: 7 tests, 2 failures
E210428 18:16:09.723213 11599440 sql/logictest/logic.go:3583  [-] 1207  testdata/logic_test/poison_after_push:40: too many errors encountered, skipping the rest of the input
    logic.go:3126: 
        testdata/logic_test/poison_after_push:40: error while processing
    logic.go:3126: testdata/logic_test/poison_after_push:40: too many errors encountered, skipping the rest of the input
        --- FAIL: TestLogic/fakedist-spec-planning/poison_after_push (1.92s)
=== RUN   TestLogic/fakedist-spec-planning
    --- FAIL: TestLogic/fakedist-spec-planning (0.67s)
Reproduce

To reproduce, try: 

make stressrace TESTS=TestLogic PKG=./pkg/sql/logictest TESTTIMEOUT=5m STRESSFLAGS='-timeout 5m' 2>&1

Parameters in this failure:

  • GOFLAGS=-json

Same failure on other branches

/cc @jordanlewis

This test on roachdash | Improve this report!

@cockroach-teamcity
Copy link
Member Author

sql/logictest.TestLogic failed with artifacts on master @ ea6bcca8816a2705e46481eeb7543b16bb7c258c:

=== RUN   TestLogic
    test_log_scope.go:73: test logs captured to: /go/src/github.com/cockroachdb/cockroach/artifacts/logTestLogic134511204
    test_log_scope.go:74: use -show-logs to present logs inline
=== CONT  TestLogic
    logic.go:3351: -- test log scope end --
test logs left over in: /go/src/github.com/cockroachdb/cockroach/artifacts/logTestLogic134511204
--- FAIL: TestLogic (840.65s)
=== RUN   TestLogic/fakedist/poison_after_push
=== PAUSE TestLogic/fakedist/poison_after_push
=== CONT  TestLogic/fakedist/poison_after_push
=== CONT  TestLogic/fakedist/poison_after_push
    logic.go:2540: 
        
        testdata/logic_test/poison_after_push:35: SELECT * FROM t
        expected success, but found
        (XXUUU) failed to connect to n2 at 127.0.0.1:43475: initial connection heartbeat failed: rpc error: code = Unavailable desc = connection error: desc = "transport: authentication handshake failed: context deadline exceeded"
        nodedialer.go:169: in dial()
E210429 07:43:04.114254 3494957 sql/logictest/logic.go:3558  [-] 511  
E210429 07:43:04.114254 3494957 sql/logictest/logic.go:3558  [-] 511 +pq: failed to connect to n2 at 127.0.0.1:43475: initial connection heartbeat failed: rpc error: code = Unavailable desc = connection error: desc = "transport: authentication handshake failed: context deadline exceeded"
    logic.go:2273: 
         pq: failed to connect to n2 at 127.0.0.1:43475: initial connection heartbeat failed: rpc error: code = Unavailable desc = connection error: desc = "transport: authentication handshake failed: context deadline exceeded"
--- done: testdata/logic_test/poison_after_push with config fakedist: 7 tests, 2 failures
E210429 07:43:04.115097 3494957 sql/logictest/logic.go:3583  [-] 512  testdata/logic_test/poison_after_push:40: too many errors encountered, skipping the rest of the input
    logic.go:3126: 
        testdata/logic_test/poison_after_push:40: error while processing
    logic.go:3126: testdata/logic_test/poison_after_push:40: too many errors encountered, skipping the rest of the input
E210429 07:43:04.118965 4588676 sql/stats/automatic_stats.go:302  [-] 513  failed to refresh stats: node unavailable; try another peer
        --- FAIL: TestLogic/fakedist/poison_after_push (1.42s)
=== RUN   TestLogic/fakedist/pg_extension
=== PAUSE TestLogic/fakedist/pg_extension
=== CONT  TestLogic/fakedist/pg_extension
E210429 07:43:02.638568 4568557 jobs/adopt.go:260  [n1] 500  job 654087889146118145: adoption completed with error could not remove enum value "hello" as it is being used by "use_greetings2" in row: k=1, v='hello'
--- done: testdata/logic_test/orms with config fakedist: 21 tests, 0 failures
=== CONT  TestLogic/fakedist/pg_extension
    logic.go:3130: 
        testdata/logic_test/pg_extension:55: error while processing
    logic.go:3130: test was successful but validation upon completion failed: failed to test for descriptor JSON round-trip: pq: failed to connect to n3 at 127.0.0.1:44877: initial connection heartbeat failed: rpc error: code = Unavailable desc = connection error: desc = "transport: authentication handshake failed: context deadline exceeded"
E210429 07:43:04.106818 4588518 sql/stats/automatic_stats.go:302  [-] 509  failed to refresh stats: node unavailable; try another peer
E210429 07:43:04.113834 3494957 sql/logictest/logic.go:3571  [-] 510  
E210429 07:43:04.113834 3494957 sql/logictest/logic.go:3571  [-] 510 +testdata/logic_test/poison_after_push:35: SELECT * FROM t
E210429 07:43:04.113834 3494957 sql/logictest/logic.go:3571  [-] 510 +expected success, but found
E210429 07:43:04.113834 3494957 sql/logictest/logic.go:3571  [-] 510 +(XXUUU) failed to connect to n2 at 127.0.0.1:43475: initial connection heartbeat failed: rpc error: code = Unavailable desc = connection error: desc = "transport: authentication handshake failed: context deadline exceeded"
E210429 07:43:04.113834 3494957 sql/logictest/logic.go:3571  [-] 510 +nodedialer.go:169: in dial()
        --- FAIL: TestLogic/fakedist/pg_extension (1.57s)
=== RUN   TestLogic/fakedist
    --- FAIL: TestLogic/fakedist (0.76s)
Reproduce

To reproduce, try: 

make stressrace TESTS=TestLogic PKG=./pkg/sql/logictest TESTTIMEOUT=5m STRESSFLAGS='-timeout 5m' 2>&1

Parameters in this failure:

  • GOFLAGS=-json

Same failure on other branches

/cc @jordanlewis

This test on roachdash | Improve this report!

@ajwerner
Copy link
Contributor

Another https://teamcity.cockroachdb.com/viewLog.html?buildId=2941529&buildTypeId=Cockroach_UnitTests

@cockroach-teamcity
Copy link
Member Author

sql/logictest.TestLogic failed with artifacts on master @ 0604c999494816236a1ed8660405144f071e655b:

=== RUN   TestLogic
    test_log_scope.go:73: test logs captured to: /go/src/github.com/cockroachdb/cockroach/artifacts/logTestLogic738526644
    test_log_scope.go:74: use -show-logs to present logs inline
=== CONT  TestLogic
    logic.go:3355: -- test log scope end --
test logs left over in: /go/src/github.com/cockroachdb/cockroach/artifacts/logTestLogic738526644
--- FAIL: TestLogic (1221.08s)
=== RUN   TestLogic/local-vec-off/inflight_trace_spans
=== PAUSE TestLogic/local-vec-off/inflight_trace_spans
=== CONT  TestLogic/local-vec-off/inflight_trace_spans
=== CONT  TestLogic/local-vec-off/inflight_trace_spans
    logic.go:2317: let $curr_trace_id = 1139691570243500368
E210624 19:44:03.657660 1390457 sql/logictest/logic.go:3563  [-] 170  
E210624 19:44:03.657660 1390457 sql/logictest/logic.go:3563  [-] 170 +
E210624 19:44:03.657660 1390457 sql/logictest/logic.go:3563  [-] 170 +testdata/logic_test/inflight_trace_spans:44: SELECT count(*) = 0
E210624 19:44:03.657660 1390457 sql/logictest/logic.go:3563  [-] 170 +  FROM current_trace_spans
E210624 19:44:03.657660 1390457 sql/logictest/logic.go:3563  [-] 170 +expected:
E210624 19:44:03.657660 1390457 sql/logictest/logic.go:3563  [-] 170 +    true
E210624 19:44:03.657660 1390457 sql/logictest/logic.go:3563  [-] 170 +but found (query options: "") :
E210624 19:44:03.657660 1390457 sql/logictest/logic.go:3563  [-] 170 +    false
    logic.go:2276: 
         
        testdata/logic_test/inflight_trace_spans:44: SELECT count(*) = 0
          FROM current_trace_spans
        expected:
            true
        but found (query options: "") :
            false
--- done: testdata/logic_test/inflight_trace_spans with config local-vec-off: 9 tests, 1 failures
        --- FAIL: TestLogic/local-vec-off/inflight_trace_spans (3.13s)
=== RUN   TestLogic/local-vec-off
    --- FAIL: TestLogic/local-vec-off (0.93s)
Reproduce

To reproduce, try: 

make stressrace TESTS=TestLogic PKG=./pkg/sql/logictest TESTTIMEOUT=5m STRESSFLAGS='-timeout 5m' 2>&1

Parameters in this failure:

  • GOFLAGS=-json

Same failure on other branches

/cc @cockroachdb/sql-queries jordanlewis

This test on roachdash | Improve this report!

@cockroach-teamcity
Copy link
Member Author

sql/logictest.TestLogic failed with artifacts on master @ 5989de86b019c154076e42eb0cac1a55ac5c0be3:

=== RUN   TestLogic
    test_log_scope.go:73: test logs captured to: /go/src/github.com/cockroachdb/cockroach/artifacts/logTestLogic769877379
    test_log_scope.go:74: use -show-logs to present logs inline
=== CONT  TestLogic
    logic.go:3362: -- test log scope end --
test logs left over in: /go/src/github.com/cockroachdb/cockroach/artifacts/logTestLogic769877379
--- FAIL: TestLogic (1369.21s)
=== RUN   TestLogic/local/inflight_trace_spans
=== PAUSE TestLogic/local/inflight_trace_spans
=== CONT  TestLogic/local/inflight_trace_spans
--- done: testdata/logic_test/int_size with config local: 32 tests, 0 failures
--- progress: testdata/logic_test/vectorize: 155 statements/queries
--- progress: testdata/logic_test/role: 263 statements/queries
=== CONT  TestLogic/local/inflight_trace_spans
    logic.go:2324: let $curr_trace_id = 9111394917085194647
=== CONT  TestLogic/local/inflight_trace_spans
    logic.go:2283: 
         
        testdata/logic_test/inflight_trace_spans:44: SELECT count(*) = 0
          FROM current_trace_spans
        expected:
            true
        but found (query options: "") :
            false
--- done: testdata/logic_test/inflight_trace_spans with config local: 9 tests, 1 failures
        --- FAIL: TestLogic/local/inflight_trace_spans (3.20s)
=== RUN   TestLogic/local
    --- FAIL: TestLogic/local (1.29s)
Reproduce

To reproduce, try: 

make stressrace TESTS=TestLogic PKG=./pkg/sql/logictest TESTTIMEOUT=5m STRESSFLAGS='-timeout 5m' 2>&1

Parameters in this failure:

  • GOFLAGS=-json

Same failure on other branches

/cc @cockroachdb/sql-queries jordanlewis

This test on roachdash | Improve this report!

@cockroach-teamcity
Copy link
Member Author

sql/logictest.TestLogic failed with artifacts on master @ e723a85739a2e1b514f5de3221a2177a3a37d0e6:

            concat
        expected:
            count_1  count_lower  count_upper  concat
            3        3            3            aaa
            3        3            3            bbb
            
        but found (query options: "colnames") :
            count_1  count_lower  count_upper  concat
            3        3            3            ���
            3        3            3            bbb
E210812 05:33:45.323018 10152167 sql/logictest/logic.go:3566  [-] 939  
E210812 05:33:45.323018 10152167 sql/logictest/logic.go:3566  [-] 939 +testdata/logic_test/aggregate:3134: too many errors encountered, skipping the rest of the input
    logic.go:1818: 
         testdata/logic_test/aggregate:3134: too many errors encountered, skipping the rest of the input
--- done: testdata/logic_test/aggregate with config fakedist-disk: 499 tests, 2 failures
            --- FAIL: TestLogic/fakedist-disk/aggregate/string_agg (1.34s)
=== RUN   TestLogic/fakedist-disk/aggregate
=== PAUSE TestLogic/fakedist-disk/aggregate
=== CONT  TestLogic/fakedist-disk/aggregate
        --- FAIL: TestLogic/fakedist-disk/aggregate (12.51s)
=== RUN   TestLogic/fakedist-disk/window
=== PAUSE TestLogic/fakedist-disk/window
=== CONT  TestLogic/fakedist-disk/window
=== CONT  TestLogic/fakedist-disk/window
    logic.go:2274: 
         
        testdata/logic_test/window:385: SELECT k, concat_agg(s) OVER (PARTITION BY v ORDER BY w, k) FROM kv ORDER BY 1
        expected:
            1  ba
            3  Aa
            5  NULL
            6  bab
            7  b
            8  A
            
        but found (query options: "") :
            1  ��
            3  Aa
            5  NULL
            6  ���
            7  �
            8  A
--- done: testdata/logic_test/window with config fakedist-disk: 56 tests, 1 failures
E210812 05:34:13.660944 9811824 sql/logictest/logic.go:3591  [-] 990  testdata/logic_test/window:395: too many errors encountered, skipping the rest of the input
    logic.go:3132: 
        testdata/logic_test/window:395: error while processing
    logic.go:3132: testdata/logic_test/window:395: too many errors encountered, skipping the rest of the input
        --- FAIL: TestLogic/fakedist-disk/window (2.27s)
=== RUN   TestLogic/fakedist-disk
    --- FAIL: TestLogic/fakedist-disk (0.63s)
Reproduce

To reproduce, try: 

make stressrace TESTS=TestLogic PKG=./pkg/sql/logictest TESTTIMEOUT=5m STRESSFLAGS='-timeout 5m' 2>&1

Parameters in this failure:

  • GOFLAGS=-json

Same failure on other branches

/cc @cockroachdb/sql-queries jordanlewis

This test on roachdash | Improve this report!

@yuzefovich
Copy link
Member

I was able to reproduce something related to the last hit here with fakedist-disk config after one and a half hours on the gceworker:

=== CONT  TestLogic/fakedist-disk/window
    logic.go:2541: 
        
        testdata/logic_test/window:2119: SELECT product_name, price, nth_value(product_name, 2) OVER w AS second FROM products WHERE price = 200 OR price = 700 WINDOW w as (PARTITION BY price ORDER BY product_name RANGE BETWEEN CURRENT ROW AND UNBOUNDED FOLLOWING) ORDER BY price, product_name
        expected success, but found
        (XX000) internal error: unexpectedly found decreasing offsets: [0 7 0 9]
        bytes.go:80: in AssertOffsetsAreNonDecreasing()
        DETAIL: stack trace:
        github.com/cockroachdb/cockroach/pkg/col/coldata/bytes.go:80: AssertOffsetsAreNonDecreasing()
        github.com/cockroachdb/cockroach/pkg/col/coldata/bytes.go:547: AssertOffsetsAreNonDecreasing()
        github.com/cockroachdb/cockroach/pkg/sql/colexec/invariants_checker.go:87: Next()
        github.com/cockroachdb/cockroach/pkg/sql/colflow/stats.go:98: Next()
        github.com/cockroachdb/cockroach/pkg/sql/colexec/sort.go:146: spool()
        github.com/cockroachdb/cockroach/pkg/sql/colexec/sort.go:283: Next()
        github.com/cockroachdb/cockroach/pkg/sql/colexec/disk_spiller.go:197: func1()
        github.com/cockroachdb/cockroach/pkg/sql/colexecerror/error.go:91: CatchVectorizedRuntimeError()
        github.com/cockroachdb/cockroach/pkg/sql/colexec/disk_spiller.go:195: Next()
        github.com/cockroachdb/cockroach/pkg/sql/colexec/invariants_checker.go:79: Next()
        github.com/cockroachdb/cockroach/pkg/sql/colflow/stats.go:98: Next()
        github.com/cockroachdb/cockroach/pkg/sql/colexec/colexecutils/deselector.go:63: Next()
        github.com/cockroachdb/cockroach/pkg/sql/colflow/colrpc/outbox.go:282: func1()
        github.com/cockroachdb/cockroach/pkg/sql/colexecerror/error.go:91: CatchVectorizedRuntimeError()
        github.com/cockroachdb/cockroach/pkg/sql/colflow/colrpc/outbox.go:273: sendBatches()
        github.com/cockroachdb/cockroach/pkg/sql/colflow/colrpc/outbox.go:407: runWithStream()
        github.com/cockroachdb/cockroach/pkg/sql/colflow/colrpc/outbox.go:216: Run()
        github.com/cockroachdb/cockroach/pkg/sql/colflow/vectorized_flow.go:729: func1()
        github.com/cockroachdb/cockroach/pkg/sql/colflow/vectorized_flow.go:1320: 1()

The expected output for the query is

Microsoft Lumia  200.00  Samsung
Samsung          200.00  NULL
Lenovo Thinkpad  700.00  Sony VAIO
Sony VAIO        700.00  iPad
iPad             700.00  NULL

It seems that the offsets are about the third column.

Guessing is that we're forgetting to call coldata.Batch.SetLength() somewhere, and it looks like the window functions might be to blame, but I didn't immediately find where. @DrewKimball curious if you have any insight. (Note that in the comment above both aggregate and window logic test files failed, but there are some window function in aggregate.)

I'm also not sure how/why fakedist-disk is the failing config.

@DrewKimball
Copy link
Collaborator

I don't see how we could be missing a SetLength, since it's always called immediately before outputting a batch. I think it might actually be a problem with Truncate - it can actually increase maxSetLength, meaning it increases the index from which we update offsets to be non-decreasing. I'll try and figure out exactly how that might happen.

@DrewKimball
Copy link
Collaborator

DrewKimball commented Aug 14, 2021 •
edited
Loading

Hm, it looks like the one case where SpillingQueue.Enqueue doesn't call SetLength is when we spill immediately to disk and there is no selection vector. In that case, it should be possible to call Truncate with a larger index than maxSetIndex when there are nulls in the output. I'll see if I can write a query that reliably reproduces. We'd have to hit batch boundaries just right, so it might be tricky.

@DrewKimball DrewKimball mentioned this issue Aug 17, 2021
Merged
craig bot pushed a commit that referenced this issue Aug 17, 2021
@DrewKimball @irfansharif
Merge #68678 #68997 #69024 #69039
b69e790 
68678: opt: don't use outer columns as implicit grouping columns r=DrewKimball a=DrewKimball

Previously, the optbuilder logic would add any outer column that is
referenced in a grouping context to the set of grouping columns. This
is correct in some cases, because outer columns are effectively constant,
and can just be removed by norm rules. However, it is incorrect in the
case when there are no grouping columns, e.g. a `ScalarGroupBy`. In that
case, the `ScalarGroupBy` would inadvertently be converted into a `GroupBy`.
This patch modifies the optbuilder to simply ignore outer columns in a
grouping context.

Fixes #68290

Release note: None

68997: stats: use table descriptors instead of IDs r=postamar a=postamar

Previously, the sql stats package inferred various properties about
a table from its ID, like if it is a system or a virtual table.
However the table descriptor is usually readily or easily available,
providing much richer information about a table than its ID.
In particular, this allows us to stop collecting stats for views.

Release note (sql change): table statistics are no longer collected
for views.

69024: colexec: fix bytes corruption for disk-spilled window functions r=DrewKimball a=DrewKimball

This patch fixes the `Truncate` method for bytes columns so that it
updates the offsets to be non-decreasing up to the new `maxSetLength`.
This is necessary in the case when the new `maxSetLength` is greater
than the old one.

This can happen when a window function has a bytes output column and
the `SpillingQueue` that buffers input batches spills to disk. If a
batch has trailing nulls up to the last processed index, and it is
immediately enqueued to disk, `SpillingQueue` does not call `SetLength`
on the batch, so the offsets still need to be updated (in this case by
`Truncate`).

Fixes #60824

Release note: None

69039: github: route pkg/migration PRs to kv-prs sub-team r=irfansharif a=irfansharif

Missed one in #68903.

Release note: None

Co-authored-by: Drew Kimball <[email protected]>
Co-authored-by: Marius Posta <[email protected]>
Co-authored-by: irfan sharif <[email protected]>
@craig craig bot closed this as completed in de91509 Aug 17, 2021
@yuzefovich yuzefovich mentioned this issue Oct 1, 2021
Closed
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@jordanlewis jordanlewis

Labels
branch-master Failures and bugs on the master branch. C-test-failure Broken test (automatically or manually discovered). O-robot Originated from a bot.
Projects
None yet
Milestone
No milestone
Development

Successfully merging a pull request may close this issue.

colexec: fix bytes corruption for disk-spilled window functions DrewKimball/cockroach
9 participants
@jordanlewis @andreimatei @ajwerner @yuzefovich @adityamaru @RaduBerinde @cockroach-teamcity @DrewKimball @sumeerbhola