FR 3.0.12 exec_perl: ERROR: Failed to create pair &request:EAP-Message

[Thor Spruyt]

----- On Jun 4, 2017, at 3:43 PM, Alan DeKok aland at deployingradius.com wrote:

> 
>  I don't think you're running 3.0.14.
> 

The first line of the debug output says:
FreeRADIUS Version 3.0.14

> 
>  What's missing is the initial message which shows it converting the FreeRADIUS
>  attribute to a Perl variable:
> 
>			len = vp_prints_value(buffer, sizeof(buffer), vp, 0);
>			RDEBUG("$%s{'%s'} = &%s:%s -> '%s'", hash_name, vp->da->name,
> 
>  i.e. there should be a debug message saying:
> 
>	$RAD_REQUEST{'EAP-Message'} = &request:EAP-Message -> 0x....
> 

Ok, here's debug with that part:

(2475) Received Access-Request Id 205 from ... to ... length 812
(2475)   User-Name = "..."
(2475)   NAS-IP-Address = ...
(2475)   NAS-Identifier = "..."
(2475)   Called-Station-Id = "..."
(2475)   NAS-Port-Type = Wireless-802.11
(2475)   NAS-Port = 0
(2475)   Calling-Station-Id = "..."
(2475)   Connect-Info = "CONNECT 0Mbps 802.11a"
(2475)   Acct-Session-Id = "59126A80-00000035"
(2475)   Framed-MTU = 1400
(2475)   EAP-Message = 0x021f025019800000024616030102061000020202008317b2366c99d6fd70314e675cc521cf83110299de0a04c5f015fddba9e6685cf01712fbcb90332deb808e26d127b4d4711532ebb4912daba89e5dd2c660a38afc1646069c21802d4d1e7f82bed6eae80002e28f06e6748344456e98a65cbe4733d8
(2475)   State = 0x45415042414c414e43453a69643d31
(2475)   Message-Authenticator = 0xb190d2707b52b493dd1e6cbb306a8642
(2475) session-state: No cached attributes
(2475) # Executing section authorize from file server.conf
(2475)   authorize {
(2475)     [preprocess] = ok
(2475) exec_perl:   $RAD_REQUEST{'User-Name'} = &request:User-Name -> '...'
(2475) exec_perl:   $RAD_REQUEST{'NAS-IP-Address'} = &request:NAS-IP-Address -> '...'
(2475) exec_perl:   $RAD_REQUEST{'NAS-Port'} = &request:NAS-Port -> '0'
(2475) exec_perl:   $RAD_REQUEST{'Framed-MTU'} = &request:Framed-MTU -> '1400'
(2475) exec_perl:   $RAD_REQUEST{'State'} = &request:State -> '0x45415042414c414e43453a69643d31'
(2475) exec_perl:   $RAD_REQUEST{'Called-Station-Id'} = &request:Called-Station-Id -> '...'
(2475) exec_perl:   $RAD_REQUEST{'Calling-Station-Id'} = &request:Calling-Station-Id -> '...'
(2475) exec_perl:   $RAD_REQUEST{'NAS-Identifier'} = &request:NAS-Identifier -> '...'
(2475) exec_perl:   $RAD_REQUEST{'NAS-Port-Type'} = &request:NAS-Port-Type -> 'Wireless-802.11'
(2475) exec_perl:   $RAD_REQUEST{'Acct-Session-Id'} = &request:Acct-Session-Id -> '59126A80-00000035'
(2475) exec_perl:   $RAD_REQUEST{'Event-Timestamp'} = &request:Event-Timestamp -> 'Jun  5 2017 11:30:42 CEST'
(2475) exec_perl:   $RAD_REQUEST{'Connect-Info'} = &request:Connect-Info -> 'CONNECT 0Mbps 802.11a'
(2475) exec_perl:   $RAD_REQUEST{'EAP-Message'} = &request:EAP-Message -> '0x021f025019800000024616030102061000020202008317b2366c99d6fd70314e675cc521cf83110299de0a04c5f015fddba9e6685cf01712fbcb90332deb808e26d127b4d4711532ebb4912daba89e5dd2c660a38afc1646069c21802d4d1e7f82bed6eae80002e28f06e6748344456e98a65cbe4733d8c44c3a7da3c79ddc20574c01902d61c070d4b00ef52ca153a338a207253a2773a8cf4d579fcef1ae587918c01bb0486a08b905dd4fa12c6e0b6e5bed5c56fb55116b4c498854bd6433caef2b450438abf20c2cd25a1c30953f7b8532a7ee1fd076d1015b0435f8a7296de4158c4467e9a00678e940d93d139caead05db265e371b4e0fa4cb1a2d411c82a0fb12f43d9638b5c59844a6a7509258b60a75dc6cce34cb6bd0b6cf8bb153270455bdc9fecbe11829971967a3a74c2050f3356f8f648fd9e0bca84e22653e3c0ad0d72f68d9d113d8e7f8977621ef1b069095144474d8784dd22aea07323c4698f767b4bc5cd6d7273a986add053926e10b6d479b4ed5d20ac612391df721fb4bb966ec60133a8b0976bfecd3930f75110ba2d4d509ea15fcb68858fea3954b76e3624316006ab89fd6bf34b55b3af671fddeff77f52a4dfa7583bb0dc09d0be1c11d2ccf91ea4e507c7ff84ae263ee8507660cdd38bdf2b20b8ccd1ab3f96bcdcb43172738f11739839b83d431f65e15ed479989bf71343b14ad9ca1'
(2475) exec_perl:   $RAD_REQUEST{'Message-Authenticator'} = &request:Message-Authenticator -> '0xb190d2707b52b493dd1e6cbb306a8642'
(2475) exec_perl: &request:NAS-Port-Type = $RAD_REQUEST{'NAS-Port-Type'} -> 'Wireless-802.11'
(2475) exec_perl: &request:Acct-Session-Id = $RAD_REQUEST{'Acct-Session-Id'} -> '59126A80-00000035'
(2475) exec_perl: &request:Calling-Station-Id = $RAD_REQUEST{'Calling-Station-Id'} -> '...'
(2475) exec_perl: &request:Called-Station-Id = $RAD_REQUEST{'Called-Station-Id'} -> '...'
(2475) exec_perl: &request:State = $RAD_REQUEST{'State'} -> '0x45415042414c414e43453a69643d31'
(2475) exec_perl: &request:Message-Authenticator = $RAD_REQUEST{'Message-Authenticator'} -> '0xb190d2707b52b493dd1e6cbb306a8642'
(2475) exec_perl: &request:User-Name = $RAD_REQUEST{'User-Name'} -> '...'
(2475) exec_perl: &request:Event-Timestamp = $RAD_REQUEST{'Event-Timestamp'} -> 'Jun  5 2017 11:30:42 CEST'
(2475) exec_perl: &request:NAS-Identifier = $RAD_REQUEST{'NAS-Identifier'} -> '...'
(2475) exec_perl: ERROR: Failed to create pair - Length of Hex String is not even, got 1021 bytes
(2475) exec_perl: ERROR:     &request:EAP-Message = $RAD_REQUEST{'EAP-Message'} -> '0x021f025019800000024616030102061000020202008317b2366c99d6fd70314e675cc521cf83110299de0a04c5f015fddba9e6685cf01712fbcb90332deb808e26d127b4d4711532ebb4912daba89e5dd2c660a38afc1646069c21802d4d1e7f82bed6eae80002e28f06e6748344456e98a65cbe4733d8c44c3a7da3c79ddc20574c01902d61c070d4b00ef52ca153a338a207253a2773a8cf4d579fcef1ae587918c01bb0486a08b905dd4fa12c6e0b6e5bed5c56fb55116b4c498854bd6433caef2b450438abf20c2cd25a1c30953f7b8532a7ee1fd076d1015b0435f8a7296de4158c4467e9a00678e940d93d139caead05db265e371b4e0fa4cb1a2d411c82a0fb12f43d9638b5c59844a6a7509258b60a75dc6cce34cb6bd0b6cf8bb153270455bdc9fecbe11829971967a3a74c2050f3356f8f648fd9e0bca84e22653e3c0ad0d72f68d9d113d8e7f8977621ef1b069095144474d8784dd22aea07323c4698f767b4bc5cd6d7273a986add053926e10b6d479b4ed5d20ac612391df721fb4bb966ec60133a8b0976bfecd3930f75110ba2d4d509ea15fcb68858fea3954b76e3624316006ab89fd6bf34b55b3af671fddeff77f52a4dfa7583bb0dc09d0be1c11d2ccf91ea4e507c7ff84ae263ee8507660cdd38bdf2b20b8ccd1ab3f96bcdcb43172738f11739839b83d431f65e15ed479989bf71343b14ad9ca1'
(2475) exec_perl: &request:Connect-Info = $RAD_REQUEST{'Connect-Info'} -> 'CONNECT 0Mbps 802.11a'
(2475) exec_perl: &request:NAS-IP-Address = $RAD_REQUEST{'NAS-IP-Address'} -> '...'
(2475) exec_perl: &request:NAS-Port = $RAD_REQUEST{'NAS-Port'} -> '0'
(2475) exec_perl: &request:Framed-MTU = $RAD_REQUEST{'Framed-MTU'} -> '1400'
(2475)     [exec_perl] = noop
(2475)   } # authorize = ok
(2475) Starting proxy to home server ... port 1812
(2475) # Executing section pre-proxy from file server.conf
(2475)   pre-proxy {
(2475)   } # pre-proxy = noop
(2475) Proxying request to home server ... port 1812 timeout 5.000000
(2475) Sent Access-Request Id 197 from ... to ... length 274
(2475)   NAS-Port-Type = Wireless-802.11
(2475)   Acct-Session-Id = "59126A80-00000035"
(2475)   Calling-Station-Id = "..."
(2475)   Called-Station-Id = "..."
(2475)   State = 0x45415042414c414e43453a69643d31
(2475)   Message-Authenticator = 0xb190d2707b52b493dd1e6cbb306a8642
(2475)   User-Name = "..."
(2475)   Event-Timestamp = "Jun  5 2017 11:30:42 CEST"
(2475)   NAS-Identifier = "..."
(2475)   EAP-Message = 0x
(2475)   Connect-Info = "CONNECT 0Mbps 802.11a"
(2475)   NAS-IP-Address = ...
(2475)   NAS-Port = 0
(2475)   Framed-MTU = 1400
(2475)   Proxy-State = 0x323035

Thor.