iocp reactor fails to support PB & AMP

[dynamicgl]

When running the attached files, I noticed weird exceptions like Connection Lost raised.

If I used a bigger value for reactor.callLater on server side, It ran fine without any problem. I ran a similar test with AMP and got the same problem with different errors.

Because these errors didnt' exist when I used select reactor so I guess the current implementation of iocp reactor might have some problems about sending chunks data continuously.

OS: Win 7 64 bit Python version: 2.6.6 (32 bit) Twisted version: 12.0 & 11.1

[ivank]

I have observed the IOCP reactor send data completely out of order. I was using twisted.web, and saw things like:

1. HTTP responses never closing

2. Truncated HTTP responses

3. The most horrifying: all HTTP chunk lengths arriving first, then the chunk contents

I was using Twisted trunk (2012-03-03), Python 2.7.1 32-bit, Server 2008 R2 SP1 64-bit.

I tried the IOCP reactor before iocp-64bit-5373-2 and before iocp-win64-4669, but it exhibited the same problems. I have no problems with the select reactor.

Sorry for the lack of test case. I am fairly sure this problem could be reproduced by doing request.write(small_piece) 100,000 times.

[itamar]

Looking at the IOCP code, it looks like writes can be initiated because a previous write finished, or by startWriting being called after a short amount of time since the last startWriting. So that may be the issue - two or more sequences of writes happening, instead of just one.

Pavel, could you take a look?

[dynamicgl]

I have read some parts of codes for iocp support and ran some trials. It seems once the buffer is full (SEND_LIMIT is 128 K bytes), an ERROR_IO_PENDING will be returned and then

exceptions raise on client side.

two possible ways to work around:

1 change SEND_LIMIT to other values like 256K. 2 don't send too much data in a very short period.

[itamarst]

(In [34396]) Branching to 'iocp-5562'

[itamar]

Poking around I discovered that the problem is indeed reproduceable with the example script; something todo with abstract.py or tcp.py, but I couldn't get any further. Handing back to Pavel.

[dynamicgl]

Hi All

I attached a patch for this issue. I think the first two files can be used for testing purpose. Please feel free to have a look.

Thanks.

[itamar]

First, thanks for working on this; I tried to, and failed, and this is a serious bug, so it'd be really great to get the fix in.

However, the demonstration files are far too complex to serve as unit tests. Consider what happens if someone changes the implementation of PB for some reason, and coincidentally it no longer hits the edge case that causes the problem. Suddenly the test is not testing what you think it's testing. Ideally you'd just have a simple Protocol that did a few writes to demonstrate the problem; try writing a prose explanation of the problem and then translating it into the least code possible. twisted.internet.test.test_tcp has a bunch of tests that might serve as a template, and demonstrates the ReactorBuilder infrastructure you'd want to use.

[dynamicgl]

Replying to itamar:

First, thanks for working on this; I tried to, and failed, and this is a serious bug, so it'd be really great to get the fix in. However, the demonstration files are far too complex to serve as unit tests. Consider what happens if someone changes the implementation of PB for some reason, and coincidentally it no longer hits the edge case that causes the problem. Suddenly the test is not testing what you think it's testing. Ideally you'd just have a simple Protocol that did a few writes to demonstrate the problem; try writing a prose explanation of the problem and then translating it into the least code possible. twisted.internet.test.test_tcp has a bunch of tests that might serve as a template, and demonstrates the ReactorBuilder infrastructure you'd want to use.

Sorry about that, I didn't see your action before I typed. Ok, I will try to write a formal test case for that.

I think this issue can be reproduced by sending some small chunks data continuously just like ivank said, however I didn't make such that case before. Anyway I try to make a simple test case.

[dynamicgl]

Hi All

I attach a test case for this bug. A server script is also attached. In fact this bug can't be reproduced (at least on my machine) when both of server & client running in the same process.

please feel free to check it.

Thanks.

[dynamicgl]

I also attach a patch. The previous patch contains a bug which may lead to infinitely schedule the doWrite method.

please ignore the first patch.

Thanks.

[itamar]

Thanks for putting all this work into fixing this, and for writing the unit test.

