Ubuntu
software-center package

Purchasing software took almost 5 minutes

Bug #980241 reported by Natalia Bidart
10
This bug affects 2 people
Affects Status Importance Assigned to Milestone
software-center (Ubuntu)
Confirmed
Medium
Unassigned

Bug Description

I was playing with the SC UI, and decided to purchase a game. I chose "Bobby", since I liked the description and it was $0 :-).

I clicked on "Buy...", then I went through the purchase process. After the payment was completed, I was redirected again to the SC UI and I was presented with the "Installing" screen. There was a progress bar in the "activity" mode, and that progress bar remained in that state for a "long" time (see logs attached).

After 4 minutes approx, the progress bar switched to non-active mode (ie it started show real progress), and the app was finally installed.

Once the app was installed, there was no way for me to run it: it wasn't showing in the dash, nor in the launcher, nor I couldn't find it in the terminal by typing:

$ bo<tab>

After a "dpkg -L bobby", I found that bobby was located under /opt/bobby, so I ran:

nessita@dali:~$ /opt/bobby/Bobby
/opt/bobby/Bobby: error while loading shared libraries: libbass.so: cannot open shared object file: No such file or directory

And since that failed, I had to run:

nessita@dali:~$ LD_LIBRARY_PATH=/opt/bobby/ /opt/bobby/Bobby

and with that last command I could finally play the game.

Revision history for this message
Natalia Bidart (nataliabidart) wrote :
Download full text (7.0 KiB)

Logs of the SC run:

nessita@dali:~/canonical/software-store/trunk$ PYTHONPATH=. ./software-center
2012-04-12 16:17:19,039 - softwarecenter - INFO - Using data (UI, xapian) from current dir
2012-04-12 16:17:19,473 - softwarecenter.ui.gtk3.app - INFO - setting up proxy 'None'
2012-04-12 16:17:19,511 - softwarecenter.db.database - INFO - open() database: path=None use_axi=True use_agent=True
2012-04-12 16:17:19,796 - softwarecenter.ui.gtk3.app - INFO - building local database
2012-04-12 16:17:22,474 - softwarecenter.db.update - WARNING - The file: '/usr/share/app-install/desktop/kde-telepathy-send-file:kde4__ktp-send-file.desktop' could not be read correctly. The application associated with this file will not be included in the software catalog. Please consider raising a bug report for this issue with the maintainer of that application
2012-04-12 16:17:41,486 - softwarecenter.db.database - INFO - open() database: path=None use_axi=True use_agent=True
2012-04-12 16:17:41,772 - softwarecenter.backend.reviews - WARNING - Could not get usefulness from server, no username in config file
2012-04-12 16:18:19,452 - softwarecenter.ui.gtk3.app - INFO - software-center-agent finished with status 0
2012-04-12 16:18:19,453 - softwarecenter.db.database - INFO - reopen() database
2012-04-12 16:18:19,453 - softwarecenter.db.database - INFO - open() database: path=None use_axi=True use_agent=True
2012-04-12 16:36:11,789 - softwarecenter.backend - INFO - add_repo_add_key_and_install_app() 'private-ppa.launchpad.net/commercial-ppa-uploaders/bobby/ubuntu precise main' '1024R/75254D99' 'Bobby,bobby'
2012-04-12 16:36:17,430 - softwarecenter.backend - INFO - add_sources_list_entry()
2012-04-12 16:36:17,701 - softwarecenter.backend - INFO - add_vendor_key_from_keyserver()
2012-04-12 16:36:19,911 - softwarecenter.backend - INFO - reload_for_commercial_repo()
2012-04-12 16:36:19,912 - softwarecenter.backend - INFO - _reload_for_commercial_repo() Bobby,bobby
/usr/lib/python2.7/dist-packages/gi/types.py:43: Warning: value "101.000000" of type `gdouble' is invalid or out of range for property `value' of type `gint'
  return info.invoke(*args, **kwargs)
/home/nessita/canonical/software-store/trunk/softwarecenter/db/pkginfo_impl/aptcache.py:41: Warning: value "101.000000" of type `gdouble' is invalid or out of range for property `value' of type `gint'
  context.iteration()
2012-04-12 16:36:46,535 - softwarecenter.backend - INFO - _on_reload_for_add_repo_and_install_app_finished() <AptTransaction object at 0x6bc1e10 (aptdaemon+client+AptTransaction at 0x3bfba40)> False Bobby,bobby
2012-04-12 16:36:46,536 - softwarecenter.backend - INFO - looking for '/var/lib/apt/lists/private-ppa.launchpad.net_commercial-ppa-uploaders_bobby_ubuntu_dists_precise_Release.gpg'
2012-04-12 16:36:46,536 - softwarecenter.backend - WARNING - no /var/lib/apt/lists/private-ppa.launchpad.net_commercial-ppa-uploaders_bobby_ubuntu_dists_precise_Release.gpg found, re-trying
2012-04-12 16:36:46,536 - softwarecenter.backend - INFO - queuing reload in 30s
2012-04-12 16:37:17,201 - softwarecenter.backend - INFO - _reload_for_commercial_repo() Bobby,bobby
2012-04-12 16:37:39,434 - softwarecenter.backend - INFO...

