Skip to content
This repository has been archived by the owner on Mar 2, 2024. It is now read-only.

Messages fail to send to facebook after prolonged bridge uptime #26

Closed
kliu128 opened this issue Jun 9, 2019 · 5 comments
Closed

Messages fail to send to facebook after prolonged bridge uptime #26

kliu128 opened this issue Jun 9, 2019 · 5 comments
Labels
bug Something isn't working

Comments

@kliu128
Copy link

kliu128 commented Jun 9, 2019

After a prolonged amount of uptime (few days), I get this error when trying to send messages:

[2019-06-09 20:34:59,178] [ERROR@mau.as] Exception in Matrix event handler                                                     
Traceback (most recent call last):                                                                                             
  File "/usr/lib/python3.6/site-packages/fbchat/_client.py", line 190, in _post                                                
    return await check_request(r, as_json=as_json, log=self._util_log)                                                         
  File "/usr/lib/python3.6/site-packages/fbchat/_util.py", line 210, in check_request                                          
    check_json(j)                                                                                                              
  File "/usr/lib/python3.6/site-packages/fbchat/_util.py", line 175, in check_json                                             
    fb_error_message=j["errorDescription"],                                                                                    
fbchat._exception.FBchatFacebookError: Error #1357004 when sending request: Please try closing and re-opening your browser window.                                                                                                                            
                                                                                                                               
During handling of the above exception, another exception occurred:                                                            
                                                                                                                               
Traceback (most recent call last):                                                                                             
  File "/usr/lib/python3.6/site-packages/fbchat/_client.py", line 190, in _post                                                
    return await check_request(r, as_json=as_json, log=self._util_log)                                                         
  File "/usr/lib/python3.6/site-packages/fbchat/_util.py", line 210, in check_request                                          
    check_json(j)                                                                                                              
  File "/usr/lib/python3.6/site-packages/fbchat/_util.py", line 175, in check_json                                             
    fb_error_message=j["errorDescription"],                                                                                    
fbchat._exception.FBchatFacebookError: Error #1357004 when sending request: Please try closing and re-opening your browser window.                                                                                                                            
                                                                                                                               
During handling of the above exception, another exception occurred:                                                            
                                                                                                                               
Traceback (most recent call last):                                                                                             
  File "/usr/lib/python3.6/site-packages/fbchat/_client.py", line 190, in _post                                                
    return await check_request(r, as_json=as_json, log=self._util_log)                                                         
  File "/usr/lib/python3.6/site-packages/fbchat/_util.py", line 210, in check_request                                          
    check_json(j)                                                                                                              
  File "/usr/lib/python3.6/site-packages/fbchat/_util.py", line 175, in check_json                                             
    fb_error_message=j["errorDescription"],                                                                                    
fbchat._exception.FBchatFacebookError: Error #1357004 when sending request: Please try closing and re-opening your browser window.

During handling of the above exception, another exception occurred:                                                            

Traceback (most recent call last):
  File "/usr/lib/python3.6/site-packages/mautrix/appservice/appservice.py", line 208, in try_handle
    await handler_func(event)
  File "/usr/lib/python3.6/site-packages/mautrix/bridge/matrix.py", line 230, in int_handle_event
    await self.handle_message(evt.room_id, evt.sender, evt.content, evt.event_id)
  File "/usr/lib/python3.6/site-packages/mautrix/bridge/matrix.py", line 166, in handle_message
    await portal.handle_matrix_message(sender, message, event_id)
  File "/opt/mautrix-facebook/mautrix_facebook/portal.py", line 346, in handle_matrix_message
    fbid = await self._handle_matrix_text(sender, message)
  File "/opt/mautrix-facebook/mautrix_facebook/portal.py", line 363, in _handle_matrix_text
    return await sender.send(FBMessage(text=message.body), self.fbid, self.fb_type)
  File "/usr/lib/python3.6/site-packages/fbchat/_client.py", line 1374, in send
    return await self._doSendRequest(data)
  File "/usr/lib/python3.6/site-packages/fbchat/_client.py", line 1333, in _doSendRequest
    j = await self._post(self.req_url.SEND, data, fix_request=True, as_json=True)
  File "/usr/lib/python3.6/site-packages/fbchat/_client.py", line 200, in _post
    error_retries=error_retries - 1,
  File "/usr/lib/python3.6/site-packages/fbchat/_client.py", line 200, in _post
    error_retries=error_retries - 1,
  File "/usr/lib/python3.6/site-packages/fbchat/_client.py", line 200, in _post
    error_retries=error_retries - 1,
  File "/usr/lib/python3.6/site-packages/fbchat/_client.py", line 190, in _post
    return await check_request(r, as_json=as_json, log=self._util_log)
  File "/usr/lib/python3.6/site-packages/fbchat/_util.py", line 210, in check_request
    check_json(j)
  File "/usr/lib/python3.6/site-packages/fbchat/_util.py", line 175, in check_json
    fb_error_message=j["errorDescription"],

