Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Unable to sync IMAP - looping with "reader poll => []" #207

Closed
pietrushnic opened this issue Jun 13, 2015 · 23 comments
Closed

Unable to sync IMAP - looping with "reader poll => []" #207

pietrushnic opened this issue Jun 13, 2015 · 23 comments
Assignees

Comments

@pietrushnic
Copy link

I'm trying to configure IMAP with Polish hosting provider home.pl and have problems with syncing any message. They use custom IMAP server. I tried telnet and mutt to verify if IMAP works and have no problem with login and listing directories. Despite that offlineimap hangs on reader poll => [] and can't proceed further.

Log with -d all:

[17:57:31] pietrushnic:python-venv $ bin/offlineimap -d all -a foo@bar.com
OfflineIMAP 6.5.7
  Licensed under the GNU GPL v2 or any later version (with an OpenSSL exception)
Now debugging for imap: IMAP protocol debugging
Now debugging for maildir: Maildir repository debugging
Now debugging for thread: Threading debugging
Now debugging for : Other offlineimap related sync messages
Account sync foo@bar.com:
 [thread]: Register new thread 'Account sync foo@bar.com' (account 'foo@bar.com')
 [imap]: Using authentication mechanisms ['GSSAPI', 'CRAM-MD5', 'PLAIN', 'LOGIN']
 [maildir]: MaildirRepository initialized, sep is '.'
 *** Processing account foo@bar.com
 Establishing connection to foobar.home.pl:143
 [imap]:   58:34.61 Account sync foo@bar.com imaplib2 version 2.43
 [imap]:   58:34.61 Account sync foo@bar.com imaplib2 debug level 5, buffer level 3
foobar.home.pl writer:
 [imap]:   58:34.67 foobar.home.pl writer starting
Account sync foo@bar.com:
 [imap]:   58:34.67 Account sync foo@bar.com _request_push(continuation, None, {}) = GAJF0
foobar.home.pl reader:
 [imap]:   58:34.67 foobar.home.pl reader starting using poll
Account sync foo@bar.com:
 [imap]:   58:34.67 Account sync foo@bar.com None:GAJF0.ready.wait
foobar.home.pl reader:
 [imap]:   58:34.69 foobar.home.pl reader poll => [(4, 1)]
 [imap]:   58:34.69 foobar.home.pl reader rcvd 55
 [imap]:   58:34.69 foobar.home.pl reader < * OK foobar.home.pl IdeaImapServer v0.80 ready\r\n
foobar.home.pl handler:
 [imap]:   58:34.77 foobar.home.pl handler starting
 [imap]:   58:34.77 foobar.home.pl handler _put_response(* OK foobar.home.pl IdeaImapServer v0.80 ready)
 [imap]:   58:34.77 foobar.home.pl handler untagged_responses[OK] 0 += ["foobar.home.pl IdeaImapServer v0.80 ready"]
 [imap]:   58:34.77 foobar.home.pl handler state_change_free.set
 [imap]:   58:34.77 foobar.home.pl handler _request_pop(continuation, (False, '* OK foobar.home.pl IdeaImapServer v0.80 ready')) = GAJF0
 [imap]:   58:34.77 foobar.home.pl handler None:GAJF0.ready.set
Account sync foo@bar.com:
 [imap]:   58:34.77 Account sync foo@bar.com _get_untagged_response(OK) => ['foobar.home.pl IdeaImapServer v0.80 ready']
 [imap]:   58:34.77 Account sync foo@bar.com state => NONAUTH
 [imap]:   58:34.77 Account sync foo@bar.com [async] CAPABILITY ()
 [imap]:   58:34.77 Account sync foo@bar.com state_change_pending.acquire
 [imap]:   58:34.77 Account sync foo@bar.com state_change_pending.release
 [imap]:   58:34.77 Account sync foo@bar.com _request_push(GAJF1, CAPABILITY, {}) = GAJF1
 [imap]:   58:34.77 Account sync foo@bar.com data=GAJF1 CAPABILITY
 [imap]:   58:34.77 Account sync foo@bar.com CAPABILITY:GAJF1.ready.wait
foobar.home.pl writer:
 [imap]:   58:34.77 foobar.home.pl writer > GAJF1 CAPABILITY\r\n
