search

freeipa / freeipa-pr-ci

FreeIPA Pull Request CI
GNU General Public License v3.0
8 stars 32 forks source link

Tests timeout with "No free disk space" error message #422

Closed wladich closed 3 years ago

wladich commented 3 years ago

Timeout can occur

In both cases the current process looks like being stuck.

fcami commented 3 years ago

That's similar to https://github.com/freeipa/freeipa-pr-ci/issues/420

wladich commented 3 years ago

@fcami Yes, I have notticed #420 after I created this one. The differences I see:

wladich commented 3 years ago

Found one problem old jobs occupy 33 Gb on one of the runners because autocleaner is crashing when trying to remove old jobs directories:

Mar 04 07:01:32 permanent-big-runner-10 CROND[382236]: (root) CMDOUT (Started auto-cleaning process...)
Mar 04 07:01:33 permanent-big-runner-10 CROND[382236]: (root) CMDOUT (Checking if box freeipa/ci-master-f33                         (libvirt, 0.0.6) is used)
Mar 04 07:01:33 permanent-big-runner-10 CROND[382236]: (root) CMDOUT (Box is used on master in definition ipatests/prci_definitions/nightly_latest.yaml)
Mar 04 07:01:34 permanent-big-runner-10 CROND[382236]: (root) CMDOUT (Process Process-1:)
Mar 04 07:01:34 permanent-big-runner-10 CROND[382236]: (root) CMDOUT (Traceback (most recent call last):)
Mar 04 07:01:34 permanent-big-runner-10 CROND[382236]: (root) CMDOUT (  File "/usr/lib64/python3.8/multiprocessing/process.py", line 315, in _bootstrap)
Mar 04 07:01:34 permanent-big-runner-10 CROND[382236]: (root) CMDOUT (    self.run())
Mar 04 07:01:34 permanent-big-runner-10 CROND[382236]: (root) CMDOUT (  File "/usr/lib64/python3.8/multiprocessing/process.py", line 108, in run)
Mar 04 07:01:34 permanent-big-runner-10 CROND[382236]: (root) CMDOUT (    self._target(*self._args, **self._kwargs))
Mar 04 07:01:34 permanent-big-runner-10 CROND[382236]: (root) CMDOUT (  File "/root/freeipa-pr-ci/autocleaner.py", line 379, in run)
Mar 04 07:01:34 permanent-big-runner-10 CROND[382236]: (root) CMDOUT (    prune_exports = prune_exports_file(old_dirs))
Mar 04 07:01:34 permanent-big-runner-10 CROND[382236]: (root) CMDOUT (  File "/root/freeipa-pr-ci/autocleaner.py", line 152, in prune_exports_file)
Mar 04 07:01:34 permanent-big-runner-10 CROND[382236]: (root) CMDOUT (    subprocess.run(['exportfs', '-ar'], timeout=TIMEOUT))
Mar 04 07:01:34 permanent-big-runner-10 CROND[382236]: (root) CMDOUT (  File "/usr/lib64/python3.8/subprocess.py", line 489, in run)
Mar 04 07:01:34 permanent-big-runner-10 CROND[382236]: (root) CMDOUT (    with Popen(*popenargs, **kwargs) as process:)
Mar 04 07:01:34 permanent-big-runner-10 CROND[382236]: (root) CMDOUT (  File "/usr/lib64/python3.8/subprocess.py", line 854, in __init__)
Mar 04 07:01:34 permanent-big-runner-10 CROND[382236]: (root) CMDOUT (    self._execute_child(args, executable, preexec_fn, close_fds,)
Mar 04 07:01:34 permanent-big-runner-10 CROND[382236]: (root) CMDOUT (  File "/usr/lib64/python3.8/subprocess.py", line 1702, in _execute_child)
Mar 04 07:01:34 permanent-big-runner-10 CROND[382236]: (root) CMDOUT (    raise child_exception_type(errno_num, err_msg, err_filename))
Mar 04 07:01:34 permanent-big-runner-10 CROND[382236]: (root) CMDOUT (FileNotFoundError: [Errno 2] No such file or directory: 'exportfs')

In cron jobs executables should be specified with full path, i.e. /usr/sbin/exportfs as env is usually minimal

netoarmando commented 3 years ago

I've cleaned the rest of the nightly runners manually. Let's wait the next round of tests to check if the number of errors reduce.

wladich commented 3 years ago

I have checked journalctl on nightly runners - auto-cleaner is running successfully now

wladich commented 3 years ago

Some stats:

test plan Jobs timeouted before the fix Jobs timeouted after the fix
testing_master_pki 4, 2, 1 2
testing_ipa-4.6 1,0,0 0
testing_master_389ds 3, 2, 1 0
testing_ipa-4.9_previous 1,3,4 2
testing_master_testing 7, 6, 7 3
testing_ipa-4.9_latest 5, 2 0
testing_ipa-4.9_latest_selinux 5,4 2
testing_master_previous 5, 2, 5, 1, 1 0
testing_master_testing_selinux 8, 8, 5 NA
testing_master_latest_selinux 4, 0, 4 NA
testing_ipa-4.6 1, 0, 0 0
testing_master_latest 3,1, 3, 5, 4 NA

So the situation has improved, but still is not fixed completely. Remaining timeouts look following way:

2021-03-05 17:23:25,864    DEBUG  [ipatests.pytest_ipa.integration.host.Host.master.cmd38] Upgrading IPA:. Estimated time: 1 minute 30 seconds
2021-03-05 17:23:25,865    DEBUG  [ipatests.pytest_ipa.integration.host.Host.master.cmd38]   [1/11]: stopping directory server
2021-03-05 17:23:27,586    DEBUG  [ipatests.pytest_ipa.integration.host.Host.master.cmd38]   [2/11]: saving configuration
2021-03-05 17:23:27,790    DEBUG  [ipatests.pytest_ipa.integration.host.Host.master.cmd38]   [3/11]: disabling listeners
2021-03-05 17:23:27,965    DEBUG  [ipatests.pytest_ipa.integration.host.Host.master.cmd38]   [4/11]: enabling DS global lock
2021-03-05 17:23:28,092    DEBUG  [ipatests.pytest_ipa.integration.host.Host.master.cmd38]   [5/11]: disabling Schema Compat
2021-03-05 17:23:28,155    DEBUG  [ipatests.pytest_ipa.integration.host.Host.master.cmd38]   [6/11]: starting directory server
2021-03-05 17:23:31,595    DEBUG  [ipatests.pytest_ipa.integration.host.Host.master.cmd38]   [7/11]: updating schema
2021-03-05 17:23:33,500    DEBUG  [ipatests.pytest_ipa.integration.host.Host.master.cmd38]   [8/11]: upgrading server
2021-03-05 18:53:48,528 CRITICAL  Terminating execution, runtime exceeded 7200s
2021-03-05 18:53:48,583    DEBUG  Process "vagrant ssh -c IPATEST_YAML_CONFIG=/vagrant/ipa-test-config.yaml ipa-run-tests test_integration/test_acme.py --verbose --logging-level=debug --logfile-dir=/vagrant/ --html=/vagrant/report.html --junit-xml=/vagrant/junit.xml" exited with error code -9
Traceback (most recent call last):
  File "/root/freeipa-pr-ci/tasks/common.py", line 135, in __call__
    super(FallibleTask, self).__call__()
  File "/root/freeipa-pr-ci/tasks/common.py", line 122, in __call__
    raise self.exc
  File "/root/freeipa-pr-ci/tasks/common.py", line 105, in __target
    self._run()
  File "/root/freeipa-pr-ci/tasks/common.py", line 179, in _run
    raise PopenException(self)
tasks.common.PopenException: Process "vagrant ssh -c IPATEST_YAML_CONFIG=/vagrant/ipa-test-config.yaml ipa-run-tests test_integration/test_acme.py --verbose --logging-level=debug --logfile-dir=/vagrant/ --html=/vagrant/report.html --junit-xml=/vagrant/junit.xml" exited with error code -9
2021-03-05 18:53:48,628    ERROR  >>>>>> PYTEST ERROR (-9) <<<<<<
2021-03-05 18:53:48,629     INFO  Executing: VagrantCleanup
fcami commented 3 years ago

The second time of timeout is due to some kind of hang during test execution. It might be due to nested virtualization and happens randomly. I don't think these are related to the issue described here.

wladich commented 3 years ago

I managed to reproduce the situation when ipa-server-install hangs with output:

[ipatests.pytest_ipa.integration.host.Host.master.cmd38] Upgrading IPA:. Estimated time: 1 minute 30 seconds
[ipatests.pytest_ipa.integration.host.Host.master.cmd38]   [1/11]: stopping directory server
[ipatests.pytest_ipa.integration.host.Host.master.cmd38]   [2/11]: saving configuration
[ipatests.pytest_ipa.integration.host.Host.master.cmd38]   [3/11]: disabling listeners
[ipatests.pytest_ipa.integration.host.Host.master.cmd38]   [4/11]: enabling DS global lock
[ipatests.pytest_ipa.integration.host.Host.master.cmd38]   [5/11]: disabling Schema Compat
[ipatests.pytest_ipa.integration.host.Host.master.cmd38]   [6/11]: starting directory server
[ipatests.pytest_ipa.integration.host.Host.master.cmd38]   [7/11]: updating schema
[ipatests.pytest_ipa.integration.host.Host.master.cmd38]   [8/11]: upgrading server

Versions:

Test suite: test_integration/test_backup_and_restore.py::TestBackupAndRestoreWithReplica Test output: https://gist.github.com/wladich/d3c977294a68893aff7611f3e9722bca

Here is the stack at this moment:

Traceback (most recent call first):
  <built-in method result4 of LDAP object at remote 0x7fc9c6cafcc0>
  File "/usr/lib64/python3.9/site-packages/ldap/ldapobject.py", line 580, in _ldap_call

  File "/usr/lib64/python3.9/site-packages/ldap/ldapobject.py", line 774, in result4
    ldap_result = self._ldap_call(self._l.result4,msgid,all,timeout,add_ctrls,add_intermediates,add_extop)
  File "/usr/lib64/python3.9/site-packages/ldap/ldapobject.py", line 1020, in result3
    )
  File "/usr/lib64/python3.9/site-packages/ldap/ldapobject.py", line 425, in add_ext_s
    resp_type, resp_data, resp_msgid, resp_ctrls = self.result3(msgid,all=1,timeout=self.timeout)
  File "/usr/lib64/python3.9/site-packages/ldap/ldapobject.py", line 439, in add_s
    return self.add_ext_s(dn,modlist,None,None)
  File "/usr/lib/python3.9/site-packages/ipapython/ipaldap.py", line 1657, in add_entry
    self.conn.add_s(str(entry.dn), list(attrs.items()))
  File "/usr/lib/python3.9/site-packages/ipaserver/install/ldapupdate.py", line 1056, in _update_record
  File "/usr/lib/python3.9/site-packages/ipaserver/install/ldapupdate.py", line 898, in _run_updates
    entry, modified = self._update_record(update)
  File "/usr/lib/python3.9/site-packages/ipaserver/install/ldapupdate.py", line 935, in update
    self._run_updates(all_updates)
  File "/usr/lib/python3.9/site-packages/ipaserver/install/upgradeinstance.py", line 290, in __upgrade
    self.modified = (ld.update(self.files) or self.modified)
  File "/usr/lib/python3.9/site-packages/ipaserver/install/service.py", line 621, in run_step
    method()
  File "/usr/lib/python3.9/site-packages/ipaserver/install/service.py", line 1147, in start_creation
  File "/usr/lib/python3.9/site-packages/ipaserver/install/upgradeinstance.py", line 899, in create_instance
  File "/usr/lib/python3.9/site-packages/ipaserver/install/dsinstance.py", line 965, in apply_updates

  File "/usr/lib/python3.9/site-packages/ipaserver/install/server/install.py", line 4285, in install
  File "/usr/lib/python3.9/site-packages/ipaserver/install/server/install.py", line 275, in decorated
    func(installer)
  File "/usr/lib/python3.9/site-packages/ipaserver/install/server/__init__.py", line 575, in main
    master_install(self)
  File "/usr/lib/python3.9/site-packages/ipapython/install/common.py", line 65, in _install
    for unused in self._installer(self.parent):
  File "/usr/lib/python3.9/site-packages/ipapython/install/util.py", line 59, in run_generator_with_yield_from
    value = gen.send(prev_value)
  <built-in method next of module object at remote 0x7fc9d0b858b0>
  File "/usr/lib/python3.9/site-packages/ipapython/install/core.py", line 418, in <lambda>
    step = lambda: next(self.__gen)
  File "/usr/lib/python3.9/site-packages/ipapython/install/core.py", line 421, in __runner
    step()
  <built-in method next of module object at remote 0x7fc9d0b858b0>
  File "/usr/lib/python3.9/site-packages/ipapython/install/core.py", line 655, in _configure
    next(executor)
  File "/usr/lib/python3.9/site-packages/ipapython/install/util.py", line 59, in run_generator_with_yield_from
    value = gen.send(prev_value)
  <built-in method next of module object at remote 0x7fc9d0b858b0>
  File "/usr/lib/python3.9/site-packages/ipapython/install/core.py", line 418, in <lambda>
    step = lambda: next(self.__gen)
  File "/usr/lib/python3.9/site-packages/ipapython/install/core.py", line 421, in __runner
    step()
  File "/usr/lib/python3.9/site-packages/ipapython/install/core.py", line 386, in execute
    for rval in self._executor():
  File "/usr/lib/python3.9/site-packages/ipapython/install/core.py", line 360, in run
    return self.execute()
  File "/usr/lib/python3.9/site-packages/ipapython/install/cli.py", line 340, in run
    return cfgr.run()
  File "/usr/lib/python3.9/site-packages/ipapython/admintool.py", line 180, in execute
    return_value = self.run()
  File "/usr/lib/python3.9/site-packages/ipapython/admintool.py", line 156, in main
    return command.execute()
  File "/usr/lib/python3.9/site-packages/ipapython/admintool.py", line 132, in run_cli
    sys.exit(cls.main(sys.argv))
  File "/usr/lib/python3.9/site-packages/ipaserver/install/ipa_server_install.py", line 51, in run
    ServerInstall.run_cli()
  File "/usr/sbin/ipa-server-install", line 25, in <module>
    ipa_server_install.run()

