From 3de5f6dacaee80a5bf198a589c12acd6015edaf8 Mon Sep 17 00:00:00 2001 From: Codex Date: Fri, 3 Apr 2026 18:21:39 +0200 Subject: [PATCH 1/7] WebAuth: add verbose 4 troubleshooting logs for header-based auth --- FHEM/98_WebAuth.pm | 97 ++++++++++++++++++++++++++++++++++++++++++---- 1 file changed, 89 insertions(+), 8 deletions(-) diff --git a/FHEM/98_WebAuth.pm b/FHEM/98_WebAuth.pm index ec8c0dc..2a7266f 100644 --- a/FHEM/98_WebAuth.pm +++ b/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} : ''; 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, 4, "$aName: skipping authentication for path=$path because device is disabled"; + return 0; + } + if($cl->{TYPE} ne "FHEMWEB") { + main::Log3 $aName, 4, "$aName: skipping authentication for path=$path because client type is ".($cl->{TYPE} // ''); + 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, 4, "$aName: skipping authentication for path=$path because frontend=$vName is not covered by validFor"; + return 0; + } + if(!$me->{".headerAuthPolicy"}) { + main::Log3 $aName, 4, "$aName: skipping authentication for path=$path because no headerAuthPolicy is configured"; + return 0; + } - return &$doReturn(2) if(!$param); + if(!$param) { + main::Log3 $aName, 4, "$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, 4, "$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, 4, + "$aName: proxy mismatch for path=$path peer=".(defined($cl->{PEER}) ? $cl->{PEER} : '')." trustedProxy=$trustedProxy"; + return &$doReturn(0); + } + main::Log3 $aName, 4, "$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, 4, + "$aName: effective client context for path=$path peer=".(defined($clientIp) ? $clientIp : ''). + " forwarded=".(defined($forwardedIp) ? $forwardedIp : ''); } + main::Log3 $aName, 4, + "$aName: relevant headers for path=$path: "._SummarizeRelevantHeaders($me->{".headerAuthPolicy"}, \%effectiveHeaders); + if(!_HasRelevantHeaders($me->{".headerAuthPolicy"}, \%effectiveHeaders)) { if(main::AttrVal($aName, "strict", 1)) { + main::Log3 $aName, 4, "$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, 4, "$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,65 @@ sub Authenticate { ); if($error) { main::Log3 $aName, 1, "$aName: headerAuthPolicy evaluation failed: $error"; + main::Log3 $aName, 4, "$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, 4, "$aName: authentication succeeded for path=$path via headerAuthPolicy"; + return &$doReturn(1, "headerAuthPolicy"); + } + main::Log3 $aName, 4, "$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 '' if(ref($policy) ne 'HASH'); + return '' if(ref($headers) ne 'HASH'); + + my %wanted; + _CollectPolicyHeaders($policy, \%wanted); + + my @summary; + foreach my $name (sort keys %wanted) { + my $value = _HeaderValue($headers, $name); + $value = '' if(!defined($value)); + if(defined($value) && $name =~ m/^(?:authorization|cookie|set-cookie)$/i) { + $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 = '' if(!defined($value)); + push @summary, "$synthetic=$value"; + } + + return @summary ? join(', ', @summary) : ''; +} + +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) = @_; From 5762628f07184ce258231b52a05a67579a41663c Mon Sep 17 00:00:00 2001 From: Codex Date: Fri, 3 Apr 2026 18:48:46 +0200 Subject: [PATCH 2/7] WebAuth: move troubleshooting decision logs to verbose 5 --- FHEM/98_WebAuth.pm | 30 +++++++++++++++--------------- 1 file changed, 15 insertions(+), 15 deletions(-) diff --git a/FHEM/98_WebAuth.pm b/FHEM/98_WebAuth.pm index 2a7266f..4fd5736 100644 --- a/FHEM/98_WebAuth.pm +++ b/FHEM/98_WebAuth.pm @@ -99,43 +99,43 @@ sub Authenticate { }; if($me->{disabled} && main::IsDisabled($aName)) { - main::Log3 $aName, 4, "$aName: skipping authentication for path=$path because device is disabled"; + main::Log3 $aName, 5, "$aName: skipping authentication for path=$path because device is disabled"; return 0; } if($cl->{TYPE} ne "FHEMWEB") { - main::Log3 $aName, 4, "$aName: skipping authentication for path=$path because client type is ".($cl->{TYPE} // ''); + main::Log3 $aName, 5, "$aName: skipping authentication for path=$path because client type is ".($cl->{TYPE} // ''); return 0; } my $vName = $cl->{SNAME} ? $cl->{SNAME} : $cl->{NAME}; if(!$me->{".validFor"}{$vName}) { - main::Log3 $aName, 4, "$aName: skipping authentication for path=$path because frontend=$vName is not covered by validFor"; + 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, 4, "$aName: skipping authentication for path=$path because no headerAuthPolicy is configured"; + main::Log3 $aName, 5, "$aName: skipping authentication for path=$path because no headerAuthPolicy is configured"; return 0; } if(!$param) { - main::Log3 $aName, 4, "$aName: denying path=$path because no request headers were provided"; + main::Log3 $aName, 5, "$aName: denying path=$path because no request headers were provided"; return &$doReturn(2); } my $exc = main::AttrVal($aName, "noCheckFor", undef); if($exc && $param->{_Path} =~ m/$exc/) { - main::Log3 $aName, 4, "$aName: bypassing authentication for path=$path due to noCheckFor"; + main::Log3 $aName, 5, "$aName: bypassing authentication for path=$path due to noCheckFor"; return 3; } my $trustedProxy = main::AttrVal($aName, "trustedProxy", undef); if($trustedProxy) { if(!defined($cl->{PEER}) || $cl->{PEER} !~ m/$trustedProxy/) { - main::Log3 $aName, 4, + main::Log3 $aName, 5, "$aName: proxy mismatch for path=$path peer=".(defined($cl->{PEER}) ? $cl->{PEER} : '')." trustedProxy=$trustedProxy"; return &$doReturn(0); } - main::Log3 $aName, 4, "$aName: trusted proxy matched for path=$path peer=$cl->{PEER}"; + main::Log3 $aName, 5, "$aName: trusted proxy matched for path=$path peer=$cl->{PEER}"; } my %effectiveHeaders = %{$param}; @@ -148,21 +148,21 @@ sub Authenticate { if(defined($forwardedIp) && $forwardedIp ne ''); $effectiveHeaders{"X-FHEM-Trusted-Proxy-IP"} = $clientIp if(defined($clientIp) && $clientIp ne ''); - main::Log3 $aName, 4, + main::Log3 $aName, 5, "$aName: effective client context for path=$path peer=".(defined($clientIp) ? $clientIp : ''). " forwarded=".(defined($forwardedIp) ? $forwardedIp : ''); } - main::Log3 $aName, 4, + 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, 4, "$aName: denying path=$path because no relevant policy headers were present and 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, 4, "$aName: returning not-responsible for path=$path because no relevant policy headers were present and strict=0"; + 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"}; @@ -173,17 +173,17 @@ sub Authenticate { ); if($error) { main::Log3 $aName, 1, "$aName: headerAuthPolicy evaluation failed: $error"; - main::Log3 $aName, 4, "$aName: denying path=$path because policy evaluation returned an 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"); } if($ok) { - main::Log3 $aName, 4, "$aName: authentication succeeded for path=$path via headerAuthPolicy"; + main::Log3 $aName, 5, "$aName: authentication succeeded for path=$path via headerAuthPolicy"; return &$doReturn(1, "headerAuthPolicy"); } - main::Log3 $aName, 4, "$aName: denying path=$path because relevant headers were present but headerAuthPolicy did not match"; + 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"); } From a0931cd432d2f789abe427c5597d0af9a66f2441 Mon Sep 17 00:00:00 2001 From: GitHub Action Date: Fri, 3 Apr 2026 16:49:04 +0000 Subject: [PATCH 3/7] Automatic update of controls and CHANGED --- CHANGED | 2 ++ README.md | 2 +- controls_WebAuth.txt | 2 +- 3 files changed, 4 insertions(+), 2 deletions(-) diff --git a/CHANGED b/CHANGED index c9fe25f..2cbf123 100644 --- a/CHANGED +++ b/CHANGED @@ -1,3 +1,5 @@ +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 diff --git a/README.md b/README.md index ed3e316..c56f5c5 100644 --- a/README.md +++ b/README.md @@ -114,6 +114,6 @@ per branch. To add this branch as an update source in FHEM, use: ```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 ``` diff --git a/controls_WebAuth.txt b/controls_WebAuth.txt index 415b6f2..5005228 100644 --- a/controls_WebAuth.txt +++ b/controls_WebAuth.txt @@ -1,2 +1,2 @@ -UPD 2026-04-03_12:51:50 13217 FHEM/98_WebAuth.pm +UPD 2026-04-03_18:48:46 16499 FHEM/98_WebAuth.pm UPD 2026-03-29_23:56:53 4139 lib/FHEM/Core/Authentication/HeaderPolicy.pm From e97f8a4e0a3adb742382f6dd858ecdcb0b913c2a Mon Sep 17 00:00:00 2001 From: Codex Date: Fri, 3 Apr 2026 19:22:27 +0200 Subject: [PATCH 4/7] WebAuth: redact client certificate serial in debug logs --- FHEM/98_WebAuth.pm | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/FHEM/98_WebAuth.pm b/FHEM/98_WebAuth.pm index 4fd5736..cb4321d 100644 --- a/FHEM/98_WebAuth.pm +++ b/FHEM/98_WebAuth.pm @@ -201,7 +201,7 @@ sub _SummarizeRelevantHeaders { foreach my $name (sort keys %wanted) { my $value = _HeaderValue($headers, $name); $value = '' if(!defined($value)); - if(defined($value) && $name =~ m/^(?:authorization|cookie|set-cookie)$/i) { + if(defined($value) && $name =~ m/^(?:authorization|cookie|set-cookie|x-client-cert-serial)$/i) { $value = ''; } push @summary, "$name=$value"; From 105266cdfc3f50c4c250c22cfb4c1b2385964ce9 Mon Sep 17 00:00:00 2001 From: GitHub Action Date: Fri, 3 Apr 2026 17:22:44 +0000 Subject: [PATCH 5/7] Automatic update of controls and CHANGED --- CHANGED | 2 ++ controls_WebAuth.txt | 2 +- 2 files changed, 3 insertions(+), 1 deletion(-) diff --git a/CHANGED b/CHANGED index 2cbf123..9fa7186 100644 --- a/CHANGED +++ b/CHANGED @@ -1,3 +1,5 @@ +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 diff --git a/controls_WebAuth.txt b/controls_WebAuth.txt index 5005228..5f2fbcd 100644 --- a/controls_WebAuth.txt +++ b/controls_WebAuth.txt @@ -1,2 +1,2 @@ -UPD 2026-04-03_18:48:46 16499 FHEM/98_WebAuth.pm +UPD 2026-04-03_19:22:32 16520 FHEM/98_WebAuth.pm UPD 2026-03-29_23:56:53 4139 lib/FHEM/Core/Authentication/HeaderPolicy.pm From 13aeda7001c754d3f80d4196d73ca48e1bbc2bbc Mon Sep 17 00:00:00 2001 From: Codex Date: Fri, 3 Apr 2026 19:23:06 +0200 Subject: [PATCH 6/7] WebAuth: partially mask client certificate serial in debug logs --- FHEM/98_WebAuth.pm | 19 ++++++++++++++++--- 1 file changed, 16 insertions(+), 3 deletions(-) diff --git a/FHEM/98_WebAuth.pm b/FHEM/98_WebAuth.pm index cb4321d..56045e3 100644 --- a/FHEM/98_WebAuth.pm +++ b/FHEM/98_WebAuth.pm @@ -201,9 +201,7 @@ sub _SummarizeRelevantHeaders { foreach my $name (sort keys %wanted) { my $value = _HeaderValue($headers, $name); $value = '' if(!defined($value)); - if(defined($value) && $name =~ m/^(?:authorization|cookie|set-cookie|x-client-cert-serial)$/i) { - $value = ''; - } + $value = _MaskSensitiveHeaderValue($name, $value); push @summary, "$name=$value"; } @@ -217,6 +215,21 @@ sub _SummarizeRelevantHeaders { return @summary ? join(', ', @summary) : ''; } +sub _MaskSensitiveHeaderValue { + my ($name, $value) = @_; + + return $value if(!defined($value) || $value eq ''); + + return '' if($name =~ m/^(?:authorization|cookie|set-cookie)$/i); + + if($name =~ m/^x-client-cert-serial$/i) { + return '' if(length($value) <= 4); + return ('*' x (length($value) - 4)) . substr($value, -4); + } + + return $value; +} + sub _CollectPolicyHeaders { my ($node, $headers) = @_; From a93f56837dd3fde8b5b3b179039e749896926010 Mon Sep 17 00:00:00 2001 From: GitHub Action Date: Fri, 3 Apr 2026 17:23:25 +0000 Subject: [PATCH 7/7] Automatic update of controls and CHANGED --- CHANGED | 2 ++ controls_WebAuth.txt | 2 +- 2 files changed, 3 insertions(+), 1 deletion(-) diff --git a/CHANGED b/CHANGED index 9fa7186..2127a05 100644 --- a/CHANGED +++ b/CHANGED @@ -1,3 +1,5 @@ +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 diff --git a/controls_WebAuth.txt b/controls_WebAuth.txt index 5f2fbcd..31d719d 100644 --- a/controls_WebAuth.txt +++ b/controls_WebAuth.txt @@ -1,2 +1,2 @@ -UPD 2026-04-03_19:22:32 16520 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