RE: Problem with datetime and mysql

15 Sep 2023

      I have also found that the detail stored in the detail file used in the buffered-sql is wright:

Fri Sep 15 12:25:34 2023
        Service-Type = Framed-User
        Framed-Protocol = PPP
        NAS-Port = 15728736
        NAS-Port-Type = Virtual
        User-Name = "angel.luis@um.es"
        Calling-Station-Id = "155.54.67.5"
        Called-Station-Id = "155.54.213.7"
        MS-CHAP-Domain = "um.es"
        Acct-Session-Id = "81a0005c"
        Framed-IP-Address = 155.54.194.55
        Acct-Authentic = RADIUS
        Event-Timestamp = "Sep 15 2023 12:25:34 CEST"
        Acct-Status-Type = Start
        NAS-Identifier = "MikroTik-Pruebas"
        Acct-Delay-Time = 0
        Mikrotik-Realm = "um.es"
        NAS-IP-Address = 155.54.213.7
        Huntgroup-Name = "vpn"
        X-Atica-Service = "vpn"
        X-Atica-Service-Filter = "vpn"
        Stripped-User-Name = "angel.luis"
        Realm = "um.es"
        SQL-User-Name = "angel.luis@um.es"
        Timestamp = 1694773534

but this is the processed detail shown with freeradius -X:

detail (/datapool/radacct/acct_sql_log): Read packet from /datapool/radacct/acct_sql_log.work
        Service-Type = Framed-User
        Framed-Protocol = PPP
        NAS-Port = 15728736
        NAS-Port-Type = Virtual
        User-Name = "angel.luis@um.es"
        Calling-Station-Id = "155.54.67.5"
        Called-Station-Id = "155.54.213.7"
        MS-CHAP-Domain = "um.es"
        Acct-Session-Id = "81a0005c"
        Framed-IP-Address = 155.54.194.55
        Acct-Authentic = RADIUS
        Event-Timestamp = "Sep 15 2023 13:25:34 CEST"
        Acct-Status-Type = Start
        NAS-Identifier = "MikroTik-Pruebas"
        Acct-Delay-Time = 4294963801
        Mikrotik-Realm = "um.es"
        NAS-IP-Address = 155.54.213.7
        Huntgroup-Name = "vpn"
        X-Atica-Service = "vpn"
        X-Atica-Service-Filter = "vpn"
        Stripped-User-Name = "angel.luis"
        Realm = "um.es"
        SQL-User-Name = "angel.luis@um.es"
        Packet-Original-Timestamp = "Sep 15 2023 12:25:34 CEST"
        Packet-Transmit-Counter = 1

--
Angel L. Mateo Martínez
Sección de Telemática
Área de Tecnologías de la Información y las Comunicaciones Aplicadas (ATICA)
http://www.um.es/atica
Tfo: 868889150
Fax: 868888337

________________________________________
De: Freeradius-Users <freeradius-users-bounces+amateo=um.es@lists.freeradius.org> en nombre de ANGEL LUIS MATEO MARTINEZ <amateo@um.es>
Enviado: viernes, 15 de septiembre de 2023 12:19
Para: FreeRadius users mailing list
Asunto: RE: Problem with datetime and mysql

With more debugging I have found that this the detail saved for the Start record:

Fri Sep 15 12:15:57 2023
        Service-Type = Framed-User
        Framed-Protocol = PPP
        NAS-Port = 15728735
        NAS-Port-Type = Virtual
        User-Name = "angel.luis@um.es"
        Calling-Station-Id = "155.54.67.5"
        Called-Station-Id = "155.54.213.7"
        MS-CHAP-Domain = "um.es"
        Acct-Session-Id = "81a0005b"
        Framed-IP-Address = 155.54.194.54
        Acct-Authentic = RADIUS
        Event-Timestamp = "Sep 15 2023 12:15:57 CEST"
        Acct-Status-Type = Start
        NAS-Identifier = "MikroTik-Pruebas"
        Acct-Delay-Time = 0
        Mikrotik-Realm = "um.es"
        NAS-IP-Address = 155.54.213.7
        Huntgroup-Name = "vpn"
        X-Atica-Service = "vpn"
        X-Atica-Service-Filter = "vpn"
        Stripped-User-Name = "angel.luis"
        Realm = "um.es"
        Timestamp = 1694772957

But this is the content passed to buffered-sql site:

