社区版4.1 日志中每十分钟出一次OB_SCHEMA_ERROR报错

OceanBase
#1

更新一下： 该问题在v4.1.0_CE_BP2版本中已经修复

【 使用环境 】测试环境
【 OB or 其他组件 】
【 使用版本 】社区版4.1
【问题描述】
用社区版OCP 4.0.3 新部署的4.1社区版，只有两台机器，1-1架构，除了sys外，只新建了一个1002租户，规格是64c152G, 每十分钟observer日志里就会出一次 OB_SCHEMA_ERROR 报错

请教这个要怎么处理？

日志如下：
[2023-05-11 01:14:32.029940] ERROR check_sys_table_schemas_ (ob_root_inspection.cpp:1343) [288247][RSInspectTask][T0][Y0-0000000000000000-0-0] [lt=6][errcode=-4754] root inspection is not passed(msg=“inner tables are unmatched”, ret=-4029, ret=“OB_SCHEMA_ERROR”, tenant_id=1001)
[2023-05-11 01:14:32.249873] ERROR check_sys_table_schemas_ (ob_root_inspection.cpp:1343) [288247][RSInspectTask][T0][Y0-0000000000000000-0-0] [lt=4][errcode=-4754] root inspection is not passed(msg=“inner tables are unmatched”, ret=-4029, ret=“OB_SCHEMA_ERROR”, tenant_id=1002)
[2023-05-11 01:24:32.038068] ERROR check_sys_table_schemas_ (ob_root_inspection.cpp:1343) [288247][RSInspectTask][T0][Y0-0000000000000000-0-0] [lt=5][errcode=-4754] root inspection is not passed(msg=“inner tables are unmatched”, ret=-4029, ret=“OB_SCHEMA_ERROR”, tenant_id=1001)
[2023-05-11 01:24:32.255180] ERROR check_sys_table_schemas_ (ob_root_inspection.cpp:1343) [288247][RSInspectTask][T0][Y0-0000000000000000-0-0] [lt=4][errcode=-4754] root inspection is not passed(msg=“inner tables are unmatched”, ret=-4029, ret=“OB_SCHEMA_ERROR”, tenant_id=1002)
[2023-05-11 01:34:32.010972] ERROR check_sys_table_schemas_ (ob_root_inspection.cpp:1343) [288247][RSInspectTask][T0][Y0-0000000000000000-0-0] [lt=9][errcode=-4754] root inspection is not passed(msg=“inner tables are unmatched”, ret=-4029, ret=“OB_SCHEMA_ERROR”, tenant_id=1001)
[2023-05-11 01:34:32.232100] ERROR check_sys_table_schemas_ (ob_root_inspection.cpp:1343) [288247][RSInspectTask][T0][Y0-0000000000000000-0-0] [lt=3][errcode=-4754] root inspection is not passed(msg=“inner tables are unmatched”, ret=-4029, ret=“OB_SCHEMA_ERROR”, tenant_id=1002)

1 个赞
#3

有手动换过不同版本的binary，没有走升级流程吗

#5

没有哦，就是OCP里部署的新集群，做了以下设置：
ALTER SYSTEM SET _ob_trans_rpc_timeout = ‘25s’;
ALTER SYSTEM SET __easy_memory_reserved_percentage = 10;
ALTER SYSTEM SET __easy_memory_limit = ‘20G’;
ALTER PROXYCONFIG SET enable_compression_protocol = False;
ALTER PROXYCONFIG SET automatic_match_work_thread = True;
ALTER PROXYCONFIG SET monitor_log_level = ‘ERROR’;
ALTER PROXYCONFIG SET xflush_log_level=“ERROR”;
ALTER PROXYCONFIG SET syslog_level=“ERROR”;

alter system set enable_monotonic_weak_read = true;
alter system set weak_read_version_refresh_interval=‘5s’;

alter system set memory_limit_percentage = 90;
alter system set freeze_trigger_percentage = 50;
alter system set memstore_limit_percentage = 55;

alter system set enable_early_lock_release=true tenant=‘test’;
alter system set memory_chunk_cache_size=0;
alter system set syslog_io_bandwidth_limit=‘30m’;
alter system set enable_async_syslog=true;
alter system set large_query_worker_percentage=10;
alter system set builtin_db_data_verify_cycle=0;
alter system set micro_block_merge_verify_level=0;
alter system set large_query_threshold=‘200s’;
alter system set trace_log_slow_query_watermark=‘10s’;
alter system set server_permanent_offline_time=‘36000s’;
alter system set _ob_get_gts_ahead_interval=‘1ms’;
alter system set bf_cache_priority=10;
alter system set user_block_cache_priority=5;
alter system set syslog_level=‘PERF’;
alter system set plan_cache_evict_interval=‘30s’;
alter system set bf_cache_miss_count_threshold=1;
alter system set _enable_defensive_check=False;
alter system set _rowsets_enabled=false tenant=‘test’;
alter system set _enable_newsort=false;
alter system set _trace_control_info=’’ tenant=‘test’;
alter system set _lcl_op_interval=‘0ms’;
alter system set ob_enable_batched_multi_statement=True tenant=‘test’;
alter system set writing_throttling_trigger_percentage=100 tenant=‘test’;

alter proxyconfig set enable_prometheus=False;
alter proxyconfig set enable_metadb_used=False;
alter proxyconfig set enable_standby=False;
alter proxyconfig set enable_strict_stat_time=False;
alter proxyconfig set use_local_dbconfig=True;
alter proxyconfig set enable_compression_protocol=False;
alter proxyconfig set enable_ob_protocol_v2=False;

#6

将报错前后的完整日志发下

#7

observer的日志

#8

[2023-05-11 12:24:31.970002] INFO [STORAGE] schedule_all_tablets_medium (ob_tenant_tablet_scheduler.cpp:1161) [288703][T1_MediumLoop][T1][Y0-0000000000000000-0-0] [lt=15] finish schedule all tablet merge(merge_version=1683741603403108685, schedule_stats_={schedule_cnt:794, finish_cnt:794, wait_rs_validate_cnt:0}, tenant_merge_finish=true, merged_version_=1683741603403108685)
[2023-05-11 12:24:31.970017] INFO [STORAGE] runTimerTask (ob_tenant_tablet_scheduler.cpp:136) [288703][T1_MediumLoop][T1][Y0-0000000000000000-0-0] [lt=13] MediumLoopTask(cost_ts=3499)
[2023-05-11 12:24:31.973267] INFO [PALF] handle_next_submit_log_ (log_sliding_window.cpp:1010) [288706][T1_TxLoopWorker][T1][Y0-0000000000000000-0-0] [lt=10] [PALF STAT GROUP LOG INFO](palf_id=1, self=“192.168.51.176:2882”, role=“LEADER”, total_group_log_cnt=10, avg_log_batch_cnt=1, total_group_log_size=1220, avg_group_log_size=122)
[2023-05-11 12:24:31.975713] INFO [COORDINATOR] refresh (ob_leader_coordinator.cpp:145) [288587][T1_Occam][T1][Y0-0000000000000000-0-0] [lt=20] refresh all_ls_election_reference_info success(ret=0, ret=“OB_SUCCESS”, *new_all_ls_election_reference_info=[{1,0,False,{False,},False,False,True}])
[2023-05-11 12:24:31.980449] INFO [ARCHIVE] gc_stale_ls_task (ob_ls_mgr.cpp:537) [288696][T1_LSArchiveMgr][T1][YB42C0A833B0-0005FB597152FA1F-0-0] [lt=10] gc stale ls task succ
[2023-05-11 12:24:31.985407] INFO [SHARE] refresh_primary_cluster_id (ob_alive_server_tracer.cpp:402) [288121][ServerTracerTim][T0][YB42C0A833B0-0005FB5972431B6A-0-0] [lt=11] refresh primary cluster finish(ret=0, primary_cluster_id=-1)
[2023-05-11 12:24:31.989585] INFO [STORAGE.TRANS] get_number (ob_id_service.cpp:389) [288807][T1_L0_G5][T1][YB42C0A833B1-0005FB597A24E8AC-0-0] [lt=17] get number(ret=0, service_type_=0, range=1, base_id=1683779071989582696, start_id=1683779071989582696, end_id=1683779071989582697)
[2023-05-11 12:24:31.993054] INFO [SHARE.SCHEMA] get_database_id (ob_schema_getter_guard.cpp:1684) [288247][RSInspectTask][T1001][YB42C0A833B0-0005FB597693C4C8-0-0] [lt=12] database not exist(tenant_id=1001, database_name=INFORMATION_SCHEMA)
[2023-05-11 12:24:31.993075] WDIAG resolve_basic_table_without_cte (ob_dml_resolver.cpp:2730) [288247][RSInspectTask][T1001][YB42C0A833B0-0005FB597693C4C8-0-0] [lt=13][errcode=-5019] Table ‘INFORMATION_SCHEMA.REFERENTIAL_CONSTRAINTS’ doesn’t exist
[2023-05-11 12:24:31.993086] WDIAG do_expand_view (ob_dml_resolver.cpp:4523) [288247][RSInspectTask][T1001][YB42C0A833B0-0005FB597693C4C8-0-0] [lt=12][errcode=-5231] View ‘information_schema.TABLE_CONSTRAINTS’ references invalid table(s) or column(s) or function(s) or definer/invoker of view lack rights to use them
[2023-05-11 12:24:31.993093] WDIAG resolve_view_definition (ob_table_columns.cpp:937) [288247][RSInspectTask][T1001][YB42C0A833B0-0005FB597693C4C8-0-0] [lt=5][errcode=-5231] View ‘information_schema.TABLE_CONSTRAINTS’ references invalid table(s) or column(s) or function(s) or definer/invoker of view lack rights to use them

