Skip to content

XMPP Refactoring#511

Closed
caronc wants to merge 3 commits intomasterfrom
497-xmpp-refactor
Closed

XMPP Refactoring#511
caronc wants to merge 3 commits intomasterfrom
497-xmpp-refactor

Conversation

@caronc
Copy link
Owner

@caronc caronc commented Dec 29, 2021

Description:

Related issue (if applicable): #497

Re-factored the way the connections are handled.

Deadlocks and Crashes:

I spent hours trying different things and haven't gotten to far. I may have fixed just the connection issue you were receiving earlier though @drequivalent.

The Issues:

  • The biggest issue i see with slixmpp is that that there seems to be incompatibilities with Python >=3.8. This made it tough to troubleshoot timeouts and forever values for me. The asyncio.loop seems to deadlock from time to time under certain conditions.
    • One of which is easily reproduced if the hostname in the jid can't be resolved (something like ?jid=user@405c5318a47031) The built in DNS feature seems to block indefinitely if it fails to resolve. This may also just be related to my Python version incompatibilities. I can't seem to find an easy way to just completely disable DNS. Most exploits always come down to DNS anyhow (such as the recent Apache log4j2 issue in the news). Ideally this should be turned off.

@linkmauve do you have any suggestions? Perhaps you could review my PR and let me know if you spot anything unusual?

Side Notes

I know very little about XMPP; this is one of those features i was hoping to just adopt through a 3rd party library. The concerns i have with the deadlocks is that they introduce a denial of service attack for people hosting this via the Apprise API. I may need to disable XMPP there by default for the time being.

Going forward:

There is the thought of maybe switching to a different library; possibly:

  • nbxmpp: Seems basic; but that is all Apprise offers is a simple gateway to each upstream provider. So maybe this is enough? It would be a significant downgrade in features when compared with slixmpp. Perhaps more Python version compatibility instead of Just Python v3.7 thought?
  • xmpppy seems very active as well with a release just 2 days ago (Release 0.7.0). @amotl do you have any comments here? I see you're getting 18K downloads a month which is great. I don't see to many tickets open either so I presume you've got the messaging of servers down pat? Is there support for Secure connections as well?
  • Alternatively we just keep going with silxmpp and clean up the issues we're having. I see leveraging the creation of a second asyncio.loop and putting all of the calls to this library in it's own thread. This will allow it to avoid deadlocking in the main loop and it will also allow me to put a async timeout on the entire call to it when/if the deadlocks continue. Will definitely want your thoughts feedback here @linkmauve (if you have time)
  • Anyone have any other thoughts/views as to possible ways forward? I know @drequivalent referenced a very young application (without much global feedback yet) running Go (here). Calling a 3rd party tool via Apprise is also a possibility too.

Any advice would be welcome 🙏

Testing

Anyone can help test this source code as follows:

# Create a virtual environment to work in
# This way you can just destroy it after when it's all over.
# The below will create a directory called apprise
python3 -m venv apprise

# Change into our new directory
cd apprise

# Activate our virtual environment
source bin/activate

# Install the branch
pip install git+https://github.com/caronc/apprise.git@497-xmpp-refactor

# Give it a go:
apprise -vv -b "test" -t "test" "xmpp://user:pass@hostname?jid=user@host"

Additional

  • @drequivalent, do you think you could check out this branch and test it for me? See Testing section above. 👍

Checklist

  • The code change is tested and works locally.
  • There is no commented out code in this PR.
  • No lint errors (use flake8)
  • 100% test coverage

@codecov-commenter
Copy link

codecov-commenter commented Dec 29, 2021

Codecov Report

Merging #511 (af7379f) into master (9a21de2) will decrease coverage by 0.75%.
The diff coverage is 16.66%.

@@             Coverage Diff             @@
##            master     #511      +/-   ##
===========================================
- Coverage   100.00%   99.24%   -0.76%     
===========================================
  Files          112      113       +1     
  Lines        14416    14527     +111     
  Branches      2725     2743      +18     
