Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

nixos-rebuild switch --upgrade goes to tty1 #39791

Closed
magnetophon opened this issue May 1, 2018 · 8 comments
Closed

nixos-rebuild switch --upgrade goes to tty1 #39791

magnetophon opened this issue May 1, 2018 · 8 comments

Comments

@magnetophon
Copy link
Member

Issue description

When I run nixos-rebuild switch --upgrade, NixOS goes to tty1, and I can't login there: nothing I type shows up in the screen.

I get the following output:

unpacking channels...
building Nix...
building the system configuration...
perl: warning: Setting locale failed.
perl: warning: Please check that your locale settings:
	LANGUAGE = (unset),
	LC_ALL = (unset),
	LC_MEASUREMENT = "nl_NL.UTF-8",
	LC_PAPER = "nl_NL.UTF-8",
	LC_MONETARY = "nl_NL.UTF-8",
	LC_NAME = "nl_NL.UTF-8",
	LC_ADDRESS = "nl_NL.UTF-8",
	LC_TELEPHONE = "nl_NL.UTF-8",
	LC_IDENTIFICATION = "nl_NL.UTF-8",
	LC_TIME = "nl_NL.UTF-8",
	LANG = "en_US.UTF-8"
    are supported and installed on your system.
perl: warning: Falling back to the standard locale ("C").
stopping the following units: alsa-store.service, audit.service, chronyd.service, cups.service, fstrim.timer, kmod-static-nodes.service, network-local-commands.service, network-manager.service, network-setup.service, nix-daemon.service, nix-daemon.socket, nscd.service, psd-resync.timer, psd.service, smartd.service, system.slice, systemd-modules-load.service, systemd-sysctl.service, systemd-tmpfiles-clean.timer, systemd-tmpfiles-setup-dev.service, systemd-udev-settle.service, systemd-udev-trigger.service, systemd-udevd-control.socket, systemd-udevd-kernel.socket, systemd-udevd.service, thinkfan.service, tlp.service, udisks2.service, wpa_supplicant.service
/nix/store/p1zqgifnq0zzzv19fpprm3157jq19czi-nixos-rebuild/bin/nixos-rebuild: line 235:  2974 Hangup                  "$@"

It might be related to these lines in my config.

Technical details

  • system: "x86_64-linux"
  • host os: Linux 4.16.5, NixOS, 18.09pre138687.1b1be29bf82 (Jellyfish)
  • multi-user?: no
  • sandbox: yes
  • version: nix-env (Nix) 2.0.1
  • channels(bart): ""
  • channels(root): "nixos"
  • nixpkgs: /nix/var/nix/profiles/per-user/root/channels/nixos/nixpkgs
@lheckemann
Copy link
Member

Is there any reason that you have both those session variable settings, but defaultLocale = "en_US.UTF-8";? Regardless, it's odd because all locales should be supported by default.

I don't think the main issue is related to the locale though. Is there anything in the journal that might explain why X (I'm assuming you're using it?) stops?

@magnetophon
Copy link
Member Author

@lheckemann
I want time, currency etcetera in Dutch, and language in English.

Yes, I'm using X.
This part of the journal seems relevant:

May 01 05:27:08 thinknix systemd[1]: Stopping Load/Save Random Seed...
May 01 05:27:08 thinknix systemd[1]: Unmounting /run/wrappers...
May 01 05:27:08 thinknix systemd[1]: Unmounting POSIX Message Queue File System...
May 01 05:27:08 thinknix systemd[1]: Closed /dev/initctl Compatibility Named Pipe.
May 01 05:27:08 thinknix wpa_supplicant[1149]: nl80211: deinit ifname=wlp3s0 disabled_11b_rates=0
May 01 05:27:08 thinknix systemd[1]: Stopping Network Time Synchronization...
May 01 05:27:08 thinknix systemd[1]: Stopping X11 Server...
May 01 05:27:08 thinknix wpa_supplicant[1149]: wlp3s0: CTRL-EVENT-TERMINATING
May 01 05:27:08 thinknix compton[1202]: [ 441236.66 ] error    9 BadDrawable  request  139 minor    4 XIO:  fatal IO error 11 (Resource temporarily unavailable) on X server ":0.0"
May 01 05:27:08 thinknix compton[1202]:       after 31507302 requests (31507302 known processed) with 0 events remaining.
May 01 05:27:08 thinknix systemd[1]: Stopping Load/Save Screen Backlight Brightness of backlight:acpi_video0...
May 01 05:27:09 thinknix unclutter[1200]: XIO:  fatal IO error 11 (Resource temporarily unavailable) on X server ":0.0"
May 01 05:27:09 thinknix unclutter[1200]:       after 11168 requests (11167 known processed) with 0 events remaining.
May 01 05:27:09 thinknix display-manager[912]: slim: unexpected signal 15
May 01 05:27:09 thinknix display-manager[912]: slim: connection to X server lost.
May 01 05:27:09 thinknix umount[31279]: umount: /run/user/1000: target is busy.
May 01 05:27:08 thinknix systemd[1137]: unclutter-xfixes.service: Main process exited, code=exited, status=1/FAILURE
May 01 05:27:09 thinknix dunst[1201]: XIO:  fatal IO error 11 (Resource temporarily unavailable) on X server ":0.0"
May 01 05:27:09 thinknix dunst[1201]:       after 1172 requests (1172 known processed) with 0 events remaining.
May 01 05:27:09 thinknix compton[1202]: serial 29875810: "BadDrawable (invalid Pixmap or Window parameter)"
May 01 05:27:09 thinknix compton[1202]: [ 441236.66 ] error  143 BadPicture   request  139 minor    8 serial 29875811: "RenderBadPicture (invalid Picture parameter)"
May 01 05:27:09 thinknix compton[1202]: [ 441236.67 ] error  143 BadPicture   request  139 minor    7 serial 29875925: "RenderBadPicture (invalid Picture parameter)"
May 01 05:27:09 thinknix compton[1202]: [ 441236.67 ] error    4 BadPixmap    request   54 minor    0 serial 29875926: "BadPixmap (invalid Pixmap parameter)"
May 01 05:27:09 thinknix compton[1202]: [ 468872.85 ] error    9 BadDrawable  request  139 minor    4 serial 31440841: "BadDrawable (invalid Pixmap or Window parameter)"
May 01 05:27:09 thinknix compton[1202]: [ 468872.85 ] error  143 BadPicture   request  139 minor    8 serial 31440842: "RenderBadPicture (invalid Picture parameter)"
May 01 05:27:09 thinknix compton[1202]: [ 468872.85 ] error  143 BadPicture   request  139 minor    7 serial 31440938: "RenderBadPicture (invalid Picture parameter)"
May 01 05:27:09 thinknix compton[1202]: [ 468872.85 ] error    4 BadPixmap    request   54 minor    0 serial 31440939: "BadPixmap (invalid Pixmap parameter)"
May 01 05:27:09 thinknix sshd[921]: Received signal 15; terminating.
May 01 05:27:09 thinknix systemd[1]: Unmounting Kernel Debug File System...
May 01 05:27:09 thinknix systemd[1]: Stopped Load Kernel Modules.
May 01 05:27:09 thinknix systemd[1137]: unclutter-xfixes.service: Failed with result 'exit-code'.
May 01 05:27:09 thinknix systemd[1]: Stopping Update UTMP about System Boot/Shutdown...
May 01 05:27:09 thinknix systemd[1]: Stopping SSH Daemon...
May 01 05:27:09 thinknix systemd[1]: Stopping Authorization Manager...
May 01 05:27:09 thinknix systemd[1137]: compton.service: Main process exited, code=exited, status=1/FAILURE
May 01 05:27:09 thinknix systemd[1137]: compton.service: Failed with result 'exit-code'.
May 01 05:27:09 thinknix systemd[1137]: dunst.service: Main process exited, code=exited, status=1/FAILURE
May 01 05:27:09 thinknix systemd[1137]: dunst.service: Failed with result 'exit-code'.
May 01 05:27:09 thinknix systemd[1]: Stopped S.M.A.R.T. Daemon.
May 01 05:27:09 thinknix systemd[1]: Stopped Thinkfan.
May 01 05:27:09 thinknix xsession[1144]: Exiting due to signal.
May 01 05:27:09 thinknix systemd[1]: Stopped SSH Daemon.
May 01 05:27:09 thinknix systemd[1]: Stopped Getty on tty1.
May 01 05:27:09 thinknix systemd[1]: Stopped CUPS Scheduler.
May 01 05:27:09 thinknix systemd[1]: Stopped WPA supplicant.
May 01 05:27:09 thinknix ..udiskie-wrapp[1203]: .udiskie-wrapped: Fatal IO error 11 (Resource temporarily unavailable) on X server :0.0.
May 01 05:27:09 thinknix xsession[1144]: 05:27:09 WARNING: The X11 connection broke: I/O error (code 1)
May 01 05:27:09 thinknix xsession[1144]: XIO:  fatal IO error 0 (Success) on X server ":0.0"
May 01 05:27:09 thinknix xsession[1144]:       after 448401 requests (448401 known processed) with 0 events remaining.
May 01 05:27:09 thinknix systemd[1]: Stopped Udisks2 service.
May 01 05:27:09 thinknix systemd[1]: Stopped Authorization Manager.
May 01 05:27:09 thinknix systemd[1137]: udiskie.service: Main process exited, code=exited, status=1/FAILURE
May 01 05:27:09 thinknix systemd[1137]: udiskie.service: Failed with result 'exit-code'.
May 01 05:27:09 thinknix systemd[1]: Stopped udev Kernel Device Manager.
May 01 05:27:09 thinknix .termite-wrappe[22580]: termite: Fatal IO error 11 (Resource temporarily unavailable) on X server :0.0.
May 01 05:27:09 thinknix systemd[1]: Stopped Network Time Synchronization.
May 01 05:27:09 thinknix python3[1199]: .clipster-wrapped: Fatal IO error 11 (Resource temporarily unavailable) on X server :0.0.
May 01 05:27:09 thinknix xsession[1144]: [libi3] libi3/font.c Using Pango font FontAwesome 8,Terminus, size 8
May 01 05:27:09 thinknix systemd[1]: run-user-1000.mount: Mount process exited, code=exited status=32

@guibou
Copy link
Contributor

guibou commented May 1, 2018

I have the same issue, with a similar locale issue in my log:

$ nixos-rebuild switch
building Nix...
building the system configuration...
perl: warning: Setting locale failed.
perl: warning: Please check that your locale settings:
	LANGUAGE = (unset),
	LC_ALL = (unset),
	LC_CTYPE = "en_US.UTF-8",
	LANG = "en_US.UTF-8"
    are supported and installed on your system.
perl: warning: Falling back to the standard locale ("C").
stopping the following units: accounts-daemon.service, acpid.service, audit.service, cpufreq.service, kmod-static-nodes.service, network-local-commands.service, network-manager.service, network-setup.service, nix-daemon.service, nix-daemon.socket, nscd.service, rngd.service, rtkit-daemon.service, system.slice, systemd-modules-load.service, systemd-sysctl.service, systemd-timesyncd.service, systemd-tmpfiles-clean.timer, systemd-tmpfiles-setup-dev.service, systemd-udev-settle.service, systemd-udev-trigger.service, systemd-udevd-control.socket, systemd-udevd-kernel.socket, systemd-udevd.service, upower.service

Most of the time it reboots directly, but sometimes I land to a broken tty.

This is highly similar to bug #18158 no?

(Edit: more details. I'm not using --upgrade and I'm on nixos-unstable channel, updated yesterday)

@ben0x539
Copy link
Contributor

ben0x539 commented May 3, 2018

Also getting this, nothing fancy with locales in my configuration. Here's some journal dumps:

May 03 23:43:48.233075 blah nix-daemon[19447]: accepted connection from pid 12154, user root (trusted)
May 03 23:43:48.696632 blah nixos[12174]: �[0;1;39m�[0;1;31m�[0;1;39mswitching to system configuration /nix/store/p7n90wcp81zllklm6alp8cbji4rdm4x0-nixos-system-blah-18.09pre138871.af55a0c3002�[0m
May 03 23:43:48.708244 blah systemd[1]: Stopping ACPI Daemon...
May 03 23:43:48.709783 blah systemd[1]: Stopping Kernel Auditing...
May 03 23:43:48.710548 blah systemd[1]: Stopping CUPS Remote Printer Discovery...
May 03 23:43:48.711504 blah systemd[1]: Stopped CPU Frequency Governor Setup.
May 03 23:43:48.712640 blah systemd[1]: Stopping Docker Application Container Engine...
May 03 23:43:48.712773 blah dockerd[2850]: time="2018-05-03T23:43:48.712731853+02:00" level=info msg="Processing signal 'terminated'"
May 03 23:43:48.713512 blah systemd[1]: Stopping Grafana Service Daemon...
May 03 23:43:48.748365 blah prometheus-start[2852]: time="2018-05-03T23:43:48+02:00" level=warning msg="Received SIGTERM, exiting gracefully..." source="main.go:236"
May 03 23:43:48.748365 blah prometheus-start[2852]: time="2018-05-03T23:43:48+02:00" level=info msg="See you next time!" source="main.go:243"
May 03 23:43:48.748365 blah prometheus-start[2852]: time="2018-05-03T23:43:48+02:00" level=info msg="Stopping target manager..." source="targetmanager.go:77"
May 03 23:43:48.748365 blah prometheus-start[2852]: time="2018-05-03T23:43:48+02:00" level=info msg="Target manager stopped." source="targetmanager.go:89"
May 03 23:43:48.748365 blah prometheus-start[2852]: time="2018-05-03T23:43:48+02:00" level=info msg="Stopping rule manager..." source="manager.go:388"
May 03 23:43:48.748365 blah prometheus-start[2852]: time="2018-05-03T23:43:48+02:00" level=info msg="Rule manager stopped." source="manager.go:394"
May 03 23:43:48.729492 blah avahi-daemon[2649]: Got SIGTERM, quitting.
May 03 23:43:48.753817 blah grafana-server[2709]: t=2018-05-03T23:43:48+0200 lvl=info msg="Shutdown started" logger=server code=0 reason="system signal: terminated"
May 03 23:43:48.753817 blah grafana-server[2709]: t=2018-05-03T23:43:48+0200 lvl=info msg="Stopped HTTP server" logger=http.server
May 03 23:43:48.753817 blah grafana-server[2709]: t=2018-05-03T23:43:48+0200 lvl=info msg="Stopped Stream Manager"
May 03 23:43:48.753817 blah grafana-server[2709]: t=2018-05-03T23:43:48+0200 lvl=info msg="Stopped Alerting" logger=alerting.engine reason="context canceled"
May 03 23:43:48.753817 blah grafana-server[2709]: t=2018-05-03T23:43:48+0200 lvl=info msg="Stopped Plugins" logger=plugins error="context canceled"
May 03 23:43:48.753817 blah grafana-server[2709]: t=2018-05-03T23:43:48+0200 lvl=info msg="Stopped CleanUpService" logger=cleanup reason="context canceled"
May 03 23:43:48.753817 blah grafana-server[2709]: t=2018-05-03T23:43:48+0200 lvl=info msg="Grafana shutdown completed." code=0
May 03 23:43:48.713984 blah systemd[1]: Stopped Create list of required static device nodes for the current kernel.
May 03 23:43:48.754735 blah nix-daemon[19447]: error: interrupted by the user
May 03 23:43:48.729546 blah avahi-daemon[2649]: Leaving mDNS multicast group on interface virbr0.IPv4 with address 192.168.122.1.
May 03 23:43:48.714614 blah systemd[1]: Stopping laptop-stats.service...
May 03 23:43:48.729574 blah avahi-daemon[2649]: Leaving mDNS multicast group on interface docker0.IPv4 with address 172.17.0.1.
May 03 23:43:48.756728 blah prometheus-start[2852]: time="2018-05-03T23:43:48+02:00" level=info msg="Stopping notification handler..." source="notifier.go:418"
May 03 23:43:48.756728 blah prometheus-start[2852]: time="2018-05-03T23:43:48+02:00" level=info msg="Stopping local storage..." source="storage.go:457"
May 03 23:43:48.756728 blah prometheus-start[2852]: time="2018-05-03T23:43:48+02:00" level=info msg="Stopping maintenance loop..." source="storage.go:459"
May 03 23:43:48.756728 blah prometheus-start[2852]: time="2018-05-03T23:43:48+02:00" level=info msg="Maintenance loop stopped." source="storage.go:1463"
May 03 23:43:48.756728 blah prometheus-start[2852]: time="2018-05-03T23:43:48+02:00" level=info msg="Stopping series quarantining..." source="storage.go:463"
May 03 23:43:48.756728 blah prometheus-start[2852]: time="2018-05-03T23:43:48+02:00" level=info msg="Series quarantining stopped." source="storage.go:1912"
May 03 23:43:48.756728 blah prometheus-start[2852]: time="2018-05-03T23:43:48+02:00" level=info msg="Stopping chunk eviction..." source="storage.go:467"
May 03 23:43:48.756728 blah prometheus-start[2852]: time="2018-05-03T23:43:48+02:00" level=info msg="Chunk eviction stopped." source="storage.go:1158"
May 03 23:43:48.756728 blah prometheus-start[2852]: time="2018-05-03T23:43:48+02:00" level=info msg="Checkpointing in-memory metrics and chunks..." source="persistence.go:633"
May 03 23:43:48.761402 blah 2a967llb7382gcxiag19zcl40bdr87gc-audit-stop[12231]: No rules
May 03 23:43:48.715650 blah systemd[1]: Stopped laptop-stats.service.
May 03 23:43:48.729595 blah avahi-daemon[2649]: Leaving mDNS multicast group on interface enp3s0f0.IPv4 with address 192.168.0.5.
May 03 23:43:48.765238 blah display-manager[2771]: slim: unexpected signal 15
May 03 23:43:48.766961 blah xsession[4650]: XIO:  fatal IO error 11 (Resource temporarily unavailable) on X server ":0.0"
May 03 23:43:48.766961 blah xsession[4650]:       after 1656552 requests (1656552 known processed) with 0 events remaining.
May 03 23:43:48.767687 blah pulseaudio[4922]: XIO:  fatal IO error 11 (Resource temporarily unavailable) on X server ":0.0"
May 03 23:43:48.767687 blah pulseaudio[4922]:       after 12 requests (6 known processed) with 0 events remaining.
May 03 23:43:48.770434 blah 2a967llb7382gcxiag19zcl40bdr87gc-audit-stop[12231]: enabled 0
May 03 23:43:48.770434 blah 2a967llb7382gcxiag19zcl40bdr87gc-audit-stop[12231]: failure 1
May 03 23:43:48.770434 blah 2a967llb7382gcxiag19zcl40bdr87gc-audit-stop[12231]: pid 0
May 03 23:43:48.770434 blah 2a967llb7382gcxiag19zcl40bdr87gc-audit-stop[12231]: rate_limit 0
May 03 23:43:48.770434 blah 2a967llb7382gcxiag19zcl40bdr87gc-audit-stop[12231]: backlog_limit 64
May 03 23:43:48.770434 blah 2a967llb7382gcxiag19zcl40bdr87gc-audit-stop[12231]: lost 0
May 03 23:43:48.770434 blah 2a967llb7382gcxiag19zcl40bdr87gc-audit-stop[12231]: backlog 0
May 03 23:43:48.770434 blah 2a967llb7382gcxiag19zcl40bdr87gc-audit-stop[12231]: backlog_wait_time 60000
May 03 23:43:48.716434 blah systemd[1]: Stopped target Local File Systems.
May 03 23:43:48.736076 blah avahi-daemon[2649]: avahi-daemon 0.7 exiting.
May 03 23:43:48.717401 blah systemd[1]: Stopped target All Network Interfaces (deprecated).
May 03 23:43:48.752458 blah sshd[3223]: Received signal 15; terminating.
May 03 23:43:48.718019 blah systemd[1]: Stopped Extra networking commands..
May 03 23:43:48.718259 blah cupsd[3838]: REQUEST localhost - - "POST / HTTP/1.1" 200 123 Cancel-Subscription client-error-not-found
May 03 23:43:48.785574 blah display-manager[2771]: slim: connection to X server lost.
May 03 23:43:48.718538 blah systemd[1]: Stopping Network Manager...
May 03 23:43:48.718625 blah cupsd[3838]: �[0;1;31m�[0;1;39m�[0;1;31m[Client 358] Request from "localhost" using invalid Host: field "[v1.::1]:631".�[0m
May 03 23:43:48.719411 blah systemd[1]: Stopped Networking Setup.
May 03 23:43:48.720047 blah systemd[1]: Stopping Nix Daemon...
May 03 23:43:48.721840 blah systemd[1]: Stopping Name Service Cache Daemon...
May 03 23:43:48.722538 blah systemd[1]: Stopping prometheus-node-exporter.service...
May 03 23:43:48.723203 blah systemd[1]: Stopping prometheus.service...
May 03 23:43:48.723682 blah systemd[1]: Stopped target Remote File Systems.
May 03 23:43:48.726525 blah systemd[1]: Stopped prometheus-node-exporter.service.
May 03 23:43:48.727114 blah systemd[1]: Stopping RealtimeKit Scheduling Policy Service...
May 03 23:43:48.728084 blah systemd[1]: Stopped CUPS Remote Printer Discovery.
May 03 23:43:48.729032 blah systemd[1]: Stopped Name Service Cache Daemon.
May 03 23:43:48.793485 blah umount[12263]: umount: /run/user/1000: target is busy.
May 03 23:43:48.729495 blah systemd[1]: Stopping Avahi mDNS/DNS-SD Stack...
May 03 23:43:48.729529 blah cupsd[3838]: Scheduler shutting down normally.
May 03 23:43:48.729534 blah systemd[1]: Stopping CUPS Scheduler...
May 03 23:43:48.732689 blah systemd[1]: Unmounting /run/keys...
May 03 23:43:48.732888 blah systemd[1]: Closed Load/Save RF Kill Switch Status /dev/rfkill Watch.
May 03 23:43:48.733911 blah systemd[1]: Unmounting /home/ben/keybase...
May 03 23:43:48.735604 blah systemd[1]: Stopping Load/Save Screen Backlight Brightness of backlight:acpi_video0...
May 03 23:43:48.736717 blah cupsd[3838]: Saving job.cache...
May 03 23:43:48.737489 blah systemd[1]: Stopping Load/Save Random Seed...
May 03 23:43:48.737808 blah systemd[1]: Unmounting /boot...
May 03 23:43:48.737877 blah systemd[1]: Stopped Apply Kernel Variables.
May 03 23:43:48.739020 blah systemd[1]: Closed /dev/initctl Compatibility Named Pipe.
May 03 23:43:48.739164 blah systemd[1]: Stopping Getty on tty1...
May 03 23:43:48.739433 blah systemd[1]: Unmounting FUSE Control File System...
May 03 23:43:48.740124 blah systemd[1]: Stopping Firewall...
May 03 23:43:48.740271 blah systemd[1]: Stopping Network Time Synchronization...
May 03 23:43:48.740603 blah systemd[1]: Unmounting Huge Pages File System...
May 03 23:43:48.740754 blah systemd[1]: Closed Virtual machine lock manager socket.
May 03 23:43:48.741648 blah systemd[1]: Stopping Update UTMP about System Boot/Shutdown...
May 03 23:43:48.741734 blah systemd[1]: Stopping Authorization Manager...
May 03 23:43:48.741780 blah systemd[1]: Stopping WPA supplicant...
May 03 23:43:48.741819 blah systemd[1]: Stopping udev Kernel Device Manager...
May 03 23:43:48.742442 blah systemd[1]: Unmounting /run/wrappers...
May 03 23:43:48.742698 blah systemd[1]: Unmounting POSIX Message Queue File System...
May 03 23:43:48.742812 blah systemd[1]: Closed Virtual machine log manager socket.
May 03 23:43:48.743355 blah systemd[1]: Unmounting Kernel Debug File System...
May 03 23:43:48.743985 blah systemd[1]: Unmounting /run/user/1000...
May 03 23:43:48.744026 blah systemd[1]: Stopped Mount ZFS filesystems.
May 03 23:43:48.744126 blah systemd[1]: Stopping SSH Daemon...
May 03 23:43:48.744203 blah systemd[1]: Stopping X11 Server...
May 03 23:43:48.802407 blah xsession[4650]: urxvt: X connection to ':0.0' broken, unable to recover, exiting.
May 03 23:43:48.749918 blah systemd[1]: Stopping Suspend/Resume Running libvirt Guests...
May 03 23:43:48.802630 blah xsession[4650]: urxvt: X connection to ':0.0' broken, unable to recover, exiting.
May 03 23:43:48.757079 blah systemd[1]: Stopped udev Kernel Device Manager.
May 03 23:43:48.802782 blah xsession[4650]: urxvt: X connection to ':0.0' broken, unable to recover, exiting.
May 03 23:43:48.760510 blah systemd[1]: Stopped Network Time Synchronization.
May 03 23:43:48.766496 blah systemd[1]: Stopped Avahi mDNS/DNS-SD Stack.
May 03 23:43:48.768163 blah systemd[1]: Stopped Grafana Service Daemon.
May 03 23:43:48.768449 blah .evolution-wrap[19768]: �[0;1;39m�[0;1;31m�[0;1;39mconnection_closed_cb: assertion 'connection != pconnection' failed�[0m
May 03 23:43:48.769434 blah systemd[1]: Stopped SSH Daemon.
May 03 23:43:48.770549 blah systemd[1]: Stopped Getty on tty1.
May 03 23:43:48.772247 blah systemd[1]: Stopped Authorization Manager.
May 03 23:43:48.773695 blah systemd[1]: Stopped WPA supplicant.
May 03 23:43:48.775035 blah systemd[1]: Stopped RealtimeKit Scheduling Policy Service.
May 03 23:43:48.778069 blah systemd[1]: �[0;1;39m�[0;1;31m�[0;1;39mnix-daemon.service: Main process exited, code=exited, status=1/FAILURE�[0m
May 03 23:43:48.778079 blah systemd[1]: �[0;1;39m�[0;1;31m�[0;1;39mnix-daemon.service: Failed with result 'exit-code'.�[0m
May 03 23:43:48.804369 blah xsession[4650]: urxvt: X connection to ':0.0' broken, unable to recover, exiting.
May 03 23:43:48.778753 blah systemd[1]: Stopped Nix Daemon.
May 03 23:43:48.780795 blah systemd[1]: Stopped Kernel Auditing.
May 03 23:43:48.783298 blah systemd[4635]: �[0;1;39m�[0;1;31m�[0;1;39mpulseaudio.service: Main process exited, code=exited, status=1/FAILURE�[0m
May 03 23:43:48.783461 blah systemd[4635]: �[0;1;39m�[0;1;31m�[0;1;39mpulseaudio.service: Failed with result 'exit-code'.�[0m
May 03 23:43:48.783522 blah systemd[1]: Unmounted /run/keys.
May 03 23:43:48.785148 blah systemd[1]: Unmounted /home/ben/keybase.
May 03 23:43:48.787300 blah systemd[1]: Stopped Load/Save Screen Backlight Brightness of backlight:acpi_video0.
May 03 23:43:48.790353 blah systemd[1]: Stopped Network Manager.
May 03 23:43:48.792325 blah systemd[1]: Stopped Load/Save Random Seed.
May 03 23:43:48.794538 blah systemd[1]: Unmounted /boot.
May 03 23:43:48.795473 blah systemd[1]: Unmounted FUSE Control File System.
May 03 23:43:48.796369 blah systemd[1]: Unmounted Huge Pages File System.
May 03 23:43:48.798337 blah systemd[1]: Unmounted /run/wrappers.
May 03 23:43:48.799390 blah systemd[1]: Unmounted POSIX Message Queue File System.
May 03 23:43:48.800411 blah systemd[1]: Unmounted Kernel Debug File System.
May 03 23:43:48.800741 blah systemd[1]: �[0;1;39m�[0;1;31m�[0;1;39mrun-user-1000.mount: Mount process exited, code=exited status=32�[0m
May 03 23:43:48.800753 blah systemd[1]: �[0;1;31m�[0;1;39m�[0;1;31mFailed unmounting /run/user/1000.�[0m
May 03 23:43:48.804655 blah systemd[1]: Stopped target Swap.
May 03 23:43:48.805650 blah systemd[1]: Deactivating swap /dev/blah/swap...
May 03 23:43:48.806327 blah systemd[1]: Removed slice system-systemd\x2dbacklight.slice.
May 03 23:43:48.806560 blah systemd[1]: Closed Nix Daemon Socket.
May 03 23:43:48.807645 blah systemd[1]: Stopping Permit User Sessions...
May 03 23:43:48.809561 blah systemd[1]: Removed slice system-getty.slice.
May 03 23:43:48.809810 blah systemd[1]: Closed Avahi mDNS/DNS-SD Stack Activation Socket.
May 03 23:43:48.809895 blah systemd[1]: Stopped Create Static Device Nodes in /dev.
May 03 23:43:48.814977 blah systemd[1]: Stopped Update UTMP about System Boot/Shutdown.
May 03 23:43:48.818161 blah systemd[1]: Unmounting /home/ben...
May 03 23:43:48.821899 blah systemd[1]: Stopped Firewall.
May 03 23:43:48.822391 blah systemd[1]: Stopped Load Kernel Modules.
May 03 23:43:48.823844 blah umount[12336]: umount: /home/ben: target is busy.
May 03 23:43:48.824035 blah systemd[1]: �[0;1;39m�[0;1;31m�[0;1;39mhome-ben.mount: Mount process exited, code=exited status=32�[0m
May 03 23:43:48.824052 blah systemd[1]: �[0;1;31m�[0;1;39m�[0;1;31mFailed unmounting /home/ben.�[0m
May 03 23:43:48.825757 blah systemd[1]: Unmounting /home...
May 03 23:43:48.826826 blah systemd[1]: Stopped Daily Cleanup of Temporary Directories.
May 03 23:43:48.832359 blah umount[12337]: umount: /home: target is busy.
May 03 23:43:48.833268 blah systemd[1]: �[0;1;39m�[0;1;31m�[0;1;39mhome.mount: Mount process exited, code=exited status=32�[0m
May 03 23:43:48.833287 blah systemd[1]: �[0;1;31m�[0;1;39m�[0;1;31mFailed unmounting /home.�[0m
May 03 23:43:48.874371 blah sudo[29655]: pam_unix(sudo:session): session closed for user root
May 03 23:43:48.875353 blah systemd[1]: Stopped Permit User Sessions.
May 03 23:43:48.882616 blah systemd[1]: Stopped CUPS Scheduler.
May 03 23:43:48.884623 blah systemd[1]: Stopped Create Volatile Files and Directories.
May 03 23:43:48.884701 blah systemd[1]: Stopped Flush Journal to Persistent Storage.
May 03 23:43:48.884754 blah systemd[1]: Stopped Remount Root and Kernel File Systems.
May 03 23:43:48.884917 blah systemd-journald[1883]: Journal stopped
�[0;1;39m-- Reboot --�[0m


At some point I ctrl-alt-del to reboot and that's not visible from those messages, probably because it says "journal stopped" at the end, but it's a bit confusing.

@lheckemann
Copy link
Member

Might be related to #38991 somehow after all?

@primeos
Copy link
Member

primeos commented May 11, 2018

Ok, I've managed to find the reason for this.

Due to an upstream change that removed the system.slice unit file (systemd/systemd@d8e5a93), switch-to-configuration.pl was stopping system.slice:

[...]
    if (-e $prevUnitFile && ($state->{state} eq "active" || $state->{state} eq "activating")) {
        if (! -e $newUnitFile || abs_path($newUnitFile) eq "/dev/null") {
            my $unitInfo = parseUnit($prevUnitFile);
            $unitsToStop{$unit} = 1 if boolIsTrue($unitInfo->{'X-StopOnRemoval'} // "yes");
        }
[...]

This is unfortunate but at least it means that this won't happen again.

@magnetophon
Copy link
Member Author

Great, thanks @primeos!
Would you like me to test this, and if so, how?

primeos added a commit that referenced this issue Jul 28, 2018
Problem: Restarting (stopping) system.slice would not only stop X11 but
also most system units/services. We obviously don't want this happening
to users when they switch from 18.03 to 18.09 or nixos-unstable.

Reason: The following change in systemd:
systemd/systemd@d8e5a93

The commit adds system.slice to the perpetual units, which means
removing the unit file and adding it to the source code. This is done so
that system.slice can't be stopped anymore but in our case it ironically
would cause this script to stop system.slice because the unit file was
removed (and an older systemd version is still running).

Related issue: #39791
primeos added a commit that referenced this issue Aug 1, 2018
Problem: Restarting (stopping) system.slice would not only stop X11 but
also most system units/services. We obviously don't want this happening
to users when they switch from 18.03 to 18.09 or nixos-unstable.

Reason: The following change in systemd:
systemd/systemd@d8e5a93

The commit adds system.slice to the perpetual units, which means
removing the unit file and adding it to the source code. This is done so
that system.slice can't be stopped anymore but in our case it ironically
would cause this script to stop system.slice because the unit file was
removed (and an older systemd version is still running).

Related issue: #39791

(cherry picked from commit 7098b0f)
Reason: Make sure that this problem wouldn't occur if we would update
the systemd version.
@primeos
Copy link
Member

primeos commented Aug 4, 2018

@magnetophon Sorry, I've completely forgotten to answer... :o There was no need to test it (but ofc it never hurts) but thanks for your offer :)

I initially thought that this wouldn't matter anymore but it turned out that 18.03 still has a unit file for system.slice (missed that when I initially checked it...). #43682 (also backported to 18.03) should prevent this problem from occurring again (when switching from 18.03 to 18.09). I'm closing this issue, if you don't mind, since it should be solved by now (at least for 18.03 -> 18.09/nixos-unstable).

@primeos primeos closed this as completed Aug 4, 2018
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

5 participants