Problem with MySQL and Accouting-On record

classic Classic list List threaded Threaded
17 messages Options
| Threaded
Open this post in threaded view
|

Problem with MySQL and Accouting-On record

Ángel L. Mateo
Hi,

        I have a radius server (freeradius 3.0.19) to authenticate a VPN server
(among other services). I have virtual server to listen from this
device. In this server I have the config:

accouting {
    ...
    sql_log_um
    ...
}

        where "sql_log_um" es a detail config to a file, like this:

detail sql_log_um {
   filename = ${radacctdir}/eduroam/eduroam_sql
   escape_filenames = no
   permissions = 0600
   header = "%t"
   locking = false
   suppress {
     User-Password
   }
}

        Then I have enabled the buffered-sql listening to the previous file and
with:

accouting {
   sql
}

        to write accouting packets to a mysql database.

        My problem is that whenever I reboot this VPN server, it sends an
Accouting-On request which is written to this file like:

Fri Nov  6 13:44:04 2020
        Acct-Status-Type = Accounting-On
        NAS-Identifier = "MikroTik-CCR-VPN-1-Test"
        Acct-Delay-Time = 0
        NAS-IP-Address = 192.168.1.100
        X-Atica-Service = "vpn"
        X-Atica-Service-Filter = "vpn"
        Timestamp = 1604666644

        and then the buffered-sql runs a query like:

UPDATE radacct
SET acctstoptime = FROM_UNIXTIME(1604663265),
     acctsessiontime = '1604663265' - UNIX_TIMESTAMP(acctstarttime),
     acctterminatecause = 'NAS-Reboot'
WHERE acctstoptime IS NULL AND
       nasipaddress = '155.54.213.6' AND
       acctstarttime <= FROM_UNIXTIME(1604663265)

        the problem I have is that is queried is run but the record is not
deleted from the detail file neither is marked with the Donestamp mark,
so buffered-sql runs it again and again, without passing to next records.

        My first hypothesis has been that this query lasts too match (this is a
very large database), so I have changed the query (just to try) to
something like:

UPDATE radacct
SET acctstoptime = FROM_UNIXTIME(1604663265),
     acctsessiontime = '1604663265' - UNIX_TIMESTAMP(acctstarttime),
     acctterminatecause = 'NAS-Reboot'
WHERE 1 = 0

        just to try and check that the problem is not this, but I'm getting the
same result.

        Any help? Thanks.

--
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
-
List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
| Threaded
Open this post in threaded view
|

Re: Problem with MySQL and Accouting-On record

Alan DeKok-2
On Nov 6, 2020, at 8:13 AM, Ángel L. Mateo <[hidden email]> wrote:
> I have a radius server (freeradius 3.0.19) to authenticate a VPN server (among other services). I have virtual server to listen from this device. In this server I have the config:
>
> accouting {
>   ...
>   sql_log_um
>   ...
> }

  OK...

> where "sql_log_um" es a detail config to a file, like this:

  We don't need to see the config files.  *All* of the documentation says this.  Including the message you get when you join the list.

  Is there somewhere *else* we should put the documentation so that people will read it?

> the problem I have is that is queried is run but the record is not deleted from the detail file neither is marked with the Donestamp mark, so buffered-sql runs it again and again, without passing to next records.

  If only there was some kind of debug output which let you know what the server was doing.

  Honestly... the documentation says over and over again what to do.  Why ignore it?

  Alan DeKok.


-
List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
| Threaded
Open this post in threaded view
|

Re: Problem with MySQL and Accouting-On record

Ángel L. Mateo
        Sorry... I was describing the config, I thought it would be enough. The
whole config is:

* this is the server config:


El 6/11/20 a las 14:19, Alan DeKok escribió:

> On Nov 6, 2020, at 8:13 AM, Ángel L. Mateo <[hidden email]> wrote:
>> I have a radius server (freeradius 3.0.19) to authenticate a VPN server (among other services). I have virtual server to listen from this device. In this server I have the config:
>>
>> accouting {
>>    ...
>>    sql_log_um
>>    ...
>> }
>
>    OK...
>
>> where "sql_log_um" es a detail config to a file, like this:
>
>    We don't need to see the config files.  *All* of the documentation says this.  Including the message you get when you join the list.
>
>    Is there somewhere *else* we should put the documentation so that people will read it?
>
>> the problem I have is that is queried is run but the record is not deleted from the detail file neither is marked with the Donestamp mark, so buffered-sql runs it again and again, without passing to next records.
>
>    If only there was some kind of debug output which let you know what the server was doing.
>
>    Honestly... the documentation says over and over again what to do.  Why ignore it?
>
>    Alan DeKok.
>
>
> -
> List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
>

--
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
-
List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
| Threaded
Open this post in threaded view
|

Re: Problem with MySQL and Accouting-On record

Ángel L. Mateo
In reply to this post by Alan DeKok-2
        Sorry... I was describing the config, putting the relevant elements, I
thought it would be enough. The whole config is:

* this is the server config:
server vpn {


   authorize {
     update request {
   X-Atica-Service = "vpn"
   X-Atica-Service-Filter = "vpn"
}

     preprocess
     vpn_log
     suffix
     ldap
     files_vpn
     pap
     mschap
   }

   authenticate {
     Auth-Type PAP {
   pap
}
Auth-Type MS-CHAP {
   mschap
}

     pam
   }

   preacct {
     suffix
   }

   accounting {
     update request {
   X-Atica-Service = "vpn"
   X-Atica-Service-Filter = "vpn"
}

     vpn_log
     syslog_accounting
     sql_log_um
     pool_vpn { notfound = 1 }
     pool_vpn_alu { notfound = 1 }
     pool_vpn_avanttic { notfound = 1 }
     pool_vpn_gnoss { notfound = 1 }
     pool_vpn_izertis { notfound = 1 }
     pool_vpn_ext_pas { notfound = 1 }
     pool_vpn_ingenia { notfound = 1 }
     sqlippool
   }

   session {

   }

   post-auth {
     update reply { User-Name = &request:User-Name }
     pool_vpn
     pool_vpn_alu
     pool_vpn_avanttic
     pool_vpn_gnoss
     pool_vpn_izertis
     pool_vpn_ext_pas
     pool_vpn_ingenia
     sqlippool
     vpn_log
     expiration { userlock = 1 }
     if (userlock) {
   update reply {
     &reply:Reply-Message = "La clave de su cuenta %{User-Name} expiró
el %{control:Expiration}. Debe renovar su clave (cambiarla) en
https://webmail.um.es/cambiaclave/. Para más información diríjase al CAU
de la UMU (ext 4222, tlf 868884222, [hidden email])."
   }
   syslog_expiration
   reject
} else {
   syslog
}

     if (&control:Expiration) { update reply { &reply:Reply-Message =
"La clave de su cuenta %{User-Name} va a expirar el
%{control:Expiration}. Debe renovar (cambiar) su clave antes del
%{control:Expiration} o no podrá acceder a las aplicaciones y servicios
de la UMU. Para cambiar su clave acceda a
https://webmail.um.es/cambiaclave/. Para más información diríjase al CAU
de la UMU (ext 4222, tlf 868884222, [hidden email])." } }
     Post-Auth-Type REJECT {
   vpn_log
   syslog
}

   }

   pre-proxy {

   }

   post-proxy {

   }
}

server buffered-sql-eduroam {
   listen {
     type = detail
     filename = ${radacctdir}/eduroam/eduroam_sql
     load_factor = 10
     poll_interval = 1
     retry_interval = 30
     track = yes
   }
   authorize {
   }
   authenticate {
   }
   preacct {
     preprocess
     acct_unique
   }
   accounting {
     sql
   }
   session {
   }
   post-auth {
   }
   pre-proxy {
   }
   post-proxy {
   }
}

sql sql {
        dialect = "mysql"
        driver = "rlm_sql_${dialect}"
        server = "MYSQLSERVER"
        port = "3306"
        login = "MYSQLUSER"
        password = "PASSWORD"
        radius_db = "dbradiuslog"
        acct_table1 = "radacct"
        acct_table2 = "radacct"
        postauth_table = "radpostauth"
        authcheck_table = "radcheck"
        groupcheck_table = "radgroupcheck"
        authreply_table = "radreply"
        groupreply_table = "radgroupreply"
        usergroup_table = "radusergroup"
        read_groups = yes
        delete_stale_sessions = yes
       
        pool {
                start = 1
                min = 1
                max = ${thread[pool].max_servers}
                spare = 1
                uses = 0
                retry_delay = 60
                lifetime = 0
                idle_timeout = 60
                connect_timeout = 3.0
        }
        read_clients = no
        client_table = nas
        group_attribute = "${.:instance}-${.:name}-Group"
        $INCLUDE ${modconfdir}/${.:name}/main/${dialect}/queries.conf
}

detail sql_log_um {
   filename = ${radacctdir}/eduroam/eduroam_sql
   escape_filenames = no
   permissions = 0600
   header = "%t"
   locking = false
   suppress {
     User-Password
   }
}

        I put the queries.conf as an attach.

        Do you any other config?

El 6/11/20 a las 14:19, Alan DeKok escribió:

> On Nov 6, 2020, at 8:13 AM, Ángel L. Mateo <[hidden email]> wrote:
>> I have a radius server (freeradius 3.0.19) to authenticate a VPN server (among other services). I have virtual server to listen from this device. In this server I have the config:
>>
>> accouting {
>>    ...
>>    sql_log_um
>>    ...
>> }
>
>    OK...
>
>> where "sql_log_um" es a detail config to a file, like this:
>
>    We don't need to see the config files.  *All* of the documentation says this.  Including the message you get when you join the list.
>
>    Is there somewhere *else* we should put the documentation so that people will read it?
>
>> the problem I have is that is queried is run but the record is not deleted from the detail file neither is marked with the Donestamp mark, so buffered-sql runs it again and again, without passing to next records.
>
>    If only there was some kind of debug output which let you know what the server was doing.
>
>    Honestly... the documentation says over and over again what to do.  Why ignore it?
>
>    Alan DeKok.
>
>
> -
> List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
>
--
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

-
List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html

queries.conf (17K) Download Attachment
| Threaded
Open this post in threaded view
|

Re: Problem with MySQL and Accouting-On record

Alan DeKok-2
In reply to this post by Ángel L. Mateo


> On Nov 9, 2020, at 8:42 AM, Ángel L. Mateo <[hidden email]> wrote:
>
> Sorry... I was describing the config, I thought it would be enough. The whole config is:
>
> * this is the server config:

  Read this before doing anything else:  http://wiki.freeradius.org/list-help

  The mailing list strips attachments which are "zip" files.  We don't need to see the server configuration.  And we REALLY don't need to see the default configuration files.  It's a mystery to me why people post the default configuration files to the list.  Do people think we haven't seen it before?

  We ask for the debug output because NOTHING else lets us figure out what the server is doing.  We put this recommendation _everywhere_, and still people don't follow it.  And people still don't understand _why_ it's necessary, despite all the documentation explaining it.

  20 years of writing documentation and having people ignore it will make anyone cranky.

  In short, post the debug output.  And when you need to fix an issue, _read_ the debug output.  It tells you exactly what the server is doing, and why.

  Alan DeKok.


-
List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
| Threaded
Open this post in threaded view
|

Re: Problem with MySQL and Accouting-On record

Ángel L. Mateo
        Ok. I think I'm closer to the problem.

        I have attached 2 debug files, for 2 different tests I have run. Boths
tests have been run with an empty mysql.

        In the debug_works.txt I have done this:

* Start freeradius
* Send accounting start record for one user (request (1)). This record
is stored in mysql and deleted from the buffered file.
* Send another start record for other user from other NAS, the one I
want to send later an "Accouting-On" (request (2) and (3)). This record
is also stored in the mysql and deleted from the buffered file.
* Send "Accouting-On" packet from the same NAS than previous (request
(4) and (5)). This requests updates one record in the mysql (line 3443)
and is deleted from the buffered file.
* Later requests are also processed (I don't have tested this, but as
buffered files are empty, it should be no problem to be processed).

        In the debug_dontwork.txt I have done this:

* Start freeradius
* Send accounting start record for one user (request (1)). This record
is stored in mysql and deleted from the buffered file. This NAS
(155.54.213.5) is different than the one sending Accouting-On packets
(155.54.213.6)
* Send "Accouting-On" packet from other NAS than previous (request (2)
and (3)). This request updates no record (line 3267) and is not deleted
from the buffered file. It doesn't update any record because I don't any
record stored from this NAS, so it's correct not to update any record.
* Send accouting stop record for the previous user (request (5)). This
request is never been processed from buffered files, because (6) and
later always tries to make first the pending "Accouting-On"


El 9/11/20 a las 14:55, Alan DeKok escribió:

>
>
>> On Nov 9, 2020, at 8:42 AM, Ángel L. Mateo <[hidden email]> wrote:
>>
>> Sorry... I was describing the config, I thought it would be enough. The whole config is:
>>
>> * this is the server config:
>
>    Read this before doing anything else:  http://wiki.freeradius.org/list-help
>
>    The mailing list strips attachments which are "zip" files.  We don't need to see the server configuration.  And we REALLY don't need to see the default configuration files.  It's a mystery to me why people post the default configuration files to the list.  Do people think we haven't seen it before?
>
>    We ask for the debug output because NOTHING else lets us figure out what the server is doing.  We put this recommendation _everywhere_, and still people don't follow it.  And people still don't understand _why_ it's necessary, despite all the documentation explaining it.
>
>    20 years of writing documentation and having people ignore it will make anyone cranky.
>
>    In short, post the debug output.  And when you need to fix an issue, _read_ the debug output.  It tells you exactly what the server is doing, and why.
>
>    Alan DeKok.
>
>
> -
> List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
>
--
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

-
List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html

debug_dontwork.txt (201K) Download Attachment
debug_works.txt (192K) Download Attachment
| Threaded
Open this post in threaded view
|

Re: Problem with MySQL and Accouting-On record

Alan DeKok-2
On Nov 10, 2020, at 4:23 AM, Ángel L. Mateo <[hidden email]> wrote:
>
> Ok. I think I'm closer to the problem.
>
> I have attached 2 debug files, for 2 different tests I have run. Boths tests have been run with an empty mysql.

  That's good.
...
> In the debug_dontwork.txt I have done this:
>
> * Start freeradius
> * Send accounting start record for one user (request (1)). This record is stored in mysql and deleted from the buffered file. This NAS (155.54.213.5) is different than the one sending Accouting-On packets (155.54.213.6)
> * Send "Accouting-On" packet from other NAS than previous (request (2) and (3)). This request updates no record (line 3267) and is not deleted from the buffered file. It doesn't update any record because I don't any record stored from this NAS, so it's correct not to update any record.
> * Send accouting stop record for the previous user (request (5)). This request is never been processed from buffered files, because (6) and later always tries to make first the pending "Accouting-On"

  OK, the issue is that there's no "fall back" query which runs when there "accounting-on" packet doesn't update any rows.

  I've pushed fixes which will be part of 3.0.22.

  This kind of feedback is *exactly* what I need in order to find and fix problems.

  Alan DeKok.


-
List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
| Threaded
Open this post in threaded view
|

Re: Problem with MySQL and Accouting-On record

Ángel L. Mateo
El 11/11/20 a las 14:28, Alan DeKok escribió:
>
>    OK, the issue is that there's no "fall back" query which runs when there "accounting-on" packet doesn't update any rows.
>
>    I've pushed fixes which will be part of 3.0.22.

        Is there any place where I can take it and apply to my installation? I
can't find it at github. I don't know if it isn't there or that I don't
find it.
>
>    This kind of feedback is *exactly* what I need in order to find and fix problems.
>
        I'm sorry about not providing the correct information since the beginning.

        Thank you for your help.

--
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
-
List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
| Threaded
Open this post in threaded view
|

Re: Problem with MySQL and Accouting-On record

Alan DeKok-2

On Nov 12, 2020, at 8:01 AM, Ángel L. Mateo <[hidden email]> wrote:
> Is there any place where I can take it and apply to my installation? I can't find it at github. I don't know if it isn't there or that I don't find it.

 You can just download the updated file here:

https://github.com/FreeRADIUS/freeradius-server/blob/v3.0.x/raddb/mods-config/sql/main/mysql/queries.conf

>>   This kind of feedback is *exactly* what I need in order to find and fix problems.
> I'm sorry about not providing the correct information since the beginning.

  Thanks.  It's why I'm so fanatical about asking for the debug output.  Nothing else really helps.

> Thank you for your help.

  Despite my general crankiness, it's what I do.  You're welcome/

  Alan DeKok.


-
List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
| Threaded
Open this post in threaded view
|

Re: Problem with MySQL and Accouting-On record

Ángel L. Mateo
        I'm afraid that the patch doesn't work with my config. I have run the
same problem test with the patch applied (now I'm running 3.0.21 with
the patch)

1. Start freeradius
2. Send accounting start record for one user (request (1)). This record
is stored in mysql and deleted from the buffered file. This NAS
(155.54.213.5) is different than the one sending Accouting-On packets
(155.54.213.6)
3. Send "Accouting-On" packet from other NAS than previous (request (2)
and (3)). This request updates no record (line 3267) and is not deleted
from the buffered file. It doesn't update any record because I don't any
record stored from this NAS, so it's correct not to update any record.
4. Send accouting stop record for the previous user (request (4) and
(5)). This request is never been processed from buffered files.

        After step 3, there is a eduroam_sql.work file with the content of the
"Accounting-On" request. And after step 4, there is also a eduroam_sql
file with the content of the Stop request, and the eduroam_sql.work is
still there with the same content (Accounting-On).

        I guess the "SELECT true" statement doesn't make the desire behaviour.
This is what is shown in the debug (the whole debug in in the attached
debug.txt file):

(3) sql: Executing query: UPDATE radacct SET acctstoptime =
FROM_UNIXTIME(1605258058), acctsessiontime = '1605258058' -
UNIX_TIMESTAMP(acctstarttime), acctterminatecause = 'NAS-Reboot' WHERE
acctstoptime IS NULL AND nasipaddress   = '155.54.213.6' AND
acctstarttime <= FROM_UNIXTIME(1605258058)
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 SELECT true
(3) sql:    --> SELECT true
(3) sql: Executing query: SELECT true
(3) sql: SQL query returned: success
(3) sql: -1 record(s) updated
(3) sql: No additional queries configured
rlm_sql (sql): Released connection (0)
(3)     [sql] = noop
(3)   } # accounting = noop

        To run the test, I'm sending accounting packets with radclient from the
localhost, not from the real NAS. I have also attached the files with
packets I'm sending. The command I use is:

cat acct_stop.txt | radclient -d /etc/freeradius/3.0/ -x localhost:1813
acct <SECRET>


El 12/11/20 a las 14:42, Alan DeKok escribió:

>
> On Nov 12, 2020, at 8:01 AM, Ángel L. Mateo <[hidden email]> wrote:
>> Is there any place where I can take it and apply to my installation? I can't find it at github. I don't know if it isn't there or that I don't find it.
>
>   You can just download the updated file here:
>
> https://github.com/FreeRADIUS/freeradius-server/blob/v3.0.x/raddb/mods-config/sql/main/mysql/queries.conf
>
>>>    This kind of feedback is *exactly* what I need in order to find and fix problems.
>> I'm sorry about not providing the correct information since the beginning.
>
>    Thanks.  It's why I'm so fanatical about asking for the debug output.  Nothing else really helps.
>
>> Thank you for your help.
>
>    Despite my general crankiness, it's what I do.  You're welcome/
>
>    Alan DeKok.
>
>
> -
> List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
>
--
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

-
List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html

debug.txt (177K) Download Attachment
accouting_on.txt (176 bytes) Download Attachment
acct_start.txt (756 bytes) Download Attachment
acct_stop.txt (1K) Download Attachment
| Threaded
Open this post in threaded view
|

Re: Problem with MySQL and Accouting-On record

Bjørn Mork
Ángel L. Mateo <[hidden email]> writes:

> (3) # Executing section accounting from file /etc/freeradius/3.0/sites-enabled/buffered-sql-eduroam
> (3)   accounting {
> (3) sql: EXPAND %{tolower:type.%{%{Acct-Status-Type}:-%{Request-Processing-Stage}}.query}
> (3) sql:    --> type.accounting-on.query
> (3) sql: Using query template 'query'
> rlm_sql (sql): Reserved connection (0)
> (3) sql: EXPAND %{User-Name}
> (3) sql:    -->
> (3) sql: SQL-User-Name set to ''
> (3) sql: EXPAND UPDATE radacct SET acctstoptime = FROM_UNIXTIME(%{integer:Event-Timestamp}), acctsessiontime = '%{integer:Event-Timestamp}' - UNIX_TIMESTAMP(acctstarttime), acctterminatecause = '%{%{Acct-Terminate-Cause}:-NAS-Reboot}' WHERE acctstoptime IS NULL AND nasipaddress   = '%{NAS-IP-Address}' AND acctstarttime <= FROM_UNIXTIME(%{integer:Event-Timestamp})
> (3) sql:    --> UPDATE radacct SET acctstoptime = FROM_UNIXTIME(1605258058), acctsessiontime = '1605258058' - UNIX_TIMESTAMP(acctstarttime), acctterminatecause = 'NAS-Reboot' WHERE acctstoptime IS NULL AND nasipaddress   = '155.54.213.6' AND acctstarttime <= FROM_UNIXTIME(1605258058)
> (3) sql: Executing query: UPDATE radacct SET acctstoptime = FROM_UNIXTIME(1605258058), acctsessiontime = '1605258058' - UNIX_TIMESTAMP(acctstarttime), acctterminatecause = 'NAS-Reboot' WHERE acctstoptime IS NULL AND nasipaddress   = '155.54.213.6' AND acctstarttime <= FROM_UNIXTIME(1605258058)
> 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 SELECT true
> (3) sql:    --> SELECT true
> (3) sql: Executing query: SELECT true
> (3) sql: SQL query returned: success
> (3) sql: -1 record(s) updated
> (3) sql: No additional queries configured
> rlm_sql (sql): Released connection (0)
> (3)     [sql] = noop
> (3)   } # accounting = noop
> (3) detail (/var/log/freeradius/radacct/eduroam/eduroam_sql): No response to request.  Will retry in 30 seconds
> (3) Finished request
> (3) Cleaning up request packet ID 1 with timestamp +20


The problem is obviously the "No response to request.  Will retry in 30
seconds" here.  Which is how RADIUS accounting is designed.  Requests
are repeated until acked or naked.  If not, then you might silently miss
requests. Which of course is unacceptable.

But back to the problem: You do want to ignore some of the accounting
requests. And you can define those to be ignored as the set where you
sql module returns noop.  Then simply turn that noop into ok at the end
of the accounting section:

        accounting {

                ... call the sql the accounting module etc

                # Always ACK on noop's.  Which may happen if the input is
                # considered invalid
                # the alternative would be to retransmit such packets forever...
                if (noop) {
                        ok
                }
        }


This will make your detail listener "ack" the accounting request, and it
will be removed from the work file.



Bjørn

-
List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
| Threaded
Open this post in threaded view
|

Re: Problem with MySQL and Accouting-On record

Alan DeKok-2
In reply to this post by Ángel L. Mateo
On Nov 13, 2020, at 4:15 AM, Ángel L. Mateo <[hidden email]> wrote:
>
> I'm afraid that the patch doesn't work with my config. I have run the same problem test with the patch applied (now I'm running 3.0.21 with the patch)

  Arg.

> I guess the "SELECT true" statement doesn't make the desire behaviour. This is what is shown in the debug (the whole debug in in the attached debug.txt file):
>
> (3) sql: Executing query: UPDATE radacct SET acctstoptime = FROM_UNIXTIME(1605258058), acctsessiontime = '1605258058' - UNIX_TIMESTAMP(acctstarttime), acctterminatecause = 'NAS-Reboot' WHERE acctstoptime IS NULL AND nasipaddress   = '155.54.213.6' AND acctstarttime <= FROM_UNIXTIME(1605258058)
> 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 SELECT true
> (3) sql:    --> SELECT true
> (3) sql: Executing query: SELECT true
> (3) sql: SQL query returned: success
> (3) sql: -1 record(s) updated
> (3) sql: No additional queries configured
> rlm_sql (sql): Released connection (0)
> (3)     [sql] = noop
> (3)   } # accounting = noop

  Yeah.

  In the short term, use Bjorn's suggestion.  You can make it specific to Accounting "on" or "off" packers by checking for them:

        sql
        if (noop && ((Acct-Status-Type == Accounting-On) || (Acct-Status-Type == Accounting-Off)) {
                ok
        }

  I'll see if there's a better way to fix this.  It should really be automatic in the server, instead of "unlang" magic.

  Alan DeKok.


-
List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
| Threaded
Open this post in threaded view
|

Re: Problem with MySQL and Accouting-On record

Ángel L. Mateo
El 13/11/20 a las 14:03, Alan DeKok escribió:

>
>    In the short term, use Bjorn's suggestion.  You can make it specific to Accounting "on" or "off" packers by checking for them:
>
> sql
> if (noop && ((Acct-Status-Type == Accounting-On) || (Acct-Status-Type == Accounting-Off)) {
> ok
> }
>
>    I'll see if there's a better way to fix this.  It should really be automatic in the server, instead of "unlang" magic.
>
        The workaround works.

--
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
-
List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
| Threaded
Open this post in threaded view
|

Re: Problem with MySQL and Accouting-On record

Ángel L. Mateo
El 16/11/20 a las 10:33, Ángel L. Mateo escribió:

> El 13/11/20 a las 14:03, Alan DeKok escribió:
>>
>>    In the short term, use Bjorn's suggestion.  You can make it
>> specific to Accounting "on" or "off" packers by checking for them:
>>
>>     sql
>>     if (noop && ((Acct-Status-Type == Accounting-On) ||
>> (Acct-Status-Type == Accounting-Off)) {
>>         ok
>>     }
>>
>>    I'll see if there's a better way to fix this.  It should really be
>> automatic in the server, instead of "unlang" magic.
>>
>      The workaround works.
>
        Althought this workaround worked in my test environment, I'm still
having problems in production.

        I can't run productionn with "freeradius -X", so I'm trying to get
debug log with raddebug. My problem is that when I run "raddebug -c
'Acct-Status-Type == Accouting-On' I'm getting the debug from the packet
when it is received by freeradius, but I'm not getting the info when it
is processed by the buffered-sql virtual server.

        I'm looking for a way to debug only this virtual server, but I can't
find it. Is there a way to do this? to debug just the buffered-sql
virtual server?

--
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
-
List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
| Threaded
Open this post in threaded view
|

Re: Problem with MySQL and Accouting-On record

Alan DeKok-2
On Nov 17, 2020, at 8:10 AM, Ángel L. Mateo <[hidden email]> wrote:
> Althought this workaround worked in my test environment, I'm still having problems in production.

  Then something's different in the configuration between the two systems.

> I can't run productionn with "freeradius -X", so I'm trying to get debug log with raddebug. My problem is that when I run "raddebug -c 'Acct-Status-Type == Accouting-On' I'm getting the debug from the packet when it is received by freeradius, but I'm not getting the info when it is processed by the buffered-sql virtual server.
>
> I'm looking for a way to debug only this virtual server, but I can't find it. Is there a way to do this? to debug just the buffered-sql virtual server?

  Hmm... the detail file reader injects packets into the server core using the same system as the other listeners.  I'm not sure why it wouldn't print out those packets.

  Have you checked that those packets are in the detail file?

  Alan DeKok.


-
List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
| Threaded
Open this post in threaded view
|

Re: Problem with MySQL and Accouting-On record

Ángel L. Mateo
El 17/11/20 a las 15:01, Alan DeKok escribió:
> On Nov 17, 2020, at 8:10 AM, Ángel L. Mateo <[hidden email]> wrote:
>> Althought this workaround worked in my test environment, I'm still having problems in production.
>
>    Then something's different in the configuration between the two systems.
>
        Configuration is the same, but I think I have found the problem in
production. Although this isn't the whole debug capture (I couldn't
take) I found this:

(0) sql: EXPAND UPDATE radacct SET acctstoptime =
FROM_UNIXTIME(%{integer:Event-Timestamp}), acctsessiontime =
'%{integer:Event-Timestamp}' - UNIX_TIMESTAMP(acctstarttime),
acctterminatecause = '%{%{Acct-Terminate-Cause}:-NAS-Reboot}' WHERE
acctstoptime IS NULL AND nasipaddress   = '%{NAS-IP-Address}' AND
acctstarttime <= FROM_UNIXTIME(%{integer:Event-Timestamp})
(0) sql:    --> UPDATE radacct SET acctstoptime =
FROM_UNIXTIME(1605668493), acctsessiontime = '1605668493' -
UNIX_TIMESTAMP(acctstarttime), acctterminatecause = 'NAS-Reboot' WHERE
acctstoptime IS NULL AND nasipaddress   = '155.54.213.6' AND
acctstarttime <= FROM_UNIXTIME(1605668493)
(0) sql: Executing query: UPDATE radacct SET acctstoptime =
FROM_UNIXTIME(1605668493), acctsessiontime = '1605668493' -
UNIX_TIMESTAMP(acctstarttime), acctterminatecause = 'NAS-Reboot' WHERE
acctstoptime IS NULL AND nasipaddress   = '155.54.213.6' AND
acctstarttime <= FROM_UNIXTIME(1605668493)
(0) sql: ERROR: rlm_sql_mysql: ERROR 1205 (Lock wait timeout exceeded;
try restarting transaction): HY000
(0) sql: SQL query returned: server error
rlm_sql (sql): Released connection (0)
(0)     [sql] = fail
(0)   } # accounting = fail
(0) detail (/datapool/radacct/eduroam/eduroam_sql): No response to
request.  Will retry in 30 seconds
(0) Finished request

        There is a lock timeout. I think the problem is:

* My database is huge, about 6GB
* The update uses a WHERE with 3 fields, acctstoptime, nasipaddress and
acctstarttime. I'm not a DBA, but although I have indexes in these 3
fields, in this query I think that only the index for acctstoptime field
is use.

        I'm going to try to create an complex index for (acctstoptime,
nasipaddress, acctstarttime) and check if this solves the problem.

--
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
-
List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
| Threaded
Open this post in threaded view
|

Re: Problem with MySQL and Accouting-On record

Alan DeKok-2
On Nov 19, 2020, at 7:14 AM, Ángel L. Mateo <[hidden email]> wrote:
>
> (0) sql: ERROR: rlm_sql_mysql: ERROR 1205 (Lock wait timeout exceeded; try restarting transaction): HY000
> (0) sql: SQL query returned: server error

  Well, that's bad.

> There is a lock timeout. I think the problem is:
>
> * My database is huge, about 6GB

  There's no reason for that.  You need *a* database.  You don't need *one* database.

  The DB used by RADIUS should be a "production" database.  It should be kept small, to minimize these kinds of issues.

  Any "historical" information can go into a separate database.  If you're doing billing, or data analysis, it's OK for the queries to take 5 seconds.  It is definitely *not* OK for a RADIUS query to take 5 seconds.

> * The update uses a WHERE with 3 fields, acctstoptime, nasipaddress and acctstarttime. I'm not a DBA, but although I have indexes in these 3 fields, in this query I think that only the index for acctstoptime field is use.
>
> I'm going to try to create an complex index for (acctstoptime, nasipaddress, acctstarttime) and check if this solves the problem.

  That should help a lot.  Also, split the database into "production" and "historical".  Copy data daily from "production" to "historical". and then delete the data from "production".

  If the RADIUS server doesn't use the information, then it shouldn't be in the database used by RADIUS.

  Alan DeKok.


-
List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html