------- Stdout: -------
=== RUN   TestDirectoryConnect/drain_connection
I210709 02:16:09.314625 8563 ccl/sqlproxyccl/proxy_handler.go:385  [client=127.0.0.1:56960,cluster=tenant-cluster,tenant=28] 505  new connection
I210709 02:16:09.324338 8570 sql/catalog/lease/lease.go:1113  [-] 506  released orphaned lease: {id:33 version:1 expiration:{Time:{wall:686484000 ext:63761394074 loc:<nil>}}}
I210709 02:16:09.325606 8566 sql/catalog/lease/lease.go:1113  [-] 507  released orphaned lease: {id:4 version:1 expiration:{Time:{wall:246870000 ext:63761394072 loc:<nil>}}}
I210709 02:16:09.325762 8567 sql/catalog/lease/lease.go:1113  [-] 508  released orphaned lease: {id:12 version:1 expiration:{Time:{wall:610912000 ext:63761394064 loc:<nil>}}}
I210709 02:16:09.326159 8569 sql/catalog/lease/lease.go:1113  [-] 509  released orphaned lease: {id:23 version:1 expiration:{Time:{wall:760855000 ext:63761394071 loc:<nil>}}}
I210709 02:16:09.342513 8568 sql/catalog/lease/lease.go:1113  [-] 510  released orphaned lease: {id:15 version:1 expiration:{Time:{wall:529705000 ext:63761394053 loc:<nil>}}}
I210709 02:16:10.046458 7988 ccl/sqlproxyccl/tenant/directory.go:327  [-] 511  established watch on pods
    proxy_handler_test.go:621: 
        	Error Trace:	proxy_handler_test.go:621
        	            				proxy_handler_test.go:921
        	Error:      	An error is expected but got nil.
        	Test:       	TestDirectoryConnect/drain_connection
I210709 02:16:10.319246 7988 ccl/sqlproxyccl/tenant/directory.go:327  [-] 512  established watch on pods
W210709 02:16:10.325747 8489 jobs/registry.go:664  [-] 513  canceling all adopted jobs due to stopper quiescing
W210709 02:16:10.326089 8454 ccl/kvccl/kvtenantccl/connector.go:159  [sql,tenant-connector] 514  error consuming GossipSubscription RPC: rpc error: code = Canceled desc = context canceled
I210709 02:16:10.326384 8563 ccl/sqlproxyccl/proxy_handler.go:388  [client=127.0.0.1:56960,cluster=tenant-cluster,tenant=28] 515  closing after 1.01s
W210709 02:16:10.331097 6964 sql/sqlliveness/slinstance/slinstance.go:183  [n1] 516  exiting heartbeat loop
W210709 02:16:10.331468 6965 jobs/registry.go:664  [-] 517  canceling all adopted jobs due to stopper quiescing
    --- FAIL: TestDirectoryConnect/drain_connection (1.01s)

