Skip to content

sql: TestErrorOnCommitFinalizesTxn failed under stress #29028

Closed
Closed
sql: TestErrorOnCommitFinalizesTxn failed under stress#29028
Assignees
knz
Labels
A-sql-executorSQL txn logicC-test-failureBroken test (automatically or manually discovered).O-robotOriginated from a bot.
Milestone
2.1
@cockroach-teamcity

Description

@cockroach-teamcity
cockroach-teamcity
opened on Aug 24, 2018

SHA: https://github.com/cockroachdb/cockroach/commits/d6a4a0d6a7e84debc0195822f6cd196405c584c4

Parameters:

TAGS=
GOFLAGS=-race

To repro, try:

# Don't forget to check out a clean suitable branch and experiment with the
# stress invocation until the desired results present themselves. For example,
# using stressrace instead of stress and passing the '-p' stressflag which
# controls concurrency.
./scripts/gceworker.sh start && ./scripts/gceworker.sh mosh
cd ~/go/src/github.com/cockroachdb/cockroach && \
make stress TESTS=TestErrorOnCommitFinalizesTxn PKG=github.com/cockroachdb/cockroach/pkg/sql TESTTIMEOUT=5m STRESSFLAGS='-stderr=false -maxtime 20m -timeout 10m'

Failed test: https://teamcity.cockroachdb.com/viewLog.html?buildId=858423&tab=buildLog

