search

errbotio / errbot

Errbot is a chatbot, a daemon that connects to your favorite chat service and bring your tools and some fun into the conversation.
http://errbot.io
GNU General Public License v3.0
3.12k stars 614 forks source link

bot doesn't answer on command until new message was sent by me. #1516

Closed ChzenChzen closed 2 years ago

ChzenChzen commented 3 years ago

In order to let us help you better, please fill out the following fields as best you can:

I am...

I am running...

Issue description

I try to make XMPP bot. I made command which send http request to my service to get some balance info. After that I trying to get answer from bot with this information. But it doesn't work until I chat any text to bot again. If I send any message to bot, it will answer me with proper message.

Steps to reproduce

from errbot import BotPlugin, botcmd, arg_botcmd
import decimal
import os
import requests

class Example(BotPlugin):
    """
    This is a very basic plugin to try out your new installation and get you started.
    Feel free to tweak me to experiment with Errbot.
    You can find me in your init directory in the subdirectory plugins.
    """
    GET_BALANCE = "get_balance"
    ADD_PAYMENT_REQUEST = "add_payment_request"
    CLEAN_ELECTRUM_WATCHER_ADDR = os.environ.get("CLEAN_ELECTRUM_WATCHER_ADDR")
    DIRTY_ELECTRUM_WATCHER_ADDR = os.environ.get("DIRTY_ELECTRUM_WATCHER_ADDR")

    @arg_botcmd("--address", dest="address", type=str)
    @arg_botcmd("--amount", dest="amount", type=str)
    def mix(self, msg, address=None, amount=None):
        try:
            amount = decimal.Decimal(amount)
        except decimal.InvalidOperation:
            return f"amount in wrong format: {amount}"
        except TypeError:
            return f"amount isn't number: {amount}"

        # todo add checking btc address checksum.
        if address is None:
            return f"address isn't set: {address}"

        clean_balance = self.checking_balance()
        return f"It *works* !\naddress: {address}, amount: {amount} balance: {clean_balance}"

    def checking_balance(self):
        url = f"{self.CLEAN_ELECTRUM_WATCHER_ADDR}/{self.GET_BALANCE}"
        resp = requests.get(url)
        json = resp.json()
        return json['result']['confirmed']

Additional info

sijis commented 3 years ago

Doesn't this work using the text backend?

ChzenChzen commented 3 years ago

@sijis in text backend all works perfect.

ChzenChzen commented 3 years ago

Could somebody help me?

nzlosh commented 3 years ago

The code snippet doesn't appear to have anything special happening in it that would block the command result until further interaction with the bot has happened. Have you enabled debugging and checked for error/warning messages in the logs? Perhaps you could add some logging to your code so you can determine where exactly the delay is happening to try and narrow the search?

ChzenChzen commented 3 years ago

@nvzard also If wait for several minutes, chat updates on it own.

2021-06-13 20:10:39,735 INFO     errbot.bootstrap          Found Storage plugin: Shelf.
2021-06-13 20:10:39,740 INFO     errbot.bootstrap          Found Backend plugin: XMPP
2021-06-13 20:10:39,740 DEBUG    errbot.storage            Opening storage 'repomgr'
2021-06-13 20:10:39,742 DEBUG    errbot.storage.shelf      Open shelf storage ./data/repomgr.db
2021-06-13 20:10:39,770 WARNING  slixmpp.stringprep        Using slower stringprep, consider compiling the faster cython/libidn one.
2021-06-13 20:10:39,806 DEBUG    errbot.core               ErrBot init.
2021-06-13 20:10:39,807 DEBUG    errbot.backends.base      Backend init.
2021-06-13 20:10:39,811 DEBUG    errbot.core               created a thread pool of size 10.
2021-06-13 20:10:39,813 DEBUG    asyncio                   Using selector: EpollSelector
2021-06-13 20:10:39,816 DEBUG    slixmpp.plugins.base      Loaded Plugin: RFC 6120: Stream Feature: STARTTLS
2021-06-13 20:10:39,818 DEBUG    slixmpp.plugins.base      Loaded Plugin: RFC 6120: Stream Feature: Resource Binding
2021-06-13 20:10:39,819 DEBUG    slixmpp.plugins.base      Loaded Plugin: RFC 3920: Stream Feature: Start Session
2021-06-13 20:10:39,821 DEBUG    slixmpp.plugins.base      Loaded Plugin: RFC 6121: Stream Feature: Roster Versioning
2021-06-13 20:10:39,822 DEBUG    slixmpp.plugins.base      Loaded Plugin: RFC 6121: Stream Feature: Subscription Pre-Approval
2021-06-13 20:10:39,824 DEBUG    slixmpp.plugins.base      Loaded Plugin: RFC 6120: Stream Feature: SASL
2021-06-13 20:10:39,826 DEBUG    slixmpp.plugins.base      Loaded Plugin: XEP-0030: Service Discovery
2021-06-13 20:10:39,829 DEBUG    slixmpp.plugins.base      Loaded Plugin: XEP-0004: Data Forms
2021-06-13 20:10:39,830 DEBUG    slixmpp.plugins.base      Loaded Plugin: XEP-0045: Multi-User Chat
2021-06-13 20:10:39,831 DEBUG    slixmpp.plugins.base      Loaded Plugin: XEP-0199: XMPP Ping
2021-06-13 20:10:39,833 DEBUG    slixmpp.plugins.base      Loaded Plugin: XEP-0203: Delayed Delivery
2021-06-13 20:10:39,834 DEBUG    slixmpp.plugins.base      Loaded Plugin: XEP-0249: Direct MUC Invitations
2021-06-13 20:10:39,839 DEBUG    MARKDOWN                  Successfully loaded extension "markdown.extensions.fenced_code.FencedCodeExtension".
2021-06-13 20:10:39,840 DEBUG    MARKDOWN                  Successfully loaded extension "markdown.extensions.footnotes.FootnoteExtension".
2021-06-13 20:10:39,841 DEBUG    MARKDOWN                  Successfully loaded extension "markdown.extensions.attr_list.AttrListExtension".
2021-06-13 20:10:39,842 DEBUG    MARKDOWN                  Successfully loaded extension "markdown.extensions.def_list.DefListExtension".
2021-06-13 20:10:39,843 DEBUG    MARKDOWN                  Successfully loaded extension "markdown.extensions.tables.TableExtension".
2021-06-13 20:10:39,844 DEBUG    MARKDOWN                  Successfully loaded extension "markdown.extensions.abbr.AbbrExtension".
2021-06-13 20:10:39,845 DEBUG    MARKDOWN                  Successfully loaded extension "markdown.extensions.md_in_html.MarkdownInHtmlExtension".
2021-06-13 20:10:39,846 DEBUG    MARKDOWN                  Successfully loaded extension "markdown.extensions.extra.ExtraExtension".
2021-06-13 20:10:39,849 DEBUG    MARKDOWN                  Successfully loaded extension "markdown.extensions.fenced_code.FencedCodeExtension".
2021-06-13 20:10:39,849 DEBUG    MARKDOWN                  Successfully loaded extension "markdown.extensions.footnotes.FootnoteExtension".
2021-06-13 20:10:39,850 DEBUG    MARKDOWN                  Successfully loaded extension "markdown.extensions.attr_list.AttrListExtension".
2021-06-13 20:10:39,851 DEBUG    MARKDOWN                  Successfully loaded extension "markdown.extensions.def_list.DefListExtension".
2021-06-13 20:10:39,852 DEBUG    MARKDOWN                  Successfully loaded extension "markdown.extensions.tables.TableExtension".
2021-06-13 20:10:39,853 DEBUG    MARKDOWN                  Successfully loaded extension "markdown.extensions.abbr.AbbrExtension".
2021-06-13 20:10:39,853 DEBUG    MARKDOWN                  Successfully loaded extension "markdown.extensions.md_in_html.MarkdownInHtmlExtension".
2021-06-13 20:10:39,854 DEBUG    MARKDOWN                  Successfully loaded extension "markdown.extensions.extra.ExtraExtension".
2021-06-13 20:10:39,855 DEBUG    MARKDOWN                  Successfully loaded extension "errbot.rendering.ansiext.AnsiExtension".
2021-06-13 20:10:39,856 DEBUG    errbot.storage            Opening storage 'core'
2021-06-13 20:10:39,857 DEBUG    errbot.storage.shelf      Open shelf storage ./data/core.db
2021-06-13 20:10:39,865 DEBUG    errbot.core               Initializing backend storage
2021-06-13 20:10:39,865 DEBUG    errbot.storage            Opening storage 'xmpp_backend'
2021-06-13 20:10:39,867 DEBUG    errbot.storage.shelf      Open shelf storage ./data/xmpp_backend.db
2021-06-13 20:10:39,879 DEBUG    errbot.plugin_manager     New entries added to sys.path:
2021-06-13 20:10:39,880 DEBUG    errbot.plugin_manager     /usr/local/lib/python3.9/site-packages/errbot/core_plugins
2021-06-13 20:10:39,880 DEBUG    errbot.plugin_manager     ./plugins/err-example
2021-06-13 20:10:39,883 DEBUG    errbot.plugins.Health     Logger for plugin initialized...
2021-06-13 20:10:39,883 DEBUG    errbot.plugins.Help       Logger for plugin initialized...
2021-06-13 20:10:39,885 DEBUG    errbot.plugins.Flows      Logger for plugin initialized...
2021-06-13 20:10:39,886 DEBUG    errbot.plugins.CommandNotFoundFilter Logger for plugin initialized...
2021-06-13 20:10:39,887 DEBUG    errbot.plugins.Backup     Logger for plugin initialized...
2021-06-13 20:10:39,888 DEBUG    errbot.plugins.TextCmds   Logger for plugin initialized...
2021-06-13 20:10:39,889 DEBUG    errbot.plugins.Plugins    Logger for plugin initialized...
2021-06-13 20:10:39,890 DEBUG    errbot.plugins.ChatRoom   Logger for plugin initialized...
2021-06-13 20:10:39,891 DEBUG    errbot.plugins.ACLs       Logger for plugin initialized...
2021-06-13 20:10:39,911 DEBUG    errbot.plugins.VersionChecker Logger for plugin initialized...
2021-06-13 20:10:39,954 INFO     errbot                    webhooks:  Flag to bind /echo to echo
2021-06-13 20:10:39,955 DEBUG    errbot.plugins.Webserver  Logger for plugin initialized...
2021-06-13 20:10:39,956 DEBUG    errbot.plugins.Utils      Logger for plugin initialized...
2021-06-13 20:10:39,967 DEBUG    errbot.plugins.Example    Logger for plugin initialized...
2021-06-13 20:10:39,969 DEBUG    errbot.bootstrap          Start serving commands from the xmpp backend.
2021-06-13 20:10:39,970 DEBUG    slixmpp.xmlstream.xmlstream Event triggered: connecting
2021-06-13 20:10:39,971 DEBUG    slixmpp.xmlstream.resolver DNS: Querying SRV records for pacificside.me
2021-06-13 20:10:39,996 DEBUG    slixmpp.xmlstream.resolver DNS: Exception while querying for pacificside.me SRV records: (4, 'Domain name not found')
2021-06-13 20:10:39,997 DEBUG    slixmpp.xmlstream.resolver DNS: Querying pacificside.me for AAAA records.
2021-06-13 20:10:40,054 DEBUG    slixmpp.xmlstream.resolver DNS: Exception while querying for pacificside.me AAAA records: (1, 'DNS server returned answer with no data')
2021-06-13 20:10:40,056 DEBUG    slixmpp.xmlstream.resolver DNS: Querying pacificside.me for A records.
2021-06-13 20:10:40,102 DEBUG    slixmpp.xmlstream.xmlstream Event triggered: connected
2021-06-13 20:10:40,103 DEBUG    slixmpp.xmlstream.xmlstream SEND: <stream:stream to='pacificside.me' xmlns:stream='http://etherx.jabber.org/streams' xmlns='jabber:client' xml:lang='en' version='1.0'>
2021-06-13 20:10:40,146 DEBUG    slixmpp.xmlstream.xmlstream RECV: <stream:stream id="16683367293296979147" version="1.0" xml:lang="en" from="pacificside.me">
2021-06-13 20:10:40,147 DEBUG    slixmpp.xmlstream.xmlstream RECV: <stream:features xmlns="http://etherx.jabber.org/streams"><starttls xmlns="urn:ietf:params:xml:ns:xmpp-tls"><required /></starttls></stream:features>
2021-06-13 20:10:40,149 DEBUG    slixmpp.xmlstream.xmlstream SEND: <starttls xmlns="urn:ietf:params:xml:ns:xmpp-tls"><required /></starttls>
2021-06-13 20:10:40,193 DEBUG    slixmpp.xmlstream.xmlstream RECV: <proceed xmlns="urn:ietf:params:xml:ns:xmpp-tls" />
2021-06-13 20:10:40,194 DEBUG    slixmpp.features.feature_starttls.starttls Starting TLS
2021-06-13 20:10:40,295 DEBUG    slixmpp.xmlstream.xmlstream Event triggered: ssl_cert
2021-06-13 20:10:40,300 DEBUG    slixmpp.xmlstream.xmlstream Event triggered: tls_success
2021-06-13 20:10:40,302 DEBUG    slixmpp.xmlstream.xmlstream SEND: <stream:stream to='pacificside.me' xmlns:stream='http://etherx.jabber.org/streams' xmlns='jabber:client' xml:lang='en' version='1.0'>
2021-06-13 20:10:40,348 DEBUG    slixmpp.xmlstream.xmlstream RECV: <stream:stream id="2026159606577079272" version="1.0" xml:lang="en" from="pacificside.me">
2021-06-13 20:10:40,352 DEBUG    slixmpp.xmlstream.xmlstream RECV: <stream:features xmlns="http://etherx.jabber.org/streams"><mechanisms xmlns="urn:ietf:params:xml:ns:xmpp-sasl"><mechanism>DIGEST-MD5</mechanism><mechanism>PLAIN</mechanism><mechanism>SCRAM-SHA-512-PLUS</mechanism><mechanism>SCRAM-SHA-512</mechanism><mechanism>SCRAM-SHA-256-PLUS</mechanism><mechanism>SCRAM-SHA-256</mechanism><mechanism>SCRAM-SHA-1-PLUS</mechanism><mechanism>SCRAM-SHA-1</mechanism><mechanism>X-OAUTH2</mechanism></mechanisms><register xmlns="http://jabber.org/features/iq-register" /></stream:features>
2021-06-13 20:10:40,357 DEBUG    slixmpp.xmlstream.xmlstream SEND: <auth xmlns="urn:ietf:params:xml:ns:xmpp-sasl" mechanism="SCRAM-SHA-512-PLUS">cD10bHMtdW5pcXVlLCxuPXNlY3JldGFyeSxyPTk2MzUwMTMzNjc5OTM5MDI=</auth>
2021-06-13 20:10:40,420 DEBUG    slixmpp.xmlstream.xmlstream RECV: <challenge xmlns="urn:ietf:params:xml:ns:xmpp-sasl">cj05NjM1MDEzMzY3OTkzOTAyTnpteGIrMEpZV0tESFdnOFc2ZmhMZz09LHM9VzNLV25VUUhLWm5kVlhWTWZ4dWxvQT09LGk9NDA5Ng==</challenge>
2021-06-13 20:10:40,472 DEBUG    slixmpp.xmlstream.xmlstream SEND: <response xmlns="urn:ietf:params:xml:ns:xmpp-sasl">Yz1jRDEwYkhNdGRXNXBjWFZsTEN5TFB2c25wdFprd2FJT1RPaz0scj05NjM1MDEzMzY3OTkzOTAyTnpteGIrMEpZV0tESFdnOFc2ZmhMZz09LHA9WUtHaVlsQ1FZMzN4dUxtL3E3amxyMkRvMjhldHVpeis4dzZZcGZiWWMrZ2g3WHFWWkhMU3ZSWWlheW1iUVB1Y3pRL2J1ckFrUXNEeG8waTFkcVI5TWc9PQ==</response>
2021-06-13 20:10:40,517 DEBUG    slixmpp.xmlstream.xmlstream RECV: <success xmlns="urn:ietf:params:xml:ns:xmpp-sasl">dj02SUFOWFduMzNUYm5BZHVrcUNUWCt2RkpXYWNNa1l3SFRaRUFJckJpSm54d2ZSd1ZvS3BiZlZSbmRLUUVzbUdGVkZ1cmRjOE4zdHFGQjhubVpSRmw3Zz09</success>
2021-06-13 20:10:40,519 DEBUG    slixmpp.xmlstream.xmlstream Event triggered: auth_success
2021-06-13 20:10:40,520 DEBUG    slixmpp.xmlstream.xmlstream SEND: <stream:stream to='pacificside.me' xmlns:stream='http://etherx.jabber.org/streams' xmlns='jabber:client' xml:lang='en' version='1.0'>
2021-06-13 20:10:40,565 DEBUG    slixmpp.xmlstream.xmlstream RECV: <stream:stream id="2936447776712268377" version="1.0" xml:lang="en" from="pacificside.me">
2021-06-13 20:10:40,565 DEBUG    slixmpp.xmlstream.xmlstream 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="NqMDrgCx03HLh3URMusgDnNsR30=" 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>
2021-06-13 20:10:40,566 DEBUG    slixmpp.features.feature_rosterver.rosterver Enabling roster versioning.
2021-06-13 20:10:40,567 DEBUG    slixmpp.features.feature_bind.bind Requesting resource: 
2021-06-13 20:10:40,568 DEBUG    slixmpp.xmlstream.xmlstream SEND: <iq id="acd9c1f9769945039146d50710b70078" type="set"><bind xmlns="urn:ietf:params:xml:ns:xmpp-bind" /></iq>
2021-06-13 20:10:40,612 DEBUG    slixmpp.xmlstream.xmlstream RECV: <iq type="result" id="acd9c1f9769945039146d50710b70078"><bind xmlns="urn:ietf:params:xml:ns:xmpp-bind"><jid>secretary@pacificside.me/1590471547735937335036306</jid></bind></iq>
2021-06-13 20:10:40,613 DEBUG    slixmpp.xmlstream.xmlstream Event triggered: session_bind
2021-06-13 20:10:40,614 INFO     slixmpp.features.feature_bind.bind JID set to: secretary@pacificside.me/1590471547735937335036306
2021-06-13 20:10:40,615 DEBUG    slixmpp.xmlstream.xmlstream Event triggered: session_start
2021-06-13 20:10:40,616 INFO     errbot.core               Activate internal commands
2021-06-13 20:10:40,616 INFO     errbot.plugin_manager     Activate bot plugins...
2021-06-13 20:10:40,617 INFO     errbot.plugin_manager     Activate plugin: Health.
2021-06-13 20:10:40,618 DEBUG    errbot.templating         Templates directory found for this plugin [/usr/local/lib/python3.9/site-packages/errbot/core_plugins/templates]
2021-06-13 20:10:40,618 DEBUG    errbot.botplugin          Init storage for Health.
2021-06-13 20:10:40,619 DEBUG    errbot.storage            Opening storage 'Health'
2021-06-13 20:10:40,620 DEBUG    errbot.storage.shelf      Open shelf storage ./data/Health.db
2021-06-13 20:10:40,627 DEBUG    errbot.core               Adding command : restart -> restart.
2021-06-13 20:10:40,628 DEBUG    errbot.core               Adding command : shutdown -> shutdown.
2021-06-13 20:10:40,629 DEBUG    errbot.core               Adding command : status -> status.
2021-06-13 20:10:40,629 DEBUG    errbot.core               Adding command : status_gc -> status_gc.
2021-06-13 20:10:40,630 DEBUG    errbot.core               Adding command : status_load -> status_load.
2021-06-13 20:10:40,630 DEBUG    errbot.core               Adding command : status_plugins -> status_plugins.
2021-06-13 20:10:40,631 DEBUG    errbot.core               Adding command : uptime -> uptime.
2021-06-13 20:10:40,632 INFO     errbot.core_plugins.wsview Checking Health for webhooks
2021-06-13 20:10:40,632 INFO     errbot.plugin_manager     Activate plugin: Help.
2021-06-13 20:10:40,633 DEBUG    errbot.templating         Templates directory found for this plugin [/usr/local/lib/python3.9/site-packages/errbot/core_plugins/templates]
2021-06-13 20:10:40,634 DEBUG    errbot.botplugin          Init storage for Help.
2021-06-13 20:10:40,634 DEBUG    errbot.storage            Opening storage 'Help'
2021-06-13 20:10:40,636 DEBUG    errbot.storage.shelf      Open shelf storage ./data/Help.db
2021-06-13 20:10:40,643 DEBUG    errbot.core               Adding command : about -> about.
2021-06-13 20:10:40,644 DEBUG    errbot.core               Adding command : apropos -> apropos.
2021-06-13 20:10:40,645 DEBUG    errbot.core               Adding command : help -> help.
2021-06-13 20:10:40,646 INFO     errbot.core_plugins.wsview Checking Help for webhooks
2021-06-13 20:10:40,647 INFO     errbot.plugin_manager     Activate plugin: Flows.
2021-06-13 20:10:40,648 DEBUG    errbot.templating         Templates directory found for this plugin [/usr/local/lib/python3.9/site-packages/errbot/core_plugins/templates]
2021-06-13 20:10:40,649 DEBUG    errbot.botplugin          Init storage for Flows.
2021-06-13 20:10:40,649 DEBUG    errbot.storage            Opening storage 'Flows'
2021-06-13 20:10:40,650 DEBUG    errbot.storage.shelf      Open shelf storage ./data/Flows.db
2021-06-13 20:10:40,658 DEBUG    errbot.core               Adding command : flows_kill -> flows_kill.
2021-06-13 20:10:40,659 DEBUG    errbot.core               Adding command : flows_list -> flows_list.
2021-06-13 20:10:40,659 DEBUG    errbot.core               Adding command : flows_show -> flows_show.
2021-06-13 20:10:40,660 DEBUG    errbot.core               Adding command : flows_start -> flows_start.
2021-06-13 20:10:40,660 DEBUG    errbot.core               Adding command : flows_status -> flows_status.
2021-06-13 20:10:40,661 DEBUG    errbot.core               Adding command : flows_stop -> flows_stop.
2021-06-13 20:10:40,662 INFO     errbot.core_plugins.wsview Checking Flows for webhooks
2021-06-13 20:10:40,663 INFO     errbot.plugin_manager     Activate plugin: CommandNotFoundFilter.
2021-06-13 20:10:40,663 DEBUG    errbot.templating         Templates directory found for this plugin [/usr/local/lib/python3.9/site-packages/errbot/core_plugins/templates]
2021-06-13 20:10:40,664 DEBUG    errbot.botplugin          Init storage for CommandNotFoundFilter.
2021-06-13 20:10:40,665 DEBUG    errbot.storage            Opening storage 'CommandNotFoundFilter'
2021-06-13 20:10:40,666 DEBUG    errbot.storage.shelf      Open shelf storage ./data/CommandNotFoundFilter.db
2021-06-13 20:10:40,672 DEBUG    errbot.core               Adding command filter: cnf_filter
2021-06-13 20:10:40,673 INFO     errbot.core_plugins.wsview Checking CommandNotFoundFilter for webhooks
2021-06-13 20:10:40,674 INFO     errbot.plugin_manager     Activate plugin: Backup.
2021-06-13 20:10:40,674 DEBUG    errbot.templating         Templates directory found for this plugin [/usr/local/lib/python3.9/site-packages/errbot/core_plugins/templates]
2021-06-13 20:10:40,675 DEBUG    errbot.botplugin          Init storage for Backup.
2021-06-13 20:10:40,676 DEBUG    errbot.storage            Opening storage 'Backup'
2021-06-13 20:10:40,677 DEBUG    errbot.storage.shelf      Open shelf storage ./data/Backup.db
2021-06-13 20:10:40,683 DEBUG    errbot.core               Adding command : backup -> backup.
2021-06-13 20:10:40,683 INFO     errbot.core_plugins.wsview Checking Backup for webhooks
2021-06-13 20:10:40,684 INFO     errbot.plugin_manager     Activate plugin: TextCmds.
2021-06-13 20:10:40,685 DEBUG    errbot.templating         Templates directory found for this plugin [/usr/local/lib/python3.9/site-packages/errbot/core_plugins/templates]
2021-06-13 20:10:40,685 INFO     errbot.core_plugins.wsview Checking TextModeCmds for webhooks
2021-06-13 20:10:40,686 INFO     errbot.plugin_manager     Activate plugin: Plugins.
2021-06-13 20:10:40,687 DEBUG    errbot.templating         Templates directory found for this plugin [/usr/local/lib/python3.9/site-packages/errbot/core_plugins/templates]
2021-06-13 20:10:40,687 DEBUG    errbot.botplugin          Init storage for Plugins.
2021-06-13 20:10:40,688 DEBUG    errbot.storage            Opening storage 'Plugins'
2021-06-13 20:10:40,689 DEBUG    errbot.storage.shelf      Open shelf storage ./data/Plugins.db
2021-06-13 20:10:40,696 DEBUG    errbot.core               Adding command : plugin_activate -> plugin_activate.
2021-06-13 20:10:40,696 DEBUG    errbot.core               Adding command : plugin_blacklist -> plugin_blacklist.
2021-06-13 20:10:40,697 DEBUG    errbot.core               Adding command : plugin_config -> plugin_config.
2021-06-13 20:10:40,697 DEBUG    errbot.core               Adding command : plugin_deactivate -> plugin_deactivate.
2021-06-13 20:10:40,698 DEBUG    errbot.core               Adding command : plugin_info -> plugin_info.
2021-06-13 20:10:40,699 DEBUG    errbot.core               Adding command : plugin_reload -> plugin_reload.
2021-06-13 20:10:40,699 DEBUG    errbot.core               Adding command : plugin_unblacklist -> plugin_unblacklist.
2021-06-13 20:10:40,699 DEBUG    errbot.core               Adding command : repos -> repos.
2021-06-13 20:10:40,700 DEBUG    errbot.core               Adding command : repos_install -> repos_install.
2021-06-13 20:10:40,701 DEBUG    errbot.core               Adding command : repos_search -> repos_search.
2021-06-13 20:10:40,701 DEBUG    errbot.core               Adding command : repos_uninstall -> repos_uninstall.
2021-06-13 20:10:40,702 DEBUG    errbot.core               Adding command : repos_update -> repos_update.
2021-06-13 20:10:40,703 INFO     errbot.core_plugins.wsview Checking Plugins for webhooks
2021-06-13 20:10:40,704 INFO     errbot.plugin_manager     Activate plugin: ChatRoom.
2021-06-13 20:10:40,704 DEBUG    errbot.templating         Templates directory found for this plugin [/usr/local/lib/python3.9/site-packages/errbot/core_plugins/templates]
2021-06-13 20:10:40,705 DEBUG    errbot.botplugin          Init storage for ChatRoom.
2021-06-13 20:10:40,706 DEBUG    errbot.storage            Opening storage 'ChatRoom'
2021-06-13 20:10:40,707 DEBUG    errbot.storage.shelf      Open shelf storage ./data/ChatRoom.db
2021-06-13 20:10:40,714 DEBUG    errbot.core               Adding command : room_create -> room_create.
2021-06-13 20:10:40,715 DEBUG    errbot.core               Adding command : room_destroy -> room_destroy.
2021-06-13 20:10:40,716 DEBUG    errbot.core               Adding command : room_invite -> room_invite.
2021-06-13 20:10:40,716 DEBUG    errbot.core               Adding command : room_join -> room_join.
2021-06-13 20:10:40,717 DEBUG    errbot.core               Adding command : room_leave -> room_leave.
2021-06-13 20:10:40,718 DEBUG    errbot.core               Adding command : room_list -> room_list.
2021-06-13 20:10:40,718 DEBUG    errbot.core               Adding command : room_occupants -> room_occupants.
2021-06-13 20:10:40,719 DEBUG    errbot.core               Adding command : room_topic -> room_topic.
2021-06-13 20:10:40,720 INFO     errbot.core_plugins.wsview Checking ChatRoom for webhooks
2021-06-13 20:10:40,720 INFO     errbot.plugins.ChatRoom   Connecting bot chatrooms
2021-06-13 20:10:40,721 INFO     errbot.plugin_manager     Activate plugin: ACLs.
2021-06-13 20:10:40,722 DEBUG    errbot.templating         Templates directory found for this plugin [/usr/local/lib/python3.9/site-packages/errbot/core_plugins/templates]
2021-06-13 20:10:40,722 DEBUG    errbot.botplugin          Init storage for ACLs.
2021-06-13 20:10:40,723 DEBUG    errbot.storage            Opening storage 'ACLs'
2021-06-13 20:10:40,724 DEBUG    errbot.storage.shelf      Open shelf storage ./data/ACLs.db
2021-06-13 20:10:40,731 DEBUG    errbot.core               Adding command filter: acls
2021-06-13 20:10:40,732 INFO     errbot.core_plugins.wsview Checking ACLS for webhooks
2021-06-13 20:10:40,733 INFO     errbot.plugin_manager     Activate plugin: VersionChecker.
2021-06-13 20:10:40,733 DEBUG    errbot.templating         Templates directory found for this plugin [/usr/local/lib/python3.9/site-packages/errbot/core_plugins/templates]
2021-06-13 20:10:40,734 DEBUG    errbot.plugins.VersionChecker Checking version in background.
2021-06-13 20:10:40,735 DEBUG    errbot.botplugin          Programming the polling of version_check every 86400 seconds with args [] and kwargs {}
2021-06-13 20:10:40,736 DEBUG    urllib3.connectionpool    Starting new HTTPS connection (1): errbot.io:443
2021-06-13 20:10:40,736 DEBUG    errbot.botplugin          Init storage for VersionChecker.
2021-06-13 20:10:40,737 DEBUG    errbot.storage            Opening storage 'VersionChecker'
2021-06-13 20:10:40,738 DEBUG    errbot.storage.shelf      Open shelf storage ./data/VersionChecker.db
2021-06-13 20:10:40,745 INFO     errbot.core_plugins.wsview Checking VersionChecker for webhooks
2021-06-13 20:10:40,746 INFO     errbot.plugin_manager     Activate plugin: Webserver.
2021-06-13 20:10:40,746 DEBUG    errbot.templating         Templates directory found for this plugin [/usr/local/lib/python3.9/site-packages/errbot/core_plugins/templates]
2021-06-13 20:10:40,747 INFO     errbot.plugins.Webserver  Webserver is not configured. Forbid activation
2021-06-13 20:10:40,748 INFO     errbot.core_plugins.wsview Checking Webserver for webhooks
2021-06-13 20:10:40,748 INFO     errbot.core_plugins.wsview Webhook routing echo
2021-06-13 20:10:40,749 INFO     errbot.plugin_manager     Activate plugin: Utils.
2021-06-13 20:10:40,750 DEBUG    errbot.templating         Templates directory found for this plugin [/usr/local/lib/python3.9/site-packages/errbot/core_plugins/templates]
2021-06-13 20:10:40,751 DEBUG    errbot.botplugin          Init storage for Utils.
2021-06-13 20:10:40,751 DEBUG    errbot.storage            Opening storage 'Utils'
2021-06-13 20:10:40,752 DEBUG    errbot.storage.shelf      Open shelf storage ./data/Utils.db
2021-06-13 20:10:40,759 DEBUG    errbot.core               Adding command : echo -> echo.
2021-06-13 20:10:40,760 DEBUG    errbot.core               Adding command : history -> history.
2021-06-13 20:10:40,761 DEBUG    errbot.core               Adding command : log_tail -> log_tail.
2021-06-13 20:10:40,761 DEBUG    errbot.core               Adding command : render_test -> render_test.
2021-06-13 20:10:40,762 DEBUG    errbot.core               Adding command : whoami -> whoami.
2021-06-13 20:10:40,763 INFO     errbot.core_plugins.wsview Checking Utils for webhooks
2021-06-13 20:10:40,763 INFO     errbot.plugin_manager     Activate plugin: Example.
2021-06-13 20:10:40,764 DEBUG    errbot.templating         No templates directory found for this plugin [Looking for plugins/err-example/templates]
2021-06-13 20:10:40,765 DEBUG    errbot.botplugin          Init storage for Example.
2021-06-13 20:10:40,765 DEBUG    errbot.storage            Opening storage 'Example'
2021-06-13 20:10:40,767 DEBUG    errbot.storage.shelf      Open shelf storage ./data/Example.db
2021-06-13 20:10:40,774 DEBUG    errbot.core               Adding command : mix -> mix.
2021-06-13 20:10:40,774 INFO     errbot.core_plugins.wsview Checking Example for webhooks
2021-06-13 20:10:40,775 DEBUG    errbot.plugin_manager     Activate flow plugins ...
2021-06-13 20:10:40,776 INFO     errbot.core               Notifying connection to all the plugins...
2021-06-13 20:10:40,776 DEBUG    errbot.core               Trigger callback_connect on Health.
2021-06-13 20:10:40,777 DEBUG    errbot.core               Trigger callback_connect on Help.
2021-06-13 20:10:40,778 DEBUG    errbot.core               Trigger callback_connect on Flows.
2021-06-13 20:10:40,778 DEBUG    errbot.core               Trigger callback_connect on CommandNotFoundFilter.
2021-06-13 20:10:40,779 DEBUG    errbot.core               Trigger callback_connect on Backup.
2021-06-13 20:10:40,779 DEBUG    errbot.core               Trigger callback_connect on Plugins.
2021-06-13 20:10:40,780 DEBUG    errbot.core               Trigger callback_connect on ChatRoom.
2021-06-13 20:10:40,780 INFO     errbot.plugins.ChatRoom   Connecting bot chatrooms
2021-06-13 20:10:40,781 DEBUG    errbot.core               Trigger callback_connect on ACLS.
2021-06-13 20:10:40,781 DEBUG    urllib3.connectionpool    https://errbot.io:443 "GET /versions.json HTTP/1.1" 302 240
2021-06-13 20:10:40,782 DEBUG    errbot.core               Trigger callback_connect on VersionChecker.
2021-06-13 20:10:40,783 DEBUG    urllib3.connectionpool    Starting new HTTPS connection (1): errbot.readthedocs.io:443
2021-06-13 20:10:40,784 DEBUG    errbot.core               Trigger callback_connect on Utils.
2021-06-13 20:10:40,785 DEBUG    errbot.core               Trigger callback_connect on Example.
2021-06-13 20:10:40,786 INFO     errbot.core               Plugin activation done.
2021-06-13 20:10:40,787 DEBUG    slixmpp.clientxmpp        Finished processing stream features.
2021-06-13 20:10:40,787 DEBUG    slixmpp.xmlstream.xmlstream Event triggered: stream_negotiated
2021-06-13 20:10:40,788 DEBUG    slixmpp.xmlstream.xmlstream Event triggered: sent_presence
2021-06-13 20:10:40,789 DEBUG    slixmpp.xmlstream.xmlstream SEND: <presence id="f4646f190fc1459fb916627284069b2b" xml:lang="en" />
2021-06-13 20:10:40,790 DEBUG    slixmpp.xmlstream.xmlstream SEND: <iq id="bf343233ba424e5b96872304d0614e5a" type="get"><query xmlns="jabber:iq:roster" ver="" /></iq>
2021-06-13 20:10:40,839 DEBUG    slixmpp.xmlstream.xmlstream RECV: <presence xml:lang="en" to="secretary@pacificside.me/1590471547735937335036306" from="secretary@pacificside.me/1590471547735937335036306" id="f4646f190fc1459fb916627284069b2b"><x xmlns="vcard-temp:x:update" /></presence>
2021-06-13 20:10:40,840 DEBUG    slixmpp.xmlstream.xmlstream Event triggered: presence
2021-06-13 20:10:40,841 DEBUG    slixmpp.xmlstream.xmlstream Event triggered: presence_available
2021-06-13 20:10:40,842 DEBUG    slixmpp.xmlstream.xmlstream Event triggered: got_online
2021-06-13 20:10:40,842 DEBUG    errbot.backends.xmpp      contact_online <presence xml:lang="en" to="secretary@pacificside.me/1590471547735937335036306" from="secretary@pacificside.me/1590471547735937335036306" id="f4646f190fc1459fb916627284069b2b"><x xmlns="vcard-temp:x:update" /></presence>.
2021-06-13 20:10:40,843 DEBUG    errbot.core               Triggering callback_presence on Health.
2021-06-13 20:10:40,844 DEBUG    errbot.core               Triggering callback_presence on Help.
2021-06-13 20:10:40,845 DEBUG    errbot.core               Triggering callback_presence on Flows.
2021-06-13 20:10:40,846 DEBUG    errbot.core               Triggering callback_presence on CommandNotFoundFilter.
2021-06-13 20:10:40,847 DEBUG    errbot.core               Triggering callback_presence on Backup.
2021-06-13 20:10:40,847 DEBUG    errbot.core               Triggering callback_presence on Plugins.
2021-06-13 20:10:40,848 DEBUG    errbot.core               Triggering callback_presence on ChatRoom.
2021-06-13 20:10:40,849 DEBUG    errbot.core               Triggering callback_presence on ACLs.
2021-06-13 20:10:40,850 DEBUG    errbot.core               Triggering callback_presence on VersionChecker.
2021-06-13 20:10:40,850 DEBUG    errbot.core               Triggering callback_presence on Utils.
2021-06-13 20:10:40,851 DEBUG    errbot.core               Triggering callback_presence on Example.
2021-06-13 20:10:40,852 DEBUG    slixmpp.xmlstream.xmlstream Event triggered: changed_status
2021-06-13 20:10:40,853 DEBUG    errbot.backends.xmpp      user_changed_status <presence xml:lang="en" to="secretary@pacificside.me/1590471547735937335036306" from="secretary@pacificside.me/1590471547735937335036306" id="f4646f190fc1459fb916627284069b2b"><x xmlns="vcard-temp:x:update" /></presence>.
2021-06-13 20:10:40,853 DEBUG    errbot.core               Triggering callback_presence on Health.
2021-06-13 20:10:40,854 DEBUG    errbot.core               Triggering callback_presence on Help.
2021-06-13 20:10:40,855 DEBUG    errbot.core               Triggering callback_presence on Flows.
2021-06-13 20:10:40,856 DEBUG    errbot.core               Triggering callback_presence on CommandNotFoundFilter.
2021-06-13 20:10:40,856 DEBUG    errbot.core               Triggering callback_presence on Backup.
2021-06-13 20:10:40,857 DEBUG    errbot.core               Triggering callback_presence on Plugins.
2021-06-13 20:10:40,858 DEBUG    errbot.core               Triggering callback_presence on ChatRoom.
2021-06-13 20:10:40,859 DEBUG    errbot.core               Triggering callback_presence on ACLs.
2021-06-13 20:10:40,859 DEBUG    errbot.core               Triggering callback_presence on VersionChecker.
2021-06-13 20:10:40,860 DEBUG    errbot.core               Triggering callback_presence on Utils.
2021-06-13 20:10:40,861 DEBUG    errbot.core               Triggering callback_presence on Example.
2021-06-13 20:10:40,861 DEBUG    slixmpp.xmlstream.xmlstream RECV: <iq xml:lang="en" to="secretary@pacificside.me/1590471547735937335036306" from="secretary@pacificside.me" type="result" id="bf343233ba424e5b96872304d0614e5a"><query xmlns="jabber:iq:roster" ver="554464ed444e9643cf7541905cd935a0ea9e24b2"><item subscription="both" jid="worker@pacificside.me" /><item subscription="both" jid="simple@pacificside.me" /><item subscription="both" jid="teacher@pacificside.me" /></query></iq>
2021-06-13 20:10:40,862 DEBUG    slixmpp.xmlstream.xmlstream Event triggered: roster_update
2021-06-13 20:10:40,863 DEBUG    slixmpp.xmlstream.xmlstream RECV: <presence xml:lang="en" to="secretary@pacificside.me/1590471547735937335036306" from="teacher@pacificside.me/fomotoshis-MacBook-Air" id="dc530f42bd5e479687edb17a99c2f42a"><c xmlns="http://jabber.org/protocol/caps" node="https://psi-plus.com" ver="plB5NF2Lzq3bL0h8RtwBtRpuDq8=" hash="sha-1" /><x xmlns="vcard-temp:x:update" /><delay xmlns="urn:xmpp:delay" from="teacher@pacificside.me/fomotoshis-MacBook-Air" stamp="2021-06-13T20:09:28.795471Z" /><priority>50</priority></presence>
2021-06-13 20:10:40,864 DEBUG    slixmpp.xmlstream.xmlstream Event triggered: presence
2021-06-13 20:10:40,865 DEBUG    slixmpp.xmlstream.xmlstream Event triggered: presence_available
2021-06-13 20:10:40,866 DEBUG    slixmpp.xmlstream.xmlstream Event triggered: got_online
2021-06-13 20:10:40,866 DEBUG    errbot.backends.xmpp      contact_online <presence xml:lang="en" to="secretary@pacificside.me/1590471547735937335036306" from="teacher@pacificside.me/fomotoshis-MacBook-Air" id="dc530f42bd5e479687edb17a99c2f42a"><c xmlns="http://jabber.org/protocol/caps" node="https://psi-plus.com" ver="plB5NF2Lzq3bL0h8RtwBtRpuDq8=" hash="sha-1" /><x xmlns="vcard-temp:x:update" /><delay xmlns="urn:xmpp:delay" from="teacher@pacificside.me/fomotoshis-MacBook-Air" stamp="2021-06-13T20:09:28.795471Z" /><priority>50</priority></presence>.
2021-06-13 20:10:40,867 DEBUG    errbot.core               Triggering callback_presence on Health.
2021-06-13 20:10:40,868 DEBUG    errbot.core               Triggering callback_presence on Help.
2021-06-13 20:10:40,869 DEBUG    errbot.core               Triggering callback_presence on Flows.
2021-06-13 20:10:40,869 DEBUG    errbot.core               Triggering callback_presence on CommandNotFoundFilter.
2021-06-13 20:10:40,870 DEBUG    errbot.core               Triggering callback_presence on Backup.
2021-06-13 20:10:40,871 DEBUG    errbot.core               Triggering callback_presence on Plugins.
2021-06-13 20:10:40,871 DEBUG    errbot.core               Triggering callback_presence on ChatRoom.
2021-06-13 20:10:40,872 DEBUG    errbot.core               Triggering callback_presence on ACLs.
2021-06-13 20:10:40,873 DEBUG    errbot.core               Triggering callback_presence on VersionChecker.
2021-06-13 20:10:40,873 DEBUG    errbot.core               Triggering callback_presence on Utils.
2021-06-13 20:10:40,874 DEBUG    errbot.core               Triggering callback_presence on Example.
2021-06-13 20:10:40,875 DEBUG    slixmpp.xmlstream.xmlstream Event triggered: changed_status
2021-06-13 20:10:40,875 DEBUG    errbot.backends.xmpp      user_changed_status <presence xml:lang="en" to="secretary@pacificside.me/1590471547735937335036306" from="teacher@pacificside.me/fomotoshis-MacBook-Air" id="dc530f42bd5e479687edb17a99c2f42a"><c xmlns="http://jabber.org/protocol/caps" node="https://psi-plus.com" ver="plB5NF2Lzq3bL0h8RtwBtRpuDq8=" hash="sha-1" /><x xmlns="vcard-temp:x:update" /><delay xmlns="urn:xmpp:delay" from="teacher@pacificside.me/fomotoshis-MacBook-Air" stamp="2021-06-13T20:09:28.795471Z" /><priority>50</priority></presence>.
2021-06-13 20:10:40,876 DEBUG    errbot.core               Triggering callback_presence on Health.
2021-06-13 20:10:40,876 DEBUG    errbot.core               Triggering callback_presence on Help.
2021-06-13 20:10:40,877 DEBUG    errbot.core               Triggering callback_presence on Flows.
2021-06-13 20:10:40,877 DEBUG    errbot.core               Triggering callback_presence on CommandNotFoundFilter.
2021-06-13 20:10:40,878 DEBUG    errbot.core               Triggering callback_presence on Backup.
2021-06-13 20:10:40,879 DEBUG    errbot.core               Triggering callback_presence on Plugins.
2021-06-13 20:10:40,880 DEBUG    errbot.core               Triggering callback_presence on ChatRoom.
2021-06-13 20:10:40,880 DEBUG    errbot.core               Triggering callback_presence on ACLs.
2021-06-13 20:10:40,881 DEBUG    errbot.core               Triggering callback_presence on VersionChecker.
2021-06-13 20:10:40,881 DEBUG    errbot.core               Triggering callback_presence on Utils.
2021-06-13 20:10:40,882 DEBUG    errbot.core               Triggering callback_presence on Example.
2021-06-13 20:10:40,883 DEBUG    slixmpp.xmlstream.xmlstream RECV: <presence xml:lang="en" to="secretary@pacificside.me/1590471547735937335036306" from="simple@pacificside.me/fomotoshis-MacBook-Air" id="f7b58669ee514afd8b757a567a08c962"><c xmlns="http://jabber.org/protocol/caps" node="https://psi-plus.com" ver="plB5NF2Lzq3bL0h8RtwBtRpuDq8=" hash="sha-1" /><x xmlns="vcard-temp:x:update" /><delay xmlns="urn:xmpp:delay" from="simple@pacificside.me/fomotoshis-MacBook-Air" stamp="2021-06-13T20:09:28.791091Z" /><priority>50</priority></presence>
2021-06-13 20:10:40,884 DEBUG    slixmpp.xmlstream.xmlstream Event triggered: presence
2021-06-13 20:10:40,884 DEBUG    slixmpp.xmlstream.xmlstream Event triggered: presence_available
2021-06-13 20:10:40,885 DEBUG    slixmpp.xmlstream.xmlstream Event triggered: got_online
2021-06-13 20:10:40,886 DEBUG    errbot.backends.xmpp      contact_online <presence xml:lang="en" to="secretary@pacificside.me/1590471547735937335036306" from="simple@pacificside.me/fomotoshis-MacBook-Air" id="f7b58669ee514afd8b757a567a08c962"><c xmlns="http://jabber.org/protocol/caps" node="https://psi-plus.com" ver="plB5NF2Lzq3bL0h8RtwBtRpuDq8=" hash="sha-1" /><x xmlns="vcard-temp:x:update" /><delay xmlns="urn:xmpp:delay" from="simple@pacificside.me/fomotoshis-MacBook-Air" stamp="2021-06-13T20:09:28.791091Z" /><priority>50</priority></presence>.
2021-06-13 20:10:40,886 DEBUG    errbot.core               Triggering callback_presence on Health.
2021-06-13 20:10:40,887 DEBUG    errbot.core               Triggering callback_presence on Help.
2021-06-13 20:10:40,888 DEBUG    errbot.core               Triggering callback_presence on Flows.
2021-06-13 20:10:40,888 DEBUG    errbot.core               Triggering callback_presence on CommandNotFoundFilter.
2021-06-13 20:10:40,889 DEBUG    errbot.core               Triggering callback_presence on Backup.
2021-06-13 20:10:40,890 DEBUG    errbot.core               Triggering callback_presence on Plugins.
2021-06-13 20:10:40,890 DEBUG    errbot.core               Triggering callback_presence on ChatRoom.
2021-06-13 20:10:40,891 DEBUG    errbot.core               Triggering callback_presence on ACLs.
2021-06-13 20:10:40,892 DEBUG    errbot.core               Triggering callback_presence on VersionChecker.
2021-06-13 20:10:40,892 DEBUG    errbot.core               Triggering callback_presence on Utils.
2021-06-13 20:10:40,893 DEBUG    errbot.core               Triggering callback_presence on Example.
2021-06-13 20:10:40,893 DEBUG    slixmpp.xmlstream.xmlstream Event triggered: changed_status
2021-06-13 20:10:40,894 DEBUG    errbot.backends.xmpp      user_changed_status <presence xml:lang="en" to="secretary@pacificside.me/1590471547735937335036306" from="simple@pacificside.me/fomotoshis-MacBook-Air" id="f7b58669ee514afd8b757a567a08c962"><c xmlns="http://jabber.org/protocol/caps" node="https://psi-plus.com" ver="plB5NF2Lzq3bL0h8RtwBtRpuDq8=" hash="sha-1" /><x xmlns="vcard-temp:x:update" /><delay xmlns="urn:xmpp:delay" from="simple@pacificside.me/fomotoshis-MacBook-Air" stamp="2021-06-13T20:09:28.791091Z" /><priority>50</priority></presence>.
2021-06-13 20:10:40,895 DEBUG    errbot.core               Triggering callback_presence on Health.
2021-06-13 20:10:40,896 DEBUG    errbot.core               Triggering callback_presence on Help.
2021-06-13 20:10:40,896 DEBUG    errbot.core               Triggering callback_presence on Flows.
2021-06-13 20:10:40,897 DEBUG    errbot.core               Triggering callback_presence on CommandNotFoundFilter.
2021-06-13 20:10:40,898 DEBUG    errbot.core               Triggering callback_presence on Backup.
2021-06-13 20:10:40,898 DEBUG    errbot.core               Triggering callback_presence on Plugins.
2021-06-13 20:10:40,899 DEBUG    errbot.core               Triggering callback_presence on ChatRoom.
2021-06-13 20:10:40,900 DEBUG    errbot.core               Triggering callback_presence on ACLs.
2021-06-13 20:10:40,900 DEBUG    errbot.core               Triggering callback_presence on VersionChecker.
2021-06-13 20:10:40,901 DEBUG    errbot.core               Triggering callback_presence on Utils.
2021-06-13 20:10:40,902 DEBUG    errbot.core               Triggering callback_presence on Example.
2021-06-13 20:10:40,902 DEBUG    slixmpp.xmlstream.xmlstream RECV: <presence xml:lang="en" to="secretary@pacificside.me/1590471547735937335036306" from="worker@pacificside.me/fomotoshis-MacBook-Air" id="639e8e4da92b44ef8a2a520cafa4b7ea"><c xmlns="http://jabber.org/protocol/caps" node="https://psi-plus.com" ver="plB5NF2Lzq3bL0h8RtwBtRpuDq8=" hash="sha-1" /><x xmlns="vcard-temp:x:update" /><delay xmlns="urn:xmpp:delay" from="worker@pacificside.me/fomotoshis-MacBook-Air" stamp="2021-06-13T20:09:28.794652Z" /><priority>50</priority></presence>
2021-06-13 20:10:40,903 DEBUG    slixmpp.xmlstream.xmlstream Event triggered: presence
2021-06-13 20:10:40,904 DEBUG    slixmpp.xmlstream.xmlstream Event triggered: presence_available
2021-06-13 20:10:40,905 DEBUG    slixmpp.xmlstream.xmlstream Event triggered: got_online
2021-06-13 20:10:40,905 DEBUG    errbot.backends.xmpp      contact_online <presence xml:lang="en" to="secretary@pacificside.me/1590471547735937335036306" from="worker@pacificside.me/fomotoshis-MacBook-Air" id="639e8e4da92b44ef8a2a520cafa4b7ea"><c xmlns="http://jabber.org/protocol/caps" node="https://psi-plus.com" ver="plB5NF2Lzq3bL0h8RtwBtRpuDq8=" hash="sha-1" /><x xmlns="vcard-temp:x:update" /><delay xmlns="urn:xmpp:delay" from="worker@pacificside.me/fomotoshis-MacBook-Air" stamp="2021-06-13T20:09:28.794652Z" /><priority>50</priority></presence>.
2021-06-13 20:10:40,906 DEBUG    errbot.core               Triggering callback_presence on Health.
2021-06-13 20:10:40,907 DEBUG    errbot.core               Triggering callback_presence on Help.
2021-06-13 20:10:40,907 DEBUG    errbot.core               Triggering callback_presence on Flows.
2021-06-13 20:10:40,908 DEBUG    errbot.core               Triggering callback_presence on CommandNotFoundFilter.
2021-06-13 20:10:40,908 DEBUG    errbot.core               Triggering callback_presence on Backup.
2021-06-13 20:10:40,909 DEBUG    errbot.core               Triggering callback_presence on Plugins.
2021-06-13 20:10:40,909 DEBUG    errbot.core               Triggering callback_presence on ChatRoom.
2021-06-13 20:10:40,910 DEBUG    errbot.core               Triggering callback_presence on ACLs.
2021-06-13 20:10:40,911 DEBUG    errbot.core               Triggering callback_presence on VersionChecker.
2021-06-13 20:10:40,912 DEBUG    errbot.core               Triggering callback_presence on Utils.
2021-06-13 20:10:40,912 DEBUG    errbot.core               Triggering callback_presence on Example.
2021-06-13 20:10:40,913 DEBUG    slixmpp.xmlstream.xmlstream Event triggered: changed_status
2021-06-13 20:10:40,914 DEBUG    errbot.backends.xmpp      user_changed_status <presence xml:lang="en" to="secretary@pacificside.me/1590471547735937335036306" from="worker@pacificside.me/fomotoshis-MacBook-Air" id="639e8e4da92b44ef8a2a520cafa4b7ea"><c xmlns="http://jabber.org/protocol/caps" node="https://psi-plus.com" ver="plB5NF2Lzq3bL0h8RtwBtRpuDq8=" hash="sha-1" /><x xmlns="vcard-temp:x:update" /><delay xmlns="urn:xmpp:delay" from="worker@pacificside.me/fomotoshis-MacBook-Air" stamp="2021-06-13T20:09:28.794652Z" /><priority>50</priority></presence>.
2021-06-13 20:10:40,914 DEBUG    errbot.core               Triggering callback_presence on Health.
2021-06-13 20:10:40,915 DEBUG    errbot.core               Triggering callback_presence on Help.
2021-06-13 20:10:40,915 DEBUG    errbot.core               Triggering callback_presence on Flows.
2021-06-13 20:10:40,916 DEBUG    errbot.core               Triggering callback_presence on CommandNotFoundFilter.
2021-06-13 20:10:40,917 DEBUG    errbot.core               Triggering callback_presence on Backup.
2021-06-13 20:10:40,918 DEBUG    errbot.core               Triggering callback_presence on Plugins.
2021-06-13 20:10:40,918 DEBUG    errbot.core               Triggering callback_presence on ChatRoom.
2021-06-13 20:10:40,919 DEBUG    errbot.core               Triggering callback_presence on ACLs.
2021-06-13 20:10:40,920 DEBUG    errbot.core               Triggering callback_presence on VersionChecker.
2021-06-13 20:10:40,920 DEBUG    errbot.core               Triggering callback_presence on Utils.
2021-06-13 20:10:40,921 DEBUG    errbot.core               Triggering callback_presence on Example.
2021-06-13 20:10:41,041 DEBUG    urllib3.connectionpool    https://errbot.readthedocs.io:443 "GET /versions.json HTTP/1.1" 302 0
2021-06-13 20:10:41,068 DEBUG    urllib3.connectionpool    https://errbot.readthedocs.io:443 "GET /en/latest/versions.json HTTP/1.1" 200 47
2021-06-13 20:10:41,070 DEBUG    errbot.plugins.VersionChecker Latest Errbot version is: 6.1.7
2021-06-13 20:10:41,071 DEBUG    errbot.plugins.VersionChecker Installed Errbot version is: 6.1.7
2021-06-13 20:10:52,729 DEBUG    slixmpp.xmlstream.xmlstream RECV: <message xml:lang="en" to="secretary@pacificside.me/1590471547735937335036306" from="worker@pacificside.me/fomotoshis-MacBook-Air" type="chat" id="aacea"><active xmlns="http://jabber.org/protocol/chatstates" /><request xmlns="urn:xmpp:receipts" /><body>!mix --amount 0.002 --address bc1q2vwxkad92qfxw6kmhauzrd6d4v4ufv52ynuanv</body></message>
2021-06-13 20:10:52,735 DEBUG    slixmpp.xmlstream.xmlstream Event triggered: message
2021-06-13 20:10:52,738 DEBUG    errbot.backends.xmpp      incoming_message from: None
2021-06-13 20:10:52,743 DEBUG    errbot.core               *** frm = worker@pacificside.me/fomotoshis-MacBook-Air
2021-06-13 20:10:52,747 DEBUG    errbot.core               *** username = worker@pacificside.me
2021-06-13 20:10:52,751 DEBUG    errbot.core               *** text = !mix --amount 0.002 --address bc1q2vwxkad92qfxw6kmhauzrd6d4v4ufv52ynuanv
2021-06-13 20:10:52,754 DEBUG    errbot.plugins.ACLs       Check mix for ACLs.
2021-06-13 20:10:52,757 INFO     errbot.plugins.ACLs       Matching ACL {} against username worker@pacificside.me for command Example:mix.
2021-06-13 20:10:52,759 DEBUG    errbot.plugins.ACLs       Check if mix is admin only command.
2021-06-13 20:10:52,761 INFO     errbot.core               Processing command "mix" with parameters "--amount 0.002 --address bc1q***nuanv" from worker@pacificside.me/fomotoshis-MacBook-Air
2021-06-13 20:10:52,763 DEBUG    errbot.core               Triggering callback_message on Health.
2021-06-13 20:10:52,764 DEBUG    errbot.flow               Test if the command mix is a trigger for an inflight flow ...
2021-06-13 20:10:52,767 DEBUG    errbot.flow               None matched.
2021-06-13 20:10:52,765 DEBUG    errbot.core               Triggering callback_message on Help.
2021-06-13 20:10:52,772 DEBUG    errbot.core               Triggering callback_message on Flows.
2021-06-13 20:10:52,774 DEBUG    errbot.core               Triggering callback_message on CommandNotFoundFilter.
2021-06-13 20:10:52,771 DEBUG    urllib3.connectionpool    Starting new HTTP connection (1): clean_electrum_watcher:8888
2021-06-13 20:10:52,775 DEBUG    errbot.core               Triggering callback_message on Backup.
2021-06-13 20:10:52,778 DEBUG    errbot.core               Triggering callback_message on Plugins.
2021-06-13 20:10:52,780 DEBUG    errbot.core               Triggering callback_message on ChatRoom.
2021-06-13 20:10:52,782 DEBUG    urllib3.connectionpool    http://clean_electrum_watcher:8888 "GET /get_fee_rate HTTP/1.1" 200 44
2021-06-13 20:10:52,782 DEBUG    errbot.core               Triggering callback_message on ACLs.
2021-06-13 20:10:52,785 DEBUG    urllib3.connectionpool    Starting new HTTP connection (1): clean_electrum_watcher:8888
2021-06-13 20:10:52,786 DEBUG    errbot.core               Triggering callback_message on VersionChecker.
2021-06-13 20:10:52,789 DEBUG    errbot.core               Triggering callback_message on Utils.
2021-06-13 20:10:52,790 DEBUG    errbot.core               Triggering callback_message on Example.
2021-06-13 20:10:52,794 DEBUG    urllib3.connectionpool    http://clean_electrum_watcher:8888 "GET /get_balance HTTP/1.1" 200 64
2021-06-13 20:10:52,796 DEBUG    urllib3.connectionpool    Starting new HTTP connection (1): dirty_electrum_watcher:8888
2021-06-13 20:10:52,814 DEBUG    urllib3.connectionpool    http://dirty_electrum_watcher:8888 "POST /add_payment_request HTTP/1.1" 200 474
2021-06-13 20:10:52,815 DEBUG    errbot.backends.xmpp      send_message to worker@pacificside.me/fomotoshis-MacBook-Air
2021-06-13 20:10:52,816 DEBUG    errbot.flow               Test if the command mix is a trigger for an inflight flow ...
2021-06-13 20:10:52,817 DEBUG    errbot.flow               None matched.
2021-06-13 20:10:52,818 DEBUG    errbot.flow               Test if the command mix is an auto-trigger for any flow ...
2021-06-13 20:11:09,262 DEBUG    slixmpp.xmlstream.xmlstream SEND: <message type="chat" to="worker@pacificside.me/fomotoshis-MacBook-Air" id="fcb977a1af0447699f58cba98b4f2a9f" xml:lang="en"><origin-id xmlns="urn:xmpp:sid:0" id="fcb977a1af0447699f58cba98b4f2a9f" /><body>address for dirty: bc1***nvpcd, amount: 0.002</body></message>
2021-06-13 20:11:09,267 DEBUG    slixmpp.xmlstream.xmlstream RECV: <message xml:lang="en" to="secretary@pacificside.me/1590471547735937335036306" from="worker@pacificside.me/fomotoshis-MacBook-Air" type="chat" id="aad0a"><active xmlns="http://jabber.org/protocol/chatstates" /><request xmlns="urn:xmpp:receipts" /><body>d</body></message>
2021-06-13 20:11:09,271 DEBUG    slixmpp.xmlstream.xmlstream Event triggered: message
2021-06-13 20:11:09,274 DEBUG    errbot.backends.xmpp      incoming_message from: None
2021-06-13 20:11:09,277 DEBUG    errbot.core               *** frm = worker@pacificside.me/fomotoshis-MacBook-Air
2021-06-13 20:11:09,280 DEBUG    errbot.core               *** username = worker@pacificside.me
2021-06-13 20:11:09,282 DEBUG    errbot.core               *** text = d
2021-06-13 20:11:09,287 DEBUG    errbot.core               Triggering callback_message on Health.
2021-06-13 20:11:09,289 DEBUG    errbot.core               Triggering callback_message on Help.
2021-06-13 20:11:09,291 DEBUG    errbot.core               Triggering callback_message on Flows.
2021-06-13 20:11:09,293 DEBUG    errbot.core               Triggering callback_message on CommandNotFoundFilter.
2021-06-13 20:11:09,294 DEBUG    errbot.core               Triggering callback_message on Backup.
2021-06-13 20:11:09,296 DEBUG    errbot.core               Triggering callback_message on Plugins.
2021-06-13 20:11:09,297 DEBUG    errbot.core               Triggering callback_message on ChatRoom.
2021-06-13 20:11:09,299 DEBUG    errbot.core               Triggering callback_message on ACLs.
2021-06-13 20:11:09,300 DEBUG    errbot.core               Triggering callback_message on VersionChecker.
2021-06-13 20:11:09,302 DEBUG    errbot.core               Triggering callback_message on Utils.
2021-06-13 20:11:09,305 DEBUG    errbot.core               Triggering callback_message on Example.
nzlosh commented 3 years ago

It looks like the delay is related to the xmpp backend or slixmpp module. Errbot is handling the !mix command within ~100ms delay.

Based on the logs you've posted the events are as follows 2021-06-13 20:10:52,751 Errbot receives mix command. 2021-06-13 20:10:52,814 HTTP response received for command. 2021-06-13 20:10:52,815 XMPP backend calls send message function. 2021-06-13 20:11:09,262 slixmpp module sends message to XMPP server.

There appears to be something buffering/blocking around the XMPP backend and/or the slixmpp module. This will require someone to dig deeper into the XMPP backend code and the slixmpp module to try and replicate this issue. Unfortunately, I don't have the time/resources required to investigate the issue further right now.

m00lean commented 3 years ago

I see the same behavior when enabling the BOT_ASYNC. With BOT_ASYNC = False, everything works as intended.

ChzenChzen commented 2 years ago

it helps!