How can I catch the bug?

work vlpl thework.vlpl at gmail.com
Mon Jul 23 20:42:29 CEST 2018


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


More information about the Freeradius-Users mailing list