Loop crash unexpected after a 3-4 days of running it

un-hongly commented 5 months ago

Before we start...

[X] I've searched existing issues, but my problem hasn't been reported yet.
[X] I've read the documentation (including notes on error messages and rate limiting), but my problem is something else.
[X] I've tested the behaviour on Skype for Web, and it works there but not with SkPy.

Summary

I got an unexpected error after a fews day running it the loop start to crash. The error message said "You must create an endpoint before performing this operation."

Code sample

bot.py
from skpy import SkypeEventLoop, SkypeNewMessageEvent, SkypeChatUpdateEvent
import os
import httpx
from utils import message_to_dict

class Bot(SkypeEventLoop):
    def __init__(self):
        self.username = os.getenv("SKYPE_USERNAME", "")
        self.password = os.getenv("SKYPE_PASSWORD", "")
        self.message_endpoint = os.getenv("MESSAGE_PUSH_ENDPOINT", "")
        super(Bot, self).__init__(self.username, self.password, autoAck=True)

    def onEvent(self, event):
        try:
            if (
                isinstance(event, SkypeNewMessageEvent)
                and not event.msg.userId == self.userId
            ):
                print("== NEW INCOMING MESSAGE ==")
                print(event.msg)
                data = message_to_dict(event.msg, event)
                httpx.post(self.message_endpoint, json=data)

        except Exception as e:
            print(e)

main.py
def start_listen_skype_msg():
    try:
        bot.loop()
    except Exception as e:
        print("=> Loop exception:", e)
        print('=> Date now', datetime.now().isoformat())
        print('=> Skype token expiry', bot.conn.tokenExpiry.get("skype").isoformat())
        print('=> Reg token expiry', bot.conn.tokenExpiry.get("reg").isoformat())

if __name__ == "__main__":
    incoming_msg_thread = Thread(target=start_listen_skype_msg, daemon=True)
    incoming_msg_thread.start()

Code output

=> [11/06 08:07:38] 201

 {'Cache-Control': 'no-store, must-revalidate, no-cache',

  'Content-Length': '37',

  'Content-Type': 'application/json; charset=utf-8',

  'ContextId': 'tcid=8721571324804262422,server=SN3PEPF00009BDF',

  'Date': 'Tue, 11 Jun 2024 08:07:38 GMT',

  'Location': 'https://azscus1-client-s.gateway.messenger.live.com/v1/users/ME/conversations/19:2ca13735db7241c8bec55a8946e0f492@thread.skype/messages/1718093258848',

  'Pragma': 'no-cache',

  'X-Content-Type-Options': 'nosniff'}

 {'OriginalArrivalTime': 1718093258831}

 INFO:     10.3.4.144:57348 - "POST /send-text-message HTTP/1.1" 200 OK

 <= [11/06 08:07:39] POST https://login.live.com/RST.srf

 {'data': '\n'

          "    <Envelope xmlns='http://schemas.xmlsoap.org/soap/envelope/'\n"

          "       xmlns:wsse='http://schemas.xmlsoap.org/ws/2003/06/secext'\n"

          "       xmlns:wsp='http://schemas.xmlsoap.org/ws/2002/12/policy'\n"

          "       xmlns:wsa='http://schemas.xmlsoap.org/ws/2004/03/addressing'\n"

          "       xmlns:wst='http://schemas.xmlsoap.org/ws/2004/04/trust'\n"

          '       '

          "xmlns:ps='http://schemas.microsoft.com/Passport/SoapServices/PPCRL'>\n"

          '       <Header>\n'

          '           <wsse:Security>\n'

          "               <wsse:UsernameToken Id='user'>\n"

          '                   '

          '<wsse:Username>***</wsse:Username>\n'

          '                   '

          '<wsse:Password>***</wsse:Password>\n'

          '               </wsse:UsernameToken>\n'

          '           </wsse:Security>\n'

          '       </Header>\n'

          '       <Body>\n'

          "           <ps:RequestMultipleSecurityTokens Id='RSTS'>\n"

          "               <wst:RequestSecurityToken Id='RST0'>\n"

          '                   '

          '<wst:RequestType>http://schemas.xmlsoap.org/ws/2004/04/security/trust/Issue</wst:RequestType>\n'

          '                   <wsp:AppliesTo>\n'

          '                       <wsa:EndpointReference>\n'

          '                           <wsa:Address>wl.skype.com</wsa:Address>\n'

          '                       </wsa:EndpointReference>\n'

          '                   </wsp:AppliesTo>\n'

          '                   <wsse:PolicyReference '

          "URI='MBI_SSL'></wsse:PolicyReference>\n"

          '               </wst:RequestSecurityToken>\n'

          '           </ps:RequestMultipleSecurityTokens>\n'

          '       </Body>\n'

          '    </Envelope>\n'

          '    ',

  'headers': {}}

 => [11/06 08:07:39] 200

 {'Cache-Control': 'no-store, no-cache',

  'Content-Encoding': 'gzip',

  'Content-Length': '1426',

  'Content-Type': 'text/html; charset=utf-8',

  'Date': 'Tue, 11 Jun 2024 08:07:39 GMT',

  'Expires': 'Tue, 11 Jun 2024 08:06:39 GMT',

  'P3P': 'CP="DSP CUR OTPi IND OTRi ONL FIN"',

  'PPServer': 'PPV: 30 H: SN1PEPF0002F950 V: 0',

  'Pragma': 'no-cache',

  'Referrer-Policy': 'strict-origin-when-cross-origin',

  'Strict-Transport-Security': 'max-age=31536000',

  'Vary': 'Accept-Encoding',

  'X-Content-Type-Options': 'nosniff',

  'X-XSS-Protection': '1; mode=block',

  'x-ms-request-id': '381d681f-9be5-443d-978d-bd1d80c3bce8',

  'x-ms-route-info': 'C508_SN1'}

 <?xml version="1.0" encoding="utf-8" ?><S:Envelope xmlns:S="http://schemas.xmlsoap.org/soap/envelope/"><S:Header></S:Header><S:Body><wst:RequestSecurityTokenResponseCollection xmlns:S="http://schemas.xmlsoap.org/soap/envelope/" xmlns:wst="http://schemas.xmlsoap.org/ws/2004/04/trust" xmlns:wsse="http://schemas.xmlsoap.org/ws/2003/06/secext" xmlns:wsu="http://docs.oasis-open.org/wss/2004/01/oasis-200401-wss-wssecurity-utility-1.0.xsd" xmlns:saml="urn:oasis:names:tc:SAML:1.0:assertion" xmlns:wsp="http://schemas.xmlsoap.org/ws/2002/12/policy" xmlns:psf="http://schemas.microsoft.com/Passport/SoapServices/SOAPFault"><wst:RequestSecurityTokenResponse><wst:TokenType>urn:passport:compact</wst:TokenType><wsp:AppliesTo xmlns:wsa="http://schemas.xmlsoap.org/ws/2004/03/addressing"><wsa:EndpointReference><wsa:Address>wl.skype.com</wsa:Address></wsa:EndpointReference></wsp:AppliesTo><wst:LifeTime><wsu:Created>2024-06-11T08:07:39Z</wsu:Created><wsu:Expires>2024-06-12T08:07:39Z</wsu:Expires></wst:LifeTime><wst:RequestedSecurityToken><wsse:BinarySecurityToken Id="Compact0">t=***/yUC&amp;p=</wsse:BinarySecurityToken></wst:RequestedSecurityToken><wst:RequestedTokenReference><wsse:KeyIdentifier ValueType="urn:passport:compact"></wsse:KeyIdentifier><wsse:Reference URI="#Compact0"></wsse:Reference></wst:RequestedTokenReference></wst:RequestSecurityTokenResponse></wst:RequestSecurityTokenResponseCollection></S:Body></S:Envelope>

 <= [11/06 08:07:39] POST https://edge.skype.com/rps/v1/rps/skypetoken

 {'data': {'access_token':  '***',

           'partner': 999,

           'scopes': 'client'},

  'headers': {}}

 => [11/06 08:07:39] 200

 {'Cache-Control': 'no-cache, max-age=0, s-maxage=0, private',

  'Content-Type': 'application/json; charset=utf-8',

  'Date': 'Tue, 11 Jun 2024 08:07:39 GMT',

  'MS-CV': 'IW5QRUn+vkyYEt+c5EbyIw.0',

  'Strict-Transport-Security': 'max-age=2592000',

  'Transfer-Encoding': 'chunked',

  'X-Cache': 'CONFIG_NOCACHE',

  'X-Content-Type-Options': 'nosniff',

  'X-Frame-Options': 'deny',

  'X-MSEdge-Ref': 'Ref A: 6E4FD43583BC4DC6BC60DB18CBC7CD07 Ref B: TPE31EDGE0612 '

                  'Ref C: 2024-06-11T08:07:39Z',

  'X-Processing-Time': '99ms',

  'X-Skype-Request-Id': 'DDD5A035',

  'X-XSS-Protection': '1; mode=block'}

 {'anid': '912D177FC8C597960E83D873FFFFFFFF',

  'expiresIn': 86399,

  'isBusinessTenant': False,

  'signinname': '***',

  'skypeid': 'live:.cid.c77efcf73740fe8c',

  'skypetoken': '***',

  'status': {'code': 20000, 'text': 'OK'}}

 <= [11/06 08:07:39] GET https://api.skype.com/users/self/profile

 {'headers': {'X-SkypeToken': '***'}}

 => [11/06 08:07:40] 200

 {'Cache-Control': 'must-revalidate, no-cache, stratus-cache-per-request=true',

  'Connection': 'keep-alive',

  'Content-Length': '430',

  'Content-Type': 'application/json; ver=1.0; charset=utf-8',

  'Date': 'Tue, 11 Jun 2024 08:07:40 GMT',

  'Server': 'nginx',

  'Strict-Transport-Security': 'max-age=31536000; includeSubdomains;',

  'Vary': 'Origin',

  'X-Azure-Instance-ID': 'Test_1',

  'X-Azure-Location': 'westeurope',

  'X-Content-Type-Options': 'nosniff',

  'X-Frame-Options': 'SAMEORIGIN',

  'X-Processing-Time': '0.081',

  'X-Skype-Processing-Time': '11.03120',

  'X-Skype-Request-Id': 'e2a0bb30',

  'X-Stratus-Endpoint': '/users/:username/profile',

  'X-Stratus-Processing-Time': '0.0756',

  'X-XSS-Protection': '1; mode=block'}

 {'about': None,

  'avatarUrl': 'https://avatar.skype.com/v1/avatars/live:.cid.c77efcf73740fe8c?auth_key=1045077718',

  'birthday': None,

  'city': None,

  'country': None,

  'emails': ['***'],

  'firstname': 'MPAY',

  'gender': '0',

  'homepage': None,

  'jobtitle': None,

  'language': 'en',

  'lastname': 'Bot',

  'mood': None,

  'phoneHome': None,

  'phoneMobile': None,

  'phoneOffice': None,

  'province': None,

  'richMood': None,

  'username': 'live:.cid.c77efcf73740fe8c'}

 <= [11/06 08:07:40] POST https://client-s.gateway.messenger.live.com/v1/users/ME/endpoints

 {'headers': {'Authentication': 'skypetoken=***',

              'BehaviorOverride': 'redirectAs404',

              'LockAndKey': 'appId=msmsgs@msnmsgr.com; time=1718093260; '

                            'lockAndKeyResponse=1496de6311da1bd68e9523da0f6ac788'},

  'json': {'endpointFeatures': 'Agent'}}

 => [11/06 08:07:42] 201

 {'Cache-Control': 'no-store, must-revalidate, no-cache',

  'Content-Length': '2',

  'Content-Type': 'application/json; charset=utf-8',

  'ContextId': 'tcid=1220702527784438455,server=BY3PEPF00008394',

  'Date': 'Tue, 11 Jun 2024 08:07:41 GMT',

  'Location': 'https://azwus1-client-s.gateway.messenger.live.com/v1/users/ME/endpoints/%7Bbe3dcc12-ac64-4565-b79c-5bec671f507a%7D',

  'Pragma': 'no-cache',

  'Set-RegistrationToken': 'registrationToken=***'

                           'expires=1718179659; '

                           'endpointId={be3dcc12-ac64-4565-b79c-5bec671f507a}',

  'X-Content-Type-Options': 'nosniff'}

 {}

 <= [11/06 08:07:42] POST https://azwus1-client-s.gateway.messenger.live.com/v1/users/ME/endpoints

 {'headers': {'Authentication': 'skypetoken=***',

              'BehaviorOverride': 'redirectAs404',

              'LockAndKey': 'appId=msmsgs@msnmsgr.com; time=1718093262; '

                            'lockAndKeyResponse=4f946cf78b1b61a87b7cc728d2968b23'},

  'json': {'endpointFeatures': 'Agent'}}

 => [11/06 08:07:42] 201

 {'Cache-Control': 'no-store, must-revalidate, no-cache',

  'Content-Length': '2',

  'Content-Type': 'application/json; charset=utf-8',

  'ContextId': 'tcid=2877862929629251163,server=BY3PEPF00008465',

  'Date': 'Tue, 11 Jun 2024 08:07:41 GMT',

  'Location': 'https://azwus1-client-s.gateway.messenger.live.com/v1/users/ME/endpoints/%7B1afc7c47-6e30-4eb3-8686-94cd31e99140%7D',

  'Pragma': 'no-cache',

  'Set-RegistrationToken': 'registrationToken':  '***'

                           'expires=1718179659; '

                           'endpointId={1afc7c47-6e30-4eb3-8686-94cd31e99140}',

  'X-Content-Type-Options': 'nosniff'}

 {}

 <= [11/06 08:07:42] PUT https://azwus1-client-s.gateway.messenger.live.com/v1/users/ME/endpoints/{1afc7c47-6e30-4eb3-8686-94cd31e99140}/presenceDocs/messagingService

 {'headers': {'RegistrationToken': '***'},

  'json': {'id': 'messagingService',

           'privateInfo': {'epname': 'skype'},

           'publicInfo': {'capabilities': '',

                          'nodeInfo': 'xx',

                          'skypeNameVersion': 'skype.com',

                          'type': 1,

                          'version': '908/1.30.0.128'},

           'selfLink': 'uri',

           'type': 'EndpointPresenceDoc'}}

 => [11/06 08:07:42] 200

 {'Cache-Control': 'no-store, must-revalidate, no-cache',

  'Content-Encoding': 'gzip',

  'Content-Length': '277',

  'Content-Type': 'application/json; charset=utf-8',

  'ContextId': 'tcid=744374316372904839,server=BY3PEPF00008465',

  'Date': 'Tue, 11 Jun 2024 08:07:42 GMT',

  'Pragma': 'no-cache',

  'X-Content-Type-Options': 'nosniff'}

 {'id': 'messagingService',

  'privateInfo': {'epname': 'skype'},

  'publicInfo': {'capabilities': '',

                 'nodeInfo': 'xx',

                 'skypeNameVersion': 'skype.com',

                 'typ': '',

                 'version': '908/1.30.0.128'},

  'selfLink': 'https://azwus1-client-s.gateway.messenger.live.com/v1/users/8:live:.cid.c77efcf73740fe8c/endpoints/{1afc7c47-6e30-4eb3-8686-94cd31e99140}/presenceDocs/messagingService',

  'type': 'EndpointPresenceDoc'}

 <= [11/06 08:07:42] GET https://azwus1-client-s.gateway.messenger.live.com/v1/users/ME/presenceDocs/messagingService

 {'headers': {'RegistrationToken': '***'}, 'params': {'view': 'expanded'}}

 => [11/06 08:07:43] 200

 {'Cache-Control': 'no-store, must-revalidate, no-cache',

  'Content-Encoding': 'gzip',

  'Content-Length': '319',

  'Content-Type': 'application/json; charset=utf-8',

  'ContextId': 'tcid=4485066839856847571,server=BY3PEPF00008465',

  'Date': 'Tue, 11 Jun 2024 08:07:42 GMT',

  'Pragma': 'no-cache',

  'X-Content-Type-Options': 'nosniff'}

 {'availability': 'Offline',

  'capabilities': '',

  'endpointPresenceDocs': [{'link': 'https://azwus1-client-s.gateway.messenger.live.com/v1/users/8:live:.cid.c77efcf73740fe8c/endpoints/{1afc7c47-6e30-4eb3-8686-94cd31e99140}/presenceDocs/messagingService',

                            'privateInfo': {'epname': 'skype'},

                            'publicInfo': {'capabilities': '',

                                           'nodeInfo': 'xx',

                                           'skypeNameVersion': 'skype.com',

                                           'typ': '',

                                           'version': '908/1.30.0.128'},

                            'type': 'EndpointPresenceDoc'}],

  'id': 'messagingService',

  'status': 'Offline',

  'type': 'UserPresenceDoc'}

 <= [11/06 08:07:43] POST https://client-s.gateway.messenger.live.com/v1/users/ME/endpoints

 {'headers': {'Authentication': 'skypetoken=***',

              'BehaviorOverride': 'redirectAs404',

              'LockAndKey': 'appId=msmsgs@msnmsgr.com; time=1718093263; '

                            'lockAndKeyResponse=e9a72ea6428574f6a0c38e365dc3d061'},

  'json': {'endpointFeatures': 'Agent'}}

 => [11/06 08:07:43] 201

 {'Cache-Control': 'no-store, must-revalidate, no-cache',

  'Content-Length': '2',

  'Content-Type': 'application/json; charset=utf-8',

  'ContextId': 'tcid=6438758253327377667,server=BY3PEPF00008394',

  'Date': 'Tue, 11 Jun 2024 08:07:43 GMT',

  'Location': 'https://azwus1-client-s.gateway.messenger.live.com/v1/users/ME/endpoints/%7B22aaf884-fdb7-4d51-a58c-be376d7d3fe9%7D',

  'Pragma': 'no-cache',

  'Set-RegistrationToken': 'registrationToken=***'

                           'expires=1718179659; '

                           'endpointId={22aaf884-fdb7-4d51-a58c-be376d7d3fe9}',

  'X-Content-Type-Options': 'nosniff'}

 {}

 <= [11/06 08:07:43] POST https://azwus1-client-s.gateway.messenger.live.com/v1/users/ME/endpoints

 {'headers': {'Authentication': 'skypetoken=***',

              'BehaviorOverride': 'redirectAs404',

              'LockAndKey': 'appId=msmsgs@msnmsgr.com; time=1718093263; '

                            'lockAndKeyResponse=e9a72ea6428574f6a0c38e365dc3d061'},

  'json': {'endpointFeatures': 'Agent'}}

 timed out

 <= [11/06 08:07:43] POST https://azscus1-client-s.gateway.messenger.live.com/v1/users/ME/conversations/ALL/messages/1718093258160/ack

 {'headers': {'RegistrationToken': '***'}}

 => [11/06 08:07:43] 201

 {'Cache-Control': 'no-store, must-revalidate, no-cache',

  'Content-Length': '2',

  'Content-Type': 'application/json; charset=utf-8',

  'ContextId': 'tcid=9164430583356747496,server=BY3PEPF00008465',

  'Date': 'Tue, 11 Jun 2024 08:07:42 GMT',

  'Location': 'https://azwus1-client-s.gateway.messenger.live.com/v1/users/ME/endpoints/%7Bc1d4ecb0-c54f-4728-8825-9a7211ee8cde%7D',

  'Pragma': 'no-cache',

  'Set-RegistrationToken': 'registrationToken=***'

                           'expires=1718179659; '

                           'endpointId={c1d4ecb0-c54f-4728-8825-9a7211ee8cde}',

  'X-Content-Type-Options': 'nosniff'}

 {}

 <= [11/06 08:07:43] PUT https://azwus1-client-s.gateway.messenger.live.com/v1/users/ME/endpoints/{c1d4ecb0-c54f-4728-8825-9a7211ee8cde}/presenceDocs/messagingService

 {'headers': {'RegistrationToken': '***'},

  'json': {'id': 'messagingService',

           'privateInfo': {'epname': 'skype'},

           'publicInfo': {'capabilities': '',

                          'nodeInfo': 'xx',

                          'skypeNameVersion': 'skype.com',

                          'type': 1,

                          'version': '908/1.30.0.128'},

           'selfLink': 'uri',

           'type': 'EndpointPresenceDoc'}}

 => [11/06 08:07:43] 404

 {'Cache-Control': 'no-store, must-revalidate, no-cache',

  'Content-Length': '91',

  'Content-Type': 'application/json; charset=utf-8',

  'ContextId': 'tcid=7411242851431710710,server=SN3PEPF00009BDF',

  'Date': 'Tue, 11 Jun 2024 08:07:43 GMT',

  'Pragma': 'no-cache',

  'StatusText': 'You must create an endpoint before performing this operation.'}

 {'errorCode': 729,

  'message': 'You must create an endpoint before performing this operation.'}

 => Loop exception: ('404 response from POST https://azscus1-client-s.gateway.messenger.live.com/v1/users/ME/conversations/ALL/messages/1718093258160/ack', <Response [404]>)

 => Date now 2024-06-11T08:07:43.568669

 => Skype token expiry 2024-06-12T08:07:38

 => Reg token expiry 2024-06-12T08:07:39

