search

esl / MongooseIM

MongooseIM is Erlang Solutions' robust, scalable and efficient XMPP server, aimed at large installations. Specifically designed for enterprise purposes, it is fault-tolerant and can utilise the resources of multiple clustered machines.
Other
1.64k stars 422 forks source link

How to implement stream resumption in XEP-0198 stream management from client side ? #4220

Open alvinlal opened 3 months ago

alvinlal commented 3 months ago

MongooseIM version: 6.1.1 Installed from: pkg Erlang/OTP version: 26

i am trying to implement stream resumption feature from xep 0198 but i am getting <failed xmlns='urn:xmpp:sm:3'><unexpected-request xmlns='urn:ietf:params:xml:ns:xmpp-stanzas'/></failed> after sending the <resume/> stanza. I am using strophe.js client and have enabled mod_ping in mongooseim to detect broken connections. After the connectiion is reestablished after lossing connection, i am reconnecting using strophe.js's connect method, and then then sending <resume h="<current h value>" previd="<previous-id>" xmlns="urn:xmpp:sm:3"/> , but in response i am getting the <failed xmlns='urn:xmpp:sm:3'><unexpected-request xmlns='urn:ietf:params:xml:ns:xmpp-stanzas'/></failed> response

DenysGonchar commented 3 months ago

the provided information is insufficient to make any suggestions. If you want further assistance, you must provide a config file and the dump of the XMMP traffic (all of the messages). don't forget to obfuscate all the secrets and passwords.

also here is an example of stream resumption from our integration tests, you can use it as a reference

alvinlal commented 3 months ago

my config file 👇 , stream management module is enabled by [modules.mod_stream_management]

[general]
  loglevel = "all"
  hosts = ["<domain name is here>","localhost"]
  host_types = []
  default_server_domain = "localhost"
  registration_timeout = "infinity"
  language = "en"
  max_fsm_queue = 1000

[[listen.http]]
  port = 5280
  transport.num_acceptors = 10
  transport.max_connections = 1024

  [[listen.http.handlers.mod_bosh]]
    host = "_"
    path = "/http-bind"

  [[listen.http.handlers.mod_websockets]]
    host = "_"
    path = "/ws-xmpp"
    timeout = "infinity"
    #ping_rate = 30_000
    c2s_state_timeout = "infinity"

[[listen.http]]
  port = 5285
  transport.num_acceptors = 10
  transport.max_connections = 1024
  tls.verify_mode = "none"
  tls.certfile = "/etc/letsencrypt/live/<domain name>/fullchain.pem"
  tls.keyfile = "/etc/letsencrypt/live/<domain name>/privkey.pem"

  [[listen.http.handlers.mod_bosh]]
    host = "_"
    path = "/http-bind"

  [[listen.http.handlers.mod_websockets]]
    host = "_"
    path = "/ws-xmpp"
    #ping_rate = 30_000
    c2s_state_timeout = "infinity"

[[listen.http]]
  ip_address = "0.0.0.0"
  port = 8088
  transport.num_acceptors = 10
  transport.max_connections = 1024

  [[listen.http.handlers.mongoose_admin_api]]
    host = "_"
    path = "/api"
    username = "admin"
    password = "secret"

[[listen.http]]
  port = 8089
  transport.num_acceptors = 10
  transport.max_connections = 1024
  protocol.compress = true
  tls.verify_mode = "none"
  tls.certfile = "priv/ssl/fake_cert.pem"
  tls.keyfile = "priv/ssl/fake_key.pem"
  tls.password = ""

  [[listen.http.handlers.mongoose_client_api]]
    host = "_"
    path = "/api"

[[listen.http]]
  ip_address = "127.0.0.1"
  port = 5551
  transport.num_acceptors = 10
  transport.max_connections = 1024

  [[listen.http.handlers.mongoose_graphql_handler]]
    host = "localhost"
    path = "/api/graphql"
    schema_endpoint = "admin"
    username = "admin"
    password = "secret"

[[listen.http]]
  ip_address = "0.0.0.0"
  port = 5541
  transport.num_acceptors = 10
  transport.max_connections = 1024

  [[listen.http.handlers.mongoose_graphql_handler]]
    host = "_"
    path = "/api/graphql"
    schema_endpoint = "domain_admin"

[[listen.http]]
  ip_address = "0.0.0.0"
  port = 5561
  transport.num_acceptors = 10
  transport.max_connections = 1024

  [[listen.http.handlers.mongoose_graphql_handler]]
    host = "_"
    path = "/api/graphql"
    schema_endpoint = "user"

[[listen.c2s]]
  port = 5222
  access = "c2s"
  shaper = "c2s_shaper"
  max_stanza_size = 65536
  tls.verify_mode = "none"
  tls.certfile = "priv/ssl/fake_server.pem"

[[listen.s2s]]
  port = 5269
  shaper = "s2s_shaper"
  max_stanza_size = 131072

