one-context-force.service fails on ubuntu 18.04

[meier-rene]

systemctl status one-context-force.service
● one-context-force.service - OpenNebula forced reconfiguration
   Loaded: loaded (/usr/lib/systemd/system/one-context-force.service; disabled; vendor preset: enabled)
   Active: failed (Result: exit-code) since Tue 2018-08-21 06:19:28 UTC; 17min ago
 Main PID: 732 (code=exited, status=1/FAILURE)

Aug 21 06:19:28 localhost systemd[1]: Starting OpenNebula forced reconfiguration...
Aug 21 06:19:28 localhost one-context-run[732]: Contextualization must start first as a boot service
Aug 21 06:19:28 localhost systemd[1]: one-context-force.service: Main process exited, code=exited, status=1/FAILURE
Aug 21 06:19:28 localhost systemd[1]: one-context-force.service: Failed with result 'exit-code'.
Aug 21 06:19:28 localhost systemd[1]: Failed to start OpenNebula forced reconfiguration.

I installed an ubuntu18.04 server image with the one-context_5.6.0-1.deb package. My context section is just

CONTEXT = [
  SET_HOSTNAME = "$NAME" ]

and I get the above error on boot.

[vholer]

There are several systemd services to deal with different situations, but the main ones you should check are one-context-local and one-context. These are started on boot and the errors you see are just the safety checks to ensure no other derived contextualization services (e.g. one-context-reconfigure, one-context-reconfigure-delayed, or one-context-force) are started before them.

Please check the status of one-context-local and one-context services also you can provide logs:

$ grep one-context /var/log/syslog

Thank you.

[vholer]

Also, also check this issue #119 (comment) just in case you didn't do clean package installation, but just upgraded already installed older package.

[puppetmaster]

Hi

Do we have a "work around" for this ?

We have this issue with the 5.8.0 release on ubuntu 18.04, the services

one-conext-local

and

one-context

are both active

`● one-context.service - OpenNebula contextualization script
Loaded: loaded (/usr/lib/systemd/system/one-context.service; enabled; vendor preset: enabled)
Active: active (exited) since Fri 2019-03-01 15:16:26 CET; 4 days ago
Main PID: 1916 (code=exited, status=0/SUCCESS)
Tasks: 0 (limit: 2318)
CGroup: /system.slice/one-context.service

mars 01 15:16:15 eolebase-2.7.0 systemd[1]: Starting OpenNebula contextualization script...
mars 01 15:16:16 eolebase-2.7.0 ntpdate[2165]: 51.255.141.154 rate limit response from server.
mars 01 15:16:26 eolebase-2.7.0 one-contextd[2326]: Done
mars 01 15:16:26 eolebase-2.7.0 systemd[1]: Started OpenNebula contextualization script.
root@ldap-b:~# systemctl status one-context-local
● one-context-local.service - OpenNebula pre-networking contextualization script
Loaded: loaded (/usr/lib/systemd/system/one-context-local.service; enabled; vendor preset: enabled)
Active: active (exited) since Fri 2019-03-01 15:14:15 CET; 4 days ago
Main PID: 551 (code=exited, status=0/SUCCESS)
Tasks: 0 (limit: 2318)
CGroup: /system.slice/one-context-local.service

mars 01 15:14:14 eolebase-2.7.0 one-contextd[1035]: Script loc-14-mount-swap: Finished with exit code 255
mars 01 15:14:14 eolebase-2.7.0 one-contextd[1037]: Script loc-16-gen-env: Starting ...
mars 01 15:14:14 eolebase-2.7.0 one-contextd[1047]: Script loc-16-gen-env output: cat: /var/run/one-context/mount.bHWLt
mars 01 15:14:14 eolebase-2.7.0 one-contextd[1048]: Script loc-16-gen-env: Finished with exit code 0
mars 01 15:14:14 eolebase-2.7.0 one-contextd[1050]: Script loc-20-set-username-password: Starting ...
mars 01 15:14:14 eolebase-2.7.0 one-contextd[1061]: Script loc-20-set-username-password: Finished with exit code 0
mars 01 15:14:14 eolebase-2.7.0 one-contextd[1063]: Script loc-22-ssh_public_key: Starting ...
mars 01 15:14:14 eolebase-2.7.0 one-contextd[1066]: Script loc-22-ssh_public_key: Finished with exit code 0
mars 01 15:14:15 eolebase-2.7.0 one-contextd[1197]: Unmounting /var/run/one-context/mount.bHWLtR
mars 01 15:14:15 eolebase-2.7.0 systemd[1]: Started OpenNebula pre-networking contextualization script.
`

[baby-gnu]

I have the same issue on Debian Buster.

It looks like the /usr/sbin/one-context-run is looking for /var/run/one-context/context.sh.local and /var/run/one-context/context.sh.network but /var/run/one-context/ does not exists when one-context-force.service runs.

I added a some debug in the script to see what's happening:

--- /usr/sbin/one-context-run.orig	2019-07-09 16:15:12.807287544 +0200
+++ /usr/sbin/one-context-run	2019-07-09 16:15:19.831274161 +0200
@@ -36,5 +36,6 @@
     fi
 else
     echo 'Contextualization must start first as a boot service' >&2
+    ls -l $(dirname ${CONTEXT_BASE}) >&2
     exit 1
 fi

# systemctl status one-context-force.service 
● one-context-force.service - OpenNebula forced reconfiguration
   Loaded: loaded (/lib/systemd/system/one-context-force.service; disabled; vendor preset: enabled)
   Active: failed (Result: exit-code) since Tue 2019-07-09 16:11:53 CEST; 41s ago
  Process: 345 ExecStart=/usr/sbin/one-context-run force (code=exited, status=1/FAILURE)
 Main PID: 345 (code=exited, status=1/FAILURE)

juil. 09 16:11:53 buster systemd[1]: Starting OpenNebula forced reconfiguration...
juil. 09 16:11:53 buster one-context-run[345]: Contextualization must start first as a boot service
juil. 09 16:11:53 buster one-context-run[345]: ls: cannot access '/var/run/one-context/': No such file or directory
juil. 09 16:11:53 buster systemd[1]: one-context-force.service: Main process exited, code=exited, status=1/FAILURE
juil. 09 16:11:53 buster systemd[1]: one-context-force.service: Failed with result 'exit-code'.
juil. 09 16:11:53 buster systemd[1]: Failed to start OpenNebula forced reconfiguration.

Looking at the last boot logs I see that one-context-run is started before one-contextd

