SSL/TLS Exceptions

Grant Traynor

unread,

Mar 22, 2018, 5:39:22 PM3/22/18

to rabbitmq-users

Hi,

I'm using the rmq container on docker hub with TLS enabled as per the following:

I'm migrating from an old version onto a new one on a different server. I have an AMQP shovel setup between the servers whilst the connections slowly migrate over.

Clients are typically MQTT using Paho Python.

I'm regularly getting the following exception/log message. Is there anyone who might have some clues as to what might be going on here?

Kind Regards,

Grant.

2018-03-22 19:52:07.024 [info] <0.8012.8> MQTT vhost picked using vhost in username or default

2018-03-22 19:52:07.033 [info] <0.8012.8> accepting MQTT connection <0.8012.8> (103.55.47.153:42119 -> 172.17.0.3:8883)

2018-03-22 19:52:07.153 [error] <0.8012.8> ** Generic server <0.8012.8> terminating

** Last message in was {inet_async,{sslsocket,{gen_tcp,#Port<0.231001>,tls_connection,<0.1269.0>},<0.8009.8>},#Ref<0.4053695308.2039742465.140262>,{ok,<<16,86,0,4,77,81,84,84,4,6,0,60,0,19,100,114,111,112,108,101,116,98,56,50,55,101,98,52,52,53,55,51,52,0,50,100,114,111,112,108,101,116,101,118,101,110,116,115,46,48,48,48,48,48,48,48,48,45,48,48,48,48,45,48,48,48,48,45,48,48,48,48,45,98,56,50,55,101,98,52,52,53,55,51,52,0,1,48>>}}

** When Server state == {state,{sslsocket,{gen_tcp,#Port<0.231001>,tls_connection,<0.1269.0>},<0.8009.8>},"103.55.47.153:42119 -> 172.17.0.3:8883",true,undefined,true,running,{none,<0.8038.8>},<0.8011.8>,false,none,{proc_state,{sslsocket,{gen_tcp,#Port<0.231001>,tls_connection,<0.1269.0>},<0.8009.8>},#{"devices/00000000-0000-0000-0000-b827eb445734/#" => [1]},{undefined,<<"amq.ctag-w_CkolFyOQ9vx8arYYaGBQ">>},{0,nil},{0,nil},undefined,1,"dropletb827eb445734",true,{mqtt_msg,false,0,"dropletevents.00000000-0000-0000-0000-b827eb445734",false,undefined,<<"0">>},{<0.8026.8>,undefined},<0.8019.8>,<<"amq.topic">>,{amqp_adapter_info,{0,0,0,0,0,65535,44049,3},8883,{0,0,0,0,0,65535,26423,12185},42119,<<"103.55.47.153:42119 -> 172.17.0.3:8883">>,{'MQTT',"N/A"},[{variable_map,#{<<"client_id">> => <<"dropletb827eb445734">>}},{channels,1},{channel_max,1},{frame_max,0},{client_properties,[{<<"product">>,longstr,<<"MQTT client">>}]},{ssl,true},{ssl_protocol,'tlsv1.2'},{ssl_key_exchange,ecdhe_rsa},{ssl_cipher,aes_256_gcm},{ssl_hash,null},{peer_cert_issuer,<<"CN=SwitchDin MQTT CA,OU=SwitchDin Certificate Authority,O=SwitchDin Pty Ltd,C=AU">>},{peer_cert_subject,<<"CN=mqtt.switchdin.com,OU=SwitchDin CA,O=SwitchDin Pty Ltd,L=Newcastle,ST=New South Wales,C=AU">>},{peer_cert_validity,<<"2017-10-18T05:22:38Z - 2019-10-18T05:22:38Z">>}]},<<"CN=mqtt.switchdin.com,OU=SwitchDin CA,O=SwitchDin Pty Ltd,L=Newcastle,ST=New South Wales,C=AU">>,<0.1247.0>,{auth_state,<<"guest">>,{user,<<"guest">>,[administrator],[{rabbit_auth_backend_internal,none}]},<<"/">>},#Fun<rabbit_mqtt_processor.0.96330891>},<0.8019.8>,{state,fine,5000,#Ref<0.4053695308.2039742465.140049>}}

** Reason for termination ==

** {function_clause,[{rabbit_mqtt_processor,process_login,[<<"guest">>,<<"guest">>,4,{proc_state,{sslsocket,{gen_tcp,#Port<0.231001>,tls_connection,<0.1269.0>},<0.8009.8>},#{"devices/00000000-0000-0000-0000-b827eb445734/#" => [1]},{undefined,<<"amq.ctag-w_CkolFyOQ9vx8arYYaGBQ">>},{0,nil},{0,nil},undefined,1,"dropletb827eb445734",true,{mqtt_msg,false,0,"dropletevents.00000000-0000-0000-0000-b827eb445734",false,undefined,<<"0">>},{<0.8026.8>,undefined},<0.8019.8>,<<"amq.topic">>,{amqp_adapter_info,{0,0,0,0,0,65535,44049,3},8883,{0,0,0,0,0,65535,26423,12185},42119,<<"103.55.47.153:42119 -> 172.17.0.3:8883">>,{'MQTT',"N/A"},[{variable_map,#{<<"client_id">> => <<"dropletb827eb445734">>}},{variable_map,#{<<"client_id">> => <<"dropletb827eb445734">>}},{channels,1},{channel_max,1},{frame_max,0},{client_properties,[{<<"product">>,longstr,<<"MQTT client">>}]},{ssl,true},{ssl_protocol,'tlsv1.2'},{ssl_key_exchange,ecdhe_rsa},{ssl_cipher,aes_256_gcm},{ssl_hash,null},{peer_cert_issuer,<<"CN=SwitchDin MQTT CA,OU=SwitchDin Certificate Authority,O=SwitchDin Pty Ltd,C=AU">>},{peer_cert_subject,<<"CN=mqtt.switchdin.com,OU=SwitchDin CA,O=SwitchDin Pty Ltd,L=Newcastle,ST=New South Wales,C=AU">>},{peer_cert_validity,<<"2017-10-18T05:22:38Z - 2019-10-18T05:22:38Z">>}]},<<"CN=mqtt.switchdin.com,OU=SwitchDin CA,O=SwitchDin Pty Ltd,L=Newcastle,ST=New South Wales,C=AU">>,<0.1247.0>,{auth_state,<<"guest">>,{user,<<"guest">>,[administrator],[{rabbit_auth_backend_internal,none}]},<<"/">>},#Fun<rabbit_mqtt_processor.0.96330891>}],[{file,"src/rabbit_mqtt_processor.erl"},{line,473}]},{rabbit_mqtt_processor,process_request,3,[{file,"src/rabbit_mqtt_processor.erl"},{line,112}]},{rabbit_mqtt_processor,process_frame,2,[{file,"src/rabbit_mqtt_processor.erl"},{line,69}]},{rabbit_mqtt_reader,process_received_bytes,2,[{file,...},...]},...]}

2018-03-22 19:52:07.153 [error] <0.8012.8> CRASH REPORT Process <0.8012.8> with 0 neighbours exited with reason: no function clause matching rabbit_mqtt_processor:process_login(<<"guest">>, <<"guest">>, 4, {proc_state,{sslsocket,{gen_tcp,#Port<0.231001>,tls_connection,<0.1269.0>},<0.8009.8>},#{"d..." => ...},...}) line 473 in gen_server2:terminate/3 line 1166

2018-03-22 19:52:07.154 [error] <0.8010.8> Supervisor {<0.8010.8>,rabbit_mqtt_connection_sup} had child rabbit_mqtt_reader started with rabbit_mqtt_reader:start_link(<0.8011.8>, {acceptor,{0,0,0,0,0,0,0,0},8883}, {sslsocket,{gen_tcp,#Port<0.231001>,tls_connection,<0.1269.0>},<0.8009.8>}) at <0.8012.8> exit with reason no function clause matching rabbit_mqtt_processor:process_login(<<"guest">>, <<"guest">>, 4, {proc_state,{sslsocket,{gen_tcp,#Port<0.231001>,tls_connection,<0.1269.0>},<0.8009.8>},#{"d..." => ...},...}) line 473 in context child_terminated

2018-03-22 19:52:07.154 [error] <0.8010.8> Supervisor {<0.8010.8>,rabbit_mqtt_connection_sup} had child rabbit_mqtt_reader started with rabbit_mqtt_reader:start_link(<0.8011.8>, {acceptor,{0,0,0,0,0,0,0,0},8883}, {sslsocket,{gen_tcp,#Port<0.231001>,tls_connection,<0.1269.0>},<0.8009.8>}) at <0.8012.8> exit with reason reached_max_restart_intensity in context shutdown

Luke Bakken

unread,

Mar 22, 2018, 5:48:55 PM3/22/18

to rabbitmq-users

Hi Grant,

What version of Erlang and RabbitMQ are you using, and on what operating system?

Thanks,

Luke

On Thursday, March 22, 2018 at 2:39:22 PM UTC-7, Grant Traynor wrote:

Grant Traynor

unread,

Mar 22, 2018, 6:17:05 PM3/22/18

to rabbitmq-users

Hi Luke,

Sorry, put that in the attached photos. Details below.

Cheers,

Grant.

RMQ3.7.4Erlang 20.2.2

lsb_release -a

No LSB modules are available.

Distributor ID: Ubuntu

Description: Ubuntu 16.04.4 LTS

Release: 16.04

Codename: xenial

uname -a

Linux ip-10-2-1-50 4.4.0-1049-aws #58-Ubuntu SMP Fri Jan 12 23:17:09 UTC 2018 x86_64 x86_64 x86_64 GNU/Linux

Docker Docker version 17.05.0-ce, build 89658be.

rabbitmq latest f0c46fce8422 10 days ago 127MB

docker inspect rabbitmq

[

{

"Id": "d39815b6003986260c12477f7829000c65a684e759e18e2b6fcb8987e37e515c",

"Created": "2018-03-22T01:13:18.316059009Z",

"Path": "docker-entrypoint.sh",

"Args": [

"rabbitmq-server"

],

"State": {

"Status": "running",

"Running": true,

"Paused": false,

"Restarting": false,

"OOMKilled": false,

"Dead": false,

"Pid": 11028,

"ExitCode": 0,

"Error": "",

"StartedAt": "2018-03-22T01:13:55.333042341Z",

"FinishedAt": "2018-03-22T01:13:54.805126956Z"

},

"Image": "sha256:f0c46fce842280b04c607511431570d352a88470db991d9bd04d37686e2ff6f8",

"ResolvConfPath": "/var/lib/docker/containers/d39815b6003986260c12477f7829000c65a684e759e18e2b6fcb8987e37e515c/resolv.conf",

"HostnamePath": "/var/lib/docker/containers/d39815b6003986260c12477f7829000c65a684e759e18e2b6fcb8987e37e515c/hostname",

"HostsPath": "/var/lib/docker/containers/d39815b6003986260c12477f7829000c65a684e759e18e2b6fcb8987e37e515c/hosts",

"LogPath": "/var/lib/docker/containers/d39815b6003986260c12477f7829000c65a684e759e18e2b6fcb8987e37e515c/d39815b6003986260c12477f7829000c65a684e759e18e2b6fcb8987e37e515c-json.log",

"Name": "/rabbitmq",

"RestartCount": 0,

"Driver": "aufs",

"MountLabel": "",

"ProcessLabel": "",

"AppArmorProfile": "docker-default",

"ExecIDs": null,

"HostConfig": {

"Binds": [

"/opt/switchdin/pki/ip-10-2-1-50/:/certs/:ro"

],

"ContainerIDFile": "",

"LogConfig": {

"Type": "json-file",

"Config": {}

},

"NetworkMode": "default",

"PortBindings": {

"15670/tcp": [

{

"HostIp": "0.0.0.0",

"HostPort": "15670"

}

],

"15672/tcp": [

{

"HostIp": "0.0.0.0",

"HostPort": "15672"

}

],

"15674/tcp": [

{

"HostIp": "0.0.0.0",

"HostPort": "15674"

}

],

"1883/tcp": [

{

"HostIp": "0.0.0.0",

"HostPort": "1883"

}

],

"5671/tcp": [

{

"HostIp": "0.0.0.0",

"HostPort": "5671"

}

],

"5672/tcp": [

{

"HostIp": "0.0.0.0",

"HostPort": "5672"

}

],

"8883/tcp": [

{

"HostIp": "0.0.0.0",

"HostPort": "8883"

}

]

},

"RestartPolicy": {

"Name": "on-failure",

"MaximumRetryCount": 0

},

"AutoRemove": false,

"VolumeDriver": "",

"VolumesFrom": null,

"CapAdd": null,

"CapDrop": null,

"Dns": null,

"DnsOptions": null,

"DnsSearch": null,

"ExtraHosts": null,

"GroupAdd": null,

"IpcMode": "",

"Cgroup": "",

"Links": null,

"OomScoreAdj": 0,

"PidMode": "",

"Privileged": false,

"PublishAllPorts": false,

"ReadonlyRootfs": false,

"SecurityOpt": null,

"UTSMode": "",

"UsernsMode": "",

"ShmSize": 67108864,

"Runtime": "runc",

"ConsoleSize": [

0,

0

],

"Isolation": "",

"CpuShares": 0,

"Memory": 0,

"NanoCpus": 0,

"CgroupParent": "",

"BlkioWeight": 0,

"BlkioWeightDevice": null,

"BlkioDeviceReadBps": null,

"BlkioDeviceWriteBps": null,

"BlkioDeviceReadIOps": null,

"BlkioDeviceWriteIOps": null,

"CpuPeriod": 0,

"CpuQuota": 0,

"CpuRealtimePeriod": 0,

"CpuRealtimeRuntime": 0,

"CpusetCpus": "",

"CpusetMems": "",

"Devices": null,

"DeviceCgroupRules": null,

"DiskQuota": 0,

"KernelMemory": 0,

"MemoryReservation": 0,

"MemorySwap": 0,

"MemorySwappiness": -1,

"OomKillDisable": false,

"PidsLimit": 0,

"Ulimits": null,

"CpuCount": 0,

"CpuPercent": 0,

"IOMaximumIOps": 0,

"IOMaximumBandwidth": 0

},

"GraphDriver": {

"Data": null,

"Name": "aufs"

},

"Mounts": [

{

"Type": "bind",

"Source": "/opt/switchdin/pki/ip-10-2-1-50",

"Destination": "/certs",

"Mode": "ro",

"RW": false,

"Propagation": ""

},

{

"Type": "volume",

"Name": "37a3b47ea65b7433990f3aeca2cd9e7c2025265f0fac5d736e8a8e0a204ea646",

"Source": "/var/lib/docker/volumes/37a3b47ea65b7433990f3aeca2cd9e7c2025265f0fac5d736e8a8e0a204ea646/_data",

"Destination": "/var/lib/rabbitmq",

"Driver": "local",

"Mode": "",

"RW": true,

"Propagation": ""

}

],

"Config": {

"Hostname": "rabbitmq",

"Domainname": "",

"User": "",

"AttachStdin": false,

"AttachStdout": false,

"AttachStderr": false,

"ExposedPorts": {

"15670/tcp": {},

"15672/tcp": {},

"15674/tcp": {},

"1883/tcp": {},

"25672/tcp": {},

"4369/tcp": {},

"5671/tcp": {},

"5672/tcp": {},

"8883/tcp": {}

},

"Tty": false,

"OpenStdin": false,

"StdinOnce": false,

"Env": [

"RABBITMQ_USER=switchdin",

"RABBITMQ_PASS=switchdin.password",

"RABBITMQ_SERVICE_HOST=127.0.0.1",

"RABBITMQ_ERLANG_COOKIE=SWITCHDINCOOKIE",

"RABBITMQ_CONFIG_FILE=/etc/rabbitmq/rabbitmq.config",

"RABBITMQ_NODES=10.2.1.50",

"RABBITMQ_PORT=5672",

"PATH=/usr/lib/rabbitmq/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin",

"GOSU_VERSION=1.10",

"RABBITMQ_LOGS=-",

"RABBITMQ_SASL_LOGS=-",

"RABBITMQ_GPG_KEY=0A9AF2115F4687BD29803A206B73A36E6026DFCA",

"RABBITMQ_VERSION=3.7.4",

"RABBITMQ_GITHUB_TAG=v3.7.4",

"RABBITMQ_DEBIAN_VERSION=3.7.4-1",

"LANG=C.UTF-8",

"HOME=/var/lib/rabbitmq"

],

"Cmd": [

"rabbitmq-server"

],

"ArgsEscaped": true,

"Image": "rabbitmq",

"Volumes": {

"/certs/": {},

"/var/lib/rabbitmq": {}

},

"WorkingDir": "",

"Entrypoint": [

"docker-entrypoint.sh"

],

"OnBuild": null,

"Labels": {}

},

"NetworkSettings": {

"Bridge": "",

"SandboxID": "66259bb0992d6b2a47040ac749b5e20480388da8dbe55ea11c0c4481281ca2b0",

"HairpinMode": false,

"LinkLocalIPv6Address": "",

"LinkLocalIPv6PrefixLen": 0,

"Ports": {

"15670/tcp": [

{

"HostIp": "0.0.0.0",

"HostPort": "15670"

}

],

"15672/tcp": [

{

"HostIp": "0.0.0.0",

"HostPort": "15672"

}

],

"15674/tcp": [

{

"HostIp": "0.0.0.0",

"HostPort": "15674"

}

],

"1883/tcp": [

{

"HostIp": "0.0.0.0",

"HostPort": "1883"

}

],

"25672/tcp": null,

"4369/tcp": null,

"5671/tcp": [

{

"HostIp": "0.0.0.0",

"HostPort": "5671"

}

],

"5672/tcp": [

{

"HostIp": "0.0.0.0",

"HostPort": "5672"

}

],

"8883/tcp": [

{

"HostIp": "0.0.0.0",

"HostPort": "8883"

}

]

},

"SandboxKey": "/var/run/docker/netns/66259bb0992d",

"SecondaryIPAddresses": null,

"SecondaryIPv6Addresses": null,

"EndpointID": "5c2c141ecbe9ebb86cbed44b2e205dfb93db7992a6ff9480e24bc2ee77da4296",

"Gateway": "172.17.0.1",

"GlobalIPv6Address": "",

"GlobalIPv6PrefixLen": 0,

"IPAddress": "172.17.0.3",

"IPPrefixLen": 16,

"IPv6Gateway": "",

"MacAddress": "02:42:ac:11:00:03",

"Networks": {

"bridge": {

"IPAMConfig": null,

"Links": null,

"Aliases": null,

"NetworkID": "0f099bb8e42d93e786c846cfd7203d06b9cfe7dec087b1605e42f39b386044ab",

"EndpointID": "5c2c141ecbe9ebb86cbed44b2e205dfb93db7992a6ff9480e24bc2ee77da4296",

"Gateway": "172.17.0.1",

"IPAddress": "172.17.0.3",

"IPPrefixLen": 16,

"IPv6Gateway": "",

"GlobalIPv6Address": "",

"GlobalIPv6PrefixLen": 0,

"MacAddress": "02:42:ac:11:00:03"

}

]

Luke Bakken

unread,

Mar 22, 2018, 7:22:49 PM3/22/18

to rabbitmq-users

Hi Grant,

Thanks for the info. I didn't notice the smaller screen shot with version information.

Here is the error itself -

** {function_clause,[{rabbit_mqtt_processor,process_login,[<<"guest">>,<<"guest">>,4,{proc_state,

I found the same error mentioned here: https://lists.rabbitmq.com/pipermail/rabbitmq-discuss/2014-June/036483.html

Basically, the process state is not what that function is expecting here:

https://github.com/rabbitmq/rabbitmq-mqtt/blob/master/src/rabbit_mqtt_processor.erl?utf8=%E2%9C%93#L473-L477

The function expects the channels field to have value {undefined, undefined}, but in the stack trace you provide, there is a channel in the first element of that tuple, causing the function_clause error.

Can you answer the following questions -

* What version of RabbitMQ are you migrating from?

* Did you ever see this error using that older version?

* Which RabbitMQ node is this error being logged to? Is it the same node to which your Python clients connect?

* How are the client connections being migrated from the old environment to the new one?

* Do you ever use non-TLS connections? If so, do you see this error in that scenario?

* This issue may have something to do with your Paho Python client code. Can you share that?

* Have there been any changes to the client code that correspond to these log messages?

Thanks,

Luke

Grant Traynor

unread,

Mar 22, 2018, 8:04:25 PM3/22/18

to rabbitm...@googlegroups.com

Hi Luke,

* What version of RabbitMQ are you migrating from?

RabbitMQ 3.6.3, Erlang 18.3

* Did you ever see this error using that older version?

Don't think so. That version is rock star solid.

* Which RabbitMQ node is this error being logged to? Is it the same node to which your Python clients connect?

Yes. Seems to happen over direct connection or via the shovel from the old to the new.

* How are the client connections being migrated from the old environment to the new one?

I've moved the IP address of the service on the route table, letting them reconnect themselves. Have actively disconnected some from the management gui on the old version, watched them reconnect on the new.

* Do you ever use non-TLS connections? If so, do you see this error in that scenario?

Seems to happen in both scenarios. Less often with qos1, but that might be a false indicator.

* This issue may have something to do with your Paho Python client code. Can you share that?

I can send exaclty the same packet and it seems to only happen occasionally ...

paho-mqtt (1.2)

This causes it I think ... I'll keep checking ...

import paho.mqtt.publish as mqtt_publish

import json

import zlib

payload = [{“uuid”: “34d1a966-2e2c-11e8-bc7f-acbc32adb03d”,

“user_intervention”: “NONE”,

“extra”: {},

“importance”: “NONE”,

“access_level”: 1,

“reason”: “NONE”,

“droplet_timestamp”: 1521762803.449009,

“active”: “ACTIVE”,

“system_state”: “NONE”,

“serial”: “UNKNOWN”,

“model”: “UNKNOWN”}]

payload_json = json.dumps(payload)

payload_zip = zlib.compress(payload_json, 9)

topic = “eventz” + ‘.’ + “00000000-0000-0000-0000-18d6c71ece7d”

mqtt_publish.single(topic, bytearray(payload_zip), hostname=‘<<SERVER>>’, qos=0)

* Have there been any changes to the client code that correspond to these log messages?

No changes on the client side.

--
You received this message because you are subscribed to a topic in the Google Groups "rabbitmq-users" group.
To unsubscribe from this topic, visit https://groups.google.com/d/topic/rabbitmq-users/b9KaU8M5MaE/unsubscribe.
To unsubscribe from this group and all its topics, send an email to rabbitmq-users+unsubscribe@googlegroups.com.
To post to this group, send email to rabbitmq-users@googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

--

Grant TRAYNOR
Home : +61 (0)2 4942 5802
Mobile : +61 (0)428 408 558

Grant Traynor

unread,

Mar 22, 2018, 9:39:12 PM3/22/18

to rabbitmq-users

I've moved everything over to the new server and disabled the shovel. It seems more stable now.

Oddly, I can post exactly the same payload many times, and everything is OK. Then occasionally it goes bang ...

2018-03-23 01:10:21.137 [info] <0.20144.13> closing MQTT connection <0.20144.13> (211.27.16.89:53846 -> 172.17.0.3:1883)

2018-03-23 01:10:22.303 [info] <0.20178.13> MQTT vhost picked using plugin configuration or default

2018-03-23 01:10:22.310 [info] <0.20178.13> accepting MQTT connection <0.20178.13> (211.27.16.89:53849 -> 172.17.0.3:1883)

2018-03-23 01:10:22.326 [info] <0.20178.13> closing MQTT connection <0.20178.13> (211.27.16.89:53849 -> 172.17.0.3:1883)

2018-03-23 01:10:23.483 [info] <0.20212.13> MQTT vhost picked using plugin configuration or default

2018-03-23 01:10:23.487 [info] <0.20212.13> accepting MQTT connection <0.20212.13> (211.27.16.89:53852 -> 172.17.0.3:1883)

2018-03-23 01:10:23.502 [info] <0.20212.13> closing MQTT connection <0.20212.13> (211.27.16.89:53852 -> 172.17.0.3:1883)

2018-03-23 01:10:24.661 [info] <0.20246.13> MQTT vhost picked using plugin configuration or default

2018-03-23 01:10:24.673 [info] <0.20246.13> accepting MQTT connection <0.20246.13> (211.27.16.89:53855 -> 172.17.0.3:1883)

2018-03-23 01:10:24.688 [info] <0.20246.13> closing MQTT connection <0.20246.13> (211.27.16.89:53855 -> 172.17.0.3:1883)

2018-03-23 01:10:25.847 [info] <0.20276.13> MQTT vhost picked using plugin configuration or default

2018-03-23 01:10:25.851 [info] <0.20276.13> accepting MQTT connection <0.20276.13> (211.27.16.89:53858 -> 172.17.0.3:1883)

2018-03-23 01:10:25.866 [info] <0.20276.13> closing MQTT connection <0.20276.13> (211.27.16.89:53858 -> 172.17.0.3:1883)

2018-03-23 01:10:27.025 [info] <0.20310.13> MQTT vhost picked using plugin configuration or default

2018-03-23 01:10:27.029 [info] <0.20310.13> accepting MQTT connection <0.20310.13> (211.27.16.89:53861 -> 172.17.0.3:1883)

2018-03-23 01:10:27.047 [info] <0.20310.13> closing MQTT connection <0.20310.13> (211.27.16.89:53861 -> 172.17.0.3:1883)

2018-03-23 01:10:27.048 [error] <0.20323.13> ** Generic server <0.20323.13> terminating

** Last message in was {'$gen_cast',{method,{'basic.publish',0,<<"amq.topic">>,<<"eventz.00000000-0000-0000-0000-18d6c71ece7d">>,false,false},{content,60,{'P_basic',undefined,undefined,[{<<"x-mqtt-publish-qos">>,byte,0},{<<"x-mqtt-dup">>,bool,false}],1,undefined,undefined,undefined,undefined,undefined,undefined,undefined,undefined,undefined,undefined},none,none,[<<120,218,85,142,193,74,196,48,16,134,95,37,228,108,101,211,110,187,173,183,165,168,20,165,43,178,234,65,164,204,38,35,4,154,164,36,211,226,178,236,187,155,212,147,199,249,254,249,254,153,207,11,159,103,173,248,29,227,223,53,52,165,40,183,89,142,69,149,9,129,117,6,53,54,25,200,147,44,114,80,167,77,161,248,13,227,115,64,63,104,75,232,23,180,164,157,77,114,239,44,166,16,127,200,67,4,151,107,28,180,153,156,39,176,18,211,74,251,218,29,187,118,255,156,214,64,74,12,97,24,113,193,49,102,229,38,50,143,16,254,202,94,208,27,29,130,94,144,101,236,209,205,86,177,7,152,71,74,166,242,110,26,145,6,210,6,3,129,153,162,32,202,92,236,170,221,54,175,110,155,58,111,68,179,94,160,232,167,182,125,123,236,222,239,147,27,206,129,208,12,81,163,53,161,216,176,114,244,26,210,31,252,173,127,234,15,31,125,130,198,41,252,199,174,95,191,210,207,90,190>>]},flow}}

** When Server state == {ch,running,rabbit_framing_amqp_0_9_1,1,<0.20320.13>,<0.20320.13>,<0.20313.13>,<<"211.27.16.89:53861 -> 172.17.0.3:1883">>,{lstate,<0.20322.13>,false},none,1,{[],[]},{user,<<"guest">>,[administrator],[{rabbit_auth_backend_internal,none}]},<<"/">>,<<>>,#{},{state,{dict,0,16,16,8,80,48,{[],[],[],[],[],[],[],[],[],[],[],[],[],[],[],[]},{{[],[],[],[],[],[],[],[],[],[],[],[],[],[],[],[]}}},erlang},#{},#{},{set,0,16,16,8,80,48,{[],[],[],[],[],[],[],[],[],[],[],[],[],[],[],[]},{{[],[],[],[],[],[],[],[],[],[],[],[],[],[],[],[]}}},<0.20317.13>,{state,fine,5000,#Ref<0.4053695308.2077491201.178357>},false,1,{{0,nil},{0,nil}},[],[],{{0,nil},{0,nil}},[{<<"publisher_confirms">>,bool,true},{<<"exchange_exchange_bindings">>,bool,true},{<<"basic.nack">>,bool,true},{<<"consumer_cancel_notify">>,bool,true},{<<"connection.blocked">>,bool,true},{<<"authentication_failure_close">>,bool,true}],none,10,none,flow,[]}

** Reason for termination ==

** {{{shutdown,normal},{gen_server,call,[<0.20313.13>,{info,[amqp_params]},15000]}},[{gen_server,call,3,[{file,"gen_server.erl"},{line,214}]},{rabbit_channel,check_topic_authorisation,5,[{file,"src/rabbit_channel.erl"},{line,855}]},{rabbit_channel,handle_method,3,[{file,"src/rabbit_channel.erl"},{line,1081}]},{rabbit_channel,handle_cast,2,[{file,"src/rabbit_channel.erl"},{line,523}]},{gen_server2,handle_msg,2,[{file,"src/gen_server2.erl"},{line,1050}]},{proc_lib,init_p_do_apply,3,[{file,"proc_lib.erl"},{line,247}]}]}

2018-03-23 01:10:27.048 [error] <0.20323.13> CRASH REPORT Process <0.20323.13> with 0 neighbours exited with reason: {{shutdown,normal},{gen_server,call,[<0.20313.13>,{info,[amqp_params]},15000]}} in gen_server:call/3 line 214 in gen_server2:terminate/3 line 1166

2018-03-23 01:10:27.050 [error] <0.20321.13> Supervisor {<0.20321.13>,rabbit_channel_sup} had child channel started with rabbit_channel:start_link(1, <0.20320.13>, <0.20320.13>, <0.20313.13>, <<"211.27.16.89:53861 -> 172.17.0.3:1883">>, rabbit_framing_amqp_0_9_1, {user,<<"guest">>,[administrator],[{rabbit_auth_backend_internal,none}]}, <<"/">>, [{<<"publisher_confirms">>,bool,true},{<<"exchange_exchange_bindings">>,bool,true},{<<"basic.nack">>,...},...], <0.20317.13>, <0.20322.13>) at <0.20323.13> exit with reason {{shutdown,normal},{gen_server,call,[<0.20313.13>,{info,[amqp_params]},15000]}} in gen_server:call/3 line 214 in context child_terminated

2018-03-23 01:10:27.051 [error] <0.20321.13> Supervisor {<0.20321.13>,rabbit_channel_sup} had child channel started with rabbit_channel:start_link(1, <0.20320.13>, <0.20320.13>, <0.20313.13>, <<"211.27.16.89:53861 -> 172.17.0.3:1883">>, rabbit_framing_amqp_0_9_1, {user,<<"guest">>,[administrator],[{rabbit_auth_backend_internal,none}]}, <<"/">>, [{<<"publisher_confirms">>,bool,true},{<<"exchange_exchange_bindings">>,bool,true},{<<"basic.nack">>,...},...], <0.20317.13>, <0.20322.13>) at <0.20323.13> exit with reason reached_max_restart_intensity in context shutdown

Michael Klishin

unread,

Mar 23, 2018, 2:53:32 AM3/23/18

to rabbitm...@googlegroups.com

The last one is a known issue that affects MQTT,

it was addressed in https://github.com/rabbitmq/rabbitmq-common/pull/253.

--
You received this message because you are subscribed to the Google Groups "rabbitmq-users" group.
To unsubscribe from this group and stop receiving emails from it, send an email to rabbitmq-users+unsubscribe@googlegroups.com.

To post to this group, send email to rabbitmq-users@googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

--

MK

Staff Software Engineer, Pivotal/RabbitMQ

Luke Bakken

unread,

Mar 23, 2018, 10:25:10 AM3/23/18

to rabbitmq-users

Hi Grant,

Thanks for the information. I suspect you won't see this issue again in your new environment and it had something to do with how you were moving client connections. I'm not sure how the shovel connections could have logged it as they are long-running.

Can you give me the exact sequence of commands for how you're doing this, or at least a bit more detail? "I've moved the IP address of the service on the route table, letting them reconnect themselves"

I'll see if I can reproduce it locally.

Thanks,

Luke

Grant Traynor

unread,

Mar 23, 2018, 4:49:09 PM3/23/18

to rabbitm...@googlegroups.com

Thanks Michael. Is there a view as to when 3.7.5 might be released? Would be great to have that fix in our system.

To post to this group, send email to rabbitm...@googlegroups.com.

For more options, visit https://groups.google.com/d/optout.

--
MK

Staff Software Engineer, Pivotal/RabbitMQ

--
You received this message because you are subscribed to a topic in the Google Groups "rabbitmq-users" group.
To unsubscribe from this topic, visit https://groups.google.com/d/topic/rabbitmq-users/b9KaU8M5MaE/unsubscribe.
To unsubscribe from this group and all its topics, send an email to rabbitmq-users+unsubscribe@googlegroups.com.

To post to this group, send email to rabbitmq-users@googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

--

Grant Traynor

unread,

Mar 23, 2018, 4:55:45 PM3/23/18

to rabbitm...@googlegroups.com

Hi Luke,

It does appear to be occurring still. Less often though. I'll keep playing / checking and let you know after a few days of running.

In terms of the migration, it's a lot simpler than perhaps you're thinking.

I have a Route53 (AWS) DNS entry pointing at server A (the old RMQ instance). I've modified it to point at server B (the new instance) in Route53.

We have a lot of IoT type clients in the field. As they disconnect / reconnect, they have gradually discovered the new server IP / DNS entry and migrated themselves.

In some cases, I've gone to the connection tab on the management UI, and fore disconnected a client, which then reconnects to the new server.

The RMQ instances are not clustered and have no knowledge of each other, apart from the shovel.

So the process was:

1. Stand up new RMQ instance

2. Point backend services at new instance

3. Setup shovel between old RMQ and new RMQ instance on all topics. Backend processes data from the new instance.

4. Change DNS entry to point to new RMQ instance.

5. Force disconnect a few clients to make sure they connect to the new instance.

6. Wait for clients to migrate themselves as they naturally disconnect / reconnect.

Make sense?

Regards,

Grant.

--

You received this message because you are subscribed to a topic in the Google Groups "rabbitmq-users" group.
To unsubscribe from this topic, visit https://groups.google.com/d/topic/rabbitmq-users/b9KaU8M5MaE/unsubscribe.
To unsubscribe from this group and all its topics, send an email to rabbitmq-users+unsubscribe@googlegroups.com.
To post to this group, send email to rabbitmq-users@googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

Michael Klishin

unread,

Mar 23, 2018, 5:20:30 PM3/23/18

to rabbitm...@googlegroups.com

3.7.5 will be released some time in April. We expect a couple of weeks

of RCs because some changes in that release are really hard to reproduce.

So most likely late April.

Grant TRAYNOR
Home : +61 (0)2 4942 5802
Mobile : +61 (0)428 408 558

--

You received this message because you are subscribed to the Google Groups "rabbitmq-users" group.
To unsubscribe from this group and stop receiving emails from it, send an email to rabbitmq-users+unsubscribe@googlegroups.com.

To post to this group, send email to rabbitmq-users@googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

--

Grant Traynor

unread,

Mar 23, 2018, 5:26:28 PM3/23/18

to rabbitm...@googlegroups.com

OK, thanks. Is it worth me reverting to an earlier version to avoid this problem?

Thanks for your advice.

Cheers,
Grant.

Michael Klishin

unread,

Mar 23, 2018, 5:30:27 PM3/23/18

to rabbitm...@googlegroups.com

I think all 3.7.x versions are affected.

We can produce a 3.7.5 milestone next week that you can use. We are fairly confident

it should be comparable to 3.7.4 in terms of stability and the biggest couple of 3.7.5 changes are not

merged yet.

--

You received this message because you are subscribed to the Google Groups "rabbitmq-users" group.
To unsubscribe from this group and stop receiving emails from it, send an email to rabbitmq-users+unsubscribe@googlegroups.com.

To post to this group, send email to rabbitmq-users@googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

--

Grant Traynor

unread,

Mar 23, 2018, 5:34:33 PM3/23/18

to rabbitm...@googlegroups.com

That would be fantastic!

Cheers,

Grant.

To post to this group, send email to rabbitm...@googlegroups.com.

For more options, visit https://groups.google.com/d/optout.

--
MK

Staff Software Engineer, Pivotal/RabbitMQ

--
You received this message because you are subscribed to a topic in the Google Groups "rabbitmq-users" group.
To unsubscribe from this topic, visit https://groups.google.com/d/topic/rabbitmq-users/b9KaU8M5MaE/unsubscribe.
To unsubscribe from this group and all its topics, send an email to rabbitmq-users+unsubscribe@googlegroups.com.

To post to this group, send email to rabbitmq-users@googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

--

Grant Traynor

unread,

Mar 24, 2018, 9:14:39 PM3/24/18

to rabbitmq-users

Hi Luke and Michael,

I'm still getting this crash, log snippets below. I have a fair amount of infrastructure turned on in the broker, and this appears to be the only exception being thrown over the past few days. Would be great to get this out of the service.

Really appreciate you guys helping me out on this.

Kind Regards,

Grant.

-------------- << SNIP >> ----------------------

> 172.17.0.3:1883)

2018-03-25 00:40:08.572 [error] <0.22461.59> Supervisor {<0.22461.59>,amqp_channel_sup_sup} had child channel_sup started with amqp_channel_sup:start_link(direct, <0.22342.59>, <<"1.128.105.82:63483 -> 172.17.0.3:1883">>) at undefined exit with reason shutdown in context shutd

own_error

2018-03-25 00:40:09.178 [info] <0.22351.59> closing MQTT connection <0.22351.59> (123.209.92.124:58977 -> 172.17.0.3:1883)

2018-03-25 00:40:09.660 [info] <0.23618.59> closing MQTT connection <0.23618.59> (1.128.111.205:27378 -> 172.17.0.3:1883)

2018-03-25 00:40:09.669 [warning] <0.21676.59> closing AMQP connection <0.21676.59> (172.17.0.1:39006 -> 172.17.0.3:5672, vhost: '/', user: 'guest'):

client unexpectedly closed TCP connection

2018-03-25 00:40:10.104 [info] <0.21369.59> closing MQTT connection <0.21369.59> (1.44.15.204:54601 -> 172.17.0.3:1883)

2018-03-25 00:40:10.104 [error] <0.21729.59> Supervisor {<0.21729.59>,amqp_channel_sup_sup} had child channel_sup started with amqp_channel_sup:start_link(direct, <0.21777.59>, <<"1.44.15.204:54601 -> 172.17.0.3:1883">>) at undefined exit with reason shutdown in context shutdo

wn_error

2018-03-25 00:40:11.448 [info] <0.22643.59> closing MQTT connection <0.22643.59> (1.128.106.20:27350 -> 172.17.0.3:1883)

2018-03-25 00:40:21.972 [error] <0.23697.59> ** Generic server <0.23697.59> terminating

** Last message in was {inet_async,#Port<0.892870>,7190,{ok,<<16,25,0,4,77,81,84,84,4,2,0,60,0,13,100,106,97,110,103,111,95,115,101,110,100,101,114,48,95,0,62,100,101,118,105,99,101,115,47,48,48,48,48,48,48,48,48,45,48,48,48,48,45,48,48,48,48,45,48,48,48,48,45,98,56,50,55,101,

98,99,49,100,51,48,100,47,99,111,110,102,105,103,47,97,108,101,114,116,95,100,101,102,115,120,218,171,86,10,115,13,10,246,244,247,83,178,82,48,52,53,52,53,53,48,51,54,50,169,5,0,72,141,5,189,224,0>>}}

** When Server state == {state,#Port<0.892870>,"172.17.0.1:42488 -> 172.17.0.3:1883",true,undefined,false,running,{none,none},<0.23698.59>,false,none,{proc_state,#Port<0.892870>,#{},{undefined,undefined},{0,nil},{0,nil},undefined,1,undefined,undefined,undefined,{undefined,unde

fined},undefined,<<"amq.topic">>,{amqp_adapter_info,{0,0,0,0,0,65535,44049,3},1883,{0,0,0,0,0,65535,44049,1},42488,<<"172.17.0.1:42488 -> 172.17.0.3:1883">>,{'MQTT',"N/A"},[{channels,1},{channel_max,1},{frame_max,0},{client_properties,[{<<"product">>,longstr,<<"MQTT client">>}

]},{ssl,false}]},none,undefined,undefined,#Fun<rabbit_mqtt_processor.0.96330891>},undefined,{state,fine,5000,undefined}}

** Reason for termination ==

** {{badmatch,{error,enotconn}},[{rabbit_mqtt_processor,process_login,4,[{file,"src/rabbit_mqtt_processor.erl"},{line,478}]},{rabbit_mqtt_processor,process_request,3,[{file,"src/rabbit_mqtt_processor.erl"},{line,112}]},{rabbit_mqtt_processor,process_frame,2,[{file,"src/rabbit_

mqtt_processor.erl"},{line,69}]},{rabbit_mqtt_reader,process_received_bytes,2,[{file,"src/rabbit_mqtt_reader.erl"},{line,270}]},{gen_server2,handle_msg,2,[{file,"src/gen_server2.erl"},{line,1050}]},{proc_lib,init_p_do_apply,3,[{file,"proc_lib.erl"},{line,247}]}]}

2018-03-25 00:40:21.972 [error] <0.23697.59> CRASH REPORT Process <0.23697.59> with 0 neighbours exited with reason: no match of right hand value {error,enotconn} in rabbit_mqtt_processor:process_login/4 line 478 in gen_server2:terminate/3 line 1166

2018-03-25 00:40:21.972 [error] <0.23702.59> Supervisor {<0.23702.59>,rabbit_mqtt_connection_sup} had child rabbit_mqtt_reader started with rabbit_mqtt_reader:start_link(<0.23698.59>, {acceptor,{0,0,0,0,0,0,0,0},1883}, #Port<0.892870>) at <0.23697.59> exit with reason no match

of right hand value {error,enotconn} in rabbit_mqtt_processor:process_login/4 line 478 in context child_terminated

2018-03-25 00:40:21.973 [error] <0.23702.59> Supervisor {<0.23702.59>,rabbit_mqtt_connection_sup} had child rabbit_mqtt_reader started with rabbit_mqtt_reader:start_link(<0.23698.59>, {acceptor,{0,0,0,0,0,0,0,0},1883}, #Port<0.892870>) at <0.23697.59> exit with reason reached_

max_restart_intensity in context shutdown

-------------- << SNIP >> ----------------------

2018-03-25 00:50:14.265 [info] <0.27476.59> closing MQTT connection <0.27476.59> (1.122.67.77:48047 -> 172.17.0.3:1883)

2018-03-25 00:50:22.247 [error] <0.28220.59> ** Generic server <0.28220.59> terminating

** Last message in was {inet_async,#Port<0.894934>,11565,{ok,<<16,25,0,4,77,81,84,84,4,2,0,60,0,13,100,106,97,110,103,111,95,115,101,110,100,101,114,48,95,0,62,100,101,118,105,99,101,115,47,48,48,48,48,48,48,48,48,45,48,48,48,48,45,48,48,48,48,45,48,48,48,48,45,98,56,50,55,101

,98,99,49,100,51,48,100,47,99,111,110,102,105,103,47,97,108,101,114,116,95,100,101,102,115,120,218,171,86,10,115,13,10,246,244,247,83,178,82,48,52,53,52,53,53,48,51,54,50,169,5,0,72,141,5,189,224,0>>}}

** When Server state == {state,#Port<0.894934>,"172.17.0.1:40394 -> 172.17.0.3:1883",true,undefined,false,running,{none,none},<0.28221.59>,false,none,{proc_state,#Port<0.894934>,#{},{undefined,undefined},{0,nil},{0,nil},undefined,1,undefined,undefined,undefined,{undefined,unde

fined},undefined,<<"amq.topic">>,{amqp_adapter_info,{0,0,0,0,0,65535,44049,3},1883,{0,0,0,0,0,65535,44049,1},40394,<<"172.17.0.1:40394 -> 172.17.0.3:1883">>,{'MQTT',"N/A"},[{channels,1},{channel_max,1},{frame_max,0},{client_properties,[{<<"product">>,longstr,<<"MQTT client">>}

]},{ssl,false}]},none,undefined,undefined,#Fun<rabbit_mqtt_processor.0.96330891>},undefined,{state,fine,5000,undefined}}

** Reason for termination ==

** {{badmatch,{error,enotconn}},[{rabbit_mqtt_processor,process_login,4,[{file,"src/rabbit_mqtt_processor.erl"},{line,478}]},{rabbit_mqtt_processor,process_request,3,[{file,"src/rabbit_mqtt_processor.erl"},{line,112}]},{rabbit_mqtt_processor,process_frame,2,[{file,"src/rabbit_

mqtt_processor.erl"},{line,69}]},{rabbit_mqtt_reader,process_received_bytes,2,[{file,"src/rabbit_mqtt_reader.erl"},{line,270}]},{gen_server2,handle_msg,2,[{file,"src/gen_server2.erl"},{line,1050}]},{proc_lib,init_p_do_apply,3,[{file,"proc_lib.erl"},{line,247}]}]}

2018-03-25 00:50:22.247 [error] <0.28220.59> CRASH REPORT Process <0.28220.59> with 0 neighbours exited with reason: no match of right hand value {error,enotconn} in rabbit_mqtt_processor:process_login/4 line 478 in gen_server2:terminate/3 line 1166

2018-03-25 00:50:22.248 [error] <0.28222.59> Supervisor {<0.28222.59>,rabbit_mqtt_connection_sup} had child rabbit_mqtt_reader started with rabbit_mqtt_reader:start_link(<0.28221.59>, {acceptor,{0,0,0,0,0,0,0,0},1883}, #Port<0.894934>) at <0.28220.59> exit with reason no match

of right hand value {error,enotconn} in rabbit_mqtt_processor:process_login/4 line 478 in context child_terminated

2018-03-25 00:50:22.248 [error] <0.28222.59> Supervisor {<0.28222.59>,rabbit_mqtt_connection_sup} had child rabbit_mqtt_reader started with rabbit_mqtt_reader:start_link(<0.28221.59>, {acceptor,{0,0,0,0,0,0,0,0},1883}, #Port<0.894934>) at <0.28220.59> exit with reason reached_

max_restart_intensity in context shutdown

2018-03-25 00:53:02.213 [error] <0.26061.59> closing MQTT connection "49.180.166.57:19316 -> 172.17.0.3:1883" (keepalive timeout)

-------------- << SNIP >> ----------------------

2018-03-25 01:00:22.916 [error] <0.32043.59> ** Generic server <0.32043.59> terminating

** Last message in was {inet_async,#Port<0.896888>,15914,{ok,<<16,25,0,4,77,81,84,84,4,2,0,60,0,13,100,106,97,110,103,111,95,115,101,110,100,101,114,48,95,0,62,100,101,118,105,99,101,115,47,48,48,48,48,48,48,48,48,45,48,48,48,48,45,48,48,48,48,45,48,48,48,48,45,98,56,50,55,101

,98,99,49,100,51,48,100,47,99,111,110,102,105,103,47,97,108,101,114,116,95,100,101,102,115,120,218,171,86,10,115,13,10,246,244,247,83,178,82,48,52,53,52,53,53,48,51,54,50,169,5,0,72,141,5,189,224,0>>}}

** When Server state == {state,#Port<0.896888>,"172.17.0.1:37652 -> 172.17.0.3:1883",true,undefined,false,running,{none,none},<0.31998.59>,false,none,{proc_state,#Port<0.896888>,#{},{undefined,undefined},{0,nil},{0,nil},undefined,1,undefined,undefined,undefined,{undefined,unde

fined},undefined,<<"amq.topic">>,{amqp_adapter_info,{0,0,0,0,0,65535,44049,3},1883,{0,0,0,0,0,65535,44049,1},37652,<<"172.17.0.1:37652 -> 172.17.0.3:1883">>,{'MQTT',"N/A"},[{channels,1},{channel_max,1},{frame_max,0},{client_properties,[{<<"product">>,longstr,<<"MQTT client">>}

]},{ssl,false}]},none,undefined,undefined,#Fun<rabbit_mqtt_processor.0.96330891>},undefined,{state,fine,5000,undefined}}

** Reason for termination ==

** {{badmatch,{error,enotconn}},[{rabbit_mqtt_processor,process_login,4,[{file,"src/rabbit_mqtt_processor.erl"},{line,478}]},{rabbit_mqtt_processor,process_request,3,[{file,"src/rabbit_mqtt_processor.erl"},{line,112}]},{rabbit_mqtt_processor,process_frame,2,[{file,"src/rabbit_

mqtt_processor.erl"},{line,69}]},{rabbit_mqtt_reader,process_received_bytes,2,[{file,"src/rabbit_mqtt_reader.erl"},{line,270}]},{gen_server2,handle_msg,2,[{file,"src/gen_server2.erl"},{line,1050}]},{proc_lib,init_p_do_apply,3,[{file,"proc_lib.erl"},{line,247}]}]}

2018-03-25 01:00:22.916 [error] <0.32043.59> CRASH REPORT Process <0.32043.59> with 0 neighbours exited with reason: no match of right hand value {error,enotconn} in rabbit_mqtt_processor:process_login/4 line 478 in gen_server2:terminate/3 line 1166

2018-03-25 01:00:22.917 [error] <0.31999.59> Supervisor {<0.31999.59>,rabbit_mqtt_connection_sup} had child rabbit_mqtt_reader started with rabbit_mqtt_reader:start_link(<0.31998.59>, {acceptor,{0,0,0,0,0,0,0,0},1883}, #Port<0.896888>) at <0.32043.59> exit with reason no match

of right hand value {error,enotconn} in rabbit_mqtt_processor:process_login/4 line 478 in context child_terminated

2018-03-25 01:00:22.918 [error] <0.31999.59> Supervisor {<0.31999.59>,rabbit_mqtt_connection_sup} had child rabbit_mqtt_reader started with rabbit_mqtt_reader:start_link(<0.31998.59>, {acceptor,{0,0,0,0,0,0,0,0},1883}, #Port<0.896888>) at <0.32043.59> exit with reason reached_

max_restart_intensity in context shutdown

2018-03-25 01:01:11.796 [info] <0.524.56> closing MQTT connection <0.524.56> (1.129.105.202:26420 -> 172.17.0.3:1883)

Michael Klishin

unread,

Mar 25, 2018, 4:57:09 PM3/25/18

to rabbitm...@googlegroups.com

> enotconn

it's a socket I/O exception: a socket operation returned an ENOTCONN on this line:
https://github.com/rabbitmq/rabbitmq-mqtt/blob/master/src/rabbit_mqtt_processor.erl#L478

which handles connection log in.

I/O exceptions are inevitable from time to time, as are client connection failures of all kinds.

--

You received this message because you are subscribed to the Google Groups "rabbitmq-users" group.

To unsubscribe from this group and stop receiving emails from it, send an email to rabbitmq-users+unsubscribe@googlegroups.com.

To post to this group, send email to rabbitmq-users@googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

--

Grant Traynor

unread,

Mar 25, 2018, 7:19:31 PM3/25/18

to rabbitm...@googlegroups.com

Hi Michael,

Thanks for that. So looks like normal behaviour now?

Thanks again for your help.

Regards,

Grant.

To post to this group, send email to rabbitm...@googlegroups.com.

For more options, visit https://groups.google.com/d/optout.

--
MK

Staff Software Engineer, Pivotal/RabbitMQ

--
You received this message because you are subscribed to a topic in the Google Groups "rabbitmq-users" group.
To unsubscribe from this topic, visit https://groups.google.com/d/topic/rabbitmq-users/b9KaU8M5MaE/unsubscribe.
To unsubscribe from this group and all its topics, send an email to rabbitmq-users+unsubscribe@googlegroups.com.

To post to this group, send email to rabbitmq-users@googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

--

Grant Traynor

unread,

Mar 27, 2018, 5:06:28 PM3/27/18

to rabbitmq-users

Just to follow up on this.

It appears as though the connection handling dynamics of 3.7.4 are quite different to 3.6.3.

After reviewing a few of our clients, it looks as though they were not publishing "correctly", using a method that we got away with in 3.6.3, but not in 3.7.4.

Specifically, some clients (using paho for python) were creating a client, sending a messing, calling loop, and then disconnecting:

- mqtt_connection = paho.Client()

- mqtt_connection.connect(settings.MQTT_HOST, settings.MQTT_PORT, 60, "")

- mqtt_connection.publish(topic, msg)

- mqtt_connection.loop()

- mqtt_connection.disconnect()

This appears to hangup the connection before RMQ has finished processing the request.

We've changed the clients to use the one-shot publish.single() method, which manages the connection/disconnection process cleanly:

+ publish.single(topic, msg, port=settings.MQTT_PORT, hostname=settings.MQTT_HOST)

Thanks again Michael and Luke for your help. Looking forward to the 3.7.5 release.

Kind Regards,

Grant.

Michael Klishin

unread,

Mar 27, 2018, 5:28:26 PM3/27/18

to rabbitm...@googlegroups.com

Opening a new connection per message is not how messaging protocols (including MQTT) are generally meant to be

used and there's the risk of TCP connection being closed prematurely.

Both protocols and client libraries provide ways to deal with that, e.g. see http://www.rabbitmq.com/confirms.html for

an AMQP 0-9-1-specific feature. MQTT QoS 1 should help with such cases but the implementation details will differ

from client to client. TCP socket lingering (SO_LINGER) values are important here and not dictated by MQTT the protocol

in any way, for instance.

If you can use longer-running connections, that's a good idea.

--
You received this message because you are subscribed to the Google Groups "rabbitmq-users" group.
To unsubscribe from this group and stop receiving emails from it, send an email to rabbitmq-users+unsubscribe@googlegroups.com.

To post to this group, send email to rabbitmq-users@googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

--

Michael Klishin

unread,

Mar 27, 2018, 5:34:42 PM3/27/18

to rabbitm...@googlegroups.com

I can't think of any major changes in that are in 3.7.x. We've switched to a different TCP acceptor

library in 3.6.0 but that's about it. Topic authorization may be introducing a bit of extra latency

depending on the backend.

But I do recall similar reports with mosquitto_pub where QoS 1 wasn't used, therefore the same

"fire and forget" took place. So your observations are unlikely to be just mere luck in one environment compared to the other.

--
You received this message because you are subscribed to the Google Groups "rabbitmq-users" group.
To unsubscribe from this group and stop receiving emails from it, send an email to rabbitmq-users+unsubscribe@googlegroups.com.

To post to this group, send email to rabbitmq-users@googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

--

Grant Traynor

unread,

Mar 27, 2018, 7:13:39 PM3/27/18

to rabbitm...@googlegroups.com

Hi Michael,

Thanks for that. Yes, I agree. The upgrade has brought a few of these issues to light.

Kind Regards,
Grant.

To post to this group, send email to rabbitm...@googlegroups.com.

For more options, visit https://groups.google.com/d/optout.

--
MK

Staff Software Engineer, Pivotal/RabbitMQ

--
You received this message because you are subscribed to a topic in the Google Groups "rabbitmq-users" group.
To unsubscribe from this topic, visit https://groups.google.com/d/topic/rabbitmq-users/b9KaU8M5MaE/unsubscribe.
To unsubscribe from this group and all its topics, send an email to rabbitmq-users+unsubscribe@googlegroups.com.

To post to this group, send email to rabbitmq-users@googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

--

Reply all

Reply to author

Forward