===========================================
+ Hits         14416    14418       +2     
- Misses           0      105     +105     
- Partials         0        4       +4     
Impacted Files Coverage Δ
apprise/plugins/NotifyMQTT.py 100.00% <ø> (ø)
apprise/plugins/NotifyXMPP/SliXmppAdapter.py 23.75% <0.00%> (-76.25%) ⬇️
apprise/plugins/NotifyXMPP/__init__.py 38.66% <100.00%> (-61.34%) ⬇️
apprise/plugins/NotifyFCM/oauth.py 98.36% <0.00%> (-1.64%) ⬇️
apprise/plugins/NotifyVonage.py 100.00% <0.00%> (ø)

Continue to review full report at Codecov.

Legend - Click here to learn more
Δ = absolute <relative> (impact), ø = not affected, ? = missing data
Powered by Codecov. Last update 9a21de2...af7379f. Read the comment docs.

@amotl
Copy link
Collaborator

amotl commented Jan 13, 2022

Dear Chris,

The biggest issue I see with slixmpp...

There have been many updates since slixmpp 1.7.1 was released in April 2021, see [1]. Specifically, according to what you reported about above, I am looking at [2] here.

I would recommend checking Apprise with the current development head of slixmpp, and, if that proves to be successful, to kindly ask the upstream authors for a new release on PyPI.

With kind regards,
Andreas.

[1] https://lab.louiz.org/poezio/slixmpp/-/commits/master
[2] https://lab.louiz.org/poezio/slixmpp/-/commit/799a6a07

/cc @poezio, @mathieui

@drequivalent
Copy link

It's not working. And I found why.

It eats the first letter off the recipient address.

