Hi guys,
I’ve been struggling with a problem for the past few weeks and I would very much welcome any thoughts or fresh eyes (I’m going more than a little bit nuts at this stage).
Any help would be very much appreciated.
All the best,
Colin
Problem Description (for wired dot1x authentication)
Situation:
Pair of clustered MAG2600’s configured as UAC with IF-MAP federation enabled.
Pulse Policy Secure software version is 5.3R5 (unfortunately I’m out of support so can’t upgrade to the latest version)
Pulse Client
EX2200 switch configured as an authenticator (Software version 12.3R12.4), authenticating against Active Directory
SRX 100 is the DHCP server attached to the EX2200
Within the network a number of SRX devices are used as infranet Enforcers
Windows 7 Professional SP1
Some other errors or issues I’m seeing
802.1x authentication protocols used on the Policy Secure Device are:
EX2200 switch configuration
set access radius-server 192.168.0.11 secret SECRET
set access radius-server 192.168.0.11 source-address Source_IP
set access profile UacProfile authentication-order radius
set access profile UacProfile radius authentication-server 192.168.0.11
set ethernet-switching-options uac-policy
I’ve tried lots of port configurations including:
Configuration #1
set protocols dot1x authenticator interface ge-0/0/8.0 supplicant single
set protocols dot1x authenticator interface ge-0/0/8.0 retries 4
set protocols dot1x authenticator interface ge-0/0/8.0 quiet-period 1
Configuration #2
set protocols dot1x authenticator interface ge-0/0/9.0 supplicant single
set protocols dot1x authenticator interface ge-0/0/9.0 retries 10
set protocols dot1x authenticator interface ge-0/0/9.0 quiet-period 1
set protocols dot1x authenticator interface ge-0/0/9.0 transmit-period 5
set protocols dot1x authenticator interface ge-0/0/9.0 reauthentication 3600
set protocols dot1x authenticator interface ge-0/0/9.0 supplicant-timeout 20
set protocols dot1x authenticator interface ge-0/0/9.0 server-timeout 10
set protocols dot1x authenticator interface ge-0/0/9.0 maximum-requests 3
set protocols dot1x authenticator interface ge-0/0/9.0 server-fail use-cache
Configuration #3
set protocols dot1x authenticator interface ge-0/0/8.0 server-reject-vlan QUARANTING_ROLE
set protocols dot1x authenticator interface ge-0/0/8.0 server-reject-vlan block-interval 130
set protocols dot1x authenticator interface ge-0/0/8.0 server-reject-vlan eapol-block
show dot1x interface ge-0/0/8.0 detail
ge-0/0/8.0
Role: Authenticator
Administrative state: Auto
Supplicant mode: Single
Number of retries: 4
Quiet period: 1 seconds
Transmit period: 30 seconds
Mac Radius: Disabled
Mac Radius Restrict: Disabled
Reauthentication: Enabled
Configured Reauthentication interval: 3600 seconds
Supplicant timeout: 30 seconds
Server timeout: 30 seconds
Maximum EAPOL requests: 2
Guest VLAN member: <not configured>
Number of connected supplicants: 1
Supplicant: anonymous, 00:8C:FA:81:90:6C
Operational state: Authenticated
Backend Authentication state: Idle
Authentcation method: Radius
Authenticated VLAN: USER_ROLES
Session Reauth interval: 86280 seconds
Reauthentication due in 86271 seconds
dot1x log from ex2200 when error message "TLS handshake failure"
=~=~=~=~=~=~=~=~=~=~=~= PuTTY log 2018.11.14 15:50:49 =~=~=~=~=~=~=~=~=~=~=~=
Nov 14 15:50:56.685160 Task receive function invoked
Nov 14 15:50:56.688539 EAPOL packet received on interface ge-0/0/8.0
Nov 14 15:50:56.689175 Creating background job to process EAPOL frame
Nov 14 15:50:56.691619 Entering background job to process received EAPOL frames rx_frame_node_count=1
Nov 14 15:50:56.692401 Invoking state machine for frame received on interface ge-0/0/8
Nov 14 15:50:56.693160 Received an EAPOL Frame...
Nov 14 15:50:56.697367 Frame is targetted to this machine...
Nov 14 15:50:56.699166 EAPOL Frame Received on Port: 78 !!!
Nov 14 15:50:56.702634 AuthHandleInEapFrame: Received Port based Eap Frame
Nov 14 15:50:56.706370 ASM Called with Event: EAPSTART_RCVD, and State: Authenticated
Nov 14 15:50:56.709363 for Port: 78, MAC: 8cfa81 - 906c
Nov 14 15:50:56.711163 Id: 19, SessionNode: 381000
Nov 14 15:50:56.715367 ASM CONNECTING : Intf ge-0/0/8.0: ReqId Count 0 Reauth Count 0
Nov 14 15:50:56.718648 ASM moved to state: CONNECTING !!
Nov 14 15:50:56.718896 TMR: Transmit Timer Started for port:78, Duration: 30 !!
Nov 14 15:50:56.721180 TMR: Timer is started
Nov 14 15:50:56.723620 Queuing EAPOL frame to be transmitted out on interface ge-0/0/8
Nov 14 15:50:56.726397 EAP Frame Sent with code: 1 !!!
Nov 14 15:50:56.728416 EAP Req Id Frame Sent !!!
Nov 14 15:50:56.730467 Processing complete for frame received on interface ge-0/0/8
Nov 14 15:50:56.731165 Deleted background job to process received EAPOL frames
Nov 14 15:50:56.737526 Task transmit function invoked
Nov 14 15:50:56.738318 EAPOL frame transmitted out on interface (ge-0/0/8.0)
Nov 14 15:50:56.741660 State: 3 Reauth: 0
Nov 14 15:50:56.748482 State: 3 Reauth: 0
Nov 14 15:50:56.845297 pnac_cleanup_white_list_entries_on_vmember_del:374:CP_DEBUG:
Nov 14 15:50:56.845838 pnac_cleanup_white_list_entries_on_vmember_del:374:CP_DEBUG:
Nov 14 15:50:56.846928 pnac_cleanup_white_list_entries_on_vmember_del:374:CP_DEBUG:
Nov 14 15:50:56.847687 pnac_cleanup_white_list_entries_on_vmember_del:374:CP_DEBUG:
Nov 14 15:50:56.895902 Task receive function invoked
Nov 14 15:50:56.897423 EAPOL packet received on interface ge-0/0/8.0
Nov 14 15:50:56.897884 Creating background job to process EAPOL frame
Nov 14 15:50:56.898492 Entering background job to process received EAPOL frames rx_frame_node_count=1
Nov 14 15:50:56.898941 Invoking state machine for frame received on interface ge-0/0/8
Nov 14 15:50:56.899669 Received an EAPOL Frame...
Nov 14 15:50:56.900261 Frame is targetted to this machine...
Nov 14 15:50:56.900472 EAPOL Frame Received on Port: 78 !!!
Nov 14 15:50:56.900680 AuthHandleInEapFrame: Received Port based Eap Frame
Nov 14 15:50:56.900915 ASM Called with Event: RXRESPID, and State: Connecting
Nov 14 15:50:56.902173 for Port: 78, MAC: 8cfa81 - 906c
Nov 14 15:50:56.902400 Id: 19, SessionNode: 381000
Nov 14 15:50:56.902593 ASM: Inside PnacAuthAsmRxrespConnecting
Nov 14 15:50:56.902806 TMR: Timer is deleted
Nov 14 15:50:56.904142 ASM moved to state: AUTHENTICATING !!
Nov 14 15:50:56.904379 BSM Called with Event: AUTHSTART, and State: Idle
Nov 14 15:50:56.904588 for Port: 78, MAC: 8cfa81-906c
Nov 14 15:50:56.904788 Id: 19, SessionNode: 381000
Nov 14 15:50:56.905918 TMR: Timer is started
Nov 14 15:50:56.908331 BSM moved to state: RESPONSE !!
Nov 14 15:50:56.909392 ASIF: Transferring Server-data to Auth Server for the user, anonymous.
Nov 14 15:50:56.909642 SessId: 8O2.1x81f5011a000a6e09 strlen: 22
Nov 14 15:50:56.909944 Queuing message to auth client to validate mac address 0:8c:fa:81:90:6c, user anonymous on interface ge-0/0/8.0
Nov 14 15:50:56.910624 ASIF: Radius REQUEST_ID: ce
Nov 14 15:50:56.911377 ASIF: Tx of Server-data to Auth Server succeeded
Nov 14 15:50:56.912243 Processing complete for frame received on interface ge-0/0/8
Nov 14 15:50:56.912417 Deleted background job to process received EAPOL frames
Nov 14 15:50:56.912680 pnac_auth_client_transmit_job created
Nov 14 15:50:56.914209 Sending message to authentication client
Nov 14 15:50:56.915442 pnac_auth_client_transmit_job: pnac_auth_client_transmit_job is deleted. num packets: 1
Nov 14 15:50:56.940617 pnac_auth_client_receive: receive job not found - creating now
Nov 14 15:50:56.941496 Received message from authentication client
Nov 14 15:50:56.942240 reply: 207910 rply_hdr: 20e000 bytes_remnant :0 len:-1 reply_len:28
Nov 14 15:50:56.942707 hdr_bytes_read 0
Nov 14 15:50:56.943801 len read : 28 reply_len: 3972 reply_code: 8
Nov 14 15:50:56.943986 bytes_remnant 3944 tot_bytes_read 28
Nov 14 15:50:56.945447 bytes_read 3944
Nov 14 15:50:56.945608 Creating background job to process reply from authentication client
Nov 14 15:50:56.945752 Received message from authentication client
Nov 14 15:50:56.945892 reply: 207910 rply_hdr: 20e000 bytes_remnant :0 len:3972 reply_len:3972
Nov 14 15:50:56.947562 EAGAIN during hdr len read, try again
Nov 14 15:50:56.948311 process_auth_reply: Entering background job to process message from authentication client
Nov 14 15:50:56.948848 process_auth_reply Reponse from Authentication Client len:3972 for SessID: 9364392189893188029
Nov 14 15:50:56.949461 Received Access-Challenge authentication message
Nov 14 15:50:56.949653 Invoking state machine for authentication response for mac 00:8c:fa:81:90:6c on intf ge-0/0/8.0
Nov 14 15:50:56.949821 UAC: authenticatingStateCause (100)
Nov 14 15:50:56.949970 ASIF: Handing over Server frame to Authenticator
Nov 14 15:50:56.951393 AUTH: Handling Server Frame
Nov 14 15:50:56.951631 SessNode got from SessIdtbl for Id 20 is : 381000, Port: 78
Nov 14 15:50:56.951829 Code = 1, Id = 20, Len = 74
Nov 14 15:50:56.952483 BSM Called with Event: AREQ_RCVD, and State: Response
Nov 14 15:50:56.953578 for Port: 78, MAC: 8cfa81-906c
Nov 14 15:50:56.954499 Id: 19, SessionNode: 381000
Nov 14 15:50:56.956880 TMR: Timer is deleted
Nov 14 15:50:56.959610 Queuing EAPOL frame to be transmitted out on interface ge-0/0/8
Nov 14 15:50:56.964170 EAP Req Frame Sent !!!
Nov 14 15:50:56.970562 TMR: Timer is started
Nov 14 15:50:56.975293 BSM moved to state: REQUEST !!
Nov 14 15:50:56.978641 ASIF: Handing over Server frame to Authenticator 78.
Nov 14 15:50:56.981318 PnacAsIfRecvFromServer : Rad Attr Statelen = 15
Nov 14 15:50:56.983727 ASIF: Received No Key from Server
Nov 14 15:50:56.990324 Processing authentication response complete
Nov 14 15:50:56.990502 Deleted background job to process replies from authentication client
Nov 14 15:50:56.990769 Task transmit function invoked
Nov 14 15:50:56.995958 EAPOL frame transmitted out on interface (ge-0/0/8.0)
Nov 14 15:50:57.403311 Task receive function invoked
Nov 14 15:50:57.404608 EAPOL packet received on interface ge-0/0/8.0
Nov 14 15:50:57.405212 Creating background job to process EAPOL frame
Nov 14 15:50:57.405754 Entering background job to process received EAPOL frames rx_frame_node_count=1
Nov 14 15:50:57.407295 Invoking state machine for frame received on interface ge-0/0/8
Nov 14 15:50:57.407732 Received an EAPOL Frame...
Nov 14 15:50:57.408886 Frame is targetted to this machine...
Nov 14 15:50:57.409762 EAPOL Frame Received on Port: 78 !!!
Nov 14 15:50:57.410908 AuthHandleInEapFrame: Received Port based Eap Frame
Nov 14 15:50:57.411799 BSM Called with Event: RXRESP, and State: Request
Nov 14 15:50:57.412944 for Port: 78, MAC: 8cfa81-906c
Nov 14 15:50:57.413803 Id: 20, SessionNode: 381000
Nov 14 15:50:57.415104 TMR: Timer is deleted
Nov 14 15:50:57.415935 TMR: Timer is started
Nov 14 15:50:57.417786 BSM moved to state: RESPONSE !!
Nov 14 15:50:57.418686 ASIF: Transferring Server-data to Auth Server for the user, anonymous.
Nov 14 15:50:57.419873 SessId: 8O2.1x81f5011a000a6e09 strlen: 22
Nov 14 15:50:57.420542 Queuing message to auth client to validate mac address 0:8c:fa:81:90:6c, user anonymous on interface ge-0/0/8.0
Nov 14 15:50:57.421945 ASIF: Radius REQUEST_ID: cf
Nov 14 15:50:57.422446 ASIF: Tx of Server-data to Auth Server succeeded
Nov 14 15:50:57.424335 Processing complete for frame received on interface ge-0/0/8
Nov 14 15:50:57.424790 Deleted background job to process received EAPOL frames
Nov 14 15:50:57.425687 pnac_auth_client_transmit_job created
Nov 14 15:50:57.427897 Sending message to authentication client
Nov 14 15:50:57.431948 pnac_auth_client_transmit_job: pnac_auth_client_transmit_job is deleted. num packets: 1
Nov 14 15:50:57.469629 pnac_auth_client_receive: receive job not found - creating now
Nov 14 15:50:57.470387 Received message from authentication client
Nov 14 15:50:57.470562 reply: 207910 rply_hdr: 20e000 bytes_remnant :0 len:-1 reply_len:3972
Nov 14 15:50:57.470736 hdr_bytes_read 0
Nov 14 15:50:57.470879 len read : 28 reply_len: 3972 reply_code: 8
Nov 14 15:50:57.473972 bytes_remnant 3944 tot_bytes_read 28
Nov 14 15:50:57.479627 bytes_read 3944
Nov 14 15:50:57.479791 Creating background job to process reply from authentication client
Nov 14 15:50:57.479939 Received message from authentication client
Nov 14 15:50:57.484148 reply: 2078ac rply_hdr: 20e000 bytes_remnant :0 len:3972 reply_len:3972
Nov 14 15:50:57.485594 EAGAIN during hdr len read, try again
Nov 14 15:50:57.488148 process_auth_reply: Entering background job to process message from authentication client
Nov 14 15:50:57.489900 process_auth_reply Reponse from Authentication Client len:3972 for SessID: 9364392189893188029
Nov 14 15:50:57.493380 Received Access-Challenge authentication message
Nov 14 15:50:57.498175 Invoking state machine for authentication response for mac 00:8c:fa:81:90:6c on intf ge-0/0/8.0
Nov 14 15:50:57.501413 UAC: authenticatingStateCause (100)
Nov 14 15:50:57.502386 ASIF: Handing over Server frame to Authenticator
Nov 14 15:50:57.505797 AUTH: Handling Server Frame
Nov 14 15:50:57.507369 SessNode got from SessIdtbl for Id 21 is : 381000, Port: 78
Nov 14 15:50:57.510120 Code = 1, Id = 21, Len = 147
Nov 14 15:50:57.512166 BSM Called with Event: AREQ_RCVD, and State: Response
Nov 14 15:50:57.515358 for Port: 78, MAC: 8cfa81-906c
Nov 14 15:50:57.519359 Id: 20, SessionNode: 381000
Nov 14 15:50:57.522241 TMR: Timer is deleted
Nov 14 15:50:57.528180 Queuing EAPOL frame to be transmitted out on interface ge-0/0/8
Nov 14 15:50:57.530909 EAP Req Frame Sent !!!
Nov 14 15:50:57.532710 TMR: Timer is started
Nov 14 15:50:57.533466 BSM moved to state: REQUEST !!
Nov 14 15:50:57.533751 ASIF: Handing over Server frame to Authenticator 78.
Nov 14 15:50:57.533977 PnacAsIfRecvFromServer : Rad Attr Statelen = 15
Nov 14 15:50:57.534831 ASIF: Received No Key from Server
Nov 14 15:50:57.535932 Processing authentication response complete
Nov 14 15:50:57.537390 Deleted background job to process replies from authentication client
Nov 14 15:50:57.537678 Task transmit function invoked
Nov 14 15:50:57.539382 EAPOL frame transmitted out on interface (ge-0/0/8.0)
Nov 14 15:50:57.539894 UAC: processing add message for (00:8c:fa:81:90:6c) from uacd
Nov 14 15:50:57.542202 UAC: Process EAP success for the mac (00:8c:fa:81:90:6c)
Nov 14 15:50:57.542672 UAC: Auth add message received from uacd. mac (00:8c:fa:81:90:6c) will be authenticated
Nov 14 15:50:57.544160 UAC: Handle vlan membership during auth reply
Nov 14 15:50:57.544426 UAC: mac address (00:8c:fa:81:90:6c) is learnt
Nov 14 15:50:57.544652 ASIF: Handing over Server frame to Authenticator
Nov 14 15:50:57.544881 AUTH: Handling Server Frame
Nov 14 15:50:57.546788 SessNode got from SessIdtbl for Id 18 is : 381000, Port: 78
Nov 14 15:50:57.549623 Code = 3, Id = 18, Len = 1024
Nov 14 15:50:57.549841 AuthHandleInServerFrame : Intf: ge-0/0/8.0 Timeout 86280 for
Nov 14 15:50:57.551974 BSM Called with Event: ASUCCESS_RCVD, and State: Request
Nov 14 15:50:57.553363 for Port: 78, MAC: 8cfa81-906c
Nov 14 15:50:57.554150 Id: 21, SessionNode: 381000
Nov 14 15:50:57.554368 BSM: No Operations to perform
Nov 14 15:50:57.554575 ASIF: Handing over Server frame to Authenticator 78.
Nov 14 15:50:57.554787 PnacAsIfRecvFromServer : Rad Attr Statelen = 0
Nov 14 15:50:57.554923 ASIF: Received No Key from Server
Nov 14 15:50:57.556771 ACCTG State no change
Nov 14 15:50:57.557679 Task receive function invoked
Nov 14 15:50:57.559622 EAPOL packet received on interface ge-0/0/8.0
Nov 14 15:50:57.559815 Creating background job to process EAPOL frame
Nov 14 15:50:57.560374 Entering background job to process received EAPOL frames rx_frame_node_count=1
Nov 14 15:50:57.560539 Invoking state machine for frame received on interface ge-0/0/8
Nov 14 15:50:57.560677 Received an EAPOL Frame...
Nov 14 15:50:57.560885 Frame is targetted to this machine...
Nov 14 15:50:57.561496 EAPOL Frame Received on Port: 78 !!!
Nov 14 15:50:57.561715 AuthHandleInEapFrame: Received Port based Eap Frame
Nov 14 15:50:57.561944 BSM Called with Event: RXRESP, and State: Request
Nov 14 15:50:57.562277 for Port: 78, MAC: 8cfa81-906c
Nov 14 15:50:57.562484 Id: 21, SessionNode: 381000
Nov 14 15:50:57.562781 TMR: Timer is deleted
Nov 14 15:50:57.563745 TMR: Timer is started
Nov 14 15:50:57.564027 BSM moved to state: RESPONSE !!
Nov 14 15:50:57.570302 ASIF: Transferring Server-data to Auth Server for the user, anonymous.
Nov 14 15:50:57.572138 SessId: 8O2.1x81f5011a000a6e09 strlen: 22
Nov 14 15:50:57.574876 Queuing message to auth client to validate mac address 0:8c:fa:81:90:6c, user anonymous on interface ge-0/0/8.0
Nov 14 15:50:57.577346 ASIF: Radius REQUEST_ID: d0
Nov 14 15:50:57.578117 ASIF: Tx of Server-data to Auth Server succeeded
Nov 14 15:50:57.581640 Processing complete for frame received on interface ge-0/0/8
Nov 14 15:50:57.584745 Deleted background job to process received EAPOL frames
Nov 14 15:50:57.586875 pnac_auth_client_transmit_job created
Nov 14 15:50:57.652827 Sending message to authentication client
Nov 14 15:50:57.660174 pnac_auth_client_transmit_job: pnac_auth_client_transmit_job is deleted. num packets: 1
Nov 14 15:50:57.688831 pnac_auth_client_receive: receive job not found - creating now
Nov 14 15:50:57.690893 Received message from authentication client
Nov 14 15:50:57.726151 reply: 2078ac rply_hdr: 20e000 bytes_remnant :0 len:-1 reply_len:3972
Nov 14 15:50:57.731816 hdr_bytes_read 0
Nov 14 15:50:57.733545 len read : 28 reply_len: 3972 reply_code: 8
Nov 14 15:50:57.735541 bytes_remnant 3944 tot_bytes_read 28
Nov 14 15:50:57.736178 bytes_read 3944
Nov 14 15:50:57.737344 Creating background job to process reply from authentication client
Nov 14 15:50:57.740716 Received message from authentication client
Nov 14 15:50:57.742934 reply: 207898 rply_hdr: 20e000 bytes_remnant :0 len:3972 reply_len:3972
Nov 14 15:50:57.757132 EAGAIN during hdr len read, try again
Nov 14 15:50:57.758554 process_auth_reply: Entering background job to process message from authentication client
Nov 14 15:50:57.759847 process_auth_reply Reponse from Authentication Client len:3972 for SessID: 9364392189893188029
Nov 14 15:50:57.761958 Received Access-Challenge authentication message
Nov 14 15:50:57.771145 Invoking state machine for authentication response for mac 00:8c:fa:81:90:6c on intf ge-0/0/8.0
Nov 14 15:50:57.771628 UAC: authenticatingStateCause (100)
Nov 14 15:50:57.772417 ASIF: Handing over Server frame to Authenticator
Nov 14 15:50:57.774443 AUTH: Handling Server Frame
Nov 14 15:50:57.775312 SessNode got from SessIdtbl for Id 22 is : 381000, Port: 78
Nov 14 15:50:57.776472 Code = 1, Id = 22, Len = 74
Nov 14 15:50:57.777363 BSM Called with Event: AREQ_RCVD, and State: Response
Nov 14 15:50:57.778509 for Port: 78, MAC: 8cfa81-906c
Nov 14 15:50:57.780349 Id: 21, SessionNode: 381000
Nov 14 15:50:57.781325 TMR: Timer is deleted
Nov 14 15:50:57.782563 Queuing EAPOL frame to be transmitted out on interface ge-0/0/8
Nov 14 15:50:57.783589 EAP Req Frame Sent !!!
Nov 14 15:50:57.784742 TMR: Timer is started
Nov 14 15:50:57.785629 BSM moved to state: REQUEST !!
Nov 14 15:50:57.786787 ASIF: Handing over Server frame to Authenticator 78.
Nov 14 15:50:57.787684 PnacAsIfRecvFromServer : Rad Attr Statelen = 15
Nov 14 15:50:57.788479 ASIF: Received No Key from Server
Nov 14 15:50:57.796769 Processing authentication response complete
Nov 14 15:50:57.797577 Deleted background job to process replies from authentication client
Nov 14 15:50:57.800299 Task transmit function invoked
Nov 14 15:50:57.802122 EAPOL frame transmitted out on interface (ge-0/0/8.0)
ops... This should have read
"EX2200 switch configured as an radius authenticator (Software version 12.3R12.4), authenticating the Pulse Policy Secure which in turn is querying Active Directory"