Mosquitto[18467]: Invalid protocol "MQTT" in CONNECT from 68.96.x.x

Myron · September 11, 2019, 8:51pm

Thanks for looking, I don’t know what else I can try.

Platform information: ubuntu 14
- Hardware: x86
- OS: Ubuntu 14.04.6 LTS
- Java Runtime Environment: openjdk version “1.8.0_222”
- openHAB version: 2.4.0-1
Issue of the topic: Although mosquitto is running, the MQTT broker don’t write to mysql.
mosquitto service is running and mosquitto_sub and mosquitto_pub work.
mysql is running
Items configuration:default.items
Number 826618bme280temp " esp8266.18 Temp [%.2f F]" (gAll)
{mqtt="<[mosquitto:/sensor18/temperature/degree:state:default]"}
- Sitemap configuration related to the issue
- Rules code related to the issue
- Services configuration

addons.cfg mt
        
    jdbc.cfg
        #tableUseRealItemNames=
    url=jdbc:mysql://localhost:3306/openhab?useUnicode=true&useJDBCCompliantTimezone
Shift=true&useLegacyDatetimeCode=false&serverTimezone=America/Chicago
user=openhab
password=asdf    
    mqtt.cfg 
mosquitto.url=tcp://localhost:1883
        name=mosquitto
host=localhost
port=1883
secure=false
username=openhab
password=asdf
    mysql.cfg
        url=jdbc:mysql://localhost/openhab?useUnicode=true&useJDBCCompliantTimezoneShift=
true&useLegacyDatetimeCode=false&serverTimezone=America/Chicago
user=openhab
password=asdf
localtime=true
    runtime.cfg 
        mt

*logs
openhab-cli console:

openhab> log:tail
15:13:04.913 [INFO ] [org.quartz.core.QuartzScheduler      ] - Scheduler openHAB-job-scheduler_$_NON_CLUSTERED paused.
15:13:05.180 [INFO ] [del.core.internal.ModelRepositoryImpl] - Loading model 'default.sitemap'
15:13:05.351 [INFO ] [del.core.internal.ModelRepositoryImpl] - Loading model 'mqtt.things'
15:13:05.739 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'exec:command:8885a44f' changed from UNINITIALIZED to INITIALIZING
15:13:05.749 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'exec:command:8885a44f' changed from INITIALIZING to ONLINE
15:13:05.776 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'exec:command:31da3c65' changed from UNINITIALIZED to INITIALIZING
15:13:05.802 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'exec:command:31da3c65' changed from INITIALIZING to ONLINE
15:13:05.931 [INFO ] [rvice.internal.HttpServiceFactoryImpl] - Binding bundle: [org.eclipse.smarthome.ui_0.10.0.oh240 [149]] to http service
15:13:06.057 [INFO ] [org.ops4j.pax.web.utils.ClassPathUtil] - Ignoring bundle scan for /META-INF/services javax.servlet.ServletContainerInitializer.
15:13:06.064 [INFO ] [ice.jetty.internal.HttpServiceContext] - registering context DefaultHttpContext [bundle=org.eclipse.smarthome.ui_0.10.0.oh240 [149], contextID=default], with context-name:
15:13:06.123 [INFO ] [e.jetty.server.handler.ContextHandler] - Started HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.eclipse.smarthome.ui_0.10.0.oh240 [149], contextID=default]}
15:13:06.156 [INFO ] [org.ops4j.pax.web.utils.ClassPathUtil] - Ignoring bundle scan for /META-INF/services javax.servlet.ServletContainerInitializer.
15:13:06.163 [INFO ] [ice.jetty.internal.HttpServiceContext] - registering context DefaultHttpContext [bundle=org.eclipse.smarthome.ui_0.10.0.oh240 [149], contextID=custom], with context-name:
15:13:06.176 [INFO ] [e.jetty.server.handler.ContextHandler] - Started HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.eclipse.smarthome.ui_0.10.0.oh240 [149], contextID=custom]}
15:13:06.205 [INFO ] [rvice.internal.HttpServiceFactoryImpl] - Binding bundle: [org.eclipse.smarthome.ui.icon_0.10.0.oh240 [150]] to http service
15:13:06.210 [INFO ] [org.ops4j.pax.web.utils.ClassPathUtil] - Ignoring bundle scan for /META-INF/services javax.servlet.ServletContainerInitializer.
15:13:06.218 [INFO ] [ice.jetty.internal.HttpServiceContext] - registering context DefaultHttpContext [bundle=org.eclipse.smarthome.ui.icon_0.10.0.oh240 [150], contextID=default], with context-name:
15:13:06.222 [INFO ] [e.jetty.server.handler.ContextHandler] - Started HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.eclipse.smarthome.ui.icon_0.10.0.oh240 [150], contextID=default]}
15:13:06.369 [INFO ] [rvice.internal.HttpServiceFactoryImpl] - Binding bundle: [org.openhab.ui.dashboard_2.4.0 [184]] to http service
15:13:06.384 [INFO ] [org.ops4j.pax.web.utils.ClassPathUtil] - Ignoring bundle scan for /META-INF/services javax.servlet.ServletContainerInitializer.
15:13:06.389 [INFO ] [ice.jetty.internal.HttpServiceContext] - registering context DefaultHttpContext [bundle=org.openhab.ui.dashboard_2.4.0 [184], contextID=default], with context-name:
15:13:06.408 [INFO ] [e.jetty.server.handler.ContextHandler] - Started HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.openhab.ui.dashboard_2.4.0 [184], contextID=default]}
15:13:06.413 [INFO ] [i.dashboard.internal.DashboardService] - Started Dashboard at http://192.168.1.45:9090
15:13:06.414 [INFO ] [i.dashboard.internal.DashboardService] - Started Dashboard at https://192.168.1.45:8443
15:13:06.595 [INFO ] [rvice.internal.HttpServiceFactoryImpl] - Binding bundle: [org.eclipse.smarthome.ui.basic_0.10.0.oh240 [192]] to http service
15:13:06.614 [INFO ] [org.ops4j.pax.web.utils.ClassPathUtil] - Ignoring bundle scan for /META-INF/services javax.servlet.ServletContainerInitializer.
15:13:06.624 [INFO ] [ice.jetty.internal.HttpServiceContext] - registering context DefaultHttpContext [bundle=org.eclipse.smarthome.ui.basic_0.10.0.oh240 [192], contextID=custom], with context-name:
15:13:06.628 [INFO ] [e.jetty.server.handler.ContextHandler] - Started HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.eclipse.smarthome.ui.basic_0.10.0.oh240 [192], contextID=custom]}
15:13:06.657 [INFO ] [org.ops4j.pax.web.utils.ClassPathUtil] - Ignoring bundle scan for /META-INF/services javax.servlet.ServletContainerInitializer.
15:13:06.669 [INFO ] [ice.jetty.internal.HttpServiceContext] - registering context DefaultHttpContext [bundle=org.eclipse.smarthome.ui.basic_0.10.0.oh240 [192], contextID=custom], with context-name:
15:13:06.674 [INFO ] [e.jetty.server.handler.ContextHandler] - Started HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.eclipse.smarthome.ui.basic_0.10.0.oh240 [192], contextID=custom]}
15:13:06.737 [INFO ] [rvice.internal.HttpServiceFactoryImpl] - Binding bundle: [org.eclipse.smarthome.ui.paper_0.10.0.oh240 [193]] to http service
15:13:06.753 [INFO ] [org.ops4j.pax.web.utils.ClassPathUtil] - Ignoring bundle scan for /META-INF/services javax.servlet.ServletContainerInitializer.
15:13:06.764 [INFO ] [ice.jetty.internal.HttpServiceContext] - registering context DefaultHttpContext [bundle=org.eclipse.smarthome.ui.paper_0.10.0.oh240 [193], contextID=custom], with context-name:
15:13:06.776 [INFO ] [e.jetty.server.handler.ContextHandler] - Started HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.eclipse.smarthome.ui.paper_0.10.0.oh240 [193], contextID=custom]}
15:13:06.778 [INFO ] [marthome.ui.paper.internal.PaperUIApp] - Started Paper UI at /paperui
15:13:07.896 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'mqtt:broker:8cdfdd75' changed from UNINITIALIZED to INITIALIZING
15:13:07.964 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'mqtt:broker:8cdfdd75' changed from INITIALIZING to OFFLINE
15:13:08.054 [INFO ] [o.transport.mqtt.MqttBrokerConnection] - Starting MQTT broker connection to '127.0.0.1' with clientid paho4242043693060978 and file store '/var/lib/openhab2/mqtt/127.0.0.1'
15:13:08.109 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'mqtt:broker:mosquitto' changed from UNINITIALIZED to INITIALIZING
15:13:08.123 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'mqtt:broker:mosquitto' changed from INITIALIZING to OFFLINE
15:13:08.124 [INFO ] [o.transport.mqtt.MqttBrokerConnection] - Starting MQTT broker connection to '127.0.0.1' with clientid openhab and file store '/var/lib/openhab2/mqtt/127.0.0.1'
15:13:08.212 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'mqtt:broker:8cdfdd75' changed from OFFLINE to ONLINE
15:13:08.222 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'mqtt:broker:mosquitto' changed from OFFLINE to ONLINE
15:13:08.247 [INFO ] [smarthome.event.ThingUpdatedEvent    ] - Thing 'mqtt:broker:8cdfdd75' has been updated.
15:13:10.181 [INFO ] [rvice.internal.HttpServiceFactoryImpl] - Binding bundle: [org.openhab.core_2.4.0 [180]] to http service
15:13:10.192 [INFO ] [org.ops4j.pax.web.utils.ClassPathUtil] - Ignoring bundle scan for /META-INF/services javax.servlet.ServletContainerInitializer.
15:13:10.202 [INFO ] [ice.jetty.internal.HttpServiceContext] - registering context DefaultHttpContext [bundle=org.openhab.core_2.4.0 [180], contextID=default], with context-name:
15:13:10.246 [INFO ] [e.jetty.server.handler.ContextHandler] - Started HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.openhab.core_2.4.0 [180], contextID=default]}
15:13:10.431 [INFO ] [org.quartz.core.QuartzScheduler      ] - Scheduler openHAB-job-scheduler_$_NON_CLUSTERED started.

/var/log/syslog shows mosquitto errors (probably configuration error) a sensor is trying to connect.

ed@Ed:~$ tail -f /var/log/syslog
Sep 11 15:25:25 Ed mosquitto[18467]: New connection from 68.96.21.83.
Sep 11 15:25:25 Ed mosquitto[18467]: Invalid protocol "MQTT" in CONNECT from 68.96.21.83.
Sep 11 15:25:25 Ed mosquitto[18467]: Socket read error on client (null), disconnecting.
Sep 11 15:25:40 Ed mosquitto[18467]: New connection from 68.96.21.83.
Sep 11 15:25:40 Ed mosquitto[18467]: Invalid protocol "MQTT" in CONNECT from 68.96.21.83.
Sep 11 15:25:40 Ed mosquitto[18467]: Socket read error on client (null), disconnecting.
Sep 11 15:25:55 Ed mosquitto[18467]: New connection from 68.96.21.83.
Sep 11 15:25:56 Ed mosquitto[18467]: Invalid protocol "MQTT" in CONNECT from 68.96.21.83.
Sep 11 15:25:56 Ed mosquitto[18467]: Socket read error on client (null), disconnecting.
Sep 11 15:26:01 Ed CRON[25947]: (ed) CMD (/home/ed/movecam1jpg >> /dev/null 2>&1)
Sep 11 15:26:11 Ed mosquitto[18467]: New connection from 68.96.21.83.
Sep 11 15:26:11 Ed mosquitto[18467]: Invalid protocol "MQTT" in CONNECT from 68.96.21.83.
Sep 11 15:26:11 Ed mosquitto[18467]: Socket read error on client (null), disconnecting.

rossko57 · September 11, 2019, 10:05pm

{mqtt="<[ ...
is an MQTT version 1 binding syntax.
It will not work with the Things and channels based MQTT version 2 binding.

You’ve got two different broker Things defined in your system. Probably one by PaperUI and one by xxx.things file.
That’s not necessarily a disaster, but I’m guessing it is not what you intended.

I don’t suppose any of that is related to your issue with Mosquitto and MySQL, I’m not really sure what you are trying to do there.

Myron · September 12, 2019, 1:07pm

Thanks a lot for your help, getting me in the right direction.