[[listen.service]]
  port = 8888
  access = "all"
  shaper_rule = "fast"
  ip_address = "127.0.0.1"
  password = "secret"

[auth]
  methods = ["rdbms"]

  [auth.rdbms]

[outgoing_pools.rdbms.default]
  scope = "global"
  workers = 5

  [outgoing_pools.rdbms.default.connection]
    driver = "mysql"
    host = "localhost"
    database = "mongooseim"
    username = "root"
    password = "password"

[outgoing_pools.http.mongoose_push_http]
  scope = "global"
  strategy = "available_worker"

  [outgoing_pools.http.mongoose_push_http.connection]
    host = "https://localhost:8443"
    tls.verify_mode = "none"

[services.service_admin_extra]

[services.service_mongoose_system_metrics]

[modules.mod_ping]

[modules.mod_offline]
  access_max_user_messages = "max_user_offline_messages"
  backend = "mnesia"

[modules.mod_pubsub]
  plugins = ["push"] # mandatory minimal config

[modules.mod_event_pusher.push]
  backend = "mnesia" # optional
  wpool.workers = 200 # optional
  plugin_module = "mod_event_pusher_push_plugin_enhanced" # optional
  virtual_pubsub_hosts = ["pubsub.@HOST@"]

[modules.mod_push_service_mongoosepush]
  pool_name = "mongoose_push_http"
  api_version = "v3"

[modules.mod_adhoc]

[modules.mod_disco]
  extra_domains = ["<domain name here>"]
  users_can_see_hidden_services = false

[modules.mod_stream_management]

[modules.mod_register]
  ip_access = [
    {address = "127.0.0.0/8", policy = "allow"},
    {address = "0.0.0.0/0", policy = "deny"}
  ]
  access = "register"

[modules.mod_presence]

[modules.mod_sic]

[modules.mod_vcard]
  host = "vjud.@HOST@"

[modules.mod_bosh]

[modules.mod_carboncopy]

[shaper.normal]
  max_rate = 1000

[shaper.fast]
  max_rate = 50_000

[shaper.mam_shaper]
  max_rate = 1

[shaper.mam_global_shaper]
  max_rate = 1000

[acl]
  local = [{}]

[access]
  max_user_sessions = [
    {acl = "all", value = 10}
  ]

  max_user_offline_messages = [
    {acl = "admin", value = 5000},
    {acl = "all", value = 100}
  ]

  local = [
    {acl = "local", value = "allow"}
  ]

  c2s = [
    {acl = "blocked", value = "deny"},
    {acl = "all", value = "allow"}
  ]

  c2s_shaper = [
    {acl = "admin", value = "none"},
    {acl = "all", value = "normal"}
  ]

  s2s_shaper = [
    {acl = "all", value = "fast"}
  ]

  muc_admin = [
    {acl = "admin", value = "allow"}
  ]

  muc_create = [
    {acl = "local", value = "allow"}
  ]

  muc = [
    {acl = "all", value = "allow"}
  ]

  register = [
    {acl = "all", value = "allow"}
  ]

  mam_set_prefs = [
    {acl = "all", value = "default"}
  ]

  mam_get_prefs = [
    {acl = "all", value = "default"}
  ]

  mam_lookup_messages = [
    {acl = "all", value = "default"}
  ]

  mam_set_prefs_shaper = [
    {acl = "all", value = "mam_shaper"}
  ]

  mam_get_prefs_shaper = [
    {acl = "all", value = "mam_shaper"}
  ]

  mam_lookup_messages_shaper = [
    {acl = "all", value = "mam_shaper"}
  ]

  mam_set_prefs_global_shaper = [
    {acl = "all", value = "mam_global_shaper"}
  ]

  mam_get_prefs_global_shaper = [
    {acl = "all", value = "mam_global_shaper"}
  ]

  mam_lookup_messages_global_shaper = [
    {acl = "all", value = "mam_global_shaper"}
  ]

[s2s]
  use_starttls = "optional"
  certfile = "priv/ssl/fake_server.pem"
  default_policy = "deny"
  outgoing.port = 5269

#[[host_config]]
#  host = "anonymous.localhost"
#
#  [host_config.auth.anonymous]
#    allow_multiple_connections = true
#    protocol = "both"

Client side xmpp traffic 👇

  1. Send stanza 👇 :- 

    <open to="<domain name here>" version="1.0" xmlns="urn:ietf:params:xml:ns:xmpp-framing"/>

  2. Received stanza 👇 :- 

    <open xml:lang='en' version='1.0' xmlns='urn:ietf:params:xml:ns:xmpp-framing' id='dc7ecf662d9a696c' from='<domain name here>'/>

  3. Received stanza 👇 :- 

    <features
