search

FreeRADIUS / freeradius-server

FreeRADIUS - A multi-protocol policy server.
http://freeradius.org
GNU General Public License v2.0
2.11k stars 1.08k forks source link

packet proxied without its attributes #637

Closed olivierbeytrison closed 10 years ago

olivierbeytrison commented 10 years ago

I'm currently testing v3.0.x HEAD on my test platform.

The radius server sitting between the NAS and the Homeserver is acting weird.

When he received the 7th packet from the home server (Access-Challenge, wich contains the mschapv2 exchange in the inner tunnel), he sends an empty Access-Challenge to the NAS, without executing the post_proxy section :

Debug: (7) proxy: Trying to allocate ID (0/2)
Debug: (7) proxy: request is now in proxy hash
Debug: (7)  proxy: allocating destination 0.0.240.25 port 1812 - Id 123
Debug: (7) Proxying request to home server 0.0.240.25 port 1812
Sending Access-Request Id 123 from 0.0.0.0:53973 to 0.0.240.25:1812
        User-Name = 'olivier.beytriso@test.hes-so.ch'
        Chargeable-User-Identity = ''
        Location-Capable = Civix-Location
        Called-Station-Id = 'ap-eia-si-test:eduroam-test'
        NAS-Port = 13
        Cisco-AVPair = 'audit-session-id=a0629d02001a3c0953747ecd'
        NAS-IP-Address = 0.0.157.2
        NAS-Identifier = 'wlc.per80'
        Airespace-Wlan-Id = 8
        Service-Type = Framed-User
        Framed-MTU = 1300
        NAS-Port-Type = Wireless-802.11
        Tunnel-Type:0 = VLAN
        Tunnel-Medium-Type:0 = IEEE-802
        Tunnel-Private-Group-Id:0 = '153'
        EAP-Message = 0x0209007b190017030100702407c5bfb5e41f65025dcfee062667cb2969feed787a9a4b442a31faba789e58094c9ee2eee8f8dae9423eea2c4b6f11d6c59191c49baa893d4b423e4280e3487e1be26c76fd6c392c6175ebc0bde0a456bc79fe62dba071387d8c498421cf76bc73858e7f09fe7591d621e2af40dd1c
        State = 0xbefbeb14b8f2f2727ed4fae300ac8f83
        Message-Authenticator = 0xb8128082e7b3d4a884c337bbcd53f30b
        Calling-Station-Id := '00-24-d7-9b-37-a4'
        HESSO-Location := 'RORG-HEFR'
        Proxy-State = 0x3634
Debug: Waking up in 0.4 seconds.
Received Access-Challenge Id 123 from 0.0.240.25:1812 to 0.0.240.15:53973 length 153
        EAP-Message = 0x010a005b19001703010050765a3defaee92d9f9923aa191d9dfa92decb7cc01f4c74cee718a4ce076e4644ba24be5446e94423d35325e0b5e12fd8ec34bc34188536bcbf0d33a2ba0102961ac0b0b153231dd3ab85648e18ab4dcd
        Message-Authenticator = 0xbccbc9ea81735b594ea44be985588538
        State = 0xbefbeb14b9f1f2727ed4fae300ac8f83
        Proxy-State = 0x3634
Debug: (7) proxy: request is no longer in proxy hash
Sending Access-Challenge Id 64 from 0.0.226.15:1812 to 0.0.157.2:32770
Debug: (7) Finished request

complete debug log available on request.

olivierbeytrison commented 10 years ago

In fact it's worth than what I thought ...

I have a case here where it's the Access-Accept message which is sent back to the NAS empty.

The packet arrives as it should on the radius :

