1505983 - Intermittent [taskcluster:error] [mounts] (Permanent) HTTP response code 401

Status: RESOLVED INCOMPLETE

(Taskcluster :: General, defect, P5)

Description

[Treeherder Bug Filer]

Filed by: ncsoregi [at] mozilla.com

https://queue.taskcluster.net/v1/task/fV62piWIQ3W1orhZAwCqcw/runs/0/artifacts/public/logs/live_backing.log

https://treeherder.mozilla.org/logviewer.html#?job_id=210691409&repo=autoland

[taskcluster 2018-11-08T23:43:21.087Z] Worker Type (gecko-t-win10-64) settings:
[taskcluster 2018-11-08T23:43:21.087Z]   {
[taskcluster 2018-11-08T23:43:21.087Z]     "aws": {
[taskcluster 2018-11-08T23:43:21.087Z]       "ami-id": "ami-038f012a68252341b",
[taskcluster 2018-11-08T23:43:21.087Z]       "availability-zone": "us-west-2a",
[taskcluster 2018-11-08T23:43:21.087Z]       "instance-id": "i-018849ab02050b2b1",
[taskcluster 2018-11-08T23:43:21.087Z]       "instance-type": "c4.2xlarge",
[taskcluster 2018-11-08T23:43:21.087Z]       "local-ipv4": "10.144.22.28",
[taskcluster 2018-11-08T23:43:21.087Z]       "public-hostname": "ec2-54-70-250-1.us-west-2.compute.amazonaws.com",
[taskcluster 2018-11-08T23:43:21.087Z]       "public-ipv4": "54.70.250.1"
[taskcluster 2018-11-08T23:43:21.087Z]     },
[taskcluster 2018-11-08T23:43:21.087Z]     "config": {
[taskcluster 2018-11-08T23:43:21.087Z]       "deploymentId": "d6e218b7334c",
[taskcluster 2018-11-08T23:43:21.087Z]       "runTasksAsCurrentUser": false
[taskcluster 2018-11-08T23:43:21.087Z]     },
[taskcluster 2018-11-08T23:43:21.087Z]     "generic-worker": {
[taskcluster 2018-11-08T23:43:21.087Z]       "go-arch": "amd64",
[taskcluster 2018-11-08T23:43:21.087Z]       "go-os": "windows",
[taskcluster 2018-11-08T23:43:21.087Z]       "go-version": "go1.10.3",
[taskcluster 2018-11-08T23:43:21.087Z]       "release": "https://github.com/taskcluster/generic-worker/releases/tag/v10.11.2",
[taskcluster 2018-11-08T23:43:21.087Z]       "revision": "4b47d5d9f45eabc283947da0a6b1c02eddd0a7fe",
[taskcluster 2018-11-08T23:43:21.087Z]       "source": "https://github.com/taskcluster/generic-worker/commits/4b47d5d9f45eabc283947da0a6b1c02eddd0a7fe",
[taskcluster 2018-11-08T23:43:21.087Z]       "version": "10.11.2"
[taskcluster 2018-11-08T23:43:21.087Z]     },
[taskcluster 2018-11-08T23:43:21.087Z]     "machine-setup": {
[taskcluster 2018-11-08T23:43:21.087Z]       "ami-created": "2018-11-07 15:22:10.782Z",
[taskcluster 2018-11-08T23:43:21.087Z]       "manifest": "https://github.com/mozilla-releng/OpenCloudConfig.git/blob/d6e218b7334cacd99193430e55f6446ea95cd19d/userdata/Manifest/gecko-t-win10-64.json"
[taskcluster 2018-11-08T23:43:21.087Z]     }
[taskcluster 2018-11-08T23:43:21.087Z]   }
[taskcluster 2018-11-08T23:43:21.088Z] Task ID: fV62piWIQ3W1orhZAwCqcw
[taskcluster 2018-11-08T23:43:21.088Z] === Task Starting ===
[taskcluster 2018-11-08T23:43:22.357Z] Uploading redirect artifact public/logs/live.log to URL https://gzdpuaiaaaawn5pmkeucgs6wt67scrbozmemxad2sxrb7dnl.taskcluster-worker.net:60023/log/ee8PypQoTSCZxPu04xQMaw with mime type "text/plain; charset=utf-8" and expiry 2018-11-09T00:43:17.160Z
[taskcluster 2018-11-08T23:43:22.685Z] [mounts] Downloading task ZsUrAilMQi6-x1Jpl8LAqg artifact public/build/mozharness.zip to Y:\downloads\JHAwxi4jQ5-CdZjQ8ML2EQ
[taskcluster:error] [mounts] Could not fetch from task ZsUrAilMQi6-x1Jpl8LAqg artifact public/build/mozharness.zip into file Y:\downloads\JHAwxi4jQ5-CdZjQ8ML2EQ: (Permanent) HTTP response code 401
[taskcluster:error] 
[taskcluster:error] Could not download artifact:ZsUrAilMQi6-x1Jpl8LAqg:public/build/mozharness.zip to Y:\downloads\JHAwxi4jQ5-CdZjQ8ML2EQ due to (Permanent) HTTP response code 401
[taskcluster:error] 
[taskcluster 2018-11-08T23:43:23.867Z] Uploading redirect artifact public/logs/live.log to URL https://queue.taskcluster.net/v1/task/fV62piWIQ3W1orhZAwCqcw/runs/0/artifacts/public/logs/live_backing.log with mime type "text/plain; charset=utf-8" and expiry 2019-11-08T21:45:08.859Z
[taskcluster:error] [mounts] (Permanent) HTTP response code 401
[taskcluster:error]

