----- On Jun 4, 2017, at 3:43 PM, Alan DeKok aland@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.