Bug 971031 - failed to (re-)start the service pki-rad caused by ERROR: Failed to create 'pkiuser/logs' -> '/var/log/pki-ra'!
Summary: failed to (re-)start the service pki-rad caused by ERROR: Failed to create '...
Keywords:
Status: CLOSED WONTFIX
Alias: None
Product: Fedora
Classification: Fedora
Component: pki-ra
Version: 17
Hardware: x86_64
OS: Unspecified
unspecified
high
Target Milestone: ---
Assignee: Matthew Harmsen
QA Contact: Fedora Extras Quality Assurance
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2013-06-05 13:45 UTC by Chris
Modified: 2013-08-01 05:02 UTC (History)
5 users (show)

Fixed In Version:
Clone Of:
Environment:
Last Closed: 2013-08-01 05:02:34 UTC
Type: Bug
Embargoed:


Attachments (Terms of Use)
pkicontrol in debug modus while trying to start the pki-rad instance to set it up (8.26 KB, text/x-log)
2013-06-06 07:18 UTC, Chris
no flags Details

Description Chris 2013-06-05 13:45:46 UTC
Description of problem:

Hi,

I have a problem, the (re-)start of the following command shows why the RA, TPS and TKS subsystems do not start:

% pkicontrol start ra
WARNING:  Symbolic link 'pkiuser/logs' does NOT exist!
INFO:  Attempting to create 'pkiuser/logs' -> '/var/log/pki-ra' . . .
ln: failed to create symbolic link `pkiuser/logs': No such file or directory
ERROR:  Failed to create 'pkiuser/logs' -> '/var/log/pki-ra'!
WARNING:  Symbolic link 'pkiuser/run' does NOT exist!
INFO:  Attempting to create 'pkiuser/run' -> '/var/run/pki/ra' . . .
ln: failed to create symbolic link `pkiuser/run': No such file or directory
ERROR:  Failed to create 'pkiuser/run' -> '/var/run/pki/ra'!
WARNING:  Symbolic link 'pkiuser/conf' does NOT exist!
INFO:  Attempting to create 'pkiuser/conf' -> '/etc/pki-ra' . . .
ln: failed to create symbolic link `pkiuser/conf': No such file or directory
ERROR:  Failed to create 'pkiuser/conf' -> '/etc/pki-ra'!

But I cannot find the correct solutions and cannot locate the evil code or config line until now.

I tried a second install, and I also tried with dogtag10.
Using fedora 17x64 at the moment and feeling unlucky about this issue... should be reported to the bugzilla accordingly *not entered on there bugzilla while writing this*

I will add a new bugzilla entry for this issue today.

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


How reproducible:


Steps to Reproduce:
1. sudo yum groupinstall Dogtag\ Directory \Server ; 
sudo yum install pki-ra
2. sudo pkicreate -pki_instance_root=/var/lib        \
             -pki_instance_name=pki-ra          \
             -subsystem_type=ra                 \
             -secure_port=12889                 \
             -non_clientauth_secure_port=12890  \
             -unsecure_port=12888               \
             -user=pkiuser                      \
             -group=pkiuser                     \
             -redirect conf=/etc/pki-ra         \
             -redirect logs=/var/log/pki-ra     \
             -verbose



Actual results:

WARNING:  Symbolic link 'pkiuser/logs' does NOT exist!
INFO:  Attempting to create 'pkiuser/logs' -> '/var/log/pki-ra' . . .
ln: failed to create symbolic link `pkiuser/logs': No such file or directory
ERROR:  Failed to create 'pkiuser/logs' -> '/var/log/pki-ra'!
Expected results:

the pki-rad service should restart w/o any errors and a start of the service
is needed to setup the subsystem accordingly

Additional info:

pki-ra-9.0.5-1.fc17.noarch

% cat /etc/os-release 
NAME=Fedora
VERSION="17 (Beefy Miracle)"
ID=fedora
VERSION_ID=17

Using default repo + update repo for F17, no update-testing enabled.
Additionally added the pki.repo, which provides the DogTag v10.0 system as an update. But this solves currently NOT the problem with Dogtag v9.0

The first three subsystems do not have this issue => CA, DRM, OCSP
But the subsystems RA, TPS and TKS are issued also

Comment 1 Chris 2013-06-06 07:18:21 UTC
Created attachment 757514 [details]
pkicontrol in debug modus while trying to start the pki-rad instance to set it up

the systemctl status command shows that pkicontrol start ra has a problem with some links...

systemctl status pki-rad                                                                                                                   pki-rad  pki-rad.target                                                                                                                        [woot@dogtag ~]# systemctl status pki-rad                                                                                                    pki-rad - PKI Registration Authority Server pki-ra
          Loaded: loaded (/usr/lib/systemd/system/pki-rad@.service; enabled)
          Active: failed (Result: exit-code) since Thu, 06 Jun 2013 09:01:11 +0200; 14min ago
         Process: 7781 ExecStart=/usr/bin/pkicontrol start ra %i (code=exited, status=1/FAILURE)
          CGroup: name=systemd:/system/pki-rad@.service/pki-ra

Jun 06 09:01:11 dogtag pkicontrol[7781]: ln: failed to create symbolic link `pkiuser/logs': No such file or directory
Jun 06 09:01:11 dogtag pkicontrol[7781]: ERROR:  Failed to create 'pkiuser/logs' -> '/var/log/pki-ra'!
Jun 06 09:01:11 dogtag pkicontrol[7781]: WARNING:  Symbolic link 'pkiuser/run' does NOT exist!
Jun 06 09:01:11 dogtag pkicontrol[7781]: INFO:  Attempting to create 'pkiuser/run' -> '/var/run/pki/ra' . . .
Jun 06 09:01:11 dogtag pkicontrol[7781]: ln: failed to create symbolic link `pkiuser/run': No such file or directory
Jun 06 09:01:11 dogtagb pkicontrol[7781]: ERROR:  Failed to create 'pkiuser/run' -> '/var/run/pki/ra'!
Jun 06 09:01:11 dogtag pkicontrol[7781]: WARNING:  Symbolic link 'pkiuser/conf' does NOT exist!
Jun 06 09:01:11 dogtag pkicontrol[7781]: INFO:  Attempting to create 'pkiuser/conf' -> '/etc/pki-ra' . . .
Jun 06 09:01:11 dogtag pkicontrol[7781]: ln: failed to create symbolic link `pkiuser/conf': No such file or directory
Jun 06 09:01:11 dogtag pkicontrol[7781]: ERROR:  Failed to create `pkiuser/conf' -> '/etc/pki-ra'!


This attached logfile is the bash debug modus of the command:
% /usr/bin/pkicontrol start ra

Comment 2 Chris 2013-06-06 07:35:34 UTC
seems to be an error in pkicontrol 
while setting up some VARs in the script.

I have compared the start of the pki-ca with 
the pki-ra instance and something is wrong 
with the PATH variable -> it is set to pkiuser wrongly for RA


...pki-ca...
declare -p base_symlinks
+ base_symlinks_string='declare -A base_symlinks='\''([logs]="/var/log/pki-ca" [conf]="/etc/pki-ca" )'\'''
+ eval 'declare -A symlinks='\''([logs]="/var/log/pki-ca" [conf]="/etc/pki-ca" )'\'''
++ declare -A 'symlinks=([logs]="/var/log/pki-ca" [conf]="/etc/pki-ca" )'
+ check_symlinks /var/lib/pki-ca pkiuser pkiuser
+ path=/var/lib/pki-ca
+ user=pkiuser
+ group=pkiuser
+ rv=0
+ for key in '"${!symlinks[@]}"'
+ symlink=/var/lib/pki-ca/logs


....pki-ra...
+ '[' ra == ra ']'
++ declare -p apache_symlinks
+ apache_symlinks_string='declare -A apache_symlinks='\''([logs]="/var/log/pki-ra" [run]="/var/run/pki/ra" [conf]="/etc/pki-ra" )'\'''
+ eval 'declare -A symlinks='\''([logs]="/var/log/pki-ra" [run]="/var/run/pki/ra" [conf]="/etc/pki-ra" )'\'''
++ declare -A 'symlinks=([logs]="/var/log/pki-ra" [run]="/var/run/pki/ra" [conf]="/etc/pki-ra" )'
+ check_symlinks pkiuser pkiuser
+ path=pkiuser
+ user=pkiuser
+ group=
+ rv=0
+ for key in '"${!symlinks[@]}"'
+ symlink=pkiuser/logs
+ target=/var/log/pki-ra
+ '[' -e pkiuser/logs ']'
+ echo 'WARNING:  Symbolic link '\''pkiuser/logs'\'' does NOT exist!'
WARNING:  Symbolic link 'pkiuser/logs' does NOT exist!
+ make_symlink pkiuser/logs /var/log/pki-ra pkiuser
+ symlink=pkiuser/logs
+ target=/var/log/pki-ra
+ user=pkiuser
+ group=
+ rv=0
+ echo 'INFO:  Attempting to create '\''pkiuser/logs'\'' -> '\''/var/log/pki-ra'\'' . . .'
INFO:  Attempting to create 'pkiuser/logs' -> '/var/log/pki-ra' . . .
+ '[' -e /var/log/pki-ra ']'
++ readlink -qe /var/log/pki-ra
+ '[' '!' /var/log/pki-ra ']'
+ ln -s /var/log/pki-ra pkiuser/logs
ln: failed to create symbolic link `pkiuser/logs': No such file or directory
+ rv=1
+ '[' 1 -eq 0 ']'
+ echo 'ERROR:  Failed to create '\''pkiuser/logs'\'' -> '\''/var/log/pki-ra'\''!'

Comment 3 Chris 2013-06-06 07:48:28 UTC
following the code in /usr/bin/pkicontrol which sources the /usr/share/pki/scripts/functions, there is the PKI_INSTANCE_PATH variable w/o a value.

Setting manually this value before calling 
the pkicontrol brings up another error :*


PKI_INSTANCE_PATH=/var/lib/pki-ra /usr/bin/pkicontrol start ra


PKI_INSTANCE_PATH = /var/lib/pki-ra
Starting pki-ra: runcon: /usr/sbin/httpd.worker: Permission denied
[FAILED]

So what shall I do now ? hand off and waiting for some replies/patches or bugfixes?

Comment 4 Chris 2013-06-06 09:50:56 UTC
* added new file: /etc/sysconfig/pki-ra 
 content:
PKI_INSTANCE_PATH=/var/lib/pki-ra

* changed file: usr/lib/systemd/system/pki-rad@.service

diff -u /usr/lib/systemd/system/pki-rad@.service.orig /usr/lib/systemd/system/pki-rad@.service 
--- /usr/lib/systemd/system/pki-rad@.service.orig       2013-06-06 11:46:29.962255689 +0200
+++ /usr/lib/systemd/system/pki-rad@.service    2013-06-06 11:30:05.071451599 +0200
@@ -4,6 +4,8 @@
 BindTo=pki-rad.target
 
 [Service]
+# EnvironmentFile=-/etc/sysconfig/pki-ra
+Environment=PKI_INSTANCE_PATH=/var/lib/pki-ra 
 Type=forking
 ExecStart=/usr/bin/pkicontrol start ra %i
 ExecStop=/usr/bin/pkicontrol stop ra %i


# delete orig file and reload system unit(s)
% rm /usr/lib/systemd/system/pki-rad@.service.orig
% systemctl --system daemon-reload



If I now try to (re-)start this service, I got now an error itself from the invoked httpd.worker, in detail, here the error message:

/usr/bin/systemctl restart pki-rad 
Job failed. See system journal and 'systemctl status' for details.
# /usr/bin/systemctl status pki-rad 
pki-rad - PKI Registration Authority Server pki-ra
          Loaded: loaded (/usr/lib/systemd/system/pki-rad@.service; enabled)
          Active: failed (Result: exit-code) since Thu, 06 Jun 2013 11:49:20 +0200; 2s ago
         Process: 9699 ExecStart=/usr/bin/pkicontrol start ra %i (code=exited, status=1/FAILURE)
          CGroup: name=systemd:/system/pki-rad@.service/pki-ra

Jun 06 11:49:20 dogtag pkicontrol[9699]: Starting pki-ra: httpd.worker: Could not reliably determine the server's fully qualified domain name, using 10.0.0.16 for ServerName
Jun 06 11:49:20 dogtag pkicontrol[9699]: (13)Permission denied: make_sock: could not bind to address [::]:12890
Jun 06 11:49:20 dogtag pkicontrol[9699]: (13)Permission denied: make_sock: could not bind to address 0.0.0.0:12890
Jun 06 11:49:20 dogtag pkicontrol[9699]: no listening sockets available, shutting down
Jun 06 11:49:20 dogtag pkicontrol[9699]: Unable to open logs
Jun 06 11:49:20 dogtag pkicontrol[9699]: [FAILED]

so the show is going on...

Comment 5 Chris 2013-06-06 10:47:07 UTC
... I am back again :D

running semanage to add the missing port to the already allowed ports for the RA instance did the trick !!!


semanage port -l |grep pki
pki_ca_port_t                  tcp      9180, 9701, 9443-9447
pki_kra_port_t                 tcp      10180, 10701, 10443-10446
pki_ocsp_port_t                tcp      11180, 11701, 11443-11446
pki_ra_port_t                  tcp      12888-12889
pki_tks_port_t                 tcp      13180, 13701, 13443-13446
pki_tps_port_t                 tcp      7888-7889


semanage port -a -t pki_ra_port_t -p tcp 12890

So, NOW I am able to go on with the initial setup for pki-ra..

I think the other two instance regarding this issue can be solved in the same way

cheers,
chris

Comment 6 Fedora End Of Life 2013-07-04 00:59:01 UTC
This message is a reminder that Fedora 17 is nearing its end of life.
Approximately 4 (four) weeks from now Fedora will stop maintaining
and issuing updates for Fedora 17. It is Fedora's policy to close all
bug reports from releases that are no longer maintained. At that time
this bug will be closed as WONTFIX if it remains open with a Fedora 
'version' of '17'.

Package Maintainer: If you wish for this bug to remain open because you
plan to fix it in a currently maintained version, simply change the 'version' 
to a later Fedora version prior to Fedora 17's end of life.

Bug Reporter:  Thank you for reporting this issue and we are sorry that 
we may not be able to fix it before Fedora 17 is end of life. If you 
would still like  to see this bug fixed and are able to reproduce it 
against a later version  of Fedora, you are encouraged  change the 
'version' to a later Fedora version prior to Fedora 17's end of life.

Although we aim to fix as many bugs as possible during every release's 
lifetime, sometimes those efforts are overtaken by events. Often a 
more recent Fedora release includes newer upstream software that fixes 
bugs or makes them obsolete.

Comment 7 Fedora End Of Life 2013-08-01 05:02:42 UTC
Fedora 17 changed to end-of-life (EOL) status on 2013-07-30. Fedora 17 is 
no longer maintained, which means that it will not receive any further 
security or bug fix updates. As a result we are closing this bug.

If you can reproduce this bug against a currently maintained version of 
Fedora please feel free to reopen this bug against that version.

Thank you for reporting this bug and we are sorry it could not be fixed.


Note You need to log in before you can comment on or make changes to this bug.