[LTCTest][OPAL][OP920] OPAL PRD generated logs is not available in /var/log/opal-prd.log file

[bugproxy]

[Impact]
Without this fix we end up creating /var/log/opal-prd.log file with root user. Hence rsyslogd will not be able to write data to this file. Hence we will not have enough opal-prd logs for debugging.

[Test Case]
- install fixed version of opal-prd package
- stop opal-prd daemon : sudo systemctl stop opal-prd
- force log rotation : sudo /usr/sbin/logrotate -f /etc/logrotate.conf
- check whether opal-prd logs /var/log/opal-prd.log file has 644 mode and non root owner.
- start opal-prd daemon : sudo systemctl start opal-prd : at that point opal-prd should just re-use the log with the proper mode.

[Regression Potential]
This is just changing owner for /var/log/opal-prd.log file.
Without this fix, file won't be created and prd logs gets dropped.
I do not see any possible regression with this fix.

----------------

Original description follows:

== Comment: #0 - PAVAMAN SUBRAMANIYAM - 2018-06-27 05:00:15 ==

Install a P9 Open Power Hardware with the latest OP920 Firmware images provided in the following link:
http://pfd.austin.ibm.com/releasenotes/openpower9/OP920/OP920_1824A/OP920_1824A_RelNote_Main.html

root@witherspoon:~# cat /etc/os-release
ID="openbmc-phosphor"
NAME="Phosphor OpenBMC (Phosphor OpenBMC Project Reference Distro)"
VERSION="ibm-v2.1"
VERSION_ID="ibm-v2.1-438-g0030304-r15-0-g19832d3"
PRETTY_NAME="Phosphor OpenBMC (Phosphor OpenBMC Project Reference Distro) ibm-v2.1"
BUILD_ID="ibm-v2.1-438-g0030304-r15"
root@witherspoon:~# cat /var/lib/phosphor-software-manager/pnor/ro/VERSION
IBM-witherspoon-ibm-OP9-v2.0.3-2.17
        op-build-v2.0.3-2-g6279a04-dirty
        buildroot-2018.02.1-6-ga8d1126
        skiboot-v6.0.4
        hostboot-9df0950-p378630b
        occ-90208bb
        linux-4.16.13-openpower1-pc10362e
        petitboot-v1.7.1-pcc0e2c7
        machine-xml-7cd20a6
        hostboot-binaries-8097b96
        capp-ucode-p9-dd2-v4
        sbe-0b006e7
        hcode-fbe2c7c

Then check if the OPAL prd generated logs are captured in /var/log/opal-prd.log file.

root@ltc-wspoon11:/var/log# cat opal-prd.log
root@ltc-wspoon11:/var/log# echo $?
0

