FR 3.0.12 exec_perl: ERROR: Failed to create pair &request:EAP-Message
Hi, I have a problem with FR 3.0.12 as a proxy with a perl modules in the authorize section which does not include the EAP-Message attributes from the incoming request into the outgoing proxy request. When I disable the perl module, the EAP-Message is proxied correctly and the problem only occurs with multiple EAP-Message attributes. I found this conversation from 11/2016 which seems to be related: http://freeradius.1045715.n5.nabble.com/PERL-and-EAL-TLS-Modul-gt-Failed-to-... However, the conversation seems to have stopped without a solution or fix and I don't see anything in the release notes of 3.0.13 or 3.0.14 either... so I guess the issue has not been taken care of yet. Here's some debugging output: (1255) Received Access-Request Id 41 ... length 804 (1255) User-Name = "x" ... (1255) EAP-Message = 0x0276024819800000023e16030302061000020202006288d372a198ab690b34793275ed4eb9b448611f3cf207b5321e147bd85ce371e5d95b9f43572fab73517455ef1b3fe3eca0232825c5feb7e7233c3b08cd9d77205d49a157afa734730496f7a2b9b284654486313cc104e5f70fbd0ff2b5478549a5 ... (1255) session-state: No cached attributes (1255) # Executing section authorize from file server.conf (1255) authorize { (1255) [preprocess] = ok (1255) exec_perl: $RAD_REQUEST{'User-Name'} = &request:User-Name -> 'x' ... (1255) exec_perl: $RAD_REQUEST{'EAP-Message'} = &request:EAP-Message -> '0x0276024819800000023e16030302061000020202006288d372a198ab690b34793275ed4eb9b448611f3cf207b5321e147bd85ce371e5d95b9f43572fab73517455ef1b3fe3eca0232825c5feb7e7233c3b08cd9d77205d49a157afa734730496f7a2b9b284654486313cc104e5f70fbd0ff2b5478549a5d992778059693e3857f542e79b6bcca778b991167120b479ac90efc8508af066f6e600720b1f43130963f9f9299b91736210d6e3ad28eaed792800c9dff95c7df1eeae1a2bd5f18394c41476d38e8a348f2f0093890dd192695840f6e681ccc6cdb79b95fba1cd6a479d9ff8bc57312454d9203e9d19e4544650374e4f632bbb2cac4dfa501401862b3eb2152d7dc96b2d30a736233ba77600009a7ca4702d76ddd4f5e5afd9f00426ff88b8fb07902e7aacdfd76ec86847600c764177b435f8cdf2c4b44a6b62154c60640ff21ccac1105a8f0088a6e6582d7e70f525829b90a2961348e569fc71be3347280381c7d8b58d0c3a502042539092d31e73e0f44ffdfb01b618c4b0be79df064e3584c62e9374ddba8301e7afa9fcca4f286b8463b2b6d885088db0c1275873714904141ab79b62f5a8f363466c33c659d58f139cbaaf6db5b3aa7b6eececc1224c626b22bb529fba206d8816fa9da708cf223e3c50079e3378cfd37890b331f0092ad5ae62e218c3dde18d974ff24318bb16639702399448d62b92' ... (1255) exec_perl: &request:User-Name = $RAD_REQUEST{'User-Name'} -> 'x' (1255) exec_perl: ERROR: Failed to create pair &request:EAP-Message = $RAD_REQUEST{'EAP-Message'} -> '0x0276024819800000023e16030302061000020202006288d372a198ab690b34793275ed4eb9b448611f3cf207b5321e147bd85ce371e5d95b9f43572fab73517455ef1b3fe3eca0232825c5feb7e7233c3b08cd9d77205d49a157afa734730496f7a2b9b284654486313cc104e5f70fbd0ff2b5478549a5d992778059693e3857f542e79b6bcca778b991167120b479ac90efc8508af066f6e600720b1f43130963f9f9299b91736210d6e3ad28eaed792800c9dff95c7df1eeae1a2bd5f18394c41476d38e8a348f2f0093890dd192695840f6e681ccc6cdb79b95fba1cd6a479d9ff8bc57312454d9203e9d19e4544650374e4f632bbb2cac4dfa501401862b3eb2152d7dc96b2d30a736233ba77600009a7ca4702d76ddd4f5e5afd9f00426ff88b8fb07902e7aacdfd76ec86847600c764177b435f8cdf2c4b44a6b62154c60640ff21ccac1105a8f0088a6e6582d7e70f525829b90a2961348e569fc71be3347280381c7d8b58d0c3a502042539092d31e73e0f44ffdfb01b618c4b0be79df064e3584c62e9374ddba8301e7afa9fcca4f286b8463b2b6d885088db0c1275873714904141ab79b62f5a8f363466c33c659d58f139cbaaf6db5b3aa7b6eececc1224c626b22bb529fba206d8816fa9da708cf223e3c50079e3378cfd37890b331f0092ad5ae62e218c3dde18d974ff24318bb16639702399448d62b92' ... (1255) [exec_perl] = noop ... (1255) } # authorize = ok (1255) Starting proxy to home server ... port 1812 (1255) # Executing section pre-proxy from file server.conf (1255) pre-proxy { (1255) } # pre-proxy = noop (1255) Proxying request to home server ... port 1812 timeout 5.000000 (1255) Sent Access-Request Id 130 from ... length 273 ... (1255) User-Name = "x" (1255) EAP-Message = 0x ... Waking up in 0.1 seconds. Kind regards, Thor
Thor Spruyt wrote:
Hi,
I have a problem with FR 3.0.12 as a proxy with a perl modules in the authorize section which does not include the EAP-Message attributes from the incoming request into the outgoing proxy request. When I disable the perl module, the EAP-Message is proxied correctly and the problem only occurs with multiple EAP-Message attributes.
I found this conversation from 11/2016 which seems to be related: http://freeradius.1045715.n5.nabble.com/PERL-and-EAL-TLS-Modul-gt-Failed-to-... However, the conversation seems to have stopped without a solution or fix and I don't see anything in the release notes of 3.0.13 or 3.0.14 either... so I guess the issue has not been taken care of yet.
I remember trying to reproduce that case without success. Even though, could you still try it with 3.0.14, not every fix ends up in the changelog or a mail thread. Otherwise, since this problem occurs something in the conversion of binary data to a hexadecimal representation, I guess we could fix it by skipping that step. Perl can handle binary strings perfectly fine, and trying to make changes to a binary value in rlm_perl now requires a pack and unpack. If we make it a config option that is disabled by default, but enabled in the default cofig, all existing setups won't have behaviour changes when upgrading -- Herwin Weststrate
I'm not sure about an exact way to reproduce. What I know is that it happens when there are multiple EAP-Message attributes in the request packet. It appears that such large EAP-Message content is sent by the client after the server certificate has been received and when TLS 1.2 is used. Here's an example: AVP: l=255 t=EAP-Message(79) Segment[1] AVP: l=255 t=EAP-Message(79) Segment[2] AVP: l=80 t=EAP-Message(79) Last Segment[3] EAP fragment Extensible Authentication Protocol Code: Response (2) Id: 6 Length: 584 Type: Protected EAP (EAP-PEAP) (25) EAP-TLS Flags: 0x80 EAP-TLS Length: 574 Secure Sockets Layer TLSv1.2 Record Layer: Handshake Protocol: Client Key Exchange TLSv1.2 Record Layer: Change Cipher Spec Protocol: Change Cipher Spec TLSv1.2 Record Layer: Handshake Protocol: Multiple Handshake Messages Anyway, I'll check how 3.0.14 handles it... Thor ----- Original Message ----- From: "Herwin Weststrate" <freeradius@herwinw.nl> To: "FreeRadius users mailing list" <freeradius-users@lists.freeradius.org> Sent: Saturday, June 3, 2017 9:29:25 AM Subject: Re: FR 3.0.12 exec_perl: ERROR: Failed to create pair &request:EAP-Message Thor Spruyt wrote:
Hi,
I have a problem with FR 3.0.12 as a proxy with a perl modules in the authorize section which does not include the EAP-Message attributes from the incoming request into the outgoing proxy request. When I disable the perl module, the EAP-Message is proxied correctly and the problem only occurs with multiple EAP-Message attributes.
I found this conversation from 11/2016 which seems to be related: http://freeradius.1045715.n5.nabble.com/PERL-and-EAL-TLS-Modul-gt-Failed-to-... However, the conversation seems to have stopped without a solution or fix and I don't see anything in the release notes of 3.0.13 or 3.0.14 either... so I guess the issue has not been taken care of yet.
I remember trying to reproduce that case without success. Even though, could you still try it with 3.0.14, not every fix ends up in the changelog or a mail thread. Otherwise, since this problem occurs something in the conversion of binary data to a hexadecimal representation, I guess we could fix it by skipping that step. Perl can handle binary strings perfectly fine, and trying to make changes to a binary value in rlm_perl now requires a pack and unpack. If we make it a config option that is disabled by default, but enabled in the default cofig, all existing setups won't have behaviour changes when upgrading -- Herwin Weststrate - List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
Unfortunately, also with v3.0.14 the problem seems to be there, although the error message is slightly different ... (7961) Received Access-Request Id 208 ... length 779 (7961) EAP-Message = 0x0205024819800000023e1603030206100002020200180326c978bbd15ef07089d5ab8bc9d6f0ef586dded8142e2b765df12ed496d949de19467445830a97bedaa533a0b04b8e3acfb548c5c21ed685dd318d1ecde553b071b540f84de2b2d3d4abd383c50a24d97990bdd74bde45250a2c314cf599ee42 (7961) authorize { (7961) [preprocess] = ok (7961) exec_perl: ERROR: Failed to create pair - Length of Hex String is not even, got 1021 bytes (7961) exec_perl: ERROR: &request:EAP-Message = $RAD_REQUEST{'EAP-Message'} -> '0x0205024819800000023e1603030206100002020200180326c978bbd15ef07089d5ab8bc9d6f0ef586dded8142e2b765df12ed496d949de19467445830a97bedaa533a0b04b8e3acfb548c5c21ed685dd318d1ecde553b071b540f84de2b2d3d4abd383c50a24d97990bdd74bde45250a2c314cf599ee429b2dc2713d7e91bf654235cc5f111d90258c0f143dd7aa07f3062d1a4b0b6b9b584c0eab0366472ff366ce0de7101c7aa9287ef2a6eb3527a3b811e66867ea79db089ed13005416bdcf6d8f4334a13adcff49eeb3caae0e1fdab59092f4e75b2b78b80fd87cb19642b53a24432eda80267eb65302928001777f718809b33074405eb1b1c0f82d657a36c4c0f64eb0aa1145711d0fc1c5ac8692472988839a7ad465fca137a03fbef5898b864b3a0e3bd29641d5327fd38369cbcd2c85ea53fd66e76e701d5b35a894aa34f77bd85beb753173ab36e3f0521997c464f690fd59194b883d09fba327dc42c6c0820d2bdcf3e5e214599056de278fcb0f13b3effdbe626f4c9e0168c57455dbc64d479f00f9d6fc914810d8a03e76493924beaeee88d6d8f3e6f286b5464a9a1fb1a89c2735732984503b1f6696e78815d19ee6efd3ba6d09f0f2b936c1c4ef2ce9a72f941606e5c82eea9cb88af837b79ab2170b957a6c55b98b9e3d05d2ba778cc6c90d6f2beac20059000f6e9adfae12a1811c36e734a420a8b6b' (7961) [exec_perl] = noop (7961) } # authorize = ok (7961) Proxying request to home server ... timeout 5.000000 (7961) Sent Access-Request Id 210 ... length 249 (7961) 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 ? If I remove the "concat" from the EAP-Message attribute in the dictionary, then it works! (9411) Received Access-Request Id 135 ... length 770 (9411) EAP-Message = 0x02060250198000000246160301020610000202020071def3e123a0d39f7e0e0b3d63db878d3619a4b0bd64577a2971622958a765dad49388574562da2879698ecb451925923bd6eb187dd779d177ec16ed4f43c74070eeab77a7179925e27432acc54d347b00a1f018c8767c8d3d2fcb34a2846f0e7b13 (9411) EAP-Message = 0x4154f8d66b565876cd48a207c266e2b6a5118b4381b734c6ad0eef3b1b504f641ae35ead9cfac5ed0963edc97b5384e8b7812fb4aa06db3e199f456ddfdea0df6e3741321f8b815b0d580ffd6b148d69dc36b59612c0fc1382733d01cebd7460106021dd8cf99299bd8ff7c59be3292ee233efe76f4aa2 (9411) EAP-Message = 0x9e20b49d4edd2419cbce1f01f388dcbdf461b51df6c7f470275146140301000101160301003040923dd99bfb21c5eedad62f213ae486b977b292f528acc59956128674b9f25322b8d92699fd6eb758221e4448e572ca (9411) authorize { (9411) [preprocess] = ok (9411) exec_perl: &request:EAP-Message += $RAD_REQUEST{'EAP-Message'} -> '0x02060250198000000246160301020610000202020071def3e123a0d39f7e0e0b3d63db878d3619a4b0bd64577a2971622958a765dad49388574562da2879698ecb451925923bd6eb187dd779d177ec16ed4f43c74070eeab77a7179925e27432acc54d347b00a1f018c8767c8d3d2fcb34a2846f0e7b13672deac9cbae52d0725077be905d0ff02a0650836932199efbd1a7c3dcb43f9f251f66581f40f51b63feb2e776fa3b47135026ca929bdb3ab454ef3356424baa06dc98d80200127c8aca7b0b024f4c1b9ccbc49d75fa944967e4d39418f2c2a9fb7340299c9c5ea93267322b9f2f016fb922507febf9012899db25b242661ae8df7d8e6ab88b' (9411) exec_perl: &request:EAP-Message += $RAD_REQUEST{'EAP-Message'} -> '0x4154f8d66b565876cd48a207c266e2b6a5118b4381b734c6ad0eef3b1b504f641ae35ead9cfac5ed0963edc97b5384e8b7812fb4aa06db3e199f456ddfdea0df6e3741321f8b815b0d580ffd6b148d69dc36b59612c0fc1382733d01cebd7460106021dd8cf99299bd8ff7c59be3292ee233efe76f4aa28a3c80c84d427b0b3d04d4cc8541aaab0a9be24f71488b804cad76cfe90c658f39bc35f1dc09245510092794f8799ae3e86c268f1fbbf21611a962d7134e25c87dc9996a0b1a66564c3a3d0ce9bcbe2260b03bc91682d892957feed7f83ac2de5f69c9efef9d88d8deef12c63e5aa94278ffc417838e874113ea2469c96828d31d6fd9f577c7' (9411) exec_perl: &request:EAP-Message += $RAD_REQUEST{'EAP-Message'} -> '0x9e20b49d4edd2419cbce1f01f388dcbdf461b51df6c7f470275146140301000101160301003040923dd99bfb21c5eedad62f213ae486b977b292f528acc59956128674b9f25322b8d92699fd6eb758221e4448e572ca' (9411) [exec_perl] = noop (9411) } # authorize = ok (9411) Proxying request to home server ... timeout 5.000000 (9411) Sent Access-Request Id 1 ... length 830 (9411) EAP-Message += 0x02060250198000000246160301020610000202020071def3e123a0d39f7e0e0b3d63db878d3619a4b0bd64577a2971622958a765dad49388574562da2879698ecb451925923bd6eb187dd779d177ec16ed4f43c74070eeab77a7179925e27432acc54d347b00a1f018c8767c8d3d2fcb34a2846f0e7b13 (9411) EAP-Message += 0x4154f8d66b565876cd48a207c266e2b6a5118b4381b734c6ad0eef3b1b504f641ae35ead9cfac5ed0963edc97b5384e8b7812fb4aa06db3e199f456ddfdea0df6e3741321f8b815b0d580ffd6b148d69dc36b59612c0fc1382733d01cebd7460106021dd8cf99299bd8ff7c59be3292ee233efe76f4aa2 (9411) EAP-Message += 0x9e20b49d4edd2419cbce1f01f388dcbdf461b51df6c7f470275146140301000101160301003040923dd99bfb21c5eedad62f213ae486b977b292f528acc59956128674b9f25322b8d92699fd6eb758221e4448e572ca I realize that this is not a good solution, but it works as a workaround since the perl module actually doesn't need the EAP-Message content anyway. Thor
On Jun 3, 2017, at 8:34 PM, Thor Spruyt <thor.spruyt@telenet.be> wrote:
Unfortunately, also with v3.0.14 the problem seems to be there, although the error message is slightly different ...
I don't think you're running 3.0.14.
(7961) Received Access-Request Id 208 ... length 779 (7961) EAP-Message = 0x0205024819800000023e1603030206100002020200180326c978bbd15ef07089d5ab8bc9d6f0ef586dded8142e2b765df12ed496d949de19467445830a97bedaa533a0b04b8e3acfb548c5c21ed685dd318d1ecde553b071b540f84de2b2d3d4abd383c50a24d97990bdd74bde45250a2c314cf599ee42 (7961) authorize { (7961) [preprocess] = ok (7961) exec_perl: ERROR: Failed to create pair - Length of Hex String is not even, got 1021 bytes (7961) exec_perl: ERROR: &request:EAP-Message = $RAD_REQUEST{'EAP-Message'} ->
That message is when it's trying to convert the Perl variable to a FreeRADIUS attribute. 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 really think you're not running 3.0.14. Alan DeKok.
----- On Jun 4, 2017, at 3:43 PM, Alan DeKok aland@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.
----- 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.
On Jun 5, 2017, at 7:35 AM, Thor Spruyt <thor.spruyt@telenet.be> wrote:
I made a patch to v3.0.14 rlm_perl.c which add some length stuff in debug output and fixes the issue:
That just masks the issue with a larger buffer. I've pushed changes to the v3.0.x head which should fix this problem completely. Alan DeKok.
participants (3)
-
Alan DeKok -
Herwin Weststrate -
Thor Spruyt