------- Stdout: -------
=== RUN   TestDirectoryConnect
I210709 02:16:06.222958 6026 server/testserver.go:124  [-] 388  test Config is randomly setting enabledSeparated: false
I210709 02:16:06.224160 6026 3@vendor/github.com/cockroachdb/pebble/version_set.go:156  [n?,pebble,s?] 389  [JOB 1] MANIFEST created 000001
I210709 02:16:06.225176 6026 3@vendor/github.com/cockroachdb/pebble/open.go:305  [n?,pebble,s?] 390  [JOB 1] WAL created 000002
I210709 02:16:06.226032 6026 server/config.go:564  [n?] 391  1 storage engine initialized
I210709 02:16:06.227314 6026 server/config.go:567  [n?] 393  Pebble cache size: 128 MiB
I210709 02:16:06.227584 6026 server/config.go:567  [n?] 394  store 0: in-memory, size 512 MiB
I210709 02:16:06.226877 6630 3@vendor/github.com/cockroachdb/pebble/table_stats.go:118  [n?,pebble,s?] 392  [JOB 2] all initial table stats loaded
W210709 02:16:06.228439 6026 server/status/runtime.go:318  [n?] 395  could not parse build timestamp: parsing time "" as "2006/01/02 15:04:05": cannot parse "" as "2006"
I210709 02:16:06.232608 6026 3@vendor/github.com/cockroachdb/pebble/version_set.go:156  [n?,pebble,s?] 396  [JOB 1] MANIFEST created 000001
I210709 02:16:06.232940 6026 3@vendor/github.com/cockroachdb/pebble/open.go:305  [n?,pebble,s?] 397  [JOB 1] WAL created 000002
I210709 02:16:06.233528 6661 3@vendor/github.com/cockroachdb/pebble/table_stats.go:118  [n?,pebble,stemp] 398  [JOB 2] all initial table stats loaded
I210709 02:16:06.416924 6026 1@server/server.go:957  [n?] 399  monitoring forward clock jumps based on server.clock.forward_jump_check_enabled
I210709 02:16:06.428533 6026 server/init.go:196  [n?] 400  no stores initialized
I210709 02:16:06.428619 6026 server/init.go:197  [n?] 401  awaiting `cockroach init` or join with an already initialized node
I210709 02:16:06.428655 6026 server/init.go:261  [n?] 402  cluster a7cafb69-b36c-4f57-8ff5-be01338a3592 has been created
I210709 02:16:06.428714 6026 server/init.go:262  [n?] 403  allocated node ID: n1 (for self)
I210709 02:16:06.428741 6026 server/init.go:263  [n?] 404  active cluster version: 21.1-116
I210709 02:16:06.428862 6026 gossip/gossip.go:402  [n1] 406  NodeDescriptor set to node_id:1 address:<network_field:"tcp" address_field:"127.8.92.27:45063" > attrs:<> locality:<> ServerVersion:<major_val:21 minor_val:1 patch:0 internal:116 > build_tag:"v21.2.0-alpha.00000000-2180-g5826528850" started_at:1625796966428856368 cluster_name:"" sql_address:<network_field:"tcp" address_field:"127.8.92.27:45325" >
I210709 02:16:06.428886 6697 1@server/server.go:1596  [n1] 405  connecting to gossip network to verify cluster ID "a7cafb69-b36c-4f57-8ff5-be01338a3592"
I210709 02:16:06.430373 6701 kv/kvserver/closedts/provider/provider.go:135  [ct-closer] 407  disabling legacy closed-timestamp mechanism; the new one is enabled
I210709 02:16:06.470048 6697 1@server/server.go:1599  [n1] 409  node connected via gossip
I210709 02:16:06.468632 6026 server/node.go:392  [n1] 408  initialized store s1
I210709 02:16:06.473609 6026 kv/kvserver/stores.go:250  [n1] 410  read 0 node addresses from persistent storage
I210709 02:16:06.473818 6026 server/node.go:469  [n1] 411  started with engine type 2
I210709 02:16:06.473913 6026 server/node.go:471  [n1] 412  started with attributes []
I210709 02:16:06.474664 6026 1@server/server.go:1723  [n1] 413  starting http server at 127.8.92.27:35621 (use: 127.8.92.27:35621)
I210709 02:16:06.474924 6026 1@server/server.go:1728  [n1] 414  starting postgres server at 127.8.92.27:45325 (use: 127.8.92.27:45325)
I210709 02:16:06.475231 6026 1@server/server.go:1730  [n1] 415  starting grpc server at 127.8.92.27:45063
I210709 02:16:06.475295 6026 1@server/server.go:1731  [n1] 416  advertising CockroachDB node at 127.8.92.27:45063
I210709 02:16:06.534995 6026 1@util/log/event_log.go:32  [n1] 417 ={"Timestamp":1625796966534992443,"EventType":"node_join","NodeID":1,"StartedAt":1625796966428856368,"LastUp":1625796966428856368}
I210709 02:16:06.535162 6026 sql/sqlliveness/slinstance/slinstance.go:252  [n1] 418  starting SQL liveness instance
I210709 02:16:06.538031 6975 kv/kvserver/replica_rangefeed.go:619  [n1,rangefeed=lease,s1,r6/1:/Table/{SystemCon…-11}] 419  RangeFeed closed timestamp is empty
I210709 02:16:06.538454 6873 sql/temporary_schema.go:492  [n1] 420  running temporary object cleanup background job
I210709 02:16:06.539243 6964 sql/sqlliveness/slstorage/slstorage.go:386  [n1] 421  inserted sqlliveness session 246a1c26b6c14a7cb52032f93ac5a8d1
I210709 02:16:06.539293 6964 sql/sqlliveness/slinstance/slinstance.go:144  [n1] 422  created new SQL liveness session 246a1c26b6c14a7cb52032f93ac5a8d1
W210709 02:16:06.543596 6637 kv/range_lookup.go:243  [n1,rangefeed=table-stats-cache,range-lookup=/Meta2/Table/20/NULL] 423  range lookup of key /Meta2/Table/20/NULL found only non-matching ranges []; retrying
W210709 02:16:06.545207 6636 kv/range_lookup.go:243  [n1,rangefeed=table-stats-cache,range-lookup=/Table/20] 424  range lookup of key /Table/20 found only non-matching ranges []; retrying
I210709 02:16:06.558759 6873 sql/temporary_schema.go:529  [n1] 425  found 0 temporary schemas
I210709 02:16:06.558890 6873 sql/temporary_schema.go:532  [n1] 426  early exiting temporary schema cleaner as no temporary schemas were found
I210709 02:16:06.558940 6873 sql/temporary_schema.go:533  [n1] 427  completed temporary object cleanup job
I210709 02:16:06.558970 6873 sql/temporary_schema.go:612  [n1] 428  temporary object cleaner next scheduled to run at 2021-07-09 02:46:06.538421379 +0000 UTC
I210709 02:16:06.567167 7090 util/log/event_log.go:32  [n1,intExec=optInToDiagnosticsStatReporting] 429 ={"Timestamp":1625796966559757903,"EventType":"set_cluster_setting","Statement":"SET CLUSTER SETTING \"diagnostics.reporting.enabled\" = true","Tag":"SET CLUSTER SETTING","User":"root","ApplicationName":"$ internal-optInToDiagnosticsStatReporting","SettingName":"diagnostics.reporting.enabled","Value":"true"}
I210709 02:16:06.594288 7174 migration/migrationmanager/manager.go:102  [n1,intExec=set-setting,migration-mgr] 430  no need to migrate, cluster already at newest version
I210709 02:16:06.601489 7174 util/log/event_log.go:32  [n1,intExec=set-setting] 431 ={"Timestamp":1625796966589974890,"EventType":"set_cluster_setting","Statement":"SET CLUSTER SETTING version = $1","Tag":"SET CLUSTER SETTING","User":"root","ApplicationName":"$ internal-set-setting","PlaceholderValues":["'21.1-116'"],"SettingName":"version","Value":"21.1-116"}
I210709 02:16:06.627871 7352 util/log/event_log.go:32  [n1,intExec=initializeClusterSecret] 432 ={"Timestamp":1625796966618892776,"EventType":"set_cluster_setting","Statement":"SET CLUSTER SETTING \"cluster.secret\" = gen_random_uuid()::STRING","Tag":"SET CLUSTER SETTING","User":"root","ApplicationName":"$ internal-initializeClusterSecret","SettingName":"cluster.secret","Value":"9cf9bf7c-7786-4d47-a9ec-f2d523c926d6"}
I210709 02:16:06.660291 7334 5@util/log/event_log.go:32  [n1,intExec=create-default-DB] 433 ={"Timestamp":1625796966630430682,"EventType":"create_database","Statement":"CREATE DATABASE IF NOT EXISTS defaultdb","Tag":"CREATE DATABASE","User":"root","DescriptorID":50,"ApplicationName":"$ internal-create-default-DB","DatabaseName":"defaultdb"}
I210709 02:16:06.671940 7595 5@util/log/event_log.go:32  [n1,intExec=create-default-DB] 434 ={"Timestamp":1625796966661257517,"EventType":"create_database","Statement":"CREATE DATABASE IF NOT EXISTS postgres","Tag":"CREATE DATABASE","User":"root","DescriptorID":51,"ApplicationName":"$ internal-create-default-DB","DatabaseName":"postgres"}
I210709 02:16:06.696651 6026 server/server_sql.go:922  [n1] 435  done ensuring all necessary startup migrations have run
I210709 02:16:06.696934 7782 jobs/job_scheduler.go:360  [n1] 436  waiting 4m0s before scheduled jobs daemon start
I210709 02:16:06.705798 7784 server/auto_upgrade.go:55  [n1] 437  no need to upgrade, cluster already at the newest version
I210709 02:16:06.725803 6709 3@vendor/github.com/cockroachdb/pebble/db.go:1530  [n1,pebble,s1] 438  [JOB 3] WAL created 000004
I210709 02:16:06.728600 6026 1@server/server.go:2260  [n1] 439  serving sql connections
I210709 02:16:06.736925 7815 kv/kvserver/replica_command.go:396  [n1,s1,r39/1:/{Table/43-Max}] 440  initiating a split of this range at key /Tenant/28 [r40] (manual)
I210709 02:16:07.773429 7988 ccl/sqlproxyccl/tenant/directory.go:327  [-] 441  established watch on pods
--- FAIL: TestDirectoryConnect (5.14s)