Linelog module sending message twice that has "warning" or higher severity level.

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

Linelog module sending message twice that has "warning" or higher severity level.

Yiğit YAŞAR
Hi all,

I have some issue with the linelog module.

My "linelog" configuration as in below;























*linelog {filename = syslogescape_filenames = nopermissions =
0600syslog_facility = daemonsyslog_severity = infoformat = "This is a log
message for %{User-Name}"reference =
"messages.%{%{reply:Packet-Type}:-default}"}linelog log_postauth {filename
= syslogsyslog_facility = authprivsyslog_severity = infoformat = "User
'%{User-Name}' authenticated via Radius"}linelog log_postreject {filename =
syslogsyslog_facility = authprivsyslog_severity = warningformat = "User
'%{User-Name}' authentication request rejected by Radius!"}*

Also in "default" configuration file is like ;




























*post-auth {log_postauthlog_postrejectif (session-state:User-Name &&
reply:User-Name && request:User-Name && (reply:User-Name ==
request:User-Name)) {update reply {&User-Name !* ANY}}update {&reply: +=
&session-state:}-sqlexecremove_reply_message_if_eapPost-Auth-Type REJECT
{-sqllog_postrejectattr_filter.access_rejecteapremove_reply_message_if_eap}Post-Auth-Type
ACCEPT {log_postauth}Post-Auth-Type Challenge {}}*

Problem is, when linelog sends log message with warning or higher severity,
log message sending twice.There is no problem with info or lower severity
level, they sending once.

What could be the problem, do you have any idea?

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

Re: Linelog module sending message twice that has "warning" or higher severity level.

Jorge Pereira-2
First of all.

Read the mailing list https://wiki.freeradius.org/guide/Users-Mailing-List <https://wiki.freeradius.org/guide/Users-Mailing-List> guidance, and then about how to share the debug output https://wiki.freeradius.org/guide/radiusd-X <https://wiki.freeradius.org/guide/radiusd-X>
--
Jorge Pereira
[hidden email]




> On 9 Sep 2020, at 03:25, Yiğit YAŞAR <[hidden email]> wrote:
>
> Hi all,
>
> I have some issue with the linelog module.
>
> My "linelog" configuration as in below;
>
>
>
>
>
>
>
>
>
>
>
>
>
>
>
>
>
>
>
>
>
>
>
> *linelog {filename = syslogescape_filenames = nopermissions =
> 0600syslog_facility = daemonsyslog_severity = infoformat = "This is a log
> message for %{User-Name}"reference =
> "messages.%{%{reply:Packet-Type}:-default}"}linelog log_postauth {filename
> = syslogsyslog_facility = authprivsyslog_severity = infoformat = "User
> '%{User-Name}' authenticated via Radius"}linelog log_postreject {filename =
> syslogsyslog_facility = authprivsyslog_severity = warningformat = "User
> '%{User-Name}' authentication request rejected by Radius!"}*
>
> Also in "default" configuration file is like ;
>
>
>
>
>
>
>
>
>
>
>
>
>
>
>
>
>
>
>
>
>
>
>
>
>
>
>
>
> *post-auth {log_postauthlog_postrejectif (session-state:User-Name &&
> reply:User-Name && request:User-Name && (reply:User-Name ==
> request:User-Name)) {update reply {&User-Name !* ANY}}update {&reply: +=
> &session-state:}-sqlexecremove_reply_message_if_eapPost-Auth-Type REJECT
> {-sqllog_postrejectattr_filter.access_rejecteapremove_reply_message_if_eap}Post-Auth-Type
> ACCEPT {log_postauth}Post-Auth-Type Challenge {}}*
>
> Problem is, when linelog sends log message with warning or higher severity,
> log message sending twice.There is no problem with info or lower severity
> level, they sending once.
>
> What could be the problem, do you have any idea?
>
> Thanks in advance
> Yigit
> -
> List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html

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

Re: Linelog module sending message twice that has "warning" or higher severity level.

Yiğit YAŞAR
Dear Jorge thank you for guidance,

Here is my debug output on a failed authentication attempt.

(0) pap: Login attempt with password
(0) pap: Comparing with "known-good" SSHA2-512-Password
(0) pap: ERROR: SSHA2-512 digest does not match "known good" digest
(0) pap: Passwords don't match
(0)     [pap] = reject
(0)   } # Auth-Type PAP = reject
(0) Failed to authenticate the user
(0) Using Post-Auth-Type Reject
(0) # Executing group from file
/opt/radius/bin/freeradius/etc/raddb/sites-enabled/default
(0)   Post-Auth-Type REJECT {
(0) sql: EXPAND .query
(0) sql:    --> .query
(0) sql: Using query template 'query'
rlm_sql (sql): Reserved connection (3)
(0) sql: EXPAND %{User-Name}
(0) sql:    --> user
(0) sql: SQL-User-Name set to 'user'
(0) sql: EXPAND INSERT INTO radpostauth (username, pass, reply, authdate)
VALUES ( '%{SQL-User-Name}', '*****', '%{reply:Packet-Type}', '%S')
(0) sql:    --> INSERT INTO radpostauth (username, pass, reply, authdate)
VALUES ( 'user', '*****', 'Access-Reject', '2020-09-10 09:45:58')
(0) sql: Executing query: INSERT INTO radpostauth (username, pass, reply,
authdate) VALUES ( 'user', '*****', 'Access-Reject', '2020-09-10 09:45:58')
(0) sql: SQL query returned: success
(0) sql: 1 record(s) updated
rlm_sql (sql): Released connection (3)
(0)     [sql] = ok
(0) log_postreject: EXPAND User '%{User-Name}' authentication request
rejected by Radius!
(0) log_postreject:    --> User 'user' authentication request rejected by
Radius!
(0)     [log_postreject] = ok
(0) attr_filter.access_reject: EXPAND %{User-Name}
(0) attr_filter.access_reject:    --> user
(0) attr_filter.access_reject: Matched entry DEFAULT at line 11
(0)     [attr_filter.access_reject] = updated
(0)     [eap] = noop
(0)     policy remove_reply_message_if_eap {
(0)       if (&reply:EAP-Message && &reply:Reply-Message) {
(0)       if (&reply:EAP-Message && &reply:Reply-Message)  -> FALSE
(0)       else {
(0)         [noop] = noop
(0)       } # else = noop
(0)     } # policy remove_reply_message_if_eap = noop
(0)   } # Post-Auth-Type REJECT = updated
(0) Login incorrect (Failed retrieving values required to evaluate
condition): [user] (from client client10 port 1812)
(0) Delaying response for 1.000000 seconds
Waking up in 0.3 seconds.
Waking up in 0.6 seconds.
(0) Sending delayed response
(0) Sent Access-Reject Id 217 from 192.168.17.164:1812 to
192.168.17.164:49999 length 20
Waking up in 3.9 seconds.
(0) Cleaning up request packet ID 217 with timestamp +15
Ready to process requests

Jorge Pereira <[hidden email]>, 9 Eyl 2020 Çar, 20:01 tarihinde
şunu yazdı:

> First of all.
>
> Read the mailing list https://wiki.freeradius.org/guide/Users-Mailing-List
> <https://wiki.freeradius.org/guide/Users-Mailing-List> guidance, and then
> about how to share the debug output
> https://wiki.freeradius.org/guide/radiusd-X <
> https://wiki.freeradius.org/guide/radiusd-X>
> --
> Jorge Pereira
> [hidden email]
>
>
>
>
> > On 9 Sep 2020, at 03:25, Yiğit YAŞAR <[hidden email]> wrote:
> >
> > Hi all,
> >
> > I have some issue with the linelog module.
> >
> > My "linelog" configuration as in below;
> >
> >
> >
> >
> >
> >
> >
> >
> >
> >
> >
> >
> >
> >
> >
> >
> >
> >
> >
> >
> >
> >
> >
> > *linelog {filename = syslogescape_filenames = nopermissions =
> > 0600syslog_facility = daemonsyslog_severity = infoformat = "This is a log
> > message for %{User-Name}"reference =
> > "messages.%{%{reply:Packet-Type}:-default}"}linelog log_postauth
> {filename
> > = syslogsyslog_facility = authprivsyslog_severity = infoformat = "User
> > '%{User-Name}' authenticated via Radius"}linelog log_postreject
> {filename =
> > syslogsyslog_facility = authprivsyslog_severity = warningformat = "User
> > '%{User-Name}' authentication request rejected by Radius!"}*
> >
> > Also in "default" configuration file is like ;
> >
> >
> >
> >
> >
> >
> >
> >
> >
> >
> >
> >
> >
> >
> >
> >
> >
> >
> >
> >
> >
> >
> >
> >
> >
> >
> >
> >
> > *post-auth {log_postauthlog_postrejectif (session-state:User-Name &&
> > reply:User-Name && request:User-Name && (reply:User-Name ==
> > request:User-Name)) {update reply {&User-Name !* ANY}}update {&reply: +=
> > &session-state:}-sqlexecremove_reply_message_if_eapPost-Auth-Type REJECT
> >
> {-sqllog_postrejectattr_filter.access_rejecteapremove_reply_message_if_eap}Post-Auth-Type
> > ACCEPT {log_postauth}Post-Auth-Type Challenge {}}*
> >
> > Problem is, when linelog sends log message with warning or higher
> severity,
> > log message sending twice.There is no problem with info or lower severity
> > level, they sending once.
> >
> > What could be the problem, do you have any idea?
> >
> > Thanks in advance
> > Yigit
> > -
> > List info/subscribe/unsubscribe? See
> http://www.freeradius.org/list/users.html
>
> -
> List info/subscribe/unsubscribe? See
> http://www.freeradius.org/list/users.html
-
List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
| Threaded
Open this post in threaded view
|

Re: Linelog module sending message twice that has "warning" or higher severity level.

Alan DeKok-2
On Sep 10, 2020, at 2:58 AM, Yiğit YAŞAR <[hidden email]> wrote:
> Here is my debug output on a failed authentication attempt.

  So... what's the problem?  Everything looks normal.

  Please explain *what* you think is wrong, and *why* you think it's wrong.

  Alan DeKok.


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

Re: Linelog module sending message twice that has "warning" or higher severity level.

Matthew Newton-3


On 10/09/2020 13:43, Alan DeKok wrote:
> On Sep 10, 2020, at 2:58 AM, Yiğit YAŞAR <[hidden email]> wrote:
>> Here is my debug output on a failed authentication attempt.
>
>    So... what's the problem?  Everything looks normal.
>
>    Please explain *what* you think is wrong, and *why* you think it's wrong.

 From the original mangled message it looks like post-auth is calling
both log_postauth AND log_postreject.

*post-auth {log_postauthlog_postrejectif (session-state:User-Name &&
reply:User-Name && request:User-Name && (reply:User-Name ==
request:User-Name)) {update reply {&User-Name !* ANY}}update {&reply: +=

But that debug output doesn't show this part of the config, so is rather
meaningless.

OP: please follow the instructions Jorge posted and send *full* debug
output for both a working and non-working scenario. Mangled text and
small extracts really doesn't help much.

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

Re: Linelog module sending message twice that has "warning" or higher severity level.

Yiğit YAŞAR
As mentioned at first post, my problem is the reject messages are sending
twice.
After some experimental works I discovered this situation only happening if
severity is higher than "warning".
There is no problem with successfully authentication message, its only sent
once.
I still could not find the solution.

This is my syslog event file, as you can see warning severity sending twice.
"2020-09-11 16:42:35" "ygtysr" "authpriv" "info" "User 'ygtysr'
authenticated via Radius!"
"2020-09-11 16:42:41" "ygtysr" "authpriv" "warning" "User 'ygtysr'
authentication request rejected by Radius!"
"2020-09-11 16:42:41" "ygtysr" "authpriv" "warning" "User 'ygtysr'
authentication request rejected by Radius!"

I use radtest for authentication test.
I attached the full debug.

Thanks in advance.



Matthew Newton <[hidden email]>, 10 Eyl 2020 Per, 15:52 tarihinde şunu
yazdı:

>
>
> On 10/09/2020 13:43, Alan DeKok wrote:
> > On Sep 10, 2020, at 2:58 AM, Yiğit YAŞAR <[hidden email]> wrote:
> >> Here is my debug output on a failed authentication attempt.
> >
> >    So... what's the problem?  Everything looks normal.
> >
> >    Please explain *what* you think is wrong, and *why* you think it's
> wrong.
>
>  From the original mangled message it looks like post-auth is calling
> both log_postauth AND log_postreject.
>
> *post-auth {log_postauthlog_postrejectif (session-state:User-Name &&
> reply:User-Name && request:User-Name && (reply:User-Name ==
> request:User-Name)) {update reply {&User-Name !* ANY}}update {&reply: +=
>
> But that debug output doesn't show this part of the config, so is rather
> meaningless.
>
> OP: please follow the instructions Jorge posted and send *full* debug
> output for both a working and non-working scenario. Mangled text and
> small extracts really doesn't help much.
>
> --
> Matthew
> -
> List info/subscribe/unsubscribe? See
> http://www.freeradius.org/list/users.html

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

radiusDebugLog.log (69K) Download Attachment
| Threaded
Open this post in threaded view
|

Re: Linelog module sending message twice that has "warning" or higher severity level.

Alan DeKok-2
On Sep 11, 2020, at 9:49 AM, Yiğit YAŞAR <[hidden email]> wrote:
>
> As mentioned at first post, my problem is the reject messages are sending
> twice.

  Yes, except that the debug logs you're posing don't show that.

> After some experimental works I discovered this situation only happening if
> severity is higher than "warning".
> There is no problem with successfully authentication message, its only sent
> once.
> I still could not find the solution.

  You still haven't shown a problem with *FreeADIUS*.

> This is my syslog event file, as you can see warning severity sending twice.
> "2020-09-11 16:42:35" "ygtysr" "authpriv" "info" "User 'ygtysr'
> authenticated via Radius!"
> "2020-09-11 16:42:41" "ygtysr" "authpriv" "warning" "User 'ygtysr'
> authentication request rejected by Radius!"
> "2020-09-11 16:42:41" "ygtysr" "authpriv" "warning" "User 'ygtysr'
> authentication request rejected by Radius!"

  That has nothing to do with FreeRADIUS.  The debug log shows that the "log_postreject" module is only called once.  And, the "log_postauth" module isn't called at all.

  So... FreeRADIUS sends one log message, and syslog stores two.  Check the *rest* of the system to see why these messages are getting duplicated.

  You can also use "strace" on Linux to verify that FreeRADIUS is calling syslog only *once*.

> I use radtest for authentication test.
> I attached the full debug.

  Attached as a ".log" file.  <sigh>

  The documentation is EXTREMELY clear on what we need.  And, what is polite to post to the list.

  When you make us do unnecessary work to help you, we're inclined to just ignore you completely.

  Alan DeKok.


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

Re: Linelog module sending message twice that has "warning" or higher severity level.

Yiğit YAŞAR
ok, i will be more careful about "attachment" rule.
thanks for the advice Mr.Dekok.

Alan DeKok <[hidden email]>, 11 Eyl 2020 Cum, 17:07 tarihinde
şunu yazdı:

> On Sep 11, 2020, at 9:49 AM, Yiğit YAŞAR <[hidden email]> wrote:
> >
> > As mentioned at first post, my problem is the reject messages are sending
> > twice.
>
>   Yes, except that the debug logs you're posing don't show that.
>
> > After some experimental works I discovered this situation only happening
> if
> > severity is higher than "warning".
> > There is no problem with successfully authentication message, its only
> sent
> > once.
> > I still could not find the solution.
>
>   You still haven't shown a problem with *FreeADIUS*.
>
> > This is my syslog event file, as you can see warning severity sending
> twice.
> > "2020-09-11 16:42:35" "ygtysr" "authpriv" "info" "User 'ygtysr'
> > authenticated via Radius!"
> > "2020-09-11 16:42:41" "ygtysr" "authpriv" "warning" "User 'ygtysr'
> > authentication request rejected by Radius!"
> > "2020-09-11 16:42:41" "ygtysr" "authpriv" "warning" "User 'ygtysr'
> > authentication request rejected by Radius!"
>
>   That has nothing to do with FreeRADIUS.  The debug log shows that the
> "log_postreject" module is only called once.  And, the "log_postauth"
> module isn't called at all.
>
>   So... FreeRADIUS sends one log message, and syslog stores two.  Check
> the *rest* of the system to see why these messages are getting duplicated.
>
>   You can also use "strace" on Linux to verify that FreeRADIUS is calling
> syslog only *once*.
>
> > I use radtest for authentication test.
> > I attached the full debug.
>
>   Attached as a ".log" file.  <sigh>
>
>   The documentation is EXTREMELY clear on what we need.  And, what is
> polite to post to the list.
>
>   When you make us do unnecessary work to help you, we're inclined to just
> ignore you completely.
>
>   Alan DeKok.
>
>
> -
> List info/subscribe/unsubscribe? See
> http://www.freeradius.org/list/users.html
-
List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html