Merge lp:~danilo/launchpad/bug-820511 into lp:launchpad

[Данило Шеган]

[r=jcsackett][bug=820511] Log Job IDs on INFO level when running jobs to ease debugging efforts when things go wrong.

= Bug 820511 =

Log the job ID and class name on the INFO level in the runner.

== Tests ==

bin/test -cvvt test_runner

== Demo and Q/A ==

Run any jobs (eg. cronscripts/run_jobs.py packaging_translations) with no -v parameters and note how job ID is listed along with the class name.

= Launchpad lint =

Checking for conflicts and issues in changed files.

Linting changed files:
  lib/lp/services/job/runner.py
  lib/lp/services/job/tests/test_runner.py

[j.c.sackett (jcsackett)]

This looks good. It'll certainly be easier to debug jobs this way.

One question, though.

> 18 @@ -262,7 +265,8 @@
> 19 def _logOopsId(self, oops_id):
> 20 """Report oopses by id to the log."""
> 21 if self.logger is not None:
> 22 - self.logger.info('Job resulted in OOPS: %s' % oops_id)
> 23 + self.logger.info('Job resulted in OOPS: %s' % (
> 24 + oops_id))
> 25 self.oops_ids.append(oops_id)

I'm not sure I see the need for this change; it doesn't look like the line was over the character limit, and functionally the two are identical, aren't they?

Given that I think they're identical, this doesn't block approval, I'm just curious what the intent was.

review: Approve

[Данило Шеган (danilo)]

The intent was to add the job ID to this line as well, and then that was reverted :) Reverting this change altogether, thanks for catching it. And thanks for the review.

=== modified file 'lib/lp/code/scripts/tests/test_create_merge_proposals.py'
--- lib/lp/code/scripts/tests/test_create_merge_proposals.py	2010-10-04 19:50:45 +0000
+++ lib/lp/code/scripts/tests/test_create_merge_proposals.py	2011-08-12 13:56:33 +0000
@@ -33,7 +33,7 @@
         email, file_alias, source, target = (
             self.factory.makeMergeDirectiveEmail(
                 signing_context=signing_context))
-        CreateMergeProposalJob.create(file_alias)
+        job = CreateMergeProposalJob.create(file_alias)
         self.assertEqual(0, source.landing_targets.count())
         transaction.commit()
         retcode, stdout, stderr = run_script(
@@ -41,7 +41,8 @@
         self.assertEqual(0, retcode)
         self.assertEqual(
             'INFO    Creating lockfile: /var/lock/launchpad-create_merge_proposals.lock\n'
-            'INFO    Ran 1 CreateMergeProposalJobs.\n', stderr)
+            'INFO    Running CreateMergeProposalJob (ID %d) in status Waiting\n'
+            'INFO    Ran 1 CreateMergeProposalJobs.\n' % job.job.id, stderr)
         self.assertEqual('', stdout)
         self.assertEqual(1, source.landing_targets.count())
 
 
=== modified file 'lib/lp/code/scripts/tests/test_merge_proposal_jobs.py'
--- lib/lp/code/scripts/tests/test_merge_proposal_jobs.py	2010-12-02 16:13:51 +0000
+++ lib/lp/code/scripts/tests/test_merge_proposal_jobs.py	2011-08-12 13:56:33 +0000
@@ -34,7 +34,9 @@
             'INFO    Creating lockfile:'
             ' /var/lock/launchpad-merge-proposal-jobs.lock\n'
             'INFO    Running through Twisted.\n'
-            'INFO    Ran 1 GenerateIncrementalDiffJob jobs.\n', stderr)
+            'INFO    Running GenerateIncrementalDiffJob (ID %d).\n'
+            'INFO    Ran 1 GenerateIncrementalDiffJob jobs.\n' % job.job.id,
+            stderr)
         self.assertEqual(JobStatus.COMPLETED, job.status)
 
 
 
