Bug 44918 - Add logging to ucs-school-ntlm-auth
Add logging to ucs-school-ntlm-auth
Status: CLOSED FIXED
Product: UCS@school
Classification: Unclassified
Component: Radius
UCS@school 4.1 R2
Other Linux
: P5 normal (vote)
: UCS@school 4.1 R2 v13
Assigned To: Sönke Schwardt-Krummrich
Florian Best
http://jenkins.knut.univention.de:808...
:
Depends on:
Blocks: 44919 45482 45490
  Show dependency treegraph
 
Reported: 2017-06-30 17:58 CEST by Sönke Schwardt-Krummrich
Modified: 2017-10-05 16:43 CEST (History)
0 users

See Also:
What kind of report is it?: Development Internal
What type of bug is this?: ---
Who will be affected by this bug?: ---
How will those affected feel about the bug?: ---
User Pain:
Enterprise Customer affected?:
School Customer affected?:
ISV affected?:
Waiting Support:
Flags outvoted (downgraded) after PO Review:
Ticket number:
Bug group (optional):
Max CVSS v3 score:


Attachments

Note You need to log in before you can comment on or make changes to this bug.
Description Sönke Schwardt-Krummrich univentionstaff 2017-06-30 17:58:34 CEST
Debugging of ucs-school-ntlm-auth is hard since there is no feedback other than success/failed.

So we need some kind of logging for support/professional service/development.
Comment 1 Sönke Schwardt-Krummrich univentionstaff 2017-07-11 13:43:20 CEST
A new UCR variable has been added to specify a logging file name for the auth helper ucs-school-ntlm-auth: freeradius/conf/auth-type/mschap/debugfn

ucr set freeradius/conf/auth-type/mschap/debugfn=/tmp/mschap.log
invoke-rc.d freeradius restart

The debugging output should help to identify
- in which WLAN groups the user is member of
- if WLAN is enabled for the group with highest priority
- if the sambaNTPassword value could be fetched
- if the user is disabled via sambaAcctFlags
- if the password is wrong (→ none of the above errors)

It is not intended to use this logging feature for continuous logging (too much output, no automatic permission handling for the logfile).

ucs-school-radius-802.1x.yaml:
r81030 | Bug #43421, #44603, #44900, #44916, #44918: updated advisory

ucs-school-radius-802.1x (5.0.1-1):
r81033 | Bug #44918: revamp debugging output
r81031 | Bug #44918: add UCR variable for enabling debugging of NTLM auth helper
r81029 | Bug #44918: switch from @%@BCWARNING=@%@ to @%@UCRWARNING=@%@
r81028 | Bug #44918: fixed typo in README
r81027 | Bug #44918: updated copyright
r80753 | Bug #44918: add some basic logging for debugging

Package: ucs-school-radius-802.1x
Version: 5.0.1-1.17.201707111320
Branch: ucs_4.1-0
Scope: ucs-school-4.1r2


Help for QA:
---[eapol_test.conf]---
network={
        key_mgmt=WPA-EAP
        eap=PEAP
        identity="norbert1"
        anonymous_identity="anonymous"
        password="univention"
        phase2="autheap=MSCHAPV2"
}
-----[cut]--------------

# eapol_test -c eappol_test.conf -s testing123
# eapol_test -c eappol_test.conf -s testing123 -M 11:22:33:44:55:66

The user "norbert1" should exist and should (not) be member of a class/workgroup with assigned internet rule. Within the internet rule WLAN may be enabled/disabled.
"testing123" is the default password in /etc/freeradius/clients.conf for communication between accesspoint and freeradius.
Comment 2 Florian Best univentionstaff 2017-07-19 16:51:01 CEST
REOPEN:
+	parser.add_option('--debug-stderr', dest='debug_stderr', action='store_true', default=False)
+	parser.add_option('--debug-fn', dest='debug_fn')

→ I think the first is unnecessary because one could just to --debug-fn=/dev/stderr.
→ I think a better name than --debug-fn would be --logfile.

+	helper_cmd += ' --debug-fn=%s' % (debug_fn,)
→ Missing shell escaping.

+	if True not in [wlanEnabled for (grpname, priority, wlanEnabled, ) in matchingGroups if priority == maxPriority]:
→ This should be better:
if not any(True for (grpname, priority, wlanEnabled, ) in matchingGroups if priority == maxPriority and wlanEnabled):
Comment 3 Florian Best univentionstaff 2017-07-19 17:15:16 CEST
usr/bin/ucs-school-ntlm-auth|104 col 27 error| E226 missing whitespace around arithmetic operator
Comment 4 Florian Best univentionstaff 2017-07-19 17:16:22 CEST
The tests are also failing because of the following change:
r81033
-	groups = [groupInfo[group] for group in groups if group in groupInfo]
-	if not groups:
+	matchingGroups = [[group]+list(groupInfo[group]) for group in groups if group in groupInfo]
+	if not matchingGroups:
…
-	(maxPriority, _, ) = max(groups)
+	(_, maxPriority, _, ) = max(matchingGroups)