xmlns='http://etherx.jabber.org/streams'>
<starttls
    xmlns='urn:ietf:params:xml:ns:xmpp-tls'/>
    <register
        xmlns='http://jabber.org/features/iq-register'/>
        <sm
            xmlns='urn:xmpp:sm:3'/>
            <mechanisms
                xmlns='urn:ietf:params:xml:ns:xmpp-sasl'>
                <mechanism>SCRAM-SHA-512</mechanism>
                <mechanism>SCRAM-SHA-384</mechanism>
                <mechanism>SCRAM-SHA-256</mechanism>
                <mechanism>SCRAM-SHA-224</mechanism>
                <mechanism>SCRAM-SHA-1</mechanism>
                <mechanism>PLAIN</mechanism>
            </mechanisms>
</features>

  4. Send stanza 👇 :-

    <auth mechanism="SCRAM-SHA-1"
xmlns="urn:ietf:params:xml:ns:xmpp-sasl">biwsbj0rOTE5MjA3MjQ4NjY0LHI9M2M4NDFhYTM1NDVkYTUyNWE3YmMwNjA0NWNjNDYyZDI=
</auth>

  5. Received stanza 👇 :- 

    <challenge
xmlns='urn:ietf:params:xml:ns:xmpp-sasl'>cj0zYzg0MWFhMzU0NWRhNTI1YTdiYzA2MDQ1Y2M0NjJkMjN5MEtZTGJuMVB4TTdEdTg1VmEra1E9PSxzPXREY2VLNTE1Y25QY2VobllOQllrQWc9PSxpPTEwMDAw
</challenge>

  6. Send stanza 👇 :- 

    <response
xmlns="urn:ietf:params:xml:ns:xmpp-sasl">Yz1iaXdzLHI9M2M4NDFhYTM1NDVkYTUyNWE3YmMwNjA0NWNjNDYyZDIzeTBLWUxibjFQeE03RHU4NVZhK2tRPT0scD14ZzJBa1dLN0ZzbllMbHA5cmN6SEwwRW5RbXc9
</response>

  7. Received stanza 👇 :- 

    <success xmlns='urn:ietf:params:xml:ns:xmpp-sasl'>dj1pSE1BcFBVYmV3NWpNQTd0dXFiWnB0RE9pYVE9</success>

  8. Send stanza 👇 :- 

    <open to="domain name here" version="1.0" xmlns="urn:ietf:params:xml:ns:xmpp-framing"/>

  9. Received stanza 👇 :- 

    <open xml:lang='en' version='1.0' xmlns='urn:ietf:params:xml:ns:xmpp-framing' id='035fe37c437c9543' from='domain name here'/>

  10. Received stanza 👇 :- 

    <features
xmlns='http://etherx.jabber.org/streams'>
<session
    xmlns='urn:ietf:params:xml:ns:xmpp-session'/>
    <bind
        xmlns='urn:ietf:params:xml:ns:xmpp-bind'/>
        <register
            xmlns='http://jabber.org/features/iq-register'/>
            <sm
                xmlns='urn:xmpp:sm:3'/>
</features>

  11. Send stanza 👇 :- 

    <iq id="_bind_auth_2" type="set"
xmlns="jabber:client">
<bind
    xmlns="urn:ietf:params:xml:ns:xmpp-bind">
    <resource>mobile</resource>
</bind>
</iq>

  12. Receive stanza 👇 :- 

    <iq id='_bind_auth_2' type='result'
xmlns='jabber:client'>
<bind
    xmlns='urn:ietf:params:xml:ns:xmpp-bind'>
    <jid>jid here/mobile</jid>
</bind>
</iq>

  13. Send stanza 👇 :- 

    <iq id="_session_auth_2" type="set"
xmlns="jabber:client">
<session
    xmlns="urn:ietf:params:xml:ns:xmpp-session"/>
</iq>

  14. Received stanza 👇 :- 

    <iq from='domain name here' to='jid here/mobile' id='_session_auth_2' type='result'
xmlns='jabber:client'>
<session
    xmlns='urn:ietf:params:xml:ns:xmpp-session'/>
</iq>

  15. Send stanza 👇 , attempting to resume stream :- 

    <resume h="57" previd="qtsPBR8Dl9mIgDOI2g3R1y17c/tz" xmlns="urn:xmpp:sm:3"/>

  16. Received stanza 👇 , got failed result back :- 

    <failed xmlns='urn:xmpp:sm:3'><unexpected-request xmlns='urn:ietf:params:xml:ns:xmpp-stanzas'/></failed>

Do note that previd from the stanza send on the 15 step is an actual stream id from a previous session, the xmpp traffic posted above is after the websocket connection has disconnected and while trying to reconnect again and resume the previous stream.

Is it possible the failed response is because of trying to bind the resource again (stanzas 11 to 14), which seems to be missing from the integration tests you provided.

alvinlal commented 3 months ago

hi @DenysGonchar , it was indeed because of trying to bind the resource again, i am successfully getting <resumed xmlns='urn:xmpp:sm:3' previd='qBa79OdCU6XDh/MkI6oLqkrcNzDr' h='3'/> stanza back when not trying to bind the resource, But now another problem is that i am getting the below stanza 👇 just after the <resumed/> stanza and the stream is getting disconnected and i am not able to send any further stanza's

