search

SpectrumIM / spectrum2

Spectrum 2 IM transports
https://spectrum.im
408 stars 91 forks source link

Invalid XML generated by OOB split feature #357

Open mbirth opened 5 years ago

mbirth commented 5 years ago

Since upgrading from 2.0.10 to 2.0.12 I can't receive images/photos from purple-hangouts anymore. Usually they popped up in Gajim and/or Conversations as a HTML message (with "View full image" link pointing to googleusercontent.com and a thumbnail) and were stored in the MAM history as only the link to the jpg at googleusercontent.com.

Since the upgrade, I don't even get notified when someone sends me a photo. Nothing happens in any client. Also no entry appears in the history.

backend.log:

5796: 2019-07-17 12:27:56,475 INFO  backend: conv_write_im()
5796: 2019-07-17 12:27:56,475 INFO  backend: conv_write_im(): msg='<a href='https://lh3.googleusercontent.com/-mGD4raf_nlU/XS74KqWcDnI/AAAAAAAABwc/2qpUlz_ibCIbZaDOZBs9AON9ITbDPgYGACK8BGAs/s0/2019-07-17.jpg'>View full image <img id='3' src='https://lh3.googleusercontent.com/-mGD4raf_nlU/XS74KqWcDnI/AAAAAAAABwc/2qpUlz_ibCIbZaDOZBs9AON9ITbDPgYGACK8BGAs/s0/2019-07-17.jpg' /></a>', flags=4098
5796: 2019-07-17 12:27:56,476 INFO  backend: Received image body='<a href='https://lh3.googleusercontent.com/-mGD4raf_nlU/XS74KqWcDnI/AAAAAAAABwc/2qpUlz_ibCIbZaDOZBs9AON9ITbDPgYGACK8BGAs/s0/2019-07-17.jpg'>View full image <img id='3' src='https://lh3.googleusercontent.com/-mGD4raf_nlU/XS74KqWcDnI/AAAAAAAABwc/2qpUlz_ibCIbZaDOZBs9AON9ITbDPgYGACK8BGAs/s0/2019-07-17.jpg' /></a>'
5796: 2019-07-17 12:27:56,476 INFO  backend: Image ID = '3' 165 166
5796: 2019-07-17 12:27:56,476 INFO  libpurple: imgstore:retrieved image id 3
5796: 2019-07-17 12:27:56,477 INFO  backend: Storing image to /var/www/html/chat/uploads/c9bc7a7c6a7dfb5648b9e79cd78a00160377bc78.jpg
5796: 2019-07-17 12:27:56,499 INFO  backend: New image body='<a href='https://lh3.googleusercontent.com/-mGD4raf_nlU/XS74KqWcDnI/AAAAAAAABwc/2qpUlz_ibCIbZaDOZBs9AON9ITbDPgYGACK8BGAs/s0/2019-07-17.jpg'>View full image <img src="https://xmpp.myserver.com/uploads/c9bc7a7c6a7dfb5648b9e79cd78a00160377bc78.jpg" src='https://lh3.googleusercontent.com/-mGD4raf_nlU/XS74KqWcDnI/AAAAAAAABwc/2qpUlz_ibCIbZaDOZBs9AON9ITbDPgYGACK8BGAs/s0/2019-07-17.jpg' /></a>'
5796: 2019-07-17 12:27:56,500 INFO  backend: Received message body='View full image  <https://lh3.googleusercontent.com/-mGD4raf_nlU/XS74KqWcDnI/AAAAAAAABwc/2qpUlz_ibCIbZaDOZBs9AON9ITbDPgYGACK8BGAs/s0/2019-07-17.jpg>' xhtml='<a href="https://lh3.googleusercontent.com/-mGD4raf_nlU/XS74KqWcDnI/AAAAAAAABwc/2qpUlz_ibCIbZaDOZBs9AON9ITbDPgYGACK8BGAs/s0/2019-07-17.jpg">View full image <img src='https://lh3.googleusercontent.com/-mGD4raf_nlU/XS74KqWcDnI/AAAAAAAABwc/2qpUlz_ibCIbZaDOZBs9AON9ITbDPgYGACK8BGAs/s0/2019-07-17.jpg' alt='' /></a>' name='117102903236799523736'