== Comment: #4 - VASANT HEGDE - 2018-06-27 09:12:48 ==
root@ltc-wspoon11:~# grep prd /var/log/syslog
Jun 27 08:00:44 ltc-wspoon11 rsyslogd: file '/var/log/opal-prd.log': open error: Permission denied [v8.32.0 try http://www.rsyslog.com/e/2433 ]

root@ltc-wspoon11:~# ls -l /var/log
total 83332
-rw-r--r-- 1 root root 11833 Jun 15 03:15 alternatives.log
....
-rw-r--r-- 1 root root 0 May 1 06:25 opal-prd.log
-rw-r----- 1 syslog adm 5084615 May 1 02:12 opal-prd.log.1

Notice that opal-prd.log file is owned by root user while opal-prd.log.1 is owned by syslog.
That means someone has manually created that log file?

I deleted opal-prd.log file and restart opal-prd daemon.

rm /var/log/opal-prd.log

systemctl restart opal-prd

head /var/log/opal-prd.log
Jun 27 08:02:41 ltc-wspoon11 opal-prd: CTRL: Starting PRD daemon
Jun 27 08:02:41 ltc-wspoon11 opal-prd: I2C: Found Chip: 00000000 engine 3 port 0
Jun 27 08:02:41 ltc-wspoon11 opal-prd: I2C: Found Chip: 00000000 engine 1 port 2
Jun 27 08:02:41 ltc-wspoon11 opal-prd: I2C: Found Chip: 00000008 engine 3 port 1
Jun 27 08:02:41 ltc-wspoon11 opal-prd: I2C: Found Chip: 00000008 engine 1 port 2
Jun 27 08:02:41 ltc-wspoon11 opal-prd: I2C: Found Chip: 00000000 engine 3 port 1
Jun 27 08:02:41 ltc-wspoon11 opal-prd: I2C: Found Chip: 00000000 engine 2 port 0
Jun 27 08:02:41 ltc-wspoon11 opal-prd: I2C: Found Chip: 00000000 engine 1 port 0
Jun 27 08:02:41 ltc-wspoon11 opal-prd: I2C: Found Chip: 00000008 engine 3 port 0
Jun 27 08:02:41 ltc-wspoon11 opal-prd: I2C: Found Chip: 00000008 engine 1 port 0

root@ltc-wspoon11:~# ls -l /var/log
...
-rw-r----- 1 syslog syslog 80804 Jun 27 08:02 opal-prd.log
...

So looks like its user error.

-Vasant

== Comment: #6 - VASANT HEGDE - 2018-07-30 23:16:39 ==
Looks like logrorate stuff is creating new file with root user. Below change should fix this.

:/etc/logrotate.d# diff -Naurp opal-prd.org opal-prd
--- opal-prd.org 2018-07-30 13:04:08.814168026 -0400
+++ opal-prd 2018-07-31 00:09:04.145154122 -0400
@@ -5,5 +5,5 @@
  delaycompress
  missingok
  notifempty
- create 644 root root
+ create 644 syslog adm
 }

-Vasant

== Comment: #7 - VASANT HEGDE - 2018-07-30 23:17:38 ==
Fred,

Can you look into the proposed change?

-Vasant

== Comment: #8 - Frederic Bonnard <email address hidden> - 2018-07-31 01:18:28 ==
Hi all,
thanks Vasant for the investigation. The fix looks good,
I'm just going to check that on Debian as well.
I'll let you know asap,

F.

[Frédéric Bonnard (frediz)]

Fixed in skiboot-6.1-2 (Debian/Unstable).
You may use the same fix for 18.04 there :
https://salsa.debian.org/debian/skiboot/commit/0e6ac150e51a0e7b3701acf78c311709b6336d58

F.

[Michael Hudson-Doyle (mwhudson)]

Would it be possible for one of the subscribers to this bug to update it with the impact/test case/regression potential per https://wiki.ubuntu.com/StableReleaseUpdates#SRU_Bug_Template ?

[bugproxy (bugproxy)]

------- Comment From <email address hidden> 2018-09-27 02:17 EDT-------
(In reply to comment #19)
> Would it be possible for one of the subscribers to this bug to update it
> with the impact/test case/regression potential per
> https://wiki.ubuntu.com/StableReleaseUpdates#SRU_Bug_Template ?

[Impact]
Without this fix we end up creating /var/log/opal-prd.log file with root user. Hence rsyslogd will not be able to write data to this file. Hence we will not have enough opal-prd logs for debugging.

[Test Case]
- Installed fixed version of opal-prd package
- restart opal-prd daemon (systemctl restart opal-prd)
- check whether opal-prd logs are stored in /var/log/opal-prd.log file.

[Regression Potential]
Nothing.

-Vasant

[Robie Basak (racb)]

The skiboot SRU needs a proper Regression Potential section please.

[bugproxy (bugproxy)]

------- Comment From <email address hidden> 2018-10-05 02:06 EDT-------
(In reply to comment #21)
> The skiboot SRU needs a proper Regression Potential section please.

[Regression Potential]
This is just changing owner for /var/log/opal-prd.log file.
Without this fix, file won't be created and prd logs gets dropped.
I do not see any possible regression with this fix.

-Vasant

[Andrew Cloke (andrew-cloke)]

Updated "[Regression Potential]" section in bug description with text from comment #5.

[Brian Murray (brian-murray)]

Hello bugproxy, or anyone else affected,

Accepted skiboot into bionic-proposed. The package will build now and be available at https://launchpad.net/ubuntu/+source/skiboot/5.10~rc4-1ubuntu1.1 in a few hours, and then in the -proposed repository.

Please help us by testing this new package. See https://wiki.ubuntu.com/Testing/EnableProposed for documentation on how to enable and use -proposed. Your feedback will aid us getting this update out to other Ubuntu users.

If this package fixes the bug for you, please add a comment to this bug, mentioning the version of the package you tested and change the tag from verification-needed-bionic to verification-done-bionic. If it does not fix the bug for you, please add a comment stating that, and change the tag to verification-failed-bionic. In either case, without details of your testing we will not be able to proceed.

Further information regarding the verification process can be found at https://wiki.ubuntu.com/QATeam/PerformingSRUVerification . Thank you in advance for helping!

N.B. The updated package will be released to -updates after the bug(s) fixed by this package have been verified and the package has been in -proposed for a minimum of 7 days.

[Frédéric Bonnard (frediz)]

Hi,
the log file mode is dealt with by logrotate. So restarting opal-prd won't make logrotate start and change anything (logrotate is called from crontab). The test case would rather be :

[Test Case]
- install fixed version of opal-prd package
- stop opal-prd daemon : sudo systemctl stop opal-prd
- force log rotation : sudo /usr/sbin/logrotate -f /etc/logrotate.conf
- check whether opal-prd logs /var/log/opal-prd.log file has 644 mode and non root owner.
- start opal-prd daemon : sudo systemctl start opal-prd : at that point opal-prd should just re-use the log with the proper mode.

That worked well for me with opal-prd 5.10~rc4-1ubuntu1.1 from bionic-proposed.

F.

[Michael Hudson-Doyle (mwhudson)]

Ah, thanks for the improved test case. I've been through the steps (boring transcript below) and also verified the fix.

ubuntu@dradis:~$ systemctl status opal-prd
● opal-prd.service - OPAL PRD daemon
   Loaded: loaded (/lib/systemd/system/opal-prd.service; enabled; vendor preset: enabled)
   Active: active (running) since Mon 2018-10-15 02:06:02 UTC; 17s ago
     Docs: man:opal-prd(8)
 Main PID: 4545 (opal-prd)
    Tasks: 1 (limit: 24575)
   CGroup: /system.slice/opal-prd.service
           └─4545 /usr/sbin/opal-prd

Oct 15 02:06:03 dradis opal-prd[4545]: HBRT: PRDF:<<PRDF::initialize()
Oct 15 02:06:03 dradis opal-prd[4545]: HBRT: ATTN_SLOW:I>Service::enableAttns() enter
Oct 15 02:06:03 dradis opal-prd[4545]: HBRT: TARG:[TARG] I> getNextTarget: Using next node 1
Oct 15 02:06:03 dradis opal-prd[4545]: HBRT: TARG:[TARG] E> getNextTarget: Node 0 targets: first 0x7ba601bbfc1c, current 0x7ba601bc4b00, last 0x7ba601bc4
Oct 15 02:06:03 dradis opal-prd[4545]: HBRT: TARG:[TARG] E> getNextTarget: Target not found
Oct 15 02:06:03 dradis opal-prd[4545]: HBRT: ATTN_SLOW:I>Service::enableAttns() exit
Oct 15 02:06:03 dradis opal-prd[4545]: HBRT: ATTN_SLOW:I><<ATTN_RT::enableAttns rc: 0
Oct 15 02:06:03 dradis opal-prd[4545]: HBRT: calling get_ipoll_events
Oct 15 02:06:03 dradis opal-prd[4545]: HBRT: enabling IPOLL events 0x5b90000000000000
Oct 15 02:06:03 dradis opal-prd[4545]: FW: writing init message
ubuntu@dradis:~$ less /var/log/opal-prd.log
ubuntu@dradis:~$ -l /var/log/opal-prd.log
-l: command not found
ubuntu@dradis:~$ ls -l /var/log/opal-prd.log
-rw-r----- 1 syslog adm 34057 Oct 15 02:06 /var/log/opal-prd.log
ubuntu@dradis:~$ dplg -^C
ubuntu@dradis:~$ sudo systemctl stop opal-prd
ubuntu@dradis:~$ sudo /usr/sbin/logrotate -f /etc/logrotate.conf
ubuntu@dradis:~$ ls -l /var/log/opal-prd.log
-rw-r--r-- 1 root root 0 Oct 15 02:06 /var/log/opal-prd.log
ubuntu@dradis:~$ sudo systemctl start opal-prd
ubuntu@dradis:~$ less opal-prd
opal-prd: No such file or directory
ubuntu@dradis:~$ ls -l /var/log/opal-prd.log
-rw-r--r-- 1 root root 0 Oct 15 02:06 /var/log/opal-prd.log
ubuntu@dradis:~$ sudo systemctl stop opal-prd
ubuntu@dradis:~$ dpkg -l opal-prd
Desired=Unknown/Install/Remove/Purge/Hold
| Status=Not/Inst/Conf-files/Unpacked/halF-conf/Half-inst/trig-aWait/Trig-pend
|/ Err?=(none)/Reinst-required (Status,Err: uppercase=bad)
||/ Name Version Architecture Description
+++-================================-=====================-=====================-=====================================================================
ii opal-prd 5.10~rc4-1ubuntu1 ppc64el OPAL Processor Recovery Diagnostics daemon
ubuntu@dradis:~$ wget https://launchpad.net/ubuntu/+archive/primary/+files/opal-prd_5.10~rc4-1ubuntu1.1_ppc64el.deb
--2018-10-15 02:07:37-- https://launchpad.net/ubuntu/+archive/primary/+files/opal-prd_5.10~rc4-1ubuntu1.1_ppc64el.deb
Resolving launchpad.net (launchpad.net)... 91.189.89.222, 91.189.89.223
Connecting to launchpad.net (launchpad.net)|91.189.89.222|:443... connected.
HTTP request sent, awaiting response... 303 See Other
Location: https://launchpadlibrarian.net/39...

[Launchpad Janitor (janitor)]

This bug was fixed in the package skiboot - 5.10~rc4-1ubuntu1.1

---------------
skiboot (5.10~rc4-1ubuntu1.1) bionic; urgency=medium

  * d/opal-prd.logrotate: fix ownership of /var/log/opal-prd.log.
    (LP: #1785026)

 -- Michael Hudson-Doyle <email address hidden> Wed, 03 Oct 2018 12:27:12 +1300

[Robie Basak (racb)]

The verification of the Stable Release Update for skiboot has completed successfully and the package has now been released to -updates. Subsequently, the Ubuntu Stable Release Updates Team is being unsubscribed and will not receive messages about this bug report. In the event that you encounter a regression using the package from -updates please report a new bug using ubuntu-bug and tag the bug report regression-update so we can easily find any regressions.

[bugproxy (bugproxy)]

------- Comment From <email address hidden> 2019-03-13 05:48 EDT-------
I have installed Ubuntu 18.04.2 OS on a P9 8335-GTH Hardware.

root@ltc-wspoon11:~# uname -a
Linux ltc-wspoon11 4.15.0-46-generic #49-Ubuntu SMP Wed Feb 6 09:32:48 UTC 2019 ppc64le ppc64le ppc64le GNU/Linux
root@ltc-wspoon11:~# cat /etc/os-release
NAME="Ubuntu"
VERSION="18.04.2 LTS (Bionic Beaver)"
ID=ubuntu
ID_LIKE=debian
PRETTY_NAME="Ubuntu 18.04.2 LTS"
VERSION_ID="18.04"
HOME_URL="https://www.ubuntu.com/"
SUPPORT_URL="https://help.ubuntu.com/"
BUG_REPORT_URL="https://bugs.launchpad.net/ubuntu/"
PRIVACY_POLICY_URL="https://www.ubuntu.com/legal/terms-and-policies/privacy-policy"
VERSION_CODENAME=bionic
UBUNTU_CODENAME=bionic
root@ltc-wspoon11:~# cat /proc/cpuinfo | tail
cpu : POWER9, altivec supported
clock : 2300.000000MHz
revision : 2.3 (pvr 004e 1203)

timebase : 512000000
platform : PowerNV
model : 8335-GTH
machine : PowerNV 8335-GTH
firmware : OPAL
MMU : Radix

root@ltc-wspoon11:~# service opal-prd status
? opal-prd.service - OPAL PRD daemon
Loaded: loaded (/lib/systemd/system/opal-prd.service; enabled; vendor preset: enabled)
Active: active (running) since Wed 2019-03-13 04:05:10 CDT; 37min ago
Docs: man:opal-prd(8)
Main PID: 5284 (opal-prd)
Tasks: 1 (limit: 22118)
CGroup: /system.slice/opal-prd.service
??5284 /usr/sbin/opal-prd

Mar 13 04:05:12 ltc-wspoon11 opal-prd[5284]: HBRT: PRDF:<<PRDF::initialize()
Mar 13 04:05:12 ltc-wspoon11 opal-prd[5284]: HBRT: ATTN_SLOW:I>Service::enableAttns() enter
Mar 13 04:05:12 ltc-wspoon11 opal-prd[5284]: HBRT: ATTN_SLOW:I>Service::enableAttns() exit
Mar 13 04:05:12 ltc-wspoon11 opal-prd[5284]: HBRT: ATTN_SLOW:I><<ATTN_RT::enableAttns rc: 0
Mar 13 04:05:12 ltc-wspoon11 opal-prd[5284]: HBRT: HBRT:<< enable_attns: rc=0x0
Mar 13 04:05:12 ltc-wspoon11 opal-prd[5284]: HBRT: calling get_ipoll_events
Mar 13 04:05:12 ltc-wspoon11 opal-prd[5284]: HBRT: HBRT:>> get_ipoll_events
Mar 13 04:05:12 ltc-wspoon11 opal-prd[5284]: HBRT: HBRT:<< get_ipoll_events: rc=0x0
Mar 13 04:05:12 ltc-wspoon11 opal-prd[5284]: HBRT: enabling IPOLL events 0x5b90000000000000
Mar 13 04:05:12 ltc-wspoon11 opal-prd[5284]: FW: writing init message
root@ltc-wspoon11:~# ps -ef | grep opal
root 880 2 0 04:04 ? 00:00:01 [kopald]
root 5284 1 0 04:05 ? 00:00:00 /usr/sbin/opal-prd
root 6583 6005 0 04:42 pts/0 00:00:00 grep --color=auto opal

root@ltc-wspoon11:~# ls -l /var/log/opal-prd.log
-rw-r----- 1 syslog adm 105414 Mar 13 04:05 /var/log/opal-prd.log

root@ltc-wspoon11:~# cat /etc/rsyslog.d/10-opal-prd.conf
if $programname == 'opal-prd' then /var/log/opal-prd.log
if $programname == 'opal-prd' and $syslogseverity <= 4 then /var/log/syslog
if $programname == 'opal-prd' then ~

As can be seen the file is getting created

[Brahadambal Srinivasan (latha)]

Did this fix make it to 18.04.2 ? We are seeing the issue in 18.04.2.

[Frank Heimes (fheimes)]

According to the changelog:
https://launchpad.net/ubuntu/bionic/+source/skiboot/+changelog
this got fixed with skiboot package version 5.10~rc4-1ubuntu1.1
and there is an even newer version ( 5.10~rc4-1ubuntu1.2) in bionic-updates:
 skiboot | 5.10~rc4-1ubuntu1 | bionic | source
 skiboot | 5.10~rc4-1ubuntu1.2 | bionic-updates | source
Hence it should be in.
Which version do you have and see in your system?
Please run:
sudo apt update
followed by:
apt-cache policy skiboot
and paste the output.
Make sure the system is on the latest level in case it's not yet.