The string 'Pinentry' is a module name, which is defined in libgpg-error.
It means, the error source is pinentry.

When an error is generated in pinentry, like at
https://git.gnupg.org/cgi-bin/gitweb.cgi?p=pinentry.git;a=blob;f=pinentry/pinentry-curses.c;h=f6c86b8ffa5c8aa143d6b3b85f4174b4d4c80bcf;hb=HEAD#l875

the error number from system (like ENOENT: No such file or directory) and the module name information are encoded into the type gpg_error_t.

Please check your environment variable GPG_TTY when you use pinentry-curses.

GPG_TTY in my tests from which I generated the logs above is set to /dev/pts/1 (which is what "tty" returns, what exists in the FS, and what is writable to the user which performs the test).

If I change to pinentry-tty (GPG_TTY still set as before), I get the same behavior.

If I simply call "pintentry-tty" or "pinentry-curses" without any options, the pinentry program starts...

What else to try/check?

Strange. pinentry-tty has no place to report ENOENT. I wonder if you notified gpg-agent when you change the config (like gpgconf --reload gpg-agent).

Anyway, please check your original /tmp/gpgagent.log, before the line

2022-02-02 11:57:15 gpg-agent[53192] DBG: chan_6 <- OK

There must be "connection to PIN entry established" line, and "OPTION" lines.
When GPG_TTY is configured correctly, it should have a line "OPTION ttyname=/dev/<somewhere>', and "OPTION ttytype=<terminaltype>". If none, there is another problem.

I killed gpg-agent after the config change / before running gpg again. That should be enough to pick-up the config change, correct? In the mean time the system in question was rebooted. Here the full log /with key related stuff redacted).

The original log is after a minute of running 29 MB big, filtering out the socket-errors strips it down to 12 KB.

Thank you for your debugging.

pinentry-tty tries to access /dev/pts/2 and fails.

What I see in the log are:

• Your version of pinentry is 1.1.1
• The path to tty in question is: /dev/pts/2
  • I wonder if it's correct one or not
• There is a log:

2022-02-04 07:33:36 gpg-agent[12918] DBG: chan_6 -> GETINFO ttyinfo
2022-02-04 07:33:36 gpg-agent[12918] DBG: chan_6 <- D /dev/pts/2 tmux-256color - ? 1001/1001 0

• ^-- this means (the info with ?) that pinentry cannot access with the path, for some reason (at pinentry/pinentry/pinentry.c:device_stat_string).
• I think that it fails fopening with the path.
  • then it gets SEGV, because of the bug of pinentry-tty
    • ... which was fixed in rP7f7fd8bcfd74: tty: Fix error return paths and its resource leaks. in 1.2.0

Yes, this was the correct tty at the time of the generation of this log.

What kind of debugging would be beneficial at that point? Or should I update to pinentry 1.2.0 and it will start to work?

As the above commit only references pinentry-tty.c, what's the problem with pinentry-curses? Shall I provide the same log with pinentry-curses?

The change of pinentry-tty rP7f7fd8bcfd74: tty: Fix error return paths and its resource leaks. fixes SEGV, but the problem of your case is that access to the device file (/dev/pts/2 in the case of your log with pinentry-tty) failed.

Please check (say, by typing ls -l /dev/pts/2 of the path to the device), when you do experiment to see what's going on.

That is:

• Do the experiment
• Check the log file to find GETINFO ttyinfo... line
• Next line, you should fine the path to the tty device.
• Do ls -l /dev/<something> to see the permission of the path

% export GPG_TTY=$(tty)

% echo $GPG_TTY
/dev/pts/2

% ls -l /dev/pts/2
crw--w---- 1 netchild tty 0x148 7 Feb. 11:56 /dev/pts/2

% id
uid=1001(netchild) gid=1001(netchild) groups=1001(netchild),0(wheel)

% gpg --edit-key xxxx
...

expire

...

% grep -2 GETINFO /tmp/gpgagent.log
...
2022-02-07 11:58:48 gpg-agent[13780] DBG: chan_6 -> GETINFO ttyinfo
2022-02-07 11:58:48 gpg-agent[13780] DBG: chan_6 <- D /dev/pts/2 tmux-256color - ? 1001/1001 0
...

Thank you for the debug information.

From other terminal, you can see /dev/pts/2, but it is not accessible from gpg-agent.
I don't know about such a situation... Is it in some jail environment?
If so, you need to mount /dev/pts in your jail environment.
Reference: https://forums.freebsd.org/threads/jails-in-freebsd-8-0.9403/

FYI: When you have a problem with pinentry, possible workaround is using gpg with --pinentry-mode=loopback, which redirects pinentry queries to the caller (instead of invoking pinentry session).

Yes, this is in a jail. But the output above was from the same shell session inside the jail. So gpg-agent was forked from gpg which I executed in the same shell (same process) as the ls. As you can see from the output of ls, /dev/pts is mounted there. The link you provided tells to mount the devfs inside the jail. This is the case here (that's basics, it needs to be there for a lot of things to work inside a jail).

On the other hand, if I replace pinentry with a shell-wrapper which does a ls of /dev/pts to a logfile, I see no files there. I will discuss this part with some people in FreeBSD-land and come back later about it.

The loopback option works. I get asked for the PW. In general: Is it advised that this option should be used for a gpg which is started via a webmail-interface from an http server, or should the default settings be OK in this case?

Regarding the numerous "accept failed for extra: Socket operation on non-socket": I disabled the extra socket and now it complains about the browser socket in the same way... I will investigate further there too.

You can close this ticket. It's a jail-specific behavior when the jail is entered from the host via command line (https://lists.freebsd.org/archives/freebsd-hackers/2022-February/000832.html for the curious people) and something is used which closes all FDs. When the jail is accessed via ssh, it works.

And the accept failed part can be ignored too, it's caused by a bug in parts of what I did to debug this.

Sorry for the noise.

Good to hear the cause.

Thank you sharing your experience, anyway.