Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Invalid XML generated by OOB split feature #357

Open
mbirth opened this issue Jul 17, 2019 · 10 comments
Open

Invalid XML generated by OOB split feature #357

mbirth opened this issue Jul 17, 2019 · 10 comments
Labels
Bug

Comments

@mbirth
Copy link

mbirth commented Jul 17, 2019 •
edited
Loading

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: [email protected]: Adding conversation 117102903236799523736
2019-07-17 12:27:55,929 INFO  Component.RAW: RAW DATA OUT <message from="[email protected]/bot" to="[email protected]" 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="[email protected]/bot" to="[email protected]" 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="[email protected]/bot" to="[email protected]" 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="[email protected]/bot" to="[email protected]" 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 vitalyster added the Bug label Jul 17, 2019
@vitalyster
Copy link
Collaborator

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

@mbirth
Copy link
Author

mbirth commented Jul 18, 2019

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
Copy link
Collaborator

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

@vitalyster vitalyster assigned vitalyster and unassigned vitalyster Jul 18, 2019
@vitalyster vitalyster changed the title Hangouts images are ignored Invalid XML generated by OOB split feature Jul 18, 2019
@vitalyster
Copy link
Collaborator

cc @himselfv

@himselfv
Copy link
Contributor

On it

@himselfv
Copy link
Contributor

@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
Copy link
Author

mbirth commented Jul 18, 2019 •
edited
Loading

@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: [email protected]: Adding conversation 101602501167992504565
2019-07-18 18:41:20,819 INFO  Component.RAW: RAW DATA OUT <message from="[email protected]/bot" to="[email protected]" 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="[email protected]/bot" to="[email protected]" 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="[email protected]/bot" to="[email protected]" 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="[email protected]/bot" to="[email protected]" 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
Copy link
Collaborator

@mbirth backend log should start with backend version

@himselfv
Copy link
Contributor

This seems right, thanks!

@himselfv
Copy link
Contributor

himselfv commented Jul 19, 2019 •
edited
Loading

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.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
Bug
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@mbirth @vitalyster @himselfv