logproxy获取不到变化数据

光明 · 2023 年6 月 2 日 17:21

【使用环境】测试环境

【 OB or 其他组件】
OB
logproxy
flinkcdc
【使用版本】
oblogproxy-ce-for-4x-1.1.1-20230418115957
OceanBase_CE 4.1.0.0 (r100000192023032010-0265dfc6d00ff4f0ff4ad2710504a18962abaef6)
flink-sql-connector-oceanbase-cdc-2.3.0.jar

【问题描述】清晰明确描述问题

参见附件，能捕获到全量数据，但捕获不到增量数据
【复现路径】问题出现前后相关操作

【问题现象及影响】
参见附件，能捕获到全量数据，但捕获不到增量数据

E20230602 16:06:20.432765 10497 mysql_protocol.cpp:239] Failed to query observer:Table ‘oceanbase.__all_virtual_server_clog_stat’ doesn’t exist, unexpected column count: 0
E20230602 16:06:20.432960 10497 clog_meta_routine.cpp:45] Failed to check the existence of svr_min_log_timestamp column in __all_virtual_server_clog_stat, disable clog check
W20230602 16:09:19.477509 10497 arranger.cpp:327] Exited oblogreader of pid: 16601 with clientId: 172.20.30.76_2172_1685693177_1_sysbench_tenant of peer5484844125217882120, fd:8, addr:1277039788, port:1024
W20230602 16:09:19.477573 10497 arranger.cpp:342] Failed to fetch peer info of fd:8, errno:9, error:Bad file descriptor
W20230602 16:09:19.477598 10497 arranger.cpp:349] Try to shutdown fd: 8
W20230602 16:09:19.477607 10497 arranger.cpp:351] Shutdown fd: 8
E20230602 16:09:22.893711 10497 mysql_protocol.cpp:239] Failed to query observer:Table ‘oceanbase.__all_virtual_server_clog_stat’ doesn’t exist, unexpected column count: 0
E20230602 16:09:22.893741 10497 clog_meta_routine.cpp:45] Failed to check the existence of svr_min_log_timestamp column in __all_virtual_server_clog_stat, disable clog check
W20230602 16:31:47.710134 10497 arranger.cpp:327] Exited oblogreader of pid: 17310 with clientId: 172.20.30.76_17032_1685693359_1_sysbench_tenant of peer5484844125226336264, fd:8, addr:1277039788, port:1153
W20230602 16:31:47.710275 10497 arranger.cpp:342] Failed to fetch peer info of fd:8, errno:9, error:Bad file descriptor
W20230602 16:31:47.710295 10497 arranger.cpp:349] Try to shutdown fd: 8
W20230602 16:31:47.710302 10497 arranger.cpp:351] Shutdown fd: 8
E20230602 16:36:41.697717 10497 mysql_protocol.cpp:239] Failed to query observer:Table ‘oceanbase.__all_virtual_server_clog_stat’ doesn’t exist, unexpected column count: 0
E20230602 16:36:41.697775 10497 clog_meta_routine.cpp:45] Failed to check the existence of svr_min_log_timestamp column in __all_virtual_server_clog_stat, disable clog check
W20230602 16:36:50.700817 10497 arranger.cpp:327] Exited oblogreader of pid: 21674 with clientId: 172.20.30.76_20280_1685694998_1_sysbench_tenant of peer5484844125641179144, fd:8, addr:1277039788, port:7483
W20230602 16:36:50.700886 10497 arranger.cpp:342] Failed to fetch peer info of fd:8, errno:9, error:Bad file descriptor
W20230602 16:36:50.700901 10497 arranger.cpp:349] Try to shutdown fd: 8
W20230602 16:36:50.700906 10497 arranger.cpp:351] Shutdown fd: 8
E20230602 16:37:45.124590 10497 mysql_protocol.cpp:239] Failed to query observer:Table ‘oceanbase.__all_virtual_server_clog_stat’ doesn’t exist, unexpected column count: 0
E20230602 16:37:45.124647 10497 clog_meta_routine.cpp:45] Failed to check the existence of svr_min_log_timestamp column in __all_virtual_server_clog_stat, disable clog check
W20230602 16:37:58.128762 10497 arranger.cpp:327] Exited oblogreader of pid: 21989 with clientId: 172.20.30.76_596_1685695061_1_sysbench_tenant of peer5484844125645504520, fd:8, addr:1277039788, port:7549
W20230602 16:37:58.128857 10497 arranger.cpp:342] Failed to fetch peer info of fd:8, errno:9, error:Bad file descriptor
W20230602 16:37:58.128885 10497 arranger.cpp:349] Try to shutdown fd: 8
W20230602 16:37:58.128901 10497 arranger.cpp:351] Shutdown fd: 8
E20230602 16:38:10.545706 10497 mysql_protocol.cpp:239] Failed to query observer:Table ‘oceanbase.__all_virtual_server_clog_stat’ doesn’t exist, unexpected column count: 0
E20230602 16:38:10.545738 10497 clog_meta_routine.cpp:45] Failed to check the existence of svr_min_log_timestamp column in __all_virtual_server_clog_stat, disable clog check
W20230602 16:39:16.561769 10497 arranger.cpp:327] Exited oblogreader of pid: 22248 with clientId: 172.20.30.76_6000_1685695080_1_sysbench_tenant of peer5484844125649764360, fd:8, addr:1277039788, port:7614
W20230602 16:39:16.561864 10497 arranger.cpp:342] Failed to fetch peer info of fd:8, errno:9, error:Bad file descriptor
W20230602 16:39:16.561897 10497 arranger.cpp:349] Try to shutdown fd: 8
W20230602 16:39:16.561904 10497 arranger.cpp:351] Shutdown fd: 8
E20230602 16:40:43.504006 10497 mysql_protocol.cpp:239] Failed to query observer:Table ‘oceanbase.__all_virtual_server_clog_stat’ doesn’t exist, unexpected column count: 0
E20230602 16:40:43.504045 10497 clog_meta_routine.cpp:45] Failed to check the existence of svr_min_log_timestamp column in __all_virtual_server_clog_stat, disable clog check
E20230602 16:42:29.949071 10497 mysql_protocol.cpp:239] Failed to query observer:Table ‘oceanbase.__all_virtual_server_clog_stat’ doesn’t exist, unexpected column count: 0
E20230602 16:42:29.949132 10497 clog_meta_routine.cpp:45] Failed to check the existence of svr_min_log_timestamp column in __all_virtual_server_clog_stat, disable clog check
E20230602 16:46:02.417183 10497 mysql_protocol.cpp:239] Failed to query observer:Table ‘oceanbase.__all_virtual_server_clog_stat’ doesn’t exist, unexpected column count: 0
E20230602 16:46:02.417220 10497 clog_meta_routine.cpp:45] Failed to check the existence of svr_min_log_timestamp column in __all_virtual_server_clog_stat, disable clog check
E20230602 16:48:08.363970 10497 mysql_protocol.cpp:239] Failed to query observer:Table ‘oceanbase.__all_virtual_server_clog_stat’ doesn’t exist, unexpected column count: 0
E20230602 16:48:08.364012 10497 clog_meta_routine.cpp:45] Failed to check the existence of svr_min_log_timestamp column in __all_virtual_server_clog_stat, disable clog check
E20230602 16:53:55.364971 10497 mysql_protocol.cpp:239] Failed to query observer:Table ‘oceanbase.__all_virtual_server_clog_stat’ doesn’t exist, unexpected column count: 0
E20230602 16:53:55.365032 10497 clog_meta_routine.cpp:45] Failed to check the existence of svr_min_log_timestamp column in __all_virtual_server_clog_stat, disable clog check
E20230602 16:55:44.812893 10497 mysql_protocol.cpp:239] Failed to query observer:Table ‘oceanbase.__all_virtual_server_clog_stat’ doesn’t exist, unexpected column count: 0
E20230602 16:55:44.812942 10497 clog_meta_routine.cpp:45] Failed to check the existence of svr_min_log_timestamp column in __all_virtual_server_clog_stat, disable clog check
[root@dghpl3109 log]#
【附件】

夏进 · 2023 年6 月 2 日 17:37

稍等下，帮你找下相关同学解答

刘彻 · 2023 年6 月 2 日 17:44

看一下liboblog.log日志，另外增量是不可以订阅sys租户的，要确认一下不是订阅sys租户的数据

云飞 · 2023 年6 月 2 日 17:54

您好，我和贴主使用的相同组件版本，我的全量同步和增量同步都不行。 Flink SQL Client 查询表数据的时候查不到。能帮忙一起看看吗？

Flink Task Manager的日志如下：

2023-06-02 17:55:45,976 INFO org.apache.flink.runtime.taskmanager.Task [] - Source: ob_t[5] → ConstraintEnforcer[6] → Sink: Collect table sink (1/1)#0 (1c66d1c1e00c5f06b56a81b6a0b5ed8f_cbc357ccb763df2852fee8c4fc7d55f2_0_0) switched from CREATED to DEPLOYING.

2023-06-02 17:55:45,990 INFO org.apache.flink.runtime.taskmanager.Task [] - Loading JAR files for task Source: ob_t[5] → ConstraintEnforcer[6] → Sink: Collect table sink (1/1)#0 (1c66d1c1e00c5f06b56a81b6a0b5ed8f_cbc357ccb763df2852fee8c4fc7d55f2_0_0) [DEPLOYING].

2023-06-02 17:55:45,992 INFO org.apache.flink.runtime.blob.BlobClient [] - Downloading 7c9409d1bfb573e0cf8578f0749ead81/p-1a80d5a424ce0ae95b9fd9753c9a35fd41eded49-d9d91665e68013015cec4e9d2d11de59 from localhost/127.0.0.1:35342

2023-06-02 17:55:46,015 INFO org.apache.flink.runtime.blob.BlobClient [] - Downloading 7c9409d1bfb573e0cf8578f0749ead81/p-934ed733171eb46b5e06f37d5f96d10cd381ed93-f29bd8ce8c976a078e3acb5e4bdff937 from localhost/127.0.0.1:35342

2023-06-02 17:55:47,028 INFO org.apache.flink.streaming.runtime.tasks.StreamTask [] - No state backend has been configured, using default (HashMap) org.apache.flink.runtime.state.hashmap.HashMapStateBackend@2db6ef74

2023-06-02 17:55:47,029 INFO org.apache.flink.runtime.state.StateBackendLoader [] - State backend loader loads the state backend as HashMapStateBackend

2023-06-02 17:55:47,029 INFO org.apache.flink.streaming.runtime.tasks.StreamTask [] - Checkpoint storage is set to ‘jobmanager’

2023-06-02 17:55:47,032 INFO org.apache.flink.runtime.taskmanager.Task [] - Source: ob_t[5] → ConstraintEnforcer[6] → Sink: Collect table sink (1/1)#0 (1c66d1c1e00c5f06b56a81b6a0b5ed8f_cbc357ccb763df2852fee8c4fc7d55f2_0_0) switched from DEPLOYING to INITIALIZING.

2023-06-02 17:55:47,135 INFO org.apache.flink.streaming.api.operators.collect.CollectSinkFunction [] - Initializing collect sink state with offset = 0, buffered results bytes = 0

2023-06-02 17:55:47,137 INFO org.apache.flink.streaming.api.operators.collect.CollectSinkFunction [] - Collect sink server established, address = localhost/127.0.0.1:35250

2023-06-02 17:55:47,140 INFO com.ververica.cdc.connectors.oceanbase.source.OceanBaseRichSourceFunction [] - initialize checkpoint

2023-06-02 17:55:47,147 INFO org.apache.flink.runtime.taskmanager.Task [] - Source: ob_t[5] → ConstraintEnforcer[6] → Sink: Collect table sink (1/1)#0 (1c66d1c1e00c5f06b56a81b6a0b5ed8f_cbc357ccb763df2852fee8c4fc7d55f2_0_0) switched from INITIALIZING to RUNNING.

2023-06-02 17:55:47,186 INFO com.ververica.cdc.connectors.oceanbase.source.OceanBaseRichSourceFunction [] - Start to initial table whitelist