Full backtrace with argument values: https://gist.githubusercontent.com/wladich/a70a521a40bc5538d907abae9edad0e2/raw/996dbcdfaf70563240ee94f2202f066cb9011677/gistfile1.txt

wladich commented 3 years ago

The frame

File "/usr/lib/python3.9/site-packages/ipaserver/install/ldapupdate.py", line 898, in _run_updates
    entry, modified = self._update_record(update)

is from https://github.com/freeipa/freeipa/blob/daec8049610ad7bbe0718276d2e7d6ffc1a7f66e/ipaserver/install/ldapupdate.py#L898

The update at which the process stuck:

local 'update' = {'dn': <DN(rdns=[[('cn', 'FleetCommander Desktop Profile Administrators', 1)], [('cn', 'privileges', 1)], [('cn', 'pbac', 1)], [('dc', 'ipa', 1)], [('dc', 'test', 1)]]) at remote 0x7fc9c5904d90>, 'default': [{'attr': 'objectClass', 'value': b'top'}, {'attr': 'objectClass', 'value': b'groupofnames'}, {'attr': 'objectClass', 'value': b'nestedgroup'}, {'attr': 'cn', 'value': b'FleetCommander Desktop Profile Administrators'}, {'attr': 'description', 'value': b'FleetCommander Desktop Profile Administrators'}, {'attr': 'member', 'value': b'cn=FleetCommander Desktop Profile Administrators,cn=roles,cn=accounts,dc=ipa,dc=test'}]}
wladich commented 3 years ago

Tails of log files: ipaserver-install.log

021-03-08T18:09:15Z DEBUG ---------------------------------------------
2021-03-08T18:09:15Z DEBUG Initial value
2021-03-08T18:09:15Z DEBUG dn: cn=FleetCommander Desktop Profile Administrators,cn=privileges,cn=pbac,dc=ipa,dc=test
2021-03-08T18:09:15Z DEBUG objectClass:
2021-03-08T18:09:15Z DEBUG      top
2021-03-08T18:09:15Z DEBUG      groupofnames
2021-03-08T18:09:15Z DEBUG      nestedgroup
2021-03-08T18:09:15Z DEBUG cn:
2021-03-08T18:09:15Z DEBUG      FleetCommander Desktop Profile Administrators
2021-03-08T18:09:15Z DEBUG description:
2021-03-08T18:09:15Z DEBUG      FleetCommander Desktop Profile Administrators
2021-03-08T18:09:15Z DEBUG member:
2021-03-08T18:09:15Z DEBUG      cn=FleetCommander Desktop Profile Administrators,cn=roles,cn=accounts,dc=ipa,dc=test
2021-03-08T18:09:15Z DEBUG ---------------------------------------------
2021-03-08T18:09:15Z DEBUG Final value after applying updates
2021-03-08T18:09:15Z DEBUG dn: cn=FleetCommander Desktop Profile Administrators,cn=privileges,cn=pbac,dc=ipa,dc=test
2021-03-08T18:09:15Z DEBUG objectClass:
2021-03-08T18:09:15Z DEBUG      top
2021-03-08T18:09:15Z DEBUG      groupofnames
2021-03-08T18:09:15Z DEBUG      nestedgroup
2021-03-08T18:09:15Z DEBUG cn:
2021-03-08T18:09:15Z DEBUG      FleetCommander Desktop Profile Administrators
2021-03-08T18:09:15Z DEBUG description:
2021-03-08T18:09:15Z DEBUG      FleetCommander Desktop Profile Administrators
2021-03-08T18:09:15Z DEBUG member:
2021-03-08T18:09:15Z DEBUG      cn=FleetCommander Desktop Profile Administrators,cn=roles,cn=accounts,dc=ipa,dc=test

/var/log/dirsrv/slapd-IPA-TEST/access

[08/Mar/2021:18:09:15.251444986 +0000] conn=4 op=560 SRCH base="cn=FleetCommander Desktop Profile Administrators,cn=roles,cn=accounts,dc=ipa,dc=test" scope=0 filter="(objectClass=*)" attrs="objectClasses aci * attributeTypes"
[08/Mar/2021:18:09:15.254228232 +0000] conn=4 op=560 RESULT err=32 tag=101 nentries=0 wtime=0.000043607 optime=0.002790379 etime=0.002831271
[08/Mar/2021:18:09:15.255947668 +0000] conn=4 op=561 ADD dn="cn=FleetCommander Desktop Profile Administrators,cn=roles,cn=accounts,dc=ipa,dc=test"
[08/Mar/2021:18:09:15.261133390 +0000] conn=4 op=562 SRCH base="cn=FleetCommander Desktop Profile Administrators,cn=privileges,cn=pbac,dc=ipa,dc=test" scope=0 filter="(objectClass=*)" attrs="objectClasses aci * attributeTypes"
[08/Mar/2021:18:09:15.263940289 +0000] conn=4 op=563 ADD dn="cn=FleetCommander Desktop Profile Administrators,cn=privileges,cn=pbac,dc=ipa,dc=test"
[08/Mar/2021:18:09:15.264024493 +0000] conn=4 op=562 RESULT err=32 tag=101 nentries=0 wtime=0.000045722 optime=0.002898152 etime=0.002941253
[08/Mar/2021:18:09:15.261304370 +0000] conn=4 op=561 RESULT err=0 tag=105 nentries=0 wtime=0.000103907 optime=0.005360651 etime=0.005394639

/var/log/dirsrv/slapd-IPA-TEST/errors

[08/Mar/2021:18:09:15.182928557 +0000] - DEBUG - replication - copy_operation_parameters - replica is null.
[08/Mar/2021:18:09:15.198978244 +0000] - DEBUG - replication - copy_operation_parameters - replica is null.
[08/Mar/2021:18:09:15.204505454 +0000] - DEBUG - replication - copy_operation_parameters - replica is null.
[08/Mar/2021:18:09:15.210718019 +0000] - DEBUG - replication - copy_operation_parameters - replica is null.
[08/Mar/2021:18:09:15.220642151 +0000] - DEBUG - replication - copy_operation_parameters - replica is null.
[08/Mar/2021:18:09:15.238207210 +0000] - DEBUG - replication - copy_operation_parameters - replica is null.
[08/Mar/2021:18:09:15.243289646 +0000] - DEBUG - replication - copy_operation_parameters - replica is null.
[08/Mar/2021:18:09:15.249045439 +0000] - DEBUG - replication - copy_operation_parameters - replica is null.
[08/Mar/2021:18:09:15.253931239 +0000] - ERR - cos-plugin - cos_dn_defs_cb - Skipping CoS Definition cn=Password Policy,cn=accounts,dc=ipa,dc=test--no CoS Templates found, which should be added before the CoS Definition.
[08/Mar/2021:18:09:15.257972154 +0000] - DEBUG - replication - copy_operation_parameters - replica is null.
[08/Mar/2021:18:09:15.264569761 +0000] - DEBUG - replication - copy_operation_parameters - replica is null.
[08/Mar/2021:18:09:15.267646456 +0000] - DEBUG - replication - copy_operation_parameters - replica is null.
[08/Mar/2021:18:09:25.087851748 +0000] - DEBUG - replication - copy_operation_parameters - replica is null.

journalctl -p warning

Mar 08 18:03:43 master.ipa.test pwdhash[29104]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:03:44 master.ipa.test certutil[29128]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:03:44 master.ipa.test ns-slapd[29136]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:03:49 master.ipa.test ns-slapd[29174]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:03:53 master.ipa.test ns-slapd[29212]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:04:02 master.ipa.test ns-slapd[29313]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:04:14 master.ipa.test certutil[29582]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:04:14 master.ipa.test certutil[29583]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:04:15 master.ipa.test certutil[29584]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:04:15 master.ipa.test certutil[29586]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:04:16 master.ipa.test certutil[29604]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:04:17 master.ipa.test certutil[29605]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:04:18 master.ipa.test java[29607]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:04:20 master.ipa.test java[29624]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:04:51 master.ipa.test java[29646]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:04:55 master.ipa.test java[29694]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:05:00 master.ipa.test java[29801]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:05:13 master.ipa.test certutil[29929]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:05:13 master.ipa.test certutil[29930]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:05:21 master.ipa.test certutil[29937]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:05:25 master.ipa.test java[29956]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:05:27 master.ipa.test java[29973]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:05:29 master.ipa.test java[29990]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:05:31 master.ipa.test java[30007]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:05:33 master.ipa.test java[30024]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:05:35 master.ipa.test java[30041]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:05:37 master.ipa.test java[30058]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:05:39 master.ipa.test java[30075]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:05:41 master.ipa.test java[30092]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:05:43 master.ipa.test java[30109]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:05:45 master.ipa.test java[30126]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:05:46 master.ipa.test certutil[30142]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:05:46 master.ipa.test pk12util[30143]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:05:48 master.ipa.test certutil[30146]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:05:48 master.ipa.test certutil[30147]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:05:48 master.ipa.test certutil[30148]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:05:48 master.ipa.test certutil[30149]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:05:48 master.ipa.test certutil[30150]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:05:48 master.ipa.test certutil[30151]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:05:48 master.ipa.test certutil[30152]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:05:48 master.ipa.test certutil[30153]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:05:48 master.ipa.test certutil[30154]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:05:48 master.ipa.test certutil[30155]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:05:50 master.ipa.test java[30158]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:05:53 master.ipa.test java[30172]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:05:55 master.ipa.test java[30189]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:05:57 master.ipa.test java[30206]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:05:58 master.ipa.test certutil[30224]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:05:58 master.ipa.test certutil[30225]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:05:58 master.ipa.test certutil[30226]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:05:59 master.ipa.test java[30228]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:06:01 master.ipa.test java[30245]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:06:03 master.ipa.test java[30262]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:06:05 master.ipa.test java[30279]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:06:07 master.ipa.test java[30296]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:06:09 master.ipa.test java[30314]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:06:12 master.ipa.test certutil[30361]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:06:12 master.ipa.test certutil[30362]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:06:14 master.ipa.test java[30395]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:06:19 master.ipa.test java[30506]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:06:39 master.ipa.test java[30793]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:06:45 master.ipa.test java[30899]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:07:02 master.ipa.test dogtag-ipa-renew-agent-submit[31091]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:07:27 master.ipa.test dogtag-submit[31141]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:07:27 master.ipa.test certmonger[31157]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:07:27 master.ipa.test dogtag-submit[31158]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:07:27 master.ipa.test dogtag-submit[31161]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:07:29 master.ipa.test dogtag-submit[31165]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:07:30 master.ipa.test certmonger[31171]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:07:33 master.ipa.test certmonger[31187]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:07:33 master.ipa.test certmonger[31187]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:07:35 master.ipa.test certmonger[31188]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:07:35 master.ipa.test certmonger[31188]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:07:37 master.ipa.test certmonger[31190]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:07:37 master.ipa.test certmonger[31191]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:07:37 master.ipa.test certmonger[31190]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:07:37 master.ipa.test certmonger[31191]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:07:38 master.ipa.test certmonger[31192]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:07:38 master.ipa.test certmonger[31192]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:07:39 master.ipa.test certmonger[31193]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:07:39 master.ipa.test certmonger[31193]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:07:40 master.ipa.test certmonger[31194]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:07:40 master.ipa.test certmonger[31194]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:07:40 master.ipa.test certmonger[31195]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:07:40 master.ipa.test certmonger[31196]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:07:40 master.ipa.test certmonger[31195]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:07:40 master.ipa.test certmonger[31196]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:07:40 master.ipa.test certmonger[31197]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:07:40 master.ipa.test certmonger[31197]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:07:41 master.ipa.test certmonger[31198]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:07:41 master.ipa.test certmonger[31198]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:07:41 master.ipa.test certmonger[31199]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:07:41 master.ipa.test certmonger[31199]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:07:41 master.ipa.test certmonger[31200]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:07:41 master.ipa.test certmonger[31200]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:07:43 master.ipa.test certmonger[31247]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:07:43 master.ipa.test certmonger[31247]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:07:43 master.ipa.test certmonger[31248]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:07:44 master.ipa.test certmonger[31248]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:07:44 master.ipa.test certmonger[31249]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:07:44 master.ipa.test certmonger[31249]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:07:45 master.ipa.test certmonger[31250]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:07:45 master.ipa.test certmonger[31250]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:07:45 master.ipa.test certmonger[31251]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:07:45 master.ipa.test certmonger[31251]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:07:45 master.ipa.test certmonger[31252]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:07:45 master.ipa.test certmonger[31252]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:07:46 master.ipa.test certmonger[31254]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:07:46 master.ipa.test certmonger[31254]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:07:47 master.ipa.test certutil[31259]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:07:47 master.ipa.test certutil[31260]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:07:47 master.ipa.test certutil[31271]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:07:47 master.ipa.test dogtag-submit[31274]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:07:47 master.ipa.test certmonger[31280]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:07:48 master.ipa.test certmonger[31280]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:07:48 master.ipa.test certmonger[31282]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:07:48 master.ipa.test certmonger[31282]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:07:48 master.ipa.test certmonger[31283]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:07:48 master.ipa.test certmonger[31283]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:07:48 master.ipa.test certmonger[31284]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:07:48 master.ipa.test certmonger[31284]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:07:48 master.ipa.test certmonger[31285]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:07:48 master.ipa.test certmonger[31285]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:07:48 master.ipa.test certmonger[31286]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:07:48 master.ipa.test certmonger[31286]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:07:48 master.ipa.test certmonger[31287]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:07:48 master.ipa.test certmonger[31287]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:07:49 master.ipa.test certmonger[31288]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:07:49 master.ipa.test certmonger[31288]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:07:50 master.ipa.test certmonger[31290]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:07:50 master.ipa.test certmonger[31290]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:07:50 master.ipa.test certmonger[31291]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:07:50 master.ipa.test certmonger[31291]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:07:51 master.ipa.test dogtag-submit[31292]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:07:52 master.ipa.test certmonger[31296]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:07:52 master.ipa.test certmonger[31296]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:07:52 master.ipa.test certmonger[31298]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:07:52 master.ipa.test certmonger[31298]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:07:59 master.ipa.test ns-slapd[31341]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:08:00 master.ipa.test certmonger[31377]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:08:00 master.ipa.test certutil[31378]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:08:00 master.ipa.test certmonger[31377]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:08:01 master.ipa.test certmonger[31382]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:08:01 master.ipa.test certmonger[31382]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:08:01 master.ipa.test certutil[31383]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:08:01 master.ipa.test certutil[31386]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:08:01 master.ipa.test certutil[31389]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:08:03 master.ipa.test ns-slapd[31425]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:08:10 master.ipa.test ns-slapd[31502]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:08:14 master.ipa.test java[31561]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:08:20 master.ipa.test java[31671]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:08:45 master.ipa.test dogtag-submit[31916]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:08:45 master.ipa.test certmonger[31922]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:08:45 master.ipa.test certmonger[31922]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:08:45 master.ipa.test certmonger[31925]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:08:45 master.ipa.test certmonger[31925]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:08:46 master.ipa.test certmonger[31935]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:08:46 master.ipa.test dogtag-submit[31936]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:08:47 master.ipa.test certmonger[31945]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:08:48 master.ipa.test certmonger[31957]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:08:48 master.ipa.test certmonger[31957]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:08:49 master.ipa.test certmonger[31960]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:08:49 master.ipa.test certmonger[31960]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:08:49 master.ipa.test certmonger[31962]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:08:57 master.ipa.test dogtag-submit[32296]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:08:57 master.ipa.test certmonger[32302]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:08:57 master.ipa.test certmonger[32302]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:08:57 master.ipa.test certmonger[32304]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:08:57 master.ipa.test certmonger[32304]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:08:57 master.ipa.test certmonger[32306]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:08:57 master.ipa.test certmonger[32313]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:08:57 master.ipa.test dogtag-submit[32348]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:08:58 master.ipa.test certmonger[32354]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:09:02 master.ipa.test certmonger[32382]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:09:03 master.ipa.test certmonger[32382]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:09:03 master.ipa.test ns-slapd[32389]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:09:03 master.ipa.test certmonger[32390]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:09:04 master.ipa.test certmonger[32390]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:09:04 master.ipa.test certmonger[32393]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 08 18:09:04 master.ipa.test certmonger[32395]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
wladich commented 3 years ago

