Authentication Failure

Tue Sep 27 22:12:52 UTC 2011

Indeed one would have thought that it would.  

I have done as you suggested, and changed the ui, the attached debug.log
file is the result of this, with the same behaviour exhibited.  

Additionally, I downloaded the alternate encodings branch from git, and
the same results occurred.

One thing to note, I am using Archlinux, and the symptoms occur both on
32bit (my laptop) and 64bit (my desktop) systems.  I will install debian
in a vm later to rule out it being an OS related issue.

The problem seems to be specific to my email provider (fasthosts) as I
have used offlineimap with my employers imap server (curiously both
Exchange 2010) with to no ill effect.

Regards,

Simon

On Tue, Sep 27, 2011 at 01:40:48PM +0200, Sebastian Spaeth wrote:
> On Sun, 25 Sep 2011 21:45:26 +0000, SimonChambers wrote:
> 
> > I am having a slight difficulty configuring my offlineimap client ( I am using the latest git and the 6.3.4 release ) to authenticate with my imap server.  I am able to log in using alternate clients, but not offlineimap.
> 
> > [Repository Remote-Home]
> > type = IMAP
> > ssl=no
> > remotehost = mail.simonchambers.org
> > remoteuser = mail at simonchambers.org
> > remotepass = *********
> 
> Hi there, this looks straightforward enough and should work, one would assume.
> 
> Your log shows that it first attempts to login via CRAM-MD5. It gets the challenge:
> 
> PDE1MzI3MzQ1MzAuMTMxNjk4NDk1N0Bwb3AtcHJveHktMDMubGl2ZW1haWwuY28udWs+
> 
> and returns the answer 
> 
> bWFpbEBzaW1vbmNoYW1iZXJzLm9yZyA1YjEyMDhkY2JjYWUzN2Q2ZDM5ZTJmZmNlNzkwODAxMA==\r\n
> which the server comments with: NO LOGIN failed.\r\n :-(
> 
> It then attempts plaintext login, sending:
> 
> GLGE5 LOGIN mail at simonchambers.org "*********"
> 
> to the server, which returns "NO: LOGIN failed."
> and the server then drops the connection.
> 
> This is weird, as the same string in your telnet session works:
> . login mail at simonchambers.org "*********"
> 
> Dumb question, but have you verified that the passwords are actually the
> same? I suspect that it might actually be something with system
> encodings and file encodings that might lead to special chars not being
> read in correctly?
> 
> You might want to try first to use a ui that supports password querying,
> such as TTYUI, and leave the password out of your config, so that it
> asks you to type it directly in the console. Does this work?
> 
> I have created an experimental branch that reads in a users config files
> per his preferred encoding (eg 'UTF-8'). If you are comfortable with
> git, you might want to try if the branch WIP/ConfigEncoding at my repo at
> git://github.com/spaetz/offlineimap.git works.
> 
> Sebastian

-------------- next part --------------
 OfflineIMAP 6.3.4
Copyright 2002-2011 John Goerzen & contributors.
Licensed under the GNU GPL v2+ (v2 or any later version).

 Debug mode: Forcing to singlethreaded.
 Now debugging for imap: IMAP protocol debugging
 Now debugging for : Other offlineimap related sync messages
Account sync Home:
 ***** Processing account Home
 Copying folder structure from IMAP to Maildir
 Establishing connection to mail.simonchambers.org:143.
 DEBUG[imap]:   10:38.39 Account sync Home imaplib2 version 2.24
 DEBUG[imap]:   10:38.39 Account sync Home imaplib2 debug level 5, buffer level 3
mail.simonchambers.org writer:
 DEBUG[imap]:   10:38.49 mail.simonchambers.org writer starting
mail.simonchambers.org reader:
 DEBUG[imap]:   10:38.49 mail.simonchambers.org reader starting using poll
Account sync Home:
 DEBUG[imap]:   10:38.50 Account sync Home _request_push(continuation, None, {}) = GLAN0
 DEBUG[imap]:   10:38.50 Account sync Home None:GLAN0.ready.wait
mail.simonchambers.org reader:
 DEBUG[imap]:   10:38.54 mail.simonchambers.org reader poll => [(4, 1)]
 DEBUG[imap]:   10:38.54 mail.simonchambers.org reader rcvd 18
 DEBUG[imap]:   10:38.54 mail.simonchambers.org reader < * OK IMAP4 ready\r\n
mail.simonchambers.org handler:
 DEBUG[imap]:   10:38.60 mail.simonchambers.org handler starting
 DEBUG[imap]:   10:38.60 mail.simonchambers.org handler untagged_responses[OK] 0 += ["IMAP4 ready"]
 DEBUG[imap]:   10:38.60 mail.simonchambers.org handler state_change_free.set
 DEBUG[imap]:   10:38.60 mail.simonchambers.org handler _request_pop(continuation, (False, '* OK IMAP4 ready')) = GLAN0
 DEBUG[imap]:   10:38.60 mail.simonchambers.org handler None:GLAN0.ready.set
Account sync Home:
 DEBUG[imap]:   10:38.60 Account sync Home _get_untagged_response(OK) => ['IMAP4 ready']
 DEBUG[imap]:   10:38.60 Account sync Home state => NONAUTH
 DEBUG[imap]:   10:38.60 Account sync Home [async] CAPABILITY ()
 DEBUG[imap]:   10:38.60 Account sync Home state_change_pending.acquire
 DEBUG[imap]:   10:38.60 Account sync Home state_change_pending.release
 DEBUG[imap]:   10:38.60 Account sync Home _request_push(GLAN1, CAPABILITY, {}) = GLAN1
 DEBUG[imap]:   10:38.60 Account sync Home data=GLAN1 CAPABILITY
 DEBUG[imap]:   10:38.60 Account sync Home CAPABILITY:GLAN1.ready.wait
mail.simonchambers.org writer:
 DEBUG[imap]:   10:38.60 mail.simonchambers.org writer > GLAN1 CAPABILITY\r\n
mail.simonchambers.org reader:
 DEBUG[imap]:   10:38.65 mail.simonchambers.org reader poll => [(4, 1)]
 DEBUG[imap]:   10:38.65 mail.simonchambers.org reader rcvd 162
 DEBUG[imap]:   10:38.65 mail.simonchambers.org reader < * CAPABILITY IMAP4 IMAP4rev1 UIDPLUS LITERAL+ LOGIN-REFERRALS ID ENABLE SASL-IR AUTH=PLAIN AUTH=LOGIN AUTH=CRAM-MD5 AUTH=PLAIN AUTH=CRAM-MD5\r\n
 DEBUG[imap]:   10:38.65 mail.simonchambers.org reader < GLAN1 OK completed\r\n
mail.simonchambers.org handler:
 DEBUG[imap]:   10:38.65 mail.simonchambers.org handler untagged_responses[CAPABILITY] 0 += ["IMAP4 IMAP4rev1 UIDPLUS LITERAL+ LOGIN-REFERRALS ID ENABLE SASL-IR AUTH=PLAIN AUTH=LOGIN AUTH=CRAM-MD5 AUTH=PLAIN AUTH=CRAM-MD5"]
 DEBUG[imap]:   10:38.65 mail.simonchambers.org handler state_change_free.set
 DEBUG[imap]:   10:38.65 mail.simonchambers.org handler _request_pop(GLAN1, ('OK', ['completed'])) = GLAN1
 DEBUG[imap]:   10:38.65 mail.simonchambers.org handler CAPABILITY:GLAN1.ready.set
Account sync Home:
 DEBUG[imap]:   10:38.66 Account sync Home _get_untagged_response(CAPABILITY) => ['IMAP4 IMAP4rev1 UIDPLUS LITERAL+ LOGIN-REFERRALS ID ENABLE SASL-IR AUTH=PLAIN AUTH=LOGIN AUTH=CRAM-MD5 AUTH=PLAIN AUTH=CRAM-MD5']
 DEBUG[imap]:   10:38.66 Account sync Home _untagged_response(OK, ?, CAPABILITY) => ['IMAP4 IMAP4rev1 UIDPLUS LITERAL+ LOGIN-REFERRALS ID ENABLE SASL-IR AUTH=PLAIN AUTH=LOGIN AUTH=CRAM-MD5 AUTH=PLAIN AUTH=CRAM-MD5']
 DEBUG[imap]:   10:38.66 Account sync Home CAPABILITY: ('IMAP4', 'IMAP4REV1', 'UIDPLUS', 'LITERAL+', 'LOGIN-REFERRALS', 'ID', 'ENABLE', 'SASL-IR', 'AUTH=PLAIN', 'AUTH=LOGIN', 'AUTH=CRAM-MD5', 'AUTH=PLAIN', 'AUTH=CRAM-MD5')
 DEBUG[imap]: Attempting CRAM-MD5 authentication
 DEBUG[imap]:   10:38.66 Account sync Home [sync] AUTHENTICATE ('CRAM-MD5',)
 DEBUG[imap]:   10:38.66 Account sync Home state_change_pending.acquire
 DEBUG[imap]:   10:38.66 Account sync Home _request_push(GLAN2, AUTHENTICATE, {}) = GLAN2
 DEBUG[imap]:   10:38.66 Account sync Home data=GLAN2 AUTHENTICATE CRAM-MD5
 DEBUG[imap]:   10:38.66 Account sync Home _request_push(continuation, None, {}) = GLAN3
 DEBUG[imap]:   10:38.66 Account sync Home None:GLAN3.ready.wait
mail.simonchambers.org writer:
 DEBUG[imap]:   10:38.66 mail.simonchambers.org writer > GLAN2 AUTHENTICATE CRAM-MD5\r\n
mail.simonchambers.org reader:
 DEBUG[imap]:   10:38.71 mail.simonchambers.org reader poll => [(4, 1)]
 DEBUG[imap]:   10:38.71 mail.simonchambers.org reader rcvd 72
 DEBUG[imap]:   10:38.71 mail.simonchambers.org reader < + PDc2NTY1MjkyNC4xMzE3MTYxNDM5QHBvcC1wcm94eS0wNC5saXZlbWFpbC5jby51az4=\r\n
mail.simonchambers.org handler:
 DEBUG[imap]:   10:38.71 mail.simonchambers.org handler _request_pop(continuation, (True, 'PDc2NTY1MjkyNC4xMzE3MTYxNDM5QHBvcC1wcm94eS0wNC5saXZlbWFpbC5jby51az4=')) = GLAN3
 DEBUG[imap]:   10:38.71 mail.simonchambers.org handler None:GLAN3.ready.set
Account sync Home:
 DEBUG[imap]:   10:38.71 Account sync Home continuation => True, PDc2NTY1MjkyNC4xMzE3MTYxNDM5QHBvcC1wcm94eS0wNC5saXZlbWFpbC5jby51az4=
 DEBUG[imap]: md5handler: got challenge <765652924.1317161439 at pop-proxy-04.livemail.co.uk>
 DEBUG[imap]: md5handler: returning mail at simonchambers.org fc0f5dd2fdc1a331c3e9a849bf9c8271
 DEBUG[imap]:   10:46.79 Account sync Home _request_push(continuation, None, {}) = GLAN4
 DEBUG[imap]:   10:46.79 Account sync Home write literal size 76
 DEBUG[imap]:   10:46.79 Account sync Home None:GLAN4.ready.wait
mail.simonchambers.org writer:
 DEBUG[imap]:   10:46.79 mail.simonchambers.org writer > bWFpbEBzaW1vbmNoYW1iZXJzLm9yZyBmYzBmNWRkMmZkYzFhMzMxYzNlOWE4NDliZjljODI3MQ==\r\n
mail.simonchambers.org reader:
 DEBUG[imap]:   10:46.93 mail.simonchambers.org reader poll => [(4, 1)]
 DEBUG[imap]:   10:46.93 mail.simonchambers.org reader rcvd 24
 DEBUG[imap]:   10:46.93 mail.simonchambers.org reader < GLAN2 NO LOGIN failed.\r\n
mail.simonchambers.org handler:
 DEBUG[imap]:   10:46.93 mail.simonchambers.org handler _request_pop(GLAN2, ('NO', ['LOGIN failed.'])) = GLAN2
mail.simonchambers.org reader:
 DEBUG[imap]:   10:46.93 mail.simonchambers.org reader poll => [(4, 1)]
mail.simonchambers.org handler:
 DEBUG[imap]:   10:46.93 mail.simonchambers.org handler AUTHENTICATE:GLAN2.ready.set
 DEBUG[imap]:   10:46.93 mail.simonchambers.org handler state_change_free.set
mail.simonchambers.org reader:
 DEBUG[imap]:   10:46.93 mail.simonchambers.org reader rcvd 0
mail.simonchambers.org handler:
 DEBUG[imap]:   10:46.93 mail.simonchambers.org handler _request_pop(continuation, (False, 'GLAN2 NO LOGIN failed.')) = GLAN4
 DEBUG[imap]:   10:46.94 mail.simonchambers.org handler None:GLAN4.ready.set
Account sync Home:
 DEBUG[imap]:   10:46.94 Account sync Home continuation => False, GLAN2 NO LOGIN failed.
mail.simonchambers.org handler:
 DEBUG[imap]:   10:46.94 mail.simonchambers.org handler NO response: LOGIN failed.
Account sync Home:
 DEBUG[imap]:   10:46.94 Account sync Home AUTHENTICATE:GLAN2.ready.wait
 DEBUG[imap]:   10:46.94 Account sync Home state_change_pending.release
 DEBUG[imap]: Attempting plain authentication
 DEBUG[imap]:   10:46.94 Account sync Home [sync] LOGIN ('mail at simonchambers.org', '"*********"')
 DEBUG[imap]:   10:46.94 Account sync Home state_change_pending.acquire
 DEBUG[imap]:   10:46.94 Account sync Home _request_push(GLAN5, LOGIN, {}) = GLAN5
 DEBUG[imap]:   10:46.94 Account sync Home data=GLAN5 LOGIN mail at simonchambers.org "*********"
 DEBUG[imap]:   10:46.94 Account sync Home LOGIN:GLAN5.ready.wait
mail.simonchambers.org writer:
 DEBUG[imap]:   10:46.94 mail.simonchambers.org writer > GLAN5 LOGIN mail at simonchambers.org "*********"\r\n
mail.simonchambers.org reader:
 DEBUG[imap]:   10:47.03 mail.simonchambers.org reader poll => [(4, 25)]
 DEBUG[imap]:   10:47.04 mail.simonchambers.org reader rcvd 0
 DEBUG[imap]:   10:47.14 mail.simonchambers.org reader last 20 log messages:
 DEBUG[imap]:   10:38.49 mail.simonchambers.org writer starting
 DEBUG[imap]:   10:38.50 mail.simonchambers.org reader starting using poll
 DEBUG[imap]:   10:38.60 mail.simonchambers.org handler starting
 DEBUG[imap]:   10:38.60 Account sync Home state => NONAUTH
 DEBUG[imap]:   10:38.60 Account sync Home [async] CAPABILITY ()
 DEBUG[imap]:   10:38.66 Account sync Home CAPABILITY: ('IMAP4', 'IMAP4REV1', 'UIDPLUS', 'LITERAL+', 'LOGIN-REFERRALS', 'ID', 'ENABLE', 'SASL-IR', 'AUTH=PLAIN', 'AUTH=LOGIN', 'AUTH=CRAM-MD5', 'AUTH=PLAIN', 'AUTH=CRAM-MD5')
 DEBUG[imap]:   10:38.66 Account sync Home [sync] AUTHENTICATE ('CRAM-MD5',)
 DEBUG[imap]:   10:46.94 mail.simonchambers.org handler NO response: LOGIN failed.
 DEBUG[imap]:   10:46.94 Account sync Home [sync] LOGIN ('mail at simonchambers.org', '"*********"')
 DEBUG[imap]:   10:47.14 mail.simonchambers.org reader socket error: <type 'exceptions.IOError'> - Error Hang up
 DEBUG[imap]:   10:47.14 mail.simonchambers.org reader finished
mail.simonchambers.org handler:
 DEBUG[imap]:   10:47.14 mail.simonchambers.org handler terminating: "socket error: <type 'exceptions.IOError'> - Error Hang up"
 DEBUG[imap]:   10:47.14 mail.simonchambers.org handler LOGIN:GLAN5.ready.set
Account sync Home:
 DEBUG[imap]:   10:47.14 Account sync Home state_change_pending.release
mail.simonchambers.org writer:
 DEBUG[imap]:   10:47.14 mail.simonchambers.org writer finished
mail.simonchambers.org handler:
 DEBUG[imap]:   10:47.14 mail.simonchambers.org handler state_change_free.set
 DEBUG[imap]:   10:47.14 mail.simonchambers.org handler finished
Account sync Home:
 WARNING: Error occured attempting to sync account 'Home':
Traceback (most recent call last):
  File "/usr/lib/python2.7/site-packages/offlineimap/accounts.py", line 177, in syncrunner
    self.sync()
  File "/usr/lib/python2.7/site-packages/offlineimap/accounts.py", line 235, in sync
    remoterepos.syncfoldersto(localrepos, [statusrepos])
  File "/usr/lib/python2.7/site-packages/offlineimap/repository/Base.py", line 124, in syncfoldersto
    srcfolders = src.getfolders()
  File "/usr/lib/python2.7/site-packages/offlineimap/repository/IMAP.py", line 276, in getfolders
    imapobj = self.imapserver.acquireconnection()
  File "/usr/lib/python2.7/site-packages/offlineimap/imapserver.py", line 254, in acquireconnection
    self.plainauth(imapobj)
  File "/usr/lib/python2.7/site-packages/offlineimap/imapserver.py", line 133, in plainauth
    imapobj.login(self.username, self.getpassword())
  File "/usr/lib/python2.7/site-packages/offlineimap/imaplib2.py", line 791, in login
    typ, dat = self._simple_command('LOGIN', user, self._quote(password))
  File "/usr/lib/python2.7/site-packages/offlineimap/imaplib2.py", line 1549, in _simple_command
    return self._command_complete(self._command(name, *args), kw)
  File "/usr/lib/python2.7/site-packages/offlineimap/imaplib2.py", line 1310, in _command_complete
    typ, dat = rqb.get_response('command: %s => %%s' % rqb.name)
  File "/usr/lib/python2.7/site-packages/offlineimap/imaplib2.py", line 172, in get_response
    raise typ(exc_fmt % str(val))
abort: command: LOGIN => socket error: <type 'exceptions.IOError'> - Error Hang up

 ***** Finished processing account Home