terminating connection due to administrator

概要

本篇主要讲解GaussDB使用过程中遇到的“FATAL:  terminating connection due to administrator command”相关报错进行阐述。按报错现象可分为两类场景，一类是在客户端报错的同时，查找cn日志相应时间点的日志，可以找到相关报错日志；另一类是客户端报错，但cn日志在报错时间点未能找到相关报错日志。接下来分别以这两种场景进行以案例的形式进行介绍介绍。（后续有其他场景或案例会持续补充更新）

目录

【场景一： CN在客户端报错相应时间点有日志记录】

【问题描述】

【分析过程】

【闭环方案】

【场景二： CN在客户端报错相应时间点未找到日志记录】

【分析及案例】

【场景一： CN在客户端报错相应时间点有日志记录】

【问题描述】

 业务偶现报错“FATAL:  terminating connection due to administrator command”，如下图：

【分析过程】

业务报错打印“FATAL: terminating connection due to administrator command”, 经过排查代码只有在收到SIGTERM信号时打印此信息。

进一步分析SIGTERM信号只有3个场景会触发：

（1）集群停止shutdown；

（2）强制清理连接clean connection force；

（3）调用终止服务线程函数pg_terminate_backend(pid)

三种场景详细分析如下：

第一种情况：集群停止shutdown场景，分析全量日志，查看报错时间点是否有任何集群停止命令对应日志，若没有排除集群停止shutdown导致服务线程终止因素。

# grep -nr “fast shutdown request” ./

第二种情况：强制清理连接clean connection force，通过排查数据库各模块代码，在数据库内没有任何调用此接口的代码，只是一个对外接口，排除数据库内部自行调用clean触发因素。

第三种情况：调用终止服务线程函数pg_terminate_backend(pid)，通过排查各模块代码，数据库内部有且仅有cm_agent模块一处调用。

        cm_agent在检测磁盘超过阈值（默认90%）场景下，会调用命令“select pg_terminate_backend(pid) from pg_stat_activity where usesysid <> 10”终止当前CN上所有非omm用户的SQL，同时打印调用日志“cancel session ok”，排查cma日志，报错时间点是否出现过cma终止当前cn所有非omm用户sql的打印。并未发现日志打印，说明cma并没有发送终止命令。

# grep “pg_terminate_backend” cm/*/*.log

• 目前为止遇到的此报错大多数是由于客户端调用pg_terminate_backend和clean connection foece导致，当用户遇到此类问题时，排除集群停止shutdown导致服务线程终止因素，建议排查执行的作业是否包含pg_terminate_backend和clean connection foece关键字，以下通过两个案例简单说明。
• 案例详解
• 案例一：

1、  报错现象：客户跑批时sql被无故杀掉，业务报错打印“FATAL: terminating connection due to administrator command”

2、  在日志中查看到，有关于pg_terminate_backend调用的记录(如下图)

3、  另外，CM在检查磁盘空间超过阈值设置只读时，也会下发pg_terminate_backend

BDP17189/logfiles/cm/cm_agent/cm_agent-2019-08-06_111323-current.log:2019-10-26 22:12:28.502 tid=127209 LOG: exec: (select pg_terminate_backend(pid) from pg_stat_activity where usesysid <> 10), cancel session ok.  BDP17189/logfiles/cm/cm_agent/cm_agent-2019-08-06_111323-current.log:2019-10-27 20:14:47.912 tid=127209 LOG: exec: (select pg_terminate_backend(pid) from pg_stat_activity where usesysid <> 10), cancel session ok.  BDP17189/logfiles/cm/cm_agent/cm_agent-2019-08-06_111323-current.log:2019-10-29 04:08:51.278 tid=127209 LOG: exec: (select pg_terminate_backend(pid) from pg_stat_activity where usesysid <> 10), cancel session ok.

4、  因此从日志来看，业务侧确实有调用pg_terminate_backend杀线程， 另外cm在检查磁盘空间超过阈值设置只读时也下发过几次pg_terminate_backend

• 案例二：

    1、报错现象：

    客户端偶现报错：

    2、分析

    1）根据上述报错场景分析，排除集群停止shutdown，怀疑可能是调用了clean connection force和pg_terminate_backend，gdb抓现场，设置两个断点断点：pg_terminal_backend和clean_connection force。

(gdb) bt #0  CleanConnection (stmt=0x7f62118aa468) at poolutils.cpp:274 #1  0x0000000001875f35 in standard_ProcessUtility (parsetree=0x7f62118aa468, queryString=0x7f62118a9060 “CLEAN CONNECTION TO ALL FORCE FOR DATABASE postgres;”, params=0x0, isTopLevel=true,     dest=0x7f62118aa580, sentToRemote=false, completionTag=0x7f61d95648a0 “”) at utility.cpp:6498 #2  0x0000000001886098 in pgaudit_ProcessUtility (parsetree=0x7f62118aa468, queryString=0x7f62118a9060 “CLEAN CONNECTION TO ALL FORCE FOR DATABASE postgres;”, params=0x0, isTopLevel=true,     dest=0x7f62118aa580, sentToRemote=false, completionTag=0x7f61d95648a0 “”) at auditfuncs.cpp:1240 #3  0x000000000186803e in ProcessUtility (parsetree=0x7f62118aa468, queryString=0x7f62118a9060 “CLEAN CONNECTION TO ALL FORCE FOR DATABASE postgres;”, params=0x0, isTopLevel=true, dest=0x7f62118aa580,     sentToRemote=false, completionTag=0x7f61d95648a0 “”) at utility.cpp:1506 #4  0x00000000018637c9 in PortalRunUtility (portal=0x7f62118af060, utilityStmt=0x7f62118aa468, isTopLevel=true, dest=0x7f62118aa580, completionTag=0x7f61d95648a0 “”) at pquery.cpp:1682 #5  0x0000000001863c2c in PortalRunMulti (portal=0x7f62118af060, isTopLevel=true, dest=0x7f62118aa580, altdest=0x7f62118aa580, completionTag=0x7f61d95648a0 “”) at pquery.cpp:1842 #6  0x0000000001862522 in PortalRun (portal=0x7f62118af060, count=9223372036854775807, isTopLevel=true, dest=0x7f62118aa580, altdest=0x7f62118aa580, completionTag=0x7f61d95648a0 “”) at pquery.cpp:1114 #7  0x000000000184c22b in exec_simple_query (query_string=0x7f62118a9060 “CLEAN CONNECTION TO ALL FORCE FOR DATABASE postgres;”, messageType=QUERY_MESSAGE, msg=0x7f61d9564ba0) at postgres.cpp:2777 #8  0x0000000001857110 in PostgresMain (argc=1, argv=0x7f624818f850, dbname=0x7f62437418a8 “database_resource_monitor”, username=0x7f6243741840 “user_resource_monitor”) at postgres.cpp:8268 #9  0x000000000166bcd3 in BackendRun (port=0x7f61d95661c0) at postmaster.cpp:7063 #10 0x000000000166d743 in SubPostmasterMain (argc=3, argv=0x7f61d9566430) at postmaster.cpp:7810 #11 0x000000000166c8f7 in MainStarterThreadFunc (args=0x7f625ad01bd8) at postmaster.cpp:7250 #12 0x0000000001d67ae6 in ThreadStarterFunc (arg=0x7f625ad01bc0) at gs_thread.cpp:389 #13 0x00007f633bf97806 in start_thread () from /lib64/libpthread.so.0 #14 0x00007f633bcf264d in clone () from /lib64/libc.so.6 #15 0x0000000000000000 in ?? () (gdb) p *MyProcPort $1 = {sock = 212, …, remote_host = 0x7f2e6074aee0 “100.185.178.233”, remote_hostname = 0x7f2e6074aee0 “100.185.178.233”, remote_hostname_resolv = 0, remote_port = 0x7f2e6074af70 “52563”, …}

    2）由上知，对端100.185.178.233，端口41684 ，明确对端信息后，登录到对端查看此连接对应的对端进程到底在做什么

    3）登录到对端机器100.185.178.233，根据remote_port 52563找到进程，结果如下图：

    linux178233:/lvs_kehuduan/script/dml # netstat -anop | grep 52563

    tcp        0      0 100.185.178.233:52563   100.185.185.182:6000    ESTABLISHED 229505/gsql         keepalive (1.40/0/0)

    linux178233:/lvs_kehuduan/script/dml # ps ux | grep 229505

    root     229505  0.7  0.0  53048  3400 pts/1    S    22:07   0:00 gsql -d database_resource_monitor -p 6000 -U user_resource_monitor -W           -h 100.185.185.182 -f dml/test_clean_connection.sql

    root     229531  0.0  0.0   5736   816 pts/4    S+   22:08   0:00 grep 229505

    linux178233:/lvs_kehuduan/script/dml #

    3、结论

    最终发现是用户在100.185.178.233 上通过gsql连接到集群，并持续执行test_clean_connection.sql，就是下图一个神奇的脚本，接近无限循环清理连接。。

一直在执行test_clean_connection.sql：

–创建jack用户。 CREATE USER jack PASSWORD ‘Bigdata123@’; –删除数据库template1在dn1和dn2节点上的连接。 CLEAN CONNECTION TO NODE (dn_6001_6002) FOR DATABASE template1; –删除用户jack在dn1节点上的连接。 CLEAN CONNECTION TO NODE (dn_6001_6002) TO USER jack; –删除在数据库postgres上的所有连接。 CLEAN CONNECTION TO ALL FORCE FOR DATABASE postgres; –删除用户jack。 DROP USER jack;

• 案例三：

    1.客户业务从172节点的cn接入

    2.用户业务偶现报错打印“FATAL: terminating connection due to administrator command“，重试可成功

    2.根据以上报错场景分析，排除shutdown场景，此报错只有两种场景：1）外部调用pg_terminate_backend函数 2）clean connection force

    3.排查发现用户自己有杀超时语句的程序，但是在172节点客户程序的日志中未找到该语句被杀的记录，并且语句是刚跑起来就被杀

    4.继续排查，在171节点的客户程序日志中找到了该语句被杀的日志

    5.经分析，是因为客户杀语句的程序使用了current_time() – backend_start

【闭环方案】

    排查代码中下发SIGTERM信号场景，后续版本中在调用pg_terminate_backend和clean connection force时，均打印日志，例如：

    Send SIGTERM to thread:

    send SIGTERM signal to walreceiver thread

    use pg_terminate_backend to terminate backend thread,tid

【场景二： CN在客户端报错相应时间点未找到日志记录】

    【分析及案例】

    1、报错现象

    Jdbc客户端报错如下：

    2、分析

    1）CN和DN日志中均未搜到“FATAL: terminating connection …”报错信息。按照场景一种提到的三种方式排查，均为发现异常。

    2）查看用户设置的session_timeout为1d，当达到超时时间时，集群会自动关闭此连接，如下图，在11:24时重新执行作业报错，查看日志发现在11:18:54.387因为已经达到超时时间，连接已经被关闭。

    3、对于jdbc来说，客户端和cn的之间的连接达到了session_timeout被kill，但是getConnections又从jdbc连接池拿了这个连接所以报的错。