[Pkg-privacy-maintainers] Bug#1069949: (regression) fatal: socket: Function not implemented

Sat Apr 27 13:26:39 BST 2024

Package: torsocks
Version: 2.4.0-1
Severity: important
Tags: upstream
X-Debbugs-Cc: debbug.torsocks at sideload.33mail.com

After upgrading from Bullseye to Bookworm, this is what happens in the
logs when sending a Tor-routed message:

(/var/log/mail.log)
===8<----------------------------------------
2024-04-25T13:10:25.165542+02:00 MannysHost postfix/smtpd[*]: connect from localhost[127.0.0.1]
2024-04-25T13:10:25.186729+02:00 MannysHost postfix/smtpd[*]: 2D6EFE313A: client=localhost[127.0.0.1]
2024-04-25T13:10:25.232021+02:00 MannysHost postfix/cleanup[*]: 2D6EFE313A: message-id=<timestamp.yadayada at MannysHost>
2024-04-25T13:10:25.236765+02:00 MannysHost postfix/qmgr[*]: 2D6EFE313A: from=<debbug.1069758 at sideload.33mail.com>, size=1181, nrcpt=1 (queue active)
2024-04-25T13:10:25.236875+02:00 MannysHost postfix/smtpd[*]: disconnect from localhost[127.0.0.1] ehlo=1 mail=1 rcpt=1 data=1 quit=1 commands=5
2024-04-25T13:10:25.298945+02:00 MannysHost postfix/smtp[*]: fatal: socket: Function not implemented
2024-04-25T13:10:26.357045+02:00 MannysHost postfix/smtp[*]: fatal: socket: Function not implemented
2024-04-25T13:10:27.444922+02:00 MannysHost postfix/smtp[*]: fatal: socket: Function not implemented
2024-04-25T13:10:28.533021+02:00 MannysHost postfix/smtp[*]: fatal: socket: Function not implemented
2024-04-25T13:10:29.636915+02:00 MannysHost postfix/smtp[*]: fatal: socket: Function not implemented
2024-04-25T13:10:30.694143+02:00 MannysHost postfix/smtp[*]: fatal: socket: Function not implemented
2024-04-25T13:10:31.808365+02:00 MannysHost postfix/smtp[*]: fatal: socket: Function not implemented
2024-04-25T13:10:32.921259+02:00 MannysHost postfix/smtp[*]: fatal: socket: Function not implemented
2024-04-25T13:10:34.026594+02:00 MannysHost postfix/smtp[*]: fatal: socket: Function not implemented
2024-04-25T13:10:35.140735+02:00 MannysHost postfix/smtp[*]: fatal: socket: Function not implemented
2024-04-25T13:10:36.234895+02:00 MannysHost postfix/smtp[*]: fatal: socket: Function not implemented
2024-04-25T13:10:37.352079+02:00 MannysHost postfix/smtp[*]: fatal: socket: Function not implemented
2024-04-25T13:10:38.440755+02:00 MannysHost postfix/smtp[*]: fatal: socket: Function not implemented
2024-04-25T13:10:39.549476+02:00 MannysHost postfix/smtp[*]: fatal: socket: Function not implemented
…
===8<----------------------------------------

This is what the log looked like in Bullseye just before the upgrade,
when sending over Tor still worked correctly:

(/var/log/mail.log)
===8<----------------------------------------
Apr 24 09:37:17 MannysHost postfix/postfix-script[2130]: refreshing the Postfix mail system
Apr 24 09:37:17 MannysHost postfix/master[1026]: reload -- version 3.5.24, configuration /etc/postfix
Apr 24 09:37:17 MannysHost postfix/postfix-script[2168]: refreshing the Postfix mail system
Apr 24 09:37:17 MannysHost postfix/master[1026]: reload -- version 3.5.24, configuration /etc/postfix
Apr 24 12:32:42 MannysHost postfix/submission/smtpd[27946]: connect from localhost[127.0.0.1]
Apr 24 12:32:42 MannysHost postfix/submission/smtpd[27946]: 3C344E3262: client=localhost[127.0.0.1]
Apr 24 12:32:42 MannysHost postfix/submission/cleanup/cleanup[27949]: 3C344E3262: message-id=<timestamp.yadayada at MannysHost>
Apr 24 12:32:42 MannysHost postfix/submission/smtpd[27946]: disconnect from localhost[127.0.0.1] ehlo=1 mail=1 rcpt=1 data=1 quit=1 commands=5
Apr 24 12:32:42 MannysHost postfix/qmgr[2173]: 3C344E3262: from=<manny’s at email.addy>, size=1126, nrcpt=1 (queue active)
Apr 24 12:32:50 MannysHost postfix/smtptor/smtp[27956]: 3C344E3262: to=<tor at recipient.addy>, relay=recipient.mx.server[1.2.3.4]:587, delay=8.1, delays=0.07/0.13/5.8/2.1, dsn=2.0.0, status=sent (250 OK id=yadayada)
===8<----------------------------------------

Sending over clearnet has no issues in any version. It’s only when a
message must go over the Tor network that there is a problem.

The configuration consists of the following:

