Skip to content

Instantly share code, notes, and snippets.

@andrewbaptist

andrewbaptist/r53.log Secret

Created September 8, 2022 13:48
Show Gist options
  • Save andrewbaptist/b4dc8e7303c6894f14bfc462e0a6169c to your computer and use it in GitHub Desktop.
Save andrewbaptist/b4dc8e7303c6894f14bfc462e0a6169c to your computer and use it in GitHub Desktop.
Download ZIP
Raw
r53.log
I220908 12:59:11.476301 12 kv/kvserver/replica_command.go:416 [n1,s1,r52/1:/{Table/52-Max},*roachpb.AdminSplitRequest] 648 initiating a split of this range at key /Table/Max [r53] (manual)
I220908 12:59:11.498465 734 go.etcd.io/etcd/raft/v3/raft.go:1651 [n1,s1,r53/1:/{Table/Max-Max}] 665 1 switched to configuration voters=(1)
I220908 12:59:11.498505 734 go.etcd.io/etcd/raft/v3/raft.go:680 [n1,s1,r53/1:/{Table/Max-Max}] 666 1 became follower at term 5
I220908 12:59:11.498543 734 go.etcd.io/etcd/raft/v3/raft.go:361 [n1,s1,r53/1:/{Table/Max-Max}] 667 newRaft 1 [peers: [1], term: 5, commit: 10, applied: 10, lastindex: 10, lastterm: 5]
I220908 12:59:11.498564 734 go.etcd.io/etcd/raft/v3/raft.go:767 [n1,s1,r53/1:/{Table/Max-Max}] 668 1 is starting a new election at term 5
I220908 12:59:11.498574 734 go.etcd.io/etcd/raft/v3/raft.go:709 [n1,s1,r53/1:/{Table/Max-Max}] 669 1 became pre-candidate at term 5
I220908 12:59:11.498583 734 go.etcd.io/etcd/raft/v3/raft.go:827 [n1,s1,r53/1:/{Table/Max-Max}] 670 1 received MsgPreVoteResp from 1 at term 5
I220908 12:59:11.498596 734 go.etcd.io/etcd/raft/v3/raft.go:693 [n1,s1,r53/1:/{Table/Max-Max}] 671 1 became candidate at term 6
I220908 12:59:11.498604 734 go.etcd.io/etcd/raft/v3/raft.go:827 [n1,s1,r53/1:/{Table/Max-Max}] 672 1 received MsgVoteResp from 1 at term 6
I220908 12:59:11.498620 734 go.etcd.io/etcd/raft/v3/raft.go:745 [n1,s1,r53/1:/{Table/Max-Max}] 673 1 became leader at term 6
I220908 12:59:11.498799 734 kv/kvserver/raft.go:185 [n1,s1,r53/1:/{Table/Max-Max},raft] 674 raft ready (must-sync=true)
I220908 12:59:11.498799 734 kv/kvserver/raft.go:185 [n1,s1,r53/1:/{Table/Max-Max},raft] 674 + SoftState updated: {Lead:1 RaftState:StateLeader}
I220908 12:59:11.498799 734 kv/kvserver/raft.go:185 [n1,s1,r53/1:/{Table/Max-Max},raft] 674 + HardState updated: {Term:6 Vote:1 Commit:12}
I220908 12:59:11.498799 734 kv/kvserver/raft.go:185 [n1,s1,r53/1:/{Table/Max-Max},raft] 674 + New Entry[0]: 6/11 EntryNormal [empty]
I220908 12:59:11.498799 734 kv/kvserver/raft.go:185 [n1,s1,r53/1:/{Table/Max-Max},raft] 674 + New Entry[1]: 6/12 EntryNormal [225c61505c7865375c7830365c7862355e5c7866322122] [9]
I220908 12:59:11.498799 734 kv/kvserver/raft.go:185 [n1,s1,r53/1:/{Table/Max-Max},raft] 674 + Committed Entry[0]: 6/11 EntryNormal [empty]
I220908 12:59:11.498799 734 kv/kvserver/raft.go:185 [n1,s1,r53/1:/{Table/Max-Max},raft] 674 + Committed Entry[1]: 6/12 EntryNormal [225c61505c7865375c7830365c7862355e5c7866322122] [9]
I220908 12:59:11.505783 12 13@kv/kvserver/replica_command.go:2319 [n1,s1,r53/1:/{Table/Max-Max},*roachpb.AdminChangeReplicasRequest] 677 change replicas (add [(n3,s3):2LEARNER] remove []): existing descriptor r53:/{Table/Max-Max} [(n1,s1):1, next=2, gen=1, sticky=9223372036.854775807,2147483647]
I220908 12:59:11.506525 747 kv/kvserver/raft.go:185 [n1,s1,r53/1:/{Table/Max-Max},raft] 678 raft ready (must-sync=true)
I220908 12:59:11.506525 747 kv/kvserver/raft.go:185 [n1,s1,r53/1:/{Table/Max-Max},raft] 678 + HardState updated: {Term:6 Vote:1 Commit:13}
I220908 12:59:11.506525 747 kv/kvserver/raft.go:185 [n1,s1,r53/1:/{Table/Max-Max},raft] 678 + New Entry[0]: 6/13 EntryNormal [225c7831395c7865365c783161785c786630695c7862375c78646322] [277]
I220908 12:59:11.506525 747 kv/kvserver/raft.go:185 [n1,s1,r53/1:/{Table/Max-Max},raft] 678 + Committed Entry[0]: 6/13 EntryNormal [225c7831395c7865365c783161785c786630695c7862375c78646322] [277]
I220908 12:59:11.510100 12 13@kv/kvserver/replica_raft.go:346 [n1,s1,r53/1:/{Table/Max-Max}] 681 proposing SIMPLE(l2) [(n3,s3):2LEARNER]: after=[(n1,s1):1 (n3,s3):2LEARNER] next=3
I220908 12:59:11.510402 738 kv/kvserver/raft.go:185 [n1,s1,r53/1:/{Table/Max-Max},raft] 682 raft ready (must-sync=true)
I220908 12:59:11.510402 738 kv/kvserver/raft.go:185 [n1,s1,r53/1:/{Table/Max-Max},raft] 682 + HardState updated: {Term:6 Vote:1 Commit:14}
I220908 12:59:11.510402 738 kv/kvserver/raft.go:185 [n1,s1,r53/1:/{Table/Max-Max},raft] 682 + New Entry[0]: 6/14 EntryConfChange l2
I220908 12:59:11.510402 738 kv/kvserver/raft.go:185 [n1,s1,r53/1:/{Table/Max-Max},raft] 682 + Committed Entry[0]: 6/14 EntryConfChange l2
I220908 12:59:11.510604 738 go.etcd.io/etcd/raft/v3/raft.go:1651 [n1,s1,r53/1:/{Table/Max-Max}] 683 1 switched to configuration voters=(1) learners=(2)
I220908 12:59:11.510680 738 kv/kvserver/raft.go:185 [n1,s1,r53/1:/{Table/Max-Max},raft] 684 raft ready (must-sync=false)
I220908 12:59:11.510680 738 kv/kvserver/raft.go:185 [n1,s1,r53/1:/{Table/Max-Max},raft] 684 + Outgoing Message[0]: 1->2 MsgApp Term:6 Log:6/13 Commit:14 Entries:[6/14 EntryConfChange l2]
I220908 12:59:11.533655 1974 kv/kvserver/store_raft.go:351 [n3,s3,r53/2:{-},raft] 688 incoming raft message:
I220908 12:59:11.533655 1974 kv/kvserver/store_raft.go:351 [n3,s3,r53/2:{-},raft] 688 +1->2 MsgApp Term:6 Log:6/13 Commit:14 Entries:[6/14 EntryConfChange l2]
I220908 12:59:11.533706 1974 go.etcd.io/etcd/raft/v3/raft.go:1651 [n3,s3,r53/2:{-}] 689 2 switched to configuration voters=()
I220908 12:59:11.533735 1974 go.etcd.io/etcd/raft/v3/raft.go:680 [n3,s3,r53/2:{-}] 690 2 became follower at term 0
I220908 12:59:11.533761 1974 go.etcd.io/etcd/raft/v3/raft.go:361 [n3,s3,r53/2:{-}] 691 newRaft 2 [peers: [], term: 0, commit: 0, applied: 0, lastindex: 0, lastterm: 0]
I220908 12:59:11.533783 1974 go.etcd.io/etcd/raft/v3/raft.go:862 [n3,s3,r53/2:{-}] 692 2 [term: 0] received a MsgApp message with higher term from 1 [term: 6]
I220908 12:59:11.533812 1974 go.etcd.io/etcd/raft/v3/raft.go:680 [n3,s3,r53/2:{-}] 693 2 became follower at term 6
I220908 12:59:11.533828 1974 go.etcd.io/etcd/raft/v3/raft.go:1480 [n3,s3,r53/2:{-}] 694 2 [logterm: 0, index: 13] rejected MsgApp [logterm: 6, index: 13] from 1
I220908 12:59:11.533900 1974 kv/kvserver/raft.go:185 [n3,s3,r53/2:{-},raft] 695 raft ready (must-sync=true)
I220908 12:59:11.533900 1974 kv/kvserver/raft.go:185 [n3,s3,r53/2:{-},raft] 695 + SoftState updated: {Lead:1 RaftState:StateFollower}
I220908 12:59:11.533900 1974 kv/kvserver/raft.go:185 [n3,s3,r53/2:{-},raft] 695 + HardState updated: {Term:6 Vote:0 Commit:0}
I220908 12:59:11.533900 1974 kv/kvserver/raft.go:185 [n3,s3,r53/2:{-},raft] 695 + Outgoing Message[0]: 2->1 MsgAppResp Term:6 Log:0/13 Rejected (Hint: 0)
I220908 12:59:11.534358 2316 13@kv/kvserver/store_snapshot.go:1569 [n1,s1,r53/1:/{Table/Max-Max}] 696 streamed INITIAL snapshot 57c8fce3 at applied index 14 to (n3,s3):2LEARNER with 680 B in 0.00s @ 6.7 MiB/s: kvs=8 rangeKVs=0, rate-limit: 32 MiB/s, queued: 0.00s
I220908 12:59:11.534861 2319 go.etcd.io/etcd/raft/v3/log.go:334 [n3,s3,r53/2:{-}] 697 log [committed=0, applied=0, unstable.offset=1, len(unstable.Entries)=0] starts to restore snapshot [index: 14, term: 6]
I220908 12:59:11.534918 2319 go.etcd.io/etcd/raft/v3/raft.go:1651 [n3,s3,r53/2:{-}] 698 2 switched to configuration voters=(1) learners=(2)
I220908 12:59:11.534949 2319 go.etcd.io/etcd/raft/v3/raft.go:1607 [n3,s3,r53/2:{-}] 699 2 [commit: 14, lastindex: 14, lastterm: 6] restored snapshot [index: 14, term: 6]
I220908 12:59:11.534972 2319 go.etcd.io/etcd/raft/v3/raft.go:1517 [n3,s3,r53/2:{-}] 700 2 [commit: 14] restored snapshot [index: 14, term: 6]
I220908 12:59:11.535006 2319 kv/kvserver/raft.go:185 [n3,s3,r53/2:{-}] 701 raft ready (must-sync=false)
I220908 12:59:11.535006 2319 kv/kvserver/raft.go:185 [n3,s3,r53/2:{-}] 701 + HardState updated: {Term:6 Vote:0 Commit:14}
I220908 12:59:11.535006 2319 kv/kvserver/raft.go:185 [n3,s3,r53/2:{-}] 701 + Snapshot updated: {[] {{[1] [2] [] [] false} 14 6}}
I220908 12:59:11.535006 2319 kv/kvserver/raft.go:185 [n3,s3,r53/2:{-}] 701 + Outgoing Message[0]: 2->1 MsgAppResp Term:6 Log:0/14
I220908 12:59:11.535035 2319 13@kv/kvserver/replica_raftstorage.go:877 [n3,s3,r53/2:{-}] 702 applying INITIAL snapshot 57c8fce3 from (n1,s1):1 at applied index 14
I220908 12:59:11.536784 2319 kv/kvserver/replica_raftstorage.go:888 [n3,s3,r53/2:/{Table/Max-Max}] 716 applied INITIAL snapshot 57c8fce3 from (n1,s1):1 at applied index 14 (total=2ms data=749 B ingestion=6@1ms)
I220908 12:59:11.538800 12 13@kv/kvserver/replica_command.go:2319 [n1,s1,r53/1:/{Table/Max-Max},*roachpb.AdminChangeReplicasRequest] 731 change replicas (add [(n3,s3):2] remove []): existing descriptor r53:/{Table/Max-Max} [(n1,s1):1, (n3,s3):2LEARNER, next=3, gen=2, sticky=9223372036.854775807,2147483647]
I220908 12:59:11.542303 743 kv/kvserver/raft.go:185 [n1,s1,r53/1:/{Table/Max-Max},raft] 732 raft ready (must-sync=true)
I220908 12:59:11.542303 743 kv/kvserver/raft.go:185 [n1,s1,r53/1:/{Table/Max-Max},raft] 732 + HardState updated: {Term:6 Vote:1 Commit:15}
I220908 12:59:11.542303 743 kv/kvserver/raft.go:185 [n1,s1,r53/1:/{Table/Max-Max},raft] 732 + New Entry[0]: 6/15 EntryNormal [225c665c7830345c786264305c7838655c7837665c7862625c78623522] [277]
I220908 12:59:11.542303 743 kv/kvserver/raft.go:185 [n1,s1,r53/1:/{Table/Max-Max},raft] 732 + Committed Entry[0]: 6/15 EntryNormal [225c665c7830345c786264305c7838655c7837665c7862625c78623522] [277]
I220908 12:59:11.543328 12 13@kv/kvserver/replica_raft.go:346 [n1,s1,r53/1:/{Table/Max-Max}] 735 proposing SIMPLE(v2) [(n3,s3):2]: after=[(n1,s1):1 (n3,s3):2] next=3
I220908 12:59:11.543607 744 kv/kvserver/raft.go:185 [n1,s1,r53/1:/{Table/Max-Max},raft] 736 raft ready (must-sync=true)
I220908 12:59:11.543607 744 kv/kvserver/raft.go:185 [n1,s1,r53/1:/{Table/Max-Max},raft] 736 + HardState updated: {Term:6 Vote:1 Commit:16}
I220908 12:59:11.543607 744 kv/kvserver/raft.go:185 [n1,s1,r53/1:/{Table/Max-Max},raft] 736 + New Entry[0]: 6/16 EntryConfChange v2
I220908 12:59:11.543607 744 kv/kvserver/raft.go:185 [n1,s1,r53/1:/{Table/Max-Max},raft] 736 + Committed Entry[0]: 6/16 EntryConfChange v2
I220908 12:59:11.543796 744 go.etcd.io/etcd/raft/v3/raft.go:1651 [n1,s1,r53/1:/{Table/Max-Max}] 737 1 switched to configuration voters=(1 2)
I220908 12:59:11.544250 12 13@kv/kvserver/replicate_queue.go:1145 [n1,s1,r53/1:/{Table/Max-Max}] 738 adding voter n2,s2: [1*:16, 2:0]
I220908 12:59:11.544952 12 13@kv/kvserver/replica_command.go:2319 [n1,s1,r53/1:/{Table/Max-Max}] 739 change replicas (add [(n2,s2):3LEARNER] remove []): existing descriptor r53:/{Table/Max-Max} [(n1,s1):1, (n3,s3):2, next=3, gen=3, sticky=9223372036.854775807,2147483647]
I220908 12:59:11.546237 2250 sql/catalog/internal/catkv/catalog_reader.go:89 [n1,s1,r53/1:/{Table/Max-Max},intExec=log-range-event] 740 looking up descriptors by id: [1]
I220908 12:59:11.546334 2250 sql/catalog/internal/catkv/catalog_reader.go:89 [n1,s1,r53/1:/{Table/Max-Max},intExec=log-range-event] 741 looking up descriptors by id: [13]
I220908 12:59:11.547718 745 kv/kvserver/raft.go:185 [n1,s1,r53/1:/{Table/Max-Max},raft] 742 raft ready (must-sync=true)
I220908 12:59:11.547718 745 kv/kvserver/raft.go:185 [n1,s1,r53/1:/{Table/Max-Max},raft] 742 + New Entry[0]: 6/17 EntryNormal [225c7830305a5c786565575c786538305c7865655c78396422] [380]
I220908 12:59:11.562798 755 kv/kvserver/store_raft.go:351 [n1,s1,r53/1:/{Table/Max-Max},raft] 747 incoming raft message:
I220908 12:59:11.562798 755 kv/kvserver/store_raft.go:351 [n1,s1,r53/1:/{Table/Max-Max},raft] 747 +2->1 MsgAppResp Term:6 Log:0/13 Rejected (Hint: 0)
I220908 12:59:11.562861 755 go.etcd.io/etcd/raft/v3/raft.go:1129 [n1,s1,r53/1:/{Table/Max-Max}] 748 1 received MsgAppResp(rejected, hint: (index 0, term 0)) from 2 for index 13
I220908 12:59:11.562894 755 go.etcd.io/etcd/raft/v3/raft.go:1230 [n1,s1,r53/1:/{Table/Max-Max}] 749 1 decreased progress of 2 to [StateProbe match=0 next=1]
I220908 12:59:11.562928 755 go.etcd.io/etcd/raft/v3/raft.go:460 [n1,s1,r53/1:/{Table/Max-Max}] 750 1 [firstindex: 11, commit: 16] sent snapshot[index: 16, term: 6] to 2 [StateProbe match=0 next=1]
I220908 12:59:11.562982 755 go.etcd.io/etcd/raft/v3/raft.go:463 [n1,s1,r53/1:/{Table/Max-Max}] 751 1 paused sending replication messages to 2 [StateSnapshot match=0 next=1 paused pendingSnap=16]
I220908 12:59:11.563021 755 kv/kvserver/raft.go:185 [n1,s1,r53/1:/{Table/Max-Max},raft] 752 raft ready (must-sync=false)
I220908 12:59:11.563021 755 kv/kvserver/raft.go:185 [n1,s1,r53/1:/{Table/Max-Max},raft] 752 + Outgoing Message[0]: 1->2 MsgSnap Term:6 Log:0/0 Snapshot:{[] {{[] [] [] [] false} 16 6}}
I220908 12:59:11.563285 758 kv/kvserver/store_raft.go:351 [n1,s1,r53/1:/{Table/Max-Max},raft] 753 incoming raft message:
I220908 12:59:11.563285 758 kv/kvserver/store_raft.go:351 [n1,s1,r53/1:/{Table/Max-Max},raft] 753 +2->1 MsgAppResp Term:6 Log:0/14
I220908 12:59:12.362377 766 kv/kvserver/raft.go:185 [n1,s1,r53/1:/{Table/Max-Max},raft] 770 raft ready (must-sync=false)
...
W220908 13:00:14.362821 696 kv/kvserver/replica_raft.go:1371 [n1,s1,r53/1:/{Table/Max-Max},raft] 2032 have been waiting 62.00s for slow proposal HeartbeatTxn [/Local/Range/Table/Max/RangeDescriptor,/Min), [txn: 02f4b3a1]
I220908 13:00:14.362950 696 kv/kvserver/raft.go:185 [n1,s1,r53/1:/{Table/Max-Max},raft] 2033 raft ready (must-sync=true)
I220908 13:00:14.362950 696 kv/kvserver/raft.go:185 [n1,s1,r53/1:/{Table/Max-Max},raft] 2033 + New Entry[0]: 6/58 EntryNormal [225c7830305a5c786565575c786538305c7865655c78396422] [380]
I220908 13:00:14.362950 696 kv/kvserver/raft.go:185 [n1,s1,r53/1:/{Table/Max-Max},raft] 2033 + New Entry[1]: 6/59 EntryNormal [226c5c783163342d5c78633574567322] [181]
I220908 13:00:14.362950 696 kv/kvserver/raft.go:185 [n1,s1,r53/1:/{Table/Max-Max},raft] 2033 + Outgoing Message[0]: 1->2 MsgHeartbeat Term:6 Log:0/0 Commit:14
I220908 13:00:14.363390 5441 kv/kvserver/replica_circuit_breaker.go:149 [n1,s1,r53/1:/{Table/Max-Max}] 2034 breaker: tripped with error: replica unavailable: (n1,s1):1 unable to serve request to r53:/{Table/Max-Max} [(n1,s1):1, (n3,s3):2, next=3, gen=3, sticky=9223372036.854775807,2147483647]: closed timestamp: 1662641948.543528798,0 (2022-09-08 12:59:08); raft status: {"id":"1","term":6,"vote":"1","commit":16,"lead":"1","raftState":"StateLeader","applied":16,"progress":{"1":{"match":59,"next":60,"state":"StateReplicate"},"2":{"match":14,"next":15,"state":"StateSnapshot"}},"leadtransferee":"0"}: have been waiting 62.00s for slow proposal HeartbeatTxn [/Local/Range/Table/Max/RangeDescriptor,/Min), [txn: 02f4b3a1]
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment