Linelog module sending message twice that has "warning" or higher severity level.
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
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 jpereira@freeradius.org
On 9 Sep 2020, at 03:25, Yiğit YAŞAR <y.yasar92@gmail.com> 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
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 <jpereira@freeradius.org>, 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 jpereira@freeradius.org
On 9 Sep 2020, at 03:25, Yiğit YAŞAR <y.yasar92@gmail.com> 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
On 10/09/2020 13:43, Alan DeKok wrote:
On Sep 10, 2020, at 2:58 AM, Yiğit YAŞAR <y.yasar92@gmail.com> 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
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 <mcn@freeradius.org>, 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 <y.yasar92@gmail.com> 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
On Sep 11, 2020, at 9:49 AM, Yiğit YAŞAR <y.yasar92@gmail.com> 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.
ok, i will be more careful about "attachment" rule. thanks for the advice Mr.Dekok. Alan DeKok <aland@deployingradius.com>, 11 Eyl 2020 Cum, 17:07 tarihinde şunu yazdı:
On Sep 11, 2020, at 9:49 AM, Yiğit YAŞAR <y.yasar92@gmail.com> 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
participants (4)
-
Alan DeKok -
Jorge Pereira -
Matthew Newton -
Yiğit YAŞAR