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

[CDC] RpcContext is destroyed, but no response sent #2736

Closed
ajcaldera1 opened this issue Oct 26, 2019 · 2 comments
Closed

[CDC] RpcContext is destroyed, but no response sent #2736

ajcaldera1 opened this issue Oct 26, 2019 · 2 comments
Assignees
@nspiegelberg
Labels
area/cdc Change Data Capture

Comments

@ajcaldera1
Copy link
Contributor

Errors encountered during test:

Log file created at: 2019/10/25 11:04:52
Running on machine: ip-172-152-29-168.ec2.internal
Application fingerprint: version 2.0.3.0 build PRE_RELEASE revision bbbd34d12fb1255aeee5b61720c8250031d78d84 build_type RELEASE built at 24 Oct 2019 05:12:14 UTC
Running duration (h:mm:ss): 21:30:05
Log line format: [IWEF]mmdd hh:mm:ss.uuuuuu threadid file:line] msg
E1025 11:04:52.724860 24620 rpc_context.cc:96] RpcContext is destroyed, but response has not been sent, for call: Call yb.cdc.CDCService.GetChanges 172.151.61.240:39526 => 172.152.29.168:9100 (request call id 13782402)
E1025 11:39:10.787760 24609 rpc_context.cc:96] RpcContext is destroyed, but response has not been sent, for call: Call yb.cdc.CDCService.GetChanges 172.151.36.172:46440 => 172.152.29.168:9100 (request call id 24779542)
Log file created at: 2019/10/25 15:15:21
Running on machine: ip-172-152-29-168.ec2.internal
Application fingerprint: version 2.0.3.0 build PRE_RELEASE revision bbbd34d12fb1255aeee5b61720c8250031d78d84 build_type RELEASE built at 24 Oct 2019 05:12:14 UTC
Running duration (h:mm:ss): 3:35:19
Log line format: [IWEF]mmdd hh:mm:ss.uuuuuu threadid file:line] msg
E1025 15:15:21.342093 13376 rpc_context.cc:96] RpcContext is destroyed, but response has not been sent, for call: Call yb.cdc.CDCService.GetChanges 172.151.61.240:58798 => 172.152.29.168:9100 (request call id 16888177)
E1025 16:31:30.958396 12052 rpc_context.cc:96] RpcContext is destroyed, but response has not been sent, for call: Call yb.cdc.CDCService.GetChanges 172.151.61.240:44217 => 172.152.29.168:9100 (request call id 17804198)
Log file created at: 2019/10/25 17:06:50
Running on machine: ip-172-152-29-168.ec2.internal
Application fingerprint: version 2.0.3.0 build PRE_RELEASE revision bbbd34d12fb1255aeee5b61720c8250031d78d84 build_type RELEASE built at 24 Oct 2019 05:12:14 UTC
Running duration (h:mm:ss): 0:34:48
Log line format: [IWEF]mmdd hh:mm:ss.uuuuuu threadid file:line] msg
E1025 17:06:50.408964  3645 rpc_context.cc:96] RpcContext is destroyed, but response has not been sent, for call: Call yb.cdc.CDCService.GetChanges 172.151.26.23:41536 => 172.152.29.168:9100 (request call id 29012284)
@ajcaldera1 ajcaldera1 added the area/cdc Change Data Capture label Oct 26, 2019
@ajcaldera1
Copy link
Contributor Author

Adjacent INFO log file:

I1025 17:03:42.190135  3361 log.cc:853] T 3446f89705b448f59abf73195079da63 P d8a555ca7ac046a5bca4d7900f84a949: Running Log GC on /mnt/d1/yb-data/tserver/wals/table-c173c6446a834ab39d6a006814a7dc4f/tablet-3446f89705b448f59abf73195079da63: retaining ops >= 205981, log segment size = 67108864
I1025 17:03:42.190204  3361 log_reader.cc:419] T 3446f89705b448f59abf73195079da63 P d8a555ca7ac046a5bca4d7900f84a949: Removed log segment sequence numbers from log reader: [47, 48]
I1025 17:03:42.190214  3361 log.cc:878] T 3446f89705b448f59abf73195079da63 P d8a555ca7ac046a5bca4d7900f84a949: Deleting log segment in path: /mnt/d1/yb-data/tserver/wals/table-c173c6446a834ab39d6a006814a7dc4f/tablet-3446f89705b448f59abf73195079da63/wal-000000047 (GCed ops < 205981)
I1025 17:03:42.190243  3361 log.cc:878] T 3446f89705b448f59abf73195079da63 P d8a555ca7ac046a5bca4d7900f84a949: Deleting log segment in path: /mnt/d1/yb-data/tserver/wals/table-c173c6446a834ab39d6a006814a7dc4f/tablet-3446f89705b448f59abf73195079da63/wal-000000048 (GCed ops < 205981)
I1025 17:03:42.192699  3361 maintenance_manager.cc:373] Time spent running LogGCOp(3446f89705b448f59abf73195079da63): real 0.003s	user 0.000s	sys 0.002s
W1025 17:03:42.457356  4862 wire_protocol.cc:228] Unknown error code in status:
W1025 17:03:42.457453  4862 tablet_rpc.cc:340] Runtime error (yb/common/wire_protocol.cc:230): Failed CDCReadRpc: stream_id: "04fb5a752ad449cd8b8407cb7afa752e" tablet_id: "5a06a780236e40a098285eb308767a05" from_checkpoint { op_id { term: 1 index: 53907 } }, retrier: { task_id: -1 state: kIdle deadline: 99408.374s } to tablet 5a06a780236e40a098285eb308767a05 on tablet server { uuid: c8795b2b270b408a986a8d8a6694762a private: [host: "172.152.49.98" port: 9100] cloud_info: placement_cloud: "aws" placement_region: "us-east-1" placement_zone: "us-east-1c" after 1 attempt(s): (999 unknown):
I1025 17:03:50.819288  4041 consensus_queue.cc:562] T 343454ada1da460993c51ebba9482ae2 P d8a555ca7ac046a5bca4d7900f84a949 [LEADER]: The logs from index 53897 have been garbage collected and cannot be read (Not found (yb/consensus/log_reader.cc:292): Failed to read ops 53898..206527: Segment 14 which contained index 53898 has been GCed)
I1025 17:03:52.103175  3949 consensus_queue.cc:562] T 21f65a17d2ed4d15863cb8bd15c516b7 P d8a555ca7ac046a5bca4d7900f84a949 [LEADER]: The logs from index 53933 have been garbage collected and cannot be read (Not found (yb/consensus/log_reader.cc:292): Failed to read ops 53934..207442: Segment 14 which contained index 53934 has been GCed)
W1025 17:03:52.543131  4862 wire_protocol.cc:228] Unknown error code in status:
W1025 17:03:52.543272  4862 tablet_rpc.cc:340] Runtime error (yb/common/wire_protocol.cc:230): Failed CDCReadRpc: stream_id: "04fb5a752ad449cd8b8407cb7afa752e" tablet_id: "90b12c3f307e4b829c1f3642bc06ceb7" from_checkpoint { op_id { term: 1 index: 53155 } }, retrier: { task_id: -1 state: kIdle deadline: 99418.459s } to tablet 90b12c3f307e4b829c1f3642bc06ceb7 on tablet server { uuid: c8795b2b270b408a986a8d8a6694762a private: [host: "172.152.49.98" port: 9100] cloud_info: placement_cloud: "aws" placement_region: "us-east-1" placement_zone: "us-east-1c" after 1 attempt(s): (999 unknown):
W1025 17:03:53.008496  3668 wire_protocol.cc:228] Unknown error code in status:
W1025 17:03:53.008599  3668 tablet_rpc.cc:340] Runtime error (yb/common/wire_protocol.cc:230): Failed CDCReadRpc: stream_id: "04fb5a752ad449cd8b8407cb7afa752e" tablet_id: "9aa43220e93e410ebc866ddeddc7aa80" from_checkpoint { op_id { term: 1 index: 53107 } }, retrier: { task_id: -1 state: kIdle deadline: 99418.925s } to tablet 9aa43220e93e410ebc866ddeddc7aa80 on tablet server { uuid: c8795b2b270b408a986a8d8a6694762a private: [host: "172.152.49.98" port: 9100] cloud_info: placement_cloud: "aws" placement_region: "us-east-1" placement_zone: "us-east-1c" after 1 attempt(s): (999 unknown):
W1025 17:03:55.180145  3668 wire_protocol.cc:228] Unknown error code in status:
W1025 17:03:55.180229  3668 tablet_rpc.cc:340] Runtime error (yb/common/wire_protocol.cc:230): Failed CDCReadRpc: stream_id: "04fb5a752ad449cd8b8407cb7afa752e" tablet_id: "66134dcfc9084d2c9a5af40590c6dabe" from_checkpoint { op_id { term: 1 index: 53387 } }, retrier: { task_id: -1 state: kIdle deadline: 99421.096s } to tablet 66134dcfc9084d2c9a5af40590c6dabe on tablet server { uuid: c8795b2b270b408a986a8d8a6694762a private: [host: "172.152.49.98" port: 9100] cloud_info: placement_cloud: "aws" placement_region: "us-east-1" placement_zone: "us-east-1c" after 1 attempt(s): (999 unknown):
I1025 17:04:04.548740  3385 consensus_queue.cc:562] T 23b7af8f37ba46ea8d93d29482b5ccc5 P d8a555ca7ac046a5bca4d7900f84a949 [LEADER]: The logs from index 53736 have been garbage collected and cannot be read (Not found (yb/consensus/log_reader.cc:292): Failed to read ops 53737..206108: Segment 14 which contained index 53737 has been GCed)
W1025 17:04:14.862162  3527 wire_protocol.cc:228] Unknown error code in status:
W1025 17:04:14.862269  3527 tablet_rpc.cc:340] Runtime error (yb/common/wire_protocol.cc:230): Failed CDCReadRpc: stream_id: "04fb5a752ad449cd8b8407cb7afa752e" tablet_id: "3446f89705b448f59abf73195079da63" from_checkpoint { op_id { term: 1 index: 53733 } }, retrier: { task_id: -1 state: kIdle deadline: 99440.778s } to tablet 3446f89705b448f59abf73195079da63 on tablet server { uuid: c8795b2b270b408a986a8d8a6694762a private: [host: "172.152.49.98" port: 9100] cloud_info: placement_cloud: "aws" placement_region: "us-east-1" placement_zone: "us-east-1c" after 1 attempt(s): (999 unknown):
W1025 17:04:48.068980  3645 wire_protocol.cc:228] Unknown error code in status:
W1025 17:04:48.069095  3645 tablet_rpc.cc:340] Runtime error (yb/common/wire_protocol.cc:230): Failed CDCReadRpc: stream_id: "04fb5a752ad449cd8b8407cb7afa752e" tablet_id: "5a06a780236e40a098285eb308767a05" from_checkpoint { op_id { term: 1 index: 53907 } }, retrier: { task_id: -1 state: kIdle deadline: 99473.985s } to tablet 5a06a780236e40a098285eb308767a05 on tablet server { uuid: c8795b2b270b408a986a8d8a6694762a private: [host: "172.152.49.98" port: 9100] cloud_info: placement_cloud: "aws" placement_region: "us-east-1" placement_zone: "us-east-1c" after 1 attempt(s): (999 unknown):
I1025 17:04:55.991890  3373 ts_tablet_manager.cc:291] Memstore global limit of 665843118 bytes reached, looking for tablet to flush
I1025 17:04:55.992040  3373 ts_tablet_manager.cc:299] Flushing tablet 0123e09b08374975a37f1f3d0745a2dd with oldest memstore write at { physical: 1572021242294962 }
I1025 17:04:55.992099  3373 db_impl.cc:5295] T 0123e09b08374975a37f1f3d0745a2dd P d8a555ca7ac046a5bca4d7900f84a949 [R]: [default] New memtable created with log file: #71
I1025 17:04:55.992138  3674 db_impl.cc:3170] T 0123e09b08374975a37f1f3d0745a2dd P d8a555ca7ac046a5bca4d7900f84a949 [R]: Calling FlushMemTableToOutputFile with column family [default], flush slots scheduled 1, total flush slots 1, compaction slots scheduled 0, compaction tasks [], total compaction slots 1
I1025 17:04:55.992167  3674 flush_job.cc:249] T 0123e09b08374975a37f1f3d0745a2dd P d8a555ca7ac046a5bca4d7900f84a949 [R]: [default] [JOB 5] Flushing memtable with next log file: 71
I1025 17:04:55.992180  3674 event_logger.cc:67] T 0123e09b08374975a37f1f3d0745a2dd P d8a555ca7ac046a5bca4d7900f84a949 [R]: EVENT_LOG_v1 {"time_micros": 1572023095992177, "job": 5, "event": "flush_started", "num_memtables": 1, "num_entries": 247, "num_deletes": 0, "memory_usage": 30440}
I1025 17:04:55.992187  3674 flush_job.cc:277] T 0123e09b08374975a37f1f3d0745a2dd P d8a555ca7ac046a5bca4d7900f84a949 [R]: [default] [JOB 5] Level-0 flush table #80: started
I1025 17:04:55.992794  3674 flush_job.cc:309] T 0123e09b08374975a37f1f3d0745a2dd P d8a555ca7ac046a5bca4d7900f84a949 [R]: [default] [JOB 5] Level-0 flush table #80: 70521 bytes OK
I1025 17:04:55.992837  3674 event_logger.cc:67] T 0123e09b08374975a37f1f3d0745a2dd P d8a555ca7ac046a5bca4d7900f84a949 [R]: EVENT_LOG_v1 {"time_micros": 1572023095992827, "cf_name": "default", "job": 5, "event": "table_file_creation", "file_number": 80, "file_size": 70521, "table_properties": {"data_size": 4176, "data_index_size": 28, "filter_size": 65482, "filter_index_size": 21, "raw_key_size": 23712, "raw_average_key_size": 96, "raw_value_size": 2223, "raw_average_value_size": 9, "num_data_blocks": 1, "num_entries": 247, "num_filter_blocks": 1, "num_data_index_blocks": 1, "filter_policy_name": "DocKeyHashedComponentsFilter", "kDeletedKeys": "0"}}
I1025 17:04:55.992949  3674 db_impl.cc:1869] [default] Level summary: files[2] max score 0.40
I1025 17:04:55.992977  3674 memtable_list.cc:374] T 0123e09b08374975a37f1f3d0745a2dd P d8a555ca7ac046a5bca4d7900f84a949 [R]: [default] Level-0 commit table #80 started
I1025 17:04:55.992982  3674 memtable_list.cc:390] T 0123e09b08374975a37f1f3d0745a2dd P d8a555ca7ac046a5bca4d7900f84a949 [R]: [default] Level-0 commit table #80: memtable #1 done
I1025 17:04:55.992986  3674 event_logger.cc:77] T 0123e09b08374975a37f1f3d0745a2dd P d8a555ca7ac046a5bca4d7900f84a949 [R]: EVENT_LOG_v1 {"time_micros": 1572023095992927, "job": 5, "event": "flush_finished", "lsm_state": [2]}
I1025 17:04:56.050109  3373 ts_tablet_manager.cc:299] Flushing tablet 9b1ce54c91514c5e941d148b619a2434 with oldest memstore write at { physical: 1572021243384089 }
I1025 17:04:56.050182  3373 db_impl.cc:5295] T 9b1ce54c91514c5e941d148b619a2434 P d8a555ca7ac046a5bca4d7900f84a949 [R]: [default] New memtable created with log file: #71
I1025 17:04:56.050228  3674 flush_job.cc:249] T 9b1ce54c91514c5e941d148b619a2434 P d8a555ca7ac046a5bca4d7900f84a949 [R]: [default] [JOB 5] Flushing memtable with next log file: 71
I1025 17:04:56.050256  3674 event_logger.cc:67] T 9b1ce54c91514c5e941d148b619a2434 P d8a555ca7ac046a5bca4d7900f84a949 [R]: EVENT_LOG_v1 {"time_micros": 1572023096050252, "job": 5, "event": "flush_started", "num_memtables": 1, "num_entries": 124, "num_deletes": 0, "memory_usage": 15528}
I1025 17:04:56.050263  3674 flush_job.cc:277] T 9b1ce54c91514c5e941d148b619a2434 P d8a555ca7ac046a5bca4d7900f84a949 [R]: [default] [JOB 5] Level-0 flush table #80: started
I1025 17:04:56.050741  3674 flush_job.cc:309] T 9b1ce54c91514c5e941d148b619a2434 P d8a555ca7ac046a5bca4d7900f84a949 [R]: [default] [JOB 5] Level-0 flush table #80: 68519 bytes OK
I1025 17:04:56.050765  3674 event_logger.cc:67] T 9b1ce54c91514c5e941d148b619a2434 P d8a555ca7ac046a5bca4d7900f84a949 [R]: EVENT_LOG_v1 {"time_micros": 1572023096050756, "cf_name": "default", "job": 5, "event": "table_file_creation", "file_number": 80, "file_size": 68519, "table_properties": {"data_size": 2176, "data_index_size": 28, "filter_size": 65482, "filter_index_size": 21, "raw_key_size": 11904, "raw_average_key_size": 96, "raw_value_size": 1116, "raw_average_value_size": 9, "num_data_blocks": 1, "num_entries": 124, "num_filter_blocks": 1, "num_data_index_blocks": 1, "filter_policy_name": "DocKeyHashedComponentsFilter", "kDeletedKeys": "0"}}
I1025 17:04:56.050858  3674 memtable_list.cc:374] T 9b1ce54c91514c5e941d148b619a2434 P d8a555ca7ac046a5bca4d7900f84a949 [R]: [default] Level-0 commit table #80 started
I1025 17:04:56.050864  3674 memtable_list.cc:390] T 9b1ce54c91514c5e941d148b619a2434 P d8a555ca7ac046a5bca4d7900f84a949 [R]: [default] Level-0 commit table #80: memtable #1 done
I1025 17:04:56.050868  3674 event_logger.cc:77] T 9b1ce54c91514c5e941d148b619a2434 P d8a555ca7ac046a5bca4d7900f84a949 [R]: EVENT_LOG_v1 {"time_micros": 1572023096050834, "job": 5, "event": "flush_finished", "lsm_state": [2]}
I1025 17:04:56.058142  3373 ts_tablet_manager.cc:299] Flushing tablet 361893342cfa46778cefc6e7f682afe2 with oldest memstore write at { physical: 1572021248334395 }
I1025 17:04:56.058182  3373 db_impl.cc:5295] T 361893342cfa46778cefc6e7f682afe2 P d8a555ca7ac046a5bca4d7900f84a949 [R]: [default] New memtable created with log file: #71
I1025 17:04:56.058235  3674 flush_job.cc:249] T 361893342cfa46778cefc6e7f682afe2 P d8a555ca7ac046a5bca4d7900f84a949 [R]: [default] [JOB 5] Flushing memtable with next log file: 71
I1025 17:04:56.058255  3674 event_logger.cc:67] T 361893342cfa46778cefc6e7f682afe2 P d8a555ca7ac046a5bca4d7900f84a949 [R]: EVENT_LOG_v1 {"time_micros": 1572023096058252, "job": 5, "event": "flush_started", "num_memtables": 1, "num_entries": 123, "num_deletes": 0, "memory_usage": 15272}
I1025 17:04:56.058260  3674 flush_job.cc:277] T 361893342cfa46778cefc6e7f682afe2 P d8a555ca7ac046a5bca4d7900f84a949 [R]: [default] [JOB 5] Level-0 flush table #80: started
I1025 17:04:56.058655  3674 flush_job.cc:309] T 361893342cfa46778cefc6e7f682afe2 P d8a555ca7ac046a5bca4d7900f84a949 [R]: [default] [JOB 5] Level-0 flush table #80: 68467 bytes OK
I1025 17:04:56.058696  3674 event_logger.cc:67] T 361893342cfa46778cefc6e7f682afe2 P d8a555ca7ac046a5bca4d7900f84a949 [R]: EVENT_LOG_v1 {"time_micros": 1572023096058686, "cf_name": "default", "job": 5, "event": "table_file_creation", "file_number": 80, "file_size": 68467, "table_properties": {"data_size": 2124, "data_index_size": 28, "filter_size": 65482, "filter_index_size": 21, "raw_key_size": 11808, "raw_average_key_size": 96, "raw_value_size": 1107, "raw_average_value_size": 9, "num_data_blocks": 1, "num_entries": 123, "num_filter_blocks": 1, "num_data_index_blocks": 1, "filter_policy_name": "DocKeyHashedComponentsFilter", "kDeletedKeys": "0"}}
I1025 17:04:56.058766  3674 memtable_list.cc:374] T 361893342cfa46778cefc6e7f682afe2 P d8a555ca7ac046a5bca4d7900f84a949 [R]: [default] Level-0 commit table #80 started
I1025 17:04:56.058773  3674 memtable_list.cc:390] T 361893342cfa46778cefc6e7f682afe2 P d8a555ca7ac046a5bca4d7900f84a949 [R]: [default] Level-0 commit table #80: memtable #1 done
I1025 17:04:56.058776  3674 event_logger.cc:77] T 361893342cfa46778cefc6e7f682afe2 P d8a555ca7ac046a5bca4d7900f84a949 [R]: EVENT_LOG_v1 {"time_micros": 1572023096058745, "job": 5, "event": "flush_finished", "lsm_state": [2]}
I1025 17:04:56.082022  3373 ts_tablet_manager.cc:299] Flushing tablet 23b7af8f37ba46ea8d93d29482b5ccc5 with oldest memstore write at { physical: 1572021312311297 }
I1025 17:04:56.082072  3373 db_impl.cc:5295] T 23b7af8f37ba46ea8d93d29482b5ccc5 P d8a555ca7ac046a5bca4d7900f84a949 [R]: [default] New memtable created with log file: #74
I1025 17:04:56.082119  3674 flush_job.cc:249] T 23b7af8f37ba46ea8d93d29482b5ccc5 P d8a555ca7ac046a5bca4d7900f84a949 [R]: [default] [JOB 5] Flushing memtable with next log file: 74
I1025 17:04:56.082157  3674 event_logger.cc:67] T 23b7af8f37ba46ea8d93d29482b5ccc5 P d8a555ca7ac046a5bca4d7900f84a949 [R]: EVENT_LOG_v1 {"time_micros": 1572023096082153, "job": 5, "event": "flush_started", "num_memtables": 1, "num_entries": 43349, "num_deletes": 0, "memory_usage": 54207880}
I1025 17:04:56.082163  3674 flush_job.cc:277] T 23b7af8f37ba46ea8d93d29482b5ccc5 P d8a555ca7ac046a5bca4d7900f84a949 [R]: [default] [JOB 5] Level-0 flush table #83: started
I1025 17:04:56.203608  3674 flush_job.cc:309] T 23b7af8f37ba46ea8d93d29482b5ccc5 P d8a555ca7ac046a5bca4d7900f84a949 [R]: [default] [JOB 5] Level-0 flush table #83: 11647835 bytes OK
I1025 17:04:56.203666  3674 event_logger.cc:67] T 23b7af8f37ba46ea8d93d29482b5ccc5 P d8a555ca7ac046a5bca4d7900f84a949 [R]: EVENT_LOG_v1 {"time_micros": 1572023096203656, "cf_name": "default", "job": 5, "event": "table_file_creation", "file_number": 83, "file_size": 11647835, "table_properties": {"data_size": 11530060, "data_index_size": 120772, "filter_size": 65482, "filter_index_size": 23, "raw_key_size": 3267557, "raw_average_key_size": 75, "raw_value_size": 49292648, "raw_average_value_size": 1137, "num_data_blocks": 1577, "num_entries": 43349, "num_filter_blocks": 1, "num_data_index_blocks": 5, "filter_policy_name": "DocKeyHashedComponentsFilter", "kDeletedKeys": "0"}}
I1025 17:04:56.203778  3674 memtable_list.cc:374] T 23b7af8f37ba46ea8d93d29482b5ccc5 P d8a555ca7ac046a5bca4d7900f84a949 [R]: [default] Level-0 commit table #83 started
I1025 17:04:56.203799  3674 memtable_list.cc:390] T 23b7af8f37ba46ea8d93d29482b5ccc5 P d8a555ca7ac046a5bca4d7900f84a949 [R]: [default] Level-0 commit table #83: memtable #1 done
I1025 17:04:56.203804  3674 event_logger.cc:77] T 23b7af8f37ba46ea8d93d29482b5ccc5 P d8a555ca7ac046a5bca4d7900f84a949 [R]: EVENT_LOG_v1 {"time_micros": 1572023096203739, "job": 5, "event": "flush_finished", "lsm_state": [4]}
I1025 17:04:56.285432  3361 log.cc:853] T 23b7af8f37ba46ea8d93d29482b5ccc5 P d8a555ca7ac046a5bca4d7900f84a949: Running Log GC on /mnt/d1/yb-data/tserver/wals/table-c173c6446a834ab39d6a006814a7dc4f/tablet-23b7af8f37ba46ea8d93d29482b5ccc5: retaining ops >= 206227, log segment size = 67108864
I1025 17:04:56.285490  3361 log_reader.cc:419] T 23b7af8f37ba46ea8d93d29482b5ccc5 P d8a555ca7ac046a5bca4d7900f84a949: Removed log segment sequence numbers from log reader: [47, 48]
I1025 17:04:56.285496  3361 log.cc:878] T 23b7af8f37ba46ea8d93d29482b5ccc5 P d8a555ca7ac046a5bca4d7900f84a949: Deleting log segment in path: /mnt/d1/yb-data/tserver/wals/table-c173c6446a834ab39d6a006814a7dc4f/tablet-23b7af8f37ba46ea8d93d29482b5ccc5/wal-000000047 (GCed ops < 206227)
I1025 17:04:56.285526  3361 log.cc:878] T 23b7af8f37ba46ea8d93d29482b5ccc5 P d8a555ca7ac046a5bca4d7900f84a949: Deleting log segment in path: /mnt/d1/yb-data/tserver/wals/table-c173c6446a834ab39d6a006814a7dc4f/tablet-23b7af8f37ba46ea8d93d29482b5ccc5/wal-000000048 (GCed ops < 206227)
I1025 17:04:56.288049  3361 maintenance_manager.cc:373] Time spent running LogGCOp(23b7af8f37ba46ea8d93d29482b5ccc5): real 0.003s	user 0.000s	sys 0.002s
I1025 17:04:56.429884  3668 consensus_queue.cc:562] T 343454ada1da460993c51ebba9482ae2 P d8a555ca7ac046a5bca4d7900f84a949 [LEADER]: The logs from index 53897 have been garbage collected and cannot be read (Not found (yb/consensus/log_reader.cc:292): Failed to read ops 53898..206682: Segment 14 which contained index 53898 has been GCed)
I1025 17:04:57.714244  3668 consensus_queue.cc:562] T 21f65a17d2ed4d15863cb8bd15c516b7 P d8a555ca7ac046a5bca4d7900f84a949 [LEADER]: The logs from index 53933 have been garbage collected and cannot be read (Not found (yb/consensus/log_reader.cc:292): Failed to read ops 53934..207616: Segment 14 which contained index 53934 has been GCed)
W1025 17:04:58.149237  3527 wire_protocol.cc:228] Unknown error code in status:
W1025 17:04:58.149346  3527 tablet_rpc.cc:340] Runtime error (yb/common/wire_protocol.cc:230): Failed CDCReadRpc: stream_id: "04fb5a752ad449cd8b8407cb7afa752e" tablet_id: "90b12c3f307e4b829c1f3642bc06ceb7" from_checkpoint { op_id { term: 1 index: 53155 } }, retrier: { task_id: -1 state: kIdle deadline: 99484.065s } to tablet 90b12c3f307e4b829c1f3642bc06ceb7 on tablet server { uuid: c8795b2b270b408a986a8d8a6694762a private: [host: "172.152.49.98" port: 9100] cloud_info: placement_cloud: "aws" placement_region: "us-east-1" placement_zone: "us-east-1c" after 1 attempt(s): (999 unknown):
W1025 17:04:58.621074  4862 wire_protocol.cc:228] Unknown error code in status:
W1025 17:04:58.621181  4862 tablet_rpc.cc:340] Runtime error (yb/common/wire_protocol.cc:230): Failed CDCReadRpc: stream_id: "04fb5a752ad449cd8b8407cb7afa752e" tablet_id: "9aa43220e93e410ebc866ddeddc7aa80" from_checkpoint { op_id { term: 1 index: 53107 } }, retrier: { task_id: -1 state: kIdle deadline: 99484.537s } to tablet 9aa43220e93e410ebc866ddeddc7aa80 on tablet server { uuid: c8795b2b270b408a986a8d8a6694762a private: [host: "172.152.49.98" port: 9100] cloud_info: placement_cloud: "aws" placement_region: "us-east-1" placement_zone: "us-east-1c" after 1 attempt(s): (999 unknown):
W1025 17:05:00.786206  3384 wire_protocol.cc:228] Unknown error code in status:
W1025 17:05:00.786294  3384 tablet_rpc.cc:340] Runtime error (yb/common/wire_protocol.cc:230): Failed CDCReadRpc: stream_id: "04fb5a752ad449cd8b8407cb7afa752e" tablet_id: "66134dcfc9084d2c9a5af40590c6dabe" from_checkpoint { op_id { term: 1 index: 53387 } }, retrier: { task_id: -1 state: kIdle deadline: 99486.702s } to tablet 66134dcfc9084d2c9a5af40590c6dabe on tablet server { uuid: c8795b2b270b408a986a8d8a6694762a private: [host: "172.152.49.98" port: 9100] cloud_info: placement_cloud: "aws" placement_region: "us-east-1" placement_zone: "us-east-1c" after 1 attempt(s): (999 unknown):
I1025 17:05:10.157809  3949 consensus_queue.cc:562] T 23b7af8f37ba46ea8d93d29482b5ccc5 P d8a555ca7ac046a5bca4d7900f84a949 [LEADER]: The logs from index 53736 have been garbage collected and cannot be read (Not found (yb/consensus/log_reader.cc:292): Failed to read ops 53737..206269: Segment 14 which contained index 53737 has been GCed)
W1025 17:05:20.468883  3949 wire_protocol.cc:228] Unknown error code in status:
W1025 17:05:20.468979  3949 tablet_rpc.cc:340] Runtime error (yb/common/wire_protocol.cc:230): Failed CDCReadRpc: stream_id: "04fb5a752ad449cd8b8407cb7afa752e" tablet_id: "3446f89705b448f59abf73195079da63" from_checkpoint { op_id { term: 1 index: 53733 } }, retrier: { task_id: -1 state: kIdle deadline: 99506.385s } to tablet 3446f89705b448f59abf73195079da63 on tablet server { uuid: c8795b2b270b408a986a8d8a6694762a private: [host: "172.152.49.98" port: 9100] cloud_info: placement_cloud: "aws" placement_region: "us-east-1" placement_zone: "us-east-1c" after 1 attempt(s): (999 unknown):
W1025 17:05:53.676709  4041 wire_protocol.cc:228] Unknown error code in status:
W1025 17:05:53.676800  4041 tablet_rpc.cc:340] Runtime error (yb/common/wire_protocol.cc:230): Failed CDCReadRpc: stream_id: "04fb5a752ad449cd8b8407cb7afa752e" tablet_id: "5a06a780236e40a098285eb308767a05" from_checkpoint { op_id { term: 1 index: 53907 } }, retrier: { task_id: -1 state: kIdle deadline: 99539.593s } to tablet 5a06a780236e40a098285eb308767a05 on tablet server { uuid: c8795b2b270b408a986a8d8a6694762a private: [host: "172.152.49.98" port: 9100] cloud_info: placement_cloud: "aws" placement_region: "us-east-1" placement_zone: "us-east-1c" after 1 attempt(s): (999 unknown):
I1025 17:06:02.036362  3645 consensus_queue.cc:562] T 343454ada1da460993c51ebba9482ae2 P d8a555ca7ac046a5bca4d7900f84a949 [LEADER]: The logs from index 53897 have been garbage collected and cannot be read (Not found (yb/consensus/log_reader.cc:292): Failed to read ops 53898..206861: Segment 14 which contained index 53898 has been GCed)
I1025 17:06:03.324589  3527 consensus_queue.cc:562] T 21f65a17d2ed4d15863cb8bd15c516b7 P d8a555ca7ac046a5bca4d7900f84a949 [LEADER]: The logs from index 53933 have been garbage collected and cannot be read (Not found (yb/consensus/log_reader.cc:292): Failed to read ops 53934..207806: Segment 14 which contained index 53934 has been GCed)
W1025 17:06:03.764765  3645 wire_protocol.cc:228] Unknown error code in status:
W1025 17:06:03.764868  3645 tablet_rpc.cc:340] Runtime error (yb/common/wire_protocol.cc:230): Failed CDCReadRpc: stream_id: "04fb5a752ad449cd8b8407cb7afa752e" tablet_id: "90b12c3f307e4b829c1f3642bc06ceb7" from_checkpoint { op_id { term: 1 index: 53155 } }, retrier: { task_id: -1 state: kIdle deadline: 99549.681s } to tablet 90b12c3f307e4b829c1f3642bc06ceb7 on tablet server { uuid: c8795b2b270b408a986a8d8a6694762a private: [host: "172.152.49.98" port: 9100] cloud_info: placement_cloud: "aws" placement_region: "us-east-1" placement_zone: "us-east-1c" after 1 attempt(s): (999 unknown):
W1025 17:06:04.234596  3385 wire_protocol.cc:228] Unknown error code in status:
W1025 17:06:04.234706  3385 tablet_rpc.cc:340] Runtime error (yb/common/wire_protocol.cc:230): Failed CDCReadRpc: stream_id: "04fb5a752ad449cd8b8407cb7afa752e" tablet_id: "9aa43220e93e410ebc866ddeddc7aa80" from_checkpoint { op_id { term: 1 index: 53107 } }, retrier: { task_id: -1 state: kIdle deadline: 99550.151s } to tablet 9aa43220e93e410ebc866ddeddc7aa80 on tablet server { uuid: c8795b2b270b408a986a8d8a6694762a private: [host: "172.152.49.98" port: 9100] cloud_info: placement_cloud: "aws" placement_region: "us-east-1" placement_zone: "us-east-1c" after 1 attempt(s): (999 unknown):
W1025 17:06:06.402253  4041 wire_protocol.cc:228] Unknown error code in status:
W1025 17:06:06.402354  4041 tablet_rpc.cc:340] Runtime error (yb/common/wire_protocol.cc:230): Failed CDCReadRpc: stream_id: "04fb5a752ad449cd8b8407cb7afa752e" tablet_id: "66134dcfc9084d2c9a5af40590c6dabe" from_checkpoint { op_id { term: 1 index: 53387 } }, retrier: { task_id: -1 state: kIdle deadline: 99552.319s } to tablet 66134dcfc9084d2c9a5af40590c6dabe on tablet server { uuid: c8795b2b270b408a986a8d8a6694762a private: [host: "172.152.49.98" port: 9100] cloud_info: placement_cloud: "aws" placement_region: "us-east-1" placement_zone: "us-east-1c" after 1 attempt(s): (999 unknown):
I1025 17:06:09.970105  3373 ts_tablet_manager.cc:291] Memstore global limit of 665843118 bytes reached, looking for tablet to flush
I1025 17:06:09.970293  3373 ts_tablet_manager.cc:299] Flushing tablet 535d7715852d4663a0b502c51851f7c4 with oldest memstore write at { physical: 1572021314825607 }
I1025 17:06:09.970320  3373 db_impl.cc:5295] T 535d7715852d4663a0b502c51851f7c4 P d8a555ca7ac046a5bca4d7900f84a949 [R]: [default] New memtable created with log file: #71
I1025 17:06:09.970361  3674 db_impl.cc:3170] T 535d7715852d4663a0b502c51851f7c4 P d8a555ca7ac046a5bca4d7900f84a949 [R]: Calling FlushMemTableToOutputFile with column family [default], flush slots scheduled 1, total flush slots 1, compaction slots scheduled 0, compaction tasks [], total compaction slots 1
I1025 17:06:09.970392  3674 flush_job.cc:249] T 535d7715852d4663a0b502c51851f7c4 P d8a555ca7ac046a5bca4d7900f84a949 [R]: [default] [JOB 5] Flushing memtable with next log file: 71
I1025 17:06:09.970407  3674 event_logger.cc:67] T 535d7715852d4663a0b502c51851f7c4 P d8a555ca7ac046a5bca4d7900f84a949 [R]: EVENT_LOG_v1 {"time_micros": 1572023169970402, "job": 5, "event": "flush_started", "num_memtables": 1, "num_entries": 124, "num_deletes": 0, "memory_usage": 15368}
I1025 17:06:09.970412  3674 flush_job.cc:277] T 535d7715852d4663a0b502c51851f7c4 P d8a555ca7ac046a5bca4d7900f84a949 [R]: [default] [JOB 5] Level-0 flush table #80: started
I1025 17:06:09.970911  3674 flush_job.cc:309] T 535d7715852d4663a0b502c51851f7c4 P d8a555ca7ac046a5bca4d7900f84a949 [R]: [default] [JOB 5] Level-0 flush table #80: 68483 bytes OK
I1025 17:06:09.970958  3674 event_logger.cc:67] T 535d7715852d4663a0b502c51851f7c4 P d8a555ca7ac046a5bca4d7900f84a949 [R]: EVENT_LOG_v1 {"time_micros": 1572023169970947, "cf_name": "default", "job": 5, "event": "table_file_creation", "file_number": 80, "file_size": 68483, "table_properties": {"data_size": 2140, "data_index_size": 28, "filter_size": 65482, "filter_index_size": 21, "raw_key_size": 11904, "raw_average_key_size": 96, "raw_value_size": 1116, "raw_average_value_size": 9, "num_data_blocks": 1, "num_entries": 124, "num_filter_blocks": 1, "num_data_index_blocks": 1, "filter_policy_name": "DocKeyHashedComponentsFilter", "kDeletedKeys": "0"}}
I1025 17:06:09.971046  3674 db_impl.cc:1869] [default] Level summary: files[2] max score 0.40
I1025 17:06:09.971091  3674 memtable_list.cc:374] T 535d7715852d4663a0b502c51851f7c4 P d8a555ca7ac046a5bca4d7900f84a949 [R]: [default] Level-0 commit table #80 started
I1025 17:06:09.971098  3674 memtable_list.cc:390] T 535d7715852d4663a0b502c51851f7c4 P d8a555ca7ac046a5bca4d7900f84a949 [R]: [default] Level-0 commit table #80: memtable #1 done
I1025 17:06:09.971102  3674 event_logger.cc:77] T 535d7715852d4663a0b502c51851f7c4 P d8a555ca7ac046a5bca4d7900f84a949 [R]: EVENT_LOG_v1 {"time_micros": 1572023169971029, "job": 5, "event": "flush_finished", "lsm_state": [2]}
I1025 17:06:09.995429  3373 ts_tablet_manager.cc:299] Flushing tablet ee125b3feb0a4354bf8f4bed9e0d55e1 with oldest memstore write at { physical: 1572021320668454 }
I1025 17:06:09.995496  3373 db_impl.cc:5295] T ee125b3feb0a4354bf8f4bed9e0d55e1 P d8a555ca7ac046a5bca4d7900f84a949 [R]: [default] New memtable created with log file: #71
I1025 17:06:09.995544  3674 flush_job.cc:249] T ee125b3feb0a4354bf8f4bed9e0d55e1 P d8a555ca7ac046a5bca4d7900f84a949 [R]: [default] [JOB 5] Flushing memtable with next log file: 71
I1025 17:06:09.995570  3674 event_logger.cc:67] T ee125b3feb0a4354bf8f4bed9e0d55e1 P d8a555ca7ac046a5bca4d7900f84a949 [R]: EVENT_LOG_v1 {"time_micros": 1572023169995565, "job": 5, "event": "flush_started", "num_memtables": 1, "num_entries": 123, "num_deletes": 0, "memory_usage": 15272}
I1025 17:06:09.995594  3674 flush_job.cc:277] T ee125b3feb0a4354bf8f4bed9e0d55e1 P d8a555ca7ac046a5bca4d7900f84a949 [R]: [default] [JOB 5] Level-0 flush table #80: started
I1025 17:06:09.996053  3674 flush_job.cc:309] T ee125b3feb0a4354bf8f4bed9e0d55e1 P d8a555ca7ac046a5bca4d7900f84a949 [R]: [default] [JOB 5] Level-0 flush table #80: 68481 bytes OK
I1025 17:06:09.996101  3674 event_logger.cc:67] T ee125b3feb0a4354bf8f4bed9e0d55e1 P d8a555ca7ac046a5bca4d7900f84a949 [R]: EVENT_LOG_v1 {"time_micros": 1572023169996092, "cf_name": "default", "job": 5, "event": "table_file_creation", "file_number": 80, "file_size": 68481, "table_properties": {"data_size": 2138, "data_index_size": 28, "filter_size": 65482, "filter_index_size": 21, "raw_key_size": 11808, "raw_average_key_size": 96, "raw_value_size": 1107, "raw_average_value_size": 9, "num_data_blocks": 1, "num_entries": 123, "num_filter_blocks": 1, "num_data_index_blocks": 1, "filter_policy_name": "DocKeyHashedComponentsFilter", "kDeletedKeys": "0"}}
I1025 17:06:09.996196  3674 memtable_list.cc:374] T ee125b3feb0a4354bf8f4bed9e0d55e1 P d8a555ca7ac046a5bca4d7900f84a949 [R]: [default] Level-0 commit table #80 started
I1025 17:06:09.996201  3674 memtable_list.cc:390] T ee125b3feb0a4354bf8f4bed9e0d55e1 P d8a555ca7ac046a5bca4d7900f84a949 [R]: [default] Level-0 commit table #80: memtable #1 done
I1025 17:06:09.996206  3674 event_logger.cc:77] T ee125b3feb0a4354bf8f4bed9e0d55e1 P d8a555ca7ac046a5bca4d7900f84a949 [R]: EVENT_LOG_v1 {"time_micros": 1572023169996170, "job": 5, "event": "flush_finished", "lsm_state": [2]}
I1025 17:06:10.029004  3373 ts_tablet_manager.cc:299] Flushing tablet 4736ad9c803f44c8ba2319deccdb8c1e with oldest memstore write at { physical: 1572021324976831 }
I1025 17:06:10.029083  3373 db_impl.cc:5295] T 4736ad9c803f44c8ba2319deccdb8c1e P d8a555ca7ac046a5bca4d7900f84a949 [R]: [default] New memtable created with log file: #71
I1025 17:06:10.029147  3674 flush_job.cc:249] T 4736ad9c803f44c8ba2319deccdb8c1e P d8a555ca7ac046a5bca4d7900f84a949 [R]: [default] [JOB 5] Flushing memtable with next log file: 71
I1025 17:06:10.029191  3674 event_logger.cc:67] T 4736ad9c803f44c8ba2319deccdb8c1e P d8a555ca7ac046a5bca4d7900f84a949 [R]: EVENT_LOG_v1 {"time_micros": 1572023170029186, "job": 5, "event": "flush_started", "num_memtables": 1, "num_entries": 58, "num_deletes": 0, "memory_usage": 7432}
I1025 17:06:10.029197  3674 flush_job.cc:277] T 4736ad9c803f44c8ba2319deccdb8c1e P d8a555ca7ac046a5bca4d7900f84a949 [R]: [default] [JOB 5] Level-0 flush table #80: started
I1025 17:06:10.029640  3674 flush_job.cc:309] T 4736ad9c803f44c8ba2319deccdb8c1e P d8a555ca7ac046a5bca4d7900f84a949 [R]: [default] [JOB 5] Level-0 flush table #80: 67518 bytes OK
I1025 17:06:10.029665  3674 event_logger.cc:67] T 4736ad9c803f44c8ba2319deccdb8c1e P d8a555ca7ac046a5bca4d7900f84a949 [R]: EVENT_LOG_v1 {"time_micros": 1572023170029655, "cf_name": "default", "job": 5, "event": "table_file_creation", "file_number": 80, "file_size": 67518, "table_properties": {"data_size": 1175, "data_index_size": 28, "filter_size": 65482, "filter_index_size": 21, "raw_key_size": 5568, "raw_average_key_size": 96, "raw_value_size": 522, "raw_average_value_size": 9, "num_data_blocks": 1, "num_entries": 58, "num_filter_blocks": 1, "num_data_index_blocks": 1, "filter_policy_name": "DocKeyHashedComponentsFilter", "kDeletedKeys": "0"}}
I1025 17:06:10.029754  3674 memtable_list.cc:374] T 4736ad9c803f44c8ba2319deccdb8c1e P d8a555ca7ac046a5bca4d7900f84a949 [R]: [default] Level-0 commit table #80 started
I1025 17:06:10.029760  3674 memtable_list.cc:390] T 4736ad9c803f44c8ba2319deccdb8c1e P d8a555ca7ac046a5bca4d7900f84a949 [R]: [default] Level-0 commit table #80: memtable #1 done
I1025 17:06:10.029763  3674 event_logger.cc:77] T 4736ad9c803f44c8ba2319deccdb8c1e P d8a555ca7ac046a5bca4d7900f84a949 [R]: EVENT_LOG_v1 {"time_micros": 1572023170029730, "job": 5, "event": "flush_finished", "lsm_state": [2]}
I1025 17:06:10.034085  3373 ts_tablet_manager.cc:299] Flushing tablet 8200fa5ed5254c4891663671c3a4f8dd with oldest memstore write at { physical: 1572021324978216 }
I1025 17:06:10.034126  3373 db_impl.cc:5295] T 8200fa5ed5254c4891663671c3a4f8dd P d8a555ca7ac046a5bca4d7900f84a949 [R]: [default] New memtable created with log file: #71
I1025 17:06:10.034162  3674 flush_job.cc:249] T 8200fa5ed5254c4891663671c3a4f8dd P d8a555ca7ac046a5bca4d7900f84a949 [R]: [default] [JOB 5] Flushing memtable with next log file: 71
I1025 17:06:10.034180  3674 event_logger.cc:67] T 8200fa5ed5254c4891663671c3a4f8dd P d8a555ca7ac046a5bca4d7900f84a949 [R]: EVENT_LOG_v1 {"time_micros": 1572023170034177, "job": 5, "event": "flush_started", "num_memtables": 1, "num_entries": 29, "num_deletes": 0, "memory_usage": 3760}
I1025 17:06:10.034186  3674 flush_job.cc:277] T 8200fa5ed5254c4891663671c3a4f8dd P d8a555ca7ac046a5bca4d7900f84a949 [R]: [default] [JOB 5] Level-0 flush table #80: started
I1025 17:06:10.034492  3674 flush_job.cc:309] T 8200fa5ed5254c4891663671c3a4f8dd P d8a555ca7ac046a5bca4d7900f84a949 [R]: [default] [JOB 5] Level-0 flush table #80: 66967 bytes OK
I1025 17:06:10.034513  3674 event_logger.cc:67] T 8200fa5ed5254c4891663671c3a4f8dd P d8a555ca7ac046a5bca4d7900f84a949 [R]: EVENT_LOG_v1 {"time_micros": 1572023170034504, "cf_name": "default", "job": 5, "event": "table_file_creation", "file_number": 80, "file_size": 66967, "table_properties": {"data_size": 624, "data_index_size": 28, "filter_size": 65482, "filter_index_size": 21, "raw_key_size": 2784, "raw_average_key_size": 96, "raw_value_size": 261, "raw_average_value_size": 9, "num_data_blocks": 1, "num_entries": 29, "num_filter_blocks": 1, "num_data_index_blocks": 1, "filter_policy_name": "DocKeyHashedComponentsFilter", "kDeletedKeys": "0"}}
I1025 17:06:10.034579  3674 memtable_list.cc:374] T 8200fa5ed5254c4891663671c3a4f8dd P d8a555ca7ac046a5bca4d7900f84a949 [R]: [default] Level-0 commit table #80 started
I1025 17:06:10.034585  3674 memtable_list.cc:390] T 8200fa5ed5254c4891663671c3a4f8dd P d8a555ca7ac046a5bca4d7900f84a949 [R]: [default] Level-0 commit table #80: memtable #1 done
I1025 17:06:10.034590  3674 event_logger.cc:77] T 8200fa5ed5254c4891663671c3a4f8dd P d8a555ca7ac046a5bca4d7900f84a949 [R]: EVENT_LOG_v1 {"time_micros": 1572023170034559, "job": 5, "event": "flush_finished", "lsm_state": [2]}
I1025 17:06:10.036336  3373 ts_tablet_manager.cc:299] Flushing tablet 3807188d7dd04536821593b31aef3d46 with oldest memstore write at { physical: 1572021324979709 }
I1025 17:06:10.036373  3373 db_impl.cc:5295] T 3807188d7dd04536821593b31aef3d46 P d8a555ca7ac046a5bca4d7900f84a949 [R]: [default] New memtable created with log file: #71
I1025 17:06:10.036406  3674 flush_job.cc:249] T 3807188d7dd04536821593b31aef3d46 P d8a555ca7ac046a5bca4d7900f84a949 [R]: [default] [JOB 5] Flushing memtable with next log file: 71
I1025 17:06:10.036412  3373 ts_tablet_manager.cc:299] Flushing tablet 0a895790fa37460eb408d28577e4a94d with oldest memstore write at { physical: 1572021386355330 }
I1025 17:06:10.036425  3674 event_logger.cc:67] T 3807188d7dd04536821593b31aef3d46 P d8a555ca7ac046a5bca4d7900f84a949 [R]: EVENT_LOG_v1 {"time_micros": 1572023170036423, "job": 5, "event": "flush_started", "num_memtables": 1, "num_entries": 29, "num_deletes": 0, "memory_usage": 3880}
I1025 17:06:10.036432  3674 flush_job.cc:277] T 3807188d7dd04536821593b31aef3d46 P d8a555ca7ac046a5bca4d7900f84a949 [R]: [default] [JOB 5] Level-0 flush table #80: started
I1025 17:06:10.036432  3373 db_impl.cc:5295] T 0a895790fa37460eb408d28577e4a94d P d8a555ca7ac046a5bca4d7900f84a949 [R]: [default] New memtable created with log file: #74
I1025 17:06:10.036736  3674 flush_job.cc:309] T 3807188d7dd04536821593b31aef3d46 P d8a555ca7ac046a5bca4d7900f84a949 [R]: [default] [JOB 5] Level-0 flush table #80: 66963 bytes OK
I1025 17:06:10.036757  3674 event_logger.cc:67] T 3807188d7dd04536821593b31aef3d46 P d8a555ca7ac046a5bca4d7900f84a949 [R]: EVENT_LOG_v1 {"time_micros": 1572023170036750, "cf_name": "default", "job": 5, "event": "table_file_creation", "file_number": 80, "file_size": 66963, "table_properties": {"data_size": 620, "data_index_size": 28, "filter_size": 65482, "filter_index_size": 21, "raw_key_size": 2784, "raw_average_key_size": 96, "raw_value_size": 261, "raw_average_value_size": 9, "num_data_blocks": 1, "num_entries": 29, "num_filter_blocks": 1, "num_data_index_blocks": 1, "filter_policy_name": "DocKeyHashedComponentsFilter", "kDeletedKeys": "0"}}
I1025 17:06:10.036845  3674 memtable_list.cc:374] T 3807188d7dd04536821593b31aef3d46 P d8a555ca7ac046a5bca4d7900f84a949 [R]: [default] Level-0 commit table #80 started
I1025 17:06:10.036854  3674 memtable_list.cc:390] T 3807188d7dd04536821593b31aef3d46 P d8a555ca7ac046a5bca4d7900f84a949 [R]: [default] Level-0 commit table #80: memtable #1 done
I1025 17:06:10.036857  3674 event_logger.cc:77] T 3807188d7dd04536821593b31aef3d46 P d8a555ca7ac046a5bca4d7900f84a949 [R]: EVENT_LOG_v1 {"time_micros": 1572023170036821, "job": 5, "event": "flush_finished", "lsm_state": [2]}
I1025 17:06:10.036871  3674 flush_job.cc:249] T 0a895790fa37460eb408d28577e4a94d P d8a555ca7ac046a5bca4d7900f84a949 [R]: [default] [JOB 5] Flushing memtable with next log file: 74
I1025 17:06:10.036880  3674 event_logger.cc:67] T 0a895790fa37460eb408d28577e4a94d P d8a555ca7ac046a5bca4d7900f84a949 [R]: EVENT_LOG_v1 {"time_micros": 1572023170036878, "job": 5, "event": "flush_started", "num_memtables": 1, "num_entries": 43747, "num_deletes": 0, "memory_usage": 54449440}
I1025 17:06:10.036885  3674 flush_job.cc:277] T 0a895790fa37460eb408d28577e4a94d P d8a555ca7ac046a5bca4d7900f84a949 [R]: [default] [JOB 5] Level-0 flush table #83: started
I1025 17:06:10.159826  3674 flush_job.cc:309] T 0a895790fa37460eb408d28577e4a94d P d8a555ca7ac046a5bca4d7900f84a949 [R]: [default] [JOB 5] Level-0 flush table #83: 11712218 bytes OK
I1025 17:06:10.159965  3674 event_logger.cc:67] T 0a895790fa37460eb408d28577e4a94d P d8a555ca7ac046a5bca4d7900f84a949 [R]: EVENT_LOG_v1 {"time_micros": 1572023170159953, "cf_name": "default", "job": 5, "event": "table_file_creation", "file_number": 83, "file_size": 11712218, "table_properties": {"data_size": 11594050, "data_index_size": 121673, "filter_size": 65482, "filter_index_size": 23, "raw_key_size": 3299315, "raw_average_key_size": 75, "raw_value_size": 49469308, "raw_average_value_size": 1130, "num_data_blocks": 1585, "num_entries": 43747, "num_filter_blocks": 1, "num_data_index_blocks": 5, "filter_policy_name": "DocKeyHashedComponentsFilter", "kDeletedKeys": "0"}}
I1025 17:06:10.160099  3674 memtable_list.cc:374] T 0a895790fa37460eb408d28577e4a94d P d8a555ca7ac046a5bca4d7900f84a949 [R]: [default] Level-0 commit table #83 started
I1025 17:06:10.160107  3674 memtable_list.cc:390] T 0a895790fa37460eb408d28577e4a94d P d8a555ca7ac046a5bca4d7900f84a949 [R]: [default] Level-0 commit table #83: memtable #1 done
I1025 17:06:10.160111  3674 event_logger.cc:77] T 0a895790fa37460eb408d28577e4a94d P d8a555ca7ac046a5bca4d7900f84a949 [R]: EVENT_LOG_v1 {"time_micros": 1572023170160043, "job": 5, "event": "flush_finished", "lsm_state": [4]}
I1025 17:06:10.381880  3361 log.cc:853] T 0a895790fa37460eb408d28577e4a94d P d8a555ca7ac046a5bca4d7900f84a949: Running Log GC on /mnt/d0/yb-data/tserver/wals/table-c173c6446a834ab39d6a006814a7dc4f/tablet-0a895790fa37460eb408d28577e4a94d: retaining ops >= 206438, log segment size = 67108864
I1025 17:06:10.381930  3361 log_reader.cc:419] T 0a895790fa37460eb408d28577e4a94d P d8a555ca7ac046a5bca4d7900f84a949: Removed log segment sequence numbers from log reader: [48]
I1025 17:06:10.381938  3361 log.cc:878] T 0a895790fa37460eb408d28577e4a94d P d8a555ca7ac046a5bca4d7900f84a949: Deleting log segment in path: /mnt/d0/yb-data/tserver/wals/table-c173c6446a834ab39d6a006814a7dc4f/tablet-0a895790fa37460eb408d28577e4a94d/wal-000000048 (GCed ops < 206438)
I1025 17:06:10.383642  3361 maintenance_manager.cc:373] Time spent running LogGCOp(0a895790fa37460eb408d28577e4a94d): real 0.002s	user 0.000s	sys 0.001s
I1025 17:06:15.767865  3527 consensus_queue.cc:562] T 23b7af8f37ba46ea8d93d29482b5ccc5 P d8a555ca7ac046a5bca4d7900f84a949 [LEADER]: The logs from index 53736 have been garbage collected and cannot be read (Not found (yb/consensus/log_reader.cc:292): Failed to read ops 53737..206456: Segment 14 which contained index 53737 has been GCed)
W1025 17:06:26.075368  4041 wire_protocol.cc:228] Unknown error code in status:
W1025 17:06:26.075474  4041 tablet_rpc.cc:340] Runtime error (yb/common/wire_protocol.cc:230): Failed CDCReadRpc: stream_id: "04fb5a752ad449cd8b8407cb7afa752e" tablet_id: "3446f89705b448f59abf73195079da63" from_checkpoint { op_id { term: 1 index: 53733 } }, retrier: { task_id: -1 state: kIdle deadline: 99571.992s } to tablet 3446f89705b448f59abf73195079da63 on tablet server { uuid: c8795b2b270b408a986a8d8a6694762a private: [host: "172.152.49.98" port: 9100] cloud_info: placement_cloud: "aws" placement_region: "us-east-1" placement_zone: "us-east-1c" after 1 attempt(s): (999 unknown):
E1025 17:06:50.408964  3645 rpc_context.cc:96] RpcContext is destroyed, but response has not been sent, for call: Call yb.cdc.CDCService.GetChanges 172.151.26.23:41536 => 172.152.29.168:9100 (request call id 29012284)

@ajcaldera1
Copy link
Contributor Author

This was just before one of the events noted by issue #2735

nspiegelberg pushed a commit that referenced this issue Nov 7, 2019
@ndeodhar @nspiegelberg
[#2365] [#2332] [#2736] [#2733] [#2863] [CDC] Use new GetChanges API …
7f917f6 
…on CDC Consumer

Summary:
Depends on D7480
Previously, I created CDCReadRpc to handle CDC read requests using the TabletInvoker API.
TabletInvoker handles creating a <tablet, proxy> cache, handling replica failover & errors, and
encoding standard retry logic.  Using this on the CDC Consumer will solve a number of
outstanding tasks related to these issues.  Additionally, I added multi-universe support since I
needed to differentiate between the various clients created anyways.

Test Plan:
1. Used pgbench in a 3 node setup to send 100k messages.
2. ybd --cxx-test twodc-test -n 20

Reviewers: rahuldesirazu, hector, neha

Reviewed By: neha

Subscribers: sergei, ybase, bogdan

Differential Revision: https://phabricator.dev.yugabyte.com/D7456
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@nspiegelberg nspiegelberg

Labels
area/cdc Change Data Capture
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@ndeodhar @ajcaldera1 @nspiegelberg