Comment 1

[Dustin J. Mitchell [:dustin] (he/him)]

From the queue's logs:

Nov 08 23:43:23 taskcluster-queue app/web.1: Authorized project/taskcluster/aws-provisioner/production for GET access to /v1/task/ZsUrAilMQi6-x1Jpl8LAqg/artifacts/public%2Fbuild%2Fmozharness.zip?bewit=cHJvamVjdC90YXNrY2x1c3Rlci9hd3MtcHJvdmlzaW9uZXIvcHJvZHVjdGlvblwxNTQxNzIyNDAyXHlOS2ozSng0S0dNQnpnM3Z5WjZhdlpTaHJUbXFJaHFzdkQ1alpmcmdPU1E9XGV5SmpaWEowYVdacFkyRjBaU0k2ZXlKMlpYSnphVzl1SWpveExDSnpZMjl3WlhNaU9sc2lZWE56ZFcxbE9uZHZjbXRsY2kxMGVYQmxPbUYzY3kxd2NtOTJhWE5wYjI1bGNpMTJNUzluWldOcmJ5MTBMWGRwYmpFd0xUWTBJaXdpWVhOemRXMWxPbmR2Y210bGNpMXBaRG9xSWwwc0luTjBZWEowSWpveE5UUXhOekEzTWpNM056UXhMQ0psZUhCcGNua2lPakUxTkRJd05USTRNemMzTkRFc0luTmxaV1FpT2lKMVMyaDVaWFJaUzFKM1QyVnZOMVZuVXpSRVpFcDNhVTVaUlVwTGFETlVNMjF4TjNCbWJHeHBVWHB4UVNJc0luTnBaMjVoZEhWeVpTSTZJbk14VkZSMU1XeFNRaXRZUVRrMlQyUXZORWhUZW5OUGRETjVSSEYxVnpWRVJYVmpZVmszYUVsNVozTTlJbjE5 
Nov 08 23:43:23 taskcluster-queue heroku/router: at=info method=GET path="/v1/task/ZsUrAilMQi6-x1Jpl8LAqg/artifacts/public%2Fbuild%2Fmozharness.zip?bewit=cHJvamVjdC90YXNrY2x1c3Rlci9hd3MtcHJvdmlzaW9uZXIvcHJvZHVjdGlvblwxNTQxNzIyNDAyXHJrUGE0bkpJOEk0RmZNM0VUZzRJYTBCdVhtYS9uR01XMGJaa1VDM0lVc1E9XGV5SmpaWEowYVdacFkyRjBaU0k2ZXlKMlpYSnphVzl1SWpveExDSnpZMjl3WlhNaU9sc2lZWE56ZFcxbE9uZHZjbXRsY2kxMGVYQmxPbUYzY3kxd2NtOTJhWE5wYjI1bGNpMTJNUzluWldOcmJ5MTBMWGRwYmpFd0xUWTBJaXdpWVhOemRXMWxPbmR2Y210bGNpMXBaRG9xSWwwc0luTjBZWEowSWpveE5UUXhOekUzTURFM05qTTRMQ0psZUhCcGNua2lPakUxTkRJd05qSTJNVGMyTXpnc0luTmxaV1FpT2lJdFNsRmZkRTFrT1ZGTWRYZFdWSGxEVEZKSFFtSjNUVVpPZUdwSFQzbFRUMWRvVVdNd2N6VjNRVkJzWnlJc0luTnBaMjVoZEhWeVpTSTZJa3MwY1VoNlYzUTNUelZKVkhrd1VUazRLME5SV25SYVQwOVVOMU5yY1ZsbFMyUmpNV05VUmxaTGMzTTlJbjE5" host=queue.taskcluster.net request_id=7b3389b9-3db4-4afb-92cc-9fdf5e52d5d6 fwd="54.70.250.1" dyno=web.1 connect=0ms service=555ms status=401 bytes=1153 protocol=https 

401 means AuthenticationFailed.  It's sad the worker doesn't log the response body, as that might help figure out what the issue is.  Notably, it is not InsufficientScopes (which is 403).

Breaking down that bewit a little:

dustin@jemison ~ $ base64 -d <<EOF
> cHJvamVjdC90YXNrY2x1c3Rlci9hd3MtcHJvdmlzaW9uZXIvcHJvZHVjdGlvblwxNTQxNzIyNDAyXHlOS2ozSng0S0dNQnpnM3Z5WjZhdlpTaHJUbXFJaHFzdkQ1alpmcmdPU1E9XGV5SmpaWEowYVdacFkyRjBaU0k2ZXlKMlpYSnphVzl1SWpveExDSnpZMjl3WlhNaU9sc2lZWE56ZFcxbE9uZHZjbXRsY2kxMGVYQmxPbUYzY3kxd2NtOTJhWE5wYjI1bGNpMTJNUzluWldOcmJ5MTBMWGRwYmpFd0xUWTBJaXdpWVhOemRXMWxPbmR2Y210bGNpMXBaRG9xSWwwc0luTjBZWEowSWpveE5UUXhOekEzTWpNM056UXhMQ0psZUhCcGNua2lPakUxTkRJd05USTRNemMzTkRFc0luTmxaV1FpT2lKMVMyaDVaWFJaUzFKM1QyVnZOMVZuVXpSRVpFcDNhVTVaUlVwTGFETlVNMjF4TjNCbWJHeHBVWHB4UVNJc0luTnBaMjVoZEhWeVpTSTZJbk14VkZSMU1XeFNRaXRZUVRrMlQyUXZORWhUZW5OUGRETjVSSEYxVnpWRVJYVmpZVmszYUVsNVozTTlJbjE5
> EOF
project/taskcluster/aws-provisioner/production\1541722402\yNKj3Jx4KGMBzg3vyZ6avZShrTmqIhqsvD5jZfrgOSQ=\eyJjZXJ0aWZpY2F0ZSI6eyJ2ZXJzaW9uIjoxLCJzY29wZXMiOlsiYXNzdW1lOndvcmtlci10eXBlOmF3cy1wcm92aXNpb25lci12MS9nZWNrby10LXdpbjEwLTY0IiwiYXNzdW1lOndvcmtlci1pZDoqIl0sInN0YXJ0IjoxNTQxNzA3MjM3NzQxLCJleHBpcnkiOjE1NDIwNTI4Mzc3NDEsInNlZWQiOiJ1S2h5ZXRZS1J3T2VvN1VnUzREZEp3aU5ZRUpLaDNUM21xN3BmbGxpUXpxQSIsInNpZ25hdHVyZSI6InMxVFR1MWxSQitYQTk2T2QvNEhTenNPdDN5RHF1VzVERXVjYVk3aEl5Z3M9In19

dustindustin@jemison ~ $ base64 -d <<EOF
eyJjZXJ0aWZpY2F0ZSI6eyJ2ZXJzaW9uIjoxLCJzY29wZXMiOlsiYXNzdW1lOndvcmtlci10eXBlOmF3cy1wcm92aXNpb25lci12MS9nZWNrby10LXdpbjEwLTY0IiwiYXNzdW1lOndvcmtlci1pZDoqIl0sInN0YXJ0IjoxNTQxNzA3MjM3NzQxLCJleHBpcnkiOjE1NDIwNTI4Mzc3NDEsInNlZWQiOiJ1S2h5ZXRZS1J3T2VvN1VnUzREZEp3aU5ZRUpLaDNUM21xN3BmbGxpUXpxQSIsInNpZ25hdHVyZSI6InMxVFR1MWxSQitYQTk2T2QvNEhTenNPdDN5RHF1VzVERXVjYVk3aEl5Z3M9In19
EOF
{"certificate":{"version":1,"scopes":["assume:worker-type:aws-provisioner-v1/gecko-t-win10-64","assume:worker-id:*"],"start":1541707237741,"expiry":1542052837741,"seed":"uKhyetYKRwOeo7UgS4DdJwiNYEJKh3T3mq7pflliQzqA","signature":"s1TTu1lRB+XA96Od/4HSzsOt3yDquW5DEucaY7hIygs="}}

dustin@jemison ~ $ python
Python 2.7.13 (default, Dec  1 2017, 09:21:53) 
[GCC 6.4.1 20170727 (Red Hat 6.4.1-1)] on linux2
Type "help", "copyright", "credits" or "license" for more information.
>>> from time import *
>>> asctime(gmtime(1541722402))  # bewit.split('\\')[1] (expiration)
'Fri Nov  9 00:13:22 2018'
>>> asctime(gmtime(1541707237741/1000))  # certificate.start
'Thu Nov  8 20:00:37 2018'
>>> asctime(gmtime(1542052837741/1000))  # certificate.expiry
'Mon Nov 12 20:00:37 2018'

So the times are valid.

Without seeing the error code, I can't tell much more.  It's interesting that it logs "Authorized.." yet returns a 401!

Pete, any chance it's an easy hack to add such output?

Comment 2

[Intermittent Failures Robot]

1 failures in 3007 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:
* autoland: 1

Platform breakdown:
* windows10-64: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1505983&startday=2018-11-05&endday=2018-11-11&tree=all

Comment 3

[Pete Moore [:pmoore][:pete]]

The request headers+body and response headers+body (in case of failure) are logged in the worker logs, but not in the task logs. I wasn't sure if the response might contain auth information (for example in response headers) that we wouldn't want to share.

I guess I could log the response body, without the response headers, and not log the request headers/body at all - it felt a little dangerous to do so without any guarantee that nothing private would be returned.

Note, bug 1444362 will help solve the general problem of relating task logs to worker logs.

Comment 4

[Firefox Bug Husbandry Bot]

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup