Cannot DELETE session (driver.quit)

Issues/Bugs
1

Hi,

I’ve tackled with a new regression in appium impl ,
The session cannot be deleted after executing driver.quit

Pls see the logs :

> [HTTP] → DELETE /wd/hub/session/f5f9b28b-49a9-40c9-abf0-c9b8bb833162 {}
> [MJSONWP] Calling AppiumDriver.deleteSession() with args: [“f5f9b28b-49a9-40c9-abf0-c9b8bb833162”]
> [debug] [iOS] Deleting ios session
> [debug] [UIAuto] Destroying instruments client socket.
> [debug] [UIAuto] Closing socket server.
> [debug] [UIAuto] Instruments socket server was closed
> [debug] [Instruments] [INST] 2016-04-23 07:03:15 +0000 Debug: Got new command 1074 from instruments: au.getElementByAccessibilityId(‘productCode’, ‘1022’)
> [debug] [Instruments] Starting shutdown.
> [debug] [Instruments] Sending sigterm to instruments

[debug] [Instruments] [INST] 2016-04-23 07:03:15 +0000 Debug: evaluating au.getElementByAccessibilityId(‘productCode’, ‘1022’)
[debug] [Instruments] [INST] 2016-04-23 07:03:15 +0000 Debug: evaluation finished
[debug] [Instruments] [INST] 2016-04-23 07:03:15 +0000 Debug: Lookup returned [object UIAStaticText] with the name “productCode” (id: 1023).
[debug] [Instruments] [INST] 2016-04-23 07:03:15 +0000 Debug: responding with:
[debug] [Instruments] [INST] 2016-04-23 07:03:15 +0000 Debug: Running system command #1075: /usr/local/Cellar/node/0.12.6/bin/node /usr/local/lib/node_modules/appium/node_modules/appium-ios-driver/node_modules/appium-uiauto/build/lib/bin/command-proxy-client.js /var/folders/80/rv4jbh0d0nn4bhnmnnn2zclc0000gp/T/instruments_sock 2,{“status”:0,“value”:{“ELEMENT”:“1023”}}…
[debug] [Instruments] [INST] 2016-04-23 07:03:15 +0000 Debug: Got new command 1075 from instruments: au.getElement(‘1023’).isDisplayed()
[debug] [Instruments] [INST] 2016-04-23 07:03:15 +0000 Debug: evaluating au.getElement(‘1023’).isDisplayed()
[debug] [Instruments] [INST] 2016-04-23 07:03:15 +0000 Debug: evaluation finished
[debug] [Instruments] [INST] 2016-04-23 07:03:15 +0000 Debug: responding with:
[debug] [Instruments] [INST] 2016-04-23 07:03:15 +0000 Debug: Running system command #1076: /usr/local/Cellar/node/0.12.6/bin/node /usr/local/lib/node_modules/appium/node_modules/appium-ios-driver/node_modules/appium-uiauto/build/lib/bin/command-proxy-client.js /var/folders/80/rv4jbh0d0nn4bhnmnnn2zclc0000gp/T/instruments_sock 2,{“status”:0,“value”:true}…
[debug] [Instruments] [INST] 2016-04-23 07:03:15 +0000 Debug: Got new command 1076 from instruments: au.getElementsByAccessibilityId(‘marketCell’)
[debug] [Instruments] [INST] 2016-04-23 07:03:15 +0000 Debug: evaluating au.getElementsByAccessibilityId(‘marketCell’)
[debug] [Instruments] [INST] 2016-04-23 07:03:15 +0000 Debug: evaluation finished
[debug] [Instruments] [INST] 2016-04-23 07:03:15 +0000 Debug: Lookup returned [object UIATableCell] with the name “marketCell” (id: 1024).
[debug] [Instruments] [INST] 2016-04-23 07:03:15 +0000 Debug: responding with:
[debug] [Instruments] [INST] 2016-04-23 07:03:15 +0000 Debug: Running system command #1077: /usr/local/Cellar/node/0.12.6/bin/node /usr/local/lib/node_modules/appium/node_modules/appium-ios-driver/node_modules/appium-uiauto/build/lib/bin/command-proxy-client.js /var/folders/80/rv4jbh0d0nn4bhnmnnn2zclc0000gp/T/instruments_sock 2,{“status”:0,“value”:[{“ELEMENT”:“1024”}]}…
[debug] [Instruments] [INST] 2016-04-23 07:03:15 +0000 Debug: Got new command 1077 from instruments: au.getElementByAccessibilityId(‘productCode’, ‘1024’)
[debug] [Instruments] [INST] 2016-04-23 07:03:15 +0000 Debug: evaluating au.getElementByAccessibilityId(‘productCode’, ‘1024’)
[debug] [Instruments] [INST] 2016-04-23 07:03:15 +0000 Debug: evaluation finished
[debug] [Instruments] [INST] 2016-04-23 07:03:15 +0000 Debug: Lookup returned [object UIAStaticText] with the name “productCode” (id: 1025).
[debug] [Instruments] [INST] 2016-04-23 07:03:15 +0000 Debug: responding with:
[debug] [Instruments] [INST] 2016-04-23 07:03:15 +0000 Debug: Running system command #1078: /usr/local/Cellar/node/0.12.6/bin/node /usr/local/lib/node_modules/appium/node_modules/appium-ios-driver/node_modules/appium-uiauto/build/lib/bin/command-proxy-client.js /var/folders/80/rv4jbh0d0nn4bhnmnnn2zclc0000gp/T/instruments_sock 2,{“status”:0,“value”:{“ELEMENT”:“1025”}}…
[debug] [Instruments] [INST] 2016-04-23 07:03:15 +0000 Debug: Got new command 1078 from instruments: au.getElement(‘1025’).value()
[debug] [Instruments] [INST] 2016-04-23 07:03:15 +0000 Debug: evaluating au.getElement(‘1025’).value()
[debug] [Instruments] [INST] 2016-04-23 07:03:15 +0000 Debug: evaluation finished
[debug] [Instruments] [INST] 2016-04-23 07:03:15 +0000 Debug: responding with:
[debug] [Instruments] [INST] 2016-04-23 07:03:15 +0000 Debug: Running system command #1079: /usr/local/Cellar/node/0.12.6/bin/node /usr/local/lib/node_modules/appium/node_modules/appium-ios-driver/node_modules/appium-uiauto/build/lib/bin/command-proxy-client.js /var/folders/80/rv4jbh0d0nn4bhnmnnn2zclc0000gp/T/instruments_sock 2,{“status”:0,“value”:“GCG6”}…
[debug] [Instruments] [INST] 2016-04-23 07:03:15 +0000 Debug: Got new command 1079 from instruments: au.getElementByAccessibilityId(‘topAsk’, ‘1024’)
[debug] [Instruments] [INST] 2016-04-23 07:03:15 +0000 Debug: evaluating au.getElementByAccessibilityId(‘topAsk’, ‘1024’)
[debug] [Instruments] [INST] 2016-04-23 07:03:15 +0000 Debug: evaluation finished
[debug] [Instruments] [INST] 2016-04-23 07:03:15 +0000 Debug: Lookup returned [object UIAButton] with the name “topAsk” (id: 1026).
[debug] [Instruments] [INST] 2016-04-23 07:03:15 +0000 Debug: responding with:
[debug] [Instruments] [INST] 2016-04-23 07:03:15 +0000 Debug: Running system command #1080: /usr/local/Cellar/node/0.12.6/bin/node /usr/local/lib/node_modules/appium/node_modules/appium-ios-driver/node_modules/appium-uiauto/build/lib/bin/command-proxy-client.js /var/folders/80/rv4jbh0d0nn4bhnmnnn2zclc0000gp/T/instruments_sock 2,{“status”:0,“value”:{“ELEMENT”:“1026”}}…
[debug] [Instruments] [INST] 2016-04-23 07:03:15 +0000 Debug: Got new command 1080 from instruments: au.getElement(‘1026’).value()
[debug] [Instruments] [INST] 2016-04-23 07:03:15 +0000 Debug: evaluating au.getElement(‘1026’).value()
[debug] [Instruments] [INST] 2016-04-23 07:03:15 +0000 Debug: evaluation finished
[debug] [Instruments] [INST] 2016-04-23 07:03:15 +0000 Debug: responding with:
[debug] [Instruments] [INST] 2016-04-23 07:03:15 +0000 Debug: Running system command #1081: /usr/local/Cellar/node/0.12.6/bin/node /usr/local/lib/node_modules/appium/node_modules/appium-ios-driver/node_modules/appium-uiauto/build/lib/bin/command-proxy-client.js /var/folders/80/rv4jbh0d0nn4bhnmnnn2zclc0000gp/T/instruments_sock 2,{“status”:0,“value”:“448.9”}…
[debug] [Instruments] [INST] 2016-04-23 07:03:15 +0000 Debug: Got new command 1081 from instruments: au.getElementByAccessibilityId(‘topBid’, ‘1024’)
[debug] [Instruments] [INST] 2016-04-23 07:03:15 +0000 Debug: evaluating au.getElementByAccessibilityId(‘topBid’, ‘1024’)
[debug] [Instruments] [INST] 2016-04-23 07:03:15 +0000 Debug: evaluation finished
[debug] [Instruments] [INST] 2016-04-23 07:03:15 +0000 Debug: Lookup returned [object UIAButton] with the name “topBid” (id: 1027).
[debug] [Instruments] [INST] 2016-04-23 07:03:15 +0000 Debug: responding with:
[debug] [Instruments] [INST] 2016-04-23 07:03:15 +0000 Debug: Running system command #1082: /usr/local/Cellar/node/0.12.6/bin/node /usr/local/lib/node_modules/appium/node_modules/appium-ios-driver/node_modules/appium-uiauto/build/lib/bin/command-proxy-client.js /var/folders/80/rv4jbh0d0nn4bhnmnnn2zclc0000gp/T/instruments_sock 2,{“status”:0,“value”:{“ELEMENT”:“1027”}}…
[debug] [Instruments] [INST] 2016-04-23 07:03:15 +0000 Debug: Got new command 1082 from instruments: au.getElement(‘1027’).value()
> [iOS] Instruments didn’t shut down. Error: Instruments did not terminate after 5 seconds!
> [debug] [iOSLog] Stopping iOS log capture
> [debug] [iOS] Reset not set, not ending sim
> [Appium] Removing session f5f9b28b-49a9-40c9-abf0-c9b8bb833162 from our master session list
> [debug] [MJSONWP] Received response: null
> [debug] [MJSONWP] But deleting session, so not returning
> [MJSONWP] Responding to client with driver.deleteSession() result: null
> [HTTP] ← DELETE /wd/hub/session/f5f9b28b-49a9-40c9-abf0-c9b8bb833162 200 5104 ms - 76

Eventually the session hasn’t being terminated , and tons of data being logged.

appium 1.5.2
java_client 3.4.1
IOS 9.1

Someone familiar with the issue ?

Thanks

2

I’ve seen this exact behavior as well on appium 1.5.2
“Instruments didn’t shut down. Error: Instruments did not terminate after 5 seconds”

This then leads to leaked instruments processes that hog up resources on our test servers and cause mass failures. Seems as though the Appium server is not always able to clean up instruments. I didn’t have this issue in 1.4.13

3

Looks like the old instruments.js in appium 1.4.X was much more draconian about killing instruments, issuing SIGKILL

appium/node_modules/appium-instruments/lib/instruments.js, line 92

Instruments.killAll = function () {
logger.debug(“Killall instruments”);
exec(‘pkill -9 instruments’);
};

Whereas the new one has a more polite approach:

appium/node_modules/appium-instruments/lib/instruments.js, line 755

_logger2[‘default’].debug(‘Sending sigterm to instruments’);
this.proc.kill(‘SIGTERM’);

Sure enough when I override driver.quit() and add a hard-coded “pkill -9 instruments” my long test runs no longer fail to launch nor leak instruments processes.

Edit: I also confirmed that changing the above to this.proc.kill(‘SIGKILL’); fixes the issue

Anyone see a reason not to just issue a SIGKILL? Not sure how instruments gets into this state, but it does happen with 100% reproducibility for one of my tests.

4

@vic thanks for the investigation.

@jonahss any chance to fix it for the next appium release ?

Thanks

5

Screenshot from 2016-05-02 19-58-13.png1867×885 253 KB

I am running appium 1.5.2 on ubuntu. I have attached the appium CLI screenshot. As soon as i start a session it is invoking AppiumDriver.deleteSession() with arg. Then shutting down the Android driver.
Then its runs adb with one of its arg as force-stop.

Thus my application is terminating and my tests are failing. Can anyone please provide me some solution to resolve this issue.

Capabilities used is as follows :
cap.setCapability(MobileCapabilityType.DEVICE_NAME, “Custom_Phone”);
cap.setCapability(MobileCapabilityType.VERSION, “6.0”);
cap.setCapability(MobileCapabilityType.APP_PACKAGE, “com.appname”);
cap.setCapability(MobileCapabilityType.APP_ACTIVITY, “com.appname.SplashActivity”);

    driver = new AndroidDriver(new URL("http://127.0.0.1:4723/wd/hub"), cap);

And I’m using GenyMotion emulator as device.

6

Filed a ticket here:
https://github.com/appium/appium-instruments/issues/72

7

Thanks vic ,
but I see that there is no response from Appium’s team.

The appium’s ver was switched to 1.5.3 already , but the problem is still there …

Any idea for temp workaround ?