Timeout error after calling set_location

[Trevor Harmon]

Hi,

I have a Calabash test suite that requires the GPS to be set at a particular location. So far, I've been hard-coding the location in the iOS Simulator's Custom Location box, but now I want to do it automatically using Calabash's set_location. I've added the following to launch.rb's relaunch method:

set_location(latitude: -17.884659, longitude: -5.099488)

This all works perfectly, except that 1 of my 7 scenarios now fails with a timeout error (see log pasted at the end of this email). I did some troubleshooting, and the good news is that the hang is completely reproducible and deterministic. It goes away if I take out the call to set_location. If I leave it in, the error always happens... at the same line... of the same step... of the same scenario… every time.

Of course, the question is why, and I have no idea. The call immediately before the hang is a simple touch() call to dismiss an alert view. I can see both in the Simulator and in the logs that it worked: calabash-server ran the /play command and printed "Playback complete".

The next call is a simple query() -- this is what triggers the timeout error. calabash-server never handles the request, leaving the client hanging. I traced through the server code in the Xcode debugger, and I can see /map being handled by GCDAsyncSocket. It gets as far as completeCurrentRead, line 4499, where dispatch_async is called (to invoke didReadData on the delegate: LPHTTPConnection) but for some reason the block never runs, and thus didReadData is never called on the delegate.

It is certainly odd that set_location would cause this one particular step of this one particular scenario to fail, while the other 50+ steps I have run fine. I suppose LocationOne is somehow upsetting the balance of things, but I don't see how. Any suggestions on where to go from here? Thanks,

Trevor


Given I have added a credit card # features/step_definitions/profile_steps.rb:1
Retrying.. HTTPClient::ReceiveTimeoutError: (execution expired)
Retrying.. HTTPClient::ReceiveTimeoutError: (execution expired)
When I remove the credit card # features/step_definitions/profile_steps.rb:14
Failing... HTTPClient::ReceiveTimeoutError
execution expired (HTTPClient::ReceiveTimeoutError)
./features/step_definitions/profile_steps.rb:16:in `/^I remove the credit card$/'
features/profile.feature:25:in `When I remove the credit card'
Then I should see "Add Card" # calabash-cucumber-0.9.126/features/step_definitions/calabash_steps.rb:296
And I should not see "7356" # calabash-cucumber-0.9.126/features/step_definitions/calabash_steps.rb:304
Retrying.. HTTPClient::ReceiveTimeoutError: (execution expired)
Retrying.. HTTPClient::ReceiveTimeoutError: (execution expired)
execution expired (HTTPClient::ReceiveTimeoutError)
/Users/trevor/.rvm/gems/ruby-1.9.3-p327/gems/httpclient-2.2.7/lib/httpclient/session.rb:875:in `gets'
/Users/trevor/.rvm/gems/ruby-1.9.3-p327/gems/httpclient-2.2.7/lib/httpclient/session.rb:875:in `block in parse_header'
/Users/trevor/.rvm/gems/ruby-1.9.3-p327/gems/httpclient-2.2.7/lib/httpclient/session.rb:872:in `parse_header'
/Users/trevor/.rvm/gems/ruby-1.9.3-p327/gems/httpclient-2.2.7/lib/httpclient/session.rb:855:in `read_header'
/Users/trevor/.rvm/gems/ruby-1.9.3-p327/gems/httpclient-2.2.7/lib/httpclient/session.rb:664:in `get_header'
/Users/trevor/.rvm/gems/ruby-1.9.3-p327/gems/httpclient-2.2.7/lib/httpclient.rb:1124:in `do_get_header'
/Users/trevor/.rvm/gems/ruby-1.9.3-p327/gems/httpclient-2.2.7/lib/httpclient.rb:1073:in `do_get_block'
/Users/trevor/.rvm/gems/ruby-1.9.3-p327/gems/httpclient-2.2.7/lib/httpclient.rb:873:in `block in do_request'
/Users/trevor/.rvm/gems/ruby-1.9.3-p327/gems/httpclient-2.2.7/lib/httpclient.rb:966:in `protect_keep_alive_disconnected'
/Users/trevor/.rvm/gems/ruby-1.9.3-p327/gems/httpclient-2.2.7/lib/httpclient.rb:872:in `do_request'
/Users/trevor/.rvm/gems/ruby-1.9.3-p327/gems/httpclient-2.2.7/lib/httpclient.rb:760:in `request'
/Users/trevor/.rvm/gems/ruby-1.9.3-p327/gems/httpclient-2.2.7/lib/httpclient.rb:663:in `get'
/Users/trevor/.rvm/gems/ruby-1.9.3-p327/gems/calabash-cucumber-0.9.126/lib/calabash-cucumber/core.rb:484:in `block in make_http_request'
/Users/trevor/.rvm/gems/ruby-1.9.3-p327/gems/calabash-cucumber-0.9.126/lib/calabash-cucumber/core.rb:476:in `times'
/Users/trevor/.rvm/gems/ruby-1.9.3-p327/gems/calabash-cucumber-0.9.126/lib/calabash-cucumber/core.rb:476:in `make_http_request'
/Users/trevor/.rvm/gems/ruby-1.9.3-p327/gems/calabash-cucumber-0.9.126/lib/calabash-cucumber/core.rb:455:in `http'
/Users/trevor/.rvm/gems/ruby-1.9.3-p327/gems/calabash-cucumber-0.9.126/lib/calabash-cucumber/core.rb:424:in `calabash_exit'
/Users/trevor/Documents/Repositories/consumer-ios/Tests/features/support/launch.rb:66:in `After'

[Krukow]

Thanks for the detailed report - that's really weird! I tried to do the same for the sample app: https://github.com/calabash/calabash-ios-example (modifying it to track location on the map).

However, I'm not able to reproduce the problem (of course you say that it only occurs in 1 of your 7 scenarios).

I have a couple of things we can do to try and track this down.

1) reproduce the problem in the sample app,

2) give me access to the project files and tests (I think I signed NDA when I visited you)

3) Just to see how this is related to set_location, we can try using the new "external" uia-based approach to set location (I'll give some detail on this later today - but briefly you need to install the pre release 0.9.127.pre1, modify to use start_app_in_background; sleep(10), and call: send_uia_command :command => "target.setLocation({latitude: -17.884659, longitude: -5.099488})")

- Karl

[Trevor Harmon]

Ah ha! I was able to reproduce it on your calabash-ios-example!

The problem is related to UIAlertView. If set_location is invoked, and then a UIAlertView appears, the entire app becomes unresponsive. (This was actually happening in 2 of my 7 scenarios, but I didn't notice the other one because that scenario ended as soon as the alert view appeared.)

To reproduce:

1) Add a button handler to LPFirstViewController:

- (IBAction)login:(id)sender {
    UIAlertView *alert = [[UIAlertView alloc] initWithTitle:nil message:@"this is an alert" delegate:nil cancelButtonTitle:@"OK" otherButtonTitles:nil];
    [alert show];
}

2) Link the Login button's Touch Up Inside to the handler.

3) Launch the app.

4) Launch the Calabash console and do: set_location(latitude: -17.884659, longitude: -5.099488). Of course, I think any parameters will work here.

5) Wait a few moments.

6) Tap Login.

At this point, you should see the alert view, but clicking on it does nothing.

Step #5 is kind of interesting -- if you call set_location in the console, and then immediately switch to the app, you can get a couple of alert views to appear before the app becomes unresponsive. There's some kind of delay between the time /uia is handled and the time the problem starts.

Haven't tried the external uia method yet.

I'll continue to investigate, but I hope this new information and your knowledge of the framework will lead us to a quick and easy fix.

Thank you,

Trevor

[Trevor Harmon]

Tracked in issue #95:

https://github.com/calabash/calabash-ios/issues/95

Trevor

[Krukow]

On Friday, December 28, 2012 7:38:52 PM UTC+1, Trevor Harmon wrote:

Ah ha! I was able to reproduce it on your calabash-ios-example!

Thanks - this is always the most efficient way that we can debug a problem!

 

