Open coreyjansen opened 4 years ago
I haven't tried yet but would I be able to manually implement the changes from the following commit https://github.com/carpedm20/fbchat/commit/0d139cee734cc9b7378c36c2a4131d5b43257a06
The commit you referenced don't have anything to do with this issue š.
But I can't diagnose your issue further yet, I need to get some more information! Does it happen every time you start the script, or once in a while? Can you try reducing the amount of code needed to reproduce the issue? And can you try adding the following at the top of your code to enable debug logging, and then give me the output?
import logging
logging.basicConfig(level=logging.DEBUG)
Thanks for the quick answer.
Had it happen again: I took two screenshots https://imgur.com/a/zYtKnFD
It actually looked like it was hung up before the reconnect line, I maximized the window and then it resumed briefly and when it stopped again is where I took the first screenshot. The second screenshot is what it showed after I clicked Ctrl+C
First Hang
DEBUG:paho.mqtt.client:Received PINGRESP
DEBUG:paho.mqtt.client:Sending PINGREQ
DEBUG:paho.mqtt.client:Received PINGRESP
DEBUG:paho.mqtt.client:Received PUBLISH (d0, q0, r1, m0), '/orca_presence', ... (187 bytes)
DEBUG:client:MQTT payload: /orca_presence, {'list_type': 'inc', 'list': [{'u': 100019908758517, 'p': 2, 'l': 1579906933, 'c': 546842634}, {'u': 535205247, 'p': 2, 'l': 1579906928, 'c': 542638154}, {'u': 520557117, 'p': 0, 'l': 1579905945, 'c': 551026778}]}
DEBUG:client:Chat Timestamps received: {'100019908758517': ActiveStatus(active=True, last_active=1579906933, in_game=None), '535205247': ActiveStatus(active=True, last_active=1579906928, in_game=None), '520557117': ActiveStatus(active=False, last_active=1579905945, in_game=None)}
DEBUG:paho.mqtt.client:Sending PINGREQ
DEBUG:paho.mqtt.client:Received PINGRESP
DEBUG:paho.mqtt.client:Sending PINGREQ
DEBUG:paho.mqtt.client:Received PINGRESP
DEBUG:paho.mqtt.client:Sending PINGREQ
DEBUG:paho.mqtt.client:Received PINGRESP
DEBUG:paho.mqtt.client:Sending PINGREQ
DEBUG:paho.mqtt.client:Received PINGRESP
DEBUG:paho.mqtt.client:Sending PINGREQ
DEBUG:paho.mqtt.client:Received PINGRESP
DEBUG:paho.mqtt.client:Sending PINGREQ
DEBUG:paho.mqtt.client:Received PINGRESP
DEBUG:paho.mqtt.client:Sending PINGREQ
DEBUG:paho.mqtt.client:Received PINGRESP
DEBUG:paho.mqtt.client:Sending PINGREQ
Connection lost, retrying
WARNING:client:Connection lost, retrying
DEBUG:paho.mqtt.client:Sending CONNECT (u1, p0, wr0, wq0, wf0, c1, k10) client_id=b'mqttwsclient'
DEBUG:paho.mqtt.client:Received CONNACK (0, 0)
DEBUG:paho.mqtt.client:Sending PUBLISH (d0, q1, r0, m4), 'b'/messenger_sync_get_diffs'', ... (168 bytes)
DEBUG:paho.mqtt.client:Received PUBACK (Mid: 4)
DEBUG:paho.mqtt.client:Received PUBLISH (d0, q0, r1, m0), '/orca_presence', ... (494 bytes)
DEBUG:client:MQTT payload: /orca_presence, {'list_type': 'full', 'list': [{'u': 1602473570, 'p': 2, 'l': 1579907064, 'c': 9969680}, {'u': 100019908758517, 'p': 2, 'l': 1579907064, 'vc': 10, 'c': 546842634}, {'u': 515131692, 'p': 2, 'l': 1579906986, 'vc': 74, 'c': 551026778}, {'u': 752500082, 'p': 2, 'l': 1579907064, 'vc': 10, 'c': 546842650}, {'u': 535205247, 'p': 2, 'l': 1579907014, 'vc': 74, 'c': 551026762}, {'u': 520557117, 'p': 0, 'l': 1579905945, 'vc': 74, 'c': 551026778}, {'u': 100003575547440, 'p': 0, 'l': 1579895850, 'vc': 74, 'c': 551026778}, {'u': 548925547, 'p': 0, 'l': 1579904794, 'c': 9961488}]}
DEBUG:client:Chat Timestamps received: {'1602473570': ActiveStatus(active=True, last_active=1579907064, in_game=None), '100019908758517': ActiveStatus(active=True, last_active=1579907064, in_game=None), '515131692': ActiveStatus(active=True, last_active=1579906986, in_game=None), '752500082': ActiveStatus(active=True, last_active=1579907064, in_game=None), '535205247': ActiveStatus(active=True, last_active=1579907014, in_game=None), '520557117': ActiveStatus(active=False, last_active=1579905945, in_game=None), '100003575547440': ActiveStatus(active=False, last_active=1579895850, in_game=None), '548925547': ActiveStatus(active=False, last_active=1579904794, in_game=None)}
Second Hang:
DEBUG:paho.mqtt.client:Received PINGRESP
DEBUG:paho.mqtt.client:Sending PINGREQ
DEBUG:paho.mqtt.client:Received PINGRESP
DEBUG:paho.mqtt.client:Sending PINGREQ
DEBUG:paho.mqtt.client:Received PINGRESP
DEBUG:paho.mqtt.client:Sending PINGREQ
Connection lost, retrying
WARNING:client:Connection lost, retrying
DEBUG:paho.mqtt.client:Sending CONNECT (u1, p0, wr0, wq0, wf0, c1, k10) client_id=b'mqttwsclient'
DEBUG:paho.mqtt.client:Received CONNACK (0, 0)
DEBUG:paho.mqtt.client:Sending PUBLISH (d0, q1, r0, m4), 'b'/messenger_sync_get_diffs'', ... (168 bytes)
DEBUG:paho.mqtt.client:Received PUBACK (Mid: 4)
DEBUG:paho.mqtt.client:Received PUBLISH (d0, q0, r1, m0), '/orca_presence', ... (494 bytes)
DEBUG:client:MQTT payload: /orca_presence, {'list_type': 'full', 'list': [{'u': 1602473570, 'p': 2, 'l': 1579907064, 'c': 9969680}, {'u': 100019908758517, 'p': 2, 'l': 1579907064, 'vc': 10, 'c': 546842634}, {'u': 515131692, 'p': 2, 'l': 1579906986, 'vc': 74, 'c': 551026778}, {'u': 752500082, 'p': 2, 'l': 1579907064, 'vc': 10, 'c': 546842650}, {'u': 535205247, 'p': 2, 'l': 1579907014, 'vc': 74, 'c': 551026762}, {'u': 520557117, 'p': 0, 'l': 1579905945, 'vc': 74, 'c': 551026778}, {'u': 100003575547440, 'p': 0, 'l': 1579895850, 'vc': 74, 'c': 551026778}, {'u': 548925547, 'p': 0, 'l': 1579904794, 'c': 9961488}]}
DEBUG:client:Chat Timestamps received: {'1602473570': ActiveStatus(active=True, last_active=1579907064, in_game=None), '100019908758517': ActiveStatus(active=True, last_active=1579907064, in_game=None), '515131692': ActiveStatus(active=True, last_active=1579906986, in_game=None), '752500082': ActiveStatus(active=True, last_active=1579907064, in_game=None), '535205247': ActiveStatus(active=True, last_active=1579907014, in_game=None), '520557117': ActiveStatus(active=False, last_active=1579905945, in_game=None), '100003575547440': ActiveStatus(active=False, last_active=1579895850, in_game=None), '548925547': ActiveStatus(active=False, last_active=1579904794, in_game=None)}
DEBUG:paho.mqtt.client:Received PUBLISH (d0, q1, r1, m6321), '/t_ms', ... (672 bytes)
DEBUG:paho.mqtt.client:Sending PUBACK (Mid: 6321)
DEBUG:client:MQTT payload: /t_ms, {'deltas': [{'attachments': [], 'body': 'I ed', 'irisSeqId': '2525', 'irisTags': ['DeltaNewMessage', 'is_from_iris_fanout'], 'messageMetadata': {'actorFbId': '752500082', 'folderId': {'systemFolderId': 'INBOX'}, 'messageId': 'mid.$gAAuK9uL6H6Z2CxINrlv2cyFmJtSb', 'offlineThreadingId': '6626610489007199387', 'skipBumpThread': False, 'tags': ['source:chat:orca', 'app_id:256002347743983'], 'threadKey': {'threadFbId': '3249017718448038'}, 'threadReadStateEffect': 'MARK_UNREAD', 'timestamp': '1579907073454'}, 'participants': ['752500082', '100046287759200'], 'requestContext': {'apiArgs': {}}, 'tqSeqId': '65', 'class': 'NewMessage'}], 'firstDeltaSeqId': 2525, 'lastIssuedSeqId': 2525, 'queueEntityId': 100046287759200}
DEBUG:urllib3.connectionpool:Resetting dropped connection: www.facebook.com
DEBUG:urllib3.connectionpool:https://www.facebook.com:443 "POST /ajax/mercury/delivery_receipts.php HTTP/1.1" 200 None
DEBUG:client:{'__ar': 1, 'payload': [], 'bootloadable': {}, 'ixData': {}, 'bxData': {}, 'gkxData': {}, 'qexData': {}, 'lid': '6785649313326547392'}
DEBUG:urllib3.connectionpool:https://www.facebook.com:443 "POST /ajax/mercury/change_read_status.php HTTP/1.1" 200 None
DEBUG:client:{'__ar': 1, 'payload': {'payload_source': 'server_change_read_status'}, 'bootloadable': {}, 'ixData': {}, 'bxData': {}, 'gkxData': {}, 'qexData': {}, 'lid': '6785649312600880157'}
DEBUG:paho.mqtt.client:Received PUBLISH (d0, q0, r1, m0), '/thread_typing', ... (76 bytes)
DEBUG:client:MQTT payload: /thread_typing, {'sender_fbid': 752500082, 'state': 1, 'type': 'typ', 'thread': '3249017718448038'}
DEBUG:paho.mqtt.client:Received PUBLISH (d0, q1, r1, m6323), '/t_ms', ... (669 bytes)
DEBUG:paho.mqtt.client:Sending PUBACK (Mid: 6323)
DEBUG:client:MQTT payload: /t_ms, {'deltas': [{'attachments': [], 'body': 'F', 'irisSeqId': '2526', 'irisTags': ['DeltaNewMessage', 'is_from_iris_fanout'], 'messageMetadata': {'actorFbId': '752500082', 'folderId': {'systemFolderId': 'INBOX'}, 'messageId': 'mid.$gAAuK9uL6H6Z2CxIq5Fv2cziO0yuB', 'offlineThreadingId': '6626610588473830273', 'skipBumpThread': False, 'tags': ['source:chat:orca', 'app_id:256002347743983'], 'threadKey': {'threadFbId': '3249017718448038'}, 'threadReadStateEffect': 'MARK_UNREAD', 'timestamp': '1579907080932'}, 'participants': ['752500082', '100046287759200'], 'requestContext': {'apiArgs': {}}, 'tqSeqId': '66', 'class': 'NewMessage'}], 'firstDeltaSeqId': 2526, 'lastIssuedSeqId': 2526, 'queueEntityId': 100046287759200}
DEBUG:urllib3.connectionpool:https://www.facebook.com:443 "POST /ajax/mercury/delivery_receipts.php HTTP/1.1" 200 None
DEBUG:client:{'__ar': 1, 'payload': [], 'bootloadable': {}, 'ixData': {}, 'bxData': {}, 'gkxData': {}, 'qexData': {}, 'lid': '6785649318076763421'}
DEBUG:urllib3.connectionpool:https://www.facebook.com:443 "POST /ajax/mercury/change_read_status.php HTTP/1.1" 200 None
DEBUG:client:{'__ar': 1, 'payload': {'payload_source': 'server_change_read_status'}, 'bootloadable': {}, 'ixData': {}, 'bxData': {}, 'gkxData': {}, 'qexData': {}, 'lid': '6785649317010685228'}
DEBUG:paho.mqtt.client:Received PUBLISH (d0, q0, r1, m0), '/thread_typing', ... (76 bytes)
DEBUG:client:MQTT payload: /thread_typing, {'sender_fbid': 752500082, 'state': 0, 'type': 'typ', 'thread': '3249017718448038'}
DEBUG:paho.mqtt.client:Received PUBLISH (d0, q0, r1, m0), '/t_ms', ... (316 bytes)
DEBUG:client:MQTT payload: /t_ms, {'deltas': [{'actionTimestamp': '1579907097979', 'irisSeqId': '2527', 'irisTags': ['DeltaMarkRead', 'is_from_iris_fanout'], 'threadKeys': [{'threadFbId': '3249017718448038'}], 'tqSeqId': '67', 'watermarkTimestamp': '1579907096079', 'class': 'MarkRead'}], 'firstDeltaSeqId': 2527, 'lastIssuedSeqId': 2527, 'queueEntityId': 100046287759200}
Marked messages as seen in threads [('3249017718448038', 'GROUP')] at 1579907097.979s
INFO:client:Marked messages as seen in threads [('3249017718448038', 'GROUP')] at 1579907097.979s
DEBUG:paho.mqtt.client:Received PUBLISH (d0, q0, r1, m0), '/t_ms', ... (316 bytes)
DEBUG:client:MQTT payload: /t_ms, {'deltas': [{'actionTimestamp': '1579907098106', 'irisSeqId': '2528', 'irisTags': ['DeltaMarkRead', 'is_from_iris_fanout'], 'threadKeys': [{'threadFbId': '3249017718448038'}], 'tqSeqId': '68', 'watermarkTimestamp': '1579907096204', 'class': 'MarkRead'}], 'firstDeltaSeqId': 2528, 'lastIssuedSeqId': 2528, 'queueEntityId': 100046287759200}
Marked messages as seen in threads [('3249017718448038', 'GROUP')] at 1579907098.106s
INFO:client:Marked messages as seen in threads [('3249017718448038', 'GROUP')] at 1579907098.106s
DEBUG:paho.mqtt.client:Sending PINGREQ
DEBUG:paho.mqtt.client:Received PINGRESP
DEBUG:paho.mqtt.client:Sending PINGREQ
DEBUG:paho.mqtt.client:Received PINGRESP
DEBUG:paho.mqtt.client:Sending PINGREQ
DEBUG:paho.mqtt.client:Received PINGRESP
Huh... I don't really have an idea what the problem could be here!
A few very vague guesses:
hasMessagedThread
/logThread
might somehow be blocking on the file? Could you try using a simple list instead?paho.mqtt.python
, but if it is, I really don't know where to look... šMqtt._messenger_queue_publish
in /fbchat/_mqtt.py
as follows:
@@ -150,8 +150,8 @@ class Mqtt(object):
# configure receiving messages.
payload = {
"sync_api_version": 10,
- "max_deltas_able_to_process": 1000,
- "delta_batch_size": 500,
+ "max_deltas_able_to_process": 2,
+ "delta_batch_size": 2,
"encoding": "JSON",
"entity_fbid": self._state.user_id,
}
Just had it happen again right where I bolded the text.
`Messages seen by 535205247 in 2555758894492220 (GROUP) at 1579927833.742s Marked messages as seen in threads [('2555758894492220', 'GROUP')] at 1579927856.838s Messages seen by 853320077 in 2555758894492220 (GROUP) at 1579927859.384s Messages seen by 525330194 in 2555758894492220 (GROUP) at 1579927863.56s Marked messages as seen in threads [('2555758894492220', 'GROUP')] at 1579927975.557s Marked messages as seen in threads [('2555758894492220', 'GROUP')] at 1579927984.204s Messages seen by 535205247 in 2555758894492220 (GROUP) at 1579927985.505s Marked messages as seen in threads [('2555758894492220', 'GROUP')] at 1579927988.246s Messages seen by 853320077 in 2555758894492220 (GROUP) at 1579928009.182s Messages seen by 515131692 in 2555758894492220 (GROUP) at 1579928014.811s New pending message from 590006207 Marked messages as seen in threads [('752500082', 'USER')] at 1579928113.856s Marked messages as seen in threads [('752500082', 'USER')] at 1579928130.947s Messages seen by 100019908758517 in 2555758894492220 (GROUP) at 1579929674.882s Marked messages as seen in threads [('2555758894492220', 'GROUP')] at 1579929692.375s Messages seen by 535205247 in 2555758894492220 (GROUP) at 1579929838.576s Messages seen by 853320077 in 2555758894492220 (GROUP) at 1579929873.711s Marked messages as seen in threads [('752500082', 'USER')] at 1579936268.696s Messages seen by 598801255 in 1015032871953633 (GROUP) at 1579937693.477s Marked messages as seen in threads [('1015032871953633', 'GROUP')] at 1579943285.433s Messages seen by 520557117 in 1015032871953633 (GROUP) at 1579955463.698s Failed parsing MQTT data on /notify_disconnect as JSON Traceback (most recent call last): File "/home/corey/.local/lib/python3.6/site-packages/fbchat/_util.py", line 91, in parse_json return json.loads(content) File "/usr/lib/python3.6/json/init.py", line 354, in loads return _default_decoder.decode(s) File "/usr/lib/python3.6/json/decoder.py", line 339, in decode obj, end = self.raw_decode(s, idx=_w(s, 0).end()) File "/usr/lib/python3.6/json/decoder.py", line 357, in raw_decode raise JSONDecodeError("Expecting value", s, err.value) from None json.decoder.JSONDecodeError: Expecting value: line 1 column 1 (char 0)
During handling of the above exception, another exception occurred:
Traceback (most recent call last):
File "/home/corey/.local/lib/python3.6/site-packages/fbchat/_mqtt.py", line 77, in _on_message_handler
j = _util.parse_json(message.payload.decode("utf-8"))
File "/home/corey/.local/lib/python3.6/site-packages/fbchat/_util.py", line 93, in parse_json
raise FBchatFacebookError("Error while parsing JSON: {!r}".format(content))
fbchat._exception.FBchatFacebookError: Error while parsing JSON: 'IRIS_CURSOR_LIMIT'
Friend request from 575757371
^CTraceback (most recent call last):
File "/mnt/c/Users/Gustin Quon/Documents/Ubuntu/chatbot/draftChatBot.py", line 200, in
I will try to have it as a simple list instead of reading and writing from a file and if that doesnt work I will try the second option you suggested
Hmm, your output did give me some useful information, now I know that the /notify_disconnect
topic returns b'IRIS_CURSOR_LIMIT'
; but it doesn't help me diagnose your problem š
My interim solution is to use a bash script to restart my python script every hour and when my python script is called it goes through all of my threads and makes sure it hasn't missed anything if it had got hung up or during the 5 seconds it took to reset. Probably not the most ideal solution but it is working
So I switched from running this on a Ubuntu Windows 10 subsystem to a Raspberry pi running Raspbian and I rarely run into this issue. On top of that, I have the pi restart every night automatically so I don't notice the issue if it does run into it.
Description of the problem
My Script hangs on when Listening until I click ctrl+c which resumes it. There is not trace when it happens
Code to reproduce
Environment information
fbchat
version 1.9.6$ python -m pip list
If you have done any research, include that. Make sure to redact all personal information.