[Resolved] Appium 1.3.7 disappearing unexpectedly without any error indication

pmneve · April 17, 2015, 5:41pm

Crash is consistent (always crashes) but the exact place in the test script.
In ruby using appium_lib and watir-webdriver and selenium ruby bindings.
Testing against android emulator (both ARM and x86 with HAXM) on Windows 7

The emulator launches, Webdriver launches the browser.
The script calls for navigation to three consecutive pages.
Crash can occur before or after any of them.

There is nothing in the appium log indicating an error. The ruby log shows ECONNREFUSED error, probably because appium rest server is gone. Node.exe disappears just before the error appears in ruby log.

Is there a way to get logging out of node.js that might indicate what is going wrong?
Node version is 0.10.26

pmneve · April 17, 2015, 9:46pm

Additional information:
Windows 7 Enterprise SP1
appium_lib 6.0.0
selenium_webdriver 2.45.0
ruby 2.0.0p451 (2014-02-24) [i386-mingw32]

Here is relevant code:

def open_browser_mobile(device_id, device_type, ios_version='8.1')
     mark_test_level(": #{device_type.titleize}")

     debug_to_log("#{Dir.pwd.chomp}")
     log_file = File.join(Dir.pwd.chomp, 'log', "#{@myName}_appium_#{@start_timestamp.strftime("%Y%m%d%H%M%S")}.log")
     command  = "appium --log-timestamp --log-level debug:debug --log #{log_file} &"
     debug_to_log(command) #<break
     appium = IO.popen(command, :err => :out) #<break
     debug_to_log("Appium PID: #{appium.pid}")

     5.times.each {
       debug_to_log("appium: #{appium.gets.chomp}")
     }

     sleep_for(15)

     desired_caps = set_mobile_capabilities(device_id, device_type, ios_version)

     server_url     = "http://127.0.0.1:4723/wd/hub"
     client         = Selenium::WebDriver::Remote::Http::Default.new
     client.timeout = 300
     debug_to_log(desired_caps.to_yaml)

     Watir::Browser.new(:chrome,
                   :url                  => server_url,
                   :desired_capabilities => desired_caps,
                   :http_client          => client #
     )
end

def set_mobile_capabilities(device_id, device_type, ios_version)
     case device_type
       when "android device"

         desired_caps = {
             'deviceName'   => "My_device",
             'platformName' => "Android",
             'app'          => "Chrome",
             'appPackage'   => "com.android.chrome",
             'udid'         => device_id }

       when "android emulator"

         desired_caps = {
             'newCommandTimeout'         => 600,
             'androidDeviceReadyTimeout' => 420,
             'avdLaunchTimeout'          => 240000,
             'avdReadyTimeout'           => 240000,
             'deviceName'                => "My_device",
             'platformName'              => "Android",
             'avd'                       => "poc-x86",
             'browserName'               => "Browser",
             'avdArgs'                   => '-no-audio -http-proxy 151.151.15.250:8080 -dns-server 10.27.206.11:55,10.27.206.101:55,10.91.218.197:55',
             'chromeOptions'             => { 'args' => 'ignore-certificate-errors=true homepage=about:blank test_type=true' }
         }

       when "ios device"
         desired_caps = {
             'platformVersion' => ios_version,
             'deviceName'      => "My_device",
             'platformName'    => "iOS",
             'browserName'     => 'Safari',
             'udid'            => device_id }

       else #iOS simulator
         desired_caps = {
             'deviceName'      => device_type,
             'platformVersion' => ios_version,
             'browserName'     => 'Safari',
             'platformName'    => "iOS" }
     end
     desired_caps
 end

Here is complete log file:

2015-04-17 21:27:52:948 - info: Welcome to Appium v1.3.7 (REV 72fbfaa116d3d9f6a862600ee99cf02f6d0e2182)
2015-04-17 21:27:52:949 - info: Appium REST http interface listener started on 0.0.0.0:4723
2015-04-17 21:27:52:951 - info: [debug] Non-default server args: {"log":"C:/projects/wria2/wf2/src/wf2-automation/tests/automation/log/appium_demo_appium_20150417142746.log","loglevel":"debug:debug","logTimestamp":true}
2015-04-17 21:27:52:951 - info: Console LogLevel: debug
2015-04-17 21:27:52:951 - info: File LogLevel: debug
2015-04-17 21:28:08:180 - info: --> POST /wd/hub/session {"desiredCapabilities":{"newCommandTimeout":600,"androidDeviceReadyTimeout":420,"avdLaunchTimeout":240000,"avdReadyTimeout":240000,"deviceName":"My_device","platformName":"Android","avd":"poc-x86","browserName":"Browser","avdArgs":"-no-audio -http-proxy 151.151.15.250:8080 -dns-server 10.27.206.11:55,10.27.206.101:55,10.91.218.197:55","chromeOptions":{"args":"ignore-certificate-errors=true homepage=about:blank test_type=true"},"chrome.switches":"ignore-certificate-errors=true homepage=about:blank test_type=true"}}
2015-04-17 21:28:08:182 - info: Client User-Agent string: appium/ruby_lib/6.0.0
2015-04-17 21:28:08:183 - info: [debug] The following desired capabilities were provided, but not recognized by appium. They will be passed on to any other services running on this server. : androidDeviceReadyTimeout, chromeOptions, chrome.switches
2015-04-17 21:28:08:184 - info: Set mode: Proxying straight through to Chromedriver
2015-04-17 21:28:08:184 - info: [debug] Looks like we want chrome on android
2015-04-17 21:28:08:185 - info: [debug] Creating new appium session 198807ae-40ec-4697-8d26-2628ca79f1b4
2015-04-17 21:28:08:186 - info: [debug] Checking whether adb is present
2015-04-17 21:28:08:189 - info: [debug] Using adb from C:\android\sdk\platform-tools\adb.exe
2015-04-17 21:28:08:190 - info: [debug] Using fast reset? true
2015-04-17 21:28:08:190 - info: [debug] Preparing device for session
2015-04-17 21:28:08:190 - info: [debug] Not checking whether app is present since we are assuming it's already on the device
2015-04-17 21:28:08:190 - info: [debug] Trying to find poc-x86 emulator
2015-04-17 21:28:08:191 - info: [debug] Getting connected emulators
2015-04-17 21:28:08:191 - info: [debug] Getting connected devices...
2015-04-17 21:28:08:192 - info: [debug] executing cmd: C:\android\sdk\platform-tools\adb.exe devices
2015-04-17 21:28:12:476 - info: [debug] 0 device(s) connected
2015-04-17 21:28:12:476 - info: [debug] 0 emulator(s) connected
2015-04-17 21:28:12:476 - info: [debug] Launching Emulator with AVD poc-x86, launchTimeout 240000ms and readyTimeout 240000ms
2015-04-17 21:28:12:477 - info: [debug] Checking whether emulator is present
2015-04-17 21:28:12:479 - info: [debug] Using emulator from C:\android\sdk\tools\emulator.exe
2015-04-17 21:28:12:518 - info: [debug] Trying to find poc-x86 emulator
2015-04-17 21:28:12:518 - info: [debug] Getting connected emulators
2015-04-17 21:28:12:518 - info: [debug] Getting connected devices...
2015-04-17 21:28:12:519 - info: [debug] executing cmd: C:\android\sdk\platform-tools\adb.exe devices
2015-04-17 21:28:12:666 - info: [debug] 0 device(s) connected
2015-04-17 21:28:12:666 - info: [debug] 0 emulator(s) connected
2015-04-17 21:28:14:681 - info: [debug] Trying to find poc-x86 emulator
2015-04-17 21:28:14:681 - info: [debug] Getting connected emulators
2015-04-17 21:28:14:683 - info: [debug] Getting connected devices...
2015-04-17 21:28:14:683 - info: [debug] executing cmd: C:\android\sdk\platform-tools\adb.exe devices
2015-04-17 21:28:14:849 - info: [debug] 0 device(s) connected
2015-04-17 21:28:14:849 - info: [debug] 0 emulator(s) connected

Here is complete console output of ruby script:

INFO    [212746.18822]:[  0.00000]:[-LVL0]:[] >> Starting Appium Demo 2015-04-17 21:27:46 UTC (14:27:46 Pacific Daylight Time)
INFO    [212746.18922]:[  0.00100]:[-LVL0]:[] >> Logging to C:/projects/wria2/wf2/src/wf2-automation/tests/automation/log/appium_demo_20150417142746.log
INFO    [212746.26122]:[  0.07200]:[-LVL0]:[] >> Running with ruby 2.0.0p451 (2014-02-24) [i386-mingw32]}
DEBUG   [212746.26122]:[  0.00000]:[     ]:[=>appium_demo.rb:149:in `end_processes'] end_processes /adb.exe|node.exe|emulator-arm.exe|emulator-x86.exe|chromedriver.exe/
adb.exe 8032
emulator-x86.exe 6228
DEBUG   [212746.47523]:[  0.21401]:[     ]:[=>appium_demo.rb:151:in `end_processes'] 2015-04-17 14:27:46 -0700: ['8032', 'adb.exe', '6228', 'emulator-x86.exe']
End these processes:
---
'8032': adb.exe
'6228': emulator-x86.exe
DEBUG   [212746.47723]:[  0.00200]:[     ]:[=>appium_demo.rb:161:in `end_processes'] [taskkill /f /pid 8032] adb.exe
DEBUG   [212746.64824]:[  0.17101]:[     ]:[=>appium_demo.rb:161:in `end_processes'] SUCCESS: The process with PID 8032 has been terminated.
DEBUG   [212746.64924]:[  0.00100]:[     ]:[=>appium_demo.rb:161:in `end_processes'] [taskkill /f /pid 6228] emulator-x86.exe
DEBUG   [212746.93726]:[  0.28802]:[     ]:[=>appium_demo.rb:161:in `end_processes'] SUCCESS: The process with PID 6228 has been terminated.
INFO    [212746.93926]:[  0.00200]:[-LVL2]:[=>appium_demo.rb:65:in `open_browser_mobile'] Open Browser Mobile: Android Emulator
DEBUG   [212746.93926]:[  0.00000]:[     ]:[=>appium_demo.rb:67:in `open_browser_mobile'] C:/projects/wria2/wf2/src/wf2-automation/tests/automation
DEBUG   [212746.93926]:[  0.00000]:[     ]:[=>appium_demo.rb:70:in `open_browser_mobile'] appium --log-timestamp --log-level debug:debug --log C:/projects/wria2/wf2/src/wf2-automation/tests/automation/log/appium_demo_appium_20150417142746.log &
DEBUG   [212746.98026]:[  0.04100]:[     ]:[=>appium_demo.rb:72:in `open_browser_mobile'] Appium PID: 7280
DEBUG   [212752.94860]:[  5.96834]:[     ]:[=>appium_demo.rb:74:in `open_browser_mobile'] appium: 2015-04-17 21:27:52:946 - info: Welcome to Appium v1.3.7 (REV 72fbfaa116d3d9f6a862600ee99cf02f6d0e2182)
DEBUG   [212752.94960]:[  0.00100]:[     ]:[=>appium_demo.rb:74:in `open_browser_mobile'] appium: 2015-04-17 21:27:52:949 - info: Appium REST http interface listener started on 0.0.0.0:4723
DEBUG   [212752.95160]:[  0.00200]:[     ]:[=>appium_demo.rb:74:in `open_browser_mobile'] appium: 2015-04-17 21:27:52:951 - info: [debug] Non-default server args: {"log":"C:/projects/wria2/wf2/src/wf2-automation/tests/automation/log/appium_demo_appium_20150417142746.log","loglevel":"debug:debug","logTimestamp":true}
DEBUG   [212752.95160]:[  0.00000]:[     ]:[=>appium_demo.rb:74:in `open_browser_mobile'] appium: 2015-04-17 21:27:52:951 - info: Console LogLevel: debug
DEBUG   [212752.95160]:[  0.00000]:[     ]:[=>appium_demo.rb:74:in `open_browser_mobile'] appium: 2015-04-17 21:27:52:951 - info: File LogLevel: debug
INFO    [212752.95260]:[  0.00100]:[-LVL0]:[=>appium_demo.rb:78:in `open_browser_mobile'] Sleeping for 15 seconds. 
 [[TRACE:=>appium_demo.rb:78:in `open_browser_mobile']]
DEBUG   [212807.95446]:[ 15.00186]:[     ]:[=>appium_demo.rb:85:in `open_browser_mobile'] ---
newCommandTimeout: 600
androidDeviceReadyTimeout: 420
avdLaunchTimeout: 240000
avdReadyTimeout: 240000
deviceName: My_device
platformName: Android
avd: poc-x86
browserName: Browser
avdArgs: -no-audio -http-proxy 151.151.15.250:8080 -dns-server 10.27.206.11:55,10.27.206.101:55,10.91.218.197:55
chromeOptions:
  args: ignore-certificate-errors=true homepage=about:blank test_type=true

WARN    [212817.30300]:[  9.34853]:[-FAIL]:[=>appium_demo.rb:58:in `rescue in run'] Unable to Rescue: 'No connection could be made because the target machine actively refused it. - connect(2)'
INFO    [212817.30400]:[  0.00100]:[-LVL0]:[] >> Appium Demo duration: 00:00:31
INFO    [212817.30500]:[  0.00100]:[-LVL0]:[] >> Appium Demo validations: 1 fail: 1]
INFO    [212817.30700]:[  0.00200]:[-LVL0]:[] >> End Appium Demo 2015-04-17 21:28:17 UTC (14:28:17 Pacific Daylight Time)

pmneve · April 17, 2015, 9:48pm

What is listed above is all the information I can find.

The emulator does start and keeps going, but just as it starts, the node.exe process simply disappears.

pmneve · April 21, 2015, 4:50pm

This issue is logged as #4952 in github issues.
Just hoping someone here has encountered something like this and might have suggestions.

pmneve · April 29, 2015, 6:19pm

Have workaround. By using ‘IO.popen(“start /k appium…”)’ instead of just ‘appium…’, the node process is stable.

I suspect it is something with Ruby 2.0 pipes under Windows 7, but am not sure.