This reminds me of Schmavery/facebook-chat-api#555 which is also experienced by matrix-puppet-facebook. The only solution they found was to create a supervisor script that restarts the bridge every ~8 hours.
@kliu128
Copy link
Author

kliu128 commented Jun 9, 2019

Whoops, looks like this actually uses a different Facebook library - fbchat. The only trace I found there was fbchat-dev/fbchat#175.

@Berulacks
Copy link

I have the exact same problem, as well. That issue you linked to mentions that it could be caused by not sending any message at all for 3 days. Maybe an option to regularly re-login to FB?

@spantaleev
Copy link

I've had the same happen to me today. I've started (well, continued / bumped) a chat from Facebook, expecting a portal room to be created for it on the Matrix side.

This happened:

Jun 10 06:57:18 matrix-mautrix-facebook[22496]: [2019-06-10 04:57:18,408] [DEBUG@fbchat.util.@user:DOMAIN] {'t': 'msg', 'seq': 98, 'u': 555555555555, 'ms': [{'ofd_ts': 1560142638362, 'delta': {'attachments': [], 'body': 'message text here', 'irisSeqId': '1495682', 'irisTags': [], 'messageMetadata': {'actorFbId': '395264435', 'folderId': {'systemFolderId': 'INBOX'}, 'messageId': 'mid.$cAABa8xugEbpxcQS02lrP79rtZlTA', 'offlineThreadingId': '6543712507126433384', 'skipSnippetUpdate': False, 'tags': ['source:messenger:web'], 'threadKey': {'otherUserFbId': '100000444444444'}, 'threadReadStateEffect': 'KEEP_AS_IS', 'timestamp': '1560142638298'}, 'requestContext': {'apiArgs': {}}, 'class': 'NewMessage'}, 'type': 'delta', 'iseq': 1495682, 'queue': 555555555555}]}
Jun 10 06:57:18 matrix-mautrix-facebook[22496]: [2019-06-10 04:57:18,408] [DEBUG@fbchat.request.@user:DOMAIN] GET https://0-edge-chat.facebook.com/pull?__rev=1000801002&__user=555555555555&__a=1&ttstamp=658171511157686112658185735865816995681111001031098987662&fb_dtsg=BQG4sLVpAQUI:BQC_DodgmUWB&msgs_recv=0&sticky_token=1326&sticky_pool=ratn0c01_chatproxy-regional&clientid=288ea5d4&state=offline&__req=782&seq=98
Jun 10 06:57:18 matrix-mautrix-facebook[22496]: [2019-06-10 04:57:18,412] [DEBUG@mau.user.@user:DOMAIN] onMessage(Message(text='message text here?', mentions=[], emoji_size=None, uid='mid.$cAABa8xugEbpxcQS02lrP79rtZlTA', author='555555555555', timestamp=1560142638298, is_read=None, read_by=[], reactions={}, sticker=None, attachments=[], quick_replies=[], unsent=False, reply_to_id=None, replied_to=None, forwarded=False), 100000677534703, ThreadType.USER)
Jun 10 06:57:18 matrix-mautrix-facebook[22496]: [2019-06-10 04:57:18,445] [DEBUG@fbchat.request.@user:DOMAIN] POST https://www.facebook.com/api/graphqlbatch/ {'__rev': 1000801002, '__user': '555555555555', '__a': '1', 'ttstamp': '658171511157686112658185735865816995681111001031098987662', 'fb_dtsg': 'BQG4sLVpAQUI:BQC_DodgmUWB', 'method': 'GET', 'response_format': 'json', 'queries': '{"q0": {"doc_id": "2147762685294928", "query_params": {"id": "100000677534703", "message_limit": 0, "load_messages": false, "load_read_receipts": false, "before": null}}}', '__req': '783', 'seq': 98}
Jun 10 06:57:18 matrix-mautrix-facebook[22496]: [2019-06-10 04:57:18,520] [WARNING@fbchat.client.@ user:DOMAIN] Got error #1357004. Doing a _postLogin, and resending request
Jun 10 06:57:18 matrix-mautrix-facebook[22496]: /usr/lib/python3.6/site-packages/fbchat/_client.py:125: RuntimeWarning: coroutine 'Client._postLogin' was never awaited
Jun 10 06:57:18 matrix-mautrix-facebook[22496]: self._postLogin()
Jun 10 06:57:18 matrix-mautrix-facebook[22496]: [2019-06-10 04:57:18,619] [DEBUG@fbchat.request.@user:DOMAIN] POST https://www.facebook.com/api/graphqlbatch/ {'__rev': 1000402010, '__user': '555555555555', '__a': '1', 'ttstamp': '658171511157686112658185735865816995681111001031098987662', 'fb_dtsg': 'BQG4sLVpAQUI:BQC_DodgmUWB', 'method': 'GET', 'response_format': 'json', 'queries': '{"q0": {"doc_id": "4142761685294928", "query_params": {"id": "111111111111111", "message_limit": 0, "load_messages": false, "load_read_receipts": false, "before": null}}}', '__req': '786', 'seq': 98}
Jun 10 06:57:18 matrix-mautrix-facebook[22496]: [2019-06-10 04:57:18,691] [ERROR@mau.portal.111111111111111<->555555555555] Failed to create portal
Jun 10 06:57:18 matrix-mautrix-facebook[22496]: Traceback (most recent call last):
Jun 10 06:57:18 matrix-mautrix-facebook[22496]: File "/usr/lib/python3.6/site-packages/fbchat/_client.py", line 188, in _post
Jun 10 06:57:18 matrix-mautrix-facebook[22496]: return graphql_response_to_json(content, log=self._util_log)
Jun 10 06:57:18 matrix-mautrix-facebook[22496]: File "/usr/lib/python3.6/site-packages/fbchat/_graphql.py", line 52, in graphql_response_to_json
Jun 10 06:57:18 matrix-mautrix-facebook[22496]: _util.check_json(x)
Jun 10 06:57:18 matrix-mautrix-facebook[22496]: File "/usr/lib/python3.6/site-packages/fbchat/_util.py", line 175, in check_json
Jun 10 06:57:18 matrix-mautrix-facebook[22496]: fb_error_message=j["errorDescription"],
Jun 10 06:57:18 matrix-mautrix-facebook[22496]: fbchat._exception.FBchatFacebookError: Error #1357004 when sending request: Please try closing and re-opening your browser window.
Jun 10 06:57:18 matrix-mautrix-facebook[22496]: During handling of the above exception, another exception occurred:
Jun 10 06:57:18 matrix-mautrix-facebook[22496]: Traceback (most recent call last):
Jun 10 06:57:18 matrix-mautrix-facebook[22496]: File "/usr/lib/python3.6/site-packages/fbchat/_client.py", line 188, in _post
Jun 10 06:57:18 matrix-mautrix-facebook[22496]: return graphql_response_to_json(content, log=self._util_log)
Jun 10 06:57:18 matrix-mautrix-facebook[22496]: File "/usr/lib/python3.6/site-packages/fbchat/_graphql.py", line 52, in graphql_response_to_json
Jun 10 06:57:18 matrix-mautrix-facebook[22496]: _util.check_json(x)
Jun 10 06:57:18 matrix-mautrix-facebook[22496]: File "/usr/lib/python3.6/site-packages/fbchat/_util.py", line 175, in check_json
Jun 10 06:57:18 matrix-mautrix-facebook[22496]: fb_error_message=j["errorDescription"],
Jun 10 06:57:18 matrix-mautrix-facebook[22496]: fbchat._exception.FBchatFacebookError: Error #1357004 when sending request: Please try closing and re-opening your browser window.
Jun 10 06:57:18 matrix-mautrix-facebook[22496]: During handling of the above exception, another exception occurred:
Jun 10 06:57:18 matrix-mautrix-facebook[22496]: Traceback (most recent call last):
Jun 10 06:57:18 matrix-mautrix-facebook[22496]: File "/usr/lib/python3.6/site-packages/fbchat/_client.py", line 188, in _post
Jun 10 06:57:18 matrix-mautrix-facebook[22496]: return graphql_response_to_json(content, log=self._util_log)
Jun 10 06:57:18 matrix-mautrix-facebook[22496]: File "/usr/lib/python3.6/site-packages/fbchat/_graphql.py", line 52, in graphql_response_to_json
Jun 10 06:57:18 matrix-mautrix-facebook[22496]: _util.check_json(x)
Jun 10 06:57:18 matrix-mautrix-facebook[22496]: File "/usr/lib/python3.6/site-packages/fbchat/_util.py", line 175, in check_json
Jun 10 06:57:18 matrix-mautrix-facebook[22496]: fb_error_message=j["errorDescription"],
Jun 10 06:57:18 matrix-mautrix-facebook[22496]: fbchat._exception.FBchatFacebookError: Error #1357004 when sending request: Please try closing and re-opening your browser window.
Jun 10 06:57:18 matrix-mautrix-facebook[22496]: During handling of the above exception, another exception occurred:
Jun 10 06:57:18 matrix-mautrix-facebook[22496]: Traceback (most recent call last):
Jun 10 06:57:18 matrix-mautrix-facebook[22496]: File "/opt/mautrix-facebook/mautrix_facebook/portal.py", line 250, in create_matrix_room
Jun 10 06:57:18 matrix-mautrix-facebook[22496]: return await self._create_matrix_room(source, info)
Jun 10 06:57:18 matrix-mautrix-facebook[22496]: File "/opt/mautrix-facebook/mautrix_facebook/portal.py", line 261, in _create_matrix_room
Jun 10 06:57:18 matrix-mautrix-facebook[22496]: info = await self.update_info(source=source, info=info)
Jun 10 06:57:18 matrix-mautrix-facebook[22496]: File "/opt/mautrix-facebook/mautrix_facebook/portal.py", line 169, in update_info
Jun 10 06:57:18 matrix-mautrix-facebook[22496]: info = (await source.fetchThreadInfo(self.fbid))[self.fbid]
Jun 10 06:57:18 matrix-mautrix-facebook[22496]: File "/usr/lib/python3.6/site-packages/fbchat/_client.py", line 979, in fetchThreadInfo
Jun 10 06:57:18 matrix-mautrix-facebook[22496]: j = await self.graphql_requests(*queries)
Jun 10 06:57:18 matrix-mautrix-facebook[22496]: File "/usr/lib/python3.6/site-packages/fbchat/_client.py", line 287, in graphql_requests
Jun 10 06:57:18 matrix-mautrix-facebook[22496]: await self._post(self.req_url.GRAPHQL, data, fix_request=True, as_graphql=True)
Jun 10 06:57:18 matrix-mautrix-facebook[22496]: File "/usr/lib/python3.6/site-packages/fbchat/_client.py", line 200, in _post
Jun 10 06:57:18 matrix-mautrix-facebook[22496]: error_retries=error_retries - 1,
Jun 10 06:57:18 matrix-mautrix-facebook[22496]: File "/usr/lib/python3.6/site-packages/fbchat/_client.py", line 200, in _post
Jun 10 06:57:18 matrix-mautrix-facebook[22496]: error_retries=error_retries - 1,
Jun 10 06:57:18 matrix-mautrix-facebook[22496]: File "/usr/lib/python3.6/site-packages/fbchat/_client.py", line 200, in _post
Jun 10 06:57:18 matrix-mautrix-facebook[22496]: error_retries=error_retries - 1,
Jun 10 06:57:18 matrix-mautrix-facebook[22496]: File "/usr/lib/python3.6/site-packages/fbchat/_client.py", line 188, in _post
Jun 10 06:57:18 matrix-mautrix-facebook[22496]: return graphql_response_to_json(content, log=self._util_log)
Jun 10 06:57:18 matrix-mautrix-facebook[22496]: File "/usr/lib/python3.6/site-packages/fbchat/_graphql.py", line 52, in graphql_response_to_json
Jun 10 06:57:18 matrix-mautrix-facebook[22496]: _util.check_json(x)
Jun 10 06:57:18 matrix-mautrix-facebook[22496]: File "/usr/lib/python3.6/site-packages/fbchat/_util.py", line 175, in check_json
Jun 10 06:57:18 matrix-mautrix-facebook[22496]: fb_error_message=j["errorDescription"],
Jun 10 06:57:18 matrix-mautrix-facebook[22496]: fbchat._exception.FBchatFacebookError: Error #1357004 when sending request: Please try closing and re-opening your browser window.

