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