Appium 1.3.7 not launching android emulator when appium started with separate method in Ruby

Issues/Bugs
1

Already posted and rejected by github support.
Using
appium 1.3.7
appium_lib 6.0.0
ruby 2.0.0p451
chromedriver 2.15.322448
watir-webdriver 0.6.10 (from gem list)
selenium-webdriver 2.45.0 (from gem list)
Win 7 Enterprise 64bit SP 1

This works:

    def run
    end_processes('adb.exe', 'node.exe', 'emulator-arm.exe', 'emulator-x86.exe')

    # start_appium
    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 #{log_file}"
    debug_to_log(command)
    appium = IO.popen(command) 
    debug_to_log("Appium PID: #{appium.pid}")
    3.times { debug_to_log(appium.readline.chomp) }

    browser = open_browser_mobile("", "android emulator")
    debug_to_log("#{browser.driver.capabilities.to_yaml}")

    go_to_url(browser, "https://hxbbfb75.etforge.com/2.6.0rc6/examples/index.html")
    . . .
    browser.close if browser
    end_processes('adb.exe', 'node.exe', 'emulator-arm.exe', 'emulator-x86.exe')
    end

    def open_browser_mobile(device_id, device_type, ios_version='8.1')

    desired_caps = set_mobile_capabilties(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, # :remote,
                       :url                  => server_url,
                       :desired_capabilities => desired_caps,
                       :http_client          => client
    )
end

This does not:

def start_appium
    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 #{log_file}"
    debug_to_log(command)
    appium = IO.popen(command) # --log-no-colors --log-timestamp  --log appium_log.txt  , :err => :out
    debug_to_log("Appium PID: #{appium.pid}")
    3.times { debug_to_log(appium.readline.chomp) }
    appium
end

def run
  end_processes('adb.exe', 'node.exe', 'emulator-arm.exe', 'emulator-x86.exe')

  start_appium

  browser = open_browser_mobile("", "android emulator")
  . . .
end

The appium start code is identical… if it is enclosed in a method and called, webdriver tries to start right away and fails with ECONNREFUSED. If the code is inside the same method where webdriver is started, it waits for the appium server to launch the emulator, waits for the browser to open, etc… behaving correctly.

The appium log in the failing instance is this (in entirety). Note that it ends prematurely, i.e. without showing the error at all:

2015-04-09 22:16:05:916 - info: Welcome to Appium v1.3.7 (REV 72fbfaa)
2015-04-09 22:16:05:917 - info: Appium REST http interface listener started on 0.0.0.0:4723
2015-04-09 22:16:05:919 - info: [debug] Non-default server args: {“log”:“C:/projects/wria2/wf2/src/wf2-automation/tests/automation/log/appium_demo_appium_20150409151600.log”,“logTimestamp”:true}
2015-04-09 22:16:05:919 - info: Console LogLevel: debug
2015-04-09 22:16:05:919 - info: File LogLevel: debug

When it succeeds the log looks like this:
2015-04-09 22:17:46:068 - info: Welcome to Appium v1.3.7 (REV 72fbfaa)
2015-04-09 22:17:46:069 - info: Appium REST http interface listener started on 0.0.0.0:4723
2015-04-09 22:17:46:071 - info: [debug] Non-default server args: {“log”:“C:/projects/wria2/wf2/src/wf2-automation/tests/automation/log/appium_demo_appium_20150409151740.log”,“logTimestamp”:true}
2015-04-09 22:17:46:071 - info: Console LogLevel: debug
2015-04-09 22:17:46:071 - info: File LogLevel: debug
2015-04-09 22:17:46:269 - info: --> POST /wd/hub/session {“desiredCapabilities”:{“newCommandTimeout”:600,“androidDeviceReadyTimeout”:420,“avdLaunchTimeout”:240000,“avdReadyTimeout”:240000,“deviceName”:“My_device”,“platformName”:“Android”,“avd”:“poc”,“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-09 22:17:46:271 - info: Client User-Agent string: Ruby
2015-04-09 22:17:46:271 - warn: Converting cap chrome.switches to string, since it was an object. This might be a user error. Original value was: [“ignore-certificate-errors=true”,“homepage=about:blank”,“test_type=true”]
2015-04-09 22:17:46:272 - 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-09 22:17:46:272 - info: Set mode: Proxying straight through to Chromedriver
2015-04-09 22:17:46:272 - info: [debug] Looks like we want chrome on android
2015-04-09 22:17:46:274 - info: [debug] Creating new appium session f4f658ba-0a0a-490b-af34-cadbac51aeb7
2015-04-09 22:17:46:275 - info: [debug] Checking whether adb is present
2015-04-09 22:17:46:277 - info: [debug] Using adb from C:\android\sdk\platform-tools\adb.exe
2015-04-09 22:17:46:278 - info: [debug] Using fast reset? true
2015-04-09 22:17:46:278 - info: [debug] Preparing device for session
2015-04-09 22:17:46:278 - info: [debug] Not checking whether app is present since we are assuming it’s already on the device
2015-04-09 22:17:46:278 - info: [debug] Trying to find poc emulator
2015-04-09 22:17:46:279 - info: [debug] Getting connected emulators
2015-04-09 22:17:46:279 - info: [debug] Getting connected devices…
2015-04-09 22:17:46:280 - info: [debug] executing cmd: C:\android\sdk\platform-tools\adb.exe devices
2015-04-09 22:17:50:541 - info: [debug] 0 device(s) connected
2015-04-09 22:17:50:541 - info: [debug] 0 emulator(s) connected
2015-04-09 22:17:50:542 - info: [debug] Launching Emulator with AVD poc, launchTimeout 240000ms and readyTimeout 240000ms
2015-04-09 22:17:50:542 - info: [debug] Checking whether emulator is present
2015-04-09 22:17:50:547 - info: [debug] Using emulator from C:\android\sdk\tools\emulator.exe
2015-04-09 22:17:50:591 - info: [debug] Trying to find poc emulator
2015-04-09 22:17:50:591 - info: [debug] Getting connected emulators
2015-04-09 22:17:50:591 - info: [debug] Getting connected devices…
2015-04-09 22:17:50:592 - info: [debug] executing cmd: C:\android\sdk\platform-tools\adb.exe devices

2

Wow, that’s weird. I don’t know much about the inner workings of Ruby, but I wonder if a ProcMon capture might help. Total SWAG: maybe something about the difference in scope changes the working directory so that in one case all the dependencies get loaded and in another they don’t?

3

Truly weird. I’ll look into ProcMon
If it were that kind of scope issue I suspect I’d have seen it before.
My wild guess is it has to do with the iopen.
If I can figure another way to start the process without killing the ruby process (it is supposed to run independently anyway) I’ll try that.

4

I think I’ve figured it out. It turns out to be a timing issue as well as a method scope issue. By separating start of appium server in its own method and/or not forcing an appropriate pause to wait for it to have started Webdriver::Browser.new is invoked too soon so there is not server to talk to.