2023-06-02 17:55:47,295 INFO org.apache.flink.streaming.api.operators.collect.CollectSinkFunction [] - Coordinator connection received

2023-06-02 17:55:47,298 INFO org.apache.flink.streaming.api.operators.collect.CollectSinkFunction [] - Invalid request. Received version = , offset = 0, while expected version = 2bc88186-94bf-43f9-bf09-7b71924b60f3, offset = 0

2023-06-02 17:55:47,303 INFO com.ververica.cdc.connectors.oceanbase.source.OceanBaseRichSourceFunction [] - Start readChangeRecords process

2023-06-02 17:55:47,310 INFO com.ververica.cdc.connectors.oceanbase.source.OceanBaseRichSourceFunction [] - LogProxyClient started

2023-06-02 17:55:47,311 INFO com.oceanbase.clogproxy.client.connection.ClientStream [] - Try to reconnect

2023-06-02 17:55:47,319 INFO com.oceanbase.clogproxy.client.connection.ClientHandler [] - ClientId: 192.xx.xx.128_42920_1685699741_1_test_tenant: rootserver_list=192.xx.xx.128:2882:2881, cluster_user=test_user@test_tenant, cluster_password=******, tb_white_list=test_tenant.test_db.t, tb_black_list=|, start_timestamp=0, timezone=+00:00, working_mode=storage connecting LogProxy: 192.xx.xx130:2983

2023-06-02 17:55:47,323 INFO com.oceanbase.clogproxy.client.connection.ClientStream [] - Reconnect successfully

2023-06-02 17:55:47,613 INFO com.oceanbase.clogproxy.client.connection.ClientHandler [] - Connected to LogProxyServer, ip:192.xx.xx130, version:b18f6c7651e79c655a461eb3249461afc40cb704

OBlogproxy的日志如下：

I20230602 17:55:47.550936 45479 comm.cpp:165] On connect from '192.xx.xx.128:42678, fd: 8

I20230602 17:55:47.551990 45479 comm.cpp:232] On event fd: 8 got channel, peer: id:9292237476556308488, fd:8, addr:2163517632, port:42678

I20230602 17:55:47.555634 45479 msg_buf.cpp:117] got EOF while call next

I20230602 17:55:47.555753 45479 arranger.cpp:74] Arranger on_msg fired: id:9292237476556308488, fd:8, addr:2163517632, port:42678

I20230602 17:55:47.555797 45479 arranger.cpp:81] Handshake request from peer: id:9292237476556308488, fd:8, addr:2163517632, port:42678, msg: log_type:0, id:192.xx.xx.128_42920_1685699741_1_test_tenant, ip:192.xx.xx.128, version:1.0.5, configuration:tb_white_list=test_tenant.test_db.t cluster_user=test_user@test_tenant tb_black_list=| timezone=+00:00 working_mode=storage rootserver_list=192.xx.xx.128:2882:2881 first_start_timestamp=0 cluster_password=15CBE07988BCA4AB7F9E7B80D73571A35C0E64E5 , enable_monitor:0,

I20230602 17:55:47.556635 45479 arranger.cpp:93] ObConfig from peer: id:9292237476556308488, fd:8, addr:2163517632, port:42678 after resolve: cluster_id:,cluster_password:ob,cluster_url:,cluster_user:test_user@test_tenant,first_start_timestamp:0,first_start_timestamp_us:0,id:,rootserver_list:192.xx.xx.128:2882:2881,sys_password:,sys_user:,tb_white_list:test_tenant.test_db.t,

I20230602 17:55:47.559722 45479 io.cpp:119] Connect to server success after poll. host=192.xx.xx.128,port=2881

I20230602 17:55:47.560595 45479 mysql_protocol.cpp:51] Connect to server success: 192.xx.xx.128:2881, user: root@sys

I20230602 17:55:47.561065 45479 mysql_protocol.cpp:82] Receive handshake packet from server: 192.xx.xx.128:2881, user: root@sys

I20230602 17:55:47.561131 45479 ob_mysql_packet.cpp:256] Observer version: 5.7.25

I20230602 17:55:47.561146 45479 ob_mysql_packet.cpp:264] Connection id: 3221487688

