register-push-gcm completed but returned "no user found!"

[ezraimanuel]

Hello, I'm having issue with gcm, registration succeeded but i got "no user found!" in log message, is there anything i missed? This is the log:

2016-03-15 05:16:15.937 [debug] <0.779.0>@ejabberd_receiver:process_data:283 Received XML on stream = <<"<iq id=\"gm3vbv0uok\" to=\"xmpp.domain.tld\" type=\"set\" from=\"account@domain.tld/resource\"><command action=\"execute\" node=\"register-push-gcm\" xmlns=\"http://jabber.org/protocol/commands\"><x type=\"submit\" xmlns=\"jabber:x:data\"><field var=\"token\"><value>cyEy7hdw7DA:APA91bEwS6AQiPGo6W3RBm07FR2u9oWNoC0SYyjc82gs6GGKm3pmaZPWNYcL7jZRoGiOU58BaoBeOejs9gErLI026jlL3Dkh7oWJAwOfeolXbKQMOmbPhntMrsxKdotI_r5i7BCO_Ryr</value></field><field var=\"device-id\"><value>7257ffd0acfa9a38</value></field></x></command></iq>">>
        packet {xmlel,<<"iq">>,[{<<"xml:lang">>,<<"en">>},{<<"id">>,<<"gm3vbv0uok">>},{<<"to">>,<<"xmpp.domain.tld">>},{<<"type">>,<<"set">>},{<<"from">>,<<"account@domain.tld/resource">>}],[{xmlel,<<"command">>,[{<<"xmlns">>,<<"http://jabber.org/protocol/commands">>},{<<"action">>,<<"execute">>},{<<"node">>,<<"register-push-gcm">>}],[{xmlel,<<"x">>,[{<<"xmlns">>,<<"jabber:x:data">>},{<<"type">>,<<"submit">>}],[{xmlel,<<"field">>,[{<<"var">>,<<"token">>}],[{xmlel,<<"value">>,[],[{xmlcdata,<<"cyEy7hdw7DA:APA91bEwS6AQiPGo6W3RBm07FR2u9oWNoC0SYyjc82gs6GGKm3pmaZPWNYcL7jZRoGiOU58BaoBeOejs9gErLI026jlL3Dkh7oWJAwOfeolXbKQMOmbPhntMrsxKdotI_r5i7BCO_Ryr">>}]}]},{xmlel,<<"field">>,[{<<"var">>,<<"device-id">>}],[{xmlel,<<"value">>,[],[{xmlcdata,<<"7257ffd0acfa9a38">>}]}]}]}]}]}
2016-03-15 05:16:16.015 [debug] <0.429.0>@mod_adhoc:process_adhoc_request:237 About to parse {iq,<<"gm3vbv0uok">>,set,<<"http://jabber.org/protocol/commands">>,<<"en">>,{xmlel,<<"command">>,[{<<"xmlns">>,<<"http://jabber.org/protocol/commands">>},{<<"action">>,<<"execute">>},{<<"node">>,<<"register-push-gcm">>}],[{xmlel,<<"x">>,[{<<"xmlns">>,<<"jabber:x:data">>},{<<"type">>,<<"submit">>}],[{xmlel,<<"field">>,[{<<"var">>,<<"token">>}],[{xmlel,<<"value">>,[],[{xmlcdata,<<"cyEy7hdw7DA:APA91bEwS6AQiPGo6W3RBm07FR2u9oWNoC0SYyjc82gs6GGKm3pmaZPWNYcL7jZRoGiOU58BaoBeOejs9gErLI026jlL3Dkh7oWJAwOfeolXbKQMOmbPhntMrsxKdotI_r5i7BCO_Ryr">>}]}]},{xmlel,<<"field">>,[{<<"var">>,<<"device-id">>}],[{xmlel,<<"value">>,[],[{xmlcdata,<<"7257ffd0acfa9a38">>}]}]}]}]}}...
2016-03-15 05:16:16.016 [debug] <0.618.0>@mod_pubsub:node_action:4174 node_action <<"xmpp.domain.tld">> <<"push">> get_entity_subscriptions [<<"xmpp.domain.tld">>,{jid,<<"account">>,<<"domain.tld">>,<<"resource">>,<<"account">>,<<"domain.tld">>,<<"resource">>}]
2016-03-15 05:16:16.016 [debug] <0.618.0>@mod_pubsub:node_call:4155 node_call <<"push">> get_entity_subscriptions [<<"xmpp.domain.tld">>,{jid,<<"account">>,<<"domain.tld">>,<<"resource">>,<<"account">>,<<"domain.tld">>,<<"resource">>}]
2016-03-15 05:16:16.017 [debug] <0.429.0>@mod_push:register_client:215 +++++ register_client: found backend
        packet {xmlel,<<"iq">>,[{<<"id">>,<<"gm3vbv0uok">>},{<<"type">>,<<"result">>}],[{xmlel,<<"command">>,[{<<"xmlns">>,<<"http://jabber.org/protocol/commands">>},{<<"sessionid">>,<<"2016-03-14T22:16:16.017962Z">>},{<<"node">>,<<"register-push-gcm">>},{<<"status">>,<<"completed">>}],[{xmlel,<<"x">>,[{<<"xmlns">>,<<"jabber:x:data">>},{<<"type">>,<<"result">>}],[{xmlel,<<"field">>,[{<<"var">>,<<"jid">>}],[{xmlel,<<"value">>,[],[{xmlcdata,<<"xmpp.domain.tld">>}]}]},{xmlel,<<"field">>,[{<<"var">>,<<"node">>}],[{xmlel,<<"value">>,[],[{xmlcdata,<<"13895595969827853154">>}]}]},{xmlel,<<"field">>,[{<<"var">>,<<"secret">>}],[{xmlel,<<"value">>,[],[{xmlcdata,<<"5739172620165810255">>}]}]}]}]}]}
