ASR1002 LNS getting stuck in PPP BCP

thoooooo · ‎09-23-2022

Hello all,

I'm working on an ASR1002 running as LNS. I'm facing the issue that 1 out of 4 times (give or take) the PPP negotiation gets stuck with BCP as protocol. At that point the ASR only brings up IPV6CP and the IPCP configuration requests from to client are not recognized. The client stays connected, even with the "ipcp address required". Is there a way to disallow the use of BCP for a certain virtual-template? Or to disable it on the ASR completely? (I do not have any bridge-domains or layer-2 stuff on this router at this point)

Software / hardware

Cisco IOS XE Software, Version 03.16.10.S - Extended Support Release
Cisco IOS Software, ASR1000 Software (PPC_LINUX_IOSD-ADVENTERPRISEK9-M), Version 15.5(3)S10, RELEASE SOFTWARE (fc3)

cisco ASR1002 (2RU) processor (revision 2RU) with 1638757K/6147K bytes of memory.

My configuration:

! Last configuration change at 22:02:08 CEST Thu Sep 22 2022 by root
! NVRAM config last updated at 22:07:53 CEST Thu Sep 22 2022 by root
!
version 15.5
service timestamps debug datetime msec
service timestamps log datetime
service password-encryption
service unsupported-transceiver
no platform punt-keepalive disable-kernel-core
!
hostname BRAS1
!
boot-start-marker
boot-end-marker
!
!
vrf definition Mgmt-intf
 !
 address-family ipv4
 exit-address-family
 !
 address-family ipv6
 exit-address-family
!
vrf definition internet
 rd 64519:1
 !
 address-family ipv4
 exit-address-family
 !
 address-family ipv6
 exit-address-family
!
logging buffered 40960
!
aaa new-model
!
!
aaa group server radius RADIUS1
 server-private X.X.X.X auth-port 1812 acct-port 1813 key ....
 ip radius source-interface Port-channel1.410
 deadtime 0
!
aaa authentication login default local
aaa authentication ppp default group RADIUS1
aaa authorization exec default local 
aaa authorization network default group RADIUS1 
aaa authorization configuration dhcpv6-pd-radius group RADIUS1 
aaa accounting delay-start
aaa accounting update periodic 10
aaa accounting network default start-stop group RADIUS1
aaa accounting connection default start-stop group RADIUS1
!
!
!
!
!
!
aaa session-id common
aaa policy interface-config allow-subinterface
clock timezone CET 1 0
clock summer-time CEST recurring last Sun Mar 2:00 last Sun Oct 3:00
!
!
!
!
!
!
!
!
!
!
!


no ip bootp server
ip name-server Z.Z.Z.Z Y.Y.Y.Y

no ip domain lookup
ip domain name lns.local
ip cef load-sharing algorithm include-ports source destination
!
!
!
ipv6 unicast-routing
ipv6 dhcp iana-route-add
ipv6 dhcp binding track ppp
no ipv6 dhcp ppp terminate
no ipv6 dhcp ppp framed-prefix cache
ipv6 dhcp pool lns-dhcp-delegate6
 prefix-delegation aaa method-list dhcpv6-pd-radius
 dns-server 2606:4700:4700::1111
 dns-server 2620:FE::10
!
!
!
!
!
!
!
!
subscriber templating
virtual-profile if-needed
virtual-profile virtual-template 1
!
multilink bundle-name authenticated
vpdn enable
vpdn multihop
vpdn authen-before-forward
vpdn logging
vpdn logging local
vpdn logging remote
vpdn logging user
vpdn logging tunnel-drop
vpdn logging accounting
vpdn logging dead-cache
vpdn search-order domain  
!
vpdn-group LNS
 accept-dialin
  protocol l2tp
  virtual-template 1
 source-ip ....
 local name bras1
 force-local-chap
 lcp renegotiation always
 l2tp tunnel password ....
 ip tos reflect
!
!
domain lns.local
no virtual-template snmp
!
!
!
!
!
!
!
!
!
spanning-tree extend system-id
!
username root privilege 15 password ....
!
redundancy
 mode none
!
!
!
!
!
!
!
! 
!
!
!
!
!
!
!
!
!
!
!
! 
! 
! 
! 
! 
! 
!
!
interface Loopback0
 description LNS Loopback
 ip address .... 255.255.255.255
!
interface Loopback1
 description lns PPP Loopback
 vrf forwarding internet
 ip address 100.127.0.1 255.255.255.255
 no ip redirects
 no ip unreachables
 no ip proxy-arp
 ipv6 address BBBB:BBBB::127:0:1/128
!
interface Port-channel1
 mtu 9216
 ip address ....
 ip mtu 1600
 no negotiation auto
!
interface Port-channel1.410
 encapsulation dot1Q 410
 ip address 172.25.17.2 255.255.255.0
 ip mtu 1500
!
interface Port-channel1.555
 encapsulation dot1Q 555
 vrf forwarding internet
 ip address .... 255.255.255.254
 ip mtu 1500
!
interface GigabitEthernet0/0/0
 mtu 9216
 no ip address
 speed 1000
 no negotiation auto
 lacp rate fast
 channel-group 1 mode active
!
interface GigabitEthernet0/0/1
 mtu 9216
 no ip address
 speed 1000
 no negotiation auto
 lacp rate fast
 channel-group 1 mode active
!
interface GigabitEthernet0/0/2
 mtu 9216
 no ip address
 speed 1000
 no negotiation auto
 lacp rate fast
 channel-group 1 mode active
!
interface GigabitEthernet0/0/3
 mtu 9216
 no ip address
 speed 1000
 no negotiation auto
 lacp rate fast
 channel-group 1 mode active
!
interface TenGigabitEthernet0/2/0
 description Link to CR1 XE-0/0/6:0
 mtu 9216
 ip address .... 255.255.255.254
 ip mtu 2000
!
interface TenGigabitEthernet0/2/0.11
 encapsulation dot1Q 11
 vrf forwarding internet
 ip address .... 255.255.255.254
 ip mtu 1500
!
interface TenGigabitEthernet0/3/0
 description Link to CR2 XE-0/0/6:0
 mtu 9216
 ip address .... 255.255.255.254
 ip mtu 2000
!
interface TenGigabitEthernet0/3/0.11
 encapsulation dot1Q 11
 vrf forwarding internet
 ip address .... 255.255.255.254
 ip mtu 1500
!
interface GigabitEthernet0
 vrf forwarding Mgmt-intf
 no ip address
 shutdown
 negotiation auto
!
interface Virtual-Template1
 description L2TP PPP Termination 1
 mtu 1492
 vrf forwarding internet
 ip unnumbered Loopback1
 no ip redirects
 no ip unreachables
 no ip proxy-arp
 ip verify unicast reverse-path
 no logging event link-status
 ipv6 unnumbered Loopback1
 ipv6 enable
 ipv6 nd reachable-time 30
 no ipv6 nd prefix framed-ipv6-prefix
 ipv6 nd router-preference High
 no ipv6 nd ra suppress
 ipv6 nd ra lifetime 14400
 ipv6 nd ra interval 4 3
 ipv6 dhcp server lns-dhcp-delegate6
 peer ip address forced
 peer default ip address pool lns-default4
 peer default ipv6 pool lns-default6
 no snmp trap link-status
 keepalive 10 3
 ppp max-configure 3
 ppp max-failure 3
 ppp pfc local forbid
 ppp pfc remote reject
 ppp acfc local forbid
 ppp acfc remote reject
 ppp authentication chap callin
 ppp eap refuse
 ppp ms-chap refuse
 ppp ms-chap-v2 refuse
 ppp pap refuse
 ppp ipcp dns 1.1.1.1 9.9.9.10
 ppp ipcp mask reject
 ppp ipcp address required
 ppp ipcp address unique
 ppp ipcp no-renegotiation
 ppp ipv6cp address unique
 ppp ncp passive ipcp ipv6cp
 ppp link reorders
 ppp timeout retry 10
 ppp timeout ncp 10
!
router bgp 64519
 bgp log-neighbor-changes
 neighbor LAC-NET peer-group
 neighbor LAC-NET remote-as ....
 neighbor LAC-NET timers 10 30
 neighbor .... peer-group LAC-NET
 neighbor .... update-source TenGigabitEthernet0/2/0
 neighbor .... peer-group LAC-NET
 neighbor .... update-source TenGigabitEthernet0/3/0
 !
 address-family ipv4
  redistribute connected
  neighbor LAC-NET soft-reconfiguration inbound
  neighbor LAC-NET route-map lac-net_out out
  neighbor .... activate
  neighbor .... activate
  maximum-paths eibgp 2
 exit-address-family
 !
 address-family ipv4 vrf internet
  redistribute connected
  redistribute static
  neighbor CORE peer-group
  neighbor CORE remote-as 64518
  neighbor CORE soft-reconfiguration inbound
  neighbor CORE route-map core_in in
  neighbor CORE route-map core_out out
  neighbor .... peer-group CORE
  neighbor .... activate
 exit-address-family
!
ip local pool lns-default4 100.127.127.0 100.127.127.255
ip forward-protocol nd
!
no ip http server
no ip http secure-server
ip route 10.0.0.0 255.0.0.0 172.25.17.1
ip route Z.Z.Z.Z 255.255.255.255 172.25.17.1
ip route Y.Y.Y.Y 255.255.255.255 172.25.17.1
ip route 172.16.0.0 255.240.0.0 172.25.17.1
ip route 192.168.0.0 255.255.0.0 172.25.17.1
ip route vrf internet 0.0.0.0 0.0.0.0 ...
ip ssh version 2
ip ssh dh min size 2048
ip ssh pubkey-chain
  username root
ip ssh server algorithm mac hmac-sha1
ip ssh server algorithm encryption aes256-ctr
ip ssh server algorithm authentication password
!
ip access-list extended allow-snmp
 permit ip host 172.20.211.8 any
!
!
ip prefix-list framed-ip seq 5 permit ..../24 ge 32
ip prefix-list framed-ip seq 10 permit ..../24 ge 32
ip prefix-list framed-ip seq 15 permit ..../25 ge 32
!
ip prefix-list framed-route seq 5 permit ..../30
!
ip prefix-list lns-ip seq 5 permit ..../32
ip radius source-interface Port-channel1.410 
logging source-interface Port-channel1.410
logging host 172.25.17.38
ipv6 local pool lns-default6 ..../48 64
ipv6 local pool lns-delegate6 ..../46 62
!
route-map lac-net_out permit 10
 match ip address prefix-list lns-ip
 match source-protocol connected
!
route-map lac-net_out deny 1000
!
route-map core_out permit 10
 match ip address prefix-list framed-ip
 match source-protocol connected
!
route-map core_out permit 15
 match ip address prefix-list framed-route
 match source-protocol static
!
route-map core_out deny 1000
!
route-map core_in deny 1000
!
snmp-server community lns RO
snmp-server location ..../Rack 1
snmp-server contact ....
!
!
radius-server attribute 6 on-for-login-auth
radius-server attribute 8 include-in-access-req
radius-server attribute 67 include-in-access-req
radius-server attribute 66 include-in-access-req
!
!
control-plane
!
call admission new-model
call admission cpu-limit 80
call admission vpdn 10 1
 !
 !
 !
 !
!
!
!
!
!
line con 0
 stopbits 1
line aux 0
 stopbits 1
line vty 0 4
 transport input ssh
!
ntp server Z.Z.Z.Z source Port-channel1.410
ntp server Y.Y.Y.Y source Port-channel1.410
netconf lock-time 30
netconf ssh
!
end

I do not like defaults (I only want to allow a single specific configuration on the client), hence my rather big virtual-template. Nevertheless even with the simpler example ones I'm running into the same issues.

In a bad state the client looks like this:

BRAS1#sh ppp int vi2.1    
Vi2.1 No PPP serial context
PPP Session Info
----------------
Interface        : Vi2.1
PPP ID           : 0x680008F2
Phase            : UP
Stage            : Local Termination
Peer Name        : user1000012@LNS
Peer Address     : 0.0.0.0
Control Protocols: LCP[Open] CHAP+ IPV6CP[Open] BCP[Stopped] 
Session ID       : 133
AAA Unique ID    : 16440
SSS Manager ID   : 0x20000330
SIP ID           : 0x200032F
PPP_IN_USE       : 0x10

Vi2.1 LCP: [Open] 
Our Negotiated Options
Vi2.1 LCP:    MRU 1492 (0x010405D4)
Vi2.1 LCP:    AuthProto CHAP (0x0305C22305)
Vi2.1 LCP:    MagicNumber 0x6A87EA28 (0x05066A87EA28)
Peer's Negotiated Options
Vi2.1 LCP:    MRU 1492 (0x010405D4)
Vi2.1 LCP:    MagicNumber 0x32B21B70 (0x050632B21B70)

Vi2.1 IPV6CP: [Open] 
Our Negotiated Options
Vi2.1 IPV6CP:    Interface-Id 0223:04FF:FEA7:6E00 (0x010A022304FFFEA76E00)
Peer's Negotiated Options
Vi2.1 IPV6CP:    Interface-Id 9A9B:CBFF:FEA5:8F44 (0x010A9A9BCBFFFEA58F44)
BRAS1#

During this time the debug is also flooded with the incoming requests for IPCP:

Sep 23 07:39:56.403: Vi2.1 IPCP: I CONFREQ [UNKNOWN] id 169 len 22
Sep 23 07:39:56.404: Vi2.1 IPCP:    Address A.A.A.A (0x0306B98EE3C8)
Sep 23 07:39:56.404: Vi2.1 IPCP:    PrimaryDNS 1.1.1.1 (0x810601010101)
Sep 23 07:39:56.404: Vi2.1 IPCP:    SecondaryDNS 9.9.9.10 (0x83060909090A)
Sep 23 07:39:56.404: Vi2.1 LCP: O PROTREJ [Open] id 105 len 28 protocol IPCP 
Sep 23 07:39:56.404: Vi2.1 LCP: (0x01A900160306B98EE3C8810601010101)
Sep 23 07:39:56.404: Vi2.1 LCP: (0x83060909090A)
Sep 23 07:39:57.400: Vi2.1 IPCP: I CONFREQ [UNKNOWN] id 170 len 22
Sep 23 07:39:57.400: Vi2.1 IPCP:    Address A.A.A.A (0x0306B98EE3C8)
Sep 23 07:39:57.400: Vi2.1 IPCP:    PrimaryDNS 1.1.1.1 (0x810601010101)
Sep 23 07:39:57.400: Vi2.1 IPCP:    SecondaryDNS 9.9.9.10 (0x83060909090A)
Sep 23 07:39:57.400: Vi2.1 LCP: O PROTREJ [Open] id 106 len 28 protocol IPCP 
Sep 23 07:39:57.400: Vi2.1 LCP: (0x01AA00160306B98EE3C8810601010101)
Sep 23 07:39:57.400: Vi2.1 LCP: (0x83060909090A)
Sep 23 07:39:57.412: Vi2.1 IPCP: I CONFREQ [UNKNOWN] id 171 len 22
Sep 23 07:39:57.412: Vi2.1 IPCP:    Address A.A.A.A (0x0306B98EE3C8)
Sep 23 07:39:57.412: Vi2.1 IPCP:    PrimaryDNS 1.1.1.1 (0x810601010101)
Sep 23 07:39:57.412: Vi2.1 IPCP:    SecondaryDNS 9.9.9.10 (0x83060909090A)
Sep 23 07:39:57.412: Vi2.1 LCP: O PROTREJ [Open] id 107 len 28 protocol IPCP 
Sep 23 07:39:57.412: Vi2.1 LCP: (0x01AB00160306B98EE3C8810601010101)
Sep 23 07:39:57.412: Vi2.1 LCP: (0x83060909090A)

When I disconnect the client and it reconnects in a good state it looks like this (same client, seconds later):

BRAS1#clear ppp int vi2.1
BRAS1#sh ppp int vi2.1   
Vi2.1 No PPP serial context
PPP Session Info
----------------
Interface        : Vi2.1
PPP ID           : 0x1E0008F6
Phase            : UP
Stage            : Local Termination
Peer Name        : user1000012@LNS
Peer Address     : A.A.A.A
Control Protocols: LCP[Open] CHAP+ IPCP[Open] IPV6CP[Open] 
Session ID       : 137
AAA Unique ID    : 16575
SSS Manager ID   : 0xD8000338
SIP ID           : 0xCB000337
PPP_IN_USE       : 0x11

Vi2.1 LCP: [Open] 
Our Negotiated Options
Vi2.1 LCP:    MRU 1492 (0x010405D4)
Vi2.1 LCP:    AuthProto CHAP (0x0305C22305)
Vi2.1 LCP:    MagicNumber 0x6D86C3BA (0x05066D86C3BA)
Peer's Negotiated Options
Vi2.1 LCP:    MRU 1492 (0x010405D4)
Vi2.1 LCP:    MagicNumber 0x32B3C8E5 (0x050632B3C8E5)

Vi2.1 IPCP: [Open] 
Our Negotiated Options
Vi2.1 IPCP:    Address 100.127.0.1 (0x0306647F0001)
Peer's Negotiated Options
Vi2.1 IPCP:    Address A.A.A.A (0x0306B98EE3C8)
Vi2.1 IPCP:    PrimaryDNS 1.1.1.1 (0x810601010101)
Vi2.1 IPCP:    SecondaryDNS 9.9.9.10 (0x83060909090A)

Vi2.1 IPV6CP: [Open] 
Our Negotiated Options
Vi2.1 IPV6CP:    Interface-Id 0223:04FF:FEA7:6E00 (0x010A022304FFFEA76E00)
Peer's Negotiated Options
Vi2.1 IPV6CP:    Interface-Id 9A9B:CBFF:FEA5:8F44 (0x010A9A9BCBFFFEA58F44)
BRAS1#

This is what happens in debug during the connection negotiation when all goes well:

Sep 23 09:51:26.840: ppp137 PPP: Phase is ESTABLISHING
Sep 23 09:51:26.840: ppp137 PPP: Using vpn set call direction
Sep 23 09:51:26.840: ppp137 PPP: Treating connection as a callin
Sep 23 09:51:26.840: ppp137 PPP: Session handle[1E0008F6] Session id[137]
Sep 23 09:51:26.840: ppp137 LCP: Event[OPEN] State[Initial to Starting]
Sep 23 09:51:26.840: ppp137 PPP LCP: Enter passive mode, state[Stopped]
Sep 23 09:51:28.851: ppp137 PPP LCP: Exit passive mode, state[Starting]
Sep 23 09:51:28.852: ppp137 LCP: O CONFREQ [Starting] id 1 len 19
Sep 23 09:51:28.852: ppp137 LCP:    MRU 1492 (0x010405D4)
Sep 23 09:51:28.852: ppp137 LCP:    AuthProto CHAP (0x0305C22305)
Sep 23 09:51:28.852: ppp137 LCP:    MagicNumber 0x6D86C3BA (0x05066D86C3BA)
Sep 23 09:51:28.852: ppp137 LCP: Event[UP] State[Starting to REQsent]
Sep 23 09:51:28.863: ppp137 LCP: I CONFREQ [REQsent] id 5 len 14
Sep 23 09:51:28.863: ppp137 LCP:    MRU 1492 (0x010405D4)
Sep 23 09:51:28.863: ppp137 LCP:    MagicNumber 0x32B3C8E5 (0x050632B3C8E5)
Sep 23 09:51:28.863: ppp137 LCP: O CONFACK [REQsent] id 5 len 14
Sep 23 09:51:28.863: ppp137 LCP:    MRU 1492 (0x010405D4)
Sep 23 09:51:28.863: ppp137 LCP:    MagicNumber 0x32B3C8E5 (0x050632B3C8E5)
Sep 23 09:51:28.863: ppp137 LCP: Event[Receive ConfReq+] State[REQsent to ACKsent]
Sep 23 09:51:28.864: ppp137 LCP: I CONFACK [ACKsent] id 1 len 19
Sep 23 09:51:28.864: ppp137 LCP:    MRU 1492 (0x010405D4)
Sep 23 09:51:28.864: ppp137 LCP:    AuthProto CHAP (0x0305C22305)
Sep 23 09:51:28.864: ppp137 LCP:    MagicNumber 0x6D86C3BA (0x05066D86C3BA)
Sep 23 09:51:28.864: ppp137 LCP: Event[Receive ConfAck] State[ACKsent to Open]
Sep 23 09:51:28.883: ppp137 PPP: Phase is AUTHENTICATING, by this end
Sep 23 09:51:28.883: ppp137 CHAP: O CHALLENGE id 1 len 26 from "BRAS1"
Sep 23 09:51:28.884: ppp137 LCP: State is Open
Sep 23 09:51:28.895: ppp137 CHAP: I RESPONSE id 1 len 44 from "user1000012@LNS"
Sep 23 09:51:28.895: ppp137 PPP: Phase is FORWARDING, Attempting Forward
Sep 23 09:51:28.896: ppp137 PPP: Phase is AUTHENTICATING, Unauthenticated User
Sep 23 09:51:28.898: ppp137 PPP: Phase is FORWARDING, Attempting Forward
Sep 23 09:51:28.943: VT[Vi2.1]:Request took 44 msec, 43 msec processing time
Sep 23 09:51:28.955: Vi2.1 PPP: Phase is AUTHENTICATING, Authenticated User
Sep 23 09:51:28.955: Vi2.1 CHAP: O SUCCESS id 1 len 4
Sep 23 09:51:28.957: Vi2.1 PPP: Phase is UP
Sep 23 09:51:28.957: Vi2.1 IPCP: Protocol configured, start CP. state[Initial]
Sep 23 09:51:28.957: Vi2.1 IPCP: Event[OPEN] State[Initial to Starting]
Sep 23 09:51:28.957: Vi2.1 PPP IPCP: Enter passive mode, state[Stopped]
Sep 23 09:51:28.957: Vi2.1 IPV6CP: Protocol configured, start CP. state[Initial]
Sep 23 09:51:28.957: Vi2.1 IPV6CP: Event[OPEN] State[Initial to Starting]
Sep 23 09:51:28.957: Vi2.1 PPP IPV6CP: Enter passive mode, state[Stopped]
Sep 23 09:51:28.969: Vi2.1 IPCP: I CONFREQ [Stopped] id 172 len 22
Sep 23 09:51:28.969: Vi2.1 IPCP:    Address A.A.A.A (0x0306B98EE3C8)
Sep 23 09:51:28.969: Vi2.1 IPCP:    PrimaryDNS 1.1.1.1 (0x810601010101)
Sep 23 09:51:28.969: Vi2.1 IPCP:    SecondaryDNS 9.9.9.10 (0x83060909090A)
Sep 23 09:51:28.969: Vi2.1 IPCP AUTHOR: Start.  Her address A.A.A.A, we want 0.0.0.0
Sep 23 09:51:28.969: Vi2.1 set_ip_peer: new(5): A.A.A.A prior(0): 0.0.0.0
Sep 23 09:51:28.969: Vi2.1 IPCP AUTHOR: Done.  Her address A.A.A.A, we want A.A.A.A
Sep 23 09:51:28.969: Vi2.1 IPCP: O CONFREQ [Stopped] id 1 len 10
Sep 23 09:51:28.969: Vi2.1 IPCP:    Address 100.127.0.1 (0x0306647F0001)
Sep 23 09:51:28.969: Vi2.1 IPCP: O CONFACK [Stopped] id 172 len 22
Sep 23 09:51:28.969: Vi2.1 IPCP:    Address A.A.A.A (0x0306B98EE3C8)
Sep 23 09:51:28.969: Vi2.1 IPCP:    PrimaryDNS 1.1.1.1 (0x810601010101)
Sep 23 09:51:28.969: Vi2.1 IPCP:    SecondaryDNS 9.9.9.10 (0x83060909090A)
Sep 23 09:51:28.969: Vi2.1 IPCP: Event[Receive ConfReq+] State[Stopped to ACKsent]
Sep 23 09:51:28.969: Vi2.1 IPV6CP: I CONFREQ [Stopped] id 139 len 14
Sep 23 09:51:28.969: Vi2.1 IPV6CP:    Interface-Id 9A9B:CBFF:FEA5:8F44 (0x010A9A9BCBFFFEA58F44)
Sep 23 09:51:28.969: Vi2.1 IPV6CP: O CONFREQ [Stopped] id 1 len 14
Sep 23 09:51:28.969: Vi2.1 IPV6CP:    Interface-Id 0223:04FF:FEA7:6E00 (0x010A022304FFFEA76E00)
Sep 23 09:51:28.970: Vi2.1 IPV6CP: O CONFACK [Stopped] id 139 len 14
Sep 23 09:51:28.970: Vi2.1 IPV6CP:    Interface-Id 9A9B:CBFF:FEA5:8F44 (0x010A9A9BCBFFFEA58F44)
Sep 23 09:51:28.970: Vi2.1 IPV6CP: Event[Receive ConfReq+] State[Stopped to ACKsent]
Sep 23 09:51:28.981: Vi2.1 IPCP: I CONFACK [ACKsent] id 1 len 10
Sep 23 09:51:28.981: Vi2.1 IPCP:    Address 100.127.0.1 (0x0306647F0001)
Sep 23 09:51:28.981: Vi2.1 IPCP: Event[Receive ConfAck] State[ACKsent to Open]
Sep 23 09:51:28.986: Vi2.1 IPV6CP: I CONFACK [ACKsent] id 1 len 14
Sep 23 09:51:28.986: Vi2.1 IPV6CP:    Interface-Id 0223:04FF:FEA7:6E00 (0x010A022304FFFEA76E00)
Sep 23 09:51:28.986: Vi2.1 IPV6CP: Event[Receive ConfAck] State[ACKsent to Open]
Sep 23 09:51:29.012: Vi2.1 IPCP: State is Open
Sep 23 09:51:29.012: Vi2.1 IPV6CP: State is Open
Sep 23 09:51:29.015: ppp_session_ntfy, topswidb Vi2.1, va Vi2.1, platform notify 0
Sep 23 09:51:29.018: Vi2.1 Added to neighbor route AVL tree: topoid 2, address A.A.A.A
Sep 23 09:51:29.018: Vi2.1 IPCP: Install route to A.A.A.A

And the 1 out of 4 times it fails:

Sep 23 09:59:46.323: ppp139 PPP: Phase is ESTABLISHING
Sep 23 09:59:46.323: ppp139 LCP: Event[OPEN] State[Initial to Starting]
Sep 23 09:59:46.323: ppp139 LCP: O CONFREQ [Starting] id 1 len 19
Sep 23 09:59:46.323: ppp139 LCP:    MRU 1492 (0x010405D4)
Sep 23 09:59:46.324: ppp139 LCP:    AuthProto CHAP (0x0305C22305)
Sep 23 09:59:46.324: ppp139 LCP:    MagicNumber 0x6D8E5C35 (0x05066D8E5C35)
Sep 23 09:59:46.324: ppp139 LCP: Event[UP] State[Starting to REQsent]
Sep 23 09:59:46.332: ppp139 LCP: I CONFREQ [REQsent] id 3 len 14
Sep 23 09:59:46.332: ppp139 LCP:    MRU 1492 (0x010405D4)
Sep 23 09:59:46.332: ppp139 LCP:    MagicNumber 0x32B6A609 (0x050632B6A609)
Sep 23 09:59:46.332: ppp139 LCP: O CONFACK [REQsent] id 3 len 14
Sep 23 09:59:46.332: ppp139 LCP:    MRU 1492 (0x010405D4)
Sep 23 09:59:46.332: ppp139 LCP:    MagicNumber 0x32B6A609 (0x050632B6A609)
Sep 23 09:59:46.332: ppp139 LCP: Event[Receive ConfReq+] State[REQsent to ACKsent]
Sep 23 09:59:46.332: ppp139 LCP: I CONFACK [ACKsent] id 1 len 19
Sep 23 09:59:46.332: ppp139 LCP:    MRU 1492 (0x010405D4)
Sep 23 09:59:46.333: ppp139 LCP:    AuthProto CHAP (0x0305C22305)
Sep 23 09:59:46.333: ppp139 LCP:    MagicNumber 0x6D8E5C35 (0x05066D8E5C35)
Sep 23 09:59:46.333: ppp139 LCP: Event[Receive ConfAck] State[ACKsent to Open]
Sep 23 09:59:46.356: ppp139 PPP: Phase is AUTHENTICATING, by this end
Sep 23 09:59:46.356: ppp139 CHAP: O CHALLENGE id 1 len 26 from "BRAS1"
Sep 23 09:59:46.356: ppp139 LCP: State is Open
Sep 23 09:59:46.364: ppp139 CHAP: I RESPONSE id 1 len 44 from "user1000012@LNS"
Sep 23 09:59:46.364: ppp139 PPP: Phase is FORWARDING, Attempting Forward
Sep 23 09:59:46.365: ppp139 PPP: Phase is AUTHENTICATING, Unauthenticated User
Sep 23 09:59:46.457: ppp139 PPP: Phase is FORWARDING, Attempting Forward
Sep 23 09:59:46.485: VT[Vi2.1]:Request took 27 msec, 27 msec processing time
Sep 23 09:59:46.496: Vi2.1 PPP: Phase is AUTHENTICATING, Authenticated User
Sep 23 09:59:46.496: Vi2.1 CHAP: O SUCCESS id 1 len 4
Sep 23 09:59:46.497: Vi2.1 PPP: Phase is UP
Sep 23 09:59:46.497: Vi2.1 IPV6CP: Protocol configured, start CP. state[Initial]
Sep 23 09:59:46.497: Vi2.1 IPV6CP: Event[OPEN] State[Initial to Starting]
Sep 23 09:59:46.497: Vi2.1 PPP IPV6CP: Enter passive mode, state[Stopped]
Sep 23 09:59:46.497: Vi2.1 BCP: Protocol configured, start CP. state[Initial]
Sep 23 09:59:46.497: Vi2.1 BCP: Event[OPEN] State[Initial to Starting]
Sep 23 09:59:46.497: Vi2.1 BCP: O CONFREQ [Starting] id 1 len 11
Sep 23 09:59:46.497: Vi2.1 BCP:    Tagged Enable (0x080301)
Sep 23 09:59:46.498: Vi2.1 BCP:    Mgmt Inline (0x0902)
Sep 23 09:59:46.498: Vi2.1 BCP:    BPDU Indicator (0x0A02)
Sep 23 09:59:46.498: Vi2.1 BCP: Event[UP] State[Starting to REQsent]
Sep 23 09:59:46.507: Vi2.1 LCP: I PROTREJ [Open] id 5 len 17 protocol BCP (0x0101000B08030109020A02)
Sep 23 09:59:46.507: Vi2.1 BCP: Event[Receive CodeRej-] State[REQsent to Stopped]
Sep 23 09:59:46.507: Vi2.1 IPCP: I CONFREQ [UNKNOWN] id 176 len 22
Sep 23 09:59:46.507: Vi2.1 IPCP:    Address A.A.A.A (0x0306B98EE3C8)
Sep 23 09:59:46.507: Vi2.1 IPCP:    PrimaryDNS 1.1.1.1 (0x810601010101)
Sep 23 09:59:46.507: Vi2.1 IPCP:    SecondaryDNS 9.9.9.10 (0x83060909090A)
Sep 23 09:59:46.507: Vi2.1 LCP: O PROTREJ [Open] id 2 len 28 protocol IPCP 
Sep 23 09:59:46.507: Vi2.1 LCP: (0x01B000160306B98EE3C8810601010101)
Sep 23 09:59:46.508: Vi2.1 LCP: (0x83060909090A)
Sep 23 09:59:46.822: Vi2.1 IPV6CP: I CONFREQ [Stopped] id 143 len 14
Sep 23 09:59:46.822: Vi2.1 IPV6CP:    Interface-Id 9A9B:CBFF:FEA5:8F44 (0x010A9A9BCBFFFEA58F44)
Sep 23 09:59:46.822: Vi2.1 IPV6CP: O CONFREQ [Stopped] id 1 len 14
Sep 23 09:59:46.822: Vi2.1 IPV6CP:    Interface-Id 0223:04FF:FEA7:6E00 (0x010A022304FFFEA76E00)
Sep 23 09:59:46.822: Vi2.1 IPV6CP: O CONFACK [Stopped] id 143 len 14
Sep 23 09:59:46.822: Vi2.1 IPV6CP:    Interface-Id 9A9B:CBFF:FEA5:8F44 (0x010A9A9BCBFFFEA58F44)
Sep 23 09:59:46.822: Vi2.1 IPV6CP: Event[Receive ConfReq+] State[Stopped to ACKsent]
Sep 23 09:59:46.831: Vi2.1 IPV6CP: I CONFACK [ACKsent] id 1 len 14
Sep 23 09:59:46.831: Vi2.1 IPV6CP:    Interface-Id 0223:04FF:FEA7:6E00 (0x010A022304FFFEA76E00)
Sep 23 09:59:46.831: Vi2.1 IPV6CP: Event[Receive ConfAck] State[ACKsent to Open]
Sep 23 09:59:46.836: Vi2.1 IPV6CP: State is Open
Sep 23 09:59:48.096: Vi2.1 IPCP: I CONFREQ [UNKNOWN] id 177 len 22
Sep 23 09:59:48.096: Vi2.1 IPCP:    Address A.A.A.A (0x0306B98EE3C8)
Sep 23 09:59:48.096: Vi2.1 IPCP:    PrimaryDNS 1.1.1.1 (0x810601010101)
Sep 23 09:59:48.096: Vi2.1 IPCP:    SecondaryDNS 9.9.9.10 (0x83060909090A)
Sep 23 09:59:48.096: Vi2.1 LCP: O PROTREJ [Open] id 3 len 28 protocol IPCP 
Sep 23 09:59:48.096: Vi2.1 LCP: (0x01B100160306B98EE3C8810601010101)
Sep 23 09:59:48.096: Vi2.1 LCP: (0x83060909090A)
Sep 23 09:59:48.254: Vi2.1 IPCP: I CONFREQ [UNKNOWN] id 178 len 22
Sep 23 09:59:48.254: Vi2.1 IPCP:    Address A.A.A.A (0x0306B98EE3C8)
Sep 23 09:59:48.254: Vi2.1 IPCP:    PrimaryDNS 1.1.1.1 (0x810601010101)
Sep 23 09:59:48.254: Vi2.1 IPCP:    SecondaryDNS 9.9.9.10 (0x83060909090A)
Sep 23 09:59:48.254: Vi2.1 LCP: O PROTREJ [Open] id 4 len 28 protocol IPCP 
Sep 23 09:59:48.254: Vi2.1 LCP: (0x01B200160306B98EE3C8810601010101)
Sep 23 09:59:48.254: Vi2.1 LCP: (0x83060909090A)

What is going wrong:

- LCP is fine for both connection attempts

- The ASR sometimes decides it has BCP configured and starts the initialization process:

Sep 23 09:59:46.497: Vi2.1 BCP: Protocol configured, start CP. state[Initial]

- The modem seems to give back some odd response (we have the same issue on the AVM Fritzbox 7530/7590 as on Mikrotik RB4011's):

Sep 23 09:59:46.497: Vi2.1 BCP: Event[OPEN] State[Initial to Starting]
Sep 23 09:59:46.497: Vi2.1 BCP: O CONFREQ [Starting] id 1 len 11
Sep 23 09:59:46.497: Vi2.1 BCP:    Tagged Enable (0x080301)
Sep 23 09:59:46.498: Vi2.1 BCP:    Mgmt Inline (0x0902)
Sep 23 09:59:46.498: Vi2.1 BCP:    BPDU Indicator (0x0A02)
Sep 23 09:59:46.498: Vi2.1 BCP: Event[UP] State[Starting to REQsent]
Sep 23 09:59:46.507: Vi2.1 LCP: I PROTREJ [Open] id 5 len 17 protocol BCP (0x0101000B08030109020A02)
Sep 23 09:59:46.507: Vi2.1 BCP: Event[Receive CodeRej-] State[REQsent to Stopped]

- After this the IPCP part fails and the flooding starts (as the ASR decided BCP is the way to go):

Sep 23 09:59:46.507: Vi2.1 IPCP: I CONFREQ [UNKNOWN] id 176 len 22
Sep 23 09:59:46.507: Vi2.1 IPCP:    Address 185.142.227.200 (0x0306B98EE3C8)
Sep 23 09:59:46.507: Vi2.1 IPCP:    PrimaryDNS 1.1.1.1 (0x810601010101)
Sep 23 09:59:46.507: Vi2.1 IPCP:    SecondaryDNS 9.9.9.10 (0x83060909090A)
Sep 23 09:59:46.507: Vi2.1 LCP: O PROTREJ [Open] id 2 len 28 protocol IPCP 
Sep 23 09:59:46.507: Vi2.1 LCP: (0x01B000160306B98EE3C8810601010101)
Sep 23 09:59:46.508: Vi2.1 LCP: (0x83060909090A)

- There is no disconnect even after following statements are in the virtual-template configuration:

peer ip address forced

ppp ipcp address required

And yes, I'm aware this is a confliciting the required flag, but removing it wont help (the ipcp is not required, just turned on as I'm trying to figure out why this specific case fails)

 ppp ncp passive ipcp ipv6cp

I have been looking at this now for multiple days and I can't really see what's missing or misconfigured. It would be fine for me to turn off BCP completely but I cannot find anything in the command reference guide related to this. Any help at all is greatly appreciated.