PERL and EAL-TLS Modul -> Failed to create pair &request:EAP-Message = $RAD_REQUEST{'EAP-Message'}

Poltorak, Paul (CT DD DS EVO O BFD TM&ISEC 1) Paul.Poltorak at evosoft.com
Fri Nov 4 09:36:55 CET 2016


Hello all,

i'm using source complied version 3.0.12 on an SUSE SLES 12 SP1 x64.
EAP-TLS is working fine without PERL.
Now I would like to add PERL to do some stuff too.
But with enabled perl module it results in error and REJECT. 

This is my default server
server default {
listen {
        type = auth
        ipaddr = *
        port = 0
        limit {
              max_connections = 16
              lifetime = 0
              idle_timeout = 30
        }
}

listen {
        ipaddr = *
        port = 0
        type = acct
        limit {
        }
}

authorize {
        filter_username
        preprocess
        auth_log
        GoPerl
        EAP
}

authenticate {
        EAP
}


accounting {
        detail
}
}

This is a snip of the perl script the authorize part.
It default return "OK" for testing.
I have added RAD_REPLY values for testing too.

sub authorize {
#       # For debugging purposes only
#       &log_request_attributes;
#
#       # Here's where your authorization code comes
#       # You can call another function from here:
#       &test_call;
        $RAD_REPLY{"Tunnel-Private-Group-id"} = "2";
        $RAD_REPLY{"Tunnel-Type"} = "VLAN";
        $RAD_REPLY{"Tunnel-Medium-Type"} = "IEEE-802";
        return RLM_MODULE_OK;
}

In that constellation I've got the error " ERROR: (5) GoPerl: Failed to create pair &request:EAP-Message = $RAD_REQUEST{'EAP-Message'} ->" and "There was no response configured: rejecting request ... Using Post-Auth-Type Reject"
I have found this https://github.com/FreeRADIUS/freeradius-server/issues/1697, I have changed as "dhpark21" described but then I have many errors at perl modul RAD_REQUEST and RAD_REPLY -> undef then perl modul will not be executed but working with EAP-TLS.
Hope someone could help.

