#606 Weird EWS behaviour

[Robert Ayrapetyan]

Server side:
- MS Exchange 2010 (?)
- WebDAV is disabled

DavMail config:
...
davmail.url=https://outlook.companyname.com/ews/exchange.asmx
...
davmail.enableEws=true
...

How things look\work from a web-browser:

1. Open https://outlook.companyname.com/ews/exchange.asmx page.
2. NTLM "Credentials" request box appears.
3. Type proper credentials
4. User is redirected to the https://outlook.companyname.com/ews/Services.wsdl page (valid WSDL is displayed)

How things look\work from a Thunderbird mail client:

1. Restart DavMail service.
   DavMail output:
   2015-11-10 10:23:52,180 DEBUG [Shutdown] davmail - Stopping DavMail gateway
   2015-11-10 10:23:52,182 INFO [Shutdown] davmail - DavMail gateway stopped
   2015-11-10 10:23:52,352 DEBUG [main] davmail - OS Name: FreeBSD Java version: 1.7.0_80 64 System tray not supported
   2015-11-10 10:23:52,402 INFO [main] davmail - DavMail Gateway 4.6.1-2343 listening on SMTP port 1025 POP port 1110 IMAP port 1143 CALDAV port 1080 LDAP port 1389
   2015-11-10 10:23:52,707 DEBUG [CheckRelease] davmail.DavGateway - DavMail released version: 4.7.0-2408
   2015-11-10 10:23:52,707 INFO [CheckRelease] davmail - A new version (4.7.0-2408) of DavMail Gateway is available !

