[SOLVED] Xmonad aborts unexpectedly - Fatal IO error 11

drrossum · 2017-01-24 07:52:42

My X Server and tty session terminate when I print to a file that already exists in firefox. This is 100% reproducible. My system is up-to-date.

This is what I can find in logs related to the problem:
Xorg.0.log:

server :0..(II) Server terminated successfully (0). Closing log file. unable to recover, exiting.urxvt: X connection to ':0' broken, unable to recover, exiting.Gdk-Message: firefox: Fatal IO error 11 (Resource temporarily unavailable) on X

journalctl:

Jan 23 18:00:07 idefix pulseaudio[479]: XIO:  fatal IO error 11 (Resource temporarily unavailable) on X server ":0"
Jan 23 18:00:07 idefix pulseaudio[479]:       after 9 requests (8 known processed) with 0 events remaining.
Jan 23 18:00:07 idefix systemd[418]: pulseaudio.service: Main process exited, code=exited, status=1/FAILURE
Jan 23 18:00:07 idefix systemd[418]: pulseaudio.service: Unit entered failed state.
Jan 23 18:00:07 idefix systemd[418]: pulseaudio.service: Failed with result 'exit-code'.
Jan 23 18:00:08 idefix systemd[418]: pulseaudio.service: Service hold-off time over, scheduling restart.
Jan 23 18:00:08 idefix systemd[418]: Stopped Sound Service.
Jan 23 18:00:08 idefix systemd[418]: Starting Sound Service...
Jan 23 18:00:08 idefix rtkit-daemon[484]: Successfully made thread 602 of process 602 (/usr/bin/pulseaudio) owned by '2221' high priority at nice level -11.
Jan 23 18:00:08 idefix rtkit-daemon[484]: Supervising 1 threads of 1 processes of 1 users.
Jan 23 18:00:08 idefix pulseaudio[602]: W: [pulseaudio] pid.c: Stale PID file, overwriting.
Jan 23 18:00:08 idefix rtkit-daemon[484]: Supervising 1 threads of 1 processes of 1 users.
Jan 23 18:00:08 idefix rtkit-daemon[484]: Successfully made thread 603 of process 602 (/usr/bin/pulseaudio) owned by '2221' RT at priority 5.
Jan 23 18:00:08 idefix rtkit-daemon[484]: Supervising 2 threads of 1 processes of 1 users.
Jan 23 18:00:08 idefix rtkit-daemon[484]: Supervising 2 threads of 1 processes of 1 users.
Jan 23 18:00:08 idefix rtkit-daemon[484]: Successfully made thread 604 of process 602 (/usr/bin/pulseaudio) owned by '2221' RT at priority 5.
Jan 23 18:00:08 idefix rtkit-daemon[484]: Supervising 3 threads of 1 processes of 1 users.
Jan 23 18:00:08 idefix systemd[418]: Started Sound Service.
Jan 23 18:00:10 idefix login[386]: pam_unix(login:session): session closed for user me
Jan 23 18:00:10 idefix systemd[1]: getty@tty1.service: Service has no hold-off time, scheduling restart.
Jan 23 18:00:10 idefix systemd[1]: Stopped Getty on tty1.
Jan 23 18:00:10 idefix systemd[1]: Started Getty on tty1.
Jan 23 18:00:10 idefix systemd-logind[341]: Removed session c1.
Jan 23 18:00:10 idefix systemd[1]: Stopping User Manager for UID 2221...
Jan 23 18:00:10 idefix systemd[418]: Stopping Accessibility services bus...
Jan 23 18:00:10 idefix systemd[418]: Stopped target Default.
Jan 23 18:00:10 idefix systemd[418]: Stopping Sound Service...
Jan 23 18:00:10 idefix systemd[418]: Stopping GnuPG private key agent...
Jan 23 18:00:10 idefix systemd[418]: Stopping Virtual filesystem service...
Jan 23 18:00:10 idefix systemd[418]: Stopping D-Bus User Message Bus...
Jan 23 18:00:10 idefix systemd[418]: Stopped Accessibility services bus.
Jan 23 18:00:10 idefix systemd[418]: Stopped GnuPG private key agent.
Jan 23 18:00:10 idefix systemd[418]: Stopped D-Bus User Message Bus.
Jan 23 18:00:10 idefix systemd[418]: Stopped Sound Service.
Jan 23 18:00:10 idefix login[616]: pam_unix(login:session): session opened for user me by LOGIN(uid=0)
Jan 23 18:00:10 idefix systemd-logind[341]: New session c2 of user me.
Jan 23 18:00:10 idefix systemd[1]: Started Session c2 of user me.
Jan 23 18:00:10 idefix systemd[418]: Stopped Virtual filesystem service.
Jan 23 18:00:10 idefix systemd[418]: Stopped target Basic System.
Jan 23 18:00:10 idefix systemd[418]: Stopped target Paths.
Jan 23 18:00:10 idefix systemd[418]: Stopped target Sockets.
Jan 23 18:00:10 idefix systemd[418]: Closed Sound System.
Jan 23 18:00:10 idefix systemd[418]: Stopped target Timers.
Jan 23 18:00:10 idefix systemd[418]: Closed D-Bus User Message Bus Socket.
Jan 23 18:00:10 idefix systemd[418]: Reached target Shutdown.
Jan 23 18:00:10 idefix systemd[418]: Starting Exit the Session...
Jan 23 18:00:10 idefix systemd[418]: Received SIGRTMIN+24 from PID 624 (kill).
Jan 23 18:00:10 idefix systemd[420]: pam_unix(systemd-user:session): session closed for user me
Jan 23 18:00:10 idefix systemd[1]: Starting User Manager for UID 2221...
Jan 23 18:00:10 idefix systemd[628]: pam_unix(systemd-user:session): session opened for user me by (uid=0)
Jan 23 18:00:10 idefix systemd[628]: Reached target Paths.
Jan 23 18:00:10 idefix systemd[628]: Reached target Timers.
Jan 23 18:00:10 idefix systemd[628]: Starting D-Bus User Message Bus Socket.
Jan 23 18:00:10 idefix systemd[628]: Listening on Sound System.
Jan 23 18:00:10 idefix systemd[628]: Listening on D-Bus User Message Bus Socket.
Jan 23 18:00:10 idefix systemd[628]: Reached target Sockets.
Jan 23 18:00:10 idefix systemd[628]: Reached target Basic System.
Jan 23 18:00:10 idefix systemd[628]: Starting GnuPG private key agent...
Jan 23 18:00:10 idefix systemd[628]: Started GnuPG private key agent.
Jan 23 18:00:10 idefix systemd[628]: Reached target Default.
Jan 23 18:00:10 idefix systemd[628]: Startup finished in 13ms.
Jan 23 18:00:10 idefix systemd[1]: Started User Manager for UID 2221.
Jan 23 18:00:10 idefix login[616]: LOGIN ON tty1 BY me
Jan 23 18:00:10 idefix acpid[337]: client 457[2221:100] has disconnected
Jan 23 18:00:10 idefix acpid[337]: client connected from 666[2221:100]
Jan 23 18:00:10 idefix acpid[337]: 1 client rule loaded
Jan 23 18:00:11 idefix systemd[628]: Starting Sound Service...
Jan 23 18:00:11 idefix rtkit-daemon[484]: Successfully made thread 679 of process 679 (/usr/bin/pulseaudio) owned by '2221' high priority at nice level -11.
Jan 23 18:00:11 idefix rtkit-daemon[484]: Supervising 1 threads of 1 processes of 1 users.
Jan 23 18:00:11 idefix systemd[628]: Started D-Bus User Message Bus.
Jan 23 18:00:11 idefix rtkit-daemon[484]: Supervising 1 threads of 1 processes of 1 users.
Jan 23 18:00:11 idefix rtkit-daemon[484]: Successfully made thread 681 of process 679 (/usr/bin/pulseaudio) owned by '2221' RT at priority 5.
Jan 23 18:00:11 idefix rtkit-daemon[484]: Supervising 2 threads of 1 processes of 1 users.
Jan 23 18:00:11 idefix rtkit-daemon[484]: Supervising 2 threads of 1 processes of 1 users.

It looks like the pulseaudio service dies and systemd consequently starts a chain of correcting actions. It looks like there is a bug in firefox, that triggers a bug in pulseaudio, which is is not handled gracefully by the systemd services. Is that correct?

Can I prevent this chain of badness from happening by tweaking a systemd service file such as getty?

Last edited by drrossum (2017-01-24 12:51:30)

V1del · 2017-01-24 08:54:31

Your login session dies unexpectedly, you should look into that before you try to look at pulseaudio or getty. Are you on wayland? Maybe firefox or the print module tries to access X in an XWayland incompatible way. There have been similar issues with e.g. VLC's fullscreen overlay which also triggers a crash of the session.

drrossum · 2017-01-24 09:06:11

Thanks for pointing that out. I have changed the title accordingly. Advice on how to debug the login session is welcome!

I'll research this issue more to see what others find out about it.

No wayland here.

seth · 2017-01-24 11:58:08

The fatal I/O is a follow-up, firefox tries to talk to the gone X server.
What kind of session is that (kde, gnome, openbox, ...)?
Whatever is supposed to keep the session alive dies and then X just terminates (legally, it's not an X11 crash)

drrossum · 2017-01-24 12:05:43

I have no display manager. I use a getty service to login and run `exec startx` from the .bash_profile with XMonad as WM.

[Service]
ExecStart=
ExecStart=-/usr/bin/agetty --autologin me --noclear %I 38400 linux
TTYVTDisallocate=no

drrossum · 2017-01-24 12:30:09

seth wrote:

The fatal I/O is a follow-up, firefox tries to talk to the gone X server.

But printing to the same (existing) file from chromium or acroread does not trigger this error.

seth · 2017-01-24 12:32:34

and your xinitrc looks like?
but it's likely xmonad which is crashing: try to run an xterm instead, run xmonad from the xterm, try to cause the problem and see whether xmoad segfaults. then to get a core dump (in doubt run it in gdb)

edit: the line *triggers* nothing, it's an indication that an X11 clients fails to talk to the server (which the client could handle gracefully instead of crashing itself, though)

Last edited by seth (2017-01-24 12:34:10)

drrossum · 2017-01-24 12:49:25

seth wrote:

and your xinitrc looks like?
but it's likely xmonad which is crashing: try to run an xterm instead, run xmonad from the xterm, try to cause the problem and see whether xmoad segfaults. then to get a core dump (in doubt run it in gdb)

You were right, it was xmonad crashing. I had neglected to "xmonad --rebuild" after upgrading the xmonad and xmonad-contrib packages.

This topic describes the same bug I was running into.

Marking as solved. Thank you!

Last edited by drrossum (2017-01-24 15:05:21)

Arch Linux

#1 2017-01-24 07:52:42

[SOLVED] Xmonad aborts unexpectedly - Fatal IO error 11

#2 2017-01-24 08:54:31

Re: [SOLVED] Xmonad aborts unexpectedly - Fatal IO error 11

#3 2017-01-24 09:06:11

Re: [SOLVED] Xmonad aborts unexpectedly - Fatal IO error 11

#4 2017-01-24 11:58:08

Re: [SOLVED] Xmonad aborts unexpectedly - Fatal IO error 11

#5 2017-01-24 12:05:43

Re: [SOLVED] Xmonad aborts unexpectedly - Fatal IO error 11

#6 2017-01-24 12:30:09

Re: [SOLVED] Xmonad aborts unexpectedly - Fatal IO error 11

#7 2017-01-24 12:32:34

Re: [SOLVED] Xmonad aborts unexpectedly - Fatal IO error 11

#8 2017-01-24 12:49:25

Re: [SOLVED] Xmonad aborts unexpectedly - Fatal IO error 11

Board footer