965107 - [DSDS][MMS] Found twice MMS received by SIM 2 always stays in downloading status after data call switching.

Status: RESOLVED WORKSFORME

(Firefox OS Graveyard :: RIL, defect)

Description

[Enpei]

Attachment: buri_mms.txt

+++ This bug was found during Bug #961934 patch verification +++

I can't download some MMS of SIM 2 even they are just MMS with subject and text, not large files. You can check buri_mms.txt, a message with "Dhh" subject cannot be downloaded and keep in downloading status around 20:35. After reboot device(check buri_mmsafterreboot.txt), try to download both subject "GFDD" and "Dhh" messages, all just keep in downloading status. 

Then I sent some mms to SIM1 which switched data call to SIM 1. After messages were all downloaded, I sent another MMS with only subject "4" to SIM 2, confirmed switching data call to SIM 2, message was downloaded (20:35 of buri_mmsafterreboot.txt) yet the first 2 mms messages "GFDD" and "Dhh" still couldn't be downloaded.

* Build Number  
Fugu + bug 961934 patch
Gaia      e28eaba31b69f52b204076d9bbf2463b23cbb070
Gecko     6253dc2dfe846c59da4fd5bb5a694ac29d6ee2cf
BuildID   20140127172620
Version   29.0a1

* Reproduce Steps
1. Send a MMS to non-primary data SIM.
2. Once receive the message, press download button within it.
Repeat steps 1 to 2

* Expected Result
Data call will be switched to non-primary data SIM and start downloading.

* Actual Result
Data call can be switched, but messages are always in downloading status.

* Occurrence rate
about 2 messages out of 10 hit the problem.

Comment 1

[Enpei]

Next day I kept sending several mms(above 5) to SIM 2, all can be downloaded. And later both messages that were stuck in downloading status are downloaded one after another. 

I will monitor this bug on 1.3 after bug 961934 landed.

Comment 2

[Bevis Tseng[:bevis][:btseng](Exited)]

Hi Enpei,

I am sorry to say that mms related logs were not enabled in the attached log.
It will be difficult to know what really happened that causes the message kept in sending state. :(

Hence, I've update the HOWTO of enabling mms log in the following link:
https://intranet.mozilla.org/QA/B2G_Tips_and_Tricks#Enable_MMS_transaction_related_log

The other way to enable it via preference is mentioned here:
https://wiki.mozilla.org/B2G/QA/Tips_And_Tricks#Changing_preferences
All you need to do is add a new line to the prefs.js you pull out:
user_pref("mms.debugging.enabled", true);

After enabling it, you shall be able to see the log tagged with "MmsService".
Please help to capture the log with RIL/MMS enabled when you encountered this symptom again for further analysis.

Thanks,
Bevis

Comment 3

[Julien Wajsberg [:julienw]]

Wondering whether this can be fixed by bug 961938 where we wait for the SIM switch before actually request the download.

Comment 4

[Enpei]

Hi Bevis,

I've enabled mms service message first and reproduced the bug on Fugu. Can you help to check the log again?
Gaia      bb36b4164d3e51ca04b612e507e1178f80bf240d
Gecko     4227240a4d3e1e418ced160c2a48cb454d7b5645
BuildID   20140204104742
Version   28.0

* I sent MMS to SIM 2 at 16:46, I confirmed data switch then and SIM 2 data call was established but the message was not downloaded.
* SIM 1 recieved MMS at 16:54, then I switched data call to SIM 1 and got message downloaded.
* I pressed SIM 2 MMS downloaded button again to do data call switch, the message I first got at 16:46 finally downloaded at 16:57.

Comment 5

[Enpei]

Attachment: log with MMS enabled.

Comment 6

[Bevis Tseng[:bevis][:btseng](Exited)]

Update finding so far:
1. The data was switched to SIM 2 successfully after user confirmed.
2. However, when trying to download the MMS message, we got strange error in the response of HTTP GET from MMSC:
   "status = 403, statusText = Invalid MSISDN number received."
3. At 2nd trial at 16:57 with same flow. The MMS message was retrieved successfully.

Still need more testing/logging to figure out whether this is network issue or not.
--
[Failed at 1st Trial]
02-05 16:45:00.911 I/Gecko   (  107): -*- RadioInterface[1]: handleSmsReceived: {"SMSC":"[phone]","mti":0,"udhi":64,"sender":"886911520045","recipient":null,"pid":0,"epid":0,"dcs":4,"mwi":null,"replace":false,"header":{"length":11,"langIndex":0,"langShiftIndex":0,"destinationPort":2948,"originatorPort":9200,"segmentRef":8,"segmentMaxSeq":2,"segmentSeq":1},"body":null,"timestamp":1391589893000,"status":null,"scts":null,"dt":null,"encoding":4,"messageClass":"normal","segmentMaxSeq":2,"receivedSegments":2,"segments":[null,{"0":100,"1":6,"2":49,"3":97,"4":112,"5":112,"6":108,"7":105,"8":99,"9":97,"10":116,"11":105,"12":111,"13":110,"14":47,"15":118,"16":110,"17":100,"18":46,"19":119,"20":97,"21":112,"22":46,"23":109,"24":109,"25":115,"26":45,"27":109,"28":101,"29":115,"30":115,"31":97,"32":103,"33":101,"34":0,"35":177,"36":49,"37":48,"38":46,"39":56,"40":46,"41":49,"42":51,"43":48,"44":46,"45":49,"46":57,"47":0,"48":175,"49":132,"50":180,"51":129,"52":140,"53":130,"54":152,"55":66,"56":
02-05 16:45:00.981 I/Gecko   (  107): -@- MmsService: Running protocol version: 1.1
02-05 16:45:00.991 I/Gecko   (  107): -@- MmsService: receiveWapPush: msg = {"headers":{"x-mms-message-type":130,"x-mms-transaction-id":"BfrxUsYSGwL1XAAAkDs07wfiAAAAAAAA","x-mms-mms-version":16,"from":{"address":"1","type":"alphanum"},"subject":"Gfffg","x-mms-message-class":"personal","x-mms-message-size":584,"x-mms-expiry":90000,"x-mms-content-location":{"uri":"http://mms.emome.net:8002/BfrxUsYSGwL1XAAAkDs07wfiAAAAAAAA"}},"type":130}
02-05 16:45:01.001 I/Gecko   (  107): -@- MmsService: Switch to 'manual' mode to download MMS for non-active SIM: serviceId = 1 doesn't equal to mmsDefaultServiceId = 0
02-05 16:45:07.371 I/Gecko   (  107): -@- MmsService: Running protocol version: 1.1
02-05 16:45:07.371 I/Gecko   (  107): -@- MmsService: Retrieving message with ID 3
02-05 16:45:07.381 I/Gecko   (  107): -@- MmsService: RIL service is not active to retrieve MMS.
02-05 16:45:46.811 I/Gecko   (  107): -@- MmsService: Retrieving message with ID 3
02-05 16:45:47.111 I/Gecko   (  107): -@- MmsService: acquire: buffer the MMS request and setup the MMS data call.
02-05 16:45:47.111 I/Gecko   (  107): -*- RILNetworkInterface[1:2]: Going to set up data connection with APN emome
02-05 16:45:47.121 I/Gecko   (  107): RIL Worker[1]: Received chrome message {"radioTech":2,"apn":"emome","chappap":3,"pdptype":"IP","rilMessageToken":12,"rilMessageType":"setupDataCall"}
02-05 16:45:47.121 I/Gecko   (  107): RIL Worker[1]: New outgoing parcel of type 27
02-05 16:45:47.121 I/Gecko   (  107): RIL Worker[1]: Outgoing parcel: 0,0,0,72,27,0,0,0,112,0,0,0,7,0,0,0,1,0,0,0,52,0,0,0,1,0,0,0,48,0,0,0,5,0,0,0,101,0,109,0,111,0,109,0,101,0,0,0,255,255,255,255,255,255,255,255,1,0,0,0,51,0,0,0,2,0,0,0,73,0,80,0,0,0,0,0
02-05 16:45:53.061 I/Gecko   (  107): RIL Worker[1]: Solicited response for request type 27, token 112, error 0
02-05 16:45:53.061 I/Gecko   (  107): RIL Worker[1]: Handling parcel as REQUEST_SETUP_DATA_CALL
02-05 16:45:53.061 I/Gecko   (  107): -*- RILNetworkInterface[1:2]: Data call ID: 2, interface name: veth1, APN name: emome
02-05 16:45:53.071 D/DHCP    (  107): getaddrinfo failed: invalid address
02-05 16:45:53.081 D/NetUtils(  107): failed to remove default route for veth1: No such process
02-05 16:45:53.781 I/Gecko   (  107): -@- MmsService: Got the MMS network connected! Resend the buffered MMS requests: number: 1
02-05 16:45:53.781 I/Gecko   (  107): -@- MmsService: sendRequest: register proxy filter to http://mms.emome.net:8002/BfrxUsYSGwL1XAAAkDs07wfiAAAAAAAA
02-05 16:45:53.791 I/Gecko   (  107): -@- MmsService: applyFilter: MMSC/Content Location is matched with: {"uri":"{\"spec\":\"http://mms.emome.net:8002/BfrxUsYSGwL1XAAAkDs07wfiAAAAAAAA\",\"prePath\":\"http://mms.emome.net:8002\",\"scheme\":\"http\",\"userPass\":\"\",\"username\":\"\",\"password\":\"\",\"hostPort\":\"mms.emome.net:8002\",\"host\":\"mms.emome.net\",\"port\":8002,\"path\":\"/BfrxUsYSGwL1XAAAkDs07wfiAAAAAAAA\",\"asciiSpec\":\"http://mms.emome.net:8002/BfrxUsYSGwL1XAAAkDs07wfiAAAAAAAA\",\"asciiHost\":\"mms.emome.net\",\"originCharset\":\"UTF-8\",\"ref\":\"\",\"specIgnoringRef\":\"http://mms.emome.net:8002/BfrxUsYSGwL1XAAAkDs07wfiAAAAAAAA\",\"hasRef\":false}","mmsProxyInfo":{"host":"10.1.1.1","port":8080,"type":"http","flags":1,"resolveFlags":0,"failoverTimeout":1800,"failoverProxy":null,"TRANSPARENT_PROXY_RESOLVES_HOST":1}}
02-05 16:46:14.901 I/Gecko   (  107): -@- MmsService: xhr done, but status = 403, statusText = Invalid MSISDN number received.
02-05 16:46:14.901 I/Gecko   (  107): -@- MmsService: Fail to retrieve. Will retry after: 60000


--
[Success at 2nd Trial]
02-05 16:56:48.971 I/Gecko   (  107): -@- MmsService: Retrieving message with ID 3
02-05 16:56:49.261 I/Gecko   (  107): -@- MmsService: acquire: buffer the MMS request and setup the MMS data call.
02-05 16:56:49.261 I/Gecko   (  107): -*- RILNetworkInterface[1:2]: Going to set up data connection with APN emome
02-05 16:56:58.121 I/Gecko   (  107): -*- RILNetworkInterface[1:2]: Data call ID: 2, interface name: veth1, APN name: emome
02-05 16:56:58.141 I/Gecko   (  107): -@- MmsService: Got the MMS network connected! Resend the buffered MMS requests: number: 1
02-05 16:56:58.151 I/Gecko   (  107): -@- MmsService: sendRequest: register proxy filter to http://mms.emome.net:8002/BfrxUsYSGwL1XAAAkDs07wfiAAAAAAAA
02-05 16:56:58.161 I/Gecko   (  107): -@- MmsService: getProxyInfo: {"host":"10.1.1.1","port":8080,"type":"http","flags":1,"resolveFlags":0,"failoverTimeout":1800,"failoverProxy":null,"TRANSPARENT_PROXY_RESOLVES_HOST":1}
02-05 16:56:58.161 I/Gecko   (  107): -@- MmsService: applyFilter: MMSC/Content Location is matched with: {"uri":"{\"spec\":\"http://mms.emome.net:8002/BfrxUsYSGwL1XAAAkDs07wfiAAAAAAAA\",\"prePath\":\"http://mms.emome.net:8002\",\"scheme\":\"http\",\"userPass\":\"\",\"username\":\"\",\"password\":\"\",\"hostPort\":\"mms.emome.net:8002\",\"host\":\"mms.emome.net\",\"port\":8002,\"path\":\"/BfrxUsYSGwL1XAAAkDs07wfiAAAAAAAA\",\"asciiSpec\":\"http://mms.emome.net:8002/BfrxUsYSGwL1XAAAkDs07wfiAAAAAAAA\",\"asciiHost\":\"mms.emome.net\",\"originCharset\":\"UTF-8\",\"ref\":\"\",\"specIgnoringRef\":\"http://mms.emome.net:8002/BfrxUsYSGwL1XAAAkDs07wfiAAAAAAAA\",\"hasRef\":false}","mmsProxyInfo":{"host":"10.1.1.1","port":8080,"type":"http","flags":1,"resolveFlags":0,"failoverTimeout":1800,"failoverProxy":null,"TRANSPARENT_PROXY_RESOLVES_HOST":1}}
02-05 16:57:00.241 I/Gecko   (  107): -@- MmsService: xhr success, response headers: Content-Encoding: gzip
02-05 16:57:00.241 I/Gecko   (  107): Content-Length: 385
02-05 16:57:00.241 I/Gecko   (  107): Content-Type: application/vnd.wap.mms-message
02-05 16:57:00.251 I/Gecko   (  107): -@- MmsService: retrievedMsg = {"headers":{"x-mms-message-type":132,"x-mms-transaction-id":"BfrxUsYSGwL1XAAAkDs07wfiAAAAAAAA","x-mms-mms-version":17,"from":{"address":"[phone]","type":"PLMN"},"to":{"address":"[phone]","type":"PLMN"},"subject":"Gfffg","x-mms-message-class":"personal","x-mms-priority":129,"x-mms-read-report":true,"message-id":"[phone]_05gver##hracowt812qaa14@w.","date":"2014-02-05T08:44:53.000Z","x-mms-delivery-report":false,"content-type":{"media":"application/vnd.wap.multipart.related","params":{"type":"application/smil","start":"<smil>"}}},"type":132,"parts":[{"index":0,"headers":{"content-type":{"media":"application/smil","params":{"name":"smil.xml","charset":{"charset":"utf-8"}}},"content-length":324,"content-location":"smil.xml","content-id":"<smil>"},"content":"<smil><head><layout><root-layout width=\"320px\" height=\"480px\"/><region id=\"Image\" left=\"0px\" top=\"0px\" width=\"320px\" height=\"320px\" fit=\"
02-05 16:57:00.361 I/Gecko   (  107): -@- MmsService: Broadcasting the MMS system message: sms-received

Comment 7

[Julien Wajsberg [:julienw]]

Bevis, assigning to you since you're the best to handle this successfully ;)

Comment 8

[Enpei]

With new log enabled and reproduce on latest Fugu for 30 times, I cannot reproduce the bug. Close it first.
Gaia      a43904d9646109b48836d62f7aa51e499fbf4b2e
Gecko     0b4f0a800c967e94edf23180d19f42e3fbbb2a9d
BuildID   20140219124438
Version   28.0