Got a 401 on a fresh purchase

There is. So this isn't an issue with the agent, but with Launchpad. The private ppa htaccess files are only updated every 5 minutes currently :(

*/5 * * * * LPCONFIG=ppa /srv/launchpad.net/codelines/current/cronscripts/generate-ppa-htaccess.py -vv

I wonder if we can have this updated to every minute until there is infrastructure to trigger it immediately.

So currently the client will need to poll for a maximum of whatever the cron period is.

Looking at the logs for generate-ppa-htaccess, it currently takes around 2 minutes to run each time.

I checked with mthaddon, and he's hesitant to increase the frequency of this script until it is faster, but not entirely against it.

I've created bug 628711 and added thoughts on how the script can be made faster in the short-term.

Soyuz task set to medium priority since the software centre can work around it temporarily by re-trying.

I added code now to the client that makes it spin for up to 5 minutes waiting for the repo to become available.

Waiting 5 extra minutes to download an app you just purchased is a terrible experience. Can Soyuz fix this before Maverick ships?

Rick, indeed. I've started on bug 628711 an hour ago. I'm hoping to improve the speed of the cronjob so we can run it at least every two minutes, but hopefully every minute (as a short-term fix until we have immediate updating of the htaccess files).

Rick, as Michael says he's trying to reduce the latency, but there will always at least be one of up to a minute with the current code. For this to be relatively instant, we need a re-write of the code to handle some sort of message passing instead of using cron to generate the .htaccess files in the repo area.

This bug was fixed in the package software-center - 2.1.15

