Checkrad problem with Acct-Unique-Session-Id

SC SCx kredaxx at gmail.com
Sat Nov 14 14:30:10 CET 2015


Freeradius 3.0.9

Hi,

I have a simple setup using Simultaneous-Use=1 and checkrad with sql as the
session backend.

[freeradius] ------------ [nas] ------------- [user]

server default {

listen {
        type = auth
        ipaddr = *
        port = 0
        limit {
              max_connections = 16
              lifetime = 0
              idle_timeout = 30
        }
}

listen {
        type = acct
        ipaddr = *
        port = 0
}

authorize {
        filter_username
        preprocess
        chap
        suffix
        custom_python
        expiration
        logintime
}

authenticate {
        Auth-Type CHAP {
                chap
        }
}

preacct {
        preprocess
        acct_unique
        suffix
}

accounting {
        custom_python
        -sql
        attr_filter.accounting_response
}


session {
        sql
}

post-auth {
        -sql
        Post-Auth-Type REJECT {
                attr_filter.access_reject
        }
  }

}

I got excited that I can use checkrad to immediately remove stale sessions
from radacct table by simply querying the nas.

So I tested a situation where I connect a client to the NAS.

radacct table looks now like this:

  id:1 acctsessionid:7427542-L_pppoe1-1
acctuniqueid:ef4c9a0535776f8a2a8f6de0f7afad48 username:user
nasipaddress:10.2.2.14 nasportid:em1 nasporttype:Ethernet
acctstarttime:2015-11-13
16:12:21 acctupdatetime:2015-11-13 16:12:21 acctstoptime:NULL

I then proceed to reboot the nas (non-gracefully) to simulate the effect of
nas hardware failure.

Once the nas is up, a connection attempt is made by the client.

The access request received has a different Acct-Session-Id:
7427566-L_pppoe1-1 (the previous one was: 7427542-L_pppoe1-1)

During the request radius checks for an existing session in radacct

  SELECT COUNT(*) FROM radacct WHERE username = 'user' AND acctstoptime IS
NULL

It returns 1, so it queries for additional data to invoke checkrad with

  SELECT radacctid, acctsessionid, username, nasipaddress, nasportid,
framedipaddress, callingstationid, framedprotocol FROM radacct WHERE
username = 'user' AND acctstoptime IS NULL

Checkrad is invoked with params: ( nas_ip: 10.2.2.14, nas_port: 0,
session_id: 7427542-L_pppoe1-1, login: user ).

Return code is 0 (no logged user) so it's time to cleanup a stale session.
(And this is where problems start)

Since this Access-Request has a different Acct-Session-Id, the hash value
of Acct-Unique-Session-Id is different.

An update query is called to remove the stale session, but because of the
different Acct-Unique-Session-Id it doesn't match the previous session
entry.

  UPDATE radacct SET acctstoptime = FROM_UNIXTIME(1447427566),
acctsessiontime    = 192, acctinputoctets  = '0' << 32 | '0',
acctoutputoctets = '0' << 32 | '0', acctterminatecause = '',
connectinfo_stop = '' WHERE AcctUniqueId =
'9785b846930595ba6d83f5955a13fa1d'

Then a queued? (Says 'trying next query...') query is called which inserts
a new session entry to radacct table:

  INSERT INTO radacct (acctsessionid,           acctuniqueid,
username, realm,                        nasipaddress,           nasportid,
nasporttype,         acctstarttime,               acctupdatetime,
acctstoptime,           acctsessiontime,        acctauthentic,
connectinfo_start,       connectinfo_stop,       acctinputoctets,
acctoutputoctets,      calledstationid,     callingstationid,
acctterminatecause,   servicetype,            framedprotocol,
framedipaddress) VALUES ('7427542-L_pppoe1-1',
'9785b846930595ba6d83f5955a13fa1d', 'user', '', '10.2.2.14', '0', '',
FROM_UNIXTIME(1447427566 - 192), FROM_UNIXTIME(1447427566),
FROM_UNIXTIME(1447427566), 192, '', '', '', '0' << 32 | '0', '0' << 32 |
'0', '', '', '', 'Framed-User', 'PPP', '10.10.11.42')

At this point radacct table looks like this:

  id:1  acctsessionid:7427542-L_pppoe1-1
acctuniqueid:ef4c9a0535776f8a2a8f6de0f7afad48 username:user
nasipaddress:10.2.2.14 nasportid:em1 nasporttype:Ethernet
acctstarttime:2015-11-13
16:12:21 acctupdatetime:2015-11-13 16:12:21 acctstoptime:NULL

  id:2  acctsessionid:7427542-L_pppoe1-1
acctuniqueid:9785b846930595ba6d83f5955a13fa1d username:user
nasipaddress:10.2.2.14 nasportid:0 nasporttype:Ethernet
acctstarttime:2015-11-13
16:12:21 acctupdatetime:2015-11-13 16:12:21 acctstoptime:2015-11-13 16:12:46

