Appium not maintaining auth-token

Hi everyone,

I am writing some tests for an Android application using Java with Selenium and Appium (v 1.3.4.1).

My problem:
After doing a manual login operation on the tablet to authenticate into application, logs are displaying that login REST service is returning a JSON with some “authtoken” and “userID” parameters as following:

D/Retrofit(12762): <— HTTP 200 https://myserver/login (249ms)
D/Retrofit(12762): Content-Type: application/json;charset=UTF-8
D/Retrofit(12762): {“authToken”:“0ffd7caa-ab0b-4779-92ef-a1d85f3870a9”,“userID”:“101438”}
D/Retrofit(12762): —> END HTTP (63-byte body)

In order to do other specific actions such as retrieving details from server for that specific user, the application is doing another call which is using the above authToken and userID as parameters:

D/Retrofit(12762): —> HTTP POST https://myserver/getUserDetails
D/Retrofit(12762): X-Auth-Token: 0ffd7caa-ab0b-4779-92ef-a1d85f3870a9
D/Retrofit(12762): userID: 101438
D/Retrofit(12762): Content-Type: application/json;charset=UTF-8
D/Retrofit(12762): [//some JSON content]
D/Retrofit(12762): —> END HTTP (259-byte body)

Everything works fine when doing actions manually on the tablet but when running automated tests to retrieve user details the POST request is not including anymore X-Auth-Token and userID parameters,causing the app to fail:

Request:

D/Retrofit(15186): —> HTTP POST https://myserver/getUserDetails
D/Retrofit(15186): Content-Type: application/json;charset=UTF-8
D/Retrofit(15186): [//some JSON content]
D/Retrofit(15186): —> END HTTP (315-byte body)

Response:

D/Retrofit(15186): <— HTTP 400 https://myserver/getUserDetails
D/Retrofit(15186): Content-Type: application/json;charset=UTF-8
D/Retrofit(15186): {“errorCode”:“USER_ID_HEADER_MISSING”,“message”:“User id header missing”}
D/Retrofit(15186): <— END HTTP (81-byte body)

Does anyone have an idea why Appium doesn’t pass these parameters across the application when running automated tests?

Many Thanks,
Lucian

I’m having trouble understanding what’s going on here, so I’m figuring that’s probably the case for most people. Here is what I get out of the above post, please correct me where I’m wrong:

  1. When clicking some button on this app, an HTTP request is made and a JSON response is expected
  2. If the above is manually done, all works
  3. If the above is done with Appium, an ‘authToken’ and ‘userID’ are missing from the HTTP request and therefore the JSON response has errors

If the above is true I would suspect that the App is in some bad state. Appium is literally ‘clicking buttons’ in the same way you would manually. In fact, I would suspect that you may have a timing issue here, because Appium can click buttons a lot faster than you or I can. But I could be wrong…

Hi Wreed,

Thanks for the answer, you understood this correctly.

Just to clarify the steps:
Manual mode:

  1. Doing Login action -> JSON with “authToken” and “userID” is retrieved into response body for login method
  2. Doing Get User Details action -> “authToken” and “userID” are inserted into HTTP Request Header for getUserDetails method, retrieving user details successfully

Automatic mode:

  1. Doing Login action -> JSON with “authToken” and “userID” is retrieved into response body for login method
  2. Doing Get User Details action -> “authToken” and “userID” are NOT inserted anymore into HTTP Request Header for getUserDetails method, causing request to fail

Certainly this is not a delay issue, my guess is that somehow the above parameters are flushed during the run and appium is loosing the session…

But how is that possible? Does the app get these parameters from Appium? It certainly does not get them from a user that is clicking buttons. I still think this is a timing issue, and in fact I’d go further that it’s a bug in the App. The buttons should not populate the screen when these values are not available.

It may be that these values get populated fast enough that you would never see this problem from a user perspective. I personally would try adding a timeout to my automation (and in this case you would have to use an Explicit timeout) and see if the parameters are available after the timeout. I’d start w/ 5 seconds & if that works decrease until I found a ‘sweet spot’ that works reliably. I’d then add 1 second to give it a better chance of always working.

Hi Wreed,

Thanks for coming back to me.
No, app is not getting parameters from Appium
I tried today to add an explicit wait with 10 seconds between actions but with no luck.
However I noticed the following line in the logs before Get User Details request, app is somehow checking if user is still logged in before each action:

Manual Mode:
capture loggedinUser: true

Automatic Mode:
capture loggedinUser: false

Maybe this has something to do with --no reset-- / --full reset-- settings of the Appium server which is somehow flushing the session…tried both ways anyway but same behavior is present…

Tomorrow I will post here the entire logs along with a piece of code if you are interested.

Thanks a lot!
Lucian

Have you spoken to a developer about this behavior? Maybe there is some requirement that is not being met. Honestly I’m not sure what is happening. At the very least one of your developers should be able to let you know what ‘capture loggedinUser’ does. And sure, post the logs & I’ll take a look.

Added Logs for manual and auto run before and after triggering getUserDetails:

Manual:

D/TESTFAIRYSDK(1536): There are 52 events in memory, sending out a batch of 50
D/TESTFAIRYSDK(1536): Forcing a flush of all 10 events that are in memory
W/EGL_emulation(1536): eglSurfaceAttrib not implemented
W/OpenGLRenderer(1536): Failed to set EGL_SWAP_BEHAVIOR on surface 0xa23b9500, error=EGL_SUCCESS
V/TESTFAIRYSDK(1536): Successfully sent events from memory over the wire
D/TESTFAIRYSDK(1536): There are 22 events in memory, sending out a batch of 50
D/OpenGLRenderer(1536): endAllStagingAnimators on 0x9f897080 (RippleDrawable) with handle 0xa0dff780
> E/eee(1536): intercept() logged in:true
D/Retrofit(1536): —> HTTP POST https://myserver/getUserDetails
D/Retrofit(1536): X-Auth-Token: 23327e22-d342-4823-87c2-83ecb146bd15
D/Retrofit(1536): userID: 901418
D/Retrofit(1536): Content-Type: application/json;charset=UTF-8
D/Retrofit(1536): Content-Length: 259
D/Retrofit(1536): [//some JSON content]
D/Retrofit(1536): —> END HTTP (259-byte body)
D/Retrofit(1536): <— HTTP 201 https://myserver/getUserDetails (464ms)
D/Retrofit(1536): Date: Tue, 12 May 2015 07:45:52 GMT
D/Retrofit(1536): Access-Control-Allow-Headers: Origin, X-Requested-With, Content-Type, Accept, userID, X-Auth-Token
D/Retrofit(1536): Access-Control-Allow-Methods: PATCH, PUT, POST, GET, OPTIONS, DELETE
D/Retrofit(1536): Access-Control-Allow-Origin: *
D/Retrofit(1536): Access-Control-Max-Age: 0
D/Retrofit(1536): Keep-Alive: timeout=5, max=100
D/Retrofit(1536): Connection: Keep-Alive
D/Retrofit(1536): Transfer-Encoding: chunked
D/Retrofit(1536): Content-Type: application/json;charset=UTF-8
D/Retrofit(1536): OkHttp-Selected-Protocol: http/1.1
D/Retrofit(1536): OkHttp-Sent-Millis: 1431416752483
D/Retrofit(1536): OkHttp-Received-Millis: 1431416752819
D/Retrofit(1536): [//some JSON content with user details]
D/Retrofit(1536): <— END HTTP (76-byte body)

Auto:

0/TESTFAIRYSDK(2264): There are 52 events in memory, sending out a batch of 50
V/TESTFAIRYSDK(2264): Successfully sent events from memory over the wire
W/EGL_emulation(2264): eglSurfaceAttrib not implemented
W/OpenGLRenderer(2264): Failed to set EGL_SWAP_BEHAVIOR on surface 0xabbfa440, error=EGL_SUCCESS
D/OpenGLRenderer(2264): endAllStagingAnimators on 0x9d5c0a00 (RippleDrawable) with handle 0x9d54a050
> E/eee(2264): intercept() logged in:false
D/Retrofit(2264): —> HTTP POST https://myserver/getUserDetails
D/Retrofit(2264): Content-Type: application/json;charset=UTF-8
D/Retrofit(2264): Content-Length: 378
D/Retrofit(2264): [// some JSON content]
D/Retrofit(2264): —> END HTTP (378-byte body)
D/Retrofit(2264): <— HTTP 400 https://myserver/getUserDetails
D/Retrofit(2264): Date: Tue, 12 May 2015 07:58:08 GMT
D/Retrofit(2264): Server: Oracle-HTTP-Server-12c
D/Retrofit(2264): Access-Control-Allow-Headers: Origin, X-Requested-With, Content-Type, Accept, userID, X-Auth-Token
D/Retrofit(2264): Access-Control-Allow-Methods: PATCH, PUT, POST, GET, OPTIONS, DELETE
D/Retrofit(2264): Access-Control-Allow-Origin: *
D/Retrofit(2264): Access-Control-Max-Age: 0
D/Retrofit(2264): Connection: close
D/Retrofit(2264): Transfer-Encoding: chunked
D/Retrofit(2264): Content-Type: application/json;charset=UTF-8
D/Retrofit(2264): OkHttp-Selected-Protocol: http/1.1
D/Retrofit(2264): OkHttp-Sent-Millis: 1431417488817
D/Retrofit(2264): OkHttp-Received-Millis: 1431417488869
D/Retrofit(2264): {“errorCode”:“USER_ID_HEADER_MISSING”,“message”:“User id header missing”}
D/Retrofit(2264): <— END HTTP (81-byte body)

The only difference that I can see causing getUserDetails method to fail its related to intercept() logged in action which I don’t know what this relates to…is intercept() a specific method from Appium?

looking same - App freezes when automated ?

@amedvedev Thanks for the link, I’ve checked that thread but it’s not the same issue

In my situation the current session for a logged user is somehow flushed across the application and can’t do any other actions (applications behaves like the user would be logged out)

did you try to disable logging in application? we met with issue when we have enable logging and have JSON = appium freezes.

I haven’t tried, will speak with devs in order to see if they can release another .apk version with debug disabled and see if this solves the issue

Hi guys,

Just to let you know, I managed to solve this.

The issue was caused by a bug into application which was forcing a silent log out, causing the session to be flushed.

Thanks a lot for your advice!

Ha! Glad it worked out for you!