search

xmppjs / xmpp.js

XMPP for JavaScript
ISC License
2.19k stars 372 forks source link

Prosody, Stanza-Error: service-unavailable #838

Closed ghost closed 4 years ago

ghost commented 4 years ago

Dear maintainer,

I am trying to run the client example from your webpage. After connecting and successfull authentication I receive the error "service-unavailable" (please see log at the end of this post).

My server is running prosody 0.11.2 and is serving many different clients without any problem. To narrow down the problem, I also tried a fresh install of prosody 0.11.5 using the default configuraiton, however the same error occurs.

Then I tried to use older versions of xmpp.js. When installing version 0.8.0 (npm i @xmpp/client@0.8.0) everything works fine and I can connect, receive and send messages. Beginning with 0.9.x the error occurs again.

Thanks for your help, best regards, Thomas

status connecting xmpp://x.x.x.x
status connect 
status opening 
status open <stream:stream from="xxx.de" xml:lang="en" id="9d8c0cb3-6823-4881-8d2b-4305f598d533" xmlns="jabber:client" xmlns:stream="http://etherx.jabber.org/streams" version="1.0"/>
IN
<stream:features xmlns="http://etherx.jabber.org/streams"><starttls xmlns="urn:ietf:params:xml:ns:xmpp-tls"><required/></starttls><register xmlns="http://jabber.org/features/iq-register"/></stream:features>
OUT
<starttls xmlns="urn:ietf:params:xml:ns:xmpp-tls"/>
IN
<proceed xmlns="urn:ietf:params:xml:ns:xmpp-tls"/>
status opening 
status open <stream:stream from="xxx.de" xml:lang="en" id="9a431834-d2b9-474a-8426-8d39c9d64322" xmlns="jabber:client" xmlns:stream="http://etherx.jabber.org/streams" version="1.0"/>
IN
<stream:features xmlns="http://etherx.jabber.org/streams"><register xmlns="http://jabber.org/features/iq-register"/><mechanisms xmlns="urn:ietf:params:xml:ns:xmpp-sasl"><mechanism>PLAIN</mechanism><mechanism>SCRAM-SHA-1-PLUS</mechanism><mechanism>SCRAM-SHA-1</mechanism></mechanisms></stream:features>
OUT
<auth xmlns="urn:ietf:params:xml:ns:xmpp-sasl" mechanism="SCRAM-SHA-1"><hidden xmlns="xmpp.js"/></auth>
IN
<challenge xmlns="urn:ietf:params:xml:ns:xmpp-sasl"><hidden xmlns="xmpp.js"/></challenge>
OUT
<response xmlns="urn:ietf:params:xml:ns:xmpp-sasl" mechanism="SCRAM-SHA-1"><hidden xmlns="xmpp.js"/></response>
IN
<success xmlns="urn:ietf:params:xml:ns:xmpp-sasl"><hidden xmlns="xmpp.js"/></success>
status opening 
status open <stream:stream from="xxx.de" xml:lang="en" id="aefcf0fb-d491-4f1e-b707-11dccfe6d607" xmlns="jabber:client" xmlns:stream="http://etherx.jabber.org/streams" version="1.0"/>
IN
<stream:features xmlns="http://etherx.jabber.org/streams"><c hash="sha-1" xmlns="http://jabber.org/protocol/caps" node="http://prosody.im" ver="5sHXd3JVG3kRIkokfulMOW7pa2A="/><bind xmlns="urn:ietf:params:xml:ns:xmpp-bind"><required/></bind><session xmlns="urn:ietf:params:xml:ns:xmpp-session"><optional/></session><ver xmlns="urn:xmpp:features:rosterver"/><sm xmlns="urn:xmpp:sm:2"><optional/></sm><sm xmlns="urn:xmpp:sm:3"><optional/></sm><csi xmlns="urn:xmpp:csi:0"/></stream:features>
OUT
<iq type="set" id="b28k9ue0y9" xmlns="jabber:client"><bind xmlns="urn:ietf:params:xml:ns:xmpp-bind"><resource>bot</resource></bind></iq>
IN
<iq id="b28k9ue0y9" type="error" xmlns="jabber:client"><error type="cancel"><service-unavailable xmlns="urn:ietf:params:xml:ns:xmpp-stanzas"/></error></iq>
StanzaError: service-unavailable
    at Function.fromElement (/home/thomas/Programme/js/homeApp/node_modules/@xmpp/error/index.js:29:19)
    at Function.fromElement (/home/thomas/Programme/js/homeApp/node_modules/@xmpp/middleware/lib/StanzaError.js:15:25)
    at IQCaller._route (/home/thomas/Programme/js/homeApp/node_modules/@xmpp/iq/caller.js:36:35)
    at dispatch (/home/thomas/Programme/js/homeApp/node_modules/koa-compose/index.js:42:32)
    at /home/thomas/Programme/js/homeApp/node_modules/@xmpp/stream-features/route.js:6:14
    at dispatch (/home/thomas/Programme/js/homeApp/node_modules/koa-compose/index.js:42:32)
    at /home/thomas/Programme/js/homeApp/node_modules/@xmpp/middleware/index.js:17:5
    at dispatch (/home/thomas/Programme/js/homeApp/node_modules/koa-compose/index.js:42:32)
    at /home/thomas/Programme/js/homeApp/node_modules/koa-compose/index.js:34:12
    at Client.<anonymous> (/home/thomas/Programme/js/homeApp/node_modules/@xmpp/middleware/index.js:11:31) {
  condition: 'service-unavailable',
  text: '',
  application: undefined,
  type: 'cancel',
  element: Element {
    name: 'error',
    parent: Element {
      name: 'iq',
      parent: [Element],
      children: [Array],
      attrs: [Object]
    },
    children: [ [Element] ],
    attrs: { type: 'cancel' }
  }
}
sonnyp commented 4 years ago

Looks like domain is missing, but it should be inferred from service https://github.com/xmppjs/xmpp.js/tree/master/packages/client#client-1

Can you share the options you pass to client() ? Feel free to replace sensitive information.

ghost commented 4 years ago

There is no difference when specifing the domain. I also tried different protocols (wss and xmpp) - the error keeps the same.

This is my test-program to reproduce the error (basically copy and paste from your page), it works well up to version 0.8.0 and fails for higher versions.

Thanks for looking into the problem!

const {client, xml} = require('@xmpp/client')
const debug = require('@xmpp/debug')

const xmpp = client({
  service: 'xxx.de',
  domain: 'xxx.de',
  resource: 'bot',
  username: 'thomas',
  password: 'xxx',
})

debug(xmpp, true)

xmpp.on('error', err => {
  console.error(err)
})

xmpp.on('offline', () => {
  console.log('offline')
})

xmpp.on('stanza', async stanza => {
  if (stanza.is('message')) {
    await xmpp.send(xml('presence', {type: 'unavailable'}))
    await xmpp.stop()
  }
})

xmpp.on('online', async address => {
  // Makes itself available
  await xmpp.send(xml('presence'))

  // Sends a chat message to itself
  const message = xml(
    'message',
    {type: 'chat', to: address},
    xml('body', {}, 'hello world')
  )
  await xmpp.send(message)
})

xmpp.start().catch(console.error)
sonnyp commented 4 years ago

I'm puzzled.

From your logs, it looks like xmpp.js is doing everything correctly. I don't know why prosody replies with service-unavailable.

In fact, I tried myself with your example, @xmpp/client 0.11.1, prosody 0.11.5 and its default configuration and I couldn't reproduce.

(node:17658) Warning: Setting the NODE_TLS_REJECT_UNAUTHORIZED environment variable to '0' makes TLS connections and HTTPS requests insecure by disabling certificate verification.
status connecting xmpps://127.0.0.1:5223
status connecting xmpp://127.0.0.1:5222
status connect 
status opening 
status open <stream:stream from="localhost" xmlns:stream="http://etherx.jabber.org/streams" version="1.0" id="5c4ca982-c893-4cbf-801b-4fe15a217268" xmlns="jabber:client" xml:lang="en"/>
IN
<stream:features xmlns="http://etherx.jabber.org/streams"><starttls xmlns="urn:ietf:params:xml:ns:xmpp-tls"><required/></starttls></stream:features>
OUT
<starttls xmlns="urn:ietf:params:xml:ns:xmpp-tls"/>
IN
<proceed xmlns="urn:ietf:params:xml:ns:xmpp-tls"/>
status opening 
status open <stream:stream from="localhost" xmlns:stream="http://etherx.jabber.org/streams" version="1.0" id="8b27d29b-d2e5-4c01-a945-93de349b8261" xmlns="jabber:client" xml:lang="en"/>
IN
<stream:features xmlns="http://etherx.jabber.org/streams"><mechanisms xmlns="urn:ietf:params:xml:ns:xmpp-sasl"><mechanism>PLAIN</mechanism><mechanism>SCRAM-SHA-1-PLUS</mechanism><mechanism>SCRAM-SHA-1</mechanism></mechanisms></stream:features>
OUT
<auth xmlns="urn:ietf:params:xml:ns:xmpp-sasl" mechanism="SCRAM-SHA-1"><hidden xmlns="xmpp.js"/></auth>
IN
<challenge xmlns="urn:ietf:params:xml:ns:xmpp-sasl"><hidden xmlns="xmpp.js"/></challenge>
OUT
<response xmlns="urn:ietf:params:xml:ns:xmpp-sasl" mechanism="SCRAM-SHA-1"><hidden xmlns="xmpp.js"/></response>
IN
<success xmlns="urn:ietf:params:xml:ns:xmpp-sasl"><hidden xmlns="xmpp.js"/></success>
status opening 
status open <stream:stream from="localhost" xmlns:stream="http://etherx.jabber.org/streams" version="1.0" id="5ab69aa0-bbb2-4e68-afbf-afe57249d22a" xmlns="jabber:client" xml:lang="en"/>
IN
<stream:features xmlns="http://etherx.jabber.org/streams"><ver xmlns="urn:xmpp:features:rosterver"/><c hash="sha-1" node="http://prosody.im" ver="wBlvgkM1+mhpz81eJoge4hYoI0Q=" xmlns="http://jabber.org/protocol/caps"/><bind xmlns="urn:ietf:params:xml:ns:xmpp-bind"><required/></bind><session xmlns="urn:ietf:params:xml:ns:xmpp-session"><optional/></session></stream:features>
OUT
<iq type="set" id="ciqfrbkvnl" xmlns="jabber:client"><bind xmlns="urn:ietf:params:xml:ns:xmpp-bind"><resource>example</resource></bind></iq>
IN
<iq id="ciqfrbkvnl" type="result" xmlns="jabber:client"><bind xmlns="urn:ietf:params:xml:ns:xmpp-bind"><jid>sonny@localhost/example</jid></bind></iq>
status online sonny@localhost/example
OUT
<presence xmlns="jabber:client"/>
OUT
<message type="chat" to="sonny@localhost/example" xmlns="jabber:client"><body>hello world</body></message>
IN
<presence from="sonny@localhost/example" xmlns="jabber:client"><x xmlns="vcard-temp:x:update"><photo/></x></presence>
IN
<message to="sonny@localhost/example" type="chat" from="sonny@localhost/example" xmlns="jabber:client"><body>hello world</body></message>
OUT
<presence type="unavailable" xmlns="jabber:client"/>
status closing 
IN
<presence type="unavailable" from="sonny@localhost/example" xmlns="jabber:client"/>
status close <stream:stream from="localhost" xmlns:stream="http://etherx.jabber.org/streams" version="1.0" id="5ab69aa0-bbb2-4e68-afbf-afe57249d22a" xmlns="jabber:client" xml:lang="en"/>
status disconnecting 
status disconnect [object Object]
status offline <stream:stream from="localhost" xmlns:stream="http://etherx.jabber.org/streams" version="1.0" id="5ab69aa0-bbb2-4e68-afbf-afe57249d22a" xmlns="jabber:client" xml:lang="en"/>
offline

I would suggest to enable debug log in prosody and see if there's anything helpful there.

ghost commented 4 years ago

Strange... here is the debug log from prosody (recorded on localhost with cs2 disabled):

Jun 06 11:10:55 socket  debug   server.lua: accepted new client connection from 127.0.0.1:60884 to 5222
Jun 06 11:10:55 c2s55f60641c340 info    Client connected
Jun 06 11:10:55 c2s55f60641c340 debug   Client sent opening <stream:stream> to localhost
Jun 06 11:10:55 c2s55f60641c340 debug   Sending[c2s_unauthed]: <?xml version='1.0'?>
Jun 06 11:10:55 c2s55f60641c340 debug   Sending[c2s_unauthed]: <stream:stream from='localhost' xml:lang='en' version='1.0' xmlns='jabber:client' xmlns:stream='http://etherx.jabber.org/streams' id='359c69c5-cc5e-4906-b29f-93f3863222ca'>
Jun 06 11:10:55 c2s55f60641c340 debug   Sent reply <stream:stream> to client
Jun 06 11:10:55 c2s55f60641c340 debug   Underlying connection does not support STARTTLS
Jun 06 11:10:55 c2s55f60641c340 debug   Offering mechanism SCRAM-SHA-1
Jun 06 11:10:55 c2s55f60641c340 debug   Not offering mechanism PLAIN on insecure connection
Jun 06 11:10:55 c2s55f60641c340 debug   Sending[c2s_unauthed]: <stream:features>
Jun 06 11:10:55 runnerbG235hth  debug   creating new coroutine
Jun 06 11:10:55 c2s55f60641c340 debug   Received[c2s_unauthed]: <auth mechanism='SCRAM-SHA-1' xmlns='urn:ietf:params:xml:ns:xmpp-sasl'>
Jun 06 11:10:55 localhost:saslauth  debug   sasl reply: <challenge xmlns='urn:ietf:params:xml:ns:xmpp-sasl'>cj0yODYxOTQyMmMxZTU0ZDhkODU0NDY0ZmU3NmU0YjY4YzkzZWU2ODc3LTk5ZjYtNGQ5Mi1iNDg4LTZlMTU2MTFhOWU0YyxzPVlXSTRabVl5WlRBdE5qRTBZaTAwTWprekxUazRZVEV0WlRNeE9EQTFNVGMxWkRFMixpPTQwOTY=</challenge>
Jun 06 11:10:55 c2s55f60641c340 debug   Sending[c2s_unauthed]: <challenge xmlns='urn:ietf:params:xml:ns:xmpp-sasl'>
Jun 06 11:10:55 c2s55f60641c340 debug   Received[c2s_unauthed]: <response mechanism='SCRAM-SHA-1' xmlns='urn:ietf:params:xml:ns:xmpp-sasl'>
Jun 06 11:10:55 c2s55f60641c340 info    Authenticated as thomas@localhost
Jun 06 11:10:55 localhost:saslauth  debug   sasl reply: <success xmlns='urn:ietf:params:xml:ns:xmpp-sasl'>dj1aWkNWd3JibEk0VzcvOENCVUZQbU00UDNpaFk9</success>
Jun 06 11:10:55 c2s55f60641c340 debug   Sending[c2s_unbound]: <success xmlns='urn:ietf:params:xml:ns:xmpp-sasl'>
Jun 06 11:10:55 c2s55f60641c340 debug   Client sent opening <stream:stream> to localhost
Jun 06 11:10:55 c2s55f60641c340 debug   Sending[c2s_unbound]: <?xml version='1.0'?>
Jun 06 11:10:55 c2s55f60641c340 debug   Sending[c2s_unbound]: <stream:stream from='localhost' xml:lang='en' version='1.0' xmlns='jabber:client' xmlns:stream='http://etherx.jabber.org/streams' id='65ac6e8e-34a7-4a4d-b640-fa90a7196398'>
Jun 06 11:10:55 c2s55f60641c340 debug   Sent reply <stream:stream> to client
Jun 06 11:10:55 c2s55f60641c340 debug   Underlying connection does not support STARTTLS
Jun 06 11:10:55 c2s55f60641c340 debug   Sending[c2s_unbound]: <stream:features>
Jun 06 11:10:55 c2s55f60641c340 debug   Received[c2s_unbound]: <iq type='set' id='aj2xhs0rz8'>
Jun 06 11:10:55 stanzarouter    debug   Unhandled c2s_unbound stanza: iq; xmlns=jabber:client
Jun 06 11:10:55 c2s55f60641c340 debug   Sending[c2s_unbound]: <iq type='error' id='aj2xhs0rz8'>

When I downgrade xmpp.js to 0.8.0, I get the following log:

Jun 06 11:13:39 socket  debug   server.lua: accepted new client connection from 127.0.0.1:60938 to 5222
Jun 06 11:13:39 c2s55f6064469a0 info    Client connected
Jun 06 11:13:39 c2s55f6064469a0 debug   Client sent opening <stream:stream> to localhost
Jun 06 11:13:39 c2s55f6064469a0 debug   Sending[c2s_unauthed]: <?xml version='1.0'?>
Jun 06 11:13:39 c2s55f6064469a0 debug   Sending[c2s_unauthed]: <stream:stream from='localhost' xml:lang='en' version='1.0' xmlns='jabber:client' xmlns:stream='http://etherx.jabber.org/streams' id='832d46f5-6b4d-463b-a791-839ac3c23f18'>
Jun 06 11:13:39 c2s55f6064469a0 debug   Sent reply <stream:stream> to client
Jun 06 11:13:39 c2s55f6064469a0 debug   Underlying connection does not support STARTTLS
Jun 06 11:13:39 c2s55f6064469a0 debug   Offering mechanism SCRAM-SHA-1
Jun 06 11:13:39 c2s55f6064469a0 debug   Not offering mechanism PLAIN on insecure connection
Jun 06 11:13:39 c2s55f6064469a0 debug   Sending[c2s_unauthed]: <stream:features>
Jun 06 11:13:39 runnerbbD7CPeb  debug   creating new coroutine
Jun 06 11:13:39 c2s55f6064469a0 debug   Received[c2s_unauthed]: <auth mechanism='SCRAM-SHA-1' xmlns='urn:ietf:params:xml:ns:xmpp-sasl'>
Jun 06 11:13:39 localhost:saslauth  debug   sasl reply: <challenge xmlns='urn:ietf:params:xml:ns:xmpp-sasl'>cj1hNGZmNDU4ZTI5MjMyYjEyODU2NGQyMDFkMTY1MjI3OTJjYzQxMDc3LTc3ZWYtNDVmNS1hNTA1LTlmZjVlY2MwZGU1YSxzPVlXSTRabVl5WlRBdE5qRTBZaTAwTWprekxUazRZVEV0WlRNeE9EQTFNVGMxWkRFMixpPTQwOTY=</challenge>
Jun 06 11:13:39 c2s55f6064469a0 debug   Sending[c2s_unauthed]: <challenge xmlns='urn:ietf:params:xml:ns:xmpp-sasl'>
Jun 06 11:13:39 c2s55f6064469a0 debug   Received[c2s_unauthed]: <response mechanism='SCRAM-SHA-1' xmlns='urn:ietf:params:xml:ns:xmpp-sasl'>
Jun 06 11:13:39 c2s55f6064469a0 info    Authenticated as thomas@localhost
Jun 06 11:13:39 localhost:saslauth  debug   sasl reply: <success xmlns='urn:ietf:params:xml:ns:xmpp-sasl'>dj1nNHhubVhQR3RpQnZ4L3VRampYNUhjQUlBekk9</success>
Jun 06 11:13:39 c2s55f6064469a0 debug   Sending[c2s_unbound]: <success xmlns='urn:ietf:params:xml:ns:xmpp-sasl'>
Jun 06 11:13:39 c2s55f6064469a0 debug   Client sent opening <stream:stream> to localhost
Jun 06 11:13:39 c2s55f6064469a0 debug   Sending[c2s_unbound]: <?xml version='1.0'?>
Jun 06 11:13:39 c2s55f6064469a0 debug   Sending[c2s_unbound]: <stream:stream from='localhost' xml:lang='en' version='1.0' xmlns='jabber:client' xmlns:stream='http://etherx.jabber.org/streams' id='d9fd8f9d-d878-42af-848f-248684824225'>
Jun 06 11:13:39 c2s55f6064469a0 debug   Sent reply <stream:stream> to client
Jun 06 11:13:39 c2s55f6064469a0 debug   Underlying connection does not support STARTTLS
Jun 06 11:13:39 c2s55f6064469a0 debug   Sending[c2s_unbound]: <stream:features>
Jun 06 11:13:39 c2s55f6064469a0 debug   Received[c2s_unbound]: <iq type='set' id='rmjxidoscc'>
Jun 06 11:13:39 rostermanager   debug   load_roster: asked for: thomas@localhost
Jun 06 11:13:39 rostermanager   debug   load_roster: loading for new user: thomas@localhost
Jun 06 11:13:39 c2s55f6064469a0 debug   No legacy vCard to migrate or already migrated
Jun 06 11:13:39 c2s55f6064469a0 debug   Sending[c2s]: <iq type='result' id='rmjxidoscc'>
Jun 06 11:13:39 c2s55f6064469a0 debug   Resource bound: thomas@localhost/bot

The error seems to be related to this stanca:

Not working - current version
<iq type="set" id="..." xmlns="jabber:client"><bind xmlns="urn:ietf:params:xml:ns:xmpp-bind"><resource>bot</resource></bind></iq>

Working - Version 0.8.0
<iq type="set" id="..." xmlns="undefined"><bind xmlns="urn:ietf:params:xml:ns:xmpp-bind"><resource>bot</resource></bind></iq>

The difference seems to be the namespace of the tag. Unfortunately I don't understand the XMPP protocol...

I'm using:

ghost commented 4 years ago

I found the bug ... Apparently npm had a problem cleaning up the dependencies. I have now completely reinstalled all npm packages and can no longer reproduce the error.

So if someone has the same problem:

Please excuse the effort I made!