How can I catch the bug?
Hello, I am watching a bug, that is repeated periodically, and I can not easily reproduce it. Usually the request processed without any errors, but seldom one of requests may crash the server. Can someone give me hint how I can catch and reproduce it?. There is the part of log that show how bugs happens, sorry I have to redact some information from it. ``` (34) Received Access-Request Id 119 from REDACTED.IP.ADDRESS.0:53127 to REDACTED.RADIUS.IP.ADDRESS length 438 (34) Framed-MTU = 1480 (34) NAS-IP-Address = REDATED-NAS-IP (34) NAS-Identifier = "REDACTED-THE-NAS-ID" (34) User-Name = "REDACTED-THE-USER-NAME" (34) Service-Type = Framed-User (34) Framed-Protocol = PPP (34) NAS-Port = 6 (34) NAS-Port-Type = Ethernet (34) NAS-Port-Id = "6" (34) Called-Station-Id = "REDACTED-CALLED-STATION-ID" (34) Calling-Station-Id = "REDACTED-CALLING-STATION-ID" (34) Connect-Info = "CONNECT Ethernet 1000Mbps Full duplex" (34) Tunnel-Type:0 = VLAN (34) Tunnel-Medium-Type:0 = IEEE-802 (34) Tunnel-Private-Group-Id:0 = "1050" (34) State = 0x333753657373696f6e49443d4844514e4341435330332f3332303738393230342f3336303634383b (34) EAP-Message = 0x02fa00060319 (34) Message-Authenticator = 0xa3358ee8a08bde95cc268cd2ae49cef4 (34) MS-RAS-Vendor = 11 (34) HP-Capability-Advert = 0x011a0000000b28 (34) HP-Capability-Advert = 0x011a0000000b2e (34) HP-Capability-Advert = 0x011a0000000b30 (34) HP-Capability-Advert = 0x011a0000000b3d (34) HP-Capability-Advert = 0x011a0000000b18 (34) HP-Capability-Advert = 0x011a0000000b19 (34) HP-Capability-Advert = 0x0138 (34) HP-Capability-Advert = 0x013a (34) HP-Capability-Advert = 0x0140 (34) HP-Capability-Advert = 0x0141 (34) HP-Capability-Advert = 0x0151 (34) Restoring &session-state (34) # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/virtualsite (34) authorize { (34) [preprocess] = ok (34) auth_log: EXPAND /var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d:%H (34) auth_log: --> /var/log/radius/radacct/REDACTED.IP.ADDRESS.0/auth-detail-20180721:09 (34) auth_log: /var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d:%H expands to /var/log/radius/radacct/REDACTED.IP.ADDRESS.0/auth-detail-20180721:09 (34) auth_log: EXPAND %t (34) auth_log: --> Sat Jul 21 09:19:06 2018 (34) [auth_log] = ok (34) update request { (34) Supplicant-Radius-Ip := REDACTED.IP.ADDRESS.0 (34) Supplicant-Radius-Port := REDACTED-PORT (34) Selected-EAP-Module := eap (34) } # update request = noop (34) [chap] = noop (34) [mschap] = noop *** authorize *** *************** authorize - 'reply:Supplicant-Use-Remote' := 'yes' authorize - 'reply:Supplicant-Proxy-Id' := 'REDACTED_PROXY_ID' authorize - 'reply:Supplicant-User-Name' := 'REDACTED-THE-USER-NAME' (34) [python_module_auth] = updated (34) if (updated){ (34) if (updated) -> TRUE (34) if (updated) { (34) update control { (34) No attributes updated (34) } # update control = noop (34) if (&reply:Supplicant-Use-Remote == 'yes') { (34) if (&reply:Supplicant-Use-Remote == 'yes') -> TRUE (34) if (&reply:Supplicant-Use-Remote == 'yes') { (34) update control { (34) Proxy-To-Realm := &reply:Supplicant-Proxy-Id -> 'REDACTED_PROXY_ID' (34) Cleartext-Password !* ANY (34) } # update control = noop (34) } # if (&reply:Supplicant-Use-Remote == 'yes') = noop (34) if (&reply:Supplicant-Use-Mac-Auth == 'yes') { (34) ERROR: Failed retrieving values required to evaluate condition (34) policy save_reply_to_session_state { (34) update session-state { ASSERT FAILED src/main/map.c[1112]: parent CAUGHT SIGNAL: Aborted Backtrace of last 24 frames: /usr/local/lib/libfreeradius-radius.so(fr_fault+0x115)[0x7f9a4d7e4566] /usr/local/lib/libfreeradius-server.so(rad_assert_fail+0x46)[0x7f9a4da43ff2] /usr/local/lib/libfreeradius-server.so(map_to_request+0x5cb)[0x7f9a4da3d174] /usr/local/sbin/radiusd[0x429867] /usr/local/sbin/radiusd[0x42922a] /usr/local/sbin/radiusd[0x42a14a] /usr/local/sbin/radiusd[0x42922a] /usr/local/sbin/radiusd[0x42a14a] /usr/local/sbin/radiusd[0x42922a] /usr/local/sbin/radiusd[0x42a14a] /usr/local/sbin/radiusd(modcall+0xa2)[0x42ae8f] /usr/local/sbin/radiusd(indexed_modcall+0x363)[0x42669f] /usr/local/sbin/radiusd(process_authorize+0x22)[0x42893f] /usr/local/sbin/radiusd(rad_authenticate+0x212)[0x410110] /usr/local/sbin/radiusd[0x43de39] /usr/local/sbin/radiusd[0x43ca8a] /usr/local/sbin/radiusd(request_receive+0x7c2)[0x43e6d5] /usr/local/sbin/radiusd[0x41882e] /usr/local/sbin/radiusd[0x4455ce] /usr/local/lib/libfreeradius-radius.so(fr_event_loop+0x5a8)[0x7f9a4d80bfe8] /usr/local/sbin/radiusd(radius_event_process+0x26)[0x4473cd] /usr/local/sbin/radiusd(main+0xc77)[0x431417] /lib64/libc.so.6(__libc_start_main+0xf5)[0x7f9a4beb8445] /usr/local/sbin/radiusd[0x40eeb9] No panic action set Aborted ``` And there is the policy `save_reply_to_session_state` ``` save_reply_to_session_state { update session-state { Supplicant-User-Name := User-Name } } ``` The attributes that starts with 'Supplicant', are custom attributes, that I defined in dictionary. `*** authorize ***` it is debug output from `python_module_auth`, just to make it easier to find the right place in log. -- Vladimir
On Jul 23, 2018, at 2:42 PM, work vlpl <thework.vlpl@gmail.com> wrote:
I am watching a bug, that is repeated periodically, and I can not easily reproduce it. Usually the request processed without any errors, but seldom one of requests may crash the server. Can someone give me hint how I can catch and reproduce it?.
Are you using 3.0.17? If not, upgrade. The problem should be fixed.
And there is the policy `save_reply_to_session_state`
``` save_reply_to_session_state { update session-state { Supplicant-User-Name := User-Name } } ```
The attributes that starts with 'Supplicant', are custom attributes, that I defined in dictionary.
That should just work... Alan DeKok.
Maybe this will help, or maybe you will give me a hint where I should look again to find the cause. In debug log file, that I show in first email, there are the lines ``` (34) Restoring &session-state (34) # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/virtualsite (34) authorize { ... ```
From the code of `state.c` https://github.com/FreeRADIUS/freeradius-server/blob/v3.0.x/src/main/state.c...
Judging by the code, this line `Restoring &session-state` may appear in log only if `entry` exists, and therefore `state` and `state_ctx` are copied back from cached `entry`. The restoring of session-state is happens inside `rad_authenticate()` function https://github.com/FreeRADIUS/freeradius-server/blob/v3.0.x/src/main/auth.c#... And after that, the modules described in the virtual site configuration are executed, with update session-state, that failed on assertion. I may miss something, but it seems, that `state_ctx` is not changed after it was set in `fr_state_get_vps()` function and before failed assertion. So this means, the cached entry contains `state_ctx = NULL`. Also I watch in logs lines like this ``` ... (31) session-state: Saving cached attributes (31) Supplicant-User-Name := "redacted-redacted-redacted-redacted-redacted" State should be 16 octets! ... ``` And `State` attributes in received request (see logs in first email) has values like these (values are from different requests): State = 0x333753657373696f6e49443d4844514e4341435330332f3332303738393230342f3336303634383b State = 0x333753657373696f6e49443d4844514e4341435330332f3332303738393230342f3336303634373b If I understand correctly function that search state `fr_state_find()` uses only first 16 octets https://github.com/FreeRADIUS/freeradius-server/blob/v3.0.x/src/main/state.c... Because of using sizeof and structure `state` defined like this https://github.com/FreeRADIUS/freeradius-server/blob/v3.0.x/src/main/state.c... And although, function `fr_state_create()` also using only first 16 octets, it does not matter because, first 16 octets, from two different request are match. So function `fr_state_find()` select the wrong state. -- Vladimir
On Jul 25, 2018, at 9:45 AM, work vlpl <thework.vlpl@gmail.com> wrote:
Maybe this will help, or maybe you will give me a hint where I should look again to find the cause. ... Judging by the code, this line `Restoring &session-state` may appear in log only if `entry` exists, and therefore `state` and `state_ctx` are copied back from cached `entry`.
Sure.
The restoring of session-state is happens inside `rad_authenticate()` function https://github.com/FreeRADIUS/freeradius-server/blob/v3.0.x/src/main/auth.c#... And after that, the modules described in the virtual site configuration are executed, with update session-state, that failed on assertion. I may miss something, but it seems, that `state_ctx` is not changed after it was set in `fr_state_get_vps()` function and before failed assertion. So this means, the cached entry contains `state_ctx = NULL`.
state_ctx isn't supposed to change. And state_ctx=NULL might be OK. I'll take a look.
And `State` attributes in received request (see logs in first email) has values like these (values are from different requests):
State = 0x333753657373696f6e49443d4844514e4341435330332f3332303738393230342f3336303634383b State = 0x333753657373696f6e49443d4844514e4341435330332f3332303738393230342f3336303634373b
These are from another system, not from FreeRADIUS.
If I understand correctly function that search state `fr_state_find()` uses only first 16 octets https://github.com/FreeRADIUS/freeradius-server/blob/v3.0.x/src/main/state.c...
Yes,
And although, function `fr_state_create()` also using only first 16 octets, it does not matter because, first 16 octets, from two different request are match. So function `fr_state_find()` select the wrong state.
Yeah. It's best to fix the state code so that if State is larger than 16 octets, then the state code uses MD5(State), which should be better. I've pushed a fix. Alan DeKok.
state_ctx isn't supposed to change. And state_ctx=NULL might be OK. I'll take a look. Thank you.
Yeah. It's best to fix the state code so that if State is larger than 16 octets, then the state code uses MD5(State), which should be better. I think `fr_state_find()` function also require a fix https://github.com/FreeRADIUS/freeradius-server/blob/v3.0.x/src/main/state.c... because it still uses only first 16 octets. Or am I wrong?
-- Vladimir
On Jul 25, 2018, at 12:33 PM, work vlpl <thework.vlpl@gmail.com> wrote:
Yeah. It's best to fix the state code so that if State is larger than 16 octets, then the state code uses MD5(State), which should be better. I think `fr_state_find()` function also require a fix https://github.com/FreeRADIUS/freeradius-server/blob/v3.0.x/src/main/state.c... because it still uses only first 16 octets. Or am I wrong?
I've pushed a fix. Alan DeKok.
participants (2)
-
Alan DeKok -
work vlpl