#3382 ipa install error Unable to find preop.pin
Closed: Fixed None Opened 11 years ago by mkosek.

https://bugzilla.redhat.com/show_bug.cgi?id=905064 (Red Hat Enterprise Linux 6)

Description of problem:

On some i386 servers I'm seeing the following during ipa-server-install and
sometimes during ipa-replica-install:

2013-01-25T02:58:44Z DEBUG   [3/21]: configuring certificate server instance
2013-01-25T02:58:44Z INFO   File
"/usr/lib/python2.6/site-packages/ipaserver/install/installutils.py", line 614,
in run_script
    return_value = main_function()

  File "/usr/sbin/ipa-server-install", line 942, in main
    subject_base=options.subject)

  File "/usr/lib/python2.6/site-packages/ipaserver/install/cainstance.py", line
617, in configure_instance
    self.start_creation(runtime=210)

  File "/usr/lib/python2.6/site-packages/ipaserver/install/service.py", line
358, in start_creation
    method()

  File "/usr/lib/python2.6/site-packages/ipaserver/install/cainstance.py", line
790, in __configure_instance
    self.server_root, self.dogtag_constants.PKI_INSTANCE_NAME)

  File "/usr/lib/python2.6/site-packages/ipaserver/install/cainstance.py", line
124, in get_preop_pin
    raise RuntimeError("Unable to find preop.pin in %s. Is your CA already
configured?" % filename)

2013-01-25T02:58:44Z INFO The ipa-server-install command failed, exception:
RuntimeError: Unable to find preop.pin in /var/lib/pki-ca/conf/CS.cfg. Is your
CA already configured?


And when I log into the failed master this was from, I can see this:

[root@cloud-qe-3 log]# grep preop.pin /var/lib/pki-ca/conf/CS.cfg|sed
's/preop.pin=[a-Z0-9]*$/preop.pin=XXXXXXXXXXXXXX/'
preop.pin=XXXXXXXXXXXXXX

After some debugging, Ade Lee from Dev found this:

----- Original Message -----
>
> The failure occurs in cainstance.py (the ipa install scripts) after
> pkicreate has run, and before pkisilent is run.
>
> pkicreate completes successfully and the pin is stored in the CS.cfg.
> I extracted and the ipa code that is run to get the pin, and it
> returns
> the correct value.
>
> The code looks like this:
>
> def get_preop_pin(instance_root, instance_name):
>     # Only used for Dogtag 9
>     preop_pin = None
>
>     filename = instance_root + "/" + instance_name + "/conf/CS.cfg"
>
>     # read the config file and get the preop pin
>     try:
>         f=open(filename)
>     except IOError, e:
>         root_logger.error("Cannot open configuration file." + str(e))
>         raise e
>     data = f.read()
>     data = data.split('\n')
>     pattern = re.compile("preop.pin=(.*)" )
>     for line in data:
>         match = re.search(pattern, line)
>         if (match):
>             preop_pin=match.group(1)
>             break
>
>     if preop_pin is None:
>         raise RuntimeError("Unable to find preop.pin in %s. Is your
>         CA already configured?" % filename)
>
> which means, I think, that if the IPA script were unable to read the
> config file, it would have raised a different exception.
>
> The only thing that could be happening here is some kind of race
> condition where the ipa install scripts are reading the CS.cfg prior
> to
> it being written to disk.  If I do a stat
> on /var/lib/pki-ca/conf/CS.cfg, I see:
>
> Access: 2013-01-25 11:31:41.031896697 -0500
> Modify: 2013-01-24 21:58:44.557951715 -0500
> Change: 2013-01-24 21:58:44.561951715 -0500
>
> and in the ipa-install log, we have the error occurring at
> 2013-01-25T02:58:44Z.  Ignoring the difference in the hours (local
> vs.
> UTC?), its possible this race condition might have happened.
>
> In fact, it looks like we go directly from running pkicreate, to
> getting
> the pin, to running pkisilent.  There is the potential of a race
> condition in this sequence.  It is probably better to:
>
> 1. run pkicreate
> 2. check that CA is up
> 3. get pin
> 4. run pkisilent
>
> Ade

Version-Release number of selected component (if applicable):

At least on 3.0.0-22.el6

How reproducible:

I have been seeing it on automated tests noticeably but, have not been able to
reproduce it manually yet.

Steps to Reproduce:
1.  ipa-server-install to setup a master on RHEL6 i386 build.

Actual results:
preop.pin failure

Expected results:
no failure

Additional info:

This milestone is retired, moving the ticket to Triage to rescope it.

This particular code branch is called upon only with Dogtag 9 (as can be even seen in the comment of the referenced function in the description of the bug).

With Dogtag 10, we do not read CS.cfg in similiar manner and therefore such race condition would not happen. Since we no longer support Dogtag 9 installs, this should not be an issue.

As a data point, IRC user basic` basic@osuosl/staff/basic “Rudy Grigar” reported the problem on a x86_64 VM (unspecified what version of IPA and what distro).

Revive the ticket since bug 905064 is still alive and reproduced on RHEL 6.5

When fixing this ticket, do it simple:

  • Try to read preop.pin in a loop, catch for IOError, wait for some time and try to read it again
  • timeout at api.env.startup_timeout
  • Make sure that this situation is properly logged in debug

ipa-3-0:

  • 1ec270e cainstance: Read CS.cfg for preop.pin in a loop

Metadata Update from @mkosek:
- Issue assigned to tbabej
- Issue set to the milestone: FreeIPA 3.0.3 (bug fixing)

7 years ago

Login to comment on this ticket.

Metadata