(sc) SocketChannel can do short gathering writes when channel configured blocking (win)

FULL PRODUCT VERSION :
java version "1.7.0"
Java(TM) SE Runtime Environment (build 1.7.0-b147)
Java HotSpot(TM) Client VM (build 21.0-b17, mixed mode, sharing)

ADDITIONAL OS VERSION INFORMATION :
Microsoft Windows [Version 6.0.6002]

A DESCRIPTION OF THE PROBLEM :
Gathered write to a blocking SocketChannel sometimes behaves non-blocking.
I.e. not all remaining bytes of all the buffers are written. Instead write returns less bytes written than bytes available in the buffers previous to the call.

Remarkably, the call allways returns after 131071 bytes written, independent of the actual size of the message (which is larger than 131071, of course)

Excerpt from the source code (with workaround in place):


final boolean d = logger.isDebugEnabled();
if (d) {
logger.debug("Sending " + size + " messages:");
for (final MuxClientMessage msg : msgs)
logger.debug("Message: " + msg);
}

if (!serverChannel.isConnected()) {
logger.info("Server output closed");
break;
}

// Write all the messages
//
final long wrote;
{
// Build the array of buffers
//
final ByteBuffer[] bufs = new ByteBuffer[2*size];
for (int i=0; i<size; i++) {
final MuxClientMessage msg = msgs.get(i);
final int bi = 2*i;
final ByteBuffer connectionIdBuffer = msg.getConnectionIdBuffer();
connectionIdBuffer.position(0);
connectionIdBuffer.limit(4);
bufs[bi] = connectionIdBuffer;
bufs[bi+1] = msg.getMessageBuffer();
if (d) logger.debug("Set buffers for msg " + i + ": id=" + connectionIdBuffer + " msg=" + msg.getMessageBuffer());
}

boolean rem;
long tot = 0;
if (d) logger.debug("Writing to channel " + serverChannel + " isBlocking=" + serverChannel.isBlocking());
do {
final long w = serverChannel.write(bufs);
if (d) logger.debug("Wrote " + w + " bytes");
tot += w;
rem = false;
for (int i=0; i<bufs.length; i++) {
if (d) logger.debug("Checking buf[" + i + "]: " + bufs[i]);
if (bufs[i].hasRemaining()) {
rem = true;
}
}
if (rem) logger.warn("RRR");
} while (rem);
wrote = tot;
}

// Flag delivery
if (d) logger.debug("Wrote " + wrote + " bytes, flagging delivery for " + size + " messages:");

Excerpt from 20MB log file:

2011-08-03 11:45:20,639 DEBUG [Sender(MuxServerHandle#1(55411))] prince.middleware.mwproxy.mux.MuxServerHandle - Sending 1 messages:
2011-08-03 11:45:20,639 DEBUG [Sender(MuxServerHandle#1(55411))] prince.middleware.mwproxy.mux.MuxServerHandle - Message: MuxClientMessage#4(MuxClientHandle#364(54933, /15.3.222.48:29441), len=131594)
2011-08-03 11:45:20,639 DEBUG [Sender(MuxServerHandle#1(55411))] prince.middleware.mwproxy.mux.MuxServerHandle - Set buffers for msg 0: id=java.nio.DirectByteBuffer[pos=0 lim=4 cap=8] msg=java.nio.DirectByteBufferR[pos=0 lim=131598 cap=163840]
2011-08-03 11:45:20,639 DEBUG [Sender(MuxServerHandle#1(55411))] prince.middleware.mwproxy.mux.MuxServerHandle - Writing to channel java.nio.channels.SocketChannel[connected local=/15.3.222.113:55411 remote=WLM1W632/15.3.222.113:1621] isBlocking=true
2011-08-03 11:45:20,639 DEBUG [Sender(MuxServerHandle#1(55411))] prince.middleware.mwproxy.mux.MuxServerHandle - Wrote 131071 bytes
2011-08-03 11:45:20,639 DEBUG [Sender(MuxServerHandle#1(55411))] prince.middleware.mwproxy.mux.MuxServerHandle - Checking buf[0]: java.nio.DirectByteBuffer[pos=4 lim=4 cap=8]
2011-08-03 11:45:20,639 DEBUG [Sender(MuxServerHandle#1(55411))] prince.middleware.mwproxy.mux.MuxServerHandle - Checking buf[1]: java.nio.DirectByteBufferR[pos=131067 lim=131598 cap=163840]
2011-08-03 11:45:20,639 WARN [Sender(MuxServerHandle#1(55411))] prince.middleware.mwproxy.mux.MuxServerHandle - RRR
2011-08-03 11:45:20,639 DEBUG [Sender(MuxServerHandle#1(55411))] prince.middleware.mwproxy.mux.MuxServerHandle - Wrote 531 bytes
2011-08-03 11:45:20,639 DEBUG [Sender(MuxServerHandle#1(55411))] prince.middleware.mwproxy.mux.MuxServerHandle - Checking buf[0]: java.nio.DirectByteBuffer[pos=4 lim=4 cap=8]
2011-08-03 11:45:20,639 DEBUG [Sender(MuxServerHandle#1(55411))] prince.middleware.mwproxy.mux.MuxServerHandle - Checking buf[1]: java.nio.DirectByteBufferR[pos=131598 lim=131598 cap=163840]
2011-08-03 11:45:20,639 DEBUG [Sender(MuxServerHandle#1(55411))] prince.middleware.mwproxy.mux.MuxServerHandle - Wrote 131602 bytes, flagging delivery for 1 messages:


REGRESSION. Last worked in version 6u26

STEPS TO FOLLOW TO REPRODUCE THE PROBLEM :
I have no means to reproduce the problem in isolated form as it occurs in a specific run in a dedicated grid of 32 test servers in a load test.


REPRODUCIBILITY :
This bug can be reproduced always.

CUSTOMER SUBMITTED WORKAROUND :
Loop over write until all bytes have been written (like in non-blocking mode).