Logo Questions Linux Laravel Mysql Ubuntu Git Menu
HTML CSS JAVASCRIPT SQL PYTHON PHP BOOTSTRAP JAVA JQUERY R React Kotlin
 

Constantly get error "HTTPClient::ReceiveTimeoutError" with my very simple calabash test case

Tags:

android

cucumber

calabash

calabash-android

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 "[email protected]" 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 "[email protected]" 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 "[email protected]" 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.

like image 201
Leem.fin Avatar asked Aug 26 '16 14:08

Leem.fin

1 Answers

Downgrade calabash-android to verstion 0.7.3 solved my problem.

like image 71
Leem.fin Avatar answered Sep 30 '22 08:09

Leem.fin
Sign in to Comment

Related questions

Conent Transition NPE with empty shared elements
BottomSheetDialog not showing?
Best way to add android standard icons in Xamarin
Emulator disconnect frequently and Android Studio Stuck. How To fix it?
What are the alternative classes for localTime and localDate in Android? [duplicate]
QuickBlox WebRtc VideoChat Android
Element ignore is not allowed here, in Android lint.xml
Fused Location Provider - onLocationChanged stops getting called
Android Creating custom dimension in google analytics
Why Two Methods for FirebaseDatabase Client Offline?
Sugar ORM listAll() not showing any data
Getting Error: Execution failed for task app:transformClassesWithMultidexlistForDebug
DisplayLeakActivity does not exist
Android RealmList<Integer> and RealmList<String>
Notification with setGroupSummary(true) is not visible in Android N
Android different packageName with flavors
Android GridView last column getting cut
Override Google Calendar default settings for reminders
How to set size of the bitmap in ZXing?
How to implement multiple filtering on RecyclerView based android app?

Donate For Us

If you love us? You can donate to us via Paypal or buy me a coffee so we can maintain and grow! Thank you!