Hello Jing, thanks for reporting this issue. At this moment, I have a simple advice to give. The internal connectors are not fully ready for production system, we still encourage you to use the Jetty and Simple extensions. Having said that, we are aware that in some cases the internal connectors freeze, and we are on the way to stabilize them. On our side we have some reproductible scenario that should help us to enhance these connectors, but need some time to fix the issues. Please stay tuned.
Best regards, Thierry Boileau 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 > ------------------------------------------------------ http://restlet.tigris.org/ds/viewMessage.do?dsForumId=4447&dsMessageId=3010416
