Investigate Celery legal docs refresh issue

[ccostino]

The upgrade to Celery 4.0.2 changed the default serialization from the pickle module to JSON, and this seems to have an impact on the legal docs refresh. See the stack trace below I caught in dev:

 ERR Can't decode message body: ContentDisallowed('Refusing to deserialize untrusted content of type pickle (application/x-python-serialize)',) [type:'application/x-python-serialize' encoding:'binary' headers:{}]
 ERR body: b'\x80\x02}q\x00(X\x06\x00\x00\x00kwargsq\x01}q\x02X\x07\x00\x00\x00tasksetq\x03NX\t\x00\x00\x00timelimitq\x04NN\x86q\x05X\x04\x00\x00\x00taskq\x06X$\x00\x00\x00webservices.tasks.legal_docs.refreshq\x07X\t\x00\x00\x00callbacksq\x08NX\x03\x00\x00\x00utcq\t\x88X\x02\x00\x00\x00idq\nX$\x00\x00\x005df15062-9455-49c4-93e4-6fa35d50f251q\x0bX\x04\x00\x00\x00argsq\x0c]q\rX\x07\x00\x00\x00expiresq\x0eNX\x07\x00\x00\x00retriesq\x0fK\x00X\x05\x00\x00\x00chordq\x10NX\x03\x00\x00\x00etaq\x11NX\x08\x00\x00\x00errbacksq\x12Nu.' (279b)
 ERR Traceback (most recent call last):
 ERR   File "/home/vcap/deps/0/python/lib/python3.5/site-packages/celery/worker/consumer/consumer.py", line 546, in on_task_received
 ERR     type_ = message.headers['task']                # protocol v2
 ERR KeyError: 'task'
 ERR During handling of the above exception, another exception occurred:
 ERR Traceback (most recent call last):
 ERR   File "/home/vcap/deps/0/python/lib/python3.5/site-packages/celery/worker/consumer/consumer.py", line 551, in on_task_received
 ERR     payload = message.decode()
 ERR   File "/home/vcap/deps/0/python/lib/python3.5/site-packages/kombu/message.py", line 192, in decode
 ERR     self._decoded_cache = self._decode()
 ERR   File "/home/vcap/deps/0/python/lib/python3.5/site-packages/kombu/message.py", line 197, in _decode
 ERR     self.content_encoding, accept=self.accept)
 ERR   File "/home/vcap/deps/0/python/lib/python3.5/site-packages/kombu/serialization.py", line 253, in loads
 ERR     raise self._for_untrusted_content(content_type, 'untrusted')
 ERR kombu.exceptions.ContentDisallowed: Refusing to deserialize untrusted content of type pickle (application/x-python-serialize)

We'll need to debug and figure out the appropriate course of action (get the content in shape for JSON serialization or something else).

[ccostino]

I can't seem to replicate this locally, though I wonder if that's because there's nothing to refresh compared to the dev instance?

[INFO/MainProcess] Received task: webservices.tasks.legal_docs.refresh[f832c9d2-f397-4641-a8bb-68bbd70ce668]
[INFO/MainProcess] Received task: webservices.tasks.refresh.refresh_calendar[002bca2b-40b4-4517-ba36-ab6773eb08ad]
[INFO/ForkPoolWorker-1] No modified AOs found
[INFO/ForkPoolWorker-1] Task webservices.tasks.legal_docs.refresh[f832c9d2-f397-4641-a8bb-68bbd70ce668] succeeded in 1.6828779860006762s: None
[INFO/ForkPoolWorker-2] Task webservices.tasks.refresh.refresh_calendar[002bca2b-40b4-4517-ba36-ab6773eb08ad] succeeded in 3.1869491250035935s: None

[ccostino]

@vrajmohan it looks like if we can modify an AO locally this will replicate the error, I'm just not sure how to do that. I'm guessing that a modified AO results in a task that is run that attempts to return the document in the task body and that is what is failing serialization?

Part of me wonders if it is worth just enabling the pickle serialization instead given these hurdles, but I know @LindsayYoung and I would prefer to stick with JSON and remain more secure if at all possible.

[ccostino]

And to top it all off, it'd be good to test the calendar refresh tasks too just to make sure they're working - @LindsayYoung are you aware of an easy way to do that?

However, in looking in the logs in dev, it looks like the calendar refresh task completed fine with a return of None.

[vrajmohan]

I think this is a one-off issue - perhaps the deploy happened between the task getting posted and the worker picking it up. In any case, there is no payload that the worker gets and we should be OK.

I manually modified AOs on dev, and they were refreshed with no errors:

2017-07-21T16:05:00.09-0700 [APP/PROC/WEB/1] ERR [2017-07-21 23:05:00,097: INFO/MainProcess] Received task: webservices.tasks.legal_docs.refresh[84470c74-cf02-4754-b727-2007be7bbc0a]
2017-07-21T16:05:00.10-0700 [APP/PROC/WEB/1] ERR [2017-07-21 23:05:00,105: INFO/ForkPoolWorker-2] AO found 2017-05 modified at 2017-07-21 22:52:38
2017-07-21T16:05:00.10-0700 [APP/PROC/WEB/1] ERR [2017-07-21 23:05:00,106: INFO/ForkPoolWorker-2] Loading advisory opinions
2017-07-21T16:05:47.14-0700 [APP/PROC/WEB/1] ERR [2017-07-21 23:05:47,147: INFO/ForkPoolWorker-2] Loading AO: 2017-05
2017-07-21T16:05:47.59-0700 [APP/PROC/WEB/1] ERR [2017-07-21 23:05:47,593: INFO/ForkPoolWorker-2] Loading AO: 2017-06
2017-07-21T16:05:49.21-0700 [APP/PROC/WEB/1] ERR [2017-07-21 23:05:49,203: INFO/ForkPoolWorker-2] Loading AO: 2017-07
2017-07-21T16:05:49.23-0700 [APP/PROC/WEB/1] ERR [2017-07-21 23:05:49,233: INFO/ForkPoolWorker-2] 3 advisory opinions loaded
2017-07-21T16:05:50.06-0700 [APP/PROC/WEB/1] ERR [2017-07-21 23:05:50,066: INFO/ForkPoolWorker-2] Task webservices.tasks.legal_docs.refresh[84470c74-cf02-4754-b727-2007be7bbc0a] succeeded in 49.967481462983415s: None

[ccostino]

Ah nice, thank you! We'll keep an eye out then just in case it surfaces again but this is great to see. :-)