#349 Errors when issuing multiple POST request simultaneous

[Anonymous]

Originally created by: nullable... (code.google.com)@gmail.com

What steps will reproduce the problem?
1. Extract the attached zip file
2. Build and run the demo application
3. Open IE9 and type http://localhost:8080/test.html
4. Press F12 to show the IE debugger and show the console
5. Press the button 'Test' and wait until you see 'LOG: complete, error count...'

What is the expected output? What do you see instead?
Expected output in the IE debugger console:
no timeouts, no errors

Actual output in the IE debugger console:
LOG: id: 2 (9/10), status: success
LOG: id: 1 (8/10), status: success
LOG: id: 4 (7/10), status: success
LOG: id: 5 (6/10), status: success
LOG: id: 3 (5/10), status: success
LOG: id: 9 (4/10), status: error
LOG: id: 6 (3/10), status: success
LOG: id: 7 (2/10), status: timeout
LOG: id: 8 (1/10), status: timeout
LOG: id: 10 (0/10), status: timeout
LOG: complete, error count: 4

What version of the product are you using? On what operating system?
The whole VS2010 project inclusive website is attached to demonstrate the problem.

mongoose rev: 8cdb0d40ce44
OS: Windows 7 32bit
Browser: IE9

Please provide any additional information below.
The demo program intrecepts POST requests for the url /echo and sends back the received post data.
The test.html website will issue several POST request (by using jquery) simultaneously and waits for the result (success, error, timeout).

Two problems are occurring (not everytime, but often):
1. The request is answered with an error
2. The request is not answered and therefore the timeout occurs

Observations:
- The problem seems to be rooted at a multithreading issue - probably related to using POST.
- Using the browser and server on the same machine (localhost) seems to intensify the problem.

[Anonymous]

Originally posted by: bel2... (code.google.com)@gmail.com

Unfortunately your test does not seem to run with Internet Explorer 8, and Internet Explorer 9 does not run on Windows XP.

So I made a modified Version of the test which runs for IE8 (and many other Browsers) and does not require a debug console in the browser. Furthermore it uses a CGI script "echo.cgi" in the same folder instead of a callback, so it can be tested with an unmodified mongoose. It actually does not matter what the cgi script sends, as long as it is valid a json object.

The test HTML is attached.

I tried it with 8 different browsers and the server running on both, win32 and linux, localhost and remote, with rather bad results: Actually all major browsers had troubles with the async post requests. Browsers based on Presto (Opera) and Trident (IE) had a lot of problems, but I also saw troubles with WebKit (Safari, Chrome, ..) and sometimes Gecko (Firefox) browsers. Since the error can be reproduced with different web engines, and with CGI as well as with callbacks, it is very likely an issue in the mongoose core implementation.

@nullable: Could you please have a quick look if the essential meaning of your test and mine is still the same (if not I will open another issue for this), and maybe try it with IE9.

[Anonymous]

Originally posted by: nullable... (code.google.com)@gmail.com

> @nullable: Could you please have a quick look if the essential meaning of your test and mine is still the same (if not I will open another issue for this), and maybe try it with IE9.

Your test HTML is showing (as i expect) the same problem. Thank you for investigating on this issue.

I forgot to say, that i tested also with the precompiled binary from this site (v3.1) in a similar manner like you and it shows the same problems. Probably you could attach the cgi script also?

BTW: IE9 can emulate IE8 and IE7.. :-)

The problem gets intensified the more CPU cores are available. On my Core 2 Duo it shows the problem relatively seldom - but on another machine with 8 cores it shows the problem very often. Defintly a multithreading issue.

[Anonymous]

Originally posted by: bel2... (code.google.com)@gmail.com

> Probably you could attach the cgi script also?

All files required for the test are here:
https://code.google.com/r/bel2125-mongoose/source/browse#hg%2Ftest%2Fajax
In case I make any improvements to the test, they will be available there as well.

The problem does also occur on single core ARM CPUs and forcing the server to a single CPU in Win32 (by SetProcessAffinityMask(GetCurrentProcess(), 1);) does not seem to make it better. So it is at least not a "multicore only" issue.
Also reducing the number of worker thread to one does not eliminate the problem, so I think it must be somewhere in the interaction between master thread and worker thread and/or the sockets.

The result of a test with IE8, just one worker thread and process affinity set to one core is attached as an image. The server log that belongs to the image is also attached. The test was performed on localhost at a WinXP machine which is strong and idle enough that there should be no timeout.

The log shows several errors:
- The test makes 10 async requests, but according to the
  log there are just 5 accesses to the resource
- "accepted socket", "queued socket" and "grabbed socket"
  occurs 9 times each
- The log shows one error 577 and one error 400

It seems that the POST data does not reach the right socket?

[Anonymous]

Originally posted by: valenok

Thanks for looking at this!
I am repeating bel2125's tests on macos, and don't see errors.
Let's narrow down the problem -- are we seeing this only on mongoose running on windows?
Do you guys see any trouble when mongoose is running on linux/bsd/mac?

[Anonymous]

Originally posted by: bel2... (code.google.com)@gmail.com

The errors can be observed on the following OS:
- Win7 (original post from nullable with IE9)
- WinXP (dual core X86 with my modified test; IE8 and other browsers)
- Linux (dual core X86, Debian V6)
- Linux (single core ARM)

I did the last three tests and found how often the problem occurs does not seem to depend on the platform but the browser.
Opera does not seem to understand the test at all, so I got only errors from that browser (or I made something wrong with this browser). Internet Explorer (I used 8, nullable used 9) showed a lot of errors, also Safari and Chrome did not do well. Firefox worked well with the 10 test cases, but instead of the "done" message below the result table it keeps showing "running" - other browsers do not. Embedded browsers and Aurora seem to work better. However, it is not an "Internet Explorer only" problem, it is just more frequent there - if you repeat the test more often you could see the problem with any major browser.

I also tested with LunarScape, which is a browser that supports three different web engines and found the same results.

In all my tests the server was running on real machines, not VMs. A virtual machine may show a different timing, so it is probably not ideal for this kind of test.
I do not have a MacOS computer available so I did not test it there.

[Anonymous]

Originally posted by: nullable... (code.google.com)@gmail.com

I changed my test a bit by giving each request another url - but still just returning the post data. I attached the original debug log of a session with a failure (one timeout) - and the same log grouped by requests.

What seems strange to me are the different get_request_len values:
2917 (/echo_x) or 2918 (/echo_xy) seems to be the correct length, but there also 2707 (/echo_1), 415 and 416.

I attached again my changed test - just for completness. There some other small changes as reporting no longer to the browsers debug console but displaying the result on the website.

[Anonymous]

Originally posted by: bel2... (code.google.com)@gmail.com

Unfortunately your test does again not run with Internet Explorer 8, which is the most recent version available for WinXP ("Object required, line 77, row 1").
Also my Qt Browser gets stuck after the first of ten retries.

Since my test shows basically the same phenomena I continued using mine.
In my CGI script I tried to store the post data in a file, just for analysis, but when I do this the test seems to work all the time. Write to files changes the timing or leads to a serialization of the requests at the file system operations.
Certainly this cannot be a solution to the issue, but only instrumentation.

Furthermore, the problem seems to depend on the size of the post data. On the other hand, the reply data is not relevant.

[Anonymous]

Originally posted by: nullable... (code.google.com)@gmail.com

Have you similar observations about the mentioned len stated in the debug output of get_request_len(..)?

I have noticed the same about the size of the post data.

[Anonymous]

Originally posted by: bel2... (code.google.com)@gmail.com

I made a simplified test with reduced data, basically just the ID:

data: { 'id' : id }

in this test I always get a CONTENT_LENGTH of 4 bytes (5 bytes for id=10), but there seems to be some error when receiving the post data in the CGI script - I did not analyze that in more detail yet, since my method of just writing all data in a file in the CGI script seems to change the timing too much.

[Anonymous]

Originally posted by: nullable... (code.google.com)@gmail.com

I made an additional observation:
I set num_threads to 1 and tried to load the initial web-site (http://localhost:8080/test.html of the second test provided by me.

Now the following files should be transferred:
- test.html
- jquery.js
- favicon.ico -> Not Found

If i make break point in consume_socket(..) and "synchronize" the calls this way, all is fine. If i don't have a break point, the client thread hang immediately in the recv(..) call of pull(..). It can't serve the files.

1. Can someone confirm this behaviour?
2. Is it probably related to the bug we are discussing here?

[Anonymous]

Originally posted by: bel2... (code.google.com)@gmail.com

I have some more test results, with the test scripts from https://code.google.com/r/bel2125-mongoose/source/browse#hg%2Ftest%2Fajax, Version [rcf8cef88d4ba]. In contrast to the earlier tests, the test data is no longer generated but specified explicitly in test.html.

In all Tests the "async POST" button was used - then nothing was done for about a minute - then again "async POST" was pressed ...

In case the test is used unmodified (test.html contains six lines of 'longText', echo.cgi does not write the data to file), almost no test works. One has to try very often to find one "success" in the test log.
-> see bad_case.log

In case the data is stored to a file (change line 47 in echo.cgi from doLogging = false to doLogging = true), the POST requests work well. I did not observe any errors yet.
-> see good_case.log

In case the data is not stored to a file but very short (comment out all "longtext" -lines in test.html, i.e. line 52-57), it works much better. The data is now basically just "id:1" and "async:true". The "errors" are relatively rare, but they are still there.
-> see short_post_data.log

Maybe the result depends on the fragmentation of the post data - at least it depends on the size. Indeed when looking at the logs, the lenghts differ much more in the bad case.

[Anonymous]

Originally posted by: bel2... (code.google.com)@gmail.com

> 1. Can someone confirm this behaviour?

I never had problems with any browser when loading the test page (test.html + jquery.js), not for t=1, not for t=10 - not with my test, not with yours. But I can only use IE8 - IE8 is not able to execute your scripts.

In my test sometimes threads are blocked for quite a while during the test, and if only one is available of course the entire server is blocked. I made most of the tests with my own clone (https://code.google.com/r/bel2125-mongoose/), beside some fixes for keep-alive it can be configured to close a socket forcefully when it is idle for 2 minutes. This way the server is never blocked completely for a longer time.

[Anonymous]

Originally posted by: nullable... (code.google.com)@gmail.com

I'm a bit confused... i recognized, that the problem is tight coupled with the number of CPUs you have. On my machine with 8 CPU i have big problems, as described also by simply loading the files (html, js, ..) without executing the javascript part. But even once loaded successfully, executing the javascript tests are failing (at a big part).

This is much less the case on my 2 CPU machine.

To get a bit deeper into this, i made a shortcut and processed every request directly on the master thread. I was very surprised to see the same problems even with only one (the master) thread! I attached my changed code (which is marked with a "DEBUG" comment). Unfortunatly i didn't yet converted the javascripts to be able running on IE8.

I hope i didn't messed up the code and my change is valid - otherwise let me know.

[Anonymous]

Originally posted by: bel2... (code.google.com)@gmail.com

I always had the problem on single core machines as well.
At a first glance your code changes look OK for me, but I did not test it yet.

I made a test with the standard server and 10 threads using the "fiddler2" web debugger. It can be used at the client PC to log the communication between server and client (probably not for localhost). One can clearly see that in some cases the server sents a 577 error (see attachment).

@nullable: Maybe you could provide such a log for your case too? It would be interesting if your test on your machine with your IE will also yield in a 577 server response.

[Anonymous]

Originally posted by: nullable... (code.google.com)@gmail.com

Here are some test results:

With fiddler and browser running on a VM:
Tests from comment 6: no problems, always 200 OK
Tests from comment 13: no problems, always 200 OK

Without fiddler - browser running on a VM:
Tests from comment 6: often timeouts
Tests from comment 13: often timeouts

With fiddler, browser and server running on the same machine (not a VM):
Tests from comment 6: no problems, always 200 OK
Tests from comment 13: no problems, always 200 OK

Without fiddler - browser and server running on the same machine (not a VM):
Tests from comment 6: often timeouts, some errors (XHR status code 12152)
Tests from comment 13: mostly could not load test.html and jquery.js, if loaded: often timeouts, some errors (XHR status code 12152)

I never got error 577. XHR status code 12152 seems to come from IE when the response is not valid.

[Anonymous]

Originally posted by: bel2... (code.google.com)@gmail.com

Hmm. Then the fiddler web debugging proxy changes the timing too much on your machine.

Did you see any error codes in the server debug log?

[Anonymous]

Originally posted by: nullable... (code.google.com)@gmail.com

The server debug log shows 404 (after the timeout) - i guess that is when the ajax timeout closes the connection, but the request was not fully received.

On monday i will try the same tests with mongoose version 3.1 and 2.12.

[Anonymous]

Originally posted by: nullable... (code.google.com)@gmail.com

I tested now version 3.2, 3.1 and 2.12 - the sources and binaries are contained in tests.zip.

The reports (server debug log and screenshot of the browser window after a test) are attached.

The tests were made on my 8 CPU machine with Win7 64bit using IE9.

All versions shows the problem.

[Anonymous]

Originally posted by: bel2... (code.google.com)@gmail.com

With some instrumentation I found that the errors arise somewhere in push and pull.
That there were no 577 errors in the test performed by nullable is because 577s are set in "forward_body_data" only, which is called for CGI pages but not for callbacks. Still the source of these errors could be the same, in the push/pull functions.

My push and pull functions with additional traces can be found as an attachment (together with forward_body_data), as well as the debug traces.

Still this does not explain WHY the functions fwrite and recv sometimes fail in push and pull.

[Anonymous]

Originally posted by: bel2... (code.google.com)@gmail.com

Since it is not really possible to see inside Internet Explorer, I made a test client to reproduce this issue. It can be found here: https://code.google.com/r/bel2125-mongoose/source/browse/#hg%2Ftestclient
The test client sends multiple parallel requests to the web server, and indeed the issue can be reproduced.

It turns out that it there are errors not only in simultaneous POST requests, but also in GET Requests (although not that frequent). I made tests with GET requests (0 bytes of data) as well as POST requests with 3, 1000 and 10000 bytes of data. The more data is sent with the POST requests, the higher the number of errors – but there are errors basically everywhere, even for GET.

/ajax/echo.cgi GET

CPUs (bit masks): process=3, system=3
Preparing test ... OK: 77 bytes of data
Starting multi client test: 20 cycles, 20 clients each

Test cylce 1 completed

Error: Client 2002 got 0 bytes instead of 77
Error: Client 2018 got 0 bytes instead of 77
Test cylce 2 completed

Test cylce 3 completed

Test cylce 4 completed
...

/ajax/echo.cgi POST 3

CPUs (bit masks): process=3, system=3
Preparing test ... OK: 95 bytes of data
Starting multi client test: 20 cycles, 20 clients each

Error: Client 1005 got 0 bytes instead of 95
Test cylce 1 completed

Test cylce 2 completed

Test cylce 3 completed

Test cylce 4 completed

Test cylce 5 completed

Error: Client 6007 got 0 bytes instead of 95
Error: Client 6013 got 0 bytes instead of 95
Test cylce 6 completed
...

/ajax/echo.cgi POST 1000

CPUs (bit masks): process=3, system=3
Preparing test ... OK: 98 bytes of data
Starting multi client test: 20 cycles, 20 clients each

Error: Client 1000 got 33 bytes instead of 98
Test cylce 1 completed

Test cylce 2 completed

Error: Client 3002 got 33 bytes instead of 98
Error: Client 3006 got 0 bytes instead of 98
Test cylce 3 completed

Test cylce 4 completed

Test cylce 5 completed

Test cylce 6 completed
...

/ajax/echo.cgi POST 10000

CPUs (bit masks): process=3, system=3
Preparing test ... OK: 99 bytes of data
Starting multi client test: 20 cycles, 20 clients each

Error: Client 1000 got 33 bytes instead of 99
Error: Client 1003 got 33 bytes instead of 99
Error: Client 1007 got 33 bytes instead of 99
Test cylce 1 completed

Error: Client 2000 got 33 bytes instead of 99
Error: Client 2002 got 33 bytes instead of 99
Error: Client 2001 got 33 bytes instead of 99
Error: Client 2008 got 33 bytes instead of 99
Error: Client 2006 got 33 bytes instead of 99
Test cylce 2 completed

Thread 3000 did not finish!
Test cylce 3 completed

Test cylce 4 completed

Error: Client 5002 got 33 bytes instead of 99
Thread 5000 did not finish!
Test cylce 5 completed

Error: Client 6004 got 33 bytes instead of 99
Error: Client 6006 got 33 bytes instead of 99
Error: Client 6001 got 33 bytes instead of 99
Error: Client 6008 got 33 bytes instead of 99
Error: Client 6010 got 33 bytes instead of 99
Error: Client 6012 got 33 bytes instead of 99
Error: Client 6018 got 33 bytes instead of 99
Thread 6000 did not finish!
Test cylce 6 completed

Error: Client 7001 got 33 bytes instead of 99
Error: Client 7006 got 33 bytes instead of 99
Error: Client 7003 got 33 bytes instead of 99
Error: Client 7005 got 33 bytes instead of 99
Error: Client 7007 got 33 bytes instead of 99
Error: Client 7009 got 33 bytes instead of 99
Error: Client 7011 got 33 bytes instead of 99
Test cylce 7 completed

Error: Client 8005 got 33 bytes instead of 99
Error: Client 8003 got 33 bytes instead of 99
Error: Client 8000 got 33 bytes instead of 99
Error: Client 8001 got 33 bytes instead of 99
Error: Client 8002 got 33 bytes instead of 99
Error: Client 8004 got 33 bytes instead of 99
Error: Client 8006 got 33 bytes instead of 99
Test cylce 8 completed

Error: Client 9001 got 33 bytes instead of 99
Error: Client 9003 got 33 bytes instead of 99
Error: Client 9002 got 33 bytes instead of 99
Error: Client 9000 got 33 bytes instead of 99
Error: Client 9004 got 33 bytes instead of 99
Error: Client 9008 got 33 bytes instead of 99
Test cylce 9 completed

Error: Client 10002 got 33 bytes instead of 99
Error: Client 10000 got 0 bytes instead of 99
Error: Client 10001 got 33 bytes instead of 99
Error: Client 10004 got 33 bytes instead of 99
Test cylce 10 completed

Error: Client 11003 got 33 bytes instead of 99
Error: Client 11001 got 33 bytes instead of 99
Test cylce 11 completed

Error: Client 12000 got 33 bytes instead of 99
Error: Client 12018 got 33 bytes instead of 99
Test cylce 12 completed
…

[Anonymous]

Originally posted by: bel2... (code.google.com)@gmail.com

I modified the test so that it runs automatically and tests POST requests with different content lengths. The test case can be found at https://code.google.com/r/bel2125-mongoose/source/browse/#hg%2Ftestclient as version [r7ffffb3606d1].

The test logs are attached.

Errors can be found for ANY content length, there are just more frequent for larger POST requests. There are at least two kinds of errors. One with a 33 byte response, another with no response at all (0 bytes).

[Anonymous]

Originally posted by: bel2... (code.google.com)@gmail.com

When looking closer at the log, it seems like the misbehavior of mongoose is not limited to parallel requests from many clients.

There are also several error situations with just one client making a POST request, e.g.,
- https://code.google.com/p/mongoose/issues/attachmentText?id=349&aid=3490021001&name=testrun1.txt&token=cKV2NU5T5QLIZoW8EHzi4QtEju0%3A1337681079528#1216
- https://code.google.com/p/mongoose/issues/attachmentText?id=349&aid=3490021001&name=testrun1.txt&token=cKV2NU5T5QLIZoW8EHzi4QtEju0%3A1337681079528#2305
- https://code.google.com/p/mongoose/issues/attachmentText?id=349&aid=3490021001&name=testrun1.txt&token=cKV2NU5T5QLIZoW8EHzi4QtEju0%3A1337681079528#3403
- https://code.google.com/p/mongoose/issues/attachmentText?id=349&aid=3490021001&name=testrun1.txt&token=cKV2NU5T5QLIZoW8EHzi4QtEju0%3A1337681079528#4498
- https://code.google.com/p/mongoose/issues/attachmentText?id=349&aid=3490021002&name=testrun2.txt&token=JO8nywuKrKMn8rD9oR60Kq_404I%3A1337681079528#432
- https://code.google.com/p/mongoose/issues/attachmentText?id=349&aid=3490021002&name=testrun2.txt&token=JO8nywuKrKMn8rD9oR60Kq_404I%3A1337681079528#1466

In other words, mongoose is unreliable in handling POST requests in all situations, more threads and a larger amount of data just increases the frequency of the errors. However, this error may strike you even for a single client with a very simple request.

[Anonymous]

Originally posted by: nullable... (code.google.com)@gmail.com

These are bad news... do you know whether this applies also GET requests in the way stated as in comment 22?

[Anonymous]

Originally posted by: bel2... (code.google.com)@gmail.com

The POST test above was running for several hours, and then it took some time to evaluate it and to ensure the test was running correctly. I am doing the same for GET requests, but it's not completed yet.

In contrast to POST requests, GET requests may not have any body data. Only the size of the request head and the length of an optional query string may vary. Some extra data in the request head and an additional query string may actually be used for GET, POST and any other request.

In contrast to increasing the length of POST body data, increasing the length of the head data and using longer query strings does not seem to yield in a significant increase in the frequency of this error. Query strings up to somewhere between 3 and 4 kB can be used – for longer strings the server does not seem work at all, but 3 kB is well above the limit for Internet Explorer (2083 bytes according to http://en.wikipedia.org/wiki/Query_string#Compatibility_issues), so this should be sufficient. Adding some 10 kB of useless data fields in the request header does not seem to cause the same issues as adding the same amount of body data.

To find out if at least a non concurrent GET request is 100% reliable, I will first run a long term test (for several hours) with small request headers and just one client thread.

[Anonymous]

Originally posted by: bel2... (code.google.com)@gmail.com

I made another modified version of the test which performs 1 GET request every 10 seconds ([r8fabfb035854], https://code.google.com/r/bel2125-mongoose/source/browse/testclient/testclient.c?r=8fabfb035854746c902d23e2981a4ef80de04304).

The result after 3000 tests (about 9 hours) is:
GET  998 2   (998 of 1000 OK, two cases of "Client 0 got %u bytes instead of 77")
GET 1000 0  (1000 of 1000 OK)
GET  998 2   (998 of 1000 OK, two cases of "Client 0 got %u bytes instead of 77")
... that means 4 of 3000 GET requests got lost (0.133%).

This is about the same ratio as for concurrent post request with less than a few hundred bytes of body data (see the first 10 lines of testclient.log in comment 21). There 14 of 10000 small POST requests got lost (0.14%).

So there seems to be a basic flaw that hits 0.14% of all requests, no matter if they are GET or POST requests and no matter how large they are ("got 0 bytes instead xx"). In addition there is a second error that depends on the post data size ("got 33 bytes instead xx").