[jitsi-dev] [jitsi-videobridge] missing "from" in ping requests (#93)


#1

hi,

i've many logs lines that look like

2015-10-28 14:30:57.447 SEVERE: [20] org.jitsi.xmpp.component.ComponentBase.run().401 Ping timeout for ID: irRLf-1056

a rapid tcp dump show me that the ping request look like

<iq.id="irRLf-1056" to="intranet.test" type="get"><ping.xmlns="urn:xmpp:ping"></ping></iq>

and openfire explode with:

 org.jivesoftware.openfire.spi.RoutingTableImpl - Primary packet routing failed
org.jivesoftware.openfire.PacketException: Cannot route packet of type IQ or Presence to bare JID: <iq type="result" id="irRLf-11" from="intranet.test"/> 

a quick look at
http://xmpp.org/extensions/xep-0199.html#c2s
show that "from" seems to be required (it's not written but there is no mention that it's optionnal, and all exemples have "from")

totally new to xmpp & jvb
i'm using

jitsi-videobridge-linux-x64-547.zip
openfire_3_10_2.tar.gz
centos 6 lxc (fedora 22 host)
java-1.8.0-openjdk (also tried 1.7)
···

---
Reply to this email directly or view it on GitHub:
https://github.com/jitsi/jitsi-videobridge/issues/93


#2

Hi.

I have the same problem.

jvb.log:

2015-11-11 08:27:44.162 INFO: [22] org.jitsi.videobridge.xmpp.ComponentImpl.handleIQError() (serving component 'JitsiVideobridge') IQ stanza of type <tt>error</tt> received:
2015-11-11 08:27:44.163 INFO: [22] org.jitsi.videobridge.xmpp.ComponentImpl.info() RECV: <iq type="error" from="jabber.st" id="3Iosx-0"><ping xmlns="urn:xmpp:ping"/><error code="400" type="modify"><bad-request xmlns="urn:ietf:params:xml:ns:xmpp-stanzas"/></error></iq>
2015-11-11 08:27:49.160 SEVERE: [19] org.jitsi.xmpp.component.ComponentBase.run().401 Ping timeout for ID: 3Iosx-0

Message from videobridge:

<iq id="3Iosx-0" to="jabber.st" type="get">
  <ping xmlns="urn:xmpp:ping"></ping>
</iq>

Reply from ejabberd:

<iq type='error' from='jabber.st' id='3Iosx-0'>
  <ping xmlns='urn:xmpp:ping'/>
  <error code='400' type='modify'><bad-request xmlns='urn:ietf:params:xml:ns:xmpp-stanzas'/>
  </error>
</iq>

Version of videobridge:

jitsi-videobridge-linux-x64-555
···

---
Reply to this email directly or view it on GitHub:
https://github.com/jitsi/jitsi-videobridge/issues/93#issuecomment-155680353


#3

Thanks for the report we'll have a look at it !

···

---
Reply to this email directly or view it on GitHub:
https://github.com/jitsi/jitsi-videobridge/issues/93#issuecomment-155819331


#4

I have the exact same problem. I did an experiment by sending the exact same <ping> stanza copy from jitsi-videbridge trace, but sent it via a registered jid client on PSI+. I found that ejabberd did response correctly to the <ping> stanza sent from PSI+ client. However ejabberd just ignore <ping> stanza sent from jitsi-videobridge. looking at the ejabberd log.

So it is nothing wrong with the ping stanza format, My understanding is <ping> is used between a registered logon JID client and the xmpp server; and it is exchanged over the xmpp c2s port 5222.
The question is can a ping stanza be send from a jitsi-videobridge service component.and via port 5275. Since jitsi-videobridge is not an xmpp registered JID client, I would think ejabberd would not have the JID login information and have problem know whom to reply the ping result to. May be jitsi-videbridge should not use <ping> to test for active connection between itself and xmpp ejabberd server.

Below are the attached log information:
====== Sent from jitsi-videobrige. log on ejabberd server =======
14:59:19.323 [debug] Received XML on stream = <<"<iq id=\"BtEuo-126\" to=\"example.org\" type=\"get\"><ping xmlns=\"urn:xmpp:ping\"></ping></iq>">>
{state,#Port<0.6592>,gen_tcp,{maxrate,50000,8.499799547337442,1451285949323972},<0.547.0>,infinity,<<>>,infinity}
14:59:19.323 [debug] State: {maxrate,50000,8.499799547337442,1451285949323972}, Size=85
M=0.8500722544376348, I=9999.4

====== Same ping stanza sent from psi+ client: log on ejabberd server =======
15:05:16.498 [debug] Received XML on stream = <<"<iq id=\"BtEuo-153\" to=\"example.org\" type=\"get\"><ping xmlns=\"urn:xmpp:ping\"></ping></iq>">>
{state,{tlssock,#Port<0.6651>,#Port<0.6652>},p1_tls,none,<0.569.0>,65536,<<>>,infinity}
15:05:16.498 [debug] route
        from {jid,<<"admin">>,<<"example.org">>,<<"Psi+">>,<<"admin">>,<<"example.org">>,<<"Psi+">>}
        to {jid,<<>>,<<"example.org">>,<<>>,<<>>,<<"example.org">>,<<>>}
        packet {xmlel,<<"iq">>,[{<<"xml:lang">>,<<"en">>},{<<"id">>,<<"BtEuo-153">>},{<<"to">>,<<"example.org">>},{<<"type">>,<<"get">>}],[{xmlel,<<"ping">>,[{<<"xmlns">>,<<"urn:xmpp:ping">>}],[]}]}
15:05:16.498 [debug] local route
        from {jid,<<"admin">>,<<"example.org">>,<<"Psi+">>,<<"admin">>,<<"example.org">>,<<"Psi+">>}
        to {jid,<<>>,<<"example.org">>,<<>>,<<>>,<<"example.org">>,<<>>}
        packet {xmlel,<<"iq">>,[{<<"xml:lang">>,<<"en">>},{<<"id">>,<<...>>},{<<...>>,...},{...}],[{xmlel,<<...>>,...}]}
15:05:16.499 [debug] route
        from {jid,<<>>,<<"example.org">>,<<>>,<<>>,<<"example.org">>,<<>>}
        to {jid,<<"admin">>,<<"example.org">>,<<"Psi+">>,<<"admin">>,<<"example.org">>,<<"Psi+">>}
        packet {xmlel,<<"iq">>,[{<<"id">>,<<"BtEuo-153">>},{<<"type">>,<<"result">>}],[]}
15:05:16.499 [debug] local route
        from {jid,<<>>,<<"example.org">>,<<>>,<<>>,<<"example.org">>,<<>>}
        to {jid,<<"admin">>,<<"example.org">>,<<"Psi+">>,<<"admin">>,<<"example.org">>,<<"Psi+">>}
        packet {xmlel,<<"iq">>,[{<<"id">>,<<"BtEu"...>>},{<<"type">>,<<...>>}],[]}
15:05:16.499 [debug] session manager
        from {jid,<<>>,<<"example.org">>,<<>>,<<>>,<<"example.org">>,<<>>}
        to {jid,<<"admin">>,<<"example.org">>,<<"Psi+">>,<<"admin">>,<<"example.org">>,<<"Psi+">>}
        packet {xmlel,<<"iq">>,[{<<"id">>,<<"BtEu"...>>},{<<"type">>,<<...>>}],[]}
15:05:16.499 [debug] sending to process <0.569.0>
15:05:16.499 [debug] Send XML on stream = <<"<iq from='example.org' to='admin@example.org/Psi+' id='BtEuo-153' type='result'/>">>
15:05:19.329 [debug] Received XML on stream = <<"<iq id=\"BtEuo-162\" to=\"example.org\" type=\"get\"><ping xmlns=\"urn:xmpp:ping\"></ping></iq>">>
{state,#Port<0.6592>,gen_tcp,{maxrate,50000,8.499672756345218,1451286309328925},<0.547.0>,infinity,<<>>,infinity}
15:05:19.329 [debug] State: {maxrate,50000,8.499672756345218,1451286309328925}, Size=85
M=0.850072253359728, I=10000.586

···

---
Reply to this email directly or view it on GitHub:
https://github.com/jitsi/jitsi-videobridge/issues/93#issuecomment-167504262


#5

Sorry has to resend the log text, as the previous pasted text contain black-slash, leading to missing
text in previous comment.

Added Info:
The ejabberd server is v15.11 and I have modified the ejabberd src to dump both the Data and State info: ?DEBUG("Received XML on stream = ~p~n~p", [(Data), State]),

====== Sent from jitsi-videobrige. log on ejabberd server =======
14:59:19.323 [debug] Received XML on stream = <<"<iq id="BtEuo-126" to="example.org" type="get"><ping xmlns="urn:xmpp:ping"></ping></iq>">>
{state,#Port<0.6592>,gen_tcp,{maxrate,50000,8.499799547337442,1451285949323972},<0.547.0>,infinity,<<>>,infinity}
14:59:19.323 [debug] State: {maxrate,50000,8.499799547337442,1451285949323972}, Size=85
M=0.8500722544376348, I=9999.4

====== Same ping stanza sent from psi+ client: log on ejabberd server =======
15:05:16.498 [debug] Received XML on stream = <<"<iq id="BtEuo-153" to="example.org" type="get"><ping xmlns="urn:xmpp:ping"></ping></iq>">>
{state,{tlssock,#Port<0.6651>,#Port<0.6652>},p1_tls,none,<0.569.0>,65536,<<>>,infinity}
15:05:16.498 [debug] route
        from {jid,<<"admin">>,<<"example.org">>,<<"Psi+">>,<<"admin">>,<<"example.org">>,<<"Psi+">>}
        to {jid,<<>>,<<"example.org">>,<<>>,<<>>,<<"example.org">>,<<>>}
        packet {xmlel,<<"iq">>,[{<<"xml:lang">>,<<"en">>},{<<"id">>,<<"BtEuo-153">>},{<<"to">>,<<"example.org">>},{<<"type">>,<<"get">>}],[{xmlel,<<"ping">>,[{<<"xmlns">>,<<"urn:xmpp:ping">>}],[]}]}
15:05:16.498 [debug] local route
        from {jid,<<"admin">>,<<"example.org">>,<<"Psi+">>,<<"admin">>,<<"example.org">>,<<"Psi+">>}
        to {jid,<<>>,<<"example.org">>,<<>>,<<>>,<<"example.org">>,<<>>}
        packet {xmlel,<<"iq">>,[{<<"xml:lang">>,<<"en">>},{<<"id">>,<<...>>},{<<...>>,...},{...}],[{xmlel,<<...>>,...}]}
15:05:16.499 [debug] route
        from {jid,<<>>,<<"example.org">>,<<>>,<<>>,<<"example.org">>,<<>>}
        to {jid,<<"admin">>,<<"example.org">>,<<"Psi+">>,<<"admin">>,<<"example.org">>,<<"Psi+">>}
        packet {xmlel,<<"iq">>,[{<<"id">>,<<"BtEuo-153">>},{<<"type">>,<<"result">>}],[]}
15:05:16.499 [debug] local route
        from {jid,<<>>,<<"example.org">>,<<>>,<<>>,<<"example.org">>,<<>>}
        to {jid,<<"admin">>,<<"example.org">>,<<"Psi+">>,<<"admin">>,<<"example.org">>,<<"Psi+">>}
        packet {xmlel,<<"iq">>,[{<<"id">>,<<"BtEu"...>>},{<<"type">>,<<...>>}],[]}
15:05:16.499 [debug] session manager
        from {jid,<<>>,<<"example.org">>,<<>>,<<>>,<<"example.org">>,<<>>}
        to {jid,<<"admin">>,<<"example.org">>,<<"Psi+">>,<<"admin">>,<<"example.org">>,<<"Psi+">>}
        packet {xmlel,<<"iq">>,[{<<"id">>,<<"BtEu"...>>},{<<"type">>,<<...>>}],[]}
15:05:16.499 [debug] sending to process <0.569.0>
15:05:16.499 [debug] Send XML on stream = <<"<iq from='example.org' to='admin@example.org/Psi+' id='BtEuo-153' type='result'/>">>
15:05:19.329 [debug] Received XML on stream = <<"<iq id="BtEuo-162" to="example.org" type="get"><ping xmlns="urn:xmpp:ping"></ping></iq>">>
{state,#Port<0.6592>,gen_tcp,{maxrate,50000,8.499672756345218,1451286309328925},<0.547.0>,infinity,<<>>,infinity}
15:05:19.329 [debug] State: {maxrate,50000,8.499672756345218,1451286309328925}, Size=85
M=0.850072253359728, I=10000.586

···

---
Reply to this email directly or view it on GitHub:
https://github.com/jitsi/jitsi-videobridge/issues/93#issuecomment-167507758


#6

Sorry, using wireshark to capture protocol exchanges on local loopback, actually ejabberd did response to ping from jitsi-videobridge with the error code via port 5275:
<iq type="error" from="example.org" id="ItESz-64"><ping xmlns="urn:xmpp:ping"/><error code="400" type="modify"><bad-request xmlns="urn:ietf:params:xml:ns:xmpp-stanzas"/></error></iq>

···

---
Reply to this email directly or view it on GitHub:
https://github.com/jitsi/jitsi-videobridge/issues/93#issuecomment-167658365


#7

Further investigation on ejabberd_service.erl source, the missing of the attribute "from" in ping request is in fact the root cause of the problem. (sorry for my earlier incorrect feedback)

I make the following patches to the ejabberd_service.erl source, then the jitsi-videobridge does receive the correct <iq> reply to ping request.

===== extraction from ejabberd_service.erl with modification ========
stream_established({xmlstreamelement, El}, StateData) ->
    NewEl = jlib:remove_attr(<<"xmlns">>, El),
    #xmlel{name = Name, attrs = Attrs} = NewEl,
    %%% cmeng - modified for testing only %%%
    %% From = xml:get_attr_s(<<"from">>, Attrs),
    From = <<"jitsi-videobridge.example.org">>,
    FromJID = case StateData#state.check_from of
    %% If the admin does not want to check the from field
    %% when accept packets from any address.
    %% In this case, the component can send packet on
    %% behalf of the server users.
    false -> jlib:string_to_jid(From);
    %% The default is the standard behaviour in XEP-0114
    _ ->
        FromJID1 = jlib:string_to_jid(From),
        case FromJID1 of
          #jid{lserver = Server} ->
        case lists:member(Server, StateData#state.hosts) of
          true -> FromJID1;
          false -> error
        end;
          _ -> error
        end
        end,
    To = xml:get_attr_s(<<"to">>, Attrs),
  ToJID = case To of
        <<"">> -> error;
        _ -> jlib:string_to_jid(To)
      end,
    if ((Name == <<"iq">>) or (Name == <<"message">>) or
    (Name == <<"presence">>))
   and (ToJID /= error) ->
   %% and (FromJID /= error) ->
     ejabberd_router:route(FromJID, ToJID, NewEl);
       true ->
     Err = jlib:make_error_reply(NewEl, ?ERR_BAD_REQUEST),
     send_element(StateData, Err),
     error
    end,
    {next_state, stream_established, StateData};

====== correct reply to jitsi-videobridge ping request after the source patch ==========
Dec 30, 2015 8:05:51 AM org.jitsi.util.Logger info
INFO: RECV: <iq from="example.org" to="jitsi-videobridge.example.org" id="9tNKQ-265" type="result"/>

···

---
Reply to this email directly or view it on GitHub:
https://github.com/jitsi/jitsi-videobridge/issues/93#issuecomment-167903769


#8

Hi ,
Is there any update on it. i am also facing similler issue

SEVERE: [29] org.jitsi.xmpp.component.ComponentBase.run().417 Ping timeout for ID: noGrM-159
SEVERE: [29] org.jitsi.xmpp.component.ComponentBase.run().417 Ping timeout for ID: noGrM-160
SEVERE: [29] org.jitsi.xmpp.component.ComponentBase.run().417 Ping timeout for ID: noGrM-161

jitsi-videobridge-windows-x86-613
openfire_3_10_3.

Thanks

···

---
Reply to this email directly or view it on GitHub:
https://github.com/jitsi/jitsi-videobridge/issues/93#issuecomment-170267629


#9

Hi @rajuw,
I've open a PR that fix it for me, see
https://github.com/jitsi/jicoco/pull/4

···

---
Reply to this email directly or view it on GitHub:
https://github.com/jitsi/jitsi-videobridge/issues/93#issuecomment-170278566


#10

Closed #93 via jitsi/jicoco#4.

···

---
Reply to this email directly or view it on GitHub:
https://github.com/jitsi/jitsi-videobridge/issues/93#event-510285931