Sending FCM push notification failed with "hook_failed", reason=badxml

[theanhoo]

MongooseIM version: 4.0.1
Installed from: source
Erlang/OTP version: 23.3.4.17

When MongooseIM tries to send a FCM push notification to my phone, it would fail with this error:

when=2022-10-11T07:55:42.551896+00:00 level=error what=hook_failed reason="{{badxml,{xmlel,<<\"iq\">>,[{<<\"id\">>,<<>>},{<<\"type\">>,<<\"set\">>}],[{xmlel,<<\"pubsub\">>,[{<<\"xmlns\">>,<<\"http://jabber.org/protocol/pubsub\">>}],[{xmlel,<<\"publish\">>,[{<<\"node\">>,<<\"pubsub.demo3\">>}],[{xmlel,<<\"item\">>,[],[{xmlel,<<\"notification\">>,[{<<\"xmlns\">>,<<\"urn:xmpp:push:0\">>}],[{xmlel,<<\"x\">>,[{<<\"xmlns\">>,<<\"jabber:x:data\">>},{<<\"type\">>,<<\"submit\">>}],[{xmlel,<<\"field\">>,[{<<\"var\">>,<<\"FORM_TYPE\">>}],[{xmlel,<<\"value\">>,[],[{xmlcdata,<<\"urn:xmpp:push:su\"...>>}]}]},{xmlel,<<\"field\">>,[{<<\"var\">>,<<\"message-count\">>}],[{xmlel,<<\"value\">>,[],[{xmlcdata,<<\"1\">>}]}]},{xmlel,<<\"field\">>,[{<<\"var\">>,<<\"last-message-sender\">>}],[{xmlel,<<\"value\">>,[],[{xmlcdata,<<\"theanhoo\"...>>}]}]},{xmlel,<<\"field\">>,[{<<\"var\">>,<<\"last-message-body\">>}],[{xmlel,<<\"value\">>,[],[{xmlcdata,<<\"3\">>}]}]}]}]}]}]},{xmlel,<<\"publish-options\">>,[],[{xmlel,<<\"x\">>,[{<<\"xmlns\">>,<<\"jabber:x:data\">>},{<<\"type\">>,<<\"submit\">>}],[{xmlel,<<\"field\">>,[{<<\"var\">>,<<\"FORM_TYPE\">>}],[{xmlel,<<\"value\">>,[],[{xmlcdata,<<\"http://jabber.org/protocol/pubsub#publish-options\">>}]}]},{xmlel,<<\"field\">>,[{<<\"var\">>,<<\"service\">>}],[{xmlel,<<\"value\">>,[],[{xmlcdata,<<\"fcm\">>}]}]},{xmlel,<<\"field\">>,[{<<\"var\">>,<<\"device_id\">>}],[{xmlel,<<\"value\">>,[],[{xmlcdata,<<\"eUPIganPTZWlZ5If1AzQSL:APA91bEa6LXTnA_YlOSeF\"...>>}]}]},{xmlel,<<\"field\">>,[{<<\"var\">>,<<\"silent\">>}],[{xmlel,<<\"value\">>,[],[{xmlcdata,<<\"true\">>}]}]},{xmlel,<<\"field\">>,[{<<\"var\">>,<<\"priority\">>}],[{xmlel,<<\"value\">>,[],[{xmlcdata,undefined}]}]}]}]}]}]},{badarg,[{exml_nif,to_binary,[{xmlel,<<\"iq\">>,[{<<\"id\">>,<<>>},{<<\"type\">>,<<\"set\">>}],[{xmlel,<<\"pubsub\">>,[{<<\"xmlns\">>,<<\"http://jabber.org/protocol/pubsub\">>}],[{xmlel,<<\"publish\">>,[{<<\"node\">>,<<\"pubsub.demo3\">>}],[{xmlel,<<\"item\">>,[],[{xmlel,<<\"notification\">>,[{<<\"xmlns\">>,<<\"urn:xmpp:push:0\">>}],[{xmlel,<<\"x\">>,[{<<\"xmlns\">>,<<\"jabber:x:data\">>},{<<\"type\">>,<<\"submit\">>}],[{xmlel,<<\"field\">>,[{<<\"var\">>,<<\"FORM_TYP\"...>>}],[{xmlel,<<\"valu\"...>>,[],...}]},{xmlel,<<\"field\">>,[{<<\"var\">>,<<\"mess\"...>>}],[{xmlel,<<...>>,...}]},{xmlel,<<\"field\">>,[{<<\"var\">>,<<...>>}],[{xmlel,...}]},{xmlel,<<\"field\">>,[{<<...>>,...}],[{...}]}]}]}]}]},{xmlel,<<\"publish-options\">>,[],[{xmlel,<<\"x\">>,[{<<\"xmlns\">>,<<\"jabber:x:data\">>},{<<\"type\">>,<<\"submit\">>}],[{xmlel,<<\"field\">>,[{<<\"var\">>,<<\"FORM_TYPE\">>}],[{xmlel,<<\"value\">>,[],[{xmlcdata,<<\"http://jabber.org/pr\"...>>}]}]},{xmlel,<<\"field\">>,[{<<\"var\">>,<<\"service\">>}],[{xmlel,<<\"value\">>,[],[{xmlcdata,<<\"fcm\">>}]}]},{xmlel,<<\"field\">>,[{<<\"var\">>,<<\"device_id\">>}],[{xmlel,<<\"value\">>,[],[{xmlcdata,<<\"eUPIganPTZWl\"...>>}]}]},{xmlel,<<\"field\">>,[{<<\"var\">>,<<\"silent\">>}],[{xmlel,<<\"value\">>,[],[{xmlcdata,<<\"true\">>}]}]},{xmlel,<<\"field\">>,[{<<\"var\">>,<<\"priority\">>}],[{xmlel,<<\"value\">>,[],[{xmlcdata,undefined}]}]}]}]}]}]},not_pretty],[]},{exml,to_binary_nif,2,[{file,\"/home/user/MongooseIM-4.0.1/_build/default/lib/exml/src/exml.erl\"},{line,135}]},{exml,to_binary,1,[{file,\"/home/user/MongooseIM-4.0.1/_build/default/lib/exml/src/exml.erl\"},{line,92}]},{mongoose_acc,new,1,[{file,\"/home/user/MongooseIM-4.0.1/src/mongoose_acc.erl\"},{line,125}]},{mod_event_pusher_push_plugin_defaults,publish_via_pubsub,4,[{file,\"/home/user/MongooseIM-4.0.1/src/event_pusher/mod_event_pusher_push_plugin_defaults.erl\"},{line,142}]},{lists,foreach,2,[{file,\"lists.erl\"},{line,1342}]},{mod_event_pusher_push_plugin_defaults,publish_notification,4,[{file,\"/home/user/MongooseIM-4.0.1/src/event_pusher/mod_event_pusher_push_plugin_defaults.erl\"},{line,65}]},{lists,foldl,3,[{file,\"lists.erl\"},{line,1267}]}]}},[{exml,to_binary_nif,2,[{file,\"/home/user/MongooseIM-4.0.1/_build/default/lib/exml/src/exml.erl\"},{line,136}]},{exml,to_binary,1,[{file,\"/home/user/MongooseIM-4.0.1/_build/default/lib/exml/src/exml.erl\"},{line,92}]},{mongoose_acc,new,1,[{file,\"/home/user/MongooseIM-4.0.1/src/mongoose_acc.erl\"},{line,125}]},{mod_event_pusher_push_plugin_defaults,publish_via_pubsub,4,[{file,\"/home/user/MongooseIM-4.0.1/src/event_pusher/mod_event_pusher_push_plugin_defaults.erl\"},{line,142}]},{lists,foreach,2,[{file,\"lists.erl\"},{line,1342}]},{mod_event_pusher_push_plugin_defaults,publish_notification,4,[{file,\"/home/user/MongooseIM-4.0.1/src/event_pusher/mod_event_pusher_push_plugin_defaults.erl\"},{line,65}]},{lists,foldl,3,[{file,\"lists.erl\"},{line,1267}]},{mod_event_pusher_hook_translator,filter_local_packet,1,[{file,\"/home/user/MongooseIM-4.0.1/src/event_pusher/mod_event_pusher_hook_translator.erl\"},{line,59}]}]}" pid=<0.2586.0> at=ejabberd_hooks:error_running_hook/3:275 text="Error running hook" hook=filter_local_packet args= 

Is it the culprit?
{xmlel,<<"field">>,
[
{<<"var">>,<<"priority">>}
],
[
{xmlel,<<"value">>,
[],
[
{xmlcdata,undefined}
]
}
]
}

Please help.

Many thanks in advance.

[chrzaszcz]

Hi @theanhoo, the reported MongooseIM version is quite old. I would like to replicate the issue in the latest version, but to do so, I would need the IQ request that was used to enable push notifications (https://xmpp.org/extensions/xep-0357.html#enabling), especially the exact values of form fields.

[chrzaszcz]

The issue was most likely caused by a form field without a value, that was sent when enabling push notifications. This value was saved to the Mnesia database, and resulted in a crash when trying to send the push notifications. This is solved by #3916, which performs more strict checking of the form fields. Anyway, the whole issue is avoidable by simply ensuring that the form is correct.