[ejabberd] BOSH infinite loop followed by an ejabberd crash.

Max Kalika max.kalika+ejabberd at gmail.com
Thu Nov 25 00:21:42 MSK 2010


Hello,

I managed to get the reproduction case down to a single http post.  I simply execute the following to cause ejabberd to spin:

$ cat break_bosh.txt | nc ark01 5280


Here are the contents of break_bosh.txt:

POST /http-bind HTTP/1.1
Host: ark-jabber
Content-type: text/xml; charset=utf-8
Content-length: 252

<body content='text/xml; charset=utf-8' hold='1' secure='true' to='ark-jabber' wait='0' xmpp:version='' aaa:lang='en' rid='18671' xmlns='http://jabber.org/protocol/httpbind' xmlns:xmpp='urn:xmpp:xbosh' xmlns:aaa='http://www.w3.org/XML/1998/namespace'/>


And finally here's the log of what happens in ejabberd.  I've cleared all logs and restarted the server to clear up all previous artifacts.  Furthermore, this is a vanilla installation on a virtual machine so there's no external clients connecting here.

=INFO REPORT==== 2010-11-24 12:07:47 ===
D(<0.221.0>:ejabberd_captcha:331) : The option captcha_cmd is not configured, but some module wants to use the CAPTCHA feature.

=INFO REPORT==== 2010-11-24 12:07:47 ===
I(<0.38.0>:ejabberd_rdbms:37) : ejabberd has not been compiled with relational database support. Skipping database startup.

=INFO REPORT==== 2010-11-24 12:07:47 ===
I(<0.248.0>:mod_http_fileserver:176) : initialize: 
 [{".css","text/css"},
  {".gif","image/gif"},
  {".html","text/html"},
  {".jar","application/java-archive"},
  {".jpeg","image/jpeg"},
  {".jpg","image/jpeg"},
  {".js","text/javascript"},
  {".png","image/png"},
  {".txt","text/plain"},
  {".xml","application/xml"},
  {".xpi","application/x-xpinstall"},
  {".xul","application/vnd.mozilla.xul+xml"}]

=INFO REPORT==== 2010-11-24 12:07:47 ===
D(<0.257.0>:mod_pubsub:175) : pubsub init "ark-jabber" [{access_createnode,
                                                         pubsub_createnode},
                                                        {max_items_node,
                                                         1000000},
                                                        {plugins,["flat"]}]

=INFO REPORT==== 2010-11-24 12:07:47 ===
D(<0.257.0>:mod_pubsub:257) : ** tree plugin is nodetree_tree

=INFO REPORT==== 2010-11-24 12:07:47 ===
D(<0.257.0>:mod_pubsub:261) : ** PEP Mapping : []


=INFO REPORT==== 2010-11-24 12:07:47 ===
D(<0.257.0>:mod_pubsub:263) : ** init flat plugin

=INFO REPORT==== 2010-11-24 12:07:47 ===
I(<0.38.0>:ejabberd_app:70) : ejabberd 2.1.5 is started in the node ejabberd at ark01

=INFO REPORT==== 2010-11-24 13:09:05 ===
I(<0.290.0>:ejabberd_listener:232) : (#Port<0.5035>) Accepted connection {{192,168,12,1},52706} -> {{192,168,12,11},5280}

=INFO REPORT==== 2010-11-24 13:09:05 ===
D(<0.360.0>:ejabberd_http:136) : S: [{["web"],mod_http_fileserver},
                                     {["admin"],ejabberd_web_admin},
                                     {["http-bind"],mod_http_bind},
                                     {["http-poll"],ejabberd_http_poll}]


=INFO REPORT==== 2010-11-24 13:09:05 ===
I(<0.360.0>:ejabberd_http:138) : started: {gen_tcp,#Port<0.5035>}

=INFO REPORT==== 2010-11-24 13:09:06 ===
D(<0.360.0>:ejabberd_http:255) : (#Port<0.5035>) http query: 'POST' /http-bind


=INFO REPORT==== 2010-11-24 13:09:06 ===
D(<0.360.0>:ejabberd_http:421) : client data: "<body content='text/xml; charset=utf-8' hold='1' secure='true' to='ark-jabber' wait='0' xmpp:version='' aaa:lang='en' rid='18671' xmlns='http://jabber.org/protocol/httpbind' xmlns:xmpp='urn:xmpp:xbosh' xmlns:aaa='http://www.w3.org/XML/1998/namespace'/>"


=INFO REPORT==== 2010-11-24 13:09:06 ===
D(<0.360.0>:ejabberd_http:324) : ["http-bind"] matches ["http-bind"]

=INFO REPORT==== 2010-11-24 13:09:06 ===
D(<0.360.0>:mod_http_bind:67) : Incoming data: <body content='text/xml; charset=utf-8' hold='1' secure='true' to='ark-jabber' wait='0' xmpp:version='' aaa:lang='en' rid='18671' xmlns='http://jabber.org/protocol/httpbind' xmlns:xmpp='urn:xmpp:xbosh' xmlns:aaa='http://www.w3.org/XML/1998/namespace'/>

=INFO REPORT==== 2010-11-24 13:09:06 ===
D(<0.360.0>:ejabberd_http_bind:1123) : --- incoming data --- 
<body content='text/xml; charset=utf-8' hold='1' secure='true' to='ark-jabber' wait='0' xmpp:version='' aaa:lang='en' rid='18671' xmlns='http://jabber.org/protocol/httpbind' xmlns:xmpp='urn:xmpp:xbosh' xmlns:aaa='http://www.w3.org/XML/1998/namespace'/>
 --- END --- 

=INFO REPORT==== 2010-11-24 13:09:06 ===
D(<0.360.0>:ejabberd_http_bind:122) : Starting session

=INFO REPORT==== 2010-11-24 13:09:06 ===
D(<0.361.0>:ejabberd_http_bind:312) : started: {"5f1bc4b520f9aaf84b6015509ee63b8f73dfa12b",
                                                [],
                                                {{192,168,12,1},52706}}

=INFO REPORT==== 2010-11-24 13:09:06 ===
D(<0.360.0>:ejabberd_http_bind:242) : got pid: <0.361.0>

=INFO REPORT==== 2010-11-24 13:09:06 ===
D(<0.360.0>:ejabberd_http_bind:284) : Create session: "5f1bc4b520f9aaf84b6015509ee63b8f73dfa12b"

=INFO REPORT==== 2010-11-24 13:09:06 ===
D(<0.360.0>:ejabberd_http_bind:806) : Looking for session: "5f1bc4b520f9aaf84b6015509ee63b8f73dfa12b"

=INFO REPORT==== 2010-11-24 13:09:06 ===
D(<0.361.0>:ejabberd_http_bind:428) : New request: {http_put,18671,
                                                    [{"content",
                                                      "text/xml; charset=utf-8"},
                                                     {"hold","1"},
                                                     {"secure","true"},
                                                     {"to","ark-jabber"},
                                                     {"wait","0"},
                                                     {"xmpp:version",[]},
                                                     {"aaa:lang","en"},
                                                     {"rid","18671"},
                                                     {"xmlns",
                                                      "http://jabber.org/protocol/httpbind"},
                                                     {"xmlns:xmpp",
                                                      "urn:xmpp:xbosh"},
                                                     {"xmlns:aaa",
                                                      "http://www.w3.org/XML/1998/namespace"}],
                                                    [],252,1,
                                                    {"ark-jabber",[]},
                                                    {{192,168,12,1},52706}}

=INFO REPORT==== 2010-11-24 13:09:06 ===
D(<0.361.0>:ejabberd_http_bind:568) : New request: {http_put,18671,
                                                    [{"content",
                                                      "text/xml; charset=utf-8"},
                                                     {"hold","1"},
                                                     {"secure","true"},
                                                     {"to","ark-jabber"},
                                                     {"wait","0"},
                                                     {"xmpp:version",[]},
                                                     {"aaa:lang","en"},
                                                     {"rid","18671"},
                                                     {"xmlns",
                                                      "http://jabber.org/protocol/httpbind"},
                                                     {"xmlns:xmpp",
                                                      "urn:xmpp:xbosh"},
                                                     {"xmlns:aaa",
                                                      "http://www.w3.org/XML/1998/namespace"}],
                                                    [],252,1,
                                                    {"ark-jabber",[]},
                                                    {{192,168,12,1},52706}}

=INFO REPORT==== 2010-11-24 13:09:06 ===
D(<0.361.0>:ejabberd_http_bind:605) : Actually processing request: {http_put,
                                                                    18671,
                                                                    [{"content",
                                                                      "text/xml; charset=utf-8"},
                                                                     {"hold",
                                                                      "1"},
                                                                     {"secure",
                                                                      "true"},
                                                                     {"to",
                                                                      "ark-jabber"},
                                                                     {"wait",
                                                                      "0"},
                                                                     {"xmpp:version",
                                                                      []},
                                                                     {"aaa:lang",
                                                                      "en"},
                                                                     {"rid",
                                                                      "18671"},
                                                                     {"xmlns",
                                                                      "http://jabber.org/protocol/httpbind"},
                                                                     {"xmlns:xmpp",
                                                                      "urn:xmpp:xbosh"},
                                                                     {"xmlns:aaa",
                                                                      "http://www.w3.org/XML/1998/namespace"}],
                                                                    [],252,1,
                                                                    {"ark-jabber",
                                                                     []},
                                                                    {{192,168,
                                                                      12,1},
                                                                     52706}}

=INFO REPORT==== 2010-11-24 13:09:06 ===
D(<0.361.0>:ejabberd_http_bind:668) :  -- SaveKey: 


=INFO REPORT==== 2010-11-24 13:09:06 ===
D(<0.361.0>:ejabberd_http_bind:686) : reqlist: [{hbr,18671,[],[]}]

=INFO REPORT==== 2010-11-24 13:09:06 ===
D(<0.361.0>:ejabberd_http_bind:734) : really sending now: []

=INFO REPORT==== 2010-11-24 13:09:06 ===
D(<0.360.0>:ejabberd_http_bind:918) : OutPacket: [{xmlstreamstart,
                                                   "stream:stream",
                                                   [{"xml:lang","en"},
                                                    {"xmlns","jabber:client"},
                                                    {"xmlns:stream",
                                                     "http://etherx.jabber.org/streams"},
                                                    {"id","3098318317"},
                                                    {"from","ark-jabber"}]}]

=INFO REPORT==== 2010-11-24 13:09:06 ===
D(<0.360.0>:ejabberd_http_bind:918) : OutPacket: [{xmlstreamstart,
                                                   "stream:stream",
                                                   [{"xml:lang","en"},
                                                    {"xmlns","jabber:client"},
                                                    {"xmlns:stream",
                                                     "http://etherx.jabber.org/streams"},
                                                    {"id","3098318317"},
                                                    {"from","ark-jabber"}]}]

=INFO REPORT==== 2010-11-24 13:09:06 ===
D(<0.360.0>:ejabberd_http_bind:918) : OutPacket: [{xmlstreamstart,
                                                   "stream:stream",
                                                   [{"xml:lang","en"},
                                                    {"xmlns","jabber:client"},
                                                    {"xmlns:stream",
                                                     "http://etherx.jabber.org/streams"},
                                                    {"id","3098318317"},
                                                    {"from","ark-jabber"}]}]

=INFO REPORT==== 2010-11-24 13:09:06 ===
D(<0.360.0>:ejabberd_http_bind:918) : OutPacket: [{xmlstreamstart,
                                                   "stream:stream",
                                                   [{"xml:lang","en"},
                                                    {"xmlns","jabber:client"},
                                                    {"xmlns:stream",
                                                     "http://etherx.jabber.org/streams"},
                                                    {"id","3098318317"},
                                                    {"from","ark-jabber"}]}]

=INFO REPORT==== 2010-11-24 13:09:06 ===
D(<0.360.0>:ejabberd_http_bind:918) : OutPacket: [{xmlstreamstart,
                                                   "stream:stream",
                                                   [{"xml:lang","en"},
                                                    {"xmlns","jabber:client"},
                                                    {"xmlns:stream",
                                                     "http://etherx.jabber.org/streams"},
                                                    {"id","3098318317"},
                                                    {"from","ark-jabber"}]}]

=INFO REPORT==== 2010-11-24 13:09:06 ===
D(<0.360.0>:ejabberd_http_bind:918) : OutPacket: [{xmlstreamstart,
                                                   "stream:stream",
                                                   [{"xml:lang","en"},
                                                    {"xmlns","jabber:client"},
                                                    {"xmlns:stream",
                                                     "http://etherx.jabber.org/streams"},
                                                    {"id","3098318317"},
                                                    {"from","ark-jabber"}]}]

On Nov 23, 2010, at 12:22 PM, Christopher Zorn wrote:

> Hello, from reading over your description it seems it may be something the BOSH client is doing or not doing. Can you provide a client log of when this happens. Including the server log may help too. If we can see what the client is sending or not then we can probally get a better idea of what is happening. 



More information about the ejabberd mailing list