Explain your code

I build a bot on Skype to handle user messages. Bot will send message to group and user quote a reply to perform some action after perform success I remove the bot message.

In this code, I ran loop to pull new messages and It's work fine until 3 or 4 day later it will throw an error and my loop stopped. When the loop stop I need to restart server for it to work again.

SkPy version

0.10.7

Python version

3.11.7

Anything else?

No response

Terrance commented 5 months ago

I'd guess this is the problem:

<= [11/06 08:07:43] POST https://azwus1-client-s.gateway.messenger.live.com/v1/users/ME/endpoints
{'headers': {'Authentication': 'skypetoken=***',
             'BehaviorOverride': 'redirectAs404',
             'LockAndKey': 'appId=msmsgs@msnmsgr.com; time=1718093263; '
                           'lockAndKeyResponse=e9a72ea6428574f6a0c38e365dc3d061'},
 'json': {'endpointFeatures': 'Agent'}}
timed out

I assume timed out is coming from your print(e)? (NB. import traceback; traceback.print_exception(e) would be more useful, in order to capture the exception type as well as the actual traceback.)

It looks like SkPy is correctly trying to recreate its endpoint, needs to switch domain (to azwus1), but the create request there failed due to a network timeout. Does this happen consistency at that step?

un-hongly commented 5 months ago

