Bug 57490 - HttpWebRequest - Error download files after returning to a background thread from another background thread.
Summary: HttpWebRequest - Error download files after returning to a background thread ...
Status: ASSIGNED
Alias: None
Product: iOS
Classification: Xamarin
Component: BCL Class Libraries (show other bugs)
Version: unspecified
Hardware: Macintosh Mac OS
: High major
Target Milestone: Untriaged
Assignee: Martin Baulig
URL:
Depends on:
Blocks:
 
Reported: 2017-06-14 16:01 UTC by Sid Dubey
Modified: 2017-10-21 02:45 UTC (History)
9 users (show)

See Also:
Tags:
Is this bug a regression?: Yes
Last known good build:


Attachments
Mono console app test case (6.57 KB, application/zip)
2017-10-21 02:45 UTC, Brendan Zagaeski (Xamarin Support)
Details

Description Sid Dubey 2017-06-14 16:01:53 UTC
Issue occurs where attempts to read files over network fail in a specific scenario. Basically we have a sync process that starts a background thread. So the UI thread (call it thread 1) starts the synchronization  and that all happens on the background thread (call it thread id 2) . The sync process calls services on another thread (call that thread id 3). When they complete they return to their originating thread (in this case thread id 2) and processing continues. I’ve found when trying to create a HttpWebRequest to download a file after returning to the original thread (thread 2) after calling a services causes the read of the response stream to just lock up and time out.  

A sample application which shows this behavior here… build for iPad, it tries to download a file to illustrate the scenario below: https://github.com/ingybing/XamarinStreams.git

So for example

UIThread 1: Start Sync on new thread.
    Thread 2: Sync Started
    Thread 2: Calling Service waiting for response.
    Thread 3: Calling Service
    Thread 3: Returning Result
    Thread 2: Fetch And Download File. – Hangs and operation timeout exception eventually occurs.

I try and download the file just as a test at earlier points on thread 2 everything is ok…… so for example

UIThread 1: Fetch and Download File – Works Fine.
UIThread 1: Start Sync on new thread.
    Thread 2: Sync Started
    Thread 2: Fetch and Download File – Works Fine.
    Thread 2: Calling Service waiting for response.
    Thread 3: Calling Service
    Thread 3: Fetch and Download File – Works Fine.
    Thread 3: Returning Result
    Thread 2: Fetch And Download File. – Hangs and operation timeout exception eventually occurs
+++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++
How to Reproduce Issue : 
-------------------------
1. Download iOS App from https://github.com/ingybing/XamarinStreams.git
2. Open it in Xamarin Studio or Visual Studio For Mac
3. Run on iPad Simulator
4. Click Fetch Cust Ctx
5. Application hangs up on the third attempt of trying to download the file using the exact same code as use the previous two times in this test case, but after returning for the 3rd thread to the 2nd thread the call fails in the ViewController.cs at line 135 where it does 
var count = streamReader.Read(buffer, 0, BufferSize);
+++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++
IDE VERSION INFO
----------------
=== Xamarin Studio Enterprise ===

Version 6.3 (build 864)
Installation UUID: da052796-640d-4f51-9571-65cc0968c4b9
Runtime:
	Mono 5.0.1.1 (2017-02/5077205) (64-bit)
	GTK+ 2.24.23 (Raleigh theme)

	Package version: 500010001

=== NuGet ===

Version: 3.5.0.0

=== Xamarin.Profiler ===

Version: 1.5.4
Location: /Applications/Xamarin Profiler.app/Contents/MacOS/Xamarin Profiler

=== Xamarin.Android ===

Version: 7.3.1.2 (Visual Studio Enterprise)
Android SDK: /Users/Siddharth/Library/Android/sdk
	Supported Android versions:
		4.0.3  (API level 15)
		4.1    (API level 16)
		4.2    (API level 17)
		4.3    (API level 18)
		4.4    (API level 19)
		4.4.87 (API level 20)
		5.0    (API level 21)
		5.1    (API level 22)
		6.0    (API level 23)
		7.0    (API level 24)
		7.1    (API level 25)

SDK Tools Version: 26.0.1
SDK Platform Tools Version: 25.0.5
SDK Build Tools Version: 23.0.3

Java SDK: /usr
java version "1.8.0_131"
Java(TM) SE Runtime Environment (build 1.8.0_131-b11)
Java HotSpot(TM) 64-Bit Server VM (build 25.131-b11, mixed mode)

Android Designer EPL code available here:
https://github.com/xamarin/AndroidDesigner.EPL

=== Xamarin Inspector ===

Version: 1.2.2
Hash: b71b035
Branch: d15-1
Build date: Fri, 21 Apr 2017 17:57:12 GMT

=== Apple Developer Tools ===

Xcode 8.3.3 (12175.1)
Build 8E3004b

=== Xamarin.iOS ===

Version: 10.10.0.36 (Visual Studio Enterprise)
Hash: d2270eec
Branch: d15-2
Build date: 2017-05-22 16:30:53-0400

=== Xamarin.Mac ===

Version: 3.4.0.36 (Visual Studio Enterprise)

=== Build Information ===

Release ID: 603000864
Git revision: 6c2f6737278ccc3e81e12276d49c0d92f975f189
Build date: 2017-04-24 11:26:01-04
Xamarin addins: d8d46e577d8507c35260ce9d73df3c33415bb214
Build lane: monodevelop-lion-d15-1

=== Operating System ===

Mac OS X 10.12.5
Darwin Siddharths-MBP.attlocal.net 16.6.0 Darwin Kernel Version 16.6.0
    Fri Apr 14 16:21:16 PDT 2017
    root:xnu-3789.60.24~6/RELEASE_X86_64 x86_64
++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++
=== Visual Studio Enterprise 2017 for Mac ===

Version 7.0.1 (build 24)
Installation UUID: 50f82eb4-fb15-4723-b832-41705329ff5e
Runtime:
	Mono 5.0.1.1 (2017-02/5077205) (64-bit)
	GTK+ 2.24.23 (Raleigh theme)

	Package version: 500010001

=== NuGet ===

Version: 4.0.0.2323

=== .NET Core ===

Runtime: Not installed
SDK: Not installed
MSBuild SDKs: /Library/Frameworks/Mono.framework/Versions/5.0.1/lib/mono/msbuild/15.0/bin/Sdks

=== Xamarin.Profiler ===

Version: 1.5.4
Location: /Applications/Xamarin Profiler.app/Contents/MacOS/Xamarin Profiler

=== Apple Developer Tools ===

Xcode 8.3.3 (12175.1)
Build 8E3004b

=== Xamarin.iOS ===

Version: 10.10.0.36 (Visual Studio Enterprise)
Hash: d2270eec
Branch: d15-2
Build date: 2017-05-22 16:30:53-0400

=== Xamarin.Android ===

Version: 7.3.1.2 (Visual Studio Enterprise)
Android SDK: /Users/Siddharth/Library/Android/sdk
	Supported Android versions:
		4.0.3  (API level 15)
		4.1    (API level 16)
		4.2    (API level 17)
		4.3    (API level 18)
		4.4    (API level 19)
		4.4.87 (API level 20)
		5.0    (API level 21)
		5.1    (API level 22)
		6.0    (API level 23)
		7.0    (API level 24)
		7.1    (API level 25)

SDK Tools Version: 26.0.1
SDK Platform Tools Version: 25.0.5
SDK Build Tools Version: 23.0.3

Java SDK: /usr
java version "1.8.0_131"
Java(TM) SE Runtime Environment (build 1.8.0_131-b11)
Java HotSpot(TM) 64-Bit Server VM (build 25.131-b11, mixed mode)

Android Designer EPL code available here:
https://github.com/xamarin/AndroidDesigner.EPL

=== Xamarin.Mac ===

Version: 3.4.0.36 (Visual Studio Enterprise)

=== Xamarin Inspector ===

Version: 1.2.2
Hash: b71b035
Branch: d15-1
Build date: Fri, 21 Apr 2017 17:57:12 GMT

=== Build Information ===

Release ID: 700010024
Git revision: 7ab1ca2ced6f584e56b7a0d4d321d00775cd95c9
Build date: 2017-05-19 05:44:51-04
Xamarin addins: 08d17158f3365beee5e60f67999e607cce4b3f93
Build lane: monodevelop-lion-d15-2

=== Operating System ===

Mac OS X 10.12.5
Darwin 16.6.0 Darwin Kernel Version 16.6.0
    Fri Apr 14 16:21:16 PDT 2017
    root:xnu-3789.60.24~6/RELEASE_X86_64 x86_64
+++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++
----------------
Comment 1 Sid Dubey 2017-06-14 16:04:53 UTC
Please note the above issue does not occur with the following IDE configuration and works just fine. 

++++++++++++++++++++++++++++++++++++++++++++++++++++++
Xamarin Studio Community
Version 6.3 (build 863)
Installation UUID: 1587324f-9d6c-415b-9044-c70fbbe2f1f4
Runtime:
Mono 4.8.0 (mono-4.8.0-branch/9d74414) (64-bit)
GTK+ 2.24.23 (Raleigh theme)

Package version: 408000524

NuGet
Version: 3.5.0.0

Xamarin.Profiler
Version: 1.5.4
Location: /Applications/Xamarin Profiler.app/Contents/MacOS/Xamarin Profiler