=== RUN   TestErrorOnCommitFinalizesTxn
W180824 05:59:34.129435 176306 server/status/runtime.go:294  [n?] Could not parse build timestamp: parsing time "" as "2006/01/02 15:04:05": cannot parse "" as "2006"
I180824 05:59:34.224368 176306 server/server.go:830  [n?] monitoring forward clock jumps based on server.clock.forward_jump_check_enabled
I180824 05:59:34.225163 176306 base/addr_validation.go:260  [n?] server certificate addresses: IP=127.0.0.1,::1; DNS=localhost,*.local; CN=node
I180824 05:59:34.225276 176306 base/addr_validation.go:300  [n?] web UI certificate addresses: IP=127.0.0.1,::1; DNS=localhost,*.local; CN=node
I180824 05:59:34.253011 176306 server/config.go:496  [n?] 1 storage engine initialized
I180824 05:59:34.253261 176306 server/config.go:499  [n?] RocksDB cache size: 128 MiB
I180824 05:59:34.253304 176306 server/config.go:499  [n?] store 0: in-memory, size 0 B
I180824 05:59:34.492547 176306 server/node.go:373  [n?] **** cluster 778669e8-bbea-4418-8b9c-cc57e630d855 has been created
I180824 05:59:34.492824 176306 server/server.go:1401  [n?] **** add additional nodes by specifying --join=127.0.0.1:38525
I180824 05:59:34.494499 176306 gossip/gossip.go:382  [n1] NodeDescriptor set to node_id:1 address:<network_field:"tcp" address_field:"127.0.0.1:38525" > attrs:<> locality:<> ServerVersion:<major_val:2 minor_val:0 patch:0 unstable:12 > build_tag:"v2.1.0-alpha.20180702-1973-gd6a4a0d" started_at:1535090374493993901 
I180824 05:59:34.520530 176306 storage/store.go:1541  [n1,s1] [n1,s1]: failed initial metrics computation: [n1,s1]: system config not yet available
I180824 05:59:34.554931 176306 server/node.go:476  [n1] initialized store [n1,s1]: disk (capacity=512 MiB, available=512 MiB, used=0 B, logicalBytes=6.9 KiB), ranges=1, leases=1, queries=0.00, writes=0.00, bytesPerReplica={p10=7103.00 p25=7103.00 p50=7103.00 p75=7103.00 p90=7103.00 pMax=7103.00}, writesPerReplica={p10=0.00 p25=0.00 p50=0.00 p75=0.00 p90=0.00 pMax=0.00}
I180824 05:59:34.555811 176306 storage/stores.go:242  [n1] read 0 node addresses from persistent storage
I180824 05:59:34.556628 176306 server/node.go:697  [n1] connecting to gossip network to verify cluster ID...
I180824 05:59:34.562775 176306 server/node.go:722  [n1] node connected via gossip and verified as part of cluster "778669e8-bbea-4418-8b9c-cc57e630d855"
I180824 05:59:34.573922 176306 server/node.go:546  [n1] node=1: started with [<no-attributes>=<in-mem>] engine(s) and attributes []
I180824 05:59:34.585446 176306 server/status/recorder.go:652  [n1] available memory from cgroups (8.0 EiB) exceeds system memory 16 GiB, using system memory
I180824 05:59:34.585582 176306 server/server.go:1807  [n1] Could not start heap profiler worker due to: directory to store profiles could not be determined
I180824 05:59:34.593321 176306 server/server.go:1538  [n1] starting https server at 127.0.0.1:46695 (use: 127.0.0.1:46695)
I180824 05:59:34.593615 176306 server/server.go:1540  [n1] starting grpc/postgres server at 127.0.0.1:38525
I180824 05:59:34.593680 176306 server/server.go:1541  [n1] advertising CockroachDB node at 127.0.0.1:38525
I180824 05:59:34.606029 176585 server/status/recorder.go:652  [n1,summaries] available memory from cgroups (8.0 EiB) exceeds system memory 16 GiB, using system memory
I180824 05:59:34.616737 176566 storage/replica_command.go:289  [split,n1,s1,r1/1:/M{in-ax}] initiating a split of this range at key /System/"" [r2]
I180824 05:59:34.935453 176612 storage/replica_command.go:289  [split,n1,s1,r2/1:/{System/-Max}] initiating a split of this range at key /System/NodeLiveness [r3]
I180824 05:59:35.254908 176174 sql/event_log.go:126  [n1,intExec=optInToDiagnosticsStatReporting] Event: "set_cluster_setting", target: 0, info: {SettingName:diagnostics.reporting.enabled Value:true User:root}
I180824 05:59:35.294742 176319 storage/replica_command.go:289  [split,n1,s1,r3/1:/{System/NodeL…-Max}] initiating a split of this range at key /System/NodeLivenessMax [r4]
I180824 05:59:35.680462 176588 storage/replica_command.go:289  [split,n1,s1,r4/1:/{System/NodeL…-Max}] initiating a split of this range at key /System/tsd [r5]
W180824 05:59:35.772609 176622 storage/intent_resolver.go:668  [n1,s1] failed to push during intent resolution: failed to push "sql txn" id=bc409928 key=/Table/SystemConfigSpan/Start rw=true pri=0.01272964 iso=SERIALIZABLE stat=PENDING epo=0 ts=1535090375.444665706,0 orig=1535090375.444665706,0 max=1535090375.444665706,0 wto=false rop=false seq=12
I180824 05:59:35.950650 176620 sql/event_log.go:126  [n1,intExec=set-setting] Event: "set_cluster_setting", target: 0, info: {SettingName:version Value:2.0-12 User:root}
I180824 05:59:35.955512 176411 rpc/nodedialer/nodedialer.go:92  [consistencyChecker,n1,s1,r1/1:/{Min-System/}] connection to n1 established
I180824 05:59:36.086896 176558 storage/replica_command.go:289  [split,n1,s1,r5/1:/{System/tsd-Max}] initiating a split of this range at key /System/"tse" [r6]
I180824 05:59:36.547520 176624 sql/event_log.go:126  [n1,intExec=disableNetTrace] Event: "set_cluster_setting", target: 0, info: {SettingName:trace.debug.enable Value:false User:root}
I180824 05:59:36.586728 176660 storage/replica_command.go:289  [split,n1,s1,r6/1:/{System/tse-Max}] initiating a split of this range at key /Table/SystemConfigSpan/Start [r7]
I180824 05:59:36.741235 176695 storage/replica_command.go:289  [split,n1,s1,r7/1:/{Table/System…-Max}] initiating a split of this range at key /Table/11 [r8]
I180824 05:59:36.927777 176668 storage/replica_command.go:289  [split,n1,s1,r8/1:/{Table/11-Max}] initiating a split of this range at key /Table/12 [r9]
I180824 05:59:37.100845 176726 storage/replica_command.go:289  [split,n1,s1,r9/1:/{Table/12-Max}] initiating a split of this range at key /Table/13 [r10]
I180824 05:59:37.342011 176672 sql/event_log.go:126  [n1,intExec=initializeClusterSecret] Event: "set_cluster_setting", target: 0, info: {SettingName:cluster.secret Value:b2e89bf8-4a82-4ebd-9d05-d77f1d4f7da9 User:root}
I180824 05:59:37.418211 176743 storage/replica_command.go:289  [split,n1,s1,r10/1:/{Table/13-Max}] initiating a split of this range at key /Table/14 [r11]
I180824 05:59:37.669668 176689 storage/replica_command.go:289  [split,n1,s1,r11/1:/{Table/14-Max}] initiating a split of this range at key /Table/15 [r12]
I180824 05:59:37.792021 176636 sql/event_log.go:126  [n1,intExec=create-default-db] Event: "create_database", target: 50, info: {DatabaseName:defaultdb Statement:CREATE DATABASE IF NOT EXISTS defaultdb User:root}
I180824 05:59:37.993382 176733 sql/event_log.go:126  [n1,intExec=create-default-db] Event: "create_database", target: 51, info: {DatabaseName:postgres Statement:CREATE DATABASE IF NOT EXISTS postgres User:root}
I180824 05:59:37.999269 176775 storage/replica_command.go:289  [split,n1,s1,r12/1:/{Table/15-Max}] initiating a split of this range at key /Table/16 [r13]
I180824 05:59:38.155266 176306 server/server.go:1594  [n1] done ensuring all necessary migrations have run
I180824 05:59:38.155656 176306 server/server.go:1597  [n1] serving sql connections
I180824 05:59:38.288241 176658 storage/replica_command.go:289  [split,n1,s1,r13/1:/{Table/16-Max}] initiating a split of this range at key /Table/17 [r14]
I180824 05:59:38.355638 176777 server/server_update.go:67  [n1] no need to upgrade, cluster already at the newest version
I180824 05:59:38.454655 176779 sql/event_log.go:126  [n1] Event: "node_join", target: 1, info: {Descriptor:{NodeID:1 Address:{NetworkField:tcp AddressField:127.0.0.1:38525} Attrs: Locality: ServerVersion:2.0-12 BuildTag:v2.1.0-alpha.20180702-1973-gd6a4a0d StartedAt:1535090374493993901 LocalityAddress:[]} ClusterID:778669e8-bbea-4418-8b9c-cc57e630d855 StartedAt:1535090374493993901 LastUp:1535090374493993901}
I180824 05:59:38.488479 176793 storage/replica_command.go:289  [split,n1,s1,r14/1:/{Table/17-Max}] initiating a split of this range at key /Table/18 [r15]
I180824 05:59:38.685307 176760 storage/replica_command.go:289  [split,n1,s1,r15/1:/{Table/18-Max}] initiating a split of this range at key /Table/19 [r16]
I180824 05:59:38.817121 176786 storage/replica_command.go:289  [split,n1,s1,r16/1:/{Table/19-Max}] initiating a split of this range at key /Table/20 [r17]
I180824 05:59:38.981853 176837 storage/replica_command.go:289  [split,n1,s1,r17/1:/{Table/20-Max}] initiating a split of this range at key /Table/21 [r18]
I180824 05:59:39.228014 176864 storage/replica_command.go:289  [split,n1,s1,r18/1:/{Table/21-Max}] initiating a split of this range at key /Table/22 [r19]
I180824 05:59:39.465551 176828 storage/replica_command.go:289  [split,n1,s1,r19/1:/{Table/22-Max}] initiating a split of this range at key /Table/23 [r20]
I180824 05:59:39.767373 176890 storage/replica_command.go:289  [split,n1,s1,r20/1:/{Table/23-Max}] initiating a split of this range at key /Table/50 [r21]
I180824 05:59:39.895731 176931 storage/replica_command.go:289  [split,n1,s1,r21/1:/{Table/50-Max}] initiating a split of this range at key /Table/51 [r22]
I180824 05:59:41.028161 176933 storage/replica_command.go:289  [split,n1,s1,r22/1:/{Table/51-Max}] initiating a split of this range at key /Table/52 [r23]
I180824 05:59:41.034373 176953 sql/event_log.go:126  [n1,client=127.0.0.1:47040,user=root] Event: "create_database", target: 52, info: {DatabaseName:t Statement:CREATE DATABASE t User:root}
I180824 05:59:41.208302 176953 sql/event_log.go:126  [n1,client=127.0.0.1:47040,user=root] Event: "create_table", target: 53, info: {TableName:t.public.test Statement:CREATE TABLE t.public.test (k INT PRIMARY KEY, v STRING) User:root}
==================
WARNING: DATA RACE
Write at 0x00c420702048 by goroutine 549:
  github.com/cockroachdb/cockroach/pkg/sql_test.(*TxnAborter).executorKnobs.func1()
      /go/src/github.com/cockroachdb/cockroach/pkg/sql/txn_restart_test.go:376 +0xd3
  github.com/cockroachdb/cockroach/pkg/sql_test.TestErrorOnCommitFinalizesTxn()
      /go/src/github.com/cockroachdb/cockroach/pkg/sql/txn_restart_test.go:1099 +0x63a
  testing.tRunner()
      /usr/local/go/src/testing/testing.go:777 +0x16d