The problem is related to UIAlertView. If set_location is invoked, and then a UIAlertView appears, the entire app becomes unresponsive. (This was actually happening in 2 of my 7 scenarios, but I didn't notice the other one because that scenario ended as soon as the alert view appeared.)

To reproduce:

[snip..]

Some good news 

- I can reproduce the problem.

- this only seems to happen on iOS6

- there seems to be a workaround (using "external uia")

Bad news:

- Currently I have no solution to work around this issue without external uia.

Please post any workaround you find. The most likely thing to happen will be going the "external" route - soon I'll explain more about this, but it is still work in progress.

-- Karl

[Albert Golubev]

Hi Trevor did you have to write a function to use set_location?

[Trevor Harmon]

I put it in launch.rb:

def relaunch

  ...
  set_location(latitude: -17.884659, longitude: -5.099488)
end

Trevor

--
You received this message because you are subscribed to the Google Groups "calabash-ios" group.
To unsubscribe from this group and stop receiving emails from it, send an email to calabash-ios...@googlegroups.com.
For more options, visit https://groups.google.com/groups/opt_out.
 
 

[Albert Golubev]

thanks for the reply Trevor

Do you know by any  chance, why If I take a screenshot of google map with a popup.. only the popup appears in the screens shot..

[Zac Tolley]

I have the same problem.

My app is used to record a journey, so you start it, the tests use set location to simulate the user driving some place and then to finish off I have an alert box, and I ran into the same thing of either hanging or the app shutting down.

Strange thing was if I used

touch("alertView child button marked:'#{button_label}'")

then the app would instantly shut down, but if I use 

touch("alertView child button marked:'Yes'")

it hangs.

So is there really no way around this? If so thats a bit of a downer, for my app its a show stopper, I'd have to re-write my app to have a custom written alert box

zac

[Krukow]

I think there is a workaround, if you're using the later versions that support launching with instruments.

You could try 

send_uia_command :command => "target.setLocation({'latitude':22.22, 'longitude':22.222})

Also I'll need to check if this is a problem also with Frank (if not then waiting for the merge is a longer-term solution).

[Zac Tolley]

ok so call me dumb.. go on it's ok....

What do you mean later versions that support launching with instruments?

If I put :

coord = locations[desiredlocation]

loc_data =  {latitude:coord['latitude'], longitude:coord['longitude']}

send_uia_command :command => "target.setLocation(#{loc_data.to_json})"

in my step then I get 

       ArgumentError: please supply :run_loop or instance var @calabash_launcher

As things stand I just run my tests either by calling "cucumber --tags @wip or running the tests within Intellij

[Zac Tolley]

I did have a quick look at the instructions for launching using instruments to a handset... though a little lost and don't remember how I'd do that for the simulator... 

[Karl Krukow]

You have to do two things:

1) make sure your hooks are updated to those of 0.9.146 (01_launch.rb, 02_pre_stop_hooks)

2) Set DEVICE_TARGET=simulator when running 

- Karl

[Zac Tolley]

Ah… right .. I replaced the launch.rb file with the new one out of the calabash package and it started.. though as you know it's hit and miss if it starts or not.. now something else is failing at the step before the important one (just trying to press a button) but I'll get to the bottom of that.

You received this message because you are subscribed to a topic in the Google Groups "calabash-ios" group.
To unsubscribe from this topic, visit https://groups.google.com/d/topic/calabash-ios/gMix06zDJb0/unsubscribe?hl=en.
To unsubscribe from this group and all its topics, send an email to calabash-ios...@googlegroups.com.

[Zac Tolley]

Right I'm launching using the new launch hook, using 0.9.146 and I set my location using the uia command... and guess what...

It still crashes the app when I press a button in an alert view to clear the alert :(

In my console when I press the button in the step I see

03/06/2013 15:23:49.028 Parentcab-cal[6600]: Supports Method POST at Path /play (segment play): 1

03/06/2013 15:23:49.029 Parentcab-cal[6600]: Warning: token child has no : separator

03/06/2013 15:23:49.031 Parentcab-cal[6600]: Center {227.5, 283.5}

03/06/2013 15:23:49.031 Parentcab-cal[6600]: Loading events

03/06/2013 15:23:49.032 Parentcab-cal[6600]: Playback

03/06/2013 15:23:49.082 Parentcab-cal[6600]: Clicked on alert view button 1

03/06/2013 15:23:49.084 Parentcab-cal[6600]: Playback complete

03/06/2013 15:23:49.117 Parentcab-cal[6600]: *** Terminating app due to uncaught exception 'NSInvalidArgumentException', reason: '*** -[__NSPlaceholderDictionary initWithObjects:forKeys:count:]: attempt to insert nil object from objects[2]'

*** First throw call stack:

(0x1f58012 0x1b3fe7e 0x1f1ea95 0x1f4b4e9 0x64ff5 0x5edb1 0x5f5ac 0x63cda 0x59e1a 0x5c292 0x91f3ce 0x1ccd53f 0x1cdf014 0x1ccf7d5 0x1efeaf5 0x1efdf44 0x1efde1b 0x2a9a7e3 0x2a9a668 0xa83ffc 0x5790d 0x57839)

03/06/2013 15:23:49.786 com.apple.launchd.peruser.501[131]: (UIKitApplication:com.exsite.Parentcab-cal[0x2b15][6600]) Job appears to have crashed: Abort trap: 6

03/06/2013 15:23:49.790 backboardd[6565]: Application 'UIKitApplication:com.exsite.Parentcab-cal[0x2b15]' exited abnormally with signal 6: Abort trap: 6

03/06/2013 15:23:49.903 ReportCrash[6634]: Saved crash report for Parentcab-cal[6600] version 0 to /Users/ztolley/Library/Logs/DiagnosticReports/Parentcab-cal_2013-06-03-152349_Zacs-MacBook-Air.crash

03/06/2013 15:23:54.949 mstreamd[6560]: (Note ) PS: Media stream daemon stopping.

03/06/2013 15:23:54.949 mstreamd[6560]: (Note ) AS: <MSIOSAlbumSharingDaemon: 0x3106750>: Shared Streams daemon shutting down.

03/06/2013 15:23:54.950 mstreamd[6560]: (Note ) AS: <MSIOSAlbumSharingDaemon: 0x3106750>: Shared Streams daemon has shut down.

So I'm at a total loss and feeling a little bit dejected... first my chickens didn't hatch out and now I can't write a test to simulate location changes followed by an alert box :(  Come on WWDC... give me something to smile about

[Karl Krukow]

Well that sounds really weird. I think something else is going on - is there a way to reproduce this on an app I can access?

[Zac Tolley]

Either you can see my code on bitbucket if you have an id or I'll create a very very simple application to try and isolate the issue.

zac

You received this message because you are subscribed to a topic in the Google Groups "calabash-ios" group.
To unsubscribe from this topic, visit https://groups.google.com/d/topic/calabash-ios/gMix06zDJb0/unsubscribe?hl=en.
To unsubscribe from this group and all its topics, send an email to calabash-ios...@googlegroups.com.

[Karl Krukow]

I think I already tested against the code on bitbucket and it worked. Can you explain in detail step by step how to reproduce it (against that code - also send the link again)

[Zac Tolley]

you probably saw someone else code. I have a private bitbucket repository for this one.

https://bitbucket.org/ztolley/parent-cab

I can give you access to it.

I have 1 test marked as WIP which records a journey and then ends it.. the test probably won't pass when this is sorted but I'm just stuck at a step that ends a journey.

In the mean time I'll create as simple a project as I can that does the same steps to isolate the issue.

zac

[Karl Krukow]

OK, just ping me when you have a simple project which reproduces it.

[Zac Tolley]

pants… the tiny standalone app works…..

So now I need to either figure out how to step through my code when running in a test or NSLog will have to be my friend

:(

You received this message because you are subscribed to a topic in the Google Groups "calabash-ios" group.
To unsubscribe from this topic, visit https://groups.google.com/d/topic/calabash-ios/gMix06zDJb0/unsubscribe?hl=en.
To unsubscribe from this group and all its topics, send an email to calabash-ios...@googlegroups.com.

[Zac Tolley]

ok.. so.. apparently my test found a bug in my code (stop)…..



The issue was deep down in my code and only occurred when reverse geocoding returns nothing because I accidentally set my position as being in the middle of the sea.

Still….



it works now :)

[Karl Krukow]

Good that tests can find bugs :)