Some RLM_MODULE_INVALID events are not logged via detail

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

Some RLM_MODULE_INVALID events are not logged via detail

Boris Lytochkin
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

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

Re: Some RLM_MODULE_INVALID events are not logged via detail

Alan DeKok-2
On Oct 30, 2019, at 12:47 PM, Boris Lytochkin <[hidden email]> 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.


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

Re: Some RLM_MODULE_INVALID events are not logged via detail

Boris Lytochkin
Hi.

See inline.

On 30.10.2019 19:58, Alan DeKok wrote:

> On Oct 30, 2019, at 12:47 PM, Boris Lytochkin <[hidden email]> 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

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

Re: Some RLM_MODULE_INVALID events are not logged via detail

Alan DeKok-2
On Oct 30, 2019, at 4:02 PM, Boris Lytochkin <[hidden email]> 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.


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

Re: Some RLM_MODULE_INVALID events are not logged via detail

Boris Lytochkin


On 30.10.2019 23:12, Alan DeKok wrote:
> On Oct 30, 2019, at 4:02 PM, Boris Lytochkin <[hidden email]> 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

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

Re: Some RLM_MODULE_INVALID events are not logged via detail

Boris Lytochkin
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 <[hidden email]> 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

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

Re: Some RLM_MODULE_INVALID events are not logged via detail

Boris Lytochkin
Uh-oh. I was browsing code for 3.0.19 while running 3.0.15.
===============
commit 86e1e83b7e34db11ee17f494e172047fdf65130b
Author: Alan T. DeKok <[hidden email]>
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 <[hidden email]> 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

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