Received Access-Accept Id 43 from 0.0.240.25:1812 to 0.0.240.15:58359 length 507
        Reply-Message = '0'
        User-Name = 'olivier.beytriXXXXes-so.ch'
        Chargeable-User-Identity = '187ce34e7b30f8131bfcf0XXXcca2ad29'
        HESSO-Mail = 'XXXXX'
        HESSO-FullName = 'Olivier Beytrison'
        Class = XX
        Class = XX
        Class = XXX
        HESSO-Role-Raw = '31935762-440774439#RORG-HEFR-EIFR-INTR-INFO#EMP#COL'
        HESSO-Role-Raw = '31935762-440774439#RORG-HEFR-EIFR-INTR-INFO#STD#'
        MS-MPPE-Recv-Key = xx
        MS-MPPE-Send-Key = xx
        EAP-Message = 0x030b0004 
        Message-Authenticator = 0xd31919190f3f44606d2aeb0e772856be
        Proxy-State = 0x313835

But it's as if there's no VP attached to the packet structure in the server. The first check in the post_auth section :

Debug: (9) Found Auth-Type = Accept
Debug: (9) Auth-Type = Accept, accepting the user
Debug: (9) # Executing section post-auth from file /srv/freeradius/etc/raddb/sites-enabled/eduroam
Debug: (9)   post-auth {
Debug: (9)   remove_reply_message_if_eap remove_reply_message_if_eap {
Debug: (9)     if (reply:EAP-Message && reply:Reply-Message)
Debug: (9)     if (reply:EAP-Message && reply:Reply-Message)  -> FALSE
Debug: (9)    else else {
Debug: (9)   modsingle[post-auth]: calling noop (rlm_always) for request 9
Debug: (9)   modsingle[post-auth]: returned from noop (rlm_always) for request 9
Debug: (9)     [noop] = noop
Debug: (9)    } # else else = noop
Debug: (9)   } # remove_reply_message_if_eap remove_reply_message_if_eap = noop

but in fact there's an EAP-Message and a Reply-Message ...

same goes for the policy : 

Debug: (9)    wireless-policy wireless-policy {
Debug: (9)     foreach reply:HESSO-Role-Raw {
Debug: (9)     } # foreach reply:HESSO-Role-Raw = noop
Debug: (9)    } # wireless-policy wireless-policy = noop

And finally the empty packet leaves the radius ....

Sending Access-Accept Id 185 from 0.0.226.15:1812 to 0.0.157.2:32770
alandekok commented 10 years ago

Please try v3.0x branch. it should be fixed.

If so, we'll release 3.0.4

olivierbeytrison commented 10 years ago

Running it now on the test network, v3.0.x HEAD, but the problem remain the same.

If you want me to watch for specific stuff just ask, both the proxy and home server run within gdb at the moment.

alandekok commented 10 years ago

If there's a simple test case, that would help.

olivierbeytrison commented 10 years ago

I'll try ton find a simple test case tomorrow. I don't know if the same problem happen when proxying to a virtual server (which would make it easier to test)

nchaigne commented 10 years ago

I have the same issue.

My setup is : (1) a client (radeapclient), (2) a FreeRADIUS server which acts as a proxy for EAP-SIM authentication requests (among other things), and (3) a home server. (which is currently simulated by another FreeRADIUS).

Whenever the home server takes some time to answer (>= 1 second), the FreeRADIUS proxy will fail with:

rad_recv: Access-Accept packet from host 10.67.141.74 port 31812, id=132, length=286 MS-MPPE-Recv-Key = 0x1de13f3142cf87bef12f3fcdec9bb51f38790bacd7e374175d0304ac40629a53 MS-MPPE-Send-Key = 0x3e7b5ac46654c54fa1f5321b6e879aab83faedb4a834034784eac70c93303e6f EAP-Message = 0x03740004 Message-Authenticator = 0x0752fec01edc93679387666887bdb635 User-Name = '1208010000000002@wlan.mnc001.mcc208.3gppnetwork.org' Proxy-State = 0x313932 3GPP-IMSI = '208010000000002' Calling-Station-Id = '33600000002' Chargeable-User-Identity = '\001\021208010000000002\000\r33600000002' Wed May 21 14:39:15 2014 : Debug: (2) proxy: request is no longer in proxy hash Wed May 21 14:39:15 2014 : Debug: (2) Found Auth-Type = Accept Wed May 21 14:39:15 2014 : Debug: (2) Auth-Type = Accept, accepting the user (...)

The client receives an empty reply. It happens for Challenges and Accepts (tested with no delay for the Challenges, but a delay for the Accept).

There is no problem with the home server (3): when I try to send directly from (1) to (3) everything works fine, even with delays.

It fails when

I'm looking into it. Any advice appreciated, this is critical :/

I'll try to replace (2) with a minimal proxy setup, maybe it'll help.

nchaigne commented 10 years ago

The use case for failed Challenge is simpler, here is the debug output:

Wed May 21 15:11:48 2014 : Debug: (17) Empty pre-proxy section. Using default return values. Wed May 21 15:11:48 2014 : Debug: (17) proxy: Trying to allocate ID (0/2) Wed May 21 15:11:48 2014 : Debug: (17) proxy: request is now in proxy hash Wed May 21 15:11:48 2014 : Debug: (17) proxy: allocating destination 10.67.141.74 port 31812 - Id 38 Wed May 21 15:11:48 2014 : Debug: (17) Proxying request to home server 10.67.141.74 port 31812 Sending Access-Request of id 38 from 0.0.0.0 port 50174 to 10.67.141.74 port 31812 User-Name = '1208010000000002@wlan.mnc001.mcc208.3gppnetwork.org' Message-Authenticator = 0x8fa6e3c95b1be27e7f2823fc186f17ff NAS-IP-Address = 10.20.0.0 NAS-Identifier = 'LiveBox1' Calling-Station-Id = '4E:F0:F5:A7:9B:A2' EAP-Message = 0x02130038013132303830313030303030303030303240776c616e2e6d6e633030312e6d63633230382e336770706e6574776f726b2e6f7267 Proxy-State = 0x313931 Wed May 21 15:11:48 2014 : Debug: Waking up in 0.3 seconds. Wed May 21 15:11:49 2014 : Debug: Waking up in 0.4 seconds. Wed May 21 15:11:49 2014 : Debug: (17) Expecting proxy response no later than 10 seconds from now Wed May 21 15:11:49 2014 : Debug: Waking up in 9.1 seconds. rad_recv: Access-Challenge packet from host 10.67.141.74 port 31812, id=38, length=83 EAP-Message = 0x01150014120a00000f020002000100001101016b Message-Authenticator = 0xebf865b1d4d868c34c0f097672d5862f State = 0xcf0938c5cf1c2a109e486a446d69e80c Proxy-State = 0x313931 Wed May 21 15:11:49 2014 : Debug: (17) proxy: request is no longer in proxy hash Sending Access-Challenge of id 191 from 10.67.106.10 port 1812 to 10.67.106.9 port 64374 Wed May 21 15:11:49 2014 : Debug: (17) Finished request 17. Wed May 21 15:11:49 2014 : Debug: Waking up in 0.3 seconds. Wed May 21 15:11:50 2014 : Debug: (17) Cleaning up request packet ID 191 with timestamp +1956

arr2036 commented 10 years ago

We really need test configs. If you can work up from the default, with users stored in a file instance, zip it and send it over, it'd be a great help.

nchaigne commented 10 years ago

I'm working on something, I'll keep you updated

alandekok commented 10 years ago

Nicolas C wrote:

Whenever the home server takes some time to answer (>= 1 second), the FreeRADIUS proxy will fail with:

The default configuration doesn't have a 1 second timeout. So you've changed that, at least.

rad_recv: Access-Accept packet from host 10.67.141.74 port 31812, id=132, length=286 MS-MPPE-Recv-Key = 0x1de13f3142cf87bef12f3fcdec9bb51f38790bacd7e374175d0304ac40629a53 MS-MPPE-Send-Key = 0x3e7b5ac46654c54fa1f5321b6e879aab83faedb4a834034784eac70c93303e6f EAP-Message = 0x03740004 Message-Authenticator = 0x0752fec01edc93679387666887bdb635 User-Name = '1208010000000002@wlan.mnc001.mcc208.3gppnetwork.org mailto:1208010000000002@wlan.mnc001.mcc208.3gppnetwork.org' Proxy-State = 0x313932 3GPP-IMSI = '208010000000002' Calling-Station-Id = '33600000002' Chargeable-User-Identity = '\001\021208010000000002\000\r33600000002' Wed May 21 14:39:15 2014 : Debug: (2) proxy: request is no longer in proxy hash Wed May 21 14:39:15 2014 : Debug: (2) Found Auth-Type = Accept Wed May 21 14:39:15 2014 : Debug: (2) Auth-Type = Accept, accepting the user (...)

What does the rest of the debug output say? That helps to track the state machine.

If you're willing to edit the code, go to src/main/process.c, and add this at the top:

define DEBUG_STATE_MACHINE (1)

Re-build && re-install. You'll get a LOT more information in debug mode. That will help track down exactly what's going on.

nchaigne commented 10 years ago

OK, I have rebuilt with DEBUG_STATE_MACHINE.

I also set up a very simple proxy configuration, with a virtual server hosted by the same FreeRADIUS server as the home server (basically, all the proxy virtual server do is "if EAP then proxy to home server").

Here is the full debug output:

Received Access-Request Id 219 from 10.67.106.9:53400 to 10.67.141.74:1812 length 184 Code: 1 Id: 219 Length: 184 Vector: 7f06bba24190e2ca7e2bd64c97146f05 Data: 01 35 31 32 30 38 30 31 30 30 30 30 30 30 30 30 30 32 40 77 6c 61 6e 2e 6d 6e 63 30 30 31 2e 6d 63 63 32 30 38 2e 33 67 70 70 6e 65 74 77 6f 72 6b 2e 6f 72 67 50 12 34 35 a1 28 64 58 28 4f 7d 58 dc 22 2f 2a 12 1a 04 06 0a 14 00 00 20 0a 4c 69 76 65 42 6f 78 31 1f 13 34 45 3a 46 30 3a 46 35 3a 41 37 3a 39 42 3a 41 32 4f 3a 02 ac 00 38 01 31 32 30 38 30 31 30 30 30 30 30 30 30 30 30 32 40 77 6c 61 6e 2e 6d 6e 63 30 30 31 2e 6d 63 63 32 30 38 2e 33 67 70 70 6e 65 74 77 6f 72 6b 2e 6f 72 67 (0) \ STATE request_setup C-? -> C-running ** (0) \ STATE request_queue_or_run action timer live M-active C-running ** (0) \ STATE request_running action run live M-active C-running ** (0) \ STATE request_pre_handler action run live M-active C-running ** User-Name = '1208010000000002@wlan.mnc001.mcc208.3gppnetwork.org' Message-Authenticator = 0x3435a1286458284f7d58dc222f2a121a NAS-IP-Address = 10.20.0.0 NAS-Identifier = 'LiveBox1' Calling-Station-Id = '4E:F0:F5:A7:9B:A2' EAP-Message = 0x02ac0038013132303830313030303030303030303240776c616e2e6d6e633030312e6d63633230382e336770706e6574776f726b2e6f7267 Wed May 21 16:55:52 2014 : Debug: (0) # Executing section authorize from file /opt/application/sim3gppb/current/etc/raddb/sites-enabled/server-proxy Wed May 21 16:55:52 2014 : Debug: (0) authorize { Wed May 21 16:55:52 2014 : Debug: (0) if (EAP-Message) Wed May 21 16:55:52 2014 : Debug: (0) if (EAP-Message) -> TRUE Wed May 21 16:55:52 2014 : Debug: (0) if (EAP-Message) { Wed May 21 16:55:52 2014 : Debug: (0) update control { Wed May 21 16:55:52 2014 : Debug: (0) &Proxy-To-Realm := '3gpp.orange.fr' Wed May 21 16:55:52 2014 : Debug: (0) } # update control = noop Wed May 21 16:55:52 2014 : Debug: (0) } # if (EAP-Message) = noop Wed May 21 16:55:52 2014 : Debug: (0) } # authorize = noop Wed May 21 16:55:52 2014 : Debug: (0) Empty pre-proxy section. Using default return values. (0) \ Will Proxy ** Wed May 21 16:55:52 2014 : Debug: (0) proxy: Trying to allocate ID (0/2) Wed May 21 16:55:52 2014 : Debug: (0) proxy: request is now in proxy hash Wed May 21 16:55:52 2014 : Debug: (0) proxy: allocating destination 10.67.141.74 port 31812 - Id 115 Wed May 21 16:55:52 2014 : Debug: (0) Proxying request to home server 10.67.141.74 port 31812 Sending Access-Request Id 115 from 0.0.0.0:52493 to 10.67.141.74:31812 User-Name = '1208010000000002@wlan.mnc001.mcc208.3gppnetwork.org' 01 35 31 32 30 38 30 31 30 30 30 30 30 30 30 30 30 32 40 77 6c 61 6e 2e 6d 6e 63 30 30 31 2e 6d 63 63 32 30 38 2e 33 67 70 70 6e 65 74 77 6f 72 6b 2e 6f 72 67 Message-Authenticator = 0x3435a1286458284f7d58dc222f2a121a 50 12 ... NAS-IP-Address = 10.20.0.0 04 06 0a 14 00 00 NAS-Identifier = 'LiveBox1' 20 0a 4c 69 76 65 42 6f 78 31 Calling-Station-Id = '4E:F0:F5:A7:9B:A2' 1f 13 34 45 3a 46 30 3a 46 35 3a 41 37 3a 39 42 3a 41 32 EAP-Message = 0x02ac0038013132303830313030303030303030303240776c616e2e6d6e633030312e6d63633230382e336770706e6574776f726b2e6f7267 4f 3a 02 ac 00 38 01 31 32 30 38 30 31 30 30 30 30 30 30 30 30 30 32 40 77 6c 61 6e 2e 6d 6e 63 30 30 31 2e 6d 63 63 32 30 38 2e 33 67 70 70 6e 65 74 77 6f 72 6b 2e 6f 72 67 Proxy-State = 0x323139 21 05 32 31 39 Code: 1 Id: 115 Length: 189 Vector: 6533e356649c5a70e40be632993ecb20 Data: 01 35 31 32 30 38 30 31 30 30 30 30 30 30 30 30 30 32 40 77 6c 61 6e 2e 6d 6e 63 30 30 31 2e 6d 63 63 32 30 38 2e 33 67 70 70 6e 65 74 77 6f 72 6b 2e 6f 72 67 50 12 8f ee 68 63 c3 d2 18 bd f3 c6 ad c2 20 38 d0 1b 04 06 0a 14 00 00 20 0a 4c 69 76 65 42 6f 78 31 1f 13 34 45 3a 46 30 3a 46 35 3a 41 37 3a 39 42 3a 41 32 4f 3a 02 ac 00 38 01 31 32 30 38 30 31 30 30 30 30 30 30 30 30 30 32 40 77 6c 61 6e 2e 6d 6e 63 30 30 31 2e 6d 63 63 32 30 38 2e 33 67 70 70 6e 65 74 77 6f 72 6b 2e 6f 72 67 21 05 32 31 39 Wed May 21 16:55:52 2014 : Debug: Waking up in 0.3 seconds. Received Access-Request Id 115 from 10.67.141.74:52493 to 10.67.141.74:31812 length 189 Code: 1 Id: 115 Length: 189 Vector: 6533e356649c5a70e40be632993ecb20 Data: 01 35 31 32 30 38 30 31 30 30 30 30 30 30 30 30 30 32 40 77 6c 61 6e 2e 6d 6e 63 30 30 31 2e 6d 63 63 32 30 38 2e 33 67 70 70 6e 65 74 77 6f 72 6b 2e 6f 72 67 50 12 8f ee 68 63 c3 d2 18 bd f3 c6 ad c2 20 38 d0 1b 04 06 0a 14 00 00 20 0a 4c 69 76 65 42 6f 78 31 1f 13 34 45 3a 46 30 3a 46 35 3a 41 37 3a 39 42 3a 41 32 4f 3a 02 ac 00 38 01 31 32 30 38 30 31 30 30 30 30 30 30 30 30 30 32 40 77 6c 61 6e 2e 6d 6e 63 30 30 31 2e 6d 63 63 32 30 38 2e 33 67 70 70 6e 65 74 77 6f 72 6b 2e 6f 72 67 21 05 32 31 39 (1) \ STATE request_setup C-? -> C-running ** (1) \ STATE request_queue_or_run action timer live M-active C-running ** (1) \ STATE request_running action run live M-active C-running ** (1) \ STATE request_pre_handler action run live M-active C-running ** User-Name = '1208010000000002@wlan.mnc001.mcc208.3gppnetwork.org' Message-Authenticator = 0x8fee6863c3d218bdf3c6adc22038d01b NAS-IP-Address = 10.20.0.0 NAS-Identifier = 'LiveBox1' Calling-Station-Id = '4E:F0:F5:A7:9B:A2' EAP-Message = 0x02ac0038013132303830313030303030303030303240776c616e2e6d6e633030312e6d63633230382e336770706e6574776f726b2e6f7267 Proxy-State = 0x323139 Wed May 21 16:55:52 2014 : Debug: (1) # Executing section authorize from file /opt/application/sim3gppb/current/etc/raddb/sites-enabled/server-sim3gpp-b Wed May 21 16:55:52 2014 : Debug: (1) authorize { Wed May 21 16:55:52 2014 : Debug: (1) modsingle[authorize]: calling files (rlm_files) for request 1 Wed May 21 16:55:52 2014 : Debug: (1) files : users: Matched entry DEFAULT at line 1 Wed May 21 16:55:52 2014 : Debug: (1) files : ::: FROM 0 TO 0 MAX 0 Wed May 21 16:55:52 2014 : Debug: (1) files : ::: TO in 0 out 0 Wed May 21 16:55:52 2014 : Debug: (1) modsingle[authorize]: returned from files (rlm_files) for request 1 Wed May 21 16:55:52 2014 : Debug: (1) [files] = ok Wed May 21 16:55:52 2014 : Debug: (1) modsingle[authorize]: calling eap (rlm_eap) for request 1 Wed May 21 16:55:52 2014 : Debug: (1) eap : EAP packet type response id 172 length 56 Wed May 21 16:55:52 2014 : Debug: (1) eap : EAP-Identity reply, returning 'ok' so we can short-circuit the rest of authorize Wed May 21 16:55:52 2014 : Debug: (1) modsingle[authorize]: returned from eap (rlm_eap) for request 1 Wed May 21 16:55:52 2014 : Debug: (1) [eap] = ok Wed May 21 16:55:52 2014 : Debug: (1) modsingle[authorize]: calling sleep (rlm_exec) for request 1 Wed May 21 16:55:52 2014 : Debug: (1) sleep : Executing: /bin/sleep 1 Wed May 21 16:55:52 2014 : Debug: (1) sleep : executing cmd /bin/sleep 1 Wed May 21 16:55:52 2014 : Debug: (1) sleep : [0] /bin/sleep Wed May 21 16:55:52 2014 : Debug: (1) sleep : [1] 1 Wed May 21 16:55:53 2014 : Debug: (1) sleep : Program returned code (0) and output '' Wed May 21 16:55:53 2014 : Debug: (1) sleep : Program executed successfully Wed May 21 16:55:53 2014 : Debug: (1) modsingle[authorize]: returned from sleep (rlm_exec) for request 1 Wed May 21 16:55:53 2014 : Debug: (1) [sleep] = ok Wed May 21 16:55:53 2014 : Debug: (1) } # authorize = ok Wed May 21 16:55:53 2014 : Debug: (1) Found Auth-Type = EAP Wed May 21 16:55:53 2014 : Debug: (1) # Executing group from file /opt/application/sim3gppb/current/etc/raddb/sites-enabled/server-sim3gpp-b Wed May 21 16:55:53 2014 : Debug: (1) authenticate { Wed May 21 16:55:53 2014 : Debug: (1) modsingle[authenticate]: calling eap (rlm_eap) for request 1 Wed May 21 16:55:53 2014 : Debug: (1) eap : Peer sent Identity (1) Wed May 21 16:55:53 2014 : Debug: (1) eap : Calling eap_sim to process EAP data Wed May 21 16:55:53 2014 : Debug: (1) eap : Underlying EAP-Type set EAP ID to 121 Wed May 21 16:55:53 2014 : Debug: (1) eap : New EAP session, adding 'State' attribute to reply 0x1f379c441f4e8ebb Wed May 21 16:55:53 2014 : Debug: (1) modsingle[authenticate]: returned from eap (rlm_eap) for request 1 Wed May 21 16:55:53 2014 : Debug: (1) [eap] = handled Wed May 21 16:55:53 2014 : Debug: (1) } # authenticate = handled (1) \ Finished ** (1) \ STATE request_finish action run live M-active C-running ** Sending Access-Challenge Id 115 from 10.67.141.74:31812 to 10.67.141.74:52493 EAP-Message = 0x01790014120a00000f0200020001000011010100 4f 16 01 79 00 14 12 0a 00 00 0f 02 00 02 00 01 00 00 11 01 01 00 Message-Authenticator = 0x00000000000000000000000000000000 50 12 ... State = 0x1f379c441f4e8ebb40bcc799fed55976 18 12 1f 37 9c 44 1f 4e 8e bb 40 bc c7 99 fe d5 59 76 Proxy-State = 0x323139 21 05 32 31 39 Code: 11 Id: 115 Length: 83 Vector: 0ff621fb50ac1b34f6738f9a38110242 Data: 4f 16 01 79 00 14 12 0a 00 00 0f 02 00 02 00 01 00 00 11 01 01 00 50 12 47 57 48 e2 62 85 b8 bc fa 3e 06 29 23 4e 99 7a 18 12 1f 37 9c 44 1f 4e 8e bb 40 bc c7 99 fe d5 59 76 21 05 32 31 39 Wed May 21 16:55:53 2014 : Debug: (1) Finished request (0) \ STATE request_timer action timer live M-active C-proxied ** (0) \ STATE request_running action timer live M-active C-proxied ** (0) \ STATE request_process_timer action timer live M-active C-proxied ** (1) \ STATE request_timer action timer live M-active C-done ** (1) \ STATE request_running action timer live M-active C-done ** (1) \ STATE request_process_timer action timer live M-active C-done ** (1) \ STATE request_done action done live M-active C-done ** (1) \ STATE request_done C-done -> C-done ** Wed May 21 16:55:53 2014 : Debug: (1) Cleaning up request packet ID 115 with timestamp +3 Received Access-Challenge Id 115 from 10.67.141.74:31812 to 10.67.141.74:52493 length 83 Code: 11 Id: 115 Length: 83 Vector: 0ff621fb50ac1b34f6738f9a38110242 Data: 4f 16 01 79 00 14 12 0a 00 00 0f 02 00 02 00 01 00 00 11 01 01 00 50 12 47 57 48 e2 62 85 b8 bc fa 3e 06 29 23 4e 99 7a 18 12 1f 37 9c 44 1f 4e 8e bb 40 bc c7 99 fe d5 59 76 21 05 32 31 39 (0) \ STATE proxy_wait_for_reply action proxy-reply live M-active C-proxied ** (0) \ STATE request_queue_or_run action timer live M-active C-proxied ** (0) \ STATE proxy_running action run live M-active C-running ** (0) \ STATE request_running action run live M-active C-running ** (0) \ STATE request_pre_handler action run live M-active C-running ** EAP-Message = 0x01790014120a00000f0200020001000011010100 Message-Authenticator = 0x475748e26285b8bcfa3e0629234e997a State = 0x1f379c441f4e8ebb40bcc799fed55976 Proxy-State = 0x323139 Wed May 21 16:55:53 2014 : Debug: (0) proxy: request is no longer in proxy hash (0) \ Finished ** (0) \ STATE request_finish action run live M-active C-running ** Sending Access-Challenge Id 219 from 10.67.141.74:1812 to 10.67.106.9:53400 Code: 11 Id: 219 Length: 20 Vector: 30d1dd286a9538c037cd092595477282 Wed May 21 16:55:53 2014 : Debug: (0) Finished request Wed May 21 16:55:53 2014 : Debug: Waking up in 0.3 seconds. (0) \ STATE request_timer action timer live M-active C-done ** (0) \ STATE proxy_running action timer live M-active C-done ** (0) \ STATE request_common action timer live M-active C-done ** (0) \ STATE request_process_timer action timer live M-active C-done ** (0) \ STATE request_done action done live M-active C-done ** (0) \ STATE request_done C-done -> C-done ** Wed May 21 16:55:53 2014 : Debug: (0) Cleaning up request packet ID 219 with timestamp +3 Wed May 21 16:55:53 2014 : Info: Ready to process requests.

alandekok commented 10 years ago

it works for me.

cd raddb
ln -s sites-enabled/default sites-available/default
cp sites-enabled/default sites-enabled/home
vi sites-enabled/home
    delete the "acct" listen section
   change "port = 0" to "port = 2812" for the "auth" listen section
vi proxy.conf
  change "port = 1812" to "port = 2812" for the home server
vi sites-enabled/default
  before "eap", put:

    if (EAP-Message) {
    update control {
           Proxy-To-Realm := "example.com"
    }
}
vi mods-config/files/authorize
    at the top, add : bob Cleartext-Password := "bob"

Run the server.

In another window, do:

cd src/tests
eapol_test -c peap-mschapv2.conf -s testing123

it works for me.

nchaigne commented 10 years ago

But did you add a delay in the home server ? the problem only happens if the home server is slow to respond.

Can you try with a exec "sleep 1" at the end of authorize section in the home server ?

nchaigne commented 10 years ago

In the case without delay (working), I have:

(0) ********    Finished        ********
(0) ********    STATE request_finish action proxy-reply live M-active C-running ********

In the case with delay (not working), the trace is different ("run" instead of "proxy-reply"):

(0) ********    Finished        ********
(0) ********    STATE request_finish action run live M-active C-running ********
nchaigne commented 10 years ago

Some more info:

It fails if the delay is > 0.3 seconds. It works if the delay is <= 0.3 seconds.

This 0.3 seconds limit seem to match the initial delay set in process.c (and which we can see in debug with "Waking up in 0.3 seconds.").

olivierbeytrison commented 10 years ago

Tested right now v3.0.x HEAD. problem seems to be fixed. no more packets without attributes !

Thanks Alan and Nicolas !

nchaigne commented 10 years ago

I also tested with this commit, and confirm it fixes the issue. Unit tests with delay in home server are ok. EAP transactions no longer fail randomly during stress tests. All is good :)

Thanks Alan for the great work.