@flo-renaud @fcami To me this all looks like a bug, possibly in dirsrv. I want to ask you for assistance with further investigations. I can provide access to the VM which is currently stuck at ipa-server-install.

fcami commented 3 years ago

Adding @tbordaz @mreynolds389

Similar hits: https://lists.fedorahosted.org/archives/list/freeipa-users@lists.fedorahosted.org/thread/XFYVC6MUAKYLRIR6H6WM6SD4USLMIG2E/

https://bugzilla.redhat.com/show_bug.cgi?id=1850290

mreynolds389 commented 3 years ago

This could be a DS problem, did anyone confirm if DS was hung? If it is, we just need a stack trace from ns-slapd to confirm what the server is doing (or not doing).

tbordaz commented 3 years ago

I agree with @mreynolds389 it could be a DS problem. Looking DS access logs it seems that the following ADD never completed

[08/Mar/2021:18:09:15.263940289 +0000] conn=4 op=563 ADD dn="cn=FleetCommander Desktop Profile Administrators,cn=privileges,cn=pbac,dc=ipa,dc=test"

To help DS diag we would need a pstack/"top -H -p pidof ns-slapd -b -n 10" or better access to the VM where it fails

wladich commented 3 years ago
tbordaz commented 3 years ago

The hang is triggered by a cos cacher rebuilt, that try to acquire a RWlock in write mode This blocks all others threads

Thread 6 : rebuilds cos cache (cos_cache_build_definition_list) trying to acquire vattr rwlock (in write priority)
    Thread 20: ADD an entry is blocked by Thread 6, waiting for vattr rwlock, while holding DB pages
        Thread 14: ADD an entry is blocked by Thread 20, waiting on DB pages
        Thread 11: is block because of 20 and nsslapd-global-backend-lock: on
    Thread 10: is blocked by Thread 6, waiting for vattr rwlock
    Thread 27: is blocked by Thread 6, waiting for vattr rwlock

Thread 6 (Thread 0x7f43df6b1640 (LWP 32404) "ns-slapd"):
#0  futex_abstimed_wait (private=0, abstime=0x0, clockid=0, expected=2, futex_word=) at ../sysdeps/nptl/futex-internal.h:284
#1  __pthread_rwlock_wrlock_full (abstime=0x0, clockid=0, rwlock=0x7f43f5a28240) at pthread_rwlock_common.c:830
#2  __GI___pthread_rwlock_wrlock (rwlock=0x7f43f5a28240) at pthread_rwlock_wrlock.c:27
#3  0x00007f43f7139f43 in slapi_rwlock_wrlock (rwlock=) at ldap/servers/slapd/slapi2runtime.c:305
#4  0x00007f43f713a48f in vattr_map_insert (vae=0x7f43f0d5fda0) at ldap/servers/slapd/vattr.c:2116
..
#7  0x00007f43f27becb3 in cos_dn_defs_cb (e=0x7f43f0d50380, callback_data=0x7f43df6af3e0) at ldap/servers/plugins/cos/cos_cache.c:859
#8  0x00007f43f711511e in send_ldap_search_entry_ext (pb=0x7f43f221da20, e=0x7f43f0d50380, ectrls=0x0, attrs=0x0, attrsonly=0, send_result=send_result@entry=0, nentries=0, urls=0x0) at ldap/servers/slapd/result.c:1507
...
#15 0x00007f43f71020a4 in slapi_search_internal_callback_pb (pb=pb@entry=0x7f43f221da20, callback_data=callback_data@entry=0x7f43df6af3e0, prc=prc@entry=0x0, psec=psec@entry=0x7f43f27be360 , prec=prec@entry=0x0) at ldap/servers/slapd/plugin_internal_op.c:520
..
#17 cos_cache_build_definition_list (vattr_cacheable=0x7f43f1b94f48, pDefs=0x7f43f1b94f20) at ldap/servers/plugins/cos/cos_cache.c:666
...
#20 0x00007f43f27c2195 in cos_cache_wait_on_change (arg=) at ldap/servers/plugins/cos/cos_cache.c:419

cos cache rebuilt should not hang itself because there is no thread holding 'the_map->lock' in backstack BUT the RWlock is showing 14 readers that I can not find in the stack

    (gdb) print *the_map->lock
$41 = {__data = {__readers = 14, __writers = 0, __wrphase_futex = 2, __writers_futex = 1, __pad3 = 0, __pad4 = 0, __cur_writer = 0, __shared = 0, __rwelision = 0 '\000',
    __pad1 = "\000\000\000\000\000\000", __pad2 = 0, __flags = 2},
  __size = "\016\000\000\000\000\000\000\000\002\000\000\000\001", '\000' , "\002\000\000\000\000\000\000", __align = 14}

The bug may have existed since a long time but was not an issue until Writers got the priority on RWlock https://pagure.io/389-ds-base/issue/51068

In conclusion the most probable cause is it exists rdlock leak on the RWlock, some thread forgetting to release the lock. this is not an issue while there is only readers but become blocker with writer

wladich commented 3 years ago

I have looked at nightly test results for Fedora 32 ([testing_master_previous]) and Fedora 33 ([testing_master_latest]). If we ignore failures due to low disk space, we have:

Fedora 33

