freeipa

#8181 Nightly test failure in test_xmlrpc/test_otptoken_plugin.py::TestDeleteLastOtpToken::test_delete[default-password+otp-allowed]
Closed: insufficientinfo by frenaud. Opened by frenaud.

Closed: insufficientinfo
Reopen Issue

The nightly test test_xmlrpc/test_otptoken_plugin.py::TestDeleteLastOtpToken::test_delete[default-password+otp-allowed] occasionally fails, see logs in PR #4160.

2020-01-25T15:26:16.4327677Z =================================== FAILURES ===================================
2020-01-25T15:26:16.4327974Z _______ TestDeleteLastOtpToken.test_delete[default-password+otp-allowed] _______
2020-01-25T15:26:16.4328046Z 
2020-01-25T15:26:16.4328102Z self = <ipatests.test_xmlrpc.test_otptoken_plugin.TestDeleteLastOtpToken object at 0x7f21f99cea90>
2020-01-25T15:26:16.4328354Z globalCfg = None, userCfg = ['password', 'otp'], allowDelLast = True
2020-01-25T15:26:16.4328431Z user = <ipatests.test_xmlrpc.tracker.user_plugin.UserTracker object at 0x7f21f99ce9d0>
2020-01-25T15:26:16.4328468Z 
2020-01-25T15:26:16.4328681Z     @pytest.mark.parametrize(
2020-01-25T15:26:16.4328913Z         "globalCfg,userCfg,allowDelLast", [
2020-01-25T15:26:16.4329187Z             # When Global config is not set and prevents user override,
2020-01-25T15:26:16.4329427Z             # it is possible to delete last token
2020-01-25T15:26:16.4329661Z             ([u'disabled'],  None, True),
2020-01-25T15:26:16.4329904Z             ([u'disabled'], [u'otp'], True),
2020-01-25T15:26:16.4330136Z             ([u'disabled'], [u'password'], True),
2020-01-25T15:26:16.4330385Z             ([u'disabled'], [u'password', u'otp'], True),
2020-01-25T15:26:16.4330655Z             # When Global config is not set and allows user override,
2020-01-25T15:26:16.4330876Z             # the userCfg applies
2020-01-25T15:26:16.4331122Z             # Deletion is forbidden only when usercfg = otp only
2020-01-25T15:26:16.4331356Z             (None,  None, True),
2020-01-25T15:26:16.4331574Z             (None, [u'otp'], False),
2020-01-25T15:26:16.4331798Z             (None, [u'password'], True),
2020-01-25T15:26:16.4332044Z             (None, [u'password', u'otp'], True),
2020-01-25T15:26:16.4332302Z             # When Global config is set to otp and prevents user override,
2020-01-25T15:26:16.4332545Z             # it is forbidden to delete last token
2020-01-25T15:26:16.4332790Z             ([u'disabled', u'otp'], None, False),
2020-01-25T15:26:16.4333034Z             ([u'disabled', u'otp'], [u'otp'], False),
2020-01-25T15:26:16.4333275Z             ([u'disabled', u'otp'], [u'password'], False),
2020-01-25T15:26:16.4333541Z             ([u'disabled', u'otp'], [u'password', u'otp'], False),
2020-01-25T15:26:16.4333799Z             # When Global config is set to otp and allows user override,
2020-01-25T15:26:16.4334019Z             # the userCfg applies
2020-01-25T15:26:16.4334295Z             # Deletion is forbidden when usercfg = otp only or usercfg not set
2020-01-25T15:26:16.4334518Z             ([u'otp'], None, False),
2020-01-25T15:26:16.4334742Z             ([u'otp'], [u'otp'], False),
2020-01-25T15:26:16.4334984Z             ([u'otp'], [u'password'], True),
2020-01-25T15:26:16.4335399Z             ([u'otp'], [u'password', u'otp'], True),
2020-01-25T15:26:16.4335661Z             # When Global config is set to password and prevents user override,
2020-01-25T15:26:16.4336021Z             # it is possible to delete last token
2020-01-25T15:26:16.4336256Z             ([u'disabled', u'password'], None, True),
2020-01-25T15:26:16.4336498Z             ([u'disabled', u'password'], [u'otp'], True),
2020-01-25T15:26:16.4336742Z             ([u'disabled', u'password'], [u'password'], True),
2020-01-25T15:26:16.4337010Z             ([u'disabled', u'password'], [u'password', u'otp'], True),
2020-01-25T15:26:16.4337270Z             # When Global config is set to password and allows user override,
2020-01-25T15:26:16.4337489Z             # the userCfg applies
2020-01-25T15:26:16.4337745Z             # Deletion is forbidden when usercfg = otp only
2020-01-25T15:26:16.4337977Z             ([u'password'], None, True),
2020-01-25T15:26:16.4338205Z             ([u'password'], [u'otp'], False),
2020-01-25T15:26:16.4338452Z             ([u'password'], [u'password'], True),
2020-01-25T15:26:16.4338691Z             ([u'password'], [u'password', u'otp'], True),
2020-01-25T15:26:16.4338953Z             # When Global config is set to password+otp and prevents user
2020-01-25T15:26:16.4339320Z             # override, it is possible to delete last token
2020-01-25T15:26:16.4339574Z             ([u'disabled', u'password', u'otp'], None, True),
2020-01-25T15:26:16.4339820Z             ([u'disabled', u'password', u'otp'], [u'otp'], True),
2020-01-25T15:26:16.4340089Z             ([u'disabled', u'password', u'otp'], [u'password'], True),
2020-01-25T15:26:16.4340349Z             ([u'disabled', u'password', u'otp'], [u'password', u'otp'], True),
2020-01-25T15:26:16.4340603Z             # When Global config is set to password+otp and allows user
2020-01-25T15:26:16.4340859Z             # override, the userCfg applies
2020-01-25T15:26:16.4341102Z             # Deletion is forbidden when usercfg = otp only
2020-01-25T15:26:16.4341334Z             ([u'password', u'otp'], None, True),
2020-01-25T15:26:16.4341592Z             ([u'password', u'otp'], [u'otp'], False),
2020-01-25T15:26:16.4341831Z             ([u'password', u'otp'], [u'password'], True),
2020-01-25T15:26:16.4342077Z             ([u'password', u'otp'], [u'password', u'otp'], True),
2020-01-25T15:26:16.4342289Z         ],
2020-01-25T15:26:16.4342498Z         ids=id_function)
2020-01-25T15:26:16.4342745Z     def test_delete(self, globalCfg, userCfg, allowDelLast, user):
2020-01-25T15:26:16.4342956Z         """
2020-01-25T15:26:16.4343183Z         Test the deletion of the last otp token
2020-01-25T15:26:16.4343373Z     
2020-01-25T15:26:16.4343633Z         The user auth type can be defined at a global level, or
2020-01-25T15:26:16.4343876Z         per-user if the override is not disabled.
2020-01-25T15:26:16.4344128Z         Depending on the resulting setting, the deletion of last token
2020-01-25T15:26:16.4344367Z         is allowed or forbidden.
2020-01-25T15:26:16.4344563Z         """
2020-01-25T15:26:16.4344780Z         # Save current global config
2020-01-25T15:26:16.4345005Z         result = api.Command.config_show()
2020-01-25T15:26:16.4345268Z         current_globalCfg = result.get('ipauserauthtype', None)
2020-01-25T15:26:16.4345456Z     
2020-01-25T15:26:16.4345646Z         try:
2020-01-25T15:26:16.4345890Z             # Set the global config for the test
2020-01-25T15:26:16.4346134Z             api.Command.config_mod(ipauserauthtype=globalCfg)
2020-01-25T15:26:16.4346353Z         except errors.EmptyModlist:
2020-01-25T15:26:16.4346567Z             pass
2020-01-25T15:26:16.4346834Z     
2020-01-25T15:26:16.4347025Z         try:
2020-01-25T15:26:16.4347256Z >           user.ensure_exists()
2020-01-25T15:26:16.4347289Z 
2020-01-25T15:26:16.4347514Z test_xmlrpc/test_otptoken_plugin.py:143: 
2020-01-25T15:26:16.4347635Z _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 
2020-01-25T15:26:16.4347904Z test_xmlrpc/tracker/base.py:210: in ensure_exists
2020-01-25T15:26:16.4348104Z     self.create()
2020-01-25T15:26:16.4348334Z test_xmlrpc/tracker/base.py:203: in create
2020-01-25T15:26:16.4351482Z     result = command()
2020-01-25T15:26:16.4351853Z test_xmlrpc/tracker/base.py:71: in run_command
2020-01-25T15:26:16.4352076Z     result = cmd(*args, **options)
2020-01-25T15:26:16.4352485Z ../ipalib/frontend.py:450: in __call__
2020-01-25T15:26:16.4352722Z     return self.__do_call(*args, **options)
2020-01-25T15:26:16.4353126Z ../ipalib/frontend.py:478: in __do_call
2020-01-25T15:26:16.4368689Z     ret = self.run(*args, **options)
2020-01-25T15:26:16.4369148Z ../ipalib/frontend.py:801: in run
2020-01-25T15:26:16.4369384Z     return self.forward(*args, **options)
2020-01-25T15:26:16.4369634Z ../ipalib/frontend.py:824: in forward
2020-01-25T15:26:16.4369856Z     *args, **kw)
2020-01-25T15:26:16.4370080Z ../ipalib/rpc.py:1149: in forward
2020-01-25T15:26:16.4370311Z     return self._call_command(command, params)
2020-01-25T15:26:16.4370560Z ../ipalib/rpc.py:1125: in _call_command
2020-01-25T15:26:16.4370775Z     return command(*params)
2020-01-25T15:26:16.4370998Z ../ipalib/rpc.py:1279: in _call
2020-01-25T15:26:16.4371234Z     return self.__request(name, args)
2020-01-25T15:26:16.4371291Z _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 
2020-01-25T15:26:16.4371339Z 
2020-01-25T15:26:16.4371388Z self = <ipalib.rpc.JSONServerProxy object at 0x7f21f99ce4d0>
2020-01-25T15:26:16.4371603Z name = 'user_add/1'
2020-01-25T15:26:16.4371878Z args = (('user_for_otp_test',), {'givenname': 'Test', 'sn': 'User for OTP', 'version': '2.235'})
2020-01-25T15:26:16.4371926Z 
2020-01-25T15:26:16.4372162Z     def __request(self, name, args):
2020-01-25T15:26:16.4372387Z         print_json = self.__verbose >= 2
2020-01-25T15:26:16.4372640Z         payload = {'method': unicode(name), 'params': args, 'id': 0}
2020-01-25T15:26:16.4372915Z         version = args[1].get('version', VERSION_WITHOUT_CAPABILITIES)
2020-01-25T15:26:16.4373141Z         payload = json_encode_binary(
2020-01-25T15:26:16.4373378Z             payload, version, pretty_print=print_json)
2020-01-25T15:26:16.4373584Z     
2020-01-25T15:26:16.4373790Z         if print_json:
2020-01-25T15:26:16.4373997Z             logger.info(
2020-01-25T15:26:16.4374218Z                 'Request: %s',
2020-01-25T15:26:16.4374441Z                 payload
2020-01-25T15:26:16.4377621Z             )
2020-01-25T15:26:16.4377831Z     
2020-01-25T15:26:16.4378077Z         response = self.__transport.request(
2020-01-25T15:26:16.4378302Z             self.__host,
2020-01-25T15:26:16.4378511Z             self.__handler,
2020-01-25T15:26:16.4378747Z             payload.encode('utf-8'),
2020-01-25T15:26:16.4378972Z             verbose=self.__verbose >= 3,
2020-01-25T15:26:16.4379165Z         )
2020-01-25T15:26:16.4379585Z     
2020-01-25T15:26:16.4379810Z         if print_json:
2020-01-25T15:26:16.4380015Z             logger.info(
2020-01-25T15:26:16.4380229Z                 'Response: %s',
2020-01-25T15:26:16.4380503Z                 json.dumps(json.loads(response), sort_keys=True, indent=4)
2020-01-25T15:26:16.4380704Z             )
2020-01-25T15:26:16.4381039Z     
2020-01-25T15:26:16.4381247Z         try:
2020-01-25T15:26:16.4381485Z             response = json_decode_binary(response)
2020-01-25T15:26:16.4381702Z         except ValueError as e:
2020-01-25T15:26:16.4381941Z             raise JSONError(error=str(e))
2020-01-25T15:26:16.4382210Z     
2020-01-25T15:26:16.4382427Z         error = response.get('error')
2020-01-25T15:26:16.4382626Z         if error:
2020-01-25T15:26:16.4382838Z             try:
2020-01-25T15:26:16.4383081Z                 error_class = errors_by_code[error['code']]
2020-01-25T15:26:16.4383298Z             except KeyError:
2020-01-25T15:26:16.4383531Z                 raise UnknownError(
2020-01-25T15:26:16.4383756Z                     code=error.get('code'),
2020-01-25T15:26:16.4383987Z                     error=error.get('message'),
2020-01-25T15:26:16.4384225Z                     server=self.__host,
2020-01-25T15:26:16.4384435Z                 )
2020-01-25T15:26:16.4384633Z             else:
2020-01-25T15:26:16.4384874Z                 kw = error.get('data', {})
2020-01-25T15:26:16.4385104Z                 kw['message'] = error['message']
2020-01-25T15:26:16.4385336Z >               raise error_class(**kw)
2020-01-25T15:26:16.4385952Z E               ipalib.errors.TimeLimitExceeded: Configured time limit exceeded
2020-01-25T15:26:16.4386014Z 
2020-01-25T15:26:16.4386252Z ../ipalib/rpc.py:1273: TimeLimitExceeded
2020-01-25T15:26:16.4386508Z ---------------------------- Captured stdout setup -----------------------------
2020-01-25T15:26:16.4386868Z Ran command: ipaclient.plugins.user.user_del()('user_for_otp_test', no_preserve=True, preserve=False, version='2.235'): NotFound: user_for_otp_test: user not found
2020-01-25T15:26:16.4387138Z ----------------------------- Captured stdout call -----------------------------
2020-01-25T15:26:16.4387492Z Ran command: ipaserver.plugins.user.user_add()('user_for_otp_test', givenname='Test', sn='User for OTP', version='2.235'): TimeLimitExceeded: Configured time limit exceeded
2020-01-25T15:26:16.4387856Z --------------------------- Captured stdout teardown ---------------------------
2020-01-25T15:26:16.4388411Z Ran command: ipaclient.plugins.user.user_del()('user_for_otp_test', no_preserve=True, preserve=False, version='2.235'): OK
2020-01-25T15:26:16.4388695Z --------------- generated xml file: /freeipa/logs/nosetests.xml ----------------

From the logs we can see that the test failed while adding the user:

[Sat Jan 25 15:24:44.303980 2020] [wsgi:error] [pid 5885:tid 140185360889600] [remote 2001:db8::242:ac11:2:46746] ipa: ERROR: Configured time limit exceeded while getting entries (base DN: uid=user_for_otp_test,cn=users,cn=accounts,dc=example,dc=test, filter: None)
[Sat Jan 25 15:24:44.304195 2020] [wsgi:error] [pid 5885:tid 140185360889600] [remote 2001:db8::242:ac11:2:46746] ipa: INFO: [jsonserver_session] admin@EXAMPLE.TEST: user_add/1('user_for_otp_test', givenname='Test', sn='User for OTP', version='2.235'): TimeLimitExceeded

The pipeline does not store 389-ds logs so it's difficult to understand what happened on DS side. We can only see in the journal that around the same time, named reconnected to DS and possibly re-read the data:

Jan 25 15:24:40 ipa.example.test named-pkcs11[5635]: successfully reconnected to LDAP server
Jan 25 15:24:40 ipa.example.test named-pkcs11[5635]: LDAP configuration for instance 'ipa' synchronized

Without more information it's not possible to diagnose the issue.

Metadata Update from @frenaud:
- Issue close_status updated to: insufficientinfo
- Issue status updated to: Closed (was: Open)
Metadata
None

test-failure tests

None
None
None
Static archive. pagure.io was sunset in 2026; this is a read-only snapshot.
Red Hat Logo

Fedora is sponsored by Red Hat. Learn more about the relationship between Red Hat and Fedora »

© Red Hat, Inc. and others.