That is a snip of the debug:
---------------------------------------
Fri Nov  4 09:09:42 2016 : Debug: (5) GoPerl:   $RAD_REQUEST{'User-Name'} = &request:User-Name -> 'host/~~~~~~~~~'
Fri Nov  4 09:09:42 2016 : Debug: (5) GoPerl:   $RAD_REQUEST{'NAS-IP-Address'} = &request:NAS-IP-Address -> ~~~~~~~~~
Fri Nov  4 09:09:42 2016 : Debug: (5) GoPerl:   $RAD_REQUEST{'NAS-Port'} = &request:NAS-Port -> '60000'
Fri Nov  4 09:09:42 2016 : Debug: (5) GoPerl:   $RAD_REQUEST{'Service-Type'} = &request:Service-Type -> 'Framed-User'
Fri Nov  4 09:09:42 2016 : Debug: (5) GoPerl:   $RAD_REQUEST{'Framed-MTU'} = &request:Framed-MTU -> '9216'
Fri Nov  4 09:09:42 2016 : Debug: (5) GoPerl:   $RAD_REQUEST{'State'} = &request:State -> '0x217dacef257ba1999dff0cf1ce39de5f'
Fri Nov  4 09:09:42 2016 : Debug: (5) GoPerl:   $RAD_REQUEST{'Called-Station-Id'} = &request:Called-Station-Id -> ~~~~~~~~~
Fri Nov  4 09:09:42 2016 : Debug: (5) GoPerl:   $RAD_REQUEST{'Calling-Station-Id'} = &request:Calling-Station-Id -> ~~~~~~~~~
Fri Nov  4 09:09:42 2016 : Debug: (5) GoPerl:   $RAD_REQUEST{'Proxy-State'} = &request:Proxy-State -> '0x8b16a47700000efc'
Fri Nov  4 09:09:42 2016 : Debug: (5) GoPerl:   $RAD_REQUEST{'NAS-Port-Type'} = &request:NAS-Port-Type -> 'Ethernet'
Fri Nov  4 09:09:42 2016 : Debug: (5) GoPerl:   $RAD_REQUEST{'Event-Timestamp'} = &request:Event-Timestamp -> 'Nov  4 2016 09:09:42 CET'
Fri Nov  4 09:09:42 2016 : Debug: (5) GoPerl:   $RAD_REQUEST{'EAP-Message'} = &request:EAP-Message -> '0x020605d40dc00000073016030106f00b0005a000059d00059a30820596308204ffa0030201020213160000d0096957d9bd45cc808400060000d009300d06092a864886f70d01010b0500308198311e301c06092a864886f70d010901160f6564764065766f736f66742e636f6d310b30090603550406130244453110300e060355040813074261766172696131123010060355040713094e7572656d6265726731153013060355040a130c45766f736f667420476d624831153013060355040b130c45766f736f667420476d6248311530130603550403130c45766f736f667420476d6248301e170d3136303831353134303134305a170d3138303831353134303134305a301f311d301b0603550403131445564f30323130302e65766f736f66742e636f6d30820122300d06092a864886f70d01010105000382010f003082010a0282010100afc52515cdb53d2173c492869d2fdf296c2afde310c301240746d2140f93482d2a08c4cda93eed450533635c932804c1776fd15f69ac8942a15a529b4689adf2a0f9db8613f250e91601a964e7611e0815e10d225df9e22ca0119c58f9dede6cc8775ef0f5add475325cd3ad87a93065a1948f9a53d01f10e66ec141fc83a32b571b5ad910a98a016044c39c8832e40fcf6d88cbb5b11a4173877464016d1fc786c28c5d2a04a215e8eecaa6b62241d88bf6d0ca789def'
Fri Nov  4 09:09:42 2016 : Debug: (5) GoPerl:   $RAD_REQUEST{'Message-Authenticator'} = &request:Message-Authenticator -> '0x2bebafeecaeb11596c759f7208148ddf'
Fri Nov  4 09:09:42 2016 : Debug: (5) GoPerl:   $RAD_REQUEST{'NAS-Port-Id'} = &request:NAS-Port-Id -> ~~~~~~~~~
Fri Nov  4 09:09:42 2016 : Debug: (5) GoPerl:   $RAD_REQUEST{'Cisco-AVPair'}[0] = &request:Cisco-AVPair -> 'service-type=Framed'
Fri Nov  4 09:09:42 2016 : Debug: (5) GoPerl:   $RAD_REQUEST{'Cisco-AVPair'}[1] = &request:Cisco-AVPair -> 'audit-session-id=0A016E020002255B4748D1E8'
Fri Nov  4 09:09:42 2016 : Debug: (5) GoPerl:   $RAD_REQUEST{'Cisco-AVPair'}[2] = &request:Cisco-AVPair -> 'method=dot1x'
SOFT ASSERT FAILED src/modules/rlm_perl/rlm_perl.c[703]: *vps
Fri Nov  4 09:09:42 2016 : Debug: (5) GoPerl: &request:Message-Authenticator = $RAD_REQUEST{'Message-Authenticator'} -> '0x2bebafeecaeb11596c759f7208148ddf'
Fri Nov  4 09:09:42 2016 : Debug: (5) GoPerl: &request:NAS-Port-Type = $RAD_REQUEST{'NAS-Port-Type'} -> 'Ethernet'
Fri Nov  4 09:09:42 2016 : ERROR: (5) GoPerl: Failed to create pair &request:EAP-Message = $RAD_REQUEST{'EAP-Message'} -> '0x020605d40dc00000073016030106f00b0005a000059d00059a30820596308204ffa0030201020213160000d0096957d9bd45cc808400060000d009300d06092a864886f70d01010b0500308198311e301c06092a864886f70d010901160f6564764065766f736f66742e636f6d310b30090603550406130244453110300e060355040813074261766172696131123010060355040713094e7572656d6265726731153013060355040a130c45766f736f667420476d624831153013060355040b130c45766f736f667420476d6248311530130603550403130c45766f736f667420476d6248301e170d3136303831353134303134305a170d3138303831353134303134305a301f311d301b0603550403131445564f30323130302e65766f736f66742e636f6d30820122300d06092a864886f70d01010105000382010f003082010a0282010100afc52515cdb53d2173c492869d2fdf296c2afde310c301240746d2140f93482d2a08c4cda93eed450533635c932804c1776fd15f69ac8942a15a529b4689adf2a0f9db8613f250e91601a964e7611e0815e10d225df9e22ca0119c58f9dede6cc8775ef0f5add475325cd3ad87a93065a1948f9a53d01f10e66ec141fc83a32b571b5ad910a98a016044c39c8832e40fcf6d88cbb5b11a4173877464016d1fc786c28c5d2a04a215e8eecaa6b62241d88bf6d0ca789def'
Fri Nov  4 09:09:42 2016 : Debug: (5) GoPerl: &request:Calling-Station-Id = $RAD_REQUEST{'Calling-Station-Id'} -> ~~~~~~~~~
Fri Nov  4 09:09:42 2016 : Debug: (5) GoPerl: &request:Proxy-State = $RAD_REQUEST{'Proxy-State'} -> '0x8b16a47700000efc'
Fri Nov  4 09:09:42 2016 : Debug: (5) GoPerl: &request:Event-Timestamp = $RAD_REQUEST{'Event-Timestamp'} -> 'Nov  4 2016 09:09:42 CET'
Fri Nov  4 09:09:42 2016 : Debug: (5) GoPerl: &request:Framed-MTU = $RAD_REQUEST{'Framed-MTU'} -> '9216'
Fri Nov  4 09:09:42 2016 : Debug: (5) GoPerl: &request:NAS-IP-Address = $RAD_REQUEST{'NAS-IP-Address'} -> ~~~~~~~~~
Fri Nov  4 09:09:42 2016 : Debug: (5) GoPerl: &request:Cisco-AVPair += $RAD_REQUEST{'Cisco-AVPair'} -> 'service-type=Framed'
Fri Nov  4 09:09:42 2016 : Debug: (5) GoPerl: &request:Cisco-AVPair += $RAD_REQUEST{'Cisco-AVPair'} -> 'audit-session-id=0A016E020002255B4748D1E8'
Fri Nov  4 09:09:42 2016 : Debug: (5) GoPerl: &request:Cisco-AVPair += $RAD_REQUEST{'Cisco-AVPair'} -> 'method=dot1x'
Fri Nov  4 09:09:42 2016 : Debug: (5) GoPerl: &request:User-Name = $RAD_REQUEST{'User-Name'} -> ~~~~~~~~~
Fri Nov  4 09:09:42 2016 : Debug: (5) GoPerl: &request:State = $RAD_REQUEST{'State'} -> '0x217dacef257ba1999dff0cf1ce39de5f'
Fri Nov  4 09:09:42 2016 : Debug: (5) GoPerl: &request:Called-Station-Id = $RAD_REQUEST{'Called-Station-Id'} -> ~~~~~~~~~
Fri Nov  4 09:09:42 2016 : Debug: (5) GoPerl: &request:NAS-Port-Id = $RAD_REQUEST{'NAS-Port-Id'} -> ~~~~~~~~~
Fri Nov  4 09:09:42 2016 : Debug: (5) GoPerl: &request:NAS-Port = $RAD_REQUEST{'NAS-Port'} -> '60000'
Fri Nov  4 09:09:42 2016 : Debug: (5) GoPerl: &request:Service-Type = $RAD_REQUEST{'Service-Type'} -> 'Framed-User'
SOFT ASSERT FAILED src/modules/rlm_perl/rlm_perl.c[703]: *vps
Fri Nov  4 09:09:42 2016 : Debug: (5) GoPerl: &reply:Tunnel-Type = $RAD_REPLY{'Tunnel-Type'} -> 'VLAN'
Fri Nov  4 09:09:42 2016 : Debug: (5) GoPerl: &reply:Tunnel-Private-Group-id = $RAD_REPLY{'Tunnel-Private-Group-id'} -> '2'
Fri Nov  4 09:09:42 2016 : Debug: (5) GoPerl: &reply:Tunnel-Medium-Type = $RAD_REPLY{'Tunnel-Medium-Type'} -> 'IEEE-802'
Fri Nov  4 09:09:42 2016 : Debug: (5)     modsingle[authorize]: returned from GoPerl (rlm_perl)
Fri Nov  4 09:09:42 2016 : Debug: (5)     [GoPerl] = ok
Fri Nov  4 09:09:42 2016 : Debug: (5)     modsingle[authorize]: calling EAP (rlm_eap)
Fri Nov  4 09:09:42 2016 : Debug: (5) EAP: Got EAP_START message
Fri Nov  4 09:09:42 2016 : Debug: (5)     modsingle[authorize]: returned from EAP (rlm_eap)
Fri Nov  4 09:09:42 2016 : Debug: (5)     [EAP] = handled
Fri Nov  4 09:09:42 2016 : Debug: (5)   } # authorize = handled
Fri Nov  4 09:09:42 2016 : Debug: (5) There was no response configured: rejecting request
Fri Nov  4 09:09:42 2016 : Debug: (5) Using Post-Auth-Type Reject
Fri Nov  4 09:09:42 2016 : Debug: (5) Post-Auth-Type sub-section not found.  Ignoring.
Fri Nov  4 09:09:42 2016 : Debug: (5) Delaying response for 1.000000 seconds
Fri Nov  4 09:09:42 2016 : Debug: Waking up in 0.3 seconds.
Fri Nov  4 09:09:43 2016 : Debug: Waking up in 0.6 seconds.
Fri Nov  4 09:09:43 2016 : Debug: (5) Sending delayed response
Fri Nov  4 09:09:43 2016 : Debug: (5) Sent Access-Reject Id 113 from ~~~~~~~~~to ~~~~~~~~~length 52
Fri Nov  4 09:09:43 2016 : Debug: (5)   Tunnel-Type = VLAN
Fri Nov  4 09:09:43 2016 : Debug: (5)   Tunnel-Private-Group-Id = "2"
Fri Nov  4 09:09:43 2016 : Debug: (5)   Tunnel-Medium-Type = IEEE-802
Fri Nov  4 09:09:43 2016 : Debug: (5)   EAP-Message = 0x0100000501
Fri Nov  4 09:09:43 2016 : Debug: (5)   Proxy-State = 0x8b16a47700000efc
Fri Nov  4 09:09:43 2016 : Debug: Waking up in 3.9 seconds.
Fri Nov  4 09:09:47 2016 : Debug: (0) Cleaning up request packet ID 108 with timestamp +21
Fri Nov  4 09:09:47 2016 : Debug: (1) Cleaning up request packet ID 109 with timestamp +21
Fri Nov  4 09:09:47 2016 : Debug: (2) Cleaning up request packet ID 110 with timestamp +21
Fri Nov  4 09:09:47 2016 : Debug: (3) Cleaning up request packet ID 111 with timestamp +21
Fri Nov  4 09:09:47 2016 : Debug: (4) Cleaning up request packet ID 112 with timestamp +21
Fri Nov  4 09:09:47 2016 : Debug: (5) Cleaning up request packet ID 113 with timestamp +21
Fri Nov  4 09:09:47 2016 : Info: Ready to process requests
Fri Nov  4 09:09:47 2016 : Debug: (6) Received Access-Request Id 114 from ~~~~~~~~~to ~~~~~~~~~length 300
Fri Nov  4 09:09:47 2016 : Debug: (6)   User-Name = "host/EVO02100.evosoft.com"
Fri Nov  4 09:09:47 2016 : Debug: (6)   Service-Type = Framed-User
Fri Nov  4 09:09:47 2016 : Debug: (6)   Framed-MTU = 9216
Fri Nov  4 09:09:47 2016 : Debug: (6)   Called-Station-Id = "~~~~~~~~~"
Fri Nov  4 09:09:47 2016 : Debug: (6)   Calling-Station-Id = "~~~~~~~~~"
Fri Nov  4 09:09:47 2016 : Debug: (6)   EAP-Message = 0x0201001e01686f73742f45564f30323130302e65766f736f66742e636f6d
Fri Nov  4 09:09:47 2016 : Debug: (6)   Message-Authenticator = 0xe22b7d268bf88355559f7445f864ad63
Fri Nov  4 09:09:47 2016 : Debug: (6)   NAS-IP-Address = ~~~~~~~~~
Fri Nov  4 09:09:47 2016 : Debug: (6)   NAS-Port = 60000
Fri Nov  4 09:09:47 2016 : Debug: (6)   NAS-Port-Id = "~~~~~~~~~"
Fri Nov  4 09:09:47 2016 : Debug: (6)   NAS-Port-Type = Ethernet
Fri Nov  4 09:09:47 2016 : Debug: (6)   Cisco-AVPair = "service-type=Framed"
Fri Nov  4 09:09:47 2016 : Debug: (6)   Cisco-AVPair = "audit-session-id=0A016E020002255B4748D1E8"
Fri Nov  4 09:09:47 2016 : Debug: (6)   Cisco-AVPair = "method=dot1x"
Fri Nov  4 09:09:47 2016 : Debug: (6)   Proxy-State = 0x8b16a47700000efd
Fri Nov  4 09:09:47 2016 : Debug: (6) session-state: No State attribute

Best Regards,
Paul



More information about the Freeradius-Users mailing list