payload: {"action":"created","issue":{"url":"https://api.github.com/repos/acassen/keepalived/issues/1364","repository_url":"https://api.github.com/repos/acassen/keepalived","labels_url":"https://api.github.com/repos/acassen/keepalived/issues/1364/labels{/name}","comments_url":"https://api.github.com/repos/acassen/keepalived/issues/1364/comments","events_url":"https://api.github.com/repos/acassen/keepalived/issues/1364/events","html_url":"https://github.com/acassen/keepalived/issues/1364","id":471654508,"node_id":"MDU6SXNzdWU0NzE2NTQ1MDg=","number":1364,"title":"Keepalived_vrrp Child (PID XXXX) failed to terminate after kill","user":{"login":"e-pirate","id":37085065,"node_id":"MDQ6VXNlcjM3MDg1MDY1","avatar_url":"https://avatars2.githubusercontent.com/u/37085065?v=4","gravatar_id":"","url":"https://api.github.com/users/e-pirate","html_url":"https://github.com/e-pirate","followers_url":"https://api.github.com/users/e-pirate/followers","following_url":"https://api.github.com/users/e-pirate/following{/other_user}","gists_url":"https://api.github.com/users/e-pirate/gists{/gist_id}","starred_url":"https://api.github.com/users/e-pirate/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/e-pirate/subscriptions","organizations_url":"https://api.github.com/users/e-pirate/orgs","repos_url":"https://api.github.com/users/e-pirate/repos","events_url":"https://api.github.com/users/e-pirate/events{/privacy}","received_events_url":"https://api.github.com/users/e-pirate/received_events","type":"User","site_admin":false},"labels":[{"id":1411476157,"node_id":"MDU6TGFiZWwxNDExNDc2MTU3","url":"https://api.github.com/repos/acassen/keepalived/labels/Awaiting%20feedback","name":"Awaiting feedback","color":"0052cc","default":false}],"state":"open","locked":false,"assignee":null,"assignees":[],"milestone":null,"comments":31,"created_at":"2019-07-23T11:57:11Z","updated_at":"2019-11-13T10:56:22Z","closed_at":null,"author_association":"NONE","body":"**Describe the bug**\r\nWe have Keepalived handling Tarantool in multi-shard configuration. We have 4 shards on a server, each could be master or replica and should then set specified IP address on a specified device name. Basically, we have two vrrp_instance for each shard because 'master' and 'replica' could became MASTER (in terms of KA) according to Tarantool chard state. We use scripts to control the state of a Tarantool shard. Here is a typical shard configuration:\r\n```\r\nvrrp_script chk_tnt_filedb1_pri {\r\n  script \"/etc/keepalived/scripts/checkn.sh 11013 primary\"\r\n  interval 1\r\n  timeout 3\r\n  fall 2\r\n  rise 1\r\n}\r\n\r\nvrrp_script chk_tnt_filedb1_rpl {\r\n  script \"/etc/keepalived/scripts/checkn.sh 11013 connected\"\r\n  interval 1\r\n  timeout 3\r\n  fall 2\r\n  rise 1\r\n}\r\n\r\nvrrp_instance TNT_FILEDB1_PRI {\r\n  interface eth0\r\n  state BACKUP\r\n  nopreempt\r\n  virtual_router_id 1\r\n  priority 100\r\n  advert_int 1\r\n  authentication {\r\n    auth_type AH\r\n    auth_pass PASS\r\n  }\r\n  unicast_src_ip 10.x.x.x\r\n  unicast_peer {\r\n    10.x.x.x\r\n  }\r\n  virtual_ipaddress {\r\n    10.x.x.x/32 dev master11011\r\n  }\r\n  track_script {\r\n    chk_tnt_filedb1_pri\r\n  }\r\n}\r\n\r\nvrrp_instance TNT_FILEDB1_RPL {\r\n  interface eth0\r\n  state BACKUP\r\n  nopreempt\r\n  virtual_router_id 128\r\n  priority 100\r\n  advert_int 1\r\n  authentication {\r\n    auth_type AH\r\n    auth_pass PASS\r\n  }\r\n  unicast_src_ip 10.x.x.x\r\n  unicast_peer {\r\n    10.x.x.x\r\n  }\r\n  virtual_ipaddress {\r\n    10.x.x.x/32 dev slave11011\r\n  }\r\n  track_script {\r\n    chk_tnt_filedb1_rpl\r\n  }\r\n}\r\n```\r\nThe opposite side configuration is the same except IP addresses - they point one on each other. The other 3 shard configuration is equal except port.\r\nThe script content is the fallows:\r\n```\r\n#!/bin/bash\r\n/usr/bin/echo \"lua box.info.status\" | /usr/bin/nc -w 3 localhost \"$1\" | /usr/bin/grep -q \"$2\"\r\n```\r\nSince we have 4 shards on the same server, we have the above script that uses netcat for one couple of shards, and the other couple have bash magic:\r\n```\r\n#!/bin/bash\r\nexec 5<>/dev/tcp/localhost/\"$1\" && /usr/bin/timeout 3 /usr/bin/echo -e \"lua box.info.status\\nexit\" >&5 && /usr/bin/timeout 3 /usr/bin/grep -q \"$2\" <&5\r\n```\r\nAll two scripts have timeouts hardcoded into them. Both accept two parameters: port and the word we expect from Tarantool to determine if it is master or replica.\r\n\r\nWhat we found is that at some random moment KA will start showing errors in logs:\r\n```\r\n2019-07-21T16:15:11.068 o-cld-filedb1   Keepalived_vrrp Track script chk_tnt_filedb2_pri is already running, expect idle - skipping run                                                                                                       \r\n2019-07-21T16:15:11.069 o-cld-filedb1   Keepalived_vrrp Track script chk_tnt_filedb2_rpl is already running, expect idle - skipping run                                                                                                       \r\n2019-07-21T16:15:11.069 o-cld-filedb1   Keepalived_vrrp Track script chk_tnt_filedb3_pri is already running, expect idle - skipping run                                                                                                       \r\n2019-07-21T16:15:11.069 o-cld-filedb1   Keepalived_vrrp Track script chk_tnt_filedb4_pri is already running, expect idle - skipping run                                                                                                       \r\n2019-07-21T16:15:11.069 o-cld-filedb1   Keepalived_vrrp Track script chk_tnt_filedb4_rpl is already running, expect idle - skipping run                                                                                                       \r\n2019-07-21T16:15:11.069 o-cld-filedb1   Keepalived_vrrp Track script chk_tnt_filedb1_pri is already running, expect idle - skipping run                                                                                                       \r\n2019-07-21T16:15:11.069 o-cld-filedb1   Keepalived_vrrp Track script chk_tnt_filedb1_rpl is already running, expect idle - skipping run                                                                                                       \r\n2019-07-21T16:15:11.069 o-cld-filedb1   Keepalived_vrrp Track script chk_tnt_filedb2_pri is already running, expect idle - skipping run                                                                                                       \r\n2019-07-21T16:15:12.070 o-cld-filedb1   Keepalived_vrrp Track script chk_tnt_filedb3_pri is being timed out, expect idle - skipping run                                                                                                       \r\n2019-07-21T16:15:12.070 o-cld-filedb1   Keepalived_vrrp Track script chk_tnt_filedb4_pri is being timed out, expect idle - skipping run                                                                                                       \r\n2019-07-21T16:15:12.070 o-cld-filedb1   Keepalived_vrrp Track script chk_tnt_filedb4_rpl is being timed out, expect idle - skipping run                                                                                                       \r\n2019-07-21T16:15:13.072 o-cld-filedb1   Keepalived_vrrp Track script chk_tnt_filedb3_pri is being timed out, expect idle - skipping run                                                                                                       \r\n2019-07-21T16:15:13.072 o-cld-filedb1   Keepalived_vrrp Track script chk_tnt_filedb4_pri is being timed out, expect idle - skipping run                                                                                                       \r\n2019-07-21T16:15:13.072 o-cld-filedb1   Keepalived_vrrp Track script chk_tnt_filedb4_rpl is being timed out, expect idle - skipping run                                                                                                       \r\n2019-07-21T16:15:13.072 o-cld-filedb1   Keepalived_vrrp Child (PID 7370) failed to terminate after kill\r\n2019-07-21T16:15:13.072 o-cld-filedb1   Keepalived_vrrp Child (PID 7376) failed to terminate after kill\r\n2019-07-21T16:15:13.072 o-cld-filedb1   Keepalived_vrrp Child (PID 7373) failed to terminate after kill\r\n2019-07-21T16:15:14.071 o-cld-filedb1   Keepalived_vrrp Track script chk_tnt_filedb3_pri is being timed out, expect idle - skipping run                                                                                                       \r\n2019-07-21T16:15:14.071 o-cld-filedb1   Keepalived_vrrp Track script chk_tnt_filedb4_pri is being timed out, expect idle - skipping run                                                                                                       \r\n2019-07-21T16:15:14.071 o-cld-filedb1   Keepalived_vrrp Track script chk_tnt_filedb4_rpl is being timed out, expect idle - skipping run                                                                                                       \r\n2019-07-21T16:15:14.072 o-cld-filedb1   Keepalived_vrrp Child (PID 7370) failed to terminate after kill\r\n2019-07-21T16:15:14.072 o-cld-filedb1   Keepalived_vrrp Child (PID 7376) failed to terminate after kill\r\n2019-07-21T16:15:14.072 o-cld-filedb1   Keepalived_vrrp Child (PID 7373) failed to terminate after kill\r\n2019-07-21T16:15:15.071 o-cld-filedb1   Keepalived_vrrp Track script chk_tnt_filedb3_pri is being timed out, expect idle - skipping run                                                                                                       \r\n2019-07-21T16:15:15.071 o-cld-filedb1   Keepalived_vrrp Track script chk_tnt_filedb4_pri is being timed out, expect idle - skipping run                                                                                                       \r\n2019-07-21T16:15:15.071 o-cld-filedb1   Keepalived_vrrp Track script chk_tnt_filedb4_rpl is being timed out, expect idle - skipping run\r\n```\r\n'Already running' message seems to be reasonable as scripts tend not to end in 1 second interval, as well as 'being timing out'. Both seems to be peak load related. This messages start to appear time to time and then gone after several repetitions without triggering state change. But 'failed to terminate after kill' once appeared will keep on repeating in log each 'interval' seconds (each 1 second in our case) until KA reload or restart. More interesting, none of this PIDs exist in system at the moment I find KA in that condition:\r\n```\r\n/etc/keepalived # ps aux | grep -E '7376|7373|7370'\r\nroot     31499  0.0  0.0 112704   988 pts/2    S+   14:19   0:00 grep --colour=auto -E 7376|7373|7370\r\n```\r\nBesides, I've seen KA triggering state change on Tarantool failing to respond in timeout and then returning MASTER back again a couple of seconds later without going into 'failed to terminate after kill' condition. So, this seems to be KA internal error not related to load.\r\n\r\nThe worst part of this is once KA failed this way, it will loose control over affected instances! I have modified check_script to always return non zero return code and chk_tnt_filedb1_pri remained in the MASTER state even the corresponding script was returning 1. chk_tnt_filedb2_pri (monitored by the same script) switched to the FAULT state.\r\n\r\n**Expected behavior**\r\nKA is not triggered on missing PIDs. No false error messages in logs.\r\n\r\n**Keepalived version**\r\n```Keepalived v2.0.17 (06/25,2019)\r\n\r\nCopyright(C) 2001-2019 Alexandre Cassen, <acassen@gmail.com>\r\n\r\nBuilt with kernel headers for Linux 3.10.0\r\nRunning on Linux 3.10.0-862.3.2.el7.x86_64 #1 SMP Mon May 21 23:36:36 UTC 2018\r\n\r\nconfigure options: --build=x86_64-redhat-linux-gnu --host=x86_64-redhat-linux-gnu --program-prefix= --disable-dependency-tracking --prefix=/usr --exec-prefix=/usr --bindir=/usr/bin --sbindir=/usr/sbin --sysconfdir=/etc --datadir=/usr/share --includedir=/usr/include --libdir=/usr/lib64 --libexecdir=/usr/libexec --localstatedir=/var --sharedstatedir=/var/lib --mandir=/usr/share/man --infodir=/usr/share/info --disable-nftables --disable-libiptc --disable-libipset --disable-libipset-dynamic --disable-snmp-reply-v3-for-v2 --enable-dbus --with-init=systemd build_alias=x86_64-redhat-linux-gnu host_alias=x86_64-redhat-linux-gnu PKG_CONFIG_PATH=:/usr/lib64/pkgconfig:/usr/share/pkgconfig CFLAGS=-O2 -g -pipe -Wall -Wp,-D_FORTIFY_SOURCE=2 -fexceptions -fstack-protector-strong --param=ssp-buffer-size=4 -grecord-gcc-switches -m64 -mtune=generic LDFLAGS=-Wl,-z,relro \r\n\r\nConfig options:  IPTABLES_CMD LVS VRRP VRRP_AUTH OLD_CHKSUM_COMPAT FIB_ROUTING DBUS\r\n\r\nSystem options:  PIPE2 SIGNALFD INOTIFY_INIT1 VSYSLOG EPOLL_CREATE1 IPV6_ADVANCED_API RTA_ENCAP RTA_EXPIRES RTA_PREF FRA_TUN_ID RTAX_CC_ALGO RTAX_QUICKACK FRA_OIFNAME IFA_FLAGS IP_MULTICAST_ALL NET_LINUX_IF_H_COLLISION LIBIPTC_LINUX_NET_IF_H_COLLISION VRRP_VMAC IFLA_LINK_NETNSID CN_PROC SOCK_NONBLOCK SOCK_CLOEXEC O_PATH GLOB_BRACE INET6_ADDR_GEN_MODE SO_MARK SCHED_RT SCHED_RESET_ON_FORK\r\n```\r\n\r\n**Distro (please complete the following information):**\r\nCentOS Linux release 7.5.1804 (Core) \r\n3.10.0-862.3.2.el7.x86_64(x86_64) on o-cld-filedb1.q\r\n   4 x \"Intel Core Processor (Broadwell)\", total 4 cores\r\n\r\n**Details of any containerisation or hosted service (e.g. AWS)**\r\noVirt VM\r\n\r\n**System Log entries**\r\nOnce started to 'fail to terminate' log will became endless.\r\n\r\n**Did keepalived coredump?**\r\nNever.\r\n\r\n**Additional context**\r\nThis happen only on master and never seen on a replica. Even they are both equal oVirt VMs.\r\n"},"comment":{"url":"https://api.github.com/repos/acassen/keepalived/issues/comments/553351157","html_url":"https://github.com/acassen/keepalived/issues/1364#issuecomment-553351157","issue_url":"https://api.github.com/repos/acassen/keepalived/issues/1364","id":553351157,"node_id":"MDEyOklzc3VlQ29tbWVudDU1MzM1MTE1Nw==","user":{"login":"pqarmitage","id":15689733,"node_id":"MDQ6VXNlcjE1Njg5NzMz","avatar_url":"https://avatars1.githubusercontent.com/u/15689733?v=4","gravatar_id":"","url":"https://api.github.com/users/pqarmitage","html_url":"https://github.com/pqarmitage","followers_url":"https://api.github.com/users/pqarmitage/followers","following_url":"https://api.github.com/users/pqarmitage/following{/other_user}","gists_url":"https://api.github.com/users/pqarmitage/gists{/gist_id}","starred_url":"https://api.github.com/users/pqarmitage/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/pqarmitage/subscriptions","organizations_url":"https://api.github.com/users/pqarmitage/orgs","repos_url":"https://api.github.com/users/pqarmitage/repos","events_url":"https://api.github.com/users/pqarmitage/events{/privacy}","received_events_url":"https://api.github.com/users/pqarmitage/received_events","type":"User","site_admin":false},"created_at":"2019-11-13T10:56:22Z","updated_at":"2019-11-13T10:56:22Z","author_association":"COLLABORATOR","body":"I have now merged commit 0a0095b which should resolve the issue.\r\n\r\n@e-pirate If you could also apply the following additional patch that will just log if the situation occurs where a child termination is received while the child thread is queued for a timeout, which was the cause of the problem, then we should get confirmation that the problem really is resolved if you get one of the ' pid moved from TIMEOUT to TERMINATED' messages.\r\n\r\n```\r\ndiff --git a/lib/scheduler.c b/lib/scheduler.c\r\nindex b389d42a..b25bc0ef 100644\r\n--- a/lib/scheduler.c\r\n+++ b/lib/scheduler.c\r\n@@ -1890,6 +1890,7 @@ process_child_termination(pid_t pid, int status)\r\n \t\t/* The child had been timed out, but we have not processed the timeout\r\n \t\t * and it is still on the thread->ready queue. Since we have now got\r\n \t\t * the termination, just handle the termination instead. */\r\n+log_message(LOG_INFO, \"Moving pid %d from TIMEOUT to TERMINATED on ready queue\", pid);\r\n \t\tthread->type = THREAD_CHILD_TERMINATED;\r\n \t}\r\n \telse\r\n```"}}
other: {"actor":{"display_login":"pqarmitage"}}