Bug 1627909 - postfix shows as 'active (running)' even if it's not actually accepting any mail due to missing required configuration
Summary: postfix shows as 'active (running)' even if it's not actually accepting any m...
Keywords:
Status: CLOSED EOL
Alias: None
Product: Fedora
Classification: Fedora
Component: postfix
Version: 34
Hardware: Unspecified
OS: Unspecified
unspecified
unspecified
Target Milestone: ---
Assignee: Jaroslav Škarvada
QA Contact: Fedora Extras Quality Assurance
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2018-09-11 20:32 UTC by Kevin Fenzi
Modified: 2022-06-07 22:23 UTC (History)
7 users (show)

Fixed In Version:
Clone Of:
Environment:
Last Closed: 2022-06-07 22:23:12 UTC
Type: Bug
Embargoed:


Attachments (Terms of Use)

Description Kevin Fenzi 2018-09-11 20:32:52 UTC
dnf-2.7.5-12.fc28.noarch
rpm-4.14.1-9.fc28.x86_64
dnf-automatic-2.7.5-12.fc28.noarch

root     14827  0.0  3.8 522440 156252 ?       SNs  Sep07   0:27 /usr/bin/python3 /usr/bin/dnf-automatic /etc/dnf/automatic.conf --timer --installupdates

current date/time: Tue Sep 11 21:02:56 UTC 2018

