Bug#1050196: exim4: EBADF when looking up .forward files

[Erik Hulsmann]

Package: exim4
Version: 4.96-19
Severity: important

Dear Maintainer,

we've got a setup with users' .forward files.
Handling these seems broken to me - strace shows this:


655935 11:50:46.645218 newfstatat(AT_FDCWD, "/home/XXXXX/.forward",
{st_mode=S_IFREG|0644, st_size=26, ...}, 0) = 0
Pipe gets opened:
655935 11:50:46.645335 pipe2([12, 13], 0) = 0
655935 11:50:46.645450 rt_sigaction(SIGCHLD, {sa_handler=SIG_DFL,
sa_mask=[CHLD], sa_flags=SA_RESTORER|SA_RESTART,
sa_restorer=0x7f7f94347510}, {sa_handler=SIG_DFL, sa_mask=[],
sa_flags=SA_RESTORER, sa_restorer=0x7f7f94347510}, 8) = 0
Parent closes newly allocated FD 12:
655935 11:50:46.645565 close(12) = 0
655935 11:50:46.645698 close(10) = 0
655935 11:50:46.645810 close(11) = 0
fork:
655935 11:50:46.645922 clone(child_stack=NULL,
flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD,
child_tidptr=0x7f7f93135c90) = 655936
655936 11:50:46.646714 set_robust_list(0x7f7f93135ca0, 24 <unfinished
...>
Parent closes FD 13:
655935 11:50:46.646753 close(13 <unfinished ...>
655936 11:50:46.646783 <... set_robust_list resumed> ) = 0
655935 11:50:46.646815 <... close resumed> ) = 0
655935 11:50:46.646900 read(12, <unfinished ...>
655936 11:50:46.646935 close(12 <unfinished ...>
FD is invalid in parent:
655935 11:50:46.646965 <... read resumed> 0x7ffd9f73b810, 4) = -1 EBADF
(Bad file descriptor)
655936 11:50:46.646997 <... close resumed> ) = -1 EBADF (Bad file
descriptor)
655936 11:50:46.647091 fcntl(13, F_GETFD <unfinished ...>
655935 11:50:46.647126 wait4(-1, <unfinished ...>
655936 11:50:46.647157 <... fcntl resumed> ) = 0
655936 11:50:46.647217 fcntl(13, F_SETFD, FD_CLOEXEC) = 0
655936 11:50:46.647336 geteuid() = 0
655936 11:50:46.647433 getegid() = 103
655936 11:50:46.647529 setgid(1407) = 0
655936 11:50:46.647629 setuid(1407) = 0
655936 11:50:46.647872 openat(AT_FDCWD, "/home/XXXXX/.forward",
O_RDONLY) = 10
655936 11:50:46.648021 newfstatat(10, "", {st_mode=S_IFREG|0644,
st_size=26, ...}, AT_EMPTY_PATH) = 0
655936 11:50:46.648146 newfstatat(10, "", {st_mode=S_IFREG|0644,
st_size=26, ...}, AT_EMPTY_PATH) = 0
655936 11:50:46.648290 read(10, ".......\n", 4096) = 26
655936 11:50:46.648409 close(10) = 0
FD is invalid in child as well:
655936 11:50:46.648549 write(13, "\1\0\0\0", 4) = -1 EPIPE (Broken
pipe)
655936 11:50:46.648662 --- SIGPIPE {si_signo=SIGPIPE, si_code=SI_USER,
si_pid=655936, si_uid=1407} ---
655936 11:50:46.648719 close(13) = 0
655936 11:50:46.648835 exit_group(0) = ?
655936 11:50:46.649272 +++ exited with 0 +++
655935 11:50:46.649341 <... wait4 resumed> [{WIFEXITED(s) &&
WEXITSTATUS(s) == 0}], 0, NULL) = 655936
655935 11:50:46.649438 --- SIGCHLD {si_signo=SIGCHLD,
si_code=CLD_EXITED, si_pid=655936, si_uid=1407, si_status=0, si_utime=0,
si_stime=0} ---
655935 11:50:46.649532 gettimeofday({tv_sec=1689940246,
tv_usec=649575}, NULL) = 0
655935 11:50:46.649717 newfstatat(AT_FDCWD, "/etc/localtime",
{st_mode=S_IFREG|0644, st_size=114, ...}, 0) = 0
655935 11:50:46.649889 newfstatat(AT_FDCWD, "/var/log/exim4/mainlog",
{st_mode=S_IFREG|0640, st_size=316972, ...}, 0) = 0
655935 11:50:46.650019 write(4, "2023-07-21 11:50:46 1qM2Sk-00HTHZ-2F
internal problem in userforward router (recipient is
XX...@common-lisp.net): failure to transfer data from subprocess:
status=0000 readerror='Bad file descriptor'\n", 202) = 202
655935 11:50:46.650723 write(2, "2023-07-21 11:50:46 1qM2Sk-00HTHZ-2F
internal problem in userforward router (recipient is
XX...@common-lisp.net): failure to transfer data from subprocess:
status=0000 readerror='Bad file descriptor'\n", 202) = 202

Looks like a definite bug to me.


-- Package-specific info:
Exim version 4.96 #2 built 11-Jun-2023 16:20:21
Copyright (c) University of Cambridge, 1995 - 2018
(c) The Exim Maintainers and contributors in ACKNOWLEDGMENTS file, 2007
- 2022
Berkeley DB: Berkeley DB 5.3.28: (September 9, 2013)
Support for: crypteq iconv() IPv6 PAM Perl Expand_dlfunc GnuTLS
TLS_resume move_frozen_messages Content_Scanning DANE DKIM DNSSEC Event
I18N OCSP PIPECONNECT PRDR PROXY Queue_Ramp SOCKS SPF SRS TCP_Fast_Open
Lookups (built-in): lsearch wildlsearch nwildlsearch iplsearch cdb dbm
dbmjz dbmnz dnsdb dsearch ldap ldapdn ldapm mysql nis nis0 passwd pgsql
sqlite
Authenticators: cram_md5 cyrus_sasl dovecot external plaintext spa tls
Routers: accept dnslookup ipliteral iplookup manualroute queryprogram
redirect
Transports: appendfile/maildir/mailstore/mbx autoreply lmtp pipe smtp
Malware: f-protd f-prot6d drweb fsecure sophie clamd avast sock cmdline
Fixed never_users: 0
Configure owner: 0:0
Size of off_t: 8
Configuration file search path is
/etc/exim4/exim4.conf:/var/lib/exim4/config.autogenerated
Configuration file is /etc/exim4/exim4.conf

-- System Information:
Debian Release: 9.13
APT prefers oldoldstable
APT policy: (990, 'oldoldstable'), (500, 'stable-security'), (500,
'oldstable-security'), (500, 'testing'), (500, 'stable'), (500,
'oldstable')
merged-usr: no
Architecture: amd64 (x86_64)

Kernel: Linux 5.10.0-10-amd64 (SMP w/3 CPU threads)
Locale: LANG=en_US.utf8, LC_CTYPE=en_US.utf8 (charmap=UTF-8), LANGUAGE
not set
Shell: /bin/sh linked to /bin/dash
Init: systemd (via /run/systemd/system)

Versions of packages exim4 depends on:
pn debconf | cdebconf
<none>
pn debconf | debconf-2.0
<none>
pn exim4-base
<none>
pn exim4-daemon-light | exim4-daemon-heavy | exim4-daemon-custom
<none>

exim4 recommends no packages.

exim4 suggests no packages.

-- debconf information:
exim4/drec:



-- System Information:
Debian Release: bookworm/sid
APT prefers jammy-updates
APT policy: (500, 'jammy-updates'), (500, 'jammy-security'), (500, 'jammy-proposed'), (500, 'jammy'), (500, 'focal-updates')
Architecture: amd64 (x86_64)
Foreign Architectures: i386

Kernel: Linux 6.2.0-10018-tuxedo (SMP w/16 CPU threads; PREEMPT)
Kernel taint flags: TAINT_WARN, TAINT_OOT_MODULE, TAINT_UNSIGNED_MODULE
Locale: LANG=en_US.UTF-8, LC_CTYPE=en_US.UTF-8 (charmap=UTF-8), LANGUAGE=en_US
Shell: /bin/sh linked to /usr/bin/dash
Init: systemd (via /run/systemd/system)
LSM: AppArmor: enabled

Versions of packages exim4 depends on:
ii debconf [debconf-2.0] 1.5.79ubuntu1
pn exim4-base <none>
pn exim4-daemon-light | exim4-daemon-heavy | exim4-daemon-custo <none>

exim4 recommends no packages.

exim4 suggests no packages.

[Andreas Metzler]

On 2023-08-21 Erik Hulsmann <ehu...@gmail.com> wrote:
> Package: exim4
> Version: 4.96-19
> Severity: important

> Dear Maintainer,

> we've got a setup with users' .forward files.
> Handling these seems broken to me - strace shows this:

[...]

Hello,

is thisv reproducible for you? What do the logfiles say for this
delivery? Can you tell me more about the forward files, are they
exim-filter ones or classic ones?

For debugging I just used

| logger

as .forward and ended up with the expected in mainlog
2023-08-22 10:10:58 1qYMTa-0000Vw-05 <= amet...@bebt.de H=localhost (argenau.bebt.de) [::1] P=esmtps X=TLS1.3:ECDHE_X25519__ECDSA_SECP256R1_SHA256__AES_256_GCM:256 CV=no S=531 id=2023082210...@argenau.bebt.de
2023-08-22 10:10:58 1qYMTa-0000Vw-05 => | logger <ametzler@localhost> R=userforward T=address_pipe
2023-08-22 10:10:58 1qYMTa-0000Vw-05 Completed

and journal
Aug 22 10:10:58 argenau ametzler[1984]: From amet...@bebt.de Tue Aug 22 10:10:58 2023
Aug 22 10:10:58 argenau ametzler[1984]: Received: from localhost ([::1] helo=argenau.bebt.de)
[...]

cu Andreas

--
`What a good friend you are to him, Dr. Maturin. His other friends are
so grateful to you.'
`I sew his ears on from time to time, sure'

[Erik Huelsmann]

Hi Andreas,

On Tue, Aug 22, 2023 at 10:17 AM Andreas Metzler <amet...@bebt.de> wrote:

is thisv reproducible for you?

Yes.

 

What do the logfiles say for this delivery?

$ zgrep 1qTkmU-00F3DW-2D /var/log/exim4/mainlog*
/var/log/exim4/mainlog.10.gz:2023-08-13 00:10:02 1qTkmU-00F3DW-2D internal problem in userforward router (recipient is ehuel...@common-lisp.net): failure to transfer data from subprocess: status=0000 readerror='Bad file descriptor'

 

Can you tell me more about the forward files, are they
exim-filter ones or classic ones?

$ cat /home/ehuelsmann/.forward
ehu...@gmail.com

 

For debugging I just used

| logger

as .forward and ended up with the expected in mainlog
2023-08-22 10:10:58 1qYMTa-0000Vw-05 <= amet...@bebt.de H=localhost (argenau.bebt.de) [::1] P=esmtps X=TLS1.3:ECDHE_X25519__ECDSA_SECP256R1_SHA256__AES_256_GCM:256 CV=no S=531 id=2023082210...@argenau.bebt.de
2023-08-22 10:10:58 1qYMTa-0000Vw-05 => | logger <ametzler@localhost> R=userforward T=address_pipe
2023-08-22 10:10:58 1qYMTa-0000Vw-05 Completed

and journal
Aug 22 10:10:58 argenau ametzler[1984]: From amet...@bebt.de Tue Aug 22 10:10:58 2023
Aug 22 10:10:58 argenau ametzler[1984]: Received: from localhost ([::1] helo=argenau.bebt.de)
[...]

Thanks. There's nothing specific in the "journalctl" data. The logs from mainlog were included above.

By the way, this happens to a whole slew of users, not just this one.

Regards,

Erik.

[Andreas Metzler]

On 2023-08-23 Erik Huelsmann <ehu...@gmail.com> wrote:
> On Tue, Aug 22, 2023 at 10:17 AM Andreas Metzler <amet...@bebt.de> wrote:

[...]

>> What do the logfiles say for this delivery?

> $ zgrep 1qTkmU-00F3DW-2D /var/log/exim4/mainlog*
> /var/log/exim4/mainlog.10.gz:2023-08-13 00:10:02 1qTkmU-00F3DW-2D internal
> problem in userforward router (recipient is ehuel...@common-lisp.net):
> failure to transfer data from subprocess: status=0000 readerror='Bad file
> descriptor'

That is just the mainlog. Is something in paniclog? A nearby entry
without m-id?

> > Can you tell me more about the forward files, are they
> > exim-filter ones or classic ones?

> $ cat /home/ehuelsmann/.forward
> ehu...@gmail.com

[...]

Looks like there is something really broken there. Is exim still SUID,
did you perhaps configure a apparmor policy?