Chat history in dispute is disappearing

[pinheadmz]

client 2.2.3, server 0.12.0

Dispute is open, I am the mod. Vendor opened dispute and buyer is MIA.

Go to discussion and send some comments.
Server log looks ok:
23:18:06.716 [SendMessage] [DEBUG] Sending CHAT message to QmSYkCtLM9TxeEtuiDUH93WDSomfBhtujJPzhstCcMeTMw, etc...

Click away to any other UI view and then back, chat history is completely blank again:

[pinheadmz]

Update: today I got two additional email notifications about this same dispute. The original email was 20 hours ago, and I got the other two 4 and 8 hours ago. Upon entering the (empty) "Discussion" tab, the developer console displays this error:

[pinheadmz]

ob.log:

15:44:55.167 [DEBUG] [recordAgingNotifier/PerformTask] performTask started (count 94)
15:44:55.169 [DEBUG] [recordAgingNotifier/generateSellerDisputeNotifications] created 0 vendor dispute notifications
15:44:55.169 [DEBUG] [recordAgingNotifier/generateSellerDisputeNotifications] updated lastDisputeTimeoutNotifiedAt on 0 sales
15:44:55.177 [DEBUG] [recordAgingNotifier/generateBuyerDisputeTimeoutNotifications] created 0 purchase dispute notifications
15:44:55.180 [DEBUG] [recordAgingNotifier/generateBuyerDisputeTimeoutNotifications] updated lastDisputeTimeoutNotifiedAt on 0 purchases
15:44:55.192 [DEBUG] [recordAgingNotifier/generateBuyerDisputeExpiryNotifications] created 0 buyer expiration notifications
15:44:55.193 [DEBUG] [recordAgingNotifier/generateBuyerDisputeExpiryNotifications] updated lastDisputeExpiryNotifiedAt on 0 purchases
15:44:55.295 [DEBUG] [recordAgingNotifier/generateModeratorDisputeExpiryNotifications] created 0 dispute expiration notifications
15:44:55.334 [DEBUG] [recordAgingNotifier/generateModeratorDisputeExpiryNotifications] updated lastDisputeExpiryNotifiedAt on 2 disputes
15:44:55.963 [DEBUG] [service/SendMessage] Sending CHAT message to QmSYkCtLM9TxeEtuiDUH93WDSomfBhtujJPzhstCcMeTMw
15:44:57.036 [DEBUG] [service/SendMessage] Sending CHAT message to QmSYkCtLM9TxeEtuiDUH93WDSomfBhtujJPzhstCcMeTMw
15:44:58.547 [DEBUG] [service/SendMessage] Sending CHAT message to QmSYkCtLM9TxeEtuiDUH93WDSomfBhtujJPzhstCcMeTMw
15:44:59.769 [DEBUG] [service/SendMessage] Sending CHAT message to QmSYkCtLM9TxeEtuiDUH93WDSomfBhtujJPzhstCcMeTMw
15:45:00.843 [DEBUG] [service/SendMessage] Sending CHAT message to QmSYkCtLM9TxeEtuiDUH93WDSomfBhtujJPzhstCcMeTMw
15:45:01.949 [DEBUG] [service/SendMessage] Sending CHAT message to QmSYkCtLM9TxeEtuiDUH93WDSomfBhtujJPzhstCcMeTMw
15:45:02.387 [DEBUG] [service/SendMessage] Sending CHAT message to QmSYkCtLM9TxeEtuiDUH93WDSomfBhtujJPzhstCcMeTMw
15:45:27.992 [DEBUG] [service/SendMessage] Sending CHAT message to QmSYkCtLM9TxeEtuiDUH93WDSomfBhtujJPzhstCcMeTMw
15:45:27.994 [DEBUG] [service/SendMessage] Sending CHAT message to QmSYkCtLM9TxeEtuiDUH93WDSomfBhtujJPzhstCcMeTMw
15:45:50.163 [DEBUG] [service/SendMessage] Sending CHAT message to QmSYkCtLM9TxeEtuiDUH93WDSomfBhtujJPzhstCcMeTMw
15:46:10.061 [DEBUG] [service/SendMessage] Sending CHAT message to QmWyDbXhwoiU2sNTERGckHowMzHHbnxxgPVmKMp4t79gKe
15:46:11.838 [DEBUG] [service/SendMessage] Sending CHAT message to QmWyDbXhwoiU2sNTERGckHowMzHHbnxxgPVmKMp4t79gKe
15:46:28.015 [ERROR] [core/EncryptMessage] Failed to find public key for QmWyDbXhwoiU2sNTERGckHowMzHHbnxxgPVmKMp4t79gKe
15:47:09.468 [DEBUG] [service/handleChat] Received CHAT message from QmXmpJc4P7Z3NcPtm9WGmfUFqoQExPy1ZYEna8aY1WfSxW
15:47:15.949 [DEBUG] [service/SendMessage] Sending CHAT message to QmSYkCtLM9TxeEtuiDUH93WDSomfBhtujJPzhstCcMeTMw
15:47:15.951 [DEBUG] [service/SendMessage] Sending CHAT message to QmSYkCtLM9TxeEtuiDUH93WDSomfBhtujJPzhstCcMeTMw
15:48:18.838 [ERROR] [core/IPNSResolve] Get https://gateway.ob1.io/ob/ipns/QmTJ1fUiqezCa2X7sR16vXprhwcVEJB2P2GS9aR6aWLzF2: net/http: request canceled while waiting for connection (Client.Timeout exceeded while awaiting headers)

[jjeffryes]

@placer14 @tyler-smith @cpacia do the logs above give you and idea of what might be happening here?

[placer14]

Nothing that looks bad for QmSYkCtLM9TxeEtuiDUH93WDSomfBhtujJPzhstCcMeTMw (the person the discussion references earlier) but it could be that the chat messages wouldn't be committed if the public key for a peer is not found. I believe the pub key for the recipient is needed to encrypt the chat message and if it's unavailable, it would just disappear. I'm not sure how the frontend handles such a case.

Though the logs only show the missing pub key issue is happening for QmWyDbXhwoiU2sNTERGckHowMzHHbnxxgPVmKMp4t79gKe.

@pinheadmz Could you post the peerIDs of the vendor and the buyer? Or would you happen to know which server version they're running? Might be useful to recreate the issue. Would you be able to upgrade your local server to the recent 0.12.2 release (making a backup of your data directory first) to see if the issue continues to persist?

[pinheadmz]

vendor: QmSYkCtLM9TxeEtuiDUH93WDSomfBhtujJPzhstCcMeTMw
buyer: QmWyDbXhwoiU2sNTERGckHowMzHHbnxxgPVmKMp4t79gKe

Vendor told me in a DM he had upgraded to latest, same with me, but we might have upgraded at different times or one or both of us upgrade after the dispute was opened.

Having the exact same issue with another dispute. Same vendor but different buyer (also appears to be offline): QmWyGuPgEC3KfRTMJXqTKXaAaLf6X3n4PVWyF3WKUPAPGs

$ cat ~/.openbazaar2.0/logs/ob.log | grep QmWyGuPgEC3KfRTMJXqTKXaAaLf6X3n4PVWyF3WKUPAPGs
00:36:01.644 [DEBUG] [service/SendMessage] Sending CHAT message to QmWyGuPgEC3KfRTMJXqTKXaAaLf6X3n4PVWyF3WKUPAPGs
00:36:02.936 [DEBUG] [service/SendMessage] Sending CHAT message to QmWyGuPgEC3KfRTMJXqTKXaAaLf6X3n4PVWyF3WKUPAPGs
00:36:03.979 [DEBUG] [service/SendMessage] Sending CHAT message to QmWyGuPgEC3KfRTMJXqTKXaAaLf6X3n4PVWyF3WKUPAPGs
00:36:06.344 [DEBUG] [service/SendMessage] Sending CHAT message to QmWyGuPgEC3KfRTMJXqTKXaAaLf6X3n4PVWyF3WKUPAPGs
00:36:15.838 [DEBUG] [service/SendMessage] Sending CHAT message to QmWyGuPgEC3KfRTMJXqTKXaAaLf6X3n4PVWyF3WKUPAPGs
00:36:16.912 [DEBUG] [service/SendMessage] Sending CHAT message to QmWyGuPgEC3KfRTMJXqTKXaAaLf6X3n4PVWyF3WKUPAPGs
00:36:18.296 [DEBUG] [service/SendMessage] Sending CHAT message to QmWyGuPgEC3KfRTMJXqTKXaAaLf6X3n4PVWyF3WKUPAPGs
00:36:20.446 [DEBUG] [service/SendMessage] Sending CHAT message to QmWyGuPgEC3KfRTMJXqTKXaAaLf6X3n4PVWyF3WKUPAPGs
00:36:41.915 [DEBUG] [service/SendMessage] Sending CHAT message to QmWyGuPgEC3KfRTMJXqTKXaAaLf6X3n4PVWyF3WKUPAPGs
00:36:41.918 [DEBUG] [service/SendMessage] Sending CHAT message to QmWyGuPgEC3KfRTMJXqTKXaAaLf6X3n4PVWyF3WKUPAPGs
00:37:47.334 [ERROR] [core/EncryptMessage] Failed to find public key for QmWyGuPgEC3KfRTMJXqTKXaAaLf6X3n4PVWyF3WKUPAPGs
05:36:43.843 [DEBUG] [service/SendMessage] Sending CHAT message to QmWyGuPgEC3KfRTMJXqTKXaAaLf6X3n4PVWyF3WKUPAPGs
05:36:44.880 [DEBUG] [service/SendMessage] Sending CHAT message to QmWyGuPgEC3KfRTMJXqTKXaAaLf6X3n4PVWyF3WKUPAPGs
05:36:45.943 [DEBUG] [service/SendMessage] Sending CHAT message to QmWyGuPgEC3KfRTMJXqTKXaAaLf6X3n4PVWyF3WKUPAPGs
05:36:46.994 [DEBUG] [service/SendMessage] Sending CHAT message to QmWyGuPgEC3KfRTMJXqTKXaAaLf6X3n4PVWyF3WKUPAPGs
05:36:48.284 [DEBUG] [service/SendMessage] Sending CHAT message to QmWyGuPgEC3KfRTMJXqTKXaAaLf6X3n4PVWyF3WKUPAPGs
05:36:49.327 [DEBUG] [service/SendMessage] Sending CHAT message to QmWyGuPgEC3KfRTMJXqTKXaAaLf6X3n4PVWyF3WKUPAPGs
05:36:50.786 [DEBUG] [service/SendMessage] Sending CHAT message to QmWyGuPgEC3KfRTMJXqTKXaAaLf6X3n4PVWyF3WKUPAPGs
05:38:36.522 [ERROR] [core/EncryptMessage] Failed to find public key for QmWyGuPgEC3KfRTMJXqTKXaAaLf6X3n4PVWyF3WKUPAPGs
15:53:35.755 [DEBUG] [service/SendMessage] Sending DISPUTE_CLOSE message to QmWyGuPgEC3KfRTMJXqTKXaAaLf6X3n4PVWyF3WKUPAPGs
15:53:54.133 [DEBUG] [core/SendOfflineMessage] Sending offline message to: QmWyGuPgEC3KfRTMJXqTKXaAaLf6X3n4PVWyF3WKUPAPGs, Message Type: DISPUTE_CLOSE, PointerID: QmR5JvAm2bVxhrRnwLtuD8FUxpff7fEVjEHbrireNK82m9, Location: /ipfs/zb2rheFSXE32obcRdVB3uzd4LfGtzAVNcfUXqECPmtVVVkgKV
18:52:35.398 [ERROR] [core/IPNSResolve] Get https://gateway.ob1.io/ob/ipns/QmWyGuPgEC3KfRTMJXqTKXaAaLf6X3n4PVWyF3WKUPAPGs: net/http: request canceled while waiting for connection (Client.Timeout exceeded while awaiting headers)
18:53:28.748 [ERROR] [core/IPNSResolve] Get https://gateway.ob1.io/ob/ipns/QmWyGuPgEC3KfRTMJXqTKXaAaLf6X3n4PVWyF3WKUPAPGs: net/http: request canceled while waiting for connection (Client.Timeout exceeded while awaiting headers)
18:54:20.505 [ERROR] [core/IPNSResolve] Get https://gateway.ob1.io/ob/ipns/QmWyGuPgEC3KfRTMJXqTKXaAaLf6X3n4PVWyF3WKUPAPGs: net/http: request canceled while waiting for connection (Client.Timeout exceeded while awaiting headers)
18:54:33.935 [ERROR] [core/IPNSResolve] Get https://gateway.ob1.io/ob/ipns/QmWyGuPgEC3KfRTMJXqTKXaAaLf6X3n4PVWyF3WKUPAPGs: net/http: request canceled while waiting for connection (Client.Timeout exceeded while awaiting headers)
18:56:37.503 [ERROR] [core/IPNSResolve] Get https://gateway.ob1.io/ob/ipns/QmWyGuPgEC3KfRTMJXqTKXaAaLf6X3n4PVWyF3WKUPAPGs: net/http: request canceled while waiting for connection (Client.Timeout exceeded while awaiting headers)

[pinheadmz]

Guys, this keeps happening. I can't moderate disputes.
Going to shut off moderation until this addressed, I don't want to taint my reputation as a "verified" moderator if the communication channels are down.

Logs look fine:

20:45:40.256 [DEBUG] [service/SendMessage] Sending CHAT message to QmSg6Pn5Pfpe2y6hfEe2UooNatdG1Gf8guyEA56V5madk8
20:45:40.257 [DEBUG] [service/SendMessage] Sending CHAT message to QmXF8cmS3WNmi2om1j2XuFrUSf5RUVuDYZXnBuVKWBkNDq

[pinheadmz]

when I DM the vendor (outside of the dispute channel) I get a more robust log message:

20:49:02.218 [DEBUG] [core/SendOfflineMessage] Sending offline message to: QmXF8cmS3WNmi2om1j2XuFrUSf5RUVuDYZXnBuVKWBkNDq, Message Type: CHAT, PointerID: QmZmKY3jZrCkcTHFTL3bmoGXXAGJYoJu47iwT78RdkEGaz, Location: /ipfs/zb2rhakxbBCZAnX9YL3pTbjbFhfYBVF8aBSj41TF6je7vEt3R

[pinheadmz]

Update: OK the messages are still disappearing, but they do come back... after about 5 minutes. So I guess this only happens when a party is offline. The GUI doesn't even display the message until it gets an ACK or sends the message offline. Would be great to see a "pending" indicator in the chat instead of just hiding the message...?

22:24:50.033 [DEBUG] [service/SendMessage] Sending CHAT message to QmSg6Pn5Pfpe2y6hfEe2UooNatdG1Gf8guyEA56V5madk8
22:24:50.035 [DEBUG] [service/SendMessage] Sending CHAT message to QmXF8cmS3WNmi2om1j2XuFrUSf5RUVuDYZXnBuVKWBkNDq
<... snip ...>
22:27:56.386 [DEBUG] [recordAgingNotifier/PerformTask] performTask started (count 418)
22:27:56.398 [DEBUG] [recordAgingNotifier/generateSellerDisputeNotifications] created 0 vendor dispute notifications
22:27:56.399 [DEBUG] [recordAgingNotifier/generateSellerDisputeNotifications] updated lastDisputeTimeoutNotifiedAt on 0 sales
22:27:56.410 [DEBUG] [recordAgingNotifier/generateBuyerDisputeTimeoutNotifications] created 0 purchase dispute notifications
22:27:56.411 [DEBUG] [recordAgingNotifier/generateBuyerDisputeTimeoutNotifications] updated lastDisputeTimeoutNotifiedAt on 0 purchases
22:27:56.419 [DEBUG] [recordAgingNotifier/generateBuyerDisputeExpiryNotifications] created 0 buyer expiration notifications
22:27:56.419 [DEBUG] [recordAgingNotifier/generateBuyerDisputeExpiryNotifications] updated lastDisputeExpiryNotifiedAt on 0 purchases
22:27:56.552 [DEBUG] [recordAgingNotifier/generateModeratorDisputeExpiryNotifications] created 0 dispute expiration notifications
22:27:56.592 [DEBUG] [recordAgingNotifier/generateModeratorDisputeExpiryNotifications] updated lastDisputeExpiryNotifiedAt on 3 disputes
22:28:12.817 [DEBUG] [service/SendRequest] Sending STORE request to QmY8puEnVx66uEet64gAf4VZRo7oUyMCwG6KdB9KM92EGQ
22:28:12.821 [DEBUG] [service/SendRequest] Sending STORE request to QmPPg2qeF3n2KvTRXRZLaTwHCw8JxzF4uZK93RfMoDvf2o
22:28:12.827 [DEBUG] [service/SendRequest] Sending STORE request to QmPPegaeM4rXfQDF3uu784d93pLEzV8A4zXU7akEgYnTFd
22:28:12.851 [DEBUG] [core/SendOfflineMessage] Sending offline message to: QmXF8cmS3WNmi2om1j2XuFrUSf5RUVuDYZXnBuVKWBkNDq, Message Type: CHAT, PointerID: QmZmKY3jZrCkcTHFTL3bmoGXXAGJYoJu47iwT78RdkEGaz, Location: /ipfs/zb2rhdMPUi1p3tg2rVrq4TRcFcGfidJunYTeo7ei3acESbqqH
22:28:13.055 [DEBUG] [service/SendRequest] Received response from QmPPg2qeF3n2KvTRXRZLaTwHCw8JxzF4uZK93RfMoDvf2o
22:28:13.055 [DEBUG] [core/SendStore] Sending 1 blocks to QmPPg2qeF3n2KvTRXRZLaTwHCw8JxzF4uZK93RfMoDvf2o
22:28:13.056 [DEBUG] [service/DisconnectFromPeer] Disconnecting from QmPPg2qeF3n2KvTRXRZLaTwHCw8JxzF4uZK93RfMoDvf2o
22:28:13.164 [DEBUG] [service/SendRequest] Received response from QmY8puEnVx66uEet64gAf4VZRo7oUyMCwG6KdB9KM92EGQ
22:28:13.165 [DEBUG] [core/SendStore] Sending 1 blocks to QmY8puEnVx66uEet64gAf4VZRo7oUyMCwG6KdB9KM92EGQ
22:28:13.167 [DEBUG] [service/DisconnectFromPeer] Disconnecting from QmY8puEnVx66uEet64gAf4VZRo7oUyMCwG6KdB9KM92EGQ

--> after these last messages displayed in the log, the chats came back in the GUI

[jjeffryes]

@cpacia do you have any ideas on what would cause this to happen? It shouldn't take 5 minutes to retrieve messages.

[pinheadmz]

Also seeing logs like this for user IDs involved in the weird disputes:

21:47:10.857 [ERROR] [core/EncryptMessage] Failed to find public key for QmR2xoY4TNZqCJbLjM1aTEBUsikJntzuRC8ZyUiaYYmgzy

[JasonRaveling]

I've had this problem as well. Possibly on a related note, when messages do get delivered, I've noticed some major lag. About 20 to 30 minutes. Recently, I resolved a dispute and then started receiving new messages about 40 minutes after closing the dispute. Also, while the vendor was logged in and chatting, it still showed that the vendor's contract had not been sent. The vendor's contract wasn't even received until about an hour after chatting with him and about 30 minutes after the dispute had been closed. Let me know if you'd like logs or if I should open a new issue. At first glance they seem related to what @pinheadmz is experiencing.

[placer14]

@pinheadmz The markchatasread 500 error you're getting is unrelated to the missing chat messages problem you're experiencing here. I have found a fix for that 500 error which will get delivered on the next update.

I've been testing this scenario with a 0.12.0 release and having a hard time getting it to happen locally. I'll do an audit of the message/chat handling code to see if anything jumps out at me... It's not obvious what's going wrong here, at first glance.