<presence from='my jid here' to='my jid here, same as from' type='unavailable'
    xmlns='jabber:client'>
    <status>Unknown condition</status>
</presence>
DenysGonchar commented 3 months ago

one more time, we need the full traffic to make any suggestions.

alvinlal commented 3 months ago

@DenysGonchar here is the logs from client 👇 

LOG  send stanza:- <open to="domain name here" version="1.0" xmlns="urn:ietf:params:xml:ns:xmpp-framing"/>
LOG  Received stanza:- <open xml:lang='en' version='1.0' xmlns='urn:ietf:params:xml:ns:xmpp-framing' id='e2f2eb681fadcbd3' from='domain name here'/>
LOG  Received stanza:- <features xmlns='http://etherx.jabber.org/streams'><starttls xmlns='urn:ietf:params:xml:ns:xmpp-tls'/><register xmlns='http://jabber.org/features/iq-register'/><sm xmlns='urn:xmpp:sm:3'/><mechanisms xmlns='urn:ietf:params:xml:ns:xmpp-sasl'><mechanism>SCRAM-SHA-512</mechanism><mechanism>SCRAM-SHA-384</mechanism><mechanism>SCRAM-SHA-256</mechanism><mechanism>SCRAM-SHA-224</mechanism><mechanism>SCRAM-SHA-1</mechanism><mechanism>PLAIN</mechanism></mechanisms></features>
LOG  send stanza:- <auth mechanism="SCRAM-SHA-1" xmlns="urn:ietf:params:xml:ns:xmpp-sasl">biwsbj0rOTE5MjA3MjQ4NjY0LHI9NGNhMmI3MzI5NjdiMjQ0NDM4YTk1MDg5N2NjNzM0ZTM=</auth>
LOG  Received stanza:- <challenge xmlns='urn:ietf:params:xml:ns:xmpp-sasl'>cj00Y2EyYjczMjk2N2IyNDQ0MzhhOTUwODk3Y2M3MzRlM2Jkand6SzA3RjdBS1Fac0RITEl0MFE9PSxzPWR4WmRheUNHY0Z4Y2l6YWZzMUQxUEE9PSxpPTEwMDAw</challenge>
LOG  send stanza:- <response xmlns="urn:ietf:params:xml:ns:xmpp-sasl">Yz1iaXdzLHI9NGNhMmI3MzI5NjdiMjQ0NDM4YTk1MDg5N2NjNzM0ZTNiZGp3ekswN0Y3QUtRWnNESExJdDBRPT0scD1DZlB2M0JUWUdrR1FiQTJKN29SaUgrSmQwS009</response>
LOG  Received stanza:- <success xmlns='urn:ietf:params:xml:ns:xmpp-sasl'>dj00YnZIQnVsSWNic205SGxkbEp0anBFMDdvOXc9</success>
LOG  send stanza:- <open to="domain name here" version="1.0" xmlns="urn:ietf:params:xml:ns:xmpp-framing"/>
LOG  Received stanza:- <open xml:lang='en' version='1.0' xmlns='urn:ietf:params:xml:ns:xmpp-framing' id='27384613e4f1ace3' from='domain name here'/>
LOG  Received stanza:- <features xmlns='http://etherx.jabber.org/streams'><session xmlns='urn:ietf:params:xml:ns:xmpp-session'/><bind xmlns='urn:ietf:params:xml:ns:xmpp-bind'/><register xmlns='http://jabber.org/features/iq-register'/><sm xmlns='urn:xmpp:sm:3'/></features>
LOG  send stanza:- <resume h="5" previd="aTGS1sx3QiB6zXiDc9KMp7eyraRp" xmlns="urn:xmpp:sm:3"/>
LOG  Received stanza:- <resumed xmlns='urn:xmpp:sm:3' previd='aTGS1sx3QiB6zXiDc9KMp7eyraRp' h='5'/>
LOG  Received stanza:- <presence from='jid with resourcd part' to='same as from' type='unavailable' xmlns='jabber:client'><status>Unknown condition</status></presence>
LOG  Received stanza:- <r xmlns='urn:xmpp:sm:3'/>

here is the logs from mongooseim in server 👇 

when=2024-02-06T08:55:27.382502+00:00 level=debug what=ws_init pid=<0.2615.0> at=mod_websockets:init/2:89 text="New websockets request" opts_backwards_compatible_session=true opts_c2s_state_timeout=infinity opts_ip_tuple={0,0,0,0} opts_max_stanza_size=infinity opts_proto=tcp opts_host=_ opts_path=/ws-xmpp opts_port=5280 opts_module=mod_websockets opts_timeout=infinity 
when=2024-02-06T08:55:27.383429+00:00 level=debug what=ws_init pid=<0.2614.0> at=mod_websockets:websocket_init/1:106 text="New websockets connection" peer={{112,91,829,216},6958} opts_backwards_compatible_session=true opts_c2s_state_timeout=infinity opts_ip_tuple={0,0,0,0} opts_max_stanza_size=infinity opts_peer_cert=undefined opts_proto=tcp opts_peer={{112,91,829,216},6958} opts_host=_ opts_path=/ws-xmpp opts_port=5280 opts_module=mod_websockets opts_timeout=infinity 
when=2024-02-06T08:55:27.478448+00:00 level=debug what=ws_received pid=<0.2614.0> at=mod_websockets:websocket_handle/2:117 peer={{112,91,829,216},6958} msg="<open to=\"domain name\" version=\"1.0\" xmlns=\"urn:ietf:params:xml:ns:xmpp-framing\"/>" 
when=2024-02-06T08:55:27.478966+00:00 level=debug what=ws_c2s_started pid=<0.2614.0> at=mod_websockets:do_start_fsm/2:217 text="WebSockets starts c2s process" c2s_pid=<0.2616.0> peer={{112,91,829,216},6958} 
when=2024-02-06T08:55:27.479396+00:00 level=debug what=received_raw_on_stream pid=<0.2616.0> at=mongoose_c2s:handle_socket_packet/2:222 elements="[{xmlstreamstart,<<\"stream:stream\">>,[{<<\"xmlns:stream\">>,<<\"http://etherx.jabber.org/streams\">>},{<<\"to\">>,<<\"domain name here\">>},{<<\"version\">>,<<\"1.0\">>},{<<\"xmlns\">>,<<\"jabber:client\">>}]}]" c2s_pid=<0.2616.0> 
when=2024-02-06T08:55:27.479820+00:00 level=debug what=ws_send pid=<0.2614.0> at=mod_websockets:websocket_info/2:137 text="Sending xml over WebSockets" peer={{112,91,829,216},6958} packet="<open xml:lang='en' version='1.0' xmlns='urn:ietf:params:xml:ns:xmpp-framing' id='9fc74898ca8bb0c3' from='domain name here'/>" 
when=2024-02-06T08:55:27.480130+00:00 level=debug what=ws_send pid=<0.2614.0> at=mod_websockets:websocket_info/2:137 text="Sending xml over WebSockets" peer={{112,91,829,216},6958} packet="<features xmlns='http://etherx.jabber.org/streams'><starttls xmlns='urn:ietf:params:xml:ns:xmpp-tls'/><register xmlns='http://jabber.org/features/iq-register'/><sm xmlns='urn:xmpp:sm:3'/><mechanisms xmlns='urn:ietf:params:xml:ns:xmpp-sasl'><mechanism>SCRAM-SHA-512</mechanism><mechanism>SCRAM-SHA-384</mechanism><mechanism>SCRAM-SHA-256</mechanism><mechanism>SCRAM-SHA-224</mechanism><mechanism>SCRAM-SHA-1</mechanism><mechanism>PLAIN</mechanism></mechanisms></features>" 
when=2024-02-06T08:55:27.578362+00:00 level=debug what=ws_received pid=<0.2614.0> at=mod_websockets:websocket_handle/2:117 peer={{112,91,829,216},6958} msg="<auth mechanism=\"SCRAM-SHA-1\" xmlns=\"urn:ietf:params:xml:ns:xmpp-sasl\">biwsbj0rOTE5MjA3MjQ4NjY0LHI9MjU1ZDQwYjlkMzA2ZDU5OTg1ZjZiYjE4OTZhZGMwOGI=</auth>" 
when=2024-02-06T08:55:27.578771+00:00 level=debug what=received_raw_on_stream pid=<0.2616.0> at=mongoose_c2s:handle_socket_packet/2:222 elements="[{xmlel,<<\"auth\">>,[{<<\"mechanism\">>,<<\"SCRAM-SHA-1\">>},{<<\"xmlns\">>,<<\"urn:ietf:params:xml:ns:xmpp-sasl\">>}],[{xmlcdata,<<\"biwsbj0rOTE5MjA3MjQ4NjY0LHI9MjU1ZDQwYjlkMzA2ZDU5OTg1ZjZiYjE4OTZhZGMwOGI=\">>}]}]" c2s_pid=<0.2616.0> 
when=2024-02-06T08:55:27.580033+00:00 level=debug what=ws_send pid=<0.2614.0> at=mod_websockets:websocket_info/2:137 text="Sending xml over WebSockets" peer={{112,91,829,216},6958} packet="<challenge xmlns='urn:ietf:params:xml:ns:xmpp-sasl'>cj0yNTVkNDBiOWQzMDZkNTk5ODVmNmJiMTg5NmFkYzA4YmNIT1AwWkdTd3Jzc3JFR055eFRwdnc9PSxzPWR4WmRheUNHY0Z4Y2l6YWZzMUQxUEE9PSxpPTEwMDAw</challenge>" 
when=2024-02-06T08:55:32.309825+00:00 level=debug what=ws_received pid=<0.2614.0> at=mod_websockets:websocket_handle/2:117 peer={{112,91,829,216},6958} msg="<response xmlns=\"urn:ietf:params:xml:ns:xmpp-sasl\">Yz1iaXdzLHI9MjU1ZDQwYjlkMzA2ZDU5OTg1ZjZiYjE4OTZhZGMwOGJjSE9QMFpHU3dyc3NyRUdOeXhUcHZ3PT0scD1RTTEva3BkN0hmaWcxaGE3TGhnOUw3NXk2NkU9</response>" 
when=2024-02-06T08:55:32.310291+00:00 level=debug what=received_raw_on_stream pid=<0.2616.0> at=mongoose_c2s:handle_socket_packet/2:222 elements="[{xmlel,<<\"response\">>,[{<<\"xmlns\">>,<<\"urn:ietf:params:xml:ns:xmpp-sasl\">>}],[{xmlcdata,<<\"Yz1iaXdzLHI9MjU1ZDQwYjlkMzA2ZDU5OTg1ZjZiYjE4OTZhZGMwOGJjSE9QMFpHU3dyc3NyRUdOeXhUcHZ3PT0scD1RTTEva3BkN0hmaWcxaGE3TGhnOUw3NXk2NkU9\">>}]}]" c2s_pid=<0.2616.0> 
when=2024-02-06T08:55:32.311047+00:00 level=debug what=ws_send pid=<0.2614.0> at=mod_websockets:websocket_info/2:137 text="Sending xml over WebSockets" peer={{112,91,829,216},6958} packet="<success xmlns='urn:ietf:params:xml:ns:xmpp-sasl'>dj1hSHNXRnFCTyt3NUFkQVlyY1N4clhSbGpqK3M9</success>" 
when=2024-02-06T08:55:32.310993+00:00 level=info what=auth_success pid=<0.2616.0> at=mongoose_c2s:handle_sasl_success/2:449 text="Accepted SASL authentication" c2s_state="{c2s_data,<<\"domain name here\">>,<<\"domain name here\">>,<<\"en\">>,{1707209727478901,<0.2616.0>},<<\"9c894cc38f58c39f\">>,{jid,<<\"+111111111132\">>,<<\"domain name here\">>,<<>>},{c2s_socket,mod_websockets,{websocket,<0.2614.0>,{{112,91,829,216},6958},undefined}},{parser,#Ref<0.3711087841.2278424578.44069>,[]},none,#{access => all,port => 5280,shaper => none,hibernate_after => 0,proto => tcp,max_stanza_size => 0,ip_tuple => {0,0,0,0},c2s_state_timeout => infinity,backwards_compatible_session => true,xml_socket => true},ejabberd_auth_rdbms,#{},#{}}" 
when=2024-02-06T08:55:32.361734+00:00 level=debug what=ws_received pid=<0.2614.0> at=mod_websockets:websocket_handle/2:117 peer={{112,91,829,216},6958} msg="<open to=\"domain name here\" version=\"1.0\" xmlns=\"urn:ietf:params:xml:ns:xmpp-framing\"/>" 
when=2024-02-06T08:55:32.362133+00:00 level=debug what=received_raw_on_stream pid=<0.2616.0> at=mongoose_c2s:handle_socket_packet/2:222 elements="[{xmlstreamstart,<<\"stream:stream\">>,[{<<\"xmlns:stream\">>,<<\"http://etherx.jabber.org/streams\">>},{<<\"to\">>,<<\"domain name here\">>},{<<\"version\">>,<<\"1.0\">>},{<<\"xmlns\">>,<<\"jabber:client\">>}]}]" c2s_pid=<0.2616.0> 
when=2024-02-06T08:55:32.362558+00:00 level=debug what=ws_send pid=<0.2614.0> at=mod_websockets:websocket_info/2:137 text="Sending xml over WebSockets" peer={{112,91,829,216},6958} packet="<open xml:lang='en' version='1.0' xmlns='urn:ietf:params:xml:ns:xmpp-framing' id='9c894cc38f58c39f' from='domain name here'/>" 
when=2024-02-06T08:55:32.362843+00:00 level=debug what=ws_send pid=<0.2614.0> at=mod_websockets:websocket_info/2:137 text="Sending xml over WebSockets" peer={{112,91,829,216},6958} packet="<features xmlns='http://etherx.jabber.org/streams'><session xmlns='urn:ietf:params:xml:ns:xmpp-session'/><bind xmlns='urn:ietf:params:xml:ns:xmpp-bind'/><register xmlns='http://jabber.org/features/iq-register'/><sm xmlns='urn:xmpp:sm:3'/></features>" 
when=2024-02-06T08:55:32.416834+00:00 level=debug what=ws_received pid=<0.2614.0> at=mod_websockets:websocket_handle/2:117 peer={{112,91,829,216},6958} msg="<resume h=\"5\" previd=\"uEhnZxZbkGqhwhpYcardtrbHJc+s\" xmlns=\"urn:xmpp:sm:3\"/>" 
when=2024-02-06T08:55:32.417238+00:00 level=debug what=received_raw_on_stream pid=<0.2616.0> at=mongoose_c2s:handle_socket_packet/2:222 elements="[{xmlel,<<\"resume\">>,[{<<\"h\">>,<<\"5\">>},{<<\"previd\">>,<<\"uEhnZxZbkGqhwhpYcardtrbHJc+s\">>},{<<\"xmlns\">>,<<\"urn:xmpp:sm:3\">>}],[]}]" c2s_pid=<0.2616.0> 
when=2024-02-06T08:55:32.417970+00:00 level=debug what=packet_before_session_established_sent pid=<0.2616.0> at=mongoose_c2s:handle_foreign_packet/3:689 c2s_pid=<0.2616.0> packet="{xmlel,<<\"resume\">>,[{<<\"h\">>,<<\"5\">>},{<<\"previd\">>,<<\"uEhnZxZbkGqhwhpYcardtrbHJc+s\">>},{<<\"xmlns\">>,<<\"urn:xmpp:sm:3\">>}],[]}" 
when=2024-02-06T08:55:32.418613+00:00 level=debug what=c2s_stream_error pid=<0.2600.0> at=mongoose_c2s:c2s_stream_error/2:860 xml_error="{xmlel,<<\"stream:error\">>,[],[{xmlel,<<\"conflict\">>,[{<<\"xmlns\">>,<<\"urn:ietf:params:xml:ns:xmpp-streams\">>}],[]}]}" c2s_state="{c2s_data,<<\"domain name here\">>,<<\"domain name here\">>,<<\"en\">>,{1707209661325746,<0.2600.0>},<<\"53804af2ae1eb351\">>,{jid,<<\"+111111111132\">>,<<\"domain name here\">>,<<\"mobile\">>},{c2s_socket,mod_websockets,{websocket,<0.2598.0>,{{112,91,829,216},8362},undefined}},{parser,#Ref<0.3711087841.2278424577.34976>,[]},none,#{access => all,port => 5280,shaper => none,hibernate_after => 0,proto => tcp,max_stanza_size => 0,ip_tuple => {0,0,0,0},c2s_state_timeout => infinity,backwards_compatible_session => true,xml_socket => true},ejabberd_auth_rdbms,#{mod_presence => {presences_state,{1,{{jid,<<\"+111111111132\">>,<<\"domain name here\">>,<<>>},nil,nil}},{1,{{jid,<<\"+111111111132\">>,<<\"domain name here\">>,<<>>},nil,nil}},{1,{{jid,<<\"+111111111132\">>,<<\"domain name here\">>,<<>>},nil,nil}},{0,nil},1,{xmlel,<<\"presence\">>,[{<<\"type\">>,<<\"available\">>},{<<\"xmlns\">>,<<\"jabber:client\">>}],[{xmlel,<<\"priority\">>,[],[{xmlcdata,<<\"1\">>}]}]},1707209666440180,false},mod_stream_management => {sm_state,[],0,5,5,100,1,undefined}},#{ip => {{112,91,829,216},8362},auth_module => ejabberd_auth_rdbms,publish_service => {{jid,<<>>,<<\"pubsub.domainname.com\">>,<<>>},<<\"clTKoqiDRL6odJgT51ra7k:APA91bEbKYA11LhHGBGIiPfjY4T1p5A_DeHVJf-zEndV6duaE_WgeYz8YinsIN8OYpkmmOam1-xHNX1RQ3czYxx8oPMrF3ofjidTYuVSw\"...>>,[{<<\"service\">>,<<\"fcm\">>},{<<\"device_id\">>,<<\"clTKoqiDRL6odJgT51ra7k:APA91bEbKYA11LhHGBGIiPfjY4T1p5A_DeHVJf-zEndV6duaE_WgeYz8YinsIN8OYpkmmOam1-xHNX1RQ3czY\"...>>},{<<\"silent\">>,<<\"true\">>},{<<\"topic\">>,<<\"com.appname\">>},{<<\"priority\">>,<<\"high\">>},{<<\"content-available\">>,<<\"true\">>}]},conn => c2s}}" 
when=2024-02-06T08:55:32.420072+00:00 level=debug what=ws_send pid=<0.2598.0> at=mod_websockets:websocket_info/2:137 text="Sending xml over WebSockets" peer={{112,91,829,216},8362} packet="<error xmlns='http://etherx.jabber.org/streams'><conflict xmlns='urn:ietf:params:xml:ns:xmpp-streams'/></error>" 
when=2024-02-06T08:55:32.420030+00:00 level=debug what=c2s_statem_terminate reason={shutdown,{shutdown,resumed}} pid=<0.2600.0> at=mongoose_c2s:terminate/3:195 user=+111111111132 c2s_state=session_established transport=mod_websockets dest_address_address=112,91,829,216 dest_address_port=8362 conn_type=c2s streamid=53804af2ae1eb351 session_started=2024-02-06T08:54:21.325746+00:00 resource=mobile server=domain name here jid=+111111111132@domainname.com/mobile 
when=2024-02-06T08:55:32.420239+00:00 level=debug what=ws_send pid=<0.2614.0> at=mod_websockets:websocket_info/2:137 text="Sending xml over WebSockets" peer={{112,91,829,216},6958} packet="<resumed xmlns='urn:xmpp:sm:3' previd='uEhnZxZbkGqhwhpYcardtrbHJc+s' h='5'/>" 
when=2024-02-06T08:55:32.420589+00:00 level=debug what=route pid=<0.2600.0> at=ejabberd_router:route/3:119 from_jid=+111111111132@domain name here/mobile to_jid=+111111111132@domain name here acc_timestamp=2024-02-06T08:55:32.420532+00:00 origin_pid=<0.2600.0> packet="<presence type='unavailable'><status>Unknown condition</status></presence>" 
when=2024-02-06T08:55:32.420531+00:00 level=debug what=ws_send pid=<0.2598.0> at=mod_websockets:websocket_info/2:137 text="Sending xml over WebSockets" peer={{112,91,829,216},8362} packet="<close xmlns='urn:ietf:params:xml:ns:xmpp-framing'/>" 
when=2024-02-06T08:55:32.420936+00:00 level=debug what=local_routing pid=<0.2600.0> at=ejabberd_local:do_route/4:364 from_jid=+111111111132@domain name here/mobile to_jid=+111111111132@domain name here acc_timestamp=2024-02-06T08:55:32.420532+00:00 origin_pid=<0.2600.0> packet="<presence type='unavailable'><status>Unknown condition</status></presence>" 
when=2024-02-06T08:55:32.421167+00:00 level=debug what=sm_route pid=<0.2600.0> at=ejabberd_sm:do_route/4:575 from_jid=+111111111132@domain name here/mobile to_jid=+111111111132@domain name here acc_timestamp=2024-02-06T08:55:32.420532+00:00 origin_pid=<0.2600.0> packet="<presence type='unavailable'><status>Unknown condition</status></presence>" 
when=2024-02-06T08:55:32.421908+00:00 level=debug what=sm_route pid=<0.2600.0> at=ejabberd_sm:do_route/4:575 from_jid=+111111111132@domain name here/mobile to_jid=+111111111132@domain name here/mobile acc_timestamp=2024-02-06T08:55:32.420532+00:00 origin_pid=<0.2600.0> packet="<presence type='unavailable'><status>Unknown condition</status></presence>" 
when=2024-02-06T08:55:32.422203+00:00 level=debug what=sm_route_to_pid pid=<0.2600.0> at=ejabberd_sm:do_route/4:587 from_jid=+111111111132@domain name here/mobile to_jid=+111111111132@domain name here/mobile session_pid=<0.2616.0> acc_timestamp=2024-02-06T08:55:32.420532+00:00 origin_pid=<0.2600.0> packet="<presence type='unavailable'><status>Unknown condition</status></presence>" 
when=2024-02-06T08:55:32.422707+00:00 level=debug what=ws_send pid=<0.2614.0> at=mod_websockets:websocket_info/2:137 text="Sending xml over WebSockets" peer={{112,91,829,216},6958} packet="<presence from='+111111111132@domain name here/mobile' to='+111111111132@domain name here/mobile' type='unavailable' xmlns='jabber:client'><status>Unknown condition</status></presence>" 
when=2024-02-06T08:55:32.422490+00:00 level=debug what=routing_result pid=<0.2600.0> at=ejabberd_router:route/3:123 from_jid=+111111111132@domain name here/mobile to_jid=+111111111132@domain name here routing_result=[{done,mongoose_router_localdomain}] routing_modules=[mongoose_router_global,mongoose_router_localdomain,mongoose_router_external_localnode,mongoose_router_external,mongoose_router_dynamic_domains,ejabberd_s2s] acc_timestamp=2024-02-06T08:55:32.420532+00:00 origin_pid=<0.2600.0> packet="<presence type='unavailable'><status>Unknown condition</status></presence>" 
when=2024-02-06T08:55:32.423159+00:00 level=debug what=ws_send pid=<0.2614.0> at=mod_websockets:websocket_info/2:137 text="Sending xml over WebSockets" peer={{112,91,829,216},6958} packet="<r xmlns='urn:xmpp:sm:3'/>" 
when=2024-02-06T08:55:32.423547+00:00 level=info what=cc_disable pid=<0.2600.0> at=mod_carboncopy:disable/2:334 user=+111111111132 server=domain name here
JanuszJakubiec commented 2 months ago

We are looking into the issue. Currently, we are expanding our tests, to cover the scenario described above. This may take some time, because firstly we need to make some changes to our XMPP websocket client used for tests, to make it support stream management. The necessary tasks were already added to our backlog. We will inform you when we solve the problem or find the solution.

alvinlal commented 2 months ago

@JanuszJakubiec , thanks, much appreciated