spectrum2.log:

2019-07-17 12:27:55,819 INFO  ConversationManager: mbirth@myserver.com: Adding conversation 117102903236799523736
2019-07-17 12:27:55,929 INFO  Component.RAW: RAW DATA OUT <message from="117102903236799523736@hangouts.myserver.com/bot" to="mbirth@myserver.com" type="chat"><body></body><html xmlns="http://jabber.org/protocol/xhtml-im"><body xmlns="http://www.w3.org/1999/xhtml"><html/></body></html><active xmlns="http://jabber.org/protocol/chatstates"/></message>
2019-07-17 12:27:56,533 DEBUG NetworkPluginServer: wrapIncomingMedia: matchCount==1
2019-07-17 12:27:56,535 INFO  Component.RAW: RAW DATA OUT <message from="117102903236799523736@hangouts.myserver.com/bot" to="mbirth@myserver.com" type="chat"><body>View full image  &lt;</body><html xmlns="http://jabber.org/protocol/xhtml-im"><body xmlns="http://www.w3.org/1999/xhtml"><a href="https://lh3.googleusercontent.com/-mGD4raf_nlU/XS74KqWcDnI/AAAAAAAABwc/2qpUlz_ibCIbZaDOZBs9AON9ITbDPgYGACK8BGAs/s0/2019-07-17.jpg">View full image</body></html><active xmlns="http://jabber.org/protocol/chatstates"/></message>
2019-07-17 12:27:56,539 INFO  Component.RAW: RAW DATA OUT <message from="117102903236799523736@hangouts.myserver.com/bot" to="mbirth@myserver.com" type="chat"><body>https://lh3.googleusercontent.com/-mGD4raf_nlU/XS74KqWcDnI/AAAAAAAABwc/2qpUlz_ibCIbZaDOZBs9AON9ITbDPgYGACK8BGAs/s0/2019-07-17.jpg</body><html xmlns="http://jabber.org/protocol/xhtml-im"><body xmlns="http://www.w3.org/1999/xhtml"><img src='https://lh3.googleusercontent.com/-mGD4raf_nlU/XS74KqWcDnI/AAAAAAAABwc/2qpUlz_ibCIbZaDOZBs9AON9ITbDPgYGACK8BGAs/s0/2019-07-17.jpg' alt='' /></body></html><x xmlns='jabber:x:oob'><url>https://lh3.googleusercontent.com/-mGD4raf_nlU/XS74KqWcDnI/AAAAAAAABwc/2qpUlz_ibCIbZaDOZBs9AON9ITbDPgYGACK8BGAs/s0/2019-07-17.jpg</url></x><active xmlns="http://jabber.org/protocol/chatstates"/></message>
2019-07-17 12:27:56,543 INFO  Component.RAW: RAW DATA OUT <message from="117102903236799523736@hangouts.myserver.com/bot" to="mbirth@myserver.com" type="chat"><body>&gt;</body><html xmlns="http://jabber.org/protocol/xhtml-im"><body xmlns="http://www.w3.org/1999/xhtml"></a></body></html><active xmlns="http://jabber.org/protocol/chatstates"/></message>
2019-07-17 12:27:56,544 INFO  Component.RAW: RAW DATA IN <stream:error><not-well-formed xmlns='urn:ietf:params:xml:ns:xmpp-streams'/><text xml:lang='en' xmlns='urn:ietf:params:xml:ns:xmpp-streams'>mismatched tag</text></stream:error>
2019-07-17 12:27:56,549 INFO  Component.RAW: RAW DATA OUT </stream:stream>
2019-07-17 12:27:56,549 INFO  Component.RAW: RAW DATA IN </stream:stream>
2019-07-17 12:27:56,622 INFO  Component: Disconnected from Frontend server. Error: Unexpected element error