2021-03-10 00:16:08,907    DEBUG  [ipatests.pytest_ipa.integration.host.Host.master.cmd35] Configuring certificate server (pki-tomcatd). Estimated time: 3 minutes
2021-03-10 00:16:08,907    DEBUG  [ipatests.pytest_ipa.integration.host.Host.master.cmd35]   [1/28]: configuring certificate server instance
2021-03-10 00:16:08,907    DEBUG  [ipatests.pytest_ipa.integration.host.Host.master.cmd35]   [2/28]: stopping certificate server instance to update CS.cfg
2021-03-10 00:16:08,907    DEBUG  [ipatests.pytest_ipa.integration.host.Host.master.cmd35]   [3/28]: backing up CS.cfg
2021-03-10 00:16:08,907    DEBUG  [ipatests.pytest_ipa.integration.host.Host.master.cmd35]   [4/28]: Add ipa-pki-wait-running
2021-03-10 00:16:08,908    DEBUG  [ipatests.pytest_ipa.integration.host.Host.master.cmd35]   [5/28]: secure AJP connector
2021-03-10 00:16:08,908    DEBUG  [ipatests.pytest_ipa.integration.host.Host.master.cmd35]   [6/28]: reindex attributes
2021-03-10 00:16:08,908    DEBUG  [ipatests.pytest_ipa.integration.host.Host.master.cmd35]   [7/28]: exporting Dogtag certificate store pin
2021-03-10 00:16:08,908    DEBUG  [ipatests.pytest_ipa.integration.host.Host.master.cmd35]   [8/28]: disabling nonces
2021-03-10 00:16:08,908    DEBUG  [ipatests.pytest_ipa.integration.host.Host.master.cmd35]   [9/28]: set up CRL publishing
2021-03-10 00:16:08,908    DEBUG  [ipatests.pytest_ipa.integration.host.Host.master.cmd35]   [10/28]: enable PKIX certificate path discovery and validation
2021-03-10 00:16:08,908    DEBUG  [ipatests.pytest_ipa.integration.host.Host.master.cmd35]   [11/28]: authorizing RA to modify profiles
2021-03-10 00:16:08,908    DEBUG  [ipatests.pytest_ipa.integration.host.Host.master.cmd35]   [12/28]: authorizing RA to manage lightweight CAs
2021-03-10 00:16:08,908    DEBUG  [ipatests.pytest_ipa.integration.host.Host.master.cmd35]   [13/28]: Ensure lightweight CAs container exists
2021-03-10 00:16:08,908    DEBUG  [ipatests.pytest_ipa.integration.host.Host.master.cmd35]   [14/28]: starting certificate server instance
2021-03-10 00:16:08,908    DEBUG  [ipatests.pytest_ipa.integration.host.Host.master.cmd35]   [15/28]: configure certmonger for renewals
2021-03-10 00:16:08,908    DEBUG  [ipatests.pytest_ipa.integration.host.Host.master.cmd35]   [16/28]: requesting RA certificate from CA
2021-03-10 00:16:08,908    DEBUG  [ipatests.pytest_ipa.integration.host.Host.master.cmd35]   [17/28]: publishing the CA certificate
2021-03-10 00:16:08,908    DEBUG  [ipatests.pytest_ipa.integration.host.Host.master.cmd35]   [18/28]: adding RA agent as a trusted user
2021-03-10 00:16:08,908    DEBUG  [ipatests.pytest_ipa.integration.host.Host.master.cmd35]   [19/28]: configure certificate renewals
2021-03-10 00:16:08,908    DEBUG  [ipatests.pytest_ipa.integration.host.Host.master.cmd35]   [20/28]: Configure HTTP to proxy connections
2021-03-10 03:07:02,946 CRITICAL  Terminating execution, runtime exceeded 10800s
2021-03-10 03:07:02,964    DEBUG  [ipatests.pytest_ipa.integration.host.Host.master.cmd35]   [21/28]: updating IPA configuration
2021-03-10 00:28:52,888    DEBUG  [ipatests.pytest_ipa.integration.host.Host.master.cmd35] Configuring the web interface (httpd)
2021-03-10 00:28:52,888    DEBUG  [ipatests.pytest_ipa.integration.host.Host.master.cmd35]   [1/21]: stopping httpd
2021-03-10 00:28:52,888    DEBUG  [ipatests.pytest_ipa.integration.host.Host.master.cmd35]   [2/21]: backing up ssl.conf
2021-03-10 00:28:52,888    DEBUG  [ipatests.pytest_ipa.integration.host.Host.master.cmd35]   [3/21]: disabling nss.conf
2021-03-10 00:28:52,888    DEBUG  [ipatests.pytest_ipa.integration.host.Host.master.cmd35]   [4/21]: configuring mod_ssl certificate paths
2021-03-10 00:28:52,888    DEBUG  [ipatests.pytest_ipa.integration.host.Host.master.cmd35]   [5/21]: setting mod_ssl protocol list
2021-03-10 00:28:52,888    DEBUG  [ipatests.pytest_ipa.integration.host.Host.master.cmd35]   [6/21]: configuring mod_ssl log directory
2021-03-10 00:28:52,888    DEBUG  [ipatests.pytest_ipa.integration.host.Host.master.cmd35]   [7/21]: disabling mod_ssl OCSP
2021-03-10 00:28:52,889    DEBUG  [ipatests.pytest_ipa.integration.host.Host.master.cmd35]   [8/21]: adding URL rewriting rules
2021-03-10 00:28:52,889    DEBUG  [ipatests.pytest_ipa.integration.host.Host.master.cmd35]   [9/21]: configuring httpd
2021-03-10 00:28:52,889    DEBUG  [ipatests.pytest_ipa.integration.host.Host.master.cmd35]   [10/21]: setting up httpd keytab
2021-03-10 02:20:24,752 CRITICAL  Terminating execution, runtime exceeded 7200s
2021-03-10 02:20:24,766    DEBUG  [ipatests.pytest_ipa.integration.host.Host.master.cmd35]   [11/21]: configuring Gssproxy
2021-02-17 02:02:49,068    DEBUG  [ipatests.pytest_ipa.integration.host.Host.master.cmd30] Configuring certificate server (pki-tomcatd). Estimated time: 3 minutes
2021-02-17 02:02:49,068    DEBUG  [ipatests.pytest_ipa.integration.host.Host.master.cmd30]   [1/28]: configuring certificate server instance
2021-02-17 02:02:49,068    DEBUG  [ipatests.pytest_ipa.integration.host.Host.master.cmd30]   [2/28]: stopping certificate server instance to update CS.cfg
2021-02-17 02:02:49,068    DEBUG  [ipatests.pytest_ipa.integration.host.Host.master.cmd30]   [3/28]: backing up CS.cfg
2021-02-17 02:02:49,068    DEBUG  [ipatests.pytest_ipa.integration.host.Host.master.cmd30]   [4/28]: Add ipa-pki-wait-running
2021-02-17 02:02:49,068    DEBUG  [ipatests.pytest_ipa.integration.host.Host.master.cmd30]   [5/28]: secure AJP connector
2021-02-17 02:02:49,068    DEBUG  [ipatests.pytest_ipa.integration.host.Host.master.cmd30]   [6/28]: reindex attributes
2021-02-17 02:02:49,068    DEBUG  [ipatests.pytest_ipa.integration.host.Host.master.cmd30]   [7/28]: exporting Dogtag certificate store pin
2021-02-17 02:02:49,068    DEBUG  [ipatests.pytest_ipa.integration.host.Host.master.cmd30]   [8/28]: disabling nonces
2021-02-17 02:02:49,068    DEBUG  [ipatests.pytest_ipa.integration.host.Host.master.cmd30]   [9/28]: set up CRL publishing
2021-02-17 02:02:49,068    DEBUG  [ipatests.pytest_ipa.integration.host.Host.master.cmd30]   [10/28]: enable PKIX certificate path discovery and validation
2021-02-17 02:02:49,068    DEBUG  [ipatests.pytest_ipa.integration.host.Host.master.cmd30]   [11/28]: authorizing RA to modify profiles
2021-02-17 02:47:17,302 CRITICAL  Terminating execution, runtime exceeded 3600s
2021-02-17 02:47:17,317    DEBUG  [ipatests.pytest_ipa.integration.host.Host.master.cmd30]   [12/28]: authorizing RA to manage lightweight CAs
2021-02-24 00:03:06,334    DEBUG  [ipatests.pytest_ipa.integration.host.Host.master.cmd30] Configuring the web interface (httpd)
2021-02-24 00:03:06,334    DEBUG  [ipatests.pytest_ipa.integration.host.Host.master.cmd30]   [1/21]: stopping httpd
2021-02-24 00:03:06,334    DEBUG  [ipatests.pytest_ipa.integration.host.Host.master.cmd30]   [2/21]: backing up ssl.conf
2021-02-24 00:03:06,334    DEBUG  [ipatests.pytest_ipa.integration.host.Host.master.cmd30]   [3/21]: disabling nss.conf
2021-02-24 00:03:06,334    DEBUG  [ipatests.pytest_ipa.integration.host.Host.master.cmd30]   [4/21]: configuring mod_ssl certificate paths
2021-02-24 00:03:06,334    DEBUG  [ipatests.pytest_ipa.integration.host.Host.master.cmd30]   [5/21]: setting mod_ssl protocol list
2021-02-24 00:03:06,334    DEBUG  [ipatests.pytest_ipa.integration.host.Host.master.cmd30]   [6/21]: configuring mod_ssl log directory
2021-02-24 00:03:06,334    DEBUG  [ipatests.pytest_ipa.integration.host.Host.master.cmd30]   [7/21]: disabling mod_ssl OCSP
2021-02-24 00:03:06,334    DEBUG  [ipatests.pytest_ipa.integration.host.Host.master.cmd30]   [8/21]: adding URL rewriting rules
2021-02-24 00:03:06,334    DEBUG  [ipatests.pytest_ipa.integration.host.Host.master.cmd30]   [9/21]: configuring httpd
2021-02-24 00:03:06,334    DEBUG  [ipatests.pytest_ipa.integration.host.Host.master.cmd30]   [10/21]: setting up httpd keytab
2021-02-24 00:03:06,334    DEBUG  [ipatests.pytest_ipa.integration.host.Host.master.cmd30]   [11/21]: configuring Gssproxy
2021-02-24 00:03:06,334    DEBUG  [ipatests.pytest_ipa.integration.host.Host.master.cmd30]   [12/21]: setting up ssl
2021-02-24 00:03:06,334    DEBUG  [ipatests.pytest_ipa.integration.host.Host.master.cmd30]   [13/21]: configure certmonger for renewals
2021-02-24 00:03:06,334    DEBUG  [ipatests.pytest_ipa.integration.host.Host.master.cmd30]   [14/21]: publish CA cert
2021-02-24 00:03:06,334    DEBUG  [ipatests.pytest_ipa.integration.host.Host.master.cmd30]   [15/21]: clean up any existing httpd ccaches
2021-02-24 00:03:06,334    DEBUG  [ipatests.pytest_ipa.integration.host.Host.master.cmd30]   [16/21]: configuring SELinux for httpd
2021-02-24 00:03:06,334    DEBUG  [ipatests.pytest_ipa.integration.host.Host.master.cmd30]   [17/21]: create KDC proxy config
2021-02-24 00:03:06,334    DEBUG  [ipatests.pytest_ipa.integration.host.Host.master.cmd30]   [18/21]: enable KDC proxy
2021-02-24 00:03:06,334    DEBUG  [ipatests.pytest_ipa.integration.host.Host.master.cmd30]   [19/21]: starting httpd
2021-02-24 00:03:06,334    DEBUG  [ipatests.pytest_ipa.integration.host.Host.master.cmd30]   [20/21]: configuring httpd to start on boot
2021-02-24 00:03:06,334    DEBUG  [ipatests.pytest_ipa.integration.host.Host.master.cmd30]   [21/21]: enabling oddjobd
2021-02-24 00:03:06,335    DEBUG  [ipatests.pytest_ipa.integration.host.Host.master.cmd30] Done configuring the web interface (httpd).
2021-02-24 00:31:54,762 CRITICAL  Terminating execution, runtime exceeded 3600s
2021-02-24 00:31:54,791    DEBUG  [ipatests.pytest_ipa.integration.host.Host.master.cmd30] Configuring Kerberos KDC (krb5kdc)
2021-02-24 00:43:37,980    DEBUG  [ipatests.pytest_ipa.integration.host.Host.master.cmd30] Upgrading IPA:. Estimated time: 1 minute 30 seconds
2021-02-24 00:43:37,981    DEBUG  [ipatests.pytest_ipa.integration.host.Host.master.cmd30]   [1/11]: stopping directory server
2021-02-24 00:43:37,981    DEBUG  [ipatests.pytest_ipa.integration.host.Host.master.cmd30]   [2/11]: saving configuration
2021-02-24 00:43:37,981    DEBUG  [ipatests.pytest_ipa.integration.host.Host.master.cmd30]   [3/11]: disabling listeners
2021-02-24 00:43:37,981    DEBUG  [ipatests.pytest_ipa.integration.host.Host.master.cmd30]   [4/11]: enabling DS global lock
2021-02-24 00:43:37,981    DEBUG  [ipatests.pytest_ipa.integration.host.Host.master.cmd30]   [5/11]: disabling Schema Compat
2021-02-24 01:35:29,253 CRITICAL  Terminating execution, runtime exceeded 3600s
2021-02-24 01:35:29,265    DEBUG  [ipatests.pytest_ipa.integration.host.Host.master.cmd30]   [6/11]: starting directory server
2021-03-02 23:54:21,958    DEBUG  [ipatests.pytest_ipa.integration.host.Host.master.cmd30] Configuring ipa-otpd
2021-03-02 23:54:21,958    DEBUG  [ipatests.pytest_ipa.integration.host.Host.master.cmd30]   [1/2]: starting ipa-otpd 
2021-03-03 02:42:35,863 CRITICAL  Terminating execution, runtime exceeded 10800s
2021-03-03 02:42:35,884    DEBUG  [ipatests.pytest_ipa.integration.host.Host.master.cmd30]   [2/2]: configuring ipa-otpd to start on boot
2021-03-03 00:24:25,869    DEBUG  [ipatests.pytest_ipa.integration.host.Host.master.cmd54] Configuring Kerberos KDC (krb5kdc)
2021-03-03 00:24:25,869    DEBUG  [ipatests.pytest_ipa.integration.host.Host.master.cmd54]   [1/10]: adding kerberos container to the directory
2021-03-03 00:24:25,869    DEBUG  [ipatests.pytest_ipa.integration.host.Host.master.cmd54]   [2/10]: configuring KDC
2021-03-03 00:24:25,869    DEBUG  [ipatests.pytest_ipa.integration.host.Host.master.cmd54]   [3/10]: initialize kerberos container
2021-03-03 01:50:25,288 CRITICAL  Terminating execution, runtime exceeded 5400s
2021-03-03 01:50:25,306    DEBUG  [ipatests.pytest_ipa.integration.host.Host.master.cmd54]   [4/10]: adding default ACIs

