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.
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.
"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,
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.
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?
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.
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.
Adjusting this bug to cover the 'postfix didn't show as failed' part of the problem.
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.
There's no indication this would've got 'magically' fixed along the way...
This bug appears to have been reported against 'rawhide' during the Fedora 31 development cycle. Changing version to '31'.
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.
This bug appears to have been reported against 'rawhide' during the Fedora 34 development cycle. Changing version to 34.
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.
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.