Accounting server terminates (when home-server is unavailable for a while)
Peter Balsianok
balsianok.peter at gmail.com
Tue Nov 14 13:56:02 CET 2017
Here is test scenario for this issue (accounting port is 10813).
[radiusd at tdrad1 acct-test]$ ./run-debug.sh
Tue Nov 14 13:46:16 2017 : Debug: Server was built with:
Tue Nov 14 13:46:16 2017 : Debug: accounting : yes
Tue Nov 14 13:46:16 2017 : Debug: authentication : yes
Tue Nov 14 13:46:16 2017 : Debug: ascend-binary-attributes : yes
Tue Nov 14 13:46:16 2017 : Debug: coa : yes
Tue Nov 14 13:46:16 2017 : Debug: control-socket : yes
Tue Nov 14 13:46:16 2017 : Debug: detail : yes
Tue Nov 14 13:46:16 2017 : Debug: dhcp : yes
Tue Nov 14 13:46:16 2017 : Debug: dynamic-clients : yes
Tue Nov 14 13:46:16 2017 : Debug: osfc2 : no
Tue Nov 14 13:46:16 2017 : Debug: proxy : yes
Tue Nov 14 13:46:16 2017 : Debug: regex-pcre : no
Tue Nov 14 13:46:16 2017 : Debug: regex-posix : yes
Tue Nov 14 13:46:16 2017 : Debug: regex-posix-extended : yes
Tue Nov 14 13:46:16 2017 : Debug: session-management : yes
Tue Nov 14 13:46:16 2017 : Debug: stats : yes
Tue Nov 14 13:46:16 2017 : Debug: tcp : yes
Tue Nov 14 13:46:16 2017 : Debug: threads : yes
Tue Nov 14 13:46:16 2017 : Debug: tls : yes
Tue Nov 14 13:46:16 2017 : Debug: unlang : yes
Tue Nov 14 13:46:16 2017 : Debug: vmps : yes
Tue Nov 14 13:46:16 2017 : Debug: developer : yes
Tue Nov 14 13:46:16 2017 : Debug: Server core libs:
Tue Nov 14 13:46:16 2017 : Debug: freeradius-server : 3.0.16
Tue Nov 14 13:46:16 2017 : Debug: talloc : 2.0.*
Tue Nov 14 13:46:16 2017 : Debug: ssl : 0.9.8b
release
Tue Nov 14 13:46:16 2017 : Debug: Endianness:
Tue Nov 14 13:46:16 2017 : Debug: little
Tue Nov 14 13:46:16 2017 : Debug: Compilation flags:
Tue Nov 14 13:46:16 2017 : Debug: cppflags :
Tue Nov 14 13:46:16 2017 : Debug: cflags : -I. -Isrc -include
src/freeradius-devel/autoconf.h -include src/freeradius-devel/build.h
-include src/freeradius-devel/features.h -include
src/freeradius-devel/radpaths.h -fno-strict-aliasing -g3 -Wall -std=c99
-D_GNU_SOURCE -D_REENTRANT -D_POSIX_PTHREAD_SEMANTICS -DOPENSSL_NO_KRB5
-Wshadow -Wpointer-arith -Wcast-qual -Wcast-align -Wwrite-strings
-Wstrict-prototypes -Wmissing-prototypes -Wmissing-declarations
-Wnested-externs -W -Wredundant-decls -Wundef -Wformat-y2k
-Wno-format-extra-args -Wno-format-zero-length -Wno-cast-align
-Wformat-nonliteral -Wformat-security -Wformat=2 -DWITH_VERIFY_PTR=1
-DIS_MODULE=1
Tue Nov 14 13:46:16 2017 : Debug: ldflags :
Tue Nov 14 13:46:16 2017 : Debug: libs : -lcrypto -lssl -ltalloc
-lnsl -lresolv -ldl -lpthread
Tue Nov 14 13:46:16 2017 : Debug:
Tue Nov 14 13:46:16 2017 : Info: FreeRADIUS Version 3.0.16
Tue Nov 14 13:46:16 2017 : Info: Copyright (C) 1999-2017 The FreeRADIUS
server project and contributors
Tue Nov 14 13:46:16 2017 : Info: There is NO warranty; not even for
MERCHANTABILITY or FITNESS FOR A
Tue Nov 14 13:46:16 2017 : Info: PARTICULAR PURPOSE
Tue Nov 14 13:46:16 2017 : Info: You may redistribute copies of FreeRADIUS
under the terms of the
Tue Nov 14 13:46:16 2017 : Info: GNU General Public License
Tue Nov 14 13:46:16 2017 : Info: For more information about these matters,
see the file named COPYRIGHT
Tue Nov 14 13:46:16 2017 : Info: Starting - reading configuration files ...
Tue Nov 14 13:46:16 2017 : Debug: including dictionary file
/app/radius/freeradius-3.0.15/share/freeradius/dictionary
Tue Nov 14 13:46:16 2017 : Debug: including dictionary file
/app/radius/freeradius-3.0.15/share/freeradius/dictionary.dhcp
Tue Nov 14 13:46:16 2017 : Debug: including dictionary file
/app/radius/freeradius-3.0.15/share/freeradius/dictionary.vqp
Tue Nov 14 13:46:16 2017 : Debug: including dictionary file
/app/radius/conf/acct-test/dictionary
Tue Nov 14 13:46:16 2017 : Debug: including configuration file
/app/radius/conf/acct-test/radiusd.conf
Tue Nov 14 13:46:16 2017 : Debug: including configuration file
/app/radius/conf/acct-test/templates.conf
Tue Nov 14 13:46:16 2017 : Debug: including configuration file
/app/radius/conf/acct-test/proxy.conf
Tue Nov 14 13:46:16 2017 : Debug: including configuration file
/app/radius/conf/acct-test/clients.conf
Tue Nov 14 13:46:16 2017 : Debug: including files in directory
/app/radius/conf/acct-test/mods-enabled/
Tue Nov 14 13:46:16 2017 : Debug: including configuration file
/app/radius/conf/acct-test/mods-enabled/unpack
Tue Nov 14 13:46:16 2017 : Debug: including configuration file
/app/radius/conf/acct-test/mods-enabled/files
Tue Nov 14 13:46:16 2017 : Debug: including configuration file
/app/radius/conf/acct-test/mods-enabled/expr
Tue Nov 14 13:46:16 2017 : Debug: including configuration file
/app/radius/conf/acct-test/mods-enabled/preprocess
Tue Nov 14 13:46:16 2017 : Debug: including configuration file
/app/radius/conf/acct-test/mods-enabled/attr_filter
Tue Nov 14 13:46:16 2017 : Debug: including configuration file
/app/radius/conf/acct-test/mods-enabled/always
Tue Nov 14 13:46:16 2017 : Debug: including configuration file
/app/radius/conf/acct-test/mods-enabled/linelog
Tue Nov 14 13:46:16 2017 : Debug: including configuration file
/app/radius/conf/acct-test/mods-enabled/perl
Tue Nov 14 13:46:16 2017 : Debug: including configuration file
/app/radius/conf/acct-test/mods-enabled/linelog-special
Tue Nov 14 13:46:16 2017 : Debug: including configuration file
/app/radius/conf/acct-test/mods-enabled/realm
Tue Nov 14 13:46:16 2017 : Debug: including files in directory
/app/radius/conf/acct-test/policy-enabled/
Tue Nov 14 13:46:16 2017 : Debug: including configuration file
/app/radius/conf/acct-test/policy-enabled/accounting
Tue Nov 14 13:46:16 2017 : Debug: including configuration file
/app/radius/conf/acct-test/policy-enabled/huntgroup
Tue Nov 14 13:46:16 2017 : Debug: including configuration file
/app/radius/conf/acct-test/policy-enabled/username
Tue Nov 14 13:46:16 2017 : Debug: including configuration file
/app/radius/conf/acct-test/policy-enabled/nas
Tue Nov 14 13:46:16 2017 : Debug: including files in directory
/app/radius/conf/acct-test/sites-enabled/
Tue Nov 14 13:46:16 2017 : Debug: including configuration file
/app/radius/conf/acct-test/sites-enabled/control-socket
Tue Nov 14 13:46:16 2017 : Debug: including configuration file
/app/radius/conf/acct-test/sites-enabled/default
Tue Nov 14 13:46:16 2017 : Debug: main {
Tue Nov 14 13:46:16 2017 : Debug: name = "acct-test"
Tue Nov 14 13:46:16 2017 : Debug: prefix = "/app/radius/freeradius-v3"
Tue Nov 14 13:46:16 2017 : Debug: localstatedir =
"/app_log/radius/acct-test/"
Tue Nov 14 13:46:16 2017 : Debug: sbindir =
"/app/radius/freeradius-v3/sbin"
Tue Nov 14 13:46:16 2017 : Debug: logdir = "/app_log/radius/acct-test/"
Tue Nov 14 13:46:16 2017 : Debug: run_dir = "/app_log/radius/acct-test/"
Tue Nov 14 13:46:16 2017 : Debug: libdir =
"/app/radius/freeradius-v3/lib"
Tue Nov 14 13:46:16 2017 : Debug: radacctdir =
"/app_log/radius/acct-test//radacct"
Tue Nov 14 13:46:16 2017 : Debug: panic_action = "gdb -silent -x
/app/radius/freeradius-v3/../raddb/acct-test/panic.gdb %e %p 2>&1 | tee
/app_log/radius/acct-test//gdb-acct-test-%p.log"
Tue Nov 14 13:46:16 2017 : Debug: hostname_lookups = no
Tue Nov 14 13:46:16 2017 : Debug: max_request_time = 5
Tue Nov 14 13:46:16 2017 : Debug: cleanup_delay = 2
Tue Nov 14 13:46:16 2017 : Debug: max_requests = 25600
Tue Nov 14 13:46:16 2017 : Debug: pidfile =
"/app_log/radius/acct-test//radius.pid"
Tue Nov 14 13:46:16 2017 : Debug: checkrad =
"/app/radius/freeradius-v3/sbin/checkrad"
Tue Nov 14 13:46:16 2017 : Debug: debug_level = 0
Tue Nov 14 13:46:16 2017 : Debug: proxy_requests = yes
Tue Nov 14 13:46:16 2017 : Debug: log {
Tue Nov 14 13:46:16 2017 : Debug: stripped_names = no
Tue Nov 14 13:46:16 2017 : Debug: auth = no
Tue Nov 14 13:46:16 2017 : Debug: auth_badpass = no
Tue Nov 14 13:46:16 2017 : Debug: auth_goodpass = no
Tue Nov 14 13:46:16 2017 : Debug: colourise = yes
Tue Nov 14 13:46:16 2017 : Debug: msg_denied = "You are already logged
in - access denied"
Tue Nov 14 13:46:16 2017 : Debug: }
Tue Nov 14 13:46:16 2017 : Debug: resources {
Tue Nov 14 13:46:16 2017 : Debug: }
Tue Nov 14 13:46:16 2017 : Debug: security {
Tue Nov 14 13:46:16 2017 : Debug: max_attributes = 200
Tue Nov 14 13:46:16 2017 : Debug: reject_delay = 0.000000
Tue Nov 14 13:46:16 2017 : Debug: status_server = yes
Tue Nov 14 13:46:16 2017 : Debug: }
Tue Nov 14 13:46:16 2017 : Debug: }
Tue Nov 14 13:46:16 2017 : Debug: radiusd: #### Loading Realms and Home
Servers ####
...
Tue Nov 14 13:46:16 2017 : Debug: home_server sa_server_prod {
Tue Nov 14 13:46:16 2017 : Debug: ipaddr = 80.81.224.2
Tue Nov 14 13:46:16 2017 : Debug: port = 1813
Tue Nov 14 13:46:16 2017 : Debug: type = "acct"
Tue Nov 14 13:46:16 2017 : Debug: secret = "SA4682"
Tue Nov 14 13:46:16 2017 : Debug: response_window = 30.000000
Tue Nov 14 13:46:16 2017 : Debug: response_timeouts = 1
Tue Nov 14 13:46:16 2017 : Debug: max_outstanding = 65536
Tue Nov 14 13:46:16 2017 : Debug: zombie_period = 40
Tue Nov 14 13:46:16 2017 : Debug: status_check = "none"
Tue Nov 14 13:46:16 2017 : Debug: ping_interval = 30
Tue Nov 14 13:46:16 2017 : Debug: check_timeout = 4
Tue Nov 14 13:46:16 2017 : Debug: num_answers_to_alive = 3
Tue Nov 14 13:46:16 2017 : Debug: revive_interval = 300
Tue Nov 14 13:46:16 2017 : Debug: limit {
Tue Nov 14 13:46:16 2017 : Debug: max_connections = 16
Tue Nov 14 13:46:16 2017 : Debug: max_requests = 0
Tue Nov 14 13:46:16 2017 : Debug: lifetime = 0
Tue Nov 14 13:46:16 2017 : Debug: idle_timeout = 0
Tue Nov 14 13:46:16 2017 : Debug: }
Tue Nov 14 13:46:16 2017 : Debug: coa {
Tue Nov 14 13:46:16 2017 : Debug: irt = 2
Tue Nov 14 13:46:16 2017 : Debug: mrt = 16
Tue Nov 14 13:46:16 2017 : Debug: mrc = 5
Tue Nov 14 13:46:16 2017 : Debug: mrd = 30
Tue Nov 14 13:46:16 2017 : Debug: }
Tue Nov 14 13:46:16 2017 : Debug: }
...
Tue Nov 14 13:46:16 2017 : Debug: realm sasro.sk {
Tue Nov 14 13:46:16 2017 : Debug: acct_pool = prod_pool_sa
Tue Nov 14 13:46:16 2017 : Debug: nostrip
Tue Nov 14 13:46:16 2017 : Debug: }
...
Tue Nov 14 13:46:16 2017 : Debug: realm LOCAL {
Tue Nov 14 13:46:16 2017 : Debug: authhost = LOCAL
Tue Nov 14 13:46:16 2017 : Debug: accthost = LOCAL
Tue Nov 14 13:46:16 2017 : Debug: }
Tue Nov 14 13:46:16 2017 : Debug: realm NULL {
Tue Nov 14 13:46:16 2017 : Debug: authhost = LOCAL
Tue Nov 14 13:46:16 2017 : Debug: accthost = LOCAL
Tue Nov 14 13:46:16 2017 : Debug: }
Tue Nov 14 13:46:16 2017 : Debug: realm DEFAULT {
Tue Nov 14 13:46:16 2017 : Debug: authhost = LOCAL
Tue Nov 14 13:46:16 2017 : Debug: accthost = LOCAL
Tue Nov 14 13:46:16 2017 : Debug: }
Tue Nov 14 13:46:16 2017 : Debug: radiusd: #### Loading Clients ####
...
...
Tue Nov 14 13:46:16 2017 : Debug: Listening on command file
/app_log/radius/acct-test/control.socket
Tue Nov 14 13:46:16 2017 : Debug: Listening on acct address * port 10813
bound to server default
Tue Nov 14 13:46:16 2017 : Info: Ready to process requests
Socket: 9
Proto: 0
Src IP: 127.0.0.1
port: 44671
Dst IP: 127.0.0.1
port: 10813
Code: (4) Accounting-Request
Id: 184
Length: 157
Vector: be262e53547ab77fbabb17576757ce61
Data: 28 06 00 00 00 01
2c 0a 30 30 37 39 44 35 31 36
01 0e 67 32 35 40 73 61 73 72 6f 2e 73 6b
04 06 ac 1f 08 4f
57 11 55 6e 69 71 2d 53 65 73 73 2d 49 44 33 35 38
3d 06 00 00 00 03
4d 0d 36 34 30 30 30 2f 35 37 36 30 30
1e 09 73 61 2e 63 6f 72 70
1f 0e 34 32 31 39 30 35 35 31 30 35 37 32
06 06 00 00 00 02
07 06 00 00 00 01
29 06 00 00 00 00
34 06 00 00 00 00
2a 06 00 00 00 00
35 06 00 00 00 00
2b 06 00 00 00 00
Tue Nov 14 13:46:27 2017 : Debug: (0) Received Accounting-Request Id 184
from 127.0.0.1:44671 to 127.0.0.1:10813 length 157
Tue Nov 14 13:46:27 2017 : Debug: (0) Acct-Status-Type = Start
Tue Nov 14 13:46:27 2017 : Debug: (0) Acct-Session-Id = "0079D516"
Tue Nov 14 13:46:27 2017 : Debug: (0) User-Name = "g25 at sasro.sk"
Tue Nov 14 13:46:27 2017 : Debug: (0) NAS-IP-Address = 172.31.8.79
Tue Nov 14 13:46:27 2017 : Debug: (0) NAS-Port-Id = "Uniq-Sess-ID358"
Tue Nov 14 13:46:27 2017 : Debug: (0) NAS-Port-Type = ISDN-V120
Tue Nov 14 13:46:27 2017 : Debug: (0) Connect-Info = "64000/57600"
Tue Nov 14 13:46:27 2017 : Debug: (0) Called-Station-Id = "sa.corp"
Tue Nov 14 13:46:27 2017 : Debug: (0) Calling-Station-Id = "421905510572"
Tue Nov 14 13:46:27 2017 : Debug: (0) Service-Type = Framed-User
Tue Nov 14 13:46:27 2017 : Debug: (0) Framed-Protocol = PPP
Tue Nov 14 13:46:27 2017 : Debug: (0) Acct-Delay-Time = 0
Tue Nov 14 13:46:27 2017 : Debug: (0) Acct-Input-Gigawords = 0
Tue Nov 14 13:46:27 2017 : Debug: (0) Acct-Input-Octets = 0
Tue Nov 14 13:46:27 2017 : Debug: (0) Acct-Output-Gigawords = 0
Tue Nov 14 13:46:27 2017 : Debug: (0) Acct-Output-Octets = 0
Tue Nov 14 13:46:27 2017 : Debug: (0) # Executing section preacct from file
/app/radius/conf/acct-test/sites-enabled/default
Tue Nov 14 13:46:27 2017 : Debug: (0) preacct {
Tue Nov 14 13:46:27 2017 : Debug: (0) modsingle[preacct]: calling
preprocess (rlm_preprocess)
Tue Nov 14 13:46:27 2017 : Debug: (0) modsingle[preacct]: returned from
preprocess (rlm_preprocess)
Tue Nov 14 13:46:27 2017 : Debug: (0) [preprocess] = ok
Tue Nov 14 13:46:27 2017 : Debug: (0) if ( ! &NAS-IP-Address ) {
Tue Nov 14 13:46:27 2017 : Debug: (0) if ( ! &NAS-IP-Address ) -> FALSE
Tue Nov 14 13:46:27 2017 : Debug: (0) else {
Tue Nov 14 13:46:27 2017 : Debug: (0) policy huntgroup {
Tue Nov 14 13:46:27 2017 : Debug: (0) switch &NAS-IP-Address {
Tue Nov 14 13:46:27 2017 : Debug: (0) case 172.31.8.79 {
Tue Nov 14 13:46:27 2017 : Debug: (0) update request {
Tue Nov 14 13:46:27 2017 : Debug: (0) &Huntgroup-Name :=
'IPSEC'
Tue Nov 14 13:46:27 2017 : Debug: (0) } # update request = noop
Tue Nov 14 13:46:27 2017 : Debug: (0) } # case 172.31.8.79 = noop
Tue Nov 14 13:46:27 2017 : Debug: (0) } # switch &NAS-IP-Address =
noop
Tue Nov 14 13:46:27 2017 : Debug: (0) } # policy huntgroup = noop
Tue Nov 14 13:46:27 2017 : Debug: (0) } # else = noop
Tue Nov 14 13:46:27 2017 : Debug: (0) policy username {
Tue Nov 14 13:46:27 2017 : Debug: (0) if (!&User-Name || &User-Name
== '') {
Tue Nov 14 13:46:27 2017 : Debug: (0) if (!&User-Name || &User-Name
== '') -> FALSE
Tue Nov 14 13:46:27 2017 : Debug: (0) elsif (&User-Name =~
/^[0-9]+$/) {
Tue Nov 14 13:46:27 2017 : Debug: No matches
Tue Nov 14 13:46:27 2017 : Debug: (0) elsif (&User-Name =~
/^[0-9]+$/) -> FALSE
Tue Nov 14 13:46:27 2017 : Debug: (0) } # policy username = ok
Tue Nov 14 13:46:27 2017 : Debug: (0) policy acct_counters64.preacct {
Tue Nov 14 13:46:27 2017 : Debug: (0) update request {
Tue Nov 14 13:46:27 2017 : Debug: (0) &Acct-Input-Gigawords --> 0
Tue Nov 14 13:46:27 2017 : Debug: (0) &Acct-Input-Octets --> 0
Tue Nov 14 13:46:27 2017 : Debug: (0) EXPAND
%{expr:(&Acct-Input-Gigawords << 32) | &Acct-Input-Octets}
Tue Nov 14 13:46:27 2017 : Debug: (0) --> 0
Tue Nov 14 13:46:27 2017 : Debug: (0) &Acct-Input-Octets64 = 0
Tue Nov 14 13:46:27 2017 : Debug: (0) &Acct-Output-Gigawords --> 0
Tue Nov 14 13:46:27 2017 : Debug: (0) &Acct-Output-Octets --> 0
Tue Nov 14 13:46:27 2017 : Debug: (0) EXPAND
%{expr:(&Acct-Output-Gigawords << 32) | &Acct-Output-Octets}
Tue Nov 14 13:46:27 2017 : Debug: (0) --> 0
Tue Nov 14 13:46:27 2017 : Debug: (0) &Acct-Output-Octets64 = 0
Tue Nov 14 13:46:27 2017 : Debug: (0) } # update request = noop
Tue Nov 14 13:46:27 2017 : Debug: (0) } # policy
acct_counters64.preacct = noop
Tue Nov 14 13:46:27 2017 : Debug: (0) if (&Class) {
Tue Nov 14 13:46:27 2017 : Debug: (0) if (&Class) -> FALSE
Tue Nov 14 13:46:27 2017 : Debug: (0) policy acct_unique {
Tue Nov 14 13:46:27 2017 : Debug: (0) if ("%{string:Class}" =~
/ai:([0-9a-f]{32})/i) {
Tue Nov 14 13:46:27 2017 : Debug: (0) EXPAND TMPL XLAT STRUCT
Tue Nov 14 13:46:27 2017 : Debug: (0) EXPAND %{string:Class}
Tue Nov 14 13:46:27 2017 : Debug: (0) -->
Tue Nov 14 13:46:27 2017 : Debug: No matches
Tue Nov 14 13:46:27 2017 : Debug: (0) if ("%{string:Class}" =~
/ai:([0-9a-f]{32})/i) -> FALSE
Tue Nov 14 13:46:27 2017 : Debug: (0) else {
Tue Nov 14 13:46:27 2017 : Debug: (0) update request {
Tue Nov 14 13:46:27 2017 : Debug: (0) EXPAND
%{md5:%{User-Name},%{Acct-Session-ID},%{%{NAS-IPv6-Address}:-%{NAS-IP-Address}},%{NAS-Identifier},%{NAS-Port-ID},%{NAS-Port}}
Tue Nov 14 13:46:27 2017 : Debug: (0) -->
70897db75add0d0e73023ed66148c1dd
Tue Nov 14 13:46:27 2017 : Debug: (0) &Acct-Unique-Session-Id :=
70897db75add0d0e73023ed66148c1dd
Tue Nov 14 13:46:27 2017 : Debug: (0) } # update request = noop
Tue Nov 14 13:46:27 2017 : Debug: (0) } # else = noop
Tue Nov 14 13:46:27 2017 : Debug: (0) } # policy acct_unique = noop
Tue Nov 14 13:46:27 2017 : Debug: (0) modsingle[preacct]: calling
suffix (rlm_realm)
Tue Nov 14 13:46:27 2017 : Debug: (0) suffix: Checking for suffix after "@"
Tue Nov 14 13:46:27 2017 : Debug: (0) suffix: Looking up realm "sasro.sk"
for User-Name = "g25 at sasro.sk"
Tue Nov 14 13:46:27 2017 : Debug: (0) suffix: Found realm "sasro.sk"
Tue Nov 14 13:46:27 2017 : Debug: (0) suffix: Adding Realm = "sasro.sk"
Tue Nov 14 13:46:27 2017 : Debug: (0) suffix: Proxying request from user
g25 at sasro.sk to realm sasro.sk
Tue Nov 14 13:46:27 2017 : Debug: (0) suffix: Preparing to proxy accounting
request to realm "sasro.sk"
Tue Nov 14 13:46:27 2017 : Debug: (0) modsingle[preacct]: returned from
suffix (rlm_realm)
Tue Nov 14 13:46:27 2017 : Debug: (0) [suffix] = updated
Tue Nov 14 13:46:27 2017 : Debug: (0) } # preacct = updated
Tue Nov 14 13:46:27 2017 : Debug: (0) # Executing section accounting from
file /app/radius/conf/acct-test/sites-enabled/default
Tue Nov 14 13:46:27 2017 : Debug: (0) accounting {
Tue Nov 14 13:46:27 2017 : Debug: (0) if (&control:Proxy-To-Realm ) {
Tue Nov 14 13:46:27 2017 : Debug: (0) if (&control:Proxy-To-Realm ) ->
TRUE
Tue Nov 14 13:46:27 2017 : Debug: (0) if (&control:Proxy-To-Realm ) {
Tue Nov 14 13:46:27 2017 : Debug: (0) modsingle[accounting]: calling
ok (rlm_always)
Tue Nov 14 13:46:27 2017 : Debug: (0) modsingle[accounting]: returned
from ok (rlm_always)
Tue Nov 14 13:46:27 2017 : Debug: (0) [ok] = ok
Tue Nov 14 13:46:27 2017 : Debug: (0) return
Tue Nov 14 13:46:27 2017 : Debug: (0) } # if (&control:Proxy-To-Realm
) = ok
Tue Nov 14 13:46:27 2017 : Debug: (0) } # accounting = ok
Tue Nov 14 13:46:27 2017 : Debug: Using home pool acct for realm sasro.sk
Tue Nov 14 13:46:27 2017 : Debug: (0) Starting proxy to home server
80.81.224.2 port 1813
Tue Nov 14 13:46:27 2017 : Debug: (0) Empty pre-proxy section in virtual
server "default". Using default return values.
Tue Nov 14 13:46:27 2017 : Debug: (0) proxy: Trying to allocate ID (0/2)
Tue Nov 14 13:46:27 2017 : Debug: (0) proxy: Trying to open a new listener
to the home server
Tue Nov 14 13:46:27 2017 : Debug: Opened new proxy socket 'proxy address *
port 44612'
Tue Nov 14 13:46:27 2017 : Debug: Listening on proxy address * port 44612
Tue Nov 14 13:46:27 2017 : Debug: (0) proxy: Trying to allocate ID (1/2)
Tue Nov 14 13:46:27 2017 : Debug: (0) proxy: request is now in proxy hash
Tue Nov 14 13:46:27 2017 : Debug: (0) proxy: allocating destination
80.81.224.2 port 1813 - Id 36
Tue Nov 14 13:46:27 2017 : Debug: (0) Proxying request to home server
80.81.224.2 port 1813 timeout 5.000000
28 06 00 00 00 01
2c 0a 30 30 37 39 44 35 31 36
01 0e 67 32 35 40 73 61 73 72 6f 2e 73 6b
04 06 ac 1f 08 4f
57 11 55 6e 69 71 2d 53 65 73 73 2d 49 44 33 35 38
3d 06 00 00 00 03
4d 0d 36 34 30 30 30 2f 35 37 36 30 30
1e 09 73 61 2e 63 6f 72 70
1f 0e 34 32 31 39 30 35 35 31 30 35 37 32
06 06 00 00 00 02
07 06 00 00 00 01
29 06 00 00 00 00
34 06 00 00 00 00
2a 06 00 00 00 00
35 06 00 00 00 00
2b 06 00 00 00 00
37 06 5a 0a e5 a3
21 05 31 38 34
Socket: 10
Proto: 17
Src IP: 0.0.0.0
port: 44612
Dst IP: 80.81.224.2
port: 1813
Code: (4) Accounting-Request
Id: 36
Length: 168
Vector: 00000000000000000000000000000000
Data: 28 06 00 00 00 01
2c 0a 30 30 37 39 44 35 31 36
01 0e 67 32 35 40 73 61 73 72 6f 2e 73 6b
04 06 ac 1f 08 4f
57 11 55 6e 69 71 2d 53 65 73 73 2d 49 44 33 35 38
3d 06 00 00 00 03
4d 0d 36 34 30 30 30 2f 35 37 36 30 30
1e 09 73 61 2e 63 6f 72 70
1f 0e 34 32 31 39 30 35 35 31 30 35 37 32
06 06 00 00 00 02
07 06 00 00 00 01
29 06 00 00 00 00
34 06 00 00 00 00
2a 06 00 00 00 00
35 06 00 00 00 00
2b 06 00 00 00 00
37 06 5a 0a e5 a3
21 05 31 38 34
Tue Nov 14 13:46:27 2017 : Debug: (0) Sent Accounting-Request Id 36 from
0.0.0.0:44612 to 80.81.224.2:1813 length 168
Tue Nov 14 13:46:27 2017 : Debug: (0) Acct-Status-Type = Start
Tue Nov 14 13:46:27 2017 : Debug: (0) Acct-Session-Id = "0079D516"
Tue Nov 14 13:46:27 2017 : Debug: (0) User-Name = "g25 at sasro.sk"
Tue Nov 14 13:46:27 2017 : Debug: (0) NAS-IP-Address = 172.31.8.79
Tue Nov 14 13:46:27 2017 : Debug: (0) NAS-Port-Id = "Uniq-Sess-ID358"
Tue Nov 14 13:46:27 2017 : Debug: (0) NAS-Port-Type = ISDN-V120
Tue Nov 14 13:46:27 2017 : Debug: (0) Connect-Info = "64000/57600"
Tue Nov 14 13:46:27 2017 : Debug: (0) Called-Station-Id = "sa.corp"
Tue Nov 14 13:46:27 2017 : Debug: (0) Calling-Station-Id = "421905510572"
Tue Nov 14 13:46:27 2017 : Debug: (0) Service-Type = Framed-User
Tue Nov 14 13:46:27 2017 : Debug: (0) Framed-Protocol = PPP
Tue Nov 14 13:46:27 2017 : Debug: (0) Acct-Delay-Time = 0
Tue Nov 14 13:46:27 2017 : Debug: (0) Acct-Input-Gigawords = 0
Tue Nov 14 13:46:27 2017 : Debug: (0) Acct-Input-Octets = 0
Tue Nov 14 13:46:27 2017 : Debug: (0) Acct-Output-Gigawords = 0
Tue Nov 14 13:46:27 2017 : Debug: (0) Acct-Output-Octets = 0
Tue Nov 14 13:46:27 2017 : Debug: (0) Event-Timestamp = "Nov 14 2017
13:46:27 CET"
Tue Nov 14 13:46:27 2017 : Debug: (0) Proxy-State = 0x313834
Socket: 10
Proto: 17
Src IP: 0.0.0.0
port: 44612
Dst IP: 80.81.224.2
port: 1813
Code: (4) Accounting-Request
Id: 36
Length: 168
Vector: 39c35535c7ac69694858a5e64ba9175c
Data: 28 06 00 00 00 01
2c 0a 30 30 37 39 44 35 31 36
01 0e 67 32 35 40 73 61 73 72 6f 2e 73 6b
04 06 ac 1f 08 4f
57 11 55 6e 69 71 2d 53 65 73 73 2d 49 44 33 35 38
3d 06 00 00 00 03
4d 0d 36 34 30 30 30 2f 35 37 36 30 30
1e 09 73 61 2e 63 6f 72 70
1f 0e 34 32 31 39 30 35 35 31 30 35 37 32
06 06 00 00 00 02
07 06 00 00 00 01
29 06 00 00 00 00
34 06 00 00 00 00
2a 06 00 00 00 00
35 06 00 00 00 00
2b 06 00 00 00 00
37 06 5a 0a e5 a3
21 05 31 38 34
Tue Nov 14 13:46:27 2017 : Debug: Waking up in 0.3 seconds.
Tue Nov 14 13:46:27 2017 : Debug: (0) Expecting proxy response no later
than 4.669878 seconds from now
Tue Nov 14 13:46:27 2017 : Debug: Waking up in 4.6 seconds.
Tue Nov 14 13:46:32 2017 : Debug: (0) No proxy response, giving up on
request and marking it done
Tue Nov 14 13:46:32 2017 : Proxy: Marking home server 80.81.224.2 port 1813
as zombie (it has not responded in 5.000000 seconds).
Tue Nov 14 13:46:32 2017 : ERROR: (0) Failing proxied request for user "
g25 at sasro.sk", due to lack of any response from home server 80.81.224.2
port 1813
Tue Nov 14 13:46:32 2017 : Debug: (0) Clearing existing &reply: attributes
Tue Nov 14 13:46:32 2017 : Debug: (0) Found Post-Proxy-Type Fail-Accounting
Tue Nov 14 13:46:32 2017 : Debug: (0) Post-Proxy-Type sub-section not
found. Ignoring.
Tue Nov 14 13:46:32 2017 : Debug: (0) Not sending reply to client.
Tue Nov 14 13:46:32 2017 : Debug: (0) Finished request
Tue Nov 14 13:46:32 2017 : Debug: (0) Cleaning up request packet ID 184
with timestamp +11
Tue Nov 14 13:46:32 2017 : Debug: Waking up in 30.3 seconds.
Socket: 9
Proto: 0
Src IP: 127.0.0.1
port: 59709
Dst IP: 127.0.0.1
port: 10813
Code: (4) Accounting-Request
Id: 245
Length: 157
Vector: 6a66f448ad3b9ef78f8e64420e3b1cbb
Data: 28 06 00 00 00 01
2c 0a 30 30 37 39 44 35 31 36
01 0e 67 32 35 40 73 61 73 72 6f 2e 73 6b
04 06 ac 1f 08 4f
57 11 55 6e 69 71 2d 53 65 73 73 2d 49 44 33 35 38
3d 06 00 00 00 03
4d 0d 36 34 30 30 30 2f 35 37 36 30 30
1e 09 73 61 2e 63 6f 72 70
1f 0e 34 32 31 39 30 35 35 31 30 35 37 32
06 06 00 00 00 02
07 06 00 00 00 01
29 06 00 00 00 00
34 06 00 00 00 00
2a 06 00 00 00 00
35 06 00 00 00 00
2b 06 00 00 00 00
Tue Nov 14 13:46:57 2017 : Debug: (1) Received Accounting-Request Id 245
from 127.0.0.1:59709 to 127.0.0.1:10813 length 157
Tue Nov 14 13:46:57 2017 : Debug: (1) Acct-Status-Type = Start
Tue Nov 14 13:46:57 2017 : Debug: (1) Acct-Session-Id = "0079D516"
Tue Nov 14 13:46:57 2017 : Debug: (1) User-Name = "g25 at sasro.sk"
Tue Nov 14 13:46:57 2017 : Debug: (1) NAS-IP-Address = 172.31.8.79
Tue Nov 14 13:46:57 2017 : Debug: (1) NAS-Port-Id = "Uniq-Sess-ID358"
Tue Nov 14 13:46:57 2017 : Debug: (1) NAS-Port-Type = ISDN-V120
Tue Nov 14 13:46:57 2017 : Debug: (1) Connect-Info = "64000/57600"
Tue Nov 14 13:46:57 2017 : Debug: (1) Called-Station-Id = "sa.corp"
Tue Nov 14 13:46:57 2017 : Debug: (1) Calling-Station-Id = "421905510572"
Tue Nov 14 13:46:57 2017 : Debug: (1) Service-Type = Framed-User
Tue Nov 14 13:46:57 2017 : Debug: (1) Framed-Protocol = PPP
Tue Nov 14 13:46:57 2017 : Debug: (1) Acct-Delay-Time = 0
Tue Nov 14 13:46:57 2017 : Debug: (1) Acct-Input-Gigawords = 0
Tue Nov 14 13:46:57 2017 : Debug: (1) Acct-Input-Octets = 0
Tue Nov 14 13:46:57 2017 : Debug: (1) Acct-Output-Gigawords = 0
Tue Nov 14 13:46:57 2017 : Debug: (1) Acct-Output-Octets = 0
Tue Nov 14 13:46:57 2017 : Debug: (1) # Executing section preacct from file
/app/radius/conf/acct-test/sites-enabled/default
Tue Nov 14 13:46:57 2017 : Debug: (1) preacct {
Tue Nov 14 13:46:57 2017 : Debug: (1) modsingle[preacct]: calling
preprocess (rlm_preprocess)
Tue Nov 14 13:46:57 2017 : Debug: (1) modsingle[preacct]: returned from
preprocess (rlm_preprocess)
Tue Nov 14 13:46:57 2017 : Debug: (1) [preprocess] = ok
Tue Nov 14 13:46:57 2017 : Debug: (1) if ( ! &NAS-IP-Address ) {
Tue Nov 14 13:46:57 2017 : Debug: (1) if ( ! &NAS-IP-Address ) -> FALSE
Tue Nov 14 13:46:57 2017 : Debug: (1) else {
Tue Nov 14 13:46:57 2017 : Debug: (1) policy huntgroup {
Tue Nov 14 13:46:57 2017 : Debug: (1) switch &NAS-IP-Address {
Tue Nov 14 13:46:57 2017 : Debug: (1) case 172.31.8.79 {
Tue Nov 14 13:46:57 2017 : Debug: (1) update request {
Tue Nov 14 13:46:57 2017 : Debug: (1) &Huntgroup-Name :=
'IPSEC'
Tue Nov 14 13:46:57 2017 : Debug: (1) } # update request = noop
Tue Nov 14 13:46:57 2017 : Debug: (1) } # case 172.31.8.79 = noop
Tue Nov 14 13:46:57 2017 : Debug: (1) } # switch &NAS-IP-Address =
noop
Tue Nov 14 13:46:57 2017 : Debug: (1) } # policy huntgroup = noop
Tue Nov 14 13:46:57 2017 : Debug: (1) } # else = noop
Tue Nov 14 13:46:57 2017 : Debug: (1) policy username {
Tue Nov 14 13:46:57 2017 : Debug: (1) if (!&User-Name || &User-Name
== '') {
Tue Nov 14 13:46:57 2017 : Debug: (1) if (!&User-Name || &User-Name
== '') -> FALSE
Tue Nov 14 13:46:57 2017 : Debug: (1) elsif (&User-Name =~
/^[0-9]+$/) {
Tue Nov 14 13:46:57 2017 : Debug: No matches
Tue Nov 14 13:46:57 2017 : Debug: (1) elsif (&User-Name =~
/^[0-9]+$/) -> FALSE
Tue Nov 14 13:46:57 2017 : Debug: (1) } # policy username = ok
Tue Nov 14 13:46:57 2017 : Debug: (1) policy acct_counters64.preacct {
Tue Nov 14 13:46:57 2017 : Debug: (1) update request {
Tue Nov 14 13:46:57 2017 : Debug: (1) &Acct-Input-Gigawords --> 0
Tue Nov 14 13:46:57 2017 : Debug: (1) &Acct-Input-Octets --> 0
Tue Nov 14 13:46:57 2017 : Debug: (1) EXPAND
%{expr:(&Acct-Input-Gigawords << 32) | &Acct-Input-Octets}
Tue Nov 14 13:46:57 2017 : Debug: (1) --> 0
Tue Nov 14 13:46:57 2017 : Debug: (1) &Acct-Input-Octets64 = 0
Tue Nov 14 13:46:57 2017 : Debug: (1) &Acct-Output-Gigawords --> 0
Tue Nov 14 13:46:57 2017 : Debug: (1) &Acct-Output-Octets --> 0
Tue Nov 14 13:46:57 2017 : Debug: (1) EXPAND
%{expr:(&Acct-Output-Gigawords << 32) | &Acct-Output-Octets}
Tue Nov 14 13:46:57 2017 : Debug: (1) --> 0
Tue Nov 14 13:46:57 2017 : Debug: (1) &Acct-Output-Octets64 = 0
Tue Nov 14 13:46:57 2017 : Debug: (1) } # update request = noop
Tue Nov 14 13:46:57 2017 : Debug: (1) } # policy
acct_counters64.preacct = noop
Tue Nov 14 13:46:57 2017 : Debug: (1) if (&Class) {
Tue Nov 14 13:46:57 2017 : Debug: (1) if (&Class) -> FALSE
Tue Nov 14 13:46:57 2017 : Debug: (1) policy acct_unique {
Tue Nov 14 13:46:57 2017 : Debug: (1) if ("%{string:Class}" =~
/ai:([0-9a-f]{32})/i) {
Tue Nov 14 13:46:57 2017 : Debug: (1) EXPAND TMPL XLAT STRUCT
Tue Nov 14 13:46:57 2017 : Debug: (1) EXPAND %{string:Class}
Tue Nov 14 13:46:57 2017 : Debug: (1) -->
Tue Nov 14 13:46:57 2017 : Debug: No matches
Tue Nov 14 13:46:57 2017 : Debug: (1) if ("%{string:Class}" =~
/ai:([0-9a-f]{32})/i) -> FALSE
Tue Nov 14 13:46:57 2017 : Debug: (1) else {
Tue Nov 14 13:46:57 2017 : Debug: (1) update request {
Tue Nov 14 13:46:57 2017 : Debug: (1) EXPAND
%{md5:%{User-Name},%{Acct-Session-ID},%{%{NAS-IPv6-Address}:-%{NAS-IP-Address}},%{NAS-Identifier},%{NAS-Port-ID},%{NAS-Port}}
Tue Nov 14 13:46:57 2017 : Debug: (1) -->
70897db75add0d0e73023ed66148c1dd
Tue Nov 14 13:46:57 2017 : Debug: (1) &Acct-Unique-Session-Id :=
70897db75add0d0e73023ed66148c1dd
Tue Nov 14 13:46:57 2017 : Debug: (1) } # update request = noop
Tue Nov 14 13:46:57 2017 : Debug: (1) } # else = noop
Tue Nov 14 13:46:57 2017 : Debug: (1) } # policy acct_unique = noop
Tue Nov 14 13:46:57 2017 : Debug: (1) modsingle[preacct]: calling
suffix (rlm_realm)
Tue Nov 14 13:46:57 2017 : Debug: (1) suffix: Checking for suffix after "@"
Tue Nov 14 13:46:57 2017 : Debug: (1) suffix: Looking up realm "sasro.sk"
for User-Name = "g25 at sasro.sk"
Tue Nov 14 13:46:57 2017 : Debug: (1) suffix: Found realm "sasro.sk"
Tue Nov 14 13:46:57 2017 : Debug: (1) suffix: Adding Realm = "sasro.sk"
Tue Nov 14 13:46:57 2017 : Debug: (1) suffix: Proxying request from user
g25 at sasro.sk to realm sasro.sk
Tue Nov 14 13:46:57 2017 : Debug: (1) suffix: Preparing to proxy accounting
request to realm "sasro.sk"
Tue Nov 14 13:46:57 2017 : Debug: (1) modsingle[preacct]: returned from
suffix (rlm_realm)
Tue Nov 14 13:46:57 2017 : Debug: (1) [suffix] = updated
Tue Nov 14 13:46:57 2017 : Debug: (1) } # preacct = updated
Tue Nov 14 13:46:57 2017 : Debug: (1) # Executing section accounting from
file /app/radius/conf/acct-test/sites-enabled/default
Tue Nov 14 13:46:57 2017 : Debug: (1) accounting {
Tue Nov 14 13:46:57 2017 : Debug: (1) if (&control:Proxy-To-Realm ) {
Tue Nov 14 13:46:57 2017 : Debug: (1) if (&control:Proxy-To-Realm ) ->
TRUE
Tue Nov 14 13:46:57 2017 : Debug: (1) if (&control:Proxy-To-Realm ) {
Tue Nov 14 13:46:57 2017 : Debug: (1) modsingle[accounting]: calling
ok (rlm_always)
Tue Nov 14 13:46:57 2017 : Debug: (1) modsingle[accounting]: returned
from ok (rlm_always)
Tue Nov 14 13:46:57 2017 : Debug: (1) [ok] = ok
Tue Nov 14 13:46:57 2017 : Debug: (1) return
Tue Nov 14 13:46:57 2017 : Debug: (1) } # if (&control:Proxy-To-Realm
) = ok
Tue Nov 14 13:46:57 2017 : Debug: (1) } # accounting = ok
Tue Nov 14 13:46:57 2017 : Debug: Using home pool acct for realm sasro.sk
Tue Nov 14 13:46:57 2017 : Debug: (1) Starting proxy to home server
80.81.224.2 port 1813
Tue Nov 14 13:46:57 2017 : Debug: (1) Empty pre-proxy section in virtual
server "default". Using default return values.
Tue Nov 14 13:46:57 2017 : Debug: (1) proxy: Trying to allocate ID (0/2)
Tue Nov 14 13:46:57 2017 : Debug: (1) proxy: request is now in proxy hash
Tue Nov 14 13:46:57 2017 : Debug: (1) proxy: allocating destination
80.81.224.2 port 1813 - Id 4
Tue Nov 14 13:46:57 2017 : Debug: (1) Proxying request to home server
80.81.224.2 port 1813 timeout 5.000000
28 06 00 00 00 01
2c 0a 30 30 37 39 44 35 31 36
01 0e 67 32 35 40 73 61 73 72 6f 2e 73 6b
04 06 ac 1f 08 4f
57 11 55 6e 69 71 2d 53 65 73 73 2d 49 44 33 35 38
3d 06 00 00 00 03
4d 0d 36 34 30 30 30 2f 35 37 36 30 30
1e 09 73 61 2e 63 6f 72 70
1f 0e 34 32 31 39 30 35 35 31 30 35 37 32
06 06 00 00 00 02
07 06 00 00 00 01
29 06 00 00 00 00
34 06 00 00 00 00
2a 06 00 00 00 00
35 06 00 00 00 00
2b 06 00 00 00 00
37 06 5a 0a e5 c1
21 05 32 34 35
Socket: 10
Proto: 17
Src IP: 0.0.0.0
port: 44612
Dst IP: 80.81.224.2
port: 1813
Code: (4) Accounting-Request
Id: 4
Length: 168
Vector: 00000000000000000000000000000000
Data: 28 06 00 00 00 01
2c 0a 30 30 37 39 44 35 31 36
01 0e 67 32 35 40 73 61 73 72 6f 2e 73 6b
04 06 ac 1f 08 4f
57 11 55 6e 69 71 2d 53 65 73 73 2d 49 44 33 35 38
3d 06 00 00 00 03
4d 0d 36 34 30 30 30 2f 35 37 36 30 30
1e 09 73 61 2e 63 6f 72 70
1f 0e 34 32 31 39 30 35 35 31 30 35 37 32
06 06 00 00 00 02
07 06 00 00 00 01
29 06 00 00 00 00
34 06 00 00 00 00
2a 06 00 00 00 00
35 06 00 00 00 00
2b 06 00 00 00 00
37 06 5a 0a e5 c1
21 05 32 34 35
Tue Nov 14 13:46:57 2017 : Debug: (1) Sent Accounting-Request Id 4 from
0.0.0.0:44612 to 80.81.224.2:1813 length 168
Tue Nov 14 13:46:57 2017 : Debug: (1) Acct-Status-Type = Start
Tue Nov 14 13:46:57 2017 : Debug: (1) Acct-Session-Id = "0079D516"
Tue Nov 14 13:46:57 2017 : Debug: (1) User-Name = "g25 at sasro.sk"
Tue Nov 14 13:46:57 2017 : Debug: (1) NAS-IP-Address = 172.31.8.79
Tue Nov 14 13:46:57 2017 : Debug: (1) NAS-Port-Id = "Uniq-Sess-ID358"
Tue Nov 14 13:46:57 2017 : Debug: (1) NAS-Port-Type = ISDN-V120
Tue Nov 14 13:46:57 2017 : Debug: (1) Connect-Info = "64000/57600"
Tue Nov 14 13:46:57 2017 : Debug: (1) Called-Station-Id = "sa.corp"
Tue Nov 14 13:46:57 2017 : Debug: (1) Calling-Station-Id = "421905510572"
Tue Nov 14 13:46:57 2017 : Debug: (1) Service-Type = Framed-User
Tue Nov 14 13:46:57 2017 : Debug: (1) Framed-Protocol = PPP
Tue Nov 14 13:46:57 2017 : Debug: (1) Acct-Delay-Time = 0
Tue Nov 14 13:46:57 2017 : Debug: (1) Acct-Input-Gigawords = 0
Tue Nov 14 13:46:57 2017 : Debug: (1) Acct-Input-Octets = 0
Tue Nov 14 13:46:57 2017 : Debug: (1) Acct-Output-Gigawords = 0
Tue Nov 14 13:46:57 2017 : Debug: (1) Acct-Output-Octets = 0
Tue Nov 14 13:46:57 2017 : Debug: (1) Event-Timestamp = "Nov 14 2017
13:46:57 CET"
Tue Nov 14 13:46:57 2017 : Debug: (1) Proxy-State = 0x323435
Socket: 10
Proto: 17
Src IP: 0.0.0.0
port: 44612
Dst IP: 80.81.224.2
port: 1813
Code: (4) Accounting-Request
Id: 4
Length: 168
Vector: efda7676e984e381c25f062598d1ecff
Data: 28 06 00 00 00 01
2c 0a 30 30 37 39 44 35 31 36
01 0e 67 32 35 40 73 61 73 72 6f 2e 73 6b
04 06 ac 1f 08 4f
57 11 55 6e 69 71 2d 53 65 73 73 2d 49 44 33 35 38
3d 06 00 00 00 03
4d 0d 36 34 30 30 30 2f 35 37 36 30 30
1e 09 73 61 2e 63 6f 72 70
1f 0e 34 32 31 39 30 35 35 31 30 35 37 32
06 06 00 00 00 02
07 06 00 00 00 01
29 06 00 00 00 00
34 06 00 00 00 00
2a 06 00 00 00 00
35 06 00 00 00 00
2b 06 00 00 00 00
37 06 5a 0a e5 c1
21 05 32 34 35
Tue Nov 14 13:46:57 2017 : Debug: Waking up in 0.3 seconds.
Tue Nov 14 13:46:57 2017 : Debug: (1) Expecting proxy response no later
than 4.671257 seconds from now
Tue Nov 14 13:46:57 2017 : Debug: Waking up in 4.6 seconds.
Tue Nov 14 13:47:02 2017 : Debug: (1) No proxy response, giving up on
request and marking it done
Tue Nov 14 13:47:02 2017 : ERROR: (1) Failing proxied request for user "
g25 at sasro.sk", due to lack of any response from home server 80.81.224.2
port 1813
Tue Nov 14 13:47:02 2017 : Debug: (1) Clearing existing &reply: attributes
Tue Nov 14 13:47:02 2017 : Debug: (1) Found Post-Proxy-Type Fail-Accounting
Tue Nov 14 13:47:02 2017 : Debug: (1) Post-Proxy-Type sub-section not
found. Ignoring.
Tue Nov 14 13:47:02 2017 : Debug: (1) Not sending reply to client.
Tue Nov 14 13:47:02 2017 : Debug: (1) Finished request
Tue Nov 14 13:47:02 2017 : Debug: (1) Cleaning up request packet ID 245
with timestamp +41
Tue Nov 14 13:47:02 2017 : Debug: Waking up in 0.2 seconds.
Tue Nov 14 13:47:02 2017 : Debug: PING: Zombie period is over for home
server sa_server_prod
Tue Nov 14 13:47:02 2017 : Proxy: Marking home server 80.81.224.2 port 1813
as dead.
Tue Nov 14 13:47:02 2017 : Debug: PING: Reviving home server sa_server_prod
in 300 seconds
Tue Nov 14 13:47:02 2017 : Debug: Waking up in 299.9 seconds.
Socket: 9
Proto: 0
Src IP: 127.0.0.1
port: 53195
Dst IP: 127.0.0.1
port: 10813
Code: (4) Accounting-Request
Id: 165
Length: 157
Vector: ead1279660205f3f858c8fd0f0d4efa6
Data: 28 06 00 00 00 01
2c 0a 30 30 37 39 44 35 31 36
01 0e 67 32 35 40 73 61 73 72 6f 2e 73 6b
04 06 ac 1f 08 4f
57 11 55 6e 69 71 2d 53 65 73 73 2d 49 44 33 35 38
3d 06 00 00 00 03
4d 0d 36 34 30 30 30 2f 35 37 36 30 30
1e 09 73 61 2e 63 6f 72 70
1f 0e 34 32 31 39 30 35 35 31 30 35 37 32
06 06 00 00 00 02
07 06 00 00 00 01
29 06 00 00 00 00
34 06 00 00 00 00
2a 06 00 00 00 00
35 06 00 00 00 00
2b 06 00 00 00 00
Tue Nov 14 13:47:27 2017 : Debug: (2) Received Accounting-Request Id 165
from 127.0.0.1:53195 to 127.0.0.1:10813 length 157
Tue Nov 14 13:47:27 2017 : Debug: (2) Acct-Status-Type = Start
Tue Nov 14 13:47:27 2017 : Debug: (2) Acct-Session-Id = "0079D516"
Tue Nov 14 13:47:27 2017 : Debug: (2) User-Name = "g25 at sasro.sk"
Tue Nov 14 13:47:27 2017 : Debug: (2) NAS-IP-Address = 172.31.8.79
Tue Nov 14 13:47:27 2017 : Debug: (2) NAS-Port-Id = "Uniq-Sess-ID358"
Tue Nov 14 13:47:27 2017 : Debug: (2) NAS-Port-Type = ISDN-V120
Tue Nov 14 13:47:27 2017 : Debug: (2) Connect-Info = "64000/57600"
Tue Nov 14 13:47:27 2017 : Debug: (2) Called-Station-Id = "sa.corp"
Tue Nov 14 13:47:27 2017 : Debug: (2) Calling-Station-Id = "421905510572"
Tue Nov 14 13:47:27 2017 : Debug: (2) Service-Type = Framed-User
Tue Nov 14 13:47:27 2017 : Debug: (2) Framed-Protocol = PPP
Tue Nov 14 13:47:27 2017 : Debug: (2) Acct-Delay-Time = 0
Tue Nov 14 13:47:27 2017 : Debug: (2) Acct-Input-Gigawords = 0
Tue Nov 14 13:47:27 2017 : Debug: (2) Acct-Input-Octets = 0
Tue Nov 14 13:47:27 2017 : Debug: (2) Acct-Output-Gigawords = 0
Tue Nov 14 13:47:27 2017 : Debug: (2) Acct-Output-Octets = 0
Tue Nov 14 13:47:27 2017 : Debug: (2) # Executing section preacct from file
/app/radius/conf/acct-test/sites-enabled/default
Tue Nov 14 13:47:27 2017 : Debug: (2) preacct {
Tue Nov 14 13:47:27 2017 : Debug: (2) modsingle[preacct]: calling
preprocess (rlm_preprocess)
Tue Nov 14 13:47:27 2017 : Debug: (2) modsingle[preacct]: returned from
preprocess (rlm_preprocess)
Tue Nov 14 13:47:27 2017 : Debug: (2) [preprocess] = ok
Tue Nov 14 13:47:27 2017 : Debug: (2) if ( ! &NAS-IP-Address ) {
Tue Nov 14 13:47:27 2017 : Debug: (2) if ( ! &NAS-IP-Address ) -> FALSE
Tue Nov 14 13:47:27 2017 : Debug: (2) else {
Tue Nov 14 13:47:27 2017 : Debug: (2) policy huntgroup {
Tue Nov 14 13:47:27 2017 : Debug: (2) switch &NAS-IP-Address {
Tue Nov 14 13:47:27 2017 : Debug: (2) case 172.31.8.79 {
Tue Nov 14 13:47:27 2017 : Debug: (2) update request {
Tue Nov 14 13:47:27 2017 : Debug: (2) &Huntgroup-Name :=
'IPSEC'
Tue Nov 14 13:47:27 2017 : Debug: (2) } # update request = noop
Tue Nov 14 13:47:27 2017 : Debug: (2) } # case 172.31.8.79 = noop
Tue Nov 14 13:47:27 2017 : Debug: (2) } # switch &NAS-IP-Address =
noop
Tue Nov 14 13:47:27 2017 : Debug: (2) } # policy huntgroup = noop
Tue Nov 14 13:47:27 2017 : Debug: (2) } # else = noop
Tue Nov 14 13:47:27 2017 : Debug: (2) policy username {
Tue Nov 14 13:47:27 2017 : Debug: (2) if (!&User-Name || &User-Name
== '') {
Tue Nov 14 13:47:27 2017 : Debug: (2) if (!&User-Name || &User-Name
== '') -> FALSE
Tue Nov 14 13:47:27 2017 : Debug: (2) elsif (&User-Name =~
/^[0-9]+$/) {
Tue Nov 14 13:47:27 2017 : Debug: No matches
Tue Nov 14 13:47:27 2017 : Debug: (2) elsif (&User-Name =~
/^[0-9]+$/) -> FALSE
Tue Nov 14 13:47:27 2017 : Debug: (2) } # policy username = ok
Tue Nov 14 13:47:27 2017 : Debug: (2) policy acct_counters64.preacct {
Tue Nov 14 13:47:27 2017 : Debug: (2) update request {
Tue Nov 14 13:47:27 2017 : Debug: (2) &Acct-Input-Gigawords --> 0
Tue Nov 14 13:47:27 2017 : Debug: (2) &Acct-Input-Octets --> 0
Tue Nov 14 13:47:27 2017 : Debug: (2) EXPAND
%{expr:(&Acct-Input-Gigawords << 32) | &Acct-Input-Octets}
Tue Nov 14 13:47:27 2017 : Debug: (2) --> 0
Tue Nov 14 13:47:27 2017 : Debug: (2) &Acct-Input-Octets64 = 0
Tue Nov 14 13:47:27 2017 : Debug: (2) &Acct-Output-Gigawords --> 0
Tue Nov 14 13:47:27 2017 : Debug: (2) &Acct-Output-Octets --> 0
Tue Nov 14 13:47:27 2017 : Debug: (2) EXPAND
%{expr:(&Acct-Output-Gigawords << 32) | &Acct-Output-Octets}
Tue Nov 14 13:47:27 2017 : Debug: (2) --> 0
Tue Nov 14 13:47:27 2017 : Debug: (2) &Acct-Output-Octets64 = 0
Tue Nov 14 13:47:27 2017 : Debug: (2) } # update request = noop
Tue Nov 14 13:47:27 2017 : Debug: (2) } # policy
acct_counters64.preacct = noop
Tue Nov 14 13:47:27 2017 : Debug: (2) if (&Class) {
Tue Nov 14 13:47:27 2017 : Debug: (2) if (&Class) -> FALSE
Tue Nov 14 13:47:27 2017 : Debug: (2) policy acct_unique {
Tue Nov 14 13:47:27 2017 : Debug: (2) if ("%{string:Class}" =~
/ai:([0-9a-f]{32})/i) {
Tue Nov 14 13:47:27 2017 : Debug: (2) EXPAND TMPL XLAT STRUCT
Tue Nov 14 13:47:27 2017 : Debug: (2) EXPAND %{string:Class}
Tue Nov 14 13:47:27 2017 : Debug: (2) -->
Tue Nov 14 13:47:27 2017 : Debug: No matches
Tue Nov 14 13:47:27 2017 : Debug: (2) if ("%{string:Class}" =~
/ai:([0-9a-f]{32})/i) -> FALSE
Tue Nov 14 13:47:27 2017 : Debug: (2) else {
Tue Nov 14 13:47:27 2017 : Debug: (2) update request {
Tue Nov 14 13:47:27 2017 : Debug: (2) EXPAND
%{md5:%{User-Name},%{Acct-Session-ID},%{%{NAS-IPv6-Address}:-%{NAS-IP-Address}},%{NAS-Identifier},%{NAS-Port-ID},%{NAS-Port}}
Tue Nov 14 13:47:27 2017 : Debug: (2) -->
70897db75add0d0e73023ed66148c1dd
Tue Nov 14 13:47:27 2017 : Debug: (2) &Acct-Unique-Session-Id :=
70897db75add0d0e73023ed66148c1dd
Tue Nov 14 13:47:27 2017 : Debug: (2) } # update request = noop
Tue Nov 14 13:47:27 2017 : Debug: (2) } # else = noop
Tue Nov 14 13:47:27 2017 : Debug: (2) } # policy acct_unique = noop
Tue Nov 14 13:47:27 2017 : Debug: (2) modsingle[preacct]: calling
suffix (rlm_realm)
Tue Nov 14 13:47:27 2017 : Debug: (2) suffix: Checking for suffix after "@"
Tue Nov 14 13:47:27 2017 : Debug: (2) suffix: Looking up realm "sasro.sk"
for User-Name = "g25 at sasro.sk"
Tue Nov 14 13:47:27 2017 : Debug: (2) suffix: Found realm "sasro.sk"
Tue Nov 14 13:47:27 2017 : Debug: (2) suffix: Adding Realm = "sasro.sk"
Tue Nov 14 13:47:27 2017 : Debug: (2) suffix: Proxying request from user
g25 at sasro.sk to realm sasro.sk
Tue Nov 14 13:47:27 2017 : Debug: (2) suffix: Preparing to proxy accounting
request to realm "sasro.sk"
Tue Nov 14 13:47:27 2017 : Debug: (2) modsingle[preacct]: returned from
suffix (rlm_realm)
Tue Nov 14 13:47:27 2017 : Debug: (2) [suffix] = updated
Tue Nov 14 13:47:27 2017 : Debug: (2) } # preacct = updated
Tue Nov 14 13:47:27 2017 : Debug: (2) # Executing section accounting from
file /app/radius/conf/acct-test/sites-enabled/default
Tue Nov 14 13:47:27 2017 : Debug: (2) accounting {
Tue Nov 14 13:47:27 2017 : Debug: (2) if (&control:Proxy-To-Realm ) {
Tue Nov 14 13:47:27 2017 : Debug: (2) if (&control:Proxy-To-Realm ) ->
TRUE
Tue Nov 14 13:47:27 2017 : Debug: (2) if (&control:Proxy-To-Realm ) {
Tue Nov 14 13:47:27 2017 : Debug: (2) modsingle[accounting]: calling
ok (rlm_always)
Tue Nov 14 13:47:27 2017 : Debug: (2) modsingle[accounting]: returned
from ok (rlm_always)
Tue Nov 14 13:47:27 2017 : Debug: (2) [ok] = ok
Tue Nov 14 13:47:27 2017 : Debug: (2) return
Tue Nov 14 13:47:27 2017 : Debug: (2) } # if (&control:Proxy-To-Realm
) = ok
Tue Nov 14 13:47:27 2017 : Debug: (2) } # accounting = ok
Tue Nov 14 13:47:27 2017 : Debug: Using home pool acct for realm sasro.sk
Tue Nov 14 13:47:27 2017 : ERROR: (2) Failed to find live home server:
Cancelling proxy
Tue Nov 14 13:47:27 2017 : Error: ASSERT FAILED src/main/process.c[3182]:
request->home_server != NULL
CAUGHT SIGNAL: Aborted
Backtrace of last 13 frames:
On Tue, Nov 14, 2017 at 12:02 PM, Peter Balsianok <balsianok.peter at gmail.com
> wrote:
> Sorry my mistake, you are right :).
> I have changed is to 1813 and run RADIUS again.
> In the attached file if gdb output.
>
> On Tue, Nov 14, 2017 at 11:27 AM, Alan Buxey <alan.buxey at gmail.com> wrote:
>
>> Accounting on port 1812, why? ;)
>>
>> Send the output of gdb -
>>
>> /app_log/radius/acct//gdb-acct-3088.log
>>
>>
>>
>>
>> On 14 Nov 2017 9:29 am, "Peter Balsianok" <balsianok.peter at gmail.com>
>> wrote:
>>
>> > Hi,
>> >
>> > I have problem with RADIUS server 3.0.15 (accounting). If home-server is
>> > unavailable, after while RADIUS servers terminates abnormally.
>> >
>> > proxy.conf (fragment):
>> > home_server sa_server_prod {
>> > type = acct
>> > ipaddr = 80.81.224.2
>> > port = 1812
>> > secret = "xxx"
>> >
>> > # Without status check
>> > status_check = none
>> > }
>> >
>> > home_server_pool prod_pool_sa {
>> > home_server = sa_server_prod
>> > }
>> >
>> > realm sasro.sk {
>> > nostrip
>> > acct_pool = prod_pool_sa
>> > }
>> >
>> >
>> > Debug output:
>> > Tue Nov 14 10:22:18 2017 : ERROR: (1252) ERROR: Failing proxied request
>> for
>> > user "56 at sasro.sk", due to lack of any response from home server
>> > 80.81.224.2 port 1812
>> > Tue Nov 14 10:22:18 2017 : ERROR: (1264) ERROR: Failing proxied request
>> for
>> > user "169 at sasro.sk", due to lack of any response from home server
>> > 80.81.224.2 port 1812
>> > Tue Nov 14 10:22:26 2017 : ERROR: (1520) ERROR: Failing proxied request
>> for
>> > user "g34 at sasro.sk", due to lack of any response from home server
>> > 80.81.224.2 port 1812
>> > Tue Nov 14 10:22:28 2017 : ERROR: (1577) ERROR: Failing proxied request
>> for
>> > user "56 at sasro.sk", due to lack of any response from home server
>> > 80.81.224.2 port 1812
>> > Tue Nov 14 10:22:33 2017 : ERROR: (1703) ERROR: Failing proxied request
>> for
>> > user "g34 at sasro.sk", due to lack of any response from home server
>> > 80.81.224.2 port 1812
>> > Tue Nov 14 10:22:38 2017 : Proxy: Marking home server 80.81.224.2 port
>> 1812
>> > as dead.
>> > Tue Nov 14 10:22:39 2017 : ERROR: (1889) ERROR: Failing proxied request
>> for
>> > user "169 at sasro.sk", due to lack of any response from home server
>> > 80.81.224.2 port 1812
>> > Tue Nov 14 10:22:40 2017 : Error: ASSERT FAILED
>> src/main/process.c[3182]:
>> > request->home_server != NULL
>> > CAUGHT SIGNAL: Aborted
>> > Backtrace of last 7 frames:
>> > /app/radius/freeradius-3.0.15/lib/libfreeradius-radius.so(
>> > fr_fault+0x10c)[0x8a9166]
>> > /app/radius/freeradius-3.0.15/lib/libfreeradius-server.so(
>> > rad_assert_fail+0x49)[0xbdddfe]
>> > /app/radius/freeradius-v3/sbin/radiusd[0x8084145]
>> > /app/radius/freeradius-v3/sbin/radiusd[0x80808f3]
>> > /app/radius/freeradius-v3/sbin/radiusd[0x807c641]
>> > /lib/libpthread.so.0[0x50c912]
>> > /lib/libc.so.6(clone+0x5e)[0x81347e]
>> > Calling: gdb -silent -x /app/radius/conf/acct/panic.gdb
>> > /app/radius/freeradius-v3/sbin/radiusd 3088 2>&1 | tee
>> > /app_log/radius/acct//gdb-acct-3088.log
>> > Panic action exited with 0
>> > _EXIT(0) CALLED src/lib/debug.c[743]
>> > -
>> > List info/subscribe/unsubscribe? See http://www.freeradius.org/
>> > list/users.html
>> -
>> List info/subscribe/unsubscribe? See http://www.freeradius.org/list
>> /users.html
>
>
>
More information about the Freeradius-Users
mailing list