envoy might cause X server to freeze/lock (processes are STOPped)

[blueyed]

I've seen it occasionally that the X server would appear to have frozen, usually when switching back to it (I am using two Xorg instances, through startx).

This happened occasionally and I could not reproduce it.

I am using envoy-exec in a script started from .xprofile, which runs in the background.

And now I've noticed that this also happens during login already when the gpg-agent.conf contains a non-existent entry for pinentry-program: pinentry-program /usr/bin/pinentry-qt4 (which recently moved to /usr/bin/pinentry-qt on Arch Linux).

I am using -t gpg-agent with envoy, via systemctl enable envoy@gpg-agent.socket.

[blueyed]

Closing this for now, it did not happen since a while anymore - I am using envoy-git currently (14.34.g963b231-1).

[blueyed]

I can somehow reproduce this using v14.

I have two X sessions on tty1 and tty2.

When pinentry is running (waiting for a passphrase) on tty1 and I trigger it on tty2, it will cause the "freezing" on tty2.

The symptom is that all programs started from ~/.xinitrc are in the "stopped" state (T in "ps aux", "stopped by job control signal").

gpg-agent's debug log in this case.

2015-12-25 15:00:49 gpg-agent[1328] ssh handler 0x7f1cfa5b2700 for fd 14 started
2015-12-25 15:00:49 gpg-agent[1328] ssh request handler for request_identities (11) started
2015-12-25 15:00:49 gpg-agent[1328] DBG: chan_15 <- OK GNU Privacy Guard's Smartcard server ready
2015-12-25 15:00:49 gpg-agent[1328] new connection to SCdaemon established
2015-12-25 15:00:49 gpg-agent[1328] DBG: chan_15 -> GETATTR $AUTHKEYID
2015-12-25 15:00:49 gpg-agent[1328] DBG: chan_15 <- ERR 100663404 Card error <SCD>
2015-12-25 15:00:49 gpg-agent[1328] no authentication key for ssh on card: Card error
2015-12-25 15:00:49 gpg-agent[1328] ssh request handler for request_identities (11) ready
2015-12-25 15:00:49 gpg-agent[1328] DBG: chan_15 -> BYE
2015-12-25 15:00:49 gpg-agent[1328] ssh handler 0x7f1cfa5b2700 for fd 14 terminated
2015-12-25 15:00:50 gpg-agent[1328] DBG: error calling pinentry: Operation cancelled <Pinentry>
2015-12-25 15:00:50 gpg-agent[1328] failed to unprotect the secret key: Operation cancelled
2015-12-25 15:00:50 gpg-agent[1328] failed to read the secret key
2015-12-25 15:00:50 gpg-agent[1328] ssh sign request failed: Operation cancelled <Pinentry>
2015-12-25 15:00:50 gpg-agent[1328] ssh request handler for sign_request (13) ready
2015-12-25 15:00:50 gpg-agent[1328] ssh handler 0x7f1cfa5b2700 for fd 9 started
2015-12-25 15:00:50 gpg-agent[1328] ssh request handler for request_identities (11) started
2015-12-25 15:00:50 gpg-agent[1328] DBG: chan_13 <- OK GNU Privacy Guard's Smartcard server ready
2015-12-25 15:00:50 gpg-agent[1328] new connection to SCdaemon established
2015-12-25 15:00:50 gpg-agent[1328] DBG: chan_13 -> GETATTR $AUTHKEYID
2015-12-25 15:00:50 gpg-agent[1328] DBG: chan_13 <- ERR 100663404 Card error <SCD>
2015-12-25 15:00:50 gpg-agent[1328] no authentication key for ssh on card: Card error
2015-12-25 15:00:50 gpg-agent[1328] ssh request handler for request_identities (11) ready
2015-12-25 15:00:51 gpg-agent[1328] ssh request handler for sign_request (13) started
2015-12-25 15:00:51 gpg-agent[1328] DBG: agent_get_cache '9BE66137959CA41A4EE8BD2F1FE01C0800F6D09A' (mode 4) ...
2015-12-25 15:00:51 gpg-agent[1328] DBG:   removed '9BE66137959CA41A4EE8BD2F1FE01C0800F6D09A' (mode 4) (slot not used for 30m)
2015-12-25 15:00:51 gpg-agent[1328] DBG: ... miss
2015-12-25 15:00:51 gpg-agent[1328] starting a new PIN Entry
2015-12-25 15:00:51 gpg-agent[1328] DBG: connection to PIN entry established
2015-12-25 15:00:51 gpg-agent[1328] DBG: agent_get_cache 'A648BB3BFD9B2779D1F79783A6A95D39ECB83437' (mode 4) ...
2015-12-25 15:00:51 gpg-agent[1328] DBG: ... miss

The last line I was seeing on tty2's X session when tailing the log:

2015-12-25 15:00:49 gpg-agent[1328] ssh handler 0x7f1cfa5b2700 for fd 14 terminated

I am using 2.1.10 on Arch Linux.

It might be related to this commit in Git, but not in v14: df61020fc0d299f66f4bc6e902d0d5dd3178d294.

gpg-agent or something else might cause this behavior in case stdin is not closed.

[blueyed]

It is still problematic with envoy-git, too - re-opening.

[blueyed]

I've experimented with commenting out calls to gpg_update_tty, after only commenting the call to gpg_send_message(gpg, "UPDATESTARTUPTTY\n");, and in both cases X "locked up" (processes get STOPped), through a script that uses envoy-exec.

In gpg-agent's log it looks like this:

2015-12-25 21:35:30 gpg-agent[1302] ssh handler 0x7f5adbfff700 for fd 8 started
2015-12-25 21:35:30 gpg-agent[1302] ssh request handler for request_identities (11) started
2015-12-25 21:35:30 gpg-agent[1302] DBG: chan_9 <- OK GNU Privacy Guard's Smartcard server ready
2015-12-25 21:35:30 gpg-agent[1302] new connection to SCdaemon established
2015-12-25 21:35:30 gpg-agent[1302] DBG: chan_9 -> GETATTR $AUTHKEYID
2015-12-25 21:35:30 gpg-agent[1302] DBG: chan_9 <- ERR 100663404 Card error <SCD>
2015-12-25 21:35:30 gpg-agent[1302] no authentication key for ssh on card: Card error
2015-12-25 21:35:30 gpg-agent[1302] ssh request handler for request_identities (11) ready
2015-12-25 21:35:30 gpg-agent[1302] ssh request handler for sign_request (13) started
2015-12-25 21:35:30 gpg-agent[1302] DBG: agent_get_cache 'A648BB3BFD9B2779D1F79783A6A95D39ECB83437' (mode 4) ...
2015-12-25 21:35:30 gpg-agent[1302] DBG: ... miss
2015-12-25 21:35:30 gpg-agent[1302] starting a new PIN Entry
2015-12-25 21:35:30 gpg-agent[1302] DBG: connection to PIN entry established
2015-12-25 21:35:30 gpg-agent[1302] DBG: error calling pinentry: Inappropriate ioctl for device <Pinentry>
2015-12-25 21:35:30 gpg-agent[1302] failed to unprotect the secret key: Inappropriate ioctl for device
2015-12-25 21:35:30 gpg-agent[1302] failed to read the secret key
2015-12-25 21:35:30 gpg-agent[1302] ssh sign request failed: Inappropriate ioctl for device <Pinentry>
2015-12-25 21:35:30 gpg-agent[1302] ssh request handler for sign_request (13) ready