[2023-05-11 12:24:32.002668] ERROR check_sys_table_schemas_ (ob_root_inspection.cpp:1343) [288247][RSInspectTask][T0][Y0-0000000000000000-0-0] [lt=5][errcode=-4754] root inspection is not passed(msg="inner tables are unmatched", ret=-4029, ret="OB_SCHEMA_ERROR", tenant_id=1001)

[2023-05-11 12:24:32.002674] INFO [COMMON] advance_clock (ob_fifo_arena.cpp:346) [295561][T1001_PLSSer][T1001][YB42C0A833B0-0005FB5979639D78-0-0] [lt=13] current clock is (clock_=275174688, max_seq_=275174688, mem_limit=5002110165, cur_mem_hold=383778816, attr_.tenant_id_=1001)
[2023-05-11 12:24:32.002903] INFO [PALF] handle_next_submit_log_ (log_sliding_window.cpp:1010) [295561][T1001_PLSSer][T1001][YB42C0A833B0-0005FB5979639D78-0-0] [lt=9] [PALF STAT GROUP LOG INFO](palf_id=1, self=“192.168.51.176:2882”, role=“LEADER”, total_group_log_cnt=13, avg_log_batch_cnt=1, total_group_log_size=9329, avg_group_log_size=717)
[2023-05-11 12:24:32.002921] INFO [PALF] submit_log (palf_handle_impl.cpp:403) [295561][T1001_PLSSer][T1001][YB42C0A833B0-0005FB5979639D78-0-0] [lt=20] [PALF STAT APPEND DATA SIZE](this={palf_id:1, self:“192.168.51.176:2882”, has_set_deleted:false}, append size=9329)
[2023-05-11 12:24:32.002930] INFO [LIB] stat (utility.h:1140) [295561][T1001_PLSSer][T1001][YB42C0A833B0-0005FB5979639D78-0-0] [lt=8] [PALF STAT APPEND COST](cur_stat_count=13, stat_interval=1000000, avg cost=32, this=0x7f2792fea950)
[2023-05-11 12:24:32.003152] INFO [LIB] stat (utility.h:1140) [295555][T1001_IOWorker][T1001][Y0-0000000000000000-0-0] [lt=8] [PALF STAT WRITE LOG](cur_stat_count=13, stat_interval=1000000, avg cost=245, this=0x7f279a1ffad8)
[2023-05-11 12:24:32.003166] INFO [PALF] inner_append_log (palf_handle_impl.cpp:1670) [295555][T1001_IOWorker][T1001][Y0-0000000000000000-0-0] [lt=13] [PALF STAT INNER APPEND LOG](this={palf_id:1, self:“192.168.51.176:2882”, has_set_deleted:false}, accum_size=9329)
[2023-05-11 12:24:32.003198] INFO [PALF] try_advance_committed_lsn_ (log_sliding_window.cpp:1582) [295554][T1001_LogIOCb0][T1001][Y0-0000000000000000-0-0] [lt=8] [PALF STAT COMMITTED LOG SIZE](palf_id=1, self=“192.168.51.176:2882”, committed size=9329)
[2023-05-11 12:24:32.003211] INFO [LIB] stat (utility.h:1140) [295554][T1001_LogIOCb0][T1001][Y0-0000000000000000-0-0] [lt=11] [PALF STAT FLUSH CB](cur_stat_count=13, stat_interval=1000000, avg cost=15, this=0x7f279a1ffb08)
[2023-05-11 12:24:32.003291] INFO [LIB] stat (utility.h:1140) [295935][T1001_L0_G1][T1001][YB42C0A833B1-0005FB5977B9713C-0-0] [lt=3] [PALF STAT FS CB](cur_stat_count=13, stat_interval=1000000, avg cost=5, this=0x7f279a1f73a8)
[2023-05-11 12:24:32.003301] INFO [LIB] stat (utility.h:1140) [295935][T1001_L0_G1][T1001][YB42C0A833B1-0005FB5977B9713C-0-0] [lt=10] [PALF STAT LOG LIFETIME](cur_stat_count=13, stat_interval=1000000, avg cost=422, this=0x7f279a1f73d8)
[2023-05-11 12:24:32.003311] INFO [LIB] stat (utility.h:1140) [295935][T1001_L0_G1][T1001][YB42C0A833B1-0005FB5977B9713C-0-0] [lt=9] [PALF STAT LOG SUBMIT WAIT](cur_stat_count=13, stat_interval=1000000, avg cost=20, this=0x7f279a1f7408)
[2023-05-11 12:24:32.003317] INFO [LIB] stat (utility.h:1140) [295935][T1001_L0_G1][T1001][YB42C0A833B1-0005FB5977B9713C-0-0] [lt=6] [PALF STAT LOG SLIDE WAIT](cur_stat_count=13, stat_interval=1000000, avg cost=402, this=0x7f279a1f7438)
[2023-05-11 12:24:32.016067] INFO [STORAGE] scheduler_ls_ha_handler_ (ob_storage_ha_service.cpp:186) [294917][T1002_HAService][T1002][Y0-0000000000000000-0-0] [lt=15] start do ls ha handler(ls_id_array_=[{id:1}, {id:1001}])
[2023-05-11 12:24:32.019924] INFO [SHARE.LOCATION] vtable_nonblock_renew (ob_vtable_location_service.cpp:446) [288247][RSInspectTask][T1002][YB42C0A833B0-0005FB597693C4D2-0-0] [lt=15] add_update_task succeed(ret=0, ret=“OB_SUCCESS”, task={tenant_id:1002, table_id:10002, add_timestamp:1683779072019914})
[2023-05-11 12:24:32.019948] INFO [SHARE.LOCATION] renew_vtable_location_ (ob_vtable_location_service.cpp:207) [288284][][T0][YB42C0A833B0-0005FB5975C3FC33-0-0] [lt=11] renew vtable location success(ret=0, ret=“OB_SUCCESS”, table_id=10002, locations=[{table_id:10002, partition_id:10002, partition_cnt:0, replica_locations:[{server:“192.168.51.176:2882”, role:1, sql_port:2881, replica_type:0, reserved:0, property:{memstore_percent_:100}}], renew_time:1683779072019932, sql_renew_time:1683779072019932, is_mark_fail:false}])
[2023-05-11 12:24:32.019967] INFO [SHARE.LOCATION] batch_process_tasks (ob_vtable_location_service.cpp:414) [288284][][T0][YB42C0A833B0-0005FB5975C3FC33-0-0] [lt=18] success to process renew task(task={tenant_id:1002, table_id:10002, add_timestamp:1683779072019914}, locations=[{table_id:10002, partition_id:10002, partition_cnt:0, replica_locations:[{server:“192.168.51.176:2882”, role:1, sql_port:2881, replica_type:0, reserved:0, property:{memstore_percent_:100}}], renew_time:1683779072019932, sql_renew_time:1683779072019932, is_mark_fail:false}])
[2023-05-11 12:24:32.047700] INFO [STORAGE.TRANS] get_number (ob_id_service.cpp:389) [288310][TsMgr][T1][Y0-0000000000000000-0-0] [lt=18] get number(ret=0, service_type_=0, range=1, base_id=1683779072047696281, start_id=1683779072047696281, end_id=1683779072047696282)
[2023-05-11 12:24:32.052861] INFO [PALF] log_loop_ (log_loop_thread.cpp:122) [294807][T1002_LogLoop][T1002][Y0-0000000000000000-0-0] [lt=18] LogLoopThread round_cost_time(round_cost_time=3)
[2023-05-11 12:24:32.056344] INFO [STORAGE.REDO] notify_flush (ob_storage_log_writer.cpp:546) [294874][T1002_OB_SLOG][T1002][Y0-0000000000000000-0-0] [lt=37] Successfully flush(log_item={start_cursor:ObLogCursor{file_id=1, log_id=120511, offset=48057148}, end_cursor:ObLogCursor{file_id=1, log_id=120512, offset=48057377}, is_inited:true, is_local:false, buf_size:524288, buf:0x7f28fcd08050, len:1220, log_data_len:229, seq:120511, flush_finish:false, flush_ret:0})
[2023-05-11 12:24:32.056591] INFO [STORAGE.REDO] notify_flush (ob_storage_log_writer.cpp:546) [294874][T1002_OB_SLOG][T1002][Y0-0000000000000000-0-0] [lt=16] Successfully flush(log_item={start_cursor:ObLogCursor{file_id=1, log_id=120512, offset=48057377}, end_cursor:ObLogCursor{file_id=1, log_id=120513, offset=48057597}, is_inited:true, is_local:false, buf_size:524288, buf:0x7f2902486050, len:991, log_data_len:220, seq:120512, flush_finish:false, flush_ret:0})
[2023-05-11 12:24:32.057154] INFO [COMMON] advance_clock (ob_fifo_arena.cpp:346) [294810][T1002_TeRec][T1001][YB42C0A833B0-0005FB598DC844BE-0-0] [lt=12] current clock is (clock_=275174992, max_seq_=275174992, mem_limit=5002110165, cur_mem_hold=383778816, attr_.tenant_id_=1001)
[2023-05-11 12:24:32.057683] INFO [COMMON] compute_tenant_wash_size (ob_kvcache_store.cpp:1140) [288157][KVCacheWash][T0][Y0-0000000000000000-0-0] [lt=16] Wash compute wash size(is_wash_valid=false, sys_total_wash_size=-106669987430, global_cache_size=108936527872, tenant_max_wash_size=0, tenant_min_wash_size=0, tenant_ids_=[512, 500, 506, 508, 509, 510, 1, 1001, 1002])
[2023-05-11 12:24:32.066564] INFO [STORAGE] scheduler_ls_ha_handler_ (ob_storage_ha_service.cpp:186) [295676][T1001_HAService][T1001][Y0-0000000000000000-0-0] [lt=11] start do ls ha handler(ls_id_array_=[{id:1}])
[2023-05-11 12:24:32.070198] INFO [RPC.OBMYSQL] handle_pending_destroy_list (ob_sql_nio.cpp:791) [288360][sql_nio0][T0][Y0-0000000000000000-0-0] [lt=14] can close safely, do destroy(*s={this:0x7f28fe3e5290, fd:383, err:5, last_decode_time_:1683779071703104, last_write_time_:1683779071702970, read_buffer_.get_consume_sz():2411, get_pending_flag():2, get_trace_id():Y0-0000000000000000-0-0})
[2023-05-11 12:24:32.070220] INFO [RPC.OBMYSQL] sm_conn_unlock_tenant (obsm_conn_callback.cpp:144) [288360][sql_nio0][T0][Y0-0000000000000000-0-0] [lt=16] unlock session of tenant(conn.sessid_=3221550756, proxy_sessid=0, conn.tenant_id_=1)
[2023-05-11 12:24:32.070228] INFO [RPC.OBMYSQL] sm_conn_log_close (obsm_conn_callback.cpp:159) [288360][sql_nio0][T0][Y0-0000000000000000-0-0] [lt=8] connection close(sessid=3221550756, proxy_sessid=0, tenant_id=1, server_id=1, from_proxy=false, from_java_client=false, c/s protocol=“OB_MYSQL_CS_TYPE”, is_need_clear_sessid_=true, ret=0)
[2023-05-11 12:24:32.070270] INFO [SERVER] run (obmp_disconnect.cpp:78) [288730][T1_L0_G0][T1][Y0-0000000000000000-0-0] [lt=9] free session successfully(sessid=3221550756)
[2023-05-11 12:24:32.070551] INFO [COMMON] clean_garbage_node (ob_kvcache_map.cpp:647) [288157][KVCacheWash][T0][Y0-0000000000000000-0-0] [lt=18] Cache wash clean map node details(ret=0, clean_node_count=0, clean_time=12849, clean_start_pos=19600000, clean_num=200000)
[2023-05-11 12:24:32.088871] INFO [SHARE.LOCATION] renew_all_ls_locations_by_rpc (ob_ls_location_service.cpp:795) [288278][AutoLSLocRpc][T0][YB42C0A833B0-0005FB597453A074-0-0] [lt=35] [LS_LOCATION] Get ls leaders by RPC(ret=0, ret=“OB_SUCCESS”, dests=[“192.168.51.176:2882”, “192.168.51.177:2882”], leaders=[{key:{tenant_id:1, ls_id:{id:1}, cluster_id:4}, location:{server:“192.168.51.176:2882”, role:1, sql_port:2881, replica_type:0, property:{memstore_percent_:100}, restore_status:{status:0}, proposal_id:2}}, {key:{tenant_id:1001, ls_id:{id:1}, cluster_id:4}, location:{server:“192.168.51.176:2882”, role:1, sql_port:2881, replica_type:0, property:{memstore_percent_:100}, restore_status:{status:0}, proposal_id:1}}, {key:{tenant_id:1002, ls_id:{id:1}, cluster_id:4}, location:{server:“192.168.51.176:2882”, role:1, sql_port:2881, replica_type:0, property:{memstore_percent_:100}, restore_status:{status:0}, proposal_id:1}}, {key:{tenant_id:1002, ls_id:{id:1001}, cluster_id:4}, location:{server:“192.168.51.176:2882”, role:1, sql_port:2881, replica_type:0, property:{memstore_percent_:100}, restore_status:{status:0}, proposal_id:1}}])
[2023-05-11 12:24:32.090083] INFO [STORAGE.TRANS] get_number (ob_id_service.cpp:389) [288807][T1_L0_G5][T1][YB42C0A833B1-0005FB597A24E8AF-0-0] [lt=13] get number(ret=0, service_type_=0, range=1, base_id=1683779072090079677, start_id=1683779072090079677, end_id=1683779072090079678)
[2023-05-11 12:24:32.090537] INFO [COORDINATOR] refresh (ob_leader_coordinator.cpp:145) [295548][T1001_Occam][T1001][Y0-0000000000000000-0-0] [lt=18] refresh all_ls_election_reference_info success(ret=0, ret=“OB_SUCCESS”, *new_all_ls_election_reference_info=[{1,0,False,{False,},False,False,True}])
[2023-05-11 12:24:32.093033] INFO [SQL.EXE] run2 (ob_maintain_dependency_info_task.cpp:221) [288264][MaintainDepInfo][T0][Y0-0000000000000000-0-0] [lt=9] ASYNC TASK QUEUE
[2023-05-11 12:24:32.096774] INFO [RPC.FRAME] rpc_easy_timer_cb (ob_net_easy.cpp:595) [288314][RpcIO][T0][Y0-0000000000000000-0-0] [lt=9] [RPC EASY STAT](log_str=conn count=2/2, request done=840449/31451530, request doing=0/0)
[2023-05-11 12:24:32.096885] INFO [RPC.FRAME] rpc_easy_timer_cb (ob_net_easy.cpp:595) [288316][RpcIO][T0][Y0-0000000000000000-0-0] [lt=9] [RPC EASY STAT](log_str=conn count=2/2, request done=840451/31452950, request doing=0/0)
[2023-05-11 12:24:32.097035] INFO [RPC.FRAME] rpc_easy_timer_cb (ob_net_easy.cpp:595) [288318][RpcIO][T0][Y0-0000000000000000-0-0] [lt=11] [RPC EASY STAT](log_str=conn count=2/2, request done=840455/31456410, request doing=0/0)
[2023-05-11 12:24:32.097164] INFO [RPC.FRAME] rpc_easy_timer_cb (ob_net_easy.cpp:595) [288320][RpcIO][T0][Y0-0000000000000000-0-0] [lt=8] [RPC EASY STAT](log_str=conn count=2/2, request done=840455/31459627, request doing=0/0)
[2023-05-11 12:24:32.097167] INFO [RPC.FRAME] rpc_easy_timer_cb (ob_net_easy.cpp:595) [288313][RpcIO][T0][Y0-0000000000000000-0-0] [lt=9] [RPC EASY STAT](log_str=conn count=2/2, request done=840462/31445881, request doing=0/0)
[2023-05-11 12:24:32.097265] INFO [RPC.FRAME] rpc_easy_timer_cb (ob_net_easy.cpp:595) [288315][RpcIO][T0][Y0-0000000000000000-0-0] [lt=9] [RPC EASY STAT](log_str=conn count=2/2, request done=840467/31480703, request doing=0/0)
[2023-05-11 12:24:32.097357] INFO [RPC.FRAME] rpc_easy_timer_cb (ob_net_easy.cpp:595) [288317][RpcIO][T0][Y0-0000000000000000-0-0] [lt=9] [RPC EASY STAT](log_str=conn count=2/2, request done=840485/31472057, request doing=0/0)
[2023-05-11 12:24:32.097470] INFO [RPC.FRAME] rpc_easy_timer_cb (ob_net_easy.cpp:595) [288319][RpcIO][T0][Y0-0000000000000000-0-0] [lt=7] [RPC EASY STAT](log_str=conn count=2/2, request done=840457/31473389, request doing=0/0)
[2023-05-11 12:24:32.097569] INFO [RPC.FRAME] rpc_easy_timer_cb (ob_net_easy.cpp:595) [288321][RpcIO][T0][Y0-0000000000000000-0-0] [lt=9] [RPC EASY STAT](log_str=conn count=2/2, request done=840451/31476047, request doing=0/0)
[2023-05-11 12:24:32.097661] INFO [RPC.FRAME] rpc_easy_timer_cb (ob_net_easy.cpp:595) [288323][RpcIO][T0][Y0-0000000000000000-0-0] [lt=11] [RPC EASY STAT](log_str=conn count=2/2, request done=798436/29904872, request doing=0/0)
[2023-05-11 12:24:32.097755] INFO [RPC.FRAME] rpc_easy_timer_cb (ob_net_easy.cpp:595) [288325][RpcIO][T0][Y0-0000000000000000-0-0] [lt=10] [RPC EASY STAT](log_str=conn count=2/2, request done=798444/29910897, request doing=0/0)
[2023-05-11 12:24:32.097969] INFO [RPC.FRAME] rpc_easy_timer_cb (ob_net_easy.cpp:595) [288322][RpcIO][T0][Y0-0000000000000000-0-0] [lt=6] [RPC EASY STAT](log_str=conn count=2/2, request done=798439/29881944, request doing=0/0)
[2023-05-11 12:24:32.098061] INFO [RPC.FRAME] rpc_easy_timer_cb (ob_net_easy.cpp:595) [288324][RpcIO][T0][Y0-0000000000000000-0-0] [lt=7] [RPC EASY STAT](log_str=conn count=2/2, request done=798437/29878016, request doing=0/0)
[2023-05-11 12:24:32.102631] INFO [COMMON] replace_fragment_node (ob_kvcache_map.cpp:697) [288158][KVCacheRep][T0][Y0-0000000000000000-0-0] [lt=14] Cache replace map node details(ret=0, replace_node_count=0, replace_time=6439, replace_start_pos=83600000, replace_num=100000)
[2023-05-11 12:24:32.105856] INFO [ARCHIVE] gc_stale_ls_task (ob_ls_mgr.cpp:537) [294908][T1002_LSArchive][T1002][YB42C0A833B0-0005FB5976F2FA1F-0-0] [lt=10] gc stale ls task succ
[2023-05-11 12:24:32.136808] INFO [ARCHIVE] gc_stale_ls_task (ob_ls_mgr.cpp:537) [295667][T1001_LSArchive][T1001][YB42C0A833B0-0005FB5977F2FA1F-0-0] [lt=10] gc stale ls task succ
[2023-05-11 12:24:32.148151] INFO [STORAGE.TRANS] get_number (ob_id_service.cpp:389) [288310][TsMgr][T1][Y0-0000000000000000-0-0] [lt=13] get number(ret=0, service_type_=0, range=1, base_id=1683779072148148001, start_id=1683779072148148001, end_id=1683779072148148002)
[2023-05-11 12:24:32.148172] INFO [STORAGE.TRANS] operator() (ob_ts_mgr.h:171) [288310][TsMgr][T0][Y0-0000000000000000-0-0] [lt=12] refresh gts functor(ret=0, ret=“OB_SUCCESS”, gts_tenant_info={v:1})
[2023-05-11 12:24:32.156442] INFO [SERVER] loop (ob_safe_destroy_thread.cpp:133) [288301][SafeDestroy][T0][Y0-0000000000000000-0-0] [lt=26] ObSafeDestroyTaskQueue::loop begin(queue_.size()=0)
[2023-05-11 12:24:32.156459] INFO [SERVER] loop (ob_safe_destroy_thread.cpp:140) [288301][SafeDestroy][T0][Y0-0000000000000000-0-0] [lt=11] ObSafeDestroyTaskQueue::loop finish(ret=0, queue_.size()=0)
[2023-05-11 12:24:32.156883] INFO [STORAGE] runTimerTask (ob_checkpoint_service.cpp:351) [295664][T1001_CKClogDis][T1001][Y0-0000000000000000-0-0] [lt=6] ====== check clog disk timer task ======
[2023-05-11 12:24:32.156896] INFO [PALF] get_disk_usage (palf_env_impl.cpp:781) [295664][T1001_CKClogDis][T1001][Y0-0000000000000000-0-0] [lt=10] get_disk_usage(ret=0, capacity(MB):=46694, used(MB):=460)
[2023-05-11 12:24:32.157460] INFO [STORAGE.TRANS] get_rec_scn (ob_trans_ctx_mgr_v4.cpp:1297) [295664][T1001_CKClogDis][T1001][Y0-0000000000000000-0-0] [lt=6] succ to get rec scn(*this={this:0x7f2784c04030, ls_id:{id:1}, tenant_id:1001, state:“L_WORKING”, total_tx_ctx_count:0, ls_retain_ctx_mgr:{retain_ctx_list_.size():0, max_wait_ckpt_ts_:{val:1683741604402979017}, last_push_gc_task_ts_:1683741606509569, skip_remove_cnt_:0}, aggre_rec_scn:{val:18446744073709551615}, prev_aggre_rec_scn:{val:18446744073709551615}, uref:3}, aggre_rec_scn={val:4611686018427387903})
[2023-05-11 12:24:32.157478] INFO [STORAGE.TRANS] get_rec_scn (ob_tx_ctx_memtable.cpp:232) [295664][T1001_CKClogDis][T1001][Y0-0000000000000000-0-0] [lt=18] tx ctx memtable get rec scn(this={ObITable:{this:0x7f278db76080, key:{tablet_id:{id:49401}, column_group_idx:0, table_type:“TX_CTX_MEMTABLE”, scn_range:{start_scn:{val:1}, end_scn:{val:1683741604407429}}}, ref_cnt:2, upper_trans_version:-4007, timestamp:0}, this:0x7f278db76080, snapshot_version:{val:1683741604407429}, ls_id:{id:1}, is_frozen:false}, rec_scn={val:4611686018427387903})
[2023-05-11 12:24:32.157498] INFO [STORAGE.TABLELOCK] get_rec_scn (ob_lock_memtable.cpp:742) [295664][T1001_CKClogDis][T1001][Y0-0000000000000000-0-0] [lt=15] rec_scn of ObLockMemtable is (rec_scn_={val:4611686018427387903}, flushed_scn_={val:0}, pre_rec_scn_={val:18446744073709551615}, freeze_scn_={val:0}, max_committed_scn_={val:18446744073709551615}, is_frozen_=false, ls_id_={id:1})
[2023-05-11 12:24:32.157509] INFO [STORAGE.TRANS] get_rec_scn (ob_ls_tx_service.cpp:441) [295664][T1001_CKClogDis][T1001][Y0-0000000000000000-0-0] [lt=9] [CHECKPOINT] ObLSTxService::get_rec_scn(common_checkpoint_type=“TX_DATA_MEMTABLE_TYPE”, common_checkpoints_[min_rec_scn_common_checkpoint_type_index]={ObIMemtableMgr:{Memtables:this:0x7f2792fe61b0, ref_cnt:1, is_inited:true, tablet_id:{id:49402}, freezer:0x7f2792feb290, table_type:1, memtable_head:2, memtable_tail:3, t3m:0x7f27da7e2030, tables:[null, null, 0x7f278db66080, null, null, null, null, null, null, null, null, null, null, null, null, null]}, is_freezing:false, ls_id:{id:1}, tx_data_table:0x7f2792fec650, ls_tablet_svr:0x7f2792fe6190, slice_allocator:0x7f2792fec690}, min_rec_scn={val:1683741604414006096}, ls_id_={id:1})
[2023-05-11 12:24:32.158072] INFO [STORAGE.TRANS] get_rec_scn (ob_id_service.cpp:306) [295664][T1001_CKClogDis][T1001][Y0-0000000000000000-0-0] [lt=16] get rec log scn(service_type_=0, rec_log_ts={val:1683779062749070729})
[2023-05-11 12:24:32.158084] INFO [STORAGE.TRANS] get_rec_scn (ob_id_service.cpp:306) [295664][T1001_CKClogDis][T1001][Y0-0000000000000000-0-0] [lt=11] get rec log scn(service_type_=1, rec_log_ts={val:1683756036942752884})
[2023-05-11 12:24:32.158088] INFO [STORAGE.TRANS] get_rec_scn (ob_id_service.cpp:306) [295664][T1001_CKClogDis][T1001][Y0-0000000000000000-0-0] [lt=2] get rec log scn(service_type_=2, rec_log_ts={val:1683773938917808838})
[2023-05-11 12:24:32.158092] INFO [STORAGE] update_clog_checkpoint (ob_checkpoint_executor.cpp:158) [295664][T1001_CKClogDis][T1001][Y0-0000000000000000-0-0] [lt=3] [CHECKPOINT] clog checkpoint no change(checkpoint_scn={val:1683741604414006096}, checkpoint_scn_in_ls_meta={val:1683741604414006096}, ls_id={id:1}, service_type=“TRANS_SERVICE”)
[2023-05-11 12:24:32.158101] INFO [STORAGE] cannot_recycle_log_over_threshold_ (ob_checkpoint_service.cpp:264) [295664][T1001_CKClogDis][T1001][Y0-0000000000000000-0-0] [lt=7] cannot_recycle_log_size statistics(cannot_recycle_log_size=415862594, threshold=14688788152)
[2023-05-11 12:24:32.158112] INFO [STORAGE] flush_if_need_ (ob_ls.cpp:1564) [295664][T1001_CKClogDis][T1001][Y0-0000000000000000-0-0] [lt=5] the ls no need flush to advance_checkpoint(get_ls_id()={id:1}, need_flush=false)
[2023-05-11 12:24:32.159153] INFO [COMMON] advance_clock (ob_fifo_arena.cpp:346) [294810][T1002_TeRec][T1001][YB42C0A833B0-0005FB598DC844C3-0-0] [lt=14] current clock is (clock_=275175424, max_seq_=275175424, mem_limit=5002110165, cur_mem_hold=383778816, attr_.tenant_id_=1001)
[2023-05-11 12:24:32.159201] INFO [DETECT] maintain_deadlock_info_when_end_stmt (ob_trans_deadlock_adapter.cpp:635) [294810][T1002_TeRec][T1001][Y0-0000000000000000-0-0] [lt=12] deadlock not enabled
[2023-05-11 12:24:32.173618] INFO [PALF] try_advance_committed_lsn_ (log_sliding_window.cpp:1582) [288593][T1_LogIOCb0][T1][Y0-0000000000000000-0-0] [lt=10] [PALF STAT COMMITTED LOG SIZE](palf_id=1, self=“192.168.51.176:2882”, committed size=1220)
[2023-05-11 12:24:32.174419] INFO [CLOG] run1 (ob_garbage_collector.cpp:999) [288678][T1_GCCollector][T1][Y0-0000000000000000-0-0] [lt=3] Garbage Collector is running(seq_=4263, gc_interval=10000000)
[2023-05-11 12:24:32.174446] INFO [CLOG] construct_server_ls_map_for_member_list_ (ob_garbage_collector.cpp:1114) [288678][T1_GCCollector][T1][Y0-0000000000000000-0-0] [lt=8] self is leader, skip it(ls->get_ls_id()={id:1})
[2023-05-11 12:24:32.174458] INFO [CLOG] gc_check_member_list_ (ob_garbage_collector.cpp:1074) [288678][T1_GCCollector][T1][Y0-0000000000000000-0-0] [lt=7] gc_check_member_list_ cost time(ret=0, time_us=32)
[2023-05-11 12:24:32.174466] INFO [CLOG] execute_gc_ (ob_garbage_collector.cpp:1312) [288678][T1_GCCollector][T1][Y0-0000000000000000-0-0] [lt=5] execute_gc cost time(ret=0, time_us=0)
[2023-05-11 12:24:32.174472] INFO [CLOG] gc_check_ls_status_ (ob_garbage_collector.cpp:1257) [288678][T1_GCCollector][T1][Y0-0000000000000000-0-0] [lt=5] gc_candidates push_back success(ret=0, candidate={ls_id_:{id:1}, ls_status_:1, gc_reason_:0})
[2023-05-11 12:24:32.174480] INFO [CLOG] execute_gc_ (ob_garbage_collector.cpp:1279) [288678][T1_GCCollector][T1][Y0-0000000000000000-0-0] [lt=6] ls status is normal, skip(id={id:1}, gc_candidates=[{ls_id_:{id:1}, ls_status_:1, gc_reason_:0}])
[2023-05-11 12:24:32.174488] INFO [CLOG] execute_gc_ (ob_garbage_collector.cpp:1312) [288678][T1_GCCollector][T1][Y0-0000000000000000-0-0] [lt=8] execute_gc cost time(ret=0, time_us=9)
[2023-05-11 12:24:32.190506] INFO [STORAGE.TRANS] get_number (ob_id_service.cpp:389) [288807][T1_L0_G5][T1][YB42C0A833B1-0005FB597A24E8B2-0-0] [lt=13] get number(ret=0, service_type_=0, range=1, base_id=1683779072190502643, start_id=1683779072190502643, end_id=1683779072190502644)
[2023-05-11 12:24:32.196634] INFO [PALF] log_loop_ (log_loop_thread.cpp:122) [288597][T1_LogLoop][T1][Y0-0000000000000000-0-0] [lt=10] LogLoopThread round_cost_time(round_cost_time=1)
[2023-05-11 12:24:32.210500] INFO [SHARE.SCHEMA] get_database_id (ob_schema_getter_guard.cpp:1684) [288247][RSInspectTask][T1002][YB42C0A833B0-0005FB597693C59A-0-0] [lt=11] database not exist(tenant_id=1002, database_name=INFORMATION_SCHEMA)
[2023-05-11 12:24:32.210518] WDIAG resolve_basic_table_without_cte (ob_dml_resolver.cpp:2730) [288247][RSInspectTask][T1002][YB42C0A833B0-0005FB597693C59A-0-0] [lt=14][errcode=-5019] Table ‘INFORMATION_SCHEMA.REFERENTIAL_CONSTRAINTS’ doesn’t exist
[2023-05-11 12:24:32.210526] WDIAG do_expand_view (ob_dml_resolver.cpp:4523) [288247][RSInspectTask][T1002][YB42C0A833B0-0005FB597693C59A-0-0] [lt=6][errcode=-5231] View ‘information_schema.TABLE_CONSTRAINTS’ references invalid table(s) or column(s) or function(s) or definer/invoker of view lack rights to use them
[2023-05-11 12:24:32.210534] WDIAG resolve_view_definition (ob_table_columns.cpp:937) [288247][RSInspectTask][T1002][YB42C0A833B0-0005FB597693C59A-0-0] [lt=6][errcode=-5231] View ‘information_schema.TABLE_CONSTRAINTS’ references invalid table(s) or column(s) or function(s) or definer/invoker of view lack rights to use them

*[2023-05-11 12:24:32.220040] ERROR check_sys_table_schemas_ (ob_root_inspection.cpp:1343) [288247][RSInspectTask][T0][Y0-0000000000000000-0-0] [lt=3][errcode=-4754] root inspection is not passed(msg="inner tables are unmatched", ret=-4029, ret="OB_SCHEMA_ERROR", tenant_id=1002)

[2023-05-11 12:24:32.248572] INFO [STORAGE.TRANS] get_number (ob_id_service.cpp:389) [288310][TsMgr][T1][Y0-0000000000000000-0-0] [lt=8] get number(ret=0, service_type_=0, range=1, base_id=1683779072248569290, start_id=1683779072248569290, end_id=1683779072248569291)
[2023-05-11 12:24:32.261197] INFO [COMMON] advance_clock (ob_fifo_arena.cpp:346) [294810][T1002_TeRec][T1001][YB42C0A833B0-0005FB598DC844C8-0-0] [lt=7] current clock is (clock_=275175856, max_seq_=275175856, mem_limit=5002110165, cur_mem_hold=383778816, attr_.tenant_id_=1001)
[2023-05-11 12:24:32.270829] INFO [COMMON] compute_tenant_wash_size (ob_kvcache_store.cpp:1140) [288157][KVCacheWash][T0][Y0-0000000000000000-0-0] [lt=14] Wash compute wash size(is_wash_valid=false, sys_total_wash_size=-106669987430, global_cache_size=108936527872, tenant_max_wash_size=0, tenant_min_wash_size=0, tenant_ids_=[512, 500, 506, 508, 509, 510, 1, 1001, 1002])
[2023-05-11 12:24:32.272462] INFO [COMMON] wash (ob_kvcache_store.cpp:343) [288157][KVCacheWash][T0][Y0-0000000000000000-0-0] [lt=17] Wash time detail, (compute_wash_size_time=92, refresh_score_time=1616, wash_time=0)
[2023-05-11 12:24:32.290977] INFO [STORAGE.TRANS] get_number (ob_id_service.cpp:389) [288807][T1_L0_G5][T1][YB42C0A833B1-0005FB597A24E8B5-0-0] [lt=13] get number(ret=0, service_type_=0, range=1, base_id=1683779072290973704, start_id=1683779072290973704, end_id=1683779072290973705)
[2023-05-11 12:24:32.308142] INFO [SHARE] run_loop_ (ob_bg_thread_monitor.cpp:331) [288802][BGThreadMonitor][T0][Y0-0000000000000000-0-0] [lt=10] current monitor number(seq_=-1)
[2023-05-11 12:24:32.309024] INFO [COMMON] replace_fragment_node (ob_kvcache_map.cpp:697) [288158][KVCacheRep][T0][Y0-0000000000000000-0-0] [lt=12] Cache replace map node details(ret=0, replace_node_count=0, replace_time=6319, replace_start_pos=83700000, replace_num=100000)
[2023-05-11 12:24:32.311084] INFO [COMMON] print_sender_status (ob_io_struct.cpp:716) [288129][IO_TUNING0][T0][Y0-0000000000000000-0-0] [lt=9] [IO SENDER STATUS](send_index=1, req_count=0, reservation_ts=9223372036854775807, group_limitation_ts=9223372036854775807, tenant_limitation_ts=9223372036854775807, proportion_ts=9223372036854775807)

