问题描述
备份失败。
适用版本
GaussDB全部版本。
问题现象
备份失败。
告警
云数据库 GaussDB 增量备份失败。
云数据库 GaussDB 手动全量备份失败。
云数据库 GaussDB 自动全量备份失败。
云数据库 GaussDB 自动差分备份失败。
业务影响
备份失败不影响业务。
原因分析
可能原因有以下：
1、OBS问题：OBS网络不通， OBS负载异常等。
2、底层硬件问题：物理机重启等。
3、内核问题：大集群免密超时，业务压力大触发PITR逻辑复制槽强推。
4、误删文件导致全备持续失败。
5、备份期间集群状态不正常。
分析步骤
说明：
1）本部分的示例，每一步的示例信息来自于不同情况的备份失败定位信息，之间没有前后逻辑关系。仅供问题定位流程和关键字的参考。
2）如果要确定是否是内核的问题，且已知备份执行的master节点，请直接跳转5开始向下执行，备份执行的master节点获取方式请参考4。
3）全备登录到最后一个DN分片的DN备上。如果多个DN备，先选择最后一个DN备。
4）差备登录到最后一个DN分片或第一个DN分片的DN备上，如果多个DN备，先选择最后一个DN备。第一个还是最后一个取决于管控adaptor的版本，需要都查找下。
1、查看失败的备份执行时间范围。
从任务流上可以看到备份的执行时间。
本例所示，备份执行的时间：2022/08/31 07:18:57~2022/08/31 07:36:17
2、通过树表确认备份失败的位置。
a.如果失败在如图所示的位置，需要登录到后台，查看日志确定失败原因。
b.如果失败在其他步骤，联系华为技术支持。
3、从树表确认备份任务下发节点，备份任务的下发节点，需查看adaptor日志，adaptor日志里会说明备份的执行master节点。
下发节点确认方法：失败任务的操作 -> 修改Context -> nodeId。
本例中的备份任务下发节点为：79d2f04375604f289d518373dab1d1cdno14
4、登录备份任务下发节点，查询adaptor日志。
查看本次失败备份执行时间范围内的日志。
a.确认备份执行的master节点。关键字Send backup request to node。
b.确认备份失败时下发adaptor中的报错信息。关键字ERROR 或者 failed。
c.确认每次从管控下发备份的时间，以及从内核返回的备份失败时间。（OPS的一次任务流中，如果失败，最多会重做三次备份，间隔1分钟后尝试下一次。若三次均失败，则任务流中会显示备份失败。）
cd /home/Ruby/log/adaptor_log
说明：
#找到任务流上备份开始的时间，向下搜backup，就可以查看任务流上开始的时间之后10s内会有备份开始的日志。
#如本例所示，任务流上备份开始的时间为：2022/08/31 07:18:57，把adaptor日志时间搜到2022-08-31 07:18之后，向下搜backup，就能看到在2022-08-31 07:19:05,879的时候，出现了第一次备份开始的日志。
#找到第一次备份开始的日志，向下搜ERROR或者failed，会看到任务流备份执行时间范围内，备份失败的日志，备份失败的日志一般都会有backup字样，和其他任务流失败的日志区分开。
d.一次备份中adaptor中需要关注的关键日志标识：
##backup## begin trace_id：一次备份的开始日志。
Backup retry start number [*].：本次备份任务的第几次重试，最多为3。
Send backup request to node[ip:20050]：说明备份执行的master节点，master节点的ip本例为192.168.19.186。
Start increment backup. backup key is [***] increment backup：这是增备的标识，并指定上一次备份的backup_key。全备没有这行日志，全备是在上一行日志之后就没有了。
Backup request result is：这个日志结果里的result，是本次备份的backup_key，本例为20220831_071941，唯一标识本次备份任务，如果一次尝试失败，重试的时候，backup_key不变，在各日志中可以快速定位本次备份。
Backup retry failed in count [1]：第一次尝试备份失败的日志。
e.第一次备份任务的关键日志。
# 第一次备份从adaptor上看执行时间：2022-08-31 07:19:05,879 ~ 2022-08-31 07:23:57,246
[2022-08-31 07:19:05,879][INFO][om_adaptor][common_filter.py][common_filter][func_wrapper][115][##backup## begin trace_id: [247161e628ba11ed987efa163e6870a0]]
.......
[2022-08-31 07:19:05,881][INFO][om_adaptor][engine_controller.py][engine_controller][backup][2504][Backup retry start number [1].]
[2022-08-31 07:19:05,881][INFO][om_adaptor][engine_controller.py][engine_controller][backup][2506][backup_key is in parameter [20220831_070839].]
.......
[2022-08-31 07:19:07,606][INFO][om_adaptor][engine_controller.py][engine_controller][getDNIpForBackup][322][normal instance info is ***
[2022-08-31 07:19:07,626][INFO][om_adaptor][engine_controller.py][engine_controller][doBackup][2573][Send backup request to node[192.168.19.186:20050]]
[2022-08-31 07:19:07,626][INFO][om_adaptor][engine_controller.py][engine_controller][doBackup][2586][Start increment backup. backup key is [20220831_070839]]
......
[2022-08-31 07:19:41,744][INFO][om_adaptor][engine_controller.py][engine_controller][doBackup][2630][Backup request result is {'message': 'SUCCESS', 'progress': 0, 'result': '20220831_071941', 'statusCode': '0'}]
....
[2022-08-31 07:23:54,147][INFO][om_adaptor][engine_controller.py][engine_controller][check_remote_progress_file][218][Roach build connect with cluster nodes failed time out [300 s] or retry more than 60 times.Start try to check progress.]
....
[2022-08-31 07:23:57,185][INFO][om_adaptor][adapter_common.py][adapter_common][convert_process_result][1015][roach_backup progress result is: {'message': '[GAUSS-52503] : Failed to execute checkRunStatus.py. Error: Check the current task [roach_backup] failed. Error:\nExecute command[echo "Roach task is abnormal or roach action is not executed right now still." > /var/chroot//var/lib/log/backup/metadata/roach/20220831_071941/.roach_backup_task_result && chmod 600 /var/chroot//var/lib/log/backup/metadata/roach/20220831_071941/.roach_backup_task_result] error:\n/bin/sh: /var/chroot//var/lib/log/backup/metadata/roach/20220831_071941/.roach_backup_task_result: No such file or directory', 'progress': -1, 'result': '', 'statusCode': '-1'}, trace_id : -]
[2022-08-31 07:23:57,186][INFO][om_adaptor][adapter_common.py][adapter_common][convert_process_result][1023][Get roach_backup progress is: -1]
[2022-08-31 07:23:57,186][INFO][om_adaptor][engine_controller.py][engine_controller][clean_job][247][clean_job_cmd: source /etc/profile 2>/dev/null && source ~/.bashrc && if [ -f '/home/Ruby/gauss_env_file' ]; then source /home/Ruby/gauss_env_file;fi && ps ux | grep '20220831_071941' | grep -E 'HADR.py|LocalHadr.py|GaussRoach.py|LocalRoach.py|agentRoach.py' | grep -v 'grep' | awk '{print $2}' | xargs kill -9]
....
[2022-08-31 07:23:57,245][INFO][om_adaptor][common_filter.py][common_filter][func_wrapper][117][##doBackup## end normally trace_id: [2471d29828ba11ed987efa163e6870a0]]
[2022-08-31 07:23:57,246][INFO][om_adaptor][engine_controller.py][engine_controller][backup][2529][Backup result info is {'retcode': 1, 'detailmsg': 'Backup failed.'}]
[2022-08-31 07:23:57,246][INFO][om_adaptor][engine_controller.py][engine_controller][backup][2531][Backup retry failed in count [1]. backup_result is {'retcode': 1, 'detailmsg': 'Backup failed.'}]
第一次备份开始的示例。
第一次备份失败的示例。
f.第二次备份的日志。
[2022-08-31 07:24:57,303][INFO][om_adaptor][engine_controller.py][engine_controller][backup][2504][Backup retry start number [2].]
[2022-08-31 07:24:57,304][INFO][om_adaptor][engine_controller.py][engine_controller][backup][2506][backup_key is in parameter [20220831_070839].]
......
[2022-08-31 07:24:58,867][INFO][om_adaptor][engine_controller.py][engine_controller][doBackup][2573][Send backup request to node[192.168.19.186:20050]]
[2022-08-31 07:24:58,868][INFO][om_adaptor][engine_controller.py][engine_controller][doBackup][2586][Start increment backup. backup key is [20220831_070839]]
[2022-08-31 07:29:48,809][INFO][om_adaptor][engine_controller.py][engine_controller][backup][2531][Backup retry failed in count [2]. backup_result is {'retcode': 1, 'detailmsg': 'Backup failed.'}]
[2022-08-31 07:29:48,809][INFO][om_adaptor][engine_controller.py][engine_controller][backup][2534][Waitting 60s for next backup.]
第三次备份的日志。
[2022-08-31 07:19:05,881][INFO][om_adaptor][engine_controller.py][engine_controller][backup][2504][Backup retry start number [1].]
[2022-08-31 07:19:05,881][INFO][om_adaptor][engine_controller.py][engine_controller][backup][2506][backup_key is in parameter [20220831_070839].]
.......
[2022-08-31 07:35:40,559][INFO][om_adaptor][engine_controller.py][engine_controller][backup][2529][Backup result info is {'retcode': 1, 'detailmsg': 'Backup failed.'}]
[2022-08-31 07:35:40,559][INFO][om_adaptor][engine_controller.py][engine_controller][backup][2531][Backup retry failed in count [3]. backup_result is {'retcode': 1, 'detailmsg': 'Backup failed.'}]
[2022-08-31 07:35:40,559][INFO][om_adaptor][engine_controller.py][engine_controller][backup][2540][Backup retry failed 3 times.]
5、查看备份执行的master节点的om_agent日志，查看每次备份尝试执行的时间范围内日志，搜ERROR、Error或failed，确认备份master节点上OM展示的备份失败的原因，参考如下所示。
cd /home/Ruby/log/om_agent
本示例中报错说明“/var/chroot//var/lib/log/backup/metadata/roach/20220831_071941/.roach_backup_task_result”这个记录备份结果的文件不存在，到master节点上查看该目录，无20220831_071941这次备份，20220831_071941即backup_key。
# 2022-08-31 07:19:05,879 ~ 2022-08-31 07:23:57,246
d055e21628ba11ed911efa163eeea332_140454655080192 2022-08-31 07:23:57,178 [DEBUG] check_schedule(om_agent:3000) check result: ('0', '', '{"status": -1, "errorCode": "-1", "errorMsg": "[GAUSS-52503] : Failed to execute checkRunStatus.py. Error: Check the current task [roach_backup] failed. Error:\\nExecute command[echo \\"Roach task is abnormal or roach action is not executed right now still.\\" > /var/chroot//var/lib/log/backup/metadata/roach/20220831_071941/.roach_backup_task_result && chmod 600 /var/chroot//var/lib/log/backup/metadata/roach/20220831_071941/.roach_backup_task_result] error:\\n/bin/sh: /var/chroot//var/lib/log/backup/metadata/roach/20220831_071941/.roach_backup_task_result: No such file or directory"}\n', 0)
d055e21628ba11ed911efa163eeea332_140454655080192 2022-08-31 07:23:57,181 [INFO] filter_func(rest_aop:208) enter the last branch when http method is POST
d055e21628ba11ed911efa163eeea332_140454655080192 2022-08-31 07:23:57,182 [INFO] print_output_result(rest_aop:378) function= check_schedule, result= { "message": "[GAUSS-52503] : Failed to execute checkRunStatus.py. Error: Check the current task [roach_backup] failed. Error:\nExecute command[echo \"Roach task is abnormal or roach action is not executed right now still.\" > /var/chroot//var/lib/log/backup/metadata/roach/20220831_071941/.roach_backup_task_result && chmod 600 /var/chroot//var/lib/log/backup/metadata/roach/20220831_071941/.roach_backup_task_result] error:\n/bin/sh: /var/chroot//var/lib/log/backup/metadata/roach/20220831_071941/.roach_backup_task_result: No such file or directory", "progress": -1, "result": "", "statusCode": "-1" }
6、查看备份执行master节点的roach-controller日志，确定controller日志中是否有报错，关键字ERROR：
•若有报错，找到4中确定的时间范围内第一个ERROR所在位置，查看周围日志及ERROR日志，同时截图ERROR日志周围日志(多截一些，若有failed、warning等一起采集），并继续向下分析。
•若无报错，报错不是出现在controller中，需要返回5，继续向上分析。
全备：cd $GAUSSLOG/roach/controller
增备：cd $GAUSSLOG/roach/controller_inc
vim roach_controller-***.log
# 搜索关键字：ERROR
# 若存在ERROR，查看ERROR报错信息，如果报错信息可以看出问题，问题定位成功。比如：说明因为CN连接数满，无法执行SQL，导致备份失败。
# 若ERROR看不出具体原因，继续向下。
[MainThread][2022-08-31 07:20:42.994442][2517][GaussRoach.py(doBackup:736)][backup][ERROR]:[GAUSS-51300] : Failed to execute SQL: SELECT * FROM pg_catalog.gs_pitr_get_warning_for_xlog_force_recycle();. Error:
gsql: FATAL: Too many clients already, current/active: 2051/831, max_connections/reserved: 2048/3.
# 找到备份失败时间点周围的第一个ERROR前边sendSignal to make others quit!日志中的ip，示例是10.10.10.2，下一步登录10.10.10.2，一般在ERROR的上边。
[MainThread][2022-05-11 17:08:18.196184][3249][GSroachCommon.py(pollSubprocess:903)][][DEBUG]:pollSubprocess: node 10.10.10.2 pid 11662 process failed return code 3, sendSignal to make others quit!
roach-controller日志正常开始和结束的日志如下所示：
# 正常开始日志
[GaussRoach.py:2350][backup][DEBUG]:[main] python2 GaussRoach enter, action is [backup].
# 正常结束日志
[GaussRoach.py:2434][backup][DEBUG]:[main] python2 GaussRoach leave, action is [backup].
[GSroachCommon.py:2553][][DEBUG]:Successfully send .roach_backup_task_result to all nodes
# 开始和结束之间，无ERROR，无failed，说明本次备份在内核侧成功。
7、查看备份执行master节点的roach-agent日志，确定agent日志中是否有报错，关键字ERROR。
•若有报错，找到4中确定的时间范围内第一个ERROR所在位置，查看周围日志及ERROR日志，同时截图ERROR日志周围日志(多截一些，若有failed、warning等一起采集），并继续向下分析。
•若无报错，报错不是出现在agent中，继续分析日志。
全备：cd $GAUSSLOG/roach/controller
增备：cd $GAUSSLOG/roach/controller_inc
vim roach_agent-***.log
a.搜索：ERROR
b.查看ERROR报错信息。
若ERROR可以看出问题，定位成功。
若ERROR看不出具体原因，继续向下。
c.搜索ERROR，查看看第一个ERROR，表示10.10.10.3发送了终止信号。需要登录到10.10.10.3中查看原因。
2022-05-11 17:08:15.128 ERROR: [PID:11665] [HOST:10.10.10.2] [Thread Name:Session] [Session]: Error occured during receivePacketData from agent[10.10.10.3]. Error Msg: Received Termination.. [session.c:1536]roach-agent日志正常开始和结束的日志如下所示：
# 正常开始日志
********** Started Roach process **********# 正常结束日志：确定Backup key:对应的是需要定位的那次备份的backup_key
[MASTER] Time taken : ***[MASTER]Backup operation SUCCESSFUL. Backup key: ***
# 开始和结束之间，无ERROR，无failed，说明本次备份在内核侧成功。
8、登录从6和7获取的ip所在节点，继续查看roach-controller日志和roach-agent日志搜ERROR确定备份失败原因。
9、登录从6和7获取的ip所在节点，继续查看om_agent日志搜ERROR确定备份失败原因。
10、OBS问题：如果roach-controller和roach-agent日志中，报错信息中出现bucket、OBS字眼，基本上都是OBS的问题，需要去OBS日志中看报错对应时间点的日志信息。
cd $GAUSSLOG/bin/gs_obs
11、底层故障，此步骤在HCS可以优先检查。
快速恢复
备份失败无法快速恢复，依赖实际问题分析与解决。