However, if we can't run the test within the same process, we can't automate it very easily, and the idea is that unit tests run automatically ( http://buildbot.twistedmatrix.com/boxes-supported). Also, your test seems a bit overcomplicated. In your email posting you (I assume it was you?) described the bug as follows:

The problem is doWrite method might be triggered twice instead of once; in particular, when trying to send a large chunks data whose size is bigger then SEND_LIMIT, it will always happen. When doWrite being invoked twice, it means the same buffer data will be sent twice.

Doing a write bigger than SEND_LIMIT seems like it would be simpler to do in a test than what you're doing now. Could you see if you can reproduce the bug that way in a unit test?

[dynamicgl]

Hi Itammar

I attached a modified test case for that. Actually this bug can be reproduced by using a normal test case as long as you run that several times. Failure is not deterministic so it is why I said it couldn't be reproduced at first.

In this test case, the client initiates sending a large chunks data and then collect all data from server. The server simply send back all data got from client. Eventually the client should get exactly what it sent, the same data and the same size.

Many parts of this test case are copied from test_tcp.py, so it looks like messy, sorry about that.

[exarkun]

I applied a modified version of the test to the branch. Unfortunately I wasn't able to get it to fail (partly due to  a problem with one of our development tools). If you can see what's wrong with my version of the test, that'd be quite helpful - http://twistedmatrix.com/trac/browser/branches/iocp-5562/twisted/internet/test/test_tcp.py#L364

[dynamicgl]

Hi exarkun

You didn't do anything wrong. This bug is not always reproduced when both server and client running at the same process. You can reproduced it by running the test case several times? How many times? I don't know. Sometimes It failed on the second trial but sometimes after 50 trials.

I modified the original scripts and let server & client run in the same process. Guess what? the bug disappeared !!! I ran the script ten times and got a flawless result. If I ran in two separate process, the bug raised at the first round.

I am not an expert on network programming especially on how windows playing socket under the hood.

Do you have any idea what is different between socket communications in process and socket communications interprocess on windows? If I do know that detail, maybe I can try to simulate it.

Thanks

[BrianMatthews]

I tried the fix attached by dynamicgl. It fixed the problem, but it has the side effect of creating 10's, and possible 100's of unnecessary callLater's. The problem is the databuffer and offset are being modified by doWrite when a write is in progress. The resultant modification by the callback method _doWrite() is using the wrong offset.

[BrianMatthews]

Sorry, I meant the callback _cbWrite(), not _doWrite()

[exarkun]

Thanks for looking into this Brian. fwiw, if someone does the hard part of creating a reliably failing unit test, I'd be happy to look into how to implement a solution that doesn't involve the extra delayed calls (or investigate sufficiently to demonstrate that the extra calls aren't worth worrying about).

[BrianMatthews]

Ok I will try to do that some time today. I have another ticket open which is connected to this, #6217. The fix I did for that seems to make this problem worse.

[BrianMatthews]

Well that was easy! If you apply my fix from #6217, then your unit test 5562_test3.py fails immediately. Your fix does fix it, but with lots of extra calls. As I suspected, the #6217 bug was helping to mask this bug.

[BrianMatthews]

BTW the number of extra callLaters in 5562_test3.py after applying your fix was 4005.

[exarkun]

Well that was easy! If you apply my fix from #6217, then your unit test 5562_test3.py fails immediately. Your fix does fix it, but with lots of extra calls. As I suspected, the #6217 bug was helping to mask this bug.

Hmm. My problem with 5562_test3.py is that I could not get it to fail deterministically when run against current trunk. I checked my attempt at this into the branch identified in the ticket description (iocp-5562). Did you see the test fail deterministically against trunk?

[BrianMatthews]

OK, well the way to do it is overwhelm it with data. I have attached a version of your test_tcp.py that for me fails every time on the trunk code.

[exarkun]

Thanks! I'll give that a shot.

For future reference, a patch file is generally preferred. These are easily generated with the "svn diff" command once you have edited a file in an svn checkout (if you're using one of the other vcs mirrors, they all have similar commands too).

[dynamicgl]

Replying to BrianMatthews:

Well that was easy! If you apply my fix from #6217, then your unit test 5562_test3.py fails immediately. Your fix does fix it, but with lots of extra calls. As I suspected, the #6217 bug was helping to mask this bug.

Hi Brian

I am delighted you have some thoughts about that. I am not an expert on windows network programming and IOCP as well. The patch I provided can be considered as a work around and far away from an optimistic solution.

Yes, it has a side effect about unnecessary scheduling. As long as there is a way that doWrite & cbWrite are invoked in order, we can remove these scheduling safely.

Any idea?

[BrianMatthews]

exarkun is looking at it now, but one thing I did try was replacing

if self._doWriteCalling:

self.reactor.callLater(0, self._resumeWriting)

with

if self._doWriteCalling:

return

which seemed to work OK. _cbWrite is going to call doWrite anyway...

[BrianMatthews]

I also notice that the WSASend is returning the number of bytes written if it returns successfull immediately. It is my understanding that the I/O event will still occur even it it completes immediately. A 0 error return should be processed exactly the same as a WSA_IO_PENDING return, and the number of bytes returned when the error is 0 should be ignored.

[BrianMatthews]

Ignore previous comment. Looking closer, it does indeed ignore the immediate return.

[BrianMatthews]

My suggested fix, unified diff attached as abstract.diff

[BrianMatthews]

oops, typo in diff. Use abstract.diff2

[BrianMatthews]

readBufferSize is set to 4096. This makes the test very slow (40+ seconds) Setting it to 65K (2**2**2**2) as in other reactors makes it much faster, maybe 5-10 times. Is there any reason why this cant be used in iocpreactor?

[dynamicgl]

Replying to BrianMatthews:

readBufferSize is set to 4096. This makes the test very slow (40+ seconds) Setting it to 65K (2**2**2**2) as in other reactors makes it much faster, maybe 5-10 times. Is there any reason why this cant be used in iocpreactor?

Hi Brian

I also noticed this problem a few months ago. It looks like there is no harm to set a bigger value. Maybe you can fire a ticket for this issue.