-Tried to do step 16.3 of the install guide. It is unfortunately not up to date so I had to try and figure out the new directory structure. I think I was successful because the radius service starts normally.
From: "Jay Hauss" <jayha...@gmx.com>
To: "Mathias Didier" <mathias.did...@etrex.ch>
Subject: Re: RE: RE: [PacketFence-users] Packetfence 802.1x Radius Server with LDAP Backend (NO AD)
###############
Oct 2 10:28:08 packetfence8-1 auth[43222]: rlm_sql (sql): Opening additional connection (2), 1 of 62 pending slots used
Oct 2 10:28:08 packetfence8-1 auth[43222]: (7) Login incorrect (mschap: Program returned code (1) and output 'Reading winbind reply failed! (0xc0000001)'): [testuser] (from client 10.111.111.2 port 50121 cli a0:ce:c8:09:9a:b4 via TLS tunnel)
Oct 2 10:28:08 packetfence8-1 auth[43222]: (8) eap_peap: This means you need to read the PREVIOUS messages in the debug output
Oct 2 10:28:08 packetfence8-1 auth[43222]: (8) eap_peap: to find out the reason why the user was rejected
Oct 2 10:28:08 packetfence8-1 auth[43222]: (8) eap_peap: Look for "reject" or "fail". Those earlier messages will tell you
Oct 2 10:28:08 packetfence8-1 auth[43222]: (8) eap_peap: what went wrong, and how to fix the problem
Oct 2 10:28:08 packetfence8-1 auth[43222]: (8) Login incorrect (eap_peap: The users session was previously rejected: returning reject (again.)): [testuser] (from client 10.111.111.2 port 50121 cli a0:ce:c8:09:9a:b4)
Oct 2 10:28:08 packetfence8-1 auth[43222]: [mac:a0:ce:c8:09:9a:b4] Rejected user: testuser
(7) Tue Oct 2 10:28:08 2018: Debug: Virtual server sending reply
(7) Tue Oct 2 10:28:08 2018: Debug: MS-CHAP-Error = "\010E=691 R=0 C=b4d279a9d28c5d52009431b95d24f742 V=3 M=Authentication failed"
(7) Tue Oct 2 10:28:08 2018: Debug: EAP-Message = 0x04080004
(7) Tue Oct 2 10:28:08 2018: Debug: Message-Authenticator = 0x00000000000000000000000000000000
(7) Tue Oct 2 10:28:08 2018: Debug: eap_peap: Got tunneled reply code 3
(7) Tue Oct 2 10:28:08 2018: Debug: eap_peap: MS-CHAP-Error = "\010E=691 R=0 C=b4d279a9d28c5d52009431b95d24f742 V=3 M=Authentication failed"
(7) Tue Oct 2 10:28:08 2018: Debug: eap_peap: EAP-Message = 0x04080004
(7) Tue Oct 2 10:28:08 2018: Debug: eap_peap: Message-Authenticator = 0x00000000000000000000000000000000
(7) Tue Oct 2 10:28:08 2018: Debug: eap_peap: Tunneled authentication was rejected
(7) Tue Oct 2 10:28:08 2018: Debug: eap_peap: FAILURE
(7) Tue Oct 2 10:28:08 2018: Debug: eap: Sending EAP Request (code 1) ID 9 length 46
(7) Tue Oct 2 10:28:08 2018: Debug: eap: EAP session adding &reply:State = 0x516a5d37566344c3
(7) Tue Oct 2 10:28:08 2018: Debug: [eap] = handled
(7) Tue Oct 2 10:28:08 2018: Debug: } # authenticate = handled
(7) Tue Oct 2 10:28:08 2018: Debug: Using Post-Auth-Type Challenge
(7) Tue Oct 2 10:28:08 2018: Debug: Post-Auth-Type sub-section not found. Ignoring.
(7) Tue Oct 2 10:28:08 2018: Debug: # Executing group from file /usr/local/pf/raddb/sites-enabled/packetfence
(7) Tue Oct 2 10:28:08 2018: Debug: session-state: Saving cached attributes
(7) Tue Oct 2 10:28:08 2018: Debug: Module-Failure-Message := "mschap: Program returned code (1) and output 'Reading winbind reply failed! (0xc0000001)'"
(7) Tue Oct 2 10:28:08 2018: Debug: Sent Access-Challenge Id 247 from 10.111.111.1:1812 to 10.111.111.2:1645 length 0
(7) Tue Oct 2 10:28:08 2018: Debug: EAP-Message = 0x0109002e190017030300232f1f04f3bde47b0c6c56808ae4884450015712a80f6fc413477086802979edca38982d
(7) Tue Oct 2 10:28:08 2018: Debug: Message-Authenticator = 0x00000000000000000000000000000000
(7) Tue Oct 2 10:28:08 2018: Debug: State = 0x516a5d37566344c31362bff433ba8599
(7) Tue Oct 2 10:28:08 2018: Debug: Finished request
(8) Tue Oct 2 10:28:08 2018: Debug: Received Access-Request Id 248 from 10.111.111.2:1645 to 10.111.111.1:1812 length 303
(8) Tue Oct 2 10:28:08 2018: Debug: User-Name = "testuser"
(8) Tue Oct 2 10:28:08 2018: Debug: Service-Type = Framed-User
(8) Tue Oct 2 10:28:08 2018: Debug: Cisco-AVPair = "service-type=Framed"
(8) Tue Oct 2 10:28:08 2018: Debug: Framed-MTU = 1500
(8) Tue Oct 2 10:28:08 2018: Debug: Called-Station-Id = "2C-AB-EB-43-57-95"
(8) Tue Oct 2 10:28:08 2018: Debug: Calling-Station-Id = "A0-CE-C8-09-9A-B4"
(8) Tue Oct 2 10:28:08 2018: Debug: EAP-Message = 0x0209002e19001703030023000000000000000366b6a5e833b98aa5e66eda6d6bc55e2e155e6e91f9c844b30860ea
(8) Tue Oct 2 10:28:08 2018: Debug: Message-Authenticator = 0x9cb7174d9163358323d7e8617a6cb9f5
(8) Tue Oct 2 10:28:08 2018: Debug: Cisco-AVPair = "audit-session-id=0A6F6F02000000362599F393"
(8) Tue Oct 2 10:28:08 2018: Debug: Cisco-AVPair = "method=dot1x"
(8) Tue Oct 2 10:28:08 2018: Debug: NAS-IP-Address = 10.111.111.2
(8) Tue Oct 2 10:28:08 2018: Debug: NAS-Port-Id = "GigabitEthernet1/0/21"
(8) Tue Oct 2 10:28:08 2018: Debug: NAS-Port-Type = Ethernet
(8) Tue Oct 2 10:28:08 2018: Debug: NAS-Port = 50121
(8) Tue Oct 2 10:28:08 2018: Debug: State = 0x516a5d37566344c31362bff433ba8599
(8) Tue Oct 2 10:28:08 2018: Debug: Restoring &session-state
(8) Tue Oct 2 10:28:08 2018: Debug: &session-state:Module-Failure-Message := "mschap: Program returned code (1) and output 'Reading winbind reply failed! (0xc0000001)'"
(8) Tue Oct 2 10:28:08 2018: Debug: # Executing section authorize from file /usr/local/pf/raddb/sites-enabled/packetfence
(8) Tue Oct 2 10:28:08 2018: Debug: authorize {
(8) Tue Oct 2 10:28:08 2018: Debug: update {
(8) Tue Oct 2 10:28:08 2018: Debug: EXPAND %{Packet-Src-IP-Address}
(8) Tue Oct 2 10:28:08 2018: Debug: --> 10.111.111.2
(8) Tue Oct 2 10:28:08 2018: Debug: EXPAND %l
(8) Tue Oct 2 10:28:08 2018: Debug: --> 1538490488
(8) Tue Oct 2 10:28:08 2018: Debug: } # update = noop
(8) Tue Oct 2 10:28:08 2018: Debug: policy packetfence-set-tenant-id {
(8) Tue Oct 2 10:28:08 2018: Debug: if ( "%{%{control:PacketFence-Tenant-Id}:-0}" == "0") {
(8) Tue Oct 2 10:28:08 2018: Debug: EXPAND %{%{control:PacketFence-Tenant-Id}:-0}
(8) Tue Oct 2 10:28:08 2018: Debug: --> 0
(8) Tue Oct 2 10:28:08 2018: Debug: if ( "%{%{control:PacketFence-Tenant-Id}:-0}" == "0") -> TRUE
(8) Tue Oct 2 10:28:08 2018: Debug: if ( "%{%{control:PacketFence-Tenant-Id}:-0}" == "0") {
(8) Tue Oct 2 10:28:08 2018: Debug: update control {
(8) Tue Oct 2 10:28:08 2018: Debug: EXPAND %{User-Name}
(8) Tue Oct 2 10:28:08 2018: Debug: --> testuser
(8) Tue Oct 2 10:28:08 2018: Debug: SQL-User-Name set to 'testuser'
(8) Tue Oct 2 10:28:08 2018: Debug: Executing select query: SELECT IFNULL((SELECT tenant_id FROM radius_nas WHERE nasname = '10.111.111.2'), 0)
(8) Tue Oct 2 10:28:08 2018: Debug: EXPAND %{sql: SELECT IFNULL((SELECT tenant_id FROM radius_nas WHERE nasname = '%{Packet-Src-IP-Address}'), 0)}
(8) Tue Oct 2 10:28:08 2018: Debug: --> 1
(8) Tue Oct 2 10:28:08 2018: Debug: } # update control = noop
(8) Tue Oct 2 10:28:08 2018: Debug: } # if ( "%{%{control:PacketFence-Tenant-Id}:-0}" == "0") = noop
(8) Tue Oct 2 10:28:08 2018: Debug: if ( &control:PacketFence-Tenant-Id == 0 ) {
(8) Tue Oct 2 10:28:08 2018: Debug: if ( &control:PacketFence-Tenant-Id == 0 ) -> FALSE
(8) Tue Oct 2 10:28:08 2018: Debug: } # policy packetfence-set-tenant-id = noop
(8) Tue Oct 2 10:28:08 2018: Debug: policy rewrite_calling_station_id {
(8) Tue Oct 2 10:28:08 2018: Debug: if (&Calling-Station-Id && (&Calling-Station-Id =~ /^([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})$/i)) {
(8) Tue Oct 2 10:28:08 2018: Debug: if (&Calling-Station-Id && (&Calling-Station-Id =~ /^([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})$/i)) -> TRUE
(8) Tue Oct 2 10:28:08 2018: Debug: if (&Calling-Station-Id && (&Calling-Station-Id =~ /^([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})$/i)) {
(8) Tue Oct 2 10:28:08 2018: Debug: update request {
(8) Tue Oct 2 10:28:08 2018: Debug: EXPAND %{tolower:%{1}:%{2}:%{3}:%{4}:%{5}:%{6}}
(8) Tue Oct 2 10:28:08 2018: Debug: --> a0:ce:c8:09:9a:b4
(8) Tue Oct 2 10:28:08 2018: Debug: } # update request = noop
(8) Tue Oct 2 10:28:08 2018: Debug: [updated] = updated
(8) Tue Oct 2 10:28:08 2018: Debug: } # if (&Calling-Station-Id && (&Calling-Station-Id =~ /^([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})$/i)) = updated
(8) Tue Oct 2 10:28:08 2018: Debug: ... skipping else: Preceding "if" was taken
(8) Tue Oct 2 10:28:08 2018: Debug: } # policy rewrite_calling_station_id = updated
(8) Tue Oct 2 10:28:08 2018: Debug: policy rewrite_called_station_id {
(8) Tue Oct 2 10:28:08 2018: Debug: if ((&Called-Station-Id) && (&Called-Station-Id =~ /^([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})(:(.+))?$/i)) {
(8) Tue Oct 2 10:28:08 2018: Debug: if ((&Called-Station-Id) && (&Called-Station-Id =~ /^([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})(:(.+))?$/i)) -> TRUE
(8) Tue Oct 2 10:28:08 2018: Debug: if ((&Called-Station-Id) && (&Called-Station-Id =~ /^([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})(:(.+))?$/i)) {
(8) Tue Oct 2 10:28:08 2018: Debug: update request {
(8) Tue Oct 2 10:28:08 2018: Debug: EXPAND %{tolower:%{1}:%{2}:%{3}:%{4}:%{5}:%{6}}
(8) Tue Oct 2 10:28:08 2018: Debug: --> 2c:ab:eb:43:57:95
(8) Tue Oct 2 10:28:08 2018: Debug: } # update request = noop
(8) Tue Oct 2 10:28:08 2018: Debug: if ("%{8}") {
(8) Tue Oct 2 10:28:08 2018: Debug: EXPAND %{8}
(8) Tue Oct 2 10:28:08 2018: Debug: -->
(8) Tue Oct 2 10:28:08 2018: Debug: if ("%{8}") -> FALSE
(8) Tue Oct 2 10:28:08 2018: Debug: elsif ( (Colubris-AVPair) && "%{Colubris-AVPair}" =~ /^ssid=(.*)$/i) {
(8) Tue Oct 2 10:28:08 2018: Debug: elsif ( (Colubris-AVPair) && "%{Colubris-AVPair}" =~ /^ssid=(.*)$/i) -> FALSE
(8) Tue Oct 2 10:28:08 2018: Debug: elsif (Aruba-Essid-Name) {
(8) Tue Oct 2 10:28:08 2018: Debug: elsif (Aruba-Essid-Name) -> FALSE
(8) Tue Oct 2 10:28:08 2018: Debug: elsif ( (Cisco-AVPair) && "%{Cisco-AVPair}" =~ /^ssid=(.*)$/i) {
(8) Tue Oct 2 10:28:08 2018: Debug: EXPAND %{Cisco-AVPair}
(8) Tue Oct 2 10:28:08 2018: Debug: --> service-type=Framed
(8) Tue Oct 2 10:28:08 2018: Debug: elsif ( (Cisco-AVPair) && "%{Cisco-AVPair}" =~ /^ssid=(.*)$/i) -> FALSE
(8) Tue Oct 2 10:28:08 2018: Debug: [updated] = updated
(8) Tue Oct 2 10:28:08 2018: Debug: } # if ((&Called-Station-Id) && (&Called-Station-Id =~ /^([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})(:(.+))?$/i)) = updated
(8) Tue Oct 2 10:28:08 2018: Debug: ... skipping else: Preceding "if" was taken
(8) Tue Oct 2 10:28:08 2018: Debug: } # policy rewrite_called_station_id = updated
(8) Tue Oct 2 10:28:08 2018: Debug: policy filter_username {
(8) Tue Oct 2 10:28:08 2018: Debug: if (&User-Name) {
(8) Tue Oct 2 10:28:08 2018: Debug: if (&User-Name) -> TRUE
(8) Tue Oct 2 10:28:08 2018: Debug: if (&User-Name) {
(8) Tue Oct 2 10:28:08 2018: Debug: if (&User-Name =~ / /) {
(8) Tue Oct 2 10:28:08 2018: Debug: if (&User-Name =~ / /) -> FALSE
(8) Tue Oct 2 10:28:08 2018: Debug: if (&User-Name =~ /@[^@]*@/ ) {
(8) Tue Oct 2 10:28:08 2018: Debug: if (&User-Name =~ /@[^@]*@/ ) -> FALSE
(8) Tue Oct 2 10:28:08 2018: Debug: if (&User-Name =~ /\.\./ ) {
(8) Tue Oct 2 10:28:08 2018: Debug: if (&User-Name =~ /\.\./ ) -> FALSE
(8) Tue Oct 2 10:28:08 2018: Debug: if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) {
(8) Tue Oct 2 10:28:08 2018: Debug: if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) -> FALSE
(8) Tue Oct 2 10:28:08 2018: Debug: if (&User-Name =~ /\.$/) {
(8) Tue Oct 2 10:28:08 2018: Debug: if (&User-Name =~ /\.$/) -> FALSE
(8) Tue Oct 2 10:28:08 2018: Debug: if (&User-Name =~ /@\./) {
(8) Tue Oct 2 10:28:08 2018: Debug: if (&User-Name =~ /@\./) -> FALSE
(8) Tue Oct 2 10:28:08 2018: Debug: } # if (&User-Name) = updated
(8) Tue Oct 2 10:28:08 2018: Debug: } # policy filter_username = updated
(8) Tue Oct 2 10:28:08 2018: Debug: policy filter_password {
(8) Tue Oct 2 10:28:08 2018: Debug: if (&User-Password && (&User-Password != "%{string:User-Password}")) {
(8) Tue Oct 2 10:28:08 2018: Debug: if (&User-Password && (&User-Password != "%{string:User-Password}")) -> FALSE
(8) Tue Oct 2 10:28:08 2018: Debug: } # policy filter_password = updated
(8) Tue Oct 2 10:28:08 2018: Debug: [preprocess] = ok
(8) Tue Oct 2 10:28:08 2018: Debug: suffix: Checking for suffix after "@"
(8) Tue Oct 2 10:28:08 2018: Debug: suffix: No '@' in User-Name = "testuser", skipping NULL due to config.
(8) Tue Oct 2 10:28:08 2018: Debug: [suffix] = noop
(8) Tue Oct 2 10:28:08 2018: Debug: ntdomain: Checking for prefix before "\"
(8) Tue Oct 2 10:28:08 2018: Debug: ntdomain: No '\' in User-Name = "testuser", looking up realm NULL
(8) Tue Oct 2 10:28:08 2018: Debug: ntdomain: Found realm "null"
(8) Tue Oct 2 10:28:08 2018: Debug: ntdomain: Adding Stripped-User-Name = "testuser"
(8) Tue Oct 2 10:28:08 2018: Debug: ntdomain: Adding Realm = "null"
(8) Tue Oct 2 10:28:08 2018: Debug: ntdomain: Authentication realm is LOCAL
(8) Tue Oct 2 10:28:08 2018: Debug: [ntdomain] = ok
(8) Tue Oct 2 10:28:08 2018: Debug: eap: Peer sent EAP Response (code 2) ID 9 length 46
(8) Tue Oct 2 10:28:08 2018: Debug: eap: Continuing tunnel setup
(8) Tue Oct 2 10:28:08 2018: Debug: [eap] = ok
(8) Tue Oct 2 10:28:08 2018: Debug: } # authorize = ok
(8) Tue Oct 2 10:28:08 2018: Debug: Found Auth-Type = eap
(8) Tue Oct 2 10:28:08 2018: Debug: # Executing group from file /usr/local/pf/raddb/sites-enabled/packetfence
(8) Tue Oct 2 10:28:08 2018: Debug: authenticate {
(8) Tue Oct 2 10:28:08 2018: Debug: eap: Expiring EAP session with state 0x516a5d37566344c3
(8) Tue Oct 2 10:28:08 2018: Debug: eap: Finished EAP session with state 0x516a5d37566344c3
(8) Tue Oct 2 10:28:08 2018: Debug: eap: Previous EAP request found for state 0x516a5d37566344c3, released from the list
(8) Tue Oct 2 10:28:08 2018: Debug: eap: Peer sent packet with method EAP PEAP (25)
(8) Tue Oct 2 10:28:08 2018: Debug: eap: Calling submodule eap_peap to process data
(8) Tue Oct 2 10:28:08 2018: Debug: eap_peap: Continuing EAP-TLS
(8) Tue Oct 2 10:28:08 2018: Debug: eap_peap: [eaptls verify] = ok
(8) Tue Oct 2 10:28:08 2018: Debug: eap_peap: Done initial handshake
(8) Tue Oct 2 10:28:08 2018: Debug: eap_peap: [eaptls process] = ok
(8) Tue Oct 2 10:28:08 2018: Debug: eap_peap: Session established. Decoding tunneled attributes
(8) Tue Oct 2 10:28:08 2018: Debug: eap_peap: PEAP state send tlv failure
(8) Tue Oct 2 10:28:08 2018: Debug: eap_peap: Received EAP-TLV response
(8) Tue Oct 2 10:28:08 2018: ERROR: eap_peap: The users session was previously rejected: returning reject (again.)
(8) Tue Oct 2 10:28:08 2018: ERROR: eap: Failed continuing EAP PEAP (25) session. EAP sub-module failed
(8) Tue Oct 2 10:28:08 2018: Debug: eap: Sending EAP Failure (code 4) ID 9 length 4
(8) Tue Oct 2 10:28:08 2018: Debug: eap: Failed in EAP select
(8) Tue Oct 2 10:28:08 2018: Debug: [eap] = invalid
(8) Tue Oct 2 10:28:08 2018: Debug: } # authenticate = invalid
(8) Tue Oct 2 10:28:08 2018: Debug: Failed to authenticate the user
(8) Tue Oct 2 10:28:08 2018: Debug: Using Post-Auth-Type Reject
(8) Tue Oct 2 10:28:08 2018: Debug: # Executing group from file /usr/local/pf/raddb/sites-enabled/packetfence
(8) Tue Oct 2 10:28:08 2018: Debug: Post-Auth-Type REJECT {
(8) Tue Oct 2 10:28:08 2018: Debug: update {
(8) Tue Oct 2 10:28:08 2018: Debug: } # update = noop
(8) Tue Oct 2 10:28:08 2018: Debug: if (! EAP-Type || (EAP-Type != TTLS && EAP-Type != PEAP) ) {
(8) Tue Oct 2 10:28:08 2018: Debug: if (! EAP-Type || (EAP-Type != TTLS && EAP-Type != PEAP) ) -> FALSE
(8) Tue Oct 2 10:28:08 2018: Debug: attr_filter.access_reject: EXPAND %{User-Name}
(8) Tue Oct 2 10:28:08 2018: Debug: attr_filter.access_reject: --> testuser
(8) Tue Oct 2 10:28:08 2018: Debug: attr_filter.access_reject: Matched entry DEFAULT at line 11
(8) Tue Oct 2 10:28:08 2018: Debug: [attr_filter.access_reject] = updated
(8) Tue Oct 2 10:28:08 2018: Debug: attr_filter.packetfence_post_auth: EXPAND %{User-Name}
(8) Tue Oct 2 10:28:08 2018: Debug: attr_filter.packetfence_post_auth: --> testuser
(8) Tue Oct 2 10:28:08 2018: Debug: attr_filter.packetfence_post_auth: Matched entry DEFAULT at line 10
(8) Tue Oct 2 10:28:08 2018: Debug: [attr_filter.packetfence_post_auth] = updated
(8) Tue Oct 2 10:28:08 2018: Debug: [eap] = noop
(8) Tue Oct 2 10:28:08 2018: Debug: policy remove_reply_message_if_eap {
(8) Tue Oct 2 10:28:08 2018: Debug: if (&reply:EAP-Message && &reply:Reply-Message) {
(8) Tue Oct 2 10:28:08 2018: Debug: if (&reply:EAP-Message && &reply:Reply-Message) -> FALSE
(8) Tue Oct 2 10:28:08 2018: Debug: else {
(8) Tue Oct 2 10:28:08 2018: Debug: [noop] = noop
(8) Tue Oct 2 10:28:08 2018: Debug: } # else = noop
(8) Tue Oct 2 10:28:08 2018: Debug: } # policy remove_reply_message_if_eap = noop
(8) Tue Oct 2 10:28:08 2018: Debug: linelog: EXPAND messages.%{%{reply:Packet-Type}:-default}
(8) Tue Oct 2 10:28:08 2018: Debug: linelog: --> messages.Access-Reject
(8) Tue Oct 2 10:28:08 2018: Debug: linelog: EXPAND [mac:%{Calling-Station-Id}] Rejected user: %{User-Name}
(8) Tue Oct 2 10:28:08 2018: Debug: linelog: --> [mac:a0:ce:c8:09:9a:b4] Rejected user: testuser
(8) Tue Oct 2 10:28:08 2018: Debug: [linelog] = ok
(8) Tue Oct 2 10:28:08 2018: Debug: } # Post-Auth-Type REJECT = updated
(8) Tue Oct 2 10:28:08 2018: Debug: Delaying response for 1.000000 seconds
(8) Tue Oct 2 10:28:09 2018: Debug: Sending delayed response
(8) Tue Oct 2 10:28:09 2018: Debug: Sent Access-Reject Id 248 from 10.111.111.1:1812 to 10.111.111.2:1645 length 44
(8) Tue Oct 2 10:28:09 2018: Debug: EAP-Message = 0x04090004
(8) Tue Oct 2 10:28:09 2018: Debug: Message-Authenticator = 0x00000000000000000000000000000000
(0) Tue Oct 2 10:28:13 2018: Debug: Cleaning up request packet ID 240 with timestamp +47
From: "Mathias Didier" <mathias.did...@etrex.ch>
To: "Jay Hauss" <jayha...@gmx.com>
Subject: RE: RE: [PacketFence-users] Packetfence 802.1x Radius Server with LDAP Backend (NO AD)
Hi Jay
Did u follow that?: https://packetfence.org/doc/PacketFence_Installation_Guide.html#_eap_authentication_against_openldap
Best,
Mathias
From: Jay Hauss <jayha...@gmx.com>
Sent: 02 October 2018 14:36
To: Mathias Didier <mathias.did...@etrex.ch>
Subject: Re: RE: [PacketFence-users] Packetfence 802.1x Radius Server with LDAP Backend (NO AD)
Hey Mathias,
Thanks for the reply! Unfortunately this didn't fix it for me. I'm still getting the same error in radius.log:
#############
Oct 2 08:29:25 packetfence8-1 auth[31081]: (7) Login incorrect (mschap: Program returned code (1) and output 'Reading winbind reply failed! (0xc0000001)'): [testuser] (from client 10.111.111.2 port 50121 cli a0:ce:c8:09:9a:b4 via TLS tunnel)
Oct 2 08:29:25 packetfence8-1 auth[31081]: (8) eap_peap: This means you need to read the PREVIOUS messages in the debug output
Oct 2 08:29:25 packetfence8-1 auth[31081]: (8) eap_peap: to find out the reason why the user was rejected
Oct 2 08:29:25 packetfence8-1 auth[31081]: (8) eap_peap: Look for "reject" or "fail". Those earlier messages will tell you
Oct 2 08:29:25 packetfence8-1 auth[31081]: (8) eap_peap: what went wrong, and how to fix the problem
Oct 2 08:29:25 packetfence8-1 auth[31081]: (8) Login incorrect (eap_peap: The users session was previously rejected: returning reject (again.)): [testuser] (from client 10.111.111.2 port 50121 cli a0:ce:c8:09:9a:b4)
Oct 2 08:29:25 packetfence8-1 auth[31081]: [mac:a0:ce:c8:09:9a:b4] Rejected user: testuser
#############
The Debug looks a bit different than before ...here's some of the debug output:
###############
(7) Tue Oct 2 08:29:25 2018: Debug: # Executing group from file /usr/local/pf/raddb/sites-enabled/packetfence-tunnel
(7) Tue Oct 2 08:29:25 2018: Debug: authenticate {
(7) Tue Oct 2 08:29:25 2018: Debug: eap: Expiring EAP session with state 0x4a083f524a0025bb
(7) Tue Oct 2 08:29:25 2018: Debug: eap: Finished EAP session with state 0x4a083f524a0025bb
(7) Tue Oct 2 08:29:25 2018: Debug: eap: Previous EAP request found for state 0x4a083f524a0025bb, released from the list
(7) Tue Oct 2 08:29:25 2018: Debug: eap: Peer sent packet with method EAP MSCHAPv2 (26)
(7) Tue Oct 2 08:29:25 2018: Debug: eap: Calling submodule eap_mschapv2 to process data
(7) Tue Oct 2 08:29:25 2018: Debug: eap_mschapv2: # Executing group from file /usr/local/pf/raddb/sites-enabled/packetfence-tunnel
(7) Tue Oct 2 08:29:25 2018: Debug: eap_mschapv2: Auth-Type MS-CHAP {
(7) Tue Oct 2 08:29:25 2018: Debug: packetfence: $RAD_REQUEST{'User-Name'} = &request:User-Name -> 'testuser'
(7) Tue Oct 2 08:29:25 2018: Debug: packetfence: $RAD_REQUEST{'NAS-IP-Address'} = &request:NAS-IP-Address -> '10.111.111.2'
(7) Tue Oct 2 08:29:25 2018: Debug: packetfence: $RAD_REQUEST{'NAS-Port'} = &request:NAS-Port -> '50121'
(7) Tue Oct 2 08:29:25 2018: Debug: packetfence: $RAD_REQUEST{'Service-Type'} = &request:Service-Type -> 'Framed-User'
(7) Tue Oct 2 08:29:25 2018: Debug: packetfence: $RAD_REQUEST{'Framed-MTU'} = &request:Framed-MTU -> '1500'
(7) Tue Oct 2 08:29:25 2018: Debug: packetfence: $RAD_REQUEST{'State'} = &request:State -> '0x4a083f524a0025bb0b7946fce8b3c44a'
(7) Tue Oct 2 08:29:25 2018: Debug: packetfence: $RAD_REQUEST{'Called-Station-Id'} = &request:Called-Station-Id -> '2c:ab:eb:43:57:95'
(7) Tue Oct 2 08:29:25 2018: Debug: packetfence: $RAD_REQUEST{'Calling-Station-Id'} = &request:Calling-Station-Id -> 'a0:ce:c8:09:9a:b4'
(7) Tue Oct 2 08:29:25 2018: Debug: packetfence: $RAD_REQUEST{'NAS-Port-Type'} = &request:NAS-Port-Type -> 'Ethernet'
(7) Tue Oct 2 08:29:25 2018: Debug: packetfence: $RAD_REQUEST{'Event-Timestamp'} = &request:Event-Timestamp -> 'Oct 2 2018 08:29:25 EDT'
(7) Tue Oct 2 08:29:25 2018: Debug: packetfence: $RAD_REQUEST{'EAP-Message'} = &request:EAP-Message -> '0x020800431a0208003e31ab1ccc224345ec155aeaa80ae148fe6900000000000000000570674b27ec69badf6efe3c2f1abab3b3482da0c31c7d6e007465737475736572'
(7) Tue Oct 2 08:29:25 2018: Debug: packetfence: $RAD_REQUEST{'NAS-Port-Id'} = &request:NAS-Port-Id -> 'GigabitEthernet1/0/21'
(7) Tue Oct 2 08:29:25 2018: Debug: packetfence: $RAD_REQUEST{'Cisco-AVPair'}[0] = &request:Cisco-AVPair -> 'service-type=Framed'
(7) Tue Oct 2 08:29:25 2018: Debug: packetfence: $RAD_REQUEST{'Cisco-AVPair'}[1] = &request:Cisco-AVPair -> 'audit-session-id=0A6F6F0200000034252D4EE3'
(7) Tue Oct 2 08:29:25 2018: Debug: packetfence: $RAD_REQUEST{'Cisco-AVPair'}[2] = &request:Cisco-AVPair -> 'method=dot1x'
(7) Tue Oct 2 08:29:25 2018: Debug: packetfence: $RAD_REQUEST{'FreeRADIUS-Proxied-To'} = &request:FreeRADIUS-Proxied-To -> '127.0.0.1'
(7) Tue Oct 2 08:29:25 2018: Debug: packetfence: $RAD_REQUEST{'MS-CHAP-Challenge'} = &request:MS-CHAP-Challenge -> '0x5bb89dfa7a17b6da194b6f6c97c8474e'
(7) Tue Oct 2 08:29:25 2018: Debug: packetfence: $RAD_REQUEST{'MS-CHAP2-Response'} = &request:MS-CHAP2-Response -> '0x0865ab1ccc224345ec155aeaa80ae148fe6900000000000000000570674b27ec69badf6efe3c2f1abab3b3482da0c31c7d6e'
(7) Tue Oct 2 08:29:25 2018: Debug: packetfence: $RAD_REQUEST{'EAP-Type'} = &request:EAP-Type -> 'MSCHAPv2'
(7) Tue Oct 2 08:29:25 2018: Debug: packetfence: $RAD_REQUEST{'Stripped-User-Name'} = &request:Stripped-User-Name -> 'testuser'
(7) Tue Oct 2 08:29:25 2018: Debug: packetfence: $RAD_REQUEST{'Realm'} = &request:Realm -> 'null'
(7) Tue Oct 2 08:29:25 2018: Debug: packetfence: $RAD_REQUEST{'MS-CHAP-User-Name'} = &request:MS-CHAP-User-Name -> 'testuser'
(7) Tue Oct 2 08:29:25 2018: Debug: packetfence: $RAD_CHECK{'Auth-Type'} = &control:Auth-Type -> 'eap'
(7) Tue Oct 2 08:29:25 2018: Debug: packetfence: $RAD_CHECK{'Proxy-To-Realm'} = &control:Proxy-To-Realm -> 'LOCAL'
(7) Tue Oct 2 08:29:25 2018: Debug: packetfence: $RAD_CONFIG{'Auth-Type'} = &control:Auth-Type -> 'eap'
(7) Tue Oct 2 08:29:25 2018: Debug: packetfence: $RAD_CONFIG{'Proxy-To-Realm'} = &control:Proxy-To-Realm -> 'LOCAL'
(7) Tue Oct 2 08:29:25 2018: Debug: packetfence: &request:NAS-Port-Type = $RAD_REQUEST{'NAS-Port-Type'} -> 'Ethernet'
(7) Tue Oct 2 08:29:25 2018: Debug: packetfence: &request:Service-Type = $RAD_REQUEST{'Service-Type'} -> 'Framed-User'
(7) Tue Oct 2 08:29:25 2018: Debug: packetfence: &request:Called-Station-Id = $RAD_REQUEST{'Called-Station-Id'} -> '2c:ab:eb:43:57:95'
(7) Tue Oct 2 08:29:25 2018: Debug: packetfence: &request:State = $RAD_REQUEST{'State'} -> '0x4a083f524a0025bb0b7946fce8b3c44a'
(7) Tue Oct 2 08:29:25 2018: Debug: packetfence: &request:FreeRADIUS-Proxied-To = $RAD_REQUEST{'FreeRADIUS-Proxied-To'} -> '127.0.0.1'
(7) Tue Oct 2 08:29:25 2018: Debug: packetfence: &request:Realm = $RAD_REQUEST{'Realm'} -> 'null'
(7) Tue Oct 2 08:29:25 2018: Debug: packetfence: &request:EAP-Type = $RAD_REQUEST{'EAP-Type'} -> 'MSCHAPv2'
(7) Tue Oct 2 08:29:25 2018: Debug: packetfence: &request:NAS-IP-Address = $RAD_REQUEST{'NAS-IP-Address'} -> '10.111.111.2'
(7) Tue Oct 2 08:29:25 2018: Debug: packetfence: &request:NAS-Port-Id = $RAD_REQUEST{'NAS-Port-Id'} -> 'GigabitEthernet1/0/21'
(7) Tue Oct 2 08:29:25 2018: Debug: packetfence: &request:Calling-Station-Id = $RAD_REQUEST{'Calling-Station-Id'} -> 'a0:ce:c8:09:9a:b4'
(7) Tue Oct 2 08:29:25 2018: Debug: packetfence: &request:MS-CHAP-User-Name = $RAD_REQUEST{'MS-CHAP-User-Name'} -> 'testuser'
(7) Tue Oct 2 08:29:25 2018: Debug: packetfence: &request:MS-CHAP-Challenge = $RAD_REQUEST{'MS-CHAP-Challenge'} -> '0x5bb89dfa7a17b6da194b6f6c97c8474e'
(7) Tue Oct 2 08:29:25 2018: Debug: packetfence: &request:Cisco-AVPair += $RAD_REQUEST{'Cisco-AVPair'} -> 'service-type=Framed'
(7) Tue Oct 2 08:29:25 2018: Debug: packetfence: &request:Cisco-AVPair += $RAD_REQUEST{'Cisco-AVPair'} -> 'audit-session-id=0A6F6F0200000034252D4EE3'
(7) Tue Oct 2 08:29:25 2018: Debug: packetfence: &request:Cisco-AVPair += $RAD_REQUEST{'Cisco-AVPair'} -> 'method=dot1x'
(7) Tue Oct 2 08:29:25 2018: Debug: packetfence: &request:User-Name = $RAD_REQUEST{'User-Name'} -> 'testuser'
(7) Tue Oct 2 08:29:25 2018: Debug: packetfence: &request:Event-Timestamp = $RAD_REQUEST{'Event-Timestamp'} -> 'Oct 2 2018 08:29:25 EDT'
(7) Tue Oct 2 08:29:25 2018: Debug: packetfence: &request:EAP-Message = $RAD_REQUEST{'EAP-Message'} -> '0x020800431a0208003e31ab1ccc224345ec155aeaa80ae148fe6900000000000000000570674b27ec69badf6efe3c2f1abab3b3482da0c31c7d6e007465737475736572'
(7) Tue Oct 2 08:29:25 2018: Debug: packetfence: &request:MS-CHAP2-Response = $RAD_REQUEST{'MS-CHAP2-Response'} -> '0x0865ab1ccc224345ec155aeaa80ae148fe6900000000000000000570674b27ec69badf6efe3c2f1abab3b3482da0c31c7d6e'
(7) Tue Oct 2 08:29:25 2018: Debug: packetfence: &request:Stripped-User-Name = $RAD_REQUEST{'Stripped-User-Name'} -> 'testuser'
(7) Tue Oct 2 08:29:25 2018: Debug: packetfence: &request:NAS-Port = $RAD_REQUEST{'NAS-Port'} -> '50121'
(7) Tue Oct 2 08:29:25 2018: Debug: packetfence: &request:Framed-MTU = $RAD_REQUEST{'Framed-MTU'} -> '1500'
(7) Tue Oct 2 08:29:25 2018: Debug: packetfence: &control:Auth-Type = $RAD_CHECK{'Auth-Type'} -> 'eap'
(7) Tue Oct 2 08:29:25 2018: Debug: packetfence: &control:Proxy-To-Realm = $RAD_CHECK{'Proxy-To-Realm'} -> 'LOCAL'
(7) Tue Oct 2 08:29:25 2018: Debug: [packetfence] = noop
(7) Tue Oct 2 08:29:25 2018: Debug: if (&control:NT-Password && &control:NT-Password != "") {
(7) Tue Oct 2 08:29:25 2018: Debug: if (&control:NT-Password && &control:NT-Password != "") -> FALSE
(7) Tue Oct 2 08:29:25 2018: Debug: else {
(7) Tue Oct 2 08:29:25 2018: Debug: policy packetfence-mschap-authenticate {
(7) Tue Oct 2 08:29:25 2018: Debug: if (PacketFence-Domain) {
(7) Tue Oct 2 08:29:25 2018: Debug: if (PacketFence-Domain) -> FALSE
(7) Tue Oct 2 08:29:25 2018: Debug: else {
(7) Tue Oct 2 08:29:25 2018: Debug: if ( "%{User-Name}" =~ /^host\/.*/) {
(7) Tue Oct 2 08:29:25 2018: Debug: EXPAND %{User-Name}
(7) Tue Oct 2 08:29:25 2018: Debug: --> testuser
(7) Tue Oct 2 08:29:25 2018: Debug: if ( "%{User-Name}" =~ /^host\/.*/) -> FALSE
(7) Tue Oct 2 08:29:25 2018: Debug: else {
(7) Tue Oct 2 08:29:25 2018: Debug: mschap: Creating challenge hash with username: testuser
(7) Tue Oct 2 08:29:25 2018: Debug: mschap: Client is using MS-CHAPv2
(7) Tue Oct 2 08:29:25 2018: Debug: mschap: Executing: /usr/local/pf/bin/ntlm_auth_wrapper -- --request-nt-key --username=%{%{Stripped-User-Name}:-%{mschap:User-Name:-None}} --challenge=%{mschap:Challenge:-00} --nt-response=%{mschap:NT-Response:-00}:
(7) Tue Oct 2 08:29:25 2018: Debug: mschap: EXPAND --username=%{%{Stripped-User-Name}:-%{mschap:User-Name:-None}}
(7) Tue Oct 2 08:29:25 2018: Debug: mschap: --> --username=testuser
(7) Tue Oct 2 08:29:25 2018: Debug: mschap: Creating challenge hash with username: testuser
(7) Tue Oct 2 08:29:25 2018: Debug: mschap: EXPAND --challenge=%{mschap:Challenge:-00}
(7) Tue Oct 2 08:29:25 2018: Debug: mschap: --> --challenge=04ccc6d6996d1c3a
(7) Tue Oct 2 08:29:25 2018: Debug: mschap: EXPAND --nt-response=%{mschap:NT-Response:-00}
(7) Tue Oct 2 08:29:25 2018: Debug: mschap: --> --nt-response=0570674b27ec69badf6efe3c2f1abab3b3482da0c31c7d6e
(7) Tue Oct 2 08:29:25 2018: ERROR: mschap: Program returned code (1) and output 'Reading winbind reply failed! (0xc0000001)'
(7) Tue Oct 2 08:29:25 2018: Debug: mschap: External script failed
(7) Tue Oct 2 08:29:25 2018: ERROR: mschap: External script says: Reading winbind reply failed! (0xc0000001)
(7) Tue Oct 2 08:29:25 2018: ERROR: mschap: MS-CHAP2-Response is incorrect
(7) Tue Oct 2 08:29:25 2018: Debug: [mschap] = reject
(7) Tue Oct 2 08:29:25 2018: Debug: } # else = reject
(7) Tue Oct 2 08:29:25 2018: Debug: } # else = reject
(7) Tue Oct 2 08:29:25 2018: Debug: } # policy packetfence-mschap-authenticate = reject
(7) Tue Oct 2 08:29:25 2018: Debug: } # else = reject
(7) Tue Oct 2 08:29:25 2018: Debug: } # Auth-Type MS-CHAP = reject
(7) Tue Oct 2 08:29:25 2018: Debug: eap: Sending EAP Failure (code 4) ID 8 length 4
(7) Tue Oct 2 08:29:25 2018: Debug: eap: Freeing handler
(7) Tue Oct 2 08:29:25 2018: Debug: [eap] = reject
(7) Tue Oct 2 08:29:25 2018: Debug: } # authenticate = reject
(7) Tue Oct 2 08:29:25 2018: Debug: Failed to authenticate the user
(7) Tue Oct 2 08:29:25 2018: Debug: Using Post-Auth-Type Reject
(7) Tue Oct 2 08:29:25 2018: Debug: # Executing group from file /usr/local/pf/raddb/sites-enabled/packetfence-tunnel
(7) Tue Oct 2 08:29:25 2018: Debug: Post-Auth-Type REJECT {
(7) Tue Oct 2 08:29:25 2018: Debug: update {
(7) Tue Oct 2 08:29:25 2018: Debug: } # update = noop
(7) Tue Oct 2 08:29:25 2018: Debug: policy packetfence-audit-log-reject {
(7) Tue Oct 2 08:29:25 2018: Debug: if (&User-Name && (&User-Name == "dummy")) {
(7) Tue Oct 2 08:29:25 2018: Debug: if (&User-Name && (&User-Name == "dummy")) -> FALSE
(7) Tue Oct 2 08:29:25 2018: Debug: else {
(7) Tue Oct 2 08:29:25 2018: Debug: policy request-timing {
(7) Tue Oct 2 08:29:25 2018: Debug: if (control:PacketFence-Request-Time != 0) {
(7) Tue Oct 2 08:29:25 2018: ERROR: Failed retrieving values required to evaluate condition
(7) Tue Oct 2 08:29:25 2018: Debug: } # policy request-timing = noop
(7) Tue Oct 2 08:29:25 2018: Debug: sql_reject: EXPAND type.reject.query
(7) Tue Oct 2 08:29:25 2018: Debug: sql_reject: --> type.reject.query
(7) Tue Oct 2 08:29:25 2018: Debug: sql_reject: Using query template 'query'
(7) Tue Oct 2 08:29:25 2018: Debug: sql_reject: EXPAND %{User-Name}
(7) Tue Oct 2 08:29:25 2018: Debug: sql_reject: --> testuser
(7) Tue Oct 2 08:29:25 2018: Debug: sql_reject: SQL-User-Name set to 'testuser'
(7) Tue Oct 2 08:29:25 2018: Debug: sql_reject: EXPAND INSERT INTO radius_audit_log ( mac, ip, computer_name, user_name, stripped_user_name, realm, event_type, switch_id, switch_mac, switch_ip_address, radius_source_ip_address, called_station_id, calling_station_id, nas_port_type, ssid, nas_port_id, ifindex, nas_port, connection_type, nas_ip_address, nas_identifier, auth_status, reason, auth_type, eap_type, role, node_status, profile, source, auto_reg, is_phone, pf_domain, uuid, radius_request, radius_reply, request_time, tenant_id) VALUES ( '%{request:Calling-Station-Id}', '%{request:Framed-IP-Address}', '%{%{control:PacketFence-Computer-Name}:-N/A}', '%{request:User-Name}', '%{request:Stripped-User-Name}', '%{request:Realm}', 'Radius-Access-Request', '%{%{control:PacketFence-Switch-Id}:-N/A}', '%{%{control:PacketFence-Switch-Mac}:-N/A}', '%{%{control:PacketFence-Switch-Ip-Address}:-N/A}', '%{Packet-Src-IP-Address}', '%{request:Called-Station-Id}', '%{request:Calling-Station-Id}', '%{request:NAS-Port-Type}', '%{request:Called-Station-SSID}', '%{request:NAS-Port-Id}', '%{%{control:PacketFence-IfIndex}:-N/A}', '%{request:NAS-Port}', '%{%{control:PacketFence-Connection-Type}:-N/A}', '%{request:NAS-IP-Address}', '%{request:NAS-Identifier}', 'Reject', '%{request:Module-Failure-Message}', '%{control:Auth-Type}', '%{request:EAP-Type}', '%{%{control:PacketFence-Role}:-N/A}', '%{%{control:PacketFence-Status}:-N/A}', '%{%{control:PacketFence-Profile}:-N/A}', '%{%{control:PacketFence-Source}:-N/A}', '%{%{control:PacketFence-AutoReg}:-0}', '%{%{control:PacketFence-IsPhone}:-0}', '%{request:PacketFence-Domain}', '', '%{pairs:&request:[*]}','%{pairs:&reply:[*]}', '%{%{control:PacketFence-Request-Time}:-N/A}', '%{control:PacketFence-Tenant-Id}')
(7) Tue Oct 2 08:29:25 2018: Debug: sql_reject: --> INSERT INTO radius_audit_log ( mac, ip, computer_name, user_name, stripped_user_name, realm, event_type, switch_id, switch_mac, switch_ip_address, radius_source_ip_address, called_station_id, calling_station_id, nas_port_type, ssid, nas_port_id, ifindex, nas_port, connection_type, nas_ip_address, nas_identifier, auth_status, reason, auth_type, eap_type, role, node_status, profile, source, auto_reg, is_phone, pf_domain, uuid, radius_request, radius_reply, request_time, tenant_id) VALUES ( 'a0:ce:c8:09:9a:b4', '', 'N/A', 'testuser', 'testuser', 'null', 'Radius-Access-Request', 'N/A', 'N/A', 'N/A', '10.111.111.2', '2c:ab:eb:43:57:95', 'a0:ce:c8:09:9a:b4', 'Ethernet', '', 'GigabitEthernet1/0/21', 'N/A', '50121', 'N/A', '10.111.111.2', '', 'Reject', 'mschap: Program returned code =281=29 and output =27Reading winbind reply failed=21 =280xc0000001=29=27', 'eap', 'MSCHAPv2', 'N/A', 'N/A', 'N/A', 'N/A', '0', '0', '', '', 'NAS-Port-Type =3D Ethernet=2C Service-Type =3D Framed-User=2C Called-Station-Id =3D =222c:ab:eb:43:57:95=22=2C State =3D 0x4a083f524a0025bb0b7946fce8b3c44a=2C FreeRADIUS-Proxied-To =3D 127.0.0.1=2C Realm =3D =22null=22=2C EAP-Type =3D MSCHAPv2=2C NAS-IP-Address =3D 10.111.111.2=2C NAS-Port-Id =3D =22GigabitEthernet1/0/21=22=2C Calling-Station-Id =3D =22a0:ce:c8:09:9a:b4=22=2C MS-CHAP-User-Name =3D =22testuser=22=2C MS-CHAP-Challenge =3D 0x5bb89dfa7a17b6da194b6f6c97c8474e=2C Cisco-AVPair =3D =22service-type=3DFramed=22=2C Cisco-AVPair =3D =22audit-session-id=3D0A6F6F0200000034252D4EE3=22=2C Cisco-AVPair =3D =22method=3Ddot1x=22=2C User-Name =3D =22testuser=22=2C Event-Timestamp =3D =22Oct 2 2018 08:29:25 EDT=22=2C EAP-Message =3D 0x020800431a0208003e31ab1ccc224345ec155aeaa80ae148fe6900000000000000000570674b27ec69badf6efe3c2f1abab3b3482da0c31c7d6e007465737475736572=2C MS-CHAP2-Response =3D 0x0865ab1ccc224345ec155aeaa80ae148fe6900000000000000000570674b27ec69badf6efe3c2f1abab3b3482da0c31c7d6e=2C Stripped-User-Name =3D =22testuser=22=2C NAS-Port =3D 50121=2C Framed-MTU =3D 1500=2C Module-Failure-Message =3D =22mschap: Program returned code =281=29 and output =27Reading winbind reply failed=21 =280xc0000001=29=27=22=2C Module-Failure-Message =3D =22mschap: External script says: Reading winbind reply failed=21 =280xc0000001=29=22=2C Module-Failure-Message =3D =22mschap: MS-CHAP2-Response is incorrect=22=2C User-Password =3D =22=2A=2A=2A=2A=2A=2A=22=2C Module-Failure-Message =3D =22Failed retrieving values required to evaluate condition=22=2C SQL-User-Name =3D =22testuser=22','MS-CHAP-Error =3D =22=5C010E=3D691 R=3D0 C=3D8ecd01590952f63a2675e82667a29e84 V=3D3 M=3DAuthentication failed=22=2C EAP-Message =3D 0x04080004=2C Message-Authenticator =3D 0x00000000000000000000000000000000', 'N/A', '')
(7) Tue Oct 2 08:29:25 2018: Debug: sql_reject: Executing query: INSERT INTO radius_audit_log ( mac, ip, computer_name, user_name, stripped_user_name, realm, event_type, switch_id, switch_mac, switch_ip_address, radius_source_ip_address, called_station_id, calling_station_id, nas_port_type, ssid, nas_port_id, ifindex, nas_port, connection_type, nas_ip_address, nas_identifier, auth_status, reason, auth_type, eap_type, role, node_status, profile, source, auto_reg, is_phone, pf_domain, uuid, radius_request, radius_reply, request_time, tenant_id) VALUES ( 'a0:ce:c8:09:9a:b4', '', 'N/A', 'testuser', 'testuser', 'null', 'Radius-Access-Request', 'N/A', 'N/A', 'N/A', '10.111.111.2', '2c:ab:eb:43:57:95', 'a0:ce:c8:09:9a:b4', 'Ethernet', '', 'GigabitEthernet1/0/21', 'N/A', '50121', 'N/A', '10.111.111.2', '', 'Reject', 'mschap: Program returned code =281=29 and output =27Reading winbind reply failed=21 =280xc0000001=29=27', 'eap', 'MSCHAPv2', 'N/A', 'N/A', 'N/A', 'N/A', '0', '0', '', '', 'NAS-Port-Type =3D Ethernet=2C Service-Type =3D Framed-User=2C Called-Station-Id =3D =222c:ab:eb:43:57:95=22=2C State =3D 0x4a083f524a0025bb0b7946fce8b3c44a=2C FreeRADIUS-Proxied-To =3D 127.0.0.1=2C Realm =3D =22null=22=2C EAP-Type =3D MSCHAPv2=2C NAS-IP-Address =3D 10.111.111.2=2C NAS-Port-Id =3D =22GigabitEthernet1/0/21=22=2C Calling-Station-Id =3D =22a0:ce:c8:09:9a:b4=22=2C MS-CHAP-User-Name =3D =22testuser=22=2C MS-CHAP-Challenge =3D 0x5bb89dfa7a17b6da194b6f6c97c8474e=2C Cisco-AVPair =3D =22service-type=3DFramed=22=2C Cisco-AVPair =3D =22audit-session-id=3D0A6F6F0200000034252D4EE3=22=2C Cisco-AVPair =3D =22method=3Ddot1x=22=2C User-Name =3D =22testuser=22=2C Event-Timestamp =3D =22Oct 2 2018 08:29:25 EDT=22=2C EAP-Message =3D 0x020800431a0208003e31ab1ccc224345ec155aeaa80ae148fe6900000000000000000570674b27ec69badf6efe3c2f1abab3b3482da0c31c7d6e007465737475736572=2C MS-CHAP2-Response =3D 0x0865ab1ccc224345ec155aeaa80ae148fe6900000000000000000570674b27ec69badf6efe3c2f1abab3b3482da0c31c7d6e=2C Stripped-User-Name =3D =22testuser=22=2C NAS-Port =3D 50121=2C Framed-MTU =3D 1500=2C Module-Failure-Message =3D =22mschap: Program returned code =281=29 and output =27Reading winbind reply failed=21 =280xc0000001=29=27=22=2C Module-Failure-Message =3D =22mschap: External script says: Reading winbind reply failed=21 =280xc0000001=29=22=2C Module-Failure-Message =3D =22mschap: MS-CHAP2-Response is incorrect=22=2C User-Password =3D =22=2A=2A=2A=2A=2A=2A=22=2C Module-Failure-Message =3D =22Failed retrieving values required to evaluate condition=22=2C SQL-User-Name =3D =22testuser=22','MS-CHAP-Error =3D =22=5C010E=3D691 R=3D0 C=3D8ecd01590952f63a2675e82667a29e84 V=3D3 M=3DAuthentication failed=22=2C EAP-Message =3D 0x04080004=2C Message-Authenticator =3D 0x00000000000000000000000000000000', 'N/A', '')
(7) Tue Oct 2 08:29:25 2018: Debug: sql_reject: SQL query returned: success
(7) Tue Oct 2 08:29:25 2018: Debug: sql_reject: 1 record(s) updated
(7) Tue Oct 2 08:29:25 2018: Debug: [sql_reject] = ok
(7) Tue Oct 2 08:29:25 2018: Debug: } # else = ok
(7) Tue Oct 2 08:29:25 2018: Debug: } # policy packetfence-audit-log-reject = ok
(7) Tue Oct 2 08:29:25 2018: Debug: attr_filter.access_reject: EXPAND %{User-Name}
(7) Tue Oct 2 08:29:25 2018: Debug: attr_filter.access_reject: --> testuser
(7) Tue Oct 2 08:29:25 2018: Debug: attr_filter.access_reject: Matched entry DEFAULT at line 11
(7) Tue Oct 2 08:29:25 2018: Debug: [attr_filter.access_reject] = updated
(7) Tue Oct 2 08:29:25 2018: Debug: update outer.session-state {
(7) Tue Oct 2 08:29:25 2018: Debug: } # update outer.session-state = noop
(7) Tue Oct 2 08:29:25 2018: Debug: } # Post-Auth-Type REJECT = updated
(7) Tue Oct 2 08:29:25 2018: Debug: } # server packetfence-tunnel
(7) Tue Oct 2 08:29:25 2018: Debug: Virtual server sending reply
(7) Tue Oct 2 08:29:25 2018: Debug: MS-CHAP-Error = "\010E=691 R=0 C=8ecd01590952f63a2675e82667a29e84 V=3 M=Authentication failed"
(7) Tue Oct 2 08:29:25 2018: Debug: EAP-Message = 0x04080004
(7) Tue Oct 2 08:29:25 2018: Debug: Message-Authenticator = 0x00000000000000000000000000000000
(7) Tue Oct 2 08:29:25 2018: Debug: eap_peap: Got tunneled reply code 3
(7) Tue Oct 2 08:29:25 2018: Debug: eap_peap: MS-CHAP-Error = "\010E=691 R=0 C=8ecd01590952f63a2675e82667a29e84 V=3 M=Authentication failed"
(7) Tue Oct 2 08:29:25 2018: Debug: eap_peap: EAP-Message = 0x04080004
(7) Tue Oct 2 08:29:25 2018: Debug: eap_peap: Message-Authenticator = 0x00000000000000000000000000000000
(7) Tue Oct 2 08:29:25 2018: Debug: eap_peap: Tunneled authentication was rejected
(7) Tue Oct 2 08:29:25 2018: Debug: eap_peap: FAILURE
(7) Tue Oct 2 08:29:25 2018: Debug: eap: Sending EAP Request (code 1) ID 9 length 46
(7) Tue Oct 2 08:29:25 2018: Debug: eap: EAP session adding &reply:State = 0xc22bc37cc522da70
(7) Tue Oct 2 08:29:25 2018: Debug: [eap] = handled
(7) Tue Oct 2 08:29:25 2018: Debug: } # authenticate = handled
(7) Tue Oct 2 08:29:25 2018: Debug: Using Post-Auth-Type Challenge
(7) Tue Oct 2 08:29:25 2018: Debug: Post-Auth-Type sub-section not found. Ignoring.
(7) Tue Oct 2 08:29:25 2018: Debug: # Executing group from file /usr/local/pf/raddb/sites-enabled/packetfence
(7) Tue Oct 2 08:29:25 2018: Debug: session-state: Saving cached attributes
(7) Tue Oct 2 08:29:25 2018: Debug: Module-Failure-Message := "mschap: Program returned code (1) and output 'Reading winbind reply failed! (0xc0000001)'"
(7) Tue Oct 2 08:29:25 2018: Debug: Sent Access-Challenge Id 228 from 10.111.111.1:1812 to 10.111.111.2:1645 length 0
(7) Tue Oct 2 08:29:25 2018: Debug: EAP-Message = 0x0109002e19001703030023d272e17d9f2d1fa17af0f0df0031301834d8bf3ba3e517d34a1880b4d5abb58246d051
(7) Tue Oct 2 08:29:25 2018: Debug: Message-Authenticator = 0x00000000000000000000000000000000
(7) Tue Oct 2 08:29:25 2018: Debug: State = 0xc22bc37cc522da703fc855a978a2a210
(7) Tue Oct 2 08:29:25 2018: Debug: Finished request
(8) Tue Oct 2 08:29:25 2018: Debug: Received Access-Request Id 229 from 10.111.111.2:1645 to 10.111.111.1:1812 length 303
(8) Tue Oct 2 08:29:25 2018: Debug: User-Name = "testuser"
(8) Tue Oct 2 08:29:25 2018: Debug: Service-Type = Framed-User
(8) Tue Oct 2 08:29:25 2018: Debug: Cisco-AVPair = "service-type=Framed"
(8) Tue Oct 2 08:29:25 2018: Debug: Framed-MTU = 1500
(8) Tue Oct 2 08:29:25 2018: Debug: Called-Station-Id = "2C-AB-EB-43-57-95"
(8) Tue Oct 2 08:29:25 2018: Debug: Calling-Station-Id = "A0-CE-C8-09-9A-B4"
(8) Tue Oct 2 08:29:25 2018: Debug: EAP-Message = 0x0209002e190017030300230000000000000003d1578f55402a7d560aac8e5f76a4c3c1d22e8c014cf0f5721bddf3
(8) Tue Oct 2 08:29:25 2018: Debug: Message-Authenticator = 0xddd13ef87bfacd10a26bd6cc0383e362
(8) Tue Oct 2 08:29:25 2018: Debug: Cisco-AVPair = "audit-session-id=0A6F6F0200000034252D4EE3"
(8) Tue Oct 2 08:29:25 2018: Debug: Cisco-AVPair = "method=dot1x"
(8) Tue Oct 2 08:29:25 2018: Debug: NAS-IP-Address = 10.111.111.2
(8) Tue Oct 2 08:29:25 2018: Debug: NAS-Port-Id = "GigabitEthernet1/0/21"
(8) Tue Oct 2 08:29:25 2018: Debug: NAS-Port-Type = Ethernet
(8) Tue Oct 2 08:29:25 2018: Debug: NAS-Port = 50121
(8) Tue Oct 2 08:29:25 2018: Debug: State = 0xc22bc37cc522da703fc855a978a2a210
(8) Tue Oct 2 08:29:25 2018: Debug: Restoring &session-state
(8) Tue Oct 2 08:29:25 2018: Debug: &session-state:Module-Failure-Message := "mschap: Program returned code (1) and output 'Reading winbind reply failed! (0xc0000001)'"
(8) Tue Oct 2 08:29:25 2018: Debug: # Executing section authorize from file /usr/local/pf/raddb/sites-enabled/packetfence
(8) Tue Oct 2 08:29:25 2018: Debug: authorize {
(8) Tue Oct 2 08:29:25 2018: Debug: update {
(8) Tue Oct 2 08:29:25 2018: Debug: EXPAND %{Packet-Src-IP-Address}
(8) Tue Oct 2 08:29:25 2018: Debug: --> 10.111.111.2
(8) Tue Oct 2 08:29:25 2018: Debug: EXPAND %l
(8) Tue Oct 2 08:29:25 2018: Debug: --> 1538483365
(8) Tue Oct 2 08:29:25 2018: Debug: } # update = noop
(8) Tue Oct 2 08:29:25 2018: Debug: policy packetfence-set-tenant-id {
(8) Tue Oct 2 08:29:25 2018: Debug: if ( "%{%{control:PacketFence-Tenant-Id}:-0}" == "0") {
(8) Tue Oct 2 08:29:25 2018: Debug: EXPAND %{%{control:PacketFence-Tenant-Id}:-0}
(8) Tue Oct 2 08:29:25 2018: Debug: --> 0
(8) Tue Oct 2 08:29:25 2018: Debug: if ( "%{%{control:PacketFence-Tenant-Id}:-0}" == "0") -> TRUE
(8) Tue Oct 2 08:29:25 2018: Debug: if ( "%{%{control:PacketFence-Tenant-Id}:-0}" == "0") {
(8) Tue Oct 2 08:29:25 2018: Debug: update control {
(8) Tue Oct 2 08:29:25 2018: Debug: EXPAND %{User-Name}
(8) Tue Oct 2 08:29:25 2018: Debug: --> testuser
(8) Tue Oct 2 08:29:25 2018: Debug: SQL-User-Name set to 'testuser'
(8) Tue Oct 2 08:29:25 2018: Debug: Executing select query: SELECT IFNULL((SELECT tenant_id FROM radius_nas WHERE nasname = '10.111.111.2'), 0)
(8) Tue Oct 2 08:29:25 2018: Debug: EXPAND %{sql: SELECT IFNULL((SELECT tenant_id FROM radius_nas WHERE nasname = '%{Packet-Src-IP-Address}'), 0)}
(8) Tue Oct 2 08:29:25 2018: Debug: --> 1
(8) Tue Oct 2 08:29:25 2018: Debug: } # update control = noop
(8) Tue Oct 2 08:29:25 2018: Debug: } # if ( "%{%{control:PacketFence-Tenant-Id}:-0}" == "0") = noop
(8) Tue Oct 2 08:29:25 2018: Debug: if ( &control:PacketFence-Tenant-Id == 0 ) {
(8) Tue Oct 2 08:29:25 2018: Debug: if ( &control:PacketFence-Tenant-Id == 0 ) -> FALSE
(8) Tue Oct 2 08:29:25 2018: Debug: } # policy packetfence-set-tenant-id = noop
(8) Tue Oct 2 08:29:25 2018: Debug: policy rewrite_calling_station_id {
(8) Tue Oct 2 08:29:25 2018: Debug: if (&Calling-Station-Id && (&Calling-Station-Id =~ /^([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})$/i)) {
(8) Tue Oct 2 08:29:25 2018: Debug: if (&Calling-Station-Id && (&Calling-Station-Id =~ /^([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})$/i)) -> TRUE
(8) Tue Oct 2 08:29:25 2018: Debug: if (&Calling-Station-Id && (&Calling-Station-Id =~ /^([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})$/i)) {
(8) Tue Oct 2 08:29:25 2018: Debug: update request {
(8) Tue Oct 2 08:29:25 2018: Debug: EXPAND %{tolower:%{1}:%{2}:%{3}:%{4}:%{5}:%{6}}
(8) Tue Oct 2 08:29:25 2018: Debug: --> a0:ce:c8:09:9a:b4
(8) Tue Oct 2 08:29:25 2018: Debug: } # update request = noop
(8) Tue Oct 2 08:29:25 2018: Debug: [updated] = updated
(8) Tue Oct 2 08:29:25 2018: Debug: } # if (&Calling-Station-Id && (&Calling-Station-Id =~ /^([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})$/i)) = updated
(8) Tue Oct 2 08:29:25 2018: Debug: ... skipping else: Preceding "if" was taken
(8) Tue Oct 2 08:29:25 2018: Debug: } # policy rewrite_calling_station_id = updated
(8) Tue Oct 2 08:29:25 2018: Debug: policy rewrite_called_station_id {
(8) Tue Oct 2 08:29:25 2018: Debug: if ((&Called-Station-Id) && (&Called-Station-Id =~ /^([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})(:(.+))?$/i)) {
(8) Tue Oct 2 08:29:25 2018: Debug: if ((&Called-Station-Id) && (&Called-Station-Id =~ /^([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})(:(.+))?$/i)) -> TRUE
(8) Tue Oct 2 08:29:25 2018: Debug: if ((&Called-Station-Id) && (&Called-Station-Id =~ /^([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})(:(.+))?$/i)) {
(8) Tue Oct 2 08:29:25 2018: Debug: update request {
(8) Tue Oct 2 08:29:25 2018: Debug: EXPAND %{tolower:%{1}:%{2}:%{3}:%{4}:%{5}:%{6}}
(8) Tue Oct 2 08:29:25 2018: Debug: --> 2c:ab:eb:43:57:95
(8) Tue Oct 2 08:29:25 2018: Debug: } # update request = noop
(8) Tue Oct 2 08:29:25 2018: Debug: if ("%{8}") {
(8) Tue Oct 2 08:29:25 2018: Debug: EXPAND %{8}
(8) Tue Oct 2 08:29:25 2018: Debug: -->
(8) Tue Oct 2 08:29:25 2018: Debug: if ("%{8}") -> FALSE
(8) Tue Oct 2 08:29:25 2018: Debug: elsif ( (Colubris-AVPair) && "%{Colubris-AVPair}" =~ /^ssid=(.*)$/i) {
(8) Tue Oct 2 08:29:25 2018: Debug: elsif ( (Colubris-AVPair) && "%{Colubris-AVPair}" =~ /^ssid=(.*)$/i) -> FALSE
(8) Tue Oct 2 08:29:25 2018: Debug: elsif (Aruba-Essid-Name) {
(8) Tue Oct 2 08:29:25 2018: Debug: elsif (Aruba-Essid-Name) -> FALSE
(8) Tue Oct 2 08:29:25 2018: Debug: elsif ( (Cisco-AVPair) && "%{Cisco-AVPair}" =~ /^ssid=(.*)$/i) {
(8) Tue Oct 2 08:29:25 2018: Debug: EXPAND %{Cisco-AVPair}
(8) Tue Oct 2 08:29:25 2018: Debug: --> service-type=Framed
(8) Tue Oct 2 08:29:25 2018: Debug: elsif ( (Cisco-AVPair) && "%{Cisco-AVPair}" =~ /^ssid=(.*)$/i) -> FALSE
(8) Tue Oct 2 08:29:25 2018: Debug: [updated] = updated
(8) Tue Oct 2 08:29:25 2018: Debug: } # if ((&Called-Station-Id) && (&Called-Station-Id =~ /^([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})(:(.+))?$/i)) = updated
(8) Tue Oct 2 08:29:25 2018: Debug: ... skipping else: Preceding "if" was taken
(8) Tue Oct 2 08:29:25 2018: Debug: } # policy rewrite_called_station_id = updated
(8) Tue Oct 2 08:29:25 2018: Debug: policy filter_username {
(8) Tue Oct 2 08:29:25 2018: Debug: if (&User-Name) {
(8) Tue Oct 2 08:29:25 2018: Debug: if (&User-Name) -> TRUE
(8) Tue Oct 2 08:29:25 2018: Debug: if (&User-Name) {
(8) Tue Oct 2 08:29:25 2018: Debug: if (&User-Name =~ / /) {
(8) Tue Oct 2 08:29:25 2018: Debug: if (&User-Name =~ / /) -> FALSE
(8) Tue Oct 2 08:29:25 2018: Debug: if (&User-Name =~ /@[^@]*@/ ) {
(8) Tue Oct 2 08:29:25 2018: Debug: if (&User-Name =~ /@[^@]*@/ ) -> FALSE
(8) Tue Oct 2 08:29:25 2018: Debug: if (&User-Name =~ /\.\./ ) {
(8) Tue Oct 2 08:29:25 2018: Debug: if (&User-Name =~ /\.\./ ) -> FALSE
(8) Tue Oct 2 08:29:25 2018: Debug: if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) {
(8) Tue Oct 2 08:29:25 2018: Debug: if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) -> FALSE
(8) Tue Oct 2 08:29:25 2018: Debug: if (&User-Name =~ /\.$/) {
(8) Tue Oct 2 08:29:25 2018: Debug: if (&User-Name =~ /\.$/) -> FALSE
(8) Tue Oct 2 08:29:25 2018: Debug: if (&User-Name =~ /@\./) {
(8) Tue Oct 2 08:29:25 2018: Debug: if (&User-Name =~ /@\./) -> FALSE
(8) Tue Oct 2 08:29:25 2018: Debug: } # if (&User-Name) = updated
(8) Tue Oct 2 08:29:25 2018: Debug: } # policy filter_username = updated
(8) Tue Oct 2 08:29:25 2018: Debug: policy filter_password {
(8) Tue Oct 2 08:29:25 2018: Debug: if (&User-Password && (&User-Password != "%{string:User-Password}")) {
(8) Tue Oct 2 08:29:25 2018: Debug: if (&User-Password && (&User-Password != "%{string:User-Password}")) -> FALSE
(8) Tue Oct 2 08:29:25 2018: Debug: } # policy filter_password = updated
(8) Tue Oct 2 08:29:25 2018: Debug: [preprocess] = ok
(8) Tue Oct 2 08:29:25 2018: Debug: suffix: Checking for suffix after "@"
(8) Tue Oct 2 08:29:25 2018: Debug: suffix: No '@' in User-Name = "testuser", skipping NULL due to config.
(8) Tue Oct 2 08:29:25 2018: Debug: [suffix] = noop
(8) Tue Oct 2 08:29:25 2018: Debug: ntdomain: Checking for prefix before "\"
(8) Tue Oct 2 08:29:25 2018: Debug: ntdomain: No '\' in User-Name = "testuser", looking up realm NULL
(8) Tue Oct 2 08:29:25 2018: Debug: ntdomain: Found realm "null"
(8) Tue Oct 2 08:29:25 2018: Debug: ntdomain: Adding Stripped-User-Name = "testuser"
(8) Tue Oct 2 08:29:25 2018: Debug: ntdomain: Adding Realm = "null"
(8) Tue Oct 2 08:29:25 2018: Debug: ntdomain: Authentication realm is LOCAL
(8) Tue Oct 2 08:29:25 2018: Debug: [ntdomain] = ok
(8) Tue Oct 2 08:29:25 2018: Debug: eap: Peer sent EAP Response (code 2) ID 9 length 46
(8) Tue Oct 2 08:29:25 2018: Debug: eap: Continuing tunnel setup
(8) Tue Oct 2 08:29:25 2018: Debug: [eap] = ok
(8) Tue Oct 2 08:29:25 2018: Debug: } # authorize = ok
(8) Tue Oct 2 08:29:25 2018: Debug: Found Auth-Type = eap
(8) Tue Oct 2 08:29:25 2018: Debug: # Executing group from file /usr/local/pf/raddb/sites-enabled/packetfence
(8) Tue Oct 2 08:29:25 2018: Debug: authenticate {
(8) Tue Oct 2 08:29:25 2018: Debug: eap: Expiring EAP session with state 0xc22bc37cc522da70
(8) Tue Oct 2 08:29:25 2018: Debug: eap: Finished EAP session with state 0xc22bc37cc522da70
(8) Tue Oct 2 08:29:25 2018: Debug: eap: Previous EAP request found for state 0xc22bc37cc522da70, released from the list
(8) Tue Oct 2 08:29:25 2018: Debug: eap: Peer sent packet with method EAP PEAP (25)
(8) Tue Oct 2 08:29:25 2018: Debug: eap: Calling submodule eap_peap to process data
(8) Tue Oct 2 08:29:25 2018: Debug: eap_peap: Continuing EAP-TLS
(8) Tue Oct 2 08:29:25 2018: Debug: eap_peap: [eaptls verify] = ok
(8) Tue Oct 2 08:29:25 2018: Debug: eap_peap: Done initial handshake
(8) Tue Oct 2 08:29:25 2018: Debug: eap_peap: [eaptls process] = ok
(8) Tue Oct 2 08:29:25 2018: Debug: eap_peap: Session established. Decoding tunneled attributes
(8) Tue Oct 2 08:29:25 2018: Debug: eap_peap: PEAP state send tlv failure
(8) Tue Oct 2 08:29:25 2018: Debug: eap_peap: Received EAP-TLV response
(8) Tue Oct 2 08:29:25 2018: ERROR: eap_peap: The users session was previously rejected: returning reject (again.)
(8) Tue Oct 2 08:29:25 2018: ERROR: eap: Failed continuing EAP PEAP (25) session. EAP sub-module failed
(8) Tue Oct 2 08:29:25 2018: Debug: eap: Sending EAP Failure (code 4) ID 9 length 4
(8) Tue Oct 2 08:29:25 2018: Debug: eap: Failed in EAP select
(8) Tue Oct 2 08:29:25 2018: Debug: [eap] = invalid
(8) Tue Oct 2 08:29:25 2018: Debug: } # authenticate = invalid
(8) Tue Oct 2 08:29:25 2018: Debug: Failed to authenticate the user
(8) Tue Oct 2 08:29:25 2018: Debug: Using Post-Auth-Type Reject
(8) Tue Oct 2 08:29:25 2018: Debug: # Executing group from file /usr/local/pf/raddb/sites-enabled/packetfence
(8) Tue Oct 2 08:29:25 2018: Debug: Post-Auth-Type REJECT {
(8) Tue Oct 2 08:29:25 2018: Debug: update {
(8) Tue Oct 2 08:29:25 2018: Debug: } # update = noop
(8) Tue Oct 2 08:29:25 2018: Debug: if (! EAP-Type || (EAP-Type != TTLS && EAP-Type != PEAP) ) {
(8) Tue Oct 2 08:29:25 2018: Debug: if (! EAP-Type || (EAP-Type != TTLS && EAP-Type != PEAP) ) -> FALSE
(8) Tue Oct 2 08:29:25 2018: Debug: attr_filter.access_reject: EXPAND %{User-Name}
(8) Tue Oct 2 08:29:25 2018: Debug: attr_filter.access_reject: --> testuser
(8) Tue Oct 2 08:29:25 2018: Debug: attr_filter.access_reject: Matched entry DEFAULT at line 11
(8) Tue Oct 2 08:29:25 2018: Debug: [attr_filter.access_reject] = updated
(8) Tue Oct 2 08:29:25 2018: Debug: attr_filter.packetfence_post_auth: EXPAND %{User-Name}
(8) Tue Oct 2 08:29:25 2018: Debug: attr_filter.packetfence_post_auth: --> testuser
(8) Tue Oct 2 08:29:25 2018: Debug: attr_filter.packetfence_post_auth: Matched entry DEFAULT at line 10
(8) Tue Oct 2 08:29:25 2018: Debug: [attr_filter.packetfence_post_auth] = updated
(8) Tue Oct 2 08:29:25 2018: Debug: [eap] = noop
(8) Tue Oct 2 08:29:25 2018: Debug: policy remove_reply_message_if_eap {
(8) Tue Oct 2 08:29:25 2018: Debug: if (&reply:EAP-Message && &reply:Reply-Message) {
(8) Tue Oct 2 08:29:25 2018: Debug: if (&reply:EAP-Message && &reply:Reply-Message) -> FALSE
(8) Tue Oct 2 08:29:25 2018: Debug: else {
(8) Tue Oct 2 08:29:25 2018: Debug: [noop] = noop
(8) Tue Oct 2 08:29:25 2018: Debug: } # else = noop
(8) Tue Oct 2 08:29:25 2018: Debug: } # policy remove_reply_message_if_eap = noop
(8) Tue Oct 2 08:29:25 2018: Debug: linelog: EXPAND messages.%{%{reply:Packet-Type}:-default}
(8) Tue Oct 2 08:29:25 2018: Debug: linelog: --> messages.Access-Reject
(8) Tue Oct 2 08:29:25 2018: Debug: linelog: EXPAND [mac:%{Calling-Station-Id}] Rejected user: %{User-Name}
(8) Tue Oct 2 08:29:25 2018: Debug: linelog: --> [mac:a0:ce:c8:09:9a:b4] Rejected user: testuser
(8) Tue Oct 2 08:29:25 2018: Debug: [linelog] = ok
(8) Tue Oct 2 08:29:25 2018: Debug: } # Post-Auth-Type REJECT = updated
(8) Tue Oct 2 08:29:25 2018: Debug: Delaying response for 1.000000 seconds
(8) Tue Oct 2 08:29:26 2018: Debug: Sending delayed response
(8) Tue Oct 2 08:29:26 2018: Debug: Sent Access-Reject Id 229 from 10.111.111.1:1812 to 10.111.111.2:1645 length 44
(8) Tue Oct 2 08:29:26 2018: Debug: EAP-Message = 0x04090004
(8) Tue Oct 2 08:29:26 2018: Debug: Message-Authenticator = 0x00000000000000000000000000000000
(0) Tue Oct 2 08:29:30 2018: Debug: Cleaning up request packet ID 221 with timestamp +99
###############
Sent: Tuesday, October 02, 2018 at 8:17 AM
From: "Mathias Didier" <mathias.did...@etrex.ch>
To: "packetfence-users@lists.sourceforge.net" <packetfence-users@lists.sourceforge.net>
Cc: "Jay Hauss" <jayha...@gmx.com>
Subject: RE: [PacketFence-users] Packetfence 802.1x Radius Server with LDAP Backend (NO AD)
Hi Jay
- I think, I had the same issue. Try that:
sudo nano /usr/local/pf/conf/radiusd/eap.conf
- scroll down to [% IF TTLS %] and change:
default_eap_type = mschapv2
- Restart the server
Best,
Mathias
From: Jay Hauss via PacketFence-users <packetfence-users@lists.sourceforge.net>
Sent: 02 October 2018 13:38
To: packetfence-users@lists.sourceforge.net
Cc: Jay Hauss <jayha...@gmx.com>
Subject: [PacketFence-users] Packetfence 802.1x Radius Server with LDAP Backend (NO AD)
Hello,
I've been trying to test PacketFence on our corporate network, but I keep running into roadblocks. I've tried to follow the PacketFence installation guide but am not able to do so because we do not use Microsoft Active Directory. The installation documentation guide is good but unfortunately written sequentially -- it pre-supposes you have access to an AD environment and in order to do the steps in later chapters (Say, Chapter 11), you had to have set up everything successfully in Chapter 4/5....
Our corporate environment contains little to no Microsoft products (only supporting the odd legacy workstation or laptop). Everything else is macOS, Linux or BSD.
All we're looking to do is simply have the Radius server set the VLAN on the port based on authentication. If you authenticate, you get network access. Otherwise, nothing. The most basic and simple use case of this software (which is why I'm sure the install guide starts there).
I am using the following setup:
-PacketFence 8.1 installed on CentOS 7.5 (IP: 10.111.111.1)
-Cisco 2960X 48 port switch (IP: 10.111.111.2)
-Test LDAP server (OpenDJ 2.5.2) which has been configured the same as our corporate LDAP server.
I managed to get everything installed nicely but run into issues at section 5.2 (Titled: Connecting PacketFence to a Microsoft Active Directory). Having no AD, I couldn't complete step 5.2 in its entirety (I have no Domain to define or REALM to join) but instead went to Authentication Sources and added my internal LDAP server. I receive the "Sucess !" message when trying the test button. I then configured the switch as in sections 5.3, 5.4 and 5.5. I even got out a Windows 10 Laptop to do step 5.6. However, it has never worked. I can never move beyond step 5.7.
Symptoms:
When I connect the ethernet cable to the laptop, I am immediately prompted for a Username/Password which I provide. However it says "Authentication Failed".
I've captured the output from the Radius debug using the following command run as root (Section 12.3): raddebug -t 300 -f /usr/local/pf/var/run/radiusd.sock
##### raddebug #####
(13) Mon Oct 1 12:06:01 2018: Debug: mschap: Creating challenge hash with username: testuser
(13) Mon Oct 1 12:06:01 2018: Debug: mschap: Client is using MS-CHAPv2
(13) Mon Oct 1 12:06:01 2018: Debug: mschap: Executing: /usr/local/pf/bin/ntlm_auth_wrapper -- --request-nt-key --username=%{%{Stripped-User-Name}:-%{mschap:User-Name:-None}} --challenge=%{mschap:Challenge:-00} --nt-response=%{mschap:NT-Response:-00}:
(13) Mon Oct 1 12:06:01 2018: Debug: mschap: EXPAND --username=%{%{Stripped-User-Name}:-%{mschap:User-Name:-None}}
(13) Mon Oct 1 12:06:01 2018: Debug: mschap: --> --username=testuser
(13) Mon Oct 1 12:06:01 2018: Debug: mschap: Creating challenge hash with username: testuser
(13) Mon Oct 1 12:06:01 2018: Debug: mschap: EXPAND --challenge=%{mschap:Challenge:-00}
(13) Mon Oct 1 12:06:01 2018: Debug: mschap: --> --challenge=8881e30a07b259b3
(13) Mon Oct 1 12:06:01 2018: Debug: mschap: EXPAND --nt-response=%{mschap:NT-Response:-00}
(13) Mon Oct 1 12:06:01 2018: Debug: mschap: --> --nt-response=10a441d370fdb1c7723ca301f3885e45ca2bcd6ca6f61dd9
(13) Mon Oct 1 12:06:01 2018: ERROR: mschap: Program returned code (1) and output 'Reading winbind reply failed! (0xc0000001)'
(13) Mon Oct 1 12:06:01 2018: Debug: mschap: External script failed
(13) Mon Oct 1 12:06:01 2018: ERROR: mschap: External script says: Reading winbind reply failed! (0xc0000001)
(13) Mon Oct 1 12:06:01 2018: ERROR: mschap: MS-CHAP2-Response is incorrect
(13) Mon Oct 1 12:06:01 2018: Debug: [mschap] = reject
(13) Mon Oct 1 12:06:01 2018: Debug: } # else = reject
(13) Mon Oct 1 12:06:01 2018: Debug: } # else = reject
(13) Mon Oct 1 12:06:01 2018: Debug: } # policy packetfence-mschap-authenticate = reject
(13) Mon Oct 1 12:06:01 2018: Debug: } # else = reject
(13) Mon Oct 1 12:06:01 2018: Debug: } # Auth-Type MS-CHAP = reject
(13) Mon Oct 1 12:06:01 2018: Debug: eap: Sending EAP Failure (code 4) ID 8 length 4
##################
Or example of the issue from radius.log
#### radius.log ####
Oct 1 13:55:43 packetfence8-1 auth[35178]: rlm_sql (sql): Closing connection (0): Hit idle_timeout, was idle for 96 seconds
Oct 1 13:55:43 packetfence8-1 auth[35178]: rlm_sql (sql): Closing connection (1): Hit idle_timeout, was idle for 96 seconds
Oct 1 13:55:43 packetfence8-1 auth[35178]: rlm_sql (sql): Opening additional connection (2), 1 of 64 pending slots used
Oct 1 13:55:43 packetfence8-1 auth[35178]: Need 2 more connections to reach min connections (3)
Oct 1 13:55:43 packetfence8-1 auth[35178]: rlm_sql (sql): Opening additional connection (3), 1 of 63 pending slots used
Oct 1 13:55:43 packetfence8-1 auth[35178]: (13) mschap: ERROR: Program returned code (1) and output 'Reading winbind reply failed! (0xc0000001)'
Oct 1 13:55:43 packetfence8-1 auth[35178]: (13) Login incorrect (mschap: Program returned code (1) and output 'Reading winbind reply failed! (0xc0000001)'): [testuser] (from client 10.111.111.2 port 50121 cli a0:ce:c8:09:9a:b4 via TLS tunnel)
Oct 1 13:55:43 packetfence8-1 auth[35178]: (14) eap_peap: This means you need to read the PREVIOUS messages in the debug output
Oct 1 13:55:43 packetfence8-1 auth[35178]: (14) eap_peap: to find out the reason why the user was rejected
Oct 1 13:55:43 packetfence8-1 auth[35178]: (14) eap_peap: Look for "reject" or "fail". Those earlier messages will tell you
Oct 1 13:55:43 packetfence8-1 auth[35178]: (14) eap_peap: what went wrong, and how to fix the problem
Oct 1 13:55:43 packetfence8-1 auth[35178]: (14) Login incorrect (eap_peap: The users session was previously rejected: returning reject (again.)): [testuser] (from client 10.111.111.2 port 50121 cli a0:ce:c8:09:9a:b4)
Oct 1 13:55:43 packetfence8-1 auth[35178]: [mac:a0:ce:c8:09:9a:b4] Rejected user: testuser
###############
I've seen the "windbind reply fail previously" posted on the message board here but for a different use case: https://www.mail-archive.com/packetfence-users@lists.sourceforge.net/msg15094.html
I tried adding the required portions to packetfence-tunnel template file:
##########
# The ldap module reads passwords from the LDAP database.
ldap
if (ok) {update control {&MS-CHAP-Use-NTLM-Auth := No}}
##########
But now my Radius server won't start up. It's saying there's no LDAP module installed. Here is the output from 'journalctl -xe':
##########
Oct 01 14:56:41 packetfence8-1.testdomain.local radiusd[43004]: /usr/local/pf/raddb/sites-enabled/packetfence-tunnel[122]: Failed to find "ldap" as a module or policy.
Oct 01 14:56:41 packetfence8-1.testdomain.local radiusd[43004]: /usr/local/pf/raddb/sites-enabled/packetfence-tunnel[122]: Please verify that the configuration exists in /usr/local/pf/raddb/mods-enabled/ldap.
Oct 01 14:56:41 packetfence8-1.testdomain.local radiusd[43004]: /usr/local/pf/raddb/sites-enabled/packetfence-tunnel[25]: Errors parsing authorize section.
##########
I don't want to start hacking around with the Freeradius instance in PacketFence blindly. I don't know Freeradius (and was hoping PacketFence would buffer me from having to hack together config files) but it appears this is where my issues are.
So! Could anybody recommend a way to move forward ?
I don't want to believe that PacketFence has AD as a requirement for usage, but it seems like every guide or tutorial about Packetfence involves it. Every error code or issue I look up has something to do with AD. It even appears to be an integral part of the PacketFence GUI.
I hope in the future the developpers would take into consideration that not everybody uses Microsoft products.
-J
_______________________________________________ PacketFence-users mailing list PacketFence-users@lists.sourceforge.net https://lists.sourceforge.net/lists/listinfo/packetfence-users