=== modified file 'lib/lp/code/scripts/tests/test_reclaim_branch_space.py'
--- lib/lp/code/scripts/tests/test_reclaim_branch_space.py	2010-10-04 19:50:45 +0000
+++ lib/lp/code/scripts/tests/test_reclaim_branch_space.py	2011-08-12 13:56:33 +0000
@@ -66,7 +66,9 @@
         self.assertEqual('', stdout)
         self.assertEqual(
             'INFO    Creating lockfile: /var/lock/launchpad-reclaimbranchspace.lock\n'
-            'INFO    Reclaimed space for 1 branches.\n', stderr)
+            'INFO    Running ReclaimBranchSpaceJob (ID %d) in status Waiting\n'
+            'INFO    Reclaimed space for 1 branches.\n' % reclaim_job.job.id,
+            stderr)
         self.assertEqual(0, retcode)
         self.assertFalse(
             os.path.exists(mirrored_path))
 
=== modified file 'lib/lp/code/scripts/tests/test_sendbranchmail.py'
--- lib/lp/code/scripts/tests/test_sendbranchmail.py	2011-07-18 20:46:27 +0000
+++ lib/lp/code/scripts/tests/test_sendbranchmail.py	2011-08-12 13:56:33 +0000
@@ -49,14 +49,15 @@
         """Ensure sendbranchmail runs and sends email."""
         self.useBzrBranches()
         branch, tree = self.createBranch()
-        RevisionMailJob.create(
+        mail_job = RevisionMailJob.create(
             branch, 1, '[e-mail]', 'body', True, 'foo')
         transaction.commit()
         retcode, stdout, stderr = run_script(
             'cronscripts/sendbranchmail.py', [])
         self.assertEqual(
             'INFO    Creating lockfile: /var/lock/launchpad-sendbranchmail.lock\n'
-            'INFO    Ran 1 RevisionMailJobs.\n', stderr)
+            'INFO    Running RevisionMailJob (ID %d) in status Waiting\n'
+            'INFO    Ran 1 RevisionMailJobs.\n' % mail_job.job.id, stderr)
         self.assertEqual('', stdout)
         self.assertEqual(0, retcode)
 
@@ -86,14 +87,15 @@
         # required to generate the revision-id.
         with override_environ(BZR_EMAIL='[e-mail]'):
             tree.commit('Added foo.', rev_id='rev2')
-        RevisionsAddedJob.create(
+        job = RevisionsAddedJob.create(
             branch, 'rev1', 'rev2', '[e-mail]')
         transaction.commit()
         retcode, stdout, stderr = run_script(
             'cronscripts/sendbranchmail.py', [])
         self.assertEqual(
             'INFO    Creating lockfile: /var/lock/launchpad-sendbranchmail.lock\n'
-            'INFO    Ran 1 RevisionMailJobs.\n',
+            'INFO    Running RevisionsAddedJob (ID %d) in status Waiting\n'
+            'INFO    Ran 1 RevisionMailJobs.\n' % job.job.id,
             stderr)
         self.assertEqual('', stdout)
         self.assertEqual(0, retcode)
 
=== modified file 'lib/lp/services/job/runner.py'
--- lib/lp/services/job/runner.py	2011-06-21 13:24:57 +0000
+++ lib/lp/services/job/runner.py	2011-08-12 13:56:33 +0000
@@ -182,8 +182,11 @@
         """Attempt to run a job, updating its status as appropriate."""
         job = IRunnableJob(job)
 
-        self.logger.debug(
-            'Running job in status %s' % (job.status.title,))
+        class_name = job.__class__.__name__
+        job_id = removeSecurityProxy(job).job.id
+        self.logger.info(
+            'Running %s (ID %d) in status %s' % (
+                class_name, job_id, job.status.title,))
         job.start()
         transaction.commit()
         do_retry = False
@@ -402,10 +405,10 @@
             packages=('_pythonpath', 'twisted', 'ampoule'), env=env)
         super(TwistedJobRunner, self).__init__(logger, error_utility)
         self.job_source = job_source
-        import_name = '%s.%s' % (
+        self.import_name = '%s.%s' % (
             removeSecurityProxy(job_source).__module__, job_source.__name__)
         self.pool = pool.ProcessPool(
-            JobRunnerProcess, ampChildArgs=[import_name, str(dbuser)],
+            JobRunnerProcess, ampChildArgs=[self.import_name, str(dbuser)],
             starter=starter, min=0, timeout_signal=SIGHUP)
 
     def runJobInSubprocess(self, job):
@@ -423,6 +426,12 @@
         transaction.commit()
         job_id = job.id
         deadline = timegm(job.lease_expires.timetuple())
+
+        # Log the job class and database ID for debugging purposes.
+        class_name = job.__class__.__name__
+        ijob_id = removeSecurityProxy(job).job.id
+        self.logger.info(
+            'Running %s (ID %d).' % (class_name, ijob_id))
         self.logger.debug(
             'Running %r, lease expires %s', job, job.lease_expires)
         deferred = self.pool.doWork(
 
=== modified file 'lib/lp/services/job/tests/test_runner.py'
--- lib/lp/services/job/tests/test_runner.py	2011-07-05 09:01:53 +0000
+++ lib/lp/services/job/tests/test_runner.py	2011-08-12 13:56:33 +0000
@@ -539,6 +539,8 @@
         self.assertThat(logger.getLogBuffer(), MatchesRegex(
             dedent("""\
             INFO Running through Twisted.
+            INFO Running StuckJob \(ID .*\).
+            INFO Running StuckJob \(ID .*\).
             INFO Job resulted in OOPS: .*
             """)))
 
@@ -559,13 +561,16 @@
         oops = self.getOopsReport(runner, 0)
         self.assertEqual(
             (1, 1), (len(runner.completed_jobs), len(runner.incomplete_jobs)))
-        self.assertEqual(
-            (dedent("""\
-             INFO Running through Twisted.
-             INFO Job resulted in OOPS: %s
-             """) % oops.id,
-             'TimeoutError', 'Job ran too long.'),
-            (logger.getLogBuffer(), oops.type, oops.value))
+        self.assertThat(
+            logger.getLogBuffer(), MatchesRegex(
+                dedent("""\
+                INFO Running through Twisted.
+                INFO Running ShorterStuckJob \(ID .*\).
+                INFO Running ShorterStuckJob \(ID .*\).
+                INFO Job resulted in OOPS: %s
+                """) % oops.id))
+        self.assertEqual(('TimeoutError', 'Job ran too long.'),
+                         (oops.type, oops.value))
 
     def test_previous_failure_gives_new_process(self):
         """Failed jobs cause their worker to be terminated.
 
=== modified file 'lib/lp/translations/scripts/tests/test_packaging_translations.py'
--- lib/lp/translations/scripts/tests/test_packaging_translations.py	2011-05-19 14:40:55 +0000
+++ lib/lp/translations/scripts/tests/test_packaging_translations.py	2011-08-12 13:56:33 +0000
@@ -34,8 +34,10 @@
         matcher = MatchesRegex(dedent("""\
             INFO    Creating lockfile: /var/lock/launchpad-jobcronscript.lock
             INFO    Running synchronously.
+            INFO    Running TranslationMergeJob \(ID .*\) in status Waiting
             INFO    Merging .* and .* in Ubuntu Distroseries.*
             INFO    Deleted POTMsgSets: 1.  TranslationMessages: 1.
+            INFO    Running TranslationSplitJob \(ID .*\) in status Waiting
             INFO    Splitting .* and .* in Ubuntu Distroseries.*
             INFO    Ran 1 TranslationMergeJob jobs.
             INFO    Ran 1 TranslationSplitJob jobs.