ejabberd - Comments for "strange loop - ejabberd_router"

re

mfoss — Sat, 14 May 2011 10:17:15 +0000

dzejefkej wrote:

- get_status does not work (c2s hangs in call - thats mysterious also btw.)

Try:
ejabberd_sm:get_session_pid("badlop", "localhost", "home").

strange loop

dzejefkej — Thu, 12 May 2011 21:53:38 +0000

I think that {ejabberd_c2s,bounce_messages,0} is a root of my problems. It is executed endlessly.
It is because session is not removed from session table.. but why?;)

strange loop

dzejefkej — Wed, 11 May 2011 19:34:56 +0000

badlop wrote:

dzejefkej wrote:

how to discover Pid of a reciever of the c2s?)

Maybe I didn't understand your question. ejabberd creates two processes per XMPP session (one for sm and one for c2s). In this example, the processes are 0.483.0 and 0.484.0:

Your right, but that info comes from INFO debbug level. I cannot turn it on on production.
Is there any other way to discover Pid of the reciever belonging to c2s?
- get_status does not work (c2s hangs in call - thats mysterious also btw.)
- process_info on pid which is lower by 1 integer 483 and 484 returns undefined, however under heavy traffic there is no guarantee that those pids diff by 1.

badlop wrote:

dzejefkej wrote:

The data flow is:
ejabberd_router:route
ejabberd_router:do_route
ejabberd_sm:route

and again _router..

How to determine if those are new messages or some loop in the code?

Check if the function is called with the same arguments several times:

--- a/src/ejabberd_router.erl
+++ b/src/ejabberd_router.erl
@@ -65,6 +65,7 @@ start_link() ->
 
 
 route(From, To, Packet) ->
+    ?INFO_MSG("ejabberd_router:route:~nFrom: ~p~nTo: ~p~nPacket: ~p", [ From, To, Packet]),
     case catch do_route(From, To, Packet) of
        {'EXIT', Reason} ->
            ?ERROR_MSG("~p~nwhen processing: ~p",

I attached DBG on production to malfunctioning process. It is all the time the same presence unavailable stanza
with From = To. I traced calls and messages on _router, _local, _sm, _c2s, _roster. Here is the result, sometimes instead of presence I see unsubscribe. Couple sec of dbg generates ~50mb of trace :/

(<6567.1465.114>) << {route,
                         {jid,"test43",
                             "example.test.com","mobile",
                             "test43",
                             "example.test.com","mobile"},
                         {jid,"test43",
                             "example.test.com","mobile",
                             "test43",
                             "example.test.com","mobile"},
                         {xmlelement,"presence",[{"type","unavailable"}],[]}}
(<6567.1465.114>) call ejabberd_router:route({jid,"test43","example.test.com","mobile",
     "test43","example.test.com","mobile"},{jid,"test43","example.test.com","mobile",
     "test43","example.test.com","mobile"},{xmlelement,"presence",[{"type","unavailable"}],[]})
(<6567.1465.114>) call ejabberd_local:route({jid,"test43","example.test.com","mobile",
     "test43","example.test.com","mobile"},{jid,"test43","example.test.com","mobile",
     "test43","example.test.com","mobile"},{xmlelement,"presence",[{"type","unavailable"}],[]})
(<6567.1465.114>) call ejabberd_sm:route({jid,"test43","example.test.com","mobile",
     "test43","example.test.com","mobile"},{jid,"test43","example.test.com","mobile",
     "test43","example.test.com","mobile"},{xmlelement,"presence",[{"type","unavailable"}],[]})
(<6567.1465.114>) <6567.1465.114> ! {route,
                                     {jid,"test43",
                                      "example.test.com","mobile",
                                      "test43",
                                      "example.test.com","mobile"},
                                     {jid,"test43",
                                      "example.test.com","mobile",
                                      "test43",
                                      "example.test.com","mobile"},
                                     {xmlelement,"presence",
                                      [{"type","unavailable"}],
                                      []}}
(<6567.1465.114>) << {route,
                         {jid,"test43",
                             "example.test.com","mobile",
                             "test43",
                             "example.test.com","mobile"},
                         {jid,"test43",
                             "example.test.com","mobile",
                             "test43",
                             "example.test.com","mobile"},
                         {xmlelement,"presence",[{"type","unavailable"}],[]}}

So the SM asks for PID of To - it gets it, because it is in session table. It routs the presence to the PID and gets it back from router. Is there any mechanism to prevent such a behavior when From = To ? Also.. I do not see c2s here in dbg, so even if it hangs in 'call' why it does not time out?

badlop wrote:

dzejefkej wrote:

=ERROR REPORT==== 2011-05-05 23:37:17 ===
E(<0.7292.2960>:ejabberd_c2s:1154) : Unexpected info: {'DOWN',
#Ref<0.0.1439.188998>,
process,
<10545.13676.2940>,
killed}

A process number 0.XXX.0 means that the process lives in the local node where you see that number. A number like 123.XXX.0 means that the process lives in a remote node of the cluster.

Maybe ejabberd got confused with the routing scheme, and is sending a XMPP packet from one node to the other, and back to the first, and to the second... until some process dies or timeouts?

Yeah, I got the pid structure, for now it looks like completely unrelated to 'loop'. Still I do not like correlation in time of those 2 issues. How to investigate routing scheme? How would you look for a reason to kill this local process?
I thought that socket may be closed, this kills receiver, which kills c2s and eventually affects the other side of conversation.

appreciate any hints on that..

dzejefkej wrote: how to

mfoss — Tue, 10 May 2011 22:53:08 +0000

dzejefkej wrote:

how to discover Pid of a reciever of the c2s?)

Maybe I didn't understand your question. ejabberd creates two processes per XMPP session (one for sm and one for c2s). In this example, the processes are 0.483.0 and 0.484.0:

=INFO REPORT==== 11-May-2011::00:44:10 ===
I(<0.476.0>:ejabberd_listener:281) : (#Port<0.5268>)
Accepted connection {{127,0,0,1},59334} -> {{127,0,0,1},5222}

=INFO REPORT==== 11-May-2011::00:44:10 ===
I(<0.484.0>:ejabberd_c2s:517) : ({socket_state,gen_tcp,#Port<0.5268>,<0.483.0>})
Accepted legacy authentication for badlop@localhost/work by ejabberd_auth_internal

dzejefkej wrote:

The data flow is:
ejabberd_router:route
ejabberd_router:do_route
ejabberd_sm:route

and again _router..

How to determine if those are new messages or some loop in the code?

Check if the function is called with the same arguments several times:

--- a/src/ejabberd_router.erl
+++ b/src/ejabberd_router.erl
@@ -65,6 +65,7 @@ start_link() ->
 
 
 route(From, To, Packet) ->
+    ?INFO_MSG("ejabberd_router:route:~nFrom: ~p~nTo: ~p~nPacket: ~p", [ From, To, Packet]),
     case catch do_route(From, To, Packet) of
        {'EXIT', Reason} ->
            ?ERROR_MSG("~p~nwhen processing: ~p",

dzejefkej wrote:

=ERROR REPORT==== 2011-05-05 23:37:17 ===
E(<0.7292.2960>:ejabberd_c2s:1154) : Unexpected info: {'DOWN',
#Ref<0.0.1439.188998>,
process,
<10545.13676.2940>,
killed}

A process number 0.XXX.0 means that the process lives in the local node where you see that number. A number like 123.XXX.0 means that the process lives in a remote node of the cluster.

Maybe ejabberd got confused with the routing scheme, and is sending a XMPP packet from one node to the other, and back to the first, and to the second... until some process dies or timeouts?