Radacct not working
Yahn do Amaral Almeida Pinheiro
yahnaamaralp at gmail.com
Thu Nov 16 21:07:27 CET 2017
(0) Received Access-Request Id 178 from 172.23.4.2:16505 to
177.38.112.4:1812 length 236
(0) Cisco-AVPair = "client-mac-address=4c5e.0cf7.1979"
(0) Acct-Session-Id = "0000391b"
(0) NAS-Port-Id = "0/0/12/500"
(0) Cisco-NAS-Port = "0/0/12/500"
(0) User-Name = "tiago at tmw.net"
(0) Service-Type = Framed-User
(0) User-Password = "tmw"
(0) X-Ascend-Connect-Progress = LCP-Opened
(0) Cisco-AVPair = "connect-progress=LCP Open"
(0) Framed-Protocol = PPP
(0) NAS-Port-Type = Wireless-XGP
(0) Event-Timestamp = "Nov 16 2017 18:05:41 -02"
(0) NAS-Identifier = "PPPoE_ASR9001"
(0) NAS-IP-Address = 172.23.4.2
(0) NAS-IPv6-Address = ::
(0) # Executing section authorize from file
/usr/local/etc/raddb/sites-enabled/default
(0) authorize {
(0) policy filter_username {
(0) if (&User-Name) {
(0) if (&User-Name) -> TRUE
(0) if (&User-Name) {
(0) if (&User-Name =~ / /) {
(0) if (&User-Name =~ / /) -> FALSE
(0) if (&User-Name =~ /@[^@]*@/ ) {
(0) if (&User-Name =~ /@[^@]*@/ ) -> FALSE
(0) if (&User-Name =~ /\.\./ ) {
(0) if (&User-Name =~ /\.\./ ) -> FALSE
(0) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) {
(0) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) ->
FALSE
(0) if (&User-Name =~ /\.$/) {
(0) if (&User-Name =~ /\.$/) -> FALSE
(0) if (&User-Name =~ /@\./) {
(0) if (&User-Name =~ /@\./) -> FALSE
(0) } # if (&User-Name) = notfound
(0) } # policy filter_username = notfound
(0) [preprocess] = ok
(0) [chap] = noop
(0) [mschap] = noop
(0) [digest] = noop
(0) suffix: Checking for suffix after "@"
(0) suffix: Looking up realm "tmw.net" for User-Name = "tiago at tmw.net"
(0) suffix: No such realm "tmw.net"
(0) [suffix] = noop
(0) eap: No EAP-Message, not doing EAP
(0) [eap] = noop
(0) sql: EXPAND %{User-Name}
(0) sql: --> tiago at tmw.net
(0) sql: SQL-User-Name set to 'tiago at tmw.net'
rlm_sql (sql): Closing connection (1): Hit idle_timeout, was idle for 2043
seconds
rlm_sql_postgresql: Socket destructor called, closing socket
rlm_sql (sql): Closing connection (2): Hit idle_timeout, was idle for 2043
seconds
rlm_sql_postgresql: Socket destructor called, closing socket
rlm_sql (sql): Closing connection (3): Hit idle_timeout, was idle for 2043
seconds
rlm_sql_postgresql: Socket destructor called, closing socket
rlm_sql (sql): Closing connection (4): Hit idle_timeout, was idle for 2043
seconds
rlm_sql (sql): You probably need to lower "min"
rlm_sql_postgresql: Socket destructor called, closing socket
rlm_sql (sql): Closing connection (0): Hit idle_timeout, was idle for 2043
seconds
rlm_sql (sql): You probably need to lower "min"
rlm_sql_postgresql: Socket destructor called, closing socket
rlm_sql (sql): Closing connection (5): Hit idle_timeout, was idle for 2043
seconds
rlm_sql (sql): You probably need to lower "min"
rlm_sql_postgresql: Socket destructor called, closing socket
rlm_sql (sql): 0 of 0 connections in use. You may need to increase "spare"
rlm_sql (sql): Opening additional connection (6), 1 of 32 pending slots used
rlm_sql_postgresql: Connecting using parameters: dbname='radius'
host='10.65.65.253' port=5432 user='radius' password='bdR4dius'
Connected to database 'radius' on '10.65.65.253' server version 100000,
protocol version 3, backend PID 8814
rlm_sql (sql): Reserved connection (6)
(0) sql: EXPAND SELECT id, UserName, Attribute, Value, Op FROM radcheck
WHERE Username = '%{SQL-User-Name}' ORDER BY id
(0) sql: --> SELECT id, UserName, Attribute, Value, Op FROM radcheck
WHERE Username = 'tiago at tmw.net' ORDER BY id
(0) sql: Executing select query: SELECT id, UserName, Attribute, Value, Op
FROM radcheck WHERE Username = 'tiago at tmw.net' ORDER BY id
rlm_sql_postgresql: Status: PGRES_TUPLES_OK
rlm_sql_postgresql: query affected rows = 2 , fields = 5
(0) sql: User found in radcheck table
(0) sql: Conditional check items matched, merging assignment check items
(0) sql: Cleartext-Password := "tmw"
(0) sql: Pool-Name := "Fixo"
(0) sql: EXPAND SELECT id, UserName, Attribute, Value, Op FROM radreply
WHERE Username = '%{SQL-User-Name}' ORDER BY id
(0) sql: --> SELECT id, UserName, Attribute, Value, Op FROM radreply
WHERE Username = 'tiago at tmw.net' ORDER BY id
(0) sql: Executing select query: SELECT id, UserName, Attribute, Value, Op
FROM radreply WHERE Username = 'tiago at tmw.net' ORDER BY id
rlm_sql_postgresql: Status: PGRES_TUPLES_OK
rlm_sql_postgresql: query affected rows = 0 , fields = 5
(0) sql: EXPAND SELECT GroupName FROM radusergroup WHERE
UserName='%{SQL-User-Name}' ORDER BY priority
(0) sql: --> SELECT GroupName FROM radusergroup WHERE UserName='
tiago at tmw.net' ORDER BY priority
(0) sql: Executing select query: SELECT GroupName FROM radusergroup WHERE
UserName='tiago at tmw.net' ORDER BY priority
rlm_sql_postgresql: Status: PGRES_TUPLES_OK
rlm_sql_postgresql: query affected rows = 0 , fields = 1
(0) sql: User not found in any groups
rlm_sql (sql): Released connection (6)
Need 2 more connections to reach min connections (3)
rlm_sql (sql): Opening additional connection (7), 1 of 31 pending slots used
rlm_sql_postgresql: Connecting using parameters: dbname='radius'
host='10.65.65.253' port=5432 user='radius' password='bdR4dius'
Connected to database 'radius' on '10.65.65.253' server version 100000,
protocol version 3, backend PID 8815
(0) [sql] = ok
(0) [expiration] = noop
(0) [logintime] = noop
(0) [pap] = updated
(0) } # authorize = updated
(0) Found Auth-Type = PAP
(0) # Executing group from file /usr/local/etc/raddb/sites-enabled/default
(0) Auth-Type PAP {
(0) pap: Login attempt with password
(0) pap: Comparing with "known good" Cleartext-Password
(0) pap: User authenticated successfully
(0) [pap] = ok
(0) } # Auth-Type PAP = ok
(0) # Executing section post-auth from file
/usr/local/etc/raddb/sites-enabled/default
(0) post-auth {
(0) update {
(0) No attributes updated
(0) } # update = noop
(0) sql: EXPAND .query
(0) sql: --> .query
(0) sql: Using query template 'query'
rlm_sql (sql): Reserved connection (6)
(0) sql: EXPAND %{User-Name}
(0) sql: --> tiago at tmw.net
(0) sql: SQL-User-Name set to 'tiago at tmw.net'
(0) sql: EXPAND INSERT INTO radpostauth (username, pass, reply, authdate)
VALUES('%{User-Name}', '%{%{User-Password}:-Chap-Password}',
'%{reply:Packet-Type}', NOW())
(0) sql: --> INSERT INTO radpostauth (username, pass, reply, authdate)
VALUES('tiago at tmw.net', 'tmw', 'Access-Accept', NOW())
(0) sql: Executing query: INSERT INTO radpostauth (username, pass, reply,
authdate) VALUES('tiago at tmw.net', 'tmw', 'Access-Accept', NOW())
rlm_sql_postgresql: Status: PGRES_COMMAND_OK
rlm_sql_postgresql: query affected rows = 1
(0) sql: SQL query returned: success
(0) sql: 1 record(s) updated
rlm_sql (sql): Released connection (6)
(0) [sql] = ok
rlm_sql (sql): Reserved connection (7)
(0) sqlippool: EXPAND %{User-Name}
(0) sqlippool: --> tiago at tmw.net
(0) sqlippool: SQL-User-Name set to 'tiago at tmw.net'
(0) sqlippool: EXPAND START TRANSACTION
(0) sqlippool: --> START TRANSACTION
(0) sqlippool: Executing query: START TRANSACTION
rlm_sql_postgresql: Status: PGRES_COMMAND_OK
rlm_sql_postgresql: query affected rows = 0
(0) sqlippool: EXPAND UPDATE radippool SET nasipaddress = '', pool_key = 0,
callingstationid = '', expiry_time = 'now'::timestamp(0) - '1
second'::interval WHERE nasipaddress = '%{NAS-IP-Address}' AND pool_key =
'%{Calling-Station-Id}'
(0) sqlippool: --> UPDATE radippool SET nasipaddress = '', pool_key = 0,
callingstationid = '', expiry_time = 'now'::timestamp(0) - '1
second'::interval WHERE nasipaddress = '172.23.4.2' AND pool_key = ''
(0) sqlippool: Executing query: UPDATE radippool SET nasipaddress = '',
pool_key = 0, callingstationid = '', expiry_time = 'now'::timestamp(0) - '1
second'::interval WHERE nasipaddress = '172.23.4.2' AND pool_key = ''
rlm_sql_postgresql: Status: PGRES_COMMAND_OK
rlm_sql_postgresql: query affected rows = 0
(0) sqlippool: EXPAND COMMIT
(0) sqlippool: --> COMMIT
(0) sqlippool: Executing query: COMMIT
rlm_sql_postgresql: Status: PGRES_COMMAND_OK
rlm_sql_postgresql: query affected rows = 0
(0) sqlippool: EXPAND START TRANSACTION
(0) sqlippool: --> START TRANSACTION
(0) sqlippool: Executing query: START TRANSACTION
rlm_sql_postgresql: Status: PGRES_COMMAND_OK
rlm_sql_postgresql: query affected rows = 0
(0) sqlippool: EXPAND SELECT framedipaddress FROM radippool WHERE pool_name
= '%{control:Pool-Name}' AND expiry_time < 'now'::timestamp(0) ORDER BY
RANDOM() LIMIT 1 FOR UPDATE
(0) sqlippool: --> SELECT framedipaddress FROM radippool WHERE pool_name
= 'Fixo' AND expiry_time < 'now'::timestamp(0) ORDER BY RANDOM() LIMIT 1
FOR UPDATE
(0) sqlippool: Executing select query: SELECT framedipaddress FROM
radippool WHERE pool_name = 'Fixo' AND expiry_time < 'now'::timestamp(0)
ORDER BY RANDOM() LIMIT 1 FOR UPDATE
rlm_sql_postgresql: Status: PGRES_TUPLES_OK
rlm_sql_postgresql: query affected rows = 1 , fields = 1
(0) sqlippool: Allocated IP 177.38.114.9
(0) sqlippool: EXPAND UPDATE radippool SET nasipaddress =
'%{NAS-IP-Address}', pool_key = '%{Calling-Station-Id}', callingstationid =
'%{Calling-Station-Id}', username = '%{SQL-User-Name}', expiry_time =
'now'::timestamp(0) + '3600 second'::interval WHERE framedipaddress =
'177.38.114.9'
(0) sqlippool: --> UPDATE radippool SET nasipaddress = '172.23.4.2',
pool_key = '', callingstationid = '', username = 'tiago at tmw.net',
expiry_time = 'now'::timestamp(0) + '3600 second'::interval WHERE
framedipaddress = '177.38.114.9'
(0) sqlippool: Executing query: UPDATE radippool SET nasipaddress =
'172.23.4.2', pool_key = '', callingstationid = '', username = '
tiago at tmw.net', expiry_time = 'now'::timestamp(0) + '3600 second'::interval
WHERE framedipaddress = '177.38.114.9'
rlm_sql_postgresql: Status: PGRES_COMMAND_OK
rlm_sql_postgresql: query affected rows = 1
(0) sqlippool: EXPAND COMMIT
(0) sqlippool: --> COMMIT
(0) sqlippool: Executing query: COMMIT
rlm_sql_postgresql: Status: PGRES_COMMAND_OK
rlm_sql_postgresql: query affected rows = 0
rlm_sql (sql): Released connection (7)
(0) sqlippool: EXPAND Allocated IP: %{reply:Framed-IP-Address} from
%{control:Pool-Name} (did %{Called-Station-Id} cli %{Calling-Station-Id}
port %{NAS-Port} user %{User-Name})
(0) sqlippool: --> Allocated IP: 177.38.114.9 from Fixo (did cli port
user tiago at tmw.net)
(0) [sqlippool] = ok
(0) [exec] = noop
(0) policy remove_reply_message_if_eap {
(0) if (&reply:EAP-Message && &reply:Reply-Message) {
(0) if (&reply:EAP-Message && &reply:Reply-Message) -> FALSE
(0) else {
(0) [noop] = noop
(0) } # else = noop
(0) } # policy remove_reply_message_if_eap = noop
(0) } # post-auth = ok
(0) Sent Access-Accept Id 178 from 177.38.112.4:1812 to 172.23.4.2:16505
length 0
(0) Framed-IP-Address = 177.38.114.9
(0) Finished request
Waking up in 7.9 seconds.
(0) Cleaning up request packet ID 178 with timestamp +2043
Ready to process requests
2017-11-16 17:49 GMT-02:00 Alan DeKok <aland at deployingradius.com>:
>
> > On Nov 16, 2017, at 2:46 PM, Yahn do Amaral Almeida Pinheiro <
> yahnaamaralp at gmail.com> wrote:
> >
> > My Radacct is not working, can anyone help me?
> >
> > Radius -X:
>
> Post a debug log where it shows the server receiving, and processing, a
> packet.
>
> Alan DeKok.
>
>
> -
> List info/subscribe/unsubscribe? See http://www.freeradius.org/
> list/users.html
More information about the Freeradius-Users
mailing list