Decoding of connect message failed: EOF

[ptweety]

Hi,

ich verwende Node-RED und habe dort eine MQTT-Verbindung zum CCU-Jack eingerichtet. Wenn ich nun ins Log schaue, dann kommen wiederholt Meldungen, dass Decoding of connect message failed: EOF.

Wenn ich mit den selben Parametern (user, pass, host, port) eine Verbindung über den MQTT-Explorer starte, dann kommt die Warnung nicht. Dabei ist es egal, ob ich über Port 1883 oder 8883 komme ...

An was kann das liegen? Muss seitens Node-RED dort spezifisch ein Topic / Payload in den jeweiligen birth, close oder will Messages geliefert werden?

2023-02-12 21:58:09 | TRACE | veap-handler | Request body: {"v":{"CCU":{"Address":"127.0.0.1","Interfaces":["BidCosRF","HmIPRF","VirtualDevices"],"InitID":"CCU-Jack"},"Host":{"Name":"ccu3-webui","Addre…
-- | -- | -- | --
2023-02-12 21:58:09 | DEBUG | veap-handler | Request from 192.168.178.47:54783, method PUT, URL /~vendor/config/~pv
2023-02-12 21:58:07 | TRACE | script-client | HM script response: OK\n1674467985\nSome very important text\nOK\n1676204158\n1
2023-02-12 21:58:07 | TRACE | script-client | Executing HM script: ! Reading multiple values\nstring id; foreach(id,"15030 14089") {\n var dp=dom.GetObject(id);\n if (dp) {\n if (dp.IsTypeOf(OT_DP) \|\|…
2023-02-12 21:58:07 | DEBUG | script-client | Reading values of objects: 15030 14089
2023-02-12 21:58:04 | TRACE | veap-handler | Response code: 200
2023-02-12 21:58:04 | TRACE | veap-handler | Response body: {"ts":1676235484629,"v":{"CCU":{"Address":"127.0.0.1","Interfaces":["BidCosRF","HmIPRF","VirtualDevices"],"InitID":"CCU-Jack"},"Host":{"Name"…
2023-02-12 21:58:04 | DEBUG | veap-handler | Request from 192.168.178.47:54783, method GET, URL /~vendor/config/~pv
2023-02-12 21:58:04 | TRACE | script-client | HM script response: OK\n1676204158\n1\nOK\n1674467985\nSome very important text
2023-02-12 21:58:04 | TRACE | script-client | Executing HM script: ! Reading multiple values\nstring id; foreach(id,"14089 15030") {\n var dp=dom.GetObject(id);\n if (dp) {\n if (dp.IsTypeOf(OT_DP) \|\|…
2023-02-12 21:58:04 | DEBUG | script-client | Reading values of objects: 14089 15030
2023-02-12 21:58:03 | TRACE | xmlrpc-server | Response XML: <?xml version="1.0" encoding="ISO-8859-1"?>\n<methodResponse><params><param><value><array><data><value></value></data></array></value></param>…
2023-02-12 21:58:03 | TRACE | itf-intercon | Discarding PONG event
2023-02-12 21:58:03 | DEBUG | itf-server | Call of method event received: CCU-Jack-BidCos-RF, CENTRAL, PONG, nr
2023-02-12 21:58:03 | DEBUG | xmlrpc-server | Call of method system.multicall with 1 elements received
2023-02-12 21:58:03 | TRACE | xmlrpc-server | Request XML: <?xml version="1.0" encoding="iso-8859-1"?>\n<methodCall><methodName>system.multicall</methodName>\n<params><param><value><array><data><value><…
2023-02-12 21:58:03 | TRACE | xmlrpc-server | Request received from 127.0.0.1:41024, URI /RPC2
2023-02-12 21:58:02 | TRACE | veap-handler | Response code: 200
2023-02-12 21:58:02 | TRACE | veap-handler | Response body: {"ts":1676235482545,"v":{"Log":[["2023-02-12 21:58:02","DEBUG","veap-handler","Request from 192.168.178.47:54783, method GET, URL /~vendor/di…
2023-02-12 21:58:02 | DEBUG | veap-handler | Request from 192.168.178.47:54783, method GET, URL /~vendor/diagnostics/~pv
2023-02-12 21:58:01 | TRACE | script-client | HM script response: OK\n1674467985\nSome very important text\nOK\n1676204158\n1
2023-02-12 21:58:01 | TRACE | script-client | Executing HM script: ! Reading multiple values\nstring id; foreach(id,"15030 14089") {\n var dp=dom.GetObject(id);\n if (dp) {\n if (dp.IsTypeOf(OT_DP) \|\|…
2023-02-12 21:58:01 | DEBUG | script-client | Reading values of objects: 15030 14089
2023-02-12 21:57:58 | TRACE | script-client | HM script response: OK\n1674467985\nSome very important text\nOK\n1676204158\n1
2023-02-12 21:57:58 | TRACE | script-client | Executing HM script: ! Reading multiple values\nstring id; foreach(id,"15030 14089") {\n var dp=dom.GetObject(id);\n if (dp) {\n if (dp.IsTypeOf(OT_DP) \|\|…
2023-02-12 21:57:58 | DEBUG | script-client | Reading values of objects: 15030 14089
2023-02-12 21:57:57 | DEBUG | mqtt | (2663/nodered_14be0e5b6b6386de) Subscribing topic "program/#", 0 retained messages
2023-02-12 21:57:57 | DEBUG | mqtt | (2663/nodered_14be0e5b6b6386de) Subscribing topic "sysvar/#", 2 retained messages
2023-02-12 21:57:57 | DEBUG | mqtt | (2663/nodered_14be0e5b6b6386de) Subscribing topic "device/#", 612 retained messages
2023-02-12 21:57:57 | DEBUG | mqtt | (2663/nodered_14be0e5b6b6386de) Subscribing topic "virtdev/#", 0 retained messages
2023-02-12 21:57:57 | TRACE | veap-handler | Response code: 200
2023-02-12 21:57:57 | TRACE | veap-handler | Response body: [{"control":"RHS.STATE","default":"CLOSED","flags":1,"id":"STATE","identifier":"STATE","maximum":"OPEN","minimum":"CLOSED","mqttStatusTopic":…
2023-02-12 21:57:57 | DEBUG | veap-handler | Request from 192.168.178.47:54916, method GET, URL /~query?~path=/device/*/[^$]*/[^$]*&~path=/virtdev/*/[^$]*/[^$]*
2023-02-12 21:57:57 | TRACE | veap-handler | Response code: 200
2023-02-12 21:57:57 | TRACE | veap-handler | Response body: [{"address":"000393C994DA01:0","aesActive":1,"availableFirmware":"","children":null,"direction":0,"firmware":"","flags":1,"group":"","identif…
2023-02-12 21:57:56 | DEBUG | veap-handler | Request from 192.168.178.47:54911, method GET, URL /~query?~path=/device/*/[^$]*&~path=/virtdev/*/[^$]*
2023-02-12 21:57:56 | TRACE | veap-handler | Response code: 200
2023-02-12 21:57:56 | TRACE | veap-handler | Response body: [{"address":"001F98A99A3319","aesActive":1,"availableFirmware":"0.0.0","children":["001F98A99A3319:0"],"direction":0,"firmware":"4.4.22","fla…
2023-02-12 21:57:56 | TRACE | veap-handler | Response code: 200
2023-02-12 21:57:56 | TRACE | veap-handler | Response body: [{"active":true,"identifier":"14257","mqttGetTopic":"program/get/14257","mqttSetTopic":"program/set/14257","mqttStatusTopic":"program/status/…
2023-02-12 21:57:56 | TRACE | veap-handler | Response code: 200
2023-02-12 21:57:56 | TRACE | veap-handler | Response body: [{"description":"DutyCycle CCU","identifier":"4697","maximum":100,"minimum":-1,"mqttGetTopic":"sysvar/get/4697","mqttSetTopic":"sysvar/set/46…
2023-02-12 21:57:56 | DEBUG | veap-handler | Request from 192.168.178.47:54907, method GET, URL /~query?~path=/program/*
2023-02-12 21:57:56 | TRACE | veap-handler | Response code: 200
2023-02-12 21:57:56 | TRACE | veap-handler | Response body: [{"identifier":"1228","title":"Badezimmer","~links":[{"rel":"collection","href":"..","title":"Rooms"},{"rel":"channel","href":"/device/000393…
2023-02-12 21:57:56 | DEBUG | veap-handler | Request from 192.168.178.47:54906, method GET, URL /~query?~path=/sysvar/*
2023-02-12 21:57:56 | DEBUG | veap-handler | Request from 192.168.178.47:54908, method GET, URL /~query?~path=/room/*
2023-02-12 21:57:56 | DEBUG | veap-handler | Request from 192.168.178.47:54905, method GET, URL /~query?~path=/device/*
2023-02-12 21:57:56 | TRACE | veap-handler | Response code: 200
2023-02-12 21:57:56 | TRACE | veap-handler | Response body: [{"address":"JACK000000","aesActive":0,"availableFirmware":"","children":["JACK000000:0","JACK000000:1","JACK000000:2","JACK000000:3","JACK00…
2023-02-12 21:57:56 | DEBUG | veap-handler | Request from 192.168.178.47:54904, method GET, URL /~query?~path=/virtdev/*
2023-02-12 21:57:56 | TRACE | veap-handler | Response code: 200
2023-02-12 21:57:56 | TRACE | veap-handler | Response body: [{"identifier":"1217","title":"Sicherheit","~links":[{"rel":"collection","href":"..","title":"Functions"},{"rel":"channel","href":"/device/00…
2023-02-12 21:57:56 | DEBUG | veap-handler | Request from 192.168.178.47:54903, method GET, URL /~query?~path=/function/*
2023-02-12 21:57:56 | TRACE | veap-handler | Response code: 200
2023-02-12 21:57:56 | TRACE | veap-handler | Response body: [{"description":"Functions of the ReGaHss","identifier":"function","title":"Functions","~links":[{"rel":"function","href":"1221","title":"Ene…
2023-02-12 21:57:56 | DEBUG | veap-handler | Request from 192.168.178.47:54900, method GET, URL /~query?~path=/[a-z]*
2023-02-12 21:57:56 | TRACE | veap-handler | Response code: 200
2023-02-12 21:57:56 | TRACE | veap-handler | Response body: {"ts":-6795364578871,"v":false,"s":0}
2023-02-12 21:57:56 | DEBUG | veap-handler | Request from 192.168.178.47:54897, method GET, URL /~vendor/refresh/~pv
2023-02-12 21:57:56 | TRACE | veap-handler | Response code: 200
2023-02-12 21:57:56 | TRACE | veap-handler | Response body: {"description":"Root of the CCU-Jack VEAP server","identifier":"root","title":"Root","~links":[{"rel":"domain","href":"program","title":"Prog…
2023-02-12 21:57:56 | DEBUG | veap-handler | Request from 192.168.178.47:54895, method GET, URL /
2023-02-12 21:57:56 | TRACE | veap-handler | Response code: 200
2023-02-12 21:57:56 | TRACE | veap-handler | Response body: {"description":"Information about the server and the vendor","identifier":"~vendor","serverDescription":"REST/MQTT-Interface for the HomeMati…
2023-02-12 21:57:56 | DEBUG | veap-handler | Request from 192.168.178.47:54896, method GET, URL /~vendor
2023-02-12 21:57:56 | TRACE | veap-handler | Response code: 200
2023-02-12 21:57:56 | TRACE | veap-handler | Response body: {"ts":1676235476657,"v":{"CCU":{"Address":"127.0.0.1","Interfaces":["BidCosRF","HmIPRF","VirtualDevices"],"InitID":"CCU-Jack"},"Host":{"Name"…
2023-02-12 21:57:56 | DEBUG | veap-handler | Request from 192.168.178.47:54898, method GET, URL /~vendor/config/~pv
2023-02-12 21:57:55 | TRACE | script-client | HM script response: OK\n1674467985\nSome very important text\nOK\n1676204158\n1
2023-02-12 21:57:55 | TRACE | script-client | Executing HM script: ! Reading multiple values\nstring id; foreach(id,"15030 14089") {\n var dp=dom.GetObject(id);\n if (dp) {\n if (dp.IsTypeOf(OT_DP) \|\|…
2023-02-12 21:57:55 | DEBUG | script-client | Reading values of objects: 15030 14089
2023-02-12 21:57:55 | DEBUG | mqtt | (2663/nodered_14be0e5b6b6386de) Subscribing topic "device/status/000855699C48F0/+/PRESS_SHORT", 0 retained messages
2023-02-12 21:57:55 | DEBUG | mqtt | (2663/nodered_14be0e5b6b6386de) Connection established
2023-02-12 21:57:55 | TRACE | mqtt | (nodered_14be0e5b6b6386de) Authenticating user: mqtt
2023-02-12 21:57:55 | WARNING | mqtt | Decoding of connect message failed: EOF
2023-02-12 21:57:55 | WARNING | mqtt | Decoding of connect message failed: EOF
2023-02-12 21:57:55 | TRACE | mqtt | Client 192.168.178.47:54876 is connecting
2023-02-12 21:57:55 | TRACE | mqtt | Client 192.168.178.47:54877 is connecting
2023-02-12 21:57:55 | TRACE | mqtt | Client 192.168.178.47:54853 is connecting
2023-02-12 21:57:53 | WARNING | mqtt | (2661/nodered_baac0adb9fb9f581) Connection unexpectedly closed, sending Will message
2023-02-12 21:57:53 | DEBUG | mqtt | (2661/nodered_baac0adb9fb9f581) Sent 172322 bytes in 2075 messages
2023-02-12 21:57:53 | DEBUG | mqtt | (2661/nodered_baac0adb9fb9f581) Received 8468 bytes in 2076 messages
2023-02-12 21:57:53 | TRACE | mqtt | (2661/nodered_baac0adb9fb9f581) Closing connection
2023-02-12 21:57:52 | TRACE | script-client | HM script response: OK\n1674467985\nSome very important text\nOK\n1676204158\n1
2023-02-12 21:57:52 | TRACE | script-client | Executing HM script: ! Reading multiple values\nstring id; foreach(id,"15030 14089") {\n var dp=dom.GetObject(id);\n if (dp) {\n if (dp.IsTypeOf(OT_DP) \|\|…
2023-02-12 21:57:52 | DEBUG | script-client | Reading values of objects: 15030 14089
2023-02-12 21:57:49 | TRACE | script-client | HM script response: OK\n1674467985\nSome very important text\nOK\n1676204158\n1
2023-02-12 21:57:49 | TRACE | script-client | Executing HM script: ! Reading multiple values\nstring id; foreach(id,"15030 14089") {\n var dp=dom.GetObject(id);\n if (dp) {\n if (dp.IsTypeOf(OT_DP) \|\|…
2023-02-12 21:57:49 | DEBUG | script-client | Reading values of objects: 15030 14089
2023-02-12 21:57:49 | DEBUG | rtcfg | Configuration saved to file: ccu-jack.cfg
2023-02-12 21:57:47 | TRACE | veap-handler | Response code: 200
2023-02-12 21:57:47 | TRACE | veap-handler | Response body: {"ts":1676235467710,"v":{"Log":[["2023-02-12 21:57:47","DEBUG","veap-handler","Request from 192.168.178.47:54783, method GET, URL /~vendor/di…
2023-02-12 21:57:47 | DEBUG | veap-handler | Request from 192.168.178.47:54783, method GET, URL /~vendor/diagnostics/~pv
2023-02-12 21:57:46 | TRACE | script-client | HM script response: OK\n1674467985\nSome very important text\nOK\n1676204158\n1
2023-02-12 21:57:46 | TRACE | script-client | Executing HM script: ! Reading multiple values\nstring id; foreach(id,"15030 14089") {\n var dp=dom.GetObject(id);\n if (dp) {\n if (dp.IsTypeOf(OT_DP) \|\|…
2023-02-12 21:57:46 | DEBUG | script-client | Reading values of objects: 15030 14089
2023-02-12 21:57:46 | TRACE | veap-handler | Response code: 200
2023-02-12 21:57:46 | TRACE | veap-handler | Response body: {"ts":1676235466503,"v":{"CCU":{"Address":"127.0.0.1","Interfaces":["BidCosRF","HmIPRF","VirtualDevices"],"InitID":"CCU-Jack"},"Host":{"Name"…
2023-02-12 21:57:46 | DEBUG | veap-handler | Request from 192.168.178.47:54783, method GET, URL /~vendor/config/~pv
2023-02-12 21:57:46 | TRACE | veap-handler | Response code: 200

[ptweety]

Hi nochmals,

ich habe etwas den Code seitens Node-RED debugged und folgendes festgestellt:

Es gibt dort ein Feature, dass sich der interne MQTT-Client automatisch bei Neustart mit dem Broker verbindet

• ist das Feature aktiviert, dann taucht der Log-Eintrag in CCU-Jack auf
• sollte das Feature deaktiviert sein, dann taucht kein Eintrag im Log des CCU-Jack auf

Daher tippe ich derzeit auf ein Timing-Problem.

[mdzio]

Die Connect-Message vom MQTT-Client im Node-Red ist wohl ungültig, da sie zu kurz ist.

Verbindet sich der Client denn neu? Hat die Warnmeldung Auswirkungen auf die Funktion?

Probiert der Client es vielleicht als erstes mit MQTT Version 5.

[ptweety]

Verbindet sich der Client denn neu?

Ja, das scheint ohne Probleme zu verlaufen.

Hat die Warnmeldung Auswirkungen auf die Funktion?

Nein, außer eben der Warnung ist keine Einschränkung zu erkennen

Probiert der Client es vielleicht als erstes mit MQTT Version 5.

Das kann ich leider nicht sagen. Es gibt allerdings eine V5 Implementierung in Node-RED die an vielen Stellen im Code zu erkennen ist. Allerdings habe ich natürlich auf V3.1.1 eingestellt.

Mir fehlt allerdings etwas das Wissen, wie ich hier weiter debuggen kann.

Ich habe lediglich die Stellen im Code identifiziert, welche relevant sein mögen:

• hier erfolgt die Entscheidung zum autoConnect: https://github.com/node-red/node-red/blob/adfc5b3e98ea98e5c6c5da0660becbc6bc67fec3/packages/node_modules/%40node-red/nodes/core/network/10-mqtt.js#L708-L714
• hier wird versucht eine neue Verbindung aufzubauen: https://github.com/node-red/node-red/blob/adfc5b3e98ea98e5c6c5da0660becbc6bc67fec3/packages/node_modules/%40node-red/nodes/core/network/10-mqtt.js#L736-L741
• dabei wird nun eine externes Package genutzt: https://github.com/mqttjs/MQTT.js/blob/b3ce3da84147c86eb176759f53fa929e96de7969/lib/connect/index.js#L53-L58
• und ich vermute, dass ab hier die relevante Implementierung zu finden ist: https://github.com/mqttjs/MQTT.js/blob/b3ce3da84147c86eb176759f53fa929e96de7969/lib/client.js#L241-L254

Leider verstehe ich da zu wenig vom Protokoll, um da tiefer reinzugehen und auch zu verstehen, wo es klemmt.

Ich bin etwas ratlos, wie ich den Verbindungsaufbau nun weiter untersuchen kann. Am liebsten würde ich die Netzwerkpakete untersuchen, aber mit z.B. Wireshark kenne ich mich auch nicht aus.

Irgendwelche Empfehlungen deinerseits, was ich noch machen könnte?

[ptweety]

Hi,

ich habe etwas weiter debugged und komme so langsam zum Punkt, dass hier irgendwo der Wurm in Node-RED bzw. dem genutzten MQTT.js package liegt.

Dazu habe ich mal alles, was ich an Logs generieren konnte in eine zeitlich sortierte Liste zusammengefasst:

Zeitstempel	Dringlichkeit	Module	Meldung
-----------	-----------	-----------	-------------------
.	.	.	Alte Verbindung mit der clientId nodered_b28d13ed98a61b9f verschindet wegen Neustart
-----------	-----------	-----------	-------------------
2023-02-15 17:22:51	WARNING	mqtt	(136/nodered_b28d13ed98a61b9f) Connection unexpectedly closed, sending Will message
.	.	.	.
15 Feb 17:22:52	.	Node-RED	[info]
.	.	.	Welcome to Node-RED ===================
15 Feb 17:22:52	.	Node-RED	[info] Node-RED version: v3.0.2-git
15 Feb 17:22:52	.	Node-RED	[info] Node.js version: v18.12.1
15 Feb 17:22:52	.	Node-RED	[info] Darwin 22.2.0 arm64 LE
15 Feb 17:22:52	.	Node-RED	[info] Loading palette nodes
15 Feb 17:22:53	.	Node-RED	[debug] Module: @ptweety/node-red-contrib-ccu-jack 0.0.10 /Users/ptweety/Development/@ptweety/.node-red/node_modules/@ptweety/node-red-contrib-ccu-jack
15 Feb 17:22:53	.	Node-RED	[debug] node-red-contrib-ccu-jack version: 0.0.10
15 Feb 17:22:53	.	Node-RED	[info] Settings file : /Users/ptweety/Development/@ptweety/.node-red/settings.js
15 Feb 17:22:53	.	Node-RED	[info] Context store : 'default' [module=memory]
15 Feb 17:22:53	.	Node-RED	[info] User directory : /Users/ptweety/Development/@ptweety/.node-red
15 Feb 17:22:53	.	Node-RED	[warn] Projects disabled : set editorTheme.projects.enabled=true to enable
15 Feb 17:22:53	.	Node-RED	[info] Flows file : /Users/ptweety/Development/@ptweety/.node-red/flows.json
15 Feb 17:22:53	.	Node-RED	[info] Server now running at http://127.0.0.1:1880/
15 Feb 17:22:53	.	Node-RED	[debug] loaded flow revision: 27bca16feecc7564bd6958bb5a0d21d5
15 Feb 17:22:53	.	Node-RED	[debug] red/runtime/nodes/credentials.load : user provided key
15 Feb 17:22:53	.	Node-RED	[debug] red/runtime/nodes/credentials.load : keyType=user
15 Feb 17:22:53	.	Node-RED	[info] Starting flows
15 Feb 17:22:53	.	Node-RED	[debug] red/nodes/flows.start : starting flow : global
15 Feb 17:22:53	.	Node-RED	[debug] red/nodes/flows.start : starting flow : 41722688f844f9e1
15 Feb 17:22:53	.	Node-RED	[debug] red/nodes/flows.start : starting flow : 62591c5e2ae416a5
-----------	-----------	-----------	-------------------
.	.	.	Ab hier totale Verwirrung mit der clientId nodered_25c7528b039477a6, welche nirgends im log des CCU-Jack auftaucht
-----------	-----------	-----------	-------------------
15 Feb 17:22:53	.	Node-RED	[info] [mqtt-broker:jack-broker] pre-connect
.	.	mqttjs	connecting to an MQTT broker... +0ms
.	.	mqttjs:client	MqttClient :: options.protocol mqtts +0ms
.	.	mqttjs:client	MqttClient :: options.protocolVersion 4 +0ms
.	.	mqttjs:client	MqttClient :: options.username mqtt +0ms
.	.	mqttjs:client	MqttClient :: options.keepalive 60 +0ms
.	.	mqttjs:client	MqttClient :: options.reconnectPeriod 5000 +0ms
.	.	mqttjs:client	MqttClient :: options.rejectUnauthorized false +0ms
.	.	mqttjs:client	MqttClient :: options.topicAliasMaximum undefined +0ms
.	.	mqttjs:client	MqttClient :: clientId nodered_25c7528b039477a6 +0ms
.	.	mqttjs:client	MqttClient :: setting up stream +1ms
.	.	mqttjs:client	_setupStream :: calling method to clear reconnect +0ms
.	.	mqttjs:client	_clearReconnect : clearing reconnect timer +0ms
.	.	mqttjs:client	_setupStream :: using streamBuilder provided to client to create stream +0ms
.	.	mqttjs	calling streambuilder for mqtts +1ms
.	.	mqttjs:client	_setupStream :: pipe stream to writable stream +19ms
.	.	mqttjs:client	_setupStream: sending packet connect +0ms
.	.	mqttjs:client	sendPacket :: packet: { cmd: 'connect' } +0ms
.	.	mqttjs:client	sendPacket :: emitting packetsend +1ms
.	.	mqttjs:client	sendPacket :: writing to stream +0ms
.	.	mqttjs:client	sendPacket :: writeToStream result true +8ms
15 Feb 17:22:53	.	Node-RED	[info] [mqtt-broker:jack-broker] post-connect
15 Feb 17:22:53	.	Node-RED	[info] Started flows
15 Feb 17:22:53	.	Node-RED	[debug] [inject:root] repeat = 21600000
.	.	mqttjs:client	writable stream :: parsing buffer +142ms
.	.	mqttjs:client	parser :: on packet push to packets array. +1ms
.	.	mqttjs:client	work :: getting next packet in queue +0ms
.	.	mqttjs:client	work :: packet pulled from queue +0ms
.	.	mqttjs:client	_handlePacket :: emitting packetreceive +0ms
.	.	mqttjs:client	_handleConnack +0ms
.	.	mqttjs:client	_setupPingTimer :: keepalive 60 (seconds) +0ms
.	.	mqttjs:client	connect :: sending queued packets +1ms
.	.	mqttjs:client	deliver :: entry undefined +0ms
.	.	mqttjs:client	_resubscribe +0ms
15 Feb 17:22:53	.	Node-RED	[info] [mqtt-broker:jack-broker] Connected to broker: mqtts://ccu3-webui.fritz.box:8883
.	.	mqttjs:client	publish :: message { "v": "connected", "s": 0 } to topic conn/nodered +1ms
.	.	mqttjs:client	publish :: qos 0 +0ms
.	.	mqttjs:client	MqttClient:publish: packet cmd: publish +0ms
.	.	mqttjs:client	_sendPacket :: (nodered_25c7528b039477a6) :: start +0ms
.	.	mqttjs:client	sendPacket :: packet: {
.	.	mqttjs:client	cmd: 'publish',
.	.	mqttjs:client	topic: 'conn/nodered',
.	.	mqttjs:client	payload: '{ "v": "connected", "s": 0 }',
.	.	mqttjs:client	qos: 0,
.	.	mqttjs:client	retain: false,
.	.	mqttjs:client	messageId: 0,
.	.	mqttjs:client	dup: false
.	.	mqttjs:client	} +0ms
.	.	mqttjs:client	sendPacket :: emitting packetsend +0ms
.	.	mqttjs:client	sendPacket :: writing to stream +0ms
.	.	mqttjs:client	sendPacket :: writeToStream result true +0ms
.	.	mqttjs:client	sendPacket :: invoking cb +1ms
.	.	mqttjs:client	_sendPacket :: (nodered_25c7528b039477a6) :: end +0ms
15 Feb 17:23:14	.	Node-RED	[debug] saved flow revision: 01ca028aa3041ee2d9d01a0999048e0e
15 Feb 17:23:14	.	Node-RED	[info] Stopping modified nodes
15 Feb 17:23:14	.	Node-RED	[debug] red/nodes/flows.stop : stopping flow : 41722688f844f9e1
.	.	mqttjs:client	publish :: message { "v": "disconnecting", "s": 100 } to topic conn/nodered +21s
.	.	mqttjs:client	publish :: qos 0 +0ms
.	.	mqttjs:client	MqttClient:publish: packet cmd: publish +0ms
.	.	mqttjs:client	_sendPacket :: (nodered_25c7528b039477a6) :: start +0ms
.	.	mqttjs:client	sendPacket :: packet: {
.	.	mqttjs:client	cmd: 'publish',
.	.	mqttjs:client	topic: 'conn/nodered',
.	.	mqttjs:client	payload: '{ "v": "disconnecting", "s": 100 }',
.	.	mqttjs:client	qos: 0,
.	.	mqttjs:client	retain: false,
.	.	mqttjs:client	messageId: 0,
.	.	mqttjs:client	dup: false
.	.	mqttjs:client	} +0ms
.	.	mqttjs:client	sendPacket :: emitting packetsend +0ms
.	.	mqttjs:client	sendPacket :: writing to stream +0ms
.	.	mqttjs:client	sendPacket :: writeToStream result true +0ms
.	.	mqttjs:client	sendPacket :: invoking cb +0ms
.	.	mqttjs:client	end :: (nodered_25c7528b039477a6) +0ms
.	.	mqttjs:client	end :: cb? true +0ms
.	.	mqttjs:client	_clearReconnect : clearing reconnect timer +0ms
.	.	mqttjs:client	end :: (nodered_25c7528b039477a6) :: immediately calling finish +0ms
.	.	mqttjs:client	end :: (nodered_25c7528b039477a6) :: finish :: calling _cleanUp with force false +0ms
.	.	mqttjs:client	_cleanUp :: done callback provided for on stream close +0ms
.	.	mqttjs:client	_cleanUp :: forced? false +0ms
.	.	mqttjs:client	_cleanUp :: (nodered_25c7528b039477a6) :: call _sendPacket with disconnect packet +0ms
.	.	mqttjs:client	_sendPacket :: (nodered_25c7528b039477a6) :: start +0ms
.	.	mqttjs:client	sendPacket :: packet: { cmd: 'disconnect' } +0ms
.	.	mqttjs:client	sendPacket :: emitting packetsend +0ms
.	.	mqttjs:client	sendPacket :: writing to stream +0ms
.	.	mqttjs:client	sendPacket :: writeToStream result true +0ms
.	.	mqttjs:client	sendPacket :: invoking cb +0ms
.	.	mqttjs:client	_cleanUp :: clearing pingTimer +1ms
.	.	mqttjs:client	_sendPacket :: (nodered_25c7528b039477a6) :: end +0ms
15 Feb 17:23:14	.	Node-RED	[debug] red/nodes/flows.stop : stopping flow : 62591c5e2ae416a5
15 Feb 17:23:14	.	Node-RED	[debug] red/nodes/flows.stop : stopping flow : global
15 Feb 17:23:14	.	Node-RED	[info] Stopped modified nodes
15 Feb 17:23:14	.	Node-RED	[info] Updated flows
15 Feb 17:23:14	.	Node-RED	[info] Starting modified nodes
15 Feb 17:23:14	.	Node-RED	[info] Started modified nodes
.	.	.	.
2023-02-15 17:24:20	DEBUG	rtcfg	Configuration saved to file: ccu-jack.cfg
.	.	.	.
.	.	mqttjs:client	(nodered_25c7528b039477a6)stream :: on close +10ms
.	.	mqttjs:client	flushVolatile :: deleting volatile messages from the queue and setting their callbacks as error function +0ms
.	.	mqttjs:client	stream: emit close to MqttClient +0ms
.	.	mqttjs:client	close :: connected set to false +0ms
.	.	mqttjs:client	close :: clearing connackTimer +0ms
.	.	mqttjs:client	close :: clearing ping timer +0ms
.	.	mqttjs:client	close :: calling _setupReconnect +0ms
.	.	mqttjs:client	_setupReconnect :: doing nothing... +0ms
.	.	mqttjs:client	end :: finish :: calling process.nextTick on closeStores +0ms
.	.	mqttjs:client	end :: closeStores: closing incoming and outgoing stores +0ms
.	.	mqttjs:client	end :: closeStores: emitting end +0ms
.	.	mqttjs:client	end :: closeStores: invoking callback with args +0ms
-----------	-----------	-----------	-------------------
.	.	.	Ab hier nachvollziehbar ein Verbindungsaufbau mit der clientId nodered_bebfa12b176b5c71
-----------	-----------	-----------	-------------------
.	.	mqttjs	connecting to an MQTT broker... +1m
.	.	mqttjs:client	MqttClient :: options.protocol mqtts +1m
.	.	mqttjs:client	MqttClient :: options.protocolVersion 4 +0ms
.	.	mqttjs:client	MqttClient :: options.username mqtt +0ms
.	.	mqttjs:client	MqttClient :: options.keepalive 60 +0ms
.	.	mqttjs:client	MqttClient :: options.reconnectPeriod 5000 +0ms
.	.	mqttjs:client	MqttClient :: options.rejectUnauthorized false +0ms
.	.	mqttjs:client	MqttClient :: options.topicAliasMaximum undefined +0ms
.	.	mqttjs:client	MqttClient :: clientId nodered_bebfa12b176b5c71 +1ms
.	.	mqttjs:client	MqttClient :: setting up stream +0ms
.	.	mqttjs:client	_setupStream :: calling method to clear reconnect +0ms
.	.	mqttjs:client	_clearReconnect : clearing reconnect timer +0ms
.	.	mqttjs:client	_setupStream :: using streamBuilder provided to client to create stream +0ms
.	.	mqttjs	calling streambuilder for mqtts +2ms
.	.	mqttjs:client	_setupStream :: pipe stream to writable stream +1ms
.	.	mqttjs:client	_setupStream: sending packet connect +1ms
.	.	mqttjs:client	sendPacket :: packet: { cmd: 'connect' } +0ms
.	.	mqttjs:client	sendPacket :: emitting packetsend +0ms
.	.	mqttjs:client	sendPacket :: writing to stream +0ms
.	.	mqttjs:client	sendPacket :: writeToStream result true +0ms
.	.	mqttjs:client	writable stream :: parsing buffer +200ms
.	.	mqttjs:client	parser :: on packet push to packets array. +0ms
.	.	mqttjs:client	work :: getting next packet in queue +0ms
.	.	mqttjs:client	work :: packet pulled from queue +1ms
.	.	mqttjs:client	_handlePacket :: emitting packetreceive +0ms
.	.	mqttjs:client	_handleConnack +0ms
.	.	mqttjs:client	_setupPingTimer :: keepalive 60 (seconds) +0ms
.	.	mqttjs:client	connect :: sending queued packets +0ms
.	.	mqttjs:client	deliver :: entry undefined +0ms
.	.	mqttjs:client	_resubscribe +0ms
15 Feb 17:24:21	.	Node-RED	[info] [mqtt-broker:jack-broker] Connected to broker: mqtts://ccu3-webui.fritz.box:8883
.	.	mqttjs:client	publish :: message { "v": "connected", "s": 0 } to topic conn/nodered +2ms
.	.	mqttjs:client	publish :: qos 0 +0ms
.	.	mqttjs:client	MqttClient:publish: packet cmd: publish +0ms
.	.	mqttjs:client	_sendPacket :: (nodered_bebfa12b176b5c71) :: start +1ms
.	.	mqttjs:client	sendPacket :: packet: {
.	.	mqttjs:client	cmd: 'publish',
.	.	mqttjs:client	topic: 'conn/nodered',
.	.	mqttjs:client	payload: '{ "v": "connected", "s": 0 }',
.	.	mqttjs:client	qos: 0,
.	.	mqttjs:client	retain: false,
.	.	mqttjs:client	messageId: 0,
.	.	mqttjs:client	dup: false
.	.	mqttjs:client	} +0ms
.	.	mqttjs:client	sendPacket :: emitting packetsend +0ms
.	.	mqttjs:client	sendPacket :: writing to stream +0ms
.	.	mqttjs:client	sendPacket :: writeToStream result true +1ms
.	.	mqttjs:client	sendPacket :: invoking cb +0ms
.	.	mqttjs:client	_sendPacket :: (nodered_bebfa12b176b5c71) :: end +0ms
.	.	.	.
2023-02-15 17:24:21	TRACE	mqtt	Client 192.168.178.47:50838 is connecting
2023-02-15 17:24:21	TRACE	mqtt	(nodered_bebfa12b176b5c71) Authenticating user: mqtt
2023-02-15 17:24:21	DEBUG	mqtt	(138/nodered_bebfa12b176b5c71) Connection established
.	.	.	.
15 Feb 17:24:28	.	Node-RED	[info] [jack-config:3014F711A0001F98A99A3319] Connecting to VEAP server https://ccu3-webui.fritz.box:2122
-----------	-----------	-----------	-------------------
.	.	.	Und hier nun die Warnung zur connect message, zu dem keinerlei log auf node-Seite existiert.
-----------	-----------	-----------	-------------------
2023-02-15 17:24:28	TRACE	mqtt	Client 192.168.178.47:50860 is connecting
2023-02-15 17:24:28	TRACE	mqtt	Client 192.168.178.47:50859 is connecting
2023-02-15 17:24:28	WARNING	mqtt	Decoding of connect message failed: EOF
2023-02-15 17:24:28	WARNING	mqtt	Decoding of connect message failed: EOF
.	.	.	.
15 Feb 17:24:29	.	Node-RED	[debug] [jack-config:3014F711A0001F98A99A3319] Requesting configuration
2023-02-15 17:24:29	DEBUG	veap-handler	Request from 192.168.178.47:50862, method GET, URL /
2023-02-15 17:24:29	TRACE	veap-handler	Response body: {"description":"Root of the CCU-Jack VEAP server","identifier":"root",...}
2023-02-15 17:24:29	TRACE	veap-handler	Response code: 200
15 Feb 17:24:29	.	Node-RED	[debug] GET request: https://ccu3-webui.fritz.box:2122/, duration: 169
.	.	.	.
2023-02-15 17:24:29	DEBUG	veap-handler	Request from 192.168.178.47:50863, method GET, URL /~vendor
2023-02-15 17:24:29	TRACE	veap-handler	Response body: {"description":"Information about the server and the vendor","identifier":"~vendor",...}
2023-02-15 17:24:29	TRACE	veap-handler	Response code: 200
15 Feb 17:24:29	.	Node-RED	[debug] GET request: https://ccu3-webui.fritz.box:2122/~vendor, duration: 172
.	.	.	.
2023-02-15 17:24:29	DEBUG	veap-handler	Request from 192.168.178.47:50864, method GET, URL /~vendor/refresh/~pv
2023-02-15 17:24:29	TRACE	veap-handler	Response body: {"ts":-6795364578871,"v":false,"s":0}
2023-02-15 17:24:29	TRACE	veap-handler	Response code: 200
15 Feb 17:24:29	.	Node-RED	[debug] GET request: https://ccu3-webui.fritz.box:2122/~vendor/refresh/~pv, duration: 174
.	.	.	.
2023-02-15 17:24:29	DEBUG	veap-handler	Request from 192.168.178.47:50865, method GET, URL /~vendor/config/~pv
2023-02-15 17:24:29	TRACE	veap-handler	Response body: {"ts":1676478269554,"v":{"CCU":...},"s":0}
2023-02-15 17:24:29	TRACE	veap-handler	Response code: 200
15 Feb 17:24:29	.	Node-RED	[debug] GET request: https://ccu3-webui.fritz.box:2122/~vendor/config/~pv, duration: 177

@mdzio: wenn dir dazu nun nichts mehr einfällt, dann können wir das issue als interessante Beobachtung einordnen und schließen.

[mdzio]

Neue Erkenntnisse hat das Log leider nicht gebracht. Da würde dann nur weiteres Debugging des Javascript-Codes oder der Einsatz von Wireshark o.ä. helfen. Ich schließe dann diesen Eintrag wie vorgeschlagen.