Fastlane-plugin-test_center: Simulator logs can't be collected because Scan uses the wrong device

[lilyball]

New Issue Checklist

• [ ] Updated fastlane-plugin-test_center to the latest version
• [X] I read the README.md
• [X] I reviewed the example(s) for the action(s) I am using
• [X] I have removed any sensitive data such as passwords, authentication tokens, or anything else I do not want to world to see

If you love this fastlane plugin, consider sponsoring it or asking your company to sponsor it. I would really appreciate any
gesture: https://github.com/sponsors/lyndsey-ferguson.

Issue Description

When using multi_scan to run tests in parallel, it does the initial build-for-testing passing the selected device to Scan, and then it runs separate Scan instances specifying destination instead of device. The problem is Scan uses the wrong device when running the tests, including it's "Disable 'Slide to Type'" step and its "Collecting system logs" step.

Digging into the source it looks like this plugin is explicitly omitting the device option for the actual test runs, instead using destination to specify where to run it. However these steps use Scan.devices. I suspect this just contains the same device that was originally used to build for testing, but it may alternatively include the default detected device used when device/devices is not specified.

Ultimately, this means the actual test run itself works, but the auxiliary steps that Scan takes don't. I'm really not sure why test_center is relying on destination here instead of using device. I believe it's not actually reassigning to Scan.config in between build-for-testing and the test, meaning it won't recalculate Scan.devices anyway, but even if it did it wouldn't pick up the right device.

Complete output when running fastlane, including the stack trace and command used

I don't feel comfortable including that here. But the two relevant bits look like

[worker 1] [14:30:10]: $ set -o pipefail && env NSUnbufferedIO=YES xcodebuild -destination 'platform=iOS Simulator,id=BFA67400-C7A2-4220-BC81-8A3D7E125129' …
…
[worker 1] [14:46:13]: $ xcrun simctl spawn --standalone 1E7FA8C3-65E3-46CA-AA7E-809BA7EEBFA7 log collect --output /path/to/fastlane/test_output/TargetName/TargetNameTests-batch-1/system_logs-iPhone\ 8_iOS_13.4.logarchive 2>/dev/null

Note how it's using a different simulator for these two actions. And that's because the former is using the destination config value but the latter is trying to collect logs for each entry in Scan.devices.

Environment

I don't feel comfortable giving you all this info either. However the parameters we're passing to multi_scan look like the following:

{
  buildlog_path: "fastlane/logs/scan/",
  derived_data_path: "fastlane/DerivedData",
  output_directory: "/path/to/fastlane/test_output/TargetName",
  scheme: "TargetNameTests",
  xcargs: "some random args here",
  fail_build: false,
  quit_simulators: true,
  include_simulator_logs: true,
  try_count: 2,
  batch_count: 1,
  parallel_testrun_count: 4,
  testrun_completed_block: some_block,
  only_testing: array_of_tests,
  device: "iPhone 8"
}

fastlane itself is currently version 2.143.0, and the test_center plugin is v3.10.1, but I don't see any relevant changes in test_center since that version.

[lyndsey-ferguson]

Hello @lilyball, thanks for the report. The reason why destination is used is that multi_scan clones the chosen simulator for each parallel_testrun so that the subset of tests runs _only_ on that simulator. No other tests will run on that simulator.

I'm not familiar with the "slide to unlock" step, are you saying that is part of the scan action itself? And that it is using the "device" option instead of whatever is given? I _believe_ that I specifically wipe out the :device option to ensure that it uses the :destinations option.

The general summary of this issue is that logs are not collected for the cloned simulators?

[lilyball]

"Disable 'Slide to Type'" is just one of the steps scan seems to run by default. It involves writing a defaults key on the simulator, prior to running the tests. I'm not really sure why it does this but it's just an example of an action that Scan applies to Scan.devices that is supposed to be applied to the test simulator.

More important to me is the fact that logs aren't being collected, because it's trying to collect them from Scan.devices, which doesn't contain the correct device.

test_center is wiping out device and devices from Scan.config but Scan.devices is left alone, which means it contains the device originally used for build-for-testing. If you skip the build-for-testing step then I expect it would end up auto-detecting the first available device, because assigning to Scan.config will do that, which would still leave it running these actions on the wrong device.

[lyndsey-ferguson]

Ok, I've duplicated the problem, and made significant progress. However, the logs are not brought into the final output folder when I'm collating the results. I have to fix that.

[lyndsey-ferguson]

If you want to observe the lack of a crash, modify your Pluginfile per my instructions below, run bundle install, and then run your fastlane again (with the --verbose flag)?

Pluginfile:

gem 'fastlane-plugin-test_center', :git => "https://github.com/lyndsey-ferguson/fastlane-plugin-test_center.git", :branch => "issue-233-prepopulated-devices-sent-to-scan"

If there are still problems, please let me know and attach the console output as a text file to this issue (makes it easier for me to review). If it works, please let me know.

[lilyball]

It didn't work.

It's still using the wrong device for the "Disabling 'Slide to Type'" and "Collecting system logs" steps. Not only that, but it's failing after merging the result bundles.

There's a crazy amount of console output, including a lot of details about the project, so I really don't feel comfortable attaching it. But the failure looks like

DEBUG [2020-06-17 17:27:24.39]: Collating xcresult bundles ["/path/to/fastlane/test_output/TargetNameTests-batch-4/report.xcresult", "/path/to/fastlane/test_output/TargetNameTests-batch-2/report.xcresult", "/path/to/fastlane/test_output/TargetNameTests-batch-1/report.xcresult", "/path/to/fastlane/test_output/TargetNameTests-batch-3/report.xcresult"]
INFO [2020-06-17 17:27:24.39]: $ xcrun xcresulttool merge /path/to/fastlane/test_output/TargetNameTests-batch-4/report.xcresult /path/to/fastlane/test_output/TargetNameTests-batch-2/report.xcresult /path/to/fastlane/test_output/TargetNameTests-batch-1/report.xcresult /path/to/fastlane/test_output/TargetNameTests-batch-3/report.xcresult --output-path /var/folders/nq/dmc1zzf938163pj2rm8tcrbr0000gn/T/collated_result_20200617-78487-147hm84.xcresult
INFO [2020-06-17 17:27:35.27]: ▸ [v3] Merged to: /var/folders/nq/dmc1zzf938163pj2rm8tcrbr0000gn/T/collated_result_20200617-78487-147hm84.xcresult
INFO [2020-06-17 17:27:35.76]: Finished collating xcresults to '/path/to/fastlane/test_output/TargetNameTests/report.xcresult'
ERROR [2020-06-17 17:27:35.99]: Error setting value '["/path/to/fastlane/test_output/TargetNameTests/report.xcresult", "/path/to/fastlane/test_output/report.xcresult"]' for option 'xcresults'

and then of course fastlane itself failed with the error

ERROR [2020-06-17 17:27:36.12]: Error: xcresult bundle not found: '/path/to/fastlane/test_output/report.xcresult'

I'm not sure what's going on here, and the changes on your branch seem to be unrelated. So this may be an issue caused by going to test_center v3.11.2, which itself would be a problem.

---

As for the device, it's still using the exact same device for the two steps as it was before, which is the original test device (which also happens to be the first device in my list, so I can't tell offhand if it's preserving the test device or re-detecting it). The only improvement I noticed was multi_scan now told Scan not to collect logs on the build-for-testing step (which is good because if the simulator has never been launched then that step will fail).

I have saved the complete verbose output locally if you want me to look something up in it. I did notice the following debug line:

[worker 4] DEBUG [2020-06-17 17:25:17.83]:  Setting Scan.devices to an empty array

but that didn't actually work. Glancing at the code right now, you're just defining a local variable instead of actually overwriting Scan.devices; I believe you want scan_devices.clear instead of scan_devices = []. Still, if that did work, that would disable the log collection step entirely.

FWIW I expect the "crash" you're talking about is the fact that log collection fails if the simulator in question has never been run. The branch does indeed fix that merely by disabling log collection on the build.

[lyndsey-ferguson]

There should be a stack crawl providing more information of what crashed without exposing any of your data.

scan_devices is a method, and I think you're right about how to clear it out. The crash was for the build step.

I won't be able to look into it more today, hopefully I'll get some more time tomorrow evening

[lyndsey-ferguson]

I have not been able to make it crash, here is my fastlane env:

✅ fastlane environment ✅

Stack

| Key | Value |
| --------------------------- | ------------------------------------------------- |
| OS | 10.15.5 |
| Ruby | 2.4.1 |
| Bundler? | false |
| Git | git version 2.25.0 |
| Installation Source | ~/.rbenv/versions/2.4.1/bin/fastlane |
| Host | Mac OS X 10.15.5 (19F101) |
| Ruby Lib Dir | ~/.rbenv/versions/2.4.1/lib |
| OpenSSL Version | OpenSSL 1.1.0j 20 Nov 2018 |
| Is contained | false |
| Is homebrew | false |
| Is installed via Fabric.app | false |
| Xcode Path | /Applications/Xcode11.4.1.app/Contents/Developer/ |
| Xcode Version | 11.4.1 |

System Locale

| Variable | Value | |
| -------- | ----------- | - |
| LANG | en_US.UTF-8 | ✅ |
| LC_ALL | | |
| LANGUAGE | | |

fastlane files:

./fastlane/Fastfile

require_relative 'test_center_utils'

# Retrieves the example code from each action and runs it to ensure that everything
# is working as intended.
lane :run_examples do
  action_examples.values.flatten.each do |example_code_snippet|
    # rubocop:disable Security/Eval
    eval(example_code_snippet)
    # rubocop:enable Security/Eval
  end
end

lane :testing do
  multi_scan(
    workspace: File.absolute_path('../AtomicBoy/AtomicBoy.xcworkspace'),
    scheme: 'AtomicBoy',
    try_count: 3,
    buildlog_path: "logs/scan/",
    derived_data_path: "DerivedData",
    fail_build: false,
    result_bundle: true,
    batch_count: 1,
    quit_simulators: true,
    include_simulator_logs: true,
    parallel_testrun_count: 4,
    device: "iPhone 8"
  )
end

No Appfile found

fastlane gems

| Gem | Version | Update-Status |
| -------- | ------- | ------------- |
| fastlane | 2.149.1 | ✅ Up-To-Date |

Loaded fastlane plugins:

| Plugin | Version | Update-Status |
| --------------------------- | ------- | ------------- |
| fastlane-plugin-test_center | 3.11.2 | ✅ Up-To-Date |

Loaded gems

