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/pgwire: TestAuthenticationAndHBARules failed #49930

Closed
cockroach-teamcity opened this issue Jun 6, 2020 · 3 comments · Fixed by #49936
Closed

sql/pgwire: TestAuthenticationAndHBARules failed #49930

cockroach-teamcity opened this issue Jun 6, 2020 · 3 comments · Fixed by #49936
Assignees
@knz
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.
Milestone
20.2

Comments

@cockroach-teamcity
Copy link
Member

(sql/pgwire).TestAuthenticationAndHBARules failed on master@dfb6e1bee4abc2f2ff82d545686908d983f82872:

=== RUN   TestAuthenticationAndHBARules/insecure=false/insecure
I200606 03:21:05.504564 35436 base/addr_validation.go:296  [n?] server certificate addresses: IP=127.0.0.1,::1; DNS=localhost,*.local; CN=node
I200606 03:21:05.504727 35436 base/addr_validation.go:342  [n?] web UI certificate addresses: IP=127.0.0.1,::1; DNS=localhost,*.local; CN=node
W200606 03:21:05.505618 35436 server/status/runtime.go:309  [n?] Could not parse build timestamp: parsing time "" as "2006/01/02 15:04:05": cannot parse "" as "2006"
I200606 03:21:05.573149 35436 server/server.go:748  [n?] monitoring forward clock jumps based on server.clock.forward_jump_check_enabled
I200606 03:21:05.577501 35436 server/config.go:595  [n?] 1 storage engine initialized
I200606 03:21:05.577757 35436 server/config.go:598  [n?] Pebble cache size: 128 MiB
I200606 03:21:05.577883 35436 server/config.go:598  [n?] store 0: in-memory, size 0 B
I200606 03:21:05.633348 35436 server/server.go:1245  [n?] **** add additional nodes by specifying --join=127.0.0.1:40927
I200606 03:21:05.633828 35436 server/init.go:173  [n?] no stores bootstrapped and --join flag specified, awaiting init command or join with an already initialized node.
I200606 03:21:05.634017 35436 server/init.go:193  [n?] **** cluster 76e747f8-0fa8-41a3-a6b6-6b201e1aac61 has been created
I200606 03:21:05.634804 35436 gossip/gossip.go:405  [n1] NodeDescriptor set to node_id:1 address:<network_field:"tcp" address_field:"127.0.0.1:40927" > attrs:<> locality:<> ServerVersion:<major_val:20 minor_val:1 patch:0 unstable:7 > build_tag:"v20.2.0-alpha.00000000-2059-gdfb6e1bee4" started_at:1591413665634480395 cluster_name:"" sql_address:<network_field:"tcp" address_field:"127.0.0.1:36697" > 
I200606 03:21:05.642374 35408 server/server.go:1327  [n1] connecting to gossip network to verify cluster ID "76e747f8-0fa8-41a3-a6b6-6b201e1aac61"
I200606 03:21:05.678164 35408 server/server.go:1330  [n1] node connected via gossip
W200606 03:21:05.678336 35611 kv/kvserver/store.go:1652  [n1,s1,r6/1:/Table/{SystemCon…-11}] could not gossip system config: [NotLeaseHolderError] r6: replica (n1,s1):1 not lease holder; lease holder unknown
I200606 03:21:05.688124 35436 server/node.go:412  [n1] initialized store [n1,s1]: disk (capacity=512 MiB, available=512 MiB, used=0 B, logicalBytes=18 KiB), ranges=34, leases=2, queries=0.00, writes=0.00, bytesPerReplica={p10=0.00 p25=0.00 p50=0.00 p75=0.00 p90=166.00 pMax=15513.00}, writesPerReplica={p10=0.00 p25=0.00 p50=0.00 p75=0.00 p90=0.00 pMax=0.00}
I200606 03:21:05.688562 35436 kv/kvserver/stores.go:236  [n1] read 0 node addresses from persistent storage
I200606 03:21:05.689333 35436 server/node.go:468  [n1] node=1: started with [<no-attributes>=<in-mem>] engine(s) and attributes []
I200606 03:21:05.716844 35436 server/server.go:1426  [n1] starting https server at 127.0.0.1:46029 (use: 127.0.0.1:46029)
I200606 03:21:05.717341 35436 server/server.go:1431  [n1] starting postgres server at 127.0.0.1:36697 (use: 127.0.0.1:36697)
I200606 03:21:05.717409 35436 server/server.go:1433  [n1] starting grpc server at 127.0.0.1:40927
I200606 03:21:05.717459 35436 server/server.go:1434  [n1] advertising CockroachDB node at 127.0.0.1:40927
I200606 03:21:05.806247 35752 sql/temporary_schema.go:473  [n1] running temporary object cleanup background job
I200606 03:21:05.828962 35680 kv/kvserver/replica_rangefeed.go:608  [n1,s1,r6/1:/Table/{SystemCon…-11}] RangeFeed closed timestamp is empty
I200606 03:21:05.848825 35752 sql/temporary_schema.go:508  [n1] found 0 temporary schemas
I200606 03:21:05.849423 35752 sql/temporary_schema.go:511  [n1] early exiting temporary schema cleaner as no temporary schemas were found
I200606 03:21:05.849828 35752 sql/temporary_schema.go:512  [n1] completed temporary object cleanup job
I200606 03:21:05.850217 35752 sql/temporary_schema.go:595  [n1] temporary object cleaner next scheduled to run at 2020-06-06 03:51:05.805881316 +0000 UTC
I200606 03:21:05.859794 35751 sql/event_log.go:132  [n1] Event: "node_join", target: 1, info: {Descriptor:{NodeID:1 Address:127.0.0.1:40927 Attrs: Locality: ServerVersion:20.1-7 BuildTag:v20.2.0-alpha.00000000-2059-gdfb6e1bee4 StartedAt:1591413665634480395 LocalityAddress:[] ClusterName: SQLAddress:127.0.0.1:36697} ClusterID:76e747f8-0fa8-41a3-a6b6-6b201e1aac61 StartedAt:1591413665634480395 LastUp:1591413665634480395}
I200606 03:21:05.882088 35633 sql/event_log.go:132  [n1,intExec=optInToDiagnosticsStatReporting] Event: "set_cluster_setting", target: 0, info: {SettingName:diagnostics.reporting.enabled Value:true User:root}
I200606 03:21:05.917154 35750 server/server_update.go:55  [n1] no need to upgrade, cluster already at the newest version
I200606 03:21:05.962378 35799 sql/event_log.go:132  [n1,intExec=set-setting] Event: "set_cluster_setting", target: 0, info: {SettingName:version Value:20.1-7 User:root}
I200606 03:21:06.099204 36085 sql/event_log.go:132  [n1,intExec=initializeClusterSecret] Event: "set_cluster_setting", target: 0, info: {SettingName:cluster.secret Value:0d385601-282f-437c-aa29-425d9799b420 User:root}
I200606 03:21:06.140545 36199 sql/event_log.go:132  [n1,intExec=create-default-db] Event: "create_database", target: 50, info: {DatabaseName:defaultdb Statement:CREATE DATABASE IF NOT EXISTS defaultdb User:root}
I200606 03:21:06.168884 36200 sql/event_log.go:132  [n1,intExec=create-default-db] Event: "create_database", target: 51, info: {DatabaseName:postgres Statement:CREATE DATABASE IF NOT EXISTS postgres User:root}
I200606 03:21:06.289100 35436 server/server_sql.go:645  [n1] done ensuring all necessary migrations have run
I200606 03:21:06.289208 35436 server/server.go:1747  [n1] serving sql connections
I200606 03:21:06.289414 35436 server/server.go:1768  [n1] starting postgres server at unix:/tmp/TestAuth329856130/.s.PGSQL.6
I200606 03:21:06.290329 36123 sqlmigrations/migrations.go:727  [n1] starting wait for upgrade finalization before schema change job migration
I200606 03:21:06.294764 36123 sqlmigrations/migrations.go:759  [n1] starting schema change job migration
FAIL	github.com/cockroachdb/cockroach/pkg/sql/pgwire	109.459s
More

