Stuck bitcoin node preventing ORDER messages from notifying vendor (me)

[pinheadmz]

Yesterday I received a twitter DM that someone had made a purchase on my OB store. I had my OB client open the whole time and received no notification. Upon checking the ob log I noticed that my server had indeed received the ORDER messages, but I was not notified at all on the client.

I restarted my server and the notifications popped back up, communicated with the buyer and everything is great! However, I know from being a moderator that this happens a lot: vendors are not getting notified about orders on their store, the buyer assumes they're a deadbeat and opens a dispute, which is the first time the vendor even knows the order happened at all.

Poking around a bit more, I think what happened is the server was still waiting for the bitcoin payment associated with the order. Looks like my OB server's bitcoin node was stuck on a block (after a reorg?) with no new log messages for over 3 hours -- of course, the exact window my customer made a purchase! In fact, looks like the node froze FIVE MINUTES before the order came in! SHEESH!

All I can think to say is, maybe the user should be notified about orders even before the payment comes through. At least then maybe a vendor could check out why the payment hasn't come through, check their blockchain height, etc.

Also maybe the UI could have an error message or warning, pretty simple just like if there's no new block for an hour or so, or no new log messages for 15 minutes, something to just inform the user they need to kick the tires.

ob.log

18:12:14.339 [DEBUG] [recordAgingNotifier/PerformTask] notifications created/records updated: dispute: 0/0, sales: 0/0, purchaseTimeout: 0/0, purchaseExpire: 0/0
18:22:14.331 [DEBUG] [recordAgingNotifier/PerformTask] notifications created/records updated: sales: 0/0, purchaseTimeout: 0/0, purchaseExpire: 0/0, dispute: 0/0
18:30:45.760 [DEBUG] [service/handleOrder] Received addr-req ORDER message from QmNxxqaezMroT9YbFt9yjfEot4goAvmYtma4M967uGxv8p
18:32:14.350 [DEBUG] [recordAgingNotifier/PerformTask] notifications created/records updated: sales: 0/0, purchaseTimeout: 0/0, purchaseExpire: 0/0, dispute: 0/0
18:38:03.703 [DEBUG] [service/handleOrder] Received addr-req ORDER message from QmNxxqaezMroT9YbFt9yjfEot4goAvmYtma4M967uGxv8p
18:38:13.312 [DEBUG] [service/handleFollow] Received FOLLOW message from QmNxxqaezMroT9YbFt9yjfEot4goAvmYtma4M967uGxv8p
18:39:59.784 [DEBUG] [service/handleOrder] Received addr-req ORDER message from QmNxxqaezMroT9YbFt9yjfEot4goAvmYtma4M967uGxv8p
18:41:48.239 [DEBUG] [service/handleChat] Received CHAT message from QmNxxqaezMroT9YbFt9yjfEot4goAvmYtma4M967uGxv8p
18:42:14.346 [DEBUG] [recordAgingNotifier/PerformTask] notifications created/records updated: sales: 0/0, purchaseTimeout: 0/0, purchaseExpire: 0/0, dispute: 0/0
18:42:14.404 [INFO] [ResyncManager/CheckUnfunded] Rolling back blockchain 24h11m31.404798711s looking for payments for 3 orders
18:42:44.668 [DEBUG] [service/handleChat] Received CHAT message from QmNxxqaezMroT9YbFt9yjfEot4goAvmYtma4M967uGxv8p

bitcoin.log -- unabridged, showing freeze and restart

18:26:46.927 [DEBUG] [bitcoin/handleInvMsg] Requesting block 000000000000000000071bc9556b6eaa33dc81c58968c629bc76dcb763c84701, len request queue: 0
18:26:47.068 [DEBUG] [bitcoin/handleInvMsg] Requesting block 000000000000000000071bc9556b6eaa33dc81c58968c629bc76dcb763c84701, len request queue: 0
18:26:47.144 [WARNING] [bitcoin/CommitHeader] REORG!!! REORG!!! REORG!!! At block 551355, Wiped out 1 blocks
18:26:47.145 [INFO] [bitcoin/handleMerkleBlockMsg] Received merkle block 000000000000000000071bc9556b6eaa33dc81c58968c629bc76dcb763c84701 at height 551356
18:26:51.871 [DEBUG] [bitcoin/handleMerkleBlockMsg] Request queue at zero. Pushing new locator.
18:26:51.872 [WARNING] [bitcoin/handleMerkleBlockMsg] Received block from 35.189.172.3:8333 (outbound) when we aren't current
18:42:19.838 [INFO] [bitcoin/startSync] Starting chain download from 119.46.16.214:8333 (outbound)
22:05:39.366 [INFO] [bitcoin/Start] Starting wire service at height 551354
22:05:39.839 [INFO] [bitcoin/Start] Loaded 5457 peers from cache
22:05:40.039 [DEBUG] [bitcoin/onVerack] Connected to [2604:a880:800:a1::59:9001]:8333 - /Satoshi:0.16.0/
22:05:40.146 [DEBUG] [bitcoin/onVerack] Connected to 97.116.13.94:8333 - /Satoshi:0.16.2/
22:05:40.225 [DEBUG] [bitcoin/onVerack] Connected to 78.46.16.252:8333 - /Satoshi:0.16.0/
22:05:40.242 [DEBUG] [bitcoin/onVerack] Connected to 104.248.156.182:8333 - /Satoshi:0.17.0/
22:05:40.268 [DEBUG] [bitcoin/onVerack] Connected to 194.44.31.18:8333 - /Satoshi:0.13.1/
22:05:40.269 [DEBUG] [bitcoin/onVerack] Connected to 128.199.89.12:8333 - /Satoshi:0.13.2/

bitcoin.log - after restart

22:06:32.208 [DEBUG] [bitcoin/handleTxMsg] Ingested new tx 1c26e0e14cdd16b392350f51762e2510fdd81c5e5b9ce835b2859fe22bed0276 at height 551596
...
22:06:34.977 [DEBUG] [bitcoin/handleTxMsg] Ingested new tx afa1a15b4fc3890da99b8f71db065d678068e22664d03ddb54841eb2bb87afd8 at height 551603

ob.log - after restart

22:06:29.374 [DEBUG] [transaction-listener/processSalePayment] Received payment for order Qmbj1BG6crZU4kJMhKhTXJcnKRdhSFQaSjdaxvfo1Rutoz
22:06:33.046 [DEBUG] [transaction-listener/processSalePayment] Received payment for order Qmd3LN1paUryfGJky9xhRM8rtdpDJrdCXHZm3U94JdAxHY

[jjeffryes]

@placer14 You might want to look at the part of this where things got stuck.

@pinheadmz you can see unfunded orders, but you need to click the filter to show them in transactions, which is off by default.

We don't notify vendors because many buyers will buy something and then never pay for it, and vendors asked us to not tell them about those orders, since they were usually just abandoned.

[pinheadmz]

That makes sense. It's a tough situation when the bitcoin node can't detect payments though ;-)