Apple Developer Tools
Xcode 8.2 (11766)
Build 8C38

Xamarin.Android
Not Installed

Xamarin Inspector
Version: 1.3.0-alpha2
Hash: fa030e0
Branch: master
Build date: Thu, 01 Jun 2017 20:55:26 GMT
Client compatibility: 1

Xamarin.Mac
Version: 3.5.0.126 (Xamarin Studio Community)

Xamarin.iOS
Version: 10.8.0.175 (Xamarin Studio Community)
Hash: a04678c2
Branch: d15-1
Build date: 2017-03-28 14:05:38-0400

Build Information
Release ID: 603000863
Git revision: a2163670efe259c85cd8f335d95b175068fbbe2a
Build date: 2017-04-03 14:33:15-04
Xamarin addins: 2045d688ea1420e0381b473360ca62a763eb7d04
Build lane: monodevelop-lion-d15-1

Operating System
Mac OS X 10.11.6
Darwin Davids-MacBook-Pro.local 15.6.0 Darwin Kernel Version 15.6.0
    Tue Apr 11 16:00:51 PDT 2017
    root:xnu-3248.60.11.5.3~1/RELEASE_X86_64 x86_64
+++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++
Comment 2 Vincent Dondain [MSFT] 2017-06-14 23:00:44 UTC
Hi Sid,

You gave very detailed explanations and thank you for that but I'm failing to see exactly how to reproduce using the test case.

I followed steps 1, 2, 3, 4 and now I see a "Downloading..." on the right but no hang on "Fetch And Download File".

https://www.dropbox.com/s/ow0ddwrn375xp04/Screenshot%202017-06-14%2018.57.19.png?dl=0

Is it possible for you to create a screencast to demonstrate the issue using the app?

Note: I'm using the following environment https://gist.github.com/VincentDondain/a84e7b2cc058b8b890c98752809a57e0
Comment 3 David Ingham 2017-06-15 23:26:52 UTC
Hi

I've created some screen casts to try and explain whats going wrong.... Basically at the 3rd call of the download file it will try and enqueue some work on my thread sync context when it shouldn't be.. the code then dead locks and eventually the streamreader.read operation times out and throws exception.... after the 3rd execution it never gets past line 135 in viewcontroller.cs

Part 1:
https://screencast.com/t/oI3gQlhQ3

Part 2:
https://screencast.com/t/94ESz71ccY

Part 3:
https://screencast.com/t/5V3Zox1Xxvh

grab a machine take it back to xamarin studio release that was running on mono4 (april / early may releases??) and you'll see the difference in the output and the debug output window.

Regards,

Dave
Comment 4 David Ingham 2017-06-16 10:37:54 UTC
I've been digging around and think i've pinned it down to a change in socket.....

Commit: 13c15c25fb349ab80fbdc930f885800e8ad4b8ac

One of my colleagues has looked and main stream .net doesn't do it this way that commit changed it to work like but core.net does. Is Mono being aligned to core.net? Are these changes going to make their way into mainstream .net in the future?

Regards,

Dave
Comment 5 David Ingham 2017-06-16 15:21:01 UTC
I've tried to find the direct equivalent of this method in the reference source but can't, so not sure if my colleague said is actually correct. Can you please advise if the changes made are to being anything inline and is this going to change in mainstream .net as well?
Comment 7 Vincent Dondain [MSFT] 2017-06-28 20:02:30 UTC
Hi David,

I'm still having trouble reproducing this (not getting any deadlock).

You mentioned: "difference in the output and the debug output window" between a Xamarin Studio release that was running on Mono 4 and VSMac with Mono 5. Could you actually https://gist.github.com those differences?

I do fall into https://github.com/ingybing/XamarinStreams/blob/master/ReadBug/ViewController.cs#L230-L233 after the 3rd attempt but both with Mono 5.2.0.189 and 4.8.1.0.

Can anyone else on the team reproduce this?

Also what makes you think the issue is related to this socket change: 13c15c25fb349ab80fbdc930f885800e8ad4b8ac?
Comment 8 David Ingham 2017-07-01 23:31:52 UTC
https://www.screencast.com/t/cteQeeApo

Thats a screen cast walk through of how to repro from scratch... what i believe is the issue and why... sorry i end up talking a bit quickly but screen cast only gives me 5 min vids :D

Any questions give me a shout.
Comment 10 Brendan Zagaeski (Xamarin Support) 2017-10-21 02:31:57 UTC
## Confirmation status: no longer replicable on Xamarin.iOS 10.12 and higher, with this exact test case

