normally mpd should delete the connected route when the pppoe session is terminated, but in my case we have a "ghost" route still present and when a new pppoe connection is requesting 10.128.32.4 which is supposed to be available, we have an error from mpd :
Mar 20 09:00:02 bng1 mpd[77832]: [BT1517-167] IPCP: state change Ack-Rcvd --> Opened
Mar 20 09:00:02 bng1 mpd[77832]: [BT1517-167] IPCP: LayerUp
Mar 20 09:00:02 bng1 mpd[77832]: [BT1517-167] 10.128.35.254 -> 10.128.32.4
Mar 20 09:00:02 bng1 mpd[77832]: [BT1517-167] IFACE: Adding IPv4 address to ng142 failed: File exists
Mar 20 09:00:02 bng1 mpd[77832]: [BT1517-167] IFACE: IfaceChangeAddr() error, closing IPCP
Mar 20 09:00:02 bng1 mpd[77832]: [BT1517-167] IPCP: parameter negotiation failed
Mar 20 09:00:02 bng1 mpd[77832]: [BT1517-167] IPCP: state change Opened --> Stopping
Mar 20 09:00:02 bng1 mpd[77832]: [BT1517-167] IPCP: SendTerminateReq #2
Mar 20 09:00:02 bng1 mpd[77832]: [BT1517-167] IPCP: LayerDown
Mar 20 09:00:02 bng1 mpd[77832]: [BT1517-167] IFACE: Removing IPv4 address from ng142 failed: Can't assign requested address
Are you able to reproduce this using "clean" environment? That is: take a system having no such bad route yet, run "script route.log route -n monitor", reproduce the problem, post route.log
Last edit: Eugene Grosbein 2025-08-02
If you would like to refer to this comment somewhere else in this project, copy and paste the following link:
Hello,
normally mpd should delete the connected route when the pppoe session is terminated, but in my case we have a "ghost" route still present and when a new pppoe connection is requesting 10.128.32.4 which is supposed to be available, we have an error from mpd :
Mar 20 09:00:02 bng1 mpd[77832]: [BT1517-167] IPCP: state change Ack-Rcvd --> Opened
Mar 20 09:00:02 bng1 mpd[77832]: [BT1517-167] IPCP: LayerUp
Mar 20 09:00:02 bng1 mpd[77832]: [BT1517-167] 10.128.35.254 -> 10.128.32.4
Mar 20 09:00:02 bng1 mpd[77832]: [BT1517-167] IFACE: Adding IPv4 address to ng142 failed: File exists
Mar 20 09:00:02 bng1 mpd[77832]: [BT1517-167] IFACE: IfaceChangeAddr() error, closing IPCP
Mar 20 09:00:02 bng1 mpd[77832]: [BT1517-167] IPCP: parameter negotiation failed
Mar 20 09:00:02 bng1 mpd[77832]: [BT1517-167] IPCP: state change Opened --> Stopping
Mar 20 09:00:02 bng1 mpd[77832]: [BT1517-167] IPCP: SendTerminateReq #2
Mar 20 09:00:02 bng1 mpd[77832]: [BT1517-167] IPCP: LayerDown
Mar 20 09:00:02 bng1 mpd[77832]: [BT1517-167] IFACE: Removing IPv4 address from ng142 failed: Can't assign requested address
I cannot remove this "bug" route :
root@bng1:/var/log # route -n get 10.128.32.4
route to: 10.128.32.4
destination: 10.128.32.4
fib: 0
interface: if#130
flags: <up,host,done,pinned>
recvpipe sendpipe ssthresh rtt,msec mtu weight expire
0 0 0 0 0 1 0</up,host,done,pinned>
root@bng1:/var/log # route delete -host 10.128.32.4
delete host 10.128.32.4 fib 0: gateway uses the same route
I think rebooting would solve the issue but I prefer avoid it.
I am on FreeBSD 14.2
mpd5-5.9.16
Regards.
This is kernel bug (not mpd bug) already fixed in stable/14 branch:
https://bugs.freebsd.org/bugzilla/show_bug.cgi?id=279988
Either switch to 14.2-STABLE or apply the fix manually to the 14.2-RELEASE kernel or wait for 14.3-RELEASE.
This bug looks similar to the previous thread "IFACE: Adding IPv4 address to ng0 failed: File exists + iBGP or OSPF"
but I am on freeBSD 14.2, it should be fixed....
I also posted in FreeBSF Forum :
https://forums.freebsd.org/threads/cannot-delete-ip-route.97263/#post-694914
Last edit: Yannick C 2025-03-25
Hi @dadv,
any update for us please ?
Cheers?
Also, 13.5-RELEASE contains the fix, too. So you may find that version useful.
Hi Eugene,
We are on FreeBSD 14.3-RELEASE and the bug is still present.
Which options do we have without moving to STABLE versions ?
Thanks in advance for your advice.
Are you able to reproduce this using "clean" environment? That is: take a system having no such bad route yet, run "script route.log route -n monitor", reproduce the problem, post route.log
Last edit: Eugene Grosbein 2025-08-02
Hi Eugene,
thank you for replying and your support.
The script is running, we are waitinf for the next route event.
Regards.
Hi Eugene,
the issue just happened, here are the grabbed log files. Please let us know your thoughts.
Regards.
Hello Eugene,
it happened again :
route_monitor.log
03:01:03.057 PID 0 add/repl iface iface#225 ng192 admin DOWN oper DOWN mtu 1500
03:01:03.058 PID 0 add/repl iface iface#225 ng192 admin DOWN oper DOWN mtu 1492
03:01:03.078 PID 0 add/repl iface iface#225 ng192 admin UP oper UP mtu 1492
03:01:03.078 PID 0 add/repl addr 10.129.39.254/32 -> 10.129.36.24 iface ng192
03:01:03.078 PID 0 add/repl addr 10.129.39.254/32 -> 10.129.36.24 iface ng192
03:01:03.078 PID 0 add/repl iface iface#225 ng192 admin UP oper UP mtu 1492
03:01:03.102 PID 0 add/repl iface iface#225 ng192 admin UP oper UP mtu 1500
03:01:03.104 PID 0 add/repl iface iface#225 ng192 admin DOWN oper DOWN mtu 1500
03:01:03.104 PID 0 delete iface iface#225 ng192 admin DOWN oper DOWN mtu 1500
mpd.log
Oct 17 03:01:03 bng2 mpd[3701]: [LT1519-263] RADIUS: Authenticating user '2000020682626@voda'
Oct 17 03:01:03 bng2 mpd[3701]: [LT1519-263] RADIUS: Rec'd RAD_ACCESS_ACCEPT for user '2000020682626@voda'
Oct 17 03:01:03 bng2 mpd[3701]: [LT1519-263] AUTH: RADIUS returned: authenticated
Oct 17 03:01:03 bng2 mpd[3701]: [LT1519-263] CHAP: Auth return status: authenticated
Oct 17 03:01:03 bng2 mpd[3701]: [LT1519-263] CHAP: Reply message: Welcome
Oct 17 03:01:03 bng2 mpd[3701]: [LT1519-263] CHAP: sending SUCCESS #1 len: 11
Oct 17 03:01:03 bng2 mpd[3701]: [LT1519-263] LCP: authorization successful
Oct 17 03:01:03 bng2 mpd[3701]: [LT1519-263] Link: Matched action 'bundle "BT1519" ""'
Oct 17 03:01:03 bng2 mpd[3701]: [LT1519-263] Creating new bundle using template "BT1519".
Oct 17 03:01:03 bng2 mpd[3701]: [BT1519-218] Bundle: Interface ng192 created
Oct 17 03:01:03 bng2 mpd[3701]: [LT1519-263] Link: Join bundle "BT1519-218"
Oct 17 03:01:03 bng2 mpd[3701]: [BT1519-218] Bundle: Status update: up 1 link, total bandwidth 64000 bps
Oct 17 03:01:03 bng2 mpd[3701]: [BT1519-218] IPCP: Open event
Oct 17 03:01:03 bng2 mpd[3701]: [BT1519-218] IPCP: state change Initial --> Starting
Oct 17 03:01:03 bng2 mpd[3701]: [BT1519-218] IPCP: LayerStart
Oct 17 03:01:03 bng2 mpd[3701]: [BT1519-218] IPCP: Up event
Oct 17 03:01:03 bng2 mpd[3701]: [BT1519-218] IPCP: Got IP 10.129.36.24 from pool "pool_1519" for peer
Oct 17 03:01:03 bng2 mpd[3701]: [BT1519-218] IPCP: state change Starting --> Req-Sent
Oct 17 03:01:03 bng2 mpd[3701]: [BT1519-218] IPCP: SendConfigReq #1
Oct 17 03:01:03 bng2 mpd[3701]: [BT1519-218] IPADDR 10.129.39.254
Oct 17 03:01:03 bng2 mpd[3701]: [LT1519-263] RADIUS: Accounting user '2000020682626@voda' (Type: 1)
Oct 17 03:01:03 bng2 mpd[3701]: [BT1519-218] IPCP: rec'd Configure Request #1 (Req-Sent)
Oct 17 03:01:03 bng2 mpd[3701]: [BT1519-218] IPADDR 0.0.0.0
Oct 17 03:01:03 bng2 mpd[3701]: [BT1519-218] NAKing with 10.129.36.24
Oct 17 03:01:03 bng2 mpd[3701]: [BT1519-218] COMPPROTO VJCOMP, 16 comp. channels, allow comp-cid
Oct 17 03:01:03 bng2 mpd[3701]: [BT1519-218] PRIDNS 0.0.0.0
Oct 17 03:01:03 bng2 mpd[3701]: [BT1519-218] NAKing with 103.129.122.180
Oct 17 03:01:03 bng2 mpd[3701]: [BT1519-218] SECDNS 0.0.0.0
Oct 17 03:01:03 bng2 mpd[3701]: [BT1519-218] NAKing with 103.129.123.180
Oct 17 03:01:03 bng2 mpd[3701]: [BT1519-218] IPCP: SendConfigRej #1
Oct 17 03:01:03 bng2 mpd[3701]: [BT1519-218] COMPPROTO VJCOMP, 16 comp. channels, allow comp-cid
Oct 17 03:01:03 bng2 mpd[3701]: [BT1519-218] IPCP: rec'd Configure Ack #1 (Req-Sent)
Oct 17 03:01:03 bng2 mpd[3701]: [BT1519-218] IPADDR 10.129.39.254
Oct 17 03:01:03 bng2 mpd[3701]: [BT1519-218] IPCP: state change Req-Sent --> Ack-Rcvd
Oct 17 03:01:03 bng2 mpd[3701]: [LT1519-263] RADIUS: Rec'd RAD_ACCOUNTING_RESPONSE for user '2000020682626@voda'
Oct 17 03:01:03 bng2 mpd[3701]: [BT1519-218] IPCP: rec'd Configure Request #2 (Ack-Rcvd)
Oct 17 03:01:03 bng2 mpd[3701]: [BT1519-218] IPADDR 0.0.0.0
Oct 17 03:01:03 bng2 mpd[3701]: [BT1519-218] NAKing with 10.129.36.24
Oct 17 03:01:03 bng2 mpd[3701]: [BT1519-218] PRIDNS 0.0.0.0
Oct 17 03:01:03 bng2 mpd[3701]: [BT1519-218] NAKing with 103.129.122.180
Oct 17 03:01:03 bng2 mpd[3701]: [BT1519-218] SECDNS 0.0.0.0
Oct 17 03:01:03 bng2 mpd[3701]: [BT1519-218] NAKing with 103.129.123.180
Oct 17 03:01:03 bng2 mpd[3701]: [BT1519-218] IPCP: SendConfigNak #2
Oct 17 03:01:03 bng2 mpd[3701]: [BT1519-218] IPADDR 10.129.36.24
Oct 17 03:01:03 bng2 mpd[3701]: [BT1519-218] PRIDNS 103.129.122.180
Oct 17 03:01:03 bng2 mpd[3701]: [BT1519-218] SECDNS 103.129.123.180
Oct 17 03:01:03 bng2 mpd[3701]: [BT1519-218] IPCP: rec'd Configure Request #3 (Ack-Rcvd)
Oct 17 03:01:03 bng2 mpd[3701]: [BT1519-218] IPADDR 10.129.36.24
Oct 17 03:01:03 bng2 mpd[3701]: [BT1519-218] 10.129.36.24 is OK
Oct 17 03:01:03 bng2 mpd[3701]: [BT1519-218] PRIDNS 103.129.122.180
Oct 17 03:01:03 bng2 mpd[3701]: [BT1519-218] SECDNS 103.129.123.180
Oct 17 03:01:03 bng2 mpd[3701]: [BT1519-218] IPCP: SendConfigAck #3
Oct 17 03:01:03 bng2 mpd[3701]: [BT1519-218] IPADDR 10.129.36.24
Oct 17 03:01:03 bng2 mpd[3701]: [BT1519-218] PRIDNS 103.129.122.180
Oct 17 03:01:03 bng2 mpd[3701]: [BT1519-218] SECDNS 103.129.123.180
Oct 17 03:01:03 bng2 mpd[3701]: [BT1519-218] IPCP: state change Ack-Rcvd --> Opened
Oct 17 03:01:03 bng2 mpd[3701]: [BT1519-218] IPCP: LayerUp
Oct 17 03:01:03 bng2 mpd[3701]: [BT1519-218] 10.129.39.254 -> 10.129.36.24
Oct 17 03:01:03 bng2 mpd[3701]: [BT1519-218] IFACE: Adding IPv4 address to ng192 failed: File exists
Oct 17 03:01:03 bng2 mpd[3701]: [BT1519-218] IFACE: IfaceChangeAddr() error, closing IPCP
Oct 17 03:01:03 bng2 mpd[3701]: [BT1519-218] IPCP: parameter negotiation failed
Oct 17 03:01:03 bng2 mpd[3701]: [BT1519-218] IPCP: state change Opened --> Stopping
Oct 17 03:01:03 bng2 mpd[3701]: [BT1519-218] IPCP: SendTerminateReq #2
Oct 17 03:01:03 bng2 mpd[3701]: [BT1519-218] IPCP: LayerDown
Oct 17 03:01:03 bng2 mpd[3701]: [BT1519-218] IFACE: Removing IPv4 address from ng192 failed: Can't assign requested address
Oct 17 03:01:03 bng2 mpd[3701]: [BT1519-218] IPCP: rec'd Terminate Ack #2 (Stopping)
Oct 17 03:01:03 bng2 mpd[3701]: [BT1519-218] IPCP: state change Stopping --> Stopped
Oct 17 03:01:03 bng2 mpd[3701]: [BT1519-218] IPCP: LayerFinish
Oct 17 03:01:03 bng2 mpd[3701]: [BT1519-218] Bundle: No NCPs left. Closing links...
Oct 17 03:01:03 bng2 mpd[3701]: [BT1519-218] Bundle: closing link "LT1519-263"...
Oct 17 03:01:03 bng2 mpd[3701]: [LT1519-263] Link: CLOSE event
Oct 17 03:01:03 bng2 mpd[3701]: [LT1519-263] LCP: Close event
Oct 17 03:01:03 bng2 mpd[3701]: [LT1519-263] LCP: state change Opened --> Closing
Oct 17 03:01:03 bng2 mpd[3701]: [LT1519-263] Link: Leave bundle "BT1519-218"
Oct 17 03:01:03 bng2 mpd[3701]: [LT1519-263] RADIUS: Accounting user '2000020682626@voda' (Type: 2)
Oct 17 03:01:03 bng2 mpd[3701]: [BT1519-218] Bundle: Status update: up 0 links, total bandwidth 9600 bps
Oct 17 03:01:03 bng2 mpd[3701]: [BT1519-218] IPCP: Close event
Oct 17 03:01:03 bng2 mpd[3701]: [BT1519-218] IPCP: state change Stopped --> Closed
Oct 17 03:01:03 bng2 mpd[3701]: [BT1519-218] IPCP: Down event
Oct 17 03:01:03 bng2 mpd[3701]: [BT1519-218] IPCP: state change Closed --> Initial
Oct 17 03:01:03 bng2 mpd[3701]: [BT1519-218] Bundle: Shutdown
Oct 17 03:01:03 bng2 mpd[3701]: [LT1519-263] LCP: SendTerminateReq #3
Oct 17 03:01:03 bng2 mpd[3701]: [LT1519-263] LCP: LayerDown
Hi @Eugene,
could you kindly check this ?
Regards.