I've set this in hangouts.cfg:

web_directory=/var/www/html/chat/uploads
web_url=https://xmpp.myserver.com/uploads

And from the log above, it seems to download the thumbnail and put it into web_directory just fine (it's there, I've checked). (I believe this worked before this way, too.) But it fails to send the generated message to me.

vitalyster commented 5 years ago

can you please try to add oob_split=false into [service] config section and try again?

mbirth commented 5 years ago

Now it works again (and looks like before, i.e. clients show the HTML part of the message incl. the "View full image" link, history shows link to image only).

vitalyster commented 5 years ago

Great, so it is the issue of the new oob split feature, I did disable it from being defaults

vitalyster commented 5 years ago

cc @himselfv

himselfv commented 5 years ago

On it

himselfv commented 5 years ago

@mbirth Are you sure the backend log is from 2.0.12? The backend stopped saying "New IMAGE body" some time ago and it currently just says "new BODY". (plus it's trace, not info now)

mbirth commented 5 years ago

@himselfv Not exactly sure, but I'm pretty sure I've restarted spectrum2 after updating. However, after enabling oob_split again and restarting everything, the bug still exists. No image received in any client.

backend.log

17147: 2019-07-18 18:41:21,338 INFO  backend: conv_write_im()
17147: 2019-07-18 18:41:21,338 DEBUG backend: conv_write_im(): msg='<a href='https://lh3.googleusercontent.com/-x0EjrNBIqcI/XTChMPa9ZiI/AAAAAAAAACU/kfmodM8SKH8ZPfwic6oOsHXJiQat_ravwCK8BGAs/s0/IMG_0664.JPG'>View full image <img id='1' src='https://lh3.googleusercontent.com/-x0EjrNBIqcI/XTChMPa9ZiI/AAAAAAAAACU/kfmodM8SKH8ZPfwic6oOsHXJiQat_ravwCK8BGAs/s0/IMG_0664.JPG' /></a>', flags=4098
17147: 2019-07-18 18:41:21,338 DEBUG backend: Received image body='<a href='https://lh3.googleusercontent.com/-x0EjrNBIqcI/XTChMPa9ZiI/AAAAAAAAACU/kfmodM8SKH8ZPfwic6oOsHXJiQat_ravwCK8BGAs/s0/IMG_0664.JPG'>View full image <img id='1' src='https://lh3.googleusercontent.com/-x0EjrNBIqcI/XTChMPa9ZiI/AAAAAAAAACU/kfmodM8SKH8ZPfwic6oOsHXJiQat_ravwCK8BGAs/s0/IMG_0664.JPG' /></a>'
17147: 2019-07-18 18:41:21,339 DEBUG backend: Image ID = '1' 163 164
17147: 2019-07-18 18:41:21,339 INFO  libpurple: imgstore:retrieved image id 1
17147: 2019-07-18 18:41:21,342 DEBUG backend: Storing image to /var/www/html/chat/uploads/da28856ca018eed0edf1b9f0b9813734895a3a02.jpg
17147: 2019-07-18 18:41:22,262 INFO  libpurple: http:Performing new request 0xaaaafcbbf000 to clients6.google.com.
17147: 2019-07-18 18:41:22,263 INFO  libpurple: http:Performing new request 0xaaaafcb62af0 to clients6.google.com.
17147: 2019-07-18 18:41:22,609 INFO  libpurple: http:Request 0xaaaafcb62af0 performed successfully.
17147: 2019-07-18 18:41:22,610 INFO  libpurple: hangouts:A 'SetFocusResponse' says 'csfrp'

spectrum2.log

2019-07-18 18:41:20,814 INFO  ConversationManager: mbirth@myserver.com: Adding conversation 101602501167992504565
2019-07-18 18:41:20,819 INFO  Component.RAW: RAW DATA OUT <message from="101602501167992504565@hangouts.myserver.com/bot" to="mbirth@myserver.com" type="chat"><body></body><html xmlns="http://jabber.org/protocol/xhtml-im"><body xmlns="http://www.w3.org/1999/xhtml"><html/></body></html><active xmlns="http://jabber.org/protocol/chatstates"/></message>
2019-07-18 18:41:21,419 DEBUG NetworkPluginServer: wrapIncomingMedia: matchCount==1
2019-07-18 18:41:21,421 INFO  Component.RAW: RAW DATA OUT <message from="101602501167992504565@hangouts.myserver.com/bot" to="mbirth@myserver.com" type="chat"><body>View full image https://xmpp.myserver.com/uploads/da28856ca018eed0edf1b9f0b9813734895a3a02.jpg &lt;</body><html xmlns="http://jabber.org/protocol/xhtml-im"><body xmlns="http://www.w3.org/1999/xhtml"><a href="https://lh3.googleusercontent.com/-x0EjrNBIqcI/XTChMPa9ZiI/AAAAAAAAACU/kfmodM8SKH8ZPfwic6oOsHXJiQat_ravwCK8BGAs/s0/IMG_0664.JPG">View full image</body></html><active xmlns="http://jabber.org/protocol/chatstates"/></message>
2019-07-18 18:41:21,426 INFO  Component.RAW: RAW DATA OUT <message from="101602501167992504565@hangouts.myserver.com/bot" to="mbirth@myserver.com" type="chat"><body>https://lh3.googleusercontent.com/-x0EjrNBIqcI/XTChMPa9ZiI/AAAAAAAAACU/kfmodM8SKH8ZPfwic6oOsHXJiQat_ravwCK8BGAs/s0/IMG_0664.JPG</body><html xmlns="http://jabber.org/protocol/xhtml-im"><body xmlns="http://www.w3.org/1999/xhtml"><img src='https://lh3.googleusercontent.com/-x0EjrNBIqcI/XTChMPa9ZiI/AAAAAAAAACU/kfmodM8SKH8ZPfwic6oOsHXJiQat_ravwCK8BGAs/s0/IMG_0664.JPG' alt='' /></body></html><x xmlns='jabber:x:oob'><url>https://lh3.googleusercontent.com/-x0EjrNBIqcI/XTChMPa9ZiI/AAAAAAAAACU/kfmodM8SKH8ZPfwic6oOsHXJiQat_ravwCK8BGAs/s0/IMG_0664.JPG</url></x><active xmlns="http://jabber.org/protocol/chatstates"/></message>
2019-07-18 18:41:21,428 INFO  Component.RAW: RAW DATA OUT <message from="101602501167992504565@hangouts.myserver.com/bot" to="mbirth@myserver.com" type="chat"><body>&gt;</body><html xmlns="http://jabber.org/protocol/xhtml-im"><body xmlns="http://www.w3.org/1999/xhtml"></a></body></html><active xmlns="http://jabber.org/protocol/chatstates"/></message>
2019-07-18 18:41:21,429 INFO  Component.RAW: RAW DATA IN <stream:error><not-well-formed xmlns='urn:ietf:params:xml:ns:xmpp-streams'/><text xml:lang='en' xmlns='urn:ietf:params:xml:ns:xmpp-streams'>mismatched tag</text></stream:error>
2019-07-18 18:41:21,430 INFO  Component.RAW: RAW DATA OUT </stream:stream>
2019-07-18 18:41:21,430 INFO  Component.RAW: RAW DATA IN </stream:stream>
2019-07-18 18:41:21,441 INFO  Component: Disconnected from Frontend server. Error: Unexpected element error
vitalyster commented 5 years ago

@mbirth backend log should start with backend version

himselfv commented 5 years ago

This seems right, thanks!

himselfv commented 5 years ago

The problem is with <a ...><img></a> structure which is too complicated for the naive splitting implemented. I'll do HTML-aware splitting but oob_split is a workaround for certain clients anyway so it's okay to run without it.