This error occurs when a unit test file has more than one test which runs cronscripts.
The branch lp:~adeuring/launchpad/cronscript-for-hwdb-report-fixes
has several tests which run a cronscript in
lib/lp/hardwaredb/scripts/tests/test_hwdbsubmissions.py
(test_run_reprocessing_script.*)
If only one of these tests is run, it passes without any problem.
If two of these tests are run, they pass too, but the second test
leaves these lines in /var/log/postgresql/postgresql-8.4-main.log for the
second script:
[2011-09-13 16:25:28 CEST] hwdb-submission-processor@launchpad_ftest_19275 LOG: statement: INSERT INTO ScriptActivity (date_completed, date_started, hostname, name) VALUES (E'2011-09-13 14:25:28.819243+00:00', E'2011-09-13 14:25:28.816929+00:00', E'klato5', E'hwdbsubmissions') RETURNING ScriptActivity.id
[2011-09-13 16:25:28 CEST] hwdb-submission-processor@launchpad_ftest_19275 ERROR: duplicate key value violates unique constraint "scriptactivity_pkey"
[2011-09-13 16:25:28 CEST] hwdb-submission-processor@launchpad_ftest_19275 STATEMENT: INSERT INTO ScriptActivity (date_completed, date_started, hostname, name) VALUES (E'2011-09-13 14:25:28.819243+00:00', E'2011-09-13 14:25:28.816929+00:00', E'klato5', E'hwdbsubmissions') RETURNING ScriptActivity.id
[2011-09-13 16:25:28 CEST] hwdb-submission-processor@launchpad_ftest_19275 LOG: statement: ROLLBACK
[2011-09-13 16:25:28 CEST] librarian@launchpad_ftest_19275 LOG: statement: BEGIN; SET TRANSACTION ISOLATION LEVEL READ COMMITTED
[2011-09-13 16:25:28 CEST] librarian@launchpad_ftest_19275 LOG: statement: SELECT current_database()
[2011-09-13 16:25:28 CEST] librarian@launchpad_ftest_19275 LOG: statement: INSERT INTO LibraryFileContent (datecreated, filesize, md5, sha1) VALUES (CURRENT_TIMESTAMP AT TIME ZONE 'UTC', 3435, E'fd36ba6974d4161bc59c6eada472d7dd', E'5bc1cfaad82751cd9eebd377e36fc7ef447fa804') RETURNING LibraryFileContent.id
[2011-09-13 16:25:28 CEST] librarian@launchpad_ftest_19275 LOG: statement: SELECT LibraryFileContent.datecreated FROM LibraryFileContent WHERE LibraryFileContent.id = 93
[2011-09-13 16:25:28 CEST] librarian@launchpad_ftest_19275 LOG: statement: INSERT INTO LibraryFileAlias (mimetype, date_created, hits, content, restricted, filename, last_accessed, expires) VALUES (E'text/plain;charset=ascii', DEFAULT, 0, 93, false, E'd5IGGbmtoidYE8XJjaXlE01iLWY.txt', DEFAULT, E'2011-12-12 14:25:28+00:00') RETURNING LibraryFileAlias.id
[2011-09-13 16:25:28 CEST] librarian@launchpad_ftest_19275 LOG: statement: SELECT LibraryFileAlias.date_created, LibraryFileAlias.last_accessed FROM LibraryFileAlias WHERE LibraryFileAlias.id = 93
[2011-09-13 16:25:28 CEST] librarian@launchpad_ftest_19275 LOG: statement: COMMIT
So, the second script could not add a record to ScriptActivity; then it added a record to LibraryFileContent and LibraryFileAlias.
If three tests are run, these lines appear _additionally_ in /var/log/postgresql/postgresql-8.4-main.log:
[2011-09-13 16:27:27 CEST] hwdb-submission-processor@launchpad_ftest_19623 LOG: statement: INSERT INTO ScriptActivity (date_completed, date_started, name, hostname) VALUES (E'2011-09-13 14:27:27.492902+00:00', E'2011-09-13 14:27:27.478150+00:00', E'hwdbsubmissions', E'klato5') RETURNING ScriptActivity.id
[2011-09-13 16:27:27 CEST] hwdb-submission-processor@launchpad_ftest_19623 ERROR: duplicate key value violates unique constraint "scriptactivity_pkey"
[2011-09-13 16:27:27 CEST] hwdb-submission-processor@launchpad_ftest_19623 STATEMENT: INSERT INTO ScriptActivity (date_completed, date_started, name, hostname) VALUES (E'2011-09-13
14:27:27.492902+00:00', E'2011-09-13 14:27:27.478150+00:00', E'hwdbsubmissions', E'klato5') RETURNING ScriptActivity.id
[2011-09-13 16:27:27 CEST] hwdb-submission-processor@launchpad_ftest_19623 LOG: statement: ROLLBACK
[2011-09-13 16:27:27 CEST] librarian@launchpad_ftest_19623 LOG: statement: BEGIN; SET TRANSACTION ISOLATION LEVEL READ COMMITTED
[2011-09-13 16:27:27 CEST] librarian@launchpad_ftest_19623 LOG: statement: SELECT current_database()
[2011-09-13 16:27:27 CEST] librarian@launchpad_ftest_19623 LOG: statement: INSERT INTO LibraryFileContent (datecreated, filesize, md5, sha1) VALUES (CURRENT_TIMESTAMP AT TIME ZONE 'UTC', 3435, E'fd36ba6974d4161bc59c6eada472d7dd', E'5bc1cfaad82751cd9eebd377e36fc7ef447fa804') RETURNING LibraryFileContent.id
[2011-09-13 16:27:27 CEST] librarian@launchpad_ftest_19623 ERROR: duplicate key value violates unique constraint "libraryfilecontent_pkey"
[2011-09-13 16:27:27 CEST] librarian@launchpad_ftest_19623 STATEMENT: INSERT INTO LibraryFileContent (datecreated, filesize, md5, sha1) VALUES (CURRENT_TIMESTAMP AT TIME ZONE 'UTC', 3435, E'fd36ba6974d4161bc59c6eada472d7dd', E'5bc1cfaad82751cd9eebd377e36fc7ef447fa804') RETURNING LibraryFileContent.id
[2011-09-13 16:27:27 CEST] librarian@launchpad_ftest_19623 LOG: statement: ROLLBACK
[2011-09-13 16:27:27 CEST] librarian@launchpad_ftest_19623 LOG: statement: BEGIN; SET TRANSACTION ISOLATION LEVEL READ COMMITTED
[2011-09-13 16:27:27 CEST] librarian@launchpad_ftest_19623 LOG: statement: SELECT current_database()
[2011-09-13 16:27:27 CEST] librarian@launchpad_ftest_19623 LOG: statement: INSERT INTO LibraryFileContent (datecreated, filesize, md5, sha1) VALUES (CURRENT_TIMESTAMP AT TIME ZONE 'UTC', 3435, E'fd36ba6974d4161bc59c6eada472d7dd', E'5bc1cfaad82751cd9eebd377e36fc7ef447fa804') RETURNING LibraryFileContent.id
[2011-09-13 16:27:27 CEST] librarian@launchpad_ftest_19623 LOG: statement: SELECT LibraryFileContent.datecreated FROM LibraryFileContent WHERE LibraryFileContent.id = 94
[2011-09-13 16:27:27 CEST] librarian@launchpad_ftest_19623 LOG: statement: INSERT INTO LibraryFileAlias (mimetype, date_created, hits, content, restricted, filename, last_accessed, expires) VALUES (E'text/plain;charset=ascii', DEFAULT, 0, 94, false, E'd5IGGbmtoidYE8XJjaXlE01iLWY.txt', DEFAULT, E'2011-12-12 14:27:27+00:00') RETURNING LibraryFileAlias.id
[2011-09-13 16:27:27 CEST] librarian@launchpad_ftest_19623 ERROR: duplicate key value violates unique constraint "libraryfilealias_pkey"
[2011-09-13 16:27:27 CEST] librarian@launchpad_ftest_19623 STATEMENT: INSERT INTO LibraryFileAlias (mimetype, date_created, hits, content, restricted, filename, last_accessed, expires) VALUES (E'text/plain;charset=ascii', DEFAULT, 0, 94, false, E'd5IGGbmtoidYE8XJjaXlE01iLWY.txt', DEFAULT, E'2011-12-12 14:27:27+00:00') RETURNING LibraryFileAlias.id
[2011-09-13 16:27:27 CEST] librarian@launchpad_ftest_19623 LOG: statement: ROLLBACK
So, the the third script could not create a ScriptActiivity record, and it could not create a Librarian file, in both cases due to a duplicate key error.
Note that the tests still pass -- with one exception:
test_run_reprocessing_script_two_batches(). This test wants to create a few Librarian files, but fails too with a duplicate key error if at least two other script tests ran before -- but it runs fine as the only test or when it runs first (to reproduce the latter: rename the test to test_a_run_reprocessing_script_two_batches().)
It is possible to run all tests successfully by simply disabling LaunchpadCronScript.record_activity():
--- lib/lp/services/scripts/base.py 2011-08-14 23:11:45 +0000
+++ lib/lp/services/scripts/base.py 2011-09-13 14:40:06 +0000
@@ -404,6 +404,7 @@
@log_unhandled_exception_and_exit
def record_activity(self, date_started, date_completed):
"""Record the successful completion of the script."""
+ return
self.txn.begin()
self.login(ANONYMOUS)
getUtility(IScriptActivitySet).recordSuccess(
This also affects lib/lp/