On 14/05/20 01:40 -0400, Viktor Dukhovni wrote:
I'f you're comfortable with gdb, and willing to build both Postfix and
OpenSSL from source with debugging symbols, then you could add a "-D"
flag to the "smtpd" entry in the /opt/postfix/etc/master.cf file, and
attach to a "screen" running a debugger on smtpd, setting a breakpoint
in SSL_shutdown, and continue. Then report a stack trace...
The plot thickens.
In a nutshell, the problem is "solved" by changing the virtual(8) hosts
to use UNIX domain sockets (rather than e.g. 127.0.0.1). In both cases,
the connection settings are for a local PostgreSQL database.
While debugging in gdb, I noticed that when it would break on
SSL_shutdown, the backtrace showed a bunch of pgsql stuff. Twice in
a row, always. Once I continued past both SSL_shutdown breaks, it
wouldn't break again on that function (and smtpd would log the "usual"
'TLS library problem' about SSL_shutdown:shutdown while in init).
I thought this strange, and so I changed my approach to break on the
filename/lineno combo (in my case, ssl/ssl_lib.c:2086). Same thing.
So I set about quickly removing the perceived strangeness by changing
the virtual(8) hosts values to use local sockets. Once I made this
change, I went back to debugging the SSL_shutdown context, but the
problem was gone.
It's only been an hour, but as there has been no disruption to mail
delivery due to the 'SSL_shutdown:shutdown while in init' issue as
several emails have come and gone, I wanted to report these findings
because they're quite strange.
This has 'fixed' the issue for me for both sending and
receiving.
So, this turn of events seems to indict some facet of the postgres
apparatus. I did get a backtrace of SSL_shutdown as invoked by the
postgres component, but I hadn't yet put debug symbols on the table for
that piece of it, so there are some unresolved symbols. Maybe it's
useful. It's attached.
At this point, I'd like to get postfix back to TCP connections to pgsql,
so I'm going to try juggling versions of buster's postfix-pgsql to see
if the issue lay there.
On 14/05/20 08:06 -0400, Scott Kitterman wrote:
Debian automatically builds debug symbol packages for ~all packages. They are
located in a separate package repository. For instructions on how to enable
it and install them, see:
This was helpful and saved me a lot of time. Thanks.
Alexander
Breakpoint 1, SSL_shutdown (s=0x55aa36c6b630) at ../ssl/ssl_lib.c:2060
2060 ../ssl/ssl_lib.c: No such file or directory.
#0 SSL_shutdown (s=0x55aa36c6b630) at ../ssl/ssl_lib.c:2060
#1 0x00007f3bc7b9c33d in ?? () from /usr/lib/x86_64-linux-gnu/libpq.so.5
#2 0x00007f3bc7b9c4a0 in ?? () from /usr/lib/x86_64-linux-gnu/libpq.so.5
#3 0x00007f3bc7b84410 in PQconnectPoll () from
/usr/lib/x86_64-linux-gnu/libpq.so.5
#4 0x00007f3bc7b851cf in ?? () from /usr/lib/x86_64-linux-gnu/libpq.so.5
#5 0x00007f3bc7b882e5 in PQsetdbLogin () from
/usr/lib/x86_64-linux-gnu/libpq.so.5
#6 0x00007f3bca539d35 in ?? () from /usr/lib/postfix/postfix-pgsql.so
#7 0x00007f3bca56e934 in dict_utf8_lookup (dict=0x55aa36c2a480,
key=0x55aa36c69d20 "<data scrubbed>") at dict_utf8.c:160
#8 0x00007f3bca5a48c5 in maps_find (maps=maps@entry=0x55aa36c07510,
name=0x55aa36c69d20 "<data scrubbed>", flags=flags@entry=0) at maps.c:195
#9 0x00007f3bca59f853 in find_addr (path=path@entry=0x55aa36c07510,
address=address@entry=0x55aa36c69e60 "<data scrubbed>", flags=flags@entry=0,
with_domain=with_domain@entry=1, query_form=query_form@entry=3,
ext_addr_buf=ext_addr_buf@entry=0x55aa36c306e0) at mail_addr_find.c:251
#10 0x00007f3bca59fc2c in mail_addr_find_opt (path=path@entry=0x55aa36c07510,
address=0x55aa36c69ca0 "<data scrubbed>", extp=extp@entry=0x0,
in_form=in_form@entry=1, query_form=query_form@entry=3,
out_form=out_form@entry=2, strategy=23) at mail_addr_find.c:373
#11 0x000055aa35f32241 in check_mail_addr_find
(state=state@entry=0x7ffc8305e390, reply_name=reply_name@entry=0x55aa36c69140
"<data scrubbed>",
maps=0x55aa36c07510, key=<optimized out>, ext=0x0) at smtpd_check.c:1185
#12 0x000055aa35f32375 in check_rcpt_maps (state=state@entry=0x7ffc8305e390,
sender=<optimized out>, recipient=recipient@entry=0x55aa36c69140 "<data
scrubbed>",
reply_class=<optimized out>, reply_class@entry=0x55aa35f498be "Sender
address") at smtpd_check.c:5158
#13 0x000055aa35f38bd8 in check_sender_rcpt_maps (sender=0x55aa36c69140 "<data
scrubbed>", state=0x7ffc8305e390) at smtpd_check.c:5119
#14 check_sender_rcpt_maps (sender=0x55aa36c69140 "<data scrubbed>",
state=0x7ffc8305e390) at smtpd_check.c:5105
#15 smtpd_check_mail (state=state@entry=0x7ffc8305e390, sender=0x55aa36c69140
"<data scrubbed>") at smtpd_check.c:4903
#16 0x000055aa35f390ab in smtpd_check_rcpt (state=0x7ffc8305e390,
recipient=0x55aa36c5adc0 "<data scrubbed>") at smtpd_check.c:5017
#17 0x000055aa35f29e38 in rcpt_cmd (state=0x7ffc8305e390, argc=3,
argv=0x55aa36c639f0) at smtpd.c:2957
#18 0x000055aa35f2b73f in smtpd_proto (state=<optimized out>) at smtpd.c:5719
#19 0x000055aa35f2dee8 in smtpd_service (stream=<optimized out>,
service=0x7ffc83060e39 "588", argv=<optimized out>) at smtpd.c:5971
#20 0x00007f3bca5fb74a in single_server_wakeup (fd=<optimized out>, attr=0x0)
at single_server.c:303
#21 0x00007f3bca557ae0 in event_loop (delay=<optimized out>) at events.c:1186
#22 0x00007f3bca5fc858 in single_server_main (argc=<optimized out>,
argv=<optimized out>, service=0x55aa35f2dcb0 <smtpd_service>) at
single_server.c:819
#23 0x000055aa35f26170 in main (argc=32, argv=0x7ffc8305ef78) at
../../include/mail_server.h:96
Continuing.
Breakpoint 1, SSL_shutdown (s=0x55aa36c8a490) at ../ssl/ssl_lib.c:2060
2060 in ../ssl/ssl_lib.c
#0 SSL_shutdown (s=0x55aa36c8a490) at ../ssl/ssl_lib.c:2060
#1 0x00007f3bc7b9c33d in ?? () from /usr/lib/x86_64-linux-gnu/libpq.so.5
#2 0x00007f3bc7b9c4a0 in ?? () from /usr/lib/x86_64-linux-gnu/libpq.so.5
#3 0x00007f3bc7b84410 in PQconnectPoll () from
/usr/lib/x86_64-linux-gnu/libpq.so.5
#4 0x00007f3bc7b851cf in ?? () from /usr/lib/x86_64-linux-gnu/libpq.so.5
#5 0x00007f3bc7b882e5 in PQsetdbLogin () from
/usr/lib/x86_64-linux-gnu/libpq.so.5
#6 0x00007f3bca539d35 in ?? () from /usr/lib/postfix/postfix-pgsql.so
#7 0x00007f3bca56e934 in dict_utf8_lookup (dict=0x55aa36c2b2e0,
key=0x55aa36c69da0 "<data scrubbed>") at dict_utf8.c:160
#8 0x00007f3bca5a48c5 in maps_find (maps=maps@entry=0x55aa36c2a9d0,
name=0x55aa36c69da0 "<data scrubbed>", flags=flags@entry=0) at maps.c:195
#9 0x00007f3bca59f853 in find_addr (path=path@entry=0x55aa36c2a9d0,
address=address@entry=0x55aa36c69e60 "<data scrubbed>", flags=flags@entry=0,
with_domain=with_domain@entry=1, query_form=query_form@entry=3,
ext_addr_buf=ext_addr_buf@entry=0x55aa36c306e0) at mail_addr_find.c:251
#10 0x00007f3bca59fc2c in mail_addr_find_opt (path=path@entry=0x55aa36c2a9d0,
address=0x55aa36c69ca0 "<data scrubbed>", extp=extp@entry=0x0,
in_form=in_form@entry=1, query_form=query_form@entry=3,
out_form=out_form@entry=2, strategy=23) at mail_addr_find.c:373
#11 0x000055aa35f32241 in check_mail_addr_find
(state=state@entry=0x7ffc8305e390, reply_name=reply_name@entry=0x55aa36c69140
"<data scrubbed>",
maps=0x55aa36c2a9d0, key=<optimized out>, ext=0x0) at smtpd_check.c:1185
#12 0x000055aa35f32689 in check_rcpt_maps (state=state@entry=0x7ffc8305e390,
sender=<optimized out>, recipient=recipient@entry=0x55aa36c69140 "<data
scrubbed>",
reply_class=<optimized out>, reply_class@entry=0x55aa35f498be "Sender
address") at smtpd_check.c:5242
#13 0x000055aa35f38bd8 in check_sender_rcpt_maps (sender=0x55aa36c69140 "<data
scrubbed>", state=0x7ffc8305e390) at smtpd_check.c:5119
#14 check_sender_rcpt_maps (sender=0x55aa36c69140 "<data scrubbed>",
state=0x7ffc8305e390) at smtpd_check.c:5105
#15 smtpd_check_mail (state=state@entry=0x7ffc8305e390, sender=0x55aa36c69140
"<data scrubbed>") at smtpd_check.c:4903
#16 0x000055aa35f390ab in smtpd_check_rcpt (state=0x7ffc8305e390,
recipient=0x55aa36c5adc0 "<data scrubbed>") at smtpd_check.c:5017
#17 0x000055aa35f29e38 in rcpt_cmd (state=0x7ffc8305e390, argc=3,
argv=0x55aa36c639f0) at smtpd.c:2957
#18 0x000055aa35f2b73f in smtpd_proto (state=<optimized out>) at smtpd.c:5719
#19 0x000055aa35f2dee8 in smtpd_service (stream=<optimized out>,
service=0x7ffc83060e39 "588", argv=<optimized out>) at smtpd.c:5971
#20 0x00007f3bca5fb74a in single_server_wakeup (fd=<optimized out>, attr=0x0)
at single_server.c:303
#21 0x00007f3bca557ae0 in event_loop (delay=<optimized out>) at events.c:1186
#22 0x00007f3bca5fc858 in single_server_main (argc=<optimized out>,
argv=<optimized out>, service=0x55aa35f2dcb0 <smtpd_service>) at
single_server.c:819
#23 0x000055aa35f26170 in main (argc=32, argv=0x7ffc8305ef78) at
../../include/mail_server.h:96
Continuing.