Previous read at 0x00c420702048 by goroutine 926:
  github.com/cockroachdb/cockroach/pkg/sql.(*connExecutor).execStmtInOpenState.func4()
      /go/src/github.com/cockroachdb/cockroach/pkg/sql/conn_executor_exec.go:181 +0xa4
  github.com/cockroachdb/cockroach/pkg/sql.(*connExecutor).execStmtInOpenState()
      /go/src/github.com/cockroachdb/cockroach/pkg/sql/conn_executor_exec.go:433 +0xe78
  github.com/cockroachdb/cockroach/pkg/sql.(*connExecutor).execStmt()
      /go/src/github.com/cockroachdb/cockroach/pkg/sql/conn_executor_exec.go:95 +0x46e
  github.com/cockroachdb/cockroach/pkg/sql.(*connExecutor).run()
      /go/src/github.com/cockroachdb/cockroach/pkg/sql/conn_executor.go:1135 +0x1ed4
  github.com/cockroachdb/cockroach/pkg/sql.(*internalExecutorImpl).initConnEx.func1()
      /go/src/github.com/cockroachdb/cockroach/pkg/sql/internal.go:210 +0x97

Goroutine 549 (running) created at:
  testing.(*T).Run()
      /usr/local/go/src/testing/testing.go:824 +0x564
  testing.runTests.func1()
      /usr/local/go/src/testing/testing.go:1063 +0xa4
  testing.tRunner()
      /usr/local/go/src/testing/testing.go:777 +0x16d
  testing.runTests()
      /usr/local/go/src/testing/testing.go:1061 +0x4e1
  testing.(*M).Run()
      /usr/local/go/src/testing/testing.go:978 +0x2cd
  github.com/cockroachdb/cockroach/pkg/sql_test.TestMain()
      /go/src/github.com/cockroachdb/cockroach/pkg/sql/main_test.go:36 +0x15d
  main.main()
      _testmain.go:508 +0x22a