Now an Accounting-Request comes in and anoher radacct table insert is made:

  INSERT INTO radacct (acctsessionid,           acctuniqueid,
username, realm,                        nasipaddress,           nasportid,
nasporttype,         acctstarttime,               acctupdatetime,
acctstoptime,           acctsessiontime,        acctauthentic,
connectinfo_start,       connectinfo_stop,       acctinputoctets,
acctoutputoctets,      calledstationid,     callingstationid,
acctterminatecause,   servicetype,            framedprotocol,
framedipaddress) VALUES ('7427566-L_pppoe1-1',
'502963895dc1d5a8f1d967d6f1e3db04', 'user', '', '10.2.2.14', 'em1',
'Ethernet', FROM_UNIXTIME(1447427566), FROM_UNIXTIME(1447427566), NULL,
'0', 'RADIUS', '', '', '0', '0', 'service1', '6a:61:0a:7f:37:27', '',
'Framed-User', 'PPP', '10.10.11.42')

At this point radacct table looks like this:

  id:1 acctsessionid:7427542-L_pppoe1-1
acctuniqueid:ef4c9a0535776f8a2a8f6de0f7afad48 username:user
nasipaddress:10.2.2.14 nasportid:em1 nasporttype:Ethernet
acctstarttime:2015-11-13
16:12:21 acctupdatetime:2015-11-13 16:12:21 acctstoptime:NULL

  id:2 acctsessionid:7427542-L_pppoe1-1
acctuniqueid:9785b846930595ba6d83f5955a13fa1d username:user
nasipaddress:10.2.2.14 nasportid:0 nasporttype:Ethernet
acctstarttime:2015-11-13
16:09:34 acctupdatetime:2015-11-13 16:12:46 acctstoptime:2015-11-13 16:12:46

  id:3 acctsessionid:7427542-L_pppoe1-1
acctuniqueid:502963895dc1d5a8f1d967d6f1e3db04 username:user
nasipaddress:10.2.2.14 nasportid:em1 nasporttype:Ethernet
acctstarttime:2015-11-13
16:12:46 acctupdatetime:2015-11-13 16:12:46 acctstoptime:NULL

So there's a total 3 records when I would expect to see just 2.

Bad news is that whenever "user" connects it will force checkrad to be
called always (since there always will be a stale session). Good news is
that the "user" will be allowed because checkrad will correctly report that
there's no such user logged in the nas.

One solution I see would be to use a cronjob to periodically remove such
stale entries.

However I thought that the whole point of checkrad was to close such
entries in the first place.

Checkrad is supplied with parameters from this query:

  SELECT radacctid, acctsessionid, username, nasipaddress, nasportid,
framedipaddress, callingstationid, framedprotocol FROM radacct WHERE
username = 'user' AND acctstoptime IS NULL

Among them is 'AcctSessionId' which I would expect to be used to close a
stale session, but instead in the update query 'AcctUniqueId' from the
current request is used which will never match. Leaving a stale entry
behind.

Anything I can do to fix it? Or is a cronjob the only solution (but then it
means that checkrad is a little bit wonky)

Thank you.




Below I supplied a debug log of:

1)Access-Request
2)Accounting-Request
[nas gets killed at this point and reboots]
3)Access-Request
4)Accounting-Request


