Can't refresh token: error http 400

fapdash commented 2 years ago

This error happens when I call org-gcal-fetch. This used to work with no problems since my initial setup a couple of months ago. I'm quite confused about this error as I didn't change anything on my emacs setup or my Google console Oauth settings. Also no one else seems to have this problem?

Versions

Org mode version 9.4.6 (9.4.6-796-ge68375.dirty-elpa @ /home/fap/.emacs.d/elpa/org-20210929/) GNU Emacs 27.2 (build 1, x86_64-pc-linux-gnu, GTK+ Version 3.24.20, cairo version 1.16.0) of 2021-11-05 org-gcal: 20211007.1843 (Commit: 8b6df4b727339e3933c68045e104b6b1d99816f7)

Output from `org-gcal-toggle-debug`:

...
OAuth token expired. Now trying to refresh-token
Received HTTP 401
OAuth token expired. Now trying to refresh-token
[debug] request--curl: --silent --location --cookie /home/fap/.emacs.d/request/curl-cookie-jar --cookie-jar /home/fap/.emacs.d/request/curl-cookie-jar --include --write-out \n(:num-redirects %{num_redirects} :url-effective "%{url_effective}") --compressed --request POST --url https://www.googleapis.com/oauth2/v3/token --data-binary @-
[debug] request--curl-callback: event finished

[debug] request--callback: UNPARSED
HTTP/2 400 
pragma: no-cache
cache-control: no-cache, no-store, max-age=0, must-revalidate
expires: Mon, 01 Jan 1990 00:00:00 GMT
date: Wed, 24 Nov 2021 12:11:45 GMT
content-type: application/json; charset=utf-8
vary: Origin
vary: X-Origin
vary: Referer
content-encoding: gzip
server: scaffolding on HTTPServer2
content-length: 79
x-xss-protection: 0
x-frame-options: SAMEORIGIN
x-content-type-options: nosniff
alt-svc: h3=":443"; ma=2592000,h3-29=":443"; ma=2592000,h3-Q050=":443"; ma=2592000,h3-Q046=":443"; ma=2592000,h3-Q043=":443"; ma=2592000,quic=":443"; ma=2592000; v="46,43"

{
  "error": "invalid_grant",
  "error_description": "Bad Request"
}
[error] request--callback: peculiar error: 400
[debug] request--callback: executing error
[error] request-default-error-callback: https://www.googleapis.com/oauth2/v3/token error
[debug] request--callback: executing complete
deferred error : (error "Got error 400: (error http 400)")

telotortium commented 2 years ago

That is strange - I don't generally encounter this issue. What were the contents of the *request-log* buffer (or the buffer with the name contained in the variable request-log-buffer-name)? Try to redact your refresh token, as well as any other sensitive tokens - I don't see it here, which is good.

Does this prevent the whole fetch from happening, or is it a transient error?

fapdash commented 2 years ago

The whole fetch fails.

*request-log*:

[debug] request--curl: --silent --location --cookie /home/fap/.emacs.d/request/curl-cookie-jar --cookie-jar /home/fap/.emacs.d/request/curl-cookie-jar --include --write-out \n(:num-redirects %{num_redirects} :url-effective "%{url_effective}") --compressed --request GET --header Accept: application/json --header Authorization: Bearer <BEARER_TOKEN> --url https://www.googleapis.com/calendar/v3/calendars/fabian.pfaff@vogella.com/events?access_token=<BEARER_TOKEN>&singleEvents=True&syncToken=<SYNC_TOKEN>
[debug] request--curl-callback: event finished

[debug] request--callback: UNPARSED
HTTP/2 401 
www-authenticate: Bearer realm="https://accounts.google.com/", error="invalid_token"
vary: Origin
vary: X-Origin
vary: Referer
content-type: application/json; charset=UTF-8
date: Wed, 24 Nov 2021 16:59:18 GMT
server: ESF
content-length: 507
x-xss-protection: 0
x-frame-options: SAMEORIGIN
x-content-type-options: nosniff
alt-svc: h3=":443"; ma=2592000,h3-29=":443"; ma=2592000,h3-Q050=":443"; ma=2592000,h3-Q046=":443"; ma=2592000,h3-Q043=":443"; ma=2592000,quic=":443"; ma=2592000; v="46,43"

{
  "error": {
    "code": 401,
    "message": "Request had invalid authentication credentials. Expected OAuth 2 access token, login cookie or other valid authentication credential. See https://developers.google.com/identity/sign-in/web/devconsole-project.",
    "errors": [
      {
        "message": "Invalid Credentials",
        "domain": "global",
        "reason": "authError",
        "location": "Authorization",
        "locationType": "header"
      }
    ],
    "status": "UNAUTHENTICATED"
  }
}

[error] request--callback: peculiar error: 401
[debug] request--callback: executing error
[error] request-default-error-callback: https://www.googleapis.com/calendar/v3/calendars/fabian.pfaff@vogella.com/events?access_token=<BEARER_TOKEN>&singleEvents=True&syncToken=<SYNC_TOKEN> error
[debug] request--callback: executing complete
[debug] request--curl: --silent --location --cookie /home/fap/.emacs.d/request/curl-cookie-jar --cookie-jar /home/fap/.emacs.d/request/curl-cookie-jar --include --write-out \n(:num-redirects %{num_redirects} :url-effective "%{url_effective}") --compressed --request POST --url https://www.googleapis.com/oauth2/v3/token --data-binary @-
[debug] request--curl-callback: event finished

[debug] request--callback: UNPARSED
HTTP/2 400 
date: Wed, 24 Nov 2021 16:59:19 GMT
expires: Mon, 01 Jan 1990 00:00:00 GMT
cache-control: no-cache, no-store, max-age=0, must-revalidate
pragma: no-cache
content-type: application/json; charset=utf-8
vary: Origin
vary: X-Origin
vary: Referer
content-encoding: gzip
server: scaffolding on HTTPServer2
content-length: 79
x-xss-protection: 0
x-frame-options: SAMEORIGIN
x-content-type-options: nosniff
alt-svc: h3=":443"; ma=2592000,h3-29=":443"; ma=2592000,h3-Q050=":443"; ma=2592000,h3-Q046=":443"; ma=2592000,h3-Q043=":443"; ma=2592000,quic=":443"; ma=2592000; v="46,43"

{
  "error": "invalid_grant",
  "error_description": "Bad Request"
}
[error] request--callback: peculiar error: 400
[debug] request--callback: executing error
[error] request-default-error-callback: https://www.googleapis.com/oauth2/v3/token error
[debug] request--callback: executing complete

While Finding :entry-id: locations these errors show up but these seem unrelated:

Debugger entered--Lisp error: (wrong-number-of-arguments (0 . 0) 1)
  #f(compiled-function () #<bytecode 0x1570c8bfe1f9>)(nil)
  deferred:call-lambda(#f(compiled-function () #<bytecode 0x1570c8bfe1f9>) nil)
  #f(compiled-function (x) #<bytecode 0x1570c8c97a7d>)(nil)
  deferred:call-lambda(#f(compiled-function (x) #<bytecode 0x1570c8c97a7d>) nil)
  deferred:exec-task(#s(deferred :callback #f(compiled-function (x) #<bytecode 0x1570c8c97a7d>) :errorback #f(compiled-function (e) #<bytecode 0x1570c8c97a95>) :cancel deferred:default-cancel :next nil :status nil :value nil) ok nil)
  deferred:set-next(#s(deferred :callback deferred:default-callback :errorback deferred:default-errorback :cancel deferred:default-cancel :next #s(deferred :callback #f(compiled-function (x) #<bytecode 0x1570c8c97a7d>) :errorback #f(compiled-function (e) #<bytecode 0x1570c8c97a95>) :cancel deferred:default-cancel :next nil :status nil :value nil) :status nil :value nil) #s(deferred :callback #f(compiled-function (x) #<bytecode 0x1570c8c97a7d>) :errorback #f(compiled-function (e) #<bytecode 0x1570c8c97a95>) :cancel deferred:default-cancel :next nil :status nil :value nil))
  deferred:watch(#s(deferred :callback deferred:default-callback :errorback deferred:default-errorback :cancel deferred:default-cancel :next #s(deferred :callback #f(compiled-function (x) #<bytecode 0x1570c8c97a7d>) :errorback #f(compiled-function (e) #<bytecode 0x1570c8c97a95>) :cancel deferred:default-cancel :next nil :status nil :value nil) :status nil :value nil) #f(compiled-function () #<bytecode 0x1570c8bfe1f9>))
  org-gcal-sync-buffer(t nil filter-time filter-managed)
  #f(compiled-function (file) #<bytecode 0x1570c801a0f1>)("~/repos/org/todo/vogella_gcal.org")
  mapc(#f(compiled-function (file) #<bytecode 0x1570c801a0f1>) ("~/repos/org/todo/vogella_gcal.org" "~/repos/org/todo/vogella_gcal.org_archive"))
  #f(compiled-function (_) #<bytecode 0x1570ca5b74dd>)(nil)
  deferred:call-lambda(#f(compiled-function (_) #<bytecode 0x1570ca5b74dd>) nil)
  deferred:exec-task(#s(deferred :callback #f(compiled-function (_) #<bytecode 0x1570ca5b74dd>) :errorback deferred:default-errorback :cancel deferred:default-cancel :next #s(deferred :callback #f(compiled-function (x) #<bytecode 0x1570caa97bf9>) :errorback #f(compiled-function (e) #<bytecode 0x1570cb2f1dbd>) :cancel deferred:default-cancel :next nil :status nil :value nil) :status nil :value nil) ok nil)
  deferred:set-next(#s(deferred :callback deferred:default-callback :errorback deferred:default-errorback :cancel deferred:default-cancel :next #s(deferred :callback #f(compiled-function (_) #<bytecode 0x1570ca5b74dd>) :errorback deferred:default-errorback :cancel deferred:default-cancel :next #s(deferred :callback #f(compiled-function (x) #<bytecode 0x1570caa97bf9>) :errorback #f(compiled-function (e) #<bytecode 0x1570cb2f1dbd>) :cancel deferred:default-cancel :next nil :status nil :value nil) :status nil :value nil) :status nil :value nil) #s(deferred :callback #f(compiled-function (_) #<bytecode 0x1570ca5b74dd>) :errorback deferred:default-errorback :cancel deferred:default-cancel :next #s(deferred :callback #f(compiled-function (x) #<bytecode 0x1570caa97bf9>) :errorback #f(compiled-function (e) #<bytecode 0x1570cb2f1dbd>) :cancel deferred:default-cancel :next nil :status nil :value nil) :status nil :value nil))
  deferred:exec-task(#s(deferred :callback #f(compiled-function (x) #<bytecode 0x1570ca5b7549>) :errorback deferred:default-errorback :cancel #f(compiled-function (x) #<bytecode 0x1570ca5b74d1>) :next #s(deferred :callback #f(compiled-function (_) #<bytecode 0x1570ca5b74dd>) :errorback deferred:default-errorback :cancel deferred:default-cancel :next #s(deferred :callback #f(compiled-function (x) #<bytecode 0x1570caa97bf9>) :errorback #f(compiled-function (e) #<bytecode 0x1570cb2f1dbd>) :cancel deferred:default-cancel :next nil :status nil :value nil) :status nil :value nil) :status nil :value nil) ok nil)
  deferred:worker()
  apply(deferred:worker nil)
  timer-event-handler([t 24990 28518 440271 nil deferred:worker nil nil 920000])

and

Debugger entered--Lisp error: (wrong-number-of-arguments (0 . 0) 1)
  #f(compiled-function () #<bytecode 0x1570c8bfe1f9>)(nil)
  deferred:call-lambda(#f(compiled-function () #<bytecode 0x1570c8bfe1f9>) nil)
  #f(compiled-function (x) #<bytecode 0x1570caf63725>)(nil)
  deferred:call-lambda(#f(compiled-function (x) #<bytecode 0x1570caf63725>) nil)
  deferred:exec-task(#s(deferred :callback #f(compiled-function (x) #<bytecode 0x1570caf63725>) :errorback #f(compiled-function (e) #<bytecode 0x1570caf6373d>) :cancel deferred:default-cancel :next nil :status nil :value nil) ok nil)
  deferred:set-next(#s(deferred :callback deferred:default-callback :errorback deferred:default-errorback :cancel deferred:default-cancel :next #s(deferred :callback #f(compiled-function (x) #<bytecode 0x1570caf63725>) :errorback #f(compiled-function (e) #<bytecode 0x1570caf6373d>) :cancel deferred:default-cancel :next nil :status nil :value nil) :status nil :value nil) #s(deferred :callback #f(compiled-function (x) #<bytecode 0x1570caf63725>) :errorback #f(compiled-function (e) #<bytecode 0x1570caf6373d>) :cancel deferred:default-cancel :next nil :status nil :value nil))
  deferred:watch(#s(deferred :callback deferred:default-callback :errorback deferred:default-errorback :cancel deferred:default-cancel :next #s(deferred :callback #f(compiled-function (x) #<bytecode 0x1570caf63725>) :errorback #f(compiled-function (e) #<bytecode 0x1570caf6373d>) :cancel deferred:default-cancel :next nil :status nil :value nil) :status nil :value nil) #f(compiled-function () #<bytecode 0x1570c8bfe1f9>))
  org-gcal-sync-buffer(t nil filter-time filter-managed)
  #f(compiled-function (file) #<bytecode 0x1570c801a0f1>)("~/repos/org/todo/vogella_gcal.org_archive")
  mapc(#f(compiled-function (file) #<bytecode 0x1570c801a0f1>) ("~/repos/org/todo/vogella_gcal.org" "~/repos/org/todo/vogella_gcal.org_archive"))
  #f(compiled-function (_) #<bytecode 0x1570ca5b74dd>)(nil)
  deferred:call-lambda(#f(compiled-function (_) #<bytecode 0x1570ca5b74dd>) nil)
  deferred:exec-task(#s(deferred :callback #f(compiled-function (_) #<bytecode 0x1570ca5b74dd>) :errorback deferred:default-errorback :cancel deferred:default-cancel :next #s(deferred :callback #f(compiled-function (x) #<bytecode 0x1570caa97bf9>) :errorback #f(compiled-function (e) #<bytecode 0x1570cb2f1dbd>) :cancel deferred:default-cancel :next nil :status nil :value nil) :status nil :value nil) ok nil)
  deferred:set-next(#s(deferred :callback deferred:default-callback :errorback deferred:default-errorback :cancel deferred:default-cancel :next #s(deferred :callback #f(compiled-function (_) #<bytecode 0x1570ca5b74dd>) :errorback deferred:default-errorback :cancel deferred:default-cancel :next #s(deferred :callback #f(compiled-function (x) #<bytecode 0x1570caa97bf9>) :errorback #f(compiled-function (e) #<bytecode 0x1570cb2f1dbd>) :cancel deferred:default-cancel :next nil :status nil :value nil) :status nil :value nil) :status nil :value nil) #s(deferred :callback #f(compiled-function (_) #<bytecode 0x1570ca5b74dd>) :errorback deferred:default-errorback :cancel deferred:default-cancel :next #s(deferred :callback #f(compiled-function (x) #<bytecode 0x1570caa97bf9>) :errorback #f(compiled-function (e) #<bytecode 0x1570cb2f1dbd>) :cancel deferred:default-cancel :next nil :status nil :value nil) :status nil :value nil))
  deferred:exec-task(#s(deferred :callback #f(compiled-function (x) #<bytecode 0x1570ca5b7549>) :errorback deferred:default-errorback :cancel #f(compiled-function (x) #<bytecode 0x1570ca5b74d1>) :next #s(deferred :callback #f(compiled-function (_) #<bytecode 0x1570ca5b74dd>) :errorback deferred:default-errorback :cancel deferred:default-cancel :next #s(deferred :callback #f(compiled-function (x) #<bytecode 0x1570caa97bf9>) :errorback #f(compiled-function (e) #<bytecode 0x1570cb2f1dbd>) :cancel deferred:default-cancel :next nil :status nil :value nil) :status nil :value nil) :status nil :value nil) ok nil)
  deferred:worker()
  apply(deferred:worker nil)
  timer-event-handler([t 24990 28518 440271 nil deferred:worker nil nil 920000])

and

Debugger entered--Lisp error: (wrong-number-of-arguments (0 . 0) 1)
  #f(compiled-function () #<bytecode 0x1570c8bfce2d>)(("~/repos/org/todo/vogella_gcal.org" "~/repos/org/todo/vogella_gcal.org_archive"))
  deferred:call-lambda(#f(compiled-function () #<bytecode 0x1570c8bfce2d>) ("~/repos/org/todo/vogella_gcal.org" "~/repos/org/todo/vogella_gcal.org_archive"))
  #f(compiled-function (x) #<bytecode 0x1570caa97bf9>)(("~/repos/org/todo/vogella_gcal.org" "~/repos/org/todo/vogella_gcal.org_archive"))
  deferred:call-lambda(#f(compiled-function (x) #<bytecode 0x1570caa97bf9>) ("~/repos/org/todo/vogella_gcal.org" "~/repos/org/todo/vogella_gcal.org_archive"))
  deferred:exec-task(#s(deferred :callback #f(compiled-function (x) #<bytecode 0x1570caa97bf9>) :errorback #f(compiled-function (e) #<bytecode 0x1570cb2f1dbd>) :cancel deferred:default-cancel :next nil :status nil :value nil) ok ("~/repos/org/todo/vogella_gcal.org" "~/repos/org/todo/vogella_gcal.org_archive"))
  deferred:worker()
  apply(deferred:worker nil)
  timer-event-handler([t 24990 29133 713935 nil deferred:worker nil nil 606000])

YujiShen commented 2 years ago

Looks similar to my issue based on log: https://github.com/kidd/org-gcal.el/issues/171.

fapdash commented 2 years ago

I can confirm that deleting .org-gcal-token solved my issue. On doing the fetch I got directed to the Google OAuth page and after entering the new token into Emacs the fetch ran successfully.

@YujiShen Thank you! @telotortium I hope I provided enough information so you can track the issue down.

kidd / org-gcal.el