I211103 06:58:48.502514 80716 server/node.go:499  [n1] 95  started with engine type 2
I211103 06:58:48.502630 80716 server/node.go:501  [n1] 96  started with attributes []
I211103 06:58:48.502916 80716 1@server/server.go:1688  [n1] 97  starting https server at 127.0.0.1:38519 (use: 127.0.0.1:38519)
I211103 06:58:48.503060 80716 1@server/server.go:1693  [n1] 98  starting postgres server at 127.0.0.1:44539 (use: 127.0.0.1:44539)
I211103 06:58:48.503239 80716 1@server/server.go:1695  [n1] 99  starting grpc server at 127.0.0.1:35863
I211103 06:58:48.503301 80716 1@server/server.go:1696  [n1] 100  advertising CockroachDB node at 127.0.0.1:35863
W211103 06:58:48.528490 82971 kv/range_lookup.go:243  [n1,rangefeed=table-stats-cache,range-lookup=/Meta2/Table/20/NULL] 101  range lookup of key /Meta2/Table/20/NULL found only non-matching ranges []; retrying
W211103 06:58:48.537519 82966 kv/range_lookup.go:243  [n1,rangefeed=table-stats-cache,range-lookup=/Table/20] 102  range lookup of key /Table/20 found only non-matching ranges []; retrying
I211103 06:58:48.559428 80716 1@util/log/event_log.go:32  [n1] 103 ={"Timestamp":1635922728559406002,"EventType":"node_join","NodeID":1,"StartedAt":1635922728486479793,"LastUp":1635922728486479793}
I211103 06:58:48.559567 80716 sql/sqlliveness/slinstance/slinstance.go:296  [n1] 104  starting SQL liveness instance
I211103 06:58:48.564413 86822 sql/sqlliveness/slstorage/slstorage.go:397  [n1] 105  inserted sqlliveness session c06b7258ad28434782a8d33169c0c71e
I211103 06:58:48.564505 86822 sql/sqlliveness/slinstance/slinstance.go:183  [n1] 106  created new SQL liveness session c06b7258ad28434782a8d33169c0c71e
I211103 06:58:48.565300 88375 sql/temporary_schema.go:508  [n1] 107  running temporary object cleanup background job
I211103 06:58:48.565478 88447 sql/sqlstats/persistedsqlstats/provider.go:138  [n1] 108  starting sql-stats-worker with initial delay: 51m36.213603679s
I211103 06:58:48.567318 88375 sql/temporary_schema.go:552  [n1] 109  found 0 temporary schemas
I211103 06:58:48.567557 88375 sql/temporary_schema.go:555  [n1] 110  early exiting temporary schema cleaner as no temporary schemas were found
I211103 06:58:48.567618 88375 sql/temporary_schema.go:556  [n1] 111  completed temporary object cleanup job
I211103 06:58:48.567662 88375 sql/temporary_schema.go:639  [n1] 112  temporary object cleaner next scheduled to run at 2021-11-03 07:28:48.565221589 +0000 UTC
I211103 06:58:48.596303 86077 kv/kvserver/replica_rangefeed.go:657  [n1,rangefeed=table-stats-cache,s1,r16/1:/Table/2{0-1}] 113  RangeFeed closed timestamp is empty
I211103 06:58:48.716603 96987 util/log/event_log.go:32  [n1,intExec=optInToDiagnosticsStatReporting] 114 ={"Timestamp":1635922728637506968,"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"}
I211103 06:58:48.738474 104005 migration/migrationmanager/manager.go:110  [n1,intExec=set-setting,migration-mgr] 115  no need to migrate, cluster already at newest version
I211103 06:58:48.746536 104005 util/log/event_log.go:32  [n1,intExec=set-setting] 116 ={"Timestamp":1635922728731265764,"EventType":"set_cluster_setting","Statement":"SET CLUSTER SETTING version = $1","Tag":"SET CLUSTER SETTING","User":"root","ApplicationName":"$ internal-set-setting","PlaceholderValues":["'21.2-4'"],"SettingName":"version","Value":"21.2-4"}
I211103 06:58:48.816724 113922 util/log/event_log.go:32  [n1,intExec=initializeClusterSecret] 117 ={"Timestamp":1635922728803267470,"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":"0eded450-76a5-4bf4-a902-fa4525cdf2da"}
I211103 06:58:48.850557 116656 5@util/log/event_log.go:32  [n1,intExec=create-default-DB] 118 ={"Timestamp":1635922728823368620,"EventType":"create_database","Statement":"CREATE DATABASE IF NOT EXISTS defaultdb","Tag":"CREATE DATABASE","User":"root","DescriptorID":50,"ApplicationName":"$ internal-create-default-DB","DatabaseName":"defaultdb"}
I211103 06:58:48.865625 84555 3@vendor/github.com/cockroachdb/pebble/event.go:664  [n1,pebble,s1] 119  [JOB 3] WAL created 000004
I211103 06:58:48.872027 119234 5@util/log/event_log.go:32  [n1,intExec=create-default-DB] 120 ={"Timestamp":1635922728851472927,"EventType":"create_database","Statement":"CREATE DATABASE IF NOT EXISTS postgres","Tag":"CREATE DATABASE","User":"root","DescriptorID":51,"ApplicationName":"$ internal-create-default-DB","DatabaseName":"postgres"}
I211103 06:58:48.943720 80716 server/server_sql.go:1107  [n1] 121  done ensuring all necessary startup migrations have run
I211103 06:58:48.944409 129368 jobs/job_scheduler.go:357  [n1] 122  waiting 2m0s before scheduled jobs daemon start
I211103 06:58:48.957614 129374 server/auto_upgrade.go:55  [n1] 123  no need to upgrade, cluster already at the newest version
I211103 06:58:48.979904 80716 1@server/server.go:2345  [n1] 124  serving sql connections
I211103 06:58:48.980826 80716 testutils/testcluster/testcluster.go:1158  [-] 125  WaitForFullReplication
I211103 06:58:48.980885 80716 testutils/testcluster/testcluster.go:1162  [-] 126  WaitForFullReplication took: 418ns
I211103 06:58:48.980996 80716 2@rpc/context.go:1045  [n1] 127  dialing n1: 127.0.0.1:35863 (default)
I211103 06:58:49.026505 131028 util/log/event_log.go:32  [n1,client=127.0.0.1:43198,hostssl,user=root] 128 ={"Timestamp":1635922729010680047,"EventType":"set_cluster_setting","Statement":"SET CLUSTER SETTING \"kv.protectedts.reconciliation.interval\" = '1ms'","Tag":"SET CLUSTER SETTING","User":"root","SettingName":"kv.protectedts.reconciliation.interval","Value":"00:00:00.001"}
    jobs_protected_ts_test.go:203: 
        	Error Trace:	jobs_protected_ts_test.go:203
        	Error:      	Not equal: 
        	            	expected: 1
        	            	actual  : 0
        	Test:       	TestSchedulesProtectedTimestamp
I211103 06:58:49.132727 80716 testutils/testcluster/testcluster.go:106  [-] 129  TestCluster quiescing nodes
I211103 06:58:49.132929 81283 2@rpc/context.go:688  [n1] 130  closing [{n1: 127.0.0.1:35863 (default)}]
W211103 06:58:49.133057 86822 sql/sqlliveness/slinstance/slinstance.go:220  [n1] 131  exiting heartbeat loop
I211103 06:58:49.133173 81283 2@rpc/context.go:688  [n1] 132  closing [{n0: 127.0.0.1:35863 (default)}]
I211103 06:58:49.133115 130760 2@rpc/context.go:688  [n1] 133  closing [{n1: 127.0.0.1:35863 (default)} {n0: 127.0.0.1:35863 (default)}]
W211103 06:58:49.133224 96046 jobs/registry.go:840  [-] 134  canceling all adopted jobs due to stopper quiescing
W211103 06:58:49.133286 141992 kv/kvserver/intentresolver/intent_resolver.go:790  [-] 135  failed to gc transaction record: could not GC completed transaction anchored at /Table/37/1/707304911934783489/0: node unavailable; try another peer
W211103 06:58:49.137776 86738 kv/txn.go:693  [n1] 136  failure aborting transaction: failed to send RPC: sending to all replicas failed; last error: node unavailable; try another peer; abort caused by: failed to release record 1d853d6d-1d82-4751-837b-5b576f31c2a8: protectedts-Release: failed to send RPC: sending to all replicas failed; last error: node unavailable; try another peer
E211103 06:58:49.137899 86738 kv/kvserver/protectedts/ptreconcile/reconciler.go:179  [n1] 137  failed to reconcile protected timestamp with id 1d853d6d-1d82-4751-837b-5b576f31c2a8: failed to release record 1d853d6d-1d82-4751-837b-5b576f31c2a8: protectedts-Release: failed to send RPC: sending to all replicas failed; last error: node unavailable; try another peer
--- FAIL: TestSchedulesProtectedTimestamp (0.74s)