"Unexpected async result" and need to explicitly re-subscribe to topics.

[RickCarlino]

Greetings,

We are transitioning our codebase to use Tortoise. Today I noticed that if I intentionally take my broker offline, the connection will re-establish itself with the broker automatically, but it will not re-subscribe to the previous topics.
My question is: is this expected behavior, or am I using the library wrong?

Qucik Fix (Maybe?)

I was able to fix the problem with the following snippet:

  def resubscribe(%{client_id: client_id}) do
    meta_data = Tortoise.Connection.subscriptions(client_id)
    Tortoise.Connection.subscribe(client_id, meta_data.topics)
  end

  def connection(:up, state) do
    resubscribe(state)
    {:ok, %{state | connection_status: :up}}
  end

  def connection(status, state) do
    {:ok, %{state | connection_status: status}}
  end

I am not seeing or reading about other projects needing to do this, so I feel like maybe I made a mistake somewhere or am misunderstanding the documentation.

A Warning

Additionally, I get the following log (source code here):

18:27:19.958 [warn]  Unexpected async result

This only happens after re-subscribing.

Example Code

Since the project is also open-source, you can view the real-world offending code here and here, but it would probably be better if I created an isolated repo to demonstrate the problem. I am happy to do so if that helps- please let me know.

Thanks for all the work you put into this project! Despite this one hiccup, we've had a great experience so far.

[brianmay]

How are you subscribing to topics in the first place? If you are passing subscriptions when starting the process this should work. At least it works for me. I think it should automatically resubscribe if the connection is lost too (but I haven't exactly tested this).

If on the other hand you are attempting to call the subscribe function, i.e. use dynamic subscriptions as I call them, then read on.

See #130, in short, I couldn't get dynamic subscriptions working reliably. In the end I gave up. I think that the mqtt-5 rewrite is suppose to resolve issues such as this through a better design, but I suspect nobody has time to look at it this. I am not even sure where it got to. See the mqtt-5 branch though.

I think the idea in the current code is that you are expected to resubscribe after the connection is re-established. But not 100% sure of this.

[RickCarlino]

Hi @brianmay thanks for replying.

How are you subscribing to topics in the first place? If you are passing subscriptions when starting the process this should work. At least it works for me.

Unfortunately, my subscriptions are not dynamic. They are standard one-time subscriptions:

    opts = [
      client_id: client_id,
      user_name: username,
      password: raw_token,
      server: server,
      handler: {FarmbotExt.MQTT, [client_id: client_id, username: username]},
      backoff: [min_interval: 8_000, max_interval: 120_000],
      subscriptions: [
        {"bot/#{username}/from_clients", 0},
        {"bot/#{username}/ping/#", 0},
        {"bot/#{username}/sync/#", 0},
        {"bot/#{username}/terminal_input", 0}
      ]
    ]

    {Tortoise.Connection, opts}

It sounds like I will need to leave the re-subscription code in for now.

[brianmay]

Hmmm. It is very possible I just assumed that resubscriptions worked, without actually testing it. Thanks for you code excerpt, I probably should add it to my code. Based on my experience in #130 this makes me a bit nervous also. But maybe subscribing to topics all at once - like you appear to do - instead of one at a time - like I was - might help here.

[brianmay]

I can confirm seeing that Unexpected async result warning now too.

[brianmay]

The more I think about it, the more I seem to recall that the options passed to the init function really are suppose to be persistent across connections. So either my memory is faulty. Or there is a bug in the code somewhere that is preventing this from working correctly.

[brianmay]

I had to revert the resubscription change, it killed everything. Looks like #130.

21:28:47.958 [info]  Connection has been established

21:28:52.958 [error] GenServer {Tortoise.Registry, {Tortoise.Connection, "robotica-ceryx-deployment-c688b6f49-9vj7c"}} terminating
** (stop) :subscription_timeout
Last message: :subscribe

21:28:52.964 [error] GenServer {Tortoise.Registry, {Tortoise.Connection.Supervisor, "robotica-ceryx-deployment-c688b6f49-9vj7c"}} terminating
** (stop) :subscription_timeout
Last message: {:EXIT, #PID<0.4770.0>, :subscription_timeout}

[brianmay]

Automatic re-subscribing seems to "work for me"(TM). No idea why it didn't work for you:

23:52:08.146 [error] Lifx Brian/Light (105867434619856): publish_raw() got Tortoise.publish() got error 'closed'
        
23:52:11.542 [info]  Connection has been established
        
23:52:11.560 [info]  Subscribed to command/#
        
23:52:11.560 [info]  Subscribed to execute
        
23:52:11.560 [info]  Subscribed to mark
        
23:52:11.560 [info]  Subscribed to request/all/#
        
23:52:11.560 [info]  Subscribed to request/robotica-nerves-f447/#
        
23:52:11.561 [info]  Subscribed to stat/#
        
23:52:11.561 [info]  Subscribed to state/#
        
23:52:11.561 [info]  Subscribed to tele/#

[RickCarlino]

@brianmay Not sure what happened. I changed a few settings and everything appears to be working now, so I will assume this issue was a problem with my local configuration rather than a problem with the library. Closing.