==> /var/log/dnf.librepo.log-20180909 <==
10:36:30 lr_headercb: Server returned Content-Length: "493132" (converted 493132/493132 expected)
10:36:31 check_transfer_statuses: Transfer finished: Packages/o/openssh-server-7.8p1-1.fc28.x86_64.rpm (Effective url: https://infrastructure.fedoraproject.org/pub/fedora/linux/updates/28/Everything/x86_64/Packages/o/openssh-server-7.8p1-1.fc28.x86_64.rpm)
10:36:31 check_finished_trasfer_checksum: Checksum (sha256) 6e525045908c1847d399a8c84811f3eec254e447e53cb692a07368407bc12fdd is OK
10:36:31 lr_headercb: Server returned Content-Length: "691768" (converted 691768/691768 expected)
10:36:31 check_transfer_statuses: Transfer finished: Packages/o/openssh-clients-7.8p1-1.fc28.x86_64.rpm (Effective url: https://infrastructure.fedoraproject.org/pub/fedora/linux/updates/28/Everything/x86_64/Packages/o/openssh-clients-7.8p1-1.fc28.x86_64.rpm)
10:36:31 check_finished_trasfer_checksum: Checksum (sha256) e9df418724d6ab43ebdf1d3934527b711c5bd865295e1b364bffdf8858e7f63c is OK
10:36:31 lr_headercb: Server returned Content-Length: "145920" (converted 145920/145920 expected)
10:36:31 check_transfer_statuses: Transfer finished: Packages/g/gd-2.2.5-6.fc28.x86_64.rpm (Effective url: https://infrastructure.fedoraproject.org/pub/fedora/linux/updates/28/Everything/x86_64/Packages/g/gd-2.2.5-6.fc28.x86_64.rpm)
10:36:31 check_finished_trasfer_checksum: Checksum (sha256) 334eaa59273526df345d20da13e5676bfa8a9974112926397c82982ea75e8212 is OK
10:36:31 lr_download_packages: Restoring an old SIGINT handler

==> /var/log/dnf.log-20180909 <==
2018-09-07T10:36:31Z INFO Running transaction test
2018-09-07T10:36:31Z INFO Transaction test succeeded.
2018-09-07T10:36:31Z DDEBUG timer: transaction test: 429 ms
2018-09-07T10:36:31Z INFO Running transaction
2018-09-07T10:36:31Z DEBUG RPMDB altered outside of DNF.
2018-09-07T10:36:32Z DDEBUG RPM transaction start.
2018-09-07T10:37:12Z DDEBUG RPM transaction over.
2018-09-07T10:37:15Z DDEBUG timer: verify transaction: 2159 ms
2018-09-07T10:37:15Z DDEBUG timer: transaction: 43602 ms
2018-09-07T10:37:15Z DEBUG Completion plugin: Generating completion cache...

==> /var/log/dnf.rpm.log-20180909 <==
2018-09-07T10:37:03Z INFO Upgraded: libgs-9.23-6.fc28.x86_64
2018-09-07T10:37:04Z INFO Upgraded: gd-2.2.5-6.fc28.x86_64
2018-09-07T10:37:04Z INFO Cleanup: openssh-clients-7.7p1-6.fc28.x86_64
2018-09-07T10:37:05Z INFO Cleanup: openssh-server-7.7p1-6.fc28.x86_64
2018-09-07T10:37:05Z INFO Cleanup: openssh-7.7p1-6.fc28.x86_64
2018-09-07T10:37:06Z INFO Cleanup: ntpdate-4.2.8p11-2.fc28.x86_64
2018-09-07T10:37:07Z INFO Cleanup: ntp-4.2.8p11-2.fc28.x86_64
2018-09-07T10:37:08Z INFO Cleanup: libxkbcommon-0.8.0-5.fc28.x86_64
2018-09-07T10:37:09Z INFO Cleanup: libgs-9.23-5.fc28.x86_64
2018-09-07T10:37:11Z INFO Cleanup: gd-2.2.5-3.fc28.x86_64

# rpm -qa --last | head 
gd-2.2.5-6.fc28.x86_64                        Fri 07 Sep 2018 10:37:03 AM UTC
libgs-9.23-6.fc28.x86_64                      Fri 07 Sep 2018 10:37:00 AM UTC
libxkbcommon-0.8.2-1.fc28.x86_64              Fri 07 Sep 2018 10:36:53 AM UTC
ntp-4.2.8p12-1.fc28.x86_64                    Fri 07 Sep 2018 10:36:50 AM UTC
ntpdate-4.2.8p12-1.fc28.x86_64                Fri 07 Sep 2018 10:36:49 AM UTC
openssh-clients-7.8p1-1.fc28.x86_64           Fri 07 Sep 2018 10:36:47 AM UTC
openssh-server-7.8p1-1.fc28.x86_64            Fri 07 Sep 2018 10:36:38 AM UTC
openssh-7.8p1-1.fc28.x86_64                   Fri 07 Sep 2018 10:36:34 AM UTC
kernel-core-4.17.17-200.fc28.x86_64           Sat 25 Aug 2018 05:05:11 PM UTC
kernel-headers-4.17.17-1.fc28.x86_64          Sat 25 Aug 2018 05:05:05 PM UTC

So, it looks like it applied things and got to: 

2018-09-07T10:37:15Z DEBUG Completion plugin: Generating completion cache...

and stalled. 

# strace -f -p 14827
strace: Process 14827 attached
recvfrom(24, 

Happy to gather more information.

Comment 1 Adam Williamson 2018-09-11 20:34:15 UTC
I'm seeing this a lot on the openQA infra systems (not in openQA *tests*, note, but on the actual boxes where openQA runs). It's rather a problem as it means they're not getting updated and we don't notice until we log in and try to do something with dnf manually for some reason.

Comment 2 Adam Williamson 2018-10-01 23:47:28 UTC
"Generating completion cache..." is from here:

https://github.com/rpm-software-management/dnf-plugins-core/blob/master/plugins/generate_completion_cache.py

that script itself has not changed since 2015. It also doesn't appear to log anything *after* that message, so not sure how much further it gets before the hang.

I ran 'dnf-automatic' through strace on openqa-stg01.qa and got a bit more context, not sure if this helps anything. I'll poke at it a bit more.

unlink("/var/cache/dnf/packages.db-journal") = 0
fcntl(22, F_SETLK, {l_type=F_RDLCK, l_whence=SEEK_SET, l_start=1073741826, l_len=510}) = 0
fcntl(22, F_SETLK, {l_type=F_UNLCK, l_whence=SEEK_SET, l_start=1073741824, l_len=2}) = 0
fcntl(22, F_SETLK, {l_type=F_UNLCK, l_whence=SEEK_SET, l_start=0, l_len=0}) = 0
fstat(22, {st_mode=S_IFREG|0644, st_size=7835648, ...}) = 0
stat("/var/cache/dnf/packages.db", {st_mode=S_IFREG|0644, st_size=7835648, ...}) = 0
close(22)                               = 0
fcntl(2, F_GETFL)                       = 0x402 (flags O_RDWR|O_APPEND)
lseek(27, 0, SEEK_CUR)                  = 0
close(27)                               = 0
lseek(26, 0, SEEK_CUR)                  = 0
close(26)                               = 0
unlink("/tmp/tmp4dfzhd84")              = 0
getpid()                                = 21582
uname({sysname="Linux", nodename="openqa-stg01.qa.fedoraproject.org", ...}) = 0
stat("/usr/lib64/python3.6/encodings", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
stat("/usr/lib64/python3.6/encodings/idna.py", {st_mode=S_IFREG|0644, st_size=9170, ...}) = 0
stat("/usr/lib64/python3.6/encodings/idna.py", {st_mode=S_IFREG|0644, st_size=9170, ...}) = 0
openat(AT_FDCWD, "/usr/lib64/python3.6/encodings/__pycache__/idna.cpython-36.pyc", O_RDONLY|O_CLOEXEC) = 22
fstat(22, {st_mode=S_IFREG|0644, st_size=5767, ...}) = 0
lseek(22, 0, SEEK_CUR)                  = 0
fstat(22, {st_mode=S_IFREG|0644, st_size=5767, ...}) = 0
read(22, "3\r\r\n\306\3162[\322#\0\0\343\0\0\0\0\0\0\0\0\0\0\0\0\5\0\0\0@\0\0"..., 5768) = 5767
read(22, "", 1)                         = 0
close(22)                               = 0
stat("/usr/bin", {st_mode=S_IFDIR|0555, st_size=36864, ...}) = 0
openat(AT_FDCWD, "/usr/bin", O_RDONLY|O_NONBLOCK|O_CLOEXEC|O_DIRECTORY) = 22
fstat(22, {st_mode=S_IFDIR|0555, st_size=36864, ...}) = 0
getdents(22, /* 1030 entries */, 32768) = 32760
getdents(22, /* 309 entries */, 32768)  = 10016
getdents(22, /* 0 entries */, 32768)    = 0
close(22)                               = 0
stat("/usr/lib64/python3.6", {st_mode=S_IFDIR|0755, st_size=12288, ...}) = 0
stat("/usr/lib64/python3.6/stringprep.py", {st_mode=S_IFREG|0644, st_size=12917, ...}) = 0
stat("/usr/lib64/python3.6/stringprep.py", {st_mode=S_IFREG|0644, st_size=12917, ...}) = 0
openat(AT_FDCWD, "/usr/lib64/python3.6/__pycache__/stringprep.cpython-36.pyc", O_RDONLY|O_CLOEXEC) = 22
fstat(22, {st_mode=S_IFREG|0644, st_size=10032, ...}) = 0
lseek(22, 0, SEEK_CUR)                  = 0
fstat(22, {st_mode=S_IFREG|0644, st_size=10032, ...}) = 0
read(22, "3\r\r\n\306\3162[u2\0\0\343\0\0\0\0\0\0\0\0\0\0\0\0\213\2\0\0@\0\0"..., 10033) = 10032
read(22, "", 1)                         = 0
close(22)                               = 0
stat("/etc/resolv.conf", {st_mode=S_IFREG|0644, st_size=143, ...}) = 0
openat(AT_FDCWD, "/etc/hosts", O_RDONLY|O_CLOEXEC) = 22
fstat(22, {st_mode=S_IFREG|0644, st_size=158, ...}) = 0
read(22, "127.0.0.1   localhost localhost."..., 4096) = 158
read(22, "", 4096)                      = 0
close(22)                               = 0
openat(AT_FDCWD, "/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 22
fstat(22, {st_mode=S_IFREG|0644, st_size=50239, ...}) = 0
mmap(NULL, 50239, PROT_READ, MAP_PRIVATE, 22, 0) = 0x7f7dfa4db000
close(22)                               = 0
openat(AT_FDCWD, "/lib64/libnss_dns.so.2", O_RDONLY|O_CLOEXEC) = 22
read(22, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\340\17\0\0\0\0\0\0"..., 832) = 832
fstat(22, {st_mode=S_IFREG|0755, st_size=26976, ...}) = 0
mmap(NULL, 2117872, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 22, 0) = 0x7f7df04d5000
mprotect(0x7f7df04da000, 2093056, PROT_NONE) = 0
mmap(0x7f7df06d9000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 22, 0x4000) = 0x7f7df06d9000
close(22)                               = 0
mprotect(0x7f7df06d9000, 4096, PROT_READ) = 0
munmap(0x7f7dfa4db000, 50239)           = 0
socket(AF_INET, SOCK_DGRAM|SOCK_CLOEXEC|SOCK_NONBLOCK, IPPROTO_IP) = 22
connect(22, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("10.5.126.21")}, 16) = 0
poll([{fd=22, events=POLLOUT}], 1, 0)   = 1 ([{fd=22, revents=POLLOUT}])
sendmmsg(22, [{msg_hdr={msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="\373\353\1\0\0\1\0\0\0\0\0\0\fopenqa-stg01\2qa\rfed"..., iov_len=51}], msg_iovlen=1, msg_controllen=0, msg_flags=0}, msg_len=51}, {msg_hdr={msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="\322\367\1\0\0\1\0\0\0\0\0\0\fopenqa-stg01\2qa\rfed"..., iov_len=51}], msg_iovlen=1, msg_controllen=0, msg_flags=0}, msg_len=51}], 2, MSG_NOSIGNAL) = 2
poll([{fd=22, events=POLLIN}], 1, 1000) = 1 ([{fd=22, revents=POLLIN}])
ioctl(22, FIONREAD, [67])               = 0
recvfrom(22, "\373\353\205\200\0\1\0\1\0\0\0\0\fopenqa-stg01\2qa\rfed"..., 2048, 0, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("10.5.126.21")}, [28->16]) = 67
poll([{fd=22, events=POLLIN}], 1, 997)  = 1 ([{fd=22, revents=POLLIN}])
ioctl(22, FIONREAD, [108])              = 0
recvfrom(22, "\322\367\205\200\0\1\0\0\0\1\0\0\fopenqa-stg01\2qa\rfed"..., 65536, 0, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("10.5.126.21")}, [28->16]) = 108
close(22)                               = 0
stat("/etc/resolv.conf", {st_mode=S_IFREG|0644, st_size=143, ...}) = 0
openat(AT_FDCWD, "/etc/hosts", O_RDONLY|O_CLOEXEC) = 22
fstat(22, {st_mode=S_IFREG|0644, st_size=158, ...}) = 0
read(22, "127.0.0.1   localhost localhost."..., 4096) = 158
read(22, "", 4096)                      = 0
close(22)                               = 0
socket(AF_INET, SOCK_DGRAM|SOCK_CLOEXEC|SOCK_NONBLOCK, IPPROTO_IP) = 22
connect(22, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("10.5.126.22")}, 16) = 0
poll([{fd=22, events=POLLOUT}], 1, 0)   = 1 ([{fd=22, revents=POLLOUT}])
sendto(22, "\\\262\1\0\0\1\0\0\0\0\0\0\00272\003131\0015\00210\7in-addr"..., 42, MSG_NOSIGNAL, NULL, 0) = 42
poll([{fd=22, events=POLLIN}], 1, 1000) = 1 ([{fd=22, revents=POLLIN}])
ioctl(22, FIONREAD, [89])               = 0
recvfrom(22, "\\\262\205\200\0\1\0\1\0\0\0\0\00272\003131\0015\00210\7in-addr"..., 1024, 0, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("10.5.126.22")}, [28->16]) = 89
close(22)                               = 0
stat("/etc/resolv.conf", {st_mode=S_IFREG|0644, st_size=143, ...}) = 0
openat(AT_FDCWD, "/etc/hosts", O_RDONLY|O_CLOEXEC) = 22
fstat(22, {st_mode=S_IFREG|0644, st_size=158, ...}) = 0
read(22, "127.0.0.1   localhost localhost."..., 4096) = 158
read(22, "", 4096)                      = 0
close(22)                               = 0
openat(AT_FDCWD, "/etc/gai.conf", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
futex(0x7f7e11c41044, FUTEX_WAKE_PRIVATE, 2147483647) = 0
socket(AF_NETLINK, SOCK_RAW, NETLINK_ROUTE) = 22
bind(22, {sa_family=AF_NETLINK, nl_pid=0, nl_groups=00000000}, 12) = 0
getsockname(22, {sa_family=AF_NETLINK, nl_pid=21582, nl_groups=00000000}, [12]) = 0
sendto(22, {{len=20, type=RTM_GETADDR, flags=NLM_F_REQUEST|NLM_F_DUMP, seq=1538437523, pid=0}, {ifa_family=AF_UNSPEC, ...}}, 20, 0, {sa_family=AF_NETLINK, nl_pid=0, nl_groups=00000000}, 12) = 20
recvmsg(22, {msg_name={sa_family=AF_NETLINK, nl_pid=0, nl_groups=00000000}, msg_namelen=12, msg_iov=[{iov_base=[{{len=76, type=RTM_NEWADDR, flags=NLM_F_MULTI, seq=1538437523, pid=21582}, {ifa_family=AF_INET, ifa_prefixlen=8, ifa_flags=IFA_F_PERMANENT, ifa_scope=RT_SCOPE_HOST, ifa_index=if_nametoindex("lo")}, [{{nla_len=8, nla_type=IFA_ADDRESS}, 127.0.0.1}, {{nla_len=8, nla_type=IFA_LOCAL}, 127.0.0.1}, {{nla_len=7, nla_type=IFA_LABEL}, "lo"}, {{nla_len=8, nla_type=IFA_FLAGS}, IFA_F_PERMANENT}, {{nla_len=20, nla_type=IFA_CACHEINFO}, {ifa_prefered=4294967295, ifa_valid=4294967295, cstamp=217, tstamp=217}}]}, {{len=88, type=RTM_NEWADDR, flags=NLM_F_MULTI, seq=1538437523, pid=21582}, {ifa_family=AF_INET, ifa_prefixlen=24, ifa_flags=IFA_F_PERMANENT, ifa_scope=RT_SCOPE_UNIVERSE, ifa_index=if_nametoindex("eth0")}, [{{nla_len=8, nla_type=IFA_ADDRESS}, 10.5.131.72}, {{nla_len=8, nla_type=IFA_LOCAL}, 10.5.131.72}, {{nla_len=8, nla_type=IFA_BROADCAST}, 10.5.131.255}, {{nla_len=9, nla_type=IFA_LABEL}, "eth0"}, {{nla_len=8, nla_type=IFA_FLAGS}, IFA_F_PERMANENT|IFA_F_NOPREFIXROUTE}, {{nla_len=20, nla_type=IFA_CACHEINFO}, {ifa_prefered=4294967295, ifa_valid=4294967295, cstamp=1544, tstamp=1559}}]}, {{len=88, type=RTM_NEWADDR, flags=NLM_F_MULTI, seq=1538437523, pid=21582}, {ifa_family=AF_INET, ifa_prefixlen=24, ifa_flags=IFA_F_PERMANENT, ifa_scope=RT_SCOPE_UNIVERSE, ifa_index=if_nametoindex("virbr0")}, [{{nla_len=8, nla_type=IFA_ADDRESS}, 192.168.122.1}, {{nla_len=8, nla_type=IFA_LOCAL}, 192.168.122.1}, {{nla_len=8, nla_type=IFA_BROADCAST}, 192.168.122.255}, {{nla_len=11, nla_type=IFA_LABEL}, "virbr0"}, {{nla_len=8, nla_type=IFA_FLAGS}, IFA_F_PERMANENT}, {{nla_len=20, nla_type=IFA_CACHEINFO}, {ifa_prefered=4294967295, ifa_valid=4294967295, cstamp=2852, tstamp=2852}}]}], iov_len=4096}], msg_iovlen=1, msg_controllen=0, msg_flags=0}, 0) = 252
recvmsg(22, {msg_name={sa_family=AF_NETLINK, nl_pid=0, nl_groups=00000000}, msg_namelen=12, msg_iov=[{iov_base=[{{len=72, type=RTM_NEWADDR, flags=NLM_F_MULTI, seq=1538437523, pid=21582}, {ifa_family=AF_INET6, ifa_prefixlen=128, ifa_flags=IFA_F_PERMANENT, ifa_scope=RT_SCOPE_HOST, ifa_index=if_nametoindex("lo")}, [{{nla_len=20, nla_type=IFA_ADDRESS}, ::1}, {{nla_len=20, nla_type=IFA_CACHEINFO}, {ifa_prefered=4294967295, ifa_valid=4294967295, cstamp=217, tstamp=217}}, {{nla_len=8, nla_type=IFA_FLAGS}, IFA_F_PERMANENT}]}, {{len=72, type=RTM_NEWADDR, flags=NLM_F_MULTI, seq=1538437523, pid=21582}, {ifa_family=AF_INET6, ifa_prefixlen=64, ifa_flags=IFA_F_PERMANENT, ifa_scope=RT_SCOPE_LINK, ifa_index=if_nametoindex("eth0")}, [{{nla_len=20, nla_type=IFA_ADDRESS}, fe80::5054:ff:fe23:47b1}, {{nla_len=20, nla_type=IFA_CACHEINFO}, {ifa_prefered=4294967295, ifa_valid=4294967295, cstamp=1543, tstamp=1543}}, {{nla_len=8, nla_type=IFA_FLAGS}, IFA_F_PERMANENT}]}], iov_len=4096}], msg_iovlen=1, msg_controllen=0, msg_flags=0}, 0) = 144
recvmsg(22, {msg_name={sa_family=AF_NETLINK, nl_pid=0, nl_groups=00000000}, msg_namelen=12, msg_iov=[{iov_base={{len=20, type=NLMSG_DONE, flags=NLM_F_MULTI, seq=1538437523, pid=21582}, 0}, iov_len=4096}], msg_iovlen=1, msg_controllen=0, msg_flags=0}, 0) = 20
close(22)                               = 0
socket(AF_INET, SOCK_DGRAM|SOCK_CLOEXEC, IPPROTO_IP) = 22
connect(22, {sa_family=AF_INET, sin_port=htons(25), sin_addr=inet_addr("127.0.0.1")}, 16) = 0
getsockname(22, {sa_family=AF_INET, sin_port=htons(49526), sin_addr=inet_addr("127.0.0.1")}, [28->16]) = 0
close(22)                               = 0
socket(AF_INET6, SOCK_DGRAM|SOCK_CLOEXEC, IPPROTO_IP) = 22
connect(22, {sa_family=AF_INET6, sin6_port=htons(25), inet_pton(AF_INET6, "::1", &sin6_addr), sin6_flowinfo=htonl(0), sin6_scope_id=0}, 28) = 0
getsockname(22, {sa_family=AF_INET6, sin6_port=htons(48549), inet_pton(AF_INET6, "::1", &sin6_addr), sin6_flowinfo=htonl(0), sin6_scope_id=0}, [28]) = 0
close(22)                               = 0
socket(AF_INET6, SOCK_STREAM|SOCK_CLOEXEC, IPPROTO_TCP) = 22
connect(22, {sa_family=AF_INET6, sin6_port=htons(25), inet_pton(AF_INET6, "::1", &sin6_addr), sin6_flowinfo=htonl(0), sin6_scope_id=0}, 28) = -1 ECONNREFUSED (Connection refused)
close(22)                               = 0
socket(AF_INET, SOCK_STREAM|SOCK_CLOEXEC, IPPROTO_TCP) = 22
connect(22, {sa_family=AF_INET, sin_port=htons(25), sin_addr=inet_addr("127.0.0.1")}, 16) = 0
recvfrom(22,

Comment 3 Adam Williamson 2018-10-02 00:24:46 UTC
OK, so got a bit further. generate_completion_cache.py is a red herring, that actually completes fine. We're actually falling in one of the dnf-automatic 'emitters', the classes for sending out notifications of what it did, which it does right at the end:

https://github.com/rpm-software-management/dnf/blob/dnf-2-modularity/dnf/automatic/main.py#L224

that basically calls each configured emitter's "commit()" method. The emitter we're actually getting stuck on is this EmailEmitter:

https://github.com/rpm-software-management/dnf/blob/dnf-2-modularity/dnf/automatic/emitter.py#L73

and it's hanging exactly here:

https://github.com/rpm-software-management/dnf/blob/dnf-2-modularity/dnf/automatic/emitter.py#L103

smtp = smtplib.SMTP(self._conf.email_host)

the value of `self._conf.email_host` is 'localhost'.

So basically we're trying to do `smtplib.SMTP('localhost')` and it's sticking, apparently.

Comment 4 Adam Williamson 2018-10-02 00:36:56 UTC
Indeed I can reproduce this on one of the affected boxes by just doing:

[root@openqa-stg01 site-packages][PROD]# python3
Python 3.6.6 (default, Jul 19 2018, 14:25:17) 
[GCC 8.1.1 20180712 (Red Hat 8.1.1-5)] on linux
Type "help", "copyright", "credits" or "license" for more information.
>>> import smtplib
>>> smtplib.SMTP('localhost')

that call never returns. If I hit ctrl-c, I get this traceback:

Traceback (most recent call last):
  File "<stdin>", line 1, in <module>
  File "/usr/lib64/python3.6/smtplib.py", line 251, in __init__
    (code, msg) = self.connect(host, port)
  File "/usr/lib64/python3.6/smtplib.py", line 338, in connect
    (code, msg) = self.getreply()
  File "/usr/lib64/python3.6/smtplib.py", line 387, in getreply
    line = self.file.readline(_MAXLINE + 1)
  File "/usr/lib64/python3.6/socket.py", line 586, in readinto
    return self._sock.recv_into(b)

So at this point we're either on a bug in smtplib, or some kind of bug or misconfiguration in the mail server.

So I looked in the system logs and saw lots of instances of this:

Oct 02 00:28:48 openqa-stg01.qa.fedoraproject.org postfix/smtpd[27084]: fatal: in parameter smtpd_relay_restrictions or smtpd_recipient_restrictions, specify at least one working instance of: reject_unauth_destination, defer_unauth_destination, reject, defer, defer_if_permit or check_relay_domains
Oct 02 00:28:49 openqa-stg01.qa.fedoraproject.org postfix/master[1124]: warning: process /usr/libexec/postfix/smtpd pid 27084 exit status 1
Oct 02 00:28:49 openqa-stg01.qa.fedoraproject.org postfix/master[1124]: warning: /usr/libexec/postfix/smtpd: bad command startup -- throttling
Oct 02 00:29:49 openqa-stg01.qa.fedoraproject.org postfix/smtpd[27105]: fatal: in parameter smtpd_relay_restrictions or smtpd_recipient_restrictions, specify at least one working instance of: reject_unauth_destination, defer_unauth_destination, reject, defer, defer_if_permit or check_relay_domains
Oct 02 00:29:50 openqa-stg01.qa.fedoraproject.org postfix/master[1124]: warning: process /usr/libexec/postfix/smtpd pid 27105 exit status 1
Oct 02 00:29:50 openqa-stg01.qa.fedoraproject.org postfix/master[1124]: warning: /usr/libexec/postfix/smtpd: bad command startup -- throttling

oddly, however, this does not cause any service to show up as failed. postfix.service is active (running). But indeed there is no 'smtpd' process running, whereas on e.g. my own personal mailserver which also uses postfix, I see two:

postfix  21986  0.0  0.5 128072 11112 ?        S    17:25   0:00 smtpd -n smtp -t inet -u -o stress= -s 2
postfix  21996  0.0  0.5 128148 11036 ?        S    17:27   0:00 smtpd -n smtp -t inet -u -o stress= -s 2

At this point I'm gonna say this is basically a bug in the Fedora infra ansible plays, though postfix perhaps could do with failing harder in this case, if it means it's not actually able to accept mail at all?

Comment 5 Adam Williamson 2018-10-02 00:48:34 UTC
Seems postfix started requiring this setting around 3.3.0, at least according to this Debian bug:

https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=892218

and there is a default value of 'permit_mynetworks, permit_sasl_authenticated, defer_unauth_destination' at compatibility level 1 or higher. I guess we don't set a compat level for our infra postfix configs.

Comment 6 Adam Williamson 2018-10-02 01:06:18 UTC
So, I've filed a PR for dnf to set a timeout on SMTP connections:

https://github.com/rpm-software-management/dnf/pull/1229

and nirik is fixing the infra mail servers.

Comment 7 Adam Williamson 2018-10-02 01:20:12 UTC
Adjusting this bug to cover the 'postfix didn't show as failed' part of the problem.

Comment 8 Ben Cotton 2019-05-02 20:46:02 UTC
This message is a reminder that Fedora 28 is nearing its end of life.
On 2019-May-28 Fedora will stop maintaining and issuing updates for
Fedora 28. It is Fedora's policy to close all bug reports from releases
that are no longer maintained. At that time this bug will be closed as
EOL if it remains open with a Fedora 'version' of '28'.

Package Maintainer: If you wish for this bug to remain open because you
plan to fix it in a currently maintained version, simply change the 'version' 
to a later Fedora version.

Thank you for reporting this issue and we are sorry that we were not 
able to fix it before Fedora 28 is end of life. If you would still like 
to see this bug fixed and are able to reproduce it against a later version 
of Fedora, you are encouraged  change the 'version' to a later Fedora 
version prior this bug is closed as described in the policy above.

Although we aim to fix as many bugs as possible during every release's 
lifetime, sometimes those efforts are overtaken by events. Often a 
more recent Fedora release includes newer upstream software that fixes 
bugs or makes them obsolete.

Comment 9 Adam Williamson 2019-05-21 21:34:15 UTC
There's no indication this would've got 'magically' fixed along the way...

Comment 10 Ben Cotton 2019-08-13 16:47:09 UTC
This bug appears to have been reported against 'rawhide' during the Fedora 31 development cycle.
Changing version to '31'.

Comment 11 Ben Cotton 2020-11-03 15:02:38 UTC
This message is a reminder that Fedora 31 is nearing its end of life.
Fedora will stop maintaining and issuing updates for Fedora 31 on 2020-11-24.
It is Fedora's policy to close all bug reports from releases that are no longer
maintained. At that time this bug will be closed as EOL if it remains open with a
Fedora 'version' of '31'.

Package Maintainer: If you wish for this bug to remain open because you
plan to fix it in a currently maintained version, simply change the 'version' 
to a later Fedora version.

Thank you for reporting this issue and we are sorry that we were not 
able to fix it before Fedora 31 is end of life. If you would still like 
to see this bug fixed and are able to reproduce it against a later version 
of Fedora, you are encouraged  change the 'version' to a later Fedora 
version prior this bug is closed as described in the policy above.

Although we aim to fix as many bugs as possible during every release's 
lifetime, sometimes those efforts are overtaken by events. Often a 
more recent Fedora release includes newer upstream software that fixes 
bugs or makes them obsolete.

Comment 12 Ben Cotton 2021-02-09 15:06:45 UTC
This bug appears to have been reported against 'rawhide' during the Fedora 34 development cycle.
Changing version to 34.

Comment 13 Ben Cotton 2022-05-12 15:34:26 UTC
This message is a reminder that Fedora Linux 34 is nearing its end of life.
Fedora will stop maintaining and issuing updates for Fedora Linux 34 on 2022-06-07.
It is Fedora's policy to close all bug reports from releases that are no longer
maintained. At that time this bug will be closed as EOL if it remains open with a
'version' of '34'.

Package Maintainer: If you wish for this bug to remain open because you
plan to fix it in a currently maintained version, change the 'version' 
to a later Fedora Linux version.

Thank you for reporting this issue and we are sorry that we were not 
able to fix it before Fedora Linux 34 is end of life. If you would still like 
to see this bug fixed and are able to reproduce it against a later version 
of Fedora Linux, you are encouraged to change the 'version' to a later version
prior to this bug being closed.

Comment 14 Ben Cotton 2022-06-07 22:23:12 UTC
Fedora Linux 34 entered end-of-life (EOL) status on 2022-06-07.

Fedora Linux 34 is no longer maintained, which means that it
will not receive any further security or bug fix updates. As a result we
are closing this bug.

If you can reproduce this bug against a currently maintained version of
Fedora please feel free to reopen this bug against that version. If you
are unable to reopen this bug, please file a new report against the
current release.

Thank you for reporting this bug and we are sorry it could not be fixed.


Note You need to log in before you can comment on or make changes to this bug.