Goroutine 926 (running) created at:
  github.com/cockroachdb/cockroach/pkg/sql.(*internalExecutorImpl).initConnEx()
      /go/src/github.com/cockroachdb/cockroach/pkg/sql/internal.go:199 +0x49a
  github.com/cockroachdb/cockroach/pkg/sql.(*internalExecutorImpl).execInternal()
      /go/src/github.com/cockroachdb/cockroach/pkg/sql/internal.go:449 +0x54d
  github.com/cockroachdb/cockroach/pkg/sql.(*InternalExecutor).Exec()
      /go/src/github.com/cockroachdb/cockroach/pkg/sql/internal.go:292 +0x1d1
  github.com/cockroachdb/cockroach/pkg/storage.(*Store).insertRangeLogEvent()
      /go/src/github.com/cockroachdb/cockroach/pkg/storage/log.go:99 +0x38f
  github.com/cockroachdb/cockroach/pkg/storage.(*Store).logSplit()
      /go/src/github.com/cockroachdb/cockroach/pkg/storage/log.go:121 +0x353
  github.com/cockroachdb/cockroach/pkg/storage.(*Replica).adminSplitWithDescriptor.func1()
      /go/src/github.com/cockroachdb/cockroach/pkg/storage/replica_command.go:329 +0x422
  github.com/cockroachdb/cockroach/pkg/internal/client.(*DB).Txn.func1()
      /go/src/github.com/cockroachdb/cockroach/pkg/internal/client/db.go:585 +0x5e
  github.com/cockroachdb/cockroach/pkg/internal/client.(*Txn).exec()
      /go/src/github.com/cockroachdb/cockroach/pkg/internal/client/txn.go:692 +0xf6
  github.com/cockroachdb/cockroach/pkg/internal/client.(*DB).Txn()
      /go/src/github.com/cockroachdb/cockroach/pkg/internal/client/db.go:584 +0x13b
  github.com/cockroachdb/cockroach/pkg/storage.(*Replica).adminSplitWithDescriptor()
      /go/src/github.com/cockroachdb/cockroach/pkg/storage/replica_command.go:292 +0xcc7
  github.com/cockroachdb/cockroach/pkg/storage.(*splitQueue).processAttempt()
      /go/src/github.com/cockroachdb/cockroach/pkg/storage/split_queue.go:149 +0x1c8
  github.com/cockroachdb/cockroach/pkg/storage.(*splitQueue).process()
      /go/src/github.com/cockroachdb/cockroach/pkg/storage/split_queue.go:127 +0x93
  github.com/cockroachdb/cockroach/pkg/storage.(*baseQueue).processReplica()
      /go/src/github.com/cockroachdb/cockroach/pkg/storage/queue.go:744 +0x313
  github.com/cockroachdb/cockroach/pkg/storage.(*baseQueue).processLoop.func1.2()
      /go/src/github.com/cockroachdb/cockroach/pkg/storage/queue.go:627 +0xdd
  github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunAsyncTask.func1()
      /go/src/github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:324 +0xf3
==================
--- FAIL: TestErrorOnCommitFinalizesTxn (7.99s)

Metadata

Metadata

Assignees

Labels

A-sql-executorSQL txn logicC-test-failureBroken test (automatically or manually discovered).O-robotOriginated from a bot.

Type

No type

Projects

No projects

Milestone

Relationships

None yet

Development

No branches or pull requests

Issue actions