2. Push "Get messages" button in Thunderbird.
   DavMail output:
   2015-11-10 10:24:19,219 DEBUG [davmail.pop.PopServer] davmail - Connection from /127.0.0.1 on port 1110
   2015-11-10 10:24:20,045 DEBUG [PopConnection-43843] davmail.exchange.ExchangeSession - Test configuration status: 401
   2015-11-10 10:24:20,048 DEBUG [PopConnection-43843] davmail - > +OK DavMail 4.6.1-2343 POP ready at Tue Nov 10 10:24:20 PST 2015
   2015-11-10 10:24:20,048 DEBUG [PopConnection-43843] davmail - < CAPA
   2015-11-10 10:24:20,048 DEBUG [PopConnection-43843] davmail - > +OK Capability list follows
   2015-11-10 10:24:20,048 DEBUG [PopConnection-43843] davmail - > TOP
   2015-11-10 10:24:20,048 DEBUG [PopConnection-43843] davmail - > USER
   2015-11-10 10:24:20,048 DEBUG [PopConnection-43843] davmail - > UIDL
   2015-11-10 10:24:20,049 DEBUG [PopConnection-43843] davmail - > .
   2015-11-10 10:24:20,151 DEBUG [PopConnection-43843] davmail - < USER companyname\username
   2015-11-10 10:24:20,151 DEBUG [PopConnection-43843] davmail - > +OK USER : companyname\username
   2015-11-10 10:24:20,151 DEBUG [PopConnection-43843] davmail - < PASS **
   2015-11-10 10:24:20,172 DEBUG [PopConnection-43843] davmail - executeFollowRedirects(https://outlook.companyname.com/ews/exchange.asmx)

3. After some time, Thunderbird raises an error message:
   "Sending of password for user companyname\username did not succeed. Mail server localhost responded: USER : companyname\username"
   In a few minutes, DavMail timeouts as well.
   DavMail output:
   2015-11-10 10:27:03,180 ERROR [PopConnection-43843] davmail.exchange.ExchangeSession - Operation timed out
   java.net.SocketException: Operation timed out
   at java.net.SocketInputStream.socketRead0(Native Method)
   at java.net.SocketInputStream.read(SocketInputStream.java:152)
   at java.net.SocketInputStream.read(SocketInputStream.java:122)
   at sun.security.ssl.InputRecord.readFully(InputRecord.java:442)
   at sun.security.ssl.InputRecord.read(InputRecord.java:480)
   at sun.security.ssl.SSLSocketImpl.readRecord(SSLSocketImpl.java:934)
   at sun.security.ssl.SSLSocketImpl.readDataRecord(SSLSocketImpl.java:891)
   at sun.security.ssl.AppInputStream.read(AppInputStream.java:102)
   at java.io.BufferedInputStream.fill(BufferedInputStream.java:235)
   at java.io.BufferedInputStream.read(BufferedInputStream.java:254)
   at org.apache.commons.httpclient.HttpParser.readRawLine(HttpParser.java:78)
   at org.apache.commons.httpclient.HttpParser.readLine(HttpParser.java:106)
   at org.apache.commons.httpclient.HttpConnection.readLine(HttpConnection.java:1116)
   at org.apache.commons.httpclient.MultiThreadedHttpConnectionManager$HttpConnectionAdapter.readLine(MultiThreadedHttpConnectionManager.java:1413)
   at org.apache.commons.httpclient.HttpMethodBase.readStatusLine(HttpMethodBase.java:1973)
   at org.apache.commons.httpclient.HttpMethodBase.readResponse(HttpMethodBase.java:1735)
   at org.apache.commons.httpclient.HttpMethodBase.execute(HttpMethodBase.java:1098)
   at org.apache.commons.httpclient.HttpMethodDirector.executeWithRetry(HttpMethodDirector.java:398)
   at org.apache.commons.httpclient.HttpMethodDirector.executeMethod(HttpMethodDirector.java:171)
   at org.apache.commons.httpclient.HttpClient.executeMethod(HttpClient.java:397)
   at org.apache.commons.httpclient.HttpClient.executeMethod(HttpClient.java:323)
   at davmail.exchange.ews.EwsExchangeSession.executeMethod(EwsExchangeSession.java:2377)
   at davmail.exchange.ews.EwsExchangeSession.internalGetFolder(EwsExchangeSession.java:1170)
   at davmail.exchange.ews.EwsExchangeSession.buildSessionInfo(EwsExchangeSession.java:289)
   at davmail.exchange.ExchangeSession.<init>(ExchangeSession.java:235)
   at davmail.exchange.ews.EwsExchangeSession.<init>(EwsExchangeSession.java:138)
   at davmail.exchange.ExchangeSessionFactory.getInstance(ExchangeSessionFactory.java:143)
   at davmail.exchange.ExchangeSessionFactory.getInstance(ExchangeSessionFactory.java:90)
   at davmail.pop.PopConnection.run(PopConnection.java:140)
   2015-11-10 10:27:03,183 ERROR [PopConnection-43843] davmail.exchange.ExchangeSession - EWS end point not available
   2015-11-10 10:27:03,183 ERROR [PopConnection-43843] davmail - EWS end point not available
   davmail.exception.DavMailAuthenticationException: EWS end point not available
   at davmail.exchange.ews.EwsExchangeSession.buildSessionInfo(EwsExchangeSession.java:299)
   at davmail.exchange.ExchangeSession.<init>(ExchangeSession.java:235)
   at davmail.exchange.ews.EwsExchangeSession.<init>(EwsExchangeSession.java:138)
   at davmail.exchange.ExchangeSessionFactory.getInstance(ExchangeSessionFactory.java:143)
   at davmail.exchange.ExchangeSessionFactory.getInstance(ExchangeSessionFactory.java:90)
   at davmail.pop.PopConnection.run(PopConnection.java:140)
   2015-11-10 10:27:03,183 DEBUG [PopConnection-43843] davmail - > -ERR EWS end point not available
   2015-11-10 10:27:03,183 DEBUG [PopConnection-43843] davmail - Connection closed

4. Click "Retry" in Thunderbird.
   DavMail output:
   2015-11-10 10:28:01,240 DEBUG [davmail.pop.PopServer] davmail - Connection from /127.0.0.1 on port 1110
   2015-11-10 10:28:01,825 DEBUG [PopConnection-12640] davmail.exchange.ExchangeSession - Test configuration status: 401
   2015-11-10 10:28:01,825 DEBUG [PopConnection-12640] davmail - > +OK DavMail 4.6.1-2343 POP ready at Tue Nov 10 10:28:01 PST 2015
   2015-11-10 10:28:01,826 DEBUG [PopConnection-12640] davmail - < CAPA
   2015-11-10 10:28:01,826 DEBUG [PopConnection-12640] davmail - > +OK Capability list follows
   2015-11-10 10:28:01,826 DEBUG [PopConnection-12640] davmail - > TOP
   2015-11-10 10:28:01,826 DEBUG [PopConnection-12640] davmail - > USER
   2015-11-10 10:28:01,826 DEBUG [PopConnection-12640] davmail - > UIDL
   2015-11-10 10:28:01,826 DEBUG [PopConnection-12640] davmail - > .
   2015-11-10 10:28:01,926 DEBUG [PopConnection-12640] davmail - < USER companyname\username
   2015-11-10 10:28:01,926 DEBUG [PopConnection-12640] davmail - > +OK USER : companyname\username
   2015-11-10 10:28:01,927 DEBUG [PopConnection-12640] davmail - < PASS **
   2015-11-10 10:28:01,927 DEBUG [PopConnection-12640] davmail - executeFollowRedirects(https://outlook.companyname.com/ews/exchange.asmx)
   2015-11-10 10:28:02,227 DEBUG [PopConnection-12640] davmail - executeFollowRedirects: /ews/Services.wsdl redirectCount:1

(it always succeeds in getting /ews/Services.wsdl on this second, "retry" attempt).

1. After some time, Thunderbird raises same error message:
   "Sending of password for user companyname\username did not succeed. Mail server localhost responded: USER : companyname\username"
   In a few minutes, DavMail timeouts as well (this time with no exception)
   DavMail output:
   2015-11-10 10:30:44,754 DEBUG [PopConnection-12640] davmail.exchange.ExchangeSession - Operation timed out
   2015-11-10 10:30:47,135 DEBUG [PopConnection-12640] davmail.exchange.ExchangeSession - Current user email is username@companyname.com, alias is username on Exchange2010_SP1
   2015-11-10 10:30:47,135 DEBUG [PopConnection-12640] davmail.exchange.ExchangeSession - Session davmail.exchange.ews.EwsExchangeSession@2354e586 created
   2015-11-10 10:30:47,135 DEBUG [PopConnection-12640] davmail.exchange.ExchangeSession - Created new session davmail.exchange.ews.EwsExchangeSession@2354e586 for user companyname\username
   2015-11-10 10:30:47,135 DEBUG [PopConnection-12640] davmail - > +OK PASS
   2015-11-10 10:30:47,135 DEBUG [PopConnection-12640] davmail - Connection closed

2. Click "Retry" in Thunderbird.
   This time everything goes fine, email client gets all messages.
   DavMail output:
   2015-11-10 10:31:40,693 DEBUG [davmail.pop.PopServer] davmail - Connection from /127.0.0.1 on port 1110
   2015-11-10 10:31:41,162 DEBUG [PopConnection-25287] davmail.exchange.ExchangeSession - Test configuration status: 401
   2015-11-10 10:31:41,162 DEBUG [PopConnection-25287] davmail - > +OK DavMail 4.6.1-2343 POP ready at Tue Nov 10 10:31:41 PST 2015
   2015-11-10 10:31:41,163 DEBUG [PopConnection-25287] davmail - < CAPA
   2015-11-10 10:31:41,163 DEBUG [PopConnection-25287] davmail - > +OK Capability list follows
   2015-11-10 10:31:41,163 DEBUG [PopConnection-25287] davmail - > TOP
   2015-11-10 10:31:41,163 DEBUG [PopConnection-25287] davmail - > USER
   2015-11-10 10:31:41,163 DEBUG [PopConnection-25287] davmail - > UIDL
   2015-11-10 10:31:41,163 DEBUG [PopConnection-25287] davmail - > .
   2015-11-10 10:31:41,267 DEBUG [PopConnection-25287] davmail - < USER companyname\username
   2015-11-10 10:31:41,267 DEBUG [PopConnection-25287] davmail - > +OK USER : companyname\username
   2015-11-10 10:31:41,267 DEBUG [PopConnection-25287] davmail - < PASS **
   2015-11-10 10:31:41,267 DEBUG [PopConnection-25287] davmail.exchange.ExchangeSession - Got session davmail.exchange.ews.EwsExchangeSession@2354e586 from cache
   2015-11-10 10:31:41,344 DEBUG [PopConnection-25287] davmail - > +OK PASS
   2015-11-10 10:31:41,344 DEBUG [PopConnection-25287] davmail - < STAT
   2015-11-10 10:31:41,489 DEBUG [PopConnection-25287] davmail.exchange.ExchangeSession - Folder INBOX - Search items current count: 166 fetchCount: 500 highest uid: 24298 lowest uid: 24130
   ...

[Mickael Guessant]

This is definitely a server side issue: when you access wsdl you only need the CAS (IIS) server.
However to access your mailbox CAS must reach the mailbox server behind.

You should probably check mailbox access with Microsoft provided EWSEditor.

[Robert Ayrapetyan]

Yes, I can't observe this behaviour anymore - looks like it was a temp glitch after switching to the 2010 version. Please close this issue.