Yes ,timed out is from my print(e). I will add import traceback; traceback.print_exception(e) to my code.

I believe timed out is from httpx.post(self.message_endpoint, json=data). When new event come I forward the message to another server for handling the message. I think when user send a a large size file I also upload it to file server and I think it might take longer than 5 seconds that can cause httpx.post() to timeout.

During my httpx.post() wait time will it interrupted your create request and cause network timeout? Sorry I'm just a python beginner.

un-hongly commented 5 months ago

Today it happened again and the error message is ('Connection aborted.', RemoteDisconnected('Remote end closed connection without response'))

Terrance commented 5 months ago

During my httpx.post() wait time will it interrupted your create request and cause network timeout?

It seems to have been interrupted somehow, as there's no response (section beginning <=) logged for the request before that timeout, possibly due to the use of threading. Are you creating other threads not shown in the code above?

the error message is ('Connection aborted.', RemoteDisconnected('Remote end closed connection without response'))

Traceback?

It would be useful to have a clean run of this without interference from httpx or whatever else -- remove your onEvent logic and see if the token renewal still fails when just listening for events. I'd also like to know exactly how long it takes to fall over (tokens typically last 24 hours so I'd expect it to be roughly a whole number of days if it is down to that).

un-hongly commented 5 months ago

Are you creating other threads not shown in the code above? => There is only one thread that run the loop that I've shown above.

It would be useful to have a clean run of this without interference from httpx or whatever else -- remove your onEvent logic and see if the token renewal still fails when just listening for events. => I have a test environment running as well but the problem never happen as no one use it everyday like the production one.

By those I assume that the problem is came from my event handler. I think due to synchronous execution cause process to hang by waiting my httpx.post() to finish.

Terrance commented 5 months ago

I'm still not entirely clear how it would break in the place it appears to, but if you're spending time in the event handler doing slow uploads then it may well be that Skype is invalidating your endpoint because you haven't listened for events in a while.

I'd suggest moving anything slow into its own thread or separate worker process etc. so that you can immediately resume listening for more Skype events (you're currently joining to a single thread which is doing nothing useful).

Seeing as it doesn't happen on a clean event loop (I also set my own no-op test going and that appears to be working), I am to assume the event loop handling is working as intended. If you can trigger it without external factors, please post an updated code sample and logs.

Terrance / SkPy