user="monitor"
password="rmgKsJUPFzeIUG"
port="None"
host="<SERVER_HIDDEN>"
fullpath="None"
path="None"
query="None"
schema="xmpp"
url="xmpp://monitor:rmgKsJUPFzeIUG@<SERVER_HIDDEN>"
qsd="{'to': 'drq@<SERVER_HIDDEN>'}"
qsd+="{}"
qsd-="{}"
qsd:="{}"
secure="False"
verify="True"
targets="['drq@<SERVER_HIDDEN>']"
2022-02-16 16:10:34,894 - DEBUG - Loaded XMPP URL: xmpp://monitor:****@<SERVER_HIDDEN>/rq%40<SERVER_HIDDEN>?format=text&overflow=upstream&rto=4.0&cto=4.0&verify=yes&xep=30%2C199
2022-02-16 16:10:34,894 - DEBUG - Using selector: EpollSelector
2022-02-16 16:10:34,895 - INFO - Notifying 1 service(s) asynchronously.
2022-02-16 16:10:34,897 - DEBUG - Using selector: EpollSelector
2022-02-16 16:10:34,903 - DEBUG - Loaded Plugin: RFC 6120: Stream Feature: STARTTLS
2022-02-16 16:10:34,904 - DEBUG - Loaded Plugin: RFC 6120: Stream Feature: Resource Binding
2022-02-16 16:10:34,906 - DEBUG - Loaded Plugin: RFC 3920: Stream Feature: Start Session
2022-02-16 16:10:34,907 - DEBUG - Loaded Plugin: RFC 6121: Stream Feature: Roster Versioning
2022-02-16 16:10:34,910 - DEBUG - Loaded Plugin: RFC 6121: Stream Feature: Subscription Pre-Approval
2022-02-16 16:10:34,912 - DEBUG - Loaded Plugin: RFC 6120: Stream Feature: SASL
2022-02-16 16:10:34,914 - DEBUG - Loaded Plugin: XEP-0030: Service Discovery
2022-02-16 16:10:34,914 - DEBUG - Loaded Plugin: XEP-0199: XMPP Ping
2022-02-16 16:10:34,914 - DEBUG - Event triggered: connecting
2022-02-16 16:10:34,915 - DEBUG - DNS: Querying SRV records for <SERVER_HIDDEN>
2022-02-16 16:10:34,923 - DEBUG - DNS: Querying <SERVER_HIDDEN> for AAAA records.
2022-02-16 16:10:34,923 - DEBUG - DNS: Exception while querying for <SERVER_HIDDEN> AAAA records: (1, 'DNS server returned answer with no data')
2022-02-16 16:10:34,923 - DEBUG - DNS: Querying <SERVER_HIDDEN> for A records.
2022-02-16 16:10:34,950 - DEBUG - Event triggered: connected
2022-02-16 16:10:34,950 - DEBUG - SEND: <stream:stream to='<SERVER_HIDDEN>' xmlns:stream='http://etherx.jabber.org/streams' xmlns='jabber:client' xml:lang='en' version='1.0'>
2022-02-16 16:10:34,976 - DEBUG - RECV: <stream:stream id="98296356061246073" version="1.0" xml:lang="en" from="<SERVER_HIDDEN>">
2022-02-16 16:10:34,976 - DEBUG - RECV: <stream:features xmlns="http://etherx.jabber.org/streams"><starttls xmlns="urn:ietf:params:xml:ns:xmpp-tls"><required /></starttls></stream:features>
2022-02-16 16:10:34,977 - DEBUG - SEND: <starttls xmlns="urn:ietf:params:xml:ns:xmpp-tls"><required /></starttls>
2022-02-16 16:10:35,002 - DEBUG - RECV: <proceed xmlns="urn:ietf:params:xml:ns:xmpp-tls" />
2022-02-16 16:10:35,003 - DEBUG - Starting TLS
2022-02-16 16:10:35,033 - DEBUG - Event triggered: ssl_cert
2022-02-16 16:10:35,033 - DEBUG - Event triggered: tls_success
2022-02-16 16:10:35,033 - DEBUG - SEND: <stream:stream to='<SERVER_HIDDEN>' xmlns:stream='http://etherx.jabber.org/streams' xmlns='jabber:client' xml:lang='en' version='1.0'>
2022-02-16 16:10:35,059 - DEBUG - RECV: <stream:stream id="741032481732413634" version="1.0" xml:lang="en" from="<SERVER_HIDDEN>">
2022-02-16 16:10:35,059 - DEBUG - RECV: <stream:features xmlns="http://etherx.jabber.org/streams"><mechanisms xmlns="urn:ietf:params:xml:ns:xmpp-sasl"><mechanism>PLAIN</mechanism><mechanism>SCRAM-SHA-1-PLUS</mechanism><mechanism>SCRAM-SHA-1</mechanism></mechanisms></stream:features>
2022-02-16 16:10:35,060 - DEBUG - SEND: <auth xmlns="urn:ietf:params:xml:ns:xmpp-sasl" mechanism="SCRAM-SHA-1-PLUS">cD10bHMtdW5pcXVlLCxuPW1vbml0b3Iscj00NzgwMjEyMTQwMjkwMzQ0</auth>
2022-02-16 16:10:35,087 - DEBUG - RECV: <challenge xmlns="urn:ietf:params:xml:ns:xmpp-sasl">cj00NzgwMjEyMTQwMjkwMzQ0cW5vRDFZWUEwcmo1MzlFK0hiTkxVUT09LHM9Y0FWWlNmT3FJUjZ5cWM3Vlc4ZFFxQT09LGk9NDA5Ng==</challenge>
2022-02-16 16:10:35,134 - DEBUG - SEND: <response xmlns="urn:ietf:params:xml:ns:xmpp-sasl">Yz1jRDEwYkhNdGRXNXBjWFZsTEN3b0E4amhXQWR3ZzVVT3ExZGJSZFNlYmJOSVpiUExzWVREc1FKYUh3ZktBSXlMTDRrYkpvUUx5L0c2SlBxR2dtMD0scj00NzgwMjEyMTQwMjkwMzQ0cW5vRDFZWUEwcmo1MzlFK0hiTkxVUT09LHA9Zmp2QTZwMGxmNkVmMW5kaGpZRVlaZDdMTFl3PQ==</response>
2022-02-16 16:10:35,160 - DEBUG - RECV: <success xmlns="urn:ietf:params:xml:ns:xmpp-sasl">dj1jU3FaU2NJUkllUmgrWGFMRlF5dnBXQjRZdVE9</success>
2022-02-16 16:10:35,161 - DEBUG - Event triggered: auth_success
2022-02-16 16:10:35,161 - DEBUG - SEND: <stream:stream to='<SERVER_HIDDEN>' xmlns:stream='http://etherx.jabber.org/streams' xmlns='jabber:client' xml:lang='en' version='1.0'>
2022-02-16 16:10:35,186 - DEBUG - RECV: <stream:stream id="5577163602734746087" version="1.0" xml:lang="en" from="<SERVER_HIDDEN>">
2022-02-16 16:10:35,187 - DEBUG - RECV: <stream:features xmlns="http://etherx.jabber.org/streams"><bind xmlns="urn:ietf:params:xml:ns:xmpp-bind" /><session xmlns="urn:ietf:params:xml:ns:xmpp-session"><optional /></session><c xmlns="http://jabber.org/protocol/caps" ver="aq0jDq6lvGILxJV9GQunc1FRZOc=" node="http://www.process-one.net/en/ejabberd/" hash="sha-1" /><sm xmlns="urn:xmpp:sm:2" /><sm xmlns="urn:xmpp:sm:3" /><ver xmlns="urn:xmpp:features:rosterver" /><csi xmlns="urn:xmpp:csi:0" /></stream:features>
2022-02-16 16:10:35,188 - DEBUG - Enabling roster versioning.
2022-02-16 16:10:35,188 - DEBUG - Requesting resource: 
2022-02-16 16:10:35,188 - DEBUG - SEND: <iq id="e789ee4d8b0e4d04bd97b10d838d0ef8" type="set"><bind xmlns="urn:ietf:params:xml:ns:xmpp-bind" /></iq>
2022-02-16 16:10:35,215 - DEBUG - RECV: <iq type="result" id="e789ee4d8b0e4d04bd97b10d838d0ef8"><bind xmlns="urn:ietf:params:xml:ns:xmpp-bind"><jid>monitor@<SERVER_HIDDEN>/525624715842916234825476498</jid></bind></iq>
2022-02-16 16:10:35,216 - DEBUG - Event triggered: session_bind
2022-02-16 16:10:35,216 - INFO - JID set to: monitor@<SERVER_HIDDEN>/525624715842916234825476498
2022-02-16 16:10:35,216 - DEBUG - Event triggered: session_start
2022-02-16 16:10:35,217 - DEBUG - Finished processing stream features.
2022-02-16 16:10:35,217 - DEBUG - Event triggered: stream_negotiated
2022-02-16 16:10:35,217 - DEBUG - SEND: <message type="chat" to="rq@<SERVER_HIDDEN>" id="97d7f796198b4584899b0298a527a0ff" xml:lang="en"><origin-id xmlns="urn:xmpp:sid:0" id="97d7f796198b4584899b0298a527a0ff" /><body>Test Message Body</body></message>
2022-02-16 16:10:35,217 - DEBUG - SEND: </stream:stream>
2022-02-16 16:10:35,248 - DEBUG - RECV: <message xml:lang="en" to="monitor@<SERVER_HIDDEN>/525624715842916234825476498" from="rq@<SERVER_HIDDEN>" type="error" id="97d7f796198b4584899b0298a527a0ff"><origin-id xmlns="urn:xmpp:sid:0" id="97d7f796198b4584899b0298a527a0ff" /><error code="503" type="cancel"><service-unavailable xmlns="urn:ietf:params:xml:ns:xmpp-stanzas" /></error><body>Test Message Body</body></message>
2022-02-16 16:10:35,249 - DEBUG - Event triggered: message
2022-02-16 16:10:35,249 - DEBUG - Event triggered: message_error
2022-02-16 16:10:35,350 - DEBUG - End of stream received
2022-02-16 16:10:35,350 - DEBUG - Event triggered: killed
2022-02-16 16:10:35,350 - INFO - connection_lost: (None,)
2022-02-16 16:10:35,351 - DEBUG - Cancelling 0 slow send tasks
2022-02-16 16:10:35,351 - DEBUG - Event triggered: session_end
2022-02-16 16:10:35,351 - DEBUG - Event triggered: disconnected
2022-02-16 16:10:35,364 - ERROR - Task was destroyed but it is pending!
task: <Task pending name='Task-9' coro=<XMLStream._consume_send_queue_before_disconnecting() running at /usr/local/lib/python3.9/dist-packages/slixmpp/xmlstream/xmlstream.py:553> wait_for=<Future finished result=None>>
2022-02-16 16:10:35,364 - ERROR - Task was destroyed but it is pending!
task: <Task pending name='Task-3' coro=<XMLStream.run_filters() running at /usr/local/lib/python3.9/dist-packages/slixmpp/xmlstream/xmlstream.py:1038> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7f5a98c022e0>()]>>
Exception ignored in: <coroutine object XMLStream.run_filters at 0x7f5a98bda2c0>
Traceback (most recent call last):
  File "/usr/local/lib/python3.9/dist-packages/slixmpp/xmlstream/xmlstream.py", line 1038, in run_filters
    (data, use_filters) = await self.waiting_queue.get()
  File "/usr/lib/python3.9/asyncio/queues.py", line 168, in get
    getter.cancel()  # Just in case getter is not done yet.
  File "/usr/lib/python3.9/asyncio/base_events.py", line 746, in call_soon
    self._check_closed()
  File "/usr/lib/python3.9/asyncio/base_events.py", line 510, in _check_closed
    raise RuntimeError('Event loop is closed')
