Merge lp:~diegosarmentero/ubuntu-sso-client/too-verbose into lp:ubuntu-sso-client

[Diego Sarmentero]

- Improve logging operations (LP: #934500).

[Natalia Bidart (nataliabidart)]

Branch looks good, but I would request a minor tweaks:

* every time you "use" a line from the log, try to have as much info as you can get from your context, so later debugging is easier. For example, here:

        logger.debug('About to emit userLoggedIn signal.')
        self.userLoggedIn.emit(email)

we could be also logging the user email, so we can later distinguish userLoggedIn from different email addresses.

Also, please note that default logging on default installs is INFO, so leave the debug entries for truly debug messages, and migrate to INFO those that are providing important info about the progress of the UI.

Thanks!

review: Needs Fixing

[lp:~diegosarmentero/ubuntu-sso-client/too-verbose]

904. By Diego Sarmentero on 2012-03-09

Some improves in the logger

[Natalia Bidart (nataliabidart)]

* Please note that there is a decorator "log_call" in ubuntu_sso/logger.py that is being used in some places. You are welcomed to re-use this decorator, if you want. But I will request not do use both, like in this case:

    124 @log_call(logger.error)
    125 def on_password_reset_error(self, app_name, error):
    126 """Action taken when there was an error requesting the reset."""
    127 logger.info('Got error on password reset for %s, error: %s',
    128 app_name, error)

(the log_call was there before your branch).* Can you please make all the log lines for initializePage be debug?

* All the log lines inside error callbacks should be logger.error, an example:

    def on_user_registration_error(self, app_name, error):
        """Let the user know we could not register."""
        logger.info('SetUpAccountPage.on_user_registration_error')
        # errors are returned as a dict with the data we want to show.

* Can you please remove this line? logger.debug('SetUpAccountPage.on_captcha_generation_error')

* Could you please add app_name, email and error to the log lines in setup_account_page.py, when available? (using the log_call decorator will make this very easy, since is done automatically)

* In sso_wizard_page.py, can you please change this:

    162 logger.info('SSOWizardPage - executing setup_page')
to

    162 logger.info('%r - setup_page, backend is %r.', self, self.backend)

so we can detect which child of SSOWizardPage is logging that line.

* In the same file, can you add a logger.error message (or log_call(logger.error) decorator) in the show_error callback? Something like:

    134 logger.error('%r - show_error for app_name %r with message %r.',
    135 self, app_name, message)

* Could you please add some debug messages in UbuntuSSOWizard for all the _move_* callbacks?

Branch is looking great, we really need this for further debugging, specially when we go live with Precise.
Thanks!

review: Needs Fixing

[lp:~diegosarmentero/ubuntu-sso-client/too-verbose]

905. By Diego Sarmentero on 2012-03-09

more improves in the logs.

[Diego Sarmentero (diegosarmentero)]

> * Please note that there is a decorator "log_call" in ubuntu_sso/logger.py
> that is being used in some places. You are welcomed to re-use this decorator,
> if you want. But I will request not do use both, like in this case:
>
> 124 @log_call(logger.error)
> 125 def on_password_reset_error(self, app_name, error):
> 126 """Action taken when there was an error requesting the
> reset."""
> 127 logger.info('Got error on password reset for %s, error: %s',
> 128 app_name, error)
>
> (the log_call was there before your branch).* Can you please make all the log
> lines for initializePage be debug?
>
> * All the log lines inside error callbacks should be logger.error, an example:
>
> def on_user_registration_error(self, app_name, error):
> """Let the user know we could not register."""
> logger.info('SetUpAccountPage.on_user_registration_error')
> # errors are returned as a dict with the data we want to show.
>
> * Can you please remove this line?
> logger.debug('SetUpAccountPage.on_captcha_generation_error')
>
> * Could you please add app_name, email and error to the log lines in
> setup_account_page.py, when available? (using the log_call decorator will make
> this very easy, since is done automatically)
>
> * In sso_wizard_page.py, can you please change this:
>
> 162 logger.info('SSOWizardPage - executing setup_page')
> to
>
> 162 logger.info('%r - setup_page, backend is %r.', self,
> self.backend)
>
> so we can detect which child of SSOWizardPage is logging that line.
>
> * In the same file, can you add a logger.error message (or
> log_call(logger.error) decorator) in the show_error callback? Something like:
>
> 134 logger.error('%r - show_error for app_name %r with message
> %r.',
> 135 self, app_name, message)
>
> * Could you please add some debug messages in UbuntuSSOWizard for all the
> _move_* callbacks?
>
> Branch is looking great, we really need this for further debugging, specially
> when we go live with Precise.
> Thanks!

Done!

[Natalia Bidart (nataliabidart)]

Looks good! Thanls for working on this

review: Approve

[Roberto Alsina (ralsina)]

+1

review: Approve

=== modified file 'ubuntu_sso/qt/current_user_sign_in_page.py'
--- ubuntu_sso/qt/current_user_sign_in_page.py	2012-03-05 21:08:40 +0000
+++ ubuntu_sso/qt/current_user_sign_in_page.py	2012-03-09 17:35:23 +0000
@@ -81,6 +81,7 @@
 
     def initializePage(self):
         """Setup UI details."""
+        logger.debug('initializePage - About to show CurrentUserSignInPage')
         self.setButtonText(QtGui.QWizard.CancelButton, CANCEL_BUTTON)
         # Layout without custom button 1,
         # without finish button
@@ -99,10 +100,8 @@
 
     def _set_translated_strings(self):
         """Set the translated strings."""
-        logger.debug('CurrentUserSignInPage._set_translated_strings')
         self.setTitle(LOGIN_TITLE.format(app_name=self.app_name))
         self.setSubTitle(LOGIN_SUBTITLE % {'app_name': self.app_name})
-
         self.ui.email_label.setText(EMAIL_LABEL)
         self.ui.password_label.setText(LOGIN_PASSWORD_LABEL)
         forgotten_text = LINK_STYLE.format(link_url='#',
@@ -112,7 +111,6 @@
 
     def _connect_ui(self):
         """Connect the buttons to perform actions."""
-        logger.debug('CurrentUserSignInPage._connect_buttons')
         self.ui.forgot_password_label.linkActivated.connect(
                                                     self.on_forgotten_password)
         self.ui.email_edit.textChanged.connect(self._validate)
@@ -130,9 +128,9 @@
 
     def login(self):
         """Perform the login using the self.backend."""
-        logger.debug('CurrentUserSignInPage.login')
         # grab the data from the view and call the backend
         email = unicode(self.ui.email_edit.text())
+        logger.info('CurrentUserSignInPage.login for: %s', email)
         password = unicode(self.ui.password_edit.text())
         args = (self.app_name, email, password)
         if self.ping_url:
@@ -158,11 +156,11 @@
         logger.info('Logged in for %s', app_name)
         self.hide_overlay()
         email = unicode(self.ui.email_edit.text())
+        logger.debug('About to emit userLoggedIn signal with: (%s).', email)
         self.userLoggedIn.emit(email)
-        logger.debug('Wizard.loginSuccess emitted.')
 
     def on_forgotten_password(self, link=None):
         """Show the user the forgotten password page."""
-        logger.info('Forgotten password')
         self.hide_overlay()
+        logger.debug('About to emit passwordForgotten signal')
         self.passwordForgotten.emit()

=== modified file 'ubuntu_sso/qt/email_verification_page.py'
--- ubuntu_sso/qt/email_verification_page.py	2012-03-05 20:30:57 +0000
+++ ubuntu_sso/qt/email_verification_page.py	2012-03-09 17:35:23 +0000
@@ -71,7 +71,6 @@
 
     def _connect_ui(self):
         """Set the connection of signals."""
-        logger.debug('EmailVerificationController._connect_ui')
         self.ui.verification_code_edit.textChanged.connect(
             self.validate_form)
         self.next_button.clicked.connect(self.validate_email)
@@ -84,7 +83,6 @@
 
     def _set_translated_strings(self):
         """Set the different titles."""
-        logger.debug('EmailVerificationController._set_titles')
         self.header.set_title(VERIFY_EMAIL_TITLE)
         self.header.set_subtitle(VERIFY_EMAIL_CONTENT % {
             "app_name": self.app_name,
@@ -103,7 +101,8 @@
 
     def validate_email(self):
         """Call the next action."""
-        logger.debug('EmailVerificationController.validate_email')
+        logger.debug('EmailVerificationController.validate_email for: %s',
+            self.email)
         code = unicode(self.ui.verification_code_edit.text())
         args = (self.app_name, self.email, self.password, code)
         self.hide_error()
@@ -123,12 +122,15 @@
 
     def on_email_validated(self, app_name, email):
         """Signal thrown after the email is validated."""
-        logger.info('EmailVerificationController.on_email_validated')
+        logger.info('EmailVerificationController.on_email_validated for %s, '
+                    'email: %s', app_name, email)
         self.hide_overlay()
         self.registrationSuccess.emit(self.email)
 
     def on_email_validation_error(self, app_name, error):
         """Signal thrown when there's a problem validating the email."""
+        logger.error('Got error on email validation %s, error: %s',
+            app_name, error)
         self.hide_overlay()
         msg = error.pop(ERROR_EMAIL_TOKEN, '')
         msg += build_general_error_message(error)
@@ -138,6 +140,7 @@
 
     def initializePage(self):
         """Called to prepare the page just before it is shown."""
+        logger.debug('initializePage - About to show EmailVerificationPage')
         self.next_button.setDefault(True)
         self.next_button.setEnabled(False)
         self.wizard().setButtonLayout([QtGui.QWizard.Stretch])

=== modified file 'ubuntu_sso/qt/forgotten_password_page.py'
--- ubuntu_sso/qt/forgotten_password_page.py	2012-03-05 20:31:22 +0000
+++ ubuntu_sso/qt/forgotten_password_page.py	2012-03-09 17:35:23 +0000
@@ -63,6 +63,7 @@
 
     def initializePage(self):
         """Set the initial state of ForgottenPassword page."""
+        logger.debug('initializePage - About to show ForgottenPasswordPage')
         self.ui.send_button.setDefault(True)
         enabled = not self.ui.email_line_edit.text().isEmpty()
         self.ui.send_button.setEnabled(enabled)
@@ -98,6 +99,7 @@
         """Send the request password operation."""
         self.hide_error()
         args = (self.app_name, self.email_address)
+        logger.debug('Sending request new password for %s, email: %s', *args)
         f = self.backend.request_password_reset_token
 
         error_handler = partial(self._handle_error, f,
@@ -113,6 +115,8 @@
 
     def on_password_reset_token_sent(self, app_name, email):
         """Action taken when we managed to get the password reset done."""
+        logger.info('ForgottenPasswordPage.on_password_reset_token_sent for '
+                    '%s, email: %s', app_name, email)
         # ignore the result and move to the reset page
         self.hide_overlay()
         self.passwordResetTokenSent.emit(email)

=== modified file 'ubuntu_sso/qt/network_detection_page.py'
--- ubuntu_sso/qt/network_detection_page.py	2012-02-29 14:00:12 +0000
+++ ubuntu_sso/qt/network_detection_page.py	2012-03-09 17:35:23 +0000
@@ -20,7 +20,7 @@
 from PyQt4 import QtGui
 
 from ubuntu_sso import networkstate
-
+from ubuntu_sso.logger import setup_logging
 from ubuntu_sso.qt.sso_wizard_page import SSOWizardPage
 from ubuntu_sso.qt.ui import network_detection_ui
 from ubuntu_sso.utils.ui import (
@@ -31,6 +31,9 @@
 )
 
 
+logger = setup_logging('ubuntu_sso.network_detection_page')
+
+
 class NetworkDetectionPage(SSOWizardPage):
 
     """Widget to show if we don't detect a network connection."""
@@ -48,6 +51,7 @@
 
     def initializePage(self):
         """Set UI details."""
+        logger.debug('initializePage - About to show NetworkDetectionPage')
         self.wizard()._next_id = None
 
         self.setButtonText(QtGui.QWizard.CustomButton1, TRY_AGAIN_BUTTON)

=== modified file 'ubuntu_sso/qt/reset_password_page.py'
--- ubuntu_sso/qt/reset_password_page.py	2012-03-05 20:30:57 +0000
+++ ubuntu_sso/qt/reset_password_page.py	2012-03-09 17:35:23 +0000
@@ -73,6 +73,7 @@
 
     def initializePage(self):
         """Extends QWizardPage initializePage method."""
+        logger.debug('initializePage - About to show ResetPasswordPage')
         super(ResetPasswordPage, self).initializePage()
         common.password_default_assistance(self.ui.password_assistance)
         self.ui.password_assistance.setVisible(False)
@@ -158,6 +159,8 @@
 
     def on_password_changed(self, app_name, email):
         """Let user know that the password was changed."""
+        logger.info('ResetPasswordPage.on_password_changed for %s, email: %s',
+            app_name, email)
         self.hide_overlay()
         email = unicode(self.wizard().forgotten.ui.email_line_edit.text())
         self.passwordChanged.emit(email)

=== modified file 'ubuntu_sso/qt/setup_account_page.py'
--- ubuntu_sso/qt/setup_account_page.py	2012-03-07 18:03:28 +0000
+++ ubuntu_sso/qt/setup_account_page.py	2012-03-09 17:35:23 +0000
@@ -31,7 +31,7 @@
 from PyQt4 import QtGui, QtCore
 
 from ubuntu_sso import NO_OP
-from ubuntu_sso.logger import setup_gui_logging
+from ubuntu_sso.logger import setup_gui_logging, log_call
 from ubuntu_sso.qt import (
     LINK_STYLE,
     build_general_error_message,
@@ -122,6 +122,7 @@
 
     def initializePage(self):
         """Setup UI details."""
+        logger.debug('initializePage - About to show SetupAccountPage')
         # Set Setup Account button
         self.wizard().setOption(QtGui.QWizard.HaveCustomButton3, True)
         try:
@@ -157,7 +158,6 @@
 
     def _set_translated_strings(self):
         """Set the strings."""
-        logger.debug('SetUpAccountPage._set_translated_strings')
         # set the translated string
         title_page = REGISTER_TITLE.format(app_name=self.app_name)
         self.setTitle(title_page)
@@ -225,7 +225,6 @@
 
     def _connect_ui(self):
         """Set the connection of signals."""
-        logger.debug('SetUpAccountPage._connect_ui')
         self._set_line_edits_validations()
 
         self.ui.captcha_view.setPixmap(QtGui.QPixmap())
@@ -302,11 +301,9 @@
         self.registerField('email_address', self.ui.email_edit)
         self.registerField('password', self.ui.password_edit)
 
+    @log_call(logger.debug)
     def on_captcha_generated(self, app_name, result):
         """A new image was generated."""
-        logger.debug('SetUpAccountPage.on_captcha_generated for %r '
-                     '(captcha id %r, filename %r).',
-                     app_name, result, self.captcha_file)
         self.captcha_id = result
         # HACK: First, let me apologize before hand, you can mention my mother
         # if needed I would do the same (mandel)
@@ -327,13 +324,13 @@
 
     def on_captcha_generation_error(self, error, *args, **kwargs):
         """An error ocurred."""
-        logger.debug('SetUpAccountPage.on_captcha_generation_error')
+        logger.error('Got error on captcha generation: %s', error)
         self.show_error(self.app_name, CAPTCHA_LOAD_ERROR)
         self.on_captcha_refresh_complete()
 
+    @log_call(logger.error)
     def on_user_registration_error(self, app_name, error):
         """Let the user know we could not register."""
-        logger.debug('SetUpAccountPage.on_user_registration_error')
         # errors are returned as a dict with the data we want to show.
         msg = error.pop(ERROR_EMAIL, '')
         if msg:
@@ -343,10 +340,10 @@
             self.show_error(self.app_name, error_msg)
         self._refresh_captcha()
 
+    @log_call(logger.info)
     def on_user_registered(self, app_name, email):
         """Execute when the user did register."""
         self.hide_overlay()
-        logger.debug('SetUpAccountPage.on_user_registered')
         email = unicode(self.ui.email_edit.text())
         self.userRegistered.emit(email)
 
@@ -406,17 +403,14 @@
 
     def is_correct_email(self, email_address):
         """Return if the email is correct."""
-        logger.debug('SetUpAccountPage.is_correct_email')
         return '@' in email_address
 
     def is_correct_email_confirmation(self, email_address):
         """Return that the email is the same."""
-        logger.debug('SetUpAccountPage.is_correct_email_confirmation')
         return unicode(self.ui.email_edit.text()) == email_address
 
     def is_correct_password_confirmation(self, password):
         """Return that the passwords are correct."""
-        logger.debug('SetUpAccountPage.is_correct_password_confirmation')
         return unicode(self.ui.password_edit.text()) == password
 
     def focus_changed(self, old, now):
@@ -505,12 +499,14 @@
 
     def on_captcha_refreshing(self):
         """Show overlay when captcha is refreshing."""
+        logger.info('SetUpAccountPage.on_captcha_refreshing')
         if self.isVisible():
             self.show_overlay()
         self.captcha_received = False
 
     def on_captcha_refresh_complete(self):
         """Hide overlay when captcha finished refreshing."""
+        logger.info('SetUpAccountPage.on_captcha_refresh_complete')
         self.hide_overlay()
         self.captcha_received = True
 

=== modified file 'ubuntu_sso/qt/sso_wizard_page.py'
--- ubuntu_sso/qt/sso_wizard_page.py	2012-03-05 21:18:15 +0000
+++ ubuntu_sso/qt/sso_wizard_page.py	2012-03-09 17:35:23 +0000
@@ -33,7 +33,7 @@
 from twisted.internet import defer
 
 from ubuntu_sso import main
-from ubuntu_sso.logger import setup_gui_logging
+from ubuntu_sso.logger import setup_gui_logging, log_call
 from ubuntu_sso.qt import PREFERED_UI_SIZE, TITLE_STYLE
 from ubuntu_sso.utils.ui import GENERIC_BACKEND_ERROR
 
@@ -129,6 +129,7 @@
 
         self.setup_page()
 
+    @log_call(logger.error)
     def show_error(self, app_name, message):
         """Show an error message inside the page."""
         self.hide_overlay()
@@ -159,7 +160,7 @@
         """Setup the widget components."""
         client = yield main.get_sso_client()
         self.backend = client.sso_login
-
+        logger.info('%r - setup_page, backend is %r.', self, self.backend)
         self._setup_signals()
         self._set_translated_strings()
         self._connect_ui()

=== modified file 'ubuntu_sso/qt/tests/login_u_p.py'
--- ubuntu_sso/qt/tests/login_u_p.py	2012-01-26 15:34:16 +0000
+++ ubuntu_sso/qt/tests/login_u_p.py	2012-03-09 17:35:23 +0000
@@ -39,7 +39,6 @@
 
     def found(*args):
         """The result was received."""
-        print "result received", args
         d.callback(args)
 
     client.cred_manager.connect_to_signal('CredentialsFound', found)
@@ -61,7 +60,6 @@
     yield cleared
 
     yield client.cred_manager.login_email_password('SUPER', args)
-    print "called ok"
     yield d
 
     yield client.disconnect()

=== modified file 'ubuntu_sso/qt/tests/show_gui.py'
--- ubuntu_sso/qt/tests/show_gui.py	2012-02-10 17:18:22 +0000
+++ ubuntu_sso/qt/tests/show_gui.py	2012-03-09 17:35:23 +0000
@@ -46,7 +46,6 @@
 
     def found(*args):
         """The result was received."""
-        print "result received", args
         d.callback(args)
 
     client.cred_manager.connect_to_signal('CredentialsFound', found)
@@ -62,7 +61,6 @@
             TC_URL_KEY: u'http://www.google.com/',
             UI_EXECUTABLE_KEY: 'ubuntu-sso-login-gtk',
         })
-    print "called ok"
     yield d
 
     yield client.disconnect()

=== modified file 'ubuntu_sso/qt/ubuntu_sso_wizard.py'
--- ubuntu_sso/qt/ubuntu_sso_wizard.py	2012-03-05 21:08:40 +0000
+++ ubuntu_sso/qt/ubuntu_sso_wizard.py	2012-03-09 17:35:23 +0000
@@ -141,6 +141,8 @@
 
     def _go_back_to_page(self, page):
         """Move back until it reaches the 'page'."""
+        logger.debug('Moving back from page: %s, to page: %s',
+            self.currentPage(), page)
         page_id = self._pages[page]
         visited_pages = self.visitedPages()
         for index in reversed(visited_pages):
@@ -150,12 +152,16 @@
 
     def _move_to_reset_password_page(self):
         """Move to the reset password page wizard."""
+        logger.debug('Moving to ResetPasswordPage from: %s',
+            self.currentPage())
         self._next_id = self.reset_password_page_id
         self.next()
         self._next_id = -1
 
     def _move_to_email_verification_page(self, email):
         """Move to the email verification page wizard."""
+        logger.debug('Moving to EmailVerificationPage from: %s',
+            self.currentPage())
         self._next_id = self.email_verification_page_id
         self.email_verification.email = unicode(email)
         self.email_verification.password = self.currentPage().password
@@ -164,18 +170,24 @@
 
     def _move_to_setup_account_page(self):
         """Move to the setup account page wizard."""
+        logger.debug('Moving to SetupAccountPage from: %s',
+            self.currentPage())
         self._next_id = self.setup_account_page_id
         self.next()
         self._next_id = -1
 
     def _move_to_login_page(self):
         """Move to the login page wizard."""
+        logger.debug('Moving to CurrentUserSignInPage from: %s',
+            self.currentPage())
         self._next_id = self.current_user_page_id
         self.next()
         self._next_id = -1
 
     def _move_to_success_page(self):
         """Move to the success page wizard."""
+        logger.debug('Moving to SuccessPage from: %s',
+            self.currentPage())
         self._next_id = self.success_page_id
         self.next()
         self.setButtonLayout([
@@ -188,6 +200,8 @@
 
     def _move_to_forgotten_page(self):
         """Move to the forgotten page wizard."""
+        logger.debug('Moving to ForgottenPasswordPage from: %s',
+            self.currentPage())
         self._next_id = self.forgotten_password_page_id
         self.next()
         self._next_id = -1