2016-03-15 05:16:16.019 [debug] <0.780.0>@ejabberd_c2s:send_text:1830 Send XML on stream = <<"<iq from='xmpp.domain.tld' to='account@domain.tld/resource' id='gm3vbv0uok' type='result'><command xmlns='http://jabber.org/protocol/commands' sessionid='2016-03-14T22:16:16.017962Z' node='register-push-gcm' status='completed'><x xmlns='jabber:x:data' type='result'><field var='jid'><value>xmpp.domain.tld</value></field><field var='node'><value>13895595969827853154</value></field><field var='secret'><value>5739172620165810255</value></field></x></command></iq>">>
2016-03-15 05:16:18.266 [debug] <0.779.0>@ejabberd_receiver:process_data:283 Received XML on stream = <<"<iq id=\"gvbj8k4d07\" type=\"set\" from=\"account@domain.tld/resource\"><enable node=\"13895595969827853154\" jid=\"xmpp.domain.tld\" xmlns=\"urn:xmpp:push:0\"><x type=\"submit\" xmlns=\"jabber:x:data\"><field var=\"FORM_TYPE\"><value>http://jabber.org/protocol/pubsub#publish-options</value></field><field var=\"secret\"><value>5739172620165810255</value></field></x></enable></iq>">>
        packet {xmlel,<<"iq">>,[{<<"xml:lang">>,<<"en">>},{<<"id">>,<<"gvbj8k4d07">>},{<<"type">>,<<"set">>},{<<"from">>,<<"account@domain.tld/resource">>}],[{xmlel,<<"enable">>,[{<<"xmlns">>,<<"urn:xmpp:push:0">>},{<<"node">>,<<"13895595969827853154">>},{<<"jid">>,<<"xmpp.domain.tld">>}],[{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">>,<<"secret">>}],[{xmlel,<<"value">>,[],[{xmlcdata,<<"5739172620165810255">>}]}]}]}]}]}
2016-03-15 05:16:18.268 [debug] <0.624.0>@mod_push:enable:451 +++++ ParsedSecret = {result,[<<"5739172620165810255">>]}
2016-03-15 05:16:18.268 [debug] <0.624.0>@mod_push:enable:474 +++++ enable: no user found!
2016-03-15 05:16:18.269 [debug] <0.624.0>@mod_push:make_config:1935 +++++ ParseResult = not_found

[royneary]

It's strange, that you get

<field var='jid'><value>xmpp.domain.tld</value></field>

in the registration response. That's the same JID as your register_host. It should be the value of pubsub_host from your config file and must be different from your register_host, e.g. "gcm-push.domain.tld". What is the pubsub_host for that GCM push backend? And do you have a host for that defined in the mod_pubsub section?

I know it's confusing, have another look at the example config in the readme.

[ezraimanuel]

Ah, I finally got it working, I use different pubsub and register host as you suggest, inside the default host_config section, and also added new dns record and its SRV. I tried with 4 multiple accounts at the same time, all working well, no more 404 nor 501.

but the "user not found!" still occurs. What can be wrong?

This is my updated configuration:

  mod_pubsub:
    host: "pubsub.domain.tld"
    access_createnode: pubsub_createnode
    ignore_pep_from_offline: true
    last_item_cache: true
    nodetree: "virtual"
    plugins:
      - "flat"
      - "hometree"
      - "pep"
      - "push"
  mod_push:
    include_senders: true
    access_backends: pubsub_createnode
    certfile: "/opt/ejabberd/conf/certificate.pem"
    backends:
      -
        type: gcm
        app_name: "com.app.name"
        register_host: "push.domain.tld"
        pubsub_host: "pubsub.domain.tld"
        auth_key: "MY_GCM_API_KEY"

And this is the what appears in log file:

2016-03-15 07:27:17.987 [debug] <0.893.0>@ejabberd_c2s:send_text:1830 Send XML on stream = <<"<iq from='account@domain.tld' to='account@domain.tld/resource' id='pcml1h65dv' type='result'><query xmlns='http://jabber.org/protocol/disco#info'><identity category='pubsub' type='pep'/><x xmlns='jabber:x:data' type='result'><field type='hidden' var='FORM_TYPE'><value>urn:xmpp:push:options</value></field><field type='boolean' var='include-senders'><value>1</value></field><field type='boolean' var='include-message-count'><value>1</value></field><field type='boolean' var='include-subscription-count'><value>1</value></field><field type='boolean' var='include-message-bodies'><value>0</value></field></x><identity category='account' type='registered'/><x xmlns='jabber:x:data' type='result'><field var='FORM_TYPE' type='hidden'><value>http://jabber.org/network/serverinfo</value></field></x><feature var='http://jabber.org/protocol/commands'/><feature var='http://jabber.org/protocol/disco#info'/><feature var='http://jabber.org/protocol/offline'/><feature var='http://jabber.org/protocol/pubsub'/><feature var='http://jabber.org/protocol/pubsub#auto-create'/><feature var='http://jabber.org/protocol/pubsub#auto-subscribe'/><feature var='http://jabber.org/protocol/pubsub#create-nodes'/><feature var='http://jabber.org/protocol/pubsub#delete-items'/><feature var='http://jabber.org/protocol/pubsub#delete-nodes'/><feature var='http://jabber.org/protocol/pubsub#filtered-notifications'/><feature var='http://jabber.org/protocol/pubsub#modify-affiliations'/><feature var='http://jabber.org/protocol/pubsub#outcast-affiliation'/><feature var='http://jabber.org/protocol/pubsub#persistent-items'/><feature var='http://jabber.org/protocol/pubsub#publish'/><feature var='http://jabber.org/protocol/pubsub#purge-nodes'/><feature var='http://jabber.org/protocol/pubsub#retract-items'/><feature var='http://jabber.org/protocol/pubsub#retrieve-affiliations'/><feature var='http://jabber.org/protocol/pubsub#retrieve-items'/><feature var='http://jabber.org/protocol/pubsub#retrieve-subscriptions'/><feature var='http://jabber.org/protocol/pubsub#subscribe'/><feature var='msgoffline'/><feature var='urn:xmpp:mam:0'/><feature var='urn:xmpp:mam:1'/><feature var='urn:xmpp:mam:tmp'/><feature var='urn:xmpp:push:0'/><feature var='vcard-temp'/></query></iq>">>
2016-03-15 07:27:18.449 [debug] <0.893.0>@mod_push:resend_packets:904 +++++++ resending packets to user <<"account@domain.tld/resource">>
2016-03-15 07:27:18.461 [debug] <0.892.0>@ejabberd_receiver:process_data:283 Received XML on stream = <<"<iq from=\"account@domain.tld/resource\" id=\"2kr8bn66fa\" to=\"push.domain.tld\" type=\"set\"><command node=\"register-push-gcm\" action=\"execute\" xmlns=\"http://jabber.org/protocol/commands\"><x type=\"submit\" xmlns=\"jabber:x:data\"><field var=\"token\"><value>MY_TOKEN</value></field><field var=\"device-id\"><value>ad6546e3d01b2f89</value></field></x></command></iq>">>
        to {jid,<<>>,<<"push.domain.tld">>,<<>>,<<>>,<<"push.domain.tld">>,<<>>}
        packet {xmlel,<<"iq">>,[{<<"xml:lang">>,<<"en">>},{<<"from">>,<<"account@domain.tld/resource">>},{<<"id">>,<<"2kr8bn66fa">>},{<<"to">>,<<"push.domain.tld">>},{<<"type">>,<<"set">>}],[{xmlel,<<"command">>,[{<<"xmlns">>,<<"http://jabber.org/protocol/commands">>},{<<"node">>,<<"register-push-gcm">>},{<<"action">>,<<"execute">>}],[{xmlel,<<"x">>,[{<<"xmlns">>,<<"jabber:x:data">>},{<<"type">>,<<"submit">>}],[{xmlel,<<"field">>,[{<<"var">>,<<"token">>}],[{xmlel,<<"value">>,[],[{xmlcdata,<<"MY_TOKEN">>}]}]},{xmlel,<<"field">>,[{<<"var">>,<<"device-id">>}],[{xmlel,<<"value">>,[],[{xmlcdata,<<"ad6546e3d01b2f89">>}]}]}]}]}]}
        to {jid,<<>>,<<"push.domain.tld">>,<<>>,<<>>,<<"push.domain.tld">>,<<>>}
2016-03-15 07:27:18.464 [debug] <0.770.0>@mod_adhoc:process_adhoc_request:237 About to parse {iq,<<"2kr8bn66fa">>,set,<<"http://jabber.org/protocol/commands">>,<<"en">>,{xmlel,<<"command">>,[{<<"xmlns">>,<<"http://jabber.org/protocol/commands">>},{<<"node">>,<<"register-push-gcm">>},{<<"action">>,<<"execute">>}],[{xmlel,<<"x">>,[{<<"xmlns">>,<<"jabber:x:data">>},{<<"type">>,<<"submit">>}],[{xmlel,<<"field">>,[{<<"var">>,<<"token">>}],[{xmlel,<<"value">>,[],[{xmlcdata,<<"MY_TOKEN">>}]}]},{xmlel,<<"field">>,[{<<"var">>,<<"device-id">>}],[{xmlel,<<"value">>,[],[{xmlcdata,<<"ad6546e3d01b2f89">>}]}]}]}]}}...
2016-03-15 07:27:18.464 [debug] <0.770.0>@mod_push:register_client:215 +++++ register_client: found backend
        from {jid,<<>>,<<"push.domain.tld">>,<<>>,<<>>,<<"push.domain.tld">>,<<>>}
        packet {xmlel,<<"iq">>,[{<<"id">>,<<"2kr8bn66fa">>},{<<"type">>,<<"result">>}],[{xmlel,<<"command">>,[{<<"xmlns">>,<<"http://jabber.org/protocol/commands">>},{<<"sessionid">>,<<"2016-03-15T00:27:18.465527Z">>},{<<"node">>,<<"register-push-gcm">>},{<<"status">>,<<"completed">>}],[{xmlel,<<"x">>,[{<<"xmlns">>,<<"jabber:x:data">>},{<<"type">>,<<"result">>}],[{xmlel,<<"field">>,[{<<"var">>,<<"jid">>}],[{xmlel,<<"value">>,[],[{xmlcdata,<<"pubsub.domain.tld">>}]}]},{xmlel,<<"field">>,[{<<"var">>,<<"node">>}],[{xmlel,<<"value">>,[],[{xmlcdata,<<"17066926935875156611">>}]}]},{xmlel,<<"field">>,[{<<"var">>,<<"secret">>}],[{xmlel,<<"value">>,[],[{xmlcdata,<<"MY_SECRET">>}]}]}]}]}]}
        from {jid,<<>>,<<"push.domain.tld">>,<<>>,<<>>,<<"push.domain.tld">>,<<>>}
        from {jid,<<>>,<<"push.domain.tld">>,<<>>,<<>>,<<"push.domain.tld">>,<<>>}
2016-03-15 07:27:18.467 [debug] <0.893.0>@ejabberd_c2s:send_text:1830 Send XML on stream = <<"<iq from='push.domain.tld' to='account@domain.tld/resource' id='2kr8bn66fa' type='result'><command xmlns='http://jabber.org/protocol/commands' sessionid='2016-03-15T00:27:18.465527Z' node='register-push-gcm' status='completed'><x xmlns='jabber:x:data' type='result'><field var='jid'><value>pubsub.domain.tld</value></field><field var='node'><value>17066926935875156611</value></field><field var='secret'><value>MY_SECRET</value></field></x></command></iq>">>
2016-03-15 07:27:19.933 [debug] <0.892.0>@ejabberd_receiver:process_data:283 Received XML on stream = <<"<iq from=\"account@domain.tld/resource\" id=\"qbiu6c4g1o\" type=\"set\"><enable node=\"17066926935875156611\" xmlns=\"urn:xmpp:push:0\" jid=\"pubsub.domain.tld\"><x type=\"submit\" xmlns=\"jabber:x:data\"><field var=\"FORM_TYPE\"><value>http://jabber.org/protocol/pubsub#publish-options</value></field><field var=\"secret\"><value>MY_SECRET</value></field></x></enable></iq>">>
        packet {xmlel,<<"iq">>,[{<<"xml:lang">>,<<"en">>},{<<"from">>,<<"account@domain.tld/resource">>},{<<"id">>,<<"qbiu6c4g1o">>},{<<"type">>,<<"set">>}],[{xmlel,<<"enable">>,[{<<"xmlns">>,<<"urn:xmpp:push:0">>},{<<"node">>,<<"17066926935875156611">>},{<<"jid">>,<<"pubsub.domain.tld">>}],[{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">>,<<"secret">>}],[{xmlel,<<"value">>,[],[{xmlcdata,<<"MY_SECRET">>}]}]}]}]}]}
2016-03-15 07:27:19.935 [debug] <0.737.0>@mod_push:enable:451 +++++ ParsedSecret = {result,[<<"MY_SECRET">>]}
2016-03-15 07:27:19.936 [debug] <0.737.0>@mod_push:enable:474 +++++ enable: no user found!
2016-03-15 07:27:19.936 [debug] <0.737.0>@mod_push:make_config:1935 +++++ ParseResult = not_found

[ezraimanuel]

Hello,

I'm still stuck at previous problem... still "no user found", and it seems not creating any config records in mnesia table, so it always returns "no user found" message

Oh by the way, i saw this in ejabberd log:
ejabberd.log:2016-03-19 16:05:47.001 [debug] <0.400.0> Supervisor ejabberd_sup started gen_server:start_link({local,'gcm_push.domain.tld'}, mod_push_gcm, [<<"MY_GCM_KEY">>,undefined,<<"/opt/ejabberd/conf/domain.tld.pem...">>], []) at pid <0.543.0>
does it look for "gcm_push.domain.tld" hostname?

thank you