Previously (before doing anything active), only this kind of messages were logged:

Jun 10 06:56:12 matrix-mautrix-facebook[22496]: [2019-06-10 04:56:12,057] [DEBUG@fbchat.util.@user:DOMAIN] {'t': 'heartbeat'}
Jun 10 06:56:12 matrix-mautrix-facebook[22496]: [2019-06-10 04:56:12,057] [DEBUG@fbchat.request.@user:DOMAIN] GET https://0-edge-chat.facebook.com/pull?__rev=1000801002&__user=595364437&__a=1&ttstamp=658171511157686112658185735865816995681111001031098987662&fb_dtsg=BQG4sLVpAQUI:BQC_DodgmUWB&msgs_recv=0&sticky_token=2236&sticky_pool=ratn0c01_chatproxy-regional&clientid=388bc9d3&state=offline&__req=77y&seq=0
Jun 10 06:56:12 matrix-mautrix-facebook[22496]: [2019-06-10 04:56:12,166] [DEBUG@fbchat.util.@user:DOMAIN] {'t': 'fullReload', 'seq': 97}
Jun 10 06:56:12 matrix-mautrix-facebook[22496]: [2019-06-10 04:56:12,167] [DEBUG@fbchat.request.@user:DOMAIN] GET https://0-edge-chat.facebook.com/pull?__rev=1000801002&__user=595364437&__a=1&ttstamp=658171511157686112658185735865816995681111001031098987662&fb_dtsg=BQG4sLVpAQUI:BQC_DodgmUWB&msgs_recv=0&sticky_token=2236&sticky_pool=ratn0c01_chatproxy-regional&clientid=388bc9d3&state=offline&__req=77z&seq=97
Jun 10 06:57:02 matrix-mautrix-facebook[22496]: [2019-06-10 04:57:02,278] [DEBUG@fbchat.util.@user:DOMAIN] {'t': 'heartbeat'}
Jun 10 06:57:02 matrix-mautrix-facebook[22496]: [2019-06-10 04:57:02,279] [DEBUG@fbchat.request.@user:DOMAIN] GET https://0-edge-chat.facebook.com/pull?__rev=1000801002&__user=595364437&__a=1&ttstamp=658171511157686112658185735865816995681111001031098987662&fb_dtsg=BQG4sLVpAQUI:BQC_DodgmUWB&msgs_recv=0&sticky_token=2236&sticky_pool=ratn0c01_chatproxy-regional&clientid=388bc9d3&state=offline&__req=780&seq=0
Jun 10 06:57:02 matrix-mautrix-facebook[22496]: [2019-06-10 04:57:02,390] [DEBUG@fbchat.util.@user:DOMAIN] {'t': 'fullReload', 'seq': 97}
Jun 10 06:57:02 matrix-mautrix-facebook[22496]: [2019-06-10 04:57:02,391] [DEBUG@fbchat.request.@user:DOMAIN] GET https://0-edge-chat.facebook.com/pull?__rev=1000801002&__user=595364437&__a=1&ttstamp=658171511157686112658185735865816995681111001031098987662&fb_dtsg=BQG4sLVpAQUI:BQC_DodgmUWB&msgs_recv=0&sticky_token=2236&sticky_pool=ratn0c01_chatproxy-regional&clientid=388bc9d3&state=offline&__req=781&seq=97

I worked around it by restarting the bridge. It caught up and appears to continue to work okay.

Perhaps the bridge can detect this problem and schedule its own "clean reconnection" or should we take this over to the fbchat side and have it handled there?

@tulir tulir mentioned this issue Jun 10, 2019
Open
@tulir tulir added the bug Something isn't working label Jun 10, 2019
@tulir tulir closed this as completed in 547f00c Jun 10, 2019
@ghost
Copy link

ghost commented Jul 10, 2020

Please re-open this. It is not solved with 547f00c on Jun 10,2019. All that did was bump a library version, however the issue persists today .

@tulir
Copy link
Member

tulir commented Jul 10, 2020

This specific error doesn't even exist anymore and the new version of the error (fbchat.PleaseRefresh) should be handled correctly. Open a new issue with a new stack trace if sending messages throws errors.

(also, bumping a library version is often enough to fix bugs)

Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees
No one assigned
Labels
bug Something isn't working
Milestone
No milestone
Development

No branches or pull requests
4 participants
@spantaleev @tulir @Berulacks @kliu128