Mosquitto bridge broker won't connect to system mosquitto server since upgrading from 1.6.12 to 2.0.2

[twegener-embertec]

I have a test setup where the bridge runs on the same host as the main mosquitto server.
Previously, when using mosquitto 1.6.12 for both bridge and system server, it worked fine.
Since upgrading to mosquitto 2.0.2 for both bridge broker and system server, the bridge tries to connect, and shows up as e.g. New connection from ::1:34006 on port 1883. in the server log, but it does not make it to the New bridge connected from stage. Instead, it eventually reports: Client <unknown> closed its connection.

1608182157: New connection from ::1:36026 on port 1883.
1608182216: Client <unknown> closed its connection.
1608182218: New connection from ::1:36030 on port 1883.
1608182278: Client <unknown> closed its connection.
1608182284: New connection from ::1:36032 on port 1883.
1608182344: Client <unknown> closed its connection.

Meanwhile, the bridge has log entries like the following:

1608182157: Connecting bridge (step 1) test.bridge (localhost:1883)
1608182157: Connecting bridge (step 2) test.bridge (localhost:1883)
1608182218: Connecting bridge (step 1) test.bridge (localhost:1883)
1608182218: Connecting bridge (step 2) test.bridge (localhost:1883)
1608182284: Connecting bridge (step 1) test.bridge (localhost:1883)
1608182284: Connecting bridge (step 2) test.bridge (localhost:1883)
1608182350: Connecting bridge (step 1) test.bridge (localhost:1883)
1608182350: Connecting bridge (step 2) test.bridge (localhost:1883)

...and it keeps cycling like that indefinitely.

The client connected to the bridge receives one $SYS/broker/connection/test.client/state message with payload '0' (where we'd hope for '1' on connect).

The bridge config looks like:

listener 1884 localhost
connection test.bridge
address localhost:1883
clientid testclient
allow_anonymous true

(I've omitted irrelevant parts such as topic config.)

The system mosquitto server is just using the default system config.

This is on Ubuntu 18.04.5 LTS, using mosquitto 2.0.2-0mosquitto3~bionic3 package from the PPA.

[twegener-embertec]

Some strace excerpts (for a different run from the log entries in the original post):

bridge mosquitto process:

getpid()                                = 25063
write(2, "1608165567: Connecting bridge (s"..., 66) = 66
rt_sigprocmask(SIG_SETMASK, ~[RTMIN RT_1], [], 8) = 0
clone(child_stack=0x7fcc9cb85ff0, flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM|CLONE_SETTLS|CLONE_PARENT_SETTID|CLONE_CHILD_CLEARTID, parent_tidptr=0x7fcc9cb86a90, tls=0x7fcc9cb867c0, child_tidptr=0x7fcc9cb86a90) = 25074
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
rt_sigprocmask(SIG_SETMASK, [HUP INT USR1 USR2 TERM], [], 8) = 0
epoll_wait(8, [], 1000, 100)            = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=262794, tv_nsec=177029085}) = 0
write(2, "1608165567: Connecting bridge (s"..., 66) = 66
socket(AF_INET6, SOCK_STREAM, IPPROTO_TCP) = 10
fcntl(10, F_GETFL)                      = 0x2 (flags O_RDWR)
fcntl(10, F_SETFL, O_RDWR|O_NONBLOCK)   = 0
connect(10, {sa_family=AF_INET6, sin6_port=htons(1883), inet_pton(AF_INET6, "::1", &sin6_addr), sin6_flowinfo=htonl(0), sin6_scope_id=0}, 28) = -1 EINPROGRESS (Operation now in progress)
fcntl(10, F_GETFL)                      = 0x802 (flags O_RDWR|O_NONBLOCK)
fcntl(10, F_SETFL, O_RDWR|O_NONBLOCK)   = 0
rt_sigprocmask(SIG_SETMASK, [HUP INT USR1 USR2 TERM], [], 8) = 0
epoll_wait(8, [], 1000, 100)            = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=262794, tv_nsec=278492636}) = 0
rt_sigprocmask(SIG_SETMASK, [HUP INT USR1 USR2 TERM], [], 8) = 0
epoll_wait(8, [], 1000, 100)            = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=262794, tv_nsec=378958318}) = 0




