Merge lp:~gary-lasker/software-center/fix-lp920741 into lp:software-center/5.2

[Gary Lasker]

* lp:~gary-lasker/software-center/fix-lp920741:
   - fix UnicodeDecodeError when a commercial app's title contains
     a unicode character (LP: #920741)

This branch fixes a UnicodeDecodeError when a commercial app's name has a non-ascii character in it, bug 920741. It's a very simple fix and actually only involves a change to a logger info statement.

[Michael Vogt (mvo)]

On Tue, Jun 26, 2012 at 04:17:22PM -0000, Gary Lasker wrote:
> Gary Lasker has proposed merging lp:~gary-lasker/software-center/fix-lp920741 into lp:software-center/5.2.
>
> Requested reviews:
> software-store-developers (software-store-developers)
> Related bugs:
> Bug #920741 in software-center (Ubuntu): "UnicodeDecodeError in add_repo_add_key_and_install_app when a appname has special chars in it"
> https://bugs.launchpad.net/ubuntu/+source/software-center/+bug/920741
>
> For more details, see:
> https://code.launchpad.net/~gary-lasker/software-center/fix-lp920741/+merge/112161
>
> This branch fixes a UnicodeDecodeError when a commercial app's name has a non-ascii character in it, bug 920741. It's a very simple fix and actually only involves a change to a logger info statement.
[..]

Thanks for your work on this branch! The code change looks good. Could
you also please add a regression test to ensure we do not regress here
in the future, especially when we move from python2 to python3? Manual
instructions how to test this against a real app would also be good
(afaik there is one with that problem currently available?).

Plus we use the Application object in a (small) number of places in a
logger call so it would be good to know if it crashes everywhere or
just in this particular place and if it crashes in all logger contexts
we need to update that code too.

Cheers,
 Michael

[Dave Morley (davmor2)]

I've tried to run the install for elementals once more and got the following:

davmor2@boromir:~/tmp/fix-lp920741$ export SOFTWARE_CENTER_AGENT_INCLUDE_QA=1
davmor2@boromir:~/tmp/fix-lp920741$ ./software-center
2012-06-27 11:05:39,084 - softwarecenter - INFO - Using data (UI, xapian) from current dir
2012-06-27 11:05:40,548 - softwarecenter.ui.gtk3.app - INFO - setting up proxy 'None'
2012-06-27 11:05:40,604 - softwarecenter.db.database - INFO - open() database: path=None use_axi=True use_agent=True
2012-06-27 11:05:41,008 - softwarecenter.ui.gtk3.app - INFO - building local database
2012-06-27 11:05:41,008 - softwarecenter.db.pkginfo_impl.aptcache - INFO - aptcache.open()
2012-06-27 11:06:23,961 - softwarecenter.db.database - INFO - open() database: path=None use_axi=True use_agent=True
2012-06-27 11:06:25,197 - softwarecenter.ui.gtk3.app - INFO - show_available_packages: search_text is '', app is None.
2012-06-27 11:06:25,575 - softwarecenter.db.pkginfo_impl.aptcache - INFO - aptcache.open()
2012-06-27 11:06:54,668 - softwarecenter.ui.gtk3.app - INFO - software-center-agent finished with status 0
2012-06-27 11:06:54,671 - softwarecenter.db.database - INFO - reopen() database
2012-06-27 11:06:54,671 - softwarecenter.db.database - INFO - open() database: path=None use_axi=True use_agent=True
2012-06-27 11:07:22,428 - softwarecenter.backend.spawn_helper - WARNING - exit code 1 from helper for '['./data/piston_generic_helper.py', '--datadir', './data', 'SoftwareCenterRecommenderAPI', 'recommend_app', '{"pkgname": "elementals-themagickey"}']'
2012-06-27 11:07:22,428 - softwarecenter.backend.spawn_helper - WARNING - got error from helper: 'WARNING:__main__:404: {'status': '404', 'content-length': '71', 'via': '1.1 papeda.canonical.com:3128 (squid/2.7.STABLE7)', 'x-cache': 'MISS from papeda.canonical.com', 'x-cache-lookup': 'MISS from papeda.canonical.com:3128', 'strict-transport-security': 'max-age=2592000', 'vary': 'Accept-Encoding', 'server': 'Apache/2.2.14 (Ubuntu)', 'etag': '"4f936a9feec02565f3937074a8d3c9e4"', 'cache-control': 'max-age=300', 'date': 'Wed, 27 Jun 2012 10:07:22 GMT', 'content-type': 'text/html; charset=utf-8', '-content-encoding': 'gzip'}
'
2012-06-27 11:07:22,429 - softwarecenter.db.categories - WARNING - Error while accessing the recommender service: WARNING:__main__:404: {'status': '404', 'content-length': '71', 'via': '1.1 papeda.canonical.com:3128 (squid/2.7.STABLE7)', 'x-cache': 'MISS from papeda.canonical.com', 'x-cache-lookup': 'MISS from papeda.canonical.com:3128', 'strict-transport-security': 'max-age=2592000', 'vary': 'Accept-Encoding', 'server': 'Apache/2.2.14 (Ubuntu)', 'etag': '"4f936a9feec02565f3937074a8d3c9e4"', 'cache-control': 'max-age=300', 'date': 'Wed, 27 Jun 2012 10:07:22 GMT', 'content-type': 'text/html; charset=utf-8', '-content-encoding': 'gzip'}

2012-06-27 11:07:22,429 - softwarecenter.ui.gtk3.widgets.recommendations - WARNING - Error while accessing the recommender agent for the details view recommendations: WARNING:__main__:404: {'status': '404', 'content-length': '71', 'via': '1.1 papeda.canonical.com:3128 (squid/2.7.STABLE7)', 'x-cache': 'MISS from papeda.canonical.com', 'x-cache-lookup': 'MISS f...

[lp:~gary-lasker/software-center/fix-lp920741]

3053. By Gary Lasker on 2012-06-27

tighten the fix

3054. By Gary Lasker on 2012-06-27

simple fix

[Gary Lasker (gary-lasker)]

I added your test case, thanks mvo! I also simplified the fix (considering the utf8 fix didn't actually work) but just displaying app.pkgname in the offending debug call.

Per your suggestion, I will look for other places where we log an instance of Application and make the same simple fix.

Note that this all is for the SRU cases only. Your fix in lp:~mvo/software-center/fix-lp920741 is really nice and is a much better general fix, so as we've discussed in IRC we should use your fix in trunk for Quantal.

Thanks again!

[lp:~gary-lasker/software-center/fix-lp920741]

3055. By Gary Lasker on 2012-06-27

additional fix for logging commercial apps

3056. By Gary Lasker on 2012-06-27

make the app.pkgname fix for DEBUG mode logger calls as well

3057. By Gary Lasker on 2012-06-27

app can be None, handle that

3058. By Gary Lasker on 2012-06-27

add prophylatic checks for app=None where they may be needed, just a further safeguard against regressions

[Michael Vogt (mvo)]

Thanks for this update.

The logging with "app" is only a problem in a context where both string and unicode objects are passed to the logger. In this case it will try to convert the application to a str first (via __str__) and then convert that to unicode. But because there is no __unicode__ method it will assume ascii encoding for the resulting string and fail.

This means that in the places where a single app argument is used its fine and will not crash and its also fine if all strings are of type "str". I mentioned this on irc:

Jun 27 17:15:17 <mvo> tremolux: the only thing that needs invesitgation is if we use a mixed unicode/str in a logger elsewhere that might crash in the same way

but because of the rush to work on the paypal bug I did not put that in the bugreport (I'm sorry for that).

I will revert the parts where there is just a single app argument in the logger and add it to the 5.2 branch
(the added benefit is that the diff also smaller which will make the SRU team happy :)

=== modified file 'softwarecenter/backend/installbackend_impl/aptd.py'
--- softwarecenter/backend/installbackend_impl/aptd.py	2012-05-21 20:40:57 +0000
+++ softwarecenter/backend/installbackend_impl/aptd.py	2012-06-27 17:23:20 +0000
@@ -550,7 +550,7 @@
         self._logger.info("add_repo_add_key_and_install_app() '%s' '%s' '%s'" %
             (re.sub("deb https://.*@", "", deb_line),  # strip out password
             signing_key_id,
-            app))
+            app.pkgname))
 
         if purchase:
             # pre-authenticate
@@ -618,7 +618,7 @@
             See _reload_for_commercial_repo_inline() for the actual work
             that is done
         """
-        self._logger.info("_reload_for_commercial_repo() %s" % app)
+        self._logger.info("_reload_for_commercial_repo() %s" % app.pkgname)
         # trigger inline_callbacked function
         self._reload_for_commercial_repo_defer(
             app, trans_metadata, sources_list)
 
=== modified file 'softwarecenter/db/application.py'
--- softwarecenter/db/application.py	2012-05-21 20:10:39 +0000
+++ softwarecenter/db/application.py	2012-06-27 17:23:20 +0000
@@ -238,7 +238,8 @@
     def _on_db_reopen(self, db):
         if self._doc:
             try:
-                LOG.debug("db-reopen, refreshing docid for %s" % self._app)
+                LOG.debug("db-reopen, refreshing docid for %s" %
+                    self._app.pkgname)
                 self._doc = self._db.get_xapian_document(
                     self._app.appname, self._app.pkgname)
             except IndexError:
 
=== modified file 'softwarecenter/ui/gtk3/panes/availablepane.py'
--- softwarecenter/ui/gtk3/panes/availablepane.py	2012-06-08 23:42:50 +0000
+++ softwarecenter/ui/gtk3/panes/availablepane.py	2012-06-27 17:23:20 +0000
@@ -740,7 +740,8 @@
 
     def on_application_selected(self, appview, app):
         """callback when an app is selected"""
-        LOG.debug("on_application_selected: '%s'" % app)
+        if app:
+            LOG.debug("on_application_selected: '%s'" % app.pkgname)
 
         if self.state.subcategory:
             self.current_app_by_subcategory[self.state.subcategory] = app
@@ -750,7 +751,8 @@
     @wait_for_apt_cache_ready
     def on_application_activated(self, appview, app):
         """callback when an app is clicked"""
-        LOG.debug("on_application_activated: '%s'" % app)
+        if app:
+            LOG.debug("on_application_activated: '%s'" % app.pkgname)
         self.state.application = app
         vm = get_viewmanager()
         vm.display_page(self, AvailablePane.Pages.DETAILS, self.state,
 
=== modified file 'softwarecenter/ui/gtk3/panes/installedpane.py'
--- softwarecenter/ui/gtk3/panes/installedpane.py	2012-05-17 12:27:58 +0000
+++ softwarecenter/ui/gtk3/panes/installedpane.py	2012-06-27 17:23:20 +0000
@@ -690,7 +690,8 @@
 
     def on_application_selected(self, appview, app):
         """callback when an app is selected"""
-        logging.debug("on_application_selected: '%s'" % app)
+        if app:
+            logging.debug("on_application_selected: '%s'" % app.pkgname)
         self.current_appview_selection = app
 
     def get_callback_for_page(self, page, state):
 
=== modified file 'softwarecenter/ui/gtk3/panes/softwarepane.py'
--- softwarecenter/ui/gtk3/panes/softwarepane.py	2012-06-08 21:53:59 +0000
+++ softwarecenter/ui/gtk3/panes/softwarepane.py	2012-06-27 17:23:20 +0000
@@ -259,7 +259,8 @@
     @wait_for_apt_cache_ready
     def on_application_activated(self, appview, app):
         """callback when an app is clicked"""
-        LOG.debug("on_application_activated: '%s'" % app)
+        if app:
+            LOG.debug("on_application_activated: '%s'" % app.pkgname)
 
         self.state.application = app
 
 
=== modified file 'softwarecenter/ui/gtk3/views/appdetailsview.py'
--- softwarecenter/ui/gtk3/views/appdetailsview.py	2012-06-18 14:39:27 +0000
+++ softwarecenter/ui/gtk3/views/appdetailsview.py	2012-06-27 17:23:20 +0000
@@ -984,7 +984,7 @@
         """ callback when new reviews are ready, cleans out the
             old ones
         """
-        LOG.debug("_review_ready_callback: %s" % app)
+        LOG.debug("_review_ready_callback: %s" % app.pkgname)
         # avoid possible race if we already moved to a new app when
         # the reviews become ready
         # (we only check for pkgname currently to avoid breaking on
@@ -1697,10 +1697,11 @@
 
     # public API
     def show_app(self, app, force=False):
-        LOG.debug("AppDetailsView.show_app '%s'" % app)
         if app is None:
             LOG.debug("no app selected")
             return
+        else:
+            LOG.debug("AppDetailsView.show_app '%s'" % app.pkgname)
 
         same_app = (self.app and
                     self.app.pkgname and
 
=== modified file 'test/test_aptd.py'
--- test/test_aptd.py	2012-01-16 14:42:49 +0000
+++ test/test_aptd.py	2012-06-27 17:23:20 +0000
@@ -1,4 +1,5 @@
 #!/usr/bin/python
+# -*- coding: utf-8 -*-
 
 import os
 import time
@@ -7,6 +8,7 @@
 from testutils import setup_test_env
 setup_test_env()
 
+from softwarecenter.db.application import Application
 from softwarecenter.backend.installbackend_impl.aptd import AptdaemonBackend
 from defer import inline_callbacks
 from mock import Mock
@@ -99,6 +101,21 @@
         addons_remove = ["gimp-plugin-registry"]
         yield self.aptd.apply_changes(pkgname, appname ,iconname, addons_install, addons_remove)
 
+    @inline_callbacks
+    def _inline_add_repo_call(self):
+        deb_line = "deb https://foo"
+        signing_key_id = u"xxx"
+        app = Application(u"Elementals: The Magic Key™", "pkgname")
+        iconname = "iconname"
+        yield self.aptd.add_repo_add_key_and_install_app(
+            deb_line, signing_key_id, app, iconname, None, None)
+        
+    def test_add_repo_add_key_and_install_app(self):
+        from mock import patch
+        with patch.object(self.aptd._logger, "info") as mock:
+            self._inline_add_repo_call()
+            self.assertTrue(
+                mock.call_args[0][0].startswith("add_repo_add_key"))
 
 if __name__ == "__main__":
     import logging