packet proxied without its attributes #637

Closed
olivierbeytrison opened this Issue May 15, 2014 · 17 comments

Projects

None yet

4 participants

@olivierbeytrison
Contributor

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
Contributor

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
Member

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

If so, we'll release 3.0.4

@olivierbeytrison
Contributor

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
Member

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

@olivierbeytrison
Contributor

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
Contributor

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

  • Sending from (1) -> (2) -> (3) during load tests (occasionnaly),
  • And always, with unit tests with a delay set in (3).

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
Contributor

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
Member
arr2036 commented May 21, 2014

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
Contributor

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

@alandekok
Member

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
Contributor

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
Member

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
Contributor

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
Contributor

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
Contributor

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.").

@alandekok alandekok closed this in f913aee May 21, 2014
@olivierbeytrison
Contributor

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

Thanks Alan and Nicolas !

@nchaigne
Contributor

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.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment