Some RLM_MODULE_INVALID events are not logged via detail
Hi. We're trying to catch a bug in some vendor's equipment resulting in "Login incorrect (eap: EAP requires the State attribute to work, but no State exists in the Access-Request packet.)" error appearing in the log and subsequent Access-Reject sent from RADIUS server (version 3.0.15 with a bit of pull requests still not merged :). It seems that this configuration does not catch that particular Access-Reject into detail(ed) log: ================== detail auth_log { header = "%t (%I)" filename = ${radacctdir}/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-%Y%m%d log_packet_header = yes permissions = 0640 } authenticate { Auth-Type EAP { eap { handled = 9999 } if (handled) { auth_log.post-auth # logging is done, return return } # eap module returned OK so we go a bit further perl # Access-Accept/Reject will be logged by authorize section } } post-auth { auth_log Post-Auth-Type REJECT { auth_log } ... } ================== Am I missing something? I took a quick tour though the code and failed to find a place where radiusd decides to **log** " Login incorrect (eap_tls: TLS Alert read:fatal:unknown CA):" into detail and **not to log** "Login incorrect (eap: EAP requires the State attribute to work, but no State exists in the Access-Request packet.)" p/s. Playing around with `handled` in Auth-Type EAP has nothing to do with detailed log as I see the same situation before I tweaked that part of the configuration. pp/s. Is there a way to print packet identifier as it is sent over the wire into detailed log? I made a trivial patch for that seeing no documented way exist to do that: =============== --- a/src/modules/rlm_detail/rlm_detail.c +++ b/src/modules/rlm_detail/rlm_detail.c @@ -336,6 +336,7 @@ static int detail_write(FILE *out, rlm_detail_t *inst, REQUEST *request, RADIUS_ } #endif } + WRITE("\tPacket-Identifier = %d\n", packet->id); WRITE("\tTimestamp = %ld\n", (unsigned long) request->timestamp); WRITE("\n"); =============== -- Boris Lytochkin Yandex NOC +7 (495) 739 70 00 ext. 7671
On Oct 30, 2019, at 12:47 PM, Boris Lytochkin <lytboris@yandex-team.ru> wrote:
We're trying to catch a bug in some vendor's equipment resulting in "Login incorrect (eap: EAP requires the State attribute to work, but no State exists in the Access-Request packet.)"
Well that's unfortunate. It's also a pretty darned serious bug.
error appearing in the log and subsequent Access-Reject sent from RADIUS server (version 3.0.15 with a bit of pull requests still not merged :).
It seems that this configuration does not catch that particular Access-Reject into detail(ed) log: ================== detail auth_log { header = "%t (%I)" filename = ${radacctdir}/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-%Y%m%d log_packet_header = yes permissions = 0640 }
authenticate { Auth-Type EAP { eap { handled = 9999 } if (handled) { auth_log.post-auth # logging is done, return return } # eap module returned OK so we go a bit further perl # Access-Accept/Reject will be logged by authorize section
The reject is logged by the Post-Auth section.
} }
post-auth { auth_log Post-Auth-Type REJECT { auth_log
That should work.
} ... } ==================
Am I missing something? I took a quick tour though the code and failed to find a place where radiusd decides to **log** " Login incorrect (eap_tls: TLS Alert read:fatal:unknown CA):" into detail and **not to log** "Login incorrect (eap: EAP requires the State attribute to work, but no State exists in the Access-Request packet.)"
The modules add a Module-Failure-Message to the request. When the "Login incorrect" message is logged, that function looks for Module-Failure-Message, and adds that text to the log message.
p/s. Playing around with `handled` in Auth-Type EAP has nothing to do with detailed log as I see the same situation before I tweaked that part of the configuration.
pp/s. Is there a way to print packet identifier as it is sent over the wire into detailed log? I made a trivial patch for that seeing no documented way exist to do that:
Not really. We can take a look at adding it. Alan DeKok.
Hi. See inline. On 30.10.2019 19:58, Alan DeKok wrote:
On Oct 30, 2019, at 12:47 PM, Boris Lytochkin <lytboris@yandex-team.ru> wrote:
error appearing in the log and subsequent Access-Reject sent from RADIUS server (version 3.0.15 with a bit of pull requests still not merged :).
It seems that this configuration does not catch that particular Access-Reject into detail(ed) log: ================== detail auth_log { header = "%t (%I)" filename = ${radacctdir}/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-%Y%m%d log_packet_header = yes permissions = 0640 }
authenticate { Auth-Type EAP { eap { handled = 9999 } if (handled) { auth_log.post-auth # logging is done, return return } # eap module returned OK so we go a bit further perl # Access-Accept/Reject will be logged by authorize section The reject is logged by the Post-Auth section.
} }
post-auth { auth_log Post-Auth-Type REJECT { auth_log
That should work. But it does not for the "State" error - packet holding Access-Reject is not recorded via detail.
Am I missing something? I took a quick tour though the code and failed to find a place where radiusd decides to **log** " Login incorrect (eap_tls: TLS Alert read:fatal:unknown CA):" into detail and **not to log** "Login incorrect (eap: EAP requires the State attribute to work, but no State exists in the Access-Request packet.)" The modules add a Module-Failure-Message to the request. When the "Login incorrect" message is logged, that function looks for Module-Failure-Message, and adds that text to the log message. Yep, the thing is that "State" message goes into radius log but Access-Reject packet is not being logged into auth_log. If you do not have any ideas why this happens I would go with further debugging via raddebug as we're unable to reproduce the issue in the lab environment.
pp/s. Is there a way to print packet identifier as it is sent over the wire into detailed log? I made a trivial patch for that seeing no documented way exist to do that: Not really. We can take a look at adding it. Before I make a pull request it would be nice to know if that patch is good enough or I should re-write it as an attribute to be usable anywhere?
-- Boris Lytochkin Yandex NOC +7 (495) 739 70 00 ext. 7671
On Oct 30, 2019, at 4:02 PM, Boris Lytochkin <lytboris@yandex-team.ru> wrote:
post-auth { auth_log Post-Auth-Type REJECT { auth_log
That should work. But it does not for the "State" error - packet holding Access-Reject is not recorded via detail.
Hmm... it should be. Maybe the reject is coming from *inside* of the TLS tunnel? Though it shouldn't be.
Yep, the thing is that "State" message goes into radius log but Access-Reject packet is not being logged into auth_log. If you do not have any ideas why this happens I would go with further debugging via raddebug as we're unable to reproduce the issue in the lab environment.
I don't know why this happens, sorry.
pp/s. Is there a way to print packet identifier as it is sent over the wire into detailed log? I made a trivial patch for that seeing no documented way exist to do that: Not really. We can take a look at adding it. Before I make a pull request it would be nice to know if that patch is good enough or I should re-write it as an attribute to be usable anywhere?
I checked, uou can use %I to get the packet ID. Alan DeKok.
On 30.10.2019 23:12, Alan DeKok wrote:
On Oct 30, 2019, at 4:02 PM, Boris Lytochkin <lytboris@yandex-team.ru> wrote:
post-auth { auth_log Post-Auth-Type REJECT { auth_log
That should work. But it does not for the "State" error - packet holding Access-Reject is not recorded via detail. Hmm... it should be. Maybe the reject is coming from *inside* of the TLS tunnel? Though it shouldn't be. I see it as a regular RADIUS packer on the wire: =================== User Datagram Protocol, Src Port: 1812, Dst Port: 50516 RADIUS Protocol Code: Access-Reject (3) Packet identifier: 0x1b (27) Length: 20 Authenticator: e3cf0e29bd7f3ed4a08d5352574918f4 [This is a response to a request in frame 113] [Time from request: 1.003118000 seconds] ===================
I'll get raddebug in charge of this then.
I checked, uou can use %I to get the packet ID. Indeed, I was confused and thought %I is expanded into (REQUEST *)request->number. Thanks!
-- Boris Lytochkin Yandex NOC +7 (495) 739 70 00 ext. 7671
And here's the answer why it is not logged: (97599) Thu Oct 31 12:34:28 2019: Debug: Auth-Type EAP { (97599) Thu Oct 31 12:34:28 2019: ERROR: eap: EAP requires the State attribute to work, but no State exists in the Access-Request packet. (97599) Thu Oct 31 12:34:28 2019: ERROR: eap: The RADIUS client is broken. No amount of changing FreeRADIUS will fix the RADIUS client. (97599) Thu Oct 31 12:34:28 2019: Debug: eap: Either EAP-request timed out OR EAP-response to an unknown EAP-request (97599) Thu Oct 31 12:34:28 2019: Debug: eap: Failed in handler (97599) Thu Oct 31 12:34:28 2019: Debug: [eap] = invalid (97599) Thu Oct 31 12:34:28 2019: Debug: } # Auth-Type EAP = invalid (97599) Thu Oct 31 12:34:28 2019: Debug: Failed to authenticate the user (97599) Thu Oct 31 12:34:28 2019: Debug: Using Post-Auth-Type Reject (97599) Thu Oct 31 12:34:28 2019: Debug: # Executing group from file /usr/local/etc/raddb/radiusd.conf (97599) Thu Oct 31 12:34:28 2019: Debug: Post-Auth-Type REJECT { (97599) Thu Oct 31 12:34:28 2019: Debug: auth_log: EXPAND /var/log/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-%Y%m%d (97599) Thu Oct 31 12:34:28 2019: Debug: auth_log: --> /var/log/radacct/.../auth-20191031 (97599) Thu Oct 31 12:34:28 2019: Debug: auth_log: /var/log/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-%Y%m%d expands to ----->>> (97599) Thu Oct 31 12:34:28 2019: WARNING: auth_log: Skipping empty packet (97599) Thu Oct 31 12:34:28 2019: Debug: [auth_log] = ok ===================== if ((packet->code == PW_CODE_ACCOUNTING_REQUEST) && !packet->vps) { RWDEBUG("Skipping empty packet"); return 0; } ===================== That's weird that this packet is treated as accounting request... On 30.10.2019 23:33, Boris Lytochkin wrote:
On 30.10.2019 23:12, Alan DeKok wrote:
On Oct 30, 2019, at 4:02 PM, Boris Lytochkin <lytboris@yandex-team.ru> wrote:
post-auth { auth_log Post-Auth-Type REJECT { auth_log That should work. But it does not for the "State" error - packet holding Access-Reject is not recorded via detail. Hmm... it should be. Maybe the reject is coming from *inside* of the TLS tunnel? Though it shouldn't be. I see it as a regular RADIUS packer on the wire: =================== User Datagram Protocol, Src Port: 1812, Dst Port: 50516 RADIUS Protocol Code: Access-Reject (3) Packet identifier: 0x1b (27) Length: 20 Authenticator: e3cf0e29bd7f3ed4a08d5352574918f4 [This is a response to a request in frame 113] [Time from request: 1.003118000 seconds] ===================
I'll get raddebug in charge of this then.
I checked, uou can use %I to get the packet ID. Indeed, I was confused and thought %I is expanded into (REQUEST *)request->number. Thanks!
-- Boris Lytochkin Yandex NOC +7 (495) 739 70 00 ext. 7671
Uh-oh. I was browsing code for 3.0.19 while running 3.0.15. =============== commit 86e1e83b7e34db11ee17f494e172047fdf65130b Author: Alan T. DeKok <aland@freeradius.org> Date: Thu Feb 22 09:47:55 2018 -0500 skip empty accounting packets, not all empty packets =============== Will proceed with upgrade. On 31.10.2019 13:16, Boris Lytochkin wrote:
And here's the answer why it is not logged:
(97599) Thu Oct 31 12:34:28 2019: Debug: Auth-Type EAP { (97599) Thu Oct 31 12:34:28 2019: ERROR: eap: EAP requires the State attribute to work, but no State exists in the Access-Request packet. (97599) Thu Oct 31 12:34:28 2019: ERROR: eap: The RADIUS client is broken. No amount of changing FreeRADIUS will fix the RADIUS client. (97599) Thu Oct 31 12:34:28 2019: Debug: eap: Either EAP-request timed out OR EAP-response to an unknown EAP-request (97599) Thu Oct 31 12:34:28 2019: Debug: eap: Failed in handler (97599) Thu Oct 31 12:34:28 2019: Debug: [eap] = invalid (97599) Thu Oct 31 12:34:28 2019: Debug: } # Auth-Type EAP = invalid (97599) Thu Oct 31 12:34:28 2019: Debug: Failed to authenticate the user (97599) Thu Oct 31 12:34:28 2019: Debug: Using Post-Auth-Type Reject (97599) Thu Oct 31 12:34:28 2019: Debug: # Executing group from file /usr/local/etc/raddb/radiusd.conf (97599) Thu Oct 31 12:34:28 2019: Debug: Post-Auth-Type REJECT { (97599) Thu Oct 31 12:34:28 2019: Debug: auth_log: EXPAND /var/log/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-%Y%m%d (97599) Thu Oct 31 12:34:28 2019: Debug: auth_log: --> /var/log/radacct/.../auth-20191031 (97599) Thu Oct 31 12:34:28 2019: Debug: auth_log: /var/log/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-%Y%m%d expands to ----->>> (97599) Thu Oct 31 12:34:28 2019: WARNING: auth_log: Skipping empty packet (97599) Thu Oct 31 12:34:28 2019: Debug: [auth_log] = ok
===================== if ((packet->code == PW_CODE_ACCOUNTING_REQUEST) && !packet->vps) { RWDEBUG("Skipping empty packet"); return 0; } ===================== That's weird that this packet is treated as accounting request...
On 30.10.2019 23:33, Boris Lytochkin wrote:
On 30.10.2019 23:12, Alan DeKok wrote:
On Oct 30, 2019, at 4:02 PM, Boris Lytochkin <lytboris@yandex-team.ru> wrote:
post-auth { auth_log Post-Auth-Type REJECT { auth_log That should work. But it does not for the "State" error - packet holding Access-Reject is not recorded via detail. Hmm... it should be. Maybe the reject is coming from *inside* of the TLS tunnel? Though it shouldn't be. I see it as a regular RADIUS packer on the wire: =================== User Datagram Protocol, Src Port: 1812, Dst Port: 50516 RADIUS Protocol Code: Access-Reject (3) Packet identifier: 0x1b (27) Length: 20 Authenticator: e3cf0e29bd7f3ed4a08d5352574918f4 [This is a response to a request in frame 113] [Time from request: 1.003118000 seconds] ===================
I'll get raddebug in charge of this then.
I checked, uou can use %I to get the packet ID. Indeed, I was confused and thought %I is expanded into (REQUEST *)request->number. Thanks!
-- Boris Lytochkin Yandex NOC +7 (495) 739 70 00 ext. 7671
participants (2)
-
Alan DeKok -
Boris Lytochkin