WebAuth: add verbose 4 troubleshooting logs for auth debugging

CHANGED

@@ -1,3 +1,9 @@
+2026-04-03 - WebAuth: partially mask client certificate serial in debug logs
+
+2026-04-03 - WebAuth: redact client certificate serial in debug logs
+
+2026-04-03 - WebAuth: move troubleshooting decision logs to verbose 5
+
 2026-04-03 - Merge pull request #7 from fhem/codex/readme-module-reference-from-pod-meta
 
 [codex] Generate README module reference from POD and META.json

FHEM/98_WebAuth.pm

@@ -82,6 +82,7 @@ sub Rename {
 sub Authenticate {
   my ($me, $cl, $param) = @_;
   my $aName = $me->{NAME};
+  my $path = (ref($param) eq 'HASH' && defined($param->{_Path})) ? $param->{_Path} : '<undef>';
 
   my $doReturn = sub($;$){
     my ($r,$a) = @_;
@@ -97,21 +98,44 @@ sub Authenticate {
     return $r;
   };
 
-  return 0 if($me->{disabled} && main::IsDisabled($aName));
-  return 0 if($cl->{TYPE} ne "FHEMWEB");
+  if($me->{disabled} && main::IsDisabled($aName)) {
+    main::Log3 $aName, 5, "$aName: skipping authentication for path=$path because device is disabled";
+    return 0;
+  }
+  if($cl->{TYPE} ne "FHEMWEB") {
+    main::Log3 $aName, 5, "$aName: skipping authentication for path=$path because client type is ".($cl->{TYPE} // '<undef>');
+    return 0;
+  }
 
   my $vName = $cl->{SNAME} ? $cl->{SNAME} : $cl->{NAME};
-  return 0 if(!$me->{".validFor"}{$vName});
-  return 0 if(!$me->{".headerAuthPolicy"});
+  if(!$me->{".validFor"}{$vName}) {
+    main::Log3 $aName, 5, "$aName: skipping authentication for path=$path because frontend=$vName is not covered by validFor";
+    return 0;
+  }
+  if(!$me->{".headerAuthPolicy"}) {
+    main::Log3 $aName, 5, "$aName: skipping authentication for path=$path because no headerAuthPolicy is configured";
+    return 0;
+  }
 
-  return &$doReturn(2) if(!$param);
+  if(!$param) {
+    main::Log3 $aName, 5, "$aName: denying path=$path because no request headers were provided";
+    return &$doReturn(2);
+  }
 
   my $exc = main::AttrVal($aName, "noCheckFor", undef);
-  return 3 if($exc && $param->{_Path} =~ m/$exc/);
+  if($exc && $param->{_Path} =~ m/$exc/) {
+    main::Log3 $aName, 5, "$aName: bypassing authentication for path=$path due to noCheckFor";
+    return 3;
+  }
 
   my $trustedProxy = main::AttrVal($aName, "trustedProxy", undef);
   if($trustedProxy) {
-    return &$doReturn(0) if(!defined($cl->{PEER}) || $cl->{PEER} !~ m/$trustedProxy/);
+    if(!defined($cl->{PEER}) || $cl->{PEER} !~ m/$trustedProxy/) {
+      main::Log3 $aName, 5,
+        "$aName: proxy mismatch for path=$path peer=".(defined($cl->{PEER}) ? $cl->{PEER} : '<undef>')." trustedProxy=$trustedProxy";
+      return &$doReturn(0);
+    }
+    main::Log3 $aName, 5, "$aName: trusted proxy matched for path=$path peer=$cl->{PEER}";
   }
 
   my %effectiveHeaders = %{$param};
@@ -124,13 +148,21 @@ sub Authenticate {
       if(defined($forwardedIp) && $forwardedIp ne '');
     $effectiveHeaders{"X-FHEM-Trusted-Proxy-IP"} = $clientIp
       if(defined($clientIp) && $clientIp ne '');
+    main::Log3 $aName, 5,
+      "$aName: effective client context for path=$path peer=".(defined($clientIp) ? $clientIp : '<undef>').
+      " forwarded=".(defined($forwardedIp) ? $forwardedIp : '<undef>');
   }
 
+  main::Log3 $aName, 5,
+    "$aName: relevant headers for path=$path: "._SummarizeRelevantHeaders($me->{".headerAuthPolicy"}, \%effectiveHeaders);
+
   if(!_HasRelevantHeaders($me->{".headerAuthPolicy"}, \%effectiveHeaders)) {
     if(main::AttrVal($aName, "strict", 1)) {
+      main::Log3 $aName, 5, "$aName: denying path=$path because no relevant policy headers were present and strict=1";
       $cl->{".httpAuthHeader"} = "HTTP/1.1 403 Forbidden\r\n";
       return &$doReturn(2, "headerAuthPolicy");
     }
+    main::Log3 $aName, 5, "$aName: returning not-responsible for path=$path because no relevant policy headers were present and strict=0";
     return &$doReturn(0);
   }
   delete $cl->{".httpAuthHeader"};
@@ -141,16 +173,78 @@ sub Authenticate {
   );
   if($error) {
     main::Log3 $aName, 1, "$aName: headerAuthPolicy evaluation failed: $error";
+    main::Log3 $aName, 5, "$aName: denying path=$path because policy evaluation returned an error";
     $cl->{".httpAuthHeader"} = "HTTP/1.1 403 Forbidden\r\n";
     return &$doReturn(2, "headerAuthPolicy");
   }
 
-  return &$doReturn(1, "headerAuthPolicy") if($ok);
+  if($ok) {
+    main::Log3 $aName, 5, "$aName: authentication succeeded for path=$path via headerAuthPolicy";
+    return &$doReturn(1, "headerAuthPolicy");
+  }
 
+  main::Log3 $aName, 5, "$aName: denying path=$path because relevant headers were present but headerAuthPolicy did not match";
   $cl->{".httpAuthHeader"} = "HTTP/1.1 403 Forbidden\r\n";
   return &$doReturn(2, "headerAuthPolicy");
 }
 
+sub _SummarizeRelevantHeaders {
+  my ($policy, $headers) = @_;
+
+  return '<no-policy>' if(ref($policy) ne 'HASH');
+  return '<no-headers>' if(ref($headers) ne 'HASH');
+
+  my %wanted;
+  _CollectPolicyHeaders($policy, \%wanted);
+
+  my @summary;
+  foreach my $name (sort keys %wanted) {
+    my $value = _HeaderValue($headers, $name);
+    $value = '<absent>' if(!defined($value));
+    $value = _MaskSensitiveHeaderValue($name, $value);
+    push @summary, "$name=$value";
+  }
+
+  foreach my $synthetic (qw(X-FHEM-Client-IP X-FHEM-Forwarded-Client-IP X-FHEM-Trusted-Proxy-IP)) {
+    next if(!$wanted{$synthetic} && !_HeaderValue($headers, $synthetic));
+    my $value = _HeaderValue($headers, $synthetic);
+    $value = '<absent>' if(!defined($value));
+    push @summary, "$synthetic=$value";
+  }
+
+  return @summary ? join(', ', @summary) : '<no-policy-headers>';
+}
+
+sub _MaskSensitiveHeaderValue {
+  my ($name, $value) = @_;
+
+  return $value if(!defined($value) || $value eq '<absent>');
+
+  return '<redacted>' if($name =~ m/^(?:authorization|cookie|set-cookie)$/i);
+
+  if($name =~ m/^x-client-cert-serial$/i) {
+    return '<redacted>' if(length($value) <= 4);
+    return ('*' x (length($value) - 4)) . substr($value, -4);
+  }
+
+  return $value;
+}
+
+sub _CollectPolicyHeaders {
+  my ($node, $headers) = @_;
+
+  return if(ref($node) ne 'HASH' || ref($headers) ne 'HASH');
+
+  if(exists $node->{op}) {
+    foreach my $item (@{$node->{items}}) {
+      _CollectPolicyHeaders($item, $headers);
+    }
+    return;
+  }
+
+  $headers->{$node->{header}} = 1 if(defined($node->{header}));
+}
+
 sub _HasRelevantHeaders {
   my ($node, $headers) = @_;
 

README.md

@@ -114,6 +114,6 @@ per branch. To add this branch as an update source in FHEM, use:
 
 <!-- BEGIN GENERATED FHEM UPDATE COMMAND -->
 ```text
-update add https://raw.githubusercontent.com/fhem/WebAuth/main/controls_WebAuth.txt
+update add https://raw.githubusercontent.com/fhem/WebAuth/codex/webauth-verbose4-auth-debug/controls_WebAuth.txt
 ```
 <!-- END GENERATED FHEM UPDATE COMMAND -->

controls_WebAuth.txt

@@ -1,2 +1,2 @@
-UPD 2026-04-03_12:51:50 13217 FHEM/98_WebAuth.pm
+UPD 2026-04-03_19:23:13 16821 FHEM/98_WebAuth.pm
 UPD 2026-03-29_23:56:53 4139 lib/FHEM/Core/Authentication/HeaderPolicy.pm