Titanium JIRA Archive
Titanium SDK/CLI (TIMOB)

[TIMOB-6016] iOS: Http request sent twice on ios 5

GitHub Issuen/a
TypeBug
PriorityHigh
StatusClosed
ResolutionFixed
Resolution Date2012-04-02T11:25:59.000+0000
Affected Version/sRelease 1.7.3
Fix Version/sRelease 1.8.0, Release 1.7.6
ComponentsiOS
Labelsdr-list, module_network
ReporterRyan DuVal
AssigneeStephen Tramer
Created2011-11-04T12:57:14.000+0000
Updated2014-06-19T12:42:43.000+0000

Description

With reference to [http request sent twice on ios 5 and mobile sdk 1.7.3](http://developer.appcelerator.com/question/127415/http-request-sent-twice-on-ios-5-and-mobile-sdk-173), we are seeing this as well. Below is an app.js that queries our development server which you can use to reproduce the issue. This works correctly on on iPad 2 running 4.3.5 and iPad 1 running 4.3.5, but duplicate requests are generated on iOS5. See attached screenshot.
var xhr = Ti.Network.createHTTPClient();
xhr.setTimeout(10000);

var win = Ti.UI.createWindow({
    backgroundColor: "#fff",
    height: "100%",
    width: "100%"
}),
top = Ti.UI.createTextArea({
    borderWidth: 1,
    left: 0,
    top: 0,
    height: 300,
    width: "100%",
    value: ""
}),
bottom = Ti.UI.createTextArea({
    borderWidth: 1,
    left: 0,
    bottom: 0,
    height: 300,
    width: "100%",
    value: ""
}),
btn = Ti.UI.createButton({
    height: 100,
    width: 300,
    right: 20,
    title: "make call"
}),
stats = Ti.UI.createLabel({
    left: 20,
    height: 200,
    width: "auto",
    text: ""
}),
data = {
    clicked: 0,
    success: 0,
    dupe: 0,
    ratio: 0,
    events: 0,
    calls: 0
};

win.add(top);
win.add(stats);
win.add(btn);
win.add(bottom);
win.open();

function callback(data) {    
    var msg;
    if (data.success) {
        msg = "Success";
        record("success", true);
    } else if (!data.success && data.error && data.error == "duplicate request") {
        msg = "Error: duplicate request";
        record("dupe", true);
    } else
        msg = "Error: Unknown\ndata: " + JSON.stringify(data);
        
    top.value += data.auth + ": " + msg + "\n";
}
Ti.App.addEventListener("events/detail", callback);
    
btn.addEventListener("click", function(e) {
    bottom.value += "call()\n";
    record("events");
    record("clicked");
    
    call("POST", "events/detail", {
        eventId: 1,
        longitude: -105.24097442626953,
        latitude: 39.97970199584961,
        appId: 1
    });
});

function call(method, uri, data) {
    Ti.API.info("Network ready state: " + xhr.readyState);

    var base = "http://dev.mobilestudying.com:8080";
    var _uri = "/examjam-1.0/" + uri;
    var timestamp = new Date().getTime();
    var contentType = "application/x-www-form-urlencoded";
    var secret = "88627d4c72a611e09f3efb27cf9a9621";
    var hash = [method, _uri.split("?", 1)[0], contentType, timestamp, secret];
    var auth = Ti.Utils.md5HexDigest(hash.join("\n"));
    
    xhr.onload = function() {
        var data = this.responseText ? JSON.parse(this.responseText) : null;
        data.auth = auth;
        //Ti.API.info("data: " + JSON.stringify(data));
        Ti.App.fireEvent(uri.split("?")[0], data);
    };
    xhr.onerror = function(){
        Ti.API.debug("ERROR: Call failed to '" + uri + "': " + this.responseText);
        Ti.API.debug("ERROR: data: " + JSON.stringify(this.responseData));
        Ti.API.debug("ERROR: status code: " + this.status);
    };

    xhr.open(method, base + _uri);
    xhr.setRequestHeader("Content-Type", contentType);
    xhr.setRequestHeader("X-ExamJam-APIKey", "b95a0551553ae446fa39b95f8ffbac26");
    xhr.setRequestHeader("Date", timestamp);
    xhr.setRequestHeader("Authorization", auth);
   
    bottom.value += "send()\n"; 
    record("calls");
    
    xhr.send(data);
}
function record(value, display) {
    data[value]++;
    
    if (display) {
        stats.text = "Clicked (events/calls): " + data.clicked + " (" + data.events + "/" + data.calls + ")";
        stats.text += "\nSuccess: " + data.success;
        stats.text += "\nDupe (ratio): " + data.dupe + " (" + ((data.dupe / data.success) * 100) + "%)";
    }
}

Attachments

FileDateSize
app_screenshot.png2011-11-05T10:11:20.000+0000126872
app.js2011-11-05T10:11:20.000+00003244
photo.PNG2011-11-04T12:57:14.000+0000185874

Comments

  1. Ingo Muschenetz 2011-11-04

    Paul, moving this into Titanium Community as this is the best place to triage this. Can you please take a look at this ASAP?
  2. Ryan DuVal 2011-11-04

    I should add that this doesn't happen every single request, but if you click the button 5-10 times, you should see a few. Can also confirm this happens in 1.7.5 as well. Just had my manager run it (he has iOS 5) and he reported that "It started off with 5 straight Success actions, but now every other is a duplicate". Finally, we created a native iOS app with XCode that does exactly the same thing as the provided app and it didn't occur.
  3. Tony Lukasavage 2011-11-04

    I reproduced this on an iPod Touch running iOS5. Can you determine if the whole call event listener is called twice, or just the HTTP call? This can help you determine if its a flaw with HTTPClient or with adding and removing Ti.App events. I think I may have spotted a potential error in the logic. Anytime you click the button, you add a Ti.App listener. The only time you clear if, however, is on a successful onload. If there is an error with your HTTP call, or anything that prevents the onload from firing, you'll end up with multiple instances of your Ti.App listener, resulting in duplicate calls. Try to change up your logic to either tighten up this flow, or move the Ti.App.addEventListener() call outside of the button click altogether, only adding it once.
  4. Paul Dowsett 2011-11-05

    Hi Ryan, thank you for bringing this bug to our attention. I have moved your issue to the TIMOB project now. Please note the changes that were necessary in order to make this possible, which are described in [How to Submit a Bug Report](http://wiki.appcelerator.org/display/guides/How+to+Submit+a+Bug+Report). This will avoid any delays for your tickets in future. In particular, note the [JIRA Ticket Checklist](http://wiki.appcelerator.org/display/guides/How+to+Submit+a+Bug+Report#HowtoSubmitaBugReport-JIRATicketChecklist). Please see [Projects Overview](http://wiki.appcelerator.org/display/guides/How+to+Submit+a+Bug+Report#HowtoSubmitaBugReport-ProjectsOverview) for the reason why tickets should be created in the TC project. Many thanks
  5. Stephen Tramer 2011-11-05

    This ticket is a duplicate of an issue we are currently in the process of resolving internally. Any commit which solves this other issue will be tagged for this one as well, and we will close it at the appropriate time. We will ensure validation against your provided test as well as the internal one.
  6. Stephen Tramer 2011-11-05

    I am continually receiving errors of this type from the test:
       f17d2cfcfd4342ff7dc6bcda788df857: Error: Unknown
       data: {"type":"events/detail","success":false,"error":"invalid call","auth":"f17d2cfcfd4342ff7dc6bcda788df857"}
       
    This is occurring on both iOS 4.3 and iOS 5.0.
  7. Stephen Tramer 2011-11-05

    As requested, the full request being sent over the wire that's generating this error:
       POST /examjam-1.0/events/detail HTTP/1.1
       Host: dev.mobilestudying.com:8080
       User-Agent: Appcelerator Titanium/0.0.0 (iPad Simulator/5.0; iPhone OS; en_US;)
       Content-Length: 73
       Accept-Encoding: gzip
       X-ExamJam-APIKey: b95a0551553ae446fa39b95f8ffbac26
       X-Requested-With: XMLHttpRequest
       Content-Type: application/x-www-form-urlencoded; charset=utf-8
       Authorization: 5fd9be99fd194e2879610b17b1d2b90a
       Date: 1320529896304
       Connection: keep-alive
       Pragma: no-cache
       Cache-Control: no-cache
       
       eventId=1&appId=1&longitude=-105.2409744262695&latitude=39.97970199584961
       
  8. Stephen Tramer 2011-11-05

    NOTE: This failure occurs ONLY in 1.8.0. The difference between the headers appears to be the following:
       Content-Type: application/x-www-form-urlencoded
       vs.
       Content-Type: application/x-www-form-urlencoded; charset=utf-8
       
    The server merely needs to be modified to accept the charset=utf-8 information.
  9. Ryan DuVal 2011-11-05

    Fair enough, we can modify our authorization hash to include the charset. You have enough to go off of now?
  10. Paul Dowsett 2011-11-05

    Hi Stephen That was thoughtful of you, about the telephone no. Thank you for doing that! :) We are getting a number of similar reports of problems between xhr and iOS5. Would you mind looking at the following, and letting me know whether existing tickets cover the problems they describe, or whether we need fresh tickets? http://developer.appcelerator.com/question/127817/getting-an-401-error-on-xhr http://developer.appcelerator.com/question/127816/xhr-not-working-in-ios-5-sdk
  11. Stephen Tramer 2011-11-05

    Ryan - No, I don't have to leave yet. I'll be available for an additional 2-3 hours, working on this problem, and back in the office early tomorrow morning. For now I've been able to disable the charset information coming through in the Content-Type so that I can continue to test, but your server WILL need to be able to process this information as part of POST for when you upgrade to 1.8 (and this will be a recommended upgrade for iOS). ---- Paul - Without actual reporting information by those users on those tickets, I can't confirm if they're the same problem. We can't resolve all HTTP issues before 1.8 freeze (scheduled for next week) but revising HTTP support is fast becoming an issue which will be addressed very early in the 1.9 development cycle.
  12. Ryan DuVal 2011-11-05

    Heh. I was just confirming that you have everything you need to dig into it. Appreciate the weekend support!
  13. Harjit Singh 2011-11-05

    Stephen - Please let me know what kind of information do you need to fix this.
  14. Stephen Tramer 2011-11-05

    Harjit - We've been able to resolve this without any additional information on your part. I'm currently going through, testing how many issues this resolves. I've confirmed that it is a bug in iOS 5, regarding an HTTP persistence feature that we take advantage of; turning off this feature is all that's needed to fix it. A pull request will be submitted shortly for us to process internally.
  15. Ryan DuVal 2011-11-05

    Great. Stephen, what is the timeline on the sdk (1.7.3, 1.7.5) being updated?
  16. Stephen Tramer 2011-11-05

    Ryan - A backport to 1.7.x will need to be discussed internally, but given that this is a critical issue which affects iOS 5, that is likely. The fix should be internally vetted by the end of day (5PM PST) tomorrow.
  17. Ryan DuVal 2011-11-05

    Ok, just keep me in the loop. Will this also result in a unit test being added? How extensive is Appcelerator testing, by the way?
  18. Harjit Singh 2011-11-05

    Stephen- That's really great. Please let me know when it will be available for download ?
  19. Stephen Tramer 2011-11-05

    Harjit - Please watch this ticket. It will be marked 'resolved' when the pull request is accepted, and 'closed' once QE has verified the fix in the appropriate release. You may also download CI builds from our build server at any time: http://builds.appcelerator.com.s3.amazonaws.com/index.html Fixes usually appear in CI ~15-20 minutes after they are accepted and merged by pull request. You may be required to start using master (1.8.0 candidate) to pick up this fix.
  20. Reggie Seagraves 2011-11-06

    Note: This fix can be merged into 1_7_X easily if necessary.
  21. Don Thorp 2011-11-06

    Let's go ahead and get this in 1.7.6
  22. Ryan DuVal 2011-11-07

    Thanks for getting to the bottom of this guys. Do we have an ETA on the 1.7.6 release? We're using a custom sdk now internally.
  23. Stephen Tramer 2011-11-08

    Ryan - There is unlikely to be an official 1.7.6 release at any point, but I've added this change to our 1_7_X branch, which means you can pick it up from continuous integration within a few minutes.
  24. Harjit Singh 2011-11-10

    I just got 1.7.6 and 1.8.0 after this fix. The 1.8.0 version is filename: mobilesdk-1.8.0.v20111109103101-osx.zip and 1.7.6 is mobilesdk-1.7.6.v20111109161100-osx.zip http Basic auth doesn't work on 4.3 and 5.0. I downgraded to 1.7.5 and 4.3 works. 5.0 doesn't work.... Here is the code for which we are using for authentication . Let me know if you need anything else for this to make it debug function setPassportCredentials(data) { if(data.networkOnline == false) { doOfflineMode(data); return; } var xhr = Titanium.Network.createHTTPClient(); Ti.API.info("Server:" + pt.app.CurrentServer()); xhr.open("POST", pt.app.CurrentServer() + "/tabulae?r=" + Date.now()); // set credentials, var authstr = 'Basic ' + Titanium.Utils.base64encode(data.username + ':' + data.password); Ti.API.info("authstr:" + authstr); xhr.setRequestHeader('Authorization', authstr); xhr.setRequestHeader("Content-Type", "text/html; charset=utf-8"); xhr.onreadystatechange = function(aEvt) { Ti.API.info("onreadystatechange login status " + xhr.status); for(var x in xhr.getResponseHeaders()) { Ti.API.info("onreadystatechange cookie " + xhr.getResponseHeaders()[x]); } } xhr.onload = function() { Ti.API.info("login status " + xhr.status); //Ti.API.info("login response " + xhr.responseText); Ti.API.info("cookie " + xhr.getResponseHeader('Set-Cookie')); // this is a hack -- for some reason for the FIRST REQUEST ONLY // we get a 404 regardless of wether login is successful. if(xhr.status == '404' && !data.retry) { Ti.API.info('Retrying once because of 404'); data.retry = true; setPassportCredentials(data); return; } if(xhr.status == '302') { Ti.API.info('Retrying once because of 302'); return; } if(xhr.status == '401' && !data.retry) { alert("Retry"); Ti.API.info('Retrying once because of 404'); data.retry = true; setPassportCredentials(data); return; } // Save values to prefs Ti.App.Properties.setString('USERNAME', data.username); Ti.App.Properties.setString('PASSWORD', data.password); //var secure_url = "https://"+encodeURIComponent(data.username+":"+data.password)+"@"+pt.app.CurrentServer().substring(8); var secure_url = "https://" + encodeURIComponent(data.username) + ":" + encodeURIComponent(data.password) + "@" + pt.app.CurrentServer().substring(8); Ti.App.Properties.setString('SECURE_URL', secure_url); Ti.App.Properties.setString('AUTH_STRING', authstr); //Ti.App.Properties.setString('COOKIE_STRING', xhr.getResponseHeader('Set-Cookie')); Ti.App.fireEvent('app:versionCheck', { data : data }); Ti.App.fireEvent('app:registerdevice', { data : data }); if(!data.keepCurrentWindow) { pt.app.USER_MODEL.queryUserInformation(data.username, function(userInfo, xhr) { pt.app.USER_MODEL.setUserPropertyFromObject(userInfo); var needsPasswordReset = userInfo.needsPasswordReset; Ti.API.info("queryUserInformation callback needsPasswordReset [" + needsPasswordReset + "]"); Ti.API.debug("queryUserInformation: success " + pt.app.USER_MODEL.getUserFromProperty()); // only on success, get the picture Ti.App.fireEvent('app:queryUserInformation.successful', { data : xhr.responseText, "cookie" : Ti.App.Properties.getString('COOKIE_STRING') }); // only on success, get the picture Ti.App.fireEvent('app:login.successful', { data : data.username, mode : 'ONLINE', needsPasswordReset : needsPasswordReset, "cookie" : Ti.App.Properties.getString('COOKIE_STRING') }); }); } xhr.abort(); } xhr.onerror = function(e) { Ti.API.debug("Location:" + xhr.getResponseHeader("Location")); Ti.API.debug("Referrer:" + xhr.getResponseHeader("Referer")); Ti.App.fireEvent("app:http.error", { action : 'login', status : xhr.status, error : e.error }); xhr.abort(); }; Ti.API.info(String.format("username [%s] password [%s]", data.username, data.password)); // clear all cookies xhr.setRequestHeader("Cookie", "PassportID="); xhr.setRequestHeader("Cookie", "PassportKey="); xhr.setRequestHeader("JSESSIONID", "PassportKey="); xhr.send(); }
  25. Michael Pettiford 2011-12-07

    Tested on Ti Studio 1.0.7.201112061404 
Ti Mob SDK 1.8.0.1.v20111207091653 
OSX Lion iPhone 4S OS 5.0.1, iPad 2 OS 5.0 Expected behavior of no duplicate requests is shown
  26. Harjit Singh 2011-12-08

    Tested with iOS 4.3 and iOs 5 and I can't login. I don't think it fixed the issue which I'm having.
  27. Stephen Tramer 2011-12-08

    If you're still experiencing failures you may need to downgrade your TLS version. This was issue TIMOB-6311, which includes documentation changes.
  28. Stephen Tramer 2011-12-20

    Harjit - You may also need to upgrade your server to handle the "charset" content-type information, as mentioned above.
  29. Dustin Hyde 2012-01-06

    Added label qe-port. Test sample does not work due to server problems.
  30. Michael Pettiford 2012-04-02

    Reopening to add/remove labels

JSON Source