Parameters:

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

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 Jun 6, 2020
@cockroach-teamcity cockroach-teamcity added this to the 20.2 milestone Jun 6, 2020
@cockroach-teamcity
Copy link
Member Author

(sql/pgwire).TestAuthenticationAndHBARules failed on master@dfb6e1bee4abc2f2ff82d545686908d983f82872:

I200606 06:30:27.534422 47556 server/config.go:595  [n?] 1 storage engine initialized
I200606 06:30:27.534516 47556 server/config.go:598  [n?] Pebble cache size: 128 MiB
I200606 06:30:27.534559 47556 server/config.go:598  [n?] store 0: in-memory, size 0 B
I200606 06:30:27.576665 47556 server/server.go:1245  [n?] **** add additional nodes by specifying --join=127.113.82.129:38575
I200606 06:30:27.576927 47556 server/init.go:173  [n?] no stores bootstrapped and --join flag specified, awaiting init command or join with an already initialized node.
I200606 06:30:27.577016 47556 server/init.go:193  [n?] **** cluster fc79cf7a-9f62-4334-96f2-072f83f3d42c has been created
I200606 06:30:27.577465 47790 server/server.go:1327  [n1] connecting to gossip network to verify cluster ID "fc79cf7a-9f62-4334-96f2-072f83f3d42c"
I200606 06:30:27.577601 47556 gossip/gossip.go:405  [n1] NodeDescriptor set to node_id:1 address:<network_field:"tcp" address_field:"127.113.82.129:38575" > attrs:<> locality:<> ServerVersion:<major_val:20 minor_val:1 patch:0 unstable:7 > build_tag:"v20.2.0-alpha.00000000-2059-gdfb6e1bee4" started_at:1591425027577341483 cluster_name:"" sql_address:<network_field:"tcp" address_field:"127.113.82.129:41715" > 
I200606 06:30:27.615760 47790 server/server.go:1330  [n1] node connected via gossip
W200606 06:30:27.616063 47869 kv/kvserver/store.go:1652  [n1,s1,r6/1:/Table/{SystemCon…-11}] could not gossip system config: [NotLeaseHolderError] r6: replica (n1,s1):1 not lease holder; lease holder unknown
I200606 06:30:27.619841 47556 server/node.go:412  [n1] initialized store [n1,s1]: disk (capacity=512 MiB, available=512 MiB, used=0 B, logicalBytes=18 KiB), ranges=34, leases=0, queries=0.00, writes=0.00, bytesPerReplica={p10=0.00 p25=0.00 p50=0.00 p75=0.00 p90=166.00 pMax=15513.00}, writesPerReplica={p10=0.00 p25=0.00 p50=0.00 p75=0.00 p90=0.00 pMax=0.00}
I200606 06:30:27.620325 47556 kv/kvserver/stores.go:236  [n1] read 0 node addresses from persistent storage
I200606 06:30:27.621076 47556 server/node.go:468  [n1] node=1: started with [<no-attributes>=<in-mem>] engine(s) and attributes []
I200606 06:30:27.622680 47556 server/server.go:1426  [n1] starting http server at 127.113.82.129:44541 (use: 127.113.82.129:44541)
I200606 06:30:27.622788 47556 server/server.go:1431  [n1] starting postgres server at 127.113.82.129:41715 (use: 127.113.82.129:41715)
I200606 06:30:27.622880 47556 server/server.go:1433  [n1] starting grpc server at 127.113.82.129:38575
I200606 06:30:27.622944 47556 server/server.go:1434  [n1] advertising CockroachDB node at 127.113.82.129:38575
I200606 06:30:27.713188 47963 sql/temporary_schema.go:473  [n1] running temporary object cleanup background job
I200606 06:30:27.725981 48034 kv/kvserver/replica_rangefeed.go:608  [n1,s1,r6/1:/Table/{SystemCon…-11}] RangeFeed closed timestamp is empty
I200606 06:30:27.737089 47963 sql/temporary_schema.go:508  [n1] found 0 temporary schemas
I200606 06:30:27.737218 47963 sql/temporary_schema.go:511  [n1] early exiting temporary schema cleaner as no temporary schemas were found
I200606 06:30:27.737276 47963 sql/temporary_schema.go:512  [n1] completed temporary object cleanup job
I200606 06:30:27.737386 47963 sql/temporary_schema.go:595  [n1] temporary object cleaner next scheduled to run at 2020-06-06 07:00:27.71277277 +0000 UTC
I200606 06:30:27.751251 47962 sql/event_log.go:132  [n1] Event: "node_join", target: 1, info: {Descriptor:{NodeID:1 Address:127.113.82.129:38575 Attrs: Locality: ServerVersion:20.1-7 BuildTag:v20.2.0-alpha.00000000-2059-gdfb6e1bee4 StartedAt:1591425027577341483 LocalityAddress:[] ClusterName: SQLAddress:127.113.82.129:41715} ClusterID:fc79cf7a-9f62-4334-96f2-072f83f3d42c StartedAt:1591425027577341483 LastUp:1591425027577341483}
I200606 06:30:27.775856 47912 sql/event_log.go:132  [n1,intExec=optInToDiagnosticsStatReporting] Event: "set_cluster_setting", target: 0, info: {SettingName:diagnostics.reporting.enabled Value:true User:root}
I200606 06:30:27.811460 47961 server/server_update.go:55  [n1] no need to upgrade, cluster already at the newest version
I200606 06:30:27.846988 48111 sql/event_log.go:132  [n1,intExec=set-setting] Event: "set_cluster_setting", target: 0, info: {SettingName:version Value:20.1-7 User:root}
I200606 06:30:27.982958 48302 sql/event_log.go:132  [n1,intExec=initializeClusterSecret] Event: "set_cluster_setting", target: 0, info: {SettingName:cluster.secret Value:031619e2-4e28-4bf4-925f-96b250a7dbbd User:root}
I200606 06:30:28.037707 48531 sql/event_log.go:132  [n1,intExec=create-default-db] Event: "create_database", target: 50, info: {DatabaseName:defaultdb Statement:CREATE DATABASE IF NOT EXISTS defaultdb User:root}
I200606 06:30:28.074192 48535 sql/event_log.go:132  [n1,intExec=create-default-db] Event: "create_database", target: 51, info: {DatabaseName:postgres Statement:CREATE DATABASE IF NOT EXISTS postgres User:root}
I200606 06:30:28.255851 47556 server/server_sql.go:645  [n1] done ensuring all necessary migrations have run
I200606 06:30:28.256007 47556 server/server.go:1747  [n1] serving sql connections
I200606 06:30:28.256275 47556 server/server.go:1768  [n1] starting postgres server at unix:/tmp/TestAuth553028591/.s.PGSQL.6
I200606 06:30:28.262142 48682 sqlmigrations/migrations.go:727  [n1] starting wait for upgrade finalization before schema change job migration
I200606 06:30:28.264328 48607 sql/pgwire/server.go:493  [n1,client=127.0.0.1:43048] 1 received connection
I200606 06:30:28.280282 48698 sql/pgwire/auth.go:335  [n1,client=127.0.0.1:43048,hostnossl,user=root] 2 connection matches HBA rule: 
I200606 06:30:28.282439 48698 sql/pgwire/auth.go:335  [n1,client=127.0.0.1:43048,hostnossl,user=root] 3 authentication succeeded
test logs left over in: /tmp/logTestAuthenticationAndHBARules_insecure=true_insecure733942419
I200606 06:30:28.334501 47556 util/stop/stopper.go:539  quiescing
I200606 06:30:28.334920 47867 kv/kvserver/queue.go:580  [n1,s1] rate limited in gossip update (merge): node unavailable; try another peer
W200606 06:30:28.335008 48537 kv/kvserver/intentresolver/intent_resolver.go:744  failed to gc transaction record: could not GC completed transaction anchored at /Table/SystemConfigSpan/Start: node unavailable; try another peer
I200606 06:30:28.335211 47923 kv/kvclient/kvcoord/transport_race.go:108  transport race promotion: ran 17 iterations on up to 271 requests
I200606 06:30:28.335351 47867 kv/kvserver/queue.go:580  [n1,s1] rate limited in gossip update (split): node unavailable; try another peer
I200606 06:30:28.342473 48607 sql/pgwire/conn.go:226  [n1,client=127.0.0.1:43048,hostnossl,user=root] 4 session terminated; duration: 62.416355ms
I200606 06:30:28.342665 48607 sql/pgwire/server.go:501  [n1,client=127.0.0.1:43048,hostnossl] 5 disconnected; duration: 78.356282ms
        --- FAIL: TestAuthenticationAndHBARules/insecure=true/insecure (0.87s)
            test_log_scope.go:77: test logs captured to: /tmp/logTestAuthenticationAndHBARules_insecure=true_insecure733942419
            testing.go:853: race detected during execution of test
=== RUN   TestAuthenticationAndHBARules/insecure=true
    --- FAIL: TestAuthenticationAndHBARules/insecure=true (9.87s)
More

Parameters:

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

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

@cockroach-teamcity
Copy link
Member Author

(sql/pgwire).TestAuthenticationAndHBARules failed on master@dfb6e1bee4abc2f2ff82d545686908d983f82872:

=== RUN   TestAuthenticationAndHBARules/insecure=false/hba_user_selection
I200606 09:14:49.178573 33039 base/addr_validation.go:296  [n?] server certificate addresses: IP=127.0.0.1,::1; DNS=localhost,*.local; CN=node
I200606 09:14:49.178723 33039 base/addr_validation.go:342  [n?] web UI certificate addresses: IP=127.0.0.1,::1; DNS=localhost,*.local; CN=node
W200606 09:14:49.179666 33039 server/status/runtime.go:309  [n?] Could not parse build timestamp: parsing time "" as "2006/01/02 15:04:05": cannot parse "" as "2006"
I200606 09:14:49.306614 33039 server/server.go:748  [n?] monitoring forward clock jumps based on server.clock.forward_jump_check_enabled
I200606 09:14:49.311605 33039 server/config.go:595  [n?] 1 storage engine initialized
I200606 09:14:49.312014 33039 server/config.go:598  [n?] Pebble cache size: 128 MiB
I200606 09:14:49.312395 33039 server/config.go:598  [n?] store 0: in-memory, size 0 B
I200606 09:14:49.383836 33039 server/server.go:1245  [n?] **** add additional nodes by specifying --join=127.0.0.1:38639
I200606 09:14:49.384752 33039 server/init.go:173  [n?] no stores bootstrapped and --join flag specified, awaiting init command or join with an already initialized node.
I200606 09:14:49.385292 33039 server/init.go:193  [n?] **** cluster 96396d6b-9cc2-40ec-a8a9-bd2a62dbe28b has been created
I200606 09:14:49.386347 33039 gossip/gossip.go:405  [n1] NodeDescriptor set to node_id:1 address:<network_field:"tcp" address_field:"127.0.0.1:38639" > attrs:<> locality:<> ServerVersion:<major_val:20 minor_val:1 patch:0 unstable:7 > build_tag:"v20.2.0-alpha.00000000-2059-gdfb6e1bee4" started_at:1591434889386021721 cluster_name:"" sql_address:<network_field:"tcp" address_field:"127.0.0.1:42699" > 
I200606 09:14:49.393055 33194 server/server.go:1327  [n1] connecting to gossip network to verify cluster ID "96396d6b-9cc2-40ec-a8a9-bd2a62dbe28b"
I200606 09:14:49.540869 33194 server/server.go:1330  [n1] node connected via gossip
W200606 09:14:49.541708 33390 kv/kvserver/store.go:1652  [n1,s1,r6/1:/Table/{SystemCon…-11}] could not gossip system config: [NotLeaseHolderError] r6: replica (n1,s1):1 not lease holder; lease holder unknown
I200606 09:14:49.550638 33039 server/node.go:412  [n1] initialized store [n1,s1]: disk (capacity=512 MiB, available=512 MiB, used=0 B, logicalBytes=18 KiB), ranges=34, leases=1, queries=0.00, writes=0.00, bytesPerReplica={p10=0.00 p25=0.00 p50=0.00 p75=0.00 p90=166.00 pMax=15513.00}, writesPerReplica={p10=0.00 p25=0.00 p50=0.00 p75=0.00 p90=0.00 pMax=0.00}
I200606 09:14:49.551035 33039 kv/kvserver/stores.go:236  [n1] read 0 node addresses from persistent storage
I200606 09:14:49.551908 33039 server/node.go:468  [n1] node=1: started with [<no-attributes>=<in-mem>] engine(s) and attributes []
I200606 09:14:49.553213 33039 server/server.go:1426  [n1] starting https server at 127.0.0.1:37127 (use: 127.0.0.1:37127)
I200606 09:14:49.553317 33039 server/server.go:1431  [n1] starting postgres server at 127.0.0.1:42699 (use: 127.0.0.1:42699)
I200606 09:14:49.553460 33039 server/server.go:1433  [n1] starting grpc server at 127.0.0.1:38639
I200606 09:14:49.553567 33039 server/server.go:1434  [n1] advertising CockroachDB node at 127.0.0.1:38639
I200606 09:14:49.700623 33520 sql/temporary_schema.go:473  [n1] running temporary object cleanup background job
I200606 09:14:49.712169 33166 kv/kvserver/replica_rangefeed.go:608  [n1,s1,r6/1:/Table/{SystemCon…-11}] RangeFeed closed timestamp is empty
I200606 09:14:49.738392 33520 sql/temporary_schema.go:508  [n1] found 0 temporary schemas
I200606 09:14:49.738986 33520 sql/temporary_schema.go:511  [n1] early exiting temporary schema cleaner as no temporary schemas were found
I200606 09:14:49.739357 33520 sql/temporary_schema.go:512  [n1] completed temporary object cleanup job
I200606 09:14:49.739679 33520 sql/temporary_schema.go:595  [n1] temporary object cleaner next scheduled to run at 2020-06-06 09:44:49.700417101 +0000 UTC
I200606 09:14:49.759646 33519 sql/event_log.go:132  [n1] Event: "node_join", target: 1, info: {Descriptor:{NodeID:1 Address:127.0.0.1:38639 Attrs: Locality: ServerVersion:20.1-7 BuildTag:v20.2.0-alpha.00000000-2059-gdfb6e1bee4 StartedAt:1591434889386021721 LocalityAddress:[] ClusterName: SQLAddress:127.0.0.1:42699} ClusterID:96396d6b-9cc2-40ec-a8a9-bd2a62dbe28b StartedAt:1591434889386021721 LastUp:1591434889386021721}
I200606 09:14:49.852157 33434 sql/event_log.go:132  [n1,intExec=optInToDiagnosticsStatReporting] Event: "set_cluster_setting", target: 0, info: {SettingName:diagnostics.reporting.enabled Value:true User:root}
I200606 09:14:49.944560 33518 server/server_update.go:55  [n1] no need to upgrade, cluster already at the newest version
I200606 09:14:49.976617 33556 sql/event_log.go:132  [n1,intExec=set-setting] Event: "set_cluster_setting", target: 0, info: {SettingName:version Value:20.1-7 User:root}
I200606 09:14:50.240393 33954 sql/event_log.go:132  [n1,intExec=initializeClusterSecret] Event: "set_cluster_setting", target: 0, info: {SettingName:cluster.secret Value:013a9de8-554e-411b-98e3-ea5c85a3d033 User:root}
I200606 09:14:50.353413 34048 sql/event_log.go:132  [n1,intExec=create-default-db] Event: "create_database", target: 50, info: {DatabaseName:defaultdb Statement:CREATE DATABASE IF NOT EXISTS defaultdb User:root}
I200606 09:14:50.443655 33973 sql/event_log.go:132  [n1,intExec=create-default-db] Event: "create_database", target: 51, info: {DatabaseName:postgres Statement:CREATE DATABASE IF NOT EXISTS postgres User:root}
I200606 09:14:50.746143 33039 server/server_sql.go:645  [n1] done ensuring all necessary migrations have run
I200606 09:14:50.746256 33039 server/server.go:1747  [n1] serving sql connections
I200606 09:14:50.746507 33039 server/server.go:1768  [n1] starting postgres server at unix:/tmp/TestAuth653709541/.s.PGSQL.6
I200606 09:14:50.759843 34137 sqlmigrations/migrations.go:727  [n1] starting wait for upgrade finalization before schema change job migration
I200606 09:14:50.761509 34137 sqlmigrations/migrations.go:759  [n1] starting schema change job migration
FAIL	github.com/cockroachdb/cockroach/pkg/sql/pgwire	96.503s
More

