[Mono-bugs] [Bug 648862] HttpWebRequest fails spectacularly in MonoDroid

[bugzilla_noreply at novell.com]

https://bugzilla.novell.com/show_bug.cgi?id=648862

https://bugzilla.novell.com/show_bug.cgi?id=648862#c9


--- Comment #9 from Jonathan Pryor <jpryor at novell.com> 2011-01-11 20:23:33 UTC ---
TL;DR: I can't reproduce.  Can you cook up a different repro?  Also, the
emulator sucks.  Also, you need to make sure that you dispose of the Stream
returned by HttpWebRequest.GetResponse() or Bad Things™ happen.

The long version:

 1. I'm testing this on MonoDroid trunk, so things may differ from Preview 10,
but I doubt it.
 2. FYI, Log.D() messages are stripped on-device.  I'd suggest using Log.I().
:-)
 3. Don't use Console.WriteLine.  Console.WriteLine() goes to stdout, and
stdout isn't saved by default.

        http://developer.android.com/guide/developing/tools/adb.html#stdout

    I would suggest using Log.E() unless you're running within a debugger
(which I'm not).

As a consequence of (2), I didn't see your GImageSearch messages at first, and
as a consequence of (3) your `catch` blocks weren't actually printing anything.

Yay.

As for README.txt, most of its contents can be ignored, as per monodroid-list
discussions (in unrelated threads).  System.Net ~always generates "An address
incompatible with the requested protocol was used" messages, so it's presence
can be ignored, as can the System.Security.Cryptography messages (there's no
Store, hence the error, and for https we delegate to Android anyway), and the
ArgumentNullExceptions seem similarly ignorable.

I also find it odd that your GImageSearch process dies; all exceptions are
caught, so it shouldn't be dying (unless README contains traces from a run w/o
the catch blocks?).  It certainly hasn't died for me.

That said, I have seen circumstances where Android can't resolve a URL and will
throw an exception; perhaps this is what you've seen?  Curiously, attempting
the SAME URL again results in success, so I'm not sure what to make of this,
but it doesn't appear to be a MonoDroid issue.

To show that it (can) work, here is `adb logcat` output on my N1, with Log.D()
changed to Log.I() and Console.WriteLine() changed to Log.E().  Note that both
the "Before web request" and "After web request" messages are shown, thus
showing that that the intervening messages are, in fact, ignorable (as they're
apparently caught internally or never thrown):

I/ActivityManager(   87): Start proc gimagesearch.gimagesearch for activity
gimagesearch.gimagesearch/gimagesearch.GImageSearch: pid=13430 uid=10067
gids={3003}
I/ActivityThread(13430): Publishing provider
gimagesearch.gimagesearch.__mono_init__: mono.MonoRuntimeProvider
V/RenderScript_jni(  164): surfaceDestroyed
D/dalvikvm(13430): Trying to load lib
/data/data/gimagesearch.gimagesearch/lib/libmonodroid.so 0x449e3f40
D/dalvikvm(13430): Added shared lib
/data/data/gimagesearch.gimagesearch/lib/libmonodroid.so 0x449e3f40
D/dalvikvm(13430): GC_FOR_MALLOC freed 12807 objects / 479056 bytes in 30ms
D/dalvikvm(13430): GC_FOR_MALLOC freed 10227 objects / 477624 bytes in 29ms
I/GImageSearch(13430): Before web request
D/dalvikvm(13430): GC_EXPLICIT freed 7465 objects / 366296 bytes in 30ms
E/mono    (13430): [0x3a3da0:] EXCEPTION handling:
System.Net.Sockets.SocketException: An address incompatible with the requested
protocol was used
D/dalvikvm(13430): GC_EXPLICIT freed 32 objects / 1080 bytes in 27ms
E/mono    (13430): [0x3de0f8:] EXCEPTION handling:
System.Security.Cryptography.CryptographicException: Store Root doesn't exists.
E/mono    (13430): [0x3de0f8:] EXCEPTION handling:
System.Security.Cryptography.CryptographicException: Store Root doesn't exists.
E/mono    (13430): [0x3de0f8:] EXCEPTION handling:
System.Security.Cryptography.CryptographicException: Store CA doesn't exists.
E/mono    (13430): [0x3de0f8:] EXCEPTION handling:
System.Security.Cryptography.CryptographicException: Store CA doesn't exists.
E/mono    (13430): [0x3de0f8:] EXCEPTION handling:
System.ArgumentNullException: Argument cannot be null.
E/mono    (13430): Parameter name: type
E/mono    (13430): [0x3de0f8:] EXCEPTION handling:
System.ArgumentNullException: Argument cannot be null.
E/mono    (13430): Parameter name: type
E/mono    (13430): [0x3de0f8:] EXCEPTION handling:
System.ArgumentNullException: Argument cannot be null.
E/mono    (13430): Parameter name: type
E/mono    (13430): [0x3de0f8:] EXCEPTION handling:
System.ArgumentNullException: Argument cannot be null.
E/mono    (13430): Parameter name: type
E/mono    (13430): [0x3de0f8:] EXCEPTION handling:
System.ArgumentNullException: Argument cannot be null.
E/mono    (13430): Parameter name: type
E/mono    (13430): [0x3de0f8:] EXCEPTION handling:
System.ArgumentNullException: Argument cannot be null.
E/mono    (13430): Parameter name: type
E/mono    (13430): [0x3de0f8:] EXCEPTION handling:
System.ArgumentNullException: Argument cannot be null.
E/mono    (13430): Parameter name: type
D/dalvikvm(13430): GC_FOR_MALLOC freed 8387 objects / 538344 bytes in 38ms
D/dalvikvm(13430): GC_FOR_MALLOC freed 8057 objects / 505736 bytes in 30ms
D/dalvikvm(13430): GC_FOR_MALLOC freed 9407 objects / 563416 bytes in 35ms
D/dalvikvm(13430): GC_EXPLICIT freed 7364 objects / 446360 bytes in 30ms
I/GImageSearch(13430): After web request


