SASL works after first authentication, but not later. access-token is nil

[clemente]

I set up Wanderlust to use XOauth2 to connect to Gmail.
I'm not sure my setup is complete, but it seems to work the first time: I'm able to send e-mails through SMTP.

But some days later (sorry, I still don't know how many), when I try to send an e-mail I see:

Exit MIME editor mode.
Sending...
Decrypting /home/dc/.emacs.d/sasl-xoauth2/7860ab959c9f51baf1babb863483f8f6.plstore...done
Contacting host: www.googleapis.com:443
Saving file /home/dc/.emacs.d/sasl-xoauth2/7860ab959c9f51baf1babb863483f8f6.plstore...
Wrote /home/dc/.emacs.d/sasl-xoauth2/7860ab959c9f51baf1babb863483f8f6.plstore
condition-case: Wrong type argument: arrayp, nil

I debugged the error and I saw it happens here:

Debugger entered--Lisp error: (wrong-type-argument arrayp nil)
  sasl-step-data(nil)
  (if (sasl-step-data step) (base64-encode-string (sasl-step-data step) t) "")
  (smtp-send-command connection (if (sasl-step-data step) (base64-encode-string (sasl-step-data step) t) ""))
  (while t (setq response […]
  (catch 'done (while t (setq […]
  (let* ((connection (smtp-find-connection […]
  smtp-primitive-auth([smtp-package [0 0 0 0 0 0 0] "n……………@gmail.com" ("n……………@gmail.com") #<buffer  *wl-draft-sending-buffer*>])

As mentioned, the first use works:

• the first use is when I do the manual synchronization: I need to go to a URL, authorize the access, and receive a code that I paste into Emacs. The e-mails I send after this, work
• the second use is when there's no manual authentication step and Wanderlust is trying to read the tokens from the .plstore file
• if I delete the .plstore file and retry, then Wanderlust starts from the first step again, and asks me to do the manual synchronization, and then it works again

If I look at the .plstore file after I get the error, I see something like:

(("e016……………" :access-token nil :refresh-token "1//037dLqk8…………………………" :access-response
  ((auth_time 25733 26284 693202 360000)
   (access_token . "ya29.a0Ae………………………………………………")
   (expires_in . 3599)
   (refresh_token . "1//037d…………………………………")
   (scope . "https://mail.google.com/")
   (token_type . "Bearer"))))

I think the access-token nil could be part of the problem. Right after manual synchronization (the first time I set it up) it has a value and it works.

The SMTP communication when it fails is:

Process SMTP deleted
220 smtp.gmail.com ESMTP g24-20020a1709063b1800b0096f6a131b9fsm3480986ejf.23 - gsmtp
EHLO sonn.gmail.com
250-smtp.gmail.com at your service, [188.27.180.89]
250-SIZE 35882577
250-8BITMIME
250-STARTTLS
250-ENHANCEDSTATUSCODES
250-PIPELINING
250-CHUNKING
250 SMTPUTF8
STARTTLS
220 2.0.0 Ready to start TLS
EHLO sonn.gmail.com
250-smtp.gmail.com at your service, [188.27.180.89]
250-SIZE 35882577
250-8BITMIME
250-AUTH LOGIN PLAIN XOAUTH2 PLAIN-CLIENTTOKEN OAUTHBEARER XOAUTH
250-ENHANCEDSTATUSCODES
250-PIPELINING
250-CHUNKING
250 SMTPUTF8
AUTH XOAUTH2 dXNXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX==
334 eyJzXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX==
QUIT
535-5.7.8 Username and Password not accepted. Learn more at
535 5.7.8  https://support.google.com/mail/?p=BadCredentials g24-20020a1709063b1800b0096f6a131b9fsm3480986ejf.23 - gsmtp

If I decode the base64-encoded parts above (where I wrote XXXXX), I see that the first one is user=n……………@gmail.comauth=Bearer nil and the 2nd one {"status":"400","schemes":"Bearer","scope":"https://mail.google.com/"}.
In .comauth=Bearer nil, between .com and auth there's a the ASCII byte 01. And after Bearer nil there's 01 01

The Bearer nil is bad; it should be the access-token. It comes from (format "user=%s\001auth=Bearer %s\001\001" in sasl-xoauth2-response, and I verified that it's nil. It was nil in the plstore file, and it's nil here.

I suggest adding a check somewhere in (setq access-token (oauth2-token-access-token oauth2-token)) (sasl-xoauth2-response at sasl-xoauth2.el) to verify that it got the token (not nil). This would detect and inform about the error in an easy way before the nil is base64-encoded and sent through SMTP.

And I still don't know why or who wrote access-token nil into the plstore file. Probably there can be some verification before writing, to make sure we don't write nil.

Versions: Wanderlust/2.15.9 (Almost Unreal), latest flim as of today (2cf5a78)

I can provide more information as I find it, or at your request. I want to keep this error documented here, to help others that see it.

[clemente]

It still happens with a recently compiled Emacs (less than a week ago), latest wanderlust+flim. I'm using oauth2 0.16 from ELPA.

I think it happens when the old token expires (sasl-xoauth2-token-expired-p). But I manually changed the expiration date in my plstore file to make it expired, I sent an e-mail, and it went through the code to refresh the token („Contacting host: www.googleapis.com:443“ etc.) and it worked and it got one, non-nil, and it saved it into plstore.
So I don't know at which moment the access-token becomes nil.
How to debug this more easily?

[ikazuhiro]

You can use advice for debugging. For example, following code signals error when :access-token is nil in plstore-save.

(advice-add
 'plstore-save
 :around
 (lambda (oldfun &rest r)
   (let* ((plstore (car r))
	  (plist (cdr (plstore-get plstore (caar (plstore--get-alist plstore)))))
	  (response (plist-get plist :access-response))
	  (refresh (plist-get plist :refresh-token))
	  (token (plist-get plist :access-token)))
     (if (and response refresh)
	 (progn (when (null token)
		  (error "Invalid OAuth2 token!!"))
		(message "DEBUG: OAuth2 access token is %s" token))
       (message "INFO: may not be OAuth2 token"))
     (apply oldfun r)))
 '((name . "validate plstore")))

Though I have no idea why your access-token is nil, below code may work as workaround.

;; Refresh token everytime.
(eval-after-load "sasl-xoauth2"
  '(defun sasl-xoauth2-token-expired-p (_token) t))

[clemente]

Thanks @ikazuhiro, I'll use this for some time to find out why access-token becomes nil.
I need to wait some time, maybe 1 day, for each test. Things work for a few hours after getting the token (even if I restart Emacs, or if I force-renew the token).