Parameters:

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

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

@knz
Copy link
Contributor

knz commented Jun 6, 2020

Here's the race:

WARNING: DATA RACE
Write at 0x000009584e70 by goroutine 138:
  github.com/cockroachdb/cockroach/pkg/util/log.redirectStderr()
      /data/home/kena/src/go/src/github.com/cockroachdb/cockroach/pkg/util/log/stderr_redirect_unix.go:53 +0x91
  github.com/cockroachdb/cockroach/pkg/util/log.hijackStderr()
      /data/home/kena/src/go/src/github.com/cockroachdb/cockroach/pkg/util/log/stderr_redirect.go:40 +0x126c
  github.com/cockroachdb/cockroach/pkg/util/log.(*syncBuffer).rotateFile()
      /data/home/kena/src/go/src/github.com/cockroachdb/cockroach/pkg/util/log/sync_buffer.go:104 +0x1247
  github.com/cockroachdb/cockroach/pkg/util/log.(*loggerT).createFile()
      /data/home/kena/src/go/src/github.com/cockroachdb/cockroach/pkg/util/log/sync_buffer.go:70 +0x13c
  github.com/cockroachdb/cockroach/pkg/util/log.(*loggerT).ensureFile()
      /data/home/kena/src/go/src/github.com/cockroachdb/cockroach/pkg/util/log/clog.go:202 +0x633
  github.com/cockroachdb/cockroach/pkg/util/log.(*loggerT).outputLogEntry()
      /data/home/kena/src/go/src/github.com/cockroachdb/cockroach/pkg/util/log/clog.go:320 +0x337
  github.com/cockroachdb/cockroach/pkg/util/log.addStructured()
      /data/home/kena/src/go/src/github.com/cockroachdb/cockroach/pkg/util/log/structured.go:68 +0x290
  github.com/cockroachdb/cockroach/pkg/util/log.logDepth()
      /data/home/kena/src/go/src/github.com/cockroachdb/cockroach/pkg/util/log/log.go:44 +0x99
  github.com/cockroachdb/cockroach/pkg/util/log.Info()
      /data/home/kena/src/go/src/github.com/cockroachdb/cockroach/pkg/util/log/log.go:85 +0xb4
  github.com/cockroachdb/cockroach/pkg/sqlmigrations.(*Manager).StartSchemaChangeJobMigration.func1()
      /data/home/kena/src/go/src/github.com/cockroachdb/cockroach/pkg/sqlmigrations/migrations.go:727 +0x5f
  github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunAsyncTask.func1()
      /data/home/kena/src/go/src/github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:323 +0x168