I20230602 17:55:47.561467 45479 ob_mysql_packet.cpp:355] Auth plugin name: mysql_native_password

I20230602 17:55:47.561517 45479 ob_mysql_packet.cpp:589] Handshake response packet len: 84

I20230602 17:55:47.564536 45479 mysql_protocol.cpp:122] Auth user success of server: 192.xx.xx.128:2881, user: root@sys

I20230602 17:55:47.564685 45479 mysql_protocol.cpp:214] Query obmysql SQL:SELECT svr_min_log_timestamp FROM oceanbase.__all_virtual_server_clog_stat WHERE zone_status=‘ACTIVE’;

I20230602 17:55:47.607896 45479 ob_mysql_packet.cpp:220] Error packet: [31487][#42S02] Table ‘oceanbase.__all_virtual_server_clog_stat’ doesn’t exist

E20230602 17:55:47.608075 45479 mysql_protocol.cpp:239] Failed to query observer:Table ‘oceanbase.__all_virtual_server_clog_stat’ doesn’t exist, unexpected column count: 0

E20230602 17:55:47.611941 45479 clog_meta_routine.cpp:45] Failed to check the existence of svr_min_log_timestamp column in __all_virtual_server_clog_stat, disable clog check

I20230602 17:55:47.612952 45479 arranger.cpp:223] Client connecting: type:0, id:192.xx.xx.128_42920_1685699741_1_test_tenant, ip:192.xx.xx.128, version:1.0.5, configuration:tb_white_list=test_tenant.test_db.t cluster_user=test_user@test_tenant tb_black_list=| timezone=+00:00 working_mode=storage rootserver_list=192.xx.xx.128:2882:2881 first_start_timestamp=0 cluster_password=15CBE07988BCA4AB7F9E7B80D73571A35C0E64E5 , pid:0, peer:fd:8, register_time:1685699747, enable_monitor:0, packet_version:2,

I20230602 17:55:47.615957 45479 source_invoke.cpp:75] +++ Created oblogreader with pid: 50209

I20230602 17:55:47.616303 45479 comm.cpp:330] Try close Channel of peer: id:9292237476556308488, fd:8, addr:2163517632, port:42678

I20230602 17:55:47.616470 45479 channel.h:46] Closed fd: 8

I20230602 17:55:47.616505 45479 arranger.cpp:241] Remove peer: id:9292237476556308488, fd:8, addr:2163517632, port:42678 after source invoked, current channel count:0

I20230602 17:55:47.696375 45479 arranger.cpp:246] Client connected: 192.xx.xx.128_42920_1685699741_1_test_tenant with peer: id:9292237476556308488, fd:8, addr:2163517632, port:42678

I20230602 17:55:55.579689 45483 status_thread.cpp:47] COUNTS:[NREADER:3][NCHANNEL:0]

I20230602 17:55:56.596902 45483 status_thread.cpp:64] METRICS:[MEM:2160/3770MB,57.29%][UDISK:9644/39195MB,24.61%][CPU:4,37.1%][LOAD1,5:29%,11%][NETIO:0KB/s,0KB/s]

I20230602 17:56:06.597560 45483 status_thread.cpp:47] COUNTS:[NREADER:3][NCHANNEL:0]

I20230602 17:56:07.141376 45483 status_thread.cpp:64] METRICS:[MEM:2646/3770MB,70.18%][UDISK:9649/39196MB,24.62%][CPU:4,25.8%][LOAD1,5:40%,14%][NETIO:0KB/s,0KB/s]

I20230602 17:56:17.142030 45483 status_thread.cpp:47] COUNTS:[NREADER:3][NCHANNEL:0]

I20230602 17:56:17.737087 45483 status_thread.cpp:64] METRICS:[MEM:2675/3770MB,70.96%][UDISK:9650/39196MB,24.62%][CPU:4,3.763%][LOAD1,5:34%,14%][NETIO:0KB/s,0KB/s]

I20230602 17:56:27.737541 45483 status_thread.cpp:47] COUNTS:[NREADER:3][NCHANNEL:0]

