Skip to content

mgmt/zebra is dropping configuration in some rare situations #21128

Closed
Closed
mgmt/zebra is dropping configuration in some rare situations#21128
Assignees
choppsv1
Labels
triageNeeds further investigation
@donaldsharp

Description

@donaldsharp
donaldsharp
opened on Mar 13, 2026

Description

the test_config.py topotest is failing here for me:

[gw33] linux -- Python 3.12.3 /usr/bin/python3

r1 = <lib.topotest.Router object at 0x7d5bbea470e0>, confdir = PosixPath('/work/home/sharpd/frr2/tests/topotests/mgmt_config/r1'), tempdir = PosixPath('/tmp/topotests/mgmt_config.test_config/worker-logs/gw33/r1')
logpath = PosixPath('/tmp/topotests/mgmt_config.test_config/worker-logs/gw33/r1/mgmtd.log')

    def test_zebra_early_end_file(r1, confdir, tempdir, logpath):
        global logbuf

        conf = "early-end-zebra.conf"
        step(f"load {conf} file with vtysh -f ")
        output = r1.cmd_nostatus(f"vtysh -f {confdir / conf}")
        logbuf = save_log_snippet(logpath, logbuf, tempdir / mapname(conf))
        print(output)

        test_func = lambda: check_show_running(
            r1,
            present=[
                "allow-external-route-update",
                "router-id 1.2.3.4",
                "ip table range 2 3",
            ],
        )
        _, result = topotest.run_and_expect(test_func, None, count=20, wait=1)
>       assert result is None, result
E       AssertionError: Missing 'allow-external-route-update' in show running:
E         Building configuration...
E
E         Current configuration:
E         !
E         frr version 10.7.0-dev
E         frr defaults traditional
E         hostname r1
E         log commands
E         log file mgmtd.log
E         log timestamp precision 6
E         ip table range 2 3
E         no service integrated-vtysh-config
E         !
E         ip route 12.0.0.0/24 101.0.0.2
E         ip route 13.1.0.0/24 101.0.0.2
E         ip route 14.1.0.0/24 101.0.0.2
E         ip route 15.1.0.0/24 101.0.0.2
E         ip route 15.2.0.0/24 101.0.0.2
E         ip route 15.3.0.0/24 101.0.0.2
E         ip route 15.4.0.0/24 101.0.0.2
E         ip route 16.1.0.0/24 101.0.0.2
E         ip route 20.1.0.0/24 101.0.0.2
E         ip route 21.1.0.0/24 101.0.0.2
E         ipv6 route 2012::/48 2101::2
E         ip router-id 1.2.3.4
E         !
E         interface r1-eth0
E          ip address 101.0.0.1/24
E          ipv6 address 2101::1/64
E         exit
E         !
E         end
E
E       assert "Missing 'allow-external-route-update' in show running:\nBuilding configuration...\n\nCurrent configuration:\n!\nfrr version 10.7.0-dev\nfrr defaults traditional\nhostname r1\nlog commands\nlog file mgmtd.log\nlog timestamp precision 6\nip table range 2 3\nno service integrated-vtysh-config\n!\nip route 12.0.0.0/24 101.0.0.2\nip route 13.1.0.0/24 101.0.0.2\nip route 14.1.0.0/24 101.0.0.2\nip route 15.1.0.0/24 101.0.0.2\nip route 15.2.0.0/24 101.0.0.2\nip route 15.3.0.0/24 101.0.0.2\nip route 15.4.0.0/24 101.0.0.2\nip route 16.1.0.0/24 101.0.0.2\nip route 20.1.0.0/24 101.0.0.2\nip route 21.1.0.0/24 101.0.0.2\nipv6 route 2012::/48 2101::2\nip router-id 1.2.3.4\n!\ninterface r1-eth0\n ip address 101.0.0.1/24\n ipv6 address 2101::1/64\nexit\n!\nend\n" is None

test_config.py:390: AssertionError

The early-end-zebra.conf file being loaded is this:

allow-external-route-update
end
router-id 1.2.3.4
end
ip table range 2 3
end

The exec.log is showing this:

2026-03-13 10:04:02,114 DEBUG: topo: '<lambda>' succeeded after 0.02 seconds
2026-03-13 10:04:02,278 DEBUG: r1: cmd_status("/bin/bash -c 'vtysh -c '"'"'send log level info === TEST-START: mgmt_config/test_config.py::test_zebra_early_end_file'"'"''")
2026-03-13 10:04:02,298  INFO: topo: STEP 12: 'load early-end-zebra.conf file with vtysh -f '
2026-03-13 10:04:02,298 DEBUG: r1: cmd_status("/bin/bash -c 'vtysh -f /work/home/sharpd/frr2/tests/topotests/mgmt_config/r1/early-end-zebra.conf'")
2026-03-13 10:04:02,823 DEBUG: r1:   stdout:
        [2857947|mgmtd] sending configuration
        [2857948|zebra] sending configuration
        [2857948|zebra] done
        [2857947|mgmtd] done
        [2857966|staticd] sending configuration
        [2857966|staticd] done
        Waiting for children to finish applying config...
2026-03-13 10:04:02,901 DEBUG: topo: '<lambda>' polling started (interval 1 secs, maximum 20 tries)
2026-03-13 10:04:02,901 DEBUG: r1: cmd_status("/bin/bash -c 'vtysh -c '"'"'show running'"'"''")
2026-03-13 10:04:02,920 DEBUG: r1:   stdout:
        Building configuration...

        Current configuration:
        !
        frr version 10.7.0-dev
        frr defaults traditional
        hostname r1
        log commands
        log file mgmtd.log
        log timestamp precision 6
        ip table range 2 3
        no service integrated-vtysh-config
        !
        ip route 12.0.0.0/24 101.0.0.2
        ip route 13.1.0.0/24 101.0.0.2
        ip route 14.1.0.0/24 101.0.0.2
        ip route 15.1.0.0/24 101.0.0.2
        ip route 15.2.0.0/24 101.0.0.2
        ip route 15.3.0.0/24 101.0.0.2
        ip route 15.4.0.0/24 101.0.0.2
        ip route 16.1.0.0/24 101.0.0.2
        ip route 20.1.0.0/24 101.0.0.2
        ip route 21.1.0.0/24 101.0.0.2
        ipv6 route 2012::/48 2101::2
        ip router-id 1.2.3.4
        !
        interface r1-eth0
         ip address 101.0.0.1/24
         ipv6 address 2101::1/64
        exit
        !
        end

And finally here is the mgmtd.log from that time:

2026/03/13 10:04:02.296032 MGMTD: === TEST-START: mgmt_config/test_config.py::test_zebra_early_end_file
2026/03/13 10:04:02.296063 ZEBRA: [M7Q4P-46WDR] vty[39]@# send log level info === TEST-START: mgmt_config/test_config.py::test_zebra_early_end_file
2026/03/13 10:04:02.296098 ZEBRA: === TEST-START: mgmt_config/test_config.py::test_zebra_early_end_file
2026/03/13 10:04:02.296121 STATIC: [M7Q4P-46WDR] vty[16]@# send log level info === TEST-START: mgmt_config/test_config.py::test_zebra_early_end_file
2026/03/13 10:04:02.296160 STATIC: === TEST-START: mgmt_config/test_config.py::test_zebra_early_end_file
2026/03/13 10:04:02.298552 MGMTD: [ZFMPX-3BJHB] FE-CLIENT: vty_close_mgmt: closing vty session
2026/03/13 10:04:02.298563 MGMTD: [S32Q5-9NY59] FE-CLIENT: mgmt_fe_find_session_by_client_id: Found session-id 1202 using client-id 202
2026/03/13 10:04:02.298565 MGMTD: [ZMQ33-YKX6A] FE-CLIENT: mgmt_fe_send_session_req: Sending SESSION_REQ destroy message for session-id: 1202 client-id 202
2026/03/13 10:04:02.298566 MGMTD: [SQ2SQ-FRHPJ] FE-client: msg_conn_send_msg: SC send: depth 1 msg: 0x5e3fc6502b90
2026/03/13 10:04:02.298568 MGMTD: [JTRGS-X06D6] FE-ADAPTER: fe_adapter_process_msg: adapter Unknown-FD-14: session-id 1202 received SESSION_REQ message
2026/03/13 10:04:02.298569 MGMTD: [T761K-EPV86] FE-ADAPTER: fe_adapter_handle_session_req: Got session-req is create 0 req-id 202 for refer-id 1202 notify-fmt 0 from 'Unknown-FD-14'
2026/03/13 10:04:02.298571 MGMTD: [WSTGT-81BA3] FE-ADAPTER: fe_adapter_send_session_reply: Sending session-reply from adapter Unknown-FD-14 to session-id 1202 req-id 202 created 0 scok 1
2026/03/13 10:04:02.298573 MGMTD: [SQ2SQ-FRHPJ] FE-ADAPTER-CONN: msg_conn_send_msg: SC send: depth 1 msg: 0x5e3fc64efdf0
2026/03/13 10:04:02.298573 MGMTD: [MJMW0-D05WX] FE-CLIENT: fe_client_handle_native_msg: Got native message for session-id 1202
2026/03/13 10:04:02.298574 MGMTD: [V7PD2-AA12D] FE-CLIENT: mgmt_fe_find_session_by_session_id: Found session of client-id 202 using session-id 1202
2026/03/13 10:04:02.298575 MGMTD: [VB6QX-DXMC1] FE-CLIENT: fe_client_pop_sent_msg: Popping sent message for client vty-mgmtd-2805038 session-id 1202 req-id 202
2026/03/13 10:04:02.298575 MGMTD: [V2RY3-GDHAH] FE-CLIENT: fe_client_handle_native_msg: Got SESSION_REPLY (destroy) for client-id 202 with session-id: 1202
2026/03/13 10:04:02.298576 MGMTD: [ST1AN-6BXP4] FE-CLIENT: fe_client_handle_native_msg: Got SESSION_REPLY (destroy) for session-id 1202
2026/03/13 10:04:02.298577 MGMTD: [V7PD2-AA12D] FE-CLIENT: mgmt_fe_find_session_by_session_id: Found session of client-id 202 using session-id 1202
2026/03/13 10:04:02.298577 MGMTD: [RG6Q2-81P87] FE-CLIENT: vty_mgmt_client_session_notified: Destroyed session for client 202 successfully
2026/03/13 10:04:02.298578 MGMTD: [G1C9T-5VM0W] FE-ADAPTER-CONN: msg_conn_send_msg: SC return from depth: 0 msg: 0x5e3fc64efdf0
2026/03/13 10:04:02.298580 MGMTD: [G1C9T-5VM0W] FE-client: msg_conn_send_msg: SC return from depth: 0 msg: 0x5e3fc6502b90
2026/03/13 10:04:02.312669 MGMTD: [M1GTF-SGG0K] FE-CLIENT: mgmt_fe_send_session_req: Sending SESSION_REQ create message for client-id 203
2026/03/13 10:04:02.312684 MGMTD: [SQ2SQ-FRHPJ] FE-client: msg_conn_send_msg: SC send: depth 1 msg: 0x5e3fc64efdf0
2026/03/13 10:04:02.312686 MGMTD: [JTRGS-X06D6] FE-ADAPTER: fe_adapter_process_msg: adapter Unknown-FD-14: session-id 0 received SESSION_REQ message
2026/03/13 10:04:02.312688 MGMTD: [T761K-EPV86] FE-ADAPTER: fe_adapter_handle_session_req: Got session-req is create 1 req-id 203 for refer-id 0 notify-fmt 0 from 'Unknown-FD-14'
2026/03/13 10:04:02.312689 MGMTD: [PGMNP-VC5E0] FE-ADAPTER: fe_session_lookup_by_client_id: Session not found using client-id 203
2026/03/13 10:04:02.312692 MGMTD: [WSTGT-81BA3] FE-ADAPTER: fe_adapter_send_session_reply: Sending session-reply from adapter Unknown-FD-14 to session-id 1203 req-id 203 created 1 scok 1
2026/03/13 10:04:02.312694 MGMTD: [SQ2SQ-FRHPJ] FE-ADAPTER-CONN: msg_conn_send_msg: SC send: depth 1 msg: 0x5e3fc6502b90
2026/03/13 10:04:02.312695 MGMTD: [MJMW0-D05WX] FE-CLIENT: fe_client_handle_native_msg: Got native message for session-id 1203
2026/03/13 10:04:02.312697 MGMTD: [VB6QX-DXMC1] FE-CLIENT: fe_client_pop_sent_msg: Popping sent message for client vty-mgmtd-2805038 session-id 0 req-id 203
2026/03/13 10:04:02.312698 MGMTD: [V2RY3-GDHAH] FE-CLIENT: fe_client_handle_native_msg: Got SESSION_REPLY (create) for client-id 203 with session-id: 1203
2026/03/13 10:04:02.312699 MGMTD: [S32Q5-9NY59] FE-CLIENT: mgmt_fe_find_session_by_client_id: Found session-id 0 using client-id 203
2026/03/13 10:04:02.312700 MGMTD: [RG6Q2-81P87] FE-CLIENT: vty_mgmt_client_session_notified: Created session for client 203 successfully
2026/03/13 10:04:02.312702 MGMTD: [G1C9T-5VM0W] FE-ADAPTER-CONN: msg_conn_send_msg: SC return from depth: 0 msg: 0x5e3fc6502b90
2026/03/13 10:04:02.312703 MGMTD: [G1C9T-5VM0W] FE-client: msg_conn_send_msg: SC return from depth: 0 msg: 0x5e3fc64efdf0
2026/03/13 10:04:02.813806 MGMTD: [M7Q4P-46WDR] vty[19]@> enable
2026/03/13 10:04:02.813983 MGMTD: [M7Q4P-46WDR] vty[19]@# conf term file-lock
2026/03/13 10:04:02.814024 MGMTD: [ZX9ZD-V3QNE] FE-CLIENT: mgmt_fe_send_lockds_req: Sending LOCKDS_REQ (LOCK) message for DS:candidate session-id 1203
2026/03/13 10:04:02.814026 MGMTD: [V7PD2-AA12D] FE-CLIENT: mgmt_fe_find_session_by_session_id: Found session of client-id 203 using session-id 1203
2026/03/13 10:04:02.814027 MGMTD: [RAVAK-B9MVY] FE-CLIENT: fe_client_push_sent_msg: Push sent message refer-id 1203 req-id 1 for session-id 1203 of client vty-mgmtd-2805038
2026/03/13 10:04:02.814029 MGMTD: [SQ2SQ-FRHPJ] FE-client: msg_conn_send_msg: SC send: depth 1 msg: 0x5e3fc64f17d0
2026/03/13 10:04:02.814033 MGMTD: [R4YY3-A9DBJ] FE-ADAPTER: fe_adapter_process_msg: adapter Unknown-FD-14: session-id 1203 received LOCK message
2026/03/13 10:04:02.814034 MGMTD: [R80RW-J2ZXJ] FE-ADAPTER: fe_session_handle_lock: Got LOCK for DS:candidate for session-id 1203 from 'Unknown-FD-14'
2026/03/13 10:04:02.814036 MGMTD: [WX5H7-YFAEM] DS: mgmt_ds_lock: LOCK on DS:candidate for session-id 1203
2026/03/13 10:04:02.814037 MGMTD: [ZW0E2-TDBY4] FE-ADAPTER: mgmt_fe_session_write_lock_ds: Write-Locked the DS:candidate for session-id: 1203 from Unknown-FD-14
2026/03/13 10:04:02.814039 MGMTD: [JTE36-YSQRX] FE-ADAPTER: fe_session_send_lock_reply: Sending lock-reply from adapter Unknown-FD-14 on session-id 1203 req-id 1 datastore 2 lock 1 scok 1
2026/03/13 10:04:02.814041 MGMTD: [SQ2SQ-FRHPJ] FE-ADAPTER-CONN: msg_conn_send_msg: SC send: depth 1 msg: 0x5e3fc64c9870
2026/03/13 10:04:02.814042 MGMTD: [MJMW0-D05WX] FE-CLIENT: fe_client_handle_native_msg: Got native message for session-id 1203
2026/03/13 10:04:02.814042 MGMTD: [V7PD2-AA12D] FE-CLIENT: mgmt_fe_find_session_by_session_id: Found session of client-id 203 using session-id 1203
2026/03/13 10:04:02.814043 MGMTD: [VB6QX-DXMC1] FE-CLIENT: fe_client_pop_sent_msg: Popping sent message for client vty-mgmtd-2805038 session-id 1203 req-id 1
2026/03/13 10:04:02.814044 MGMTD: [P3YQK-NFNKZ] FE-CLIENT: vty_mgmt_handle_lock_ds_reply: Locked DS 2 successfully
2026/03/13 10:04:02.814045 MGMTD: [G1C9T-5VM0W] FE-ADAPTER-CONN: msg_conn_send_msg: SC return from depth: 0 msg: 0x5e3fc64c9870
2026/03/13 10:04:02.814046 MGMTD: [G1C9T-5VM0W] FE-client: msg_conn_send_msg: SC return from depth: 0 msg: 0x5e3fc64f17d0
2026/03/13 10:04:02.814047 MGMTD: [ZX9ZD-V3QNE] FE-CLIENT: mgmt_fe_send_lockds_req: Sending LOCKDS_REQ (LOCK) message for DS:running session-id 1203
2026/03/13 10:04:02.814047 MGMTD: [V7PD2-AA12D] FE-CLIENT: mgmt_fe_find_session_by_session_id: Found session of client-id 203 using session-id 1203
2026/03/13 10:04:02.814048 MGMTD: [RAVAK-B9MVY] FE-CLIENT: fe_client_push_sent_msg: Push sent message refer-id 1203 req-id 2 for session-id 1203 of client vty-mgmtd-2805038
2026/03/13 10:04:02.814048 MGMTD: [SQ2SQ-FRHPJ] FE-client: msg_conn_send_msg: SC send: depth 1 msg: 0x5e3fc64c9870
2026/03/13 10:04:02.814049 MGMTD: [R4YY3-A9DBJ] FE-ADAPTER: fe_adapter_process_msg: adapter Unknown-FD-14: session-id 1203 received LOCK message
2026/03/13 10:04:02.814049 MGMTD: [R80RW-J2ZXJ] FE-ADAPTER: fe_session_handle_lock: Got LOCK for DS:running for session-id 1203 from 'Unknown-FD-14'
2026/03/13 10:04:02.814050 MGMTD: [WX5H7-YFAEM] DS: mgmt_ds_lock: LOCK on DS:running for session-id 1203
2026/03/13 10:04:02.814050 MGMTD: [ZW0E2-TDBY4] FE-ADAPTER: mgmt_fe_session_write_lock_ds: Write-Locked the DS:running for session-id: 1203 from Unknown-FD-14
2026/03/13 10:04:02.814050 MGMTD: [JTE36-YSQRX] FE-ADAPTER: fe_session_send_lock_reply: Sending lock-reply from adapter Unknown-FD-14 on session-id 1203 req-id 2 datastore 1 lock 1 scok 1
2026/03/13 10:04:02.814051 MGMTD: [SQ2SQ-FRHPJ] FE-ADAPTER-CONN: msg_conn_send_msg: SC send: depth 1 msg: 0x5e3fc64f17d0
2026/03/13 10:04:02.814051 MGMTD: [MJMW0-D05WX] FE-CLIENT: fe_client_handle_native_msg: Got native message for session-id 1203
2026/03/13 10:04:02.814052 MGMTD: [V7PD2-AA12D] FE-CLIENT: mgmt_fe_find_session_by_session_id: Found session of client-id 203 using session-id 1203
2026/03/13 10:04:02.814052 MGMTD: [VB6QX-DXMC1] FE-CLIENT: fe_client_pop_sent_msg: Popping sent message for client vty-mgmtd-2805038 session-id 1203 req-id 2
2026/03/13 10:04:02.814052 MGMTD: [P3YQK-NFNKZ] FE-CLIENT: vty_mgmt_handle_lock_ds_reply: Locked DS 1 successfully
2026/03/13 10:04:02.814053 MGMTD: [G1C9T-5VM0W] FE-ADAPTER-CONN: msg_conn_send_msg: SC return from depth: 0 msg: 0x5e3fc64f17d0
2026/03/13 10:04:02.814053 MGMTD: [G1C9T-5VM0W] FE-client: msg_conn_send_msg: SC return from depth: 0 msg: 0x5e3fc64c9870
2026/03/13 10:04:02.814127 MGMTD: [M7Q4P-46WDR] vty[19]@(config)# XFRR_start_configuration
2026/03/13 10:04:02.814297 MGMTD: [M7Q4P-46WDR] vty[19]@(config)# router-id 1.2.3.4

