Page MenuHomeVyOS Platform

Service config-sync can freeze the secondary router if it has commit-archive location
Closed, ResolvedPublicBUG

Description

The service config-sync can freeze the secondary router if it has commit-archive location xxx
To reproduce, there are 2 routes, main and secondary

Main router configuration:

set interfaces ethernet eth0 address '192.168.122.14/24'
set service config-sync mode 'load'
set service config-sync secondary address '192.168.122.11'
set service config-sync secondary key 'foo'
set service config-sync section 'nat'
set service config-sync section 'firewall'

Secondary router configuration:

set interfaces ethernet eth0 address '192.168.122.11/24'
set service https api keys id KID key 'foo'
set service https api socket
set service https virtual-host vsrv listen-address '192.168.122.11'
set system config-management commit-archive location 'scp://vyos:[email protected]/home/vyos/'
set system config-management commit-revisions '100'

Set changes in nat or firewall section on the main router:

vyos@r14# commit
INFO:vyos_config_sync:Config synchronization: Mode=load, Secondary=192.168.122.11
An error occurred: HTTPSConnectionPool(host='192.168.122.11', port=443): Read timed out. (read timeout=60)
ERROR:vyos_config_sync:An error occurred: HTTPSConnectionPool(host='192.168.122.11', port=443): Read timed out. (read timeout=60)

An error occurred: HTTPSConnectionPool(host='192.168.122.11', port=443): Read timed out. (read timeout=60)
ERROR:vyos_config_sync:An error occurred: HTTPSConnectionPool(host='192.168.122.11', port=443): Read timed out. (read timeout=60)
[edit]
vyos@r14#

CPU utilization is 100% for the secondary router, and he doesn't answer even for console. It stuck for several minutes.

The log file form the secondary node

