今天是第一次写博，在OB工作也有一段时间了，国产数据库相对于oracle，mysql这些可能在排查难度方面可能是较高，但是也有一定的技巧。每天处理过的应用断连问题也有一定的量，全链路诊断其实是一个比较复杂的过程，在可能无法判断的时候，抓包是一个很重要的手段，但是断链一般是偶现，抓包的困难性较大。所以断链问题ob这边会jdbc生成一个cs_id保证链路的完整性。但是有时候会吞掉或者一些情况不反悔cs_id，在无cs_id的情况我们该如何分析？这个是一个很大的问题，对于dba也好，交付也好，证据链的一致性是很重要的一件事，不然可能会导致一些排查方向走歪，或者直接无用功的情况。这边分享一个分析处理一个应用断链无cs_id分析的案例。
问题背景：
OB版本：4.2.1.1_101010022023110921-5d0b2ec58d7661e382f65d3753b65f3a914f89ec
OBPROXY版本：4.2.1.0-20240229214253
JDBC版本：未收集
jdbc:oceanbase://db.bcs.vt1:2883/ENS_TAE003?serverTimezone=Asia/Shanghai&useUnicode=true&characterEncoding=utf8&rewriteBatchedStatements=true&allowMultiQueries=true&useLocalSessionState=true
链路情况：应用服务器->SLB(2台)->obproxy(8台)-observer(8台) （每个F5下面挂四台 obproxy）
应用偶发性断链
应用断链报错 unexpected end of stream, read 0 bytes from 4，顶端报错语句UPDATE BS_MQ_CHECK SET SEQ_NO = ?, CHANNEL = ?, TRAN_DATE = ?, AC_NUM = ?, AC_AMOUNT = ?, NUM = ?, AMOUNT = ?, EQUAL_FLAG = ?, HIST_TYPE = ? WHERE SEQ_NO = ? AND TRAN_DATE = ?，如下
#2024-07-05 15:43:15.188 [smartgl-batch] [172.3.98.95:14083,a2e14b8e233641e7937a323a8b94da8c,3606119e120141208c4dfe52f2ce8885] [SONIC-default-step-executor-9-T2] ERROR druid.sql.Statement ? - {conn-10031, pstmt-97831} execute error. UPDATE BS_MQ_CHECK SET SEQ_NO = ?, CHANNEL = ?, TRAN_DATE = ?, AC_NUM = ?, AC_AMOUNT = ?, NUM = ?, AMOUNT = ?, EQUAL_FLAG = ?, HIST_TYPE = ? WHERE SEQ_NO = ? AND TRAN_DATE = ?
java.lang.NullPointerException: null
at com.oceanbase.jdbc.OceanBaseStatement.executeBatchExceptionEpilogue(OceanBaseStatement.java:404)
at com.oceanbase.jdbc.OceanBaseStatement.executeBatchExceptionEpilogue(OceanBaseStatement.java:451)
at com.oceanbase.jdbc.JDBC4PreparedStatement.executeBatch(JDBC4PreparedStatement.java:341)
at com.alibaba.druid.filter.FilterChainImpl.statement_executeBatch(FilterChainImpl.java:3118)
at com.alibaba.druid.filter.FilterAdapter.statement_executeBatch(FilterAdapter.java:2507)
at com.alibaba.druid.filter.FilterEventAdapter.statement_executeBatch(FilterEventAdapter.java:279)
at com.alibaba.druid.filter.FilterChainImpl.statement_executeBatch(FilterChainImpl.java:3116)
at com.alibaba.druid.proxy.jdbc.StatementProxyImpl.executeBatch(StatementProxyImpl.java:202)
at com.alibaba.druid.pool.DruidPooledPreparedStatement.executeBatch(DruidPooledPreparedStatement.java:565)
at org.apache.ibatis.executor.BatchExecutor.doFlushStatements(BatchExecutor.java:123)
at org.apache.ibatis.executor.BaseExecutor.flushStatements(BaseExecutor.java:129)
at org.apache.ibatis.executor.BaseExecutor.flushStatements(BaseExecutor.java:122)
at org.apache.ibatis.session.defaults.DefaultSqlSession.flushStatements(DefaultSqlSession.java:252)
at com.dcits.comet.dao.mybatis.DaoSupportImpl.updateAddBatch(DaoSupportImpl.java:281)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at com.dcits.comet.dao.DaoCglibProxy.intercept(DaoCglibProxy.java:137)
at com.dcits.comet.dao.DaoSupport$$EnhancerByCGLIB$$ba918808.updateAddBatch(<generated>)
at com.dcits.accounting.engine.dao.impl.BaseDaoSupportAc.updateAddBatch(BaseDaoSupportAc.java:532)
at com.dcits.accounting.engine.dao.impl.BaseDaoSupportAc$$FastClassBySpringCGLIB$$b94824dd.invoke(<generated>)
at org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:218)
at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.invokeJoinpoint(CglibAopProxy.java:793)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:163)
at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:763)
at org.springframework.dao.support.PersistenceExceptionTranslationInterceptor.invoke(PersistenceExceptionTranslationInterceptor.java:137)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:763)
at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:708)
at com.dcits.accounting.engine.dao.impl.BsMqCheckDao$$EnhancerBySpringCGLIB$$287f594e.updateAddBatch(<generated>)
at com.dcits.accounting.job.service.eodfile.error.BatchInpErrorStep.exe(BatchInpErrorStep.java:111)
at com.dcits.comet.batch.engine.execute.TStepExecutor.execute(TStepExecutor.java:34)
at com.dcits.comet.batch.engine.CometStepLauncher.run(CometStepLauncher.java:66)
at com.dcits.comet.batch.engine.CometStepLauncher$$FastClassBySpringCGLIB$$87894d54.invoke(<generated>)
at org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:218)
at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.invokeJoinpoint(CglibAopProxy.java:793)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:163)
at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:763)
at com.dcits.track.ensemble.aop.StepAspect.invoke(StepAspect.java:28)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:763)
at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:97)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:763)
at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:708)
at com.dcits.comet.batch.engine.CometStepLauncher$$EnhancerBySpringCGLIB$$1cf2726f.run(<generated>)
at com.dcits.comet.batch.sonic.NormalBatchExecutor.execute(NormalBatchExecutor.java:53)
at com.dcits.comet.batch.sonic.NormalBatchExecutor.execute(NormalBatchExecutor.java:27)
at com.dcits.sonic.executor.step.SonicExecutorManager.startStep(SonicExecutorManager.java:96)
at com.dcits.sonic.executor.step.SonicExecutorManager.lambda$start$0(SonicExecutorManager.java:69)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:748)
Caused by: com.oceanbase.jdbc.internal.util.exceptions.OceanBaseSqlException: unexpected end of stream, read 0 bytes from 4
at com.oceanbase.jdbc.internal.util.exceptions.OceanBaseSqlException.of(OceanBaseSqlException.java:79)
at com.oceanbase.jdbc.internal.protocol.AbstractQueryProtocol.executeBatchRewrite(AbstractQueryProtocol.java:1252)
at com.oceanbase.jdbc.internal.protocol.AbstractQueryProtocol.executeBatchClient(AbstractQueryProtocol.java:704)
at com.oceanbase.jdbc.JDBC4PreparedStatement.executeInternalBatch(JDBC4PreparedStatement.java:456)
at com.oceanbase.jdbc.JDBC4PreparedStatement.executeBatch(JDBC4PreparedStatement.java:326)
... 51 common frames omitted
Caused by: java.sql.SQLNonTransientConnectionException: unexpected end of stream, read 0 bytes from 4
at com.oceanbase.jdbc.internal.protocol.AbstractQueryProtocol.handleIoException(AbstractQueryProtocol.java:2737)
at com.oceanbase.jdbc.internal.protocol.AbstractQueryProtocol.readPacket(AbstractQueryProtocol.java:2211)
at com.oceanbase.jdbc.internal.protocol.AbstractQueryProtocol.getResult(AbstractQueryProtocol.java:2115)
at com.oceanbase.jdbc.internal.protocol.AbstractQueryProtocol.executeBatchRewrite(AbstractQueryProtocol.java:1244)
... 54 common frames omitted
Caused by: java.io.EOFException: unexpected end of stream, read 0 bytes from 4
at com.oceanbase.jdbc.internal.io.input.StandardPacketInputStream.readMysqlStream(StandardPacketInputStream.java:164)
at com.oceanbase.jdbc.internal.io.input.StandardPacketInputStream.getPacketArray(StandardPacketInputStream.java:113)
at com.oceanbase.jdbc.internal.io.input.StandardPacketInputStream.getPacket(StandardPacketInputStream.java:100)
at com.oceanbase.jdbc.internal.protocol.AbstractQueryProtocol.readPacket(AbstractQueryProtocol.java:2209)
... 56 common frames omitted
问题处理过程：
unexpected end of stream, read 0 bytes from 4一般指远端断开（即非client节点）因为无cs_id且无明显报错情况下，有两种方法推测obproxy断链ip，通过语句关键词过滤断链时间点的所有obproxy日志（此情况有一定的误差性），还有就是抓包判断断链ip和断链端口。
第一种方式（过滤所有obproxy节点的异常时间点日志）：
huangzhihao@U-WML2G6Q9-1902 信息 % grep 'UPDATE BS_MQ_CHECK SET SEQ_NO' obproxy.log.202407051*
obproxy.log.20240705154325:[2024-07-05 15:42:13.858996] INFO [PROXY.TXN] ob_mysql_transact.cpp:5781 [57488][Y0-00007F10639BE9B0] [lt=5] [dc=0] [ObMysqlTransact::handle_server_connection_break]((client_ip={172.1.74.240:39540}, server_ip={172.1.74.28:2881}, cs_id=2820645, proxy_sessid=12394269125218921778, ss_id=0, server_sessid=0, sm_id=1479459, proxy_user_name=ENS_GL@sx_gl_prod#VT1, database_name=ENS_GL, server_state="INTERNAL_ERROR", request_cmd="Query", sql_cmd="Query", sql=UPDATE BS_MQ_CHECK SET SEQ_NO = '801', CHANNEL = 'OB', TRAN_DATE = TO_DATE('2024-12-31 00:00:00','YYYY-MM-DD HH24:MI:SS'), AC_NUM = 6, AC_AMOUNT = 6, NUM = 6, AMOUNT = 6, EQUAL_FLAG = 'Y', HIST_TYPE = 'TRAN' WHERE SEQ_NO = '801' AND TRAN_DATE = TO_DATE('2024-12-31 00:00:00','YYYY-MM-DD HH24:MI:SS');UPDATE BS_MQ_CHECK SET SEQ_NO = '802', CHANNEL = 'RB', TRAN_DATE = TO_DATE('2024-12-31 00:00:00','YYYY-MM-DD HH24:MI:SS'), AC_NUM = 812682, AC_AMOUNT = 3940701539.94, NUM = 812664, AMOUNT = 3940694469.54, EQUAL_FLAG = 'N', HIST_TYPE = 'TRAN' WHERE SEQ_NO = '802' AND TRAN_DATE = TO_DATE('2024-12-31 00:00:00','YYYY-MM-DD HH24:MI:SS'))
obproxy.log.20240705154325:[2024-07-05 15:42:13.859024] WARN [PROXY.SM] setup_error_transfer (ob_mysql_sm.cpp:9016) [57488][Y0-00007F10639BE9B0] [lt=4] [dc=0] [setup_error_transfer] Now closing connection(sm_id=1479459, client_ip={172.1.74.240:39540}, request_cmd="Query", sql_cmd="Query", sql=UPDATE BS_MQ_CHECK SET SEQ_NO = '801', CHANNEL = 'OB', TRAN_DATE = TO_DATE('2024-12-31 00:00:00','YYYY-MM-DD HH24:MI:SS'), AC_NUM = 6, AC_AMOUNT = 6, NUM = 6, AMOUNT = 6, EQUAL_FLAG = 'Y', HIST_TYPE = 'TRAN' WHERE SEQ_NO = '801' AND TRAN_DATE = TO_DATE('2024-12-31 00:00:00','YYYY-MM-DD HH24:MI:SS');UPDATE BS_MQ_CHECK SET SEQ_NO = '802', CHANNEL = 'RB', TRAN_DATE = TO_DATE('2024-12-31 00:00:00','YYYY-MM-DD HH24:MI:SS'), AC_NUM = 812682, AC_AMOUNT = 3940701539.94, NUM = 812664, AMOUNT = 3940694469.54, EQUAL_FLAG = 'N', HIST_TYPE = 'TRAN' WHERE SEQ_NO = '802' AND TRAN_DATE = TO_DATE('2024-12-31 00:00:00','YYYY-MM-DD HH24:MI:SS'))
huangzhihao@U-WML2G6Q9-1902 信息 % grep '00007F10639BE9B0' obproxy.log.202407051* > 00007F10639BE9B0通过trace_id导出到文件中，且cs_id=2820645，trace_id=Y0-00007F10639BE9B0
obproxy.log.20240705154325:[2024-07-05 15:42:10.489018] INFO [PROXY.SS] ob_mysql_server_session.cpp:106 [57488][Y0-00007F10639BE9B0] [lt=9] [dc=0] server session born(ss_id=17793575, server_ip={172.1.74.28:2881}, cs_id=2820645, proxy_sessid=12394269125218921778, server_type=2)
obproxy.log.20240705154325:[2024-07-05 15:42:10.489769] INFO [PROXY] ob_proxy_session_info_handler.cpp:746 [57488][Y0-00007F10639BE9B0] [lt=12] [dc=0] succ to set ob_capability_flag in negotiation(client_cap=72, server_cap=916295, orig_client_cap=72, orig_server_cap=916295, client_support_ob_v2=false, server_support_checksum=false, server_support_ob_v2=true, is_auth_request=false)
obproxy.log.20240705154325:[2024-07-05 15:42:10.492553] INFO [PROXY.TXN] ob_mysql_transact.cpp:4455 [57488][Y0-00007F10639BE9B0] [lt=11] [dc=0] received reroute error, mayby need reroute((addr={172.1.74.28:2881}, pll_info={pl_attempts:1, lookup_success:true, force_renew_state:0, cached_dummy_entry_renew_state:0, te_name:{cluster_name:"VT1", tenant_name:"sx_gl_prod", database_name:"ENS_GL", package_name:"", table_name:"BS_MQ_CHECK"}, route:{consistency_level:"STRONG", cur_chosen_route_type:"ROUTE_TYPE_LEADER", cur_chosen_server:{idc_type:"", zone_type:"Invalid", replica:{server:"172.1.74.28:2881", is_dup_replica:false, role:"LEADER", type:"FULL"}, is_merging:false, is_partition_server:false, is_force_congested:false, is_used:false}, cur_chosen_pl:null, valid_count:0, leader_item:{idc_type:"", zone_type:"Invalid", replica:NULL, is_merging:false, is_partition_server:false, is_force_congested:false, is_used:true}, ldc_route:{policy:"", disable_merge_status_check:true, curr_cursor_index:0, next_index_in_site:0, location:{use_ldc:false, idc_name:"", item_count:0, site_start_index_array:[[0]0, [1]0, [2]0, [3]0], item_array:null, pl:null, ts:null, readonly_exist_status:"READONLY_ZONE_UNKNOWN"}}, is_table_entry_from_remote:false, is_part_entry_from_remote:false, need_use_dup_replica:false, table_entry:0x7f10b5466ad0, part_entry:null, dummy_entry:null, skip_leader_item:true}}, state="RESPONSE_ERROR", error_type="REQUEST_REROUTE_ERROR", reroute_info={schema_version:1716880025076472, replica:{server:"172.1.74.26:2881", is_dup_replica:false, role:"LEADER", type:"FULL"}, table_name_buf:"BS_MQ_CHECK"})
obproxy.log.20240705154325:[2024-07-05 15:42:10.492600] INFO [PROXY.TXN] ob_mysql_transact.cpp:4525 [57488][Y0-00007F10639BE9B0] [lt=47] [dc=0] get err pkt from observer, not forward to client, will be consumed soon, and maybe need retry(send_action="SERVER_SEND_REQUEST", state="RESPONSE_ERROR", error_type="REQUEST_REROUTE_ERROR", resp={is_trans_completed:true, is_resp_completed:true, ending_type:2, is_partition_hit:true, has_new_sys_var:false, has_proxy_idc_name_user_var:false, is_server_db_reset:false, reserved_len:0, connection_id:0, scramble_buf:"", is_resultset_resp:false, server_capabilities_lower_.capability:0, ok_packet_action_type:2, last_ok_pkt_len:175, rewritten_last_ok_pkt_len:0, extra_info:{is_exist_sess_info:false, sess_info_count:0, extra_len:0}, error_pkt:field_count:255, errcode:5727, sqlstate:"HY000", message:"ORA-00600: internal error code, arguments: -5727, SQL request should be rerouted"})
obproxy.log.20240705154325:[2024-07-05 15:42:10.492616] INFO [PROXY.TXN] ob_mysql_transact.cpp:1828 [57488][Y0-00007F10639BE9B0] [lt=13] [dc=0] will set strong read route dirty((is_leader=true, has_table_but_no_leader=false, origin_name={cluster_name:"VT1", tenant_name:"sx_gl_prod", database_name:"ENS_GL", package_name:"", table_name:"BS_MQ_CHECK"}, route_info={consistency_level:"STRONG", cur_chosen_route_type:"ROUTE_TYPE_LEADER", cur_chosen_server:{idc_type:"", zone_type:"Invalid", replica:{server:"172.1.74.28:2881", is_dup_replica:false, role:"LEADER", type:"FULL"}, is_merging:false, is_partition_server:false, is_force_congested:false, is_used:false}, cur_chosen_pl:null, valid_count:0, leader_item:{idc_type:"", zone_type:"Invalid", replica:NULL, is_merging:false, is_partition_server:false, is_force_congested:false, is_used:true}, ldc_route:{policy:"", disable_merge_status_check:true, curr_cursor_index:0, next_index_in_site:0, location:{use_ldc:false, idc_name:"", item_count:0, site_start_index_array:[[0]0, [1]0, [2]0, [3]0], item_array:null, pl:null, ts:null, readonly_exist_status:"READONLY_ZONE_UNKNOWN"}}, is_table_entry_from_remote:false, is_part_entry_from_remote:false, need_use_dup_replica:false, table_entry:0x7f10b5466ad0, part_entry:null, dummy_entry:null, skip_leader_item:true})
obproxy.log.20240705154325:[2024-07-05 15:42:10.492644] INFO [PROXY] ob_server_route.h:621 [57488][Y0-00007F10639BE9B0] [lt=27] [dc=0] this table entry will set to dirty and wait for update((is_need_force_flush=false, table_entry={{this:0x7f10b5466ad0, ref_count:5, cr_version:2, cr_id:0, create_time_us:1719968464960164, last_valid_time_us:1719968465390000, last_access_time_us:1720165330488911, last_update_time_us:0, schema_version:1716880025076472, tenant_version:2607672812506004230, time_for_expired:0, state:"DIRTY"}, this:0x7f10b5466ad0, is_inited:true, is_dummy_entry:false, is_entry_from_rslist:false, is_empty_entry_allowed:false, is_need_force_flush:false, has_dup_replica:false, cr_id:0, name:{cluster_name:"VT1", tenant_name:"sx_gl_prod", database_name:"ENS_GL", package_name:"", table_name:"BS_MQ_CHECK"}, table_id:502627, table_type:"USER TABLE", part_num:1, replica_num:4, buf_len:30, buf_start:0x7f10b5466bd8, first_pl:{replica_count:4, locations:[[0]{server:"172.1.74.28:2881", is_dup_replica:false, role:"LEADER", type:"FULL"}, [1]{server:"172.1.74.26:2881", is_dup_replica:false, role:"FOLLOWER", type:"FULL"}, [2]{server:"172.3.74.26:2881", is_dup_replica:false, role:"FOLLOWER", type:"FULL"}, [3]{server:"172.3.74.29:2881", is_dup_replica:false, role:"FOLLOWER", type:"FULL"}]}})
obproxy.log.20240705154325:[2024-07-05 15:42:10.492679] INFO [PROXY.TXN] ob_mysql_transact.cpp:5464 [57488][Y0-00007F10639BE9B0] [lt=29] [dc=0] pre try failed, will retry((retry_status=FOUND_EXISTING_ADDR, attempts now=2, max_connect_attempts=3, old_target_server={172.1.74.28:2881}, retry server={172.1.74.26:2881}, is_first_request=true, is_auth_request=false, is_force_renew=false, force_retry_congested=false, send_action="SERVER_SEND_REQUEST", state="RESPONSE_ERROR", route={consistency_level:"STRONG", cur_chosen_route_type:"ROUTE_TYPE_LEADER", cur_chosen_server:{idc_type:"", zone_type:"Invalid", replica:{server:"172.1.74.28:2881", is_dup_replica:false, role:"LEADER", type:"FULL"}, is_merging:false, is_partition_server:false, is_force_congested:false, is_used:false}, cur_chosen_pl:null, valid_count:0, leader_item:{idc_type:"", zone_type:"Invalid", replica:NULL, is_merging:false, is_partition_server:false, is_force_congested:false, is_used:true}, ldc_route:{policy:"", disable_merge_status_check:true, curr_cursor_index:0, next_index_in_site:0, location:{use_ldc:false, idc_name:"", item_count:0, site_start_index_array:[[0]0, [1]0, [2]0, [3]0], item_array:null, pl:null, ts:null, readonly_exist_status:"READONLY_ZONE_UNKNOWN"}}, is_table_entry_from_remote:false, is_part_entry_from_remote:false, need_use_dup_replica:false, table_entry:0x7f10b5466ad0, part_entry:null, dummy_entry:null, skip_leader_item:true}, is_reroute_to_coordinator=false, is_in_trans=false, is_internal_routing=true, s.congestion_entry={ref_count:130, this:0x7f10b19f75e0, zone_state:{ref_count:3, this:0x7f10b19ed800, zone_name:"zone2", region_name:"SX", state:"ACTIVE", last_revalidate_time_us:1719628177414180}, server_ip:{172.1.74.28:2881}, server_state:"DETECT_ALIVE", entry_state:"ENTRY_AVAIL", alive_congested:0, last_alive_congested:1719913808, last_revalidate_time_us:1720165330351017, dead_congested:0, detect_congested:0, stat_alive_failures:48026, stat_conn_failures:0, cr_version:2, conn_last_fail_time=0, conn_failure_events=0, alive_last_fail_time=1719931523, alive_failure_events=1})
obproxy.log.20240705154325:[2024-07-05 15:42:10.501887] WARN [COMMON] get_part (ob_part_desc_hash.cpp:60) [57488][Y0-00007F10639BE9B0] [lt=37] [dc=0] not support hash partition calc with range(range={"range":"table_id:null,(MIN;MAX)"})
obproxy.log.20240705154325:[2024-07-05 15:42:10.501900] WARN [PROXY] do_partition_id_calc (obproxy_expr_calculator.cpp:322) [57488][Y0-00007F10639BE9B0] [lt=12] [dc=0] fail to get first part(ret=-4002)
obproxy.log.20240705154325:[2024-07-05 15:42:10.501905] INFO [PROXY] ob_mysql_route.cpp:654 [57488][Y0-00007F10639BE9B0] [lt=3] [dc=0] fail to calculate partition id, just use tenant server(tmp_ret=-4002)
obproxy.log.20240705154325:[2024-07-05 15:42:11.986344] WARN [PROXY.SM] update_cmd_stats (ob_mysql_sm.cpp:10248) [57488][Y0-00007F10639BE9B0] [lt=3] [dc=0] Slow Query: ((client_ip={172.1.74.240:39540}, server_ip={172.1.74.26:2881}, obproxy_client_port={172.1.74.26:20006}, server_trace_id=YB42AC014A1A-00061BF31DF3E3B5-0-0, route_type=ROUTE_TYPE_NONPARTITION_UNMERGE_LOCAL, user_name=ENS_GL, tenant_name=sx_gl_prod, cluster_name=VT1, logic_database_name=, logic_tenant_name=, ob_proxy_protocol=0, cs_id=2820645, proxy_sessid=12394269125218921778, ss_id=17029174, server_sessid=3221513397, sm_id=1479459, cmd_size_stats={client_request_bytes:269, server_request_bytes:304, server_response_bytes:0, client_response_bytes:92}, cmd_time_stats={client_transaction_idle_time_us=0, client_request_read_time_us=12, client_request_analyze_time_us=11, cluster_resource_create_time_us=0, pl_lookup_time_us=49, pl_process_time_us=9, bl_lookup_time_us=0, bl_process_time_us=0, congestion_control_time_us=1, congestion_process_time_us=0, do_observer_open_time_us=1, server_connect_time_us=0, server_sync_session_variable_time_us=0, server_send_saved_login_time_us=0, server_send_use_database_time_us=0, server_send_session_variable_time_us=0, server_send_session_user_variable_time_us=0, server_send_all_session_variable_time_us=0, server_send_start_trans_time_us=0, server_send_xa_start_time_us=0, server_send_init_sql_time_us=0, build_server_request_time_us=2, plugin_compress_request_time_us=0, prepare_send_request_to_server_time_us=80, server_request_write_time_us=12, server_process_request_time_us=1484291, server_response_read_time_us=12, plugin_decompress_response_time_us=9, server_response_analyze_time_us=6, ok_packet_trim_time_us=0, client_response_write_time_us=53, request_total_time_us=1484491}, sql=/*sets:allsets*/ SELECT sum(1) as num,sum(case when reversal = 'Y' THEN -AMOUNT ELSE AMOUNT END) as amount FROM BS_GL_TRAN_HIST where tran_date = TO_DATE('2024-12-31 00:00:00','YYYY-MM-DD HH24:MI:SS') and SEND_SYSTEM = 'OB' and DATA_FLAG = 'INP' group by DATA_FLAG, trans_internal_routing_state=not in trans)
obproxy.log.20240705154325:[2024-07-05 15:42:11.986423] WARN [PROXY.SM] update_stats (ob_mysql_sm.cpp:10375) [57488][Y0-00007F10639BE9B0] [lt=2] [dc=0] Slow transaction: ((client_ip={172.1.74.240:39540}, server_ip={172.1.74.26:2881}, server_trace_id=YB42AC014A1A-00061BF31DF3E3B5-0-0, route_type=ROUTE_TYPE_NONPARTITION_UNMERGE_LOCAL, ob_proxy_protocol=0, cs_id=2820645, proxy_sessid=12394269125218921778, ss_id=17029174, server_sessid=3221513397, sm_id=1479459, state=10, trans_stats_={client_requests:1, server_responses:1, pl_lookup_retries:0, server_retries:0, client_request_bytes:269, server_request_bytes:304, server_response_bytes:0, client_response_bytes:92, client_transaction_idle_time_us=0, client_process_request_time_us=25, client_request_read_time_us=12, client_request_analyze_time_us=11, cluster_resource_create_time_us=0, pl_lookup_time_us=49, pl_process_time_us=9, congestion_control_time_us=1, congestion_process_time_us=0, do_observer_open_time_us=1, server_connect_time_us=0, sync_session_variable_time_us=0, send_saved_login_time_us=0, send_use_database_time_us=0, send_session_vars_time_us=0, send_session_user_vars_time_us=0, send_all_session_vars_time_us=0, send_start_trans_time_us=0, send_xa_start_time_us=0, build_server_request_time_us=2, plugin_compress_request_time_us=0, prepare_send_request_to_server_time_us=80, server_request_write_time_us=12, server_process_request_time_us=1484291, server_response_read_time_us=12, plugin_decompress_response_time_us=9, server_response_analyze_time_us=6, ok_packet_trim_time_us=0, client_response_write_time_us=53, trans_time_us=1484577}, last_sql=/*sets:allsets*/ SELECT sum(1) as num,sum(case when reversal = 'Y' THEN -AMOUNT ELSE AMOUNT END) as amount FROM BS_GL_TRAN_HIST where tran_date = TO_DATE('2024-12-31 00:00:00','YYYY-MM-DD HH24:MI:SS') and SEND_SYSTEM = 'OB' and DATA_FLAG = 'INP' group by DATA_FLAG)
obproxy.log.20240705154325:[2024-07-05 15:42:11.989891] WARN [COMMON] get_part (ob_part_desc_hash.cpp:60) [57488][Y0-00007F10639BE9B0] [lt=22] [dc=0] not support hash partition calc with range(range={"range":"table_id:null,(MIN;MAX)"})
obproxy.log.20240705154325:[2024-07-05 15:42:11.989905] WARN [PROXY] do_partition_id_calc (obproxy_expr_calculator.cpp:322) [57488][Y0-00007F10639BE9B0] [lt=14] [dc=0] fail to get first part(ret=-4002)
obproxy.log.20240705154325:[2024-07-05 15:42:11.989912] INFO [PROXY] ob_mysql_route.cpp:654 [57488][Y0-00007F10639BE9B0] [lt=6] [dc=0] fail to calculate partition id, just use tenant server(tmp_ret=-4002)
obproxy.log.20240705154325:[2024-07-05 15:42:13.846153] WARN [PROXY.SM] update_cmd_stats (ob_mysql_sm.cpp:10248) [57488][Y0-00007F10639BE9B0] [lt=3] [dc=0] Slow Query: ((client_ip={172.1.74.240:39540}, server_ip={172.1.74.26:2881}, obproxy_client_port={172.1.74.26:20006}, server_trace_id=YB42AC014A1A-00061BF31B386199-0-0, route_type=ROUTE_TYPE_NONPARTITION_UNMERGE_LOCAL, user_name=ENS_GL, tenant_name=sx_gl_prod, cluster_name=VT1, logic_database_name=, logic_tenant_name=, ob_proxy_protocol=0, cs_id=2820645, proxy_sessid=12394269125218921778, ss_id=17029174, server_sessid=3221513397, sm_id=1479459, cmd_size_stats={client_request_bytes:269, server_request_bytes:304, server_response_bytes:0, client_response_bytes:109}, cmd_time_stats={client_transaction_idle_time_us=0, client_request_read_time_us=18, client_request_analyze_time_us=16, cluster_resource_create_time_us=0, pl_lookup_time_us=59, pl_process_time_us=16, bl_lookup_time_us=0, bl_process_time_us=0, congestion_control_time_us=3, congestion_process_time_us=0, do_observer_open_time_us=2, server_connect_time_us=0, server_sync_session_variable_time_us=0, server_send_saved_login_time_us=0, server_send_use_database_time_us=0, server_send_session_variable_time_us=0, server_send_session_user_variable_time_us=0, server_send_all_session_variable_time_us=0, server_send_start_trans_time_us=0, server_send_xa_start_time_us=0, server_send_init_sql_time_us=0, build_server_request_time_us=3, plugin_compress_request_time_us=0, prepare_send_request_to_server_time_us=107, server_request_write_time_us=18, server_process_request_time_us=1856044, server_response_read_time_us=16, plugin_decompress_response_time_us=11, server_response_analyze_time_us=13, ok_packet_trim_time_us=0, client_response_write_time_us=30, request_total_time_us=1856300}, sql=/*sets:allsets*/ SELECT sum(1) as num,sum(case when reversal = 'Y' THEN -AMOUNT ELSE AMOUNT END) as amount FROM BS_GL_TRAN_HIST where tran_date = TO_DATE('2024-12-31 00:00:00','YYYY-MM-DD HH24:MI:SS') and SEND_SYSTEM = 'RB' and DATA_FLAG = 'INP' group by DATA_FLAG, trans_internal_routing_state=not in trans)
obproxy.log.20240705154325:[2024-07-05 15:42:13.846251] WARN [PROXY.SM] update_stats (ob_mysql_sm.cpp:10375) [57488][Y0-00007F10639BE9B0] [lt=3] [dc=0] Slow transaction: ((client_ip={172.1.74.240:39540}, server_ip={172.1.74.26:2881}, server_trace_id=YB42AC014A1A-00061BF31B386199-0-0, route_type=ROUTE_TYPE_NONPARTITION_UNMERGE_LOCAL, ob_proxy_protocol=0, cs_id=2820645, proxy_sessid=12394269125218921778, ss_id=17029174, server_sessid=3221513397, sm_id=1479459, state=10, trans_stats_={client_requests:1, server_responses:1, pl_lookup_retries:0, server_retries:0, client_request_bytes:269, server_request_bytes:304, server_response_bytes:0, client_response_bytes:109, client_transaction_idle_time_us=0, client_process_request_time_us=36, client_request_read_time_us=18, client_request_analyze_time_us=16, cluster_resource_create_time_us=0, pl_lookup_time_us=59, pl_process_time_us=16, congestion_control_time_us=3, congestion_process_time_us=0, do_observer_open_time_us=2, server_connect_time_us=0, sync_session_variable_time_us=0, send_saved_login_time_us=0, send_use_database_time_us=0, send_session_vars_time_us=0, send_session_user_vars_time_us=0, send_all_session_vars_time_us=0, send_start_trans_time_us=0, send_xa_start_time_us=0, build_server_request_time_us=3, plugin_compress_request_time_us=0, prepare_send_request_to_server_time_us=107, server_request_write_time_us=18, server_process_request_time_us=1856044, server_response_read_time_us=16, plugin_decompress_response_time_us=11, server_response_analyze_time_us=13, ok_packet_trim_time_us=0, client_response_write_time_us=30, trans_time_us=1856414}, last_sql=/*sets:allsets*/ SELECT sum(1) as num,sum(case when reversal = 'Y' THEN -AMOUNT ELSE AMOUNT END) as amount FROM BS_GL_TRAN_HIST where tran_date = TO_DATE('2024-12-31 00:00:00','YYYY-MM-DD HH24:MI:SS') and SEND_SYSTEM = 'RB' and DATA_FLAG = 'INP' group by DATA_FLAG)
obproxy.log.20240705154325:[2024-07-05 15:42:13.853458] INFO [PROXY.SS] ob_mysql_server_session.cpp:153 [57488][Y0-00007F10639BE9B0] [lt=28] [dc=0] server session do_io_close((*this={ss_id:17793570, server_sessid:3223043424, server_ip:{172.3.74.27:2881}, is_inited:true, magic:19136237, state:2, server_vc:0x7f1042bdb7b0, client_session:{this:0x7f10b592c2c0, is_proxy_mysql_client:true, is_waiting_trans_first_request:false, need_delete_cluster:false, is_first_dml_sql_got:true, vc_ready_killed:false, active:true, magic:19132429, conn_decrease:true, current_tid:57444, cs_id:2148860289, proxy_sessid:12394269125218871077, session_info:{is_inited:true, priv_info:{has_all_privilege:false, cs_id:2148860289, user_priv_set:512, cluster_name:"VT1", tenant_name:"sys", user_name:"proxyro"}, version:{common_hot_sys_var_version:0, common_sys_var_version:0, mysql_hot_sys_var_version:0, mysql_sys_var_version:0, hot_sys_var_version:0, sys_var_version:1, user_var_version:1, db_name_version:1, last_insert_id_version:0, sess_info_version:947171}, hash_version:{common_hot_sys_var_version:0, common_sys_var_version:0, mysql_hot_sys_var_version:0, mysql_sys_var_version:0, hot_sys_var_version:0, sys_var_version:0, user_var_version:0, db_name_version:0, last_insert_id_version:0, sess_info_version:0}, val_hash:{common_hot_sys_var_hash:0, common_cold_sys_var_hash:0, mysql_hot_sys_var_hash:0, mysql_cold_sys_var_hash:0, hot_sys_var_hash:0, cold_sys_var_hash:0, user_var_hash:0}, global_vars_version:0, is_global_vars_changed:false, is_trans_specified:false, is_user_idc_name_set:false, is_read_consistency_set:false, idc_name:"", cluster_id:0, real_meta_cluster_name:"", safe_read_snapshot:1, syncing_safe_read_snapshot:0, route_policy:1, proxy_route_policy:3, user_identity:4, global_vars_version:0, is_read_only_user:false, is_request_follower_user:false, obproxy_force_parallel_query_dop:1, ob20_request:{remain_payload_len:0, ob20_request_received_done:false, ob20_header:{ob 20 protocol header:{compressed_len:0, seq:0, non_compressed_len:0}, magic_num:0, header_checksum:0, connection_id:0, request_id:0, pkt_seq:0, payload_len:0, version:0, flag_.flags:0, reserved:0}}, client_cap:0, server_cap:916295, last_server_addr:{*Not IP address [0]*:0}, last_server_sess_id:0, init_sql:""}, dummy_ldc:{use_ldc:false, idc_name:"", item_count:8, site_start_index_array:[[0]0, [1]8, [2]8, [3]8], item_array:[[0]{idc_type:"SAME_IDC", zone_type:"ReadWrite", replica:{server:"172.3.74.28:2881", is_dup_replica:false, role:"FOLLOWER", type:"FULL"}, is_merging:false, is_partition_server:false, is_force_congested:false, is_used:false}, [1]{idc_type:"SAME_IDC", zone_type:"ReadWrite", replica:{server:"172.1.74.28:2881", is_dup_replica:false, role:"FOLLOWER", type:"FULL"}, is_merging:false, is_partition_server:false, is_force_congested:false, is_used:false}, [2]{idc_type:"SAME_IDC", zone_type:"ReadWrite", replica:{server:"172.1.74.26:2881", is_dup_replica:false, role:"FOLLOWER", type:"FULL"}, is_merging:false, is_partition_server:false, is_force_congested:false, is_used:false}, [3]{idc_type:"SAME_IDC", zone_type:"ReadWrite", replica:{server:"172.3.74.26:2881", is_dup_replica:false, role:"FOLLOWER", type:"FULL"}, is_merging:false, is_partition_server:false, is_force_congested:false, is_used:false}, [4]{idc_type:"SAME_IDC", zone_type:"ReadWrite", replica:{server:"172.3.74.27:2881", is_dup_replica:false, role:"FOLLOWER", type:"FULL"}, is_merging:false, is_partition_server:false, is_force_congested:false, is_used:false}, [5]{idc_type:"SAME_IDC", zone_type:"ReadWrite", replica:{server:"172.1.74.27:2881", is_dup_replica:false, role:"FOLLOWER", type:"FULL"}, is_merging:false, is_partition_server:false, is_force_congested:false, is_used:false}, [6]{idc_type:"SAME_IDC", zone_type:"ReadWrite", replica:{server:"172.3.74.29:2881", is_dup_replica:false, role:"FOLLOWER", type:"FULL"}, is_merging:false, is_partition_server:false, is_force_congested:false, is_used:false}, [7]{idc_type:"SAME_IDC", zone_type:"ReadWrite", replica:{server:"172.1.74.29:2881", is_dup_replica:false, role:"FOLLOWER", type:"FULL"}, is_merging:false, is_partition_server:false, is_force_congested:false, is_used:false}], pl:null, ts:0x7f10b6744e40, readonly_exist_status:"READONLY_ZONE_NOT_EXIST"}, dummy_entry:0x7f10429f03c0, server_state_version:2, cur_ss:null, bound_ss:0x7f10819f77f0, lii_ss:null, cluster_resource:{this:0x7f10b160b080, ref_count:7358, is_inited:true, cluster_info_key:{cluster_name:{config_string:"VT1"}, cluster_id:0}, cr_state:"CR_AVAIL", version:2, last_access_time_ns:1720165333853319916, deleting_completed_thread_num:0, fetch_rslist_task_count:0, fetch_idc_list_task_count:0, last_idc_list_refresh_time_ns:1720161599786535108, last_rslist_refresh_time_ns:1719628177345868002, server_state_version:2}, client_vc:0x7f10c85f1610, using_ldg:false, trace_stats:NULL}, transact_count:1, server_trans_stat:0, session_info:{cap:916295, ob_server:, version:{common_hot_sys_var_version:0, common_sys_var_version:0, mysql_hot_sys_var_version:0, mysql_sys_var_version:0, hot_sys_var_version:0, sys_var_version:1, user_var_version:1, db_name_version:1, last_insert_id_version:0, sess_info_version:947171}, val_hash:{common_hot_sys_var_hash:0, common_cold_sys_var_hash:0, mysql_hot_sys_var_hash:0, mysql_cold_sys_var_hash:0, hot_sys_var_hash:0, cold_sys_var_hash:0, user_var_hash:0}, checksum_switch:1, server_type:1}}, server_vc_=0x7f1042bdb7b0, this=0x7f10819f77f0)
obproxy.log.20240705154325:[2024-07-05 15:42:13.853608] INFO [PROXY.SS] ob_mysql_server_session.cpp:190 [57488][Y0-00007F10639BE9B0] [lt=144] [dc=0] server session is closing(ss_id=17793570, server_sessid=3223043424, server_ip={172.3.74.27:2881}, cs_id=2148860289, proxy_sessid=12394269125218871077)
obproxy.log.20240705154325:[2024-07-05 15:42:13.853678] INFO [PROXY] ob_mysql_route.cpp:476 [57488][Y0-00007F10639BE9B0] [lt=5] [dc=0] ObMysqlRoute get table entry succ((param_.name_={cluster_name:"VT1", tenant_name:"sx_gl_prod", database_name:"ENS_GL", package_name:"", table_name:"BS_MQ_CHECK"}, table_entry={{this:0x7f10b5466ad0, ref_count:6, cr_version:2, cr_id:0, create_time_us:1719968464960164, last_valid_time_us:1719968465390000, last_access_time_us:1720165330488911, last_update_time_us:0, schema_version:1716880025076472, tenant_version:2607672812506004230, time_for_expired:0, state:"UPDATING"}, this:0x7f10b5466ad0, is_inited:true, is_dummy_entry:false, is_entry_from_rslist:false, is_empty_entry_allowed:false, is_need_force_flush:false, has_dup_replica:false, cr_id:0, name:{cluster_name:"VT1", tenant_name:"sx_gl_prod", database_name:"ENS_GL", package_name:"", table_name:"BS_MQ_CHECK"}, table_id:502627, table_type:"USER TABLE", part_num:1, replica_num:4, buf_len:30, buf_start:0x7f10b5466bd8, first_pl:{replica_count:4, locations:[[0]{server:"172.1.74.28:2881", is_dup_replica:false, role:"LEADER", type:"FULL"}, [1]{server:"172.1.74.26:2881", is_dup_replica:false, role:"FOLLOWER", type:"FULL"}, [2]{server:"172.3.74.26:2881", is_dup_replica:false, role:"FOLLOWER", type:"FULL"}, [3]{server:"172.3.74.29:2881", is_dup_replica:false, role:"FOLLOWER", type:"FULL"}]}}, is_table_entry_from_remote=false)
obproxy.log.20240705154325:[2024-07-05 15:42:13.854106] INFO [PROXY.SS] ob_mysql_server_session.cpp:106 [57488][Y0-00007F10639BE9B0] [lt=35] [dc=0] server session born(ss_id=17793582, server_ip={172.3.74.28:2881}, cs_id=2148860289, proxy_sessid=12394269125218871077, server_type=1)
obproxy.log.20240705154325:[2024-07-05 15:42:13.855625] INFO [PROXY] ob_proxy_session_info_handler.cpp:746 [57488][Y0-00007F10639BE9B0] [lt=7] [dc=0] succ to set ob_capability_flag in negotiation(client_cap=0, server_cap=916295, orig_client_cap=0, orig_server_cap=916295, client_support_ob_v2=false, server_support_checksum=false, server_support_ob_v2=true, is_auth_request=false)
obproxy.log.20240705154325:[2024-07-05 15:42:13.858719] WARN [PROXY] is_resp_finished (ob_mysql_resp_analyzer.cpp:203) [57488][Y0-00007F10639BE9B0] [lt=11] [dc=0] invalid argument(ok pkt count=2, eof pkt count=0, err pkt count=2, cmd_=3, mysql_mode_=3, ret=-4002)
obproxy.log.20240705154325:[2024-07-05 15:42:13.858734] WARN [PROXY] do_analyzer_end (ob_mysql_compress_ob20_analyzer.cpp:109) [57488][Y0-00007F10639BE9B0] [lt=13] [dc=0] fail to check is resp finished(ending_type=7, ret=-4002)
obproxy.log.20240705154325:[2024-07-05 15:42:13.858741] ERROR [PROXY] decompress_data (ob_mysql_compress_ob20_analyzer.cpp:601) [57488][Y0-00007F10639BE9B0] [lt=7] [dc=0] do do_ananlyzer_end failed(payload_len=0, len=540, this={last_ob20_seq:1, request_id:15312500, sessid:3221892764, remain_head_checked_len:0, extra_header_len:0, extra_len:0, extra_checked_len:0, payload_checked_len:536, tail_checked_len:4, ob20_analyzer_state:3, crc64:573238262, curr_compressed_ob20_header:{ob 20 protocol header:{compressed_len:564, seq:1, non_compressed_len:0}, magic_num:8363, header_checksum:45202, connection_id:3221892764, request_id:15312500, pkt_seq:1, payload_len:536, version:20, flag_.flags:10, reserved:0}}, ret=-4002) BACKTRACE:0xc1d803 0xbe9939 0x13e2fdb 0x13e40c0 0x13d6818 0x1413b20 0x14141b8 0x141cd1e 0x13e5b3f 0x10c7194 0xb7c5ed 0xb78151 0xb77e31 0xb755ac 0xb737ce 0xb72c5e 0xb6fa81 0xd4eb1f 0x7f10e71a0ea5 0x7f10e6bc78dd
obproxy.log.20240705154325:[2024-07-05 15:42:13.858792] WARN [PROXY] analyze_last_compress_packet (ob_mysql_compress_ob20_analyzer.cpp:558) [57488][Y0-00007F10639BE9B0] [lt=50] [dc=0] fail to decompress last mysql packet(ret=-4002)
obproxy.log.20240705154325:[2024-07-05 15:42:13.858799] WARN [PROXY] analyze_compressed_response (ob_mysql_compress_analyzer.cpp:247) [57488][Y0-00007F10639BE9B0] [lt=4] [dc=0] fail to analyze last compress packet(buf_start=0x7f105db75c5f, buf_len=540, is_last_data=true, ret=-4002)
obproxy.log.20240705154325:[2024-07-05 15:42:13.858808] WARN [PROXY] analyze_compressed_response (ob_mysql_compress_analyzer.cpp:177) [57488][Y0-00007F10639BE9B0] [lt=8] [dc=0] fail to analyze compressed response(ret=-4002)
obproxy.log.20240705154325:[2024-07-05 15:42:13.858811] WARN [PROXY] analyze_first_response (ob_mysql_compress_analyzer.cpp:716) [57488][Y0-00007F10639BE9B0] [lt=3] [dc=0] fail to analyze compressed response(ret=-4002)
obproxy.log.20240705154325:[2024-07-05 15:42:13.858815] WARN [PROXY] analyze_first_response (ob_mysql_compress_ob20_analyzer.cpp:627) [57488][Y0-00007F10639BE9B0] [lt=3] [dc=0] analyze first response failed(result={status:0, header:{compressed_len:564, seq:1, non_compressed_len:0}, is_checksum_on:false}, need_receive_completed=false, ret=-4002)
obproxy.log.20240705154325:[2024-07-05 15:42:13.858826] WARN [PROXY.SM] handle_first_compress_response_packet (ob_mysql_sm.cpp:4038) [57488][Y0-00007F10639BE9B0] [lt=9] [dc=0] fail to analyze first response(server_buffer_reader_=0x7f10b4365248, need_receive_completed=false, server_response={analyze_result:{is_trans_completed:false, is_resp_completed:false, ending_type:7, is_partition_hit:true, has_new_sys_var:false, has_proxy_idc_name_user_var:false, is_server_db_reset:false, reserved_len:0, connection_id:0, scramble_buf:"", is_resultset_resp:false, server_capabilities_lower_.capability:0, ok_packet_action_type:1, last_ok_pkt_len:175, rewritten_last_ok_pkt_len:0, extra_info:{is_exist_sess_info:false, sess_info_count:0, extra_len:0}}}, sm_id=1479459, ret=-4002)
obproxy.log.20240705154325:[2024-07-05 15:42:13.858842] WARN [PROXY.SM] handle_oceanbase_first_response_packet (ob_mysql_sm.cpp:3994) [57488][Y0-00007F10639BE9B0] [lt=16] [dc=0] fail to handle_first_compress_response_packet(need_receive_completed=false, ret=-4002)
obproxy.log.20240705154325:[2024-07-05 15:42:13.858847] WARN [PROXY.SM] handle_first_response_packet (ob_mysql_sm.cpp:3972) [57488][Y0-00007F10639BE9B0] [lt=5] [dc=0] fail to handle oceanbase first response packet(ret=-4002)
obproxy.log.20240705154325:[2024-07-05 15:42:13.858850] WARN [PROXY.SM] state_server_response_read (ob_mysql_sm.cpp:3688) [57488][Y0-00007F10639BE9B0] [lt=3] [dc=0] fail to handle first response packet(ret=-4002)
obproxy.log.20240705154325:[2024-07-05 15:42:13.858853] WARN [PROXY.SM] state_server_response_read (ob_mysql_sm.cpp:3731) [57488][Y0-00007F10639BE9B0] [lt=3] [dc=0] Error parsing server response(sm_id=1479459, ret=-4002)
obproxy.log.20240705154325:[2024-07-05 15:42:13.858857] WARN [PROXY.SM] handle_server_setup_error (ob_mysql_sm.cpp:8412) [57488][Y0-00007F10639BE9B0] [lt=3] [dc=0] trace_log(trans_state_.trace_log_= | dropped=0)
obproxy.log.20240705154325:[2024-07-05 15:42:13.858862] INFO [PROXY.SS] ob_mysql_server_session.cpp:153 [57488][Y0-00007F10639BE9B0] [lt=4] [dc=0] server session do_io_close((*this={ss_id:17793575, server_sessid:3221892764, server_ip:{172.1.74.28:2881}, is_inited:true, magic:19136237, state:1, server_vc:0x7f1076189d20, client_session:{this:0x7f10a715aa00, is_proxy_mysql_client:false, is_waiting_trans_first_request:false, need_delete_cluster:false, is_first_dml_sql_got:true, vc_ready_killed:false, active:true, magic:19132429, conn_decrease:true, current_tid:57488, cs_id:2820645, proxy_sessid:12394269125218921778, session_info:{is_inited:true, priv_info:{has_all_privilege:false, cs_id:2820645, user_priv_set:436, cluster_name:"VT1", tenant_name:"sx_gl_prod", user_name:"ENS_GL"}, version:{common_hot_sys_var_version:0, common_sys_var_version:0, mysql_hot_sys_var_version:0, mysql_sys_var_version:0, hot_sys_var_version:156, sys_var_version:23, user_var_version:1, db_name_version:1, last_insert_id_version:0, sess_info_version:318}, hash_version:{common_hot_sys_var_version:0, common_sys_var_version:0, mysql_hot_sys_var_version:0, mysql_sys_var_version:0, hot_sys_var_version:0, sys_var_version:0, user_var_version:0, db_name_version:0, last_insert_id_version:0, sess_info_version:0}, val_hash:{common_hot_sys_var_hash:0, common_cold_sys_var_hash:0, mysql_hot_sys_var_hash:0, mysql_cold_sys_var_hash:0, hot_sys_var_hash:0, cold_sys_var_hash:0, user_var_hash:0}, global_vars_version:0, is_global_vars_changed:false, is_trans_specified:false, is_user_idc_name_set:false, is_read_consistency_set:false, idc_name:"", cluster_id:0, real_meta_cluster_name:"", safe_read_snapshot:1, syncing_safe_read_snapshot:0, route_policy:1, proxy_route_policy:3, user_identity:0, global_vars_version:0, is_read_only_user:false, is_request_follower_user:false, obproxy_force_parallel_query_dop:1, ob20_request:{remain_payload_len:0, ob20_request_received_done:false, ob20_header:{ob 20 protocol header:{compressed_len:0, seq:0, non_compressed_len:0}, magic_num:0, header_checksum:0, connection_id:0, request_id:0, pkt_seq:0, payload_len:0, version:0, flag_.flags:0, reserved:0}}, client_cap:72, server_cap:916295, last_server_addr:{*Not IP address [0]*:0}, last_server_sess_id:0, init_sql:""}, dummy_ldc:{use_ldc:false, idc_name:"", item_count:4, site_start_index_array:[[0]0, [1]4, [2]4, [3]4], item_array:[[0]{idc_type:"SAME_IDC", zone_type:"ReadWrite", replica:{server:"172.3.74.29:2881", is_dup_replica:false, role:"FOLLOWER", type:"FULL"}, is_merging:false, is_partition_server:false, is_force_congested:false, is_used:true}, [1]{idc_type:"SAME_IDC", zone_type:"ReadWrite", replica:{server:"172.1.74.26:2881", is_dup_replica:false, role:"FOLLOWER", type:"FULL"}, is_merging:false, is_partition_server:false, is_force_congested:false, is_used:true}, [2]{idc_type:"SAME_IDC", zone_type:"ReadWrite", replica:{server:"172.1.74.28:2881", is_dup_replica:false, role:"FOLLOWER", type:"FULL"}, is_merging:false, is_partition_server:false, is_force_congested:false, is_used:true}, [3]{idc_type:"SAME_IDC", zone_type:"ReadWrite", replica:{server:"172.3.74.26:2881", is_dup_replica:false, role:"FOLLOWER", type:"FULL"}, is_merging:false, is_partition_server:false, is_force_congested:false, is_used:true}], pl:null, ts:0x7f10b6744f60, readonly_exist_status:"READONLY_ZONE_NOT_EXIST"}, dummy_entry:0x7f10c5f85ce0, server_state_version:2, cur_ss:0x7f109159e2a0, bound_ss:null, lii_ss:null, cluster_resource:{this:0x7f10b160b080, ref_count:7358, is_inited:true, cluster_info_key:{cluster_name:{config_string:"VT1"}, cluster_id:0}, cr_state:"CR_AVAIL", version:2, last_access_time_ns:1720165333853319916, deleting_completed_thread_num:0, fetch_rslist_task_count:0, fetch_idc_list_task_count:0, last_idc_list_refresh_time_ns:1720161599786535108, last_rslist_refresh_time_ns:1719628177345868002, server_state_version:2}, client_vc:0x7f10631f1780, using_ldg:false, trace_stats:NULL}, transact_count:2, server_trans_stat:1, session_info:{cap:916295, ob_server:, version:{common_hot_sys_var_version:0, common_sys_var_version:0, mysql_hot_sys_var_version:0, mysql_sys_var_version:0, hot_sys_var_version:156, sys_var_version:23, user_var_version:1, db_name_version:1, last_insert_id_version:0, sess_info_version:316}, val_hash:{common_hot_sys_var_hash:0, common_cold_sys_var_hash:0, mysql_hot_sys_var_hash:0, mysql_cold_sys_var_hash:0, hot_sys_var_hash:0, cold_sys_var_hash:0, user_var_hash:0}, checksum_switch:1, server_type:2}}, server_vc_=0x7f1076189d20, this=0x7f109159e2a0)
obproxy.log.20240705154325:[2024-07-05 15:42:13.858976] INFO [PROXY.SS] ob_mysql_server_session.cpp:190 [57488][Y0-00007F10639BE9B0] [lt=110] [dc=0] server session is closing(ss_id=17793575, server_sessid=3221892764, server_ip={172.1.74.28:2881}, cs_id=2820645, proxy_sessid=12394269125218921778)
obproxy.log.20240705154325:[2024-07-05 15:42:13.858996] INFO [PROXY.TXN] ob_mysql_transact.cpp:5781 [57488][Y0-00007F10639BE9B0] [lt=5] [dc=0] [ObMysqlTransact::handle_server_connection_break]((client_ip={172.1.74.240:39540}, server_ip={172.1.74.28:2881}, cs_id=2820645, proxy_sessid=12394269125218921778, ss_id=0, server_sessid=0, sm_id=1479459, proxy_user_name=ENS_GL@sx_gl_prod#VT1, database_name=ENS_GL, server_state="INTERNAL_ERROR", request_cmd="Query", sql_cmd="Query", sql=UPDATE BS_MQ_CHECK SET SEQ_NO = '801', CHANNEL = 'OB', TRAN_DATE = TO_DATE('2024-12-31 00:00:00','YYYY-MM-DD HH24:MI:SS'), AC_NUM = 6, AC_AMOUNT = 6, NUM = 6, AMOUNT = 6, EQUAL_FLAG = 'Y', HIST_TYPE = 'TRAN' WHERE SEQ_NO = '801' AND TRAN_DATE = TO_DATE('2024-12-31 00:00:00','YYYY-MM-DD HH24:MI:SS');UPDATE BS_MQ_CHECK SET SEQ_NO = '802', CHANNEL = 'RB', TRAN_DATE = TO_DATE('2024-12-31 00:00:00','YYYY-MM-DD HH24:MI:SS'), AC_NUM = 812682, AC_AMOUNT = 3940701539.94, NUM = 812664, AMOUNT = 3940694469.54, EQUAL_FLAG = 'N', HIST_TYPE = 'TRAN' WHERE SEQ_NO = '802' AND TRAN_DATE = TO_DATE('2024-12-31 00:00:00','YYYY-MM-DD HH24:MI:SS'))
obproxy.log.20240705154325:[2024-07-05 15:42:13.859019] WARN [PROXY.TXN] handle_server_connection_break (ob_mysql_transact.cpp:5819) [57488][Y0-00007F10639BE9B0] [lt=5] [dc=0] trace_log(s.trace_log_= | dropped=0)
obproxy.log.20240705154325:[2024-07-05 15:42:13.859024] WARN [PROXY.SM] setup_error_transfer (ob_mysql_sm.cpp:9016) [57488][Y0-00007F10639BE9B0] [lt=4] [dc=0] [setup_error_transfer] Now closing connection(sm_id=1479459, client_ip={172.1.74.240:39540}, request_cmd="Query", sql_cmd="Query", sql=UPDATE BS_MQ_CHECK SET SEQ_NO = '801', CHANNEL = 'OB', TRAN_DATE = TO_DATE('2024-12-31 00:00:00','YYYY-MM-DD HH24:MI:SS'), AC_NUM = 6, AC_AMOUNT = 6, NUM = 6, AMOUNT = 6, EQUAL_FLAG = 'Y', HIST_TYPE = 'TRAN' WHERE SEQ_NO = '801' AND TRAN_DATE = TO_DATE('2024-12-31 00:00:00','YYYY-MM-DD HH24:MI:SS');UPDATE BS_MQ_CHECK SET SEQ_NO = '802', CHANNEL = 'RB', TRAN_DATE = TO_DATE('2024-12-31 00:00:00','YYYY-MM-DD HH24:MI:SS'), AC_NUM = 812682, AC_AMOUNT = 3940701539.94, NUM = 812664, AMOUNT = 3940694469.54, EQUAL_FLAG = 'N', HIST_TYPE = 'TRAN' WHERE SEQ_NO = '802' AND TRAN_DATE = TO_DATE('2024-12-31 00:00:00','YYYY-MM-DD HH24:MI:SS'))
obproxy.log.20240705154325:[2024-07-05 15:42:13.859051] INFO [PROXY.SM] ob_mysql_sm.cpp:9542 [57488][Y0-00007F10639BE9B0] [lt=15] [dc=0] will deallocate sm(sm_id=1479459, pending_action=NULL, api_.callout_state=0, trans_state_.trace_log= | dropped=0)
obproxy.log.20240705154325:[2024-07-05 15:42:13.859080] INFO [PROXY] ob_tenant_stat_manager.cpp:69 [57488][Y0-00007F10639BE9B0] [lt=4] [dc=0] succ to create tenant stat item(item={logic_tenant_name:"VT1_obproxy_1", logic_database_name:"", cluster_name:"VT1", tenant_name:"sx_gl_prod", database_name:"ENS_GL", database_type:2, stmt_type:27, error_code:"-4002", idle_period_count:0, stat_value:{value:[[0]0, [1]0, [2]0, [3]0, [4]0, [5]0, [6]0]}}, key={logic_tenant_hash:3861533354992431, logic_database_hash:0, cluster_hash:15652599805861649774, tenant_hash:7702633770381247636, database_hash:4006296552884565672, stmt_type:27, error_code_hash:1840104443584373992})
obproxy.log.20240705154325:[2024-07-05 15:42:13.859108] INFO [PROXY.SS] ob_mysql_client_session.cpp:652 [57488][Y0-00007F10639BE9B0] [lt=12] [dc=0] client session do_io_close((*this={this:0x7f10a715aa00, is_proxy_mysql_client:false, is_waiting_trans_first_request:false, need_delete_cluster:false, is_first_dml_sql_got:true, vc_ready_killed:false, active:true, magic:19132429, conn_decrease:true, current_tid:57488, cs_id:2820645, proxy_sessid:12394269125218921778, session_info:{is_inited:true, priv_info:{has_all_privilege:false, cs_id:2820645, user_priv_set:436, cluster_name:"VT1", tenant_name:"sx_gl_prod", user_name:"ENS_GL"}, version:{common_hot_sys_var_version:0, common_sys_var_version:0, mysql_hot_sys_var_version:0, mysql_sys_var_version:0, hot_sys_var_version:156, sys_var_version:23, user_var_version:1, db_name_version:1, last_insert_id_version:0, sess_info_version:318}, hash_version:{common_hot_sys_var_version:0, common_sys_var_version:0, mysql_hot_sys_var_version:0, mysql_sys_var_version:0, hot_sys_var_version:0, sys_var_version:0, user_var_version:0, db_name_version:0, last_insert_id_version:0, sess_info_version:0}, val_hash:{common_hot_sys_var_hash:0, common_cold_sys_var_hash:0, mysql_hot_sys_var_hash:0, mysql_cold_sys_var_hash:0, hot_sys_var_hash:0, cold_sys_var_hash:0, user_var_hash:0}, global_vars_version:0, is_global_vars_changed:false, is_trans_specified:false, is_user_idc_name_set:false, is_read_consistency_set:false, idc_name:"", cluster_id:0, real_meta_cluster_name:"", safe_read_snapshot:1, syncing_safe_read_snapshot:0, route_policy:1, proxy_route_policy:3, user_identity:0, global_vars_version:0, is_read_only_user:false, is_request_follower_user:false, obproxy_force_parallel_query_dop:1, ob20_request:{remain_payload_len:0, ob20_request_received_done:false, ob20_header:{ob 20 protocol header:{compressed_len:0, seq:0, non_compressed_len:0}, magic_num:0, header_checksum:0, connection_id:0, request_id:0, pkt_seq:0, payload_len:0, version:0, flag_.flags:0, reserved:0}}, client_cap:72, server_cap:916295, last_server_addr:{*Not IP address [0]*:0}, last_server_sess_id:0, init_sql:""}, dummy_ldc:{use_ldc:false, idc_name:"", item_count:4, site_start_index_array:[[0]0, [1]4, [2]4, [3]4], item_array:[[0]{idc_type:"SAME_IDC", zone_type:"ReadWrite", replica:{server:"172.3.74.29:2881", is_dup_replica:false, role:"FOLLOWER", type:"FULL"}, is_merging:false, is_partition_server:false, is_force_congested:false, is_used:true}, [1]{idc_type:"SAME_IDC", zone_type:"ReadWrite", replica:{server:"172.1.74.26:2881", is_dup_replica:false, role:"FOLLOWER", type:"FULL"}, is_merging:false, is_partition_server:false, is_force_congested:false, is_used:true}, [2]{idc_type:"SAME_IDC", zone_type:"ReadWrite", replica:{server:"172.1.74.28:2881", is_dup_replica:false, role:"FOLLOWER", type:"FULL"}, is_merging:false, is_partition_server:false, is_force_congested:false, is_used:true}, [3]{idc_type:"SAME_IDC", zone_type:"ReadWrite", replica:{server:"172.3.74.26:2881", is_dup_replica:false, role:"FOLLOWER", type:"FULL"}, is_merging:false, is_partition_server:false, is_force_congested:false, is_used:true}], pl:null, ts:0x7f10b6744f60, readonly_exist_status:"READONLY_ZONE_NOT_EXIST"}, dummy_entry:0x7f10c5f85ce0, server_state_version:2, cur_ss:null, bound_ss:null, lii_ss:null, cluster_resource:{this:0x7f10b160b080, ref_count:7358, is_inited:true, cluster_info_key:{cluster_name:{config_string:"VT1"}, cluster_id:0}, cr_state:"CR_AVAIL", version:2, last_access_time_ns:1720165333853319916, deleting_completed_thread_num:0, fetch_rslist_task_count:0, fetch_idc_list_task_count:0, last_idc_list_refresh_time_ns:1720161599786535108, last_rslist_refresh_time_ns:1719628177345868002, server_state_version:2}, client_vc:0x7f10631f1780, using_ldg:false, trace_stats:NULL}, client_vc_=0x7f10631f1780, this=0x7f10a715aa00)
obproxy.log.20240705154325:[2024-07-05 15:42:13.859158] INFO [PROXY.SS] ob_mysql_server_session.cpp:153 [57488][Y0-00007F10639BE9B0] [lt=49] [dc=0] server session do_io_close((*this={ss_id:17029174, server_sessid:3221513397, server_ip:{172.1.74.26:2881}, is_inited:true, magic:19136237, state:3, server_vc:0x7f1076181e60, client_session:{this:0x7f10a715aa00, is_proxy_mysql_client:false, is_waiting_trans_first_request:false, need_delete_cluster:false, is_first_dml_sql_got:true, vc_ready_killed:false, active:false, magic:19132429, conn_decrease:true, current_tid:57488, cs_id:2820645, proxy_sessid:12394269125218921778, session_info:{is_inited:true, priv_info:{has_all_privilege:false, cs_id:2820645, user_priv_set:436, cluster_name:"VT1", tenant_name:"sx_gl_prod", user_name:"ENS_GL"}, version:{common_hot_sys_var_version:0, common_sys_var_version:0, mysql_hot_sys_var_version:0, mysql_sys_var_version:0, hot_sys_var_version:156, sys_var_version:23, user_var_version:1, db_name_version:1, last_insert_id_version:0, sess_info_version:318}, hash_version:{common_hot_sys_var_version:0, common_sys_var_version:0, mysql_hot_sys_var_version:0, mysql_sys_var_version:0, hot_sys_var_version:0, sys_var_version:0, user_var_version:0, db_name_version:0, last_insert_id_version:0, sess_info_version:0}, val_hash:{common_hot_sys_var_hash:0, common_cold_sys_var_hash:0, mysql_hot_sys_var_hash:0, mysql_cold_sys_var_hash:0, hot_sys_var_hash:0, cold_sys_var_hash:0, user_var_hash:0}, global_vars_version:0, is_global_vars_changed:false, is_trans_specified:false, is_user_idc_name_set:false, is_read_consistency_set:false, idc_name:"", cluster_id:0, real_meta_cluster_name:"", safe_read_snapshot:1, syncing_safe_read_snapshot:0, route_policy:1, proxy_route_policy:3, user_identity:0, global_vars_version:0, is_read_only_user:false, is_request_follower_user:false, obproxy_force_parallel_query_dop:1, ob20_request:{remain_payload_len:0, ob20_request_received_done:false, ob20_header:{ob 20 protocol header:{compressed_len:0, seq:0, non_compressed_len:0}, magic_num:0, header_checksum:0, connection_id:0, request_id:0, pkt_seq:0, payload_len:0, version:0, flag_.flags:0, reserved:0}}, client_cap:72, server_cap:916295, last_server_addr:{*Not IP address [0]*:0}, last_server_sess_id:0, init_sql:""}, dummy_ldc:{use_ldc:false, idc_name:"", item_count:4, site_start_index_array:[[0]0, [1]4, [2]4, [3]4], item_array:[[0]{idc_type:"SAME_IDC", zone_type:"ReadWrite", replica:{server:"172.3.74.29:2881", is_dup_replica:false, role:"FOLLOWER", type:"FULL"}, is_merging:false, is_partition_server:false, is_force_congested:false, is_used:true}, [1]{idc_type:"SAME_IDC", zone_type:"ReadWrite", replica:{server:"172.1.74.26:2881", is_dup_replica:false, role:"FOLLOWER", type:"FULL"}, is_merging:false, is_partition_server:false, is_force_congested:false, is_used:true}, [2]{idc_type:"SAME_IDC", zone_type:"ReadWrite", replica:{server:"172.1.74.28:2881", is_dup_replica:false, role:"FOLLOWER", type:"FULL"}, is_merging:false, is_partition_server:false, is_force_congested:false, is_used:true}, [3]{idc_type:"SAME_IDC", zone_type:"ReadWrite", replica:{server:"172.3.74.26:2881", is_dup_replica:false, role:"FOLLOWER", type:"FULL"}, is_merging:false, is_partition_server:false, is_force_congested:false, is_used:true}], pl:null, ts:0x7f10b6744f60, readonly_exist_status:"READONLY_ZONE_NOT_EXIST"}, dummy_entry:0x7f10c5f85ce0, server_state_version:2, cur_ss:null, bound_ss:null, lii_ss:null, cluster_resource:{this:0x7f10b160b080, ref_count:7358, is_inited:true, cluster_info_key:{cluster_name:{config_string:"VT1"}, cluster_id:0}, cr_state:"CR_AVAIL", version:2, last_access_time_ns:1720165333853319916, deleting_completed_thread_num:0, fetch_rslist_task_count:0, fetch_idc_list_task_count:0, last_idc_list_refresh_time_ns:1720161599786535108, last_rslist_refresh_time_ns:1719628177345868002, server_state_version:2}, client_vc:0x7f10631f1780, using_ldg:false, trace_stats:NULL}, transact_count:419, server_trans_stat:0, session_info:{cap:916295, ob_server:, version:{common_hot_sys_var_version:0, common_sys_var_version:0, mysql_hot_sys_var_version:0, mysql_sys_var_version:0, hot_sys_var_version:156, sys_var_version:23, user_var_version:1, db_name_version:1, last_insert_id_version:0, sess_info_version:318}, val_hash:{common_hot_sys_var_hash:0, common_cold_sys_var_hash:0, mysql_hot_sys_var_hash:0, mysql_cold_sys_var_hash:0, hot_sys_var_hash:0, cold_sys_var_hash:0, user_var_hash:0}, checksum_switch:1, server_type:1}}, server_vc_=0x7f1076181e60, this=0x7f10915a6ac0)
obproxy.log.20240705154325:[2024-07-05 15:42:13.859269] INFO [PROXY.SS] ob_mysql_server_session.cpp:190 [57488][Y0-00007F10639BE9B0] [lt=87] [dc=0] server session is closing(ss_id=17029174, server_sessid=3221513397, server_ip={172.1.74.26:2881}, cs_id=2820645, proxy_sessid=12394269125218921778)
obproxy.log.20240705154325:[2024-07-05 15:42:13.859302] INFO [PROXY.CS] ob_mysql_client_session.cpp:94 [57488][Y0-00007F10639BE9B0] [lt=5] [dc=0] client session destroy(cs_id=2820645, proxy_sessid=12394269125218921778, client_vc=NULL)其中发现了,断链遇到了-4002异常，切伴随ERROR， do do_ananlyzer_end failed
obproxy.log.20240705154325:[2024-07-05 15:42:13.858719] WARN [PROXY] is_resp_finished (ob_mysql_resp_analyzer.cpp:203) [57488][Y0-00007F10639BE9B0] [lt=11] [dc=0] invalid argument(ok pkt count=2, eof pkt count=0, err pkt count=2, cmd_=3, mysql_mode_=3, ret=-4002)
obproxy.log.20240705154325:[2024-07-05 15:42:13.858734] WARN [PROXY] do_analyzer_end (ob_mysql_compress_ob20_analyzer.cpp:109) [57488][Y0-00007F10639BE9B0] [lt=13] [dc=0] fail to check is resp finished(ending_type=7, ret=-4002)
obproxy.log.20240705154325:[2024-07-05 15:42:13.858741] ERROR [PROXY] decompress_data (ob_mysql_compress_ob20_analyzer.cpp:601) [57488][Y0-00007F10639BE9B0] [lt=7] [dc=0] do do_ananlyzer_end failed(payload_len=0, len=540, this={last_ob20_seq:1, request_id:15312500, sessid:3221892764, remain_head_checked_len:0, extra_header_len:0, extra_len:0, extra_checked_len:0, payload_checked_len:536, tail_checked_len:4, ob20_analyzer_state:3, crc64:573238262, curr_compressed_ob20_header:{ob 20 protocol header:{compressed_len:564, seq:1, non_compressed_len:0}, magic_num:8363, header_checksum:45202, connection_id:3221892764, request_id:15312500, pkt_seq:1, payload_len:536, version:20, flag_.flags:10, reserved:0}}, ret=-4002) BACKTRACE:0xc1d803 0xbe9939 0x13e2fdb 0x13e40c0 0x13d6818 0x1413b20 0x14141b8 0x141cd1e 0x13e5b3f 0x10c7194 0xb7c5ed 0xb78151 0xb77e31 0xb755ac 0xb737ce 0xb72c5e 0xb6fa81 0xd4eb1f 0x7f10e71a0ea5 0x7f10e6bc78dd
obproxy.log.20240705154325:[2024-07-05 15:42:13.858792] WARN [PROXY] analyze_last_compress_packet (ob_mysql_compress_ob20_analyzer.cpp:558) [57488][Y0-00007F10639BE9B0] [lt=50] [dc=0] fail to decompress last mysql packet(ret=-4002)
obproxy.log.20240705154325:[2024-07-05 15:42:13.858799] WARN [PROXY] analyze_compressed_response (ob_mysql_compress_analyzer.cpp:247) [57488][Y0-00007F10639BE9B0] [lt=4] [dc=0] fail to analyze last compress packet(buf_start=0x7f105db75c5f, buf_len=540, is_last_data=true, ret=-4002)
obproxy.log.20240705154325:[2024-07-05 15:42:13.858808] WARN [PROXY] analyze_compressed_response (ob_mysql_compress_analyzer.cpp:177) [57488][Y0-00007F10639BE9B0] [lt=8] [dc=0] fail to analyze compressed response(ret=-4002)
obproxy.log.20240705154325:[2024-07-05 15:42:13.858811] WARN [PROXY] analyze_first_response (ob_mysql_compress_analyzer.cpp:716) [57488][Y0-00007F10639BE9B0] [lt=3] [dc=0] fail to analyze compressed response(ret=-4002)
obproxy.log.20240705154325:[2024-07-05 15:42:13.858815] WARN [PROXY] analyze_first_response (ob_mysql_compress_ob20_analyzer.cpp:627) [57488][Y0-00007F10639BE9B0] [lt=3] [dc=0] analyze first response failed(result={status:0, header:{compressed_len:564, seq:1, non_compressed_len:0}, is_checksum_on:false}, need_receive_completed=false, ret=-4002)
obproxy.log.20240705154325:[2024-07-05 15:42:13.858826] WARN [PROXY.SM] handle_first_compress_response_packet (ob_mysql_sm.cpp:4038) [57488][Y0-00007F10639BE9B0] [lt=9] [dc=0] fail to analyze first response(server_buffer_reader_=0x7f10b4365248, need_receive_completed=false, server_response={analyze_result:{is_trans_completed:false, is_resp_completed:false, ending_type:7, is_partition_hit:true, has_new_sys_var:false, has_proxy_idc_name_user_var:false, is_server_db_reset:false, reserved_len:0, connection_id:0, scramble_buf:"", is_resultset_resp:false, server_capabilities_lower_.capability:0, ok_packet_action_type:1, last_ok_pkt_len:175, rewritten_last_ok_pkt_len:0, extra_info:{is_exist_sess_info:false, sess_info_count:0, extra_len:0}}}, sm_id=1479459, ret=-4002)
obproxy.log.20240705154325:[2024-07-05 15:42:13.858842] WARN [PROXY.SM] handle_oceanbase_first_response_packet (ob_mysql_sm.cpp:3994) [57488][Y0-00007F10639BE9B0] [lt=16] [dc=0] fail to handle_first_compress_response_packet(need_receive_completed=false, ret=-4002)
obproxy.log.20240705154325:[2024-07-05 15:42:13.858847] WARN [PROXY.SM] handle_first_response_packet (ob_mysql_sm.cpp:3972) [57488][Y0-00007F10639BE9B0] [lt=5] [dc=0] fail to handle oceanbase first response packet(ret=-4002)
obproxy.log.20240705154325:[2024-07-05 15:42:13.858850] WARN [PROXY.SM] state_server_response_read (ob_mysql_sm.cpp:3688) [57488][Y0-00007F10639BE9B0] [lt=3] [dc=0] fail to handle first response packet(ret=-4002)
obproxy.log.20240705154325:[2024-07-05 15:42:13.858853] WARN [PROXY.SM] state_server_response_read (ob_mysql_sm.cpp:3731) [57488][Y0-00007F10639BE9B0] [lt=3] [dc=0] Error parsing server response(sm_id=1479459, ret=-4002)
obproxy.log.20240705154325:[2024-07-05 15:42:13.858857] WARN [PROXY.SM] handle_server_setup_error (ob_mysql_sm.cpp:8412) [57488][Y0-00007F10639BE9B0] [lt=3] [dc=0] trace_log(trans_state_.trace_log_= | dropped=0)obproxy相关的sql
obproxy.log.20240705154325:[2024-07-05 15:42:13.858996] INFO [PROXY.TXN] ob_mysql_transact.cpp:5781 [57488][Y0-00007F10639BE9B0] [lt=5] [dc=0] [ObMysqlTransact::handle_server_connection_break]((client_ip={172.1.74.240:39540}, server_ip={172.1.74.28:2881}, cs_id=2820645, proxy_sessid=12394269125218921778, ss_id=0, server_sessid=0, sm_id=1479459, proxy_user_name=ENS_GL@sx_gl_prod#VT1, database_name=ENS_GL, server_state="INTERNAL_ERROR", request_cmd="Query", sql_cmd="Query", sql=UPDATE BS_MQ_CHECK SET SEQ_NO = '801', CHANNEL = 'OB', TRAN_DATE = TO_DATE('2024-12-31 00:00:00','YYYY-MM-DD HH24:MI:SS'), AC_NUM = 6, AC_AMOUNT = 6, NUM = 6, AMOUNT = 6, EQUAL_FLAG = 'Y', HIST_TYPE = 'TRAN' WHERE SEQ_NO = '801' AND TRAN_DATE = TO_DATE('2024-12-31 00:00:00','YYYY-MM-DD HH24:MI:SS');UPDATE BS_MQ_CHECK SET SEQ_NO = '802', CHANNEL = 'RB', TRAN_DATE = TO_DATE('2024-12-31 00:00:00','YYYY-MM-DD HH24:MI:SS'), AC_NUM = 812682, AC_AMOUNT = 3940701539.94, NUM = 812664, AMOUNT = 3940694469.54, EQUAL_FLAG = 'N', HIST_TYPE = 'TRAN' WHERE SEQ_NO = '802' AND TRAN_DATE = TO_DATE('2024-12-31 00:00:00','YYYY-MM-DD HH24:MI:SS'))
obproxy.log.20240705154325:[2024-07-05 15:42:13.859019] WARN [PROXY.TXN] handle_server_connection_break (ob_mysql_transact.cpp:5819) [57488][Y0-00007F10639BE9B0] [lt=5] [dc=0] trace_log(s.trace_log_= | dropped=0)
obproxy.log.20240705154325:[2024-07-05 15:42:13.859024] WARN [PROXY.SM] setup_error_transfer (ob_mysql_sm.cpp:9016) [57488][Y0-00007F10639BE9B0] [lt=4] [dc=0] [setup_error_transfer] Now closing connection(sm_id=1479459, client_ip={172.1.74.240:39540}, request_cmd="Query", sql_cmd="Query", sql=UPDATE BS_MQ_CHECK SET SEQ_NO = '801', CHANNEL = 'OB', TRAN_DATE = TO_DATE('2024-12-31 00:00:00','YYYY-MM-DD HH24:MI:SS'), AC_NUM = 6, AC_AMOUNT = 6, NUM = 6, AMOUNT = 6, EQUAL_FLAG = 'Y', HIST_TYPE = 'TRAN' WHERE SEQ_NO = '801' AND TRAN_DATE = TO_DATE('2024-12-31 00:00:00','YYYY-MM-DD HH24:MI:SS');UPDATE BS_MQ_CHECK SET SEQ_NO = '802', CHANNEL = 'RB', TRAN_DATE = TO_DATE('2024-12-31 00:00:00','YYYY-MM-DD HH24:MI:SS'), AC_NUM = 812682, AC_AMOUNT = 3940701539.94, NUM = 812664, AMOUNT = 3940694469.54, EQUAL_FLAG = 'N', HIST_TYPE = 'TRAN' WHERE SEQ_NO = '802' AND TRAN_DATE = TO_DATE('2024-12-31 00:00:00','YYYY-MM-DD HH24:MI:SS'))时间点：2024-07-05 15:42:13.858996
server_ip：172.1.74.28:2881
proxy_sessid=12394269125218921778
disconnect_state=4表示是上游断开的，合理分析是因为obproxy解析observer的包错误，然后obproxy断开与ob的链接，后续需要抓包判断这个问题的连贯性（看推断是否正确）
sessid=3221892764
huangzhihao@U-WML2G6Q9-1902 172.1.74.28 % grep '12394269125218921778' observer.log.20240705154*
observer.log.20240705154222607:[2024-07-05 15:42:10.489669] INFO [SERVER] process (obmp_connect.cpp:480) [106241][T1072_MysqlQueu][T1072][Y0-00061BF595EE4FE2-0-0] [lt=22] MySQL LOGIN(direct_client_ip="172.1.74.26", client_ip=172.3.98.95, tenant_name=sx_gl_prod, tenant_id=1072, user_name=ENS_GL, host_name=%, sessid=3221892764, proxy_sessid=12394269125218921778, sess_create_time=0, from_proxy=true, from_java_client=false, from_oci_client=false, from_jdbc_client=false, capability=683647754, proxy_capability=916295, use_ssl=false, c/s protocol="OB_2_0_CS_TYPE", autocommit=false, proc_ret=0, ret=0, conn->client_type_=1, conn->client_version_=8590196743)
observer.log.20240705154222607:[2024-07-05 15:42:10.492471] INFO [SERVER] send_error_packet (obmp_packet_sender.cpp:502) [106417][T1072_L0_G0][T1072][YB42AC014A1C-00061BF595DE5017-0-0] [lt=11] dump txn free route audit_record(value=5, session->get_sessid()=3221892764, session->get_proxy_sessid()=12394269125218921778)
observer.log.20240705154222607:[2024-07-05 15:42:13.856764] INFO [SERVER] send_error_packet (obmp_packet_sender.cpp:502) [106369][T1072_L0_G0][T1072][YB42AC014A1C-00061BF595CE5012-0-0] [lt=9] dump txn free route audit_record(value=5, session->get_sessid()=3221892764, session->get_proxy_sessid()=12394269125218921778)
observer.log.20240705154222607:[2024-07-05 15:42:13.858616] INFO [SERVER] send_error_packet (obmp_packet_sender.cpp:502) [106369][T1072_L0_G0][T1072][YB42AC014A1C-00061BF595CE5012-0-0] [lt=10] dump txn free route audit_record(value=5, session->get_sessid()=3221892764, session->get_proxy_sessid()=12394269125218921778)
observer.log.20240705154222607:[2024-07-05 15:42:13.859377] INFO [RPC.OBMYSQL] on_disconnect (obsm_conn_callback.cpp:268) [46578][sql_nio13][T0][Y0-0000000000000000-0-0] [lt=20] kill and revert session(conn.sessid_=3221892764, proxy_sessid=12394269125218921778, server_id=2, ret=0)
observer.log.20240705154222607:[2024-07-05 15:42:13.859400] INFO [RPC.OBMYSQL] sm_conn_unlock_tenant (obsm_conn_callback.cpp:159) [46578][sql_nio13][T0][Y0-0000000000000000-0-0] [lt=8] unlock session of tenant(conn.sessid_=3221892764, proxy_sessid=12394269125218921778, conn.tenant_id_=1072)
observer.log.20240705154222607:[2024-07-05 15:42:13.859408] INFO [RPC.OBMYSQL] destroy (obsm_conn_callback.cpp:243) [46578][sql_nio13][T0][Y0-0000000000000000-0-0] [lt=7] connection close(sessid=3221892764, proxy_sessid=12394269125218921778, tenant_id=1072, server_id=2, from_proxy=true, from_java_client=false, c/s protocol="OB_2_0_CS_TYPE", is_need_clear_sessid_=true, is_sess_alloc_=true, ret=0, trace_id=YB42AC014A1C-00061BF595CE5012-0-0, conn.pkt_rec_wrapper_=[start_pkt_pos_:7, cur_pkt_pos_:11, pkt_rec[0]:{send:obp_mysql_header_{len_:6191, seq_:3}, pkt_name:"PKT_OKP", obp_mysql_header_.is_send_:1}, pkt_rec[1]:{send:obp20_header_:{payload_len:831, pkt_seq:0, req_id:15312497, flag_.flags:43, ext_flags:0}, obp_mysql_header_{len_:708, seq_:2}, pkt_name:"PKT_OKP", obp_mysql_header_.is_send_:1}, pkt_rec[2]:{send:obp20_header_:{payload_len:43, pkt_seq:0, req_id:15312498, flag_.flags:42, ext_flags:0}, obp_mysql_header_{len_:64, seq_:2}, pkt_name:"PKT_OKP", obp_mysql_header_.is_send_:1}, pkt_rec[3]:{receive:obp20_header_:{payload_len:231, pkt_seq:0, req_id:15312499, flag_.flags:46, ext_flags:0}, obp_mysql_header_{len_:227, rec_:231, seq_:0}, obp_mysql_header_.type_:3, obp_mysql_header_.is_send_:0}, pkt_rec[4]:{send:obp_compess_header_{com_len:296, com_seq:1}, obp20_header_:{payload_len:268, pkt_seq:1, req_id:15312499, flag_.flags:10, ext_flags:0}, obp_mysql_header_{len_:93, seq_:2}, pkt_name:"PKT_ERR", obp_mysql_header_.is_send_:1}, pkt_rec[5]:{send:obp_compess_header_{com_len:296, com_seq:1}, obp20_header_:{payload_len:268, pkt_seq:1, req_id:15312499, flag_.flags:10, ext_flags:0}, obp_mysql_header_{len_:175, seq_:3}, pkt_name:"PKT_OKP", obp_mysql_header_.is_send_:1}, pkt_rec[6]:{receive:obp20_header_:{payload_len:1262, pkt_seq:0, req_id:15312500, flag_.flags:47, ext_flags:0}, obp_mysql_header_{len_:634, rec_:638, seq_:0}, obp_mysql_header_.type_:3, obp_mysql_header_.is_send_:0}, pkt_rec[7]:{send:obp_compess_header_{com_len:564, com_seq:1}, obp20_header_:{payload_len:536, pkt_seq:1, req_id:15312500, flag_.flags:10, ext_flags:0}, obp_mysql_header_{len_:93, seq_:2}, pkt_name:"PKT_ERR", obp_mysql_header_.is_send_:1}, pkt_rec[8]:{send:obp_compess_header_{com_len:564, com_seq:1}, obp20_header_:{payload_len:536, pkt_seq:1, req_id:15312500, flag_.flags:10, ext_flags:0}, obp_mysql_header_{len_:175, seq_:3}, pkt_name:"PKT_OKP", obp_mysql_header_.is_send_:1}, pkt_rec[9]:{send:obp_compess_header_{com_len:564, com_seq:1}, obp20_header_:{payload_len:536, pkt_seq:1, req_id:15312500, flag_.flags:10, ext_flags:0}, obp_mysql_header_{len_:93, seq_:4}, pkt_name:"PKT_ERR", obp_mysql_header_.is_send_:1}, pkt_rec[10]:{send:obp_compess_header_{com_len:564, com_seq:1}, obp20_header_:{payload_len:536, pkt_seq:1, req_id:15312500, flag_.flags:10, ext_flags:0}, obp_mysql_header_{len_:175, seq_:5}, pkt_name:"PKT_OKP", obp_mysql_header_.is_send_:1}], disconnect_state=4)
huangzhihao@U-WML2G6Q9-1902 172.1.74.28 %
分析结论：因报错堆栈无指向性cs_id，只能通过语句判定。这条链路排查方式无法百分百保证排查准确性。尽管有断链情况，并且当时异常节点语句过滤仅有这条（无法确定您取得正不正确），这边排查显示是obproxy这边解析了ob侧错误的包导致obproxy侧断开。目前需要复现抓包，抓obproxy侧2883和2881端口的包，需要使用ip和端口号判断这条语句断链的准确性，然后百分百核实整条链路的排查准确性，并且可以查看当时发送的包为什么解析错误。抓包是必要过程
标签：false,OceanBase,us,server,version,time,cs,断链,id From： https://www.cnblogs.com/dbahuangzhihao/p/18382771