foobar.home.pl reader:
 [imap]:   58:34.80 foobar.home.pl reader poll => [(4, 1)]
 [imap]:   58:34.80 foobar.home.pl reader rcvd 138
 [imap]:   58:34.80 foobar.home.pl reader < * CAPABILITY IMAP4rev1 LITERAL+ CHILDREN I18NLEVEL=1 IDLE SORT UIDPLUS UNSELECT XLIST STARTTLS AUTH=PLAIN AUTH=LOGIN\r\n
 [imap]:   58:34.80 foobar.home.pl reader < GAJF1 OK Completed\r\n
foobar.home.pl handler:
 [imap]:   58:34.80 foobar.home.pl handler _put_response(* CAPABILITY IMAP4rev1 LITERAL+ CHILDREN I18NLEVEL=1 IDLE SORT UIDPLUS UNSELECT XLIST STARTTLS AUTH=PLAIN AUTH=LOGIN)
 [imap]:   58:34.80 foobar.home.pl handler untagged_responses[CAPABILITY] 0 += ["IMAP4rev1 LITERAL+ CHILDREN I18NLEVEL=1 IDLE SORT UIDPLUS UNSELECT XLIST STARTTLS AUTH=PLAIN AUTH=LOGIN"]
 [imap]:   58:34.80 foobar.home.pl handler _put_response(GAJF1 OK Completed)
 [imap]:   58:34.80 foobar.home.pl handler state_change_free.set
 [imap]:   58:34.80 foobar.home.pl handler _request_pop(GAJF1, ('OK', ['Completed'])) = GAJF1
 [imap]:   58:34.80 foobar.home.pl handler CAPABILITY:GAJF1.ready.set
Account sync foo@bar.com:
 [imap]:   58:34.80 Account sync foo@bar.com _get_untagged_response(CAPABILITY) => ['IMAP4rev1 LITERAL+ CHILDREN I18NLEVEL=1 IDLE SORT UIDPLUS UNSELECT XLIST STARTTLS AUTH=PLAIN AUTH=LOGIN']
 [imap]:   58:34.80 Account sync foo@bar.com _untagged_response(OK, ?, CAPABILITY) => ['IMAP4rev1 LITERAL+ CHILDREN I18NLEVEL=1 IDLE SORT UIDPLUS UNSELECT XLIST STARTTLS AUTH=PLAIN AUTH=LOGIN']
 [imap]:   58:34.80 Account sync foo@bar.com CAPABILITY: ('IMAP4REV1', 'LITERAL+', 'CHILDREN', 'I18NLEVEL=1', 'IDLE', 'SORT', 'UIDPLUS', 'UNSELECT', 'XLIST', 'STARTTLS', 'AUTH=PLAIN', 'AUTH=LOGIN')
 [imap]: Using STARTTLS connection
 [imap]:   58:34.80 Account sync foo@bar.com [sync] STARTTLS ()
 [imap]:   58:34.80 Account sync foo@bar.com state_change_pending.acquire
 [imap]:   58:34.80 Account sync foo@bar.com _request_push(GAJF2, STARTTLS, {}) = GAJF2
 [imap]:   58:34.80 Account sync foo@bar.com data=GAJF2 STARTTLS
 [imap]:   58:34.80 Account sync foo@bar.com STARTTLS:GAJF2.ready.wait
foobar.home.pl writer:
 [imap]:   58:34.80 foobar.home.pl writer > GAJF2 STARTTLS\r\n
foobar.home.pl reader:
 [imap]:   58:34.83 foobar.home.pl reader poll => [(4, 1)]
 [imap]:   58:34.83 foobar.home.pl reader rcvd 1
 [imap]:   58:34.83 foobar.home.pl reader poll => [(4, 1)]
 [imap]:   58:34.83 foobar.home.pl reader rcvd 1
 [imap]:   58:34.83 foobar.home.pl reader poll => [(4, 1)]
 [imap]:   58:34.83 foobar.home.pl reader rcvd 1
 [imap]:   58:34.83 foobar.home.pl reader poll => [(4, 1)]
 [imap]:   58:34.83 foobar.home.pl reader rcvd 1
 [imap]:   58:34.83 foobar.home.pl reader poll => [(4, 1)]
 [imap]:   58:34.83 foobar.home.pl reader rcvd 1
 [imap]:   58:34.83 foobar.home.pl reader poll => [(4, 1)]
 [imap]:   58:34.83 foobar.home.pl reader rcvd 1
 [imap]:   58:34.83 foobar.home.pl reader poll => [(4, 1)]
 [imap]:   58:34.83 foobar.home.pl reader rcvd 1
 [imap]:   58:34.83 foobar.home.pl reader poll => [(4, 1)]
 [imap]:   58:34.83 foobar.home.pl reader rcvd 1
 [imap]:   58:34.83 foobar.home.pl reader poll => [(4, 1)]
 [imap]:   58:34.83 foobar.home.pl reader rcvd 1
 [imap]:   58:34.83 foobar.home.pl reader poll => [(4, 1)]
 [imap]:   58:34.83 foobar.home.pl reader rcvd 1
 [imap]:   58:34.83 foobar.home.pl reader poll => [(4, 1)]
 [imap]:   58:34.83 foobar.home.pl reader rcvd 1
 [imap]:   58:34.83 foobar.home.pl reader poll => [(4, 1)]
 [imap]:   58:34.83 foobar.home.pl reader rcvd 1
 [imap]:   58:34.83 foobar.home.pl reader poll => [(4, 1)]
 [imap]:   58:34.83 foobar.home.pl reader rcvd 1
 [imap]:   58:34.83 foobar.home.pl reader poll => [(4, 1)]
 [imap]:   58:34.83 foobar.home.pl reader rcvd 1
 [imap]:   58:34.83 foobar.home.pl reader poll => [(4, 1)]
 [imap]:   58:34.83 foobar.home.pl reader rcvd 1
 [imap]:   58:34.83 foobar.home.pl reader poll => [(4, 1)]
 [imap]:   58:34.83 foobar.home.pl reader rcvd 1
 [imap]:   58:34.83 foobar.home.pl reader poll => [(4, 1)]
 [imap]:   58:34.83 foobar.home.pl reader rcvd 1
 [imap]:   58:34.83 foobar.home.pl reader poll => [(4, 1)]
 [imap]:   58:34.83 foobar.home.pl reader rcvd 1
 [imap]:   58:34.83 foobar.home.pl reader poll => [(4, 1)]
 [imap]:   58:34.83 foobar.home.pl reader rcvd 1
 [imap]:   58:34.83 foobar.home.pl reader poll => [(4, 1)]
 [imap]:   58:34.83 foobar.home.pl reader rcvd 1
 [imap]:   58:34.83 foobar.home.pl reader poll => [(4, 1)]
 [imap]:   58:34.83 foobar.home.pl reader rcvd 1
 [imap]:   58:34.83 foobar.home.pl reader poll => [(4, 1)]
 [imap]:   58:34.83 foobar.home.pl reader rcvd 1
 [imap]:   58:34.84 foobar.home.pl reader poll => [(4, 1)]
 [imap]:   58:34.84 foobar.home.pl reader rcvd 1
 [imap]:   58:34.84 foobar.home.pl reader poll => [(4, 1)]
 [imap]:   58:34.84 foobar.home.pl reader rcvd 1
 [imap]:   58:34.84 foobar.home.pl reader poll => [(4, 1)]
 [imap]:   58:34.84 foobar.home.pl reader rcvd 1
 [imap]:   58:34.84 foobar.home.pl reader poll => [(4, 1)]
 [imap]:   58:34.84 foobar.home.pl reader rcvd 1
 [imap]:   58:34.84 foobar.home.pl reader poll => [(4, 1)]
 [imap]:   58:34.84 foobar.home.pl reader rcvd 1
 [imap]:   58:34.84 foobar.home.pl reader poll => [(4, 1)]
 [imap]:   58:34.84 foobar.home.pl reader rcvd 1
 [imap]:   58:34.84 foobar.home.pl reader poll => [(4, 1)]
 [imap]:   58:34.84 foobar.home.pl reader rcvd 1
 [imap]:   58:34.84 foobar.home.pl reader poll => [(4, 1)]
 [imap]:   58:34.84 foobar.home.pl reader rcvd 1
 [imap]:   58:34.84 foobar.home.pl reader poll => [(4, 1)]
 [imap]:   58:34.84 foobar.home.pl reader rcvd 1
 [imap]:   58:34.84 foobar.home.pl reader poll => [(4, 1)]
 [imap]:   58:34.84 foobar.home.pl reader rcvd 1
 [imap]:   58:34.84 foobar.home.pl reader < GAJF2 OK Begin TLS negotiation\r\n
foobar.home.pl handler:
 [imap]:   58:34.84 foobar.home.pl handler _put_response(GAJF2 OK Begin TLS negotiation)
 [imap]:   58:34.84 foobar.home.pl handler state_change_free.set
 [imap]:   58:34.84 foobar.home.pl handler _request_pop(GAJF2, ('OK', ['Begin TLS negotiation'])) = GAJF2
 [imap]:   58:34.84 foobar.home.pl handler STARTTLS:GAJF2.ready.set
foobar.home.pl reader:
 [imap]:   58:34.84 foobar.home.pl reader finished
Account sync foo@bar.com:
 [imap]:   58:34.84 Account sync foo@bar.com state_change_pending.release
foobar.home.pl reader:
 [imap]:   58:35.07 foobar.home.pl reader starting using poll
Account sync foo@bar.com:
 [imap]:   58:35.07 Account sync foo@bar.com [async] CAPABILITY ()
 [imap]:   58:35.07 Account sync foo@bar.com state_change_pending.acquire
 [imap]:   58:35.07 Account sync foo@bar.com state_change_pending.release
 [imap]:   58:35.07 Account sync foo@bar.com _request_push(GAJF3, CAPABILITY, {}) = GAJF3
 [imap]:   58:35.07 Account sync foo@bar.com data=GAJF3 CAPABILITY
 [imap]:   58:35.07 Account sync foo@bar.com CAPABILITY:GAJF3.ready.wait
foobar.home.pl writer:
 [imap]:   58:35.07 foobar.home.pl writer > GAJF3 CAPABILITY\r\n

offlineimaprc:

[mbnames]
enabled = yes
filename = ~/.mutt/muttrc.mailboxes
header = "mailboxes "
peritem = "+%(accountname)s/%(foldername)s"
sep = " "
footer = "\n"

[general]
metadata = ~/.offlineimap
maxsyncaccounts = 6
maxconnections = 2
accounts = foo@bar.com
status_backend = sqlite
pythonfile = ~/.mutt/offlineimap.py

[Account foo@bar.com]
autorefresh = 3
localrepository = foo_bar
remoterepository = foo_bar_remote
postsynchook = notmuch new

[Repository foo_bar]
type = Maildir
#localfolders = ~/.mail/foo@bar.com
localfolders = ~/.mail/tmp

[Repository foo_bar_remote]
type = IMAP
remotehost = foobar.home.pl
remoteusereval = get_username("bar/username")
remotepasseval = get_password("email/foo@bar")
ssl = no
remoteport = 143

Any idea how to fix this problem ?

@nicolas33
Copy link
Member

You could try with previous stables to check if there is a regression somewhere.

@nicolas33 nicolas33 added the bug label Jun 14, 2015
@pietrushnic
Copy link
Author

@nicolas33 same results for v6.4.4, v6.5.3.1 and v6.5.4. Let me know if I can help in debugging and testing.

@pietrushnic
Copy link
Author

@nicolas33 is there any way to help with fixing this issue ?

@pietrushnic
Copy link
Author

@nicolas33 @spaetz I was able to bisect my problem it looks like STARTTLS implementation breaks my flow.

Exact commit that I have problem with is 6311716 "imapserver.py: Implement STARTTLS"

Please let me know if I can help you with fixing it.

@spaetz
Copy link
Member

spaetz commented Jul 3, 2015

Thanks for bisecting. Home.pl claims to support Starttls but once we attempt to enable it, there seems no further reply from the server. Can eg Thunderbird connect if you set it explicitely to use starttls? This is so deep on the guts of imaplib that it smells like a server error to me. You can of course use a tls connection in the first place and avoid the need for optional starttls (which is not secure if yOu have a MITM).
Disabling all security to "fix" this, is not what I'd recommend.

@spaetz
Copy link
Member

spaetz commented Jul 3, 2015

P.s. the reader poll loop seen in your log is no issue, it is simply waiting for less than a second on the server reply and continues after it.

@pietrushnic
Copy link
Author

@spaetz thanks for reply.