Jul 10 16:36:06 r11 vyos-configd[634]: Received message: {"type": "node", "data": "/usr/libexec/vyos/conf_mode/config_mgmt.py"}
Jul 10 16:36:06 r11 vyos-configd[634]: Sending response 8
Jul 10 16:36:06 r11 sudo[2688]: pam_unix(sudo:session): session closed for user root
Jul 10 16:36:06 r11 systemd[1]: opt-vyatta-config-tmp-new_config_2582.mount: Deactivated successfully.
Jul 10 16:36:06 r11 sudo[2729]:     vyos : TTY=pts/0 ; PWD=/home/vyos ; USER=root ; COMMAND=/usr/bin/mv /tmp/config.boot.2722 /opt/vyatta/etc/config/archive/config.boot
Jul 10 16:36:06 r11 sudo[2729]: pam_unix(sudo:session): session opened for user root(uid=0) by vyos(uid=1002)
Jul 10 16:36:06 r11 sudo[2729]: pam_unix(sudo:session): session closed for user root
Jul 10 16:36:06 r11 sudo[2732]:     vyos : TTY=pts/0 ; PWD=/home/vyos ; USER=root ; COMMAND=/usr/sbin/logrotate -f -s /opt/vyatta/etc/config/archive/lr.state /opt/vyatta/etc/config/archive/lr.conf
Jul 10 16:36:06 r11 sudo[2732]: pam_unix(sudo:session): session opened for user root(uid=0) by vyos(uid=1002)
Jul 10 16:36:06 r11 sudo[2732]: pam_unix(sudo:session): session closed for user root
Jul 10 16:36:12 r11 commit[2741]: Successful change to active configuration by user vyos on /dev/pts/0
Jul 10 16:36:37 r11 sudo[2774]:     vyos : TTY=pts/0 ; PWD=/home/vyos ; USER=root ; COMMAND=/usr/bin/sh -c '/usr/sbin/vyshim /usr/libexec/vyos/conf_mode/config_mgmt.py'
Jul 10 16:36:37 r11 sudo[2774]: pam_unix(sudo:session): session opened for user root(uid=0) by vyos(uid=1002)
Jul 10 16:36:37 r11 vyos-configd[634]: Received message: {"type": "init"}
Jul 10 16:36:37 r11 vyos-configd[634]: config session pid is 2582
Jul 10 16:36:37 r11 vyos-configd[634]: Received message: {"type": "node", "data": "/usr/libexec/vyos/conf_mode/config_mgmt.py"}
Jul 10 16:36:37 r11 vyos-configd[634]: Sending response 8
Jul 10 16:36:37 r11 sudo[2774]: pam_unix(sudo:session): session closed for user root
Jul 10 16:36:37 r11 systemd[1]: opt-vyatta-config-tmp-new_config_2582.mount: Deactivated successfully.
Jul 10 16:36:38 r11 sudo[2815]:     vyos : TTY=pts/0 ; PWD=/home/vyos ; USER=root ; COMMAND=/usr/bin/mv /tmp/config.boot.2808 /opt/vyatta/etc/config/archive/config.boot
Jul 10 16:36:38 r11 sudo[2815]: pam_unix(sudo:session): session opened for user root(uid=0) by vyos(uid=1002)
Jul 10 16:36:38 r11 sudo[2815]: pam_unix(sudo:session): session closed for user root
Jul 10 16:36:38 r11 sudo[2818]:     vyos : TTY=pts/0 ; PWD=/home/vyos ; USER=root ; COMMAND=/usr/sbin/logrotate -f -s /opt/vyatta/etc/config/archive/lr.state /opt/vyatta/etc/config/archive/lr.conf
Jul 10 16:36:38 r11 sudo[2818]: pam_unix(sudo:session): session opened for user root(uid=0) by vyos(uid=1002)
Jul 10 16:36:38 r11 sudo[2818]: pam_unix(sudo:session): session closed for user root
Jul 10 16:36:41 r11 commit[2827]: Successful change to active configuration by user vyos on /dev/pts/0
Jul 10 16:40:01 r11 CRON[2943]: pam_unix(cron:session): session opened for user smmsp(uid=116) by (uid=0)
Jul 10 16:40:01 r11 CRON[2944]: (smmsp) CMD (test -x /etc/init.d/sendmail && test -x /usr/share/sendmail/sendmail && test -x /usr/libexec/sendmail/sendmail && /usr/share/sendmail/sendmail cron-msp)
Jul 10 16:40:01 r11 CRON[2943]: pam_unix(cron:session): session closed for user smmsp
Jul 10 16:40:13 r11 sudo[3016]:     root : PWD=/ ; USER=root ; COMMAND=/usr/bin/sh -c '/usr/sbin/vyshim /usr/libexec/vyos/conf_mode/nat.py'
Jul 10 16:40:13 r11 sudo[3016]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0)
Jul 10 16:40:13 r11 vyos-configd[634]: Received message: {"type": "init"}
Jul 10 16:40:13 r11 vyos-configd[634]: config session pid is 2197
Jul 10 16:40:13 r11 vyos-configd[634]: Received message: {"type": "node", "data": "/usr/libexec/vyos/conf_mode/nat.py"}
Jul 10 16:40:13 r11 vyos-configd[634]: Sending response 1
Jul 10 16:40:13 r11 sudo[3016]: pam_unix(sudo:session): session closed for user root
Jul 10 16:40:13 r11 systemd[1]: opt-vyatta-config-tmp-new_config_2197.mount: Deactivated successfully.
Jul 10 16:40:13 r11 sudo[3059]:     root : PWD=/ ; USER=root ; COMMAND=/usr/bin/mv /tmp/config.boot.3052 /opt/vyatta/etc/config/archive/config.boot
Jul 10 16:40:13 r11 sudo[3059]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0)
Jul 10 16:40:13 r11 sudo[3059]: pam_unix(sudo:session): session closed for user root
Jul 10 16:40:13 r11 sudo[3061]:     root : PWD=/ ; USER=root ; COMMAND=/usr/sbin/logrotate -f -s /opt/vyatta/etc/config/archive/lr.state /opt/vyatta/etc/config/archive/lr.conf
Jul 10 16:40:13 r11 sudo[3061]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0)
Jul 10 16:40:13 r11 sudo[3061]: pam_unix(sudo:session): session closed for user root
Jul 10 16:40:47 r11 sudo[3069]:     vyos : TTY=pts/0 ; PWD=/home/vyos ; USER=root ; COMMAND=/usr/bin/journalctl -f
Jul 10 16:40:47 r11 sudo[3069]: pam_unix(sudo:session): session opened for user root(uid=0) by vyos(uid=1002)
Jul 10 16:42:26 r11 ospfd[936]: [PHJDC-499N2][EC 100663314] STARVATION: task vtysh_read (7fbff75b07e0) ran for 6408ms (cpu time 316ms)
Jul 10 16:42:30 r11 sudo[3069]: pam_unix(sudo:session): session closed for user root
Jul 10 16:43:22 r11 systemd[1]: frr.service: Watchdog timeout (limit 1min)!
Jul 10 16:43:09 r11 ospfd[936]: [YZRX4-ZXG0C][EC 100663315] Thread Starvation: {(thread *)0x55eaa1499cd0 arg=0x55eaa1498aa0 timer  r=-33.707    ospf_lsa_refresh_walker() &ospf->t_lsa_refresher from ../ospfd/ospf_lsa.c:4037} was scheduled to pop greater than 4s ago
Jul 10 16:43:22 r11 systemd[1]: frr.service: Killing process 862 (watchfrr) with signal SIGABRT.
Jul 10 16:43:12 r11 watchfrr[862]: [YZRX4-ZXG0C][EC 100663315] Thread Starvation: {(thread *)0x555678374790 arg=0x55567836b1e0 timer  r=-40.445    wakeup_send_echo() &(dmn)->t_wakeup from ../watchfrr/watchfrr.c:705} was scheduled to pop greater than 4s ago
Jul 10 16:43:24 r11 systemd[1]: frr.service: Killing process 902 (zebra) with signal SIGABRT.
Jul 10 16:43:27 r11 BABELD[959]: Received signal 6 at 1688996607 (si_addr 0x1, PC 0x7f50fc4bea71); aborting...
Jul 10 16:43:24 r11 systemd[1]: frr.service: Killing process 915 (bgpd) with signal SIGABRT.
Jul 10 16:43:27 r11 RIPNG[930]: Received signal 6 at 1688996607 (si_addr 0x1, PC 0x7fa1ae8cd2e0); aborting...
Jul 10 16:43:25 r11 systemd[1]: frr.service: Killing process 923 (ripd) with signal SIGABRT.
Jul 10 16:43:25 r11 systemd[1]: frr.service: Killing process 930 (ripngd) with signal SIGABRT.
Jul 10 16:43:26 r11 systemd[1]: frr.service: Killing process 936 (ospfd) with signal SIGABRT.
Jul 10 16:43:26 r11 systemd[1]: frr.service: Killing process 939 (ospf6d) with signal SIGABRT.
Jul 10 16:43:27 r11 systemd[1]: frr.service: Killing process 951 (isisd) with signal SIGABRT.
Jul 10 16:43:27 r11 systemd[1]: frr.service: Killing process 959 (babeld) with signal SIGABRT.
Jul 10 16:43:27 r11 systemd[1]: frr.service: Killing process 962 (ldpd) with signal SIGABRT.
Jul 10 16:43:27 r11 systemd[1]: frr.service: Killing process 963 (ldpd) with signal SIGABRT.
Jul 10 16:43:27 r11 systemd[1]: frr.service: Killing process 982 (ldpd) with signal SIGABRT.
Jul 10 16:43:27 r11 systemd[1]: frr.service: Killing process 987 (eigrpd) with signal SIGABRT.
Jul 10 16:43:27 r11 systemd[1]: frr.service: Killing process 990 (staticd) with signal SIGABRT.
Jul 10 16:43:27 r11 systemd[1]: frr.service: Killing process 994 (bfdd) with signal SIGABRT.
Jul 10 16:43:27 r11 systemd[1]: frr.service: Main process exited, code=killed, status=14/ALRM
Jul 10 16:43:27 r11 BFD[994]: Received signal 6 at 1688996607 (si_addr 0x1, PC 0x7f4836fe003b); aborting...
Jul 10 16:43:27 r11 STATIC[990]: Received signal 6 at 1688996607 (si_addr 0x1, PC 0x7f7282ebf045); aborting...
Jul 10 16:43:27 r11 OSPF6[939]: Received signal 6 at 1688996607 (si_addr 0x1, PC 0x7f02d064d190); aborting...
Jul 10 16:43:27 r11 LDP[982]: Received signal 6 at 1688996607 (si_addr 0x1, PC 0x7fbf3ef22045); aborting...
Jul 10 16:43:27 r11 ISIS[951]: Received signal 6 at 1688996607 (si_addr 0x1, PC 0x7f7a94147d20); aborting...
Jul 10 16:43:27 r11 EIGRP[987]: Received signal 6 at 1688996607 (si_addr 0x1, PC 0x7f24431b303b); aborting...
Jul 10 16:43:27 r11 EIGRP[987]: /usr/lib/x86_64-linux-gnu/frr/libfrr.so.0(zlog_backtrace_sigsafe+0x6f) [0x7f24431c901f]
Jul 10 16:43:27 r11 EIGRP[987]: /usr/lib/x86_64-linux-gnu/frr/libfrr.so.0(zlog_signal+0xf5) [0x7f24431c9225]
Jul 10 16:43:27 r11 EIGRP[987]: /usr/lib/x86_64-linux-gnu/frr/libfrr.so.0(+0xd0c91) [0x7f24431f6c91]
Jul 10 16:43:27 r11 EIGRP[987]: /lib/x86_64-linux-gnu/libc.so.6(+0x3bf90) [0x7f2442f78f90]
Jul 10 16:43:27 r11 EIGRP[987]: /usr/lib/x86_64-linux-gnu/frr/libfrr.so.0(rcu_read_lock+0x4b) [0x7f24431b303b]
Jul 10 16:43:27 r11 EIGRP[987]: /usr/lib/x86_64-linux-gnu/frr/libfrr.so.0(thread_fetch+0x975) [0x7f2443208975]
Jul 10 16:43:27 r11 EIGRP[987]: /usr/lib/x86_64-linux-gnu/frr/libfrr.so.0(frr_run+0xf3) [0x7f24431c1333]
Jul 10 16:43:27 r11 EIGRP[987]: /usr/lib/frr/eigrpd(main+0x105) [0x555b5d757005]
Jul 10 16:43:27 r11 EIGRP[987]: /lib/x86_64-linux-gnu/libc.so.6(+0x2718a) [0x7f2442f6418a]
Jul 10 16:43:27 r11 EIGRP[987]: /lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0x85) [0x7f2442f64245]
Jul 10 16:43:27 r11 EIGRP[987]: /usr/lib/frr/eigrpd(_start+0x21) [0x555b5d757251]
Jul 10 16:43:27 r11 EIGRP[987]: no thread information available
Jul 10 16:43:27 r11 STATIC[990]: /usr/lib/x86_64-linux-gnu/frr/libfrr.so.0(zlog_backtrace_sigsafe+0x6f) [0x7f7282ed501f]
Jul 10 16:43:27 r11 STATIC[990]: /usr/lib/x86_64-linux-gnu/frr/libfrr.so.0(zlog_signal+0xf5) [0x7f7282ed5225]
Jul 10 16:43:27 r11 STATIC[990]: /usr/lib/x86_64-linux-gnu/frr/libfrr.so.0(+0xd0c91) [0x7f7282f02c91]
Jul 10 16:43:27 r11 STATIC[990]: /lib/x86_64-linux-gnu/libc.so.6(+0x3bf90) [0x7f7282c71f90]
Jul 10 16:43:27 r11 STATIC[990]: /usr/lib/x86_64-linux-gnu/frr/libfrr.so.0(rcu_read_lock+0x55) [0x7f7282ebf045]
Jul 10 16:43:27 r11 STATIC[990]: /usr/lib/x86_64-linux-gnu/frr/libfrr.so.0(thread_fetch+0x975) [0x7f7282f14975]
Jul 10 16:43:27 r11 STATIC[990]: /usr/lib/x86_64-linux-gnu/frr/libfrr.so.0(frr_run+0xf3) [0x7f7282ecd333]
Jul 10 16:43:27 r11 STATIC[990]: /usr/lib/frr/staticd(main+0xef) [0x55f25fb49adf]
Jul 10 16:43:27 r11 STATIC[990]: /lib/x86_64-linux-gnu/libc.so.6(+0x2718a) [0x7f7282c5d18a]
Jul 10 16:43:27 r11 STATIC[990]: /lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0x85) [0x7f7282c5d245]
Jul 10 16:43:27 r11 STATIC[990]: /usr/lib/frr/staticd(_start+0x21) [0x55f25fb49c51]
Jul 10 16:43:27 r11 STATIC[990]: no thread information available
Jul 10 16:43:27 r11 BABELD[959]: /usr/lib/x86_64-linux-gnu/frr/libfrr.so.0(zlog_backtrace_sigsafe+0x6f) [0x7f50fc6ab01f]
Jul 10 16:43:27 r11 BABELD[959]: /usr/lib/x86_64-linux-gnu/frr/libfrr.so.0(zlog_signal+0xf5) [0x7f50fc6ab225]
Jul 10 16:43:27 r11 BABELD[959]: /usr/lib/x86_64-linux-gnu/frr/libfrr.so.0(+0xd0c91) [0x7f50fc6d8c91]
Jul 10 16:43:27 r11 BABELD[959]: /lib/x86_64-linux-gnu/libc.so.6(+0x3bf90) [0x7f50fc45af90]
Jul 10 16:43:27 r11 BABELD[959]: /lib/x86_64-linux-gnu/libc.so.6(+0x9fa71) [0x7f50fc4bea71]
Jul 10 16:43:27 r11 BABELD[959]: /usr/lib/x86_64-linux-gnu/frr/libfrr.so.0(+0x73288) [0x7f50fc67b288]
Jul 10 16:43:27 r11 BABELD[959]: /usr/lib/x86_64-linux-gnu/frr/libfrr.so.0(cmd_execute+0x63) [0x7f50fc67db63]
Jul 10 16:43:27 r11 BABELD[959]: /usr/lib/x86_64-linux-gnu/frr/libfrr.so.0(+0xe7e77) [0x7f50fc6efe77]
Jul 10 16:43:27 r11 BABELD[959]: /usr/lib/x86_64-linux-gnu/frr/libfrr.so.0(+0xe8644) [0x7f50fc6f0644]
Jul 10 16:43:27 r11 BABELD[959]: /usr/lib/x86_64-linux-gnu/frr/libfrr.so.0(+0xeb898) [0x7f50fc6f3898]
Jul 10 16:43:27 r11 BABELD[959]: /usr/lib/x86_64-linux-gnu/frr/libfrr.so.0(thread_call+0x7d) [0x7f50fc6eab7d]
Jul 10 16:43:27 r11 BABELD[959]: /usr/lib/x86_64-linux-gnu/frr/libfrr.so.0(frr_run+0xe8) [0x7f50fc6a3328]
Jul 10 16:43:27 r11 BABELD[959]: /usr/lib/frr/babeld(main+0x178) [0x55c9291b0ab8]
Jul 10 16:43:27 r11 BABELD[959]: /lib/x86_64-linux-gnu/libc.so.6(+0x2718a) [0x7f50fc44618a]
Jul 10 16:43:27 r11 BABELD[959]: /lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0x85) [0x7f50fc446245]
Jul 10 16:43:27 r11 BABELD[959]: /usr/lib/frr/babeld(_start+0x21) [0x55c9291b0b91]
Jul 10 16:43:27 r11 BABELD[959]: in thread vtysh_read scheduled from ../lib/vty.c:2740 vty_event()
Jul 10 16:43:27 r11 LDP[982]: /usr/lib/x86_64-linux-gnu/frr/libfrr.so.0(zlog_backtrace_sigsafe+0x6f) [0x7fbf3ef3801f]
Jul 10 16:43:27 r11 LDP[982]: /usr/lib/x86_64-linux-gnu/frr/libfrr.so.0(zlog_signal+0xf5) [0x7fbf3ef38225]
Jul 10 16:43:27 r11 LDP[982]: /usr/lib/x86_64-linux-gnu/frr/libfrr.so.0(+0xd0c91) [0x7fbf3ef65c91]
Jul 10 16:43:27 r11 LDP[982]: /lib/x86_64-linux-gnu/libc.so.6(+0x3bf90) [0x7fbf3ecd4f90]
Jul 10 16:43:27 r11 LDP[982]: /usr/lib/x86_64-linux-gnu/frr/libfrr.so.0(rcu_read_lock+0x55) [0x7fbf3ef22045]
Jul 10 16:43:27 r11 LDP[982]: /usr/lib/x86_64-linux-gnu/frr/libfrr.so.0(thread_fetch+0x975) [0x7fbf3ef77975]
Jul 10 16:43:27 r11 LDP[982]: /usr/lib/x86_64-linux-gnu/frr/libfrr.so.0(frr_run+0xf3) [0x7fbf3ef30333]
Jul 10 16:43:27 r11 LDP[982]: /usr/lib/frr/ldpd(main+0x695) [0x559990c3c265]
Jul 10 16:43:27 r11 LDP[982]: /lib/x86_64-linux-gnu/libc.so.6(+0x2718a) [0x7fbf3ecc018a]
Jul 10 16:43:27 r11 LDP[982]: /lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0x85) [0x7fbf3ecc0245]
Jul 10 16:43:27 r11 LDP[982]: /usr/lib/frr/ldpd(_start+0x21) [0x559990c3c3a1]
Jul 10 16:43:27 r11 LDP[982]: no thread information available
Jul 10 16:43:27 r11 BFD[994]: /usr/lib/x86_64-linux-gnu/frr/libfrr.so.0(zlog_backtrace_sigsafe+0x6f) [0x7f4836ff601f]
Jul 10 16:43:27 r11 RIPNG[930]: /usr/lib/x86_64-linux-gnu/frr/libfrr.so.0(zlog_backtrace_sigsafe+0x6f) [0x7fa1ae8a201f]
Jul 10 16:43:27 r11 RIPNG[930]: /usr/lib/x86_64-linux-gnu/frr/libfrr.so.0(zlog_signal+0xf5) [0x7fa1ae8a2225]
Jul 10 16:43:27 r11 RIPNG[930]: /usr/lib/x86_64-linux-gnu/frr/libfrr.so.0(+0xd0c91) [0x7fa1ae8cfc91]
Jul 10 16:43:27 r11 RIPNG[930]: /lib/x86_64-linux-gnu/libc.so.6(+0x3bf90) [0x7fa1ae651f90]
Jul 10 16:43:27 r11 RIPNG[930]: /usr/lib/x86_64-linux-gnu/frr/libfrr.so.0(seqlock_acquire_val+0) [0x7fa1ae8cd2e0]
Jul 10 16:43:27 r11 RIPNG[930]: /usr/lib/x86_64-linux-gnu/frr/libfrr.so.0(rcu_read_lock+0x55) [0x7fa1ae88c045]
Jul 10 16:43:27 r11 RIPNG[930]: /usr/lib/x86_64-linux-gnu/frr/libfrr.so.0(thread_fetch+0x975) [0x7fa1ae8e1975]
Jul 10 16:43:27 r11 RIPNG[930]: /usr/lib/x86_64-linux-gnu/frr/libfrr.so.0(frr_run+0xf3) [0x7fa1ae89a333]
Jul 10 16:43:27 r11 RIPNG[930]: /usr/lib/frr/ripngd(main+0xf8) [0x5558c6790098]
Jul 10 16:43:27 r11 RIPNG[930]: /lib/x86_64-linux-gnu/libc.so.6(+0x2718a) [0x7fa1ae63d18a]
Jul 10 16:43:27 r11 RIPNG[930]: /lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0x85) [0x7fa1ae63d245]
Jul 10 16:43:27 r11 RIPNG[930]: /usr/lib/frr/ripngd(_start+0x21) [0x5558c67901f1]
Jul 10 16:43:27 r11 RIPNG[930]: no thread information available
Jul 10 16:43:27 r11 BFD[994]: /usr/lib/x86_64-linux-gnu/frr/libfrr.so.0(zlog_signal+0xf5) [0x7f4836ff6225]
Jul 10 16:43:27 r11 BFD[994]: /usr/lib/x86_64-linux-gnu/frr/libfrr.so.0(+0xd0c91) [0x7f4837023c91]
Jul 10 16:43:27 r11 BFD[994]: /lib/x86_64-linux-gnu/libc.so.6(+0x3bf90) [0x7f4836d92f90]
Jul 10 16:43:27 r11 BFD[994]: /usr/lib/x86_64-linux-gnu/frr/libfrr.so.0(rcu_read_lock+0x4b) [0x7f4836fe003b]
Jul 10 16:43:27 r11 BFD[994]: /usr/lib/x86_64-linux-gnu/frr/libfrr.so.0(thread_fetch+0x975) [0x7f4837035975]
Jul 10 16:43:27 r11 BFD[994]: /usr/lib/x86_64-linux-gnu/frr/libfrr.so.0(frr_run+0xf3) [0x7f4836fee333]
Jul 10 16:43:27 r11 BFD[994]: /usr/lib/frr/bfdd(main+0x2a5) [0x5623ade0d075]
Jul 10 16:43:27 r11 BFD[994]: /lib/x86_64-linux-gnu/libc.so.6(+0x2718a) [0x7f4836d7e18a]
Jul 10 16:43:27 r11 BFD[994]: /lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0x85) [0x7f4836d7e245]
Jul 10 16:43:27 r11 BFD[994]: /usr/lib/frr/bfdd(_start+0x21) [0x5623ade0d4d1]
Jul 10 16:43:27 r11 BFD[994]: no thread information available
Jul 10 16:43:28 r11 ISIS[951]: /usr/lib/x86_64-linux-gnu/frr/libfrr.so.0(zlog_backtrace_sigsafe+0x6f) [0x7f7a9410601f]
Jul 10 16:43:28 r11 ISIS[951]: /usr/lib/x86_64-linux-gnu/frr/libfrr.so.0(zlog_signal+0xf5) [0x7f7a94106225]
Jul 10 16:43:28 r11 ISIS[951]: /usr/lib/x86_64-linux-gnu/frr/libfrr.so.0(+0xd0c91) [0x7f7a94133c91]
Jul 10 16:43:28 r11 ISIS[951]: /lib/x86_64-linux-gnu/libc.so.6(+0x3bf90) [0x7f7a93ea2f90]
Jul 10 16:43:28 r11 ISIS[951]: /usr/lib/x86_64-linux-gnu/frr/libfrr.so.0(vector_set_index+0) [0x7f7a94147d20]
Jul 10 16:43:28 r11 ISIS[951]: /usr/lib/x86_64-linux-gnu/frr/libfrr.so.0(array_to_vector+0x3a) [0x7f7a94147fea]
Jul 10 16:43:28 r11 ISIS[951]: /usr/lib/x86_64-linux-gnu/frr/libfrr.so.0(frrstr_split_vec+0x36) [0x7f7a940f0d16]
Jul 10 16:43:28 r11 ISIS[951]: /usr/lib/x86_64-linux-gnu/frr/libfrr.so.0(cmd_make_strvec+0x62) [0x7f7a940d7382]
Jul 10 16:43:28 r11 ISIS[951]: /usr/lib/x86_64-linux-gnu/frr/libfrr.so.0(cmd_execute+0xb6) [0x7f7a940d8bb6]
Jul 10 16:43:28 r11 ISIS[951]: /usr/lib/x86_64-linux-gnu/frr/libfrr.so.0(+0xe7e77) [0x7f7a9414ae77]
Jul 10 16:43:28 r11 ISIS[951]: /usr/lib/x86_64-linux-gnu/frr/libfrr.so.0(+0xe8644) [0x7f7a9414b644]
Jul 10 16:43:28 r11 ISIS[951]: /usr/lib/x86_64-linux-gnu/frr/libfrr.so.0(+0xeb898) [0x7f7a9414e898]
Jul 10 16:43:28 r11 ISIS[951]: /usr/lib/x86_64-linux-gnu/frr/libfrr.so.0(thread_call+0x7d) [0x7f7a94145b7d]
Jul 10 16:43:28 r11 ISIS[951]: /usr/lib/x86_64-linux-gnu/frr/libfrr.so.0(frr_run+0xe8) [0x7f7a940fe328]
Jul 10 16:43:28 r11 ISIS[951]: /usr/lib/frr/isisd(main+0x173) [0x565425e4e233]
Jul 10 16:43:28 r11 ISIS[951]: /lib/x86_64-linux-gnu/libc.so.6(+0x2718a) [0x7f7a93e8e18a]
Jul 10 16:43:28 r11 ISIS[951]: /lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0x85) [0x7f7a93e8e245]
Jul 10 16:43:28 r11 ISIS[951]: /usr/lib/frr/isisd(_start+0x21) [0x565425e4ea11]
Jul 10 16:43:28 r11 ISIS[951]: in thread vtysh_read scheduled from ../lib/vty.c:2740 vty_event()
Jul 10 16:43:28 r11 OSPF6[939]: /usr/lib/x86_64-linux-gnu/frr/libfrr.so.0(zlog_backtrace_sigsafe+0x6f) [0x7f02d068601f]
Jul 10 16:43:28 r11 OSPF6[939]: /usr/lib/x86_64-linux-gnu/frr/libfrr.so.0(zlog_signal+0xf5) [0x7f02d0686225]
Jul 10 16:43:28 r11 systemd[1]: frr.service: Failed with result 'watchdog'.
Jul 10 16:43:28 r11 OSPF6[939]: /usr/lib/x86_64-linux-gnu/frr/libfrr.so.0(+0xd0c91) [0x7f02d06b3c91]
Jul 10 16:43:28 r11 OSPF6[939]: /lib/x86_64-linux-gnu/libc.so.6(+0x3bf90) [0x7f02d0422f90]
Jul 10 16:43:28 r11 OSPF6[939]: /usr/lib/x86_64-linux-gnu/frr/libfrr.so.0(+0x6a190) [0x7f02d064d190]
Jul 10 16:43:28 r11 OSPF6[939]: /usr/lib/x86_64-linux-gnu/frr/libfrr.so.0(thread_fetch+0x981) [0x7f02d06c5981]
Jul 10 16:43:28 r11 OSPF6[939]: /usr/lib/x86_64-linux-gnu/frr/libfrr.so.0(frr_run+0xf3) [0x7f02d067e333]
Jul 10 16:43:28 r11 OSPF6[939]: /usr/lib/frr/ospf6d(main+0xcb) [0x55657a96979b]
Jul 10 16:43:28 r11 OSPF6[939]: /lib/x86_64-linux-gnu/libc.so.6(+0x2718a) [0x7f02d040e18a]
Jul 10 16:43:28 r11 OSPF6[939]: /lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0x85) [0x7f02d040e245]
Jul 10 16:43:28 r11 OSPF6[939]: /usr/lib/frr/ospf6d(_start+0x21) [0x55657a969d61]
Jul 10 16:43:28 r11 OSPF6[939]: no thread information available
Jul 10 16:43:28 r11 systemd[1]: frr.service: Consumed 14.041s CPU time.
Jul 10 16:43:33 r11 systemd[1]: frr.service: Scheduled restart job, restart counter is at 1.
Jul 10 16:43:33 r11 systemd[1]: Stopped frr.service - FRRouting.
Jul 10 16:43:33 r11 systemd[1]: frr.service: Consumed 14.041s CPU time.
Jul 10 16:43:33 r11 systemd[1]: Starting frr.service - FRRouting...
Jul 10 16:43:33 r11 systemd[1]: Stopping vyos-http-api.service - VyOS HTTP API service...
Jul 10 16:43:34 r11 systemd[1]: [email protected]: Deactivated successfully.
Jul 10 16:43:34 r11 systemd[1]: [email protected]: Consumed 3.603s CPU time.
Jul 10 16:43:34 r11 systemd[1]: [email protected]: Scheduled restart job, restart counter is at 1.
Jul 10 16:43:34 r11 systemd[1]: Stopped [email protected] - Getty on tty1.
Jul 10 16:43:34 r11 systemd[1]: [email protected]: Consumed 3.603s CPU time.
Jul 10 16:43:34 r11 systemd[1]: Started [email protected] - Getty on tty1.
Jul 10 16:43:34 r11 systemd[1]: opt-vyatta-config-tmp-new_config_2197.mount: Deactivated successfully.
Jul 10 16:43:36 r11 kernel: systemctl invoked oom-killer: gfp_mask=0x140cca(GFP_HIGHUSER_MOVABLE|__GFP_COMP), order=0, oom_score_adj=0
Jul 10 16:43:37 r11 kernel: CPU: 0 PID: 3208 Comm: systemctl Not tainted 6.1.38-amd64-vyos #1
Jul 10 16:43:37 r11 kernel: Hardware name: QEMU Standard PC (Q35 + ICH9, 2009), BIOS 1.15.0-1 04/01/2014
Jul 10 16:43:37 r11 kernel: Call Trace:
Jul 10 16:43:37 r11 kernel:  <TASK>
Jul 10 16:43:37 r11 kernel:  dump_stack_lvl+0x44/0x5c
Jul 10 16:43:37 r11 kernel:  dump_header+0x45/0x20c
Jul 10 16:43:37 r11 kernel:  oom_kill_process.cold+0xb/0x10
Jul 10 16:43:37 r11 kernel:  out_of_memory+0x1df/0x510
Jul 10 16:43:37 r11 kernel:  __alloc_pages_slowpath.constprop.0+0xb09/0xdf0
Jul 10 16:43:37 r11 kernel:  __alloc_pages+0x213/0x240
Jul 10 16:43:37 r11 kernel:  folio_alloc+0x12/0x40
Jul 10 16:43:37 r11 kernel:  __filemap_get_folio+0x14f/0x340
Jul 10 16:43:37 r11 kernel:  filemap_fault+0x134/0x910
Jul 10 16:43:37 r11 kernel:  ? filemap_map_pages+0x141/0x650
Jul 10 16:43:37 r11 kernel:  __do_fault+0x2e/0x110
Jul 10 16:43:37 r11 kernel:  do_fault+0x1c5/0x490
Jul 10 16:43:37 r11 kernel:  __handle_mm_fault+0x611/0x12a0
Jul 10 16:43:37 r11 kernel:  ? update_load_avg+0x7e/0x780
Jul 10 16:43:37 r11 kernel:  handle_mm_fault+0xcc/0x2b0
Jul 10 16:43:37 r11 kernel:  exc_page_fault+0x1a6/0x6f0
Jul 10 16:43:37 r11 kernel:  asm_exc_page_fault+0x22/0x30
Jul 10 16:43:37 r11 kernel: RIP: 0033:0x7fe6a3e38d00
Jul 10 16:43:37 r11 kernel: Code: 39 38 0f 84 ea fd ff ff 48 89 f9 0f 1f 80 00 00 00 00 48 83 c2 01 48 39 0c d0 75 f6 e9 d1 fd ff ff 48 8b 45 00 48 85 c0 74 0b <0f> b6 40 04 c0 e8 04 3c 02 74 76 f6 05 8f 7d 02 00 01 75 6d 4d 85
Jul 10 16:43:37 r11 kernel: RSP: 002b:00007ffd0d5f9920 EFLAGS: 00010202
Jul 10 16:43:37 r11 kernel: RAX: 00007fe6a3a5c168 RBX: 00007fe6a3a5d694 RCX: 00007fe6a3a5c168
Jul 10 16:43:37 r11 kernel: RDX: 0000000000000000 RSI: 00007fe6a32d2778 RDI: 0000000000000000
Jul 10 16:43:37 r11 kernel: RBP: 00007ffd0d5f9a78 R08: 0000000002873eda R09: 0000000000000000
Jul 10 16:43:37 r11 kernel: R10: 000000000000000f R11: 00000000a1cfb68c R12: 0000000000000000
Jul 10 16:43:37 r11 kernel: R13: 00007fe6a3cd8a50 R14: 00000000a1cfb68c R15: 00007ffd0d5f9a78
Jul 10 16:43:37 r11 kernel:  </TASK>
Jul 10 16:43:37 r11 kernel: Mem-Info:
Jul 10 16:43:37 r11 kernel: active_anon:274 inactive_anon:220616 isolated_anon:0
                             active_file:9 inactive_file:10 isolated_file:0
                             unevictable:2736 dirty:0 writeback:0
                             slab_reclaimable:3824 slab_unreclaimable:4940
                             mapped:950 shmem:448 pagetables:917
                             sec_pagetables:0 bounce:0
                             kernel_misc_reclaimable:0
                             free:12175 free_pcp:109 free_cma:0
