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

Proposed by Данило Шеган
Status: Merged
Approved by: Данило Шеган
Approved revision: no longer in the source branch.
Merged at revision: 13679
Proposed branch: lp:~danilo/launchpad/bug-820511
Merge into: lp:launchpad
Diff against target: 188 lines (+42/-19)
7 files modified
lib/lp/code/scripts/tests/test_create_merge_proposals.py (+3/-2)
lib/lp/code/scripts/tests/test_merge_proposal_jobs.py (+3/-1)
lib/lp/code/scripts/tests/test_reclaim_branch_space.py (+3/-1)
lib/lp/code/scripts/tests/test_sendbranchmail.py (+6/-4)
lib/lp/services/job/runner.py (+13/-4)
lib/lp/services/job/tests/test_runner.py (+12/-7)
lib/lp/translations/scripts/tests/test_packaging_translations.py (+2/-0)
To merge this branch: bzr merge lp:~danilo/launchpad/bug-820511
Reviewer Review Type Date Requested Status
j.c.sackett (community) Approve
Review via email: mp+71179@code.launchpad.net

Commit message

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

Description of the change

= 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

To post a comment you must log in.
Revision history for this message
j.c.sackett (jcsackett) wrote :

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
Revision history for this message
Данило Шеган (danilo) wrote :

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.

Preview Diff

[H/L] Next/Prev Comment, [J/K] Next/Prev File, [N/P] Next/Prev Hunk
1=== modified file 'lib/lp/code/scripts/tests/test_create_merge_proposals.py'
2--- lib/lp/code/scripts/tests/test_create_merge_proposals.py 2010-10-04 19:50:45 +0000
3+++ lib/lp/code/scripts/tests/test_create_merge_proposals.py 2011-08-12 13:56:33 +0000
4@@ -33,7 +33,7 @@
5 email, file_alias, source, target = (
6 self.factory.makeMergeDirectiveEmail(
7 signing_context=signing_context))
8- CreateMergeProposalJob.create(file_alias)
9+ job = CreateMergeProposalJob.create(file_alias)
10 self.assertEqual(0, source.landing_targets.count())
11 transaction.commit()
12 retcode, stdout, stderr = run_script(
13@@ -41,7 +41,8 @@
14 self.assertEqual(0, retcode)
15 self.assertEqual(
16 'INFO Creating lockfile: /var/lock/launchpad-create_merge_proposals.lock\n'
17- 'INFO Ran 1 CreateMergeProposalJobs.\n', stderr)
18+ 'INFO Running CreateMergeProposalJob (ID %d) in status Waiting\n'
19+ 'INFO Ran 1 CreateMergeProposalJobs.\n' % job.job.id, stderr)
20 self.assertEqual('', stdout)
21 self.assertEqual(1, source.landing_targets.count())
22
23
24=== modified file 'lib/lp/code/scripts/tests/test_merge_proposal_jobs.py'
25--- lib/lp/code/scripts/tests/test_merge_proposal_jobs.py 2010-12-02 16:13:51 +0000
26+++ lib/lp/code/scripts/tests/test_merge_proposal_jobs.py 2011-08-12 13:56:33 +0000
27@@ -34,7 +34,9 @@
28 'INFO Creating lockfile:'
29 ' /var/lock/launchpad-merge-proposal-jobs.lock\n'
30 'INFO Running through Twisted.\n'
31- 'INFO Ran 1 GenerateIncrementalDiffJob jobs.\n', stderr)
32+ 'INFO Running GenerateIncrementalDiffJob (ID %d).\n'
33+ 'INFO Ran 1 GenerateIncrementalDiffJob jobs.\n' % job.job.id,
34+ stderr)
35 self.assertEqual(JobStatus.COMPLETED, job.status)
36
37
38
39=== modified file 'lib/lp/code/scripts/tests/test_reclaim_branch_space.py'
40--- lib/lp/code/scripts/tests/test_reclaim_branch_space.py 2010-10-04 19:50:45 +0000
41+++ lib/lp/code/scripts/tests/test_reclaim_branch_space.py 2011-08-12 13:56:33 +0000
42@@ -66,7 +66,9 @@
43 self.assertEqual('', stdout)
44 self.assertEqual(
45 'INFO Creating lockfile: /var/lock/launchpad-reclaimbranchspace.lock\n'
46- 'INFO Reclaimed space for 1 branches.\n', stderr)
47+ 'INFO Running ReclaimBranchSpaceJob (ID %d) in status Waiting\n'
48+ 'INFO Reclaimed space for 1 branches.\n' % reclaim_job.job.id,
49+ stderr)
50 self.assertEqual(0, retcode)
51 self.assertFalse(
52 os.path.exists(mirrored_path))
53
54=== modified file 'lib/lp/code/scripts/tests/test_sendbranchmail.py'
55--- lib/lp/code/scripts/tests/test_sendbranchmail.py 2011-07-18 20:46:27 +0000
56+++ lib/lp/code/scripts/tests/test_sendbranchmail.py 2011-08-12 13:56:33 +0000
57@@ -49,14 +49,15 @@
58 """Ensure sendbranchmail runs and sends email."""
59 self.useBzrBranches()
60 branch, tree = self.createBranch()
61- RevisionMailJob.create(
62+ mail_job = RevisionMailJob.create(
63 branch, 1, 'from@example.org', 'body', True, 'foo')
64 transaction.commit()
65 retcode, stdout, stderr = run_script(
66 'cronscripts/sendbranchmail.py', [])
67 self.assertEqual(
68 'INFO Creating lockfile: /var/lock/launchpad-sendbranchmail.lock\n'
69- 'INFO Ran 1 RevisionMailJobs.\n', stderr)
70+ 'INFO Running RevisionMailJob (ID %d) in status Waiting\n'
71+ 'INFO Ran 1 RevisionMailJobs.\n' % mail_job.job.id, stderr)
72 self.assertEqual('', stdout)
73 self.assertEqual(0, retcode)
74
75@@ -86,14 +87,15 @@
76 # required to generate the revision-id.
77 with override_environ(BZR_EMAIL='me@example.com'):
78 tree.commit('Added foo.', rev_id='rev2')
79- RevisionsAddedJob.create(
80+ job = RevisionsAddedJob.create(
81 branch, 'rev1', 'rev2', 'from@example.org')
82 transaction.commit()
83 retcode, stdout, stderr = run_script(
84 'cronscripts/sendbranchmail.py', [])
85 self.assertEqual(
86 'INFO Creating lockfile: /var/lock/launchpad-sendbranchmail.lock\n'
87- 'INFO Ran 1 RevisionMailJobs.\n',
88+ 'INFO Running RevisionsAddedJob (ID %d) in status Waiting\n'
89+ 'INFO Ran 1 RevisionMailJobs.\n' % job.job.id,
90 stderr)
91 self.assertEqual('', stdout)
92 self.assertEqual(0, retcode)
93
94=== modified file 'lib/lp/services/job/runner.py'
95--- lib/lp/services/job/runner.py 2011-06-21 13:24:57 +0000
96+++ lib/lp/services/job/runner.py 2011-08-12 13:56:33 +0000
97@@ -182,8 +182,11 @@
98 """Attempt to run a job, updating its status as appropriate."""
99 job = IRunnableJob(job)
100
101- self.logger.debug(
102- 'Running job in status %s' % (job.status.title,))
103+ class_name = job.__class__.__name__
104+ job_id = removeSecurityProxy(job).job.id
105+ self.logger.info(
106+ 'Running %s (ID %d) in status %s' % (
107+ class_name, job_id, job.status.title,))
108 job.start()
109 transaction.commit()
110 do_retry = False
111@@ -402,10 +405,10 @@
112 packages=('_pythonpath', 'twisted', 'ampoule'), env=env)
113 super(TwistedJobRunner, self).__init__(logger, error_utility)
114 self.job_source = job_source
115- import_name = '%s.%s' % (
116+ self.import_name = '%s.%s' % (
117 removeSecurityProxy(job_source).__module__, job_source.__name__)
118 self.pool = pool.ProcessPool(
119- JobRunnerProcess, ampChildArgs=[import_name, str(dbuser)],
120+ JobRunnerProcess, ampChildArgs=[self.import_name, str(dbuser)],
121 starter=starter, min=0, timeout_signal=SIGHUP)
122
123 def runJobInSubprocess(self, job):
124@@ -423,6 +426,12 @@
125 transaction.commit()
126 job_id = job.id
127 deadline = timegm(job.lease_expires.timetuple())
128+
129+ # Log the job class and database ID for debugging purposes.
130+ class_name = job.__class__.__name__
131+ ijob_id = removeSecurityProxy(job).job.id
132+ self.logger.info(
133+ 'Running %s (ID %d).' % (class_name, ijob_id))
134 self.logger.debug(
135 'Running %r, lease expires %s', job, job.lease_expires)
136 deferred = self.pool.doWork(
137
138=== modified file 'lib/lp/services/job/tests/test_runner.py'
139--- lib/lp/services/job/tests/test_runner.py 2011-07-05 09:01:53 +0000
140+++ lib/lp/services/job/tests/test_runner.py 2011-08-12 13:56:33 +0000
141@@ -539,6 +539,8 @@
142 self.assertThat(logger.getLogBuffer(), MatchesRegex(
143 dedent("""\
144 INFO Running through Twisted.
145+ INFO Running StuckJob \(ID .*\).
146+ INFO Running StuckJob \(ID .*\).
147 INFO Job resulted in OOPS: .*
148 """)))
149
150@@ -559,13 +561,16 @@
151 oops = self.getOopsReport(runner, 0)
152 self.assertEqual(
153 (1, 1), (len(runner.completed_jobs), len(runner.incomplete_jobs)))
154- self.assertEqual(
155- (dedent("""\
156- INFO Running through Twisted.
157- INFO Job resulted in OOPS: %s
158- """) % oops.id,
159- 'TimeoutError', 'Job ran too long.'),
160- (logger.getLogBuffer(), oops.type, oops.value))
161+ self.assertThat(
162+ logger.getLogBuffer(), MatchesRegex(
163+ dedent("""\
164+ INFO Running through Twisted.
165+ INFO Running ShorterStuckJob \(ID .*\).
166+ INFO Running ShorterStuckJob \(ID .*\).
167+ INFO Job resulted in OOPS: %s
168+ """) % oops.id))
169+ self.assertEqual(('TimeoutError', 'Job ran too long.'),
170+ (oops.type, oops.value))
171
172 def test_previous_failure_gives_new_process(self):
173 """Failed jobs cause their worker to be terminated.
174
175=== modified file 'lib/lp/translations/scripts/tests/test_packaging_translations.py'
176--- lib/lp/translations/scripts/tests/test_packaging_translations.py 2011-05-19 14:40:55 +0000
177+++ lib/lp/translations/scripts/tests/test_packaging_translations.py 2011-08-12 13:56:33 +0000
178@@ -34,8 +34,10 @@
179 matcher = MatchesRegex(dedent("""\
180 INFO Creating lockfile: /var/lock/launchpad-jobcronscript.lock
181 INFO Running synchronously.
182+ INFO Running TranslationMergeJob \(ID .*\) in status Waiting
183 INFO Merging .* and .* in Ubuntu Distroseries.*
184 INFO Deleted POTMsgSets: 1. TranslationMessages: 1.
185+ INFO Running TranslationSplitJob \(ID .*\) in status Waiting
186 INFO Splitting .* and .* in Ubuntu Distroseries.*
187 INFO Ran 1 TranslationMergeJob jobs.
188 INFO Ran 1 TranslationSplitJob jobs.