leo device with test run3 build. Test case ID: #5468 PROCEDURE Use a post-paid VIVO Sim card. 1. Open Usage app and press home to leave it in background 2. Open Messaging app, create and send an SMS 3. Open Usage app again, on Phone check the SMS counter EXPECTED The counter is refreshed and shows the number of SMSs sent ACTUAL The counter is only refreshed when Usage app is closed at the moment when the SMS is sent. If Usage app is open, then the counter does not work properly. The number of SMSs is not updated

Nomming this. If the application is left open, the information can be misleading, and of course, it's not obvious that you need to restart the app to get the correct number. More than likely, once the app is launched, it just runs in the background until the phone itself is restarted. Consumer behavior in South American markets suggests that they pay alot of attention to data like this, particularly when on fixed plans and/or a limited budget.

Adding qawanted to reproduce. If this does repro, especially after multiple SMS messages, we may have to block.

This is still reproducible. When the app is in background, counting messages is not working. Leo device: Mozilla build ID: 20130616070209 Gecko's Revision : be276cf55ce160bca09f36d9ca679a2ae20ea7cc Gaia's Revision : f2d6ed54a236e6e3b94f0abad9f0dacb8a1cc7b3 Removing qawanted

With Unagi device, other BE, open source RIL but the same Gaia commit, we are having the same issue. I've checked with latest BE, open source RIL and v1-train in Unagi as well and is not reproducing. Asking for QA.

I'm reproducing this on an Inari with gaia master.

(In reply to Alexandre LISSY :gerard-majax from comment #5) > I'm reproducing this on an Inari with gaia master. I'm also reproducing this with current gaia v1-train on my Inari. Salvador, are you sure it does not reproduce ? What do you call latest BE ?

Today build for Gecko. OS Version: 1.1.0.0-prerelease Platform version: 18.1 Build identifier: 20130626062120

(In reply to Salvador de la Puente González [:salva] from comment #7) > Today build for Gecko. > > OS Version: 1.1.0.0-prerelease > Platform version: 18.1 > Build identifier: 20130626062120 After discussing on IRC, it seems to be reproduced on commercial RIL. FYI, E/GeckoConsole( 2677): [JavaScript Error: "[Exception... "Component returned failure code: 0x80570009 (NS_ERROR_XPC_BAD_CONVERT_JS) [nsIXPCComponents_Utils.createObjectIn]" nsresult: "0x80570009 (NS_ERROR_XPC_BAD_CONVERT_JS)" location: "JS frame :: resource://gre/modules/ObjectWrapper.jsm :: objWrapper_wrap :: line 56" data: no]" {file: "resource://gre/modules/ObjectWrapper.jsm" line: 56}] E/GeckoConsole( 2677): [JavaScript Error: "TypeError: configuration.topup.senders is undefined" {file: "app://costcontrol.gaiamobile.org/gaia_build_message_handler.js" line: 330}]

Do you still need qawanted support here or are you unblocked to fix this bug per comment 8?

adb logcat output when sending a SMS and the Cost Control app is already running: I/GeckoDump( 430): (1372262989177-3) CC /index.html>/message_handler.html: SMS sent! I/GeckoDump( 430): (1372263004087-0) CC /message_handler.html: Nothing to do in message handler, returning to app... I/GeckoDump( 430): (1372263004087-1) CC /message_handler.html: Initializing Cost Control I/GeckoDump( 430): (1372263004087-2) CC /message_handler.html: APIs loaded! E/GeckoConsole( 430): [JavaScript Error: "[Exception... "Component returned failure code: 0x80570009 (NS_ERROR_XPC_BAD_CONVERT_JS) [nsIXPCComponents_Utils.createObjectIn]" nsresult: "0x80570009 (NS_ERROR_XPC_BAD_CONVERT_JS)" location: "JS frame :: resource://gre/modules/ObjectWrapper.jsm :: objWrapper_wrap :: line 56" data: no]" {file: "resource://gre/modules/ObjectWrapper.jsm" line: 56}] adbg locat when switching to the Cost Control app: I/GeckoDump( 430): (1372262988871-87) CC /index.html: Request for: telephony I/GeckoDump( 430): (1372262988871-88) CC /index.html: Last telephony activity: {"timestamp":{"__date__":"2013-06-26T16:08:00.735Z"},"calltime":0,"smscount":4} adb logcat when sending a SMS and the Cost Control app is NOT already running: I/GeckoDump( 430): (1372263040852-0) CC /message_handler.html: Initializing Cost Control I/GeckoDump( 430): (1372263040852-1) CC /message_handler.html: APIs loaded! I/GeckoDump( 430): (1372263040852-2) CC /message_handler.html: Provider configuration done! I/GeckoDump( 430): (1372263040852-3) CC /message_handler.html: Cost Control ready! I/GeckoDump( 430): (1372263040852-4) CC /message_handler.html: Installing handlers I/GeckoDump( 430): (1372263040852-5) CC /message_handler.html: SMS sent! I/GeckoDump( 430): (1372263040852-6) CC /message_handler.html: Checking for closing... I/GeckoDump( 430): (1372262856537-61) CC /widget.html: Synchronization request for lastTelephonyActivity received! I/GeckoDump( 430): (1372263040852-7) CC /message_handler.html: Closing. I/GeckoDump( 430): (1372262856537-62) CC /widget.html: Option lastTelephonyActivity has changed! I/GeckoDump( 430): (1372262856537-63) CC /widget.html: Event optionchange dispatched for lastTelephonyActivity I/GeckoDump( 430): (1372263040852-8) CC /message_handler.html: Event optionchange dispatched for lastTelephonyActivity

Such a nightmare. With commercial RIL, device Unagi, BE from 2013/06/26 and latest Gaia v1-train it is not reproducing. Logs look like: =============== I/GeckoDump( 1658): (1372316784601-5) CC /index.html>/message_handler.html: SMS sent! I/GeckoDump( 1658): (1372316784601-6) CC /index.html>/message_handler.html: Checking for closing... I/GeckoDump( 1658): (1372316784235-104) CC /index.html: Synchronization request for lastTelephonyActivity received! I/GeckoDump( 1658): (1372316777727-32) CC /widget.html: Synchronization request for lastTelephonyActivity received! I/GeckoDump( 1658): (1372316784235-105) CC /index.html: Option lastTelephonyActivity has changed! I/GeckoDump( 1658): (1372316784235-106) CC /index.html: Event optionchange dispatched for lastTelephonyActivity I/GeckoDump( 1658): (1372316784235-107) CC /index.html: Option lastTelephonyActivity has changed! I/GeckoDump( 1658): (1372316784235-108) CC /index.html: Event optionchange dispatched for lastTelephonyActivity I/GeckoDump( 1658): (1372316777727-33) CC /widget.html: Option lastTelephonyActivity has changed! I/GeckoDump( 1658): (1372316777727-34) CC /widget.html: Event optionchange dispatched for lastTelephonyActivity I/GeckoDump( 1658): (1372316784601-7) CC /index.html>/message_handler.html: Checking for closing... I/GeckoDump( 1658): (1372316784601-8) CC /index.html>/message_handler.html: SMS sent! I/GeckoDump( 1658): (1372316784601-9) CC /index.html>/message_handler.html: Checking for closing... I/GeckoDump( 1658): (1372316784235-109) CC /index.html: Synchronization request for lastTelephonyActivity received! I/GeckoDump( 1658): (1372316777727-35) CC /widget.html: Synchronization request for lastTelephonyActivity received! I/GeckoDump( 1658): (1372316784235-110) CC /index.html: Option lastTelephonyActivity has changed! I/GeckoDump( 1658): (1372316784235-111) CC /index.html: Event optionchange dispatched for lastTelephonyActivity I/GeckoDump( 1658): (1372316777727-36) CC /widget.html: Option lastTelephonyActivity has changed! I/GeckoDump( 1658): (1372316777727-37) CC /widget.html: Event optionchange dispatched for lastTelephonyActivity I/GeckoDump( 1658): (1372316784235-112) CC /index.html: Option lastTelephonyActivity has changed! I/GeckoDump( 1658): (1372316784235-113) CC /index.html: Event optionchange dispatched for lastTelephonyActivity I/GeckoDump( 1658): (1372316784601-10) CC /index.html>/message_handler.html: Checking for closing... I/GeckoDump( 1658): (1372316784235-114) CC /index.html: Request for: telephony I/GeckoDump( 1658): (1372316784235-115) CC /index.html: Last telephony activity: {"timestamp":{"__date__":"2013-06-27T07:09:27.300Z"},"calltime":0,"smscount":3} After another SMS: ================== I/GeckoDump( 1658): (1372316784601-11) CC /index.html>/message_handler.html: SMS sent! I/GeckoDump( 1658): (1372316784601-12) CC /index.html>/message_handler.html: Checking for closing... I/GeckoDump( 1658): (1372316784235-118) CC /index.html: Synchronization request for lastTelephonyActivity received! I/GeckoDump( 1658): (1372316777727-38) CC /widget.html: Synchronization request for lastTelephonyActivity received! I/GeckoDump( 1658): (1372316784235-119) CC /index.html: Option lastTelephonyActivity has changed! I/GeckoDump( 1658): (1372316784235-120) CC /index.html: Event optionchange dispatched for lastTelephonyActivity I/GeckoDump( 1658): (1372316784235-121) CC /index.html: Option lastTelephonyActivity has changed! I/GeckoDump( 1658): (1372316784235-122) CC /index.html: Event optionchange dispatched for lastTelephonyActivity I/GeckoDump( 1658): (1372316777727-39) CC /widget.html: Option lastTelephonyActivity has changed! I/GeckoDump( 1658): (1372316777727-40) CC /widget.html: Event optionchange dispatched for lastTelephonyActivity I/GeckoDump( 1658): (1372316784601-13) CC /index.html>/message_handler.html: Checking for closing... I/GeckoDump( 1658): (1372316784235-123) CC /index.html: Request for: telephony I/GeckoDump( 1658): (1372316784235-124) CC /index.html: Last telephony activity: {"timestamp":{"__date__":"2013-06-27T07:12:15.495Z"},"calltime":0,"smscount":4} So it is increasing as expected.

Latest Gaia v1-train is commit 477e57212d4338e87182d9a8be96bb5c59c0a792

Hmmmm I'm getting spurious behavior of loadConfigurationIndex(): it seems the XHR is triggering the ObjectWrapper error.

The same code and request is fine from index.html, and is exploding when in message_handler.html

Okay, I found the root cause of the object wrapper issue I think. There is a call to window.history.back() at https://github.com/mozilla-b2g/gaia/blob/master/apps/costcontrol/js/message_handler.js#L26 When commenting this one, then it does not crash about ObjectWrapper.

Thanks Alexandre but we need to know why this is bad. What is the problem of returning back? Maybe I can prepare a patch for you adding the call to back() into a timeout or something like that. Furthermore this is not always reproducing. Maybe anyone from BE could clarify what could be happening? Alexandre, do you know who could help us?

(In reply to Salvador de la Puente González [:salva] from comment #16) > Thanks Alexandre but we need to know why this is bad. What is the problem of > returning back? Maybe I can prepare a patch for you adding the call to > back() into a timeout or something like that. Furthermore this is not always > reproducing. Maybe anyone from BE could clarify what could be happening? > Alexandre, do you know who could help us? No I don't. For all I can say now, .back()/objectWrapper issue might be unrelated. It seems like there might be a race condition with ConfigManager.requestAll(). I have no idea why back() triggers this objectWrapper issue, though.

I'm still trying to figure this out, but it seems that the mozSetMessageHandler() might have a play in this.

From my understanding, the app is registering a handler for 'sms-sent' (and others) when running in so-called standalone and application mode. So, if the app is in background, it has registered its handlers in 'application mode', and it's ready to serve. When a message is sent, the 'standalone' mode is triggered, but the handler that has been set in 'application mode' has already got a play in the ground. In the previous log, this is the message : "I/GeckoDump( 4553): (1372338868095-3) CC /index.html>/message_handler.html: SMS sent!", pay attention to the "/index.html>/message_handler.html" part ; this exposes that this handler has been registered as 'application mode'. While waiting for ConfigManager.requestAll() to process, the standalone mode is getting trigged, as the message "I/GeckoDump( 4553): (1372338882961-10) CC /message_handler.html: Installing handlers" tells us. This is messing up and the requestAll() callback never gets called, hence the SMS sent cannot be counted.

We were thinking the same. Check my opinion: I'm not reproducing but I have a theory. Asking Vivien to check if this makes sense: Cost Control registers the /message_handler.html which attends system messages. When a message is sent, system application delivers the message only to the handler declared in the Manifest. As the wndow manager open the handler in the same iframe than applications but only if the application is closed or in the background, both the Widget and the Application include the handler as an iframe to be able to attend system messages as well. While in background, if the device send a SMS, a system message is delivered to the iframe inside the Cost Control application in background but, at the same time, the window manager tries to change the location of the Cost Control application window to the message handler. I can not stop this but I trusted the system message was already handled before window manager replace the application. IMHO, here can be the race condition. But, system messages are guaranteed to be delivered so if it is not received by the application, it should be received by then handler. After reviewing the code I discovered two possible scenarios: 1. Window manager win the race and change the location of the iframe before the message was attended at all but the message handler is resolving as "nothing to do" and trying to going back without attending the message as well. Seeing the current status of the code, this could happen. 2. Cost Control application win the race condition, attend the message and sen the asynchronous call to increase the SMS counter but, in the middle of this operation, the location is changed by the window manager. I would bet for the first one. I could try to solve it, make a patch and let you apply and check ig this solves the problem. WDYT? Sorry for the long comment.

(In reply to Salvador de la Puente González [:salva] from comment #20) > We were thinking the same. Check my opinion: > > I'm not reproducing but I have a theory. Asking Vivien to check if this > makes sense: > > Cost Control registers the /message_handler.html which attends system > messages. When a message is sent, system application delivers the message > only to the handler declared in the Manifest. As the wndow manager open the > handler in the same iframe than applications but only if the application is > closed or in the background, both the Widget and the Application include the > handler as an iframe to be able to attend system messages as well. > > While in background, if the device send a SMS, a system message is delivered > to the iframe inside the Cost Control application in background but, at the > same time, the window manager tries to change the location of the Cost > Control application window to the message handler. > > I can not stop this but I trusted the system message was already handled > before window manager replace the application. IMHO, here can be the race > condition. But, system messages are guaranteed to be delivered so if it is > not received by the application, it should be received by then handler. > After reviewing the code I discovered two possible scenarios: > > 1. Window manager win the race and change the location of the iframe before > the message was attended at all but the message handler is resolving as > "nothing to do" and trying to going back without attending the message as > well. Seeing the current status of the code, this could happen. > > 2. Cost Control application win the race condition, attend the message and > sen the asynchronous call to increase the SMS counter but, in the middle of > this operation, the location is changed by the window manager. > > I would bet for the first one. I could try to solve it, make a patch and let > you apply and check ig this solves the problem. WDYT? > > Sorry for the long comment. I think your case 1 just described what I'm seeing. If you have an idea of patch, feel free, I'll try to apply it in the train or tonight !

After IRC chatting and solutions tested by Alexandre, the problem seems to be the second option. The message is attended but window_manager is changing the location before the increment takes place. There are two possible solutions: 1. Address the problem of handlers in the system by opening handlers in separated iframes without replacing the current application. 2. Solve bug 834334. Renominating bug 834334.

Is qawanted still needed on this bug? We cannot test this here with our cards, so adding need info on Isabel in case additional testing is needed.

Nope. Alex and me are in charge of this.

Waiting for solving bug 888926. Nothing is required here.

Verified fixed in unagi device with Gecko-bd579ea Gaia-680c72c from v1-train.

Marking fixed on v1-train per comment 26 and 12