[c-nsp] ASR1k PPPoE "AC: Cannot open PPPoE session."

[Patrick Cole]

Hi all,

Doing some lab work with an ASR1001 as a PPPoE AC and am getting 
the following back in the PADS packet being sent back to the PPPoE
client from the ASR:

echo: pppoe,debug,packet ether1.599: rcvd PADS from 88:F0:31:9F:14:81
echo: pppoe,debug,packet     session-id=0x0000
echo: pppoe,debug,packet     host-uniq=0x8ccb000c
echo: pppoe,debug,packet     service-name=
echo: pppoe,debug,packet     ac-cookie=86 3d bb 66 82 67 10 25 c1 6b b0 79 80 e6
34 4d
echo: pppoe,debug,packet     ac-system-error=AC: Cannot open PPPoE session.
echo: pppoe,debug,packet     session-id=0x0000

The system error "AC: Cannot open PPPoE session." above, is the issue.

The debug on the ASR is as follows:

*Mar 23 19:15:40.399: PPPoE 0: I PADI  R:4c5e.0c24.166a L:ffff.ffff.ffff 599 Gi0/0/1.599
contiguous pak, size 36
	 FF FF FF FF FF FF 4C 5E 0C 24 16 6A 81 00 02 57
	 88 63 11 09 00 00 00 0C 01 03 00 04 09 00 CF 8C
	 01 01 00 00
*Mar 23 19:15:40.399:  Service tag: NULL Tag
*Mar 23 19:15:40.399: PPPoE: PADO id 10: Starting timer for 5 msec
*Mar 23 19:15:40.400: PPPoE: Sending PADO for pado id 10
*Mar 23 19:15:40.400: PPPoE 0: O PADO, R:88f0.319f.1481 L:4c5e.0c24.166a 599 Gi0/0/1.599
*Mar 23 19:15:40.400:  Service tag: NULL Tag
contiguous pak, size 69
	 4C 5E 0C 24 16 6A 88 F0 31 9F 14 81 81 00 02 57
	 88 63 11 07 00 00 00 2D 01 03 00 04 09 00 CF 8C
	 01 01 00 00 01 02 00 09 63 6F 72 31 2E 62 72 69
	 31 01 04 00 10 86 3D BB 66 82 67 10 25 C1 6B B0
	 79 80 E6 34 4D
*Mar 23 19:15:40.402: PPPoE 0: I PADR  R:4c5e.0c24.166a L:88f0.319f.1481 599 Gi0/0/1.599
contiguous pak, size 56
	 88 F0 31 9F 14 81 4C 5E 0C 24 16 6A 81 00 02 57
	 88 63 11 19 00 00 00 20 01 03 00 04 0A 00 CF 8C
	 01 01 00 00 01 04 00 10 86 3D BB 66 82 67 10 25
	 C1 6B B0 79 80 E6 34 4D
*Mar 23 19:15:40.403:  Service tag: NULL Tag
*Mar 23 19:15:40.403: PPPoE : encap string prepared
contiguous pak, size 24
	 4C 5E 0C 24 16 6A 88 F0 31 9F 14 81 81 00 02 57
	 88 64 11 00 00 0B 00 00
*Mar 23 19:15:40.403: [11]PPPoE 11: Access IE handle allocated
*Mar 23 19:15:40.403: [11]PPPoE 11: AAA get retrieved attrs
*Mar 23 19:15:40.403: [11]PPPoE 11: AAA get nas port details
*Mar 23 19:15:40.403: [11]PPPoE 11: Error adjusting nas port format did 
*Mar 23 19:15:40.403: [11]PPPoE 11: AAA get dynamic attrs
*Mar 23 19:15:40.403: [11]PPPoE 11: AAA unique ID 16 allocated
*Mar 23 19:15:40.403: [11]PPPoE 11: AAA method list  set
*Mar 23 19:15:40.403: [11]PPPoE 11: Service request sent to SSS
*Mar 23 19:15:40.403: [11]PPPoE 11: Created, Service: None R:88f0.319f.1481 L:4c5e.0c24.166a 599 Gi0/0/1.599
*Mar 23 19:15:40.403: [11]PPPoE 11: State NAS_PORT_POLICY_INQUIRY    Event SSS DISCONNECT
*Mar 23 19:15:40.403: [11]PPPoE 0: O PADS  R:4c5e.0c24.166a L:88f0.319f.1481 Gi0/0/1.599
contiguous pak, size 90
	 4C 5E 0C 24 16 6A 88 F0 31 9F 14 81 81 00 02 57
	 88 63 11 65 00 00 00 42 01 03 00 04 0A 00 CF 8C
	 01 01 00 00 01 04 00 10 86 3D BB 66 82 67 10 25
	 C1 6B B0 79 80 E6 34 4D 02 02 00 1E 41 43 3A 20
	 43 61 6E 6E 6F 74 20 6F ...
*Mar 23 19:15:40.403: [11]PPPoE 11: Destroying  R:4c5e.0c24.166a L:88f0.319f.1481 599 Gi0/0/1.599
*Mar 23 19:15:40.403: [11]PPPoE 11: AAA get dynamic attrs
*Mar 23 19:15:40.403: [11]PPPoE 11: AAA get dynamic attrs
*Mar 23 19:15:40.404: [11]PPPoE 11: AAA get dynamic attrs
*Mar 23 19:15:40.404: [11]PPPoE 11: AAA account stopped

I pretty much copied a working bba-group/vpdn config from an existing 7200VXR.
Doesn't seem we're ever getting to the point of even starting PPP.  The ASR
just sends the PADS with that error then destroys the session.

It may be something simple, but I can't find anything useful on the web about
this particular condition.  

Has anyone seen this before?

Regards,

Patrick