# journalctl -b0 -u one-*
-- Logs begin at Tue 2019-07-09 16:13:58 CEST, end at Tue 2019-07-09 16:17:01 CEST. --
Jul 09 16:14:02 buster systemd[1]: Starting OpenNebula forced reconfiguration...
Jul 09 16:14:02 buster systemd[1]: Condition check resulted in OpenNebula delayed reconfiguration script being skipped.
Jul 09 16:14:02 buster one-context-run[345]: Contextualization must start first as a boot service
Jul 09 16:14:02 buster one-context-run[345]: ls: cannot access '/var/run/one-context': No such file or directory
Jul 09 16:14:02 buster systemd[1]: one-context-force.service: Main process exited, code=exited, status=1/FAILURE
Jul 09 16:14:02 buster systemd[1]: one-context-force.service: Failed with result 'exit-code'.
Jul 09 16:14:02 buster systemd[1]: Failed to start OpenNebula forced reconfiguration.
Jul 09 16:14:02 buster systemd[1]: Starting OpenNebula pre-networking contextualization script...
Jul 09 16:14:03 buster one-contextd[369]: Started for type local
Jul 09 16:14:03 buster one-contextd[370]: Acquiring lock /var/run/one-context/one-context.lock
Jul 09 16:14:03 buster one-contextd[372]: Acquired lock /var/run/one-context/one-context.lock
Jul 09 16:14:03 buster one-contextd[392]: Mounting CD-ROM /dev/sr0 on /var/run/one-context/mount.nFyT2S
Jul 09 16:14:03 buster one-contextd[399]: Found context /var/run/one-context/mount.nFyT2S/context.sh
Jul 09 16:14:03 buster one-contextd[402]: Comparing /var/run/one-context/context.sh.2JXf5j and /var/run/one-context/context.sh.local for changes
Jul 09 16:14:03 buster one-contextd[404]: New context with changes
Jul 09 16:14:03 buster one-contextd[412]: Processing local scripts
Jul 09 16:14:03 buster one-contextd[414]: Script loc-05-grow-rootfs: Starting ...
Jul 09 16:14:03 buster one-contextd[496]: Script loc-05-grow-rootfs output: /usr/bin/growpart: 235: /usr/bin/growpart: Illegal number: 42949672960 octets,
Jul 09 16:14:03 buster one-contextd[496]: /usr/bin/growpart: 235: /usr/bin/growpart: Illegal number: 42949672960 octets,
Jul 09 16:14:03 buster one-contextd[496]:   Physical volume "/dev/sda5" changed
Jul 09 16:14:03 buster one-contextd[496]:   1 physical volume(s) resized or updated / 0 physical volume(s) not resized
Jul 09 16:14:03 buster one-contextd[496]:   New size (9922 extents) matches existing size (9922 extents).
Jul 09 16:14:03 buster one-contextd[496]: resize2fs 1.44.5 (15-Dec-2018)
Jul 09 16:14:03 buster one-contextd[496]: The filesystem is already 10160128 (4k) blocks long.  Nothing to do!
Jul 09 16:14:03 buster one-contextd[497]: Script loc-05-grow-rootfs: Finished with exit code 0
Jul 09 16:14:03 buster one-contextd[499]: Script loc-10-network: Starting ...
Jul 09 16:14:04 buster one-contextd[601]: Script loc-10-network output: ifdown: interface ens3 not configured
Jul 09 16:14:04 buster one-contextd[602]: Script loc-10-network: Finished with exit code 0
Jul 09 16:14:04 buster one-contextd[604]: Script loc-10-network-pci: Starting ...
Jul 09 16:14:04 buster one-contextd[612]: Script loc-10-network-pci: Finished with exit code 0
Jul 09 16:14:04 buster one-contextd[614]: Script loc-11-dns: Starting ...
Jul 09 16:14:04 buster one-contextd[633]: Script loc-11-dns: Finished with exit code 0
Jul 09 16:14:04 buster one-contextd[635]: Script loc-14-mount-swap: Starting ...
Jul 09 16:14:04 buster one-contextd[645]: Script loc-14-mount-swap output: swapon: /dev/mapper/buster--vg-swap_1 : échec de swapon: Périphérique ou ressource occupé
Jul 09 16:14:04 buster one-contextd[646]: Script loc-14-mount-swap: Finished with exit code 255
Jul 09 16:14:04 buster one-contextd[648]: Script loc-16-gen-env: Starting ...
Jul 09 16:14:04 buster one-contextd[658]: Script loc-16-gen-env output: cat: /var/run/one-context/mount.nFyT2S/token.txt: Aucun fichier ou dossier de ce type
Jul 09 16:14:04 buster one-contextd[659]: Script loc-16-gen-env: Finished with exit code 0
Jul 09 16:14:04 buster one-contextd[661]: Script loc-20-set-username-password: Starting ...
Jul 09 16:14:04 buster one-contextd[672]: Script loc-20-set-username-password: Finished with exit code 0
Jul 09 16:14:04 buster one-contextd[674]: Script loc-22-ssh_public_key: Starting ...
Jul 09 16:14:04 buster one-contextd[687]: Script loc-22-ssh_public_key: Finished with exit code 0
Jul 09 16:14:04 buster one-contextd[689]: Script loc-24-ssh_host_key: Starting ...
Jul 09 16:14:04 buster one-contextd[692]: Script loc-24-ssh_host_key: Finished with exit code 0
Jul 09 16:14:04 buster one-contextd[694]: Script loc-30-console: Starting ...
Jul 09 16:14:04 buster one-contextd[819]: Script loc-30-console: Finished with exit code 0
Jul 09 16:14:04 buster one-contextd[821]: Script loc-90-eole-set-random-password: Starting ...
Jul 09 16:14:04 buster one-contextd[826]: Script loc-90-eole-set-random-password: Finished with exit code 0
Jul 09 16:14:04 buster one-contextd[828]: Script loc-91-eole-set-ip-addresses: Starting ...
Jul 09 16:14:05 buster one-contextd[831]: Script loc-91-eole-set-ip-addresses: Finished with exit code 0
Jul 09 16:14:05 buster one-contextd[833]: Script loc-92-eole-set-root-mail: Starting ...
Jul 09 16:14:05 buster one-contextd[836]: Script loc-92-eole-set-root-mail: Finished with exit code 0
Jul 09 16:14:05 buster one-contextd[837]: Finished scripts processing
Jul 09 16:14:05 buster one-contextd[838]: Done
Jul 09 16:14:05 buster one-contextd[839]: Unmounting /var/run/one-context/mount.nFyT2S
Jul 09 16:14:05 buster one-contextd[843]: Releasing lock /var/run/one-context/one-context.lock
Jul 09 16:14:05 buster systemd[1]: Started OpenNebula pre-networking contextualization script.
Jul 09 16:14:05 buster systemd[1]: Starting OpenNebula contextualization script...
Jul 09 16:14:05 buster one-contextd[1116]: Started for type network
Jul 09 16:14:05 buster one-contextd[1118]: Acquiring lock /var/run/one-context/one-context.lock
Jul 09 16:14:05 buster one-contextd[1120]: Acquired lock /var/run/one-context/one-context.lock
Jul 09 16:14:05 buster one-contextd[1129]: Mounting CD-ROM /dev/sr0 on /var/run/one-context/mount.X8ts55
Jul 09 16:14:05 buster one-contextd[1131]: Found context /var/run/one-context/mount.X8ts55/context.sh
Jul 09 16:14:05 buster one-contextd[1134]: Comparing /var/run/one-context/context.sh.2OJnfc and /var/run/one-context/context.sh.network for changes
Jul 09 16:14:05 buster one-contextd[1136]: New context with changes
Jul 09 16:14:05 buster one-contextd[1145]: Processing network scripts
Jul 09 16:14:05 buster one-contextd[1147]: Script net-11-fix-loopback: Starting ...
Jul 09 16:14:05 buster one-contextd[1151]: Script net-11-fix-loopback: Finished with exit code 0
Jul 09 16:14:05 buster one-contextd[1153]: Script net-15-hostname: Starting ...
Jul 09 16:14:05 buster one-contextd[1163]: Script net-15-hostname: Finished with exit code 0
Jul 09 16:14:05 buster one-contextd[1165]: Script net-97-start-script: Starting ...
Jul 09 16:14:05 buster one-contextd[1171]: Script net-97-start-script: Finished with exit code 0
Jul 09 16:14:05 buster one-contextd[1173]: Script net-98-execute-scripts: Starting ...
Jul 09 16:14:05 buster one-contextd[1179]: Script net-98-execute-scripts: Finished with exit code 0
Jul 09 16:14:05 buster one-contextd[1181]: Script net-99-report-ready: Starting ...
Jul 09 16:14:05 buster one-contextd[1184]: Script net-99-report-ready: Finished with exit code 0
Jul 09 16:14:05 buster one-contextd[1185]: Finished scripts processing
Jul 09 16:14:05 buster one-contextd[1186]: Done
Jul 09 16:14:05 buster one-contextd[1187]: Unmounting /var/run/one-context/mount.X8ts55
Jul 09 16:14:05 buster one-contextd[1191]: Releasing lock /var/run/one-context/one-context.lock
Jul 09 16:14:05 buster systemd[1]: Started OpenNebula contextualization script.
Jul 09 16:14:05 buster systemd[1]: Starting OpenNebula delayed reconfiguration script...
Jul 09 16:14:05 buster systemd[1]: Started OpenNebula delayed reconfiguration script.
Jul 09 16:15:05 buster one-contextd[1256]: Started for type all to reconfigure
Jul 09 16:15:05 buster one-contextd[1257]: Acquiring lock /var/run/one-context/one-context.lock
Jul 09 16:15:05 buster one-contextd[1259]: Acquired lock /var/run/one-context/one-context.lock
Jul 09 16:15:05 buster one-contextd[1268]: Mounting CD-ROM /dev/sr0 on /var/run/one-context/mount.9wxCmi
Jul 09 16:15:05 buster one-contextd[1270]: Found context /var/run/one-context/mount.9wxCmi/context.sh
Jul 09 16:15:05 buster one-contextd[1273]: Comparing /var/run/one-context/context.sh.Czwkap and /var/run/one-context/context.sh.local for changes
Jul 09 16:15:05 buster one-contextd[1275]: No changes in context, skipping
Jul 09 16:15:05 buster one-contextd[1276]: Comparing /var/run/one-context/context.sh.Czwkap and /var/run/one-context/context.sh.network for changes
Jul 09 16:15:05 buster one-contextd[1278]: No changes in context, skipping
Jul 09 16:15:05 buster one-contextd[1279]: Done
Jul 09 16:15:05 buster one-contextd[1280]: Unmounting /var/run/one-context/mount.9wxCmi
Jul 09 16:15:05 buster one-contextd[1284]: Releasing lock /var/run/one-context/one-context.lock
Jul 09 16:15:05 buster systemd[1]: one-context-reconfigure-delayed.service: Succeeded.

Seems that there is an issue with systemd ordering.

[baby-gnu]

I don't undestand how a disabled service can be started by systemd

#systemctl status one-context-force.service
● one-context-force.service - OpenNebula forced reconfiguration
   Loaded: loaded (/lib/systemd/system/one-context-force.service; disabled; vendor preset: enabled)
   Active: failed (Result: exit-code) since Wed 2019-07-10 09:45:31 CEST; 4h 54min ago
 Main PID: 390 (code=exited, status=1/FAILURE)

juil. 10 09:45:30 buster systemd[1]: Starting OpenNebula forced reconfiguration...
juil. 10 09:45:31 buster one-context-run[390]: Contextualization must start first as a boot service
juil. 10 09:45:31 buster systemd[1]: one-context-force.service: Main process exited, code=exited, status=1/FAILURE
juil. 10 09:45:31 buster systemd[1]: one-context-force.service: Failed with result 'exit-code'.
juil. 10 09:45:31 buster systemd[1]: Failed to start OpenNebula forced reconfiguration.

It's not even referenced in list-dependencies:

systemctl list-dependencies --no-pager
default.target
● ├─display-manager.service
● ├─exim4.service
● ├─gpm.service
● ├─systemd-update-utmp-runlevel.service
● └─multi-user.target
●   ├─console-setup.service
●   ├─cron.service
●   ├─exim4.service
●   ├─gpm.service
●   ├─networking.service
●   ├─one-context-local.service
●   ├─one-context.service
●   ├─open-vm-tools.service
●   ├─rsyslog.service
●   ├─ssh.service
●   ├─systemd-ask-password-wall.path
●   ├─systemd-logind.service
●   ├─systemd-update-utmp-runlevel.service
●   ├─systemd-user-sessions.service
●   ├─unattended-upgrades.service
●   ├─basic.target
●   │ ├─-.mount
●   │ ├─fstrim.service
●   │ ├─tmp.mount
●   │ ├─var.mount
●   │ ├─paths.target
●   │ ├─slices.target
●   │ │ ├─-.slice
●   │ │ └─system.slice
●   │ ├─sockets.target
●   │ │ ├─dm-event.socket
●   │ │ ├─systemd-initctl.socket
●   │ │ ├─systemd-journald-audit.socket
●   │ │ ├─systemd-journald-dev-log.socket
●   │ │ ├─systemd-journald.socket
●   │ │ ├─systemd-udevd-control.socket
●   │ │ └─systemd-udevd-kernel.socket
●   │ ├─sysinit.target
●   │ │ ├─blk-availability.service
●   │ │ ├─dev-hugepages.mount
●   │ │ ├─dev-mqueue.mount
●   │ │ ├─keyboard-setup.service
●   │ │ ├─kmod-static-nodes.service
●   │ │ ├─lvm2-lvmpolld.socket
●   │ │ ├─lvm2-monitor.service
●   │ │ ├─proc-sys-fs-binfmt_misc.automount
●   │ │ ├─sys-fs-fuse-connections.mount
●   │ │ ├─sys-kernel-config.mount
●   │ │ ├─sys-kernel-debug.mount
●   │ │ ├─systemd-ask-password-console.path
●   │ │ ├─systemd-binfmt.service
●   │ │ ├─systemd-hwdb-update.service
●   │ │ ├─systemd-journal-flush.service
●   │ │ ├─systemd-journald.service
●   │ │ ├─systemd-machine-id-commit.service
●   │ │ ├─systemd-modules-load.service
●   │ │ ├─systemd-random-seed.service
●   │ │ ├─systemd-sysctl.service
●   │ │ ├─systemd-sysusers.service
●   │ │ ├─systemd-timesyncd.service
●   │ │ ├─systemd-tmpfiles-setup-dev.service
●   │ │ ├─systemd-tmpfiles-setup.service
●   │ │ ├─systemd-udev-trigger.service
●   │ │ ├─systemd-udevd.service
●   │ │ ├─systemd-update-utmp.service
●   │ │ ├─cryptsetup.target
●   │ │ ├─local-fs.target
●   │ │ │ ├─-.mount
●   │ │ │ ├─boot.mount
●   │ │ │ ├─home.mount
●   │ │ │ ├─systemd-fsck-root.service
●   │ │ │ ├─systemd-remount-fs.service
●   │ │ │ ├─tmp.mount
●   │ │ │ └─var.mount
●   │ │ └─swap.target
●   │ │   └─dev-mapper-buster\x2d\x2dvg\x2dswap_1.swap
●   │ └─timers.target
●   │   ├─apt-daily-upgrade.timer
●   │   ├─apt-daily.timer
●   │   ├─logrotate.timer
●   │   ├─man-db.timer
●   │   └─systemd-tmpfiles-clean.timer
●   ├─getty.target
●   │ ├─getty-static.service
●   │ └─getty@tty1.service
●   └─remote-fs.target

Am I missing something?

[baby-gnu]

Ok, the problem may be due to udev rules

# Handle disk resize
SUBSYSTEM=="block", ACTION=="change", \
  ENV{RESIZE}=="1", \
  RUN+="/usr/sbin/service one-context-force start"

# Handle swap hot-attach
SUBSYSTEM=="block", ACTION=="add", \
  ENV{ID_FS_TYPE}=="swap", \
  RUN+="/usr/sbin/service one-context-force start"

[vholer]

Closing. Fixed by #173 by @baby-gnu . Thanks!