I20230602 17:56:28.341439 45483 status_thread.cpp:64] METRICS:[MEM:2677/3770MB,71%][UDISK:9651/39196MB,24.62%][CPU:4,5.698%][LOAD1,5:66%,22%][NETIO:0KB/s,0KB/s]

I20230602 17:56:38.341936 45483 status_thread.cpp:47] COUNTS:[NREADER:3][NCHANNEL:0]

I20230602 17:56:38.905058 45483 status_thread.cpp:64] METRICS:[MEM:2679/3770MB,71.05%][UDISK:9653/39196MB,24.63%][CPU:4,1.884%][LOAD1,5:55%,21%][NETIO:0KB/s,0KB/s]

I20230602 17:56:48.906113 45483 status_thread.cpp:47] COUNTS:[NREADER:3][NCHANNEL:0]

I20230602 17:56:49.453445 45483 status_thread.cpp:64] METRICS:[MEM:2681/3770MB,71.12%][UDISK:9653/39196MB,24.63%][CPU:4,3.258%][LOAD1,5:63%,23%][NETIO:0KB/s,0KB/s]

I20230602 17:56:59.454030 45483 status_thread.cpp:47] COUNTS:[NREADER:3][NCHANNEL:0]

I20230602 17:57:00.014168 45483 status_thread.cpp:64] METRICS:[MEM:2683/3770MB,71.17%][UDISK:9652/39196MB,24.62%][CPU:4,4.468%][LOAD1,5:61%,24%][NETIO:0KB/s,0KB/s]

I20230602 17:57:10.015143 45483 status_thread.cpp:47] COUNTS:[NREADER:3][NCHANNEL:0]

I20230602 17:57:10.565342 45483 status_thread.cpp:64] METRICS:[MEM:2686/3770MB,71.23%][UDISK:9652/39196MB,24.62%][CPU:4,3.846%][LOAD1,5:51%,24%][NETIO:0KB/s,0KB/s]

^[A^[OP^[OPI20230602 17:57:20.565994 45483 status_thread.cpp:47] COUNTS:[NREADER:3][NCHANNEL:0]

秃蛙 · 2023 年6 月 5 日 09:56

问题已解决。

[(none)]>show variables like ‘%bin%’;
±-----------------------------±--------+
| Variable_name | Value |
±-----------------------------±--------+
| binlog_checksum | CRC32 |
| binlog_format | ROW |
| binlog_rows_query_log_events | OFF |
| binlog_row_image | MINIMAL |
| log_bin | ON |
| recyclebin | OFF |
±-----------------------------±--------+

这个业务租户开启了非全列日志，
| binlog_row_image | MINIMAL |
目前不支持同步非全列日志，需要改为全列日志，在对应租户下执行下面的SQL：set global binlog_row_image=‘FULL’;

光明 · 2023 年6 月 5 日 09:58

问题解决了，是因为之前做压力测试的时候，把租户级别的binlog的full模式关闭了，开启后同步就正常了。
Copyright (c) 2000, 2018, Oracle, MariaDB Corporation Ab and others.

Type ‘help;’ or ‘\h’ for help. Type ‘\c’ to clear the current input statement.

MySQL [(none)]>
MySQL [(none)]>
MySQL [(none)]> show variables like ‘%bin%’;
±-----------------------------±------+
| Variable_name | Value |
±-----------------------------±------+
| binlog_checksum | CRC32 |
| binlog_format | ROW |
| binlog_rows_query_log_events | OFF |
| binlog_row_image | FULL |
| log_bin | ON |
| recyclebin | OFF |
±-----------------------------±------+

另外

1135 2023-06-05 09:48:16 tail -100f logproxy_error.20230602-160620.10497E20230605 08:51:58.187914 10497 mysql_protocol.cpp:239] Failed to query observer:Table ‘oceanbase.__all_virtual_server_clog_stat’ doesn’t exist, unexpected column count: 0
E20230605 08:51:58.187986 10497 clog_meta_routine.cpp:45] Failed to check the existence of svr_min_log_timestamp column in __all_virtual_server_clog_stat, disable clog check

这个报错不影响同步，后续这个错误会被修复