search

OpenBazaar / openbazaar-go

OpenBazaar 2.0 Server Daemon in Go
MIT License
991 stars 284 forks source link

Direct purchase hangs #1862

Open rmisio opened 4 years ago

rmisio commented 4 years ago

Not sure if others could reproduce this, but this has happened to me dozens of times. And it's pretty mysterious because sometimes it happens and other times with seemingly the same data, it doesn't happen.

Anyhow, make a direct order. The vendor seems to process it properly, aside from maybe Currency not tracked:

13:19:25.592 [DEBUG] [service/handleOrder] handling normal order from: QmUhBVZDCcY9RzhnYXbQxUFETCG8ECvHcRfSGHiR5pecSJ
13:19:25.594 [DEBUG] [service/handleOrder] incoming order linked to LTC wallet
13:19:25.594 [DEBUG] [service/handleOrder] received direct online order from QmUhBVZDCcY9RzhnYXbQxUFETCG8ECvHcRfSGHiR5pecSJ
13:19:26.511 [ERROR] [core/CalculateOrderTotal] Currency not tracked
13:19:26.514 [DEBUG] [service/handleOrder] storing sales order Qmdwv643wnThj5mrGy6tmAkC9q5Pi4MVi85JYukzfpjwbp into the database and awaiting payment
13:19:26.516 [DEBUG] [service/handleOrder] sending order confirmation message to QmUhBVZDCcY9RzhnYXbQxUFETCG8ECvHcRfSGHiR5pecSJ
13:19:26.516 [DEBUG] [service/handleOrder] received addr-req ORDER message from QmUhBVZDCcY9RzhnYXbQxUFETCG8ECvHcRfSGHiR5pecSJ
13:19:26.516 [DEBUG] [service/handleNewMessage] sending response message to: QmUhBVZDCcY9RzhnYXbQxUFETCG8ECvHcRfSGHiR5pecSJ

The buyer appears to receive the response:

13:19:25.589 [ERROR] [core/CalculateOrderTotal] Currency not tracked
13:19:25.591 [DEBUG] [service/SendRequest] Sending ORDER request to QmeRfQcEiefLYgEFRsNqn1WjjrLjrJVAddt85htU1Up32y
13:19:25.591 [DEBUG] [service/messageSenderForPeer] Found existing message sender for: QmeRfQcEiefLYgEFRsNqn1WjjrLjrJVAddt85htU1Up32y
13:19:26.517 [DEBUG] [service/handleNewMessage] Received new message from: QmeRfQcEiefLYgEFRsNqn1WjjrLjrJVAddt85htU1Up32y
13:19:26.517 [DEBUG] [service/messageSenderForPeer] Found existing message sender for: QmeRfQcEiefLYgEFRsNqn1WjjrLjrJVAddt85htU1Up32y
13:19:26.517 [DEBUG] [service/handleNewMessage] received response message from QmeRfQcEiefLYgEFRsNqn1WjjrLjrJVAddt85htU1Up32y: 845778593
13:19:26.517 [DEBUG] [service/handleNewMessage] found matching request for: 845778593
13:19:26.517 [DEBUG] [service/SendRequest] Received response from QmeRfQcEiefLYgEFRsNqn1WjjrLjrJVAddt85htU1Up32y

...but nothing else happens. The ob/purchase call just hangs.

Here's the order data:

{
   "address":"",
   "addressNotes":"",
   "alternateContactInfo":"",
   "city":"",
   "countryCode":"",
   "items":[
      {
         "listingHash":"QmQvfWwYo8rtBbtmnKupMPWGNJp26v9boe1ujfZV68KJrt",
         "options":[
         ],
         "shipping":{
            "name":""
         },
         "memo":"",
         "coupons":[
         ],
         "bigQuantity":"8"
      }
   ],
   "moderator":"",
   "paymentCoin":"LTC",
   "postalCode":"",
   "shipTo":"",
   "state":""
}

Here's the listing:

{
    "listing": {
        "slug": "hippo-test-test-do-not-buy",
        "vendorID": {
            "peerID": "QmeRfQcEiefLYgEFRsNqn1WjjrLjrJVAddt85htU1Up32y",
            "handle": "",
            "pubkeys": {
                "identity": "CAESIPsTfkSQQOJYJInAaNAHgNAbBRTKpF8YtpqVhbYCn7kY",
                "bitcoin": "A66yT4xp3/5KHw2fWVrBz4XhXmZ2NwTxJGscTHlfxOOP"
            },
            "bitcoinSig": "MEUCIQDeEIY+noMx6NywMR5hlyemLZNPT+CP9ZsJy+ev6M90UQIgGtAfyT7mr+TgG/tTAwcQ7kqhbKiT7G6hmvNeE6E3jUA="
        },
        "metadata": {
            "version": 5,
            "contractType": "DIGITAL_GOOD",
            "format": "FIXED_PRICE",
            "expiry": "2037-12-31T06:00:00.000Z",
            "acceptedCurrencies": [
                "BTC",
                "BCH",
                "ZEC",
                "LTC",
                "ETH"
            ],
            "pricingCurrency": "",
            "language": "",
            "escrowTimeoutHours": 1080,
            "coinType": "",
            "coinDivisibility": 0,
            "priceModifier": 0
        },
        "item": {
            "title": "hippo TEST TEST DO NOT BUY",
            "description": "",
            "processingTime": "",
            "price": 0,
            "nsfw": false,
            "tags": [
            ],
            "images": [
                {
                    "filename": "sombrero.gif",
                    "original": "QmfVE79ZMGdNzNgrotPTAYfrFtYWbhG9wyvaCVgTBgsM84",
                    "large": "QmURg9MHPPrP26Vuuw1jzut8HLPdtWPNiQJkLfGB4ijaRm",
                    "medium": "QmeuuQzZWQiBHVHAJXBJ3RvhKFdLE1aJnqez8mUvTzpHgc",
                    "small": "QmSLag7FXL6akEwxyiXGvuhfxpeZaQn5PRDsfodTH4dNLt",
                    "tiny": "Qmd6EN7fpKHfNWs7G56T8kSBCtyn69YcE7hugbGvq9pagC"
                }
            ],
            "categories": [
            ],
            "grams": 0,
            "condition": "NEW",
            "options": [
            ],
            "skus": [
                {
                    "productID": "",
                    "surcharge": 0,
                    "quantity": 0,
                    "bigSurcharge": "",
                    "bigQuantity": "0"
                }
            ],
            "priceModifier": 0,
            "bigPrice": "1",
            "priceCurrency": {
                "code": "USD",
                "divisibility": 2
            }
        },
        "shippingOptions": [
        ],
        "coupons": [
        ],
        "moderators": [
            "QmWpNgDmxueiPrv5R7szKKxsYMssXRrqAu7Rus1KCdFk7u"
        ],
        "termsAndConditions": "",
        "refundPolicy": ""
    },
    "hash": "QmQvfWwYo8rtBbtmnKupMPWGNJp26v9boe1ujfZV68KJrt",
    "signature": "03UN/QIYJRrZCHjqMaTgb0+3u4jKONUZrErFuM8Vfx9tW01O3xqlLCSpoO60eiKZ2uUfCs6LwllrFmtPndXqDA=="
}

The listing is priced in USD and the paymentCoin is LTC, so both of those should be tracked. Is it possible this is dependent on something transient like exchange rate data being available?

In either case, the call shouldn't hang and more info should be being piped back to the user and/or logs.

hoffmabc commented 4 years ago

13:19:25.589 [ERROR] [core/CalculateOrderTotal] Currency not tracked

indicates that you were unable to get a price for that currency from any of the specified endpoints so it cannot estimate a fee per bytes and fails.

I'm not sure what is causing this if the endpoints are up but it certainly can't proceed if it can't get a price.

rmisio commented 4 years ago

I'm not sure what is causing this if the endpoints are up but it certainly can't proceed if it can't get a price.

Ok, but the API call shouldn't hang infinitely then (I've waited 10+ minutes before and it never came back). IMO, it should kick back a 500 with a descriptive error.

hoffmabc commented 4 years ago

Just for clarity @rmisio I don't believe the endpoints timing out is causing this issue. It simply falls back to default fee rates if it times out. I'm not sure exactly what could be causing the hang as I have hard-coded potential failures throughout this purchase call and not nailed down a hanging issue.

Also your log above from the hang indicates the process got through the purchase call since it sends the order message and receives a response from the recipient.

I've tested against the very listing you displayed as well.

rmisio commented 4 years ago

Yeah, it's a huge mystery to me as well because it looks like the buyer has everything they need to proceed with the purchase, but the API call never returns.

rmisio commented 4 years ago

FWIW, I think another user is reporting the same issue:

https://github.com/OpenBazaar/openbazaar-desktop/issues/1779

and FWIW, it happens to me locally a lot.

hoffmabc commented 4 years ago

Are you positive that the log above is from a time when the order hung?

rmisio commented 4 years ago

Are you positive that the log above is from a time when the order hung?

3,689% positive. It's happened to me probably dozen times over the last couple of weeks.

hoffmabc commented 4 years ago

I just want to confirm because that log shows the order went through and rules out a lot of code as being the culprit.

rmisio commented 4 years ago

Yeah, I'd follow the code subsequent to the logs and try and find where it could potentially hang. I'd examine all deferred functionality beyond that point.

hoffmabc commented 4 years ago

One more question, is the order inserted into the orders table in the database?

rmisio commented 4 years ago

One more question, is the order inserted into the orders table in the database?

I don't recall ever specifically checking that. I don't think it is inserted, but I'm not 100% sure.

I'll try to reproduce it again and let you know.

rmisio commented 4 years ago

Looks like the purchase call is hanging on:

err = wal.AddWatchedAddress(addr)

I routinely get these types of errors:

11:54:35.020 [ERROR] [client/doRequest] timed out executing: Get https://ltc.api.openbazaar.org/api/tx/19da061787ed19cf3203090cb78745fe5044b9745360be8e22642ac74f63e847: net/http: request canceled (Client.Timeout exceeded while awaiting headers)
11:54:35.020 [ERROR] [client/doRequest] timed out executing: Get https://ltc.api.openbazaar.org/api/tx/9d5b90a54a18e0750e803052611dff3c0836cb1ff1d04cf961f2652d7ff754b5: net/http: request canceled (Client.Timeout exceeded while awaiting headers)
11:54:35.150 [ERROR] [client/doRequest] timed out executing: Get https://ltc.api.openbazaar.org/api/tx/56d8ffcbcbccd428c5248062d3b595724a44e32722650dc6645702fbed869cb7: net/http: request canceled (Client.Timeout exceeded while awaiting headers)
11:54:35.274 [ERROR] [client/doRequest] timed out executing: Get https://ltc.api.openbazaar.org/api/tx/1f7b1f52922e44afa6217aefe14880e695247b07ef5da06ad79788dafffb71ac: net/http: request canceled (Client.Timeout exceeded while awaiting headers)

Ideally our infrastructure would be able to support my internet speeds (10ish down, 1ish up), although me being located in Guatemala may be a bottleneck, but with us being a worldwide product, perhaps we need to improve our infrastructure related geo-location?

At the very least, ob-go should put a timeout on that function and after a reasonable amount of time give up and kick back an error to the user.

(Currently I'm waiting nearly 20 minutes and the call is still hanging. FWIW, I've never had the call actually come back once it gets in this hanging state)