detail (/datapool/radacct/acct_sql_log): Read packet from /datapool/radacct/acct_sql_log.work
        Service-Type = Framed-User
        Framed-Protocol = PPP
        NAS-Port = 15728735
        NAS-Port-Type = Virtual
        User-Name = "angel.luis@um.es"
        Calling-Station-Id = "155.54.67.5"
        Called-Station-Id = "155.54.213.7"
        MS-CHAP-Domain = "um.es"
        Acct-Session-Id = "81a0005b"
        Framed-IP-Address = 155.54.194.54
        Acct-Authentic = RADIUS
        Event-Timestamp = "Sep 15 2023 13:15:57 CEST"
        Acct-Status-Type = Start
        NAS-Identifier = "MikroTik-Pruebas"
        Acct-Delay-Time = 4294963696
        Mikrotik-Realm = "um.es"
        NAS-IP-Address = 155.54.213.7
        Huntgroup-Name = "vpn"
        X-Atica-Service = "vpn"
        X-Atica-Service-Filter = "vpn"
        Stripped-User-Name = "angel.luis"
        Realm = "um.es"
        SQL-User-Name = "angel.luis@um.es"
        Packet-Original-Timestamp = "Sep 15 2023 12:15:57 CEST"
        Packet-Transmit-Counter = 1

Any why the Event-Timestamp is changed in the buffered-sql?

--
Angel L. Mateo Martínez
Sección de Telemática
Área de Tecnologías de la Información y las Comunicaciones Aplicadas (ATICA)
http://www.um.es/atica
Tfo: 868889150
Fax: 868888337

________________________________________
De: Freeradius-Users <freeradius-users-bounces+amateo=um.es@lists.freeradius.org> en nombre de ANGEL LUIS MATEO MARTINEZ <amateo@um.es>
Enviado: viernes, 15 de septiembre de 2023 9:56
Para: FreeRadius users mailing list
Asunto: Problem with datetime and mysql

Hello,

I have a running freeradius with Ubuntu 18.04 and freeradius 3.0.19. In this system I'm using mysql to store accounting records in a MySQL database (radacct). To achieve this, I'm using the buffered-sql site. This is working fine.

Now I'm developing a new updated system with Ubuntu 22.04 and freeradius 3.0.26. I'm trying to configure this same MySQL database. I'm using the same database. Although the store in the database is working, I have a problem with datetime stored in acctstarttime, aactupdatetime and acctstoptime columns. The problem is that the datetime stored is 1 hour ahead of my current time.

I have both SO configured with the same timezone. In my case, it's Europe/Madrid (CEST, GMT+2 now).

I have also the same queries.conf file in both systems. I'm using the queries.conf distributed with the freeradius 3.0.26 22.04 package. In this file:

...
event_timestamp_epoch = "%{%{integer:Event-Timestamp}:-%l}"

# event_timestamp is the SQL snippet for converting an epoch timestamp
# to an SQL date.

event_timestamp = "FROM_UNIXTIME(${event_timestamp_epoch})"
...
                start {
                        #
                        #  Insert a new record into the sessions table
                        #
                        query = "\
                                INSERT INTO ${....acct_table1} \
                                        (${...column_list}) \
                                VALUES \
                                        ('%{Acct-Session-Id}', \
                                        '%{Acct-Unique-Session-Id}', \
                                        '%{SQL-User-Name}', \
                                        '%{Realm}', \
                                        '%{NAS-IP-Address}', \
                                        '%{%{NAS-Port-ID}:-%{NAS-Port}}', \
                                        '%{NAS-Port-Type}', \
                                        ${....event_timestamp}, \
                                        ${....event_timestamp}, \
                                        NULL, \
                                        '0', \
                                        '%{Acct-Authentic}', \
                                        '%{Connect-Info}', \
                                        '', \
                                        '0', \
                                        '0', \
                                        '%{Called-Station-Id}', \
                                        '%{Calling-Station-Id}', \
                                        '', \
                                        '%{Service-Type}', \
                                        '%{Framed-Protocol}', \
                                        '%{Framed-IP-Address}', \
                                        '%{Framed-IPv6-Address}', \
                                        '%{Framed-IPv6-Prefix}', \
                                        '%{Framed-Interface-Id}', \
                                        '%{Delegated-IPv6-Prefix}' \
                                        ${....class.packet_xlat})"
...

With this configuration, I have this Start record in my old system:

Fri Sep 15 09:33:10 2023
        Service-Type = Framed-User
        Framed-Protocol = PPP
        NAS-Port = 15728730
        NAS-Port-Type = Virtual
        User-Name = "XXXXX@um.es"
        Calling-Station-Id = "155.54.67.5"
        Called-Station-Id = "155.54.213.7"
        MS-CHAP-Domain = "um.es"
        Acct-Session-Id = "81a00056"
        Framed-IP-Address = 155.54.192.37
        Acct-Authentic = RADIUS
        Event-Timestamp = "Sep 15 2023 09:33:10 CEST"
        Acct-Status-Type = Start
        NAS-Identifier = "MikroTik-Pruebas"
        Acct-Delay-Time = 0
        Mikrotik-Realm = "um.es"
        NAS-IP-Address = 155.54.213.7
        Huntgroup-Name = "vpn"
        X-Atica-Service = "vpn"
        X-Atica-Service-Filter = "vpn"
        Stripped-User-Name = "XXXXX"
        Realm = "um.es"
        Timestamp = 1694763190

and the corresponding insert query in the database is:
use dbradiuslog;
SET timestamp=1694763191;
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,        framedipv6address,      framedipv6prefix, framedinterfaceid,    delegatedipv6prefix     ) VALUES ('81a00056', 'eb9b9fe238b5a46ac0e6be64acd6ec58', 'XXXXX@um.es', 'um.es', '155.54.213.7', '15728730', 'Virtual', FROM_UNIXTIME(1694763190), FROM_UNIXTIME(1694763190), NULL, '0', 'RADIUS', '', '', '0', '0', '155.54.213.7', '155.54.67.5', '', 'Framed-User', 'PPP', '155.54.192.37', '', '', '', '' );

where the 1694763191 timestamp is "Fri Sep 15 2023 09:33:11 GMT+0200" and 1694763190 is "Fri Sep 15 2023 09:33:10 GMT+0200"

and datetimes are correct.

But in the updated system I have this detail entry:
Fri Sep 15 09:35:47 2023
        Service-Type = Framed-User
        Framed-Protocol = PPP
        NAS-Port = 15728731
        NAS-Port-Type = Virtual
        User-Name = "XXXXX@um.es"
        Calling-Station-Id = "155.54.67.5"
        Called-Station-Id = "155.54.213.7"
        MS-CHAP-Domain = "um.es"
        Acct-Session-Id = "81a00057"
        Framed-IP-Address = 155.54.194.50
        Acct-Authentic = RADIUS
        Event-Timestamp = "Sep 15 2023 09:35:47 CEST"
        Acct-Status-Type = Start
        NAS-Identifier = "MikroTik-Pruebas"
        Acct-Delay-Time = 0
        Mikrotik-Realm = "um.es"
        NAS-IP-Address = 155.54.213.7
        Huntgroup-Name = "vpn"
        X-Atica-Service = "vpn"
        X-Atica-Service-Filter = "vpn"
        Stripped-User-Name = "XXXXX"
        Realm = "um.es"
        Timestamp = 1694763347

and the insert query is:
use dbradiuslog;
SET timestamp=1694763348;
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,        framedipv6address,      framedipv6prefix, framedinterfaceid,    delegatedipv6prefix     ) VALUES ('81a00057', '186c6d4ebe375d3178097fe46f3bdaae', 'XXXXX@um.es', 'um.es', '155.54.213.7', '15728731', 'Virtual', FROM_UNIXTIME(1694766947), FROM_UNIXTIME(1694766947), NULL, '0', 'RADIUS', '', '', '0', '0', '155.54.213.7', '155.54.67.5', '', 'Framed-User', 'PPP', '155.54.194.50', '', '', '', '' );

in this case, the first 1694763348 datetime (the used in SET) corresponds to "Fri Sep 15 2023 09:35:48 GMT+0200" (it's fine), but the 1694766947 used in FROM_UNIX(1694766947) corresponds to "Fri Sep 15 2023 10:35:47 GMT+0200" which is wrong. The date stored in the database is wrong too.

It seems that there is a problem somewhere in the transformation from the Event-Timestamp entry in the detail to the epoch used in the SQL query.

Any help with this? Thank you.
-
List info/subscribe/unsubscribe? See https://urldefense.com/v3/__http://www.freeradius.org/list/users.html__;!!D9...
-
List info/subscribe/unsubscribe? See https://urldefense.com/v3/__http://www.freeradius.org/list/users.html__;!!D9...