Jul 10 16:43:37 r11 kernel: Node 0 active_anon:1096kB inactive_anon:882464kB active_file:36kB inactive_file:40kB unevictable:10944kB isolated(anon):0kB isolated(file):0kB mapped:3800kB dirty:0kB writeback:0kB shmem:1792kB shmem_thp: 0kB shmem_pmdmapped: 0kB anon_thp: 86016kB writeback_tmp:0kB kernel_stack:2192kB pagetables:3668kB sec_pagetables:0kB all_unreclaimable? yes
Jul 10 16:43:37 r11 kernel: Node 0 DMA free:4436kB boost:0kB min:712kB low:888kB high:1064kB reserved_highatomic:0KB active_anon:0kB inactive_anon:10860kB active_file:0kB inactive_file:0kB unevictable:0kB writepending:0kB present:15992kB managed:15360kB mlocked:0kB bounce:0kB free_pcp:0kB local_pcp:0kB free_cma:0kB
Jul 10 16:43:37 r11 kernel: lowmem_reserve[]: 0 933 933 933
Jul 10 16:43:37 r11 kernel: Node 0 DMA32 free:44264kB boost:0kB min:44340kB low:55424kB high:66508kB reserved_highatomic:0KB active_anon:1096kB inactive_anon:871616kB active_file:36kB inactive_file:40kB unevictable:10944kB writepending:0kB present:1032048kB managed:989260kB mlocked:10944kB bounce:0kB free_pcp:436kB local_pcp:436kB free_cma:0kB
Jul 10 16:43:37 r11 kernel: lowmem_reserve[]: 0 0 0 0
Jul 10 16:43:37 r11 kernel: Node 0 DMA: 1*4kB (M) 0*8kB 1*16kB (M) 2*32kB (U) 0*64kB 2*128kB (UM) 2*256kB (UM) 1*512kB (U) 1*1024kB (M) 1*2048kB (M) 0*4096kB = 4436kB
Jul 10 16:43:37 r11 kernel: Node 0 DMA32: 716*4kB (UE) 617*8kB (UME) 285*16kB (UE) 247*32kB (UME) 135*64kB (UME) 50*128kB (UME) 13*256kB (UME) 5*512kB (UME) 3*1024kB (M) 0*2048kB 0*4096kB = 44264kB
Jul 10 16:43:37 r11 kernel: Node 0 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=1048576kB
Jul 10 16:43:37 r11 kernel: Node 0 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=2048kB
Jul 10 16:43:37 r11 kernel: 1418 total pagecache pages
Jul 10 16:43:37 r11 kernel: 262010 pages RAM
Jul 10 16:43:37 r11 kernel: 0 pages HighMem/MovableOnly
Jul 10 16:43:37 r11 kernel: 10855 pages reserved
Jul 10 16:43:37 r11 kernel: 0 pages cma reserved
Jul 10 16:43:37 r11 kernel: 0 pages hwpoisoned
Jul 10 16:43:37 r11 kernel: Tasks state (memory values in pages):
Jul 10 16:43:37 r11 kernel: [  pid  ]   uid  tgid total_vm      rss pgtables_bytes swapents oom_score_adj name
Jul 10 16:43:37 r11 kernel: [    625]     0   625    12375      654    94208        0          -250 systemd-journal
Jul 10 16:43:37 r11 kernel: [    634]     0   634    79014    15222   237568        0             0 python3
Jul 10 16:43:37 r11 kernel: [    636]     0   636    30673     4450   131072        0             0 python3
Jul 10 16:43:37 r11 kernel: [    640]     0   640     6208      997    73728        0         -1000 systemd-udevd
Jul 10 16:43:37 r11 kernel: [    673]     0   673     2065     1594    61440        0             0 haveged
Jul 10 16:43:37 r11 kernel: [    694]     0   694     3280      367    53248        0         -1000 auditd
Jul 10 16:43:37 r11 kernel: [    786]     0   786      625      223    40960        0             0 acpid
Jul 10 16:43:37 r11 kernel: [    793]     0   793     1652      460    53248        0             0 cron
Jul 10 16:43:37 r11 kernel: [    794]   103   794     2010      560    53248        0          -900 dbus-daemon
Jul 10 16:43:37 r11 kernel: [    800]     0   800     4164      533    69632        0             0 systemd-logind
Jul 10 16:43:37 r11 kernel: [    811]     0   811      895      213    49152        0             0 atd
Jul 10 16:43:37 r11 kernel: [    825]     0   825    20058      515    53248        0             0 qemu-ga
Jul 10 16:43:37 r11 kernel: [    833]     0   833      618      307    45056        0             0 atopacctd
Jul 10 16:43:37 r11 kernel: [    835]     0   835     2959     2738    61440        0         -1000 atop
Jul 10 16:43:37 r11 kernel: [   1060]     0  1060      620      277    40960        0             0 netplugd
Jul 10 16:43:37 r11 kernel: [   1921]     0  1921    55444     1167    86016        0             0 rsyslogd
Jul 10 16:43:37 r11 kernel: [   2071]   113  2071     4722      547    61440        0             0 chronyd
Jul 10 16:43:37 r11 kernel: [   2072]   113  2072     2640      506    61440        0             0 chronyd
Jul 10 16:43:37 r11 kernel: [   2119]     0  2119     3878      746    69632        0         -1000 sshd
Jul 10 16:43:37 r11 kernel: [   2197]     0  2197   386697   192280  1662976        0             0 vyos-http-api-s
Jul 10 16:43:37 r11 kernel: [   2236]     0  2236     2663      329    57344        0             0 nginx
Jul 10 16:43:37 r11 kernel: [   2237]    33  2237     2776      510    61440        0             0 nginx
Jul 10 16:43:37 r11 kernel: [   2303]     0  2303     1374      155    49152        0             0 agetty
Jul 10 16:43:37 r11 kernel: [   2312]     0  2312     4400      961    73728        0             0 sshd
Jul 10 16:43:37 r11 kernel: [   2315]  1002  2315     4702      856    77824        0           100 systemd
Jul 10 16:43:37 r11 kernel: [   2316]  1002  2316    26086     1139    86016        0           100 (sd-pam)
Jul 10 16:43:37 r11 kernel: [   2397]  1002  2397     4465      690    69632        0             0 sshd
Jul 10 16:43:37 r11 kernel: [   2398]  1002  2398     1974      860    49152        0             0 vbash
Jul 10 16:43:37 r11 kernel: [   2582]  1002  2582     2134      618    57344        0             0 vbash
Jul 10 16:43:37 r11 kernel: [   2801]  1002  2801    74613      104    73728        0             0 unionfs-fuse
Jul 10 16:43:37 r11 kernel: [   3200]     0  3200    25893     1107    86016        0             0 (s-config)
Jul 10 16:43:37 r11 kernel: [   3204]     0  3204     1799      571    53248        0             0 frrinit.sh
Jul 10 16:43:37 r11 kernel: [   3207]     0  3207     1799      312    53248        0             0 frrinit.sh
Jul 10 16:43:37 r11 kernel: [   3208]     0  3208     3333      197    65536        0             0 systemctl
Jul 10 16:43:37 r11 kernel: [   3209]     0  3209     6209      838    61440        0             0 (udev-worker)
Jul 10 16:43:37 r11 kernel: oom-kill:constraint=CONSTRAINT_NONE,nodemask=(null),cpuset=frr.service,mems_allowed=0,global_oom,task_memcg=/system.slice/vyos-http-api.service,task=vyos-http-api-s,pid=2197,uid=0
Jul 10 16:43:37 r11 kernel: Out of memory: Killed process 2197 (vyos-http-api-s) total-vm:1546788kB, anon-rss:766960kB, file-rss:2160kB, shmem-rss:0kB, UID:0 pgtables:1624kB oom_score_adj:0
Jul 10 16:43:37 r11 kernel: oom_reaper: reaped process 2197 (vyos-http-api-s), now anon-rss:0kB, file-rss:0kB, shmem-rss:0kB
Jul 10 16:43:37 r11 systemd[1]: vyos-http-api.service: A process of this unit has been killed by the OOM killer.
Jul 10 16:43:37 r11 systemd[1]: vyos-http-api.service: Killing process 2197 (vyos-http-api-s) with signal SIGKILL.
Jul 10 16:43:37 r11 systemd[1]: vyos-http-api.service: Main process exited, code=killed, status=9/KILL
Jul 10 16:43:37 r11 systemd[1]: vyos-http-api.service: Failed with result 'oom-kill'.
Jul 10 16:43:37 r11 systemd[1]: Stopped vyos-http-api.service - VyOS HTTP API service.
Jul 10 16:43:37 r11 systemd[1]: vyos-http-api.service: Consumed 2min 13.966s CPU time.
Jul 10 16:43:37 r11 systemd[1]: Stopping vyos-router.service - VyOS Router...
Jul 10 16:43:37 r11 frrinit.sh[3204]: Starting watchfrr with command: '  /usr/lib/frr/watchfrr  -d  -F traditional   zebra bgpd ripd ripngd ospfd ospf6d isisd babeld ldpd eigrpd staticd bfdd'.
Jul 10 16:43:37 r11 vyos-router[3210]: Stopping VyOS router:.
Jul 10 16:43:37 r11 vyos-router[3210]: Un-mounting VyOS Config...
Jul 10 16:43:37 r11 vyos-router[3226]: umount: /opt/vyatta/config: target is busy.
Jul 10 16:43:37 r11 vyos-router[3210]: failed.
Jul 10 16:43:37 r11 watchfrr[3228]: [T83RR-8SM5G] watchfrr 8.5.2 starting: vty@0
Jul 10 16:43:37 r11 watchfrr[3228]: [NG1AJ-FP2TQ] Terminating on signal
Jul 10 16:43:37 r11 systemd[1]: frr.service: Deactivated successfully.
Jul 10 16:43:37 r11 systemd[1]: Stopped frr.service - FRRouting.
Jul 10 16:43:37 r11 systemd[1]: vyos-router.service: Deactivated successfully.
Jul 10 16:43:37 r11 systemd[1]: Stopped vyos-router.service - VyOS Router.
Jul 10 16:43:37 r11 vyos-config[3200]: Configuration success
Jul 10 16:47:50 r11 systemd[1]: Starting systemd-tmpfiles-clean.service - Cleanup of Temporary Directories...
Jul 10 16:47:50 r11 systemd[1]: systemd-tmpfiles-clean.service: Deactivated successfully.
Jul 10 16:47:50 r11 systemd[1]: Finished systemd-tmpfiles-clean.service - Cleanup of Temporary Directories.
Jul 10 16:47:50 r11 systemd[1]: run-credentials-systemd\x2dtmpfiles\x2dclean.service.mount: Deactivated successfully.
Jul 10 16:53:41 r11 sudo[3305]:     vyos : TTY=pts/0 ; PWD=/home/vyos ; USER=root ; COMMAND=/usr/bin/journalctl -f
Jul 10 16:53:41 r11 sudo[3305]: pam_unix(sudo:session): session opened for user root(uid=0) by vyos(uid=1002)
Jul 10 16:53:47 r11 sudo[3305]: pam_unix(sudo:session): session closed for user root
Jul 10 16:53:53 r11 sudo[3309]:     vyos : TTY=pts/0 ; PWD=/home/vyos ; USER=root ; COMMAND=/usr/bin/journalctl
Jul 10 16:53:53 r11 sudo[3309]: pam_unix(sudo:session): session opened for user root(uid=0) by vyos(uid=1002)
[edit]
vyos@r11#

Details

Difficulty level
Unknown (require assessment)
Version
-
Why the issue appeared?
Will be filled on close
Is it a breaking change?
Unspecified (possibly destroys the router)
Issue type
Unspecified (please specify)

Event Timeline

Viacheslav changed the subtype of this task from "Feature Request" to "Bug".

This will be resolved after merging the PR for T6104.

jestabro moved this task from Need Triage to Finished on the VyOS 1.5 Circinus board.
jestabro moved this task from Need Triage to Finished on the VyOS 1.4 Sagitta (1.4.0-epa1) board.