1339377 - [release-notifications] AttributeError: 'NoneType' object has no attribute 'encoding'

Status: RESOLVED FIXED

(Release Engineering :: Release Automation: Other, defect, P3)

Description

[Johan Lorenzo [:jlorenzo]]

Since release-notifications sends logs to Pappertrail (bug 1334092), this error comes out quite often (several times per release).

It seems we just need a retry mechanism to fetch task definition. Here are the logs:
> Feb 13 13:02:55 heroku-release-notifications app/worker.1: 2017-02-13 21:02:55,178 - pulsenotify.util - INFO - Fetching task Fn7RG6rTTfmvQe1XkV-3Ow from Taskcluster 
> Feb 13 13:02:57 heroku-release-notifications app/worker.1: 2017-02-13 21:02:56,996 - pulsenotify.plugins.irc - INFO - Notified with IRC for Task(id=Fn7RG6rTTfmvQe1XkV-3Ow, status=task-completed) 
> Feb 13 13:02:57 heroku-release-notifications app/worker.1: 2017-02-13 21:02:57,006 - botocore.vendored.requests.packages.urllib3.connectionpool - INFO - Starting new HTTPS connection (1): mozilla-release-logs.s3.amazonaws.com 
> Feb 13 13:02:57 heroku-release-notifications app/worker.1: 2017-02-13 21:02:57,240 - pulsenotify.plugins.log_collect - INFO - log_collect: log for Task(id=Fn7RG6rTTfmvQe1XkV-3Ow, status=task-completed) uploaded to Amazon S3 
> Feb 13 13:02:57 heroku-release-notifications app/worker.1: 2017-02-13 21:02:57,252 - botocore.vendored.requests.packages.urllib3.connectionpool - INFO - Starting new HTTPS connection (1): email.us-west-2.amazonaws.com 
> Feb 13 13:02:57 heroku-release-notifications app/worker.1: 2017-02-13 21:02:57,706 - pulsenotify.plugins.ses - INFO - Notified with SES for Task(id=Fn7RG6rTTfmvQe1XkV-3Ow, status=task-completed) 
> Feb 13 13:02:57 heroku-release-notifications app/worker.1: 2017-02-13 21:02:57,710 - pulsenotify.consumer - INFO - Acknowledging consumption of Task(id=Fn7RG6rTTfmvQe1XkV-3Ow, status=task-completed) 
> Feb 13 13:02:57 heroku-release-notifications app/worker.1: 2017-02-13 21:02:57,711 - asyncio - ERROR - Task exception was never retrieved 
> Feb 13 13:02:57 heroku-release-notifications app/worker.1: future: <Task finished coro=<irc_notify() done, defined at /app/pulsenotify/plugins/irc.py:73> exception=RuntimeError('Not connected',)> 
> Feb 13 13:02:57 heroku-release-notifications app/worker.1: Traceback (most recent call last): 
> Feb 13 13:02:57 heroku-release-notifications app/worker.1:   File "uvloop/task.pyx", line 126, in uvloop.loop.BaseTask._fast_step (uvloop/loop.c:99441) 
> Feb 13 13:02:57 heroku-release-notifications app/worker.1:   File "/app/pulsenotify/plugins/irc.py", line 76, in irc_notify 
> Feb 13 13:02:57 heroku-release-notifications app/worker.1:     self.irc_client.send('JOIN', channel=channel) 
> Feb 13 13:02:57 heroku-release-notifications app/worker.1:   File "/app/.heroku/python/lib/python3.5/site-packages/bottom/client.py", line 41, in send 
> Feb 13 13:02:57 heroku-release-notifications app/worker.1:     raise RuntimeError("Not connected") 
> Feb 13 13:02:57 heroku-release-notifications app/worker.1: RuntimeError: Not connected 
> Feb 13 13:02:57 heroku-release-notifications app/worker.1: 2017-02-13 21:02:57,766 - asyncio - ERROR - Unhandled exception in event loop 
> Feb 13 13:02:57 heroku-release-notifications app/worker.1: Traceback (most recent call last): 
> Feb 13 13:02:57 heroku-release-notifications app/worker.1:   File "uvloop/handles/stream.pyx", line 786, in uvloop.loop.__uv_stream_on_read_impl (uvloop/loop.c:63166) 
> Feb 13 13:02:57 heroku-release-notifications app/worker.1:   File "uvloop/handles/stream.pyx", line 560, in uvloop.loop.UVStream._on_read (uvloop/loop.c:60666) 
> Feb 13 13:02:57 heroku-release-notifications app/worker.1:   File "/app/.heroku/python/lib/python3.5/asyncio/sslproto.py", line 505, in data_received 
> Feb 13 13:02:57 heroku-release-notifications app/worker.1:     self._app_protocol.data_received(chunk) 
> Feb 13 13:02:57 heroku-release-notifications app/worker.1:   File "/app/.heroku/python/lib/python3.5/site-packages/bottom/protocol.py", line 31, in data_received 
> Feb 13 13:02:57 heroku-release-notifications app/worker.1:     message = line.decode(self.client.encoding, "ignore").strip() 
> Feb 13 13:02:57 heroku-release-notifications app/worker.1: AttributeError: 'NoneType' object has no attribute 'encoding' 
> Feb 13 13:02:58 heroku-release-notifications app/worker.1: 2017-02-13 21:02:57,786 - pulsenotify.util - INFO - Fetching task ldWiUF-xQgqNStsOzWs5UA from Taskcluster 
> Feb 13 13:03:01 heroku-release-notifications app/worker.1: 2017-02-13 21:03:01,596 - pulsenotify.plugins.irc - INFO - Notified with IRC for Task(id=ldWiUF-xQgqNStsOzWs5UA, status=task-completed) 
> Feb 13 13:03:01 heroku-release-notifications app/worker.1: 2017-02-13 21:03:01,625 - botocore.vendored.requests.packages.urllib3.connectionpool - INFO - Starting new HTTPS connection (1): mozilla-release-logs.s3.amazonaws.com 
> Feb 13 13:03:01 heroku-release-notifications app/worker.1: 2017-02-13 21:03:01,679 - pulsenotify.plugins.log_collect - INFO - log_collect: log for Task(id=ldWiUF-xQgqNStsOzWs5UA, status=task-completed) uploaded to Amazon S3 
> Feb 13 13:03:01 heroku-release-notifications app/worker.1: 2017-02-13 21:03:01,689 - botocore.vendored.requests.packages.urllib3.connectionpool - INFO - Starting new HTTPS connection (1): email.us-west-2.amazonaws.com 
> Feb 13 13:03:02 heroku-release-notifications app/worker.1: 2017-02-13 21:03:02,140 - pulsenotify.plugins.ses - INFO - Notified with SES for Task(id=ldWiUF-xQgqNStsOzWs5UA, status=task-completed)