This gives different results now depending on the group name.

>>> max([('b', 1, None), ('a', 2, None)])
('b', 1, None)

Hotfix:
diff --git a/ucs-school-radius-802.1x/usr/bin/ucs-school-ntlm-auth b/ucs-school-radius-802.1x/usr/bin/ucs-school-ntlm-auth
index 26af9a5..5f04fff 100644
--- a/ucs-school-radius-802.1x/usr/bin/ucs-school-ntlm-auth
+++ b/ucs-school-radius-802.1x/usr/bin/ucs-school-ntlm-auth
@@ -101,7 +101,7 @@ def getNTPasswordHash(username, stationId):
 »   if groups is None:
 »   »   debug('getNTPasswordHash: user not found in any relevant group - access denied')
 »   »   return None
-»   matchingGroups = [[group]+list(groupInfo[group]) for group in groups if group in groupInfo]
+»   matchingGroups = [list(groupInfo[group]) + [group] for group in groups if group in groupInfo]
 »   if not matchingGroups:
 »   »   debug('getNTPasswordHash: user not found in any WLAN enabled group - access denied')
 »   »   debug('getNTPasswordHash: user groups=%r' % (groups,))
Comment 5 Sönke Schwardt-Krummrich univentionstaff 2017-07-28 17:45:08 CEST
(In reply to Florian Best from comment #2)
> REOPEN:
> +	parser.add_option('--debug-stderr', dest='debug_stderr',
> action='store_true', default=False)
> +	parser.add_option('--debug-fn', dest='debug_fn')
> 
> → I think the first is unnecessary because one could just to
> --debug-fn=/dev/stderr.
→ DONE

> → I think a better name than --debug-fn would be --logfile.
→ DONE
 
> +	helper_cmd += ' --debug-fn=%s' % (debug_fn,)
> → Missing shell escaping.
→ fixed

> +	if True not in [wlanEnabled for (grpname, priority, wlanEnabled, ) in
> matchingGroups if priority == maxPriority]:
> → This should be better:
> if not any(True for (grpname, priority, wlanEnabled, ) in matchingGroups if
> priority == maxPriority and wlanEnabled):
→ DONE

(In reply to Florian Best from comment #4)
> The tests are also failing because of the following change:
> -	(maxPriority, _, ) = max(groups)
> +	(_, maxPriority, _, ) = max(matchingGroups)

You are right. Fixed via
maxPriority = max(matchingGroups, key=lambda x: x[1])

r81545 | Bug #44918: updated advisory
r81544 | Bug #44918: several fixes
r81543 | Bug #44918: update changelog entry
r81542 | Bug #44918: escape filename if neccessary

Package: ucs-school-radius-802.1x
Version: 5.0.1-2.18.201707281735
Branch: ucs_4.1-0
Scope: ucs-school-4.1r2
Comment 6 Florian Best univentionstaff 2017-08-02 19:32:02 CEST
Why is this still set to REOPENED?
Comment 7 Sönke Schwardt-Krummrich univentionstaff 2017-08-24 21:08:56 CEST
The UCR variable has been renamed to 
freeradius/conf/auth-type/mschap/authhelper-logfile
Comment 8 Florian Best univentionstaff 2017-08-31 10:44:27 CEST
OK: Latest changes fix old behavior
OK: renaming UCR variable
OK: YAML (except version number)
Comment 9 Sönke Schwardt-Krummrich univentionstaff 2017-09-08 15:20:20 CEST
Had to reopen this bug: the maxPriority comparison was wrong

ucs-school-radius-802.1x (5.0.1-4):
1a37973be6 | Bug #44918: added changelog entry
467ff6beca | Bug #44918: renamed maxPriority to maxPriorityGroup
660378a472 | Bug #44918: fixed comparison in ucs-school-ntlm-auth

Package: ucs-school-radius-802.1x
Version: 5.0.1-4.20.201709081518
Branch: ucs_4.1-0
Scope: ucs-school-4.1r2
Comment 10 Sönke Schwardt-Krummrich univentionstaff 2017-09-08 15:27:03 CEST
ucs-school-radius-802.1x.yaml:
5cd0c6bf67 | Bug #44918: advisory update
Comment 11 Florian Best univentionstaff 2017-09-08 15:56:44 CEST
Looks good now.
Comment 12 Sönke Schwardt-Krummrich univentionstaff 2017-09-12 13:18:21 CEST
UCS@school 4.1 R2 v13 has been released.

http://docs.software-univention.de/changelog-ucsschool-4.1R2v13-de.html

If this error occurs again, please clone this bug.