Porting to PySide/QML: Notification Bar

I keep hearing about how great QML is to learn so I'm a bit baffled as to why I am still having such a hard time with getting more than a toy program written.  I'm trying to save my rant about that once I've gotten an application completed and can help provide more useful feedback.  In the mean time I wanted to cover a set of changes to my python code that will made the QML port a bit easier.  This is regarding code to make it easy both for users to provide good bug reports and for me to figure out what went wrong.

tl;dr

Some sample programs that demonstrate the ideas in this post

• Reporting python logging events to the user
• Logging helpers

I. print "This isn't right!"

Early on in developing for Maemo my applications made use of "print" statement and the "warning" module.  The steps needed to report an issue were

1. Suspect something is wrong
2. Close Application
3. Open terminal
4. APPLICATION > log
5. Hope the problem will be able to be reproduced
6. Close application
7. Email log file and try to remember to include context like device / maemo version and app version

Its bad enough the user has to do anything but with this they had to use the terminal and reproduce the problem.

Once I even got a log its value was only as good as what I decided to print out to it.  I only got what I put into it which was pretty simple with few indications of where I was even printing.

II. logging.warn("Just a touch bit better")

Once I made it over the hurdle of adapting to the logging module things improved drastically.

1. Suspect something is wrong
2. Hit Ctrl+i
3. Paste into a text editor
4. Email resulting file

That is better but still too much friction for users to report problems.  The quality of the logs is a lot better though.  Off the bat logging offered the following

• Levels
• Time stamps
• logging.exception records the timestamp

Logging Locations:

Originally I used the root logger.  Eventually I found out about per-module loggers (you can even do more granular loggers but I've not seen the need).

At the top of each module I have:

_moduleLogger = logging.getLogger(__name__)

Then rather than

try:
   a = []
   a[0]
except:
   logging.exception("This isn't good")

ERROR root: Internal Error: 'NoneType' object has no attribute 'scene'
Traceback (most recent call last):
...
AttributeError: 'NoneType' object has no attribute 'scene'

I do

try:
   a = []
   a[0]
except:
   _moduleLogger.exception("This isn't good")

ERROR module_name: Internal Error: 'NoneType' object has no attribute 'scene'
Traceback (most recent call last):
...
AttributeError: 'NoneType' object has no attribute 'scene'


Log Destination:

I originally had the problem that I either logged to a file or logged to the console.  The console was nice for my debugging on the desktop while a file was mandatory for users to avoid the command line when collecting debug information.  I resolved this by having separate scripts each initialize different logging destinations.  Another problem was log bloat.  I had resolved that by deleting the log on upgrade.  Unfortunately as my software matured, upgrades became infrequent and logs grew.  So I settled on the following:

logFormat = '(%(relativeCreated)5d) %(levelname)-5s %(threadName)s.%(name)s.%(funcName)s: %(message)s'
logging.basicConfig(level=logging.DEBUG, format=logFormat)

rotating = logging.handlers.RotatingFileHandler(logPath, maxBytes=512*1024, backupCount=1)
rotating.setFormatter(logging.Formatter(logFormat))

root = logging.getLogger()
root.addHandler(rotating)
_moduleLogger.debug("%s %s-%s", constants.APP_NAME, constants.VERSION, constants.BUILD)
_moduleLogger.debug("OS: %s", os.uname()[0])
_moduleLogger.debug("Kernel: %s (%s) for %s", *os.uname()[2:])
_moduleLogger.debug("Hostname: %s", os.uname()[1])

With adding a second handler (size limited one at that) I am now getting both stdout and file logging.  You'll also see demonstrated:

• Time stamps
• Thread information
• Module name
• Function name
• Logging OS information / App information

logging.exception:

To help with logging exceptions I created a decorator to log all exceptions that escape my application.  For a Qt application this would be around the slots.

@PySide.Slot()
@misc.log_exception(_moduleLogger)
def _on_shown(self):
    1/0

ERROR module_name: Internal Error: ZeroDivisionError: integer division or modulo by zero
Traceback (most recent call last):
...
ZeroDivisionError: integer division or modulo by zero

III. self._errorLog.push_error("Inform the user")

I eventually generalized the error reporting system of one of my applications to mimic Firefox-style notification bars.  I separated this out into a view / model and added some helpers to provide similar features to my logging code.  This does a great job of taking the guess work away from the user of determining what is expected behavior when they see something they think is strange.

Examples of some helpers:

with qui_utils.notify_error(self._errorLog):
   1/0
with qui_utils.notify_busy(self._errorLog, "Counting..."):

   ... Long Running Background Thread Task...

The log model had to be passed around to each instance that wanted to report problems which worked fairly well for Qt/QWidget especially since I did a horrible job separating logic into MVC.  For QML I didn't want to have to do that for every one of my models that QML required me to have.

IV. Logging, QML, and Notification Bars

To resolve the issue of reporting to the user issues without every model having "self._errorLog" I decided to create my own log handler.  Now I am able to easily notify the user of internal errors from anywhere in my program (please excuse my python and QML, I'm still struggling with what I think is the "right" way to do structure / write a Python/QML app).

Things that could be improved:

• It can only handle a discrete set of log levels
• The notification bar looks need drastic improvements
• Possibly add a notification count bubble for when there are several active notifications
• Somehow expose one or all of the following:
• all active notifications list view
• more of the message than the first line
• emailing the application developer the full log

If I get all of those improvements done, the user experience will be:

1. Get a notification of an internal error
2. Select "send report" or later hit Ctrl+i

V. Ode to Python

All of this would have been a lot more work, a lot uglier, and without as much useful information if I was doing this all in C++.  It has made a big difference in improving the error reports I've gotten from users so I can more quickly resolve their problems.  I just wish I had such powerful tools at my day job where I do C++ development.

Now back to struggling with QML.