Hi Everyone,
I've been encountering a persistent issue with my ACCEL-PPP setup and would appreciate any insights or suggestions. Here’s the problem:
When an L2TP session is terminated or drops, it appears that the IP address assigned to that session is not removed from the LNS. This leads to the following error being logged repeatedly in the ACCEL-PPP log:
error: l2tpXXX: failed to set IPv4 address: File exists
This becomes a significant issue in my network configuration where I have multiple LNS servers running ACCEL-PPP. When an incoming L2TP session is redirected to a different LNS, the previous LNS still holds onto the IP address as a kernel route. This causes conflicts because the kernel routes are being redistributed, and the stale route creates a misrouting of traffic.
I suspect I have to enable something within the configuration.
Any Ideas please?
Failed to set IPv4 address: File exists
Re: Failed to set IPv4 address: File exists
Hi @dimka88,
Further to my last post, I believe I have a serious issue with interfaces not being deleted correctly and would appreciate your input.
I am redistributing kernel routes. Please see examples from my frr.log and accel-ppp.log. It looks like when an L2TP session drops, it is not removed correctly from the kernel.
The same user then appears on another Accel-PPP server or the interface is assigned to another user on the same server, resulting in routing issues.
In my Accel-PPP config, I have check-ip=1 to check if the IP is already assigned to another PPP interface, and I've set ifname=l2tp0%d.
Please see the excerpts from my Accel-PPP and FRR logs below.
I am using the latest kernel 6.9.2, and I've read that Accel-PPP uses iputils to remove routes.
Can someone please tell me how to further diagnose this issue?
Why am I also now getting a nas-error/Unknown? Is this related to the failed attempt to set the IPv4 address? Is setting the ifname to l2tp0%d causing an issue with FRR?
Many Thanks,
accel-ppp.log
-----------------
error: l2tp017: failed to set IPv4 address: File exists
info: l2tp017: session started over l2tp session 8553-6068, 31579-62544
warn: l2tp017: radius: failed to add route 0.0.0.0/0 0.0.0.0 1
info: l2tp session 8553-6068, 31579-62544: CDN received from peer (result: 2, error: 0, message: "nas-error/Unknown"), disconnecting session
info: l2tp tunnel 28890-14945 (XXX.XXX.XXX.XXX:1701): new session 56213-40764 created following reception of ICRQ
info: ppp17: connect: ppp17 <--> l2tp(XXX.XXX.XXX.XXX:1701 session 28890-14945, 56213-40764)
info: ppp17: test01@test.com: authentication succeeded
error: l2tp017: failed to set IPv4 address: File exists
info: l2tp017: session started over l2tp session 28890-14945, 56213-40764
frr.log
--------
ZEBRA: [NXYS2-XRNQB][EC 100663305] interface l2tp019 vrf default(0) index 77 is still up while being deleted.
ZEBRA: [SK26S-R3N7Y][EC 100663305] interface rename detected on up interface: index 83 was renamed from l2tp022 to l2tp012, results are uncertain!
ZEBRA: [NXYS2-XRNQB][EC 100663305] interface l2tp022 vrf default(0) index 103 is still up while being deleted.
ZEBRA: [SK26S-R3N7Y][EC 100663305] interface rename detected on up interface: index 83 was renamed from l2tp022 to ppp22, results are uncertain!
ZEBRA: [NXYS2-XRNQB][EC 100663305] interface l2tp022 vrf default(0) index 103 is still up while being deleted.
ZEBRA: [SK26S-R3N7Y][EC 100663305] interface rename detected on up interface: index 81 was renamed from l2tp021 to l2tp017, results are uncertain!
.....
ZEBRA: [SK26S-R3N7Y][EC 100663305] interface rename detected on up interface: index 43 was renamed from l2tp07 to ppp7, results are uncertain!
ZEBRA: [NXYS2-XRNQB][EC 100663305] interface l2tp07 vrf default(0) index 43 is still up while being deleted.
ZEBRA: [SK26S-R3N7Y][EC 100663305] interface rename detected on up interface: index 51 was renamed from l2tp014 to ppp14, results are uncertain!
ZEBRA: [NXYS2-XRNQB][EC 100663305] interface l2tp014 vrf default(0) index 51 is still up while being deleted.
Further to my last post, I believe I have a serious issue with interfaces not being deleted correctly and would appreciate your input.
I am redistributing kernel routes. Please see examples from my frr.log and accel-ppp.log. It looks like when an L2TP session drops, it is not removed correctly from the kernel.
The same user then appears on another Accel-PPP server or the interface is assigned to another user on the same server, resulting in routing issues.
In my Accel-PPP config, I have check-ip=1 to check if the IP is already assigned to another PPP interface, and I've set ifname=l2tp0%d.
Please see the excerpts from my Accel-PPP and FRR logs below.
I am using the latest kernel 6.9.2, and I've read that Accel-PPP uses iputils to remove routes.
Can someone please tell me how to further diagnose this issue?
Why am I also now getting a nas-error/Unknown? Is this related to the failed attempt to set the IPv4 address? Is setting the ifname to l2tp0%d causing an issue with FRR?
Many Thanks,
accel-ppp.log
-----------------
error: l2tp017: failed to set IPv4 address: File exists
info: l2tp017: session started over l2tp session 8553-6068, 31579-62544
warn: l2tp017: radius: failed to add route 0.0.0.0/0 0.0.0.0 1
info: l2tp session 8553-6068, 31579-62544: CDN received from peer (result: 2, error: 0, message: "nas-error/Unknown"), disconnecting session
info: l2tp tunnel 28890-14945 (XXX.XXX.XXX.XXX:1701): new session 56213-40764 created following reception of ICRQ
info: ppp17: connect: ppp17 <--> l2tp(XXX.XXX.XXX.XXX:1701 session 28890-14945, 56213-40764)
info: ppp17: test01@test.com: authentication succeeded
error: l2tp017: failed to set IPv4 address: File exists
info: l2tp017: session started over l2tp session 28890-14945, 56213-40764
frr.log
--------
ZEBRA: [NXYS2-XRNQB][EC 100663305] interface l2tp019 vrf default(0) index 77 is still up while being deleted.
ZEBRA: [SK26S-R3N7Y][EC 100663305] interface rename detected on up interface: index 83 was renamed from l2tp022 to l2tp012, results are uncertain!
ZEBRA: [NXYS2-XRNQB][EC 100663305] interface l2tp022 vrf default(0) index 103 is still up while being deleted.
ZEBRA: [SK26S-R3N7Y][EC 100663305] interface rename detected on up interface: index 83 was renamed from l2tp022 to ppp22, results are uncertain!
ZEBRA: [NXYS2-XRNQB][EC 100663305] interface l2tp022 vrf default(0) index 103 is still up while being deleted.
ZEBRA: [SK26S-R3N7Y][EC 100663305] interface rename detected on up interface: index 81 was renamed from l2tp021 to l2tp017, results are uncertain!
.....
ZEBRA: [SK26S-R3N7Y][EC 100663305] interface rename detected on up interface: index 43 was renamed from l2tp07 to ppp7, results are uncertain!
ZEBRA: [NXYS2-XRNQB][EC 100663305] interface l2tp07 vrf default(0) index 43 is still up while being deleted.
ZEBRA: [SK26S-R3N7Y][EC 100663305] interface rename detected on up interface: index 51 was renamed from l2tp014 to ppp14, results are uncertain!
ZEBRA: [NXYS2-XRNQB][EC 100663305] interface l2tp014 vrf default(0) index 51 is still up while being deleted.
Re: Failed to set IPv4 address: File exists
Hi @tj-19, at first check Access-Accept, why you send Framed-Route 0.0.0.0/0 0.0.0.0 1?
As for "failed to set IPv4 address: File exists" it looks like sessions with this IP is not terminates in time. I propose you to play with [ppp] lcp params. Also, provide info how finished old sessions which IP trying to set for new session.
As for "failed to set IPv4 address: File exists" it looks like sessions with this IP is not terminates in time. I propose you to play with [ppp] lcp params. Also, provide info how finished old sessions which IP trying to set for new session.
Re: Failed to set IPv4 address: File exists
Hi @dimka88,
Thank you for your reply.
Regarding the Framed-Route, I moved to Accel-PPP from another platform where specifying a default route for each user was necessary.
Are you saying this is not needed in this case? I must admit I was confused when looking at the forum earlier because it seemed that the Framed-Route was only used for pushing IP blocks downstream of an active user. For example, if a user had the IP 10.10.30.28 and you wanted to route a /29 downstream of 10.10.30.28, would you use the Framed-Route for this? How would you specify this?
Regarding old sessions, this is the issue: it looks like the sessions are never dropped. If I use "terminate if" and the interface name, the sessions are dropped. What are the most optimal settings to resolve this issue? I haven't explicitly set the following settings in the config as they are supposed to be the default values. Based on what the manual states, I assumed if they are not set, Accel-PPP will use its defaults. However, I might have misunderstood something and could do with some pointers.
hello-interval=60
timeout=60
rtimeout=1
rtimeout-cap=16
retransmit=5
Do I need to specify single-session=replace?
Many thanks for your help.
Thank you for your reply.
Regarding the Framed-Route, I moved to Accel-PPP from another platform where specifying a default route for each user was necessary.
Are you saying this is not needed in this case? I must admit I was confused when looking at the forum earlier because it seemed that the Framed-Route was only used for pushing IP blocks downstream of an active user. For example, if a user had the IP 10.10.30.28 and you wanted to route a /29 downstream of 10.10.30.28, would you use the Framed-Route for this? How would you specify this?
Regarding old sessions, this is the issue: it looks like the sessions are never dropped. If I use "terminate if" and the interface name, the sessions are dropped. What are the most optimal settings to resolve this issue? I haven't explicitly set the following settings in the config as they are supposed to be the default values. Based on what the manual states, I assumed if they are not set, Accel-PPP will use its defaults. However, I might have misunderstood something and could do with some pointers.
hello-interval=60
timeout=60
rtimeout=1
rtimeout-cap=16
retransmit=5
Do I need to specify single-session=replace?
Many thanks for your help.
Re: Failed to set IPv4 address: File exists
Hi dimka88,
I've removed the framed-route and set the following settings in the Accel-ppp configuration file:
[common]
single-session=replace
#sid-case=upper
#sid-source=seq
#max-sessions=1000
check-ip=1
[l2tp]
verbose=1
#dictionary=/usr/local/share/accel-ppp/l2tp/dictionary
hello-interval=60
timeout=60
rtimeout=1
rtimeout-cap=16
retransmit=5
reorder-timeout=0
#ip-pool=l2tp
recv-window=32768
ppp-max-mtu=1500
ifname=l2tp0%d
I am still getting the same errors in the log. I am wondering if the issue is due to using the latest kernel, version 6.9.2.
I can see that I am now getting "lcp: no echo reply," but these are on fibre Ethernet services, which I would not expect to see go down, unlike VDSL. When users first connect, there are no errors at all. These errors appear after a service goes down and reconnects.
Any ideas on what I should do next?
---- Log File with IPs and usernames obscured for security ----
[2024-06-01 02:37:29]: info: l2tp tunnel 42727-46034 (XX.XX.XXX.XXX:1701): new session 13715-36776 created following reception of ICRQ
[2024-06-01 02:37:29]: info: ppp0: connect: ppp0 <--> l2tp(XX.XX.XXX.XXX:1701 session 42727-46034, 13715-36776)
[2024-06-01 02:37:29]: info: ppp0: test02@test.com: authentication succeeded
[2024-06-01 02:37:29]: error: l2tp00: failed to set IPv4 address: File exists
[2024-06-01 02:37:29]: info: l2tp00: session started over l2tp session 42727-46034, 13715-36776
[2024-06-01 02:56:59]: info: l2tp session 9974-59339, 51412-21570: CDN received from peer (result: 2, error: 0, message: "nas-error/Unknown"), disconnecting session
[2024-06-01 02:57:22]: info: l2tp tunnel 42727-46034 (XX.XX.XXX.XXX:1701): new session 19109-32038 created following reception of ICRQ
[2024-06-01 02:57:22]: info: ppp2: connect: ppp2 <--> l2tp(XX.XX.XXX.XXX:1701 session 42727-46034, 19109-32038)
[2024-06-01 02:57:22]: info: ppp2: test03@test.com: authentication succeeded
[2024-06-01 02:57:22]: error: l2tp02: failed to set IPv4 address: File exists
[2024-06-01 02:57:22]: info: l2tp02: session started over l2tp session 42727-46034, 19109-32038
[2024-06-01 03:29:15]: warn: l2tp08: lcp: no echo reply
[2024-06-01 03:29:15]: info: l2tp session 42727-46034, 45071-21450: data channel closed, disconnecting session
[2024-06-01 03:29:24]: info: l2tp tunnel 42727-46034 (XX.XX.XXX.XXX:1701): new session 53094-19909 created following reception of ICRQ
[2024-06-01 03:29:24]: info: ppp9: connect: ppp9 <--> l2tp(XX.XX.XXX.XXX:1701 session 42727-46034, 53094-19909)
[2024-06-01 03:29:24]: info: ppp9: test01@test.com: authentication succeeded
[2024-06-01 03:29:24]: error: l2tp08: failed to set IPv4 address: File exists
[2024-06-01 03:29:24]: info: l2tp08: session started over l2tp session 42727-46034, 53094-19909
[2024-06-01 03:55:57]: info: l2tp session 42727-46034, 53094-19909: CDN received from peer (result: 2, error: 0, message: "nas-error/Unknown"), disconnecting session
[2024-06-01 03:55:59]: info: l2tp tunnel 42727-46034 (XX.XX.XXX.XXX:1701): new session 50659-23188 created following reception of ICRQ
[2024-06-01 03:55:59]: info: ppp9: connect: ppp9 <--> l2tp(XX.XX.XXX.XXX:1701 session 42727-46034, 50659-23188)
[2024-06-01 03:55:59]: info: ppp9: test01@test.com: authentication succeeded
[2024-06-01 03:55:59]: info: l2tp08: session started over l2tp session 42727-46034, 50659-23188
[2024-06-01 07:03:09]: info: l2tp session 42727-46034, 50659-23188: CDN received from peer (result: 2, error: 0, message: "nas-error/Unknown"), disconnecting session
[2024-06-01 07:03:12]: info: l2tp tunnel 42727-46034 (XX.XX.XXX.XXX:1701): new session 63450-26153 created following reception of ICRQ
[2024-06-01 07:03:17]: warn: : chap-md5: timeout
[2024-06-01 07:03:17]: info: ppp9: connect: ppp9 <--> l2tp(XX.XX.XXX.XXX:1701 session 42727-46034, 63450-26153)
[2024-06-01 07:03:17]: info: ppp9: test01@test.com: authentication succeeded
[2024-06-01 07:03:17]: info: l2tp08: session started over l2tp session 42727-46034, 63450-26153
[2024-06-01 09:30:31]: info: l2tp session 42727-46034, 63450-26153: CDN received from peer (result: 2, error: 0, message: "nas-error/Unknown"), disconnecting session
[2024-06-01 09:30:34]: info: l2tp tunnel 42727-46034 (XX.XX.XXX.XXX:1701): new session 43687-45937 created following reception of ICRQ
[2024-06-01 09:30:34]: info: ppp9: connect: ppp9 <--> l2tp(XX.XX.XXX.XXX:1701 session 42727-46034, 43687-45937)
[2024-06-01 09:30:34]: info: ppp9: test01@test.com: authentication succeeded
[2024-06-01 09:30:34]: info: l2tp08: session started over l2tp session 42727-46034, 43687-45937
[2024-06-01 09:58:47]: info: l2tp session 42727-46034, 43687-45937: CDN received from peer (result: 2, error: 0, message: "nas-error/Unknown"), disconnecting session
[2024-06-01 09:58:50]: info: l2tp tunnel 42727-46034 (XX.XX.XXX.XXX:1701): new session 17146-26335 created following reception of ICRQ
[2024-06-01 09:58:55]: warn: : chap-md5: timeout
[2024-06-01 09:58:55]: info: ppp9: connect: ppp9 <--> l2tp(XX.XX.XXX.XXX:1701 session 42727-46034, 17146-26335)
[2024-06-01 09:58:55]: info: ppp9: test01@test.com: authentication succeeded
[2024-06-01 09:58:55]: info: l2tp08: session started over l2tp session 42727-46034, 17146-26335
[2024-06-01 17:05:58]: warn: l2tp021: lcp: no echo reply
[2024-06-01 17:05:58]: info: l2tp session 9974-59339, 61776-55040: data channel closed, disconnecting session
[2024-06-01 17:14:55]: info: l2tp tunnel 42727-46034 (XX.XX.XXX.XXX:1701): new session 13717-47128 created following reception of ICRQ
[2024-06-01 17:14:55]: info: ppp21: connect: ppp21 <--> l2tp(XX.XX.XXX.XXX:1701 session 42727-46034, 13717-47128)
[2024-06-01 17:14:55]: info: ppp21: test04@test.com: authentication succeeded
[2024-06-01 17:14:55]: warn: ppp21: IPV6CP: discarding packet
[2024-06-01 17:14:55]: error: l2tp021: failed to set IPv4 address: File exists
[2024-06-01 17:14:55]: info: l2tp021: session started over l2tp session 42727-46034, 13717-47128
I've removed the framed-route and set the following settings in the Accel-ppp configuration file:
[common]
single-session=replace
#sid-case=upper
#sid-source=seq
#max-sessions=1000
check-ip=1
[l2tp]
verbose=1
#dictionary=/usr/local/share/accel-ppp/l2tp/dictionary
hello-interval=60
timeout=60
rtimeout=1
rtimeout-cap=16
retransmit=5
reorder-timeout=0
#ip-pool=l2tp
recv-window=32768
ppp-max-mtu=1500
ifname=l2tp0%d
I am still getting the same errors in the log. I am wondering if the issue is due to using the latest kernel, version 6.9.2.
I can see that I am now getting "lcp: no echo reply," but these are on fibre Ethernet services, which I would not expect to see go down, unlike VDSL. When users first connect, there are no errors at all. These errors appear after a service goes down and reconnects.
Any ideas on what I should do next?
---- Log File with IPs and usernames obscured for security ----
[2024-06-01 02:37:29]: info: l2tp tunnel 42727-46034 (XX.XX.XXX.XXX:1701): new session 13715-36776 created following reception of ICRQ
[2024-06-01 02:37:29]: info: ppp0: connect: ppp0 <--> l2tp(XX.XX.XXX.XXX:1701 session 42727-46034, 13715-36776)
[2024-06-01 02:37:29]: info: ppp0: test02@test.com: authentication succeeded
[2024-06-01 02:37:29]: error: l2tp00: failed to set IPv4 address: File exists
[2024-06-01 02:37:29]: info: l2tp00: session started over l2tp session 42727-46034, 13715-36776
[2024-06-01 02:56:59]: info: l2tp session 9974-59339, 51412-21570: CDN received from peer (result: 2, error: 0, message: "nas-error/Unknown"), disconnecting session
[2024-06-01 02:57:22]: info: l2tp tunnel 42727-46034 (XX.XX.XXX.XXX:1701): new session 19109-32038 created following reception of ICRQ
[2024-06-01 02:57:22]: info: ppp2: connect: ppp2 <--> l2tp(XX.XX.XXX.XXX:1701 session 42727-46034, 19109-32038)
[2024-06-01 02:57:22]: info: ppp2: test03@test.com: authentication succeeded
[2024-06-01 02:57:22]: error: l2tp02: failed to set IPv4 address: File exists
[2024-06-01 02:57:22]: info: l2tp02: session started over l2tp session 42727-46034, 19109-32038
[2024-06-01 03:29:15]: warn: l2tp08: lcp: no echo reply
[2024-06-01 03:29:15]: info: l2tp session 42727-46034, 45071-21450: data channel closed, disconnecting session
[2024-06-01 03:29:24]: info: l2tp tunnel 42727-46034 (XX.XX.XXX.XXX:1701): new session 53094-19909 created following reception of ICRQ
[2024-06-01 03:29:24]: info: ppp9: connect: ppp9 <--> l2tp(XX.XX.XXX.XXX:1701 session 42727-46034, 53094-19909)
[2024-06-01 03:29:24]: info: ppp9: test01@test.com: authentication succeeded
[2024-06-01 03:29:24]: error: l2tp08: failed to set IPv4 address: File exists
[2024-06-01 03:29:24]: info: l2tp08: session started over l2tp session 42727-46034, 53094-19909
[2024-06-01 03:55:57]: info: l2tp session 42727-46034, 53094-19909: CDN received from peer (result: 2, error: 0, message: "nas-error/Unknown"), disconnecting session
[2024-06-01 03:55:59]: info: l2tp tunnel 42727-46034 (XX.XX.XXX.XXX:1701): new session 50659-23188 created following reception of ICRQ
[2024-06-01 03:55:59]: info: ppp9: connect: ppp9 <--> l2tp(XX.XX.XXX.XXX:1701 session 42727-46034, 50659-23188)
[2024-06-01 03:55:59]: info: ppp9: test01@test.com: authentication succeeded
[2024-06-01 03:55:59]: info: l2tp08: session started over l2tp session 42727-46034, 50659-23188
[2024-06-01 07:03:09]: info: l2tp session 42727-46034, 50659-23188: CDN received from peer (result: 2, error: 0, message: "nas-error/Unknown"), disconnecting session
[2024-06-01 07:03:12]: info: l2tp tunnel 42727-46034 (XX.XX.XXX.XXX:1701): new session 63450-26153 created following reception of ICRQ
[2024-06-01 07:03:17]: warn: : chap-md5: timeout
[2024-06-01 07:03:17]: info: ppp9: connect: ppp9 <--> l2tp(XX.XX.XXX.XXX:1701 session 42727-46034, 63450-26153)
[2024-06-01 07:03:17]: info: ppp9: test01@test.com: authentication succeeded
[2024-06-01 07:03:17]: info: l2tp08: session started over l2tp session 42727-46034, 63450-26153
[2024-06-01 09:30:31]: info: l2tp session 42727-46034, 63450-26153: CDN received from peer (result: 2, error: 0, message: "nas-error/Unknown"), disconnecting session
[2024-06-01 09:30:34]: info: l2tp tunnel 42727-46034 (XX.XX.XXX.XXX:1701): new session 43687-45937 created following reception of ICRQ
[2024-06-01 09:30:34]: info: ppp9: connect: ppp9 <--> l2tp(XX.XX.XXX.XXX:1701 session 42727-46034, 43687-45937)
[2024-06-01 09:30:34]: info: ppp9: test01@test.com: authentication succeeded
[2024-06-01 09:30:34]: info: l2tp08: session started over l2tp session 42727-46034, 43687-45937
[2024-06-01 09:58:47]: info: l2tp session 42727-46034, 43687-45937: CDN received from peer (result: 2, error: 0, message: "nas-error/Unknown"), disconnecting session
[2024-06-01 09:58:50]: info: l2tp tunnel 42727-46034 (XX.XX.XXX.XXX:1701): new session 17146-26335 created following reception of ICRQ
[2024-06-01 09:58:55]: warn: : chap-md5: timeout
[2024-06-01 09:58:55]: info: ppp9: connect: ppp9 <--> l2tp(XX.XX.XXX.XXX:1701 session 42727-46034, 17146-26335)
[2024-06-01 09:58:55]: info: ppp9: test01@test.com: authentication succeeded
[2024-06-01 09:58:55]: info: l2tp08: session started over l2tp session 42727-46034, 17146-26335
[2024-06-01 17:05:58]: warn: l2tp021: lcp: no echo reply
[2024-06-01 17:05:58]: info: l2tp session 9974-59339, 61776-55040: data channel closed, disconnecting session
[2024-06-01 17:14:55]: info: l2tp tunnel 42727-46034 (XX.XX.XXX.XXX:1701): new session 13717-47128 created following reception of ICRQ
[2024-06-01 17:14:55]: info: ppp21: connect: ppp21 <--> l2tp(XX.XX.XXX.XXX:1701 session 42727-46034, 13717-47128)
[2024-06-01 17:14:55]: info: ppp21: test04@test.com: authentication succeeded
[2024-06-01 17:14:55]: warn: ppp21: IPV6CP: discarding packet
[2024-06-01 17:14:55]: error: l2tp021: failed to set IPv4 address: File exists
[2024-06-01 17:14:55]: info: l2tp021: session started over l2tp session 42727-46034, 13717-47128
Re: Failed to set IPv4 address: File exists
Hi @tj-19.
You need Framed-Route exactly in case when you want to route some IPs behind allocated client IP.
About session replace, yes. In your case it will be suitable. Also check ppp
[ppp]
lcp-echo-interval=15
lcp-echo-failure=3
Also try to increase log level
[log]
copy=1
level=5
You need Framed-Route exactly in case when you want to route some IPs behind allocated client IP.
About session replace, yes. In your case it will be suitable. Also check ppp
[ppp]
lcp-echo-interval=15
lcp-echo-failure=3
Also try to increase log level
[log]
copy=1
level=5
Re: Failed to set IPv4 address: File exists/ RX and TX speed info
Hi @dimka88,
Thanks for the useful inputs.
I had to switch the debug level to 4 from 5 because the log was filling up with LCP echo information.
I still have the IP binding issue - "failed to set IPv4 address: File exists" after a tunnel is dropped and comes back up. I'm wondering if the IP address is being removed correctly on the newer 6.9.X kernels when the tunnel is dropped. I didn't have this issue before, looking back at my older kernel logs.
I've also noticed that the TX-Speed and RX-Speed are being sent by the LAC with each session. Is there a way to display this info in the show sessions, please? How can I query this using the accel-cmd? It would be useful to display this info on our user portal and is probably useful when using traffic shaping. How best can I take advantage of this extra info?
Is there a way to switch to debug level 5 without logging all the LCP echoes, please?
Many thanks for your help.
----------------------- Anonymised Log -----------------------
[2024-06-03 04:28:42]: info: ppp7: rename interface to 'l2tp07'
[2024-06-03 04:28:42]: error: l2tp07: failed to set IPv4 address: File exists
[2024-06-03 04:28:42]: info: l2tp07: session started over l2tp session 43575-61107, 40900-25895
[2024-06-03 06:55:35]: info: l2tp tunnel 43575-61107 (XXX.XXX.XXX.XXX:1701): recv [L2TP tid=43575 sid=40900 <Message-Type Call-Disconnect-Notify> <Result-Code> <Assigned-Session-ID 25895>]
[2024-06-03 06:55:35]: info: l2tp session 43575-61107, 40900-25895: handling CDN
[2024-06-03 06:55:35]: info: l2tp session 43575-61107, 40900-25895: CDN received from peer (result: 2, error: 0, message: "nas-error/Unknown"), disconnecting session
[2024-06-03 06:55:35]: info: l2tp session 43575-61107, 40900-25895: deleting session
[2024-06-03 06:55:35]: info: l2tp session 43575-61107, 40900-25895: deleting data channel
[2024-06-03 06:55:35]: info: l2tp07: session destroyed
[2024-06-03 06:55:35]: info: l2tp session 43575-61107, 40900-25895: session destroyed
[2024-06-03 06:55:57]: info: l2tp tunnel 43575-61107 (XXX.XXX.XXX.XXX:1701): recv [L2TP tid=43575 sid=0 <Message-Type Incoming-Call-Request> <Assigned-Session-ID 21496> <Call-Serial-Number 1702730780> <Bearer-Type 0> <Calling-Number XXXXXX]
[2024-06-03 06:55:57]: info: l2tp tunnel 43575-61107 (XXX.XXX.XXX.XXX:1701): handling ICRQ
[2024-06-03 06:55:57]: info: l2tp session 43575-61107, 51672-21496: sending ICRP
[2024-06-03 06:55:57]: info: l2tp tunnel 43575-61107 (XXX.XXX.XXX.XXX:1701): new session 51672-21496 created following reception of ICRQ
[2024-06-03 06:55:57]: info: l2tp tunnel 43575-61107 (XXX.XXX.XXX.XXX:1701): send [L2TP tid=61107 sid=21496 <Message-Type Incoming-Call-Reply> <Assigned-Session-ID -13864>]
[2024-06-03 06:55:57]: info: l2tp tunnel 43575-61107 (XXX.XXX.XXX.XXX:1701): recv [L2TP tid=43575 sid=51672 <Message-Type Incoming-Call-Connected> <Framing-Type 0> <TX-Speed 13037000> <Last-Sent-LCP> <Last-Recv-LCP> <Proxy-Authen-Type 2> <Proxy-Authen-Name user01@test.com> <Proxy-Authen-Challenge> <Proxy-Authen-ID 1> <Proxy-Authen-Response> <RX-Speed 5978000>]
[2024-06-03 06:55:57]: info: l2tp session 43575-61107, 51672-21496: handling ICCN
[2024-06-03 06:55:57]: info: : starting data channel for l2tp(XXX.XXX.XXX.XXX:1701 session 43575-61107, 51672-21496)
[2024-06-03 06:55:57]: info: : send [LCP ConfReq id=92 <auth CHAP-md5> <mru 1500> <magic XXXXXXXX>]
[2024-06-03 06:55:57]: info: : recv [LCP ConfReq id=1 <mru 1520>]
[2024-06-03 06:55:57]: info: : send [LCP ConfNak id=1 <mru 1500>]
[2024-06-03 06:55:57]: info: : recv [LCP ConfAck id=92 <auth CHAP-md5> <mru 1500> <magic XXXXXXXX>]
[2024-06-03 06:55:57]: info: : recv [LCP ConfReq id=2 <mru 1500>]
[2024-06-03 06:55:57]: info: : send [LCP ConfAck id=2]
[2024-06-03 06:55:57]: info: : send [CHAP Challenge id=1 <xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx> name="XXXX"]
[2024-06-03 06:55:57]: info: : recv [CHAP Response id=1 <xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx>, name="user01@test.com"]
[2024-06-03 06:55:57]: info: ppp7: connect: ppp7 <--> l2tp(XXX.XXX.XXX.XXX:1701 session 43575-61107, 51672-21496)
[2024-06-03 06:55:57]: info: ppp7: send [CHAP Success id=1 "Authentication succeeded"]
[2024-06-03 06:55:57]: info: ppp7: user01@test.com: authentication succeeded
[2024-06-03 06:55:57]: info: ppp7: send [IPCP ConfReq id=10 <addr XXX.XXX.XXX.X>]
[2024-06-03 06:55:57]: info: ppp7: recv [IPCP ConfReq id=0 < 0 a 0 0 c 1 0 0 0 0 > <addr 0.0.0.0> <dns1 0.0.0.0> <dns2 0.0.0.0>]
[2024-06-03 06:55:57]: info: ppp7: send [IPCP ConfRej id=0 < 0 a 0 0 c 1 0 0 0 0 >]
[2024-06-03 06:55:57]: info: ppp7: recv [IPCP ConfAck id=10 <addr XXX.XXX.XXX.X>]
[2024-06-03 06:55:57]: info: ppp7: recv [IPCP ConfReq id=1 <addr 0.0.0.0> <dns1 0.0.0.0> <dns2 0.0.0.0>]
[2024-06-03 06:55:57]: info: ppp7: send [IPCP ConfNak id=1 <addr XXX.XXX.XXX.XX> <dns1 XXX.XXX.XXX.X> <dns2 XXX.XXX.XXX.X>]
[2024-06-03 06:55:57]: info: ppp7: recv [IPCP ConfReq id=2 <addr XXX.XXX.XXX.XX> <dns1 XXX.XXX.XXX.X> <dns2 XXX.XXX.XXX.X>]
[2024-06-03 06:55:57]: info: ppp7: send [IPCP ConfAck id=2]
[2024-06-03 06:55:57]: info: ppp7: rename interface to 'l2tp07'
[2024-06-03 06:55:57]: error: l2tp07: failed to set IPv4 address: File exists
Thanks for the useful inputs.
I had to switch the debug level to 4 from 5 because the log was filling up with LCP echo information.
I still have the IP binding issue - "failed to set IPv4 address: File exists" after a tunnel is dropped and comes back up. I'm wondering if the IP address is being removed correctly on the newer 6.9.X kernels when the tunnel is dropped. I didn't have this issue before, looking back at my older kernel logs.
I've also noticed that the TX-Speed and RX-Speed are being sent by the LAC with each session. Is there a way to display this info in the show sessions, please? How can I query this using the accel-cmd? It would be useful to display this info on our user portal and is probably useful when using traffic shaping. How best can I take advantage of this extra info?
Is there a way to switch to debug level 5 without logging all the LCP echoes, please?
Many thanks for your help.
----------------------- Anonymised Log -----------------------
[2024-06-03 04:28:42]: info: ppp7: rename interface to 'l2tp07'
[2024-06-03 04:28:42]: error: l2tp07: failed to set IPv4 address: File exists
[2024-06-03 04:28:42]: info: l2tp07: session started over l2tp session 43575-61107, 40900-25895
[2024-06-03 06:55:35]: info: l2tp tunnel 43575-61107 (XXX.XXX.XXX.XXX:1701): recv [L2TP tid=43575 sid=40900 <Message-Type Call-Disconnect-Notify> <Result-Code> <Assigned-Session-ID 25895>]
[2024-06-03 06:55:35]: info: l2tp session 43575-61107, 40900-25895: handling CDN
[2024-06-03 06:55:35]: info: l2tp session 43575-61107, 40900-25895: CDN received from peer (result: 2, error: 0, message: "nas-error/Unknown"), disconnecting session
[2024-06-03 06:55:35]: info: l2tp session 43575-61107, 40900-25895: deleting session
[2024-06-03 06:55:35]: info: l2tp session 43575-61107, 40900-25895: deleting data channel
[2024-06-03 06:55:35]: info: l2tp07: session destroyed
[2024-06-03 06:55:35]: info: l2tp session 43575-61107, 40900-25895: session destroyed
[2024-06-03 06:55:57]: info: l2tp tunnel 43575-61107 (XXX.XXX.XXX.XXX:1701): recv [L2TP tid=43575 sid=0 <Message-Type Incoming-Call-Request> <Assigned-Session-ID 21496> <Call-Serial-Number 1702730780> <Bearer-Type 0> <Calling-Number XXXXXX]
[2024-06-03 06:55:57]: info: l2tp tunnel 43575-61107 (XXX.XXX.XXX.XXX:1701): handling ICRQ
[2024-06-03 06:55:57]: info: l2tp session 43575-61107, 51672-21496: sending ICRP
[2024-06-03 06:55:57]: info: l2tp tunnel 43575-61107 (XXX.XXX.XXX.XXX:1701): new session 51672-21496 created following reception of ICRQ
[2024-06-03 06:55:57]: info: l2tp tunnel 43575-61107 (XXX.XXX.XXX.XXX:1701): send [L2TP tid=61107 sid=21496 <Message-Type Incoming-Call-Reply> <Assigned-Session-ID -13864>]
[2024-06-03 06:55:57]: info: l2tp tunnel 43575-61107 (XXX.XXX.XXX.XXX:1701): recv [L2TP tid=43575 sid=51672 <Message-Type Incoming-Call-Connected> <Framing-Type 0> <TX-Speed 13037000> <Last-Sent-LCP> <Last-Recv-LCP> <Proxy-Authen-Type 2> <Proxy-Authen-Name user01@test.com> <Proxy-Authen-Challenge> <Proxy-Authen-ID 1> <Proxy-Authen-Response> <RX-Speed 5978000>]
[2024-06-03 06:55:57]: info: l2tp session 43575-61107, 51672-21496: handling ICCN
[2024-06-03 06:55:57]: info: : starting data channel for l2tp(XXX.XXX.XXX.XXX:1701 session 43575-61107, 51672-21496)
[2024-06-03 06:55:57]: info: : send [LCP ConfReq id=92 <auth CHAP-md5> <mru 1500> <magic XXXXXXXX>]
[2024-06-03 06:55:57]: info: : recv [LCP ConfReq id=1 <mru 1520>]
[2024-06-03 06:55:57]: info: : send [LCP ConfNak id=1 <mru 1500>]
[2024-06-03 06:55:57]: info: : recv [LCP ConfAck id=92 <auth CHAP-md5> <mru 1500> <magic XXXXXXXX>]
[2024-06-03 06:55:57]: info: : recv [LCP ConfReq id=2 <mru 1500>]
[2024-06-03 06:55:57]: info: : send [LCP ConfAck id=2]
[2024-06-03 06:55:57]: info: : send [CHAP Challenge id=1 <xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx> name="XXXX"]
[2024-06-03 06:55:57]: info: : recv [CHAP Response id=1 <xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx>, name="user01@test.com"]
[2024-06-03 06:55:57]: info: ppp7: connect: ppp7 <--> l2tp(XXX.XXX.XXX.XXX:1701 session 43575-61107, 51672-21496)
[2024-06-03 06:55:57]: info: ppp7: send [CHAP Success id=1 "Authentication succeeded"]
[2024-06-03 06:55:57]: info: ppp7: user01@test.com: authentication succeeded
[2024-06-03 06:55:57]: info: ppp7: send [IPCP ConfReq id=10 <addr XXX.XXX.XXX.X>]
[2024-06-03 06:55:57]: info: ppp7: recv [IPCP ConfReq id=0 < 0 a 0 0 c 1 0 0 0 0 > <addr 0.0.0.0> <dns1 0.0.0.0> <dns2 0.0.0.0>]
[2024-06-03 06:55:57]: info: ppp7: send [IPCP ConfRej id=0 < 0 a 0 0 c 1 0 0 0 0 >]
[2024-06-03 06:55:57]: info: ppp7: recv [IPCP ConfAck id=10 <addr XXX.XXX.XXX.X>]
[2024-06-03 06:55:57]: info: ppp7: recv [IPCP ConfReq id=1 <addr 0.0.0.0> <dns1 0.0.0.0> <dns2 0.0.0.0>]
[2024-06-03 06:55:57]: info: ppp7: send [IPCP ConfNak id=1 <addr XXX.XXX.XXX.XX> <dns1 XXX.XXX.XXX.X> <dns2 XXX.XXX.XXX.X>]
[2024-06-03 06:55:57]: info: ppp7: recv [IPCP ConfReq id=2 <addr XXX.XXX.XXX.XX> <dns1 XXX.XXX.XXX.X> <dns2 XXX.XXX.XXX.X>]
[2024-06-03 06:55:57]: info: ppp7: send [IPCP ConfAck id=2]
[2024-06-03 06:55:57]: info: ppp7: rename interface to 'l2tp07'
[2024-06-03 06:55:57]: error: l2tp07: failed to set IPv4 address: File exists
Re: Failed to set IPv4 address: File exists
Hi @dimka88,
I experienced the same routing issue this morning.
According to the log, a session was destroyed, but the connection's IP route remained in place. The session then came up on another LNS, causing a routing problem.
I believe the issue occurs when the interface is renamed. The renamed interface is dropped, and the original interface reappears.
From the accel-ppp log, when the connection is established, I see the following:
info: ppp27: rename interface to 'l2tp027'
The ip route is set up as follows:
XXX.XX.XX.XX dev l2tp027 proto kernel scope link src XXX.XX.XX.X
After the connection drops, I see the same IP in the IP route on the LNS that just dropped the session.
XXX.XX.XX.XX dev ppp27 proto kernel scope link src XXX.XX.XX.X
Here is the log of the session drop, which I caused by rebooting the router on the far end to trigger a call-disconnect-notify:
nfo: l2tp tunnel 53304-54295 (XX.XX.XXX.XX:1701): recv [L2TP tid=53304 sid=43316 <Message-Type Call-Disconnect-Notify> <Result-Code> <Assigned-Session-ID 6608>]
info: l2tp session 53304-54295, 43316-6608: handling CDN
info: l2tp session 53304-54295, 43316-6608: CDN received from peer (result: 2, error: 0, message: "nas-error/Unknown"), disconnecting session
info: l2tp session 53304-54295, 43316-6608: deleting session
info: l2tp session 53304-54295, 43316-6608: deleting data channel
info: l2tp tunnel 53304-54295 (XX.XX.XXX.XX:1701): no more session, disconnecting tunnel
info: l2tp tunnel 53304-54295 (XX.XX.XXX.XX:1701): sending StopCCN (res: 1, err: 0)
info: l2tp tunnel 53304-54295 (XX.XX.XXX.XX:1701): send [L2TP tid=54295 sid=0 <Message-Type Stop-Ctrl-Conn-Notify> <Assigned-Tunnel-ID -12232> <Result-Code>]
info: l2tp tunnel 53304-54295 (XX.XX.XXX.XX:1701): tunnel disconnection acknowledged by peer, deleting tunnel
info: l2tp tunnel 53304-54295 (XX.XX.XXX.XX:1701): deleting tunnel
info: l2tp027: session destroyed
In FRR, I see the following logs:
ZEBRA: [SK26S-R3N7Y][EC 100663305] interface rename detected on up interface: index 205 was renamed from l2tp027 to ppp27, results are uncertain!
ZEBRA: [NXYS2-XRNQB][EC 100663305] interface l2tp027 vrf default(0) index 205 is still up while being deleted.
How can I investigate this issue further?
I experienced the same routing issue this morning.
According to the log, a session was destroyed, but the connection's IP route remained in place. The session then came up on another LNS, causing a routing problem.
I believe the issue occurs when the interface is renamed. The renamed interface is dropped, and the original interface reappears.
From the accel-ppp log, when the connection is established, I see the following:
info: ppp27: rename interface to 'l2tp027'
The ip route is set up as follows:
XXX.XX.XX.XX dev l2tp027 proto kernel scope link src XXX.XX.XX.X
After the connection drops, I see the same IP in the IP route on the LNS that just dropped the session.
XXX.XX.XX.XX dev ppp27 proto kernel scope link src XXX.XX.XX.X
Here is the log of the session drop, which I caused by rebooting the router on the far end to trigger a call-disconnect-notify:
nfo: l2tp tunnel 53304-54295 (XX.XX.XXX.XX:1701): recv [L2TP tid=53304 sid=43316 <Message-Type Call-Disconnect-Notify> <Result-Code> <Assigned-Session-ID 6608>]
info: l2tp session 53304-54295, 43316-6608: handling CDN
info: l2tp session 53304-54295, 43316-6608: CDN received from peer (result: 2, error: 0, message: "nas-error/Unknown"), disconnecting session
info: l2tp session 53304-54295, 43316-6608: deleting session
info: l2tp session 53304-54295, 43316-6608: deleting data channel
info: l2tp tunnel 53304-54295 (XX.XX.XXX.XX:1701): no more session, disconnecting tunnel
info: l2tp tunnel 53304-54295 (XX.XX.XXX.XX:1701): sending StopCCN (res: 1, err: 0)
info: l2tp tunnel 53304-54295 (XX.XX.XXX.XX:1701): send [L2TP tid=54295 sid=0 <Message-Type Stop-Ctrl-Conn-Notify> <Assigned-Tunnel-ID -12232> <Result-Code>]
info: l2tp tunnel 53304-54295 (XX.XX.XXX.XX:1701): tunnel disconnection acknowledged by peer, deleting tunnel
info: l2tp tunnel 53304-54295 (XX.XX.XXX.XX:1701): deleting tunnel
info: l2tp027: session destroyed
In FRR, I see the following logs:
ZEBRA: [SK26S-R3N7Y][EC 100663305] interface rename detected on up interface: index 205 was renamed from l2tp027 to ppp27, results are uncertain!
ZEBRA: [NXYS2-XRNQB][EC 100663305] interface l2tp027 vrf default(0) index 205 is still up while being deleted.
How can I investigate this issue further?
Re: Failed to set IPv4 address: File exists
It is preatty strange. Looks like something with sync between FRR and Kernel
Could you check, ip -s -d addr show dev ppp27 and ip -s -d addr show dev l2tp027 when its happens
Could you check, ip -s -d addr show dev ppp27 and ip -s -d addr show dev l2tp027 when its happens