Previous write at 0x000009584e70 by goroutine 321:
  github.com/cockroachdb/cockroach/pkg/util/log.redirectStderr()
      /data/home/kena/src/go/src/github.com/cockroachdb/cockroach/pkg/util/log/stderr_redirect_unix.go:53 +0x91
  github.com/cockroachdb/cockroach/pkg/util/log.restoreStderr()
      /data/home/kena/src/go/src/github.com/cockroachdb/cockroach/pkg/util/log/stderr_redirect.go:45 +0x73
  github.com/cockroachdb/cockroach/pkg/util/log.(*loggerT).closeFileLocked()
      /data/home/kena/src/go/src/github.com/cockroachdb/cockroach/pkg/util/log/test_log_scope.go:209 +0x88
  github.com/cockroachdb/cockroach/pkg/util/log.(*loggerT).dirTestOverride()
      /data/home/kena/src/go/src/github.com/cockroachdb/cockroach/pkg/util/log/test_log_scope.go:197 +0x295
  github.com/cockroachdb/cockroach/pkg/util/log.dirTestOverride()
      /data/home/kena/src/go/src/github.com/cockroachdb/cockroach/pkg/util/log/test_log_scope.go:172 +0x19a
  github.com/cockroachdb/cockroach/pkg/util/log.ScopeWithoutShowLogs()
      /data/home/kena/src/go/src/github.com/cockroachdb/cockroach/pkg/util/log/test_log_scope.go:69 +0x1ae
  github.com/cockroachdb/cockroach/pkg/sql/pgwire_test.hbaRunTest.func1()
      /data/home/kena/src/go/src/github.com/cockroachdb/cockroach/pkg/sql/pgwire/auth_test.go:160 +0x2a9
  github.com/cockroachdb/cockroach/vendor/github.com/cockroachdb/datadriven.Walk()
      /data/home/kena/src/go/src/github.com/cockroachdb/cockroach/vendor/github.com/cockroachdb/datadriven/datadriven.go:366 +0x55f
  github.com/cockroachdb/cockroach/vendor/github.com/cockroachdb/datadriven.Walk.func1()
      /data/home/kena/src/go/src/github.com/cockroachdb/cockroach/vendor/github.com/cockroachdb/datadriven/datadriven.go:379 +0xff
  testing.tRunner()
      /usr/local/go/src/testing/testing.go:991 +0x1eb

that's for me to fix

@knz knz mentioned this issue Jun 6, 2020
Merged
@craig craig bot closed this as completed in f4a9f52 Jun 6, 2020
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@knz knz

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
20.2
Development

Successfully merging a pull request may close this issue.

log: add a mutex for stderr redirection knz/cockroach
2 participants
@knz @cockroach-teamcity