Closed Bug 978434 Opened 6 years ago Closed 6 years ago

STK Select timeout is not set correctly from test app and takes 14-25 secs to return the Terminal Response (v1.3)

Categories

(Firefox OS Graveyard :: Gaia::Settings, defect)

Other
Gonk (Firefox OS)
defect
Not set

Tracking

(b2g-v1.3? affected, b2g-v2.0 fixed)

RESOLVED FIXED
2.0 S1 (9may)
Tracking Status
b2g-v1.3 ? affected
b2g-v2.0 --- fixed

People

(Reporter: nsarkar, Unassigned)

Details

Attachments

(1 file)

The select timeout doesn't work on v1.3 and we get a terminal response to SELECT_ITEM command in an un-deterministic time frame ranging randomly from 14 secs to 20, 25 secs, etc.
Flags: needinfo?(frsela)
Hi,

+gerard, who implemented timeout in 894873. @Gerard, Any idea about the un-deterministic time frame?

Which value is defined into the icc.selectTimeout in your installation?

master -> https://github.com/mozilla-b2g/gaia/blob/master/build/config/common-settings.json#L76
v1.3 -> https://github.com/mozilla-b2g/gaia/blob/v1.3/build/settings.js#L172

By default (in master & v1.3) is 150 secs.

Be sure, you don't have a custom setting which changes this value for your build.

Also, if you can provide some log traces (with GAIA log traces enabled into developer menu) will be very usefull
Flags: needinfo?(frsela) → needinfo?(nsarkar)
(In reply to Nivi from comment #0)
> The select timeout doesn't work on v1.3 and we get a terminal response to
> SELECT_ITEM command in an un-deterministic time frame ranging randomly from
> 14 secs to 20, 25 secs, etc.

Without any context at all, I can just reply that it works for me and I can't do any divination ...
Hi Fernando/Gerard,

I set the icc.selectTimeout to 1 sec and the terminal response for SELECT_ITEM was received in 14 secs. I set the the timeout to 20 secs/25 secs and every time the terminal response came back in timeout + 6-10 secs. I am running stk select_item test using marionette. A snippet from the log that shows this behavior is -

01-01 00:29:16.559   319   319 I Gecko   : -*- [SUB0] QCContentHelper_QC_B2G: sendMessage to content process: icc-stkcommand{ iccId : '8934071196000746406', command : { commandNumber : 1, typeOfCommand : 36, commandQualifier : 0, options : { title : 'Toolkit Select', items : [ {identifier : 1, text : 'Item 1',  },  {identifier : 2, text : 'Item 2',  },  {identifier : 3, text : 'Item 3',  },  {identifier : 4, text : 'Item 4',  },  ],presentationType : 0,  },  } }
01-01 00:29:16.579   319   319 I Gecko   : -*- [SUB0] QCContentHelper_QC_B2G: sendMessage to content process: RIL:StkCommand{ commandNumber : 1, typeOfCommand : 36, commandQualifier : 0, options : { title : 'Toolkit Select', items : [ {identifier : 1, text : 'Item 1',  },  {identifier : 2, text : 'Item 2',  },  {identifier : 3, text : 'Item 3',  },  {identifier : 4, text : 'Item 4',  },  ],presentationType : 0,  },  }
01-01 00:29:16.579   319   319 I Gecko   : -*- QCMessageManager_QC_B2G: Received sendTargetMessage with topic='icc', message='RIL:StkCommand'
01-01 00:29:16.629   319   319 I Gecko   : MARIONETTE LOG: INFO: Received SELECT_ITEM command => {"commandNumber":1,"typeOfCommand":36,"commandQualifier":0,"options":{"title":"Toolkit Select","items":[{"identifier":1,"text":"Item 1"},{"identifier":2,"text":"Item 2"},{"identifier":3,"text":"Item 3"},{"identifier":4,"text":"Item 4"}],"presentationType":0}}
01-01 00:29:16.639   319   319 I Gecko   : MARIONETTE TEST RESULT:TEST-PASS | test_stk.js | select_item_cmd_1 - 36 should equal 36
01-01 00:29:16.639   319   319 I Gecko   : MARIONETTE TEST RESULT:TEST-PASS | test_stk.js | select_item_cmd_1 - 0 should equal 0
01-01 00:29:16.639   319   319 I Gecko   : MARIONETTE TEST RESULT:TEST-PASS | test_stk.js | select_item_cmd_1 - Toolkit Select should equal Toolkit Select
01-01 00:29:16.649   319   319 I Gecko   : MARIONETTE TEST RESULT:TEST-PASS | test_stk.js | select_item_cmd_1 - [{"identifier":1,"text":"Item 1"},{"identifier":2,"text":"Item 2"},{"identifier":3,"text":"Item 3"},{"identifier":4,"text":"Item 4"}] should equal [{"identifier":1,"text":"Item 1"},{"identifier":2,"text":"Item 2"},{"identifier":3,"text":"Item 3"},{"identifier":4,"text":"Item 4"}]
01-01 00:29:16.649   319   319 I Gecko   : MARIONETTE TEST RESULT:TEST-PASS | test_stk.js | select_item_cmd_1 - 0 should equal 0
01-01 00:29:16.699   319   319 E GeckoConsole: QCLOC: MozSettingShim: Unhandled setting: icc.data



01-01 00:29:36.659   319   319 I Gecko   : 1776664	Marionette	INFO	sendToClient: {"from":"0","error":{"message":"timed out due to inactivity","status":28}}, {dce748e2-0d95-40da-9329-6a30324a7ee3}, {dce748e2-0d95-40da-9329-6a30324a7ee3}
01-01 00:29:36.679   319   319 I Gecko   : 1776688	Marionette	INFO	sendToClient: {"from":"0","value":[["INFO","TEST-START: /net/cros-bm-p2/local/mnt/workspace/nsarkar/jb_3.2/vendor/qcom/proprietary/b2g_telephony/test/test_stk.js","Thu Jan 01 1970 00:29:04 GMT+0000 (UTC)"],["INFO","Received DISPLAY_TEXT command => {\"commandNumber\":1,\"typeOfCommand\":33,\"commandQualifier\":128,\"options\":{\"text\":\"<GO-BACKWARDS>\",\"userClear\":true}}","Thu Jan 01 1970 00:29:06 GMT+0000 (UTC)"],["INFO","Received DISPLAY_TEXT command => {\"commandNumber\":1,\"typeOfCommand\":33,\"commandQualifier\":0,\"options\":{\"text\":\"Toolkit Test 1\",\"responseNeeded\":true}}","Thu Jan 01 1970 00:29:07 GMT+0000 (UTC)"],["INFO","Received DISPLAY_TEXT command => {\"commandNumber\":1,\"typeOfCommand\":33,\"commandQualifier\":129,\"options\":{\"text\":\"Extension chars: ^{~}\",\"isHighPriority\":true,\"userClear\":true}}","Thu Jan 01 1970 00:29:07 GMT+0000 (UTC)"],["INFO","Received DISPLAY_TEXT command => {\"commandNumber\":1,\"typeOfCommand\":33,\"commandQualifier\":0,\"optio
01-01 00:29:36.729   319   319 I Gecko   : 1776743	Marionette	INFO	sendToClient: {"from":"0","value":[]}, {e82426fb-f87a-4e00-a17c-0ffaffa1851a}, {e82426fb-f87a-4e00-a17c-0ffaffa1851a}
01-01 00:29:36.759   319   319 I Gecko   : 1776774	Marionette	INFO	sendToClient: {"from":"0","ok":true}, {61f4087b-2842-4273-8c50-b4f2b9b986ad}, {61f4087b-2842-4273-8c50-b4f2b9b986ad}
01-01 00:29:42.269   319   319 I Gecko   : -*- QCMessageManager_QC_B2G: receiveMessage: RIL:SendStkResponse arrived from content process
01-01 00:29:42.279   319   319 D use-Rlog/RLOG-RIL_QC_B2G: [SUB0] [0859]> STK_SEND_TERMINAL_RESPONSE 810301240002028281830112
01-01 00:29:42.279   319   319 I Gecko   : -*- QCMessageManager_QC_B2G: Forwarding message to clientId = 0
01-01 00:29:42.279   319   319 I Gecko   : -*- [SUB0] QCContentHelper_QC_B2G: receiveMessage: 'RIL:SendStkResponse'

The select timeout was set to 15 secs and marionette inactivity timeout to 20 secs for this case. Marionette times out in 20 sec and the Terminal response comes in 26 secs. I increases the value of select timeout to 25 secs and marionette time out to 30 secs. Response came back in time > 30 secs. Marionette times out and the test fails every time. Let me know if you need any additional info.

Thanks,
Nivi.
Flags: needinfo?(nsarkar)
Any updates on this bug?
Flags: needinfo?(lissyx+mozillians)
No. Can you document your STR, please ?
Flags: needinfo?(lissyx+mozillians) → needinfo?(nsarkar)
Yes sure. I added a marionette test to run stk proactive command SELECT_ITEM. In the test script, I set the icc.selectTimeout to 20 secs. When I run the test, I expect the Terminal Response to come back in 20 secs but it doesn't. I timed it and it seems to return in > 20 secs. This was working earlier. 

Do you have test scripts for STK? If you don't you could just run a SELECT_ITEM test from the STK app on the SIM. The default select timeout is set to 150 secs so maybe you could set it to something lower (like 20 sec). Ideally the TR should come within the time set in icc.selectTimeout. But, I see it taking longer.

Let me know if you have further questions.

Thanks,
Nivi.
Flags: needinfo?(nsarkar)
I'll work on unit test this week, so I'll consider this suggestion for this command ;) - Hope it helps to locate the issue :)

(In reply to Nivi from comment #6)
> Yes sure. I added a marionette test to run stk proactive command
> SELECT_ITEM. In the test script, I set the icc.selectTimeout to 20 secs.
> When I run the test, I expect the Terminal Response to come back in 20 secs
> but it doesn't. I timed it and it seems to return in > 20 secs. This was
> working earlier. 
> 
> Do you have test scripts for STK? If you don't you could just run a
> SELECT_ITEM test from the STK app on the SIM. The default select timeout is
> set to 150 secs so maybe you could set it to something lower (like 20 sec).
> Ideally the TR should come within the time set in icc.selectTimeout. But, I
> see it taking longer.
> 
> Let me know if you have further questions.
> 
> Thanks,
> Nivi.
Thanks Fernando. I really appreciate it.

Nivi.
Comment on attachment 8406776 [details] [review]
Tests added to check timeouts

Fernando,

Looks good to me assuming the tests pass :)

Thanks,
Nivi.
Attachment #8406776 - Flags: feedback?(nsarkar) → feedback+
(In reply to Nivi from comment #10)
> Comment on attachment 8406776 [details] [review]
> Tests added to check timeouts
> 
> Fernando,
> 
> Looks good to me assuming the tests pass :)
> 
> Thanks,
> Nivi.

Yes, tests pass: https://travis-ci.org/mozilla-b2g/gaia/builds/23028638

Also tests worked correctly and timeouts are correct:

[settings-test/unit/icc_test.js] STK (App menu) >

    [settings-test/unit/icc_test.js] UI checks >
        [settings-test/unit/icc_test.js] Check initialization ‣
        [settings-test/unit/icc_test.js] Correct number of entries into the STK options list ‣
        [settings-test/unit/icc_test.js] STK Header ‣
        [settings-test/unit/icc_test.js] All items with correct NAI data ‣
        [settings-test/unit/icc_test.js] All items with correct data ‣
    [settings-test/unit/icc_test.js] Check timeouts >
        [settings-test/unit/icc_test.js] Wait for timeout (1 sec)1002ms ‣
        [settings-test/unit/icc_test.js] Wait for timeout (3 sec)3007ms ‣
        [settings-test/unit/icc_test.js] Wait for timeout (5 sec)5007ms ‣

so no 14-25 secs are needed ... it's working well.
Can you check the bug again?
Flags: needinfo?(nsarkar)
Comment on attachment 8406776 [details] [review]
Tests added to check timeouts

More unit tests for STK
Attachment #8406776 - Flags: review?(fabien)
Attachment #8406776 - Flags: review?(fabien) → review?(ehung)
Comment on attachment 8406776 [details] [review]
Tests added to check timeouts

I have no idea about how STK works. redirect to Arthur.
BTW, is this related to bug 984243?
Attachment #8406776 - Flags: review?(ehung) → review?(arthur.chen)
Fernando,

I will check your patch again and let you know. Thanks for sharing.

I will time the TR and see if the time matches what is set in icc.selectTimeout. :)

Thanks,
Nivi.
Flags: needinfo?(nsarkar)
Hey Fernando,

I am unable to test with ur patch due to STK regression - https://bugzilla.mozilla.org/show_bug.cgi?id=999235
However, I did grab your patch last week and my select item tests were passing. The only thing I was unable to do is time the tests.

You could go ahead with this change if your tests pass and once STK regression is fixed I will be able to test your patch and time the TR.

Thanks,
Nivi.
(In reply to Evelyn Hung [:evelyn] from comment #13)
> Comment on attachment 8406776 [details] [review]
> Tests added to check timeouts
> 
> I have no idea about how STK works. redirect to Arthur.
> BTW, is this related to bug 984243?

Yes, basically, the patch is the unit test of that bug ;)
(In reply to Nivi from comment #15)
> Hey Fernando,
> 
> I am unable to test with ur patch due to STK regression -
> https://bugzilla.mozilla.org/show_bug.cgi?id=999235
> However, I did grab your patch last week and my select item tests were
> passing. The only thing I was unable to do is time the tests.
> 
> You could go ahead with this change if your tests pass and once STK
> regression is fixed I will be able to test your patch and time the TR.
> 
> Thanks,
> Nivi.

Nivi, As told before I could reproduce the issue commented in the bug description. This patch is the unit test to assure it's working.

The time is displayed in the console; we can add an extra assert to assure the time is inside an accepted window
Comment on attachment 8406776 [details] [review]
Tests added to check timeouts

Sorry for the late review. The code looks good to me, however the tests seem not make sense to me. Please check my comments, thanks!
Attachment #8406776 - Flags: review?(arthur.chen)
(In reply to Arthur Chen [:arthurcc] from comment #18)
> Comment on attachment 8406776 [details] [review]
> Tests added to check timeouts
> 
> Sorry for the late review. The code looks good to me, however the tests seem
> not make sense to me. Please check my comments, thanks!

Test changed. Now using fake timers
Comment on attachment 8406776 [details] [review]
Tests added to check timeouts

r=me, thanks.
Attachment #8406776 - Flags: review?(arthur.chen) → review+
Thanks Arthur.

Landed: https://github.com/mozilla-b2g/gaia/commit/d4ab86bcf2d9c24f4d40ada0895216607f13899f
Status: NEW → RESOLVED
Closed: 6 years ago
Resolution: --- → FIXED
Target Milestone: --- → 2.0 S1 (9may)
You need to log in before you can comment on or make changes to this bug.