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