United StatesChange Country, Oracle Worldwide Web Sites Communities I am a... I want to...
JDK-7074436 : (sc) SocketChannel can do short gathering writes when channel configured blocking (win)

Details
Type:
Bug
Submit Date:
2011-08-03
Status:
Closed
Updated Date:
2014-02-12
Project Name:
JDK
Resolved Date:
2013-10-22
Component:
core-libs
OS:
windows_2008
Sub-Component:
java.nio
CPU:
x86
Priority:
P3
Resolution:
Fixed
Affected Versions:
7
Fixed Versions:

Related Reports
Backport:
Backport:
Backport:
Relates:
Relates:

Sub Tasks

Description
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).

                                    

Comments
SQE is ok to take the fix in 7u60.
                                     
2013-12-19
URL:   http://hg.openjdk.java.net/jdk8/jdk8/jdk/rev/54869853c06c
User:  lana
Date:  2013-11-05 21:09:17 +0000

                                     
2013-11-05
The review thread for this change is here: http://mail.openjdk.java.net/pipermail/nio-dev/2013-October/002367.html
                                     
2013-10-22
URL:   http://hg.openjdk.java.net/jdk8/tl/jdk/rev/54869853c06c
User:  alanb
Date:  2013-10-22 13:21:15 +0000

                                     
2013-10-22
EVALUATION

The issue with SocketChannel.write(ByteBuffer) doing short writes on Windows has been fixed by 7176630. The remaining issue is the gathering write case, SocketChannel.write(ByteBuffer[]). This is more complicated/risky and will need to bake in jdk8 before we think about a 7u release.
                                     
2011-08-28
EVALUATION

The specification sets the expectation that the write will only return when all bytes have been written but it doesn't provide a guarantee. There are several reasons why all bytes may not be written - for example attempting a write with an array of buffers larger than IOV_MAX. The issue here is that we've introduced (via 6395224) another case where a short write is possible and this has exposed a bug in application/user code that wasn't previously checking the return value. We can partially fix this so that we make a best attempt to write all bytes but there will remain cases where a short write is possible - for example if the peer terminates the connection after some bytes have been written.
                                     
2011-08-03



Hardware and Software, Engineered to Work Together