(/etc/postfix/master.cf)
===8<----------------------------------------
# The syslog_name option is not needed. It can be set to
# anything. It’s just to add distinction in mail.log between clearnet
# and Tor mail (otherwise both kinds of transmission are prefixed as
# “postfix/smtp”).
#
smtptor      unix  -       -       n       -       -       smtp_tor
  -o smtp_address_preference=ipv4
  -o smtp_dns_support_level=disabled
  -o smtp_tls_security_level=none
  -o debug_peer_level=2
  -o syslog_name=postfix/smtptor
===8<----------------------------------------

(/usr/lib/postfix/sbin/smtp_tor)
===8<----------------------------------------
!/bin/bash

typeset -r dir_cmd=$(/usr/sbin/postconf -h command_directory)
typeset -r exec_smtp=$("$dir_cmd"/postconf -h daemon_directory)/smtp

setx_output()
{
    if [[ $1 ]]; then
        exec 4>>"$1"
        BASH_XTRACEFD=4
        PS4='\D{+%F}T\t $LINENO: '
        set -x
    else
        set +x
        #BASH_XTRACEFD=2
        exec 4>&-
    fi
}
setx_output /var/log/mail_${0##*/}.log

torsocks "$exec_smtp" "$@"

setx_output
===8<----------------------------------------

To setup routing, the transport db is used.

(/etc/postfix/tor_transport)
===8<----------------------------------------
…
.onion smtptor:
===8<----------------------------------------

(/etc/postfix/main.cf)
===8<----------------------------------------
…
transport_maps = regexp:/etc/postfix/tor_transport_regexp, hash:/etc/postfix/tor_transport, hash:/etc/postfix/transport
===8<----------------------------------------

This is what appears in the separate logfile for the smtp wrapper in
both the success and failure cases:

(/var/log/mail_smtp_tor.log)
===8<----------------------------------------
…
77: torsocks /usr/lib/postfix/sbin/smtp -n smtptor -t unix -u -o smtp_address_preference=ipv4 -o smtp_dns_support_level=disabled -o smtp_tls_security_level=none -o debug_peer_level=2 -o syslog_name=postfix/smtptor
===8<----------------------------------------

The fatal error began after upgrading to Bookworm. Two recent postfix
versions were tried in Bookworm. Then Postfix was downgraded back to
the known working version and the fatal error persisted. So the
sequence of tests went like this:

Debian release -- Postfix ver -- kernel ver -- torsocks ver -- state

Bullseye -- 3.5.24-0+deb11u1 -- 5.10.0-28 -- 2.3.0-3 -- worked (for years, likely spanning older versions as well)
Bookworm -- 3.7.10-0+deb12u1 -- 6.1.0-20  -- 2.4.0-1 -- fatal error
Bookworm -- 3.7.6-0+deb12u2  -- 6.1.0-20  -- 2.4.0-1 -- fatal error
Bookworm -- 3.5.24-0+deb11u1 -- 6.1.0-20  -- 2.4.0-1 -- fatal error
Bookworm -- 3.5.24-0+deb11u1 -- 5.10.0-28 -- 2.4.0-1 -- fatal error
Bookworm -- 3.5.24-0+deb11u1 -- 5.10.0-28 -- 2.3.0-3 -- works
Bookworm -- 3.7.10-0+deb12u1 -- 5.10.0-28 -- 2.3.0-3 -- works

It’s evident from all the combinations of versions that torsocks
version 2.4.0-1 is the problem, which must have been introduced after
version 2.3.0-3.

This is a catastrophic failure for four reasons:

① service is denied without workaround

② the bug is also very hard to detect because Postfix is the primary
suspect and the kernel was the 2nd most likely culprit for the given
clues. The log file showed “postfix/smtp” not “postfix/smtptor” in the
failure case, making it (falsely) appear as if Postfix was not even
running the Tor sending wrapper script. But the nature of the failure
causes Postfix to log the wrong syslog_name.  We also would not
quickly expect a relatively simple package like torsocks to cause this
failure. All of this made the bug hunt costly.

③ Postfix also does not behave well in this case. It reattempts to
send the message endlessly, copious times per second, causing log
files to be trashed with copious output.

④ Debugging Postfix is complex and cumbersome. You apparently cannot
simply run “torsocks smtp” on the commandline. The smtp program was
not designed for that and depends on other Postfix facilities to be in
place. So either complex stubs and drivers would be needed for testing
or we must resort to debugging using a mail client with all the
Postfix framework in play.

-- System Information:
Debian Release: 12.5
  APT prefers stable-updates
  APT policy: (990, 'stable-updates'), (990, 'stable-security'), (990, 'stable'), (500, 'oldstable')
Architecture: amd64 (x86_64)
Foreign Architectures: i386

Kernel: Linux 5.10.0-28-amd64 (SMP w/2 CPU threads)
Kernel taint flags: TAINT_OOT_MODULE, TAINT_UNSIGNED_MODULE
Locale: LANG=en_US.UTF-8, LC_CTYPE=en_US.UTF-8 (charmap=UTF-8), LANGUAGE not set
Shell: /bin/sh linked to /usr/bin/dash
Init: systemd (via /run/systemd/system)
LSM: AppArmor: enabled

Versions of packages torsocks depends on:
ii  libc6  2.36-9+deb12u6

Versions of packages torsocks recommends:
ii  tor  0.4.7.16-1

torsocks suggests no packages.

-- no debconf information