Move to use interfaces, that will let us later add tests that will
verify that all the correct logging is performed. As an example, added a
test for XmlResultParser that ensures that the failures are correctly
generated. The test uses Moq to pass the different paths to be used and
later be able to verify the wirtten xml.
One of the reason why we lost the TestReport was because the xml added
from the new code did not use the same name for the log as the expected
one (https://github.com/xamarin/xamarin-macios/pull/7835/files#diff-03773861bcef485bf343300f31b60b0eR374).
If we are going to be using the description as a way to decide what is
going to be done with it, lets use static vars so that we do not have
logs added with the wrong name.
* [xharness] Timestamp all the things.
I find myself wanting timestamps if I don't have them much more than wanting
them gone when I do.
Worst case scenario: timestamps can still be disabled for specific logs if
such a desire ever becomes overwhelming.
* [xharness] Don't timestamp xml files.
* Instead of calculating a timeout based on the app size and an estimated
transfer speed, keep transferring as long as mlaunch outputs something to
stdout. The actual transfer speed can vary a lot, in particular if
installing to multiple nearby watches simultaneously.
* Improve progress text in the html report during installation to include more
statistics for the impatient.
Sometimes files just shrink, and we must cope.
Two possible causes I can think of:
* System log rotation.
* We erase a simulator when trying to capture its system log.
There are probably many more causes, but two is more than enough to make sure
we don't fail when it happens.
Should fix this (or at the very least not prevent xharness from writing out the report):
21:07:30.3947450 Failed to write log: System.IO.FileNotFoundException: Could not find file '/Users/builder/Library/Logs/CoreSimulator/6DA2ED3C-B1FA-4D0B-9DD6-113E5F9A1381/system.log'.
File name: '/Users/builder/Library/Logs/CoreSimulator/6DA2ED3C-B1FA-4D0B-9DD6-113E5F9A1381/system.log'
at System.IO.__Error.WinIOError (System.Int32 errorCode, System.String maybeFullPath) [0x00207] in /Users/builder/jenkins/workspace/build-package-osx-mono/2018-02/external/bockbuild/builds/mono-x64/mcs/class/referencesource/mscorlib/system/io/__error.cs:188
at System.IO.FileInfo.get_Length () [0x00038] in /Users/builder/jenkins/workspace/build-package-osx-mono/2018-02/external/bockbuild/builds/mono-x64/mcs/class/referencesource/mscorlib/system/io/fileinfo.cs:171
at xharness.CaptureLog.Capture () [0x0004a] in /Users/builder/jenkins/workspace/xamarin-macios/xamarin-macios/tests/xharness/Log.cs:334
at xharness.CaptureLog.Flush () [0x00008] in /Users/builder/jenkins/workspace/xamarin-macios/xamarin-macios/tests/xharness/Log.cs:373
at xharness.Jenkins.GenerateReportImpl (System.IO.Stream stream, System.IO.StreamWriter markdown_summary) [0x017db] in /Users/builder/jenkins/workspace/xamarin-macios/xamarin-macios/tests/xharness/Jenkins.cs:2012
at xharness.Jenkins.GenerateReport (System.Boolean only_if_ci) [0x00075] in /Users/builder/jenkins/workspace/xamarin-macios/xamarin-macios/tests/xharness/Jenkins.cs:1313
Detect if we failed to create a simulator device pair due to trying with a
watch that's already paired. We were already detecting this scenario if the
watch was a member of an available pair, but not if the watch was a member of
an _unavailable_ pair (since mlaunch doesn't list unavailable device pairs).
So detect this scenario from the error message simctl gives us instead, and in
that case create a new watch device and try to create the pair again.
Fixes https://github.com/xamarin/maccore/issues/830.
Make sure to override all required TextWriter methods so that the LogFile gets
all the output any writers (such as the XmlWriter that is used to create the
html report for NUnit tests by applying an XSLT transform to the xml results)
writes.
Make the collection of logs (the `Logs` class) more capable by making it
disposable (which will dispose all contained logs) and give it a Directory
property to state where the logs should be stored. This makes it possible to
simplify a few repeated path calculations. It also allows us to easily dispose
the entire collection of logs when done with a test, as opposed to dispoing
the logs one by one.
Make LogFile more capable:
* Add support for writing byte arrays.
* Add support for logging after disposal: this will still write to the file,
and not keep any files open after finished writing. This fixes a problem
where writing to a log after it was disposed would crash xharness (which is
not all that uncommon, given the async nature of how xharness runs tests).
This makes it possible to get rid of LogStream, and use LogFile instead.
Dispose logs (so that the corresponding files are closed) when we're done with
them, and also don't open a file log by default (usually we just want a
filename to pass to somebody else), but instead open the file if needed.
This should decrease the number of open file descriptors in xharness, which
sometimes become a problem when running many tests.
* [xharness] Add support for executing a command periodically.
This will be used to run 'rsync' on bots to upload the html report somewhere
while the tests are running.
* [tests] Disable all the wrench test targets, and instead run the jenkins target (only) on wrench.
* [xharness] Write xharness log to stdout as well on wrench.
Wrench has a 30-min stdout timeout: if nothing is printed in 30 minutes, then
the step fails. Printing the harness log to stdout makes us not hit this
timeout.
* [xharness] Timestamp a few more logs.
* [xharness] Disable the @MonkeyWrench calls, since we're not uploading directly to wrench anymore.
Detect MT1111 from mlaunch (which means mlaunch won't wait for the app to
exit), and instead use test run completion to determine test completion.
The main drawback is that if the test app crashes, it won't be detected (the
test run will time out, and reported as such), but it's still an improvement
over the current behavior (the tests may complete successfully, and still be
reported as timed out).
This also requires bumping maccore to get an updated mlaunch (one that reports
MT1111).
Fixes this exception:
```
Harness exception for 'introspection': System.IO.FileNotFoundException: Could not find file '/Users/builder/Library/Logs/CoreSimulator/27618A4A-7E49-4BAB-8F77-FA938CE88682/system.log'.
File name: '/Users/builder/Library/Logs/CoreSimulator/27618A4A-7E49-4BAB-8F77-FA938CE88682/system.log'
at System.IO.__Error.WinIOError (System.Int32 errorCode, System.String maybeFullPath) [0x00207] in /private/tmp/source-mono-2017-04/bockbuild-2017-04/profiles/mono-mac-xamarin/build-root/mono-x64/mcs/class/referencesource/mscorlib/system/io/__error.cs:188
at System.IO.FileInfo.get_Length () [0x00038] in /private/tmp/source-mono-2017-04/bockbuild-2017-04/profiles/mono-mac-xamarin/build-root/mono-x64/mcs/class/referencesource/mscorlib/system/io/fileinfo.cs:171
at xharness.CaptureLog.StopCapture () [0x00021] in /Users/builder/jenkins/workspace/xamarin-macios-pr-builder/tests/xharness/Log.cs:252
at (wrapper remoting-invoke-with-check) xharness.CaptureLog:StopCapture ()
at xharness.AppRunner+<RunAsync>d__68.MoveNext () [0x0127f] in /Users/builder/jenkins/workspace/xamarin-macios-pr-builder/tests/xharness/AppRunner.cs:642
--- End of stack trace from previous location where exception was thrown ---
at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw () [0x0000c] in /private/tmp/source-mono-2017-04/bockbuild-2017-04/profiles/mono-mac-xamarin/build-root/mono-x64/mcs/class/referencesource/mscorlib/system/runtime/exceptionservices/exceptionservicescommon.cs:151
at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess (System.Threading.Tasks.Task task) [0x00037] in /private/tmp/source-mono-2017-04/bockbuild-2017-04/profiles/mono-mac-xamarin/build-root/mono-x64/mcs/class/referencesource/mscorlib/system/runtime/compilerservices/TaskAwaiter.cs:187
at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification (System.Threading.Tasks.Task task) [0x00028] in /private/tmp/source-mono-2017-04/bockbuild-2017-04/profiles/mono-mac-xamarin/build-root/mono-x64/mcs/class/referencesource/mscorlib/system/runtime/compilerservices/TaskAwaiter.cs:156
at System.Runtime.CompilerServices.TaskAwaiter.ValidateEnd (System.Threading.Tasks.Task task) [0x00008] in /private/tmp/source-mono-2017-04/bockbuild-2017-04/profiles/mono-mac-xamarin/build-root/mono-x64/mcs/class/referencesource/mscorlib/system/runtime/compilerservices/TaskAwaiter.cs:128
at System.Runtime.CompilerServices.TaskAwaiter`1[TResult].GetResult () [0x00000] in /private/tmp/source-mono-2017-04/bockbuild-2017-04/profiles/mono-mac-xamarin/build-root/mono-x64/mcs/class/referencesource/mscorlib/system/runtime/compilerservices/TaskAwaiter.cs:357
at xharness.RunSimulatorTask+<RunTestAsync>d__7.MoveNext () [0x0029d] in /Users/builder/jenkins/workspace/xamarin-macios-pr-builder/tests/xharness/Jenkins.cs:2894
--- End of stack trace from previous location where exception was thrown ---
at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw () [0x0000c] in /private/tmp/source-mono-2017-04/bockbuild-2017-04/profiles/mono-mac-xamarin/build-root/mono-x64/mcs/class/referencesource/mscorlib/system/runtime/exceptionservices/exceptionservicescommon.cs:151
at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess (System.Threading.Tasks.Task task) [0x00037] in /private/tmp/source-mono-2017-04/bockbuild-2017-04/profiles/mono-mac-xamarin/build-root/mono-x64/mcs/class/referencesource/mscorlib/system/runtime/compilerservices/TaskAwaiter.cs:187
at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification (System.Threading.Tasks.Task task) [0x00028] in /private/tmp/source-mono-2017-04/bockbuild-2017-04/profiles/mono-mac-xamarin/build-root/mono-x64/mcs/class/referencesource/mscorlib/system/runtime/compilerservices/TaskAwaiter.cs:156
at System.Runtime.CompilerServices.TaskAwaiter.ValidateEnd (System.Threading.Tasks.Task task) [0x00008] in /private/tmp/source-mono-2017-04/bockbuild-2017-04/profiles/mono-mac-xamarin/build-root/mono-x64/mcs/class/referencesource/mscorlib/system/runtime/compilerservices/TaskAwaiter.cs:128
at System.Runtime.CompilerServices.TaskAwaiter.GetResult () [0x00000] in /private/tmp/source-mono-2017-04/bockbuild-2017-04/profiles/mono-mac-xamarin/build-root/mono-x64/mcs/class/referencesource/mscorlib/system/runtime/compilerservices/TaskAwaiter.cs:113
at xharness.RunTestTask+<ExecuteAsync>d__8.MoveNext () [0x0010b] in /Users/builder/jenkins/workspace/xamarin-macios-pr-builder/tests/xharness/Jenkins.cs:2538
--- End of stack trace from previous location where exception was thrown ---
at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw () [0x0000c] in /private/tmp/source-mono-2017-04/bockbuild-2017-04/profiles/mono-mac-xamarin/build-root/mono-x64/mcs/class/referencesource/mscorlib/system/runtime/exceptionservices/exceptionservicescommon.cs:151
at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess (System.Threading.Tasks.Task task) [0x00037] in /private/tmp/source-mono-2017-04/bockbuild-2017-04/profiles/mono-mac-xamarin/build-root/mono-x64/mcs/class/referencesource/mscorlib/system/runtime/compilerservices/TaskAwaiter.cs:187
at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification (System.Threading.Tasks.Task task) [0x00028] in /private/tmp/source-mono-2017-04/bockbuild-2017-04/profiles/mono-mac-xamarin/build-root/mono-x64/mcs/class/referencesource/mscorlib/system/runtime/compilerservices/TaskAwaiter.cs:156
at System.Runtime.CompilerServices.TaskAwaiter.ValidateEnd (System.Threading.Tasks.Task task) [0x00008] in /private/tmp/source-mono-2017-04/bockbuild-2017-04/profiles/mono-mac-xamarin/build-root/mono-x64/mcs/class/referencesource/mscorlib/system/runtime/compilerservices/TaskAwaiter.cs:128
at System.Runtime.CompilerServices.TaskAwaiter.GetResult () [0x00000] in /private/tmp/source-mono-2017-04/bockbuild-2017-04/profiles/mono-mac-xamarin/build-root/mono-x64/mcs/class/referencesource/mscorlib/system/runtime/compilerservices/TaskAwaiter.cs:113
at xharness.TestTask+<RunInternalAsync>d__87.MoveNext () [0x0010d] in /Users/builder/jenkins/workspace/xamarin-macios-pr-builder/tests/xharness/Jenkins.cs:1870
```
I'm not sure how this can happen, but it has on the bots [1].
[1] https://jenkins.mono-project.com/job/xamarin-macios-pr-builder/4548/Test_Report/
Don't create multiple writer streams for the same underlying file, instead
store the writer stream on the log instance, and return it whenever needed.
This fixes an issue where there would be multiple writer streams, which could
cause exceptions when creating more writer streams (access defined errors
because the file is already open).
e.g. running twice
> make run-ios-sim32-introspection
results in
Unhandled Exception:
System.AggregateException: One or more errors occurred. ---> System.IO.IOException: /Users/poupou/git/master/xamarin-macios/tests/logs/exec-ios-sim32-introspection/iPhone 5.log already exists
at System.IO.File.Copy (System.String sourceFileName, System.String destFileName, System.Boolean overwrite) [0x001bd] in /private/tmp/source-mono-4.8.0/bockbuild-mono-4.8.0-branch/profiles/mono-mac-xamarin/build-root/mono-x86/mcs/class/corlib/System.IO/File.cs:109
at System.IO.File.Copy (System.String sourceFileName, System.String destFileName) [0x00000] in /private/tmp/source-mono-4.8.0/bockbuild-mono-4.8.0-branch/profiles/mono-mac-xamarin/build-root/mono-x86/mcs/class/corlib/System.IO/File.cs:69
at xharness.CaptureLog.StopCapture () [0x00019] in /Users/poupou/git/master/xamarin-macios/tests/xharness/Log.cs:252
Example log output when bumping mono:
> Found 1 modified file(s) in the pull request #1161.
> external/mono
> Enabled 'mtouch' tests because the modified file 'external/mono' matches prefix 'external/mono'
> Enabled 'mmp' tests because the modified file 'external/mono' matches prefix 'external/mono'
> Enabled 'bcl' tests because the modified file 'external/mono' matches prefix 'external/mono'
> Found 1 label(s) in the pull request #1161: cla-already-signed
Or when changing the static registrar:
> Found 1 modified file(s) in the pull request #1164.
> tools/common/StaticRegistrar.cs
> Enabled 'mtouch' tests because the modified file 'tools/common/StaticRegistrar.cs' matches prefix 'tools/common'
> Enabled 'mmp' tests because the modified file 'tools/common/StaticRegistrar.cs' matches prefix 'tools/common'
> Found 2 label(s) in the pull request #1164: cla-already-signed, run-mmp-tests
> Enabled 'mmp' tests because the label 'run-mmp-tests' is set.
Make sure as much as possible is written to the logs, and not stdout.
Also copy an extra 1024 bytes when fetching the system log (and continue
capturing a while after stopped, since there may be unflushed system log
data in memory).
Split out the code to prepare the simulator from the AppRunner class,
which is now just handling the logic required for each test run.
This way it's easier to handle simulator preparation for multiple
test runs with the same simulator.
Also revamp logging to avoid printing directly to the console, but
instead use the logging classes that permit redirecting logging
to a file. This makes the html report show better logging.
Manuel de la Pena
Rolf Bjarne Kvinge
Vincent Dondain
Sebastien Pouliot