Google Docs upload fails; logs blame expired cookie

[GoogleCodeExporter]

What steps will reproduce the problem?
1.Start a track
2.Start Walking
3.Finish Walking
4.Stop track
5.Upload to My Maps and Docs at the same time.

What is the expected output? What do you see instead?

I keep on getting errors when tring to upload to my maps and docs at the same 
time, it says it was uploaded to my maps but failed uploading to docs. However 
if I upload to docs on its own, i do not get any errors. 

What version of MyTracks are you using? On what version of Android? On what
phone?
MyTracks version: 16
Android version: 2.1
Phone: HTC Wildfire (UK0

Please provide any additional information here:
N/A

Original issue reported on code.google.com by jonathan...@gmail.com on 26 Aug 2010 at 3:14

[GoogleCodeExporter]

I have the same problem but inverted :

I can upload to google docs, but not to My Maps.
I created previously a map on the website, but MyTracks cannot either create a 
new map neither use an existing one.

Original comment by chric...@gmail.com on 9 Sep 2010 at 12:32

[GoogleCodeExporter]

+1 on this problem, present since many versions ago. 

Workaround: 
1. only upload to Google Docs. (Will fail on first attempt).  Do it a second 
time and it will go through. 
2. now upload only to Google Maps. 

Original comment by stewart....@gmail.com on 21 Sep 2010 at 6:16

[GoogleCodeExporter]

Original comment by simmonmt@google.com on 25 Oct 2010 at 8:56

[GoogleCodeExporter]

I've attached adb logcat for a typical failure.

Distilled:  SendToDocs.getSpreadsheetId tried to get the spreadsheet ID using 
runQuery.  It got a Token Expired error from the server.  This is a case that 
the code's prepared to handle (see the retryOnFailure stuff in GDataWrapper).  
It fails the retry in invalidateAndRefresh.  The whenFinished callback gets an 
IllegalStateException because the connection pool has shut down.

Original comment by simmonmt@google.com on 15 Nov 2010 at 7:10

• Changed title: Google Docs upload fails; logs blame expired cookie

Attachments:

• mytracks.log

[GoogleCodeExporter]

I've managed to create a reproducible case for this bug.  I modified 
GDataWrapper.runOne as follows:

private boolean runOne(...) {
  try {
    // get auth token

    if (count == 0) {
      count++;
      throw new AuthenticationException("mts auth fail fake");
    }

    // existing stuff
  }
}

That is, the first time through runOne, we fail with an authentication 
exception, just like we would if the token had actually expired.  This throws 
us into the GDataWrapper retry logic, which ends up bombing out with Connection 
pool shut down.

Now to figure out why that's happening.  Is someone calling close on the 
GDataWrapper's GDataClient before the retry finishes?

Original comment by simmonmt@google.com on 15 Nov 2010 at 10:18

[GoogleCodeExporter]

In a nutshell, the problem is this:  Attempts to invalidate and refresh expired 
auth tokens are happening asynchronously to the retried requests.  The retried 
requests invariably beat the refresh, and fail.  Your second attempt to upload 
the doc, on the other hand, usually happens after the refresh eventually 
succeeds.  Complicating things, uploading to a Google Doc requires access to 
two GData services, thus allowing this refresh-retry-fail cycle to happen twice.

Long version:

If a GData call fails with an authentication failure, we're supposed to retry 
the request after invalidate and refresh the auth token.  (See the 
AccountManager docs; search for invalidateAuthToken).  This complicates the 
flow a bit.

The current implementations of SendToDocs and GDataWrapper attempt to hide the 
need to invalidate and retry from the user.  SendToDocs uses 
GDataWrapper.runQuery for individual calls.  The retry logic is hidden in 
runQuery.  The idea is that runQuery will attempt the call, and will then 
invalidate, refresh, and retry the call if necessary.  SendToDocs is blissfully 
unaware of the need to retry.

Complicating things somewhat, the code which does the retry runs 
asynchronously.  That is, you call AuthManager.invalidateAndRefresh with a 
Runnable, and it executes that Runnable when the token has been invalidated and 
refreshed (logged in).  The current code works like this:

  SendToDocs.uploadToDocs() {
    ...
    if (!getSpreadsheetId(wrapper)) {
      // it failed once, so try it again
      if (!getSpreadsheetId(wrapper)) {
        return failure;
      }
    }
    ...
  }

  SendToDocs.getSpreadsheetId(GDataWrapper wrapper) {
    wrapper.runQuery(new QueryFunction() {
      public void query(...) {
        // process the response
      }
    });
  }

  GDataWrapper.runQuery(QueryFunction function) {
    function.run();
    if (success) return true;

    if (auth failure) {
      Runnable whenFinished = new Runnable() {
        runQuery(function);
      }

      auth.invalidateAndRefresh(whenFinished);
    }

    return false;
  }

In the success case, getSpreadsheetId calls runQuery, which runs the function.  
The function succeeds and returns true.  runQuery immediately returns, as does 
getSpreadsheetId.

In the retry case, here's what's supposed to happen:
  1. getSpreadsheetId calls runQuery, which runs the function.
  2. The function fails with an authentication error.
  3. We invalidate the auth token and refresh it.
  4. We retry the function.  It succeeds.
  5. We return true to getSpreadsheetId.

Unfortunately, that's not the way the above code works.   We want step 3 above 
to be synchronous, but the current implementation does it asynchronously.  The 
code flow actually looks like the following.  The first three steps are largely 
the same.

   1. getSpreadsheetId calls runQuery, which runs the function
   2. The function fails with an authentication error
   3. We schedule the auth token invalidation and refresh.

Now, things change.  We have two separate threads of execution.  We're going to 
show the broken case below.

       Thread 1                               Thread 2
  auth.invalidateAndRefresh                     |
  schedules the invalidation and refresh
  and returns to runQuery                       |

  runQuery returns false to                     |
  getSpreadsheetId
                                                |
  getSpreadsheetId returns false to
  uploadToDocs                                  |

  uploadToDocs attempts to retry the            |
  spreadsheet ID fetch by calling 
  getSpreadsheetId again                        |

  the dance begins again, and again we fail     |
  to get the ID, since the token isn't
  valid yet.  We return false back up the       |
  chain, possibly scheduling a second
  invalidation and refresh in the process.      |
  We're going to ignore the second
  invalidation and refresh for the purposes     |
  of this description                           V

                                              The invalidation finally 
                                              succeeds.

                                              The refresh (login) succeeds.

As shown above, the asynchronous invalidation and refresh doesn't complete 
until after our two attempts to get the spreadsheet ID have failed.  After 
those two failures, uploadToDocs gives up, and the user gets a dialog box 
telling them the upload has failed.  The problem is a pain in the neck to 
diagnose, and is even more annoying to the user, because the spreadsheet ID 
fetch works the next time they try it, since the auth token is no longer 
invalid.

The fix is to make the auth token invalidation and refresh happen 
synchronously.  We'll make runQuery look something like this:

  GDataWrapper.runQuery(QueryFunction function) {
    for (int i = 0; i < 2; i++) {
      function.run();
      if (success) return true;

      if (!auth failure) return false;

      // auth failure
      FutureTask whenFinished = new FutureTask();
      auth.invalidateAndRefresh(whenFinished);
      whenFinished.get();

      // we've invalidated and refreshed, so we're ready to
      // run the function again.
    }

    return false;  // both retries failed
  }

We may also want to consider moving the auth failure invalidate/refresh/retry 
logic up into uploadToDocs.  The advantage of doing that is that the subtleties 
are exposed to the reader.  The disadvantage is that anyone using GDataWrapper 
has to reimplement the auth failure retry logic.  It may also complicate the 
flow, depending on how we implement it (i.e. whether it's one function on a 
main thread, vs a zillion functions which schedule themselves in turn).

Original comment by simmonmt@google.com on 16 Nov 2010 at 2:27

• Changed state: Started

[GoogleCodeExporter]

Change in simmonmt-137.  The three most recent deltas.

Original comment by simmonmt@google.com on 16 Nov 2010 at 2:54

• Changed state: UnderReview

[GoogleCodeExporter]

This change actually looks really nice.  I can find almost nothing to object. 
My question would do we include this in the current release or leave the 
current buggy code in the latest release.

Original comment by sandordo...@google.com on 16 Nov 2010 at 5:20

[GoogleCodeExporter]

Reviewing now.

Original comment by rdama...@google.com on 16 Nov 2010 at 5:27

[GoogleCodeExporter]

Issue 156 has been merged into this issue.

Original comment by simmonmt@google.com on 16 Nov 2010 at 4:44

[GoogleCodeExporter]

Thanks :)

Original comment by rdama...@google.com on 19 Nov 2010 at 1:05

• Changed state: Fixed

[GoogleCodeExporter]

Issue 196 has been merged into this issue.

Original comment by simmonmt@google.com on 23 Nov 2010 at 12:59