I am new in calabash-android test automation library. I have spent two days to understand the problem with no success:(
I am using calabash-android version 0.8.0, I follow the documented pre-defined steps to do the test.
My test is simple, just wait for login screen(which is an activity contains an input field with id "email_field"), enter username and password. Here is my steps in feature file:
Feature: Login feature
Scenario: As a user I can login
Then I wait for the view with id "email_field" to appear
Then I enter text "john123@gmail.com" into field with id "email_field"
Then I enter text "123456" into field with id "pwd_field"
When I run my test with command calabash-android run myApp.apk, my app is launched, the login screen is shown, but after a while, my app is closed & I constantly get the following error, no matter running on which Android device (tested on Android 4.3 and Android 6.0 devices) :
Feature: Login feature
Scenario: As a user I can login # features/my_first.feature:2
execution expired (HTTPClient::ReceiveTimeoutError)
./features/support/app_life_cycle_hooks.rb:5:in `Before'
Then I wait for the view with id "email_field" to appear # calabash-android-0.8.0/lib/calabash-android/steps/progress_steps.rb:42
Then I enter text "john123@gmail.com" into field with id "email_field" # calabash-android-0.8.0/lib/calabash-android/steps/enter_text_steps.rb:13
Then I enter text "123456" into field with id "pwd_field" # calabash-android-0.8.0/lib/calabash-android/steps/enter_text_steps.rb:13
Failing Scenarios:
cucumber features/my_first.feature:2 # Scenario: As a user I can login
1 scenario (1 failed)
3 steps (3 skipped)
0m34.567s
Why?
(In my AndroidManifest.xml, I have both <uses-permission android:name="android.permission.INTERNET" /> and <uses-sdk android:targetSdkVersion="22" />)
=== More info with calabash-android console===
I also started calabash-android console, and run command start_test_server_in_background , I get the following error stacktrace
calabash-android console myApp.apk
Starting calabash-android console...
Loading /Users/John/.rvm/gems/ruby-2.3.0/gems/calabash-android-0.8.0/irbrc
Running irb...
irb(main):001:0> start_test_server_in_background
HTTPClient::ReceiveTimeoutError: execution expired
from /Users/John/.rvm/gems/ruby-2.3.0/gems/httpclient-2.8.2.2/lib/httpclient/session.rb:799:in `gets'
from /Users/John/.rvm/gems/ruby-2.3.0/gems/httpclient-2.8.2.2/lib/httpclient/session.rb:799:in `block in parse_header'
from /Users/John/.rvm/rubies/ruby-2.3.0/lib/ruby/2.3.0/timeout.rb:101:in `timeout'
from /Users/John/.rvm/gems/ruby-2.3.0/gems/httpclient-2.8.2.2/lib/httpclient/session.rb:795:in `parse_header'
from /Users/John/.rvm/gems/ruby-2.3.0/gems/httpclient-2.8.2.2/lib/httpclient/session.rb:778:in `read_header'
from /Users/John/.rvm/gems/ruby-2.3.0/gems/httpclient-2.8.2.2/lib/httpclient/session.rb:554:in `get_header'
from /Users/John/.rvm/gems/ruby-2.3.0/gems/httpclient-2.8.2.2/lib/httpclient.rb:1297:in `do_get_header'
from /Users/John/.rvm/gems/ruby-2.3.0/gems/httpclient-2.8.2.2/lib/httpclient.rb:1243:in `do_get_block'
from /Users/John/.rvm/gems/ruby-2.3.0/gems/httpclient-2.8.2.2/lib/httpclient.rb:1017:in `block in do_request'
from /Users/John/.rvm/gems/ruby-2.3.0/gems/httpclient-2.8.2.2/lib/httpclient.rb:1131:in `protect_keep_alive_disconnected'
from /Users/John/.rvm/gems/ruby-2.3.0/gems/httpclient-2.8.2.2/lib/httpclient.rb:1012:in `do_request'
from /Users/John/.rvm/gems/ruby-2.3.0/gems/httpclient-2.8.2.2/lib/httpclient.rb:854:in `request'
from /Users/John/.rvm/gems/ruby-2.3.0/gems/httpclient-2.8.2.2/lib/httpclient.rb:763:in `post'
from /Users/John/.rvm/gems/ruby-2.3.0/gems/calabash-android-0.8.0/lib/calabash-android/operations.rb:500:in `make_http_request'
from /Users/John/.rvm/gems/ruby-2.3.0/gems/calabash-android-0.8.0/lib/calabash-android/operations.rb:437:in `http'
from /Users/John/.rvm/gems/ruby-2.3.0/gems/calabash-android-0.8.0/lib/calabash-android/operations.rb:752:in `start_application'
from /Users/John/.rvm/gems/ruby-2.3.0/gems/calabash-android-0.8.0/lib/calabash-android/operations.rb:743:in `start_test_server_in_background'
from /Users/John/.rvm/gems/ruby-2.3.0/gems/calabash-android-0.8.0/lib/calabash-android/operations.rb:143:in `start_test_server_in_background'
from (irb):1
from /Users/John/.rvm/rubies/ruby-2.3.0/bin/irb:11:in `<main>'irb(main):002:0>
=======Tried @Tobias' suggestion by setting DEBUG_HTTP flag to true=========
I tried @Tobias' suggestion, by executing command calabash-android run myApp.apk DEBUG=1 DEBUG_HTTP=1 , here is the output (at the bottom is the same error message):
No test server found for this combination of app and calabash version. Recreating test server.
Done signing the test server. Moved it to test_servers/b813b6bcf17675e303e5cb7f53c2a85f_0.8.0.apk
DEBUG: Setting Android SDK location to $ANDROID_HOME
DEBUG: Android SDK location set to '/Users/John/Library/Android/sdk'
DEBUG: Set aapt path to '/Users/John/Library/Android/sdk/build-tools/23.0.3/aapt'
DEBUG: Set zipalign path to '/Users/John/Library/Android/sdk/build-tools/23.0.3/zipalign'
DEBUG: Set adb path to '/Users/John/Library/Android/sdk/platform-tools/adb'
DEBUG: Set android jar path to '/Users/John/Library/Android/sdk/platforms/android-24/android.jar'
DEBUG: Setting Java SDK location to $JAVA_HOME
DEBUG: Java SDK location set to '/Library/Java/JavaVirtualMachines/jdk1.8.0_77.jdk/Contents/Home'
DEBUG: Found java on PATH
DEBUG: Set java path to '/Library/Java/JavaVirtualMachines/jdk1.8.0_77.jdk/Contents/Home/bin/java'
DEBUG: Found keytool on PATH
DEBUG: Set keytool path to '/Library/Java/JavaVirtualMachines/jdk1.8.0_77.jdk/Contents/Home/bin/keytool'
DEBUG: Found jarsigner on PATH
DEBUG: Set jarsigner path to '/Library/Java/JavaVirtualMachines/jdk1.8.0_77.jdk/Contents/Home/bin/jarsigner'
Feature: Login with email and password
= Request
! CONNECT TO 127.0.0.1:34777
! CONNECTION ESTABLISHED
POST //ping HTTP/1.1
Content-Type: application/json;charset=utf-8
User-Agent: HTTPClient/1.0 (2.8.2.2, ruby 2.3.0 (2015-12-25))
Accept: */*
Date: Sun, 28 Aug 2016 15:57:34 GMT
Content-Length: 2
Host: 127.0.0.1:34777
{}
= Response
! CONNECTION CLOSED
= Request
! CONNECT TO 127.0.0.1:34777
! CONNECTION ESTABLISHED
POST //ping HTTP/1.1
Content-Type: application/json;charset=utf-8
User-Agent: HTTPClient/1.0 (2.8.2.2, ruby 2.3.0 (2015-12-25))
Accept: */*
Date: Sun, 28 Aug 2016 15:57:34 GMT
Content-Length: 2
Host: 127.0.0.1:34777
{}
= Response
! CONNECTION CLOSED
= Request
! CONNECT TO 127.0.0.1:34777
! CONNECTION ESTABLISHED
POST //ping HTTP/1.1
Content-Type: application/json;charset=utf-8
User-Agent: HTTPClient/1.0 (2.8.2.2, ruby 2.3.0 (2015-12-25))
Accept: */*
Date: Sun, 28 Aug 2016 15:57:34 GMT
Content-Length: 2
Host: 127.0.0.1:34777
{}
= Response
HTTP/1.0 200 OK
Content-Type: text/html
Date: Sun, 28 Aug 2016 15:57:35 GMT
pong! CONNECTION CLOSED
= Request
! CONNECT TO 127.0.0.1:34777
! CONNECTION ESTABLISHED
POST //ping HTTP/1.1
Content-Type: application/json;charset=utf-8
User-Agent: HTTPClient/1.0 (2.8.2.2, ruby 2.3.0 (2015-12-25))
Accept: */*
Date: Sun, 28 Aug 2016 15:57:34 GMT
Content-Length: 2
Host: 127.0.0.1:34777
{}
= Response
HTTP/1.0 200 OK
Content-Type: text/html
Date: Sun, 28 Aug 2016 15:57:35 GMT
pong! CONNECTION CLOSED
= Request
! CONNECT TO 127.0.0.1:34777
! CONNECTION ESTABLISHED
POST //ready HTTP/1.1
Content-Type: application/json;charset=utf-8
User-Agent: HTTPClient/1.0 (2.8.2.2, ruby 2.3.0 (2015-12-25))
Accept: */*
Date: Sun, 28 Aug 2016 15:57:34 GMT
Content-Length: 2
Host: 127.0.0.1:34777
{}
= Response
HTTP/1.0 200 OK
Content-Type: text/html
Date: Sun, 28 Aug 2016 15:57:35 GMT
true! CONNECTION CLOSED
= Request
! CONNECT TO 127.0.0.1:34777
! CONNECTION ESTABLISHED
POST // HTTP/1.1
Content-Type: application/json;charset=utf-8
User-Agent: HTTPClient/1.0 (2.8.2.2, ruby 2.3.0 (2015-12-25))
Accept: */*
Date: Sun, 28 Aug 2016 15:57:34 GMT
Content-Length: 36
Host: 127.0.0.1:34777
{"command":"version","arguments":[]}
= Response
HTTP/1.0 200 OK
Content-Type: text/html
Date: Sun, 28 Aug 2016 15:57:35 GMT
{"bonusInformation":[],"message":"0.8.0","success":true}! CONNECTION CLOSED
= Request
! CONNECT TO 127.0.0.1:34777
! CONNECTION ESTABLISHED
POST //start-application HTTP/1.1
Content-Type: application/json;charset=utf-8
User-Agent: HTTPClient/1.0 (2.8.2.2, ruby 2.3.0 (2015-12-25))
Accept: */*
Date: Sun, 28 Aug 2016 15:57:35 GMT
Content-Length: 15
Host: 127.0.0.1:34777
{"intent":null}
= Response
! CONNECTION CLOSED
Scenario: As a user I can login # features/my_first.feature:3
Then I wait for the view with id "email_field" to appear
execution expired (HTTPClient::ReceiveTimeoutError)
./features/support/app_life_cycle_hooks.rb:5:in `Before'
Then I enter text "john123@gmail.com" into field with id "account_input" # calabash-android-0.8.0/lib/calabash-android/steps/enter_text_steps.rb:13
Then I enter text "123456" into field with id "password_input" # calabash-android-0.8.0/lib/calabash-android/steps/enter_text_steps.rb:13
By the way, about the first step in feature file, that is Then I wait for the view with id "email_field" to appear. The "email_field" is in the login activity. I start the login activity from main activity after some action has been done in main activity. It looks like the failure is on the first step.
===== Logcat log ====
Here is the logcat log, I can't figure out how it could help solving my problem.
08-29 10:54:14.892 13474 13474 I calabash: execStartActivity 4
08-29 10:54:14.892 13474 13474 I Timeline: Timeline: Activity_launch_request id:com.john.myApp time:50467579
08-29 10:54:14.893 956 3893 I ActivityManager: START u0 {cmp=com.john.myApp/.LoginActivity (has extras)} from uid 10627 on display 0
08-29 10:54:14.917 13474 13474 I mainui : onPause
08-29 10:54:14.927 13474 13474 I calabash: newActivity1
08-29 10:54:15.018 956 1025 I ActivityManager: Displayed com.john.myApp/.LoginActivity: +100ms (total +7s320ms)
08-29 10:54:15.271 956 1025 I Timeline: Timeline: Activity_windows_visible id: ActivityRecord{99dcb96 u0 com.john.myApp/.LoginActivity t14253} time:50467958
08-29 10:54:16.084 956 1003 W ActivityManager: Launch timeout has expired, giving up wake lock!
08-29 10:54:16.103 13089 13144 W FlurryAgent: Flurry session paused for context:com.estrongs.android.pop.app.InstallMonitorActivity@bb5ddc9
08-29 10:54:18.546 4723 4723 I Auth : [AuthDelegateWrapper] Service intent: Intent { cmp=com.google.android.gms/.auth.account.authenticator.DefaultAuthDelegateService }.
08-29 10:54:18.547 4723 4723 I Auth : [AuthDelegateWrapper] Service intent: Intent { cmp=com.google.android.gms/.auth.account.authenticator.DefaultAuthDelegateService }.
08-29 10:54:18.572 4723 4723 I Auth : [AuthDelegateWrapper] Service intent: Intent { cmp=com.google.android.gms/.auth.account.authenticator.DefaultAuthDelegateService }.
08-29 10:54:18.897 13501 13550 W Flag : Duration spec must be at least 2 characters long:
08-29 10:54:18.897 13501 13550 W Flag : Duration spec must be at least 2 characters long:
08-29 10:54:19.232 13501 13550 W linker : /data/app/com.google.android.gms-2/lib/arm/libgmscore.so: unused DT entry: type 0x7ffffffd arg 0xa74
08-29 10:54:19.252 13501 13550 W linker : /data/app/com.google.android.gms-2/lib/arm/libconscrypt_gmscore_jni.so: unused DT entry: type 0x1d arg 0xe0
08-29 10:54:19.252 13501 13550 W linker : /data/app/com.google.android.gms-2/lib/arm/libconscrypt_gmscore_jni.so: unused DT entry: type 0x7ffffffd arg 0x1cb
08-29 10:54:19.263 13501 13550 V JNIHelp : Registering com/google/android/gms/org/conscrypt/NativeCrypto's 255 native methods...
08-29 10:54:19.282 469 469 I Gobi : vendor/qcom/proprietary/RIDL/RIDLClient/RIDLSQL.cpp:2500: GetTransState() EBADF
08-29 10:54:19.282 469 469 I Gobi : vendor/qcom/proprietary/RIDL/RIDLClient/MainCore.cpp:1550: Failed to get TransState, rc 9
08-29 10:54:19.283 469 469 I Gobi : vendor/qcom/proprietary/RIDL/RIDLClient/RIDLSQL.cpp:2500: GetTransState() EBADF
08-29 10:54:19.283 469 469 I Gobi : vendor/qcom/proprietary/RIDL/RIDLClient/RIDLSQL.cpp:2500: GetTransState() EBADF
08-29 10:54:19.357 13501 13550 I ProviderInstaller: Installed default security provider GmsCore_OpenSSL
08-29 10:54:20.615 13415 13448 I Finsky : [6145] com.google.android.finsky.c.e.run(1154): Replicating app states via AMAS.
08-29 10:54:21.049 13415 13448 I Finsky : [6145] com.google.android.finsky.c.c.a(316): Completed 0 account content syncs with 0 successful.
08-29 10:54:21.064 13415 13415 I Finsky : [1] com.google.android.finsky.services.j.a(149): Installation state replication succeeded.
08-29 10:54:21.575 956 3287 I ActivityManager: Start proc 13734:com.joelapenna.foursquared/u0a427 for broadcast com.joelapenna.foursquared/com.foursquare.pilgrim.app.service.ReceiverPilgrimLocationClientFire
08-29 10:54:21.654 13734 13734 W System : ClassLoader referenced unknown path: /data/app/com.joelapenna.foursquared-2/lib/arm
08-29 10:54:21.675 13734 13734 I MultiDex: VM with version 2.1.0 has multidex support
08-29 10:54:21.675 13734 13734 I MultiDex: install
08-29 10:54:21.675 13734 13734 I MultiDex: VM has multidex support, MultiDex support library is disabled.
08-29 10:54:21.682 13734 13734 I FirebaseInitProvider: FirebaseApp initialization unsuccessful
08-29 10:54:21.820 13734 13734 I Fabric : Initializing Crashlytics 2.3.2.56
08-29 10:54:21.833 13734 13755 V GoogleSignatureVerifier: com.google.android.gms signature not valid. Found:
08-29 10:54:21.833 13734 13755 V GoogleSignatureVerifier: PYtRmasflljsAwIBAgIJAMLgh0ZkSjCNMA0GCSqGSIb3DQEBBAUAMHQxCzAJBgNVBAYTAlVTMRMw
08-29 10:54:21.833 13734 13755 V GoogleSignatureVerifier: AASWEQIEwpDYWxpZmurksngexorhlpquflseknvaseudGFpbiBWaWV3MRQwEgYDVQQKEwtHb29n
08-29 10:54:21.833 13734 13755 V GoogleSignatureVerifier: kIVXXCdjLjEQMA4GA1UECxMHQW5kcm9pZDEQMA4GA1UEAxMHQW5kcm9pZDAeFw0wODA4MjEyMzEz
08-29 10:54:21.833 13734 13755 V GoogleSignatureVerifier: QAMSDfw0zNjAxMDcydfgawelhsdrgrAJBgNVBAYTAlVTMRMwEQYDVQQIEwpDYWxpZm9ybmlhMRYw
08-29 10:54:21.833 13734 13755 V GoogleSignatureVerifier: PPUTIFHEw1Nb3VudGFpbiBWaWV3MRQwEgYDVQQKEwtHb29nbGUgSW5jLjEQMA4GA1UECxMHQW5k
08-29 10:54:21.833 13734 13755 V GoogleSignatureVerifier: cm9pZDEQMA4GA1UEAxMHQW5kcm9pZDCCASAwDQYJKoZIhvcNAQEBBQADggENADCCAQgCggEBAKtW
08-29 10:54:21.833 13734 13755 V GoogleSignatureVerifier: LgDYO6IIrgqWbxJOKdoR8qtW0I9Y4sypEwPpt1TTcvZApxsdyxMJZ2JORland2qSGT2y5b+3JKke
08-29 10:54:21.833 13734 13755 V GoogleSignatureVerifier: xfaLDmpHpDsz2WCbdxgxRczfey5YZnTJ4VZbH0xqWVW/8lGmPav5xVwnIiJS6HXk+BVKZF+JcWjA
08-29 10:54:21.833 13734 13755 V GoogleSignatureVerifier: dfaGEuq/eFdpuzSqeYTcfi6idkyugwfYwXFU1+5fZKUaRKYCwkkFQVfcAs1fXA5V+++FGfvjJ/Cx
08-29 10:54:21.833 13734 13755 V GoogleSignatureVerifier: UsfhBvGdGDhfXE28LWuT9ozCl5xw4Yq5OGazvV24mZVSoOO0yZ31j7kYvtwYK6NeADwbSxDdJE
08-29 10:54:21.833 13734 13755 V GoogleSignatureVerifier: jsef//0zOOIBRiGYXtqw/A0LFFoiinblsdrgsQOjgdkwgdYwHQYDVR0OBBYEFMd9jMIhF1Ylmn/T
08-29 10:54:22.095 13734 13734 D BeaconParser: Parsing beacon layout: m:2-3=beac,i:4-19,i:20-21,i:22-23,p:24-24,d:25-25
08-29 10:54:22.096 13734 13734 D BeaconParser: Parsing beacon layout: m:2-3=0215,i:4-19,i:20-21,i:22-23,p:24-24
08-29 10:54:22.098 13734 13734 D BeaconParser: Parsing beacon layout: s:0-1=feaa,m:2-2=00,p:3-3:-41,i:4-13,i:14-19
08-29 10:54:22.099 13734 13734 D BeaconParser: Parsing beacon layout: s:0-1=feaa,m:2-2=10,p:3-3:-41,i:4-20v
08-29 10:54:22.139 13734 13770 W System : ClassLoader referenced unknown path: /system/framework/tcmclient.jar
08-29 10:54:22.225 13734 13734 D AppsFlyer_4.5.0: Build Number: 138
08-29 10:54:23.776 13474 13806 I System.out: URI: //kill
08-29 10:54:23.777 13474 13806 I System.out: params: {json={}
08-29 10:54:23.777 13474 13806 I System.out: }
08-29 10:54:23.777 13474 13806 I System.out: Stopping test server
08-29 10:54:23.785 956 3256 W ActivityManager: Duplicate finish request for ActivityRecord{5c6dbdd u0 com.john.myApp/.MainActivity t14253 f}
08-29 10:54:23.786 956 3177 W ActivityManager: Duplicate finish request for ActivityRecord{5c6dbdd u0 com.john.myApp/.MainActivity t14253 f}
08-29 10:54:23.789 13474 13474 I mainui : onStop
08-29 10:54:23.813 13474 13474 I Timeline: Timeline: Activity_idle id: android.os.BinderProxy@e70b6f8 time:50476500
08-29 10:54:23.831 956 977 W ActivityManager: Finishing task with all activities already finished
08-29 10:54:23.831 956 977 W ActivityManager: Duplicate finish request for ActivityRecord{99dcb96 u0 com.john.myApp/.LoginActivity t14253 f}
08-29 10:54:23.894 3847 3847 I Timeline: Timeline: Activity_idle id: android.os.BinderProxy@2efe322 time:50476582
08-29 10:54:24.023 956 1025 I Timeline: Timeline: Activity_windows_visible id: ActivityRecord{36601a6 u0 com.sonyericsson.home/com.sonymobile.home.HomeActivity t14213} time:50476710
08-29 10:54:26.154 13089 13144 W FlurryAgent: Flurry session ended
In above logcat logs, the noticeable part is:
08-29 10:54:23.776 13474 13806 I System.out: URI: //kill
08-29 10:54:23.777 13474 13806 I System.out: params: {json={}
08-29 10:54:23.777 13474 13806 I System.out: }
08-29 10:54:23.777 13474 13806 I System.out: Stopping test server
Running on another device I see this:
W/ActivityManager( 869): Activity idle timeout for ActivityRecord{41cb4158 u0 com.john.myApp/.LoginActivity}
I/System.out( 8538): URI: //kill
I/System.out( 8538): params: {json={}
I/System.out( 8538): }
I/System.out( 8538): Stopping test server
that's when the test throw calabash error message:
execution expired (HTTPClient::ReceiveTimeoutError)
./features/support/app_life_cycle_hooks.rb:5:in `Before'
(To clarify, the login activity was launched during testing, but there was no automatic email & password input, the app was then closed.)
Anyhow, I still don't get what is wrong with logcat logs.
