September Update: New rbp1-device-osmc breaks upgrade

Hi there,

the new rbp1-device-osmc 1.2.4 (assumingly released in the last 24h, because yesterday same time it wasn’t there) breaks the upgrade.

rbp1-device-osmc 1.2.4 has a new dependency to new armv6l-diskmount-osmc which requires new armv6l-diskmount-osmc that replaces diskmount-osmc and depends on armv6l-udisks-osmc.

Sadly the new armv6l-udisks-osmc seems broken and cannot be started. (sorry for the german log)

armv6l-udisks-osmc (1.0.5-8) wird eingerichtet ...
Job for udisks.service failed. See 'systemctl status udisks.service' and 'journalctl -xn' for details.
dpkg: Fehler beim Bearbeiten des Paketes armv6l-udisks-osmc (--configure):
 Unterprozess installiertes post-installation-Skript gab den Fehlerwert 1 zurück

This way the postinstall script fails and because of that the update stops with half-configured stuff. Had to roll back manually using files from /var/cache/archive to get it working again.

I am willing to dig into that if I get a bit of help what I should try and how I can get meaningful logs from the failing service, because “journalctl -xn” did not give any log lines.

Hi

Can you post the output of

sudo -s
export LANG=C # for us English speakers
apt-get update
apt-get dist-upgrade
dpkg -l | grab-logs -A

Sam

This time it breaks in another way. Maybe this is a result of my rollback?

root@osmc:/home/osmc# apt-get update
Hit http://mirrordirector.raspbian.org jessie InRelease
Hit http://apt.osmc.tv jessie InRelease
Hit http://mirrordirector.raspbian.org jessie/main armhf Packages
Hit http://mirrordirector.raspbian.org jessie/contrib armhf Packages
Hit http://mirrordirector.raspbian.org jessie/non-free armhf Packages
Get:1 http://apt.osmc.tv jessie/main armhf Packages/DiffIndex [2023 B]              
Ign http://apt.osmc.tv jessie/main Translation-en                                       
Ign http://mirrordirector.raspbian.org jessie/contrib Translation-en
Ign http://mirrordirector.raspbian.org jessie/main Translation-en
Ign http://mirrordirector.raspbian.org jessie/non-free Translation-en
Fetched 2023 B in 16s (119 B/s)                                                                    
Reading package lists... Done
root@osmc:/home/osmc# apt-get dist-upgrade
Reading package lists... Done
Building dependency tree       
Reading state information... Done
Calculating upgrade... Done
The following packages will be REMOVED:
  diskmount-osmc
The following NEW packages will be installed:
  armv6l-diskmount-osmc armv6l-udisks-osmc libatasmart4 libdevmapper-event1.02.1 libgudev-1.0-0
  liblvm2app2.2 libparted2 libsgutils2-2
The following packages will be upgraded:
  rbp1-device-osmc
1 upgraded, 8 newly installed, 1 to remove and 0 not upgraded.
Need to get 0 B/1228 kB of archives.
After this operation, 2829 kB of additional disk space will be used.
Do you want to continue? [Y/n] 
Selecting previously unselected package libatasmart4:armhf.
(Reading database ... 35915 files and directories currently installed.)
Preparing to unpack .../libatasmart4_0.19-3_armhf.deb ...
Unpacking libatasmart4:armhf (0.19-3) ...
Selecting previously unselected package libgudev-1.0-0:armhf.
Preparing to unpack .../libgudev-1.0-0_215-17+deb8u7_armhf.deb ...
Unpacking libgudev-1.0-0:armhf (215-17+deb8u7) ...
Selecting previously unselected package libdevmapper-event1.02.1:armhf.
Preparing to unpack .../libdevmapper-event1.02.1_2%3a1.02.90-2.2+deb8u1_armhf.deb ...
Unpacking libdevmapper-event1.02.1:armhf (2:1.02.90-2.2+deb8u1) ...
Selecting previously unselected package liblvm2app2.2:armhf.
Preparing to unpack .../liblvm2app2.2_2.02.111-2.2+deb8u1_armhf.deb ...
Unpacking liblvm2app2.2:armhf (2.02.111-2.2+deb8u1) ...
Selecting previously unselected package libparted2:armhf.
Preparing to unpack .../libparted2_3.2-7_armhf.deb ...
Unpacking libparted2:armhf (3.2-7) ...
Selecting previously unselected package libsgutils2-2.
Preparing to unpack .../libsgutils2-2_1.39-1_armhf.deb ...
Unpacking libsgutils2-2 (1.39-1) ...
Selecting previously unselected package armv6l-udisks-osmc.
Preparing to unpack .../armv6l-udisks-osmc_1.0.5-8_armhf.deb ...
Unpacking armv6l-udisks-osmc (1.0.5-8) ...
Preparing to unpack .../rbp1-device-osmc_1.2.4_armhf.deb ...
Unpacking rbp1-device-osmc (1.2.4) over (1.2.0) ...
Processing triggers for dbus (1.8.22-0+deb8u1) ...
(Reading database ... 35997 files and directories currently installed.)
Removing diskmount-osmc (9.99-17) ...
dpkg-divert: error: mismatch on package
  when removing `diversion of /etc/udisks-glue.conf to /etc/udisks-glue.conf.distributed by diskmount-osmc'
  found `diversion of /etc/udisks-glue.conf to /etc/udisks-glue.conf.distributed by armv6l-diskmount-osmc'
dpkg: error processing package diskmount-osmc (--remove):
 subprocess installed post-removal script returned error exit status 2
Errors were encountered while processing:
 diskmount-osmc
E: Sub-process /usr/bin/dpkg returned an error code (1)

additionally:

root@osmc:/home/osmc# dpkg -l | grab-logs -A
Killed

My guess was OOM and dmesg confirmed it

[94376.338420] Out of memory: Kill process 1525 (python2) score 818 or sacrifice child
[94376.338460] Killed process 1525 (python2) total-vm:310844kB, anon-rss:304048kB, file-rss:144kB, shmem-rss:0kB

The mediacenter was already stopped so I don’t see any possibility to free up more RAM.

If you are getting OOM you have a different issue there.
Stop unneeded services and try update.

Like I said, I already stopped mediacenter before that. RAM is pretty much free

root@osmc:/home/osmc# free
             total       used       free     shared    buffers     cached
Mem:        361236      59488     301748       4536       3048      19900
-/+ buffers/cache:      36540     324696
Swap:            0          0          0

You shouldn’t be OOMing unless you have additional services running.

Full logs please.

Also try apt-get clean

The OOM you experienced is something else entirely, you’ll need to have a look see what caused that. However to fix the above I would do this:

sudo nano /var/lib/dpkg/info/diskmount-osmc.postrm

Just before the line that says remove_divert /etc/udisks-glue.conf.distributed /etc/udisks-glue.conf add exit on a line by itself - this will bypass attempted removal of diverts that now belong to another package.

Now try upgrading again. Long story short - there was a transitional package for diskmount-osmc with a buggy postrm script which should not have still been in the apt repo but this only caused an issue because of an incorrect dependency in rbp1-device-osmc (now fixed by 1.2.4) and the way you attempted to roll back and re-update, which tripped up the migration from diskmount-osmc to armv6l-diskmount-osmc.

It shouldn’t happen again now that both these problems are fixed.

1 Like

Still it does. My memory is free.

Here’s my full proc list, with the biggest memory hogs being init, bash and journald:

root@osmc:/home/osmc# ps -efl |cat
F S UID        PID  PPID  C PRI  NI ADDR SZ WCHAN  STIME TTY          TIME CMD
4 S root         1     0  0  80   0 -  5944 SyS_ep Oct01 ?        00:00:25 /sbin/init
1 S root         2     0  0  80   0 -     0 kthrea Oct01 ?        00:00:00 [kthreadd]
1 S root         3     2  0  80   0 -     0 smpboo Oct01 ?        00:00:05 [ksoftirqd/0]
1 S root         5     2  0  60 -20 -     0 worker Oct01 ?        00:00:00 [kworker/0:0H]
1 S root         7     2  0  80   0 -     0 rcu_gp Oct01 ?        00:00:02 [rcu_preempt]
1 S root         8     2  0  80   0 -     0 rcu_gp Oct01 ?        00:00:00 [rcu_sched]
1 S root         9     2  0  80   0 -     0 rcu_gp Oct01 ?        00:00:00 [rcu_bh]
1 S root        10     2  0  60 -20 -     0 rescue Oct01 ?        00:00:00 [lru-add-drain]
5 S root        11     2  0  80   0 -     0 devtmp Oct01 ?        00:00:00 [kdevtmpfs]
1 S root        12     2  0  60 -20 -     0 rescue Oct01 ?        00:00:00 [netns]
1 S root        13     2  0  80   0 -     0 watchd Oct01 ?        00:00:00 [khungtaskd]
1 S root        14     2  0  80   0 -     0 oom_re Oct01 ?        00:00:00 [oom_reaper]
1 S root        15     2  0  60 -20 -     0 rescue Oct01 ?        00:00:00 [writeback]
1 S root        16     2  0  80   0 -     0 kcompa Oct01 ?        00:00:00 [kcompactd0]
1 S root        17     2  0  60 -20 -     0 rescue Oct01 ?        00:00:00 [crypto]
1 S root        18     2  0  60 -20 -     0 rescue Oct01 ?        00:00:00 [bioset]
1 S root        19     2  0  60 -20 -     0 rescue Oct01 ?        00:00:00 [kblockd]
1 S root        20     2  0  60 -20 -     0 rescue Oct01 ?        00:00:00 [watchdogd]
1 S root        22     2  0  60 -20 -     0 rescue Oct01 ?        00:00:00 [rpciod]
1 S root        23     2  0  60 -20 -     0 rescue Oct01 ?        00:00:00 [xprtiod]
1 S root        24     2  0  80   0 -     0 kswapd Oct01 ?        00:07:41 [kswapd0]
1 S root        25     2  0  60 -20 -     0 rescue Oct01 ?        00:00:00 [nfsiod]
1 S root        47     2  0  60 -20 -     0 rescue Oct01 ?        00:00:00 [kthrotld]
1 S root        48     2  0  60 -20 -     0 rescue Oct01 ?        00:00:00 [bioset]
1 S root        49     2  0  60 -20 -     0 rescue Oct01 ?        00:00:00 [bioset]
1 S root        50     2  0  60 -20 -     0 rescue Oct01 ?        00:00:00 [bioset]
1 S root        51     2  0  60 -20 -     0 rescue Oct01 ?        00:00:00 [bioset]
1 S root        52     2  0  60 -20 -     0 rescue Oct01 ?        00:00:00 [bioset]
1 S root        53     2  0  60 -20 -     0 rescue Oct01 ?        00:00:00 [bioset]
1 S root        54     2  0  60 -20 -     0 rescue Oct01 ?        00:00:00 [bioset]
1 S root        55     2  0  60 -20 -     0 rescue Oct01 ?        00:00:00 [bioset]
1 S root        56     2  0  60 -20 -     0 rescue Oct01 ?        00:00:00 [bioset]
1 S root        57     2  0  60 -20 -     0 rescue Oct01 ?        00:00:00 [bioset]
1 S root        58     2  0  60 -20 -     0 rescue Oct01 ?        00:00:00 [bioset]
1 S root        59     2  0  60 -20 -     0 rescue Oct01 ?        00:00:00 [bioset]
1 S root        60     2  0  60 -20 -     0 rescue Oct01 ?        00:00:00 [bioset]
1 S root        61     2  0  60 -20 -     0 rescue Oct01 ?        00:00:00 [bioset]
1 S root        62     2  0  60 -20 -     0 rescue Oct01 ?        00:00:00 [bioset]
1 S root        63     2  0  60 -20 -     0 rescue Oct01 ?        00:00:00 [bioset]
1 S root        64     2  0  60 -20 -     0 rescue Oct01 ?        00:00:00 [bioset]
1 S root        65     2  0  60 -20 -     0 rescue Oct01 ?        00:00:00 [bioset]
1 S root        66     2  0  60 -20 -     0 rescue Oct01 ?        00:00:00 [bioset]
1 S root        67     2  0  60 -20 -     0 rescue Oct01 ?        00:00:00 [bioset]
1 S root        68     2  0  60 -20 -     0 rescue Oct01 ?        00:00:00 [bioset]
1 S root        69     2  0  60 -20 -     0 rescue Oct01 ?        00:00:00 [bioset]
1 S root        70     2  0  60 -20 -     0 rescue Oct01 ?        00:00:00 [bioset]
1 S root        71     2  0  60 -20 -     0 rescue Oct01 ?        00:00:00 [bioset]
1 S root        72     2  0  60 -20 -     0 rescue Oct01 ?        00:00:00 [iscsi_eh]
1 S root        73     2  0  60 -20 -     0 rescue Oct01 ?        00:00:00 [dwc_otg]
1 S root        74     2  0  60 -20 -     0 rescue Oct01 ?        00:00:00 [DWC Notificatio]
1 S root        75     2  0  61 -19 -     0 down_i Oct01 ?        00:00:00 [VCHIQ-0]
1 S root        76     2  0  61 -19 -     0 down_i Oct01 ?        00:00:00 [VCHIQr-0]
1 S root        77     2  0  60 -20 -     0 down_i Oct01 ?        00:00:00 [VCHIQs-0]
1 S root        87     2  0  80   0 -     0 vchiq_ Oct01 ?        00:00:00 [VCHIQka-0]
1 S root        88     2  0  70 -10 -     0 down_i Oct01 ?        00:00:00 [SMIO]
1 S root        98     2  0  60 -20 -     0 rescue Oct01 ?        00:00:00 [bioset]
1 S root        99     2  0  80   0 -     0 mmc_qu Oct01 ?        00:00:17 [mmcqd/0]
1 S root       113     2  0  80   0 -     0 kjourn Oct01 ?        00:00:00 [jbd2/mmcblk0p2-]
1 S root       114     2  0  60 -20 -     0 rescue Oct01 ?        00:00:00 [ext4-rsv-conver]
1 S root       122     2  0  60 -20 -     0 worker Oct01 ?        00:00:00 [kworker/0:1H]
1 S root       130     2  0  60 -20 -     0 rescue Oct01 ?        00:00:00 [ipv6_addrconf]
4 S root       158     1  0  80   0 -  2023 SyS_ep Oct01 ?        00:00:03 /lib/systemd/systemd-journald
1 S root       159     2  0  80   0 -     0 kaudit Oct01 ?        00:00:00 [kauditd]
4 S root       183     1  0  80   0 -  1023 SyS_ep Oct01 ?        00:00:00 /lib/systemd/systemd-udevd
4 S root       225     1  0  80   0 -   958 SyS_ep Oct01 ?        00:00:02 /lib/systemd/systemd-logind
4 S avahi      227     1  0  80   0 -   963 sys_po Oct01 ?        00:00:07 avahi-daemon: running [osmc.local]
4 S message+   229     1  0  80   0 -  1398 SyS_ep Oct01 ?        00:00:04 /usr/bin/dbus-daemon --system --address=systemd: --nofork --nopidfile --systemd-activation
1 S avahi      231   227  0  80   0 -   963 unix_s Oct01 ?        00:00:00 avahi-daemon: chroot helper
4 S root       233     1  0  80   0 -  1965 sys_po Oct01 ?        00:00:00 /usr/sbin/connmand -n --nodnsproxy --config=/etc/connman.conf
4 S root       235     1  0  80   0 -   569 select Oct01 ?        00:00:00 /usr/sbin/eventlircd --evmap=/etc/eventlircd.d --socket=/var/run/lirc/lircd --repeat-filter --release=_UP -f
1 S root       248     1  0  80   0 -   561 select Oct01 ?        00:00:00 /usr/sbin/lircd --driver=default --device=/dev/lirc0 --uinput --output=/var/run/lirc/lircd-lirc0 --pidfile=/var/run/lirc/lircd-lirc0.pid /etc/lirc/lircd.conf
4 S root       252     1  0  80   0 -  1961 select Oct01 ?        00:00:00 /usr/sbin/sshd -D
4 S root       301     1  0  80   0 -  1669 select Oct01 ?        00:00:00 /sbin/wpa_supplicant -u -s -O /run/wpa_supplicant
5 S root       303     1  0  80   0 -  1104 sys_po Oct01 ?        00:00:00 /sbin/rpcbind -w
5 S ntp        358     1  0  80   0 -  1448 select Oct01 ?        00:00:20 /usr/sbin/ntpd -p /var/run/ntpd.pid -g -u 106:110
1 S root      1234     2  0  80   0 -     0 worker 19:27 ?        00:00:00 [kworker/u2:1]
4 S root      1323   252  0  80   0 -  2982 sys_po 21:48 ?        00:00:00 sshd: osmc [priv]   
4 S osmc      1325     1  0  80   0 -  1238 SyS_ep 21:48 ?        00:00:00 /lib/systemd/systemd --user
5 S osmc      1326  1325  0  80   0 -  6283 sigtim 21:48 ?        00:00:00 (sd-pam)  
5 S osmc      1328  1323  0  80   0 -  2982 select 21:48 ?        00:00:00 sshd: osmc@pts/0    
0 S osmc      1329  1328  0  80   0 -  1320 wait   21:48 pts/0    00:00:00 -bash
4 S root      1335  1329  0  80   0 -  1706 sys_po 21:48 pts/0    00:00:00 sudo -s
4 S root      1336  1335  0  80   0 -  1311 wait   21:48 pts/0    00:00:00 /bin/bash
1 S root      1376     2  0  80   0 -     0 worker 21:49 ?        00:00:00 [kworker/u2:0]
4 S root      1584   252  0  80   0 -  2982 sys_po 21:56 ?        00:00:01 sshd: osmc [priv]   
5 S osmc      1586  1584  0  80   0 -  2982 select 21:58 ?        00:00:00 sshd: osmc@pts/1    
0 S osmc      1587  1586  0  80   0 -  1320 wait_w 21:58 pts/1    00:00:00 -bash
1 S root      1596     2  0  80   0 -     0 worker 22:03 ?        00:00:00 [kworker/0:1]
1 S root      1729     2  0  80   0 -     0 worker 22:06 ?        00:00:00 [kworker/0:2]
1 S root      1733     2  0  80   0 -     0 worker 22:16 ?        00:00:00 [kworker/0:0]
4 R root      1734  1336  0  80   0 -   779 -      22:17 pts/0    00:00:00 ps -efl
0 S root      1735  1336  0  80   0 -   489 pipe_r 22:17 pts/0    00:00:00 cat

Thank you! This solved the issue with the divert. Now I could reproduce the initial problem:

root@osmc:~# apt-get -f install  
Reading package lists... Done
Building dependency tree       
Reading state information... Done
Correcting dependencies... Done
The following extra packages will be installed:
  armv6l-diskmount-osmc
The following packages will be REMOVED:
  diskmount-osmc
The following NEW packages will be installed:
  armv6l-diskmount-osmc
0 upgraded, 1 newly installed, 1 to remove and 0 not upgraded.
9 not fully installed or removed.
Need to get 0 B/3802 B of archives.
After this operation, 60.4 kB of additional disk space will be used.
Do you want to continue? [Y/n] 
(Reading database ... 35997 files and directories currently installed.)
Removing diskmount-osmc (9.99-17) ...
Selecting previously unselected package armv6l-diskmount-osmc.
(Reading database ... 35997 files and directories currently installed.)
Preparing to unpack .../armv6l-diskmount-osmc_1.5.5_armhf.deb ...
Adding 'diversion of /sbin/mount.exfat-fuse to /sbin/mount.exfat-fuse.distributed by armv6l-diskmount-osmc'
Unpacking armv6l-diskmount-osmc (1.5.5) ...
Setting up libatasmart4:armhf (0.19-3) ...
Setting up libdevmapper-event1.02.1:armhf (2:1.02.90-2.2+deb8u1) ...
Setting up libgudev-1.0-0:armhf (215-17+deb8u7) ...
Setting up liblvm2app2.2:armhf (2.02.111-2.2+deb8u1) ...
Setting up libparted2:armhf (3.2-7) ...
Setting up libsgutils2-2 (1.39-1) ...
Setting up armv6l-udisks-osmc (1.0.5-8) ...
Job for udisks.service failed. See 'systemctl status udisks.service' and 'journalctl -xn' for details.
dpkg: error processing package armv6l-udisks-osmc (--configure):
 subprocess installed post-installation script returned error exit status 1
dpkg: dependency problems prevent configuration of armv6l-diskmount-osmc:
 armv6l-diskmount-osmc depends on armv6l-udisks-osmc; however:
  Package armv6l-udisks-osmc is not configured yet.

dpkg: error processing package armv6l-diskmount-osmc (--configure):
 dependency problems - leaving unconfigured
dpkg: dependency problems prevent configuration of rbp1-device-osmc:
 rbp1-device-osmc depends on armv6l-diskmount-osmc; however:
  Package armv6l-diskmount-osmc is not configured yet.

dpkg: error processing package rbp1-device-osmc (--configure):
 dependency problems - leaving unconfigured
Processing triggers for libc-bin (2.19-18+deb8u10) ...
Errors were encountered while processing:
 armv6l-udisks-osmc
 armv6l-diskmount-osmc
 rbp1-device-osmc
E: Sub-process /usr/bin/dpkg returned an error code (1)

I’m most inconsolable that grab-logs wants more than 310MB memory and OOMs. If grab-logs is not usable with 310MB free memory, then there’s nothing I can do about it. I’m sure you understand that I don’t want to upgrade to a bigger raspi version, just to be able to send logfiles…

How big are your logs?
Kodi log would likely be largest. What does Kodi’s temp directory look like?

Sam

root@osmc:/# ls -lh /home/osmc/.kodi/temp
total 346M
drwxr-xr-x 2 osmc osmc 4.0K Feb  6  2017 archive_cache
-rw-r--r-- 1 osmc osmc  401 Sep  6  2015 changelog.txt
-rw-r--r-- 1 osmc osmc  839 Mar 29  2016 cookies.dat
-rw-r--r-- 1 osmc osmc 218M Feb 22  2017 kodi.log
-rw-r--r-- 1 osmc osmc 128M Feb  6  2017 kodi.old.log
drwxr-xr-x 3 osmc osmc 4.0K Sep  6  2015 scrapers
drwxr-xr-x 2 osmc osmc 4.0K Sep  6  2015 temp
drwxr-xr-x 2 osmc osmc 4.0K Feb 18  2016 weather

The times are correct, I did not run kodi for quite some time now.

grab-logs is written in Python so possibly could use a lot of memory if its uploading very large log files. Instead you can use paste-log to upload a single log file using a lightweight bash script. Can you upload the system journal please so I can see why udisks is failing to start:

sudo journalctl | paste-log

That’s your problem.
You either have extremely high uptime; or have had extensive debug logging (including component based logging) enabled.

You can upload logs, excluding Kodi logs via My OSMC.
This will provide us with all the necessary details.

I’ll look into reducing memory usage when uploading Kodi logs

Sam

I decided to upload it manually, because I had to redact some confidential hostnames that were showing up in failed dns resolutions a few times when an autossh was starting up.

https://paste.osmc.tv/tajetexogu

@DBMandrake Do we only want journalctl?

I can provide other logs, too. Here is dpkg -l
https://paste.osmc.tv/xasuninufi

Seems that you’re missing /usr/bin/udisks - can you confirm this ?

Try rebooting and then running

sudo apt-get update
sudo apt-get install -f udisks-osmc --reinstall

Post the results if there is an error

If the above works without error finish off with

sudo apt-get -f install

@DBMandrake and I are discussing this in Slack, but a reinstall of udisks may be needed.
Edit: he beat me to it.

no, it’s there

root@osmc:/# ls -l /usr/bin/udisks
-rwxr-xr-x 1 root root 47248 Sep 15 11:31 /usr/bin/udisks

I am concerned that raspi might not come up after reboot because of those 3 unconfigures base packages. Can you confirm it should be safe (as far as you think)?

Should be fine to reboot.

Rebooted, but the reinstall fails

root@osmc:/# apt-get install -f udisks-osmc --reinstall
Reading package lists... Done
Building dependency tree       
Reading state information... Done
E: Unable to locate package udisks-osmc

I think because the broken upgrade did already remove udisks-osmc in favour of armv6l-udisks-osmc?

root@osmc:/# dpkg -l *udisks* |cat
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  armv6l-udisks-glue-osmc 1.3.5-6      armhf        udisks for OSMC
iF  armv6l-udisks-osmc      1.0.5-8      armhf        udisks for OSMC
un  udisks                  <none>       <none>       (no description available)
un  udisks-glue             <none>       <none>       (no description available)