When I ran in the emulator, I got different output:

E/GImageSearch(  333): WebException: Error getting response stream (Write: The
authentication or decryption has failed.): SendFailure;
System.Net.WebException: Error getting response stream (Write: The
authentication or decryption has failed.): SendFailure --->
System.IO.IOException: The authentication or decryption has failed. --->
Mono.Security.Protocol.Tls.TlsException: The server stopped the handshake.
E/GImageSearch(  333):   at
Mono.Security.Protocol.Tls.SslClientStream.SafeReceiveRecord (System.IO.Stream
s) [0x00000] in <filename unknown>:0 
E/GImageSearch(  333):   at
Mono.Security.Protocol.Tls.SslClientStream.OnNegotiateHandshakeCallback
(IAsyncResult asyncResult) [0x00000] in <filename unknown>:0 
E/GImageSearch(  333):   at
Mono.Security.Protocol.Tls.SslStreamBase.AsyncHandshakeCallback (IAsyncResult
asyncResult) [0x00000] in <filename unknown>:0 
E/GImageSearch(  333):   --- End of inner exception stack trace ---
E/GImageSearch(  333):   at
Mono.Security.Protocol.Tls.SslStreamBase.AsyncHandshakeCallback (IAsyncResult
asyncResult) [0x00000] in <filename unknown>:0 
E/GImageSearch(  333):   --- End of inner exception stack trace ---
E/GImageSearch(  333):   at System.Net.HttpWebRequest.EndGetResponse
(IAsyncResult asyncResult) [0x00000] in <filename unknown>:0 
E/GImageSearch(  333):   at System.Net.HttpWebRequest.GetResponse () [0x00000]
in <filename unknown>:0 
E/GImageSearch(  333):   at GImageSearch.GImageSearch.OnCreate
(Android.OS.Bundle bundle) [0x00000] in <filename unknown>:0 


HOWEVER, hit the Back button (thus destroying the app) and relaunching the app
results in:

I/GImageSearch(  333): After web request

i.e. it works.

HOWEVER, kill the process, restart, and it fails.  Odd...

So, throw the WebRequest.Create() call into a loop:

            for (int i = 0; i < 5; ++i) {
              try
              {
                Log.Info ("GImageSearch", "Before web request {0}",
i.ToString());
                var request = (HttpWebRequest) WebRequest.Create(url);
                HttpWebResponse response = request.GetResponse() as
HttpWebResponse;
                Log.Info ("GImageSearch", "After web request {0}", i.ToString
());
              }
              catch (WebException we)
              {
                Log.Error ("GImageSearch", "attempt {0}: WebException: {1};
{2}", i.ToString(), we.Message, we.ToString());
              }
              catch (Exception sysExc)
              {
                Log.Error ("GImageSearch", "attempt {0}: Exception: {1}; {2}",
i.ToString(), sysExc.Message, sysExc.ToString());
              }
            }

The results are...inconsistent.  In the emulator, the first iteration fails
(which seems "normal" at this point), iteration 2 and 3 succeed, iteration 4
and 5, time out (!).

On my N1, the first and second iterations succeed, iterations 3, 4, and 5 time
out.  Repeat...and they ALL time out.

I wonder if the timeouts are a symptom of the URL itself; if I visit it in a
browser, I get HTTP 400 / Bad Request.

Retry with the URL "https://encrypted.google.com/", and I get largely the same
behavior: the first few attempts succeed, subsequent attempts timeout.

Retry the loop version with the TestWebReq console app, and...it also times
out!  (The first few succeed, then all subsequent ones time out.)

Ponder a bit, and...  Apparently there's some internal resource limit to the
number of responses that can be "in-flight" at once.

Specifically, if we make the following change in the looping versions of both
TestWebReq and GImageSearch:

    - HttpWebResponse response = request.GetResponse() as HttpWebResponse;
    + using (HttpWebResponse response = request.GetResponse() as
HttpWebResponse) {
    + }

then the console TestWebReq no loner shows timeout errors, and GImageSearch w/
https://encrypted.google.com works w/o error on my N1.

On the emulator, the looping+using+encrypted.google.com version generates a
WebException on the first loop iteration ("The socket has been shut down"), and
WORKS for all subsequent iterations (ergo, the emulator seems flaky).

All that is a way to say that I can't reproduce the bug.

-- 
Configure bugmail: https://bugzilla.novell.com/userprefs.cgi?tab=email
------- You are receiving this mail because: -------
You are the QA contact for the bug.
You are the assignee for the bug.