search

aspnet / MusicStore

[Archived] MusicStore test application that uses ASP.NET/EF Core. Project moved to https://github.com/aspnet/AspNetCore
1.3k stars 878 forks source link

Re-enable tests disabled due to corefx issue #683

Closed JunTaoLuo closed 8 years ago

JunTaoLuo commented 8 years ago

627 Tested locally on mac.

cc @BrennanConroy approval: @Eilon

BrennanConroy commented 8 years ago

Whats with the Travis failure

JunTaoLuo commented 8 years ago

@BrennanConroy seems like the the tests are flaky on Travis but I have not been able to reproduce it anywhere else. I have tried agent10 agent20, my mac and your mac and it passes on those machines consistently. It seems like on travis, random POST requests will fail with the following error:

---- System.Net.Http.CurlException : Send failed since rewinding of the data stream failed
info:       Stack Trace:
info:            at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
info:            at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
info:            at System.Net.Http.HttpClient.<FinishSendAsync>d__58.MoveNext()
info:         --- End of stack trace from previous location where exception was thrown ---
info:            at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
info:            at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
info:            at System.Runtime.CompilerServices.TaskAwaiter`1.GetResult()
info:         /Users/travis/build/aspnet/MusicStore/test/E2ETests/Implementation/Validator.cs(57,0): at E2ETests.Validator.<DoPostAsync>d__15.MoveNext()
info:         --- End of stack trace from previous location where exception was thrown ---
info:            at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
info:            at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
info:            at System.Runtime.CompilerServices.TaskAwaiter`1.GetResult()
info:         /Users/travis/build/aspnet/MusicStore/test/E2ETests/Implementation/FacebookLoginScenarios.cs(62,0): at E2ETests.Validator.<LoginWithFacebook>d__0.MoveNext()
info:         --- End of stack trace from previous location where exception was thrown ---
info:            at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
info:            at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
info:            at System.Runtime.CompilerServices.TaskAwaiter.GetResult()
info:         /Users/travis/build/aspnet/MusicStore/test/E2ETests/SmokeTestHelper.cs(108,0): at E2ETests.SmokeTestHelper.<RunTestsAsync>d__0.MoveNext()
info:         --- End of stack trace from previous location where exception was thrown ---
info:            at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
info:            at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
info:            at System.Runtime.CompilerServices.TaskAwaiter.GetResult()
info:         /Users/travis/build/aspnet/MusicStore/test/E2ETests/SmokeTests.cs(207,0): at E2ETests.SmokeTests.<SmokeTestSuite>d__2.MoveNext()
info:         --- End of stack trace from previous location where exception was thrown ---
info:            at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
info:            at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
info:            at System.Runtime.CompilerServices.TaskAwaiter.GetResult()
info:         /Users/travis/build/aspnet/MusicStore/test/E2ETests/SmokeTests.cs(115,0): at E2ETests.SmokeTests_X64.<NonWindowsOS>d__3.MoveNext()
info:         --- End of stack trace from previous location where exception was thrown ---
info:            at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
info:            at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
info:         --- End of stack trace from previous location where exception was thrown ---
info:            at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
info:            at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
info:         --- End of stack trace from previous location where exception was thrown ---
info:            at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
info:            at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
info:         ----- Inner Stack Trace -----
info:            at System.Net.Http.CurlHandler.ThrowIfCURLEError(CURLcode error)
info:            at System.Net.Http.CurlHandler.MultiAgent.FinishRequest(StrongToWeakReference`1 easyWrapper, CURLcode messageResult)

Could it be an issue with the implementation with CurlHandler.MultiAgent? Do you have any ideas @stephentoub what can cause this error?

stephentoub commented 8 years ago

Do you have any ideas @stephentoub what can cause this error?

What is the test doing? Is there a redirect? Some kind of authentication challenge? This error would happen if libcurl is trying to rewind the post request content in order to re-send it but can't.

JunTaoLuo commented 8 years ago

The inconsistency makes it hard to nail down but so far the failures I have seen involve a redirect. Some but not all failures were during auth challenges so I think that's unrelated.

stephentoub commented 8 years ago

And it is posting content, right? What's the type of the HttpContent being used, and if there's a stream involved, the type of the stream? If you're able to get a repro, we can enable tracing and get a much more detailed look at what's happening.

JunTaoLuo commented 8 years ago

Yes, it's posting FormUrlEncodedContent containing a KeyValuePair<string, string>. There is no stream involved, at least I haven't seen one yet. The problem is so far I've been unable to repro this other than Travis which is why I want to get some ideas on what the issue could involve and narrow it down to something I can consistently hit.

stephentoub commented 8 years ago

Does the machine's configuration in Travis CI differ from the others you've tested on? e.g. version of OSX? Version of curl installed? Significantly faster or slower? Significantly different network bandwidth?

JunTaoLuo commented 8 years ago

Strange, seems like upgrading to OSX 10.11 on Travis fixed the problem. This is unexpected since some of the machines I was testing on were osx 10.11 and this error did not appear. Curl versions also seems to be irrelevant as the machines I used all had 7.43.0. There are some resource difference in terms of cpu, mem and bandwidth probably so that's worth a look. I'll run these tests a few more times to see if I can find anything concrete here.

Edit: scratch that, tests can still fail on 10.11.

JunTaoLuo commented 8 years ago

@stephentoub is there any way we can turn on more logging to see what the curl handler is doing? @Tratcher suggested it maybe because the POST request redirects to a GET request but curl is still trying to send the data that was in the original POST. This still doesn't explain why I'm unable to reproduce this issue anywhere else other than our Travis Mac builds but more information regarding what curl is trying to do would be useful.

stephentoub commented 8 years ago

We have very detailed EventSource tracing in the unix implementation of HttpClient, including routing all of libcurl's diagnostic data to the EventSource. If you write a simple EventListener-derived type, e.g. like https://github.com/dotnet/corefx/blob/master/src/Common/tests/System/Diagnostics/Tracing/ConsoleEventListener.cs, you can take the tracing data and route it to wherever you like.

JunTaoLuo commented 8 years ago

Seems like failure occurs right when we get the redirect response (302) from the initial POST request. I have attached the relevant tracing data here but feel free to take a look at the actual test run at https://travis-ci.org/aspnet/MusicStore/jobs/136299790 starting at line 9663. I filtered the events for "System-Net" only to reduce the verbosity but let me know if you want to trace other events too.

info: [Microsoft-System-Net-1] (System.Net.Http.HttpRequestMessage, 19474802, .ctor, Method: POST, Uri: 'Account/LogOff', 0, 1).
info: [Microsoft-System-Net-2] (System.Net.Http.HttpRequestMessage, 19474802, .ctor, , 0, 1).
info: [Microsoft-System-Net-Http-1] (System.Net.Http.HttpRequestMessage, 19474802, System.Net.Http.FormUrlEncodedContent, 41779038).
info: [Microsoft-System-Net-1] (System.Net.Http.HttpClient, 39050990, SendAsync, System.Object[]: Method: POST, RequestUri: 'http://localhost:5020/Account/LogOff', Version: 1.1, Content: System.Net.Http.FormUrlEncodedContent, Headers:
info: {
info:   Content-Type: application/x-www-form-urlencoded
info: }, 0, 1).
info: [Microsoft-System-Net-1] (System.Net.Http.CurlHandler+CurlResponseMessage, 50802233, .ctor, StatusCode: 200, ReasonPhrase: '', 0, 1).
info: [Microsoft-System-Net-2] (System.Net.Http.CurlHandler+CurlResponseMessage, 50802233, .ctor, , 0, 1).
info: [Microsoft-System-Net-Http-1] (System.Net.Http.CurlHandler+CurlResponseMessage, 50802233, System.Net.Http.HttpRequestMessage, 19474802).
info: [Microsoft-System-Net-1] (System.Net.Http.StreamContent, 47693021, .ctor, , 0, 1).
info: [Microsoft-System-Net-2] (System.Net.Http.StreamContent, 47693021, .ctor, , 0, 1).
info: [Microsoft-System-Net-Http-1] (System.Net.Http.StreamContent, 47693021, System.Net.Http.CurlHandler+CurlResponseStream, 24384077).
info: [Microsoft-System-Net-Http-1] (System.Net.Http.CurlHandler+CurlResponseMessage, 50802233, System.Net.Http.StreamContent, 47693021).
info: [Microsoft-System-Net-Http-6] (0, 925, SendAsync, Method: POST, RequestUri: 'http://localhost:5020/Account/LogOff', Version: 1.1, Content: System.Net.Http.FormUrlEncodedContent, Headers:
info: {
info:   Content-Type: application/x-www-form-urlencoded
info: }).
info: [Microsoft-System-Net-Http-6] (0, 0, EnsureWorkerIsRunning, MultiAgent worker queueing).
info: [Microsoft-System-Net-Http-6] (926, 0, WorkerBody, MultiAgent worker running).
info: [Microsoft-System-Net-2] (System.Net.Http.HttpClient, 39050990, SendAsync, System.Threading.Tasks.Task`1[System.Net.Http.HttpResponseMessage], 52284292, 1).
info: [Microsoft-System-Net-Http-6] (926, 925, HandleIncomingRequests, Type: New).
info: [Microsoft-System-Net-Http-6] (0, 925, SetUrl, Url: http://localhost:5020/Account/LogOff).
info: [Microsoft-System-Net-Http-6] (0, 925, SetRedirection, Max automatic redirections: 50).
info: [Microsoft-System-Net-Http-6] (0, 925, SetVerb, Verb: POST).
info: [Microsoft-System-Net-Http-6] (0, 925, SetVersion, HTTP version: 1.1).
info: [Microsoft-System-Net-Http-6] (0, 925, SetDecompressionOptions, Encoding: gzip,deflate).
info: [Microsoft-System-Net-Http-6] (0, 925, SetProxyOptions, UseProxy true, Proxy null, using default proxy).
info: [Microsoft-System-Net-Http-6] (0, 0, GetCredentials, Authentication scheme: None).
info: [Microsoft-System-Net-Http-6] (0, 925, SetCredentialsOptions, Credentials cleared.).
info: [Microsoft-System-Net-Http-6] (0, 925, SetCookieOption, Cookies: .AspNetCore.Session=CfDJ8PBTX6ZV20BHr9FSTLuNssPGMQbv2gqPa8sq5THWjFrxEh%2BqkN6askZNbmtCaZM%2FxAiz%2BJmzKpVtahItClVp6Qgx4hDgyapeLKU%2FnCZNjktR1mACQMzWV%2BUXRo6SagfFZwadeNlU%2FWm732mepCCnoov8r6dpTtaZUFQC86m7TQSv; .AspNetCore.Antiforgery.EJ6jRxkjlxc=CfDJ8PBTX6ZV20BHr9FSTLuNssOW7Jv7Q3Cao8nNYJvWkjk_f4Udsq85JFg7Pa-bBA3aK-87pV6qw_qa-QnXtt_vPdVAj2BmFvSFk9OGc28xy7wnNvecwcCPzmYEA0f2fzEqc8xGyfXwwOhl1ok_ezHTCLs; .AspNetCore.Identity.Application=CfDJ8PBTX6ZV20BHr9FSTLuNssOfg48xqAkSR9MwcMT_p3kvBNDPtn4NbIvrvYLNGiG_lqtaKJ_lgTVxIrH-Wycnirjh1GWLNEvOOLGj6KzZPb7pE3I8g993PeK5Z0N0_DV2338AyKZG5HO2mFWkIoY9U4rGien07Xcb9NMIOIT2RI4OibmGqtx81ERkbkSsPrwIQlJWj40w5V1iKeKUw3u9GEHkrrrlOQcPptVMrR-QuqAk0uIHFs1fSoTpkSqhuauMXoZo1sMJrn3Aq9fk07LfeZNIwGeNzmoj4Q280aPo18qJ_w62LnanhSDtFe6cDaNeiYW6xHnY3rfXTzEDnspZayzdVgO3BBF4VO878U8x2yLlep2t2zPzMMVqeB7gaPlC8zL-ryA2SB9T6z05qOEDaYkF0WWRvB3yhvBKhpcZ_r9fD3BmOjgobHPUu1mAUl8QKZ2ubqAmbsNle_CULiMx0_tA4A8qb7e4a5AwUoxds-EUC2QZXg63C6n9yY4BaMl4MS-vEAfzUdd_7Cd9JPLH2jdVmh0whF1lsRFpO3SuM6kh-icJNSrpufcNjt1y12d9-qWwUBOkOd5Tb-sNYAIjNV1_tfkcu0P44_I0KWsnlp4LsVscgr0Y-q7BOWm6pNWxFg).
info: [Microsoft-System-Net-Http-6] (0, 925, SetSslOptions, CURLOPT_SSL_CTX_FUNCTION not supported: CURLE_NOT_BUILT_IN).
info: [Microsoft-System-Net-Http-6] (0, 925, WriteAsync, Buffer=225, Offset=0, Count=225).
info: [Microsoft-System-Net-Http-6] (0, 925, WriteAsync, No waiting reader. Queueing).
info: [Microsoft-System-Net-Http-6] (926, 925, CurlDebugFunction, CURLINFO_TEXT: Found bundle for host localhost: 0x7fa91b5b4dc0).
info: [Microsoft-System-Net-Http-6] (926, 925, CurlDebugFunction, CURLINFO_TEXT: Re-using existing connection! (#9) with host localhost).
info: [Microsoft-System-Net-Http-6] (926, 925, CurlDebugFunction, CURLINFO_TEXT: Connected to localhost (::1) port 5020 (#9)).
info: [Microsoft-System-Net-Http-6] (926, 925, CurlDebugFunction, CURLINFO_HEADER_OUT: POST /Account/LogOff HTTP/1.1
info: Host: localhost:5020
info: Accept: */*
info: Accept-Encoding: gzip,deflate
info: Cookie: .AspNetCore.Session=CfDJ8PBTX6ZV20BHr9FSTLuNssPGMQbv2gqPa8sq5THWjFrxEh%2BqkN6askZNbmtCaZM%2FxAiz%2BJmzKpVtahItClVp6Qgx4hDgyapeLKU%2FnCZNjktR1mACQMzWV%2BUXRo6SagfFZwadeNlU%2FWm732mepCCnoov8r6dpTtaZUFQC86m7TQSv; .AspNetCore.Antiforgery.EJ6jRxkjlxc=CfDJ8PBTX6ZV20BHr9FSTLuNssOW7Jv7Q3Cao8nNYJvWkjk_f4Udsq85JFg7Pa-bBA3aK-87pV6qw_qa-QnXtt_vPdVAj2BmFvSFk9OGc28xy7wnNvecwcCPzmYEA0f2fzEqc8xGyfXwwOhl1ok_ezHTCLs; .AspNetCore.Identity.Application=CfDJ8PBTX6ZV20BHr9FSTLuNssOfg48xqAkSR9MwcMT_p3kvBNDPtn4NbIvrvYLNGiG_lqtaKJ_lgTVxIrH-Wycnirjh1GWLNEvOOLGj6KzZPb7pE3I8g993PeK5Z0N0_DV2338AyKZG5HO2mFWkIoY9U4rGien07Xcb9NMIOIT2RI4OibmGqtx81ERkbkSsPrwIQlJWj40w5V1iKeKUw3u9GEHkrrrlOQcPptVMrR-QuqAk0uIHFs1fSoTpkSqhuauMXoZo1sMJrn3Aq9fk07LfeZNIwGeNzmoj4Q280aPo18qJ_w62LnanhSDtFe6cDaNeiYW6xHnY3rfXTzEDnspZayzdVgO3BBF4VO878U8x2yLlep2t2zPzMMVqeB7gaPlC8zL-ryA2SB9T6z05qOEDaYkF0WWRvB3yhvBKhpcZ_r9fD3BmOjgobHPUu1mAUl8QKZ2ubqAmbsNle_CULiMx0_tA4A8qb7e4a5AwUoxds-EUC2QZXg63C6n9yY4BaMl4MS-vEAfzUdd_7Cd9JPLH2jdVmh0whF1lsRFpO3SuM6kh-icJNSrpufcNjt1y12d9-qWwUBOkOd5Tb-sNYAIjNV1_tfkcu0P44_I0KWsnlp4LsVscgr0Y-q7BOWm6pNWxFg
info: Content-Type: application/x-www-form-urlencoded
info: Content-Length: 225).
info: [Microsoft-System-Net-Http-6] (926, 925, CurlSendCallback, Size: 16384).
info: [Microsoft-System-Net-Http-6] (926, 925, TransferDataFromRequestStream, Length: 16384).
info: [Microsoft-System-Net-Http-6] (926, 925, ReadAsyncInternal, Buffer=225, Offset=0, Count=225).
info: [Microsoft-System-Net-Http-6] (926, 925, ReadAsyncInternal, Completing waiting writer).
info: [Microsoft-System-Net-Http-6] (926, 925, ReadAsyncInternal, Read 225 bytes, 0 remain buffered).
info: [Microsoft-System-Net-Http-6] (926, 925, CurlDebugFunction, CURLINFO_DATA_OUT: 225 bytes).
info: [Microsoft-System-Net-Http-6] (926, 925, CurlDebugFunction, CURLINFO_TEXT: We are completely uploaded and fine).
info: [Microsoft-System-Net-Http-6] (926, 925, CurlDebugFunction, CURLINFO_HEADER_IN: HTTP/1.1 302 Found).
info: [Microsoft-System-Net-Http-6] (926, 925, CurlReceiveHeadersCallback, Size: 20).
info: [Microsoft-System-Net-Http-6] (926, 925, CurlReceiveHeadersCallback, Received status line).
info: [Microsoft-System-Net-Http-6] (926, 925, CurlDebugFunction, CURLINFO_HEADER_IN: Cache-Control: no-cache).
info: [Microsoft-System-Net-Http-6] (926, 925, CurlReceiveHeadersCallback, Size: 25).
info: [Microsoft-System-Net-Http-6] (926, 925, CurlDebugFunction, CURLINFO_HEADER_IN: Date: Thu, 09 Jun 2016 00:21:13 GMT).
info: [Microsoft-System-Net-Http-6] (926, 925, CurlReceiveHeadersCallback, Size: 37).
info: [Microsoft-System-Net-Http-6] (926, 925, CurlDebugFunction, CURLINFO_HEADER_IN: Pragma: no-cache).
info: [Microsoft-System-Net-Http-6] (926, 925, CurlReceiveHeadersCallback, Size: 18).
info: [Microsoft-System-Net-Http-6] (926, 925, CurlDebugFunction, CURLINFO_HEADER_IN: Content-Length: 0).
info: [Microsoft-System-Net-Http-6] (926, 925, CurlReceiveHeadersCallback, Size: 19).
info: [Microsoft-System-Net-Http-6] (926, 925, CurlDebugFunction, CURLINFO_HEADER_IN: Expires: -1).
info: [Microsoft-System-Net-Http-6] (926, 925, CurlReceiveHeadersCallback, Size: 13).
info: [Microsoft-System-Net-Http-6] (926, 925, CurlSeekCallback, Offset: 0, Origin: 0).
info: [Microsoft-System-Net-Http-6] (926, 925, TryReset, TryReset failed due to in-progress copy.).
info: [Microsoft-System-Net-Http-6] (926, 925, CurlSeekCallback, Can't seek).
info: [Microsoft-System-Net-Http-6] (926, 925, CurlDebugFunction, CURLINFO_TEXT: seek callback returned error 2).
info: [Microsoft-System-Net-Http-6] (926, 925, CurlDebugFunction, CURLINFO_TEXT: Closing connection 9).
info: [Microsoft-System-Net-Http-6] (926, 925, FinishRequest, Curl result: 65).
info: [Microsoft-System-Net-Http-6] (0, 0, ThrowIfCURLEError, Send failed since rewinding of the data stream failed).
info: [Microsoft-System-Net-Http-6] (926, 925, FailRequest, Failing request: System.Net.Http.CurlException: Send failed since rewinding of the data stream failed
info:    at System.Net.Http.CurlHandler.ThrowIfCURLEError(CURLcode error)
info:    at System.Net.Http.CurlHandler.MultiAgent.FinishRequest(StrongToWeakReference`1 easyWrapper, CURLcode messageResult)).
info: [Microsoft-System-Net-Http-6] (926, 925, SignalComplete, Marking as complete).
info: [Microsoft-System-Net-Http-6] (926, 925, SignalComplete, Already completed).
info: [Microsoft-System-Net-Http-6] (926, 925, Dispose, Disposing request stream).
info: [Microsoft-System-Net-Http-6] (926, 925, EndCopyToAsync, Copy completed: RanToCompletion).
info: [Microsoft-System-Net-4] (An error occurred while sending System.Object[]. System.Net.Http.HttpRequestException: An error occurred while sending the request. ---> System.Net.Http.CurlException: Send failed since rewinding of the data stream failed
info:    at System.Net.Http.CurlHandler.ThrowIfCURLEError(CURLcode error)
info:    at System.Net.Http.CurlHandler.MultiAgent.FinishRequest(StrongToWeakReference`1 easyWrapper, CURLcode messageResult)
info:    --- End of inner exception stack trace ---
info:    at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
info:    at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
info:    at System.Net.Http.HttpClient.<FinishSendAsync>d__58.MoveNext(), SendAsync, System.Net.Http.HttpClient, 39050990, 1).
info: [Microsoft-System-Net-3] (System.Net.Http.HttpClient, SendAsync, An error occurred while sending the request., 39050990,    at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
info:    at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
info:    at System.Net.Http.HttpClient.<FinishSendAsync>d__58.MoveNext(), 1).
info: [Microsoft-System-Net-Http-6] (926, 0, Dispose, ).
info: [Microsoft-System-Net-Http-6] (926, 0, RequestWakeup, ).
info: [Microsoft-System-Net-Http-6] (926, 0, HandleIncomingRequests, Type: Shutdown).
info: [Microsoft-System-Net-Http-6] (926, 0, CleanUpRemainingActiveOperations, Shutting down 0 active operations.).
info: [Microsoft-System-Net-Http-6] (926, 0, WorkerBody, MultiAgent worker shutting down).

Can you take a look and see what the issue here is?

stephentoub commented 8 years ago

Thanks. I'll take a look.