Bug 50546 - 61_udm-users.100_test_users flaky with samba
61_udm-users.100_test_users flaky with samba
Status: CLOSED FIXED
Product: UCS Test
Classification: Unclassified
Component: S4 Connector
unspecified
Other Linux
: P5 normal (vote)
: UCS 4.4-2
Assigned To: Felix Botner
Florian Best
:
Depends on:
Blocks:
  Show dependency treegraph
 
Reported: 2019-11-26 12:24 CET by Felix Botner
Modified: 2021-05-25 10:14 CEST (History)
1 user (show)

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 Felix Botner univentionstaff 2019-11-26 12:24:37 CET
test_modlist_shadow_max_and_last_change fails on master-s4

[2019-11-26 02:37:33.887975] =================================== FAILURES ===================================
[2019-11-26 02:37:33.888133] ________ TestUsers.test_modlist_shadow_max_and_last_change[today0-None] ________
[2019-11-26 02:37:33.888220] 
[2019-11-26 02:37:33.888394] self = <100_test_users.TestUsers object at 0x7fb98b703890>, today = 18225L
[2019-11-26 02:37:33.888503] expiry_interval = None
[2019-11-26 02:37:33.888584] udm = <univention.testing.udm.UCSTestUDM object at 0x7fb98b703310>
[2019-11-26 02:37:33.888628] 
[2019-11-26 02:37:33.888709]     @pytest.mark.parametrize('today,expiry_interval', [
[2019-11-26 02:37:33.888792]             (long(time.time()) / 3600 / 24, None),
[2019-11-26 02:37:33.888907]             (long(time.time()) / 3600 / 24, 7),
[2019-11-26 02:37:33.888986]     ])
[2019-11-26 02:37:33.889066]     def test_modlist_shadow_max_and_last_change(self, today, expiry_interval, udm):
[2019-11-26 02:37:33.889147]             kw = dict(expiryInterval=expiry_interval) if expiry_interval is not None else {}
[2019-11-26 02:37:33.889233]             pwhistory = udm.create_object('policies/pwhistory', name='pw-test', **kw)
[2019-11-26 02:37:33.889312]             cn = udm.create_object('container/cn', name='testusers', policy_reference=pwhistory)
[2019-11-26 02:37:33.889403]             shadow_max_expiry = [str(expiry_interval)] if expiry_interval is not None else []
[2019-11-26 02:37:33.889513]             shadow_max_expiry_1 = [str(expiry_interval)] if expiry_interval is not None else ['1']
[2019-11-26 02:37:33.889612]     
[2019-11-26 02:37:33.889716]             user1 = udm.create_user(position=cn)[0]
[2019-11-26 02:37:33.889804]             udm.verify_ldap_object(user1, {'shadowMax': shadow_max_expiry, 'shadowLastChange': [str(today)] if expiry_interval else []})
[2019-11-26 02:37:33.889880]     
[2019-11-26 02:37:33.889996]             user2 = udm.create_user(position=cn, pwdChangeNextLogin='0')[0]
[2019-11-26 02:37:33.890074]             # FIXME?: the following was possible in UCS 4.2
[2019-11-26 02:37:33.890158]     #               udm.verify_ldap_object(user2, {'shadowMax': shadow_max_expiry, 'shadowLastChange': [str(today)]})
[2019-11-26 02:37:33.890232]     
[2019-11-26 02:37:33.890310]             user3 = udm.create_user(position=cn, pwdChangeNextLogin='1')[0]
[2019-11-26 02:37:33.890395] >           udm.verify_ldap_object(user3, {'shadowMax': shadow_max_expiry_1, 'shadowLastChange': [str(today - expiry_interval - 1) if expiry_interval else str(today - 2)]})
[2019-11-26 02:37:33.890444] 
[2019-11-26 02:37:33.890560] 100_test_users.py:372: 
[2019-11-26 02:37:33.890697] _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 
[2019-11-26 02:37:33.890819] /usr/lib/python2.7/dist-packages/univention/testing/udm.py:662: in verify_ldap_object
[2019-11-26 02:37:33.890900]     return utils.verify_ldap_object(*args, **kwargs)
[2019-11-26 02:37:33.891019] /usr/lib/python2.7/dist-packages/univention/testing/utils.py:193: in verify_ldap_object
[2019-11-26 02:37:33.891098]     delay)
[2019-11-26 02:37:33.891213] /usr/lib/python2.7/dist-packages/univention/testing/utils.py:177: in retry_on_error
[2019-11-26 02:37:33.891289]     six.reraise(*exc_info)
[2019-11-26 02:37:33.891403] /usr/lib/python2.7/dist-packages/univention/testing/utils.py:166: in retry_on_error
[2019-11-26 02:37:33.891479]     return func()
[2019-11-26 02:37:33.891624] _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 
[2019-11-26 02:37:33.891682] 
[2019-11-26 02:37:33.891818] baseDn = 'uid=xntu6oiptm,cn=testusers,dc=AutoTest091,dc=local'
[2019-11-26 02:37:33.891928] expected_attr = {'shadowLastChange': ['18223'], 'shadowMax': ['1']}
[2019-11-26 02:37:33.892032] strict = True, should_exist = True
[2019-11-26 02:37:33.892098] 
[2019-11-26 02:37:33.892182]     def __verify_ldap_object(baseDn, expected_attr=None, strict=True, should_exist=True):
[2019-11-26 02:37:33.892258]     	if expected_attr is None:
[2019-11-26 02:37:33.892333]     		expected_attr = {}
[2019-11-26 02:37:33.892414]     	try:
[2019-11-26 02:37:33.892491]     		dn, attr = get_ldap_connection().search(
[2019-11-26 02:37:33.892582]     			filter='(objectClass=*)',
[2019-11-26 02:37:33.892655]     			base=baseDn,
[2019-11-26 02:37:33.892729]     			scope=ldap.SCOPE_BASE,
[2019-11-26 02:37:33.892803]     			attr=expected_attr.keys()
[2019-11-26 02:37:33.892915]     		)[0]
[2019-11-26 02:37:33.892991]     	except (ldap.NO_SUCH_OBJECT, IndexError):
[2019-11-26 02:37:33.893065]     		if should_exist:
[2019-11-26 02:37:33.893139]     			raise LDAPObjectNotFound('DN: %s' % baseDn)
[2019-11-26 02:37:33.893212]     		return
[2019-11-26 02:37:33.893284]     
[2019-11-26 02:37:33.893357]     	if not should_exist:
[2019-11-26 02:37:33.893432]     		raise LDAPUnexpectedObjectFound('DN: %s' % baseDn)
[2019-11-26 02:37:33.893504]     
[2019-11-26 02:37:33.893578]     	values_missing = {}
[2019-11-26 02:37:33.893651]     	unexpected_values = {}
[2019-11-26 02:37:33.893726]     	for attribute, expected_values in expected_attr.items():
[2019-11-26 02:37:33.893801]     		found_values = set(attr.get(attribute, []))
[2019-11-26 02:37:33.896912]     		expected_values = set(expected_values)
[2019-11-26 02:37:33.896937]     
[2019-11-26 02:37:33.896947]     		difference = expected_values - found_values
[2019-11-26 02:37:33.896954]     		if difference:
[2019-11-26 02:37:33.896962]     			values_missing[attribute] = difference
[2019-11-26 02:37:33.896969]     
[2019-11-26 02:37:33.896975]     		if strict:
[2019-11-26 02:37:33.896982]     			difference = found_values - expected_values
[2019-11-26 02:37:33.896989]     			if difference:
[2019-11-26 02:37:33.896996]     				unexpected_values[attribute] = difference
[2019-11-26 02:37:33.897003]     
[2019-11-26 02:37:33.897013]     	values_missing = '\n'.join('%s: %r, missing   : \'%s\'' % (attribute, attr.get(attribute), '\', '.join(difference)) for attribute, difference in values_missing.iteritems())
[2019-11-26 02:37:33.897025]     	unexpected_values = '\n'.join('%s: %r, unexpected: \'%s\'' % (attribute, attr.get(attribute), '\', '.join(difference)) for attribute, difference in unexpected_values.iteritems())
[2019-11-26 02:37:33.897040]     	msg = 'DN: %s\n%s\n%s' % (baseDn, values_missing, unexpected_values)
[2019-11-26 02:37:33.897049]     
[2019-11-26 02:37:33.897056]     	if values_missing:
[2019-11-26 02:37:33.897063] >   		raise LDAPObjectValueMissing(msg)
[2019-11-26 02:37:33.897072] E     LDAPObjectValueMissing: DN: uid=xntu6oiptm,cn=testusers,dc=AutoTest091,dc=local
[2019-11-26 02:37:33.897079] E     shadowLastChange: ['18224'], missing   : '18223'
[2019-11-26 02:37:33.897086] E     shadowLastChange: ['18224'], unexpected: '18224'
Comment 1 Felix Botner univentionstaff 2019-11-26 12:27:11 CET
raised connector log level in autotest-091-master-s4.cfg
Comment 2 Florian Best univentionstaff 2019-11-26 13:43:26 CET
Might be related to the changes in Bug #50202
Comment 3 Felix Botner univentionstaff 2019-11-26 14:00:53 CET
> [2019-11-26 02:37:33.897079] E     shadowLastChange: ['18224'], missing   : 
> '18223'
> [2019-11-26 02:37:33.897086] E     shadowLastChange: ['18224'], unexpected: 
> '18224'

Seems that the problem is that the py.test parameters are evaluated before the tests are executed. This particular test has a py.test parameter "today" (time.time() / 3600/ 24) which is time depended. The parameter is set at 23.20 to x but the test starts later (because there are many tests 100_test_users) at 01.00 and now the old "today" is no longer a valid value because the "real" today is x+1


Just removed today from the py.test parameter list. This expected value for today can be set in the test itself.


ucs-test - 6503522a78d032ffbc7facff80dad0451cd96c9c
Comment 4 Florian Best univentionstaff 2019-12-12 11:14:01 CET
Nice!

FYI:
+               (None),
+               (7),

Should better have been:
+               (None,),
+               (7,),

But for one parameter both seems to work.