Not able to generate 'appium_perf_Leaks_.trace' due to error 'Encountered internal error running command'

[sanjeedsawant]

The problem

I am trying to get the Leaks trace for my iOS app, I m starting the log once app launches and before test starts command used is :: args.put("timeout", 60 * 1000); args.put("profileName", "Leaks"); args.put("pid", "current"); When test completes I stop the monitoring, while stopping it gives error saying :

[35m[XCUITest][39m There are no records for performance profile 'Leaks' and device 527a368d34b35b04c6e8b53bde75d3795a61733e. Have you started the profiling before?

Environment

• Appium version (or git revision) that exhibits the issue: 1.16.0
• Desktop OS/version used to run Appium: macbook pro Catalina 10.15.1
• Node.js version (unless using Appium.app|exe):
• Npm or Yarn package manager:
• Mobile platform/version under test: iOS 12.4.1
• Real device or emulator/simulator: Real (iPad 6th generation)
• Appium CLI or Appium.app|exe: CLI

Details

In appium logs while executing script 'stopPerfRecord' it shows:

2020-03-11 10:09:35:566 [HTTP] {"script":"mobile: stopPerfRecord","args":[{"profileName":"Leaks"}]} 2020-03-11 10:09:35:567 [W3C (9d2bf21f)] Calling AppiumDriver.execute() with args: ["mobile: stopPerfRecord",[{"profileName":"Leaks"}],"9d2bf21f-b658-4f06-92f1-c6d918dc1c6c"] 2020-03-11 10:09:35:567 [XCUITest] Executing command 'execute' 2020-03-11 10:13:33:050 [XCUITest] The size of the file is 475.45 MB 2020-03-11 10:13:34:130 [XCUITest] There are no records for performance profile 'Leaks' and device 527a368d34b35b04c6e8b53bde75d3795a61733e. Have you started the profiling before? 2020-03-11 10:13:36:703 [W3C (9d2bf21f)] Responding to client with driver.execute() result: "UEsDBAoAAAAAACF8a1AAAAAAAAAAAAAAAAAmABwAYXBwaXVtX3BlcmZfTGVha3NfMTU4MzkyMDg2NTI0NC50cmFjZS9VVAkAA1a3aF5nuGhedXgLAAEE9gEAAAQUAAAAUEsDBAoAAAAAACF8a1AAAAAAAAAAAAAAAAA2ABwAYXBwaXVtX3BlcmZfTGVha3NfMTU4MzkyMDg2NTI0NC50cmFjZS9pbnN0cnVtZW50X2RhdGEvVVQJAANWt2heZ7hoXnV4CwABBPYBAAAEFAAAAFBLAwQKAAAAAAAhfGtQAAAAAAAAAAAAAAAAWwAcAGFwcGl1bV9wZXJmX0xlYWtzXzE1ODM5MjA4NjUyNDQudHJhY2UvaW5zdHJ1bWVudF9kYXRhL0Y5RjJCMTQ3LUEwNDItNDNGMC1BNzkxLUVBNkQ2M0M3QzFFOC9VVAkAA1a3aF5nuGhedXgLAAEE9gEAAAQUAAAAUEsDBAoAAAAAACF8a1AAAAAAAAAAAAAAAABkABwAYXBwaXVtX3BlcmZfTGVha3NfMTU4MzkyMDg2NTI0NC50cmFjZS9pbnN0cnVtZW50X2RhdGEvRjlGMkIxNDctQTA0Mi00M0YwLUE3OTEtRUE2RDYzQzdDMUU4L3J1bl9kYXRhL1VUCQADVrdoXme4aF51eAsAAQT2AQAABBQAAABQSwMEFAACAAgAIXxrUBLgp8HeQgAAt0MAAG0AHABhcHBpdW1fcGVyZl9MZWFrc18xNTgzOTIwODY1MjQ0LnRyYWNlL2luc3RydW1lbnRfZGF0YS9GOUYyQjE0Ny1BMDQyLTQzRjAtQTc5MS1FQTZENjNDN0MxRTgvcnVuX2RhdGEvMS5ydW4uemlwVVQJAANWt2heVrdoXnV4CwABBPYBAAAEFAAAANW883OnT/AvGtt2NhtsbNu2bdu2nWw29sa2/Y5t8x3b9t3P95xbdetWnT/gzNTTM1M93fPq7qmp6ueHVpQBh8AAAQGBASHxtVHcj0w56xQCAZHD... 2020-03-11 10:13:41:165 [W3C (9d2bf21f)] Encountered internal error running command: Error: There are no records for performance profile 'Leaks' and device 527a368d34b35b04c6e8b53bde75d3795a61733e. Have you started the profiling before? 2020-03-11 10:13:41:166 [W3C (9d2bf21f)] at Object.wrappedLogger.errorAndThrow (/usr/local/lib/node_modules/appium/node_modules/appium-support/lib/logging.js:74:35) 2020-03-11 10:13:41:167 [W3C (9d2bf21f)] at XCUITestDriver.mobileStopPerfRecord (/usr/local/lib/node_modules/appium/node_modules/appium-xcuitest-driver/lib/commands/performance.js:196:9) 2020-03-11 10:13:41:167 [W3C (9d2bf21f)] at XCUITestDriver.executeMobile (/usr/local/lib/node_modules/appium/node_modules/appium-xcuitest-driver/lib/commands/execute.js:97:16) 2020-03-11 10:13:41:168 [W3C (9d2bf21f)] at XCUITestDriver.execute (/usr/local/lib/node_modules/appium/node_modules/appium-ios-driver/lib/commands/execute.js:15:23) 2020-03-11 10:13:41:168 [W3C (9d2bf21f)] at XCUITestDriver.execute (/usr/local/lib/node_modules/appium/node_modules/appium-xcuitest-driver/lib/commands/execute.js:16:27) 2020-03-11 10:13:41:169 [W3C (9d2bf21f)] at commandExecutor (/usr/local/lib/node_modules/appium/node_modules/appium-base-driver/lib/basedriver/driver.js:330:9) 2020-03-11 10:13:41:169 [W3C (9d2bf21f)] at /usr/local/lib/node_modules/appium/node_modules/async-lock/lib/index.js:125:12 2020-03-11 10:13:41:170 [W3C (9d2bf21f)] at AsyncLock._promiseTry (/usr/local/lib/node_modules/appium/node_modules/async-lock/lib/index.js:249:31) 2020-03-11 10:13:41:170 [W3C (9d2bf21f)] at exec (/usr/local/lib/node_modules/appium/node_modules/async-lock/lib/index.js:124:9) 2020-03-11 10:13:41:170 [W3C (9d2bf21f)] at taskFn (/usr/local/lib/node_modules/appium/node_modules/async-lock/lib/index.js:152:4) 2020-03-11 10:13:41:171 [W3C (9d2bf21f)] at done (/usr/local/lib/node_modules/appium/node_modules/async-lock/lib/index.js:93:29) 2020-03-11 10:13:41:171 [W3C (9d2bf21f)] at /usr/local/lib/node_modules/appium/node_modules/async-lock/lib/index.js:128:5

Link to Appium logs

https://gist.github.com/sanjeedsawant/8186abbe23fb7b73629d04d841654d51

Code To Reproduce Issue [ Good To Have ]

Launch the app under test

@BeforeMethod
private void startPerformanceMonitoring() {
	
		Map<String, Object> args = new HashMap<>();
		args.put("timeout", 60 * 1000);
		args.put("profileName", "Leaks");
		args.put("pid", "current");
                (JavascriptExecutor)this.driver.executeScript("mobile: startPerfRecord", args);
	}

@Test
public void demoTest(){
     //some interaction with the app
}

@AfterMethod
public void stopPerfReport() {
		File traceFileZip = new File(System.getProperty("user.dir") + File.separator + "src/test/resources/perfResult/"
				+ System.currentTimeMillis() + ".zip");
		LOG.info("Closing the perfomance logs and wrting to file: " + traceFileZip.getAbsolutePath());
		args = new HashMap<>();
		args.put("profileName", "Leaks");
		String b64Zip = (String) (JavascriptExecutor)this.driver.executeScript("mobile: stopPerfRecord", args);
		byte[] bytesZip = Base64.getMimeDecoder().decode(b64Zip);
		FileOutputStream stream;
		try {
			stream = new FileOutputStream(traceFileZip);
			stream.write(bytesZip);
                 }
                 catch (FileNotFoundException e) {
			e.printStackTrace();
		} catch (IOException e) {
			e.printStackTrace();
		}
}

[mykola-mokhnach]

I don't observe any server issues there. The request was received and the response has been sent properly. Although the client has sent the actual response twice (most likely because it took pretty lot of time to be processed) and got an error in response to the second retry, because the first one has already been finished.

Moved the ticket to java client (I assume some timeouts tuning of the http client might resolve the problem)

[sanjeedsawant]

@mykola-mokhnach, thanks for your reply.

I tried by increasing the timeout to 10mins, but after 3mins it fails with below error. Can you please help in this issue?

2020-03-13 07:44:59:253 [W3C (e8a21d01)] Calling AppiumDriver.execute() with args: ["mobile: stopPerfRecord",[{"profileName":"Leaks"}],"e8a21d01-6258-4240-a92f-d2191afc9e70"] 2020-03-13 07:44:59:254 [XCUITest] Executing command 'execute' 2020-03-13 07:45:59:157 [XCUITest] Sending SIGINT to the running instruments process 2020-03-13 07:45:59:159 [W3C (e8a21d01)] Encountered internal error running command: Error: Process didn't end after 180000ms (cmd: '/usr/bin/instruments -w 527a368d34b35b04c6e8b53bde75d3795a61733e -t Leaks -D /var/folders/s5/bc3cfmdd0p18961m5l7sqdp40000gp/T/2020213-3419-1et8nbb.u682/appium_perf_Leaks_1584084795602.trace -l 900000 -p 886') 2020-03-13 07:45:59:159 [W3C (e8a21d01)] at Timeout. (/usr/local/lib/node_modules/appium/node_modules/teen_process/lib/subprocess.js:231:16) 2020-03-13 07:45:59:159 [W3C (e8a21d01)] at listOnTimeout (internal/timers.js:531:17) 2020-03-13 07:45:59:159 [W3C (e8a21d01)] at processTimers (internal/timers.js:475:7) 2020-03-13 07:45:59:160 [W3C (e8a21d01)] --------------------------------------------- 2020-03-13 07:45:59:160 [W3C (e8a21d01)] at /usr/local/lib/node_modules/appium/node_modules/teen_process/lib/subprocess.js:230:7 2020-03-13 07:45:59:160 [W3C (e8a21d01)] at Promise.cancellationExecute [as _execute] (/usr/local/lib/node_modules/appium/node_modules/bluebird/js/release/debuggability.js:406:9) 2020-03-13 07:45:59:160 [W3C (e8a21d01)] at Promise._resolveFromExecutor (/usr/local/lib/node_modules/appium/node_modules/bluebird/js/release/promise.js:518:18) 2020-03-13 07:45:59:161 [W3C (e8a21d01)] at new Promise (/usr/local/lib/node_modules/appium/node_modules/bluebird/js/release/promise.js:103:10) 2020-03-13 07:45:59:161 [W3C (e8a21d01)] at SubProcess.stop (/usr/local/lib/node_modules/appium/node_modules/teen_process/lib/subprocess.js:226:18) 2020-03-13 07:45:59:161 [W3C (e8a21d01)] at finishPerfRecord (/usr/local/lib/node_modules/appium/node_modules/appium-xcuitest-driver/lib/commands/performance.js:30:23) 2020-03-13 07:45:59:161 [W3C (e8a21d01)] at XCUITestDriver.mobileStopPerfRecord (/usr/local/lib/node_modules/appium/node_modules/appium-xcuitest-driver/lib/commands/performance.js:202:9) 2020-03-13 07:45:59:161 [W3C (e8a21d01)] at XCUITestDriver.executeMobile (/usr/local/lib/node_modules/appium/node_modules/appium-xcuitest-driver/lib/commands/execute.js:97:16) 2020-03-13 07:45:59:162 [W3C (e8a21d01)] at XCUITestDriver.execute (/usr/local/lib/node_modules/appium/node_modules/appium-ios-driver/lib/commands/execute.js:15:23) 2020-03-13 07:45:59:162 [W3C (e8a21d01)] at XCUITestDriver.execute (/usr/local/lib/node_modules/appium/node_modules/appium-xcuitest-driver/lib/commands/execute.js:16:27) 2020-03-13 07:45:59:162 [W3C (e8a21d01)] at commandExecutor (/usr/local/lib/node_modules/appium/node_modules/appium-base-driver/lib/basedriver/driver.js:330:9) 2020-03-13 07:45:59:162 [W3C (e8a21d01)] at /usr/local/lib/node_modules/appium/node_modules/async-lock/lib/index.js:125:12 2020-03-13 07:45:59:163 [W3C (e8a21d01)] at AsyncLock._promiseTry (/usr/local/lib/node_modules/appium/node_modules/async-lock/lib/index.js:249:31) 2020-03-13 07:45:59:163 [W3C (e8a21d01)] at exec (/usr/local/lib/node_modules/appium/node_modules/async-lock/lib/index.js:124:9) 2020-03-13 07:45:59:163 [W3C (e8a21d01)] at AsyncLock.acquire (/usr/local/lib/node_modules/appium/node_modules/async-lock/lib/index.js:140:3) 2020-03-13 07:45:59:163 [W3C (e8a21d01)] at XCUITestDriver.executeCommand (/usr/local/lib/node_modules/appium/node_modules/appium-base-driver/lib/basedriver/driver.js:343:39) 2020-03-13 07:45:59:163 [W3C (e8a21d01)] at XCUITestDriver.executeCommand (/usr/local/lib/node_modules/appium/node_modules/appium-xcuitest-driver/lib/driver.js:701:24) 2020-03-13 07:45:59:164 [W3C (e8a21d01)] at AppiumDriver.executeCommand (/usr/local/lib/node_modules/appium/lib/appium.js:510:36) 2020-03-13 07:45:59:164 [W3C (e8a21d01)] at runMicrotasks () 2020-03-13 07:45:59:164 [W3C (e8a21d01)] at processTicksAndRejections (internal/process/task_queues.js:93:5) 2020-03-13 07:45:59:164 [W3C (e8a21d01)] at asyncHandler (/usr/local/lib/node_modules/appium/node_modules/appium-base-driver/lib/protocol/protocol.js:306:21)

[mykola-mokhnach]

It might be that the size of the folder generated by instruments is huge, so the server cannot compress it in 180 seconds. Try to cut off the duration of your trace.

[mykola-mokhnach]

I was talking about the http request timeout not the recording timeout

[sanjeedsawant]

can we override the http request timeout ?

[mykola-mokhnach]

Yes, this is possible by using this constructor for driver creation. The HttpFactory's createClient method must return a properly preconfigured Http client (Selenium uses OkHttp one)

[hpsaini]

@sanjeedsawant any luck. I am also facing the same issue. VIa appium leaks.trace file is generated but unable to get compressed .zip output

[FaheemAkhtar]

@sanjeedsawant @hpsaini was you able to get this resolved. I am facing the same issue.