clock_gettime(CLOCK_MONOTONIC, {tv_sec=262849, tv_nsec=140308893}) = 0
rt_sigprocmask(SIG_SETMASK, [HUP INT USR1 USR2 TERM], [], 8) = 0
epoll_wait(8, [], 1000, 100)            = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=262849, tv_nsec=241310095}) = 0
rt_sigprocmask(SIG_SETMASK, [HUP INT USR1 USR2 TERM], [], 8) = 0
epoll_wait(8, [{EPOLLIN, {u32=3701410928, u64=94583176236144}}], 1000, 100) = 1
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=262849, tv_nsec=241521864}) = 0
read(9, "\300", 1)                      = 1
read(9, "\0", 1)                        = 1
write(9, "\320\0", 2)                   = 2
rt_sigprocmask(SIG_SETMASK, [HUP INT USR1 USR2 TERM], [], 8) = 0
epoll_wait(8, [], 1000, 100)            = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=262849, tv_nsec=343193206}) = 0
rt_sigprocmask(SIG_SETMASK, [HUP INT USR1 USR2 TERM], [], 8) = 0




clock_gettime(CLOCK_MONOTONIC, {tv_sec=262977, tv_nsec=911014123}) = 0
rt_sigprocmask(SIG_SETMASK, [HUP INT USR1 USR2 TERM], [], 8) = 0
epoll_wait(8, [], 1000, 100)            = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=262978, tv_nsec=12709203}) = 0
close(10)                               = 0
rt_sigprocmask(SIG_SETMASK, [HUP INT USR1 USR2 TERM], [], 8) = 0
epoll_wait(8, [], 1000, 100)            = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=262978, tv_nsec=115076832}) = 0
rt_sigprocmask(SIG_SETMASK, [HUP INT USR1 USR2 TERM], [], 8) = 0

server mosquitto process:

clock_gettime(CLOCK_MONOTONIC, {tv_sec=270358, tv_nsec=523788718}) = 0
accept(6, NULL, NULL)                   = 11
fcntl(11, F_GETFL)                      = 0x2 (flags O_RDWR)
fcntl(11, F_SETFL, O_RDWR|O_NONBLOCK)   = 0
getpid()                                = 23748
getpeername(11, {sa_family=AF_INET6, sin6_port=htons(35282), inet_pton(AF_INET6, "::1", &sin6_addr), sin6_flowinfo=htonl(0), sin6_scope_id=0}, [128->28]) = 0
getsockname(11, {sa_family=AF_INET6, sin6_port=htons(1883), inet_pton(AF_INET6, "::1", &sin6_addr), sin6_flowinfo=htonl(0), sin6_scope_id=0}, [128->28]) = 0
openat(AT_FDCWD, "/etc/hosts.allow", O_RDONLY) = 12
fstat(12, {st_mode=S_IFREG|0644, st_size=411, ...}) = 0
read(12, "# /etc/hosts.allow: list of host"..., 4096) = 411
read(12, "", 4096)                      = 0
close(12)                               = 0
openat(AT_FDCWD, "/etc/hosts.deny", O_RDONLY) = 12
fstat(12, {st_mode=S_IFREG|0644, st_size=711, ...}) = 0
read(12, "# /etc/hosts.deny: list of hosts"..., 4096) = 711
read(12, "", 4096)                      = 0
close(12)                               = 0
getpeername(11, {sa_family=AF_INET6, sin6_port=htons(35282), inet_pton(AF_INET6, "::1", &sin6_addr), sin6_flowinfo=htonl(0), sin6_scope_id=0}, [128->28]) = 0
write(4, "1608173132: New connection from "..., 56) = 56
epoll_ctl(7, EPOLL_CTL_ADD, 11, {EPOLLIN, {u32=1874509728, u64=94615709073312}}) = 0
accept(6, NULL, NULL)                   = -1 EAGAIN (Resource temporarily unavailable)
rt_sigprocmask(SIG_SETMASK, [HUP INT USR1 USR2 TERM], [], 8) = 0
epoll_wait(7, [], 1000, 100)            = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=270358, tv_nsec=626482548}) = 0
rt_sigprocmask(SIG_SETMASK, [HUP INT USR1 USR2 TERM], [], 8) = 0
epoll_wait(7, [], 1000, 100)            = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0

[ralight]

Thanks very much, I've pushed a fix and this will be part of 2.0.3 shortly.

[twegener-embertec]

Thanks. I've confirmed that it fixes the issue for my case.