738773 - transactions that are created within AUSTable.delete/update/insert need to be committed

Status: RESOLVED FIXED

(Release Engineering :: General, defect)

Description

[[e-mail] (:bhearsum)]

When I landed bugs 734474 and 733478 together, the first Jenkins run burned. I couldn't reproduce the failure locally, so I tried rebuilding it, which was fine. I kicked more runs after that and they were all fine, too. We should try to find a way to repro, and confirm whether its a real issue or not.

FAIL: testAddRelease (auslib.test.test_db.TestReleases)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/var/lib/jenkins/jobs/Balrog/workspace/auslib/test/test_db.py", line 458, in testAddRelease
    self.assertEquals(self.releases.t.select().where(self.releases.name=='d').execute().fetchall(), expected)
AssertionError: [] != [('d', 'd', 'd', '{"name": 4}', 1)]
-------------------- >> begin captured logging << --------------------
auslib.db: DEBUG: AUSTable._prepareInsert: Executing query: 'INSERT INTO releases (name, product, version, data, data_version) VALUES (?, ?, ?, ?, ?)' with values: {'data_version': 1, 'product': 'd', 'version': 'd', 'data': '{"name": 4}', 'name': 'd'}
auslib.db: DEBUG: History.getTimestamp: returning 1332533253657
--------------------- >> end captured logging << ---------------------

https://jenkins.mozilla.org/job/Balrog/58/
https://jenkins.mozilla.org/job/Balrog/59/

Comment 1

[[e-mail] (:bhearsum)]

I just hit a similar thing locally:
➜  balrog git:(update-data-version) ✗ make clobber-test test
rm -f test.done
Running unit tests
PYTHONPATH=vendor/lib/python nosetests 
....................................................................................................................
----------------------------------------------------------------------
Ran 116 tests in 5.072s

OK
Running rules tests
python test-rules.py 
Testing aus-data-snapshots/locale-level-overrides
PASS   (2 PASS, 0 FAIL)
Testing aus-data-snapshots/3.6.12-3.6.13
PASS   (324 PASS, 0 FAIL, 1.49 sec, 216.8 tests/second)
Testing aus-data-snapshots/rule-priorities
PASS   (2 PASS, 0 FAIL)
Testing aus-data-snapshots/fallback-falls-back
PASS   (2 PASS, 0 FAIL)
Testing aus-data-snapshots/3.6.27-10.0.2-major
PASS   (108 PASS, 0 FAIL)
Testing aus-data-snapshots/version-globbing
PASS   (8 PASS, 0 FAIL)
Testing aus-data-snapshots/fallback-override
PASS   (1 PASS, 0 FAIL)
Testing aus-data-snapshots/alias
PASS   (8 PASS, 0 FAIL)
touch test.done
➜  balrog git:(update-data-version) ✗ make clobber-test test
rm -f test.done
Running unit tests
PYTHONPATH=vendor/lib/python nosetests 
..........................................................................................................F.........
======================================================================
FAIL: testAddLocaleToRelease (auslib.test.test_db.TestReleasesSchema1)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/home/bhearsum/Mozilla/checkouts/github/balrog/auslib/test/test_db.py", line 523, in testAddLocaleToRelease
    self.assertEqual(ret, expected)
AssertionError: {u'platforms': {u'p': {u'locales': {u'l': {u'complete': {u'filesize': u'1234'}}} [truncated]... != {'platforms': {'p': {'locales': {'c': {'complete': {'hashValue': 'abc'}}, 'l': { [truncated]...
- {u'name': u'a',
?  -        -

+ {'name': 'a',
-  u'platforms': {u'p': {u'locales': {u'l': {u'complete': {u'filesize': u'1234'}}}}}}
?  -              -      -            - ^    -              --------    - ^^^^   ^^^^

+  'platforms': {'p': {'locales': {'c': {'complete': {'hashValue': 'abc'}},
?                                   ^                 ++++++++      ^^^   ^

+                                  'l': {'complete': {'filesize': '1234'}}}}}}
-------------------- >> begin captured logging << --------------------
auslib.db: DEBUG: AUSTable.select: Executing query: 'SELECT releases.data 
FROM releases 
WHERE releases.name = ?
 LIMIT ? OFFSET ?'
auslib.db: DEBUG: AUSTable.select: Executing query: 'SELECT releases.name, releases.product, releases.version, releases.data, releases.data_version 
FROM releases 
WHERE releases.name = ?'
auslib.db: DEBUG: AUSTable._returnRowOrRaise: returning {u'data_version': 1, u'product': u'a', u'version': u'a', u'data': u'\n{\n    "name": "a",\n    "platforms": {\n        "p": {\n            "locales": {\n                "l": {\n                    "complete": {\n                        "filesize": "1234"\n                    }\n                }\n            }\n        }\n    }\n}\n', u'name': u'a'}
auslib.db: DEBUG: AUSTable._prepareUpdate: Preparing update to row: {u'data_version': 2, u'product': u'a', u'version': u'a', u'data': '{"platforms": {"p": {"locales": {"c": {"complete": {"hashValue": "abc"}}, "l": {"complete": {"filesize": "1234"}}}}}, "name": "a"}', u'name': u'a'}, updating as follows: {'data': '{"platforms": {"p": {"locales": {"c": {"complete": {"hashValue": "abc"}}, "l": {"complete": {"filesize": "1234"}}}}}, "name": "a"}'}
auslib.db: DEBUG: AUSTable._prepareUpdate: Executing query: 'UPDATE releases SET name=?, product=?, version=?, data=?, data_version=? WHERE releases.name = ? AND releases.data_version = ?' with values: {u'data_version': 2, u'product': u'a', u'version': u'a', u'data': '{"platforms": {"p": {"locales": {"c": {"complete": {"hashValue": "abc"}}, "l": {"complete": {"filesize": "1234"}}}}}, "name": "a"}', u'name': u'a'}
auslib.db: DEBUG: History.getTimestamp: returning 1332789423125
auslib.db: DEBUG: History.forUpdate: inserting {'product': u'a', 'name': u'a', 'timestamp': 1332789423125, 'changed_by': 'bill', 'data_version': 2, 'version': u'a', 'data': '{"platforms": {"p": {"locales": {"c": {"complete": {"hashValue": "abc"}}, "l": {"complete": {"filesize": "1234"}}}}}, "name": "a"}'} to history table
--------------------- >> end captured logging << ---------------------

----------------------------------------------------------------------
Ran 116 tests in 5.171s

FAILED (failures=1)
make: *** [test.done] Error 1


I think this might have something to do with bug 710832...if there's some queries inside web requests not using transactions, there might be some race conditions we're hitting...

Comment 2

[[e-mail] (:bhearsum)]

I've also seen:
PYTHONPATH=vendor/lib/python nosetests 
.........................................................................................F........................
======================================================================
FAIL: testGrantPermissionsWithOptions (auslib.test.test_db.TestPermissions)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/home/bhearsum/Mozilla/checkouts/github/balrog/auslib/test/test_db.py", line 591, in testGrantPermissionsWithOptions
    self.assertEquals(query.execute().fetchall(), [('/releases/:name', 'cathy', json.dumps(dict(product='SeaMonkey')), 1)])
AssertionError: Lists differ: [] != [('/releases/:name', 'cathy', ...

Second list contains 1 additional elements.
First extra element 0:
('/releases/:name', 'cathy', '{"product": "SeaMonkey"}', 1)

- []
+ [('/releases/:name', 'cathy', '{"product": "SeaMonkey"}', 1)]
-------------------- >> begin captured logging << --------------------
auslib.db: DEBUG: AUSTable._prepareInsert: Executing query: 'INSERT INTO permissions (permission, username, options, data_version) VALUES (?, ?, ?, ?)' with values: {'username': 'cathy', 'data_version': 1, 'options': '{"product": "SeaMonkey"}', 'permission': '/releases/:name'}
auslib.db: DEBUG: History.getTimestamp: returning 1332790054953
--------------------- >> end captured logging << ---------------------

----------------------------------------------------------------------


Which pretty much confirms this is an underlying issue, and not one with specific tests...

Comment 3

[[e-mail] (:bhearsum)]

Going to try to track this down...

Comment 4

[[e-mail] (:bhearsum)]

Turns out that for cases where a transaction isn't provided to update/insert/delete, we create one (because we need it to make sure the history table can't get out of sync), but never commit it! Patch incoming that fixes it.

Comment 5

[[e-mail] (:bhearsum)]

Attachment: commit transactions that are created in AUSTable

I ended up adding some additional debug code that's probably worthwhile to keep, and found a few cases in the web side where weren't passing along the provided transaction, so I did that.

Comment 6

[[e-mail] (:bhearsum)]

Comment on attachment 609705 [details] [diff] [review]
commit transactions that are created in AUSTable

Jenkins run is here: https://jenkins.mozilla.org/job/Balrog/66/