I have an application that makes use of GPG. The version details are below
GPG version :
gpg (GnuPG) 2.1.18 libgcrypt 1.7.6-beta
OS version
cat /etc/os-release PRETTY_NAME="Debian GNU/Linux 9 (stretch)" NAME="Debian GNU/Linux" VERSION_ID="9" VERSION="9 (stretch)" VERSION_CODENAME=stretch ID=debian HOME_URL="https://www.debian.org/" SUPPORT_URL="https://www.debian.org/support" BUG_REPORT_URL="https://bugs.debian.org/"
The application runs fine majority of the times but once in a while, I get IPC Connect call failed error, which causes my application to terminate.
After reading many forums and articles, I added the below lines to my gpg-agent.conf file, and added "--debug-all -vvv" to my gpg command.
Contents of gpg-agent.conf
allow-loopback-pinentry log-file /usr/local/testuser/var/agent.log debug-pinentry debug all verbose
The gpg command execution logs are below
02/02/2022 9:00:21 PM gpg: can't connect to the agent: IPC connect call failed 02/02/2022 9:00:21 PM gpg: waiting for the agent to come up ... (5s) 02/02/2022 9:00:21 PM gpg: no running gpg-agent - starting '/usr/bin/gpg-agent' 02/02/2022 9:00:21 PM gpg: DBG: [not enabled in the source] keydb_get_keyblock leave 02/02/2022 9:00:21 PM gpg: DBG: iobuf-2.0: close '?' 02/02/2022 9:00:21 PM gpg: DBG: parse_packet(iob=2): type=6 length=397 (parse.../../g10/keydb.c.1177) 02/02/2022 9:00:21 PM gpg: DBG: [not enabled in the source] keydb_get_keybock enter 02/02/2022 9:00:21 PM gpg: DBG: [not enabled in the source] keydb_search leave (found) 02/02/2022 9:00:21 PM gpg: DBG: keydb_search: searched keybox (resource 0 of 1) => Success 02/02/2022 9:00:21 PM gpg: DBG: keydb_search: searching keybox (resource 0 of 1) 02/02/2022 9:00:21 PM gpg: DBG: keydb: kid_not_found_p (67647d7ee3fc3b39) => indeterminate 02/02/2022 9:00:21 PM gpg: DBG: keydb_search 0: LONG_KID: '67647D7EE3FC3B39' 02/02/2022 9:00:21 PM gpg: DBG: keydb_search: 1 search descriptions: 02/02/2022 9:00:21 PM gpg: DBG: [not enabled in the source] keydb_search enter 02/02/2022 9:00:21 PM gpg: DBG: [not enabled in the source] keydb_new 02/02/2022 9:00:21 PM gpg: public key is 67647D7EE3FC3B39 02/02/2022 9:00:21 PM :pubkey enc packet: version 3 02/02/2022 9:00:21 PM # off=0 ctb=85 tag=1 hlen=3 plen=396 02/02/2022 9:00:21 PM gpg: DBG: parse_packet(iob=1): type=1 length=396 (parse.../../g10/mainproc.c.1351) 02/02/2022 9:00:21 PM gpg: DBG: iobuf-1.0: A->FILTER() returned rc=0 (ok) 02/02/2022 9:00:21 PM gpg: DBG: iobuf-1.0: underflow: A->FILTER (8192 bytes) 02/02/2022 9:00:21 PM gpg: DBG: iobuf-1.0: underflow: buffer size: 8192; still buffered: 0 => space for 8192 bytes 02/02/2022 9:00:21 PM gpg: DBG: iobuf-1.0: open '/usr/local/…./gpg_test_Support_txt_20220203030016a.gpg' desc=file_filter(fd) fd=3 02/02/2022 9:00:21 PM gpg: DBG: fd_cache_open (/usr/local/…./gpg_test_Support_txt_20220203030016a.gpg) not cached 02/02/2022 9:00:21 PM gpg: DBG: [not enabled in the source] start 02/02/2022 9:00:21 PM gpg: enabled debug flags: packet mpi crypto filter iobuf memory cache memstat trust hashing ipc clock lookup extprog 02/02/2022 9:00:21 PM gpg: using character set 'utf-8' 02/02/2022 9:00:21 PM gpg: reading options from '/home/testuser/.gnupg/gpg.conf' 02/02/2022 9:00:16 PM Start loading file 'gpg --no-tty --passphrase <redacted> --recipient<redacted> --debug-all -vvv --decrypt "/usr/local/…./gpg_test_Support_txt_20220203030016a.gpg"'
And at the contents of agent.log file is below for that same time.
2022-02-02 21:00:16 gpg-agent[103205] listening on socket '/run/user/1008/gnupg/S.gpg-agent' 2022-02-02 21:00:16 gpg-agent[103205] listening on socket '/run/user/1008/gnupg/S.gpg-agent.extra' 2022-02-02 21:00:16 gpg-agent[103205] listening on socket '/run/user/1008/gnupg/S.gpg-agent.browser' 2022-02-02 21:00:16 gpg-agent[103205] listening on socket '/run/user/1008/gnupg/S.gpg-agent.ssh' 2022-02-02 21:00:16 gpg-agent[103213] gpg-agent (GnuPG) 2.1.18 started 2022-02-02 21:00:16 gpg-agent[103213] socket file has been removed - shutting down 2022-02-02 21:00:16 gpg-agent[103213] gpg-agent (GnuPG) 2.1.18 stopped
Now if I check my gpg-agent, it's running just fine and simply rerunning my application to decrypt the file runs fine utilizing the same gpg-agent below. See process id below 23987.
testuser 23987 1 0 Feb01 ? 00:00:10 gpg-agent --homedir /home/testuser/.gnupg --use-standard-socket --daemon
The problem appears to be something to do with the sockets.
When I first started my gpg-agent, it used sockets under /home/testuser/.gnupg but when the "IPC connect call failed" error happens, it seems as if it's trying to use a socket under "/run/user/1008/gnupg", where 1008 is the uid of the user testuser.
2022-02-01 16:54:36 gpg-agent[23986] listening on socket '/home/testuser/.gnupg/S.gpg-agent' 2022-02-01 16:54:36 gpg-agent[23986] listening on socket '/home/testuser/.gnupg/S.gpg-agent.extra' 2022-02-01 16:54:36 gpg-agent[23986] listening on socket '/home/testuser/.gnupg/S.gpg-agent.browser' 2022-02-01 16:54:36 gpg-agent[23986] listening on socket '/home/testuser/.gnupg/S.gpg-agent.ssh' 2022-02-02 21:00:16 gpg-agent[103205] listening on socket '/run/user/1008/gnupg/S.gpg-agent' 2022-02-02 21:00:16 gpg-agent[103205] listening on socket '/run/user/1008/gnupg/S.gpg-agent.extra' 2022-02-02 21:00:16 gpg-agent[103205] listening on socket '/run/user/1008/gnupg/S.gpg-agent.browser' 2022-02-02 21:00:16 gpg-agent[103205] listening on socket '/run/user/1008/gnupg/S.gpg-agent.ssh'
**Do we know why gpg-agent would randomly want to consider itself "not started", and in attempts to try to start, it's starting up trying to use sockets under "/run/user" directory?
Many thanks in advance for help.