#9

你需要根据 报unmatch的trace id Y0-0000000000000000-0-0 去捞单纯这个报错路径上的日志，不是说了十分钟报一次，捞这十分钟的日志放到一个日志文件

#10

4209是分区leader不存在，如果确定只是新建租户，然后频繁报错，应该是触发了产品的bug.

#11

报unmatch的trace id Y0-0000000000000000-0-0 去捞单纯这个报错路径上的日志

请教一下，这个具体是要怎么操作？

#12

这个确实是新建的，刚新建好租户，什么都还没动， 不过这个报错就这么一直有，又好像不影响什么，数据库又是能正常使用的

#13

找到ob部署的节点，你是几副本的？ 去各台机器的日志目录grep 一下

#14

按 **Y0-0000000000000000-0-0**查找，日志里面一大堆，请问具体要看哪一个的呢？

[root@DB59 log]# grep -c Y0-0000000000000000-0-0 *
election.log:86900
election.log.wf:0
observer.log:268609
observer.log.20230511172156594:34855
observer.log.20230511172524698:34759
observer.log.20230511172848932:35065
observer.log.20230511173701585:113611
observer.log.20230511175858664:337009
observer.log.20230511180930376:202615
observer.log.20230511182430379:231769
observer.log.20230511184331816:294419
observer.log.20230511190528067:337880
observer.log.20230511192722686:337503
observer.log.wf:4
observer.log.wf.20230511172156594:0
observer.log.wf.20230511172524698:2
observer.log.wf.20230511172848932:0
observer.log.wf.20230511173701585:2
observer.log.wf.20230511175858664:4
observer.log.wf.20230511180930376:2
observer.log.wf.20230511182430379:2
observer.log.wf.20230511184331816:4
observer.log.wf.20230511190528067:6
observer.log.wf.20230511192722686:4
rootservice.log:21965
rootservice.log.20230511143616887:30195
rootservice.log.20230511171729703:23178
rootservice.log.wf:0
rootservice.log.wf.20230511143616887:0
rootservice.log.wf.20230511171729703:0
trace.log:0
trace.log.20230511122727369:0
trace.log.20230511135534992:0
trace.log.20230511152249319:341
trace.log.20230511164958603:0
trace.log.20230511181748338:408
trace.log.wf:0
trace.log.wf.20230511135534992:0
trace.log.wf.20230511152249319:0
trace.log.wf.20230511164958603:0
trace.log.wf.20230511181748338:0

