1387597 - NothingUsefulHappened is unnecessary

Status: VERIFIED FIXED

(Socorro :: General, task)

Description

[Peter Bengtsson [:peterbe]]

Looking through the crontabber.log we get tonnes and tonnes of these:

2017-08-04 12:25:09,478 DEBUG - MainThread -  - MainThread - bug 1387357: set([u'mozilla::ContentCacheInParent::OnEventNeedingAckHandl$
2017-08-04 12:25:09,482 ERROR - MainThread -  - MainThread - Exception raised during socorro.external.postgresql.connection_context tr$
Traceback (most recent call last):
  File "/data/socorro/socorro-virtualenv/lib/python2.7/site-packages/crontabber/transaction_executor.py", line 46, in __call__
    result = function(connection, *args, **kwargs)
  File "/data/socorro/socorro-virtualenv/lib/python2.7/site-packages/socorro-master-py2.7.egg/socorro/cron/jobs/bugzilla.py", line 175$
    raise NothingUsefulHappened('nothing useful done')
NothingUsefulHappened: nothing useful done


The problem is that it clogs up our log files with "false positives". 

The pattern we use in transaction_executor is doing a `config.logger.error` (or `config.logger.exception` within a try:except block and we use something like `except NoSingleValue` or something to simply ignore it. But if we ignore it we shouldn't log an exception. It makes debugging harder.

Comment 1

[Peter Bengtsson [:peterbe]]

Upon closer inspection, what happens is that this NothingUsefulHappened only ever happens in socorro/cron/jobs/bugzilla.py when it realizes that there were no inserts made. It then tricks the transaction_executor (instance of socorro/database/transaction_executor:TransactionExecutor) to make a transaction rollback.

However, the trick doesn't seem to work. In bugzilla.py it raises a `NothingUsefulHappened` [0] which is supposed trigger this: https://github.com/mozilla-services/socorro/blob/7681a91c1211e294c0d37de2011c4ba8a11a3e0c/socorro/database/transaction_executor.py#L46-L50 
But clearly that isn't working since I see a lot of "Exception raised during..." the bugzilla crontabber app. 

I think the solution is to simplify this. First by making bugzilla.py letting it autocommit even if no writes are made. It doesn't need to rollback just because nothing was inserted. 



[0] https://github.com/mozilla-services/socorro/blob/master/socorro/cron/jobs/bugzilla.py#L62-L65

Comment 2

[Peter Bengtsson [:peterbe]]

Attachment: bugzilla.py.log

I hooked up bugzilla.py to run locally with a real PG and I had it log ALL SQL it ran. 

So this is what happens when I ran it again and there are no NEW bug associations to update.

Comment 3

[Peter Bengtsson [:peterbe]]

Attachment: bugzilla.py.2.log

Exact same run as before but this time after https://github.com/mozilla-services/socorro/pull/3895 is used.

Comment 4

[Peter Bengtsson [:peterbe]]

PR https://github.com/mozilla-services/socorro/pull/3895

Comment 5

[[github robot]]

Commit pushed to master at https://github.com/mozilla-services/socorro

https://github.com/mozilla-services/socorro/commit/f2cbca6d64bf845b9887e4bae262b4cd101cbb86
fixes bug 1387597 - Fix transaction_executor to not log benign errors (#3895)

* fixes bug 1387597 - Fix transaction_executor to not log benign errors

* remove dryrun class

Comment 6

[Peter Bengtsson [:peterbe]]

No longer happening in crontabber.log on stage admin. yay!