1162526 - Protect against null properties during process-objects ("TypeError: 'NoneType' object has no attribute '__getitem__'")

Status: RESOLVED FIXED

(Tree Management :: Treeherder: Data Ingestion, defect, P1)

Description

[Ed Morley [:emorley]]

We're seeing exceptions during the process-objects task, on both prod and stage:
https://rpm.newrelic.com/accounts/677903/applications/4180461/traced_errors/3785087676
...
File "/data/www/treeherder.mozilla.org/treeherder-service/treeherder/model/tasks.py", line 63, in process_objects
File "/data/www/treeherder.mozilla.org/treeherder-service/treeherder/model/derived/jobs.py", line 2113, in process_objects
File "/data/www/treeherder.mozilla.org/treeherder-service/treeherder/model/derived/jobs.py", line 1270, in load_job_data
File "/data/www/treeherder.mozilla.org/treeherder-service/treeherder/model/derived/jobs.py", line 1604, in _load_ref_and_job_data_structs
TypeError: 'NoneType' object has no attribute '__getitem__'

Prod is currently deployed to this rev:
https://github.com/mozilla/treeherder/commit/464a3d7b401670a54eb6aeb409d6e58f35501aef

So line 1604 corresponds to:
https://github.com/mozilla/treeherder/blob/464a3d7b401670a54eb6aeb409d6e58f35501aef/treeherder/model/derived/jobs.py#L1604

I believe this exception is what has caused a spike in bug 1125476 (since if the worker dies, we don't recover.. and up until now this had only been occasionally during a deploy, rather than due to an exception).

Comment 1

[Ed Morley [:emorley]]

[2015-05-07 07:14:08,396: ERROR/MainProcess] Task process-objects[7b748606-8f9d-428d-86c5-a9d04da5fb9a] raised unexpected: TypeError("'NoneType' object has no attribute '__getitem__'",)
Traceback (most recent call last):
  File "/data/www/treeherder.mozilla.org/venv/lib/python2.7/site-packages/celery/app/trace.py", line 240, in trace_task
    R = retval = fun(*args, **kwargs)
  File "/data/www/treeherder.mozilla.org/venv/lib/python2.7/site-packages/newrelic-2.50.0.39/newrelic/hooks/application_celery.py", line 66, in wrapper
    return wrapped(*args, **kwargs)
  File "/data/www/treeherder.mozilla.org/venv/lib/python2.7/site-packages/celery/app/trace.py", line 437, in __protected_call__
    return self.run(*args, **kwargs)
  File "/data/www/treeherder.mozilla.org/treeherder-service/treeherder/model/tasks.py", line 63, in process_objects
    jm.process_objects(limit)
  File "/data/www/treeherder.mozilla.org/treeherder-service/treeherder/model/derived/jobs.py", line 2113, in process_objects
    self.load_job_data(rows)
  File "/data/www/treeherder.mozilla.org/treeherder-service/treeherder/model/derived/jobs.py", line 1270, in load_job_data
    tier_2_signatures
  File "/data/www/treeherder.mozilla.org/treeherder-service/treeherder/model/derived/jobs.py", line 1604, in _load_ref_and_job_data_structs
    url = url[0:255]
TypeError: 'NoneType' object has no attribute '__getitem__'

Comment 2

[Ed Morley [:emorley]]

After sifting through 46 jobs stuck in the loading state, trying to find which caused the exception (yey for insufficient logs & mysqlworkbench's inability to easily export blobs), I've found:

Execute:
> SELECT id, job_guid, processed_state, json_blob FROM try_objectstore_1.objectstore WHERE id = 9304094

+ ------- + ------------- + -------------------- + -------------- +
| id      | job_guid      | processed_state      | json_blob      |
+ ------- + ------------- + -------------------- + -------------- +
| 9304094 | 5b040469c5048002d0d42624c8097ef59cf0b3e4 | loading              | ...            |
| NULL    | NULL          | NULL                 | NULL           |
+ ------- + ------------- + -------------------- + -------------- +
2 rows

Whose json_blob is: https://emorley.pastebin.mozilla.org/8832771

Notably the 'null' here:

    "log_references": [{
      "url": "http://ftp.mozilla.org/pub/mozilla.org/firefox/try-builds/[e-mail]-1f185685074d/try-macosx64/try_snowleopard_test-mochitest-e10s-browser-chrome-3-bm108-tests1-macosx-build965.txt.gz",
      "name": "buildbot_text"
    },
    {
      "url": null,
      "name": "mozlog_json"
    }],

We generate that field ourselves, here:
https://github.com/mozilla/treeherder/blob/e1faf755a899f822d6dab749fccee8b9703bd14f/treeherder/etl/buildapi.py#L191

However we use the "blobber_fields" property to do so. Digging the job out of the daily builds-4hr archive shows the data there as:
https://emorley.pastebin.mozilla.org/8832773

\"browser-chrome-chunked_raw.log\": null,

Comment 3

[Ed Morley [:emorley]]

Attachment: Protect against null properties during ingestion

So this PR will stop this particular exception, and make similar ones less likely.

I'll file a bug against releng for the value of the URL being null in the first place.

In addition, in another bug I'll make us handle these exceptions more gracefully (ie: mark a single job as errored, rather than bailing on up to the 100 jobs in that batch).

Comment 4

[Cameron Dawson [:camd]]

Comment on attachment 8602887 [details] [review]
Protect against null properties during ingestion

Looks good.  thanks for tracking this down.  my bad...

Comment 5

[Treeherder GitHub Bugbot]

Commits pushed to master at https://github.com/mozilla/treeherder

https://github.com/mozilla/treeherder/commit/4a8e8370e3c55ab4e082b9b129668ce829656cc1
Bug 1162526 - Only add mozlog_json URLs to log_references if not null

The url for items in blobber_properties can sometimes be null, so skip
adding a mozlog_json entry for them to log_references if so.

https://github.com/mozilla/treeherder/commit/bbc0c2e0e77044ca5cee7610481b337d788c0852
Bug 1162526 - Protect against null properties during ingestion

Sometimes a property is present, but its value is null in the json_blob
in the objectstore. We must set the default value in this case too, and
not just when the property does not exist at all, to prevent exceptions
when we later perform string operations on it.