RuntimeError: Event loop is closed

@drequivalent
Copy link

When tried with "_" before the recipient login, still get the error, but the message comes through!

2022-02-16 16:20:30,020 - TRACE - XMPP URL xmpp://monitor:rmgKsJUPFzeIUG@<SERVER_HIDDEN>?to=_drq@<SERVER_HIDDEN> unpacked as:
user="monitor"
password="rmgKsJUPFzeIUG"
port="None"
host="<SERVER_HIDDEN>"
fullpath="None"
path="None"
query="None"
schema="xmpp"
url="xmpp://monitor:rmgKsJUPFzeIUG@<SERVER_HIDDEN>"
qsd="{'to': '_drq@<SERVER_HIDDEN>'}"
qsd+="{}"
qsd-="{}"
qsd:="{}"
secure="False"
verify="True"
targets="['_drq@<SERVER_HIDDEN>']"
2022-02-16 16:20:30,021 - DEBUG - Loaded XMPP URL: xmpp://monitor:****@<SERVER_HIDDEN>/drq%40<SERVER_HIDDEN>?format=text&overflow=upstream&rto=4.0&cto=4.0&verify=yes&xep=30%2C199
2022-02-16 16:20:30,021 - DEBUG - Using selector: EpollSelector
2022-02-16 16:20:30,021 - INFO - Notifying 1 service(s) asynchronously.
2022-02-16 16:20:30,023 - DEBUG - Using selector: EpollSelector
2022-02-16 16:20:30,029 - DEBUG - Loaded Plugin: RFC 6120: Stream Feature: STARTTLS
2022-02-16 16:20:30,030 - DEBUG - Loaded Plugin: RFC 6120: Stream Feature: Resource Binding
2022-02-16 16:20:30,031 - DEBUG - Loaded Plugin: RFC 3920: Stream Feature: Start Session
2022-02-16 16:20:30,033 - DEBUG - Loaded Plugin: RFC 6121: Stream Feature: Roster Versioning
2022-02-16 16:20:30,034 - DEBUG - Loaded Plugin: RFC 6121: Stream Feature: Subscription Pre-Approval
2022-02-16 16:20:30,037 - DEBUG - Loaded Plugin: RFC 6120: Stream Feature: SASL
2022-02-16 16:20:30,039 - DEBUG - Loaded Plugin: XEP-0030: Service Discovery
2022-02-16 16:20:30,039 - DEBUG - Loaded Plugin: XEP-0199: XMPP Ping
2022-02-16 16:20:30,039 - DEBUG - Event triggered: connecting
2022-02-16 16:20:30,040 - DEBUG - DNS: Querying SRV records for <SERVER_HIDDEN>
2022-02-16 16:20:30,049 - DEBUG - DNS: Querying <SERVER_HIDDEN> for AAAA records.
2022-02-16 16:20:30,049 - DEBUG - DNS: Exception while querying for <SERVER_HIDDEN> AAAA records: (1, 'DNS server returned answer with no data')
2022-02-16 16:20:30,049 - DEBUG - DNS: Querying <SERVER_HIDDEN> for A records.
2022-02-16 16:20:30,084 - DEBUG - Event triggered: connected
2022-02-16 16:20:30,084 - DEBUG - SEND: <stream:stream to='<SERVER_HIDDEN>' xmlns:stream='http://etherx.jabber.org/streams' xmlns='jabber:client' xml:lang='en' version='1.0'>
2022-02-16 16:20:30,110 - DEBUG - RECV: <stream:stream id="6584006933342943473" version="1.0" xml:lang="en" from="<SERVER_HIDDEN>">
2022-02-16 16:20:30,111 - DEBUG - RECV: <stream:features xmlns="http://etherx.jabber.org/streams"><starttls xmlns="urn:ietf:params:xml:ns:xmpp-tls"><required /></starttls></stream:features>
2022-02-16 16:20:30,111 - DEBUG - SEND: <starttls xmlns="urn:ietf:params:xml:ns:xmpp-tls"><required /></starttls>
2022-02-16 16:20:30,137 - DEBUG - RECV: <proceed xmlns="urn:ietf:params:xml:ns:xmpp-tls" />
2022-02-16 16:20:30,138 - DEBUG - Starting TLS
2022-02-16 16:20:30,168 - DEBUG - Event triggered: ssl_cert
2022-02-16 16:20:30,168 - DEBUG - Event triggered: tls_success
2022-02-16 16:20:30,168 - DEBUG - SEND: <stream:stream to='<SERVER_HIDDEN>' xmlns:stream='http://etherx.jabber.org/streams' xmlns='jabber:client' xml:lang='en' version='1.0'>
2022-02-16 16:20:30,194 - DEBUG - RECV: <stream:stream id="284475434846899630" version="1.0" xml:lang="en" from="<SERVER_HIDDEN>">
2022-02-16 16:20:30,194 - DEBUG - RECV: <stream:features xmlns="http://etherx.jabber.org/streams"><mechanisms xmlns="urn:ietf:params:xml:ns:xmpp-sasl"><mechanism>PLAIN</mechanism><mechanism>SCRAM-SHA-1-PLUS</mechanism><mechanism>SCRAM-SHA-1</mechanism></mechanisms></stream:features>
2022-02-16 16:20:30,195 - DEBUG - SEND: <auth xmlns="urn:ietf:params:xml:ns:xmpp-sasl" mechanism="SCRAM-SHA-1-PLUS">cD10bHMtdW5pcXVlLCxuPW1vbml0b3Iscj02Njk1NTU1OTMyNDYzODM3</auth>
2022-02-16 16:20:30,222 - DEBUG - RECV: <challenge xmlns="urn:ietf:params:xml:ns:xmpp-sasl">cj02Njk1NTU1OTMyNDYzODM3bjU4eVNDMmFzUUxXbTJNeTJWN1dlZz09LHM9Y0FWWlNmT3FJUjZ5cWM3Vlc4ZFFxQT09LGk9NDA5Ng==</challenge>
2022-02-16 16:20:30,270 - DEBUG - SEND: <response xmlns="urn:ietf:params:xml:ns:xmpp-sasl">Yz1jRDEwYkhNdGRXNXBjWFZsTEN3OE5qTGhxS0VPOW41bUs1VVNjSEsyb3BuaDBqSERkaU1WdFAyMkI2UVdsOWZ3Q3NIUExwWlVWUU9GdjhYSGVxOD0scj02Njk1NTU1OTMyNDYzODM3bjU4eVNDMmFzUUxXbTJNeTJWN1dlZz09LHA9VEp0ci9kbkRlajlINU9MZlRNN0RmSlBSOXpFPQ==</response>
2022-02-16 16:20:30,296 - DEBUG - RECV: <success xmlns="urn:ietf:params:xml:ns:xmpp-sasl">dj1KeEtDUms2VVd6ZmNDWlB1TEdMQVlNc3M3azQ9</success>
2022-02-16 16:20:30,296 - DEBUG - Event triggered: auth_success
2022-02-16 16:20:30,296 - DEBUG - SEND: <stream:stream to='<SERVER_HIDDEN>' xmlns:stream='http://etherx.jabber.org/streams' xmlns='jabber:client' xml:lang='en' version='1.0'>
2022-02-16 16:20:30,322 - DEBUG - RECV: <stream:stream id="10242387090325836815" version="1.0" xml:lang="en" from="<SERVER_HIDDEN>">
2022-02-16 16:20:30,323 - DEBUG - RECV: <stream:features xmlns="http://etherx.jabber.org/streams"><bind xmlns="urn:ietf:params:xml:ns:xmpp-bind" /><session xmlns="urn:ietf:params:xml:ns:xmpp-session"><optional /></session><c xmlns="http://jabber.org/protocol/caps" ver="aq0jDq6lvGILxJV9GQunc1FRZOc=" node="http://www.process-one.net/en/ejabberd/" hash="sha-1" /><sm xmlns="urn:xmpp:sm:2" /><sm xmlns="urn:xmpp:sm:3" /><ver xmlns="urn:xmpp:features:rosterver" /><csi xmlns="urn:xmpp:csi:0" /></stream:features>
2022-02-16 16:20:30,323 - DEBUG - Enabling roster versioning.
2022-02-16 16:20:30,323 - DEBUG - Requesting resource: 
2022-02-16 16:20:30,323 - DEBUG - SEND: <iq id="05b3a86b506541418ccf546cbf643401" type="set"><bind xmlns="urn:ietf:params:xml:ns:xmpp-bind" /></iq>
2022-02-16 16:20:30,350 - DEBUG - RECV: <iq type="result" id="05b3a86b506541418ccf546cbf643401"><bind xmlns="urn:ietf:params:xml:ns:xmpp-bind"><jid>monitor@<SERVER_HIDDEN>/1089667695475528928625483410</jid></bind></iq>
2022-02-16 16:20:30,350 - DEBUG - Event triggered: session_bind
2022-02-16 16:20:30,350 - INFO - JID set to: monitor@<SERVER_HIDDEN>/1089667695475528928625483410
2022-02-16 16:20:30,350 - DEBUG - Event triggered: session_start
2022-02-16 16:20:30,351 - DEBUG - Finished processing stream features.
2022-02-16 16:20:30,351 - DEBUG - Event triggered: stream_negotiated
2022-02-16 16:20:30,351 - DEBUG - SEND: <message type="chat" to="drq@<SERVER_HIDDEN>" id="f14ee74f1e734c73859c667b3c67f351" xml:lang="en"><origin-id xmlns="urn:xmpp:sid:0" id="f14ee74f1e734c73859c667b3c67f351" /><body>Test Message Body</body></message>
2022-02-16 16:20:30,351 - DEBUG - SEND: </stream:stream>
2022-02-16 16:20:30,480 - DEBUG - End of stream received
2022-02-16 16:20:30,480 - DEBUG - Event triggered: killed
2022-02-16 16:20:30,480 - INFO - connection_lost: (None,)
2022-02-16 16:20:30,481 - DEBUG - Cancelling 0 slow send tasks
2022-02-16 16:20:30,481 - DEBUG - Event triggered: session_end
2022-02-16 16:20:30,481 - DEBUG - Event triggered: disconnected
2022-02-16 16:20:30,495 - ERROR - Task was destroyed but it is pending!
task: <Task pending name='Task-9' coro=<XMLStream._consume_send_queue_before_disconnecting() running at /usr/local/lib/python3.9/dist-packages/slixmpp/xmlstream/xmlstream.py:553> wait_for=<Future finished result=None>>
2022-02-16 16:20:30,495 - ERROR - Task was destroyed but it is pending!
task: <Task pending name='Task-3' coro=<XMLStream.run_filters() running at /usr/local/lib/python3.9/dist-packages/slixmpp/xmlstream/xmlstream.py:1038> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7f4a14c132e0>()]>>
Exception ignored in: <coroutine object XMLStream.run_filters at 0x7f4a14bea2c0>
Traceback (most recent call last):
  File "/usr/local/lib/python3.9/dist-packages/slixmpp/xmlstream/xmlstream.py", line 1038, in run_filters
    (data, use_filters) = await self.waiting_queue.get()
  File "/usr/lib/python3.9/asyncio/queues.py", line 168, in get
    getter.cancel()  # Just in case getter is not done yet.
  File "/usr/lib/python3.9/asyncio/base_events.py", line 746, in call_soon
    self._check_closed()
  File "/usr/lib/python3.9/asyncio/base_events.py", line 510, in _check_closed
    raise RuntimeError('Event loop is closed')
