How best to diagnose false positive app upgrade in logs?

[btaroli]

I'm a longtime user of DVBLink and with sone of the changes in 6.7.x seems to have come a new behavior when attempting to upgrade the DVBLink Server app. In 6.7.1 it would simply fail without logging anything to the /vr/log/readynas/  path. In the latest 6.7.4, it proclaims success but doesn't actually install anything. Oops. 

Ive reported these basic symptoms to the vendor, of course. But I'd prefer to be able to offer them some additional diagnostics. It seems that in 6.7.x these actions are being captured in new locations. Just looking for some info to point me where to look. 

[btaroli · Accepted solution]

Parsing the full journalctl output, I find the following unit names. None of them include dpkg.

afpd
apache2
apache_access
apt-update.sh
avahi-daemon
backported
bt-mgmt
bt-pagent
clamd
cnid_metad
connmand
cron
CRON
crontab
dbus
disk_event_handler
dropboxmanager
exportfs
freshclam
fv-app-install
fvbackup-q
if
kernel:
logtruncate
manage.py
mdadm
minissdpd
msmtpq
netatalk
nmbd
raidard
readynasd
readynas-upgrade
rn-expand
rn-update.sh
rpcbind
rpc.mountd
rpc.statd
rsyncd
sh
smbd
sm-notify
snapperd
sshd
start2.sh
start_raids
su
sudo
Sun
sysctl
systemd
systemd-journald
systemd-logind
systemd-shutdown
systemd-udevd
tftpr6
transmission
umount
update_support_fw_db
upnphttpd
upsd
upsdrvctl
upsmon
usage
usbhid-ups
wsdd2

The best I can ascertain, perhaps apt-update.sh or fv-app-install .... ? OK, it looks like fv-app-install is the key...

# journalctl --identifier=fv-app-install
-- Logs begin at Sun 2017-05-07 20:30:01 PDT, end at Thu 2017-06-08 09:33:29 PDT. --

…

Jun 06 22:26:00 nas fv-app-install[19342]: [/tmp/plexmediaserver-ros6-binaries_1.7.2.3878-8088811b8_amd64.deb](0%) prepare
Jun 06 22:26:01 nas fv-app-install[19342]: Downloading [/tmp/plexmediaserver-ros6-binaries_1.7.2.3878-8088811b8_amd64.deb](0%) Retrieving file 1 of 1
Jun 06 22:26:01 nas fv-app-install[19342]: Downloading [/tmp/plexmediaserver-ros6-binaries_1.7.2.3878-8088811b8_amd64.deb](0%) Retrieving file 1 of 1
Jun 06 22:26:02 nas fv-app-install[19342]: Downloading [/tmp/plexmediaserver-ros6-binaries_1.7.2.3878-8088811b8_amd64.deb](0%) Retrieving file 1 of 1
Jun 06 22:26:02 nas fv-app-install[19342]: Downloading [/tmp/plexmediaserver-ros6-binaries_1.7.2.3878-8088811b8_amd64.deb](0%) Retrieving file 1 of 1
Jun 06 22:26:03 nas fv-app-install[19342]: Downloading [/tmp/plexmediaserver-ros6-binaries_1.7.2.3878-8088811b8_amd64.deb](0%) Retrieving file 1 of 1
Jun 06 22:26:03 nas fv-app-install[19342]: Downloading [/tmp/plexmediaserver-ros6-binaries_1.7.2.3878-8088811b8_amd64.deb](50%) Retrieving file 1 of 1
Jun 06 22:26:03 nas fv-app-install[19342]: Installing [/tmp/plexmediaserver-ros6-binaries_1.7.2.3878-8088811b8_amd64.deb](50%) Running dpkg
Jun 06 22:26:03 nas fv-app-install[19342]: Installing [/tmp/plexmediaserver-ros6-binaries_1.7.2.3878-8088811b8_amd64.deb](50%) Installing plexmediaserver-ros6-binaries
Jun 06 22:26:03 nas fv-app-install[19342]: Installing [/tmp/plexmediaserver-ros6-binaries_1.7.2.3878-8088811b8_amd64.deb](58%) Preparing plexmediaserver-ros6-binaries
Jun 06 22:26:34 nas fv-app-install[19342]: Installing [/tmp/plexmediaserver-ros6-binaries_1.7.2.3878-8088811b8_amd64.deb](67%) Unpacking plexmediaserver-ros6-binaries
Jun 06 22:26:34 nas fv-app-install[19342]: Installing [/tmp/plexmediaserver-ros6-binaries_1.7.2.3878-8088811b8_amd64.deb](75%) Preparing to configure plexmediaserver-ros6-binaries
Jun 06 22:26:34 nas fv-app-install[19342]: Installing [/tmp/plexmediaserver-ros6-binaries_1.7.2.3878-8088811b8_amd64.deb](75%) Running dpkg
Jun 06 22:26:34 nas fv-app-install[19342]: Installing [/tmp/plexmediaserver-ros6-binaries_1.7.2.3878-8088811b8_amd64.deb](75%) Configuring plexmediaserver-ros6-binaries
Jun 06 22:26:35 nas fv-app-install[19342]: Installing [/tmp/plexmediaserver-ros6-binaries_1.7.2.3878-8088811b8_amd64.deb](83%) Configuring plexmediaserver-ros6-binaries
Jun 06 22:26:36 nas fv-app-install[19342]: Installing [/tmp/plexmediaserver-ros6-binaries_1.7.2.3878-8088811b8_amd64.deb](92%) Installed plexmediaserver-ros6-binaries
Jun 06 22:26:36 nas fv-app-install[19342]: Installing [/tmp/plexmediaserver-ros6-binaries_1.7.2.3878-8088811b8_amd64.deb](92%) Running post-installation trigger libc-bin
Jun 06 22:26:36 nas fv-app-install[19342]: Installing [/tmp/plexmediaserver-ros6-binaries_1.7.2.3878-8088811b8_amd64.deb](92%) Running dpkg

…

Jun 06 22:26:37 nas fv-app-install[19342]: [/tmp/plexmediaserver-ros6-binaries_1.7.2.3878-8088811b8_amd64.deb](100%) complete
Jun 06 22:31:43 nas fv-app-install[21754]: [/tmp/dvblink-server-netgear-linux-r6-x86_64-6.0.0-14499.deb](0%) prepare
Jun 06 22:31:43 nas fv-app-install[21754]: [/tmp/dvblink-server-netgear-linux-r6-x86_64-6.0.0-14499.deb](100%) complete
Jun 06 22:34:10 nas fv-app-install[22434]: [/tmp/dvblink-server-netgear-linux-r6-x86_64-6.0.0-14499.deb](0%) prepare
Jun 06 22:34:11 nas fv-app-install[22434]: [/tmp/dvblink-server-netgear-linux-r6-x86_64-6.0.0-14499.deb](100%) complete

I include a successful run of upgrading PLEX and at the end I can see DVBLink Server installing. Well, not really. Unfortunately, this doesn't really provide the same level of detail (debug) the old log file did. So based on this it's just more symptoms to the vendor and not real cause. So far, their statement that they forgot to revision the build number in the package seems consistent with this output... in that there wasn't anything to do? But what if I wanted to REINSTALL an app without triggering cleanup scripts for an uninstall? Based on this behavior that seems not possible. Or was it ever? Hmm.

[StephenB]

You've tried journalctl ?

[mdgm-ntgr]

The journal is the main log. You definitely should run the command StephenB suggested.

You can filter it for a time period you want e.g.:

# journalctl --since "2017-06-05 10:00:00" --until "1 hour ago"

If you download the logs zip, you'll find the last 5000 lines of the journal are included in systemd-journal.log. The last 5000 kernel related journal lines also end up in kernel.log

[btaroli]

Sure I'll try that... but, honestly, I find searching in journalctl about as useful as looking for disk drives in haystacks. Appreciate the examples though. That might help some. What would be BETTER, honestly, is knowing what SUBSYSTEMS different events were being logged as so I don't have to sift through all the snapshot updates and similar. 😉 But we'll take what we can get. Even better would a FILE, like we had before. 😉

[mdgm-ntgr]

Well if you filter the output for things referencing apt or dpkg you should be able to find the relevant logs pretty quickly, I think.

[btaroli · Accepted solution]

Parsing the full journalctl output, I find the following unit names. None of them include dpkg.

afpd
apache2
apache_access
apt-update.sh
avahi-daemon
backported
bt-mgmt
bt-pagent
clamd
cnid_metad
connmand
cron
CRON
crontab
dbus
disk_event_handler
dropboxmanager
exportfs
freshclam
fv-app-install
fvbackup-q
if
kernel:
logtruncate
manage.py
mdadm
minissdpd
msmtpq
netatalk
nmbd
raidard
readynasd
readynas-upgrade
rn-expand
rn-update.sh
rpcbind
rpc.mountd
rpc.statd
rsyncd
sh
smbd
sm-notify
snapperd
sshd
start2.sh
start_raids
su
sudo
Sun
sysctl
systemd
systemd-journald
systemd-logind
systemd-shutdown
systemd-udevd
tftpr6
transmission
umount
update_support_fw_db
upnphttpd
upsd
upsdrvctl
upsmon
usage
usbhid-ups
wsdd2

The best I can ascertain, perhaps apt-update.sh or fv-app-install .... ? OK, it looks like fv-app-install is the key...

# journalctl --identifier=fv-app-install
-- Logs begin at Sun 2017-05-07 20:30:01 PDT, end at Thu 2017-06-08 09:33:29 PDT. --

…

Jun 06 22:26:00 nas fv-app-install[19342]: [/tmp/plexmediaserver-ros6-binaries_1.7.2.3878-8088811b8_amd64.deb](0%) prepare
Jun 06 22:26:01 nas fv-app-install[19342]: Downloading [/tmp/plexmediaserver-ros6-binaries_1.7.2.3878-8088811b8_amd64.deb](0%) Retrieving file 1 of 1
Jun 06 22:26:01 nas fv-app-install[19342]: Downloading [/tmp/plexmediaserver-ros6-binaries_1.7.2.3878-8088811b8_amd64.deb](0%) Retrieving file 1 of 1
Jun 06 22:26:02 nas fv-app-install[19342]: Downloading [/tmp/plexmediaserver-ros6-binaries_1.7.2.3878-8088811b8_amd64.deb](0%) Retrieving file 1 of 1
Jun 06 22:26:02 nas fv-app-install[19342]: Downloading [/tmp/plexmediaserver-ros6-binaries_1.7.2.3878-8088811b8_amd64.deb](0%) Retrieving file 1 of 1
Jun 06 22:26:03 nas fv-app-install[19342]: Downloading [/tmp/plexmediaserver-ros6-binaries_1.7.2.3878-8088811b8_amd64.deb](0%) Retrieving file 1 of 1
Jun 06 22:26:03 nas fv-app-install[19342]: Downloading [/tmp/plexmediaserver-ros6-binaries_1.7.2.3878-8088811b8_amd64.deb](50%) Retrieving file 1 of 1
Jun 06 22:26:03 nas fv-app-install[19342]: Installing [/tmp/plexmediaserver-ros6-binaries_1.7.2.3878-8088811b8_amd64.deb](50%) Running dpkg
Jun 06 22:26:03 nas fv-app-install[19342]: Installing [/tmp/plexmediaserver-ros6-binaries_1.7.2.3878-8088811b8_amd64.deb](50%) Installing plexmediaserver-ros6-binaries
Jun 06 22:26:03 nas fv-app-install[19342]: Installing [/tmp/plexmediaserver-ros6-binaries_1.7.2.3878-8088811b8_amd64.deb](58%) Preparing plexmediaserver-ros6-binaries
Jun 06 22:26:34 nas fv-app-install[19342]: Installing [/tmp/plexmediaserver-ros6-binaries_1.7.2.3878-8088811b8_amd64.deb](67%) Unpacking plexmediaserver-ros6-binaries
Jun 06 22:26:34 nas fv-app-install[19342]: Installing [/tmp/plexmediaserver-ros6-binaries_1.7.2.3878-8088811b8_amd64.deb](75%) Preparing to configure plexmediaserver-ros6-binaries
Jun 06 22:26:34 nas fv-app-install[19342]: Installing [/tmp/plexmediaserver-ros6-binaries_1.7.2.3878-8088811b8_amd64.deb](75%) Running dpkg
Jun 06 22:26:34 nas fv-app-install[19342]: Installing [/tmp/plexmediaserver-ros6-binaries_1.7.2.3878-8088811b8_amd64.deb](75%) Configuring plexmediaserver-ros6-binaries
Jun 06 22:26:35 nas fv-app-install[19342]: Installing [/tmp/plexmediaserver-ros6-binaries_1.7.2.3878-8088811b8_amd64.deb](83%) Configuring plexmediaserver-ros6-binaries
Jun 06 22:26:36 nas fv-app-install[19342]: Installing [/tmp/plexmediaserver-ros6-binaries_1.7.2.3878-8088811b8_amd64.deb](92%) Installed plexmediaserver-ros6-binaries
Jun 06 22:26:36 nas fv-app-install[19342]: Installing [/tmp/plexmediaserver-ros6-binaries_1.7.2.3878-8088811b8_amd64.deb](92%) Running post-installation trigger libc-bin
Jun 06 22:26:36 nas fv-app-install[19342]: Installing [/tmp/plexmediaserver-ros6-binaries_1.7.2.3878-8088811b8_amd64.deb](92%) Running dpkg

…

Jun 06 22:26:37 nas fv-app-install[19342]: [/tmp/plexmediaserver-ros6-binaries_1.7.2.3878-8088811b8_amd64.deb](100%) complete
Jun 06 22:31:43 nas fv-app-install[21754]: [/tmp/dvblink-server-netgear-linux-r6-x86_64-6.0.0-14499.deb](0%) prepare
Jun 06 22:31:43 nas fv-app-install[21754]: [/tmp/dvblink-server-netgear-linux-r6-x86_64-6.0.0-14499.deb](100%) complete
Jun 06 22:34:10 nas fv-app-install[22434]: [/tmp/dvblink-server-netgear-linux-r6-x86_64-6.0.0-14499.deb](0%) prepare
Jun 06 22:34:11 nas fv-app-install[22434]: [/tmp/dvblink-server-netgear-linux-r6-x86_64-6.0.0-14499.deb](100%) complete

I include a successful run of upgrading PLEX and at the end I can see DVBLink Server installing. Well, not really. Unfortunately, this doesn't really provide the same level of detail (debug) the old log file did. So based on this it's just more symptoms to the vendor and not real cause. So far, their statement that they forgot to revision the build number in the package seems consistent with this output... in that there wasn't anything to do? But what if I wanted to REINSTALL an app without triggering cleanup scripts for an uninstall? Based on this behavior that seems not possible. Or was it ever? Hmm.