2026/03/13 10:04:02.814323 ZEBRA: [M7Q4P-46WDR] vty[39]@> enable
2026/03/13 10:04:02.814432 MGMTD: [M7Q4P-46WDR] vty[19]@(config)# ip table range 2 3

2026/03/13 10:04:02.814568 MGMTD: [M7Q4P-46WDR] vty[19]@(config)# XFRR_end_configuration
2026/03/13 10:04:02.814585 MGMTD: [VTVCM-Y2NW3] Configuration Read in Took: 00:00:00
2026/03/13 10:04:02.814586 MGMTD: [G6NKK-8C6DV] end_config: VTY:0x5e3fc64db9b0, pending SET-CFG: 2
2026/03/13 10:04:02.814587 MGMTD: [JPCR5-KD8VP] FE-CLIENT: mgmt_fe_send_commit_req: Sending COMMIT message for src: candidate dst: running session-id 1203 action: apply unlock: 0
2026/03/13 10:04:02.814591 MGMTD: [T6SA5-BXZ6S] FE-client: mgmt_msg_send_msg: Sending native msg sess/txn-id 1203 req-id 3 code 21

Notice that it is missing the allow-external-route-update from the XFRR_start_configuration to XFRR_end_configuration lines.

Version

master

How to reproduce

Run test_config.py in parallel:

sudo -E python3 -m pytest -s -vv -n 70 --dist=each ./test_config.py

Notice that PR #21127 is being used for my testing. The test itself is a bit too aggressive in looking for answers in a heavily loaded system. I was getting lots of db is locked failure messages and additionally the test was not giving a loaded system time to finish handling the state change( a great example is the addition of static routes, that we timed out in like .2 seconds looking for them)

Expected behavior

Command should not be lost

Actual behavior

Command is lost

Additional context

I like Llamas

Checklist

  • I have searched the open issues for this bug.
  • I have not included sensitive information in this report.

Metadata

Metadata

Assignees

Labels

triageNeeds further investigation

Type

No type

Projects

No projects

Milestone

No milestone

Relationships

None yet

Development

No branches or pull requests

Issue actions