MQTT + JS Scripting = WARN spam in logs

After upgrade to OH4.1 and JS Scripting installed, all my js transformations, which i wrote to work with JSON for Mosquitto server seem to work, but every item state update spams to log with a lot of similar lines like this:

2024-01-12 21:12:18.644 [WARN ] [transport.mqtt.internal.Subscription] - A subscriber of type 'class org.openhab.binding.mqtt.generic.ChannelState' failed to process message '7B226272696768746E657373223A22323534222C22636F6C6F72223A7B22687565223A3236382C2273617475726174696F6E223A38322C2278223A302E323938322C2279223A302E313733347D2C22636F6C6F725F6D6F6465223A226873222C22636F6C6F725F74656D70223A3231332C22646F5F6E6F745F64697374757262223A66616C73652C226C6576656C5F636F6E666967223A7B226F6E5F6C6576656C223A2270726576696F7573227D2C226C696E6B7175616C697479223A37322C227374617465223A224F4E227D' to topic 'zigbee2mqtt/O_B_Color_Light_3'.

I’ve added some logging to js script to see what happens:

(function (x) {                                                                                                                                                     
var logger = log('color_bulb color_in');                                                                                                                    
logger.info(x);                                                                                                                                             
var tmp = JSON.parse(x);                                                                                                                                    
// The brightness value is received as integer 1-254 but needed as percentage                                                                               
var brightness = Math.round(parseFloat(tmp.brightness) / 254 * 100);                                                                                        
var color_mode = tmp.color_mode;                                                                                                                            
var saturation = parseFloat(tmp.color.saturation);                                                                                                          
if (color_mode == 'color_temp') {                                                                                                                           
      saturation = 0                                                                                                                                      
}                                                                                                                                                           
out = '' + tmp.color.hue + ',' + saturation + ',' + brightness                                                                                              
logger.info(out);                                                                                                                                           
return out.toString();                                                                                                                                      
})(input)  

and logs became:

2024-01-12 21:12:18.639 [INFO ] [ation.openhab-js.color_bulb color_in] - {"brightness":"254","color":{"hue":268,"saturation":82,"x":0.2982,"y":0.1734},"color_mode":"hs","color_temp":213,"do_not_disturb":false,"level_config":{"on_level":"previous"},"linkquality":72,"state":"ON"}
2024-01-12 21:12:18.640 [INFO ] [ation.openhab-js.color_bulb color_in] - 268,82,100
2024-01-12 21:12:18.644 [WARN ] [transport.mqtt.internal.Subscription] - A subscriber of type 'class org.openhab.binding.mqtt.generic.ChannelState' failed to process message '7B226272696768746E657373223A22323534222C22636F6C6F72223A7B22687565223A3236382C2273617475726174696F6E223A38322C2278223A302E323938322C2279223A302E313733347D2C22636F6C6F725F6D6F6465223A226873222C22636F6C6F725F74656D70223A3231332C22646F5F6E6F745F64697374757262223A66616C73652C226C6576656C5F636F6E666967223A7B226F6E5F6C6576656C223A2270726576696F7573227D2C226C696E6B7175616C697479223A37322C227374617465223A224F4E227D' to topic 'zigbee2mqtt/O_B_Color_Light_3'.

As I see it, the script itself works fine, but after it something strange happens: each message arrives several times, and in some strange encoding. Separately, I would like to understand what “failed to process message to topic” means, given that it seems to be a message FROM the server.
MQTT Thing configuration is:

 // O_B_Color_Light_3                                                                                                                                                    
    Thing topic O_B_Color_Light_3 "O_B_Color_Light_3" @ "O_Backyard" {                                                                                                    
        Channels:                                                                                                                                                         
        Type switch : light     "Backyard Light 3"       [                                                                                                          
            stateTopic="zigbee2mqtt/O_B_Color_Light_3",                                                                                                                   
            transformationPattern="REGEX:(.*state.*)∩JSONPATH:$.state",                                                                                                   
            commandTopic="zigbee2mqtt/O_B_Color_Light_3/set",                                                                                                             
            retained=true,                                                                                                                                                
            on="ON",                                                                                                                                                      
            off="OFF"                                                                                                                                                     
            ]                                                                                                                                                             
        Type number : brightness "Backyard light 3 brightness" [                                                                                                      
                stateTopic="zigbee2mqtt/O_B_Color_Light_3",
                transformationPattern="JS:color_bulb_brightness.js",
                commandTopic="zigbee2mqtt/O_B_Color_Light_3/set",
                transformationPatternOut="JS:color_bulb_brightness_out.js"
                ]
        Type number : color_temp "Backyard light 3 temp" [
                min="2700",
                max="6500",
                step="100",
                stateTopic="zigbee2mqtt/O_B_Color_Light_3",
                transformationPattern="JS:color_bulb_temperature.js",
                commandTopic="zigbee2mqtt/O_B_Color_Light_3/set",
                transformationPatternOut="JS:color_bulb_temperature_out.js"
                ]
        Type color : color "O_B 3 Hue" [
                //colorMode="XYY",
                stateTopic="zigbee2mqtt/O_B_Color_Light_3",
                transformationPattern="JS:color_bulb_color.js",
                commandTopic="zigbee2mqtt/O_B_Color_Light_3/set",
                transformationPatternOut="JS:color_bulb_color_out.js"
                ]
        }

