Problem with datetime and mysql

15 Sep 2023

      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.

ANGEL LUIS MATEO MARTINEZ

ANGEL LUIS MATEO MARTINEZ

ANGEL LUIS MATEO MARTINEZ

Alan DeKok

ANGEL LUIS MATEO MARTINEZ

tags

participants (2)