I tried both SSL/TLS and STARTTLS in Icedove (I'm on Debian) both works fine with home.pl server.

In case of offlineimap v6.3.4 (this works for me previously) with reverted 6311716 works for:

ssl = no
remoteport = 143

but doesn't work for:

ssl = yes
remoteport = 993

For offlineimap master both ssl yes and no doesn't work.

@nicolas33
Copy link
Member

Could you please test again with latest stable (v6.5.7) and latest development WIP in next branch?

If you still have the issue, please run latest WIP with IMAP debug logs enabled and attach the full logs here.

@pietrushnic
Copy link
Author

v6.5.7 doesn't work for me and next branch crashing. Am I missing some package ? I'm using python 2.7 virtualenv under Debian.

logs

@nicolas33
Copy link
Member

Both are stopping with same error 'module' object has no attribute 'PROTOCOL_SSLv3'. So, there's another regression.... FUCK!

Sadly, we have no context.

@pietrushnic
Copy link
Author

@nicolas33 is it possible to get more information ie. by -d all or it would not add much ?

@nicolas33
Copy link
Member

Not much. It's missing the stack trace.

@nicolas33
Copy link
Member

BTW, the reason it fails is that this protocol is not available if OpenSSL was compiled with the OPENSSL_NO_SSLv3 flag: https://docs.python.org/2/library/ssl.html#ssl.PROTOCOL_SSLv3.

I fixed this issue, please test this from https://github.com/nicolas33/offlineimap/tree/ssl3-fix.

@pietrushnic
Copy link
Author

It looks like ssl3-fix branch contain fix for SSL3 exception. I can't see exception in log.

yes_ssl_993 log
no_ssl_143 log

@nicolas33
Copy link
Member

Thanks. Fix merged upstream and applied into official next branch.

Back to your original issue, I see that TLS handshake goes fine! Both (with and without TLS) seem to fail to get response of the IMAP server CAPABILITY right after the poll driver is enabled. So, I wonder if there's a firmware issue with the poll driver.

Could you test latest offlineimap WIP (next branch) with the following change: in offlineimap/imaplib2.py line 1792, change:

if hasattr(select_module, "poll"):

to

if False:

Keep indentation as-is.

@pietrushnic
Copy link
Author

I tested above and it doesn't change much. Log looks little bit different and error persist.

no_ssl_143 log
yes_ssl_993 log

@nicolas33
Copy link
Member

Looks like home.pl does not respond to the IMAP KCOG1 CAPABILITY command.

Try within a telnet session to check how it goes for this command. There should be no need to login.
How long did you wait for a result while "hanging"?

@pietrushnic
Copy link
Author

@nicolas33

[23:01:19] pietrushnic:bin $ telnet foobar.home.pl imap
Trying x.x.x.x...
Connected to foobar.home.pl.
Escape character is '^]'.
* OK foobar.home.pl IdeaImapServer v0.80 ready
KCOG1 CAPABILITY
* CAPABILITY IMAP4rev1 LITERAL+ CHILDREN I18NLEVEL=1 IDLE SORT UIDPLUS UNSELECT XLIST STARTTLS AUTH=PLAIN AUTH=LOGIN

Measuring with script answer display on terminal in ~20ms.

@nicolas33
Copy link
Member

Is this issue still valid?

@pietrushnic
Copy link
Author

@nicolas33 I tested 6.7.0-rc1 and still the same results:

no ssl
ssl 993

@nicolas33
Copy link
Member

nicolas33 commented Jun 23, 2016

Here are some analysis from the logs:

  1. no SSL. Client connects and start talking to the server. It get responses for the CAPABILITY command. The response includes 'STARTTLS', hence offlineimap upgrades the connection to TLS/SSL. The negociation starts. Then, either it doesn't go fine or the reader don't get anymore data once up when requesting the next CAPABILITY command.
  2. SSL Client connects and get the welcome message. offlineimap sends the CAPABILITY command and never get a response.

I wonder the SSL tunnel might be broken and the server fails to detect it or to send a correct error message.

nicolas33 added a commit to nicolas33/offlineimap that referenced this issue Jun 23, 2016
Some servers might have this feature broken.

Github-ref: OfflineIMAP#207
Signed-off-by: Nicolas Sebrecht <nicolas.s-dev@laposte.net>
@nicolas33
Copy link
Member

Anyway, we should support disabling STARTTLS when we hit broken servers. This is what above patch is about.

@nicolas33 nicolas33 self-assigned this Jun 23, 2016
nicolas33 added a commit that referenced this issue Jun 26, 2016
Some servers might have this feature broken.

Github-ref: #207
Signed-off-by: Nicolas Sebrecht <nicolas.s-dev@laposte.net>
@nicolas33
Copy link
Member

Fixed.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

No branches or pull requests

3 participants