Please help me find out the reason for these messages.

Use MqttExplorer to verify that these weird encoded messages are not also being published in addition to the JSON messages.

Can you post a version of the transform without the line numbers?

Besides the warning, is the message otherwise processed correctly and the Item updated as expected?

What’s the rest of the MQTT Thing configuration? There are several properties that can impact the processing of a message.

I’ve updated post, added Thing and removed line numbers from script. As for mqttExplorer - no, there are no such messages in history. And Item behavior seems to be ok.

I don’t seen anything obvious to explain what’s going on. The fact that the Item gets the transformed color as expected hints that the transform is working.

I’ve never seen anything like this reported before so am at a loss for the cause.

@J-N-K perhaps we should add at least debug log that shows the exception details here?

I saw the same issue also. My setup is also latest Openhab4 and latest Z2M.
I also see that the messages from Z2M are sent double (in MQTT Explorer).

I was not able to figure out the root cause of that issue, but I was able to restore an older version of Z2M and I could not see that issue with version 1.32.2.
I also took a log if mqtt message with different Z2M versions running: I do not see any difference between the versions in the sent messages. Here is an excerpt:

{"brightness":101,"last_seen":"2024-01-16T20:45:11.253Z","linkquality":132,"state":"ON","update":{"installed_version":51656288,"latest_version":52442720,"state":"available"}}
{"brightness":101,"last_seen":"2024-01-16T20:40:44.401Z","linkquality":132,"state":"ON","update":{"installed_version":51656288,"latest_version":52442720,"state":"available"}}
{"brightness":101,"last_seen":"2024-01-16T20:40:44.401Z","linkquality":132,"state":"ON","update":{"installed_version":51656288,"latest_version":52442720,"state":"available"}}
{"brightness":101,"last_seen":"2024-01-16T20:40:44.325Z","linkquality":132,"state":"ON","update":{"installed_version":51656288,"latest_version":52442720,"state":"available"}}
{"brightness":101,"last_seen":"2024-01-16T20:40:44.325Z","linkquality":132,"state":"OFF","update":{"installed_version":51656288,"latest_version":52442720,"state":"available"}}
{"brightness":101,"last_seen":"2024-01-16T20:40:11.254Z","linkquality":132,"state":"OFF","update":{"installed_version":51656288,"latest_version":52442720,"state":"available"}}
{"brightness":101,"last_seen":"2024-01-16T20:37:18.972Z","linkquality":156,"state":"OFF","update":{"installed_version":51656288,"latest_version":52442720,"state":"available"}}
{"brightness":101,"last_seen":"2024-01-16T20:37:18.972Z","linkquality":156,"state":"OFF","update":{"installed_version":51656288,"latest_version":52442720,"state":"available"}}
{"brightness":101,"last_seen":"2024-01-16T20:37:18.972Z","linkquality":132,"state":"OFF","update":{"installed_version":51656288,"latest_version":52442720,"state":"available"}}
{"brightness":101,"last_seen":"2024-01-16T20:37:18.972Z","linkquality":132,"state":"OFF","update":{"installed_version":51656288,"latest_version":52442720,"state":"available"}}
{"brightness":101,"last_seen":"2024-01-16T20:37:18.904Z","linkquality":132,"state":"OFF","update":{"installed_version":51656288,"latest_version":52442720,"state":"available"}}
{"brightness":101,"last_seen":"2024-01-16T20:37:18.904Z","linkquality":132,"state":"ON","update":{"installed_version":51656288,"latest_version":52442720,"state":"available"}}
{"brightness":101,"last_seen":"2024-01-16T20:35:11.254Z","linkquality":132,"state":"ON","update":{"installed_version":51656288,"latest_version":52442720,"state":"available"}}
{"brightness":101,"last_seen":"2024-01-16T20:34:18.640Z","linkquality":132,"state":"ON","update":{"installed_version":51656288,"latest_version":52442720,"state":"available"}}
{"brightness":101,"last_seen":"2024-01-16T20:34:18.640Z","linkquality":132,"state":"ON","update":{"installed_version":51656288,"latest_version":52442720,"state":"available"}}
{"brightness":101,"last_seen":"2024-01-16T20:34:18.568Z","linkquality":136,"state":"ON","update":{"installed_version":51656288,"latest_version":52442720,"state":"available"}}
{"brightness":101,"last_seen":"2024-01-16T20:34:18.568Z","linkquality":136,"state":"OFF","update":{"installed_version":51656288,"latest_version":52442720,"state":"available"}}
{"brightness":101,"last_seen":"2024-01-16T20:20:11.252Z","linkquality":156,"state":"OFF","update":{"installed_version":51656288,"latest_version":52442720,"state":"available"}}
{"brightness":101,"last_seen":"2024-01-16T20:20:11.252Z","linkquality":132,"state":"OFF","update":{"installed_version":51656288,"latest_version":52442720,"state":"available"}}
{"brightness":101,"last_seen":"2024-01-16T20:18:58.785Z","linkquality":132,"state":"OFF","update":{"installed_version":51656288,"latest_version":52442720,"state":"available"}}
{"brightness":101,"last_seen":"2024-01-16T20:18:58.785Z","linkquality":132,"state":"OFF","update":{"installed_version":51656288,"latest_version":52442720,"state":"available"}}
{"brightness":101,"last_seen":"2024-01-16T20:18:58.770Z","linkquality":132,"state":"OFF","update":{"installed_version":51656288,"latest_version":52442720,"state":"available"}}
{"brightness":101,"last_seen":"2024-01-16T20:18:58.770Z","linkquality":132,"state":"OFF","update":{"installed_version":51656288,"latest_version":52442720,"state":"available"}}
{"brightness":101,"last_seen":"2024-01-16T20:18:58.683Z","linkquality":132,"state":"OFF","update":{"installed_version":51656288,"latest_version":52442720,"state":"available"}}
{"brightness":101,"last_seen":"2024-01-16T20:18:58.683Z","linkquality":132,"state":"ON","update":{"installed_version":51656288,"latest_version":52442720,"state":"available"}}
{"brightness":101,"last_seen":"2024-01-16T20:17:53.465Z","linkquality":132,"state":"ON","update":{"installed_version":51656288,"latest_version":52442720,"state":"available"}}
{"brightness":101,"last_seen":"2024-01-16T20:17:53.465Z","linkquality":132,"state":"OFF","update":{"installed_version":51656288,"latest_version":52442720,"state":"available"}}
{"brightness":101,"last_seen":"2024-01-16T20:16:41.583Z","linkquality":132,"state":"OFF","update":{"installed_version":51656288,"latest_version":52442720,"state":"available"}}
{"brightness":101,"last_seen":"2024-01-16T20:16:41.583Z","linkquality":132,"state":"ON","update":{"installed_version":51656288,"latest_version":52442720,"state":"available"}}
{"brightness":101,"last_seen":"2024-01-16T20:15:11.292Z","linkquality":132,"state":"ON","update":{"installed_version":51656288,"latest_version":52442720,"state":"available"}}
{"brightness":101,"last_seen":"2024-01-16T20:14:54.631Z","linkquality":140,"state":"ON","update":{"installed_version":51656288,"latest_version":52442720,"state":"available"}}
{"brightness":101,"last_seen":"2024-01-16T20:14:54.631Z","linkquality":140,"state":"OFF","update":{"installed_version":51656288,"latest_version":52442720,"state":"available"}}

Additionally I was able to get rid of one error, when setting the brightness channel to “Dimmer” type. It does not seem to work to have “Number” type with min/max/step. Probably the same should apply to your color_temp.

Maybe someone knows of changes in Zigbee2mqtt since version 1.32.

@kimifish try using this jar by dropping it into your addons folder. I simply added the exception message into the warning log.

org.openhab.core.io.transport.mqtt-4.2.0-SNAPSHOT.jar.txt (37.2 KB)

Note: you just need to remove the .txt extension. I had to add it so I can upload it here.

You might need to restart your openhab.

To revert back, just delete the file and restart again.