RuntimeError: Event loop is closed

@mathieui
Copy link

The error at the end is only a log of not anything important (and I hope to have it removed by the next release, which should be around the corner), but I have reviewed the code and I do not see where inside that PR or slixmpp the first letter could be mangled.

@caronc
Copy link
Owner Author

caronc commented Feb 18, 2022

RuntimeError: Event loop is closed

This is actually a bit of a problem because under-the-hood, silxmpp closes the event loop which affects any parent systems using it. One of the things needed to this branch to go forward would be to generate a thread (so it has it's own event loop) and run the notification there.

I'll see if i can investigate the other issue you found with the first letter of the recipient being removed.

@mathieui
Copy link

mathieui commented Feb 18, 2022

This is actually a bit of a problem because under-the-hood, silxmpp closes the event loop which affects any parent systems using it. One of the things needed to this branch to go forward would be to generate a thread (so it has it's own event loop) and run the notification there.

In this case it should be much easier, just don’t use process() but instead use a synchronization primitive (an asyncio.Event for example) and await it (and signal on it when the notification is done), process does nothing but run the event loop, and if the event loop already has an use it can be cumbersome to use. We are deprecating it in the next version and removing it in the one after that, in order to avoid confusing people.

@caronc caronc force-pushed the 497-xmpp-refactor branch from 64457cd to be89d5c Compare April 17, 2022 16:51
@caronc
Copy link
Owner Author

caronc commented Apr 17, 2022

@drequivalent ; i believe i fixed the recipient parsing issue. @mathieui, were you able to handle the closing of the event loop? I'd prefer to fix Apprise to use that version and higher.

Also @mathieui, there appears to be an issue with the internal DNS of xmpp where it will hang indefinitely if the jid isn't resolvable. Is there a way to just pass in a switch or anything to disable this DNS functionality completely from slixxmpp?

Edit: @drequivalent - would you by chance be able to test the latest branch here?

@caronc caronc force-pushed the 497-xmpp-refactor branch from aea6d29 to 9b9942a Compare June 18, 2022 19:57
@caronc
Copy link
Owner Author

caronc commented Jun 19, 2022

Updated test coverage; but in doing so, i uncovered a situation where slixxmpp still isn't correctly reporting correctly. When an instance of the slixxmpp library has already spun up and connected, multiple instances spun up thereafter, do not seem to work (hence the second instance reports it's connected when it hasn't at all yet; it's almost as though it's using some central reference (or reading from the previous initialization in memory).

Will still need to investigate running just this plugin in it's own thread if it were to continue to be supported.

The only other catch is if the server can't be connected to, there doesn't appear to be a timeout option (maybe there is, i haven't gone through the slixxmpp source code yet) to eventually stop connecting. Just specifying an invalid host would be a DOS.

@caronc caronc closed this Jul 1, 2022
@amotl
Copy link
Collaborator

amotl commented Aug 22, 2022

Hi again,

might https://lab.louiz.org/poezio/slixmpp/-/merge_requests/164 by @linkmauve be of any interest in this context?

With kind regards,
Andreas.

@Neustradamus
Copy link

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

6 participants