#15

不是，你不是说了十分钟报一次， 你把报错前后五分钟的日志捞下，最开头有时间戳的

#16

election.log observer.log rootservice.log trace.log 这四个日志文件里都有Y0-0000000000000000-0-0 这个关键字的日志，是四个日志文件都要取，还是只取observer.log日志里的就行了？

#17

observer.log.rar (1.9 MB)
我刚刚又新部署了一套架构是 1-1-1 的集群，只要新建了租户，就会出现这个错误日志了，附件是按Y0-0000000000000000-0-0 取的，报错行在第 52030 行，我贴在下面：

[2023-05-12 16:10:39.782063] INFO [SERVER] runTimerTask (ob_eliminate_task.cpp:202) [17878][T1_ReqMemEvict][T1][Y0-0000000000000000-0-0] [lt=19] sql audit evict task end(evict_high_mem_level=51191653, evict_high_size_level=9000000, evict_batch_count=0, elapse_time=1, size_used=4209, mem_used=39515136)

[2023-05-12 16:10:39.808032] WDIAG [SERVER] execute_read_inner (ob_inner_sql_connection.cpp:2020) [17480][RSInspectTask][T0][Y0-0000000000000000-0-0] [lt=6][errcode=-5231] execute sql failed(ret=-5231, tenant_id=1001, sql=SELECT FIELD FROM oceanbase.__tenant_virtual_table_column WHERE TABLE_ID = 21352)

[2023-05-12 16:10:39.808039] WDIAG [SERVER] retry_while_no_tenant_resource (ob_inner_sql_connection.cpp:890) [17480][RSInspectTask][T0][Y0-0000000000000000-0-0] [lt=7][errcode=-5231] retry_while_no_tenant_resource failed(ret=-5231, tenant_id=1001)

[2023-05-12 16:10:39.808044] WDIAG [SERVER] execute_read (ob_inner_sql_connection.cpp:1961) [17480][RSInspectTask][T0][Y0-0000000000000000-0-0] [lt=5][errcode=-5231] execute_read failed(ret=-5231, cluster_id=5, tenant_id=1001)

[2023-05-12 16:10:39.808057] WDIAG [COMMON.MYSQLP] read (ob_mysql_proxy.cpp:125) [17480][RSInspectTask][T0][Y0-0000000000000000-0-0] [lt=5][errcode=-5231] query failed(ret=-5231, conn=0x7fed352b4050, start=1683879039806336, sql=SELECT FIELD FROM oceanbase.__tenant_virtual_table_column WHERE TABLE_ID = 21352)

[2023-05-12 16:10:39.808064] WDIAG [COMMON.MYSQLP] read (ob_mysql_proxy.cpp:63) [17480][RSInspectTask][T0][Y0-0000000000000000-0-0] [lt=13][errcode=-5231] read failed(ret=-5231)

[2023-05-12 16:10:39.808078] ERROR issue_dba_error (ob_log.cpp:1792) [17480][RSInspectTask][T0][Y0-0000000000000000-0-0] [lt=7][errcode=-4388] Unexpected internal error happen, please checkout the internal errcode(errcode=-4029, file=“ob_root_inspection.cpp”, line_no=1593, info=“check sys view: expand failed”)

[2023-05-12 16:10:39.816848] INFO [SHARE] get_all_snapshots (ob_snapshot_table_proxy.cpp:426) [21551][T1002_FreInfoRe][T1002][Y0-0000000000000000-0-0] [lt=15] get all snapshots(ret=0, snapshots.count()=0, snapshots=[])

[2023-05-12 16:10:39.819796] INFO [STORAGE] dump_info (ob_sstable_struct.cpp:224) [17842][T1_MINI_MERGE][T1][YB42C0A833E9-0005FB7A4305F47C-0-0] [lt=24] dump merge info(msg=“macro block builder close”, output_row_per_s=2, new_macro_KB_per_s=2762, *this={tenant_id:1, ls_id:{id:1}, tablet_id:{id:50154}, compaction_scn:1683879024207233370, merge_type:“MINI_MERGE”, merge_cost_time:741316, merge_start_time:1683879039078476, merge_finish_time:1683879039819792, dag_id:Y0-0000000000000000-0-0, occupy_size:26761, new_flush_occupy_size:26761, original_size:26417, compressed_size:26417, macro_block_count:1, multiplexed_macro_block_count:0, new_micro_count_in_new_macro:1, multiplexed_micro_count_in_new_macro:0, total_row_count:2, incremental_row_count:2, new_flush_data_rate:0, is_full_merge:false, progressive_merge_round:0, progressive_merge_num:0, concurrent_cnt:1, parallel_merge_info:{{type:“scan_units”, info:{min:0, max:0, sum:0, count:0}}, {type:“cost_time”, info:{min:0, max:0, sum:0, count:0}}, {type:“use_old_macro_block_cnt”, info:{min:0, max:0, sum:0, count:0}}, {type:“incremental_row_count”, info:{min:0, max:0, sum:0, count:0}}, }, filter_statistics:CompactionFilterStatistics:{{type:“NOT_CHANGE”, info:0}, {type:“REMOVE”, info:0}, }, participant_table_str:"", macro_id_list:"", comment:""})