And only once it happened during `ipactl restart: runner.log

2021-03-03 01:53:34,292    DEBUG  [ipatests.pytest_ipa.integration.host.Host.master.IPAOpenSSHTransport] RUN ['ipactl', 'restart']
2021-03-03 01:53:34,292    DEBUG  [ipatests.pytest_ipa.integration.host.Host.master.cmd357] RUN ['ipactl', 'restart']
2021-03-03 01:53:34,292    DEBUG  [ipatests.pytest_ipa.integration.host.Host.master.cmd357] ipa: INFO: The ipactl command was successful
2021-03-03 01:53:34,292    DEBUG  [ipatests.pytest_ipa.integration.host.Host.master.cmd357] Restarting Directory Service
2021-03-03 01:53:34,292    DEBUG  [ipatests.pytest_ipa.integration.host.Host.master.cmd357]     debugging enabled, suppressing output.
2021-03-03 01:53:34,292    DEBUG  [ipatests.pytest_ipa.integration.host.Host.master.cmd357] Restarting krb5kdc Service
2021-03-03 01:53:34,292    DEBUG  [ipatests.pytest_ipa.integration.host.Host.master.cmd357] Restarting kadmin Service
2021-03-03 01:53:34,292    DEBUG  [ipatests.pytest_ipa.integration.host.Host.master.cmd357] Restarting named Service
2021-03-03 01:53:34,293    DEBUG  [ipatests.pytest_ipa.integration.host.Host.master.cmd357] Restarting httpd Service
2021-03-03 01:53:34,293    DEBUG  [ipatests.pytest_ipa.integration.host.Host.master.cmd357] Restarting ipa-custodia Service
2021-03-03 01:53:34,892 CRITICAL  Terminating execution, runtime exceeded 3600s
2021-03-03 01:53:34,914    DEBUG  [ipatests.pytest_ipa.integration.host.Host.master.cmd357] Restarting pki-tomcatd Service
tbordaz commented 3 years ago

@wladich thanks for this status. It will help to debug/verify a fix. I think the RC of the failure (lock leak) was introduced with https://github.com/389ds/389-ds-base/issues/2932 (2 years ago) However the failure was hidden because of priority given to readers in the RWlock. Recently we changed the priority to writers (https://github.com/389ds/389-ds-base/issues/4121), and then the lock leak became visible and detected with those tests

wladich commented 3 years ago

runner.log files for Fedora 32: http://freeipa-org-pr-ci.s3-website.eu-central-1.amazonaws.com/jobs/f74ebd2e-7bb0-11eb-808a-fa163e5185d3/runner.log.gz http://freeipa-org-pr-ci.s3-website.eu-central-1.amazonaws.com/jobs/5049d6ca-762f-11eb-bf17-fa163e290d14/runner.log.gz http://freeipa-org-pr-ci.s3-website.eu-central-1.amazonaws.com/jobs/3ffe4436-7bb6-11eb-9a5e-fa163e632508/runner.log.gz http://freeipa-org-pr-ci.s3-website.eu-central-1.amazonaws.com/jobs/10d01026-70c2-11eb-b44b-fa163eef4f62/runner.log.gz http://freeipa-org-pr-ci.s3-website.eu-central-1.amazonaws.com/jobs/31e86468-7638-11eb-bc9f-fa163ec41f36/runner.log.gz http://freeipa-org-pr-ci.s3-website.eu-central-1.amazonaws.com/jobs/e1e37268-7bba-11eb-b0e1-fa163e809cae/runner.log.gz http://freeipa-org-pr-ci.s3-website.eu-central-1.amazonaws.com/jobs/eaff2904-8142-11eb-8ccb-fa163e0817f7/runner.log.gz http://freeipa-org-pr-ci.s3-website.eu-central-1.amazonaws.com/jobs/6890c77c-8136-11eb-967a-fa163e46012f/runner.log.gz http://freeipa-org-pr-ci.s3-website.eu-central-1.amazonaws.com/jobs/8aa690b4-8134-11eb-90e7-fa163e5ccdc8/runner.log.gz

wladich commented 3 years ago

Issue reproduced for Fedora 32. It seems to be quite similar to one on Fedora 33. The main difference is the last ipa-server-install message.

Versions:

Test output tail:

Mar 11 15:40:23 sorlov-big-runner-3 bash[71937]: DEBUG: root: [ipatests.pytest_ipa.integration.host.Host.master.cmd2205] Configuring the web interface (httpd)
Mar 11 15:40:23 sorlov-big-runner-3 bash[71937]: DEBUG: root: [ipatests.pytest_ipa.integration.host.Host.master.cmd2205]   [1/21]: stopping httpd
Mar 11 15:40:23 sorlov-big-runner-3 bash[71937]: DEBUG: root: [ipatests.pytest_ipa.integration.host.Host.master.cmd2205]   [2/21]: backing up ssl.conf
Mar 11 15:40:23 sorlov-big-runner-3 bash[71937]: DEBUG: root: [ipatests.pytest_ipa.integration.host.Host.master.cmd2205]   [3/21]: disabling nss.conf
Mar 11 15:40:23 sorlov-big-runner-3 bash[71937]: DEBUG: root: [ipatests.pytest_ipa.integration.host.Host.master.cmd2205]   [4/21]: configuring mod_ssl certificate paths
Mar 11 15:40:23 sorlov-big-runner-3 bash[71937]: DEBUG: root: [ipatests.pytest_ipa.integration.host.Host.master.cmd2205]   [5/21]: setting mod_ssl protocol list
Mar 11 15:40:23 sorlov-big-runner-3 bash[71937]: DEBUG: root: [ipatests.pytest_ipa.integration.host.Host.master.cmd2205]   [6/21]: configuring mod_ssl log directory
Mar 11 15:40:23 sorlov-big-runner-3 bash[71937]: DEBUG: root: [ipatests.pytest_ipa.integration.host.Host.master.cmd2205]   [7/21]: disabling mod_ssl OCSP
Mar 11 15:40:23 sorlov-big-runner-3 bash[71937]: DEBUG: root: [ipatests.pytest_ipa.integration.host.Host.master.cmd2205]   [8/21]: adding URL rewriting rules
Mar 11 15:40:23 sorlov-big-runner-3 bash[71937]: DEBUG: root: [ipatests.pytest_ipa.integration.host.Host.master.cmd2205]   [9/21]: configuring httpd
Mar 11 15:40:23 sorlov-big-runner-3 bash[71937]: DEBUG: root: [ipatests.pytest_ipa.integration.host.Host.master.cmd2205]   [10/21]: setting up httpd keytab
Mar 11 15:40:23 sorlov-big-runner-3 bash[71937]: DEBUG: root: [ipatests.pytest_ipa.integration.host.Host.master.cmd2205]   [11/21]: configuring Gssproxy
Mar 11 15:40:23 sorlov-big-runner-3 bash[71937]: DEBUG: root: [ipatests.pytest_ipa.integration.host.Host.master.cmd2205]   [12/21]: setting up ssl
Mar 11 15:40:23 sorlov-big-runner-3 bash[71937]: DEBUG: root: [ipatests.pytest_ipa.integration.host.Host.master.cmd2205]   [13/21]: configure certmonger for renewals
Mar 11 15:40:23 sorlov-big-runner-3 bash[71937]: DEBUG: root: [ipatests.pytest_ipa.integration.host.Host.master.cmd2205]   [14/21]: publish CA cert
Mar 11 15:40:23 sorlov-big-runner-3 bash[71937]: DEBUG: root: [ipatests.pytest_ipa.integration.host.Host.master.cmd2205]   [15/21]: clean up any existing httpd ccaches
Mar 11 15:40:23 sorlov-big-runner-3 bash[71937]: DEBUG: root: [ipatests.pytest_ipa.integration.host.Host.master.cmd2205]   [16/21]: configuring SELinux for httpd
Mar 11 15:40:23 sorlov-big-runner-3 bash[71937]: DEBUG: root: [ipatests.pytest_ipa.integration.host.Host.master.cmd2205]   [17/21]: create KDC proxy config
Mar 11 15:40:23 sorlov-big-runner-3 bash[71937]: DEBUG: root: [ipatests.pytest_ipa.integration.host.Host.master.cmd2205]   [18/21]: enable KDC proxy
Mar 11 15:40:23 sorlov-big-runner-3 bash[71937]: DEBUG: root: [ipatests.pytest_ipa.integration.host.Host.master.cmd2205]   [19/21]: starting httpd
Mar 11 15:40:23 sorlov-big-runner-3 bash[71937]: DEBUG: root: [ipatests.pytest_ipa.integration.host.Host.master.cmd2205]   [20/21]: configuring httpd to start on boot

pstack `pidof ns-slapd` | grep vattr_map_insert

#1  0x00007ff4c7b831cf in vattr_map_insert () at target:/usr/lib64/dirsrv/libslapd.so.0

Stack of ipa-server-install:

Traceback (most recent call first):
  <built-in method result4 of LDAP object at remote 0x7fefd657c6c0>
  File "/usr/lib64/python3.8/site-packages/ldap/ldapobject.py", line 580, in _ldap_call

  File "/usr/lib64/python3.8/site-packages/ldap/ldapobject.py", line 774, in result4
    ldap_result = self._ldap_call(self._l.result4,msgid,all,timeout,add_ctrls,add_intermediates,add_extop)
  File "/usr/lib64/python3.8/site-packages/ldap/ldapobject.py", line 1020, in result3
    )
  File "/usr/lib64/python3.8/site-packages/ldap/ldapobject.py", line 425, in add_ext_s
    resp_type, resp_data, resp_msgid, resp_ctrls = self.result3(msgid,all=1,timeout=self.timeout)
  File "/usr/lib64/python3.8/site-packages/ldap/ldapobject.py", line 439, in add_s
    return self.add_ext_s(dn,modlist,None,None)
  File "/usr/lib/python3.8/site-packages/ipapython/ipaldap.py", line 1657, in add_entry
    self.conn.add_s(str(entry.dn), list(attrs.items()))
  File "/usr/lib/python3.8/site-packages/ipaserver/install/ldapupdate.py", line 1056, in _update_record
  File "/usr/lib/python3.8/site-packages/ipaserver/install/ldapupdate.py", line 898, in _run_updates
    entry, modified = self._update_record(update)
  File "/usr/lib/python3.8/site-packages/ipaserver/install/ldapupdate.py", line 935, in update
    self._run_updates(all_updates)
  File "/usr/lib/python3.8/site-packages/ipaserver/install/upgradeinstance.py", line 290, in __upgrade
    self.modified = (ld.update(self.files) or self.modified)
  File "/usr/lib/python3.8/site-packages/ipaserver/install/service.py", line 621, in run_step
    method()
  File "/usr/lib/python3.8/site-packages/ipaserver/install/service.py", line 1147, in start_creation
  File "/usr/lib/python3.8/site-packages/ipaserver/install/upgradeinstance.py", line 899, in create_instance
  File "/usr/lib/python3.8/site-packages/ipaserver/install/dsinstance.py", line 965, in apply_updates

  File "/usr/lib/python3.8/site-packages/ipaserver/install/server/install.py", line 4285, in install
  File "/usr/lib/python3.8/site-packages/ipaserver/install/server/install.py", line 275, in decorated
    func(installer)
  File "/usr/lib/python3.8/site-packages/ipaserver/install/server/__init__.py", line 575, in main
    master_install(self)
  File "/usr/lib/python3.8/site-packages/ipapython/install/common.py", line 65, in _install
    for unused in self._installer(self.parent):
  File "/usr/lib/python3.8/site-packages/ipapython/install/util.py", line 59, in run_generator_with_yield_from
    value = gen.send(prev_value)
  <built-in method next of module object at remote 0x7fefe0b2c090>
  File "/usr/lib/python3.8/site-packages/ipapython/install/core.py", line 418, in <lambda>
    step = lambda: next(self.__gen)
  File "/usr/lib/python3.8/site-packages/ipapython/install/core.py", line 421, in __runner
    step()
  <built-in method next of module object at remote 0x7fefe0b2c090>
  File "/usr/lib/python3.8/site-packages/ipapython/install/core.py", line 655, in _configure
    next(executor)
  File "/usr/lib/python3.8/site-packages/ipapython/install/util.py", line 59, in run_generator_with_yield_from
    value = gen.send(prev_value)
  <built-in method next of module object at remote 0x7fefe0b2c090>
  File "/usr/lib/python3.8/site-packages/ipapython/install/core.py", line 418, in <lambda>
    step = lambda: next(self.__gen)
  File "/usr/lib/python3.8/site-packages/ipapython/install/core.py", line 421, in __runner
    step()
  File "/usr/lib/python3.8/site-packages/ipapython/install/core.py", line 386, in execute
    for rval in self._executor():
  File "/usr/lib/python3.8/site-packages/ipapython/install/core.py", line 360, in run
    return self.execute()
  File "/usr/lib/python3.8/site-packages/ipapython/install/cli.py", line 340, in run
    return cfgr.run()
  File "/usr/lib/python3.8/site-packages/ipapython/admintool.py", line 180, in execute
    return_value = self.run()
  File "/usr/lib/python3.8/site-packages/ipapython/admintool.py", line 156, in main
    return command.execute()
  File "/usr/lib/python3.8/site-packages/ipapython/admintool.py", line 132, in run_cli
    sys.exit(cls.main(sys.argv))
  File "/usr/lib/python3.8/site-packages/ipaserver/install/ipa_server_install.py", line 51, in run
    ServerInstall.run_cli()
  File "/usr/sbin/ipa-server-install", line 25, in <module>
    ipa_server_install.run()

Head of py-bt-full in gdb:

(gdb) py-bt-full
#4 <built-in method result4 of LDAP object at remote 0x7fefd657c6c0>
#6 Frame 0x55f4c68fbb80, for file /usr/lib64/python3.8/site-packages/ldap/ldapobject.py, line 580, in _ldap_call (self=<SimpleLDAPObject(_trace_level=0, _trace_file=<_io.TextIOWrapper at remote 0x7fefe0b3aee0>, _trace_stack_limit=None, _uri='ldapi://%2Frun%2Fslapd-IPA-TEST.socket', _ldap_object_lock=<LDAPLock(_desc='opcall within <ldap.ldapobject.SimpleLDAPObject object at 0x7fefd657c760>', _lock=<_thread.lock at remote 0x7fefd657c690>) at remote 0x7fefd657c7c0>, _l=<LDAP at remote 0x7fefd657c6c0>, timeout=-1, bytes_mode=False, bytes_strictness='error') at remote 0x7fefd657c760>, func=<built-in method result4 of LDAP object at remote 0x7fefd657c6c0>, args=(562, 1, -1, 0, 0, 0), kwargs={}, diagnostic_message_success=None)

#14 Frame 0x55f4c6863fc0, for file /usr/lib64/python3.8/site-packages/ldap/ldapobject.py, line 774, in result4 (self=<SimpleLDAPObject(_trace_level=0, _trace_file=<_io.TextIOWrapper at remote 0x7fefe0b3aee0>, _trace_stack_limit=None, _uri='ldapi://%2Frun%2Fslapd-IPA-TEST.socket', _ldap_object_lock=<LDAPLock(_desc='opcall within <ldap.ldapobject.SimpleLDAPObject object at 0x7fefd657c760>', _lock=<_thread.lock at remote 0x7fefd657c690>) at remote 0x7fefd657c7c0>, _l=<LDAP at remote 0x7fefd657c6c0>, timeout=-1, bytes_mode=False, bytes_strictness='error') at remote 0x7fefd657c760>, msgid=562, all=1, timeout=-1, add_ctrls=0, add_intermediates=0, add_extop=0)
    ldap_result = self._ldap_call(self._l.result4,msgid,all,timeout,add_ctrls,add_intermediates,add_extop)
#22 Frame 0x55f4c684b500, for file /usr/lib64/python3.8/site-packages/ldap/ldapobject.py, line 1020, in result3 (self=<SimpleLDAPObject(_trace_level=0, _trace_file=<_io.TextIOWrapper at remote 0x7fefe0b3aee0>, _trace_stack_limit=None, _uri='ldapi://%2Frun%2Fslapd-IPA-TEST.socket', _ldap_object_lock=<LDAPLock(_desc='opcall within <ldap.ldapobject.SimpleLDAPObject object at 0x7fefd657c760>', _lock=<_thread.lock at remote 0x7fefd657c690>) at remote 0x7fefd657c7c0>, _l=<LDAP at remote 0x7fefd657c6c0>, timeout=-1, bytes_mode=False, bytes_strictness='error') at remote 0x7fefd657c760>, msgid=562, all=1, timeout=-1, resp_ctrl_classes=None)
    )
#30 Frame 0x7fefd6d3ac40, for file /usr/lib64/python3.8/site-packages/ldap/ldapobject.py, line 425, in add_ext_s (self=<SimpleLDAPObject(_trace_level=0, _trace_file=<_io.TextIOWrapper at remote 0x7fefe0b3aee0>, _trace_stack_limit=None, _uri='ldapi://%2Frun%2Fslapd-IPA-TEST.socket', _ldap_object_lock=<LDAPLock(_desc='opcall within <ldap.ldapobject.SimpleLDAPObject object at 0x7fefd657c760>', _lock=<_thread.lock at remote 0x7fefd657c690>) at remote 0x7fefd657c7c0>, _l=<LDAP at remote 0x7fefd657c6c0>, timeout=-1, bytes_mode=False, bytes_strictness='error') at remote 0x7fefd657c760>, dn='cn=FleetCommander Desktop Profile Administrators,cn=roles,cn=accounts,dc=ipa,dc=test', modlist=[('objectClass', [b'groupofnames', b'nestedgroup', b'top']), ('cn', [b'FleetCommander Desktop Profile Administrators']), ('description', [b'Responsible for managing desktop profiles'])], serverctrls=None, clientctrls=None, msgid=562)
    resp_type, resp_data, resp_msgid, resp_ctrls = self.result3(msgid,all=1,timeout=self.timeout)
#38 Frame 0x7fefd725d420, for file /usr/lib64/python3.8/site-packages/ldap/ldapobject.py, line 439, in add_s (self=<SimpleLDAPObject(_trace_level=0, _trace_file=<_io.TextIOWrapper at remote 0x7fefe0b3aee0>, _trace_stack_limit=None, _uri='ldapi://%2Frun%2Fslapd-IPA-TEST.socket', _ldap_object_lock=<LDAPLock(_desc='opcall within <ldap.ldapobject.SimpleLDAPObject object at 0x7fefd657c760>', _lock=<_thread.lock at remote 0x7fefd657c690>) at remote 0x7fefd657c7c0>, _l=<LDAP at remote 0x7fefd657c6c0>, timeout=-1, bytes_mode=False, bytes_strictness='error') at remote 0x7fefd657c760>, dn='cn=FleetCommander Desktop Profile Administrators,cn=roles,cn=accounts,dc=ipa,dc=test', modlist=[('objectClass', [b'groupofnames', b'nestedgroup', b'top']), ('cn', [b'FleetCommander Desktop Profile Administrators']), ('description', [b'Responsible for managing desktop profiles'])])
    return self.add_ext_s(dn,modlist,None,None)
#45 Frame 0x55f4c6581280, for file /usr/lib/python3.8/site-packages/ipapython/ipaldap.py, line 1657, in add_entry (self=<ldap2(_Plugin__api=<API(_API__plugins={<type at remote 0x55f4c5930060>, <type at remote 0x55f4c58d0090>, <type at remote 0x55f4c5748160>, <type at remote 0x55f4c58f0170>, <type at remote 0x55f4c58c0160>, <type at remote 0x55f4c58e01d0>, <type at remote 0x55f4c59181d0>, <type at remote 0x55f4c56b01f0>, <type at remote 0x55f4c5738250>, <type at remote 0x55f4c5740270>, <type at remote 0x55f4c59002f0>, <type at remote 0x55f4c5850300>, <type at remote 0x55f4c5908320>, <type at remote 0x55f4c5940320>, <type at remote 0x55f4c56f0340>, <type at remote 0x55f4c5880350>, <type at remote 0x55f4c5690360>, <type at remote 0x55f4c58a0410>, <type at remote 0x55f4c58d0440>, <type at remote 0x55f4c5920480>, <type at remote 0x55f4c5748510>, <type at remote 0x55f4c56a0520>, <type at remote 0x55f4c58f0520>, <type at remote 0x55f4c5898540>, <type at remote 0x55f4c58c0510>, <type at remote 0x55f4c5938550>, <type at r...(truncated)
    self.conn.add_s(str(entry.dn), list(attrs.items()))
#50 Frame 0x55f4c6a3ee40, for file /usr/lib/python3.8/site-packages/ipaserver/install/ldapupdate.py, line 1056, in _update_record (self=<LDAPUpdate(sub_dict={'REALM': 'IPA.TEST', 'DOMAIN': 'ipa.test', 'SUFFIX': <DN(rdns=[[('dc', 'ipa', 1)], [('dc', 'test', 1)]]) at remote 0x7fefd9ae9400>, 'ESCAPED_SUFFIX': 'dc=ipa,dc=test', 'FQDN': 'master.ipa.test', 'LIBARCH': '64', 'TIME': 1615477235, 'MIN_DOMAIN_LEVEL': '1', 'MAX_DOMAIN_LEVEL': '1', 'STRIP_ATTRS': 'modifiersName modifyTimestamp internalModifiersName internalModifyTimestamp', 'EXCLUDES': '(objectclass=*) $ EXCLUDE memberof idnssoaserial entryusn krblastsuccessfulauth krblastfailedauth krbloginfailedcount', 'TOTAL_EXCLUDES': '(objectclass=*) $ EXCLUDE entryusn krblastsuccessfulauth krblastfailedauth krbloginfailedcount', 'SELINUX_USERMAP_DEFAULT': 'unconfined_u:s0-s0:c0.c1023', 'SELINUX_USERMAP_ORDER': 'guest_u:s0$xguest_u:s0$user_u:s0$staff_u:s0-s0:c0.c1023$sysadm_u:s0-s0:c0.c1023$unconfined_u:s0-s0:c0.c1023', 'FIPS': ''}, conn=<ldap2(_Plugin__api=<API(_API__pl...(truncated)
#55 Frame 0x55f4c5786560, for file /usr/lib/python3.8/site-packages/ipaserver/install/ldapupdate.py, line 898, in _run_updates (self=<LDAPUpdate(sub_dict={'REALM': 'IPA.TEST', 'DOMAIN': 'ipa.test', 'SUFFIX': <DN(rdns=[[('dc', 'ipa', 1)], [('dc', 'test', 1)]]) at remote 0x7fefd9ae9400>, 'ESCAPED_SUFFIX': 'dc=ipa,dc=test', 'FQDN': 'master.ipa.test', 'LIBARCH': '64', 'TIME': 1615477235, 'MIN_DOMAIN_LEVEL': '1', 'MAX_DOMAIN_LEVEL': '1', 'STRIP_ATTRS': 'modifiersName modifyTimestamp internalModifiersName internalModifyTimestamp', 'EXCLUDES': '(objectclass=*) $ EXCLUDE memberof idnssoaserial entryusn krblastsuccessfulauth krblastfailedauth krbloginfailedcount', 'TOTAL_EXCLUDES': '(objectclass=*) $ EXCLUDE entryusn krblastsuccessfulauth krblastfailedauth krbloginfailedcount', 'SELINUX_USERMAP_DEFAULT': 'unconfined_u:s0-s0:c0.c1023', 'SELINUX_USERMAP_ORDER': 'guest_u:s0$xguest_u:s0$user_u:s0$staff_u:s0-s0:c0.c1023$sysadm_u:s0-s0:c0.c1023$unconfined_u:s0-s0:c0.c1023', 'FIPS': ''}, conn=<ldap2(_Plugin__api=<API(_API__plugi...(truncated)
    entry, modified = self._update_record(update)

ipaserver-install.log tail:

2021-03-11T15:40:42Z DEBUG ---------------------------------------------
2021-03-11T15:40:42Z DEBUG Initial value
2021-03-11T15:40:42Z DEBUG dn: cn=FleetCommander Desktop Profile Administrators,cn=roles,cn=accounts,dc=ipa,dc=test
2021-03-11T15:40:42Z DEBUG objectClass:
2021-03-11T15:40:42Z DEBUG      groupofnames
2021-03-11T15:40:42Z DEBUG      nestedgroup
2021-03-11T15:40:42Z DEBUG      top
2021-03-11T15:40:42Z DEBUG cn:
2021-03-11T15:40:42Z DEBUG      FleetCommander Desktop Profile Administrators
2021-03-11T15:40:42Z DEBUG description:
2021-03-11T15:40:42Z DEBUG      Responsible for managing desktop profiles
2021-03-11T15:40:42Z DEBUG ---------------------------------------------
2021-03-11T15:40:42Z DEBUG Final value after applying updates
2021-03-11T15:40:42Z DEBUG dn: cn=FleetCommander Desktop Profile Administrators,cn=roles,cn=accounts,dc=ipa,dc=test
2021-03-11T15:40:42Z DEBUG objectClass:
2021-03-11T15:40:42Z DEBUG      groupofnames
2021-03-11T15:40:42Z DEBUG      nestedgroup
2021-03-11T15:40:42Z DEBUG      top
2021-03-11T15:40:42Z DEBUG cn:
2021-03-11T15:40:42Z DEBUG      FleetCommander Desktop Profile Administrators
2021-03-11T15:40:42Z DEBUG description:
2021-03-11T15:40:42Z DEBUG      Responsible for managing desktop profiles

/var/log/dirsrv/slapd-IPA-TEST/access tail:

11/Mar/2021:15:40:42.863095699 +0000] conn=4 op=560 SRCH base="cn=FleetCommander Desktop Profile Administrators,cn=roles,cn=accounts,dc=ipa,dc=test" scope=0 filter="(objectClass=*)" attrs="attributeTypes objectClasses aci *"
[11/Mar/2021:15:40:42.868458393 +0000] conn=4 op=560 RESULT err=32 tag=101 nentries=0 wtime=0.000050271 optime=0.005370706 etime=0.005417428
[11/Mar/2021:15:40:42.868618941 +0000] conn=4 op=561 ADD dn="cn=FleetCommander Desktop Profile Administrators,cn=roles,cn=accounts,dc=ipa,dc=test"

/var/log/dirsrv/slapd-IPA-TEST/errors tail:

[11/Mar/2021:15:40:42.851776421 +0000] - DEBUG - replication - copy_operation_parameters - replica is null.
[11/Mar/2021:15:40:42.860483594 +0000] - DEBUG - replication - copy_operation_parameters - replica is null.
[11/Mar/2021:15:40:42.866997674 +0000] - ERR - cos-plugin - cos_dn_defs_cb - Skipping CoS Definition cn=Password Policy,cn=accounts,dc=ipa,dc=test--no CoS Templates found, which should be added before the CoS Definition.
[11/Mar/2021:15:40:42.871741287 +0000] - DEBUG - replication - copy_operation_parameters - replica is null.
[11/Mar/2021:15:40:52.716692603 +0000] - DEBUG - replication - copy_operation_parameters - replica is null.
wladich commented 3 years ago

@netoarmando Hi In (nightly run 960](https://github.com/freeipa-pr-ci2/freeipa/pull/960) test nfs failed with message "No free disk space". So it seems we have the original issue hitting us again.

report.log

wladich commented 3 years ago

Strangely same happened for the same test suite in another test run (959):

report.log

wladich commented 3 years ago

The problem is caused by huge log file test_integration-test_nfs.py-TestNFS-install/client1.ipa.test/var/log/sssd/sssd_kcm.log which occupies more then 17 Gb. I will investigate that

wladich commented 3 years ago

Issue: https://pagure.io/freeipa/issue/8877 temporary disabling nfs tests: https://github.com/freeipa/freeipa/pull/5818

netoarmando commented 3 years ago

@wladich I cleaned all runners to delete those long logs, 4 runners were storing 16GB+ inside jobs directory.

wladich commented 3 years ago

Thank you!

wladich commented 3 years ago

All issues related to disk space are now resolved, closing issue