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

Mon Oct 15 02:09:46 UTC 2018

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

ubuntu at 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 at dradis:~$ less /var/log/opal-prd.log 
ubuntu at dradis:~$ -l /var/log/opal-prd.log
-l: command not found
ubuntu at dradis:~$ ls -l /var/log/opal-prd.log
-rw-r----- 1 syslog adm 34057 Oct 15 02:06 /var/log/opal-prd.log
ubuntu at dradis:~$ dplg -^C
ubuntu at dradis:~$ sudo systemctl stop opal-prd
ubuntu at dradis:~$ sudo /usr/sbin/logrotate -f /etc/logrotate.conf
ubuntu at 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 at dradis:~$ sudo systemctl start opal-prd
ubuntu at dradis:~$ less opal-prd
opal-prd: No such file or directory
ubuntu at 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 at dradis:~$ sudo systemctl stop opal-prd
ubuntu at 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 at 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/392511113/opal-prd_5.10~rc4-1ubuntu1.1_ppc64el.deb [following]
--2018-10-15 02:07:38--  https://launchpadlibrarian.net/392511113/opal-prd_5.10~rc4-1ubuntu1.1_ppc64el.deb
Resolving launchpadlibrarian.net (launchpadlibrarian.net)... 91.189.89.228, 91.189.89.229
Connecting to launchpadlibrarian.net (launchpadlibrarian.net)|91.189.89.228|:443... connected.
HTTP request sent, awaiting response... 200 OK
Length: 47004 (46K) [application/x-debian-package]
Saving to: ‘opal-prd_5.10~rc4-1ubuntu1.1_ppc64el.deb’

opal-prd_5.10~rc4-1ubuntu1.1_ppc64el.d
100%[=========================================================================>]
45.90K  --.-KB/s    in 0.1s

2018-10-15 02:07:38 (359 KB/s) - ‘opal-
prd_5.10~rc4-1ubuntu1.1_ppc64el.deb’ saved [47004/47004]

ubuntu at dradis:~$ sudo rm /var/log/opal-prd.log
ubuntu at dradis:~$ dpkg -i opal-prd_5.10~rc4-1ubuntu1.1_ppc64el.deb 
dpkg: error: requested operation requires superuser privilege
ubuntu at dradis:~$ sudo dpkg -i opal-prd_5.10~rc4-1ubuntu1.1_ppc64el.deb 
(Reading database ... 64816 files and directories currently installed.)
Preparing to unpack opal-prd_5.10~rc4-1ubuntu1.1_ppc64el.deb ...
Unpacking opal-prd (5.10~rc4-1ubuntu1.1) over (5.10~rc4-1ubuntu1) ...
Setting up opal-prd (5.10~rc4-1ubuntu1.1) ...
Installing new version of config file /etc/logrotate.d/opal-prd ...
Processing triggers for ureadahead (0.100.0-20) ...
Processing triggers for systemd (237-3ubuntu10.3) ...
Processing triggers for rsyslog (8.32.0-1ubuntu4) ...
Processing triggers for man-db (2.8.3-2) ...
ubuntu at dradis:~$ sudo systemctl start opal-prd
ubuntu at dradis:~$ ls -l /var/log/opal-prd.log
-rw-r----- 1 syslog syslog 63555 Oct 15 02:08 /var/log/opal-prd.log
ubuntu at dradis:~$ sudo systemctl stop opal-prd
ubuntu at dradis:~$ sudo /usr/sbin/logrotate -f /etc/logrotate.conf
ubuntu at dradis:~$ ls -l /var/log/opal-prd.log
-rw-r--r-- 1 syslog syslog 0 Oct 15 02:08 /var/log/opal-prd.log
ubuntu at dradis:~$ sudo systemctl start opal-prd
ubuntu at dradis:~$ ls -l /var/log/opal-prd.log
-rw-r--r-- 1 syslog syslog 63555 Oct 15 02:08 /var/log/opal-prd.log

** Tags removed: verification-needed verification-needed-bionic
** Tags added: verification-done-bionic

-- 
You received this bug notification because you are a member of Ubuntu
Foundations Bugs, which is subscribed to skiboot in Ubuntu.
Matching subscriptions: foundations-bugs-skiboot
https://bugs.launchpad.net/bugs/1785026

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

Status in The Ubuntu-power-systems project:
  Fix Committed
Status in skiboot package in Ubuntu:
  Fix Released
Status in skiboot source package in Bionic:
  Fix Committed

Bug description:
  [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 at 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 at 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 at ltc-wspoon11:/var/log# cat opal-prd.log
  root at ltc-wspoon11:/var/log# echo $?
  0

  == Comment: #4 - VASANT HEGDE - 2018-06-27 09:12:48 ==
  root at 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 at 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 at 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 <FREDERIC at fr.ibm.com> - 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.

To manage notifications about this bug go to:
https://bugs.launchpad.net/ubuntu-power-systems/+bug/1785026/+subscriptions