invalid character '<' looking for beginning of value

[yns01]

Hey,

Some requests are failing with the following error:

invalid character '<' looking for beginning of value

I configured the number of retries to 3. Here's a timeline of what happened:

On the Stripe dashboard:

12:42:50 POST /charges ends with 200
12:42:52 POST /charges ends with 409

On my logs with LogLevel = 5:

[app logs] 2018-08-01T10:42:53.489Z\",\"caller\":\"logger/logger.go:36\",\"message\":\"Stripe request ended with an error: invalid character '<' looking for beginning of value\", 

[stripe-go logs] 
"2018/08/01 10:42:53 Retry request https://api.stripe.com/v1/charges 1 time.",
"2018/08/01 10:42:53 Stripe Response: \"{\\\\"id\\\": \\\"ch_*\\\",\
"2018/08/01 10:42:53 Completed in 2.784733977s",
"2018/08/01 10:42:52 Request failed with error: <nil>. Response: &{409....
"2018/08/01 10:42:52 Requesting POST api.stripe.com/v1/charges"
"2018/08/01 10:42:50 Requesting POST api.stripe.com/v1/charges"

One of the two requests ended with a 409 and was retried and failed with the error in the title. As it does not appear on the dashboard, it seems it did not reach your servers.

AFAIK, it should have been retried.

Similar but maybe not related to #528

go version: 1.10.1
stripe-go: 35.1.0

Thanks!

[yns01]

I suspect that < is the start of <nil>

[brandur-stripe]

@yns01 You do know if the the decoding error occurred on the first request or the second? (It looks like the second I think?)

[brandur-stripe]

@yns01 I went through and audited all the retry code here, but it's still not clear to me exactly where your problem is occurring.

It looks like what happened here is that you had a first requested which 409ed due to a conflicting request already in flight. The code retried and you got back what looks like a valid response, but decoding failed somewhere (I believe the invalid character ... was thrown by an json.Unmarshal).

Can you do two things:

1. It looks like you truncated the log like Stripe Response: \"{\\\\"id\\\": \\\"ch_*\\\",\. Could you examine the entire thing and make sure there's nothing fishy in there that would lead to an unmarshaling error?
2. Could you try to verify that the problem is indeed occurring within stripe-go by examining where charge.New is being invoked and making sure that there's nothing between there and where you're logging that error that could be causing the problem. I'm not exactly sure what causes this issue, but your guess is as good as any, and it almost seems like a nil is being coerced to a string somewhere and then accidentally being passed to a json.Unmarshal.

I'm sending #643 through to tighten up some of the logging in this area to make it more legible, but I don't expect it to solve this problem.

[yns01]

I'll update the package and see how it goes.

I think the issue was related to the second requests. I also went through the code and it's not clear to me how it went.
Here's the response:

\"{\
  \\\"id\\\": \\\"ch_1\\\",\
  \\\"object\\\": \\\"charge\\\",\
  \\\"amount\\\": 2550,\
  \\\"amount_refunded\\\": 0,\
  \\\"application\\\": null,\
  \\\"application_fee\\\": null,\
  \\\"balance_transaction\\\": \\\"txn_1\\\",\
  \\\"captured\\\": true,\
  \\\"created\\\": 1533120171,\
  \\\"currency\\\": \\\"chf\\\",\
  \\\"customer\\\": \\\"cus_CIFr\\\",\
  \\\"description\\\": \\\"\\\",\
  \\\"destination\\\": \\\"acct_1\\\",\
  \\\"dispute\\\": null,\
  \\\"failure_code\\\": null,\
  \\\"failure_message\\\": null,\
  \\\"fraud_details\\\": {\
  },\
  \\\"invoice\\\": null,\
  \\\"livemode\\\": true,\
  \\\"metadata\\\": {\
    \\\"x\\\": \\\"x\\\",\
    \\\"x\\\": \\\"x\\\",\
    \\\"x\\\": \\\"x\\\",\
    \\\"x\\\": \\\"x\\\",\
    \\\"x\\\": \\\"x\\\"\
  },\
  \\\"on_behalf_of\\\": \\\"acct_1\\\",\
  \\\"order\\\": null,\
  \\\"outcome\\\": {\
    \\\"network_status\\\": \\\"approved_by_network\\\",\
    \\\"reason\\\": null,\
    \\\"risk_level\\\": \\\"normal\\\",\
    \\\"risk_score\\\": 0,\
    \\\"rule\\\": \\\"allow_if_liability_shift__enabled\\\",\
    \\\"seller_message\\\": \\\"Payment complete.\\\",\
    \\\"type\\\": \\\"authorized\\\"\
  },\
  \\\"paid\\\": true,\
  \\\"receipt_email\\\": null,\
  \\\"receipt_number\\\": null,\
  \\\"refunded\\\": false,\
  \\\"refunds\\\": {\
    \\\"object\\\": \\\"list\\\",\
    \\\"data\\\": [\
\
    ],\
    \\\"has_more\\\": false,\
    \\\"total_count\\\": 0,\
    \\\"url\\\": \\\"/v1/charges/ch_1/refunds\\\"\
  },\
  \\\"review\\\": null,\
  \\\"shipping\\\": null,\
  \\\"source\\\": {\
    \\\"id\\\": \\\"src_1\\\",\
    \\\"object\\\": \\\"source\\\",\
    \\\"amount\\\": 2550,\
    \\\"client_secret\\\": \\\"src_client_secret_\\\",\
    \\\"created\\\": 1533120172,\
    \\\"currency\\\": \\\"chf\\\",\
    \\\"flow\\\": \\\"redirect\\\",\
    \\\"livemode\\\": true,\
    \\\"metadata\\\": {\
      \\\"x\\\": \\\"x\\\",\
      \\\"x\\\": \\\"x\\\",\
      \\\"x\\\": \\\"x\\\",\
      \\\"x\\\": \\\"x\\\"\
    },\
    \\\"owner\\\": {\
      \\\"address\\\": {\
        \\\"city\\\": null,\
        \\\"country\\\": null,\
        \\\"line1\\\": \\\"\\\",\
        \\\"line2\\\": null,\
        \\\"postal_code\\\": null,\
        \\\"state\\\": null\
      },\
      \\\"email\\\": null,\
      \\\"name\\\": \\\"xxxx\\\",\
      \\\"phone\\\": null,\
      \\\"verified_address\\\": null,\
      \\\"verified_email\\\": null,\
      \\\"verified_name\\\": null,\
      \\\"verified_phone\\\": null\
    },\
    \\\"redirect\\\": {\
      \\\"failure_reason\\\": null,\
      \\\"return_url\\\": \\\"https://www.site.com/payment/return?xx=123\\\\u0026x=1\\\\u0026y=14\\\",\
      \\\"status\\\": \\\"succeeded\\\",\
      \\\"url\\\": \\\"https://hooks.stripe.com/redirect/authenticate\\\"\
    },\
    \\\"statement_descriptor\\\": null,\
    \\\"status\\\": \\\"consumed\\\",\
    \\\"three_d_secure\\\": {\
      \\\"card\\\": \\\"src_1\\\",\
      \\\"authenticated\\\": true,\
      \\\"customer\\\": null,\
      \\\"exp_month\\\": 0,\
      \\\"exp_year\\\": 0,\
      \\\"last4\\\": null,\
      \\\"name\\\": null,\
      \\\"country\\\": null,\
      \\\"brand\\\": null,\
      \\\"address_line1_check\\\": null,\
      \\\"address_zip_check\\\": null,\
      \\\"cvc_check\\\": null,\
      \\\"funding\\\": null,\
      \\\"tokenization_method\\\": null,\
      \\\"dynamic_last4\\\": null\
    },\
    \\\"type\\\": \\\"three_d_secure\\\",\
    \\\"usage\\\": \\\"single_use\\\"\
  },\
  \\\"source_transfer\\\": null,\
  \\\"statement_descriptor\\\": null,\
  \\\"status\\\": \\\"succeeded\\\",\
  \\\"transfer\\\": \\\"tr_1\\\",\
  \\\"transfer_group\\\": \\\"group_ch_1\\\"\
}\
\""

2. I will double check with the updated package

[brandur-stripe]

Thanks! I just put your JSON through a test and it unmarshals to a charge just fine.

Regarding point no. 2 above: could you try to double-check your code elsewhere for json.Unmarshal to make sure that you're not sending a bad value into one somewhere? I still think there's a possibility that this isn't originating from within stripe-go.

[yns01]

Thanks; I will. However how would you explain that in the logs there's three requests but I only see two in the dashboard.

[brandur-stripe]

@yns01 The 409 you got back means that the API identified a conflicting request that was still in flight at the time that request was made. That request isn't fully resolved until that conflicting request finishes, and our idempotency layer returns a simple 409 to indicate to the client that there's a conflict and it should retry.

[yns01]

Well yes - But since the failed request has been retried, I expected at some point to see it in the dashboard.

Anyways, here's the logs of another occurrence:

Stripe dashboard:
409 ERR POST   /v1/charges/   08/03/2018 18:02:13
200 OK  POST  /v1/charges/  08/03/2018 18:02:12

Logs:
08/03/2018 18:02:15.242 +0200 "stripe logs: Response: %s [\"{\\\\"id\\\": \\\"ch_xxx\\\",\
08/03/2018 18:02:15.242 +0200 "stripe logs: Request completed in %v (retry: %v) [\"3.413146498s\" '\\x00']",
08/03/2018 18:02:14.593 +0200 "message\":\"could not handle Stripe error: invalid character '<' looking for beginning of value\
08/03/2018 18:02:14.593 +0200 "stripe logs: Request completed in %v (retry: %v) [\"177.201724ms\" '\\x01']"
08/03/2018 18:02:13.916 +0200 "stripe logs: Initiating retry %v for request %v %v%v after sleeping %v ['\\x01' \"POST\" \"api.stripe.com\" \"/v1/charges\" \"500ms\"]",
08/03/2018 18:02:13.915 +0200 "stripe logs: Request failed with: %s (error: %v) [\"{\\\"error\\\":{\\\"code\\\":\\\"idempotency_key_in_use\\\"
08/03/2018 18:02:13.915 +0200 "stripe logs: Request completed in %v (retry: %v) [\"251.72216ms\" '\\x00']",
08/03/2018 18:02:13.663 +0200 "stripe logs: Requesting %v %v%v [\"POST\" \"api.stripe.com\" \"/v1/charges\"]",
08/03/2018 18:02:11.828 +0200 "stripe logs: Requesting %v %v%v [\"POST\" \"api.stripe.com\" \"/v1/charges\"]",

I don't see a possible path in the code to produce these logs..

[brandur-stripe]

Well yes - But since the failed request has been retried, I expected at some point to see it in the dashboard.

You wouldn't because at that point it'll just be returning a cached response because it's equivalent to your first request — they both shared an idempotency key.

It might be a good idea to just step back here and make sure that you're using idempotency keys the way you expect. If you got a 409, that probably means that you reused an idempotency key (see here for docs) for that conflicting request. If you didn't intend to do that, you should look for instances of SetIdempotencyKey in your code and remove them (the client will generate one for you if you don't override it). Can you check on that?

[yns01]

@brandur-stripe I created a repo to reproduce https://github.com/yns01/stripe-go-invalid-char

[brandur-stripe]

@yns01 Thanks.

And yep, this one is pretty easy — just remove where you're setting IdempotencyKey. Please check out the docs, but if you're going to set this, you need to set it to something unique with every new charge that you want to create. You can also just not set it, and the library will do it for you.

That will fix your code, but there does appear to be an unmarshal problem somewhere still. I'll see if I can track it down. Thanks for the repro!

[yns01]

I'm sorry, maybe I was not clear at the beginning. But in this case, these are not a different charges. It's meant to be the exact same one, say in case of a retry from the client or a race condition with the webhook handler.
They both uniquely identify one payment. So, please correct me if I'm wrong, but I should keep the keys and since they both identify one payment, they should be the same.

Also seen here
https://github.com/stripe/stripe-payments-demo/blob/fb3d570a89936f920fffd2f958acb580130e2267/server/node/routes.js#L82

[brandur-stripe]

@yns01 Ah yes, thanks Yanis! I get you now.

I'm just looking for the problem now, and I think I'm pretty close.

[yns01]

I actually had a quick look, but I could not figure out why the retry came back with a 400 status code

[brandur-stripe]

I actually had a quick look, but I could not figure out why the retry came back with a 400 status code

Something is pretty wrong here :/ The 400 is actually coming back from the Nginx reverse proxy sitting in front of the API service:

Client 2: Request completed in 28.168402ms (retry: 1)
resbody = <html>
<head><title>400 Bad Request</title></head>
<body bgcolor="white">
<center><h1>400 Bad Request</h1></center>
<hr><center>nginx</center>
</body>
</html>

... which explains the unmarshaling problem. I'm not sure why yet.

[yns01]

This is the body of the second request:

<html>
<head><title>400 Bad Request</title></head>
<body bgcolor="white">
<center><h1>400 Bad Request</h1></center>
<hr><center>nginx</center>
</body>
</html>

So this where the '<' is coming from

Edit: You just posted the same thing

[brandur-stripe]

Yep :/

So wow, you actually stumbled on a bug here that's extremely involved and which stems from our recent addition of HTTP/2 support to api.stripe.com (and which Go clients will negotiate automatically). I think this comment explains it most concisely.

The essence of it is that before HTTP/2, it was possible in Go to reuse a Request object, but with HTTP/2, it's now sometimes possible and sometimes not.

In stripe-go, we initialize the Request once, and then just try to reuse it if we need to get a retry, and that's not working anymore.

We can fix this by setting the Body to a new value before trying to reuse the request, but our code isn't laid out very well for that right now. I have a really patch that works, but needs some rework because it's extremely ugly right now.

[brandur-stripe]

Okay, I have a fix that seems to work out for review in #646. Thanks again for reporting this and the help in tracking it down! Much appreciated.

[yns01]

It was a tricky one, I hard a hard time tracking it down

[brandur-stripe]

It was a tricky one, I hard a hard time tracking it down

Well, thanks for the effort :$ Very tricky problem for sure.

I've released this as a major (39.0.0) because technically it changes some exported interfaces in a backward compatible way, but the upgrade should be trivial to most users.