[2023-05-12 16:10:39.822062] ERROR issue_dba_error (ob_log.cpp:1792) [17480][RSInspectTask][T0][Y0-0000000000000000-0-0] [lt=0][errcode=-4388] Unexpected internal error happen, please checkout the internal errcode(errcode=-4029, file=“ob_root_inspection.cpp”, line_no=1342, info=“check sys table schema failed”)

[2023-05-12 16:10:39.822105] ERROR check_sys_table_schemas_ (ob_root_inspection.cpp:1343) [17480][RSInspectTask][T0][Y0-0000000000000000-0-0] [lt=13][errcode=-4754] root inspection is not passed(msg=“inner tables are unmatched”, ret=-4029, ret=“OB_SCHEMA_ERROR”, tenant_id=1001)

[2023-05-12 16:10:39.826085] INFO [DETECT] maintain_deadlock_info_when_end_stmt (ob_trans_deadlock_adapter.cpp:644) [21580][T1002_TenantWea][T1001][Y0-0000000000000000-0-0] [lt=57] inner session no need register to deadlock(step=2, ret=0, ret=“OB_SUCCESS”, exec_ctx.get_errcode()=0, exec_ctx.get_errcode()=“OB_SUCCESS”, session={this:0x7fed9eea60d8, id:1, tenant:“sys”, tenant_id:1, effective_tenant:“sys”, effective_tenant_id:1001, database:“oceanbase”, user:“root@%”, consistency_level:3, session_state:0, autocommit:true, tx:0x7fed9c9bf660}, desc=NULL, is_rollback=false, conflict_txs=[])

[2023-05-12 16:10:39.826624] INFO [RPC.OBMYSQL] sm_conn_build_handshake (obsm_conn_callback.cpp:104) [17560][sql_nio2][T0][Y0-0000000000000000-0-0] [lt=9] new mysql sessid created(conn.sessid_=3221709797, support_ssl=false)

[2023-05-12 16:10:39.826687] INFO [RPC.OBMYSQL] init (obsm_conn_callback.cpp:120) [17560][sql_nio2][T0][Y0-0000000000000000-0-0] [lt=27] sm conn init succ(conn.sessid_=3221709797, sess.client_addr_=“127.0.0.1:37678”)

[2023-05-12 16:10:39.826703] INFO [RPC.OBMYSQL] do_accept_one (ob_sql_nio.cpp:899) [17560][sql_nio2][T0][Y0-0000000000000000-0-0] [lt=9] accept one succ(*s={this:0x7fed95809290, fd:141, err:0, last_decode_time_:0, last_write_time_:1683879039826686, read_buffer_.get_consume_sz():0, get_pending_flag():0, get_trace_id():Y0-0000000000000000-0-0})

#18

rootservice.log里也有这个报错：

[2023-05-14 14:40:37.983196] WDIAG [RS] check_names (ob_root_inspection.cpp:1101) [21706][RSInspectTask][T0][Y0-0000000000000000-0-0] [lt=22][errcode=0] some item exist in table, but not hard coded(tenant_id=1002, table_name="_all_sys_stat", extra_names=[“current_timezone_version”])
[2023-05-14 14:40:38.972211] WDIAG [RS] check_sys_view (ob_root_inspection.cpp:1587) [21706][RSInspectTask][T0][Y0-0000000000000000-0-0] [lt=5][errcode=-5231] execute sql failed(ret=-5231, ret=“OB_ERR_VIEW_INVALID”, tenant_id=1001, table_name=TABLE_CONSTRAINTS, sql=SELECT FIELD FROM oceanbase.__tenant_virtual_table_column WHERE TABLE_ID = 21352)

> [2023-05-14 14:40:38.972235] EDIAG [RS] check_sys_view_ (ob_root_inspection.cpp:1593) [21706][RSInspectTask][T0][Y0-0000000000000000-0-0] [lt=9][errcode=-4029] check sys view: expand failed(ret=-4029, ret=“OB_SCHEMA_ERROR”, tenant_id=1001, table_name=TABLE_CONSTRAINTS) BACKTRACE:0xd7c7a79 0x5a0303c 0x5a02b4f 0x5a0293a 0x5a02778 0x6957e48 0x6952ba8 0x694aa10 0x6947970 0x694b0e7 0x694454b 0xde2ad1e 0x3daadd4 0xde2d228 0xde351f0 0xde31fca 0x7f91e92a9ea5 0x7f91e8fd2b0d

> [2023-05-14 14:40:38.972316] WDIAG [RS] check_sys_table_schemas_ (ob_root_inspection.cpp:1326) [21706][RSInspectTask][T0][Y0-0000000000000000-0-0] [lt=13][errcode=0] check sys view failed(tmp_ret=-4029, tmp_ret=“OB_SCHEMA_ERROR”, tenant_id=1001, table_id=21352, table_name=“TABLE_CONSTRAINTS”)

> [2023-05-14 14:40:38.987363] EDIAG [RS] check_sys_table_schemas_ (ob_root_inspection.cpp:1342) [21706][RSInspectTask][T0][Y0-0000000000000000-0-0] [lt=25][errcode=-4029] check sys table schema failed(ret=-4029, ret=“OB_SCHEMA_ERROR”, tenant_id=1001) BACKTRACE:0xd7c7a79 0x5a07f83 0x5a07aa6 0x5a078a6 0x59f7901 0x69531c7 0x694abfe 0x6947970 0x694b0e7 0x694454b 0xde2ad1e 0x3daadd4 0xde2d228 0xde351f0 0xde31fca 0x7f91e92a9ea5 0x7f91e8fd2b0d

[2023-05-14 14:40:38.987383] WDIAG [RS] check_sys_table_schemas_ (ob_root_inspection.cpp:1256) [21706][RSInspectTask][T0][Y0-0000000000000000-0-0] [lt=5][errcode=0] fail to check sys table schemas by tenant(tmp_ret=-4029, tmp_ret=“OB_SCHEMA_ERROR”, *tenant_id=1001)

