FR 3.0.12 exec_perl: ERROR: Failed to create pair &request:EAP-Message
Thor Spruyt
thor.spruyt at telenet.be
Mon Jun 5 13:35:08 CEST 2017
----- On Jun 4, 2017, at 3:43 PM, Alan DeKok aland at deployingradius.com wrote:
>
> 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....
>
>> What I find strange is that the request packet dump says there's only one
>> EAP-Message attribute in the request (I assume only the first one is printed)
>> while rlm_perl tries to put 510 bytes into $RAD_REQUEST{'EAP-Message'}/
>> Note the debug output where it says "got 1021 bytes" => I guess this is 1021
>> characters instead of bytes ?
>
> It's bytes. The printed string isn't being terminated for some reason.
>
>> If I remove the "concat" from the EAP-Message attribute in the dictionary, then
>> it works!
>
> Yes, because the input EAP-Message becomes shorter.
>
I made a patch to v3.0.14 rlm_perl.c which add some length stuff in debug output and fixes the issue:
--- freeradius-server-3.0.14/src/modules/rlm_perl/rlm_perl.c 2017-05-26 20:11:20.000000000 +0200
+++ freeradius-server-3.0.14-mod/src/modules/rlm_perl/rlm_perl.c 2017-06-05 12:52:48.792316684 +0200
@@ -625,19 +625,19 @@
{
size_t len;
- char buffer[1024];
+ char buffer[2048];
switch (vp->da->type) {
case PW_TYPE_STRING:
- RDEBUG("$%s{'%s'}[%i] = &%s:%s -> '%s'", hash_name, vp->da->name, *i,
- list_name, vp->da->name, vp->vp_strvalue);
+ RDEBUG("$%s{'%s'}[%i] = &%s:%s -> '%s' (length %u)", hash_name, vp->da->name, *i,
+ list_name, vp->da->name, vp->vp_strvalue, vp->vp_length);
av_push(av, newSVpvn(vp->vp_strvalue, vp->vp_length));
break;
default:
len = vp_prints_value(buffer, sizeof(buffer), vp, 0);
- RDEBUG("$%s{'%s'}[%i] = &%s:%s -> '%s'", hash_name, vp->da->name, *i,
- list_name, vp->da->name, buffer);
+ RDEBUG("$%s{'%s'}[%i] = &%s:%s -> '%s' (length %u, buffer size %u)", hash_name, vp->da->name, *i,
+ list_name, vp->da->name, buffer, len, sizeof(buffer));
av_push(av, newSVpvn(buffer, truncate_len(len, sizeof(buffer))));
break;
}
@@ -668,7 +668,7 @@
char const *name;
char namebuf[256];
- char buffer[1024];
+ char buffer[2048];
size_t len;
@@ -709,15 +709,15 @@
*/
switch (vp->da->type) {
case PW_TYPE_STRING:
- RDEBUG("$%s{'%s'} = &%s:%s -> '%s'", hash_name, vp->da->name, list_name,
- vp->da->name, vp->vp_strvalue);
+ RDEBUG("$%s{'%s'} = &%s:%s -> '%s' (length %u)", hash_name, vp->da->name, list_name,
+ vp->da->name, vp->vp_strvalue, vp->vp_length);
(void)hv_store(rad_hv, name, strlen(name), newSVpvn(vp->vp_strvalue, vp->vp_length), 0);
break;
default:
len = vp_prints_value(buffer, sizeof(buffer), vp, 0);
- RDEBUG("$%s{'%s'} = &%s:%s -> '%s'", hash_name, vp->da->name,
- list_name, vp->da->name, buffer);
+ RDEBUG("$%s{'%s'} = &%s:%s -> '%s' (length %u, buffer size %u)", hash_name, vp->da->name,
+ list_name, vp->da->name, buffer, len, sizeof(buffer));
(void)hv_store(rad_hv, name, strlen(name),
newSVpvn(buffer, truncate_len(len, sizeof(buffer))), 0);
break;
With this patch, I get the following debug output:
(251) Received Access-Request Id 88 from ... to ... length 828
(251) User-Name = "..."
(251) NAS-IP-Address = ...
(251) NAS-Identifier = "..."
(251) Called-Station-Id = "..."
(251) NAS-Port-Type = Wireless-802.11
(251) NAS-Port = 0
(251) Calling-Station-Id = "..."
(251) Connect-Info = "CONNECT 0Mbps 802.11a"
(251) Acct-Session-Id = "59347952-00000017"
(251) Framed-MTU = 1400
(251) EAP-Message = 0x022b026019800000025616030202061000020202001a79f2f72468c336114c9eb3be9e7f46191faa143bce77fafb29585a071f3bdd8d930bb69e76b16ef42e16b54ce29db57ac5e511c7c287c30bdc861fa9f5d551a7c61bb3702406e7ff9aaf4bbbd79d8a283910786dd56705277615f3fd63e9383203
(251) State = 0x45415042414c414e43453a69643d31
(251) Message-Authenticator = 0x68e56edf4f2786b641902d4379a29ef4
(251) session-state: No cached attributes
(251) # Executing section authorize from file server.conf
(251) authorize {
(251) [preprocess] = ok
(251) exec_perl: $RAD_REQUEST{'User-Name'} = &request:User-Name -> '...' (length 20)
(251) exec_perl: $RAD_REQUEST{'NAS-IP-Address'} = &request:NAS-IP-Address -> '...' (length 13, buffer size 2048)
(251) exec_perl: $RAD_REQUEST{'NAS-Port'} = &request:NAS-Port -> '0' (length 1, buffer size 2048)
(251) exec_perl: $RAD_REQUEST{'Framed-MTU'} = &request:Framed-MTU -> '1400' (length 4, buffer size 2048)
(251) exec_perl: $RAD_REQUEST{'State'} = &request:State -> '0x45415042414c414e43453a69643d31' (length 32, buffer size 2048)
(251) exec_perl: $RAD_REQUEST{'Called-Station-Id'} = &request:Called-Station-Id -> '...' (length 31)
(251) exec_perl: $RAD_REQUEST{'Calling-Station-Id'} = &request:Calling-Station-Id -> '...' (length 17)
(251) exec_perl: $RAD_REQUEST{'NAS-Identifier'} = &request:NAS-Identifier -> '...' (length 17)
(251) exec_perl: $RAD_REQUEST{'NAS-Port-Type'} = &request:NAS-Port-Type -> 'Wireless-802.11' (length 15, buffer size 2048)
(251) exec_perl: $RAD_REQUEST{'Acct-Session-Id'} = &request:Acct-Session-Id -> '59347952-00000017' (length 17)
(251) exec_perl: $RAD_REQUEST{'Event-Timestamp'} = &request:Event-Timestamp -> 'Jun 5 2017 13:18:48 CEST' (length 25, buffer size 2048)
(251) exec_perl: $RAD_REQUEST{'Connect-Info'} = &request:Connect-Info -> 'CONNECT 0Mbps 802.11a' (length 21)
(251) exec_perl: $RAD_REQUEST{'EAP-Message'} = &request:EAP-Message -> '0x022b026019800000025616030202061000020202001a79f2f72468c336114c9eb3be9e7f46191faa143bce77fafb29585a071f3bdd8d930bb69e76b16ef42e16b54ce29db57ac5e511c7c287c30bdc861fa9f5d551a7c61bb3702406e7ff9aaf4bbbd79d8a283910786dd56705277615f3fd63e938320395ca1d91358164ad6900de2a8130e861c452742b02e8c85ecb7d9f944ceae35932bdabf6851d826c0c519651981b819f377bfae135a8d660d7b002a376804711b9ae405c91a0c94863f5c17d21a3528361f47e08ab3c309ce24f5f0b4f44ac19e70d72ac5e465441312341022979d2e5376ca32e4012db7348f7b141b06e912a178013ca30361e42ad1d48893ae08a3c95c74892d7334db8a9a2494d77413c947f8c44f62464c8b37176fc332ed6aee29b6bd2104caed5304b7068e425e89393be6d054cef2d41526072dac63076b6ff9cbd8eeedb01accc7485dc6160343220779b704eb6b98301adeff666234e0d05a7f6c6b83087adeba6bdc4f02c0b2859226f8391320efc7f30fc71239bfee46011a98b398991b61cae6bcd94680b96eaed378a8fc2c0eba0d9110dff354916209f06039d0fa39f536eb674c909b75a789529035151515b73ef41fffc0a3b8764cc0ca90cf5241c92b6421d056ecdca7b6d3034dc913d0e04d392ee42c65dc195abee91fe690a4fecc0611e44848e7d0906d62614c571b413d848737c09ef74f4ce2326cd6567ecb1b592afcc18da1403020001011603020040a93b7e0cfb4aeeb8f098236442fea41694fac296e8219d56bfe14d90fc42ba9f55bd880116df4bfa72e8afbc9b23e18897684ff0b38e76560400ffb294c11712' (length 1218, buffer size 2048)
(251) exec_perl: $RAD_REQUEST{'Message-Authenticator'} = &request:Message-Authenticator -> '0x68e56edf4f2786b641902d4379a29ef4' (length 34, buffer size 2048)
(251) exec_perl: &request:NAS-Port-Type = $RAD_REQUEST{'NAS-Port-Type'} -> 'Wireless-802.11'
(251) exec_perl: &request:Acct-Session-Id = $RAD_REQUEST{'Acct-Session-Id'} -> '59347952-00000017'
(251) exec_perl: &request:Calling-Station-Id = $RAD_REQUEST{'Calling-Station-Id'} -> '...'
(251) exec_perl: &request:Called-Station-Id = $RAD_REQUEST{'Called-Station-Id'} -> '...'
(251) exec_perl: &request:State = $RAD_REQUEST{'State'} -> '0x45415042414c414e43453a69643d31'
(251) exec_perl: &request:Message-Authenticator = $RAD_REQUEST{'Message-Authenticator'} -> '0x68e56edf4f2786b641902d4379a29ef4'
(251) exec_perl: &request:User-Name = $RAD_REQUEST{'User-Name'} -> '...'
(251) exec_perl: &request:Event-Timestamp = $RAD_REQUEST{'Event-Timestamp'} -> 'Jun 5 2017 13:18:48 CEST'
(251) exec_perl: &request:NAS-Identifier = $RAD_REQUEST{'NAS-Identifier'} -> '...'
(251) exec_perl: &request:EAP-Message = $RAD_REQUEST{'EAP-Message'} -> '0x022b026019800000025616030202061000020202001a79f2f72468c336114c9eb3be9e7f46191faa143bce77fafb29585a071f3bdd8d930bb69e76b16ef42e16b54ce29db57ac5e511c7c287c30bdc861fa9f5d551a7c61bb3702406e7ff9aaf4bbbd79d8a283910786dd56705277615f3fd63e938320395ca1d91358164ad6900de2a8130e861c452742b02e8c85ecb7d9f944ceae35932bdabf6851d826c0c519651981b819f377bfae135a8d660d7b002a376804711b9ae405c91a0c94863f5c17d21a3528361f47e08ab3c309ce24f5f0b4f44ac19e70d72ac5e465441312341022979d2e5376ca32e4012db7348f7b141b06e912a178013ca30361e42ad1d48893ae08a3c95c74892d7334db8a9a2494d77413c947f8c44f62464c8b37176fc332ed6aee29b6bd2104caed5304b7068e425e89393be6d054cef2d41526072dac63076b6ff9cbd8eeedb01accc7485dc6160343220779b704eb6b98301adeff666234e0d05a7f6c6b83087adeba6bdc4f02c0b2859226f8391320efc7f30fc71239bfee46011a98b398991b61cae6bcd94680b96eaed378a8fc2c0eba0d9110dff354916209f06039d0fa39f536eb674c909b75a789529035151515b73ef41fffc0a3b8764cc0ca90cf5241c92b6421d056ecdca7b6d3034dc913d0e04d392ee42c65dc195abee91fe690a4fecc0611e44848e7d0906d62614c571b413d848737c09ef74f4ce2326cd6567ecb1b592afcc18da1403020001011603020040a93b7e0cfb4aeeb8f098236442fea41694fac296e8219d56bfe14d90fc42ba9f55bd880116df4bfa72e8afbc9b23e18897684ff0b38e76560400ffb294c11712'
(251) exec_perl: &request:Connect-Info = $RAD_REQUEST{'Connect-Info'} -> 'CONNECT 0Mbps 802.11a'
(251) exec_perl: &request:NAS-IP-Address = $RAD_REQUEST{'NAS-IP-Address'} -> '...'
(251) exec_perl: &request:NAS-Port = $RAD_REQUEST{'NAS-Port'} -> '0'
(251) exec_perl: &request:Framed-MTU = $RAD_REQUEST{'Framed-MTU'} -> '1400'
(251) [exec_perl] = noop
(251) } # authorize = ok
(251) Starting proxy to home server ... port 1812
(251) # Executing section pre-proxy from file server.conf
(251) pre-proxy {
(251) } # pre-proxy = noop
(251) Proxying request to home server ... port 1812 timeout 5.000000
(251) Sent Access-Request Id 234 from ... to ... length 887
(251) NAS-Port-Type = Wireless-802.11
(251) Acct-Session-Id = "59347952-00000017"
(251) Calling-Station-Id = "..."
(251) Called-Station-Id = "..."
(251) State = 0x45415042414c414e43453a69643d31
(251) Message-Authenticator = 0x68e56edf4f2786b641902d4379a29ef4
(251) User-Name = "..."
(251) Event-Timestamp = "Jun 5 2017 13:18:48 CEST"
(251) NAS-Identifier = "..."
(251) EAP-Message = 0x022b026019800000025616030202061000020202001a79f2f72468c336114c9eb3be9e7f46191faa143bce77fafb29585a071f3bdd8d930bb69e76b16ef42e16b54ce29db57ac5e511c7c287c30bdc861fa9f5d551a7c61bb3702406e7ff9aaf4bbbd79d8a283910786dd56705277615f3fd63e9383203
(251) Connect-Info = "CONNECT 0Mbps 802.11a"
(251) NAS-IP-Address = ...
(251) NAS-Port = 0
(251) Framed-MTU = 1400
(251) Proxy-State = 0x3838
I don't know if those changes to the code are completely correct and/or in line with how FR coding should be done, sorry for that.
Thor.
More information about the Freeradius-Users
mailing list