StreamingSubscriptionConnection.close() hangs

[dconnelly]

StreamingSubscriptionConnection.close() always seems to hang for me until the request timeout is reached. Here is a simple test case:

public void testClose() {
   ExchangeService es = new ExchangeService();
        es.setUrl(URI.create("https://outlook.office365.com/ews/exchange.asmx"));
        es.setCredentials(new WebCredentials('[email protected]', 'XXXX'));
        es.setTimeout(30000);
        es.setTraceEnabled(true);
        es.setTraceFlags(EnumSet.allOf(TraceFlags.class));
        es.setTraceListener((type, message) ->
            System.out.println("[" + type + "] " + message));
        StreamingSubscription subscription = es.subscribeToStreamingNotificationsOnAllFolders(EventType.NewMail);
        StreamingSubscriptionConnection connection = new StreamingSubscriptionConnection(es, 30);
        connection.addSubscription(subscription);
        connection.addOnNotificationEvent((sender, args) ->
                System.out.println("XXX got event!"));
        connection.addOnDisconnect((sender, args) ->
                System.out.println("XXX disconnected!"));
        connection.addOnSubscriptionError((sender, args) ->
                System.out.println("XXX subscription error: " + args.getException()));
        connection.open();
        Thread.sleep(1000);
        connection.close();
}

On my machine close() will hang for exactly 30 seconds, which is the configured request timeout.

Here are snippets of a thread dump taken while close() is stuck, starting with the notification stream response reader thread:

"pool-1-thread-1" #14 prio=5 os_prio=31 tid=0x00007f90b6857800 nid=0x6103 runnable [0x0000700001960000]
   java.lang.Thread.State: RUNNABLE
    at java.net.SocketInputStream.socketRead0(Native Method)
    at java.net.SocketInputStream.socketRead(SocketInputStream.java:116)
    at java.net.SocketInputStream.read(SocketInputStream.java:170)
    at java.net.SocketInputStream.read(SocketInputStream.java:141)
    at sun.security.ssl.InputRecord.readFully(InputRecord.java:465)
    at sun.security.ssl.InputRecord.read(InputRecord.java:503)
    at sun.security.ssl.SSLSocketImpl.readRecord(SSLSocketImpl.java:973)
    - locked <0x00000007738caa88> (a java.lang.Object)
    at sun.security.ssl.SSLSocketImpl.readDataRecord(SSLSocketImpl.java:930)
    at sun.security.ssl.AppInputStream.read(AppInputStream.java:105)
    - locked <0x00000007738a8778> (a sun.security.ssl.AppInputStream)
    at org.apache.http.impl.io.SessionInputBufferImpl.streamRead(SessionInputBufferImpl.java:139)
    at org.apache.http.impl.io.SessionInputBufferImpl.fillBuffer(SessionInputBufferImpl.java:155)
    at org.apache.http.impl.io.SessionInputBufferImpl.readLine(SessionInputBufferImpl.java:284)
    at org.apache.http.impl.io.ChunkedInputStream.getChunkSize(ChunkedInputStream.java:266)
    at org.apache.http.impl.io.ChunkedInputStream.nextChunk(ChunkedInputStream.java:227)
    at org.apache.http.impl.io.ChunkedInputStream.read(ChunkedInputStream.java:186)
    at org.apache.http.conn.EofSensorInputStream.read(EofSensorInputStream.java:137)
    at java.io.BufferedInputStream.fill(BufferedInputStream.java:246)
    at java.io.BufferedInputStream.read1(BufferedInputStream.java:286)
    at java.io.BufferedInputStream.read(BufferedInputStream.java:345)
    - locked <0x000000076b3423d8> (a java.io.BufferedInputStream)
    at microsoft.exchange.webservices.data.misc.HangingTraceStream.read(HangingTraceStream.java:117)
    at sun.nio.cs.StreamDecoder.readBytes(StreamDecoder.java:284)
    at sun.nio.cs.StreamDecoder.implRead(StreamDecoder.java:326)
    at sun.nio.cs.StreamDecoder.read(StreamDecoder.java:178)
    - locked <0x000000076b421de0> (a java.io.InputStreamReader)
    at java.io.InputStreamReader.read(InputStreamReader.java:184)
    at java.io.BufferedReader.fill(BufferedReader.java:161)
    at java.io.BufferedReader.read1(BufferedReader.java:212)
    at java.io.BufferedReader.read(BufferedReader.java:286)
    - locked <0x000000076b421de0> (a java.io.InputStreamReader)
    at com.sun.org.apache.xerces.internal.impl.XMLEntityScanner.load(XMLEntityScanner.java:1790)
    at com.sun.org.apache.xerces.internal.impl.XMLEntityScanner.arrangeCapacity(XMLEntityScanner.java:1661)
    at com.sun.org.apache.xerces.internal.impl.XMLEntityScanner.skipString(XMLEntityScanner.java:1726)
    at com.sun.org.apache.xerces.internal.impl.XMLDocumentScannerImpl$XMLDeclDriver.next(XMLDocumentScannerImpl.java:753)
    at com.sun.org.apache.xerces.internal.impl.XMLDocumentScannerImpl.next(XMLDocumentScannerImpl.java:606)
    at com.sun.org.apache.xerces.internal.impl.XMLNSDocumentScannerImpl.next(XMLNSDocumentScannerImpl.java:118)
    at com.sun.org.apache.xerces.internal.impl.XMLStreamReaderImpl.setInputSource(XMLStreamReaderImpl.java:202)
    at com.sun.org.apache.xerces.internal.impl.XMLStreamReaderImpl.<init>(XMLStreamReaderImpl.java:184)
    at com.sun.xml.internal.stream.XMLInputFactoryImpl.getXMLStreamReaderImpl(XMLInputFactoryImpl.java:262)
    at com.sun.xml.internal.stream.XMLInputFactoryImpl.createXMLStreamReader(XMLInputFactoryImpl.java:134)
    at com.sun.xml.internal.stream.XMLInputFactoryImpl.createXMLEventReader(XMLInputFactoryImpl.java:84)
    at microsoft.exchange.webservices.data.core.EwsServiceMultiResponseXmlReader.createXmlReader(EwsServiceMultiResponseXmlReader.java:90)
    at microsoft.exchange.webservices.data.core.EwsServiceMultiResponseXmlReader.initializeXmlReader(EwsServiceMultiResponseXmlReader.java:103)
    at microsoft.exchange.webservices.data.core.EwsXmlReader.<init>(EwsXmlReader.java:88)
    at microsoft.exchange.webservices.data.core.EwsServiceXmlReader.<init>(EwsServiceXmlReader.java:59)
    at microsoft.exchange.webservices.data.core.EwsServiceMultiResponseXmlReader.<init>(EwsServiceMultiResponseXmlReader.java:58)
    at microsoft.exchange.webservices.data.core.EwsServiceMultiResponseXmlReader.create(EwsServiceMultiResponseXmlReader.java:70)
    at microsoft.exchange.webservices.data.core.request.HangingServiceRequestBase.parseResponses(HangingServiceRequestBase.java:206)
    at microsoft.exchange.webservices.data.core.request.HangingServiceRequestBase.access$000(HangingServiceRequestBase.java:61)
    at microsoft.exchange.webservices.data.core.request.HangingServiceRequestBase$1.run(HangingServiceRequestBase.java:316)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
    at java.lang.Thread.run(Thread.java:745)

Next is my test code trying to close the connection:

"main" #1 prio=5 os_prio=31 tid=0x00007f90b3019800 nid=0x1703 waiting for monitor entry [0x0000700000217000]
   java.lang.Thread.State: BLOCKED (on object monitor)
    at sun.security.ssl.AppInputStream.read(AppInputStream.java:87)
    - waiting to lock <0x00000007738a8778> (a sun.security.ssl.AppInputStream)
    at org.apache.http.impl.io.SessionInputBufferImpl.streamRead(SessionInputBufferImpl.java:139)
    at org.apache.http.impl.io.SessionInputBufferImpl.fillBuffer(SessionInputBufferImpl.java:155)
    at org.apache.http.impl.io.SessionInputBufferImpl.readLine(SessionInputBufferImpl.java:284)
    at org.apache.http.impl.io.ChunkedInputStream.getChunkSize(ChunkedInputStream.java:266)
    at org.apache.http.impl.io.ChunkedInputStream.nextChunk(ChunkedInputStream.java:227)
    at org.apache.http.impl.io.ChunkedInputStream.read(ChunkedInputStream.java:186)
    at org.apache.http.impl.io.ChunkedInputStream.read(ChunkedInputStream.java:215)
    at org.apache.http.impl.io.ChunkedInputStream.close(ChunkedInputStream.java:316)
    at org.apache.http.impl.execchain.ResponseEntityProxy.streamClosed(ResponseEntityProxy.java:140)
    at org.apache.http.conn.EofSensorInputStream.checkClose(EofSensorInputStream.java:228)
    at org.apache.http.conn.EofSensorInputStream.close(EofSensorInputStream.java:174)
    at org.apache.http.util.EntityUtils.consume(EntityUtils.java:88)
    at microsoft.exchange.webservices.data.core.request.HttpClientWebRequest.close(HttpClientWebRequest.java:89)
    at org.apache.commons.io.IOUtils.closeQuietly(IOUtils.java:303)
    at microsoft.exchange.webservices.data.core.request.HangingServiceRequestBase.disconnect(HangingServiceRequestBase.java:269)
    - locked <0x000000076b1229e0> (a microsoft.exchange.webservices.data.core.request.GetStreamingEventsRequest)
    at microsoft.exchange.webservices.data.notification.StreamingSubscriptionConnection.close(StreamingSubscriptionConnection.java:347)
    - locked <0x000000076af7be60> (a microsoft.exchange.webservices.data.notification.StreamingSubscriptionConnection)

It appears as though closing the connection first attempts to consume the response entity associated with the streaming request, which is going to hang as long as the hanging request thread is still active since it holds the lock on the response stream.

Instead, we should probably just release the connection without attempting to consume the entity.

[yingnan-li]

Hi I also encounter the same issue and cannot find any solution online. Can you please explain on the meaning of 'just release the connection without attempting to consume the entity'? Thank you in advance!