[2023-05-14 14:40:39.328353] WDIAG [RS] check_sys_view_ (ob_root_inspection.cpp:1587) [21706][RSInspectTask][T0][Y0-0000000000000000-0-0] [lt=4][errcode=-5231] execute sql failed(ret=-5231, ret=“OB_ERR_VIEW_INVALID”, tenant_id=1002, table_name=TABLE_CONSTRAINTS, sql=SELECT FIELD FROM oceanbase.__tenant_virtual_table_column WHERE TABLE_ID = 21352)
[2023-05-14 14:40:39.328367] EDIAG [RS] check_sys_view_ (ob_root_inspection.cpp:1593) [21706][RSInspectTask][T0][Y0-0000000000000000-0-0] [lt=7][errcode=-4029] check sys view: expand failed(ret=-4029, ret=“OB_SCHEMA_ERROR”, tenant_id=1002, table_name=TABLE_CONSTRAINTS) BACKTRACE:0xd7c7a79 0x5a0303c 0x5a02b4f 0x5a0293a 0x5a02778 0x6957e48 0x6952ba8 0x694aa10 0x6947970 0x694b0e7 0x694454b 0xde2ad1e 0x3daadd4 0xde2d228 0xde351f0 0xde31fca 0x7f91e92a9ea5 0x7f91e8fd2b0d
[2023-05-14 14:40:39.328408] WDIAG [RS] check_sys_table_schemas_ (ob_root_inspection.cpp:1326) [21706][RSInspectTask][T0][Y0-0000000000000000-0-0] [lt=10][errcode=0] check sys view failed(tmp_ret=-4029, tmp_ret=“OB_SCHEMA_ERROR”, tenant_id=1002, table_id=21352, table_name=“TABLE_CONSTRAINTS”)
[2023-05-14 14:40:39.345861] EDIAG [RS] check_sys_table_schemas_ (ob_root_inspection.cpp:1342) [21706][RSInspectTask][T0][Y0-0000000000000000-0-0] [lt=33][errcode=-4029] check sys table schema failed(ret=-4029, ret=“OB_SCHEMA_ERROR”, tenant_id=1002) BACKTRACE:0xd7c7a79 0x5a07f83 0x5a07aa6 0x5a078a6 0x59f7901 0x69531c7 0x694abfe 0x6947970 0x694b0e7 0x694454b 0xde2ad1e 0x3daadd4 0xde2d228 0xde351f0 0xde31fca 0x7f91e92a9ea5 0x7f91e8fd2b0d
[2023-05-14 14:40:39.345901] WDIAG [RS] check_sys_table_schemas_ (ob_root_inspection.cpp:1256) [21706][RSInspectTask][T0][Y0-0000000000000000-0-0] [lt=15][errcode=0] fail to check sys table schemas by tenant(tmp_ret=-4029, tmp_ret=“OB_SCHEMA_ERROR”, *tenant_id=1002)
[2023-05-14 14:40:39.345913] WDIAG [RS] check_all (ob_root_inspection.cpp:750) [21706][RSInspectTask][T0][Y0-0000000000000000-0-0] [lt=11][errcode=0] check_sys_table_schemas failed(tmp=-4029)
[2023-05-14 14:40:39.351712] WDIAG [RS] process (ob_root_inspection.cpp:598) [21706][RSInspectTask][T0][Y0-0000000000000000-0-0] [lt=5][errcode=0] inpection task failed(tmp_ret=-4029, i=1, task=“sys_schema_checker”)
[2023-05-14 14:50:37.985564] WDIAG [RS] check_names (ob_root_inspection.cpp:1101) [21706][RSInspectTask][T0][Y0-0000000000000000-0-0] [lt=35][errcode=0] some item exist in table, but not hard coded(tenant_id=1002, table_name="all_sys_stat", extra_names=[“current_timezone_version”])
[2023-05-14 14:50:38.897569] WDIAG [RS] check_sys_view (ob_root_inspection.cpp:1587) [21706][RSInspectTask][T0][Y0-0000000000000000-0-0] [lt=3][errcode=-5231] execute sql failed(ret=-5231, ret=“OB_ERR_VIEW_INVALID”, tenant_id=1001, table_name=TABLE_CONSTRAINTS, sql=SELECT FIELD FROM oceanbase.__tenant_virtual_table_column WHERE TABLE_ID = 21352)
[2023-05-14 14:50:38.897585] EDIAG [RS] check_sys_view (ob_root_inspection.cpp:1593) [21706][RSInspectTask][T0][Y0-0000000000000000-0-0] [lt=6][errcode=-4029] check sys view: expand failed(ret=-4029, ret=“OB_SCHEMA_ERROR”, tenant_id=1001, table_name=TABLE_CONSTRAINTS) BACKTRACE:0xd7c7a79 0x5a0303c 0x5a02b4f 0x5a0293a 0x5a02778 0x6957e48 0x6952ba8 0x694aa10 0x6947970 0x694b0e7 0x694454b 0xde2ad1e 0x3daadd4 0xde2d228 0xde351f0 0xde31fca 0x7f91e92a9ea5 0x7f91e8fd2b0d
[2023-05-14 14:50:38.897625] WDIAG [RS] check_sys_table_schemas_ (ob_root_inspection.cpp:1326) [21706][RSInspectTask][T0][Y0-0000000000000000-0-0] [lt=10][errcode=0] check sys view failed(tmp_ret=-4029, tmp_ret=“OB_SCHEMA_ERROR”, tenant_id=1001, table_id=21352, table_name=“TABLE_CONSTRAINTS”)
[2023-05-14 14:50:38.912490] EDIAG [RS] check_sys_table_schemas_ (ob_root_inspection.cpp:1342) [21706][RSInspectTask][T0][Y0-0000000000000000-0-0] [lt=24][errcode=-4029] check sys table schema failed(ret=-4029, ret=“OB_SCHEMA_ERROR”, tenant_id=1001) BACKTRACE:0xd7c7a79 0x5a07f83 0x5a07aa6 0x5a078a6 0x59f7901 0x69531c7 0x694abfe 0x6947970 0x694b0e7 0x694454b 0xde2ad1e 0x3daadd4 0xde2d228 0xde351f0 0xde31fca 0x7f91e92a9ea5 0x7f91e8fd2b0d
[2023-05-14 14:50:38.912524] WDIAG [RS] check_sys_table_schemas_ (ob_root_inspection.cpp:1256) [21706][RSInspectTask][T0][Y0-0000000000000000-0-0] [lt=10][errcode=0] fail to check sys table schemas by tenant(tmp_ret=-4029, tmp_ret=“OB_SCHEMA_ERROR”, *tenant_id=1001)
[2023-05-14 14:50:39.251949] WDIAG [RS] check_sys_view_ (ob_root_inspection.cpp:1587) [21706][RSInspectTask][T0][Y0-0000000000000000-0-0] [lt=3][errcode=-5231] execute sql failed(ret=-5231, ret=“OB_ERR_VIEW_INVALID”, tenant_id=1002, table_name=TABLE_CONSTRAINTS, sql=SELECT FIELD FROM oceanbase.__tenant_virtual_table_column WHERE TABLE_ID = 21352)
[2023-05-14 14:50:39.251963] EDIAG [RS] check_sys_view_ (ob_root_inspection.cpp:1593) [21706][RSInspectTask][T0][Y0-0000000000000000-0-0] [lt=7][errcode=-4029] check sys view: expand failed(ret=-4029, ret=“OB_SCHEMA_ERROR”, tenant_id=1002, table_name=TABLE_CONSTRAINTS) BACKTRACE:0xd7c7a79 0x5a0303c 0x5a02b4f 0x5a0293a 0x5a02778 0x6957e48 0x6952ba8 0x694aa10 0x6947970 0x694b0e7 0x694454b 0xde2ad1e 0x3daadd4 0xde2d228 0xde351f0 0xde31fca 0x7f91e92a9ea5 0x7f91e8fd2b0d
[2023-05-14 14:50:39.252001] WDIAG [RS] check_sys_table_schemas_ (ob_root_inspection.cpp:1326) [21706][RSInspectTask][T0][Y0-0000000000000000-0-0] [lt=10][errcode=0] check sys view failed(tmp_ret=-4029, tmp_ret=“OB_SCHEMA_ERROR”, tenant_id=1002, table_id=21352, table_name=“TABLE_CONSTRAINTS”)
[2023-05-14 14:50:39.268556] EDIAG [RS] check_sys_table_schemas_ (ob_root_inspection.cpp:1342) [21706][RSInspectTask][T0][Y0-0000000000000000-0-0] [lt=37][errcode=-4029] check sys table schema failed(ret=-4029, ret=“OB_SCHEMA_ERROR”, tenant_id=1002) BACKTRACE:0xd7c7a79 0x5a07f83 0x5a07aa6 0x5a078a6 0x59f7901 0x69531c7 0x694abfe 0x6947970 0x694b0e7 0x694454b 0xde2ad1e 0x3daadd4 0xde2d228 0xde351f0 0xde31fca 0x7f91e92a9ea5 0x7f91e8fd2b0d
[2023-05-14 14:50:39.268577] WDIAG [RS] check_sys_table_schemas_ (ob_root_inspection.cpp:1256) [21706][RSInspectTask][T0][Y0-0000000000000000-0-0] [lt=5][errcode=0] fail to check sys table schemas by tenant(tmp_ret=-4029, tmp_ret=“OB_SCHEMA_ERROR”, *tenant_id=1002)
[2023-05-14 14:50:39.268584] WDIAG [RS] check_all (ob_root_inspection.cpp:750) [21706][RSInspectTask][T0][Y0-0000000000000000-0-0] [lt=6][errcode=0] check_sys_table_schemas failed(tmp=-4029)
[2023-05-14 14:50:39.274137] WDIAG [RS] process (ob_root_inspection.cpp:598) [21706][RSInspectTask][T0][Y0-0000000000000000-0-0] [lt=4][errcode=0] inpection task failed(tmp_ret=-4029, i=1, task=“sys_schema_checker”)

#19

更新一下情况：

  1. 那个1-1架构的集群，我在OCP上做了一个【升级版本】-【停服升级】的操作后，这个报错就没有再出现了。
    旧版本：oceanbase-ce-4.1.0.0-100000202023040520.el7.x86_64.rpm
    新版本：oceanbase-ce-4.1.0.0-101000022023050809.el7.x86_64.rpm

2.所以又用新版本oceanbase-ce-4.1.0.0-101000022023050809.el7.x86_64.rpm, 重新部署了另一套1-1-1的集群, 但在添加租户后，报错还是存在的

#20

3.新部署的这套1-1-1， 在ocp上做了一下【停止集群】 过了五分钟之后再 【启动集群】 的操作后，这个报错日志变成每过 6秒 就出一次了【之前是10分钟出来一次】

image
image1920×978 181 KB

#21

这个日志方便用附件形式传上来么
你直接在日志目录下grep Yxxxxx observer.log* 和 grep Yxxxx rootservice.log* 即可，但记得把自己再过滤下时间区间

#22

OB_LOG_test11111_6_192.168.51.233_20230515104950_20230515105450.zip (3.7 MB)
日志上传了，有劳再帮忙看看 :pray: