Closed Bug 1082740 Opened 10 years ago Closed 10 years ago

Error when trying to configure Email App for IMAP/SMTP with SSL

Categories

(Firefox OS Graveyard :: Gaia::E-Mail, defect)

ARM
Gonk (Firefox OS)
defect
Not set
normal

Tracking

(tracking-b2g:+)

RESOLVED DUPLICATE of bug 1093467
tracking-b2g +

People

(Reporter: zrzut01, Unassigned)

Details

Attachments

(1 file)

User Agent: Mozilla/5.0 (X11; Linux x86_64; rv:32.0) Gecko/20100101 Firefox/32.0
Build ID: 20140923175406

Steps to reproduce:

1. Configure account on poczta.fm
- valid email address
- valid password
- SMTP/IMAP poczta.interia.pl


Actual results:

Device stopped on 'Setting up account' when there is error in logcat:

I/GeckoDump(  697): LOG: pushCard for type: setup_progress
I/Gecko   (  697): WINF: [slog] probe:imap:connecting {"connInfo":{"hostname":"poczta.interia.pl","port":"993","crypto":"ssl"}}
I/Gecko   (  697): WLOG: [slog] oauth:credentials-ok
I/Gecko   (  697): WINF: [slog] probe:smtp:connecting {"connInfo":{"emailAddress":"notImportant@poczta.fm","hostname":"poczta.interia.pl","port":"465","crypto":"ssl"}}
I/Gecko   (  697): WLOG: [slog] oauth:credentials-ok
I/Gecko   (  697): WLOG: [slog] smtp:connect {"usingOauth2":false,"connInfo":{"emailAddress":"notImportant@poczta.fm","hostname":"poczta.interia.pl","port":"465","crypto":"ssl"}}
WINF: [slog] smtp:connected {"emailAddress":"notImportant@poczta.fm","hostname":"poczta.interia.pl","port":"465","crypto":"ssl"}
I/Gecko   (  697): WLOG: [slog] probe:smtp:checking-address-validity
I/Gecko   (  697): WINF: [slog] imap:connected {"hostname":"poczta.interia.pl","port":"993","crypto":"ssl"}
I/Gecko   (  697): WINF: [slog] probe:smtp:success
I/Gecko   (  697): WLOG: [slog] imap:protocol-error {"humanReadable":"Error in IMAP command received by server."}
I/Gecko   (  697): WERR: [slog] disaster-recovery:exception {"error":{},"errorName":"TypeError","errorMessage":"n is undefined","stack":"s/</i/<@app://email.gaiamobile.org/js/ext/imap/probe.js:19:1\ni.prototype.search/<@app://email.gaiamobile.org/js/ext/composite/configurator.js:2073:17\ni.prototype.exec/<@app://email.gaiamobile.org/js/ext/composite/configurator.js:1942:68\nr.prototype._processServerResponse@app://email.gaiamobile.org/js/ext/composite/configurator.js:1832:9\nr.prototype._processServerQueue@app://email.gaiamobile.org/js/ext/composite/configurator.js:1822:1\nr.prototype._addToServerQueue@app://email.gaiamobile.org/js/ext/composite/configurator.js:1801:9\nr.prototype._onData@app://email.gaiamobile.org/js/ext/composite/configurator.js:1793:20\nt/r</<@app://email.gaiamobile.org/js/ext/worker-bootstrap.js:8197:1\no.catchSocketExceptions@app://email.gaiamobile.org/js/ext/worker-bootstrap.js:7708:17\nt/r<@app://email.gaiamobile.org/js/ext/worker-bootstrap.js:8196:40\no/a[e]@app://email.gaiamobile.org/js/ext/worke
I/Gecko   (  697): WERR: *** Disastrous Error for email accountId undefined -- attempting to recover...
I/Gecko   (  697): WWAR: No account associated with this error; nothing to abort.


Expected results:

It should be possible to configure an e-mail account IMAP/SMTP with SSL and when there is an error the error should be shown.

Found on:

Alcatel One Touch Fire production (got from T-mobile Poland)
B2G version: 2.2.0.0-prerelease master
Platform version: 36.0a1
Build Identifier: 20141014040203 
Git commit info: 2014-10-13 17:46:17 4f86c631
[Tracking Requested - why for this release]: evaluate for priority
tracking-b2g: --- → ?
OS: All → Gonk (Firefox OS)
Hardware: All → ARM
Received a test account from the reporter, and shared it with other gaia email devs.

I can replicate with latest master on flame. Using a non-minified (but still bundled) build, I see this:

I/Gecko   ( 8011): WLOG: [slog] imap:protocol-error {"humanReadable":"Error in IMAP command received by server."}
I/Gecko   ( 8011): WERR: [slog] disaster-recovery:exception {"error":{},"errorName":"TypeError","errorMessage":"uids is undefined","stack":"determineTimezoneFromInboxMessage/</findValidUidsToCheck/<@app://email.gaiamobile.org/js/ext/imap/probe.js:113:1\nBrowserBox.prototype.search/<@app://email.gaiamobile.org/js/ext/composite/configurator.js:6454:17\nBrowserBox.prototype.exec/<@app://email.gaiamobile.org/js/ext/composite/configurator.js:6025:17\nImapClient.prototype._processServerResponse@app://email.gaiamobile.org/js/ext/composite/configurator.js:5549:24\nImapClient.prototype._processServerQueue@app://email.gaiamobile.org/js/ext/composite/configurator.js:5492:1\nImapClient.prototype._addToServerQueue@app://email.gaiamobile.org/js/ext/composite/configurator.js:5439:9\nImapClient.prototype._onData@app://email.gaiamobile.org/js/ext/composite/configurator.js:5383:1\nTCPSocketProxy/routerInfo</<@app://email.gaiamobile.org/js/ext/worker-bootstrap.js:24151:28\nDisasterRecovery.catchSocketExceptions@app://email.gaiamobile.org/js
I/Gecko   ( 8011): WERR: *** Disastrous Error for email accountId undefined -- attempting to recover...
Status: UNCONFIRMED → NEW
Ever confirmed: true
I bound axe-logger debug and log to console.log, and added a "IMAP _processResponse: " log in ImapClient.prototype._processResponse in imap/client.js, and this was the logging I see from the server.

So it seems like the server did not like "W5 UID SEARCH" command request from the client. I am a bit weak on the protocols and server expectations, another email dev may need to point the way, but logging what was found so far.

----

WINF: [slog] probe:imap:connecting {"connInfo":{"hostname":"poczta.interia.pl","port":"993","crypto":"ssl"}}
WLOG: [slog] oauth:credentials-ok
WINF: [slog] probe:smtp:connecting {"connInfo":{"emailAddress":"whatever@poczta.fm","hostname":"poczta.interia.pl","port":"465","crypto":"ssl"}}
WLOG: [slog] oauth:credentials-ok
WLOG: browserbox connecting to poczta.interia.pl:993
WLOG: browserbox entering state: false
WLOG: [slog] smtp:connect {"usingOauth2":false,"connInfo":{"emailAddress":"whatever@poczta.fm","hostname":"poczta.interia.pl","port":"465","crypto":"ssl"}}
WLOG: browserbox IMAP tcp socket opened
WLOG: browserbox IMAP received response: * OK
WLOG: [slog] IMAP _processResponse: tag: *, command: OK, attributes: [object Object],[object Object], code: CAPABILITY, capability: IMAP4REV1,UIDPLUS,CHILDREN,ID,XLIST,NAMESPACE,IDLE,AUTH=PLAIN, humanReadable: IMAP4 ready.
WLOG: browserbox session: connection established
WLOG: browserbox entering state: 1
WLOG: browserbox IMAP sending request: W1 ID
WLOG: SMTP Client SERVER: 220 ESMTP INTERIA.PL

WLOG: SMTP Client Sending EHLO localhost
WLOG: browserbox IMAP received response: * ID
WLOG: [slog] IMAP _processResponse: tag: *, command: ID, attributes: 
WLOG: browserbox IMAP received response: W1 OK
WLOG: [slog] IMAP _processResponse: tag: W1, command: OK, attributes: [object Object], humanReadable: ID completed.
WLOG: browserbox IMAP sending request: W2 login
WLOG: SMTP Client SERVER: 250-poczta.interia.pl
250-PIPELINING
250-SIZE 157286400
250-AUTH PLAIN LOGIN
250-AUTH=PLAIN LOGIN
250-ENHANCEDSTATUSCODES
250 8BITMIME

WLOG: SMTP Client Server supports AUTH PLAIN
WLOG: SMTP Client Server supports AUTH LOGIN
WLOG: SMTP Client Maximum allowd message size: 157286400
WLOG: SMTP Client Authentication via AUTH PLAIN
WLOG: browserbox IMAP received response: W2 OK
WLOG: [slog] IMAP _processResponse: tag: W2, command: OK, attributes: [object Object], humanReadable: Success.
WLOG: browserbox entering state: 2
WLOG: browserbox IMAP sending request: W3 CAPABILITY
WLOG: SMTP Client SERVER: 235 2.7.0 Authentication successful

WLOG: SMTP Client Authentication successful.
WINF: [slog] smtp:connected {"emailAddress":"whatever@poczta.fm","hostname":"poczta.interia.pl","port":"465","crypto":"ssl"}
WLOG: [slog] probe:smtp:checking-address-validity
WLOG: SMTP Client Sending MAIL FROM...
WLOG: browserbox IMAP received response: * CAPABILITY
WLOG: [slog] IMAP _processResponse: tag: *, command: CAPABILITY, attributes: [object Object],[object Object],[object Object],[object Object],[object Object],[object Object],[object Object],[object Object]
WLOG: browserbox IMAP received response: W3 OK
WLOG: [slog] IMAP _processResponse: tag: W3, command: OK, attributes: [object Object], humanReadable: CAPABILITY completed.
WLOG: browserbox post-auth capabilites updated: IMAP4REV1,UIDPLUS,CHILDREN,ID,XLIST,NAMESPACE,IDLE,AUTH=PLAIN
WINF: [slog] imap:connected {"hostname":"poczta.interia.pl","port":"993","crypto":"ssl"}
WLOG: browserbox IMAP sending request: W4 EXAMINE
WLOG: SMTP Client SERVER: 250 2.1.0 Ok

WLOG: SMTP Client MAIL FROM successful, proceeding with 1 recipients
WLOG: SMTP Client Adding recipient...
WLOG: browserbox IMAP received response: * 1
WLOG: [slog] IMAP _processResponse: tag: *, command: EXISTS, attributes: , nr: 1
WLOG: browserbox IMAP received response: * 1
WLOG: [slog] IMAP _processResponse: tag: *, command: RECENT, attributes: , nr: 1
WLOG: browserbox IMAP received response: * FLAGS
WLOG: [slog] IMAP _processResponse: tag: *, command: FLAGS, attributes: [object Object],[object Object],[object Object],[object Object],[object Object],[object Object],[object Object]
WLOG: browserbox IMAP received response: * OK
WLOG: [slog] IMAP _processResponse: tag: *, command: OK, attributes: [object Object],[object Object], code: PERMANENTFLAGS, permanentflags: , humanReadable: No permanent flags allowed
WLOG: SMTP Client SERVER: 250 2.1.5 Ok

WLOG: SMTP Client RCPT TO done, proceeding with payload
WLOG: browserbox IMAP received response: * OK
WLOG: [slog] IMAP _processResponse: tag: *, command: OK, attributes: [object Object],[object Object], code: UIDVALIDITY, uidvalidity: 1, humanReadable: UIDVALIDITY value
WLOG: browserbox IMAP received response: W4 OK
WLOG: [slog] IMAP _processResponse: tag: W4, command: OK, attributes: [object Object],[object Object], code: READ-ONLY, humanReadable: EXAMINE completed.
WLOG: browserbox entering state: 3
WLOG: browserbox IMAP sending request: W5 UID SEARCH
WLOG: SMTP Client SERVER: 354 End data with <CR><LF>.<CR><LF>

WINF: [slog] probe:smtp:success
WLOG: SMTP Client Closing connection...
WLOG: SMTP Client Socket closed.
WLOG: browserbox IMAP received response: W5 NO
WLOG: [slog] IMAP _processResponse: tag: W5, command: NO, attributes: [object Object], humanReadable: Error in IMAP command received by server.
WLOG: [slog] imap:protocol-error {"humanReadable":"Error in IMAP command received by server."}
WERR: [slog] disaster-recovery:exception {"error":{},"errorName":"TypeError","errorMessage":"uids is undefined","stack":"determineTimezoneFromInboxMessage/</findValidUidsToCheck/<@app://email.gaiamobile.org/js/ext/imap/probe.js:113:1\nBrowserBox.prototype.search/<@app://email.gaiamobile.org/js/ext/composite/configurator.js:6454:17\nBrowserBox.prototype.exec/<@app://email.gaiamobile.org/js/ext/composite/configurator.js:6025:17\nImapClient.prototype._processServerResponse@app://email.gaiamobile.org/js/ext/composite/configurator.js:5549:24\nImapClient.prototype._processServerQueue@app://email.gaiamobile.org/js/ext/composite/configurator.js:5492:1\nImapClient.prototype._addToServerQueue@app://email.gaiamobile.org/js/ext/composite/configurator.js:5439:9\nImapClient.prototype._onData@app://email.gaiamobile.org/js/ext/composite/configurator.js:5383:1\nTCPSocketProxy/routerInfo</<@app://email.gaiamobile.org/js/ext/worker-bootstrap.js:24151:28\nDisasterRecovery.catchSocketExceptions@app://email.gaiamobile.org/js
WERR: *** Disastrous Error for email accountId undefined -- attempting to recover...
Thanks for the log.  Unfortunately the straightforward log points leave out some of the goodness of the protocol trace; this diff does the most useful thing (although passwords will be revealed).

Here's the relevant bit of the trace here (smtp elided):
WLOG: OMAP: W4 EXAMINE "INBOX"
WLOG: IMAP: * 2 EXISTS
WWAR: browserbox IMAP received response: * 2
WLOG: IMAP: * 2 RECENT
WWAR: browserbox IMAP received response: * 2
WLOG: IMAP: * FLAGS (\Draft \Answered \Flagged \Deleted \Seen \Recent $Forwarded)
WWAR: browserbox IMAP received response: * FLAGS
WLOG: IMAP: * OK [PERMANENTFLAGS ()] No permanent flags allowed
WWAR: browserbox IMAP received response: * OK
WLOG: IMAP: * OK [UIDVALIDITY 1] UIDVALIDITY value
WWAR: browserbox IMAP received response: * OK
WLOG: IMAP: W4 OK [READ-ONLY] EXAMINE completed.
WWAR: browserbox IMAP received response: W4 OK
WWAR: browserbox entering state: 3
WWAR: browserbox IMAP sending request: W5 UID SEARCH
WLOG: OMAP: W5 UID SEARCH UID NaN:NaN
WLOG: IMAP: W5 NO Error in IMAP command received by server.
WWAR: browserbox IMAP received response: W5 NO

So the problem here is that the IMAP server is violating RFC 3501 and not sending the "REQUIRED" "UIDNEXT" payload (see http://tools.ietf.org/html/rfc3501#section-6.3.1 ).  It apparently was not required in earlier versions of the spec, so clients are nominally supposed to handle it being missing.  Somewhat of a complicated frustration that.

mac, can you clarify what IMAP server implementation is in use?  It seems unusually quiet on the subject, including not identifying itself via the ID command.  The support of XLIST suggests it's somewhat recent (but not too recent), which combined with the RFC 3501 violation is weird.


Implementation-wise, the problem is in our IMAP prober which is assuming it can use UIDNEXT to find a recent-ish message by UID (as opposed to using a date search.)

Triage-wise, I'd like to find out what server we're dealing with and how rare or common it is.
Flags: needinfo?(zrzut01)
The only thing in such situation is to write to Interia helpdesk (what I did with providing link to the bug and your questions) and wait for the response. I will provide information requested by you as soon as they reply or maybe they have already account here and are able to do it by themselves.
Also seeing this on 163.com/coremail.  Duping over to that bug because we know what server we're dealing with there.
Status: NEW → RESOLVED
Closed: 10 years ago
Flags: needinfo?(zrzut01)
Resolution: --- → DUPLICATE
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Created:
Updated:
Size: