Some FB chat messages sent via xmpp4r do not get received

Question

I try to send a message from one fb user to one of his friends. Most of the time the messages got received. The missing ones are marked as sent in the logs. The ruby gem used for sending the message is xmpp4r_facebook which in turn uses xmpp4r. Example missing message is Hi, friend! 2013-09-11 17:46:10 +0300 which is not received among others:

Hi, friend! 2013-09-11 17:46:05 +0300
Hi, friend! 2013-09-11 17:46:08 +0300
Hi, friend! 2013-09-11 17:46:13 +0300
Hi, friend! 2013-09-11 17:46:16 +0300

Here is the message log that looks just like the logs for the successfully received messages:

Debugging mode enabled.
Warnings mode enabled.
RESOLVING:
    _xmpp-client._tcp.chat.facebook.com (SRV)
CONNECTING:
    chat.facebook.com:5222
"Socket:"
"local address: [\"AF_INET\", 39123, \"172.27.*.**\", \"172.27.*.**\"]"
"Thread list size: 1"
#<TCPSocket:fd 11>
SENDING:
    <stream:stream xmlns:stream='http://etherx.jabber.org/streams' xmlns='jabber:client' to='chat.facebook.com' xml:lang='en' version='1.0' >
RECEIVED:
    <stream:stream from='chat.facebook.com' id='1' xml:lang='en' xmlns:stream='http://etherx.jabber.org/streams' version='1.0' xmlns='jabber:client'/>
RECEIVED:
    <stream:features><starttls xmlns='urn:ietf:params:xml:ns:xmpp-tls'/><mechanisms xmlns='urn:ietf:params:xml:ns:xmpp-sasl'><mechanism>X-FACEBOOK-PLATFORM</mechanism><mechanism>PLAIN</mechanism></mechanisms></stream:features>
FEATURES: received
PROCESSING:
    <stream:features xmlns='jabber:client'><starttls xmlns='urn:ietf:params:xml:ns:xmpp-tls'/><mechanisms xmlns='urn:ietf:params:xml:ns:xmpp-sasl'><mechanism>X-FACEBOOK-PLATFORM</mechanism><mechanism>PLAIN</mechanism></mechanisms></stream:features> (REXML::Element)
FEATURES: waiting...
TRYING stanzacbs...
FEATURES: waiting finished
TRYING message/iq/presence/cbs...
SENDING:
    <starttls xmlns='urn:ietf:params:xml:ns:xmpp-tls'/>
RECEIVED:
    <proceed xmlns='urn:ietf:params:xml:ns:xmpp-tls'/>
TLSv1: OpenSSL handshake in progress
TLSv1: restarting parser
"Socket:"
"local address: [\"AF_INET\", 39123, \"172.27.*.**\", \"172.27.*.**\"]"
"Thread list size: 1"
#<TCPSocket:fd 11>
SENDING:
    <stream:stream xmlns:stream='http://etherx.jabber.org/streams' xmlns='jabber:client' to='chat.facebook.com' xml:lang='en' version='1.0' >
RECEIVED:
    <stream:stream from='chat.facebook.com' id='1' xml:lang='en' xmlns:stream='http://etherx.jabber.org/streams' version='1.0' xmlns='jabber:client'/>
RECEIVED:
    <stream:features><mechanisms xmlns='urn:ietf:params:xml:ns:xmpp-sasl'><mechanism>X-FACEBOOK-PLATFORM</mechanism><mechanism>PLAIN</mechanism></mechanisms></stream:features>
FEATURES: waiting...
FEATURES: received
PROCESSING:
    <stream:features xmlns='jabber:client'><mechanisms xmlns='urn:ietf:params:xml:ns:xmpp-sasl'><mechanism>X-FACEBOOK-PLATFORM</mechanism><mechanism>PLAIN</mechanism></mechanisms></stream:features> (REXML::Element)
TRYING stanzacbs...
FEATURES: waiting finished
TRYING message/iq/presence/cbs...
SENDING:
    <auth mechanism='X-FACEBOOK-PLATFORM' xmlns='urn:ietf:params:xml:ns:xmpp-sasl'/>
RECEIVED:
    <challenge xmlns='urn:ietf:params:xml:ns:xmpp-sasl'>dmVyc2lvbj0x...</challenge>
SASL DIGEST-MD5 challenge:
    version=1&method=auth.xmpp_login&nonce=E547D1842...
    {"version"=>"1", "method"=>"auth.xmpp_login", "nonce"=>"E547D1842..."}
SENDING:
    <response xmlns='urn:ietf:params:xml:ns:xmpp-sasl'>YXBpX2...
    </response>
RECEIVED:
    <success xmlns='urn:ietf:params:xml:ns:xmpp-sasl'/>
"Socket:"
"local address: [\"AF_INET\", 39123, \"172.27.*.**\", \"172.27.*.**\"]"
"Thread list size: 2"
#<TCPSocket:fd 11>
SENDING:
    <stream:stream xmlns:stream='http://etherx.jabber.org/streams' xmlns='jabber:client' to='chat.facebook.com' xml:lang='en' version='1.0' >
RECEIVED:
    <stream:stream from='chat.facebook.com' id='1' xml:lang='en' xmlns:stream='http://etherx.jabber.org/streams' version='1.0' xmlns='jabber:client'/>
RECEIVED:
    <stream:features><bind xmlns='urn:ietf:params:xml:ns:xmpp-bind'/><session xmlns='urn:ietf:params:xml:ns:xmpp-session'/></stream:features>
FEATURES: received
PROCESSING:
    <stream:features xmlns='jabber:client'><bind xmlns='urn:ietf:params:xml:ns:xmpp-bind'/><session xmlns='urn:ietf:params:xml:ns:xmpp-session'/></stream:features> (REXML::Element)
TRYING stanzacbs...
TRYING message/iq/presence/cbs...
SENDING:
    <iq id='1192' type='set' xmlns='jabber:client'><bind xmlns='urn:ietf:params:xml:ns:xmpp-bind'/></iq>
RECEIVED:
    <iq from='chat.facebook.com' id='1192' type='result'><bind xmlns='urn:ietf:params:xml:ns:xmpp-bind'><jid>[email protected]/oRbc4KeQ</jid></bind></iq>
SENDING:
    <iq id='2614' type='set' xmlns='jabber:client'><session xmlns='urn:ietf:params:xml:ns:xmpp-session'/></iq>
RECEIVED:
    <iq from='chat.facebook.com' id='2614' type='result'><session xmlns='urn:ietf:params:xml:ns:xmpp-session'/></iq>
SENDING:
    <message to='[email protected]' xmlns='jabber:client'><body>    Hi, friend! 2013-09-11 17:46:10 +0300
    </body></message>
SENDING:
    </stream:stream>

Where the problem stems from? Is it a FB bug, a gem bug or what else?

Answer 1

Okay, this is going to sound insane... and it is...

I had this problem (with code that sends chat messages to a list of recipients) and pounded my head against the wall on it for the better part of two days, digging into the XMPP traffic as the OP did. I also found that the data received were invariant between successes and failures. FB just happily swallows it without delivering anything. Very frustrating!

Nearing the end of my patience, and about to decide that we would have to redesign the feature entirely (ditching FB chat), I tried a shot-in-the-dark, and it appears to have worked.

I introduced an artificial delay (1 second) between calls to Client#send.

Very mysteriously, this seems to fix it. I need to test it more, but so far 100% of messages are being delivered with that delay. I have no rational argument for the code I just committed, but it seems to be working. I'll take it!