Thursday, July 28, 2016

Notification framework

This morning I believed that ticket #1079 should be solved now, and so I did a relase in The Châtelet variant of Lino Welfare. But nope, it seems that it is not solved. The rest of my workday went into finding bugs and writing test cases for the notification framework, partly with some more changes to the API.

It was intensive work which required long-term concentration, but now Lino Welfare also has a new tested document Notifications in Lino Welfare, and the automatic tests in lino_welfare.projects.std.tests.test_notify are now more or less complete. It was really time to write these test cases!

I removed the get_actors_module() method and instead, at startup, set default values for rt.actors from rt.models.

During the release I also stumbled over the following problem which took me at least two hours.

Supervisor failed to terminate linod

In The Châtelet variant of Lino Welfare they were having a big Lino log file which is filled with lines as the following:

201607-24 13:02:44 INFO __init__ : Running job Every 10 seconds do send_pending_emails() (last run: 2016-07-24 13:02:34, next run: 2016-07-24 13:02:44)

I immediately guessed that it had to do with the logger configuration for schedule. The schedule module is clear and simple, it does this:

import logging
logger = logging.getLogger('schedule')

class Job(object):

    def run(self):
        """Run the job and immediately reschedule it."""
        logger.info('Running job %s', self)
        ret = self.job_func()
        self.last_run = datetime.datetime.now()
        self._schedule_next_run()
        return ret

So indeed we must set the schedule logger level to WARNING. lino.core.site.Site.setup_logging() does this now.

I then did a lot of Lino commits because the change “somehow didn’t work”, and I thought that the problem had to do with the logger configuration.

The actual guilty was supervisor: for some reason (I guess because I had changed several times the actual name of the linod process to start) there were a dozen of linod processes running, and of course these processes continued to to their work trustfully…

TIL: when you change the configuration of supervisor, make sure that any old processes have been stopped!

Later I realized that it was not at all inadvertance when playing with configuration. Supervisor did not terminate the process correctly: it created two processes and killed only one of them. Other Supervisor users helped my to understand why: it was because the linod.sh script spawned a subprocess which (for some reason) was not seen by Supervisor and therfore remained alive. And that the problem must be solved by adding an exec to the linod.sh script. As I (now) explain in admin.linod.