Two MX204s are seeing an issue with Active Lease Query (ALQ) synchronization with DHCP Relay. The MXs are directly connected and peer for both DHCPv4 and DHCPV6 relay within a routing-instance:
forwarding-options {
dhcp-relay {
dhcpv6 {
overrides {
client-negotiation-match incoming-interface;
delete-binding-on-renegotiation;
}
forward-snooped-clients all-interfaces;
group dhcpv6-server {
active-server-group dhcpv6-relay;
authentication {
username-include {
domain-name dhcpv6;
user-prefix mx01;
interface-name;
dynamic-profile l3-profile-BNG-Users;
interface demux0.0;
relay-agent-interface-id;
relay-agent-remote-id;
server-group {
dhcpv6-relay {
2001:db8::4;
bulk-leasequery {
attempts 10;
active-leasequery {
peer-address {
2001:db8::2;
always-write-option-82;
client-discover-match incoming-interface;
relay-option-82 {
circuit-id {
use-interface-description logical;
server-id-override;
10.98.207.132;
group dhcp-server {
active-server-group dhcp-relay;
domain-name dhcpv4;
trust-option-82;
10.98.192.2;
timeout 60;
idle-timeout 60;
With DHCPv4 and DHCPv4/DHCPv6 dual stack subscribers:
user@mx01> show subscribers summary all
Subscribers by State
Init: 2
Active: 8103
Total: 8105
Subscribers by Client Type
DHCP: 4868
VLAN: 3237
Subscribers by LS:RI
default:BNG-Users: 8105
ALQ peering is loopback to loopback (10.98.192.1 <--> 10.98.192.2). A check of the TCP connections shows it go up and back down:
user@mx01> show system connections | match \.67
Jul 11 14:37:35
tcp4 0 0 *.67 *.* LISTEN
udp4 23706 0 *.67 *.*
udp6 0 0 *.6784 *.*
udp4 0 0 *.6784 *.*
udp46 0 0 *.674 *.*
udp 0 0 0.67 0.*
Jul 11 14:37:38
tcp4 0 0 10.98.192.1.67 10.98.192.2.57012 ESTABLISHED
Jul 11 14:37:41
---(refreshed at 2024-07-11 14:37:54 UTC)---
ALQ statistics for the peer show that the number of bindings increments for a bit, then stalls:
user@mx01> show dhcp relay active-leasequery statistics peer 10.98.192.2 routing-instance BNG-Users
Jul 11 14:59:20
user@mx01> ...statistics peer 10.98.192.2 routing-instance BNG-Users | refresh 1
Jul 11 14:59:25
---(refreshed at 2024-07-11 14:59:25 UTC)---
---(refreshed at 2024-07-11 14:59:26 UTC)---
---(refreshed at 2024-07-11 14:59:27 UTC)---
---(refreshed at 2024-07-11 14:59:28 UTC)---
---(refreshed at 2024-07-11 14:59:29 UTC)---
---(refreshed at 2024-07-11 14:59:30 UTC)---
---(refreshed at 2024-07-11 14:59:31 UTC)---
---(refreshed at 2024-07-11 14:59:32 UTC)---
---(refreshed at 2024-07-11 14:59:33 UTC)---
---(refreshed at 2024-07-11 14:59:34 UTC)---
---(refreshed at 2024-07-11 14:59:35 UTC)---
---(refreshed at 2024-07-11 14:59:36 UTC)---
---(refreshed at 2024-07-11 14:59:37 UTC)---
---(refreshed at 2024-07-11 14:59:38 UTC)---
---(refreshed at 2024-07-11 14:59:39 UTC)---
peer : 10.98.192.2
Topology-Discover Configured : No
State : Connected
Bindings Sent : 385
Bindings Received : 382
Bindings Installed Successfully : 3331
Bindings Failed to install : 1
Last Synchronization Time : 2024-07-11 14:59:39 UTC
ALQ Transmit Buffer count : 65535
Max Leasequery Transmit Rate : 100
Local Interface count : 0
Remote Interface count : 0
---(refreshed at 2024-07-11 14:59:40 UTC)---
Bindings Sent : 745
Last Synchronization Time : 2024-07-11 14:59:40 UTC
---(refreshed at 2024-07-11 14:59:41 UTC)---
If logs for JDHCPD are checked, they will show state is initially synched:
Jul 11 14:57:06.162855 [MSTR][DEBUG] jdhcpd_create_and_send_alq_topology_discover_message_on: Starting ALQ with neighbor by address.
Jul 11 14:57:06.163261 [MSTR][DEBUG] jdhcpd_relay_bulk_leasequery_server_retry_timer_start: ALQ: Start one short time start for retries (10)
Jul 11 14:57:06.163281 [MSTR][NOTE] jdhcpd_tcp_start_client: TCP-C: Initializing TCP ALQ client
Jul 11 14:57:06.163450 [MSTR][INFO] jdhcpd_connect_and_send_request_to_blq_server: ALQ:Requested tcp connections 1 Max TCP connections 3, blq_server_info(5439628)
Jul 11 14:57:06.163619 [MSTR][DEBUG] dhcpv6_is_alq_topology_discover_message: ALQ: is topologydiscover 0
Jul 11 14:57:06.163698 [MSTR][DEBUG] dhcpv6_add_alq_vendor_specific_info: ALQ: invalid Input, while constructing vendor option. opt_ptr = 0xffffd058, interafce_data = 0x0, interface_data_len = 0, total_len = 0xffffd044
Jul 11 14:57:06.163894 [MSTR][DEBUG] jdhcpd_relay_bulk_leasequery_server_retry_timer_start: ALQ: Start one short time start for retries (10)
Jul 11 14:57:06.163924 [MSTR][DEBUG] dhcpv6_leasequery_add_start_time_to_packet: ALQ: DHCPV6_OPTION_LQ_START_TIME Add called start_time=0
Jul 11 14:57:06.164169 [MSTR][INFO] jdhcpd_connect_and_send_request_to_blq_server: ALQ:Requested tcp connections 2 Max TCP connections 3, blq_server_info(543967c)
Jul 11 14:57:06.164334 [MSTR][DEBUG] jdhcpd_create_and_send_alq_topology_discover_message_on: Starting ALQ with neighbor by address.
Jul 11 14:57:06.164587 [MSTR][DEBUG] jdhcpd_relay_bulk_leasequery_server_retry_timer_start: ALQ: Start one short time start for retries (10)
Jul 11 14:57:06.164607 [MSTR][NOTE] jdhcpd_tcp_start_client: TCP-C: Initializing TCP ALQ client
Jul 11 14:57:12.391058 [MSTR][INFO] [default:default][RLY][INET6][ps420.0] safd_blq_conn_info_get: safd(541a500), safd->blq_server_info(0)
Jul 11 14:57:12.391076 [MSTR][DEBUG][default:BNG-Users][RLY][INET6][lsi.0] dhcpv6_validate_leasequery_reply_msgs: dpv6_type 17 pkt(553d100), tcp_conn(e53d000), blq_srvr_info(543967c) Packet xid 0x(5089d6) safd xid 0x(0) blq_info xid 0x5089d6
Jul 11 14:57:12.391104 [MSTR][DEBUG] dhcpv6_packet_handle: ALQ: Updating leasequery packet
Jul 11 14:57:12.391126 [MSTR][DEBUG] jdhcpd_is_alq_peer_address_configured: Peer address configured for relay. default.BNG-Users
Jul 11 14:57:12.391158 [MSTR][DEBUG] dhcpv6_extract_alq_interface_info_from_option_17: received vendor option 13.
Jul 11 14:57:12.391177 [MSTR][INFO] [default:BNG-Users][RLY][INET6][lsi.0] dhcpv6_packet_handle: Leasequery Client - Interface name in interface_id option is ps420:20-1566
Jul 11 14:57:12.391196 [MSTR][DEBUG] sus_name_get: Extracted ifd_name = ps420
Jul 11 14:57:12.391213 [MSTR][INFO] [default:BNG-Users][RLY][INET6][lsi.0] dhcpv6_packet_handle: Leasequery Client - Interface ps420:20-1566 exists
Jul 11 14:57:12.391231 [MSTR][INFO] [default:BNG-Users][RLY][INET6][demux0.3221226275] dhcpv6_packet_handle: leasequery client - Using interface from interface_id, LS/RI default/BNG-Users, ifindex 536871745, if demux0.3221226275, iflname demux0.3221226275
Jul 11 14:57:12.391250 [MSTR][DEBUG] client_key_compose_dhcpv6: Successfully composed CK_TYPE_V6_CLIENT_ID (3) client key object.
Jul 11 14:57:12.391270 [MSTR][DEBUG] client_key_print: key_type CK_TYPE_V6_CLIENT_ID (3): v6_Clientid_len 10, 00 03 00 01 20 be cd 65 59 c1
Jul 11 14:57:12.391290 [MSTR][DEBUG] client_key_print: key_type CK_TYPE_V6_CLIENT_ID (3): ifindex 0: v6_Clientid_len 10, 00 03 00 01 20 be cd 65 59 c1
Jul 11 14:57:12.391307 [MSTR][DEBUG] client_key_print: key_type CK_TYPE_V6_CLIENT_ID (3) other fields: subnet 0.0.0.0, ifindex 0, opt82_len 0, -
Jul 11 14:57:12.391332 [MSTR][DEBUG][default:BNG-Users][RLY][INET6][demux0.3221226275][SID=6298] dhcpv6_find_client_from_incoming_pdu: Found client 68500 in default:BNG-Users INET6 client table entry
Jul 11 14:57:12.391352 [MSTR][DEBUG][default:BNG-Users][RLY][INET6][demux0.3221226275][SID=6298] dhcpv6_packet_handle: RECEIVE DHCPV6-LEASEQUERY-DATA: stats_safd 0xc0a7e00 demux0.3221226275, incoming_safd 0xc0a7e00 demux0.3221226275, demux 0x0 , safd 0xc0a7e00 demux0.3221226275
Jul 11 14:57:12.391375 [MSTR][DEBUG] jdhcpd_create_short_cycle_protection_key: Added RI(BNG-Users) name to short cycle protection key
Jul 11 14:57:12.391392 [MSTR][DEBUG] jdhcpd_create_short_cycle_protection_key: Added V6 DUID to short cycle protection key. key_len(10)
Jul 11 14:57:12.391407 [MSTR][DEBUG] jdhcpd_create_short_cycle_protection_key: Key created , keylen 23, strlen 0
Jul 11 14:57:12.391436 [MSTR][INFO] [default:BNG-Users][RLY][INET6][demux0.3221226275][SID=6298] dhcpv6_packet_handle: Recv LQ/BLQ reply with timestamp 2024-07-11 09:13:47 UTC, client exists in state DHCPV6_RELAY_STATE_BOUND with timestamp 2024-07-01 19:13:40 UTC.
Then, the daemon restarts:
Jul 11 14:57:21.390532 [MSTR][DEBUG] jdhcpd_process_global_cfg: Persistent-storage not set
Jul 11 14:57:21.390549 [MSTR][INFO] jdhcpd_persistent_db_set_filename: New file name = jdhcp_client_data, Old file name =
Jul 11 14:57:21.390565 [MSTR][INFO] jdhcpd_persistent_db_set_filename: New file(/var/preserve/jdhcp_client_data) and old file() are different
Jul 11 14:57:21.390597 [MSTR][INFO] jdhcpd_persistent_db_set_filename: fopen of file (/var/preserve/jdhcp_client_data) successful(duplicate)
Jul 11 14:57:21.390618 [MSTR][INFO] jdhcpd_persistent_db_set_backup_time_interval: New backup time received:24, backup_interval:24 backup_time_expired:0
Jul 11 14:57:21.390649 [MSTR][INFO] jdhcpd_process_global_cfg: got accept-max-tcp-connections 5
Jul 11 14:57:21.390667 [MSTR][INFO] jdhcpd_process_global_cfg: got request-max-tcp-connections 3
Jul 11 14:57:21.390684 [MSTR][INFO] jdhcpd_process_global_cfg: got max-leasequery-reply-packet-retries 20
Jul 11 14:57:21.390701 [MSTR][INFO] jdhcpd_process_global_cfg: got leasequery-reply-packet-retry-timer 20
Jul 11 14:57:21.390728 [MSTR][INFO] jdhcpd_process_global_cfg: got max-leasequery-reply-packet-process 500
Jul 11 14:57:21.390745 [MSTR][INFO] jdhcpd_process_global_cfg: no max-clients-supported
Jul 11 14:57:21.391310 [MSTR][DEBUG] jdhcpd_cfg_top_present_cb: Top present check action 2 app 0 RC default/BNG-Users
Jul 11 14:57:21.391334 [MSTR][DEBUG] jdhcpd_cfg_top_present_cb: Top cfg present check, skipping INET RC default/BNG-Users, NOT found
Due to a core dump:
qnc-css-lnx02:/volume/CSdata/sflorence/2024-0709-201568/Jul11/cr02-var/var/log> cat messages | grep "Jul 11 14:57:"
Jul 11 14:57:03 mx01 jade[83981]: JADE_AUTH_SUCCESS: Authentication succeded for user 'oxidized' from host '10.134.65.62'
Jul 11 14:57:20 mx01 jlaunchd[30983]: dhcp-service (PID 82810) terminated by signal number 11. Core dumped!
Jul 11 14:57:20 mx01 jlaunchd[30983]: Registered PID 84297((null)): exec_command
Jul 11 14:57:20 mx01 jlaunchd[30983]: Dump Command: /bin/sh (PID 84297) started
Jul 11 14:57:20 mx01 jlaunchd[30983]: Registered PID 84298(dhcp-service): exec_command
Jul 11 14:57:20 mx01 jlaunchd[30983]: dhcp-service (PID 84298) started
Jul 11 14:57:20 mx01 jlaunchd[30983]: Registered PID 84298(dhcp-service): new process
Jul 11 14:57:21 mx01 jdhcpd[84298]: dc=0 ts=1 cd=5 rmin=30 rn=30 ri=10 lc=0 la=90 cc=0 rc=0 ct=250000 nc=0 ml=409600 ns=409600 ss=1720709841
Jul 11 14:57:26 mx01 dumpd[84719]: Core and context for jdhcpd saved in /var/tmp/jdhcpd.core-tarball.4.tgz
Jul 11 14:57:27 mx01 mgd[82837]: UI_CHILD_SIGNALED: Child received signal: PID 82839, signal Terminated, command='/usr/libexec/ui/show-support'
Same pattern with every synch:
Jul 11 14:45:48 mx01 jlaunchd[30983]: dhcp-service (PID 69256) terminated by signal number 11. Core dumped!
Jul 11 14:46:43 mx01 jlaunchd[30983]: dhcp-service (PID 70292) terminated by signal number 11. Core dumped!
Jul 11 14:47:36 mx01 jlaunchd[30983]: dhcp-service (PID 71292) terminated by signal number 11. Core dumped!
Jul 11 14:48:29 mx01 jlaunchd[30983]: dhcp-service (PID 72336) terminated by signal number 11. Core dumped!
Jul 11 14:49:23 mx01 jlaunchd[30983]: dhcp-service (PID 73571) terminated by signal number 11. Core dumped!
Jul 11 14:50:17 mx01 jlaunchd[30983]: dhcp-service (PID 74631) terminated by signal number 11. Core dumped!
Jul 11 14:51:09 mx01 jlaunchd[30983]: dhcp-service (PID 75611) terminated by signal number 11. Core dumped!
Jul 11 14:52:00 mx01 jlaunchd[30983]: dhcp-service (PID 76637) terminated by signal number 11. Core dumped!
Jul 11 14:52:52 mx01 jlaunchd[30983]: dhcp-service (PID 77688) terminated by signal number 11. Core dumped!
Jul 11 14:53:46 mx01 jlaunchd[30983]: dhcp-service (PID 78703) terminated by signal number 11. Core dumped!
Problems is tracked and resolved via PR1818919:
https://prsearch.juniper.net/PR1818919