Comment 2

[Johan Lorenzo [:jlorenzo]]

In the past 24 hours, we got hundreds of failures, because we had to abort Firefox 52.0b9 build 1. So there's a simpler way to trigger that issue. I'm on it.

Comment 3

[Johan Lorenzo [:jlorenzo]]

Attachment: PR for python library called "bottom"

I have a fix that works locally. This fix is for one of our 3rd-party dependency. I opened a PR there, which lacks of a test.

The issue does explain why some IRC notifications didn't happen. In the meantime, I suggest we turn off the papertrail alert on this particular issue.

Comment 4

[Johan Lorenzo [:jlorenzo]]

I updated the alert query at [1] to: 

> ERROR -("AttributeError: 'NoneType' object has no attribute 'encoding'" OR "Unhandled exception in event loop ")

These errors shouldn't be bubbled up from now on (and until "bottom" is fixed)

[1] https://papertrailapp.com/searches/17080452/edit

Comment 5

[Johan Lorenzo [:jlorenzo]]

The new build described in bug 1339381 comment 5 took the latest version of bottom (1.1.0) which includes the PR, per [1]. I took out the exception made in the search query (comment 4).

This issue now fixed in production. 

[1] https://github.com/numberoverzero/bottom/pull/37#issuecomment-283124241

Comment 6

[Johan Lorenzo [:jlorenzo]]

Based on the new errors that came up, it seems the problem is still not fixed. I don't know if the fix in the library isn't correct or if we just didn't pick the correct version at install time. [1] doesn't say what version got installed. I wonder if that's a sort of cache mechanism.

I'm gonna force the version numbers in requirements.txt. This will make sure we install the correct version. 

[1] https://dashboard.heroku.com/apps/release-notifications/activity/builds/2ff70e64-4279-4378-85f0-6e82ea28c537

Comment 7

[Johan Lorenzo [:jlorenzo]]

Attachment: pulse-notify PR

While we land this PR, I updated the query like it was in comment 4.

Comment 8

[Johan Lorenzo [:jlorenzo]]

Landed on master and production at: https://github.com/mozilla-releng/pulse-notify/commit/be499d66175113c2aa6e5f6fcd704dec0c42e7ef
Production deployed at https://dashboard.heroku.com/apps/release-notifications/activity/builds/3550746d-38ff-43eb-b1fc-01fb85283458

In the deployment logs, we can see the `pip install` logs:
>        Collecting bottom==1.1.0 (from -r /tmp/build_6053dc178683943ee9719dc70903cedc/mozilla-releng-pulse-notify-be499d6/requirements.txt (line 4))

This indicates dependencies were cached, like suggested in comment 6. I re-updated the query to match comment 5.

Let's now see if the problem is correctly fixed. I'll reopen the bug if not.

Comment 9

[Johan Lorenzo [:jlorenzo]]

(In reply to Johan Lorenzo [:jlorenzo] from comment #8)
> In the deployment logs,
which are located at: https://dashboard.heroku.com/apps/release-notifications/activity/builds/3550746d-38ff-43eb-b1fc-01fb85283458