Re: radius accounting not starting....

15 Mar 2019

...
The NAS isn't sending accounting packets.  So... fix the NAS to send
accounting packets.
No amount of poking FreeRADIUS will make the NAS send accounting packets.
Alan DeKok.
Many thanks for the suggestion.after modified radius IP in controller it
worked. but still not getting data in radaact table.showing error like
"Incorrect datetime value: '1552660521' for column 'acctstarttime' at row
1". Please help.

here are the logs:

freeradius    | (0) Received Access-Request Id 169 from 192.168.0.4:47212
to 172.25.0.101:1812 length 182
freeradius    | (0)   Service-Type = Login-User
freeradius    | (0)   Framed-MTU = 1250
freeradius    | (0)   User-Name = "12378@@TM11"
freeradius    | (0)   User-Password = "55587a910882016321201e6ebbc9f595"
freeradius    | (0)   Calling-Station-Id = "9c:4e:36:9c:71:18"
freeradius    | (0)   Called-Station-Id = "00:0c:29:67:6d:ec"
freeradius    | (0)   Connect-Info = "CONNECT Unknown Radio"
freeradius    | (0)   Framed-IP-Address = 10.0.1.24
freeradius    | (0)   NAS-IP-Address = 192.168.0.4
freeradius    | (0)   NAS-Port-Type = Wireless-802.11
freeradius    | (0)   NAS-Port = 0
freeradius    | (0)   Message-Authenticator =
0x6216234be27c84e63e635425868cbca5
freeradius    | (0) # Executing section authorize from file
/etc/freeradius/sites-enabled/default
freeradius    | (0)   authorize {
freeradius    | (0)     policy filter_username {
freeradius    | (0)       if (&User-Name) {
freeradius    | (0)       if (&User-Name)  -> TRUE
freeradius    | (0)       if (&User-Name)  {
freeradius    | (0)         if (&User-Name =~ / /) {
freeradius    | (0)         if (&User-Name =~ / /)  -> FALSE
freeradius    | (0)         if (&User-Name =~ /\.\./ ) {
freeradius    | (0)         if (&User-Name =~ /\.\./ )  -> FALSE
freeradius    | (0)         if (&User-Name =~ /\.$/)  {
freeradius    | (0)         if (&User-Name =~ /\.$/)   -> FALSE
freeradius    | (0)         if (&User-Name =~ /@\./)  {
freeradius    | (0)         if (&User-Name =~ /@\./)   -> FALSE
freeradius    | (0)       } # if (&User-Name)  = notfound
freeradius    | (0)     } # policy filter_username = notfound
freeradius    | (0)     [preprocess] = ok
freeradius    | (0)     [chap] = noop
freeradius    | (0)     [mschap] = noop
freeradius    | (0)     [digest] = noop
freeradius    | (0) suffix: Checking for suffix after "@"
freeradius    | (0) suffix: Looking up realm "TM11" for User-Name =
"12378@@TM11"
freeradius    | (0) suffix: No such realm "TM11"
freeradius    | (0)     [suffix] = noop
freeradius    | (0) eap: No EAP-Message, not doing EAP
freeradius    | (0)     [eap] = noop
freeradius    | (0)     [files] = noop
freeradius    | (0) sql: EXPAND %{User-Name}
freeradius    | (0) sql:    --> 12378@@TM11
freeradius    | (0) sql: SQL-User-Name set to '12378@@TM11'
freeradius    | rlm_sql (sql): Closing connection (1): Hit idle_timeout,
was idle for 68 seconds
freeradius    | rlm_sql_mysql: Socket destructor called, closing socket
freeradius    | rlm_sql (sql): Closing connection (2): Hit idle_timeout,
was idle for 68 seconds
freeradius    | rlm_sql_mysql: Socket destructor called, closing socket
freeradius    | rlm_sql (sql): Closing connection (3): Hit idle_timeout,
was idle for 68 seconds
freeradius    | rlm_sql_mysql: Socket destructor called, closing socket
freeradius    | rlm_sql (sql): Closing connection (4): Hit idle_timeout,
was idle for 68 seconds
freeradius    | rlm_sql (sql): You probably need to lower "min"
freeradius    | rlm_sql_mysql: Socket destructor called, closing socket
freeradius    | rlm_sql (sql): Closing connection (0): Hit idle_timeout,
was idle for 68 seconds
freeradius    | rlm_sql (sql): You probably need to lower "min"
freeradius    | rlm_sql_mysql: Socket destructor called, closing socket
freeradius    | rlm_sql (sql): Closing connection (5): Hit idle_timeout,
was idle for 68 seconds
freeradius    | rlm_sql (sql): You probably need to lower "min"
freeradius    | rlm_sql_mysql: Socket destructor called, closing socket
freeradius    | rlm_sql (sql): 0 of 0 connections in use.  You  may need
to increase "spare"
freeradius    | rlm_sql (sql): Opening additional connection (6), 1 of 32
pending slots used
freeradius    | rlm_sql_mysql: Starting connect to MySQL server
freeradius    | rlm_sql_mysql: Connected to database 'radius' on
172.25.0.100 via TCP/IP, server version 5.7.25, protocol version 10
freeradius    | rlm_sql (sql): Reserved connection (6)
freeradius    | (0) sql: EXPAND SELECT id, username, attribute, value, op
FROM radcheck WHERE username = '%{SQL-User-Name}' ORDER BY id
freeradius    | (0) sql:    --> SELECT id, username, attribute, value, op
FROM radcheck WHERE username = '12378@@TM11' ORDER BY id
freeradius    | (0) sql: Executing select query: SELECT id, username,
attribute, value, op FROM radcheck WHERE username = '12378@@TM11' ORDER BY
id
freeradius    | (0) sql: User found in radcheck table
freeradius    | (0) sql: Conditional check items matched, merging
assignment check items
freeradius    | (0) sql:   Cleartext-Password :=
"55587a910882016321201e6ebbc9f595"
freeradius    | (0) sql: EXPAND SELECT id, username, attribute, value, op
FROM radreply WHERE username = '%{SQL-User-Name}' ORDER BY id
freeradius    | (0) sql:    --> SELECT id, username, attribute, value, op
FROM radreply WHERE username = '12378@@TM11' ORDER BY id
freeradius    | (0) sql: Executing select query: SELECT id, username,
attribute, value, op FROM radreply WHERE username = '12378@@TM11' ORDER BY
id
freeradius    | (0) sql: EXPAND SELECT groupname FROM radusergroup WHERE
username = '%{SQL-User-Name}' ORDER BY priority
freeradius    | (0) sql:    --> SELECT groupname FROM radusergroup WHERE
username = '12378@@TM11' ORDER BY priority
freeradius    | (0) sql: Executing select query: SELECT groupname FROM
radusergroup WHERE username = '12378@@TM11' ORDER BY priority
freeradius    | (0) sql: User found in the group table
freeradius    | (0) sql: EXPAND SELECT id, groupname, attribute, Value, op
FROM radgroupcheck WHERE groupname = '%{SQL-Group}' ORDER BY id
freeradius    | (0) sql:    --> SELECT id, groupname, attribute, Value, op
FROM radgroupcheck WHERE groupname = 'allowall' ORDER BY id
freeradius    | (0) sql: Executing select query: SELECT id, groupname,
attribute, Value, op FROM radgroupcheck WHERE groupname = 'allowall' ORDER
BY id
freeradius    | (0) sql: Group "allowall": Conditional check items matched
freeradius    | (0) sql: Group "allowall": Merging assignment check items
freeradius    | (0) sql:   Framed-Protocol := 0
freeradius    | (0) sql: EXPAND SELECT id, groupname, attribute, value, op
FROM radgroupreply WHERE groupname = '%{SQL-Group}' ORDER BY id
freeradius    | (0) sql:    --> SELECT id, groupname, attribute, value, op
FROM radgroupreply WHERE groupname = 'allowall' ORDER BY id
freeradius    | (0) sql: Executing select query: SELECT id, groupname,
attribute, value, op FROM radgroupreply WHERE groupname = 'allowall' ORDER
BY id
freeradius    | (0) sql: Group "allowall": Merging reply items
freeradius    | rlm_sql (sql): Released connection (6)
freeradius    | Need 2 more connections to reach min connections (3)
freeradius    | rlm_sql (sql): Opening additional connection (7), 1 of 31
pending slots used
freeradius    | rlm_sql_mysql: Starting connect to MySQL server
freeradius    | rlm_sql_mysql: Connected to database 'radius' on
172.25.0.100 via TCP/IP, server version 5.7.25, protocol version 10
freeradius    | (0)     [sql] = ok
freeradius    | (0)     [expiration] = noop
freeradius    | (0)     [logintime] = noop
freeradius    | (0)     [pap] = updated
freeradius    | (0)   } # authorize = updated
freeradius    | (0) Found Auth-Type = PAP
freeradius    | (0) # Executing group from file
/etc/freeradius/sites-enabled/default
freeradius    | (0)   Auth-Type PAP {
freeradius    | (0) pap: Login attempt with password
freeradius    | (0) pap: Comparing with "known good" Cleartext-Password
freeradius    | (0) pap: User authenticated successfully
freeradius    | (0)     [pap] = ok
freeradius    | (0)   } # Auth-Type PAP = ok
freeradius    | (0) # Executing section post-auth from file
/etc/freeradius/sites-enabled/default
freeradius    | (0)   post-auth {
freeradius    | (0)     update {
freeradius    | (0)       No attributes updated
freeradius    | (0)     } # update = noop
freeradius    | (0) sql: EXPAND .query
freeradius    | (0) sql:    --> .query
freeradius    | (0) sql: Using query template 'query'
freeradius    | rlm_sql (sql): Reserved connection (6)
freeradius    | (0) sql: EXPAND %{User-Name}
freeradius    | (0) sql:    --> 12378@@TM11
freeradius    | (0) sql: SQL-User-Name set to '12378@@TM11'
freeradius    | (0) sql: EXPAND INSERT INTO radpostauth (username, pass,
reply, authdate) VALUES ( '%{SQL-User-Name}',
'%{%{User-Password}:-%{Chap-Password}}', '%{reply:Packet-Type}', '%S')
freeradius    | (0) sql:    --> INSERT INTO radpostauth (username, pass,
reply, authdate) VALUES ( '12378@@TM11',
'55587a910882016321201e6ebbc9f595', 'Access-Accept', '2019-03-15
14:35:17')
freeradius    | (0) sql: Executing query: INSERT INTO radpostauth
(username, pass, reply, authdate) VALUES ( '12378@@TM11',
'55587a910882016321201e6ebbc9f595', 'Access-Accept', '2019-03-15
14:35:17')
freeradius    | (0) sql: SQL query returned: success
freeradius    | (0) sql: 1 record(s) updated
freeradius    | rlm_sql (sql): Released connection (6)
freeradius    | (0)     [sql] = ok
freeradius    | (0)     [exec] = noop
freeradius    | (0)     policy remove_reply_message_if_eap {
freeradius    | (0)       if (&reply:EAP-Message && &reply:Reply-Message) {
freeradius    | (0)       if (&reply:EAP-Message && &reply:Reply-Message) 
-> FALSE
freeradius    | (0)       else {
freeradius    | (0)         [noop] = noop
freeradius    | (0)       } # else = noop
freeradius    | (0)     } # policy remove_reply_message_if_eap = noop
freeradius    | (0)   } # post-auth = ok
freeradius    | (0) Sent Access-Accept Id 169 from 172.25.0.101:1812 to
192.168.0.4:47212 length 0
freeradius    | (0) Finished request
freeradius    | Waking up in 4.9 seconds.
freeradius    | (1) Received Accounting-Request Id 170 from
192.168.0.4:45646 to 172.25.0.101:1813 length 215
freeradius    | (1)   Acct-Status-Type = Start
freeradius    | (1)   Acct-Session-Id = "1801000A-0001122B"
freeradius    | (1)   Acct-Authentic = RADIUS
freeradius    | (1)   User-Name = "12378@@TM11"
freeradius    | (1)   Calling-Station-Id = "9c:4e:36:9c:71:18"
freeradius    | (1)   Called-Station-Id = "00:0c:29:67:6d:ec"
freeradius    | (1)   Connect-Info = "CONNECT Unknown Radio"
freeradius    | (1)   NAS-Identifier = "00:0c:29:67:6d:ec"
freeradius    | (1)   Meru-Access-Point-Id = 10
freeradius    | (1)   Meru-Access-Point-Name = "Bangalore"
freeradius    | (1)   Attr-26.15983.3 = 0x0a000118
freeradius    | (1)   Framed-IP-Address = 10.0.1.24
freeradius    | (1)   NAS-IP-Address = 192.168.0.4
freeradius    | (1)   NAS-Port-Type = Wireless-802.11
freeradius    | (1)   NAS-Port = 0
freeradius    | (1)   Acct-Delay-Time = 0
freeradius    | (1) # Executing section preacct from file
/etc/freeradius/sites-enabled/default
freeradius    | (1)   preacct {
freeradius    | (1)     [preprocess] = ok
freeradius    | (1)     policy acct_unique {
freeradius    | (1)       update request {
freeradius    | (1)         &Tmp-String-9 := "ai:"
freeradius    | (1)       } # update request = noop
freeradius    | (1)       if (("%{hex:&Class}" =~ /^%{hex:&Tmp-String-9}/)
&&       ("%{string:&Class}" =~ /^ai:([0-9a-f]{32})/i)) {
freeradius    | (1)       EXPAND %{hex:&Class}
freeradius    | (1)          -->
freeradius    | (1)       EXPAND ^%{hex:&Tmp-String-9}
freeradius    | (1)          --> ^61693a
freeradius    | (1)       if (("%{hex:&Class}" =~ /^%{hex:&Tmp-String-9}/)
&&       ("%{string:&Class}" =~ /^ai:([0-9a-f]{32})/i))  -> FALSE
freeradius    | (1)       else {
freeradius    | (1)         update request {
freeradius    | (1)           EXPAND
%{md5:%{User-Name},%{Acct-Session-ID},%{%{NAS-IPv6-Address}:-%{NAS-IP-Address}},%{NAS-Identifier},%{NAS-Port-ID},%{NAS-Port}}
freeradius    | (1)              --> d99b6270bc08322e50fc1284c175858d
freeradius    | (1)           &Acct-Unique-Session-Id :=
d99b6270bc08322e50fc1284c175858d
freeradius    | (1)         } # update request = noop
freeradius    | (1)       } # else = noop
freeradius    | (1)     } # policy acct_unique = noop
freeradius    | (1) suffix: Checking for suffix after "@"
freeradius    | (1) suffix: Looking up realm "TM11" for User-Name =
"12378@@TM11"
freeradius    | (1) suffix: No such realm "TM11"
freeradius    | (1)     [suffix] = noop
freeradius    | (1)     [files] = noop
freeradius    | (1)   } # preacct = ok
freeradius    | (1) # Executing section accounting from file
/etc/freeradius/sites-enabled/default
freeradius    | (1)   accounting {
freeradius    | (1) detail: EXPAND
/var/log/freeradius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d
freeradius    | (1) detail:    -->
/var/log/freeradius/radacct/192.168.0.4/detail-20190315
freeradius    | (1) detail:
/var/log/freeradius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d
expands to /var/log/freeradius/radacct/192.168.0.4/detail-20190315
freeradius    | (1) detail: EXPAND %t
freeradius    | (1) detail:    --> Fri Mar 15 14:35:17 2019
freeradius    | (1)     [detail] = ok
freeradius    | (1)     [unix] = ok
freeradius    | (1) sql: EXPAND %{tolower:type.%{Acct-Status-Type}.query}
freeradius    | (1) sql:    --> type.start.query
freeradius    | (1) sql: Using query template 'query'
freeradius    | rlm_sql (sql): Reserved connection (7)
freeradius    | (1) sql: EXPAND %{User-Name}
freeradius    | (1) sql:    --> 12378@@TM11
freeradius    | (1) sql: SQL-User-Name set to '12378@@TM11'
freeradius    | (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}', %{%{integer:Event-Timestamp}:-date('now')},
%{%{integer:Event-Timestamp}:-date('now')}, NULL, '0',
'%{Acct-Authentic}', '%{Connect-Info}', '', '0', '0',
'%{Called-Station-Id}', '%{Calling-Station-Id}', '', '%{Service-Type}',
'%{Framed-Protocol}', '%{Framed-IP-Address}')
freeradius    | (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 ('1801000A-0001122B',
'd99b6270bc08322e50fc1284c175858d', '12378@@TM11', '', '192.168.0.4', '0',
'Wireless-802.11', 1552660517, 1552660517, NULL, '0', 'RADIUS', 'CONNECT
Unknown Radio', '', '0', '0', '00:0c:29:67:6d:ec', '9c:4e:36:9c:71:18',
'', '', '', '10.0.1.24')
freeradius    | (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 ('1801000A-0001122B',
'd99b6270bc08322e50fc1284c175858d', '12378@@TM11', '', '192.168.0.4', '0',
'Wireless-802.11', 1552660517, 1552660517, NULL, '0', 'RADIUS', 'CONNECT
Unknown Radio', '', '0', '0', '00:0c:29:67:6d:ec', '9c:4e:36:9c:71:18',
'', '', '', '10.0.1.24')
freeradius    | (1) sql: ERROR: rlm_sql_mysql: ERROR 1292 (Incorrect
datetime value: '1552660517' for column 'acctstarttime' at row 1): 22007
freeradius    | (1) sql: SQL query returned: server error
freeradius    | rlm_sql (sql): Released connection (7)
freeradius    | (1)     [sql] = fail
freeradius    | (1)   } # accounting = fail
freeradius    | (1) Not sending reply to client.
freeradius    | (1) Finished request
freeradius    | (1) Cleaning up request packet ID 170 with timestamp +68
freeradius    | Waking up in 4.9 seconds.
freeradius    | (2) Received Accounting-Request Id 170 from
192.168.0.4:45646 to 172.25.0.101:1813 length 215
freeradius    | (2)   Acct-Status-Type = Start
freeradius    | (2)   Acct-Session-Id = "1801000A-0001122B"
freeradius    | (2)   Acct-Authentic = RADIUS
freeradius    | (2)   User-Name = "12378@@TM11"
freeradius    | (2)   Calling-Station-Id = "9c:4e:36:9c:71:18"
freeradius    | (2)   Called-Station-Id = "00:0c:29:67:6d:ec"
freeradius    | (2)   Connect-Info = "CONNECT Unknown Radio"
freeradius    | (2)   NAS-Identifier = "00:0c:29:67:6d:ec"
freeradius    | (2)   Meru-Access-Point-Id = 10
freeradius    | (2)   Meru-Access-Point-Name = "Bangalore"
freeradius    | (2)   Attr-26.15983.3 = 0x0a000118
freeradius    | (2)   Framed-IP-Address = 10.0.1.24
freeradius    | (2)   NAS-IP-Address = 192.168.0.4
freeradius    | (2)   NAS-Port-Type = Wireless-802.11
freeradius    | (2)   NAS-Port = 0
freeradius    | (2)   Acct-Delay-Time = 0
freeradius    | (2) # Executing section preacct from file
/etc/freeradius/sites-enabled/default
freeradius    | (2)   preacct {
freeradius    | (2)     [preprocess] = ok
freeradius    | (2)     policy acct_unique {
freeradius    | (2)       update request {
freeradius    | (2)         &Tmp-String-9 := "ai:"
freeradius    | (2)       } # update request = noop
freeradius    | (2)       if (("%{hex:&Class}" =~ /^%{hex:&Tmp-String-9}/)
&&       ("%{string:&Class}" =~ /^ai:([0-9a-f]{32})/i)) {
freeradius    | (2)       EXPAND %{hex:&Class}
freeradius    | (2)          -->
freeradius    | (2)       EXPAND ^%{hex:&Tmp-String-9}
freeradius    | (2)          --> ^61693a
freeradius    | (2)       if (("%{hex:&Class}" =~ /^%{hex:&Tmp-String-9}/)
&&       ("%{string:&Class}" =~ /^ai:([0-9a-f]{32})/i))  -> FALSE
freeradius    | (2)       else {
freeradius    | (2)         update request {
freeradius    | (2)           EXPAND
%{md5:%{User-Name},%{Acct-Session-ID},%{%{NAS-IPv6-Address}:-%{NAS-IP-Address}},%{NAS-Identifier},%{NAS-Port-ID},%{NAS-Port}}
freeradius    | (2)              --> d99b6270bc08322e50fc1284c175858d
freeradius    | (2)           &Acct-Unique-Session-Id :=
d99b6270bc08322e50fc1284c175858d
freeradius    | (2)         } # update request = noop
freeradius    | (2)       } # else = noop
freeradius    | (2)     } # policy acct_unique = noop
freeradius    | (2) suffix: Checking for suffix after "@"
freeradius    | (2) suffix: Looking up realm "TM11" for User-Name =
"12378@@TM11"
freeradius    | (2) suffix: No such realm "TM11"
freeradius    | (2)     [suffix] = noop
freeradius    | (2)     [files] = noop
freeradius    | (2)   } # preacct = ok
freeradius    | (2) # Executing section accounting from file
/etc/freeradius/sites-enabled/default
freeradius    | (2)   accounting {
freeradius    | (2) detail: EXPAND
/var/log/freeradius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d
freeradius    | (2) detail:    -->
/var/log/freeradius/radacct/192.168.0.4/detail-20190315
freeradius    | (2) detail:
/var/log/freeradius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d
expands to /var/log/freeradius/radacct/192.168.0.4/detail-20190315
freeradius    | (2) detail: EXPAND %t
freeradius    | (2) detail:    --> Fri Mar 15 14:35:19 2019
freeradius    | (2)     [detail] = ok
freeradius    | (2)     [unix] = ok
freeradius    | (2) sql: EXPAND %{tolower:type.%{Acct-Status-Type}.query}
freeradius    | (2) sql:    --> type.start.query
freeradius    | (2) sql: Using query template 'query'
freeradius    | rlm_sql (sql): Reserved connection (6)
freeradius    | (2) sql: EXPAND %{User-Name}
freeradius    | (2) sql:    --> 12378@@TM11
freeradius    | (2) sql: SQL-User-Name set to '12378@@TM11'
freeradius    | (2) 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}', %{%{integer:Event-Timestamp}:-date('now')},
%{%{integer:Event-Timestamp}:-date('now')}, NULL, '0',
'%{Acct-Authentic}', '%{Connect-Info}', '', '0', '0',
'%{Called-Station-Id}', '%{Calling-Station-Id}', '', '%{Service-Type}',
'%{Framed-Protocol}', '%{Framed-IP-Address}')
freeradius    | (2) 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 ('1801000A-0001122B',
'd99b6270bc08322e50fc1284c175858d', '12378@@TM11', '', '192.168.0.4', '0',
'Wireless-802.11', 1552660519, 1552660519, NULL, '0', 'RADIUS', 'CONNECT
Unknown Radio', '', '0', '0', '00:0c:29:67:6d:ec', '9c:4e:36:9c:71:18',
'', '', '', '10.0.1.24')
freeradius    | (2) 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 ('1801000A-0001122B',
'd99b6270bc08322e50fc1284c175858d', '12378@@TM11', '', '192.168.0.4', '0',
'Wireless-802.11', 1552660519, 1552660519, NULL, '0', 'RADIUS', 'CONNECT
Unknown Radio', '', '0', '0', '00:0c:29:67:6d:ec', '9c:4e:36:9c:71:18',
'', '', '', '10.0.1.24')
freeradius    | (2) sql: ERROR: rlm_sql_mysql: ERROR 1292 (Incorrect
datetime value: '1552660519' for column 'acctstarttime' at row 1): 22007
freeradius    | (2) sql: SQL query returned: server error
freeradius    | rlm_sql (sql): Released connection (6)
freeradius    | Need 1 more connections to reach min connections (3)
freeradius    | rlm_sql (sql): Opening additional connection (8), 1 of 30
pending slots used
freeradius    | rlm_sql_mysql: Starting connect to MySQL server
freeradius    | rlm_sql_mysql: Connected to database 'radius' on
172.25.0.100 via TCP/IP, server version 5.7.25, protocol version 10
freeradius    | (2)     [sql] = fail
freeradius    | (2)   } # accounting = fail
freeradius    | (2) Not sending reply to client.
freeradius    | (2) Finished request
freeradius    | (2) Cleaning up request packet ID 170 with timestamp +70
freeradius    | Waking up in 2.9 seconds.
freeradius    | (3) Received Accounting-Request Id 170 from
192.168.0.4:45646 to 172.25.0.101:1813 length 215
freeradius    | (3)   Acct-Status-Type = Start
freeradius    | (3)   Acct-Session-Id = "1801000A-0001122B"
freeradius    | (3)   Acct-Authentic = RADIUS
freeradius    | (3)   User-Name = "12378@@TM11"
freeradius    | (3)   Calling-Station-Id = "9c:4e:36:9c:71:18"
freeradius    | (3)   Called-Station-Id = "00:0c:29:67:6d:ec"
freeradius    | (3)   Connect-Info = "CONNECT Unknown Radio"
freeradius    | (3)   NAS-Identifier = "00:0c:29:67:6d:ec"
freeradius    | (3)   Meru-Access-Point-Id = 10
freeradius    | (3)   Meru-Access-Point-Name = "Bangalore"
freeradius    | (3)   Attr-26.15983.3 = 0x0a000118
freeradius    | (3)   Framed-IP-Address = 10.0.1.24
freeradius    | (3)   NAS-IP-Address = 192.168.0.4
freeradius    | (3)   NAS-Port-Type = Wireless-802.11
freeradius    | (3)   NAS-Port = 0
freeradius    | (3)   Acct-Delay-Time = 0
freeradius    | (3) # Executing section preacct from file
/etc/freeradius/sites-enabled/default
freeradius    | (3)   preacct {
freeradius    | (3)     [preprocess] = ok
freeradius    | (3)     policy acct_unique {
freeradius    | (3)       update request {
freeradius    | (3)         &Tmp-String-9 := "ai:"
freeradius    | (3)       } # update request = noop
freeradius    | (3)       if (("%{hex:&Class}" =~ /^%{hex:&Tmp-String-9}/)
&&       ("%{string:&Class}" =~ /^ai:([0-9a-f]{32})/i)) {
freeradius    | (3)       EXPAND %{hex:&Class}
freeradius    | (3)          -->
freeradius    | (3)       EXPAND ^%{hex:&Tmp-String-9}
freeradius    | (3)          --> ^61693a
freeradius    | (3)       if (("%{hex:&Class}" =~ /^%{hex:&Tmp-String-9}/)
&&       ("%{string:&Class}" =~ /^ai:([0-9a-f]{32})/i))  -> FALSE
freeradius    | (3)       else {
freeradius    | (3)         update request {
freeradius    | (3)           EXPAND
%{md5:%{User-Name},%{Acct-Session-ID},%{%{NAS-IPv6-Address}:-%{NAS-IP-Address}},%{NAS-Identifier},%{NAS-Port-ID},%{NAS-Port}}
freeradius    | (3)              --> d99b6270bc08322e50fc1284c175858d
freeradius    | (3)           &Acct-Unique-Session-Id :=
d99b6270bc08322e50fc1284c175858d
freeradius    | (3)         } # update request = noop
freeradius    | (3)       } # else = noop
freeradius    | (3)     } # policy acct_unique = noop
freeradius    | (3) suffix: Checking for suffix after "@"
freeradius    | (3) suffix: Looking up realm "TM11" for User-Name =
"12378@@TM11"
freeradius    | (3) suffix: No such realm "TM11"
freeradius    | (3)     [suffix] = noop
freeradius    | (3)     [files] = noop
freeradius    | (3)   } # preacct = ok
freeradius    | (3) # Executing section accounting from file
/etc/freeradius/sites-enabled/default
freeradius    | (3)   accounting {
freeradius    | (3) detail: EXPAND
/var/log/freeradius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d
freeradius    | (3) detail:    -->
/var/log/freeradius/radacct/192.168.0.4/detail-20190315
freeradius    | (3) detail:
/var/log/freeradius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d
expands to /var/log/freeradius/radacct/192.168.0.4/detail-20190315
freeradius    | (3) detail: EXPAND %t
freeradius    | (3) detail:    --> Fri Mar 15 14:35:21 2019
freeradius    | (3)     [detail] = ok
freeradius    | (3)     [unix] = ok
freeradius    | (3) sql: EXPAND %{tolower:type.%{Acct-Status-Type}.query}
freeradius    | (3) sql:    --> type.start.query
freeradius    | (3) sql: Using query template 'query'
freeradius    | rlm_sql (sql): Reserved connection (7)
freeradius    | (3) sql: EXPAND %{User-Name}
freeradius    | (3) sql:    --> 12378@@TM11
freeradius    | (3) sql: SQL-User-Name set to '12378@@TM11'
freeradius    | (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}', %{%{integer:Event-Timestamp}:-date('now')},
%{%{integer:Event-Timestamp}:-date('now')}, NULL, '0',
'%{Acct-Authentic}', '%{Connect-Info}', '', '0', '0',
'%{Called-Station-Id}', '%{Calling-Station-Id}', '', '%{Service-Type}',
'%{Framed-Protocol}', '%{Framed-IP-Address}')
freeradius    | (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 ('1801000A-0001122B',
'd99b6270bc08322e50fc1284c175858d', '12378@@TM11', '', '192.168.0.4', '0',
'Wireless-802.11', 1552660521, 1552660521, NULL, '0', 'RADIUS', 'CONNECT
Unknown Radio', '', '0', '0', '00:0c:29:67:6d:ec', '9c:4e:36:9c:71:18',
'', '', '', '10.0.1.24')
freeradius    | (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 ('1801000A-0001122B',
'd99b6270bc08322e50fc1284c175858d', '12378@@TM11', '', '192.168.0.4', '0',
'Wireless-802.11', 1552660521, 1552660521, NULL, '0', 'RADIUS', 'CONNECT
Unknown Radio', '', '0', '0', '00:0c:29:67:6d:ec', '9c:4e:36:9c:71:18',
'', '', '', '10.0.1.24')
freeradius    | (3) sql: ERROR: rlm_sql_mysql: ERROR 1292 (Incorrect
datetime value: '1552660521' for column 'acctstarttime' at row 1): 22007
freeradius    | (3) sql: SQL query returned: server error
freeradius    | rlm_sql (sql): Released connection (7)
freeradius    | Need 7 more connections to reach 10 spares
freeradius    | rlm_sql (sql): Opening additional connection (9), 1 of 29
pending slots used
freeradius    | rlm_sql_mysql: Starting connect to MySQL server
freeradius    | rlm_sql_mysql: Connected to database 'radius' on
172.25.0.100 via TCP/IP, server version 5.7.25, protocol version 10
freeradius    | (3)     [sql] = fail
freeradius    | (3)   } # accounting = fail
freeradius    | (3) Not sending reply to client.
freeradius    | (3) Finished request
freeradius    | (3) Cleaning up request packet ID 170 with timestamp +72
freeradius    | Waking up in 0.9 seconds.
freeradius    | (0) Cleaning up request packet ID 169 with timestamp +68
freeradius    | Ready to process requests

Re: radius accounting not starting....

Somanath Mishra