Closed olivierbeytrison closed 1 month ago
I've pushed a fix. Please verify.
no luck unfortunately, still the same behaviour. Crash on status-request after the previously failed proxied request.
radiusd: FreeRADIUS Version 3.2.4 (git #66e638978), for host x86_64-pc-linux-gnu, built on Mar 13 2024 at 15:49:23
FreeRADIUS Version 3.2.4
Copyright (C) 1999-2023 The FreeRADIUS server project and contributors
There is NO warranty; not even for MERCHANTABILITY or FITNESS FOR A
PARTICULAR PURPOSE
You may redistribute copies of FreeRADIUS under the terms of the
GNU General Public License
For more information about these matters, see the file named COPYRIGHT
Thread 1 (Thread 0x7feb69d75740 (LWP 3841245) "radiusd"):
#0 0x00007feb69e6242f in __GI___wait4 (pid=3841705, stat_loc=stat_loc@entry=0x7ffc075de628, options=options@entry=0, usage=usage@entry=0x0) at ../sysdeps/unix/sysv/linux/wait4.c:30
sc_ret = -512
sc_cancel_oldtype = 0
sc_ret = <optimized out>
#1 0x00007feb69e623ab in __GI___waitpid (pid=<optimized out>, stat_loc=stat_loc@entry=0x7ffc075de628, options=options@entry=0) at ./posix/waitpid.c:38
No locals.
#2 0x00007feb69dc8bdb in do_system (line=<optimized out>) at ../sysdeps/posix/system.c:171
__result = <optimized out>
_cleanup_start_doit = true
_buffer = {__routine = 0x7feb69dc8c60 <cancel_handler>, __arg = 0x7ffc075de630, __canceltype = 0, __prev = 0x0}
_cleanup_routine = 0x7feb69dc8c60 <cancel_handler>
cancel_args = {quit = 0x7feb69f947a0 <quit>, intr = 0x7feb69f94840 <intr>, pid = 3841705}
status = -1
ret = 0
pid = 3841705
sa = {__sigaction_handler = {sa_handler = 0x1, sa_sigaction = 0x1}, sa_mask = {__val = {65536, 0 <repeats 15 times>}}, sa_flags = 0, sa_restorer = 0x0}
omask = {__val = {0, 7453294854038368817, 0, 0, 0, 0, 7310503812617283134, 7363234149704867941, 8460403744686040434, 8028844404002664307, 0, 0, 0, 0, 7234802330899472752, 8227916443131519074}}
reset = {__val = {6, 3611945399447794744, 0, 0, 0, 0, 8299888338792379502, 8243106234986624626, 8387162053985002593, 3414401849794637667, 0, 0, 0, 0, 3900939194679983122, 3464635662526412429}}
spawn_attr = {__flags = 12, __pgrp = 0, __sd = {__val = {6, 3611945399447794744, 0, 0, 0, 0, 8299888338792379502, 8243106234986624626, 8387162053985002593, 3414401849794637667, 0, 0, 0, 0, 3900939194679983122, 3464635662526412429}}, __ss = {__val = {0, 7453294854038368817, 0, 0, 0, 0, 7310503812617283134, 7363234149704867941, 8460403744686040434, 8028844404002664307, 0, 0, 0, 0, 7234802330899472752, 8227916443131519074}}, __sp = {sched_priority = 0}, __policy = 0, __pad = {0 <repeats 16 times>}}
#3 0x00007feb6a4e761e in fr_fault (sig=6) at src/lib/debug.c:793
disable = true
cmd = "gdb -silent -x /srv/freeradius/etc/raddb/panic.gdb sbin/radiusd 3841245 2>&1 | tee /srv/freeradius/var/log/radius/gdb-radiusd-3841245.log", '\000' <repeats 394 times>
out = 0x7ffc075deea5 ".log"
left = 399
ret = 62
p = 0x7feb6a52941b <panic_action+123> ".log"
q = 0x0
code = 0
#4 0x00007feb6a5533f0 in rad_assert_fail (file=0x55b04a978002 "src/main/process.c", line=3894, expr=0x55b04a97811b "!request->in_proxy_hash") at src/main/util.c:557
No locals.
#5 0x000055b04a9434c8 in request_ping (request=0x55b04c17e260, action=5) at src/main/process.c:3894
home = 0x55b04be48700
buffer = "130.59.31.24\000U\000\000\000l\025L\260U\000\000\240:\030L\260U\000\000\000\000\000\000 ", '\000' <repeats 19 times>, "t\b\025L\260U\000\000\320\361]\a\374\177\000\000:\325$j\353\177\000\000Nv \000\000\000\000\000,\000\000\000\000\000\000\000p\000\000\000k\000\000\000\240V\327i\353\177\000\000\001\000\000\000\000\000\000\000\371/\376i\353\177\000"
__FUNCTION__ = "request_ping"
#6 0x000055b04a941122 in request_proxy_reply (packet=0x55b04c183aa0) at src/main/process.c:2954
proxy_p = 0x55b04c17e2c8
request = 0x55b04c17e260
now = {tv_sec = 1710341443, tv_usec = 187274}
buffer = "\320\361]\a\374\177\000\000S\324Qj\353\177\000\000\060\362]\a\374\177\000\000\230", '\000' <repeats 15 times>, "\240:\030L\260U\000\000\024\000\000\000\000\000\000\000\200\035\376i\353\177\000\000@:\030L\260U\000\000\000h\002\204\313\"\305_0\362]\a\374\177\000\000\060:\230J\260U\000\000\220\363]\a\374\177\000\000\370\367]\a\374\177\000\000\374\361\222J\260U\000\000x\253\230J\260U\000"
#7 0x000055b04a964341 in proxy_tls_recv (listener=0x7feb6000c1f0) at src/main/tls_listen.c:1351
sock = 0x7feb60002190
buffer = "\240\362]\a\374\177\000\000\001\000\000\000\000\000\000\000\002\000\000\000\000\000\000\000\200\020ih\353\177\000\000\000\021ih\353\177\000\000\000\021ih\353\177\000\000\001", '\000' <repeats 15 times>, "\200\020ih\353\177\000\000\000\021ih\353\177\000\000@\363]\a\374\177\000\000\000h\002\204\313\"\305_ \363]\a\374\177\000\000\226\217\223J\260U\000\000 \363]\a\374\177\000\000\200t\026L\260U\000\000 \363]\a\374\177\000\000\032\260\223J\260U\000\000\000\000\000\000\000\000\000\000\254&\231J\260U\000\000\260&\231J\260U\000\000\000h\002\204\313\"\305_p\363]\a\374\177\000\000X͓J\260U\000\000D\023\224J\260U\000\000\200"...
packet = 0x55b04c183aa0
data = 0x55b04c20f5c0 <incomplete sequence \375>
data_len = 20
#8 0x000055b04a947782 in event_socket_handler (xel=0x55b04c02da80, fd=22, ctx=0x7feb6000c1f0) at src/main/process.c:5305
listener = 0x7feb6000c1f0
#9 0x00007feb6a513313 in fr_event_loop (el=0x55b04c02da80) at src/lib/event.c:710
ef = 0x55b04c02dc78
i = 6
rcode = 1
when = {tv_sec = 1710341443, tv_usec = 493392}
wake = 0x7ffc075df520
read_fds = {fds_bits = {4194304, 0 <repeats 15 times>}}
write_fds = {fds_bits = {0 <repeats 16 times>}}
#10 0x000055b04a949a3d in radius_event_process () at src/main/process.c:6489
No locals.
#11 0x000055b04a92ff14 in main (argc=4, argv=0x7ffc075df7f8) at src/main/radiusd.c:641
rcode = 0
status = 0
argval = -1
spawn_flag = true
display_version = false
flag = 0
from_child = {-1, -1}
p = 0x7ffc075e07e3 "/radiusd"
state = 0x55b04a991f60 <global_state>
autofree = 0x55b04bc2f300
Waking up in 0.3 seconds.
(1) Marking home server 130.59.31.24 port 2083 alive
(1) Received response to status check 1 ID 253 (1 in current sequence)
ASSERT FAILED src/main/process.c[3894]: !request->in_proxy_hash
CAUGHT SIGNAL: Aborted
Backtrace of last 12 frames:
/srv/freeradius/lib/libfreeradius-radius.so(fr_fault+0x139)[0x7feb6a4e73f8]
/srv/freeradius/lib/libfreeradius-server.so(rad_assert_fail+0x4d)[0x7feb6a5533f0]
sbin/radiusd(+0x544c8)[0x55b04a9434c8]
sbin/radiusd(request_proxy_reply+0x71c)[0x55b04a941122]
sbin/radiusd(proxy_tls_recv+0x3b6)[0x55b04a964341]
sbin/radiusd(+0x58782)[0x55b04a947782]
/srv/freeradius/lib/libfreeradius-radius.so(fr_event_loop+0x60d)[0x7feb6a513313]
sbin/radiusd(radius_event_process+0x2a)[0x55b04a949a3d]
sbin/radiusd(main+0xd18)[0x55b04a92ff14]
/lib/x86_64-linux-gnu/libc.so.6(+0x29d90)[0x7feb69da1d90]
/lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0x80)[0x7feb69da1e40]
sbin/radiusd(_start+0x25)[0x55b04a906da5]
That's more than a little weird. All of the code paths which reach that assertion call the remove_from_proxy_hash()
function, which makes sure that the request isn't in the proxy hash. So the assertion should pass.
can you run it with -Xx
? That will print out more information about the state transitions it goes through
well I can't run it with -X because tls requires threading :s
I added more "x" which gave some more output
Wed Mar 13 16:32:48 2024 : Debug: Listening on auth+acct proto tcp address * port 2083 (TLS) bound to server eduroam
Wed Mar 13 16:32:48 2024 : Debug: Listening on auth address * port 1812 bound to server eduroam
Wed Mar 13 16:32:48 2024 : Debug: Listening on acct address * port 1813 bound to server eduroam
Wed Mar 13 16:32:48 2024 : Info: Ready to process requests
Wed Mar 13 16:32:59 2024 : Debug: Threads: total/active/spare threads = 5/0/5
Wed Mar 13 16:32:59 2024 : Debug: Waking up in 0.3 seconds.
Wed Mar 13 16:32:59 2024 : Debug: Thread 3 got semaphore
Wed Mar 13 16:32:59 2024 : Debug: Thread 3 handling request 0, (1 handled so far)
Wed Mar 13 16:32:59 2024 : Debug: (0) Received Access-Request Id 0 from 127.0.0.1:46698 to 127.0.0.1:1812 length 154
Wed Mar 13 16:32:59 2024 : Debug: (0) User-Name = "hefr@test.eduroam.ch"
Wed Mar 13 16:32:59 2024 : Debug: (0) NAS-IP-Address = 127.0.0.1
Wed Mar 13 16:32:59 2024 : Debug: (0) Calling-Station-Id = "02-00-00-00-00-01"
Wed Mar 13 16:32:59 2024 : Debug: (0) Framed-MTU = 1400
Wed Mar 13 16:32:59 2024 : Debug: (0) NAS-Port-Type = Wireless-802.11
Wed Mar 13 16:32:59 2024 : Debug: (0) Service-Type = Framed-User
Wed Mar 13 16:32:59 2024 : Debug: (0) Connect-Info = "CONNECT 11Mbps 802.11b"
Wed Mar 13 16:32:59 2024 : Debug: (0) EAP-Message = 0x02610019016865667240746573742e656475726f616d2e6368
Wed Mar 13 16:32:59 2024 : Debug: (0) Message-Authenticator = 0xd361b1ce115a55f9a7ad25ee430b20e3
Wed Mar 13 16:32:59 2024 : Debug: (0) session-state: No State attribute
Wed Mar 13 16:32:59 2024 : Debug: (0) # Executing section authorize from file /srv/freeradius/etc/raddb/sites-enabled/eduroam
Wed Mar 13 16:32:59 2024 : Debug: (0) authorize {
Wed Mar 13 16:32:59 2024 : Debug: (0) modsingle[authorize]: calling preprocess (rlm_preprocess)
Wed Mar 13 16:32:59 2024 : Debug: (0) modsingle[authorize]: returned from preprocess (rlm_preprocess)
Wed Mar 13 16:32:59 2024 : Debug: (0) [preprocess] = ok
Wed Mar 13 16:32:59 2024 : Debug: (0) modsingle[authorize]: calling auth_log (rlm_detail)
Wed Mar 13 16:32:59 2024 : Debug: /srv/freeradius/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d
Wed Mar 13 16:32:59 2024 : Debug: Parsed xlat tree:
Wed Mar 13 16:32:59 2024 : Debug: literal --> /srv/freeradius/var/log/radius/radacct/
Wed Mar 13 16:32:59 2024 : Debug: XLAT-IF {
Wed Mar 13 16:32:59 2024 : Debug: attribute --> Packet-Src-IP-Address
Wed Mar 13 16:32:59 2024 : Debug: }
Wed Mar 13 16:32:59 2024 : Debug: XLAT-ELSE {
Wed Mar 13 16:32:59 2024 : Debug: attribute --> Packet-Src-IPv6-Address
Wed Mar 13 16:32:59 2024 : Debug: }
Wed Mar 13 16:32:59 2024 : Debug: literal --> /auth-detail-
Wed Mar 13 16:32:59 2024 : Debug: percent --> Y
Wed Mar 13 16:32:59 2024 : Debug: percent --> m
Wed Mar 13 16:32:59 2024 : Debug: percent --> d
Wed Mar 13 16:32:59 2024 : Debug: (0) auth_log: EXPAND /srv/freeradius/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d
Wed Mar 13 16:32:59 2024 : Debug: (0) auth_log: --> /srv/freeradius/var/log/radius/radacct/127.0.0.1/auth-detail-20240313
Wed Mar 13 16:32:59 2024 : Debug: (0) auth_log: /srv/freeradius/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d expands to /srv/freeradius/var/log/radius/radacct/127.0.0.1/auth-detail-20240313
Wed Mar 13 16:32:59 2024 : Debug: %t
Wed Mar 13 16:32:59 2024 : Debug: Parsed xlat tree:
Wed Mar 13 16:32:59 2024 : Debug: percent --> t
Wed Mar 13 16:32:59 2024 : Debug: (0) auth_log: EXPAND %t
Wed Mar 13 16:32:59 2024 : Debug: (0) auth_log: --> Wed Mar 13 16:32:59 2024
Wed Mar 13 16:32:59 2024 : Debug: (0) modsingle[authorize]: returned from auth_log (rlm_detail)
Wed Mar 13 16:32:59 2024 : Debug: (0) [auth_log] = ok
Wed Mar 13 16:32:59 2024 : Debug: (0) if ("%{client:location}" == 'ROAMING') {
Wed Mar 13 16:32:59 2024 : Debug: (0) EXPAND %{client:location}
Wed Mar 13 16:32:59 2024 : Debug: (0) --> RORG-HEFR
Wed Mar 13 16:32:59 2024 : Debug: (0) if ("%{client:location}" == 'ROAMING') -> FALSE
Wed Mar 13 16:32:59 2024 : Debug: (0) policy operator-name.authorize {
Wed Mar 13 16:32:59 2024 : Debug: (0) if ("%{client:Operator-Name}") {
Wed Mar 13 16:32:59 2024 : Debug: (0) EXPAND %{client:Operator-Name}
Wed Mar 13 16:32:59 2024 : Debug: (0) --> 1hes-so.ch
Wed Mar 13 16:32:59 2024 : Debug: (0) if ("%{client:Operator-Name}") -> TRUE
Wed Mar 13 16:32:59 2024 : Debug: (0) if ("%{client:Operator-Name}") {
Wed Mar 13 16:32:59 2024 : Debug: (0) update request {
Wed Mar 13 16:32:59 2024 : Debug: (0) EXPAND %{client:Operator-Name}
Wed Mar 13 16:32:59 2024 : Debug: (0) --> 1hes-so.ch
Wed Mar 13 16:32:59 2024 : Debug: (0) &Operator-Name = 1hes-so.ch
Wed Mar 13 16:32:59 2024 : Debug: (0) } # update request = noop
Wed Mar 13 16:32:59 2024 : Debug: (0) } # if ("%{client:Operator-Name}") = noop
Wed Mar 13 16:32:59 2024 : Debug: (0) } # policy operator-name.authorize = noop
Wed Mar 13 16:32:59 2024 : Debug: (0) policy cui.authorize {
Wed Mar 13 16:32:59 2024 : Debug: (0) if ("%{client:add_cui}" == 'yes') {
Wed Mar 13 16:32:59 2024 : Debug: (0) EXPAND %{client:add_cui}
Wed Mar 13 16:32:59 2024 : Debug: (0) --> yes
Wed Mar 13 16:32:59 2024 : Debug: (0) if ("%{client:add_cui}" == 'yes') -> TRUE
Wed Mar 13 16:32:59 2024 : Debug: (0) if ("%{client:add_cui}" == 'yes') {
Wed Mar 13 16:32:59 2024 : Debug: (0) update request {
Wed Mar 13 16:32:59 2024 : Debug: (0) &Chargeable-User-Identity := 0x00
Wed Mar 13 16:32:59 2024 : Debug: (0) } # update request = noop
Wed Mar 13 16:32:59 2024 : Debug: (0) } # if ("%{client:add_cui}" == 'yes') = noop
Wed Mar 13 16:32:59 2024 : Debug: (0) } # policy cui.authorize = noop
Wed Mar 13 16:32:59 2024 : Debug: (0) policy parse_realm {
Wed Mar 13 16:32:59 2024 : Debug: (0) policy split_username_nai {
Wed Mar 13 16:32:59 2024 : Debug: (0) if (&User-Name && (&User-Name =~ /^([^@]*)(@([-[:alnum:]]+\.[-[:alnum:].]+))?$/)) {
Wed Mar 13 16:32:59 2024 : Debug: (0) if (&User-Name && (&User-Name =~ /^([^@]*)(@([-[:alnum:]]+\.[-[:alnum:].]+))?$/)) -> TRUE
Wed Mar 13 16:32:59 2024 : Debug: (0) if (&User-Name && (&User-Name =~ /^([^@]*)(@([-[:alnum:]]+\.[-[:alnum:].]+))?$/)) {
Wed Mar 13 16:32:59 2024 : Debug: (0) update request {
Wed Mar 13 16:32:59 2024 : Debug: (0) EXPAND %{1}
Wed Mar 13 16:32:59 2024 : Debug: (0) --> hefr
Wed Mar 13 16:32:59 2024 : Debug: (0) &Stripped-User-Name := hefr
Wed Mar 13 16:32:59 2024 : Debug: (0) } # update request = noop
Wed Mar 13 16:32:59 2024 : Debug: (0) if ("%{3}" != '') {
Wed Mar 13 16:32:59 2024 : Debug: (0) EXPAND %{3}
Wed Mar 13 16:32:59 2024 : Debug: (0) --> test.eduroam.ch
Wed Mar 13 16:32:59 2024 : Debug: (0) if ("%{3}" != '') -> TRUE
Wed Mar 13 16:32:59 2024 : Debug: (0) if ("%{3}" != '') {
Wed Mar 13 16:32:59 2024 : Debug: (0) update request {
Wed Mar 13 16:32:59 2024 : Debug: (0) EXPAND %{3}
Wed Mar 13 16:32:59 2024 : Debug: (0) --> test.eduroam.ch
Wed Mar 13 16:32:59 2024 : Debug: (0) &Stripped-User-Domain = test.eduroam.ch
Wed Mar 13 16:32:59 2024 : Debug: (0) } # update request = noop
Wed Mar 13 16:32:59 2024 : Debug: (0) } # if ("%{3}" != '') = noop
Wed Mar 13 16:32:59 2024 : Debug: (0) modsingle[authorize]: calling updated (rlm_always)
Wed Mar 13 16:32:59 2024 : Debug: (0) modsingle[authorize]: returned from updated (rlm_always)
Wed Mar 13 16:32:59 2024 : Debug: (0) [updated] = updated
Wed Mar 13 16:32:59 2024 : Debug: (0) } # if (&User-Name && (&User-Name =~ /^([^@]*)(@([-[:alnum:]]+\.[-[:alnum:].]+))?$/)) = updated
Wed Mar 13 16:32:59 2024 : Debug: (0) ... skipping else: Preceding "if" was taken
Wed Mar 13 16:32:59 2024 : Debug: (0) } # policy split_username_nai = updated
Wed Mar 13 16:32:59 2024 : Debug: (0) if (&Stripped-User-Domain) {
Wed Mar 13 16:32:59 2024 : Debug: (0) if (&Stripped-User-Domain) -> TRUE
Wed Mar 13 16:32:59 2024 : Debug: (0) if (&Stripped-User-Domain) {
Wed Mar 13 16:32:59 2024 : Debug: (0) if ((&Stripped-User-Domain == 'test.hes-so.ch') || (&Stripped-User-Domain == 'hes-so.ch') || (&Stripped-User-Domain == 'hefr.ch')) {
Wed Mar 13 16:32:59 2024 : Debug: (0) if ((&Stripped-User-Domain == 'test.hes-so.ch') || (&Stripped-User-Domain == 'hes-so.ch') || (&Stripped-User-Domain == 'hefr.ch')) -> FALSE
Wed Mar 13 16:32:59 2024 : Debug: (0) elsif (&Stripped-User-Domain !~ /^([-a-z0-9]+\.)+[-a-z0-9]+/) {
Wed Mar 13 16:32:59 2024 : Debug: (0) elsif (&Stripped-User-Domain !~ /^([-a-z0-9]+\.)+[-a-z0-9]+/) -> FALSE
Wed Mar 13 16:32:59 2024 : Debug: (0) else {
Wed Mar 13 16:32:59 2024 : Debug: (0) update {
Wed Mar 13 16:32:59 2024 : Debug: (0) request:Realm := 'EDUROAM'
Wed Mar 13 16:32:59 2024 : Debug: (0) control:Proxy-To-Realm := 'EDUROAM'
Wed Mar 13 16:32:59 2024 : Debug: (0) } # update = noop
Wed Mar 13 16:32:59 2024 : Debug: (0) } # else = noop
Wed Mar 13 16:32:59 2024 : Debug: (0) } # if (&Stripped-User-Domain) = noop
Wed Mar 13 16:32:59 2024 : Debug: (0) ... skipping else: Preceding "if" was taken
Wed Mar 13 16:32:59 2024 : Debug: (0) } # policy parse_realm = updated
Wed Mar 13 16:32:59 2024 : Debug: (0) policy set_location {
Wed Mar 13 16:32:59 2024 : Debug: (0) if (!&request:HESSO-Location && "%{client:location}") {
Wed Mar 13 16:32:59 2024 : Debug: (0) EXPAND %{client:location}
Wed Mar 13 16:32:59 2024 : Debug: (0) --> RORG-HEFR
Wed Mar 13 16:32:59 2024 : Debug: (0) if (!&request:HESSO-Location && "%{client:location}") -> TRUE
Wed Mar 13 16:32:59 2024 : Debug: (0) if (!&request:HESSO-Location && "%{client:location}") {
Wed Mar 13 16:32:59 2024 : Debug: (0) update request {
Wed Mar 13 16:32:59 2024 : Debug: (0) EXPAND %{client:location}
Wed Mar 13 16:32:59 2024 : Debug: (0) --> RORG-HEFR
Wed Mar 13 16:32:59 2024 : Debug: (0) HESSO-Location := RORG-HEFR
Wed Mar 13 16:32:59 2024 : Debug: (0) } # update request = noop
Wed Mar 13 16:32:59 2024 : Debug: (0) } # if (!&request:HESSO-Location && "%{client:location}") = noop
Wed Mar 13 16:32:59 2024 : Debug: (0) } # policy set_location = noop
Wed Mar 13 16:32:59 2024 : Debug: (0) if (&Stripped-User-Domain == 'hefr.ch') {
Wed Mar 13 16:32:59 2024 : Debug: (0) if (&Stripped-User-Domain == 'hefr.ch') -> FALSE
Wed Mar 13 16:32:59 2024 : Debug: (0) else {
Wed Mar 13 16:32:59 2024 : Debug: (0) modsingle[authorize]: calling eap (rlm_eap)
Wed Mar 13 16:32:59 2024 : Debug: (0) eap: Request is supposed to be proxied to Realm EDUROAM. Not doing EAP.
Wed Mar 13 16:32:59 2024 : Debug: (0) modsingle[authorize]: returned from eap (rlm_eap)
Wed Mar 13 16:32:59 2024 : Debug: (0) [eap] = noop
Wed Mar 13 16:32:59 2024 : Debug: (0) } # else = noop
Wed Mar 13 16:32:59 2024 : Debug: (0) } # authorize = updated
Wed Mar 13 16:32:59 2024 : Debug: Using home pool auth for realm EDUROAM
Wed Mar 13 16:32:59 2024 : Debug: (0) Starting proxy to home server 130.59.31.24 port 2083
Wed Mar 13 16:32:59 2024 : Debug: (0) server eduroam {
Wed Mar 13 16:32:59 2024 : Debug: (0) # Executing section pre-proxy from file /srv/freeradius/etc/raddb/sites-enabled/eduroam
Wed Mar 13 16:32:59 2024 : Debug: (0) pre-proxy {
Wed Mar 13 16:32:59 2024 : Debug: (0) modsingle[pre-proxy]: calling pre_proxy_log (rlm_detail)
Wed Mar 13 16:32:59 2024 : Debug: /srv/freeradius/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/pre-proxy-detail-%Y%m%d
Wed Mar 13 16:32:59 2024 : Debug: Parsed xlat tree:
Wed Mar 13 16:32:59 2024 : Debug: literal --> /srv/freeradius/var/log/radius/radacct/
Wed Mar 13 16:32:59 2024 : Debug: XLAT-IF {
Wed Mar 13 16:32:59 2024 : Debug: attribute --> Packet-Src-IP-Address
Wed Mar 13 16:32:59 2024 : Debug: }
Wed Mar 13 16:32:59 2024 : Debug: XLAT-ELSE {
Wed Mar 13 16:32:59 2024 : Debug: attribute --> Packet-Src-IPv6-Address
Wed Mar 13 16:32:59 2024 : Debug: }
Wed Mar 13 16:32:59 2024 : Debug: literal --> /pre-proxy-detail-
Wed Mar 13 16:32:59 2024 : Debug: percent --> Y
Wed Mar 13 16:32:59 2024 : Debug: percent --> m
Wed Mar 13 16:32:59 2024 : Debug: percent --> d
Wed Mar 13 16:32:59 2024 : Debug: (0) pre_proxy_log: EXPAND /srv/freeradius/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/pre-proxy-detail-%Y%m%d
Wed Mar 13 16:32:59 2024 : Debug: (0) pre_proxy_log: --> /srv/freeradius/var/log/radius/radacct/127.0.0.1/pre-proxy-detail-20240313
Wed Mar 13 16:32:59 2024 : Debug: (0) pre_proxy_log: /srv/freeradius/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/pre-proxy-detail-%Y%m%d expands to /srv/freeradius/var/log/radius/radacct/127.0.0.1/pre-proxy-detail-20240313
Wed Mar 13 16:32:59 2024 : Debug: %t
Wed Mar 13 16:32:59 2024 : Debug: Parsed xlat tree:
Wed Mar 13 16:32:59 2024 : Debug: percent --> t
Wed Mar 13 16:32:59 2024 : Debug: (0) pre_proxy_log: EXPAND %t
Wed Mar 13 16:32:59 2024 : Debug: (0) pre_proxy_log: --> Wed Mar 13 16:32:59 2024
Wed Mar 13 16:32:59 2024 : Debug: (0) modsingle[pre-proxy]: returned from pre_proxy_log (rlm_detail)
Wed Mar 13 16:32:59 2024 : Debug: (0) [pre_proxy_log] = ok
Wed Mar 13 16:32:59 2024 : Debug: (0) policy operator-name.pre-proxy {
Wed Mar 13 16:32:59 2024 : Debug: (0) if (("%{request:Packet-Type}" == 'Access-Request') && "%{client:Operator-Name}") {
Wed Mar 13 16:32:59 2024 : Debug: %{request:Packet-Type}
Wed Mar 13 16:32:59 2024 : Debug: Parsed xlat tree:
Wed Mar 13 16:32:59 2024 : Debug: attribute --> Packet-Type
Wed Mar 13 16:32:59 2024 : Debug: (0) EXPAND %{request:Packet-Type}
Wed Mar 13 16:32:59 2024 : Debug: (0) --> Access-Request
Wed Mar 13 16:32:59 2024 : Debug: (0) EXPAND %{client:Operator-Name}
Wed Mar 13 16:32:59 2024 : Debug: (0) --> 1hes-so.ch
Wed Mar 13 16:32:59 2024 : Debug: (0) if (("%{request:Packet-Type}" == 'Access-Request') && "%{client:Operator-Name}") -> TRUE
Wed Mar 13 16:32:59 2024 : Debug: (0) if (("%{request:Packet-Type}" == 'Access-Request') && "%{client:Operator-Name}") {
Wed Mar 13 16:32:59 2024 : Debug: (0) update proxy-request {
Wed Mar 13 16:32:59 2024 : Debug: (0) EXPAND %{client:Operator-Name}
Wed Mar 13 16:32:59 2024 : Debug: (0) --> 1hes-so.ch
Wed Mar 13 16:32:59 2024 : Debug: (0) &Operator-Name := 1hes-so.ch
Wed Mar 13 16:32:59 2024 : Debug: (0) Overwriting value "1hes-so.ch" with "1hes-so.ch"
Wed Mar 13 16:32:59 2024 : Debug: (0) } # update proxy-request = noop
Wed Mar 13 16:32:59 2024 : Debug: (0) } # if (("%{request:Packet-Type}" == 'Access-Request') && "%{client:Operator-Name}") = noop
Wed Mar 13 16:32:59 2024 : Debug: (0) } # policy operator-name.pre-proxy = noop
Wed Mar 13 16:32:59 2024 : Debug: (0) policy cui.pre-proxy {
Wed Mar 13 16:32:59 2024 : Debug: (0) if (("%{request:Packet-Type}" == 'Access-Request') && ("%{client:add_cui}" == 'yes')) {
Wed Mar 13 16:32:59 2024 : Debug: %{request:Packet-Type}
Wed Mar 13 16:32:59 2024 : Debug: Parsed xlat tree:
Wed Mar 13 16:32:59 2024 : Debug: attribute --> Packet-Type
Wed Mar 13 16:32:59 2024 : Debug: (0) EXPAND %{request:Packet-Type}
Wed Mar 13 16:32:59 2024 : Debug: (0) --> Access-Request
Wed Mar 13 16:32:59 2024 : Debug: (0) EXPAND %{client:add_cui}
Wed Mar 13 16:32:59 2024 : Debug: (0) --> yes
Wed Mar 13 16:32:59 2024 : Debug: (0) if (("%{request:Packet-Type}" == 'Access-Request') && ("%{client:add_cui}" == 'yes')) -> TRUE
Wed Mar 13 16:32:59 2024 : Debug: (0) if (("%{request:Packet-Type}" == 'Access-Request') && ("%{client:add_cui}" == 'yes')) {
Wed Mar 13 16:32:59 2024 : Debug: (0) update proxy-request {
Wed Mar 13 16:32:59 2024 : Debug: (0) &Chargeable-User-Identity = 0x00
Wed Mar 13 16:32:59 2024 : Debug: (0) Refusing to overwrite (use :=)
Wed Mar 13 16:32:59 2024 : Debug: (0) } # update proxy-request = noop
Wed Mar 13 16:32:59 2024 : Debug: (0) } # if (("%{request:Packet-Type}" == 'Access-Request') && ("%{client:add_cui}" == 'yes')) = noop
Wed Mar 13 16:32:59 2024 : Debug: (0) } # policy cui.pre-proxy = noop
Wed Mar 13 16:32:59 2024 : Debug: (0) modsingle[pre-proxy]: calling attr_filter.pre-proxy (rlm_attr_filter)
Wed Mar 13 16:32:59 2024 : Debug: %{Realm}
Wed Mar 13 16:32:59 2024 : Debug: Parsed xlat tree:
Wed Mar 13 16:32:59 2024 : Debug: attribute --> Realm
Wed Mar 13 16:32:59 2024 : Debug: (0) attr_filter.pre-proxy: EXPAND %{Realm}
Wed Mar 13 16:32:59 2024 : Debug: (0) attr_filter.pre-proxy: --> EDUROAM
Wed Mar 13 16:32:59 2024 : Debug: (0) modsingle[pre-proxy]: returned from attr_filter.pre-proxy (rlm_attr_filter)
Wed Mar 13 16:32:59 2024 : Debug: (0) [attr_filter.pre-proxy] = noop
Wed Mar 13 16:32:59 2024 : Debug: (0) } # pre-proxy = ok
Wed Mar 13 16:32:59 2024 : Debug: (0) }
Wed Mar 13 16:32:59 2024 : Debug: (0) proxy: Trying to allocate ID (0/2)
Wed Mar 13 16:32:59 2024 : Debug: (0) proxy: Trying to open a new listener to the home server
Wed Mar 13 16:32:59 2024 : Debug: (TLS) Trying new outgoing proxy connection to proxy (0.0.0.0, 0) -> home_server (130.59.31.24, 2083)
Wed Mar 13 16:32:59 2024 : Debug: Requiring Server certificate
Wed Mar 13 16:32:59 2024 : Debug: (0) (TLS) RADIUS/TLS - Handshake state [PINIT] - before SSL initialization (0)
Wed Mar 13 16:32:59 2024 : Debug: (0) (TLS) RADIUS/TLS - Handshake state [PINIT] - Client before SSL initialization (0)
Wed Mar 13 16:32:59 2024 : Debug: (0) (TLS) RADIUS/TLS - send TLS 1.2 Handshake, ClientHello
Wed Mar 13 16:32:59 2024 : ERROR: (0) (TLS) RADIUS/TLS - Client : Error in SSLv3/TLS write client hello
Wed Mar 13 16:32:59 2024 : Debug: Opened new proxy socket 'proxy (160.98.240.25, 49795) -> home_server (130.59.31.24, 2083)'
Wed Mar 13 16:32:59 2024 : Debug: Listening on proxy (160.98.240.25, 49795) -> home_server (130.59.31.24, 2083)
Wed Mar 13 16:32:59 2024 : Debug: Waking up in 0.3 seconds.
Wed Mar 13 16:32:59 2024 : Debug: (0) proxy: Trying to allocate ID (1/2)
Wed Mar 13 16:32:59 2024 : Debug: (0) proxy: request is now in proxy hash
Wed Mar 13 16:32:59 2024 : Debug: (0) proxy: allocating destination 130.59.31.24 port 2083 - Id 76
Wed Mar 13 16:32:59 2024 : Debug: (0) Proxying request to home server 130.59.31.24 port 2083 (TLS) timeout 20.000000
Wed Mar 13 16:32:59 2024 : Debug: (0) Sent Access-Request Id 76 from 160.98.240.25:49795 to 130.59.31.24:2083 length 195
Wed Mar 13 16:32:59 2024 : Debug: (0) User-Name = "hefr@test.eduroam.ch"
Wed Mar 13 16:32:59 2024 : Debug: (0) NAS-IP-Address = 127.0.0.1
Wed Mar 13 16:32:59 2024 : Debug: (0) Calling-Station-Id = "02-00-00-00-00-01"
Wed Mar 13 16:32:59 2024 : Debug: (0) Framed-MTU = 1400
Wed Mar 13 16:32:59 2024 : Debug: (0) NAS-Port-Type = Wireless-802.11
Wed Mar 13 16:32:59 2024 : Debug: (0) Service-Type = Framed-User
Wed Mar 13 16:32:59 2024 : Debug: (0) Connect-Info = "CONNECT 11Mbps 802.11b"
Wed Mar 13 16:32:59 2024 : Debug: (0) EAP-Message = 0x02610019016865667240746573742e656475726f616d2e6368
Wed Mar 13 16:32:59 2024 : Debug: (0) Message-Authenticator = 0xd361b1ce115a55f9a7ad25ee430b20e3
Wed Mar 13 16:32:59 2024 : Debug: (0) Event-Timestamp = "Mar 13 2024 16:32:59 CET"
Wed Mar 13 16:32:59 2024 : Debug: (0) Operator-Name := "1hes-so.ch"
Wed Mar 13 16:32:59 2024 : Debug: (0) Chargeable-User-Identity := 0x00
Wed Mar 13 16:32:59 2024 : Debug: (0) HESSO-Location := "RORG-HEFR"
Wed Mar 13 16:32:59 2024 : Debug: (0) Proxy-State = 0x30
Wed Mar 13 16:32:59 2024 : ERROR: (0) (TLS) RADIUS/TLS - Client : Error in SSLv3/TLS write client hello
Wed Mar 13 16:32:59 2024 : Debug: (TLS) SSL_connect() returned WANT_WRITE
Wed Mar 13 16:32:59 2024 : Debug: (0) (TLS) Writing 195 bytes for later (total 195)
Wed Mar 13 16:32:59 2024 : Debug: Thread 3 waiting to be assigned a request
Wed Mar 13 16:32:59 2024 : Debug: (0) Expecting proxy response no later than 19.668950 seconds from now
Wed Mar 13 16:32:59 2024 : Debug: Waking up in 19.6 seconds.
Wed Mar 13 16:33:02 2024 : Debug: Suppressing duplicate proxied request (tcp) to home server 130.59.31.24 port 2083 proto TCP - ID: 76
Wed Mar 13 16:33:02 2024 : Debug: Waking up in 17.0 seconds.
Wed Mar 13 16:33:08 2024 : Debug: Suppressing duplicate proxied request (tcp) to home server 130.59.31.24 port 2083 proto TCP - ID: 76
Wed Mar 13 16:33:08 2024 : Debug: Waking up in 11.0 seconds.
Wed Mar 13 16:33:19 2024 : Debug: (0) No proxy response, giving up on request and marking it done
Wed Mar 13 16:33:19 2024 : Proxy: Marking home server 130.59.31.24 port 2083 as zombie (it has not responded in 20.000000 seconds).
Wed Mar 13 16:33:19 2024 : Debug: (1) proxy: Trying to allocate ID (0/2)
Wed Mar 13 16:33:19 2024 : Debug: (1) proxy: request is now in proxy hash
Wed Mar 13 16:33:19 2024 : Debug: (1) proxy: allocating destination 130.59.31.24 port 2083 - Id 25
Wed Mar 13 16:33:19 2024 : Debug: PING: Waiting 4 seconds for response to ping
Wed Mar 13 16:33:19 2024 : Debug: (1) Sent Status-Server Id 25 from 160.98.240.25:49795 to 130.59.31.24:2083 length 70
Wed Mar 13 16:33:19 2024 : Debug: (1) Message-Authenticator := 0x00
Wed Mar 13 16:33:19 2024 : Debug: (1) NAS-Identifier := "Status Check 0. Are you alive?"
Wed Mar 13 16:33:19 2024 : Debug: (0) (TLS) RADIUS/TLS - Handshake state [TWCH] - Client SSLv3/TLS write client hello (12)
Wed Mar 13 16:33:19 2024 : Debug: (0) (TLS) RADIUS/TLS - Client : Need to read more data: SSLv3/TLS write client hello
Wed Mar 13 16:33:19 2024 : Debug: (TLS) SSL_connect() returned WANT_READ
Wed Mar 13 16:33:19 2024 : Debug: (1) (TLS) Writing 70 bytes for later (total 265)
Wed Mar 13 16:33:19 2024 : Debug: PING: Next status packet in 30 seconds
Wed Mar 13 16:33:19 2024 : ERROR: (0) Failing proxied request for user "hefr", due to lack of any response from home server 130.59.31.24 port 2083
Wed Mar 13 16:33:19 2024 : Debug: Waking up in 0.3 seconds.
Wed Mar 13 16:33:19 2024 : Debug: Thread 2 got semaphore
Wed Mar 13 16:33:19 2024 : Debug: Thread 2 handling request 0, (1 handled so far)
Wed Mar 13 16:33:19 2024 : Debug: (0) Clearing existing &reply: attributes
Wed Mar 13 16:33:19 2024 : Debug: (0) Found Post-Proxy-Type Fail-Authentication
Wed Mar 13 16:33:19 2024 : Debug: (0) server eduroam {
Wed Mar 13 16:33:19 2024 : Debug: (0) Post-Proxy-Type sub-section not found. Ignoring.
Wed Mar 13 16:33:19 2024 : Debug: (0) # Executing group from file /srv/freeradius/etc/raddb/sites-enabled/eduroam
Wed Mar 13 16:33:19 2024 : Debug: (0) }
Wed Mar 13 16:33:19 2024 : Auth: (0) Login incorrect (Home Server failed to respond): [hefr@test.eduroam.ch] (from client loopback port 0 cli 02-00-00-00-00-01)
Wed Mar 13 16:33:19 2024 : Debug: (0) There was no response configured: rejecting request
Wed Mar 13 16:33:19 2024 : Debug: (0) Using Post-Auth-Type Reject
Wed Mar 13 16:33:19 2024 : Debug: (0) # Executing group from file /srv/freeradius/etc/raddb/sites-enabled/eduroam
Wed Mar 13 16:33:19 2024 : Debug: (0) Post-Auth-Type REJECT {
Wed Mar 13 16:33:19 2024 : Debug: (0) if ("%{Packet-Type}" == 'Status-Server'){
Wed Mar 13 16:33:19 2024 : Debug: %{Packet-Type}
Wed Mar 13 16:33:19 2024 : Debug: Parsed xlat tree:
Wed Mar 13 16:33:19 2024 : Debug: attribute --> Packet-Type
Wed Mar 13 16:33:19 2024 : Debug: (0) EXPAND %{Packet-Type}
Wed Mar 13 16:33:19 2024 : Debug: (0) --> Access-Request
Wed Mar 13 16:33:19 2024 : Debug: (0) if ("%{Packet-Type}" == 'Status-Server') -> FALSE
Wed Mar 13 16:33:19 2024 : Debug: (0) } # Post-Auth-Type REJECT = noop
Wed Mar 13 16:33:19 2024 : Debug: (0) Sent Access-Reject Id 0 from 127.0.0.1:1812 to 127.0.0.1:46698 length 20
Wed Mar 13 16:33:19 2024 : Debug: (0) Finished request
Wed Mar 13 16:33:19 2024 : Debug: Thread 2 waiting to be assigned a request
Wed Mar 13 16:33:19 2024 : Debug: Proxy SSL socket has data to read
Wed Mar 13 16:33:19 2024 : Debug: (0) (TLS) RADIUS/TLS - Handshake state [TWCH] - Client SSLv3/TLS write client hello (12)
Wed Mar 13 16:33:19 2024 : Debug: (0) (TLS) RADIUS/TLS - recv TLS 1.2 Handshake, ServerHello
Wed Mar 13 16:33:19 2024 : Debug: (0) (TLS) RADIUS/TLS - Handshake state [TRSH] - Client SSLv3/TLS read server hello (3)
Wed Mar 13 16:33:19 2024 : Debug: (0) (TLS) RADIUS/TLS - recv TLS 1.2 Handshake, Certificate
Wed Mar 13 16:33:19 2024 : Debug: (0) (TLS) RADIUS/TLS - Creating attributes from server certificate
Wed Mar 13 16:33:19 2024 : Debug: (0) TLS-Cert-Serial := "01"
Wed Mar 13 16:33:19 2024 : Debug: (0) TLS-Cert-Expiration := "301103101536Z"
Wed Mar 13 16:33:19 2024 : Debug: (0) TLS-Cert-Valid-Since := "101108101536Z"
Wed Mar 13 16:33:19 2024 : Debug: (0) TLS-Cert-Subject := "/DC=org/DC=edupki/CN=eduPKI CA G 01"
Wed Mar 13 16:33:19 2024 : Debug: (0) TLS-Cert-Issuer := "/DC=org/DC=edupki/CN=eduPKI CA G 01"
Wed Mar 13 16:33:19 2024 : Debug: (0) TLS-Cert-Common-Name := "eduPKI CA G 01"
Wed Mar 13 16:33:19 2024 : Debug: (0) (TLS) chain-depth : 1
Wed Mar 13 16:33:19 2024 : Debug: (0) (TLS) error : 0
Wed Mar 13 16:33:19 2024 : Debug: (0) (TLS) common name : eduPKI CA G 01
Wed Mar 13 16:33:19 2024 : Debug: (0) (TLS) subject : /DC=org/DC=edupki/CN=eduPKI CA G 01
Wed Mar 13 16:33:19 2024 : Debug: (0) (TLS) issuer : /DC=org/DC=edupki/CN=eduPKI CA G 01
Wed Mar 13 16:33:19 2024 : Debug: (0) (TLS) verify return : 1
Wed Mar 13 16:33:19 2024 : Debug: (0) (TLS) RADIUS/TLS - Creating attributes from client certificate
Wed Mar 13 16:33:19 2024 : Debug: (0) TLS-Client-Cert-Serial := "231a75d9361f9ea038f29422"
Wed Mar 13 16:33:19 2024 : Debug: (0) TLS-Client-Cert-Expiration := "250629083105Z"
Wed Mar 13 16:33:19 2024 : Debug: (0) TLS-Client-Cert-Valid-Since := "200630083105Z"
Wed Mar 13 16:33:19 2024 : Debug: (0) TLS-Client-Cert-Subject := "/DC=net/DC=geant/DC=eduroam/C=CH/O=SWITCH/CN=ftlr1.eduroam.ch"
Wed Mar 13 16:33:19 2024 : Debug: (0) TLS-Client-Cert-Issuer := "/DC=org/DC=edupki/CN=eduPKI CA G 01"
Wed Mar 13 16:33:19 2024 : Debug: (0) TLS-Client-Cert-Common-Name := "ftlr1.eduroam.ch"
Wed Mar 13 16:33:19 2024 : Debug: (0) TLS-Client-Cert-Subject-Alt-Name-Dns := "ftlr1.eduroam.ch"
Wed Mar 13 16:33:19 2024 : Debug: (0) TLS-Client-Cert-Subject-Alt-Name-Dns := "ozza.switch.ch"
Wed Mar 13 16:33:19 2024 : Debug: (0) TLS-Client-Cert-X509v3-Basic-Constraints += "CA:FALSE"
Wed Mar 13 16:33:19 2024 : Debug: (0) Skipping TLS-Client-Cert-X509v3-Key-Usage += 'Digital Signature, Key Encipherment'. Please check that both the attribute and value are defined in the dictionaries
Wed Mar 13 16:33:19 2024 : Debug: (0) TLS-Client-Cert-X509v3-Extended-Key-Usage += "TLS Web Client Authentication, TLS Web Server Authentication"
Wed Mar 13 16:33:19 2024 : Debug: (0) TLS-Client-Cert-X509v3-Subject-Key-Identifier += "CE:A9:9C:51:B2:A5:FB:7E:5D:1D:9F:B4:FB:0F:A1:33:13:7A:D0:BA"
Wed Mar 13 16:33:19 2024 : Debug: (0) TLS-Client-Cert-X509v3-Authority-Key-Identifier += "D2:F2:23:BD:4A:A1:7F:CF:A0:58:84:EB:FC:E6:5B:08:B3:CD:B4:E4"
Wed Mar 13 16:33:19 2024 : Debug: (0) Skipping TLS-Client-Cert-X509v3-Subject-Alternative-Name += 'DNS:ftlr1.eduroam.ch, DNS:ozza.switch.ch'. Please check that both the attribute and value are defined in the dictionaries
Wed Mar 13 16:33:19 2024 : Debug: (0) TLS-Client-Cert-X509v3-Certificate-Policies += "Policy: 1.3.6.1.4.1.27262.1.13.1.1\nPolicy: 1.3.6.1.4.1.27262.1.13.1.1.1.4\nPolicy: 1.3.6.1.4.1.25178.3.1.1\nPolicy: 1.3.6.1.4.1.25178.3.1.2\nPolicy: 1.3.6.1.4.1.27262.1.13.2.1.1.8"
Wed Mar 13 16:33:19 2024 : Debug: (0) Skipping TLS-Client-Cert-X509v3-CRL-Distribution-Points += 'Full Name: URI:http://cdp.edupki.org/edupki-ca/pub/crl/cacrl.crl'. Please check that both the attribute and value are defined in the dictionaries
Wed Mar 13 16:33:19 2024 : Debug: (0) Skipping TLS-Client-Cert-Authority-Information-Access += 'OCSP - URI:http://ocsp.edupki.org/OCSP-Server/OCSP CA Issuers - URI:http://cdp.edupki.org/edupki-ca/pub/cacert/cacert.crt'. Please check that both the attribute and value are defined in the dictionaries
Wed Mar 13 16:33:19 2024 : Debug: (0) TLS-Client-Cert-X509v3-Extended-Key-Usage-OID += "1.3.6.1.5.5.7.3.2"
Wed Mar 13 16:33:19 2024 : Debug: (0) TLS-Client-Cert-X509v3-Extended-Key-Usage-OID += "1.3.6.1.5.5.7.3.1"
Wed Mar 13 16:33:19 2024 : Warning: Certificate chain - 1 intermediate CA cert(s) untrusted
Wed Mar 13 16:33:19 2024 : Warning: To forbid these certificates see 'reject_unknown_intermediate_ca'
Wed Mar 13 16:33:19 2024 : Warning: (TLS) untrusted certificate with depth [1] subject name /DC=org/DC=edupki/CN=eduPKI CA G 01
Wed Mar 13 16:33:19 2024 : Warning: (TLS) untrusted certificate with depth [0] subject name /DC=net/DC=geant/DC=eduroam/C=CH/O=SWITCH/CN=ftlr1.eduroam.ch
Wed Mar 13 16:33:19 2024 : Debug: (0) (TLS) chain-depth : 0
Wed Mar 13 16:33:19 2024 : Debug: (0) (TLS) error : 0
Wed Mar 13 16:33:19 2024 : Debug: (0) (TLS) common name : ftlr1.eduroam.ch
Wed Mar 13 16:33:19 2024 : Debug: (0) (TLS) subject : /DC=net/DC=geant/DC=eduroam/C=CH/O=SWITCH/CN=ftlr1.eduroam.ch
Wed Mar 13 16:33:19 2024 : Debug: (0) (TLS) issuer : /DC=org/DC=edupki/CN=eduPKI CA G 01
Wed Mar 13 16:33:19 2024 : Debug: (0) (TLS) verify return : 1
Wed Mar 13 16:33:19 2024 : Debug: (0) (TLS) RADIUS/TLS - Handshake state [TRSC] - Client SSLv3/TLS read server certificate (4)
Wed Mar 13 16:33:19 2024 : Debug: (0) (TLS) RADIUS/TLS - recv TLS 1.2 Handshake, ServerKeyExchange
Wed Mar 13 16:33:19 2024 : Debug: (0) (TLS) RADIUS/TLS - Client : Need to read more data: SSLv3/TLS read server key exchange
Wed Mar 13 16:33:19 2024 : Debug: (TLS) SSL_connect() returned WANT_READ
Wed Mar 13 16:33:19 2024 : Debug: Waking up in 0.3 seconds.
Wed Mar 13 16:33:19 2024 : Debug: Proxy SSL socket has data to read
Wed Mar 13 16:33:19 2024 : Debug: (0) (TLS) RADIUS/TLS - Handshake state [TRSKE] - Client SSLv3/TLS read server key exchange (6)
Wed Mar 13 16:33:19 2024 : Debug: (0) (TLS) RADIUS/TLS - recv TLS 1.2 Handshake, CertificateRequest
Wed Mar 13 16:33:19 2024 : Debug: (0) (TLS) RADIUS/TLS - Handshake state [TRCR] - Client SSLv3/TLS read server certificate request (7)
Wed Mar 13 16:33:19 2024 : Debug: (0) (TLS) RADIUS/TLS - recv TLS 1.2 Handshake, ServerHelloDone
Wed Mar 13 16:33:19 2024 : Debug: (0) (TLS) RADIUS/TLS - Handshake state [TRSD] - Client SSLv3/TLS read server done (8)
Wed Mar 13 16:33:19 2024 : Debug: (0) (TLS) RADIUS/TLS - send TLS 1.2 Handshake, Certificate
Wed Mar 13 16:33:19 2024 : Debug: (0) (TLS) RADIUS/TLS - Handshake state [TWCC] - Client SSLv3/TLS write client certificate (13)
Wed Mar 13 16:33:19 2024 : Debug: (0) (TLS) RADIUS/TLS - send TLS 1.2 Handshake, ClientKeyExchange
Wed Mar 13 16:33:19 2024 : Debug: (0) (TLS) RADIUS/TLS - Handshake state [TWCKE] - Client SSLv3/TLS write client key exchange (14)
Wed Mar 13 16:33:19 2024 : Debug: (0) (TLS) RADIUS/TLS - send TLS 1.2 Handshake, CertificateVerify
Wed Mar 13 16:33:19 2024 : Debug: (0) (TLS) RADIUS/TLS - Handshake state [TWCV] - Client SSLv3/TLS write certificate verify (15)
Wed Mar 13 16:33:19 2024 : Debug: (0) (TLS) RADIUS/TLS - send TLS 1.2 ChangeCipherSpec
Wed Mar 13 16:33:19 2024 : Debug: (0) (TLS) RADIUS/TLS - Handshake state [TWCCS] - Client SSLv3/TLS write change cipher spec (16)
Wed Mar 13 16:33:19 2024 : Debug: (0) (TLS) RADIUS/TLS - send TLS 1.2 Handshake, Finished
Wed Mar 13 16:33:19 2024 : Debug: (0) (TLS) RADIUS/TLS - Handshake state [TWFIN] - Client SSLv3/TLS write finished (18)
Wed Mar 13 16:33:19 2024 : Debug: (0) (TLS) RADIUS/TLS - Client : Need to read more data: SSLv3/TLS write finished
Wed Mar 13 16:33:19 2024 : Debug: (TLS) SSL_connect() returned WANT_READ
Wed Mar 13 16:33:19 2024 : Debug: Waking up in 0.3 seconds.
Wed Mar 13 16:33:19 2024 : Debug: Proxy SSL socket has data to read
Wed Mar 13 16:33:19 2024 : Debug: (0) (TLS) RADIUS/TLS - Handshake state [TWFIN] - Client SSLv3/TLS write finished (18)
Wed Mar 13 16:33:19 2024 : Debug: (0) (TLS) RADIUS/TLS - Handshake state [TRCCS] - Client SSLv3/TLS read change cipher spec (10)
Wed Mar 13 16:33:19 2024 : Debug: (0) (TLS) RADIUS/TLS - recv TLS 1.2 Handshake, Finished
Wed Mar 13 16:33:19 2024 : Debug: (0) (TLS) RADIUS/TLS - Handshake state [TRFIN] - Client SSLv3/TLS read finished (11)
Wed Mar 13 16:33:19 2024 : Debug: (0) (TLS) RADIUS/TLS - Handshake state [SSLOK] - SSL negotiation finished successfully (1)
Wed Mar 13 16:33:19 2024 : Debug: (TLS) proxy writing 265 to socket
Wed Mar 13 16:33:19 2024 : Debug: (TLS) OpenSSL returned WANT_READ
Wed Mar 13 16:33:19 2024 : Debug: Waking up in 0.3 seconds.
Wed Mar 13 16:33:19 2024 : Debug: Proxy SSL socket has data to read
Wed Mar 13 16:33:19 2024 : Debug: Proxy received header saying we have a packet of 20 bytes
Wed Mar 13 16:33:19 2024 : Proxy: (1) Marking home server 130.59.31.24 port 2083 alive
Wed Mar 13 16:33:19 2024 : Proxy: (1) Received response to status check 1 ID 25 (1 in current sequence)
Wed Mar 13 16:33:19 2024 : Error: ASSERT FAILED src/main/process.c[3894]: !request->in_proxy_hash
CAUGHT SIGNAL: Aborted
Backtrace of last 12 frames:
/srv/freeradius/lib/libfreeradius-radius.so(fr_fault+0x139)[0x7f809543a3f8]
/srv/freeradius/lib/libfreeradius-server.so(rad_assert_fail+0x4d)[0x7f80954a63f0]
sbin/radiusd(+0x544c8)[0x55f4d18ea4c8]
sbin/radiusd(request_proxy_reply+0x71c)[0x55f4d18e8122]
sbin/radiusd(proxy_tls_recv+0x3b6)[0x55f4d190b341]
sbin/radiusd(+0x58782)[0x55f4d18ee782]
/srv/freeradius/lib/libfreeradius-radius.so(fr_event_loop+0x60d)[0x7f8095466313]
sbin/radiusd(radius_event_process+0x2a)[0x55f4d18f0a3d]
sbin/radiusd(main+0xd18)[0x55f4d18d6f14]
/lib/x86_64-linux-gnu/libc.so.6(+0x29d90)[0x7f8094cf4d90]
/lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0x80)[0x7f8094cf4e40]
sbin/radiusd(_start+0x25)[0x55f4d18adda5]
Calling: gdb -silent -x /srv/freeradius/etc/raddb/panic.gdb sbin/radiusd 3862912 2>&1 | tee /srv/freeradius/var/log/radius/gdb-radiusd-3862912.log
Temporarily setting PR_DUMPABLE to 1
Resetting PR_DUMPABLE to 0
Panic action exited with 0
_EXIT(0) CALLED src/lib/debug.c[811]
You can run in threaded mode with radiusd -sf -xxx -l stdout
.
I'll see if I can reproduce this here, but it might take a bit. I'm busy for the next while.
You can run in threaded mode with
radiusd -sf -xxx -l stdout
.
Yeah that's what I did. btw is status-server supported/wanted with radsec or shall I try to turn it off and see if it happens again ?
If you just use tcp or udp, it should work. So yes, please try without radsec.
Well it was working fine with radius/udp before, but we're in the process to move to radsec with our ftlr and that's when this issue arose. Still I'll try a few more things, and also I'll double check with the NREN if everything is correctly working on their side.
Fixed
What type of defect/bug is this?
Crash or memory corruption (segv, abort, etc...)
How can the issue be reproduced?
This was a working configuration of a test IDP eduroam server to test radsec communication with the FTLR servers.
Pulled and compiled a fresh code this morning (
commit cd6534934d1056bac4ad1c01baf99e93fb4d4ed0 (HEAD -> v3.2.x, origin/v3.2.x)
)service started with
sbin/radiusd -fxx -l stdout
sites-available/eduroam-tls as follow :
Log output from the FreeRADIUS daemon
Relevant log output from client utilities
simple eapol_test from local server
Backtrace from LLDB or GDB