Read more...

Revision history for this message
Natalia Bidart (nataliabidart) wrote :

Further info:

nessita@dali:~$ apt-cache policy bobby
bobby:
  Installed: 1.4-0ubuntu1
  Candidate: 1.4-0ubuntu1
  Version table:
 *** 1.4-0ubuntu1 0
        500 https://private-ppa.launchpad.net/commercial-ppa-uploaders/bobby/ubuntu/ precise/main amd64 Packages
        100 /var/lib/dpkg/status

nessita@dali:~$ cat /usr/share/applications/bobby.desktop
[Desktop Entry]
Type=Application
Exec= /opt/bobby/Bobby
Path=/opt/bobby
Icon=bobby
Name=Bobby
Categories=Game
StartupNotify=false

Revision history for this message
Michael Vogt (mvo) wrote :

Hey Natalia, thanks for your bugreport.

This is probably (someone like Michael Nelson will be able to confirm) a issue with Launchpad making the repository not available to the software-center-agent earlier.

Changed in software-center (Ubuntu):
importance: Undecided → Medium
Revision history for this message
Dave Morley (davmor2) wrote :

Natalia I just ran the same test on i386 and amd64 and everything worked fine here.

The app shows up in precises dash by typing bob and runs fine from there.

Revision history for this message
Michael Nelson (michael.nelson) wrote :

So this is the delay from:

2012-04-12 16:36:11,789 - softwarecenter.backend - INFO - add_repo_add_key_and_install_app() 'private-ppa.launchpad.net/commercial-ppa-uploaders/bobby/ubuntu precise main' '1024R/75254D99' 'Bobby,bobby'
... (apparently 4 failed attempts before)...
2012-04-12 16:40:07,105 - softwarecenter.backend - INFO - _on_reload_for_add_repo_and_install_app_finished() <AptTransaction object at 0x587b370 (aptdaemon+client+AptTransaction at 0x66b5c80)> True Bobby,bobby

during which time USC is unable to see /var/lib/apt/lists/private-ppa.launchpad.net_commercial-ppa-uploaders_bobby_ubuntu_dists_precise_Release.gpg

This would indeed indicate that USC wasn't able to access the private PPA until then, but is strange as the only LP script that I can imagine causing this delay is the one updating the ht-access for the private PPA - that's currently scheduled to happen every minute (cronscripts/generate-ppa-htaccess.py has a crontab with * * * * *).

Indeed, checking the logs for generate-ppa-htaccess.py and assuming that the above logs are all -0300 (Natalia's tz) shows it happily chugging along nearly once-per minute until

{{{
2012-04-12 19:36:33 INFO Logging INFO and higher messages to /srv/launchpad.net/production-logs/lp_publish/generate-ppa-htaccess.log
2012-04-12 19:36:33 INFO Creating lockfile: /var/lock/launchpad-generate-ppa-htaccess.lock
2012-04-12 19:37:14 INFO Logging INFO and higher messages to /srv/launchpad.net/production-logs/lp_publish/generate-ppa-htaccess.log
2012-04-12 19:37:14 INFO Creating lockfile: /var/lock/launchpad-generate-ppa-htaccess.lock
2012-04-12 19:37:35 INFO Starting the PPA .htaccess generation
2012-04-12 19:38:10 INFO Logging INFO and higher messages to /srv/launchpad.net/production-logs/lp_publish/generate-ppa-htaccess.log
2012-04-12 19:38:10 INFO Creating lockfile: /var/lock/launchpad-generate-ppa-htaccess.lock
2012-04-12 19:39:10 INFO Logging INFO and higher messages to /srv/launchpad.net/production-logs/lp_publish/generate-ppa-htaccess.log
2012-04-12 19:39:10 INFO Creating lockfile: /var/lock/launchpad-generate-ppa-htaccess.lock
2012-04-12 19:39:50 INFO Committing transaction...
2012-04-12 19:39:56 INFO Finished PPA .htaccess generation
}}}

(more context for log https://pastebin.canonical.com/64326/)

which seems to indicate that:
1) Started at 19:36:33 but didn't even start PPA.htaccess generation (perhaps lockfile existed? Need to check the lp code)
2) Restarted at 19:37:14 but didn't commit the transaction or finish the htaccess generation.
3) Restarted at 19:38:10 but didn't even start PPA .htaccess generation, before finally
4) Restarted at 19:39:10 and finished 46 seconds later.

I've put that in an LP bug 982938 so we can track it (we may have to investigate/fix ourselves, just let me know).

Revision history for this message
Launchpad Janitor (janitor) wrote :

Status changed to 'Confirmed' because the bug affects multiple users.

Changed in software-center (Ubuntu):
status: New → Confirmed
Revision history for this message
Michael Vogt (mvo) wrote :

This is most likely a dupe of the launchpad htaccess generation bug #982938.

To post a comment you must log in.
This report contains Public information  
Everyone can see this information.
Subscribing...

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.