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 <aland at 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 at 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