---------------
software-center (2.1.15) maverick; urgency=low

  [ Michael Vogt ]
  * softwarecenter/view/purchasedialog.py:
    - fix size and title for additional webkit windows (LP: #625385)
  * softwarecenter/db/update.py:
    - fix screenshot url and thumbnail url loading
  * softwarecenter/enums.py:
    - switch default to buy-host to software-center.ubuntu.com
    - allow override via the SOFTWARE_CENTER_BUY_HOST environment
      (useful for testing)
  * softwarecenter/backend/aptd.py:
    - make defaults for addons_{install,remove} empty lists instead
      of None to prevent crash when called with a empty argument
    - use AptClinet.install_packages() instead of commit_packages()
      for the install of commercial stuff to get the benefit of
      aptdaemons 03_auth_me_less patch
  * softwarecenter/backend/restfulclient.py:
    - point SERVICE_ROOT for the internal login service to production
  * softwarecenter/view/appdetailsview_gtk.py:
    - minor logging improvements
  * merged lp:~mmcg069/software-center/pathbar-clip-fix that ensures
    proper clipping for the pathbar, many thanks!
  * softwarecenter/view/channelpane.py:
    - fix flicker in channelspane on db-reopen and add regression
      test
  * merged lp:~mvo/software-center/less-flicker that fixes some
    UI flicker/ghost activity (LP: #626733)
  * softwarecenter/backend/aptd.py:
    - if reload() fails when adding a commercial PPA that may be
      because there is a 5 min delay between software-center-agent
      telling us its available and it becoming availalbe in launchpad.
      In this case, retry up to 5 minutes to get the repo
      (LP: #627608)
  * merged lp:~mmcg069/software-center/prelight-icon-onhover
    (many thanks!)
  * merged lp:~mmcg069/software-center/cat-flags to support
    internal flags in the menu files

  [ Gary Lasker ]
  * merge lp:~mmcg069/software-center/misbehaving-pathbar-fix, fixes
    pathbar no longer shrinking to available width (LP: #625210),
    many thanks Matthew McGowan!
  * softwarecenter/view/viewswitcher.py:
    - only update the channel list when a model is available
      (LP: #628394)

  [ Kiwinote ]
  * data/dialogs.ui:
    - only display vscrollbar if needed for dependency removal alert
    - tweak window properties for dependency removal alert
  * data/SoftwareCenter.ui:
    - tweak window properties for the rebuilding window
  * po/POTFILES.in:
    - mark data/ui/dialogs.ui for translation
  * software-center:
    - fix typo, thanks Jeremy Bicha! (LP: #625729)
  * softwarecenter/app.py:
    - always make s-c sensitive again after catalog is rebuilt (LP: #626513)
  * softwarecenter/apt/aptcache.py:
    - don't crash when no LANGPACK_PKGDEPENDS file exists (LP: #625562)
    - speed improvements for get_addons()
    - don't allow randompkg-something to list randompkg as an add-on
  * softwarecenter/db/application.py:
    - fail nicely if a deb file can't be opened
  * softwarecenter/view/appdetailsview_gtk.py:
    - don't use capitalize() on add-on names, much thanks to Severin Heiniger!
      lp:~lantash/ubuntu/maverick/software-center/fixes-626067 (LP: #62...

Michael, have you considered having a work queue in parallel/instead
of the cron job?

The queue could simply say 'reevaluate PPA XXX', and would do one PPA.
That should get the latency down fairly low.

On Fri, Sep 3, 2010 at 10:58 AM, Robert Collins
<email address hidden> wrote:
> Michael, have you considered having a work queue in parallel/instead
> of the cron job?
>
> The queue could simply say 'reevaluate PPA XXX', and would do one PPA.
> That should get the latency down fairly low.

Yeah, I assume the longer-term solution would involve a work-queue.
Right now we need something we can do immediately (bug 628711).

On Friday 03 September 2010 09:58:55 you wrote:
> Michael, have you considered having a work queue in parallel/instead
> of the cron job?
>
> The queue could simply say 'reevaluate PPA XXX', and would do one PPA.
> That should get the latency down fairly low.

That's pretty much what I said in comment 7.

But what we don't want is a solution geared to doing only this, we want a real
message system in Launchpad. The script that generates the htaccess files
should then be a twistd script responding to messages about PPA token changes.

Just a note that the intermediate fix so that we can update the .htpasswd files each minute has been committed to the Launchpad tree a few days ago (see bug 628711) and will be rolled out with the 10.09 Launchpad rollout. Once we've confirmed the cron job is running faster we then need to work with a losa to update the cron job frequency.

You may wish to get this fast track deployed to loganberry / wherever
it runs; as long as no SPOF services are replaced it should be doable
mid-cycle.

-Rob

We've requested the cron job be updated to every minute (RT 41629) as the soyuz workaround has reduced the actual cron update time to under a second, although the setup/teardown still takes 25s.

The cronscript has been running every minute for a few weeks now:

{{{
2010-10-20 00:03:05 INFO Creating lockfile: /var/lock/launchpad-generate-ppa-htaccess.lock
2010-10-20 00:03:15 INFO Starting the PPA .htaccess generation
2010-10-20 00:03:15 INFO Committing transaction...
2010-10-20 00:03:15 INFO Finished PPA .htaccess generation
2010-10-20 00:03:24 DEBUG Removing lock file: /var/lock/launchpad-generate-ppa-htaccess.lock
2010-10-20 00:04:04 DEBUG Cronscript control file not found at file:cronscripts.ini
2010-10-20 00:04:04 INFO Creating lockfile: /var/lock/launchpad-generate-ppa-htaccess.lock
2010-10-20 00:04:14 INFO Starting the PPA .htaccess generation
2010-10-20 00:04:14 INFO Committing transaction...
2010-10-20 00:04:14 INFO Finished PPA .htaccess generation
2010-10-20 00:04:23 DEBUG Removing lock file: /var/lock/launchpad-generate-ppa-htaccess.lock
2010-10-20 00:05:04 DEBUG Cronscript control file not found at file:cronscripts.ini
2010-10-20 00:05:04 INFO Creating lockfile: /var/lock/launchpad-generate-ppa-htaccess.lock
2010-10-20 00:05:14 INFO Starting the PPA .htaccess generation
2010-10-20 00:05:15 INFO Committing transaction...
2010-10-20 00:05:15 INFO Finished PPA .htaccess generation
2010-10-20 00:05:24 DEBUG Removing lock file: /var/lock/launchpad-generate-ppa-htaccess.lock
}}}

So I assume this bug is fix released (as in users should no-longer see a 401 when the repository is accessed after a successful purchase). Soyuz would still like to work on a better long-term fix (removing the need for a cron-job).

I think this still may be open. Today (22 Oct) I tried to purchase Brukkon. The payment seemed to go through and I saw a "payment authorised" message. But then as it left the payment system and seemed to return to the software center, I got the following error message "Failure in purchase process. Unable to create a Launchpad subscription. HTTP 401: unauthorised".

I haven't tried to repurchase in case you want me to do something to help debug.

I ran into this issue. After some period of time I clicked "buy" again. I didn't have to repay, and the program installed. So, a possible work around until this is fixed is to wait 10 minutes.

@Jane - yours is a slightly different issue. (This bug is for when the purchase - including the creation of the LP subscription succeeds, but then the software center client reports a 401 when it tries to access the repository). Achuni - if you get a chance before me, Jane's issue is the same one about which we chatted on Monday (SCA user gets 401 from LP for some reason - I'll search for it once I arrive).

@Rick - can you give exact details of when and what you purchase so I can check the launchpad logs and find out why it took so long to create the repository authentication details - as per my comment above, the script is now running every minute. I'd like to be certain of exactly what happened.

I purchased Brukkon. Based on my IRC logs, I'm guessing it was around 9:30am EST. Here is the error that was reported to me by Software Center.

W:Failed to fetch https://private-ppa.launchpad.net/commercial-ppa-uploaders/brukkon/ubuntu/dists/maverick/main/binary-i386/Packages.gz The requested URL returned error: 401
 , E:Some index files failed to download, they have been ignored, or old ones used instead.

HTH

I've found and updated the other bug that describes the issue Jane experienced - bug 657109.

And I've checked the logs for Rick's purchase. The first update to the brukkon PPAs htpasswd on the 22nd was around 16:12 GMT (12:12pm EST) and the private access was updated within 1 minute as shown:

{{{
2010-10-22 16:11:13 INFO Starting the PPA .htaccess generation
2010-10-22 16:11:13 INFO Committing transaction...
2010-10-22 16:11:13 INFO Finished PPA .htaccess generation
2010-10-22 16:11:22 DEBUG Removing lock file: /var/lock/launchpad-generate-ppa-htaccess.lock
2010-10-22 16:12:06 DEBUG Cronscript control file not found at file:cronscripts.ini
2010-10-22 16:12:06 INFO Creating lockfile: /var/lock/launchpad-generate-ppa-htaccess.lock
2010-10-22 16:12:22 INFO Starting the PPA .htaccess generation
2010-10-22 16:12:22 DEBUG Replaced htpasswd for brukkon
2010-10-22 16:12:22 INFO Committing transaction...
2010-10-22 16:12:22 INFO Finished PPA .htaccess generation
2010-10-22 16:12:31 DEBUG Removing lock file: /var/lock/launchpad-generate-ppa-htaccess.lock
2010-10-22 16:13:23 DEBUG Cronscript control file not found at file:cronscripts.ini
2010-10-22 16:13:23 INFO Creating lockfile: /var/lock/launchpad-generate-ppa-htaccess.lock
2010-10-22 16:13:46 INFO Starting the PPA .htaccess generation
2010-10-22 16:13:46 INFO Committing transaction...
2010-10-22 16:13:46 INFO Finished PPA .htaccess generation
}}}

There were also updates on the 22nd to the brukkon ppa htpasswd at: 17:13GMT, 18:05GMT, 18:09GMT, 18:38, 19:09, 20:50, 20:53, 21:12, 21:17, 22:16, 23:36, but all updated minutely.

So I'm confused as to why Rick experienced the 401. When I have access to the sca logs, we can check the exact purchase time and match it up - which might help us isolate the possibilities.

Hello Rick,

could you please mail me the file(s) ~/.cache/software-center/software-center.log* (I will attach them once
I'm sure there is nothing sensitive in there, it shouldn't, but I want to be 100% sure about it).

We've been through the logs, matching the sca logs with launchpad's, and can confirm that although the script is running every minute, it didn't detect Rick's new token.

The reason is that the launchpad script that checks for new tokens does the following:

1) Log that the script started
2) Check for any new tokens since the last successful run finished
3) Do updates if there are any
4) Log that the script finished.

with the now-obvious issue that if a new token is created in the small window after (2) but before (4), it will not be detected (until the next time a new token is added to the same PPA - which is exactly what happened with Rick's subscription).

I'll prepare a LP branch that updates the script so that at (2) it checks for any new tokens since the last successful run *started* (it's an idempotent operation, so overlap won't affect the process).

Fixed in stable r11812 <http://bazaar.launchpad.net/~launchpad-pqm/launchpad/stable/revision/11812>.

This took a while to QA - we had to setup stuff on qastaging properly. Please to be QAing on landing!

On Wednesday 03 November 2010 05:40:45 you wrote:
> This took a while to QA - we had to setup stuff on qastaging properly.
> Please to be QAing on landing!
>
> ** Tags added: qa-ok
> ** Tags removed: qa-needstesting

I suspect it was already QAed on dogfood, but the tagging process gives us no
way of indicating that. I have requested this feature some time ago.