errors when restarting broker

[heinsaris]

Hi,

I get some strange behaviour when I stop and restart my broker while there is an active Tortoise connection. I use Tortoise 0.9.4 on a MBP running Macos 10.15.3 (Catalina) and Elixir 1.10.0 on top of Erlang 22.2.4 (both installed via brew).

This is how the connection is set up (As a child of the app supervisor:

{Tortoise.Connection,
[
client_id: "hein-1",
server: {
Tortoise.Transport.Tcp,
host: "localhost", port: 1883
},
handler: {Tortoise.Handler.Logger, []}
]}

I run a producer and a consumer in separate processes. The producer adds messages to a queue (BlockingQueue) , and the consumer takes the messages from the queue and publishes them via publish_sync. I tried with publish and a receive..after, but I got even worse problems (some of my messages were lost).

Here is what happens:

When the broker is stopped, I immediately get a warning from the logger:

14:51:38.193 [warn] Connection has been dropped

I can keep publishing (for minutes even) , but as soon as I restart the broker, I get an error:

14:51:50.926 [error] GenStateMachine {Tortoise.Registry, {Tortoise.Connection.Inflight, "hein-1"}} terminating
** (exit) {:protocol_violation, :unknown_identifier}
(stdlib 3.11.1) gen_statem.erl:1298: :gen_statem.loop_state_callback_result/11
(stdlib 3.11.1) proc_lib.erl:249: :proc_lib.init_p_do_apply/3
State: {{:connected, {Tortoise.Transport.Tcp, #Port<0.16>}}, %Tortoise.Connection.Inflight{client_id: "hein-1", order: [], pending: %{}}}
Callback mode: :handle_event_function

After the timeout on publish_sync I get this:

14:52:50.914 [info] answer = {:error, :timeout}

And I try to publish the message again:

14:52:50.914 [info] publish message Message 4

But get another error:

14:52:50.922 [error] GenStateMachine {Tortoise.Registry, {Tortoise.Connection.Inflight, "hein-1"}} terminating
** (CaseClauseError) no case clause matching: {:error, :closed}
(tortoise 0.9.4) lib/tortoise/connection/inflight.ex:292: Tortoise.Connection.Inflight.handle_event/4
(stdlib 3.11.1) gen_statem.erl:1161: :gen_statem.loop_state_callback/11
(stdlib 3.11.1) proc_lib.erl:249: :proc_lib.init_p_do_apply/3

Then I get this warning:

14:52:55.912 [warn] Client has been terminated with reason: {:function_clause, [{Tortoise.Handler.Logger, :connection, [:terminated, %Tortoise.Handler.Logger{}], [file: 'lib/tortoise/handler/logger.ex', line: 16]}, {Tortoise.Handler, :execute, 2, [file: 'lib/tortoise/handler.ex', line: 314]}, {Tortoise.Connection.Controller, :handle_info, 2, [file: 'lib/tortoise/connection/controller.ex', line: 215]}, {:gen_server, :try_dispatch, 4, [file: 'gen_server.erl', line: 637]}, {:gen_server, :handle_msg, 6, [file: 'gen_server.erl', line: 711]}, {:proc_lib, :init_p_do_apply, 3, [file: 'proc_lib.erl', line: 249]}]}

And this error:

14:52:55.920 [error] GenServer {Tortoise.Registry, {Tortoise.Connection.Controller, "hein-1"}} terminating
** (FunctionClauseError) no function clause matching in Tortoise.Handler.Logger.connection/2
(tortoise 0.9.4) lib/tortoise/handler/logger.ex:16: Tortoise.Handler.Logger.connection(:terminated, %Tortoise.Handler.Logger{})
(tortoise 0.9.4) lib/tortoise/handler.ex:314: Tortoise.Handler.execute/2
(tortoise 0.9.4) lib/tortoise/connection/controller.ex:215: Tortoise.Connection.Controller.handle_info/2

Then comes a ping timeout:

14:52:55.922 [error] GenServer {Tortoise.Registry, {Tortoise.Connection, "hein-1"}} terminating
** (stop) :ping_timeout
Last message: :ping
State: %Tortoise.Connection{backoff: %Tortoise.Connection.Backoff{max_interval: 30000, min_interval: 100, value: nil}, client_id: "hein-1", connect: %Tortoise.Package.Connect{META: %Tortoise.Package.Meta{flags: 0, opcode: 1}, clean_session: false, client

After 4 errors, the Tortoise client is terminated (by or via the supervisor), and a new one is created, after which everything is fine again.

I have lost no messages, but the messages that was being published at the time the broker is restarted gets published more than once.

The question is whether this is a bug in Tortoise, or am I doing something wrong? Or maybe this is what is supposed to happen and is a good example of the let it fail philosophy?

[gausby]

Looks like the server send a package with an identifier unknown to the tortoise instance…what broker are you using?

[heinsaris]

Hello Martin, Thank you for your fast response. I am running mosquitto on my Mac. It is the latest version, installed via brew. Kind regards, Hein On 31 January 2020 at 18:04:52, Martin Gausby (notifications@github.com) wrote: Looks like the server send a package with an identifier unknown to the tortoise instance…what broker are you using? — You are receiving this because you authored the thread. Reply to this email directly, view it on GitHub, or unsubscribe.