Hi, I'm running into an interesting scenario with Restlet 2.1-RC6 with the Spring and Jackson extensions. I apologize for this lengthy message, and even though I have got to a point where I can consistently reproduce the scenario, I haven't been able to reduce it to a simple test case. So here it goes:
There are two standalone JSE processes, proc1 and proc2. They are long-running and exchange REST messages between themselves. There is a third client program which runs from command line from time to time to query some status data from proc1 via REST. It prints the status, and exits. Occasionally this client would hang after sending the status request. If I turn Restlet logging to TRACE (in slf4j), client would get stuck proc1 seems to always stop after the NIO controller prints a "about to sleep" message. While the client is waiting there, if I somehow cause proc2 to send proc1 any request, it would actually wake up the selector in proc1. It would start processing proc2's request, then proceed to write the previously hanging response to the client. In proc1's log it would seem like the NIO controller gets waken up with a "selected 1 key" message. I'm attaching a fragment of the log, with the big gap between the two NIO controller messages marked. I understand that there aren't a lot of concrete data to work with, but any thoughts or pointers are much welcome and appreciated. Thanks -jx --- 22:50:41.002 TRACE Restlet-1186010055 [ ] org.restlet NIO controller woke up --- 22:50:41.002 TRACE Restlet-35138160 [ ] org.restlet NIO controlled selected no key --- 22:50:41.002 TRACE Restlet-35138160 [ ] org.restlet Handling response... --- 22:50:41.002 TRACE Restlet-35138160 [ ] org.restlet Connection status: CLOSED | IDLE, IDLE, java.nio.HeapByteBuffer[pos=0 lim=16384 cap=16384], FILLING, true | IDLE, IDLE, java.nio.HeapByteBuffer[pos=0 lim=32768 cap=32768], FILLING, true | true|Interest= READ , Ready=NONE , Canceling=false --- 22:50:41.003 TRACE Restlet-35138160 [ ] org.restlet InboundWay#clear: IDLE, IDLE, java.nio.HeapByteBuffer[pos=0 lim=16384 cap=16384], FILLING, true --- 22:50:41.003 TRACE Restlet-35138160 [ ] org.restlet OutboundWay#clear: IDLE, IDLE, java.nio.HeapByteBuffer[pos=0 lim=32768 cap=32768], FILLING, true --- 22:50:41.003 TRACE Restlet-35138160 [ ] org.restlet InboundWay#clear: IDLE, IDLE, java.nio.HeapByteBuffer[pos=0 lim=16384 cap=16384], FILLING, true --- 22:50:41.003 TRACE Restlet-35138160 [ ] org.restlet OutboundWay#clear: IDLE, IDLE, java.nio.HeapByteBuffer[pos=0 lim=32768 cap=32768], FILLING, true --- 22:50:41.003 TRACE Restlet-35138160 [ ] org.restlet NIO controller about to sleep 1 ms... ==========>>GAP HERE<<=========== No more logging from restlet here until another request comes in below. =============================== --- 22:50:51.100 TRACE Restlet-35138160 [ ] org.restlet NIO controller selected 1 key(s) ! --- 22:50:51.100 TRACE Restlet-35138160 [ ] org.restlet ReadableSocketChannel created from: java.nio.channels.SocketChannel[connected local=/127.0.0.1:9494 remote=/127.0.0.1:52530],Interest= NONE , Ready=NONE , Canceling=false. Registration: Interest= NONE , Ready=NONE , Canceling=false --- 22:50:51.100 TRACE Restlet-35138160 [ ] org.restlet Connection state (old | new) : OPENING | OPEN --- 22:50:51.100 TRACE Restlet-35138160 [ ] org.restlet InboundWay#setIoState: INTEREST --- 22:50:51.100 TRACE Restlet-35138160 [ ] org.restlet InboundWay#setMessageState: START --- 22:50:51.100 TRACE Restlet-35138160 [ ] org.restlet Old connection NIO interest: Interest= NONE , Ready=NONE , Canceling=false --- 22:50:51.100 TRACE Restlet-35138160 [ ] org.restlet New connection NIO interest: Interest= READ , Ready=NONE , Canceling=false --- 22:50:51.101 DEBUG Restlet-35138160 [ ] org.restlet Connection from "/127.0.0.1:52530" accepted. New count: 2 --- 22:50:51.101 TRACE Restlet-35138160 [ ] org.restlet Connection status: OPEN | IDLE, IDLE, java.nio.HeapByteBuffer[pos=253 lim=253 cap=16384], DRAINING, true | IDLE, IDLE, java.nio.HeapByteBuffer[pos=0 lim=32768 cap=32768], FILLING, true | false|Interest= READ , Ready=READ , Canceling=false --- 22:50:51.101 TRACE Restlet-35138160 [ ] org.restlet InboundWay#setMessageState: START --- 22:50:51.101 TRACE Restlet-35138160 [ ] org.restlet OutboundWay#setIoState: INTEREST --- 22:50:51.101 TRACE Restlet-35138160 [ ] org.restlet OutboundWay#setMessageState: START --- 22:50:51.101 TRACE Restlet-35138160 [ ] org.restlet Old connection NIO interest: Interest= READ , Ready=READ , Canceling=false --- 22:50:51.101 TRACE Restlet-35138160 [ ] org.restlet New connection NIO interest: Interest= WRITE , Ready=NONE , Canceling=false --- 22:50:51.101 TRACE Restlet-35138160 [ ] org.restlet Connection status: OPEN | INTEREST, START, java.nio.HeapByteBuffer[pos=0 lim=16384 cap=16384], FILLING, true | IDLE, IDLE, java.nio.HeapByteBuffer[pos=0 lim=32768 cap=32768], FILLING, true | true|Interest= READ , Ready=NONE , Canceling=false --- 22:50:51.101 TRACE Restlet-35138160 [ ] org.restlet Registering new NIO interest with selector: Interest= READ , Ready=NONE , Canceling=false --- 22:50:51.101 TRACE Restlet-35138160 [ ] org.restlet Updating NIO interest with selector: Interest= WRITE , Ready=NONE , Canceling=false --- 22:50:51.101 TRACE Restlet-35138160 [ ] org.restlet Update key (old | new) : READ | WRITE --- 22:50:51.101 TRACE Restlet-35138160 [ ] org.restlet NIO controller about to sleep 1 ms... --- 22:50:51.102 TRACE Restlet-35138160 [ ] org.restlet NIO controller selected 1 key(s) ! --- 22:50:51.102 TRACE Restlet-35138160 [ ] org.restlet NIO selection detected for key: sun.nio.ch.SelectionKeyImpl@3c6b93c5 --- 22:50:51.102 TRACE Restlet-35138160 [ ] org.restlet Server connection (state | inbound | outbound): OPEN | IDLE, START, java.nio.HeapByteBuffer[pos=253 lim=253 cap=16384], DRAINING, true | INTEREST, START, java.nio.HeapByteBuffer[pos=0 lim=32768 cap=32768], FILLING, true | false|Interest= WRITE , Ready=WRITE , Canceling=false --- 22:50:51.102 TRACE Restlet-35138160 [ ] org.restlet Server NIO selection (interest | ready | cancelled): Interest= WRITE , Ready=WRITE , Canceling=false --- 22:50:51.102 TRACE Restlet-35138160 [ ] org.restlet OutboundWay#setIoState: PROCESSING --- 22:50:51.102 TRACE Restlet-35138160 [ ] org.restlet Outbound way selected. Processing IO for : PROCESSING, START, java.nio.HeapByteBuffer[pos=0 lim=32768 cap=32768], FILLING, true --- 22:50:51.102 TRACE Restlet-35138160 [ ] org.restlet Beginning process of buffer java.nio.HeapByteBuffer[pos=0 lim=32768 cap=32768], FILLING, true --- 22:50:51.102 TRACE Restlet-35138160 [ ] org.restlet 0 bytes drained from buffer at pre-processing, 32768 remaining bytes --- 22:50:51.102 TRACE Restlet-35138160 [ ] org.restlet Filling buffer java.nio.HeapByteBuffer[pos=0 lim=32768 cap=32768], FILLING, true --- 22:50:51.102 DEBUG Restlet-35138160 [ ] org.restlet Writing message to /127.0.0.1:52529 ------------------------------------------------------ http://restlet.tigris.org/ds/viewMessage.do?dsForumId=4447&dsMessageId=3005493