GOOD: Xamarin.iOS 11.0.0.0   (xcode9 152b654a) 
GOOD: Xamarin.iOS 10.12.3.3  (d15-3  8a391069) (Embedded Mono: 14f2c81)
BAD:  Xamarin.iOS 10.10.0.36 (d15-2  d2270eec) (Embedded Mono: 5077205)

Between Mono 5077205 (BAD) and 14f2c81 (GOOD), there was a change in the `Socket.QueueIOSelectorJob()` (precisely the suspicious method that David pointed out in the analysis in Comment 8).  In particular, the following pull request added a "fast path" to avoid the call to `ContinueWith()` and the creation of the anonymous function: https://github.com/mono/mono/pull/4516.

Based on my results for the GOOD and BAD versions, this change does appear to resolve the symptom for the precise scenario from the current master branch of https://github.com/ingybing/XamarinStreams.  That said, if the analysis in Comment 8 is correct, then it would be reasonable to guess that the problematic behavior would still arise in cases where the Task returned by `sem.WaitAsync()` in `QueueIOSelectorJob()` does _not_ have `IsCompleted` set to `true`.  Off-hand I am not sure how to adjust the test case to force that Task to have `IsCompleted` initially set to `false`.  To facilitate further investigation, I will post a follow-up comment with a console Mono test case that I quickly pasted together based on the original iOS test case.




## Steps followed to test

1. git clone https://github.com/ingybing/XamarinStreams.git
(Tested at revision 45636c3f5665adbe4c5bd4b1354fb849bb2f7359)

2. Open the solution, and build and run the "ReadBug" project in the Debug configuration on an iPad Air iOS 10.3.1 simulator.

3. Tap the "Fetch Cust Ctx" button.




## BAD Results observed with Xamarin.iOS 10.10.0.36 (d15-2 d2270eec)

The text field in the left side of the app fills with lines about the activity on 3 different threads.

The key symptom is that the text on the left side of the app stops updating on the following lines:

> Thread 6: Creating Request.
> Thread 6: Getting Response.
> Thread 6: Processing response stream
> Thread 6: Buffer size: 5000
If you then wait for several minutes, that request will time out, and the following text will be appear in the text field:
> Thread 6: ERROR in third download attempt: The operation has timed out.
> Thread 6: CUSTOM SYNCHRONIZATIONCONTEXT HAS BEEN STOPPED



## GOOD Results observed with Xamarin.iOS 10.12.3.3 (d15-3 8a391069)

The text field in the left side of the app fills with lines about the activity on 3 different threads.

If we look at the bottom of that text field where the "BAD" results got stuck, we now see a different behavior:
> Thread 6: Creating Request.
> Thread 6: Getting Response.
> Thread 6: Processing response stream
> Thread 6: Buffer size: 5000
> Thread 6: Count: 5000
> Thread 6: StringBuilder Length: 5000
> Thread 6: Reading Stream Again
> Thread 6: Count: 5000
> Thread 6: StringBuilder Length: 10000
> Thread 6: Reading Stream Again
> Thread 6: Count: 2338
> Thread 6: StringBuilder Length: 12338
> Thread 6: Reading Stream Again
> Thread 6: Count: 0
> Thread 6: SUCCESS, closing stream etc
> Thread 6: CUSTOM SYNCHRONIZATIONCONTEXT HAS BEEN STOPPED
The right side text field also gets filled with the "lorem ipsum" text this time.




## Additional testing environment info (brief)

Visual Studio 2017 for Mac (7.0.1.24 7ab1ca2)

Mono Framework MDK 5.2.0.224 (d15-3/14f2c81) (64-bit)

Xcode 8.3.3 (12175.1), Build 8E3004b

macOS 10.12.6
US Eastern time zone, US English locale
User name: macuser
Comment 11 Brendan Zagaeski (Xamarin Support) 2017-10-21 02:45:52 UTC
Created attachment 25390 [details]
Mono console app test case

## Steps to test with this Mono console test case

1. Unzip the test case.

2. msbuild /t:Build ConsoleApp1.csproj

3. mono bin/Debug/ConsoleApp1.exe


The console output for this test case in the BAD and GOOD cases matches the text described in the previous comment for the iOS app.  Note that currently this test case demonstrates the GOOD behavior on the latest versions of Mono (as discussed in the previous comment).

In case it's helpful for context, I was thinking that one possible next investigation step could be to adjust the test case somehow (if it's possible) so that the Task returned by `sem.WaitAsync()` in `QueueIOSelectorJob()` initially has `IsCompleted` set to `false` during the WebRequest that's running in the `NonUiThreadSynchronisationContext` synchronization context.  The question would be whether that brings back the problematic behavior where the WebRequest gets stuck.

Note You need to log in before you can comment on or make changes to this bug.