delayed update on sql logging

[Oguzhan Kayhan]

>>>> I am checking simultaneous-use information, logged users etc on sql
>>>> server.
>>>> The problem is, if a user logges in, nearly after a minute later i can
>>>> see
>>>> the logged on user on mysql tables. But i can see the same user with
>>>> radlast command in the same second the user logs in.
>>>> So it seems like there is a delay between updating the data on sql.
>>>> And with this, user can log in mutliple times with same username even
>>>> i
>>>> set sim-use to 1.
>>>>
>>>> Is there any parameter for that???
>>>> Or what else can cause that problem.
>>>
>>> Are you using buffered-sql accounting?
>>>
>> How can i check if i use buffered or not?? I didnt change much in
>> default
>> settings..
>
> That would mean you don't.
>
> Do a debug radiusd -Xx of login and see how much time passes between login
> and accounting Start packet and is there a delay in inserting data into
> sql on processing Start packet.
>
> Ivan Kalik
> Kalik Informatika ISP
>


Here is the debug results..

This is the begining.. starting at 17:34:03

rad_recv: Access-Request packet from host 192.168.16.145 port 2078, id=14,
length=288
        Vendor-14559-Attr-8 = 0x312e302e3131
Wed Sep 30 17:34:03 2009 : Debug: server lojnet {
Wed Sep 30 17:34:03 2009 : Debug: +- entering group authorize
....
...

Wed Sep 30 17:34:03 2009 : Debug: } # server lojnet
Sending Access-Accept of id 14 to 192.168.16.145 port 2078
        Acct-Interim-Interval = 60
        WISPr-Bandwidth-Max-Up = 25600000
        WISPr-Bandwidth-Max-Down = 100000000
Wed Sep 30 17:34:03 2009 : Debug: Finished request 0.
Wed Sep 30 17:34:03 2009 : Debug: Going to the next request
Wed Sep 30 17:34:03 2009 : Debug: Waking up in 4.9 seconds.
....
...Wed Sep 30 17:34:03 2009 : Debug: rlm_sql (sql_lojnet): sql_set_user
escaped user --> 'aaaaa'
Wed Sep 30 17:34:03 2009 : Debug:       expand: %{Acct-Delay-Time} ->
Wed Sep 30 17:34:03 2009 : Debug:       expand:            INSERT INTO
radacct             (acctsessionid,    acctuniqueid,     username,     $
Wed Sep 30 17:34:03 2009 : Debug: rlm_sql (sql_lojnet): Reserving sql
socket id: 8
Wed Sep 30 17:34:03 2009 : Debug: rlm_sql_mysql: MYSQL check_error: 1048
received
Wed Sep 30 17:34:03 2009 : Error: rlm_sql (sql_lojnet): Couldn't insert
SQL accounting START record - Column 'AcctStopTime' cannot be null
Wed Sep 30 17:34:03 2009 : Debug:       expand: %{Acct-Delay-Time} ->
Wed Sep 30 17:34:03 2009 : Debug:       expand:            UPDATE radacct
SET              acctstarttime     = '%S',              acctstartdel$
Wed Sep 30 17:34:03 2009 : Debug: rlm_sql (sql_lojnet): Released sql
socket id: 8
Wed Sep 30 17:34:03 2009 : Debug:   modsingle[accounting]: returned from
sql_lojnet (rlm_sql) for request 1
Wed Sep 30 17:34:03 2009 : Debug: ++[sql_lojnet] returns ok


Then at 17:35:03 i can see the user on sql....


Wed Sep 30 17:35:03 2009 : Debug: +- entering group accounting
Wed Sep 30 17:35:03 2009 : Debug:   modsingle[accounting]: calling detail
(rlm_detail) for request 2
Wed Sep 30 17:35:03 2009 : Debug:       expand:
/var/log/freeradius/radacct/%{Client-IP-Address}/detail-%Y%m%d ->
/var/log/freeradius/radacct/$
Wed Sep 30 17:35:03 2009 : Debug: rlm_detail:
/var/log/freeradius/radacct/%{Client-IP-Address}/detail-%Y%m%d expands to
/var/log/freeradius/ra$
Wed Sep 30 17:35:03 2009 : Debug:       expand: %t -> Wed Sep 30 17:35:03
2009
Wed Sep 30 17:35:03 2009 : Debug:   modsingle[accounting]: returned from
detail (rlm_detail) for request 2
Wed Sep 30 17:35:03 2009 : Debug: ++[detail] returns ok
Wed Sep 30 17:35:03 2009 : Debug:   modsingle[accounting]: calling unix
(rlm_unix) for request 2
Wed Sep 30 17:35:03 2009 : Debug:   modsingle[accounting]: returned from
unix (rlm_unix) for request 2
Wed Sep 30 17:35:03 2009 : Debug: ++[unix] returns noop
Wed Sep 30 17:35:03 2009 : Debug:   modsingle[accounting]: calling
sql_lojnet (rlm_sql) for request 2
Wed Sep 30 17:35:03 2009 : Debug:       expand: %{User-Name} -> aaaaa
Wed Sep 30 17:35:03 2009 : Debug: rlm_sql (sql_lojnet): sql_set_user
escaped user --> 'aaaaa'
Wed Sep 30 17:35:03 2009 : Debug:       expand: %{Acct-Input-Gigawords} -> 0
Wed Sep 30 17:35:03 2009 : Debug:       expand: %{Acct-Input-Octets} ->
671161
Wed Sep 30 17:35:03 2009 : Debug:       expand: %{Acct-Output-Gigawords} -> 0
Wed Sep 30 17:35:03 2009 : Debug:       expand: %{Acct-Output-Octets} ->
40281
Wed Sep 30 17:35:03 2009 : Debug:       expand:            UPDATE radacct 
         SET              framedipaddress = '%{Framed-IP-Address}',$
Wed Sep 30 17:35:03 2009 : Debug: rlm_sql (sql_lojnet): Reserving sql
socket id: 7
Wed Sep 30 17:35:03 2009 : Debug:       expand: %{Acct-Session-Time} -> 61
Wed Sep 30 17:35:03 2009 : Debug:       expand: %{Acct-Delay-Time} ->
Wed Sep 30 17:35:03 2009 : Debug:       expand: %{Acct-Input-Gigawords} -> 0
Wed Sep 30 17:35:03 2009 : Debug:       expand: %{Acct-Input-Octets} ->
671161
Wed Sep 30 17:35:03 2009 : Debug:       expand: %{Acct-Output-Gigawords} -> 0
Wed Sep 30 17:35:03 2009 : Debug:       expand: %{Acct-Output-Octets} ->
40281
Wed Sep 30 17:35:03 2009 : Debug:       expand:            INSERT INTO
radacct             (acctsessionid,    acctuniqueid,      username,    $
Wed Sep 30 17:35:03 2009 : Debug: rlm_sql (sql_lojnet): Released sql
socket id: 7
Wed Sep 30 17:35:03 2009 : Debug:   modsingle[accounting]: returned from
sql_lojnet (rlm_sql) for request 2
Wed Sep 30 17:35:03 2009 : Debug: ++[sql_lojnet] returns ok
Wed Sep 30 17:35:03 2009 : Debug: } # server lojnet




At the first try of sql i see the error
rlm_sql (sql_lojnet): Couldn't insert SQL accounting START record - Column
'AcctStopTime' cannot be null

Maybe that might be causing this...
So how can i fix that???







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