| Gem | Version |
| ------------------------- | ------------ |
| did_you_mean | 1.1.0 |
| slack-notifier | 2.3.2 |
| rouge | 2.0.7 |
| xcpretty | 0.3.0 |
| terminal-notifier | 2.0.0 |
| terminal-table | 1.8.0 |
| multipart-post | 2.0.0 |
| word_wrap | 1.0.0 |
| public_suffix | 2.0.5 |
| colored | 1.2 |
| highline | 1.7.10 |
| commander-fastlane | 4.4.6 |
| http-cookie | 1.0.3 |
| faraday-cookie_jar | 0.0.6 |
| gh_inspector | 1.1.3 |
| mini_magick | 4.10.1 |
| multi_xml | 0.6.0 |
| rubyzip | 1.3.0 |
| security | 0.1.3 |
| xcpretty-travis-formatter | 1.0.0 |
| jwt | 2.1.0 |
| uber | 0.1.0 |
| declarative | 0.0.10 |
| declarative-option | 0.1.0 |
| representable | 3.0.4 |
| retriable | 3.1.2 |
| mini_mime | 1.0.2 |
| httpclient | 2.8.3 |
| google-api-client | 0.38.0 |
| nanaimo | 0.2.6 |
| colored2 | 3.1.2 |
| claide | 1.0.3 |
| CFPropertyList | 3.0.2 |
| atomos | 0.1.3 |
| xcodeproj | 1.16.0 |
| unicode-display_width | 1.7.0 |
| plist | 3.5.0 |
| addressable | 2.7.0 |
| tty-screen | 0.8.0 |
| tty-cursor | 0.7.1 |
| tty-spinner | 0.9.3 |
| babosa | 1.0.3 |
| excon | 0.75.0 |
| faraday | 1.0.1 |
| unf_ext | 0.0.7.7 |
| unf | 0.1.4 |
| domain_name | 0.5.20190701 |
| faraday_middleware | 1.0.0 |
| fastimage | 2.1.7 |
| json | 2.3.0 |
| dotenv | 2.7.5 |
| bundler | 2.1.4 |
| naturally | 2.2.0 |
| simctl | 1.6.8 |
| multi_json | 1.14.1 |
| signet | 0.14.0 |
| os | 1.1.0 |
| memoist | 0.16.2 |
| googleauth | 0.12.0 |
| digest-crc | 0.5.1 |
| google-cloud-errors | 1.0.1 |
| google-cloud-env | 1.3.2 |
| google-cloud-core | 1.5.0 |
| google-cloud-storage | 1.26.2 |
| emoji_regex | 1.0.1 |
| aws-eventstream | 1.1.0 |
| aws-sigv4 | 1.2.0 |
| aws-partitions | 1.330.0 |
| jmespath | 1.4.0 |
| aws-sdk-core | 3.100.0 |
| aws-sdk-kms | 1.34.1 |
| aws-sdk-s3 | 1.68.1 |
| openssl | 2.0.3 |
| io-console | 0.4.6 |
| mini_portile2 | 2.4.0 |
| nokogiri | 1.10.9 |
| psych | 2.2.2 |
| ox | 2.12.1 |
| xctest_list | 1.1.8 |
| colorize | 0.8.1 |

generated on: 2020-06-18

[lilyball]

The "Error setting value" line has no stack trace. The final "Error: xcresult bundle not found" has the following trace:

Stack trace

FastlaneCore::Interface::FastlaneError: [!] Error: xcresult bundle not found: '/path/to/fastlane/test_output/report.xcresult'
  /path/to/.gems/ruby/2.6.0/gems/fastlane-2.143.0/fastlane_core/lib/fastlane_core/configuration/config_item.rb:223:in `rescue in valid?'
  /path/to/.gems/ruby/2.6.0/gems/fastlane-2.143.0/fastlane_core/lib/fastlane_core/configuration/config_item.rb:219:in `valid?'
  /path/to/.gems/ruby/2.6.0/gems/fastlane-2.143.0/fastlane_core/lib/fastlane_core/configuration/config_item.rb:181:in `verify!'
  /path/to/.gems/ruby/2.6.0/gems/fastlane-2.143.0/fastlane_core/lib/fastlane_core/configuration/configuration.rb:87:in `block in verify_value_exists'
  /path/to/.gems/ruby/2.6.0/gems/fastlane-2.143.0/fastlane_core/lib/fastlane_core/configuration/configuration.rb:82:in `each'
  /path/to/.gems/ruby/2.6.0/gems/fastlane-2.143.0/fastlane_core/lib/fastlane_core/configuration/configuration.rb:82:in `verify_value_exists'
  /path/to/.gems/ruby/2.6.0/gems/fastlane-2.143.0/fastlane_core/lib/fastlane_core/configuration/configuration.rb:66:in `initialize'
  /path/to/.gems/ruby/2.6.0/gems/fastlane-2.143.0/fastlane_core/lib/fastlane_core/configuration/configuration.rb:36:in `new'
  /path/to/.gems/ruby/2.6.0/gems/fastlane-2.143.0/fastlane_core/lib/fastlane_core/configuration/configuration.rb:36:in `create'
  /path/to/.gems/ruby/2.6.0/bundler/gems/fastlane-plugin-test_center-808c8cef4e32/lib/fastlane/plugin/test_center/helper/multi_scan_manager/runner.rb:230:in `merge_single_testable_xcresult_with_final_xcresult'
  /path/to/.gems/ruby/2.6.0/bundler/gems/fastlane-plugin-test_center-808c8cef4e32/lib/fastlane/plugin/test_center/helper/multi_scan_manager/runner.rb:210:in `move_single_testable_reports_to_final_location'
  /path/to/.gems/ruby/2.6.0/bundler/gems/fastlane-plugin-test_center-808c8cef4e32/lib/fastlane/plugin/test_center/helper/multi_scan_manager/runner.rb:200:in `collate_batched_reports'
  /path/to/.gems/ruby/2.6.0/bundler/gems/fastlane-plugin-test_center-808c8cef4e32/lib/fastlane/plugin/test_center/helper/multi_scan_manager/runner.rb:179:in `run_test_batches'
  /path/to/.gems/ruby/2.6.0/bundler/gems/fastlane-plugin-test_center-808c8cef4e32/lib/fastlane/plugin/test_center/helper/multi_scan_manager/runner.rb:70:in `run'
  /path/to/.gems/ruby/2.6.0/bundler/gems/fastlane-plugin-test_center-808c8cef4e32/lib/fastlane/plugin/test_center/actions/multi_scan.rb:38:in `run'
  /path/to/.gems/ruby/2.6.0/gems/fastlane-2.143.0/fastlane/lib/fastlane/runner.rb:261:in `block (2 levels) in execute_action'
  /path/to/.gems/ruby/2.6.0/gems/fastlane-2.143.0/fastlane/lib/fastlane/actions/actions_helper.rb:50:in `execute_action'
  /path/to/.gems/ruby/2.6.0/gems/fastlane-2.143.0/fastlane/lib/fastlane/runner.rb:253:in `block in execute_action'
  /path/to/.gems/ruby/2.6.0/gems/fastlane-2.143.0/fastlane/lib/fastlane/runner.rb:227:in `chdir'
  /path/to/.gems/ruby/2.6.0/gems/fastlane-2.143.0/fastlane/lib/fastlane/runner.rb:227:in `execute_action'
  /path/to/.gems/ruby/2.6.0/gems/fastlane-2.143.0/fastlane/lib/fastlane/runner.rb:157:in `trigger_action_by_name'
  /path/to/.gems/ruby/2.6.0/gems/fastlane-2.143.0/fastlane/lib/fastlane/fast_file.rb:159:in `method_missing'
  Fastfile:503:in `block (2 levels) in parsing_binding'
  /path/to/.gems/ruby/2.6.0/gems/fastlane-2.143.0/fastlane/lib/fastlane/lane.rb:33:in `call'
  /path/to/.gems/ruby/2.6.0/gems/fastlane-2.143.0/fastlane/lib/fastlane/runner.rb:49:in `block in execute'
  /path/to/.gems/ruby/2.6.0/gems/fastlane-2.143.0/fastlane/lib/fastlane/runner.rb:45:in `chdir'
  /path/to/.gems/ruby/2.6.0/gems/fastlane-2.143.0/fastlane/lib/fastlane/runner.rb:45:in `execute'
  /path/to/.gems/ruby/2.6.0/gems/fastlane-2.143.0/fastlane/lib/fastlane/lane_manager.rb:56:in `cruise_lane'
  /path/to/.gems/ruby/2.6.0/gems/fastlane-2.143.0/fastlane/lib/fastlane/command_line_handler.rb:36:in `handle'
  /path/to/.gems/ruby/2.6.0/gems/fastlane-2.143.0/fastlane/lib/fastlane/commands_generator.rb:108:in `block (2 levels) in run'
  /path/to/.gems/ruby/2.6.0/gems/commander-fastlane-4.4.6/lib/commander/command.rb:178:in `call'
  /path/to/.gems/ruby/2.6.0/gems/commander-fastlane-4.4.6/lib/commander/command.rb:153:in `run'
  /path/to/.gems/ruby/2.6.0/gems/commander-fastlane-4.4.6/lib/commander/runner.rb:476:in `run_active_command'
  /path/to/.gems/ruby/2.6.0/gems/fastlane-2.143.0/fastlane_core/lib/fastlane_core/ui/fastlane_runner.rb:76:in `run!'
  /path/to/.gems/ruby/2.6.0/gems/commander-fastlane-4.4.6/lib/commander/delegates.rb:15:in `run!'
  /path/to/.gems/ruby/2.6.0/gems/fastlane-2.143.0/fastlane/lib/fastlane/commands_generator.rb:349:in `run'
  /path/to/.gems/ruby/2.6.0/gems/fastlane-2.143.0/fastlane/lib/fastlane/commands_generator.rb:41:in `start'
  /path/to/.gems/ruby/2.6.0/gems/fastlane-2.143.0/fastlane/lib/fastlane/cli_tools_distributor.rb:119:in `take_off'
  /path/to/.gems/ruby/2.6.0/gems/fastlane-2.143.0/bin/fastlane:23:in `<top (required)>'
  /path/to/.gems/ruby/2.6.0/bin/fastlane:23:in `load'
  /path/to/.gems/ruby/2.6.0/bin/fastlane:23:in `<top (required)>'

Looking at that actual line, it's

          config = FastlaneCore::Configuration.create(
            Fastlane::Actions::CollateXcresultsAction.available_options,
            {
              xcresults: [src_xcresult_bundlepath, dst_xcresult_bundlepath],
              collated_xcresult: dst_xcresult_bundlepath
            }
          )

Looking above this, I think this is the problem:

          # We do not need to merge if one of these do not exist
          return unless File.exist?(src_xcresult_bundlepath) || File.exist?(dst_xcresult_bundlepath)

The || here should be an && in order to match the behavior described by the comment.

---

In any case, this is all a bit of a distraction. It's definitely an issue that needs to be fixed, but it's not actually relevant to this ticket except in that I'm hitting it when trying to test this ticket. The actual fix for this ticket is ensuring Scan.devices is populated with the device that matches the destination we're trying to run the tests on.

[lyndsey-ferguson]

Hello @lilyball, I believe that I have fixed the issue now. Would you test it again? Please modify your Pluginfile per my instructions below, run bundle install, and then run your fastlane again (with the --verbose flag)?

Pluginfile:

gem 'fastlane-plugin-test_center', :git => "https://github.com/lyndsey-ferguson/fastlane-plugin-test_center.git", :branch => "issue-233-prepopulated-devices-sent-to-scan"

If there are still problems, please let me know and attach the console output as a text file (removing any sensitive data) to this issue (makes it easier for me to review). If it works, please let me know.

[lyndsey-ferguson]

@lilyball thanks to your testing, I've also fixed another Issue that someone was facing and that I could not reproduce; thanks!

[lyndsey-ferguson]

@lilyball could you give me an idea if you'll be able to test this week? I can merge on Friday without your testing, but I would love a confirmation that this fixes the issue that you were seeing.

[lyndsey-ferguson]

Fixed in v3.11.4

[lilyball]

I apologize I was unable to look at this last week because of Apple's developer conference. I'll be looking at the published version sometime soon and will let you know if I still have issues.

[lyndsey-ferguson]

No worries @lilyball ! Given what is going on in the world I was worried that you were tied up with something else, less pleasant. 👏

Make sure that you try with the latest released version.

[lilyball]

Finally tried it v3.11.5. I don't know what's going on but the .logarchives it produced were completely empty. Nothing at all in the folders. I don't know why the stderr of the log collect is piped to /dev/null, it seems like it would be useful output to have. It does appear to be referencing the correct device UUID (finally) so I don't know why there's nothing here. Because test_center moves the logarchives itself without invoking loggable shell commands I can't see what it's doing, to see if it's somehow screwing it up.

The last log collect in the run I just did looks like

xcrun simctl spawn --standalone 541925A2-E7B2-444B-9D99-42989349DC03 log collect --output /Users/jenkins/workspace/JOBNAME/fastlane/test_output/TARGET/TARGETTests-batch-3/system_logs-iPhone\ 8\ Clone\ 3\ TestCenter::Helper::MultiScanManager::SimulatorHelper\<70242128102320\>_iOS_13.4.logarchive 2>/dev/null

No output of course.