{"action":"created","issue":{"url":"https://api.github.com/repos/eclipse/paho.mqtt.golang/issues/232","repository_url":"https://api.github.com/repos/eclipse/paho.mqtt.golang","labels_url":"https://api.github.com/repos/eclipse/paho.mqtt.golang/issues/232/labels{/name}","comments_url":"https://api.github.com/repos/eclipse/paho.mqtt.golang/issues/232/comments","events_url":"https://api.github.com/repos/eclipse/paho.mqtt.golang/issues/232/events","html_url":"https://github.com/eclipse/paho.mqtt.golang/issues/232","id":344341527,"node_id":"MDU6SXNzdWUzNDQzNDE1Mjc=","number":232,"title":"Client hangs on Subscribe(); token.Wait()","user":{"login":"wari","id":525422,"node_id":"MDQ6VXNlcjUyNTQyMg==","avatar_url":"https://avatars1.githubusercontent.com/u/525422?v=4","gravatar_id":"","url":"https://api.github.com/users/wari","html_url":"https://github.com/wari","followers_url":"https://api.github.com/users/wari/followers","following_url":"https://api.github.com/users/wari/following{/other_user}","gists_url":"https://api.github.com/users/wari/gists{/gist_id}","starred_url":"https://api.github.com/users/wari/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/wari/subscriptions","organizations_url":"https://api.github.com/users/wari/orgs","repos_url":"https://api.github.com/users/wari/repos","events_url":"https://api.github.com/users/wari/events{/privacy}","received_events_url":"https://api.github.com/users/wari/received_events","type":"User","site_admin":false},"labels":[],"state":"open","locked":false,"assignee":null,"assignees":[],"milestone":null,"comments":4,"created_at":"2018-07-25T08:23:50Z","updated_at":"2018-07-26T07:36:52Z","closed_at":null,"author_association":"NONE","body":"Looking at the samples, we are told to do token.Wait() after a Subscribe(), but unfortunately, this can cause a hang on my side. Removing the token.Wait() solves the issue. \r\n\r\n```\r\n\tif token := c.Subscribe(\"go-mqtt/sample\", 0, nil); token.Wait() && token.Error() != nil {\r\n\t\tfmt.Println(token.Error())\r\n\t\tos.Exit(1)\r\n\t}\r\n```\r\n\r\nHere's a debug trace.\r\n\r\n* Without token.Wait()\r\n\r\n```\r\n2018-07-25T16:07:34+08:00 |INFO| Setting up consumer\r\n2018-07-25T16:07:34+08:00 |INFO| Done\r\n2018-07-25T16:07:34+08:00 |INFO| Launching consumer\r\n2018-07-25T16:07:34+08:00 |DEBU| [[client]   Connect()]\r\n2018-07-25T16:07:34+08:00 |DEBU| [[store]    memorystore initialized]\r\n2018-07-25T16:07:34+08:00 |DEBU| [[client]   about to write new connect msg]\r\n2018-07-25T16:07:34+08:00 |DEBU| [[client]   socket connected to broker]\r\n2018-07-25T16:07:34+08:00 |DEBU| [[client]   Using MQTT 3.1.1 protocol]               \r\n2018-07-25T16:07:34+08:00 |DEBU| [[net]      connect started]\r\n2018-07-25T16:07:34+08:00 |DEBU| [[net]      received connack]\r\n2018-07-25T16:07:34+08:00 |DEBU| [[client]   client is connected]\r\n2018-07-25T16:07:34+08:00 |DEBU| [[client]   exit startClient]\r\n2018-07-25T16:07:34+08:00 |INFO| Done\r\n2018-07-25T16:07:34+08:00 |INFO| Subscribing to: filebeat/lines\r\n2018-07-25T16:07:34+08:00 |DEBU| [[client]   enter Subscribe]\r\n2018-07-25T16:07:34+08:00 |DEBU| [[net]      incoming started]\r\n2018-07-25T16:07:34+08:00 |DEBU| [[net]      logic started]\r\n2018-07-25T16:07:34+08:00 |DEBU| [[net]      outgoing started]\r\n2018-07-25T16:07:34+08:00 |DEBU| [[net]      outgoing waiting for an outbound message]\r\n2018-07-25T16:07:34+08:00 |DEBU| [[client]   SUBSCRIBE: dup: false qos: 1 retain: false rLength: 0 MessageID: 0 topics: [filebeat/lines]]\r\n2018-07-25T16:07:34+08:00 |DEBU| [[net]      Received Message]\r\n2018-07-25T16:07:34+08:00 |DEBU| [[client]   exit Subscribe]\r\n2018-07-25T16:07:34+08:00 |INFO| Done\r\n```\r\n\r\n* With token.Wait()\r\n\r\nSee: https://pastebin.com/R0SaqMeq"},"comment":{"url":"https://api.github.com/repos/eclipse/paho.mqtt.golang/issues/comments/408005757","html_url":"https://github.com/eclipse/paho.mqtt.golang/issues/232#issuecomment-408005757","issue_url":"https://api.github.com/repos/eclipse/paho.mqtt.golang/issues/232","id":408005757,"node_id":"MDEyOklzc3VlQ29tbWVudDQwODAwNTc1Nw==","user":{"login":"wari","id":525422,"node_id":"MDQ6VXNlcjUyNTQyMg==","avatar_url":"https://avatars1.githubusercontent.com/u/525422?v=4","gravatar_id":"","url":"https://api.github.com/users/wari","html_url":"https://github.com/wari","followers_url":"https://api.github.com/users/wari/followers","following_url":"https://api.github.com/users/wari/following{/other_user}","gists_url":"https://api.github.com/users/wari/gists{/gist_id}","starred_url":"https://api.github.com/users/wari/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/wari/subscriptions","organizations_url":"https://api.github.com/users/wari/orgs","repos_url":"https://api.github.com/users/wari/repos","events_url":"https://api.github.com/users/wari/events{/privacy}","received_events_url":"https://api.github.com/users/wari/received_events","type":"User","site_admin":false},"created_at":"2018-07-26T07:36:52Z","updated_at":"2018-07-26T07:36:52Z","author_association":"NONE","body":"I did a python program as well as do a packet capture for it as well. If there are messages in the queue, the server will publish messages first on Clean Session = 0. Based on the spec:\r\n\r\n> If CleanSession is set to 0, the Server MUST resume communications with the Client based on state from the current Session (as identified by the Client identifier). If there is no Session associated with the Client identifier the Server MUST create a new Session. The Client and Server MUST store the Session after the Client and Server are disconnected.\r\n\r\nThe packet capture for the python program is as follows:\r\n\r\n```\r\n  343 22.023172429 192.168.40.103 → 52.74.21.247 MQTT 140 Connect Command\r\n  345 22.029223967 52.74.21.247 → 192.168.40.103 MQTT 70 Connect Ack\r\n  347 22.029254321 52.74.21.247 → 192.168.40.103 MQTT 156 Publish Message (id=1020) [a/b], Publish Message (id=1021) [a/b], Publish Message (id=1022) [a/b], Publish Message (id=1023) [a/b], Publish Message (id=1024) [a/b], Publish Message (id=1) [a/b], Publish Message (id=2) [a/b], Publish Message (id=3) [a/b], Publish Message (id=4) [a/b]\r\n  349 22.029259824 52.74.21.247 → 192.168.40.103 MQTT 76 Publish Message (id=5) [a/b]\r\n  351 22.029641227 192.168.40.103 → 52.74.21.247 MQTT 76 Subscribe Request (id=1) [a/b]\r\n  352 22.033844440 52.74.21.247 → 192.168.40.103 MQTT 71 Subscribe Ack (id=1)\r\n  353 22.033861139 192.168.40.103 → 52.74.21.247 MQTT 106 Publish Ack (id=1020), Publish Ack (id=1021), Publish Ack (id=1022), Publish Ack (id=1023), Publish Ack (id=1024), Publish Ack (id=1), Publish Ack (id=2), Publish Ack (id=3), Publish Ack (id=4), Publish Ack (id=5)\r\n```\r\n\r\nand the output of the python `paho-mqtt` program:\r\n\r\n```\r\nConnected with result code 0\r\nSubscribing\r\nDone Subscribe\r\na/b b'A'\r\na/b b'A'\r\na/b b'A'\r\na/b b'A'\r\na/b b'A'\r\na/b b'A'\r\na/b b'A'\r\na/b b'A'\r\na/b b'A'\r\na/b b'A'\r\n############## Client ON Subscribe\r\n<paho.mqtt.client.Client object at 0x7f1cc2e98860> None 1 (1,)\r\n```\r\n\r\nSo I decided to use the `token.Wait()` to see what conditions would hang my program:\r\n\r\n```\r\n  342 2.200720148 192.168.40.103 → 52.74.21.247 MQTT 87 Subscribe Request (id=1) [filebeat/lines]\r\n  675 2.459266810 52.74.21.247 → 192.168.40.103 MQTT 2962 Publish Message (id=263) [filebeat/lines], Subscribe Ack (id=1), Publish Message (id=264) [filebeat/lines]\r\n```\r\n\r\nThe `Subscribe Ack` came in after 260 1K-ish messages later which is about 250 ms time span.\r\n\r\nI'm not sure if the SubAck sandwiched in between a Publish caused the hang though."}}
{"actor":{"display_login":"wari"}}