Listening on proxy address * port 22303
Ready to process requests
(0) Received Access-Request Id 66 from 10.2.2.14:30089 to 10.2.2.13:1812
length 237
(0)   NAS-Identifier = "ppoe"
(0)   Message-Authenticator = 0x6d2402b5a07673ab6e60fe1a5f36cc52
(0)   Acct-Session-Id = "7427542-L_pppoe1-1"
(0)   NAS-Port = 1
(0)   NAS-Port-Type = Ethernet
(0)   Service-Type = Framed-User
(0)   Framed-Protocol = PPP
(0)   Calling-Station-Id = "6a:61:0a:7f:37:27"
(0)   Called-Station-Id = "service1"
(0)   NAS-Port-Id = "em1"
(0)   Attr-26.12341.12 = 0x4c5f7070706f65312d31
(0)   Attr-26 = 0x000030351302
(0)   Tunnel-Medium-Type:0 = IEEE-802
(0)   Tunnel-Client-Endpoint:0 = "6a:61:0a:7f:37:27"
(0)   User-Name = "user"
(0)   CHAP-Challenge =
0xbb1e687466a51fdc396ecbd5c48e2bafbf72350a8f492cc599e7b446dbbb3ab320f0288695
(0)   CHAP-Password = 0x01c71a4709e5ae36393254df5afe44adf3
(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)  -> FALSE
(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)     } # policy filter_username = notfound
(0)     [preprocess] = ok
(0) chap:   &control:Auth-Type := CHAP
(0)     [chap] = ok
(0) suffix: Checking for suffix after "@"
(0) suffix: No '@' in User-Name = "user", looking up realm NULL
(0) suffix: No such realm "NULL"
(0)     [suffix] = noop
rlm_python:authorize: 'MS-Primary-DNS-Server' = '10.10.11.1'
rlm_python:authorize: 'MS-Secondary-DNS-Server' = '8.8.8.8'
rlm_python:authorize: 'Framed-Ip-Address' = '10.10.11.42'
rlm_python:authorize: 'Simultaneous-Use' = '1'
rlm_python:authorize: 'Cleartext-Password' = 'pass123'
(0)     [custom_python] = updated
(0)     [expiration] = noop
(0)     [logintime] = noop
(0)   } # authorize = updated
(0) Found Auth-Type = CHAP
(0) # Executing group from file /usr/local/etc/raddb/sites-enabled/default
(0)   Auth-Type CHAP {
(0) chap: Comparing with "known good" Cleartext-Password
(0) chap: CHAP user "user" authenticated successfully
(0)     [chap] = ok
(0)   } # Auth-Type CHAP = ok
(0) # Executing section session from file
/usr/local/etc/raddb/sites-enabled/default
(0)   session {
(0) sql: EXPAND %{User-Name}
(0) sql:    --> user
(0) sql: SQL-User-Name set to 'user'
(0) sql: EXPAND SELECT COUNT(*) FROM radacct WHERE username =
'%{SQL-User-Name}' AND acctstoptime IS NULL
(0) sql:    --> SELECT COUNT(*) FROM radacct WHERE username = 'user' AND
acctstoptime IS NULL
rlm_sql (sql): Reserved connection (0)
(0) sql: Executing select query: SELECT COUNT(*) FROM radacct WHERE
username = 'user' AND acctstoptime IS NULL
rlm_sql (sql): Released connection (0)
rlm_sql (sql): 0 of 5 connections in use.  Need more spares
rlm_sql (sql): Opening additional connection (5), 1 of 27 pending slots used
rlm_sql_mysql: Starting connect to MySQL server
rlm_sql_mysql: Connected to database 'lms' on Localhost via UNIX socket,
server version 10.0.21-MariaDB, protocol version 10
(0)     [sql] = ok
(0)   } # session = ok
(0) # Executing section post-auth from file
/usr/local/etc/raddb/sites-enabled/default
(0)   post-auth {
(0) sql: EXPAND .query
(0) sql:    --> .query
(0) sql: Using query template 'query'
rlm_sql (sql): Reserved connection (1)
(0) sql: EXPAND %{User-Name}
(0) sql:    --> user
(0) sql: SQL-User-Name set to 'user'
(0) sql: EXPAND INSERT INTO radpostauth (username, pass, reply, authdate)
VALUES ( '%{SQL-User-Name}', '%{%{User-Password}:-%{Chap-Password}}',
'%{reply:Packet-Type}', '%S')
(0) sql:    --> INSERT INTO radpostauth (username, pass, reply, authdate)
VALUES ( 'user', '0x01c71a4709e5ae36393254df5afe44adf3', 'Access-Accept',
'2015-11-13 16:12:21')
(0) sql: Executing query: INSERT INTO radpostauth (username, pass, reply,
authdate) VALUES ( 'user', '0x01c71a4709e5ae36393254df5afe44adf3',
'Access-Accept', '2015-11-13 16:12:21')
(0) sql: SQL query returned: success
(0) sql: 1 record(s) updated
rlm_sql (sql): Released connection (1)
(0)     [sql] = ok
(0)   } # post-auth = ok
(0) Sent Access-Accept Id 66 from 10.2.2.13:1812 to 10.2.2.14:30089 length
0
(0)   MS-Primary-DNS-Server = 10.10.11.1
(0)   MS-Secondary-DNS-Server = 8.8.8.8
(0)   Framed-IP-Address = 10.10.11.42
(0) Finished request
Waking up in 4.9 seconds.
(1) Received Accounting-Request Id 6 from 10.2.2.14:21504 to 10.2.2.13:1813
length 254
(1)   NAS-Identifier = "ppoe"
(1)   Acct-Session-Id = "7427542-L_pppoe1-1"
(1)   NAS-Port = 1
(1)   NAS-Port-Type = Ethernet
(1)   Service-Type = Framed-User
(1)   Framed-Protocol = PPP
(1)   Calling-Station-Id = "6a:61:0a:7f:37:27"
(1)   Called-Station-Id = "service1"
(1)   NAS-Port-Id = "em1"
(1)   Attr-26.12341.12 = 0x4c5f7070706f65312d31
(1)   Attr-26 = 0x000030351302
(1)   Tunnel-Medium-Type:0 = IEEE-802
(1)   Tunnel-Client-Endpoint:0 = "6a:61:0a:7f:37:27"
(1)   Acct-Status-Type = Start
(1)   Framed-IP-Address = 10.10.11.42
(1)   User-Name = "user"
(1)   Acct-Multi-Session-Id = "7427542-B_pppoe1-1"
(1)   Attr-26.12341.13 = 0x425f7070706f65312d31
(1)   Attr-26.12341.14 = 0x6e6730
(1)   Attr-26.12341.15 = 0x00000004
(1)   Attr-26 = 0x000030351302
(1)   Acct-Link-Count = 1
(1)   Acct-Authentic = RADIUS
(1) # Executing section preacct from file
/usr/local/etc/raddb/sites-enabled/default
(1)   preacct {
(1)     [preprocess] = ok
(1)     policy acct_unique {
(1)       if ("%{string:Class}" =~ /ai:([0-9a-f]{32})/i) {
(1)       EXPAND %{string:Class}
(1)          -->
(1)       if ("%{string:Class}" =~ /ai:([0-9a-f]{32})/i)  -> FALSE
(1)       else {
(1)         update request {
(1)           EXPAND
%{md5:%{User-Name},%{Acct-Session-ID},%{%{NAS-IPv6-Address}:-%{NAS-IP-Address}},%{NAS-Identifier},%{NAS-Port-ID},%{NAS-Port}}
(1)              --> ef4c9a0535776f8a2a8f6de0f7afad48
(1)           &Acct-Unique-Session-Id := ef4c9a0535776f8a2a8f6de0f7afad48
(1)         } # update request = noop
(1)       } # else = noop
(1)     } # policy acct_unique = noop
(1) suffix: Checking for suffix after "@"
(1) suffix: No '@' in User-Name = "user", looking up realm NULL
(1) suffix: No such realm "NULL"
(1)     [suffix] = noop
(1)   } # preacct = ok
(1) # Executing section accounting from file
/usr/local/etc/raddb/sites-enabled/default
(1)   accounting {
(1)     [custom_python] = noop
(1) sql: EXPAND %{tolower:type.%{Acct-Status-Type}.query}
(1) sql:    --> type.start.query
(1) sql: Using query template 'query'
rlm_sql (sql): Reserved connection (2)
(1) sql: EXPAND %{User-Name}
(1) sql:    --> user
(1) sql: SQL-User-Name set to 'user'
(1) sql: EXPAND INSERT INTO radacct (acctsessionid,
acctuniqueid,           username, realm,
 nasipaddress,           nasportid, nasporttype,         acctstarttime,
          acctupdatetime, acctstoptime,           acctsessiontime,
 acctauthentic, connectinfo_start,       connectinfo_stop,
acctinputoctets, acctoutputoctets,      calledstationid,
callingstationid, acctterminatecause,   servicetype,
 framedprotocol, framedipaddress) VALUES ('%{Acct-Session-Id}',
'%{Acct-Unique-Session-Id}', '%{SQL-User-Name}', '%{Realm}',
'%{NAS-IP-Address}', '%{%{NAS-Port-ID}:-%{NAS-Port}}', '%{NAS-Port-Type}',
FROM_UNIXTIME(%{integer:Event-Timestamp}),
FROM_UNIXTIME(%{integer:Event-Timestamp}), NULL, '0', '%{Acct-Authentic}',
'%{Connect-Info}', '', '0', '0', '%{Called-Station-Id}',
'%{Calling-Station-Id}', '', '%{Service-Type}', '%{Framed-Protocol}',
'%{Framed-IP-Address}')
(1) sql:    --> INSERT INTO radacct (acctsessionid,
acctuniqueid,           username, realm,
 nasipaddress,           nasportid, nasporttype,         acctstarttime,
          acctupdatetime, acctstoptime,           acctsessiontime,
 acctauthentic, connectinfo_start,       connectinfo_stop,
acctinputoctets, acctoutputoctets,      calledstationid,
callingstationid, acctterminatecause,   servicetype,
 framedprotocol, framedipaddress) VALUES ('7427542-L_pppoe1-1',
'ef4c9a0535776f8a2a8f6de0f7afad48', 'user', '', '10.2.2.14', 'em1',
'Ethernet', FROM_UNIXTIME(1447427541), FROM_UNIXTIME(1447427541), NULL,
'0', 'RADIUS', '', '', '0', '0', 'service1', '6a:61:0a:7f:37:27', '',
'Framed-User', 'PPP', '10.10.11.42')
(1) sql: Executing query: INSERT INTO radacct (acctsessionid,
acctuniqueid,           username, realm,
 nasipaddress,           nasportid, nasporttype,         acctstarttime,
          acctupdatetime, acctstoptime,           acctsessiontime,
 acctauthentic, connectinfo_start,       connectinfo_stop,
acctinputoctets, acctoutputoctets,      calledstationid,
callingstationid, acctterminatecause,   servicetype,
 framedprotocol, framedipaddress) VALUES ('7427542-L_pppoe1-1',
'ef4c9a0535776f8a2a8f6de0f7afad48', 'user', '', '10.2.2.14', 'em1',
'Ethernet', FROM_UNIXTIME(1447427541), FROM_UNIXTIME(1447427541), NULL,
'0', 'RADIUS', '', '', '0', '0', 'service1', '6a:61:0a:7f:37:27', '',
'Framed-User', 'PPP', '10.10.11.42')
(1) sql: SQL query returned: success
(1) sql: 1 record(s) updated
rlm_sql (sql): Released connection (2)
(1)     [sql] = ok
(1) attr_filter.accounting_response: EXPAND %{User-Name}
(1) attr_filter.accounting_response:    --> user
(1) attr_filter.accounting_response: Matched entry DEFAULT at line 15
(1)     [attr_filter.accounting_response] = updated
(1)   } # accounting = updated
(1) Sent Accounting-Response Id 6 from 10.2.2.13:1813 to 10.2.2.14:21504
length 0
(1) Finished request
(1) <done>: Cleaning up request packet ID 6 with timestamp +28
Waking up in 4.9 seconds.
(0) <done>: Cleaning up request packet ID 66 with timestamp +28
Ready to process requests
(3) Received Access-Request Id 228 from 10.2.2.14:19182 to 10.2.2.13:1812
length 234
(3)   NAS-Identifier = "ppoe"
(3)   Message-Authenticator = 0x8635f9c9047b7a815f56ac7539937a50
(3)   Acct-Session-Id = "7427566-L_pppoe1-1"
(3)   NAS-Port = 1
(3)   NAS-Port-Type = Ethernet
(3)   Service-Type = Framed-User
(3)   Framed-Protocol = PPP
(3)   Calling-Station-Id = "6a:61:0a:7f:37:27"
(3)   Called-Station-Id = "service1"
(3)   NAS-Port-Id = "em1"
(3)   Attr-26.12341.12 = 0x4c5f7070706f65312d31
(3)   Attr-26 = 0x000030351302
(3)   Tunnel-Medium-Type:0 = IEEE-802
(3)   Tunnel-Client-Endpoint:0 = "6a:61:0a:7f:37:27"
(3)   User-Name = "user"
(3)   CHAP-Challenge =
0xbb1e6800688010c3ef4cada327bf23a1f8bc2e4cf15e765693eb03a6eb1a0af5da9c
(3)   CHAP-Password = 0x01f29750c6827e6ff5e45baa625d131275
(3) # Executing section authorize from file
/usr/local/etc/raddb/sites-enabled/default
(3)   authorize {
(3)     policy filter_username {
(3)       if (!&User-Name) {
(3)       if (!&User-Name)  -> FALSE
(3)       if (&User-Name =~ / /) {
(3)       if (&User-Name =~ / /)  -> FALSE
(3)       if (&User-Name =~ /@.*@/ ) {
(3)       if (&User-Name =~ /@.*@/ )  -> FALSE
(3)       if (&User-Name =~ /\.\./ ) {
(3)       if (&User-Name =~ /\.\./ )  -> FALSE
(3)       if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/))  {
(3)       if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/))   ->
FALSE
(3)       if (&User-Name =~ /\.$/)  {
(3)       if (&User-Name =~ /\.$/)   -> FALSE
(3)       if (&User-Name =~ /@\./)  {
(3)       if (&User-Name =~ /@\./)   -> FALSE
(3)     } # policy filter_username = notfound
(3)     [preprocess] = ok
(3) chap:   &control:Auth-Type := CHAP
(3)     [chap] = ok
(3) suffix: Checking for suffix after "@"
(3) suffix: No '@' in User-Name = "user", looking up realm NULL
(3) suffix: No such realm "NULL"
(3)     [suffix] = noop
rlm_python:authorize: 'MS-Primary-DNS-Server' = '10.10.11.1'
rlm_python:authorize: 'MS-Secondary-DNS-Server' = '8.8.8.8'
rlm_python:authorize: 'Framed-Ip-Address' = '10.10.11.42'
rlm_python:authorize: 'Simultaneous-Use' = '1'
rlm_python:authorize: 'Cleartext-Password' = 'pass123'
(3)     [custom_python] = updated
(3)     [expiration] = noop
(3)     [logintime] = noop
(3)   } # authorize = updated
(3) Found Auth-Type = CHAP
(3) # Executing group from file /usr/local/etc/raddb/sites-enabled/default
(3)   Auth-Type CHAP {
(3) chap: Comparing with "known good" Cleartext-Password
(3) chap: CHAP user "user" authenticated successfully
(3)     [chap] = ok
(3)   } # Auth-Type CHAP = ok
(3) # Executing section session from file
/usr/local/etc/raddb/sites-enabled/default
(3)   session {
(3) sql: EXPAND %{User-Name}
(3) sql:    --> user
(3) sql: SQL-User-Name set to 'user'
(3) sql: EXPAND SELECT COUNT(*) FROM radacct WHERE username =
'%{SQL-User-Name}' AND acctstoptime IS NULL
(3) sql:    --> SELECT COUNT(*) FROM radacct WHERE username = 'user' AND
acctstoptime IS NULL
rlm_sql (sql): Reserved connection (3)
(3) sql: Executing select query: SELECT COUNT(*) FROM radacct WHERE
username = 'user' AND acctstoptime IS NULL
(3) sql: EXPAND SELECT radacctid, acctsessionid, username, nasipaddress,
nasportid, framedipaddress, callingstationid, framedprotocol FROM radacct
WHERE username = '%{SQL-User-Name}' AND acctstoptime IS NULL
(3) sql:    --> SELECT radacctid, acctsessionid, username, nasipaddress,
nasportid, framedipaddress, callingstationid, framedprotocol FROM radacct
WHERE username = 'user' AND acctstoptime IS NULL
(3) sql: Executing select query: SELECT radacctid, acctsessionid, username,
nasipaddress, nasportid, framedipaddress, callingstationid, framedprotocol
FROM radacct WHERE username = 'user' AND acctstoptime IS NULL
CHECKRAD CALLED !!! retcode was: 0, nas_ip: 10.2.2.14, nas_port: 0,
session_id: 7427542-L_pppoe1-1, login: user
(3) # Executing section preacct from file
/usr/local/etc/raddb/sites-enabled/default
(3)   preacct {
(3)     [preprocess] = ok
(3)     policy acct_unique {
(3)       if ("%{string:Class}" =~ /ai:([0-9a-f]{32})/i) {
(3)       EXPAND %{string:Class}
(3)          -->
(3)       if ("%{string:Class}" =~ /ai:([0-9a-f]{32})/i)  -> FALSE
(3)       else {
(3)         update request {
(3)           EXPAND
%{md5:%{User-Name},%{Acct-Session-ID},%{%{NAS-IPv6-Address}:-%{NAS-IP-Address}},%{NAS-Identifier},%{NAS-Port-ID},%{NAS-Port}}
(3)              --> 9785b846930595ba6d83f5955a13fa1d
(3)           &Acct-Unique-Session-Id := 9785b846930595ba6d83f5955a13fa1d
(3)         } # update request = noop
(3)       } # else = noop
(3)     } # policy acct_unique = noop
(3) suffix: Checking for suffix after "@"
(3) suffix: No '@' in User-Name = "user", looking up realm NULL
(3) suffix: No such realm "NULL"
(3)     [suffix] = noop
(3)   } # preacct = ok
(3) # Executing section accounting from file
/usr/local/etc/raddb/sites-enabled/default
(3)   accounting {
(3)     [custom_python] = noop
(3) sql: EXPAND %{tolower:type.%{Acct-Status-Type}.query}
(3) sql:    --> type.stop.query
(3) sql: Using query template 'query'
rlm_sql (sql): Reserved connection (4)
(3) sql: EXPAND %{User-Name}
(3) sql:    --> user
(3) sql: SQL-User-Name set to 'user'
(3) sql: EXPAND UPDATE radacct SET acctstoptime =
FROM_UNIXTIME(%{integer:Event-Timestamp}), acctsessiontime    =
%{%{Acct-Session-Time}:-NULL}, acctinputoctets        =
'%{%{Acct-Input-Gigawords}:-0}' << 32 | '%{%{Acct-Input-Octets}:-0}',
acctoutputoctets = '%{%{Acct-Output-Gigawords}:-0}' << 32 |
'%{%{Acct-Output-Octets}:-0}', acctterminatecause =
'%{Acct-Terminate-Cause}', connectinfo_stop = '%{Connect-Info}' WHERE
AcctUniqueId = '%{Acct-Unique-Session-Id}'
(3) sql:    --> UPDATE radacct SET acctstoptime =
FROM_UNIXTIME(1447427566), acctsessiontime    = 192, acctinputoctets  = '0'
<< 32 | '0', acctoutputoctets = '0' << 32 | '0', acctterminatecause = '',
connectinfo_stop = '' WHERE AcctUniqueId =
'9785b846930595ba6d83f5955a13fa1d'
(3) sql: Executing query: UPDATE radacct SET acctstoptime       =
FROM_UNIXTIME(1447427566), acctsessiontime    = 192, acctinputoctets  = '0'
<< 32 | '0', acctoutputoctets = '0' << 32 | '0', acctterminatecause = '',
connectinfo_stop = '' WHERE AcctUniqueId =
'9785b846930595ba6d83f5955a13fa1d'
rlm_sql_mysql: Rows matched: 0  Changed: 0  Warnings: 0
(3) sql: SQL query returned: success
(3) sql: 0 record(s) updated
(3) sql: Trying next query...
(3) sql: EXPAND INSERT INTO radacct (acctsessionid,
acctuniqueid,           username, realm,
 nasipaddress,           nasportid, nasporttype,         acctstarttime,
          acctupdatetime, acctstoptime,           acctsessiontime,
 acctauthentic, connectinfo_start,       connectinfo_stop,
acctinputoctets, acctoutputoctets,      calledstationid,
callingstationid, acctterminatecause,   servicetype,
 framedprotocol, framedipaddress) VALUES ('%{Acct-Session-Id}',
'%{Acct-Unique-Session-Id}', '%{SQL-User-Name}', '%{Realm}',
'%{NAS-IP-Address}', '%{%{NAS-Port-ID}:-%{NAS-Port}}', '%{NAS-Port-Type}',
FROM_UNIXTIME(%{integer:Event-Timestamp} - %{%{Acct-Session-Time}:-0}),
FROM_UNIXTIME(%{integer:Event-Timestamp}),
FROM_UNIXTIME(%{integer:Event-Timestamp}), %{%{Acct-Session-Time}:-NULL},
'%{Acct-Authentic}', '', '%{Connect-Info}', '%{%{Acct-Input-Gigawords}:-0}'
<< 32 | '%{%{Acct-Input-Octets}:-0}', '%{%{Acct-Output-Gigawords}:-0}' <<
32 | '%{%{Acct-Output-Octets}:-0}', '%{Called-Station-Id}',
'%{Calling-Station-Id}', '%{Acct-Terminate-Cause}', '%{Service-Type}',
'%{Framed-Protocol}', '%{Framed-IP-Address}')
(3) sql:    --> INSERT INTO radacct (acctsessionid,
acctuniqueid,           username, realm,
 nasipaddress,           nasportid, nasporttype,         acctstarttime,
          acctupdatetime, acctstoptime,           acctsessiontime,
 acctauthentic, connectinfo_start,       connectinfo_stop,
acctinputoctets, acctoutputoctets,      calledstationid,
callingstationid, acctterminatecause,   servicetype,
 framedprotocol, framedipaddress) VALUES ('7427542-L_pppoe1-1',
'9785b846930595ba6d83f5955a13fa1d', 'user', '', '10.2.2.14', '0', '',
FROM_UNIXTIME(1447427566 - 192), FROM_UNIXTIME(1447427566),
FROM_UNIXTIME(1447427566), 192, '', '', '', '0' << 32 | '0', '0' << 32 |
'0', '', '', '', 'Framed-User', 'PPP', '10.10.11.42')
(3) sql: Executing query: INSERT INTO radacct (acctsessionid,
acctuniqueid,           username, realm,
 nasipaddress,           nasportid, nasporttype,         acctstarttime,
          acctupdatetime, acctstoptime,           acctsessiontime,
 acctauthentic, connectinfo_start,       connectinfo_stop,
acctinputoctets, acctoutputoctets,      calledstationid,
callingstationid, acctterminatecause,   servicetype,
 framedprotocol, framedipaddress) VALUES ('7427542-L_pppoe1-1',
'9785b846930595ba6d83f5955a13fa1d', 'user', '', '10.2.2.14', '0', '',
FROM_UNIXTIME(1447427566 - 192), FROM_UNIXTIME(1447427566),
FROM_UNIXTIME(1447427566), 192, '', '', '', '0' << 32 | '0', '0' << 32 |
'0', '', '', '', 'Framed-User', 'PPP', '10.10.11.42')
(3) sql: SQL query returned: success
(3) sql: 1 record(s) updated
rlm_sql (sql): Released connection (4)
rlm_sql (sql): 1 of 6 connections in use.  Need more spares
rlm_sql (sql): Opening additional connection (6), 1 of 26 pending slots used
rlm_sql_mysql: Starting connect to MySQL server
rlm_sql_mysql: Connected to database 'lms' on Localhost via UNIX socket,
server version 10.0.21-MariaDB, protocol version 10
(3)     [sql] = ok
(3) attr_filter.accounting_response: EXPAND %{User-Name}
(3) attr_filter.accounting_response:    --> user
(3) attr_filter.accounting_response: Matched entry DEFAULT at line 15
(3)     [attr_filter.accounting_response] = updated
(3)   } # accounting = updated
rlm_sql (sql): Released connection (3)
(3)     [sql] = ok
(3)   } # session = ok
(3) # Executing section post-auth from file
/usr/local/etc/raddb/sites-enabled/default
(3)   post-auth {
(3) sql: EXPAND .query
(3) sql:    --> .query
(3) sql: Using query template 'query'
rlm_sql (sql): Reserved connection (0)
(3) sql: EXPAND %{User-Name}
(3) sql:    --> user
(3) sql: SQL-User-Name set to 'user'
(3) sql: EXPAND INSERT INTO radpostauth (username, pass, reply, authdate)
VALUES ( '%{SQL-User-Name}', '%{%{User-Password}:-%{Chap-Password}}',
'%{reply:Packet-Type}', '%S')
(3) sql:    --> INSERT INTO radpostauth (username, pass, reply, authdate)
VALUES ( 'user', '0x01f29750c6827e6ff5e45baa625d131275', 'Access-Accept',
'2015-11-13 16:12:46')
(3) sql: Executing query: INSERT INTO radpostauth (username, pass, reply,
authdate) VALUES ( 'user', '0x01f29750c6827e6ff5e45baa625d131275',
'Access-Accept', '2015-11-13 16:12:46')
(3) sql: SQL query returned: success
(3) sql: 1 record(s) updated
rlm_sql (sql): Released connection (0)
(3)     [sql] = ok
(3)   } # post-auth = ok
(3) Sent Access-Accept Id 228 from 10.2.2.13:1812 to 10.2.2.14:19182 length
0
(3)   MS-Primary-DNS-Server = 10.10.11.1
(3)   MS-Secondary-DNS-Server = 8.8.8.8
(3)   Framed-IP-Address = 10.10.11.42
(3) Finished request
Waking up in 4.9 seconds.
(4) Received Accounting-Request Id 31 from 10.2.2.14:16585 to 10.2.2.13:1813
length 254
(4)   NAS-Identifier = "ppoe"
(4)   Acct-Session-Id = "7427566-L_pppoe1-1"
(4)   NAS-Port = 1
(4)   NAS-Port-Type = Ethernet
(4)   Service-Type = Framed-User
(4)   Framed-Protocol = PPP
(4)   Calling-Station-Id = "6a:61:0a:7f:37:27"
(4)   Called-Station-Id = "service1"
(4)   NAS-Port-Id = "em1"
(4)   Attr-26.12341.12 = 0x4c5f7070706f65312d31
(4)   Attr-26 = 0x000030351302
(4)   Tunnel-Medium-Type:0 = IEEE-802
(4)   Tunnel-Client-Endpoint:0 = "6a:61:0a:7f:37:27"
(4)   Acct-Status-Type = Start
(4)   Framed-IP-Address = 10.10.11.42
(4)   User-Name = "user"
(4)   Acct-Multi-Session-Id = "7427567-B_pppoe1-1"
(4)   Attr-26.12341.13 = 0x425f7070706f65312d31
(4)   Attr-26.12341.14 = 0x6e6730
(4)   Attr-26.12341.15 = 0x00000004
(4)   Attr-26 = 0x000030351302
(4)   Acct-Link-Count = 1i
(4)   Acct-Authentic = RADIUS
(4) # Executing section preacct from file
/usr/local/etc/raddb/sites-enabled/default
(4)   preacct {
(4)     [preprocess] = ok
(4)     policy acct_unique {
(4)       if ("%{string:Class}" =~ /ai:([0-9a-f]{32})/i) {
(4)       EXPAND %{string:Class}
(4)          -->
(4)       if ("%{string:Class}" =~ /ai:([0-9a-f]{32})/i)  -> FALSE
(4)       else {
(4)         update request {
(4)           EXPAND
%{md5:%{User-Name},%{Acct-Session-ID},%{%{NAS-IPv6-Address}:-%{NAS-IP-Address}},%{NAS-Identifier},%{NAS-Port-ID},%{NAS-Port}}
(4)              --> 502963895dc1d5a8f1d967d6f1e3db04
(4)           &Acct-Unique-Session-Id := 502963895dc1d5a8f1d967d6f1e3db04
(4)         } # update request = noop
(4)       } # else = noop
(4)     } # policy acct_unique = noop
(4) suffix: Checking for suffix after "@"
(4) suffix: No '@' in User-Name = "user", looking up realm NULL
(4) suffix: No such realm "NULL"
(4)     [suffix] = noop
(4)   } # preacct = ok
(4) # Executing section accounting from file
/usr/local/etc/raddb/sites-enabled/default
(4)   accounting {
(4)     [custom_python] = noop
(4) sql: EXPAND %{tolower:type.%{Acct-Status-Type}.query}
(4) sql:    --> type.start.query
(4) sql: Using query template 'query'
rlm_sql (sql): Reserved connection (5)
(4) sql: EXPAND %{User-Name}
(4) sql:    --> user
(4) sql: SQL-User-Name set to 'user'
(4) sql: EXPAND INSERT INTO radacct (acctsessionid,
acctuniqueid,           username, realm,
 nasipaddress,           nasportid, nasporttype,         acctstarttime,
          acctupdatetime, acctstoptime,           acctsessiontime,
 acctauthentic, connectinfo_start,       connectinfo_stop,
acctinputoctets, acctoutputoctets,      calledstationid,
callingstationid, acctterminatecause,   servicetype,
 framedprotocol, framedipaddress) VALUES ('%{Acct-Session-Id}',
'%{Acct-Unique-Session-Id}', '%{SQL-User-Name}', '%{Realm}',
'%{NAS-IP-Address}', '%{%{NAS-Port-ID}:-%{NAS-Port}}', '%{NAS-Port-Type}',
FROM_UNIXTIME(%{integer:Event-Timestamp}),
FROM_UNIXTIME(%{integer:Event-Timestamp}), NULL, '0', '%{Acct-Authentic}',
'%{Connect-Info}', '', '0', '0', '%{Called-Station-Id}',
'%{Calling-Station-Id}', '', '%{Service-Type}', '%{Framed-Protocol}',
'%{Framed-IP-Address}')
(4) sql:    --> INSERT INTO radacct (acctsessionid,
acctuniqueid,           username, realm,
 nasipaddress,           nasportid, nasporttype,         acctstarttime,
          acctupdatetime, acctstoptime,           acctsessiontime,
 acctauthentic, connectinfo_start,       connectinfo_stop,
acctinputoctets, acctoutputoctets,      calledstationid,
callingstationid, acctterminatecause,   servicetype,
 framedprotocol, framedipaddress) VALUES ('7427566-L_pppoe1-1',
'502963895dc1d5a8f1d967d6f1e3db04', 'user', '', '10.2.2.14', 'em1',
'Ethernet', FROM_UNIXTIME(1447427566), FROM_UNIXTIME(1447427566), NULL,
'0', 'RADIUS', '', '', '0', '0', 'service1', '6a:61:0a:7f:37:27', '',
'Framed-User', 'PPP', '10.10.11.42')
(4) sql: Executing query: INSERT INTO radacct (acctsessionid,
acctuniqueid,           username, realm,
 nasipaddress,           nasportid, nasporttype,         acctstarttime,
          acctupdatetime, acctstoptime,           acctsessiontime,
 acctauthentic, connectinfo_start,       connectinfo_stop,
acctinputoctets, acctoutputoctets,      calledstationid,
callingstationid, acctterminatecause,   servicetype,
 framedprotocol, framedipaddress) VALUES ('7427566-L_pppoe1-1',
'502963895dc1d5a8f1d967d6f1e3db04', 'user', '', '10.2.2.14', 'em1',
'Ethernet', FROM_UNIXTIME(1447427566), FROM_UNIXTIME(1447427566), NULL,
'0', 'RADIUS', '', '', '0', '0', 'service1', '6a:61:0a:7f:37:27', '',
'Framed-User', 'PPP', '10.10.11.42')
(4) sql: SQL query returned: success
(4) sql: 1 record(s) updated
rlm_sql (sql): Released connection (5)
(4)     [sql] = ok
(4) attr_filter.accounting_response: EXPAND %{User-Name}
(4) attr_filter.accounting_response:    --> user
(4) attr_filter.accounting_response: Matched entry DEFAULT at line 15
(4)     [attr_filter.accounting_response] = updated
(4)   } # accounting = updated
(4) Sent Accounting-Response Id 31 from 10.2.2.13:1813 to 10.2.2.14:16585
length 0
(4) Finished request
(4) <done>: Cleaning up request packet ID 31 with timestamp +53
Waking up in 4.9 seconds.
(3) <done>: Cleaning up request packet ID 228 with timestamp +53


More information about the Freeradius-Users mailing list