1400258 - when scriptworker tasks fail chain of trust validation, treeherder can't find logs

Status: NEW

(Release Engineering :: Release Automation, defect)

Description

[Chris AtLee [:catlee]]

e.g. https://tools.taskcluster.net/groups/KdT8-i--QjqQ4KawQw77dA/tasks/BqINbuWDSn2pFUg2ZCetMA/details

The task failed CoT validation, and so didn't execute the task payload. It only uploaded the chain_of_trust.log file.

When you click on the 'log' link from Treeherder, you get a 404 error;
https://queue.taskcluster.net/v1/task/BqINbuWDSn2pFUg2ZCetMA/runs/0/artifacts/public/logs/live_backing.log

I think this is because Treeherder only looks for live_backing.log.

Comment 1

[Intermittent Failures Robot]

3 failures in 831 pushes (0.004 failures/push) were associated with this bug in the last 7 days.    

Repository breakdown:
* mozilla-central: 3

Platform breakdown:
* linux64: 1
* linux32: 1
* Android: 1

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1400258&startday=2018-02-26&endday=2018-03-04&tree=all

Comment 2

[Intermittent Failures Robot]

7 failures in 747 pushes (0.009 failures/push) were associated with this bug in the last 7 days.    

Repository breakdown:
* mozilla-central: 4
* autoland: 3

Platform breakdown:
* linux64: 3
* windows2012-32: 2
* windows2012-64: 1
* osx-cross: 1

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1400258&startday=2018-03-05&endday=2018-03-11&tree=all

Comment 3

[Intermittent Failures Robot]

13 failures in 814 pushes (0.016 failures/push) were associated with this bug in the last 7 days.    

Repository breakdown:
* autoland: 7
* mozilla-inbound: 4
* mozilla-central: 2

Platform breakdown:
* windows2012-32: 9
* windows2012-64: 2
* linux64: 2

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1400258&startday=2018-03-12&endday=2018-03-18&tree=all

Comment 4

[Intermittent Failures Robot]

3 failures in 822 pushes (0.004 failures/push) were associated with this bug in the last 7 days.    

Repository breakdown:
* mozilla-central: 2
* mozilla-inbound: 1

Platform breakdown:
* windows2012-32: 3

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1400258&startday=2018-03-20&endday=2018-03-26&tree=trunk

Comment 5

[Intermittent Failures Robot]

13 failures in 718 pushes (0.018 failures/push) were associated with this bug in the last 7 days.    

Repository breakdown:
* mozilla-inbound: 9
* mozilla-central: 4

Platform breakdown:
* windows2012-32: 6
* windows2012-32-devedition: 4
* linux64: 2
* windows2012-64: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1400258&startday=2018-03-26&endday=2018-04-01&tree=trunk

Comment 6

[Intermittent Failures Robot]

2 failures in 792 pushes (0.003 failures/push) were associated with this bug in the last 7 days.    

Repository breakdown:
* mozilla-central: 1
* autoland: 1

Platform breakdown:
* windows2012-32: 1
* osx-cross: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1400258&startday=2018-04-09&endday=2018-04-15&tree=trunk

Comment 7

[Intermittent Failures Robot]

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

Repository breakdown:
* mozilla-central: 1

Platform breakdown:
* windows2012-64: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1400258&startday=2018-04-16&endday=2018-04-22&tree=trunk

Comment 8

[Intermittent Failures Robot]

16 failures in 780 pushes (0.021 failures/push) were associated with this bug in the last 7 days.    

Repository breakdown:
* mozilla-central: 16

Platform breakdown:
* osx-cross: 16

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1400258&startday=2018-04-23&endday=2018-04-29&tree=trunk

Comment 9

[Intermittent Failures Robot]

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

Repository breakdown:
* mozilla-central: 1

Platform breakdown:
* osx-cross: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1400258&startday=2018-04-30&endday=2018-05-06&tree=trunk

Comment 10

[Intermittent Failures Robot]

8 failures in 660 pushes (0.012 failures/push) were associated with this bug in the last 7 days.    

Repository breakdown:
* mozilla-central: 7
* autoland: 1

Platform breakdown:
* windows2012-32: 8

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1400258&startday=2018-05-07&endday=2018-05-13&tree=trunk

Comment 11

[Aki Sasaki (not active)]

Also tracked at https://github.com/mozilla-releng/scriptworker/issues/179 .

Comment 12

[Aki Sasaki (not active)]

I can implement the fix by:

- prepending chain of trust logging to the live_backing.log, or 
- writing to live_backing.log, then moving the logfile to chain_of_trust.log on success, then write a new live_backing.log for the task

The main difference will be whether successful tasks will include chain_of_trust log output in live_backing_log, or if it will be in chain_of_trust.log.

Does anyone have a preference here?

Comment 13

[Aki Sasaki (not active)]

Attachment: prepend the cot verification log to live_backing.log

Comment 14

[Aki Sasaki (not active)]

https://tools.taskcluster.net/groups/FyvCWehUQLeX2MHQW77qZQ/tasks/VC2att7CTQ67Ow-TkrQXrw/runs/0/logs/public%2Flogs%2Flive_backing.log for an example of how this will look like.

Comment 15

[Aki Sasaki (not active)]

Tom's going to fix by letting treeherder know about chain_of_trust.log.

Comment 16

[Intermittent Failures Robot]

9 failures in 655 pushes (0.014 failures/push) were associated with this bug in the last 7 days.    

Repository breakdown:
* mozilla-inbound: 9

Platform breakdown:
* windows2012-64: 3
* windows2012-32: 3
* osx-cross: 1
* linux64: 1
* linux32: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1400258&startday=2018-05-28&endday=2018-06-03&tree=trunk

Comment 17

[Aki Sasaki (not active)]

Comment on attachment 8982675 [details] [review]
prepend the cot verification log to live_backing.log

The PR is approved, but Tom's looking at a different solution.

Comment 18

[GitHub Bugzilla PR Linker]

Attachment: Link to GitHub pull-request: https://github.com/mozilla/treeherder/pull/3615

Comment 19

[Tom Prince [:tomprince]]

The solution I had in mind is recorded in

https://github.com/taskcluster/taskcluster-treeherder/pull/50
https://github.com/mozilla/treeherder/pull/3615

That is, teach treeherder about both log types. Treeherder partially supports having multiple logs, but there are numerous places that assume that there will be only one.

There are a couple of ways forward:
- Get taskcluster-treeherder to use chain_of_trust.log as the treeherder log if live_backing.log doesn't exist.
- Follow up with treeherder to get better support for multiple logs, and in the mean-time live with the slightly awkward workaround of looking at the raw logs. (Given that this is primarily caused by retriggers, which will hopefully be fixed soon, I think we could live with this).
- Put both logs in a single file.

Comment 20

[Intermittent Failures Robot]

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

Repository breakdown:
* mozilla-inbound: 1

Platform breakdown:
* windows2012-32: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1400258&startday=2018-06-11&endday=2018-06-17&tree=trunk

Comment 21

[Intermittent Failures Robot]

80 failures in 521 pushes (0.154 failures/push) were associated with this bug in the last 7 days. 

This is the #4 most frequent failure this week. 

** This failure happened more than 75 times this week! Resolving this bug is a very high priority. **

** Try to resolve this bug as soon as possible. If unresolved for 1 week, the affected test(s) may be disabled. **   

Repository breakdown:
* mozilla-beta: 79
* mozilla-central: 1

Platform breakdown:
* windows2012-32: 15
* windows2012-64: 13
* osx-cross: 11
* linux64: 10
* linux32: 8
* windows2012-64-devedition: 5
* osx-cross-devedition: 5
* windows2012-32-devedition: 4
* linux64-devedition: 4
* linux32-devedition: 4
* android-4-0-armv7-api16: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1400258&startday=2018-06-18&endday=2018-06-24&tree=trunk

Comment 22

[Intermittent Failures Robot]

24 failures in 142 pushes (0.169 failures/push) were associated with this bug yesterday.    

Repository breakdown:
* mozilla-central: 24

Platform breakdown:
* linux64: 24

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1400258&startday=2018-07-26&endday=2018-07-26&tree=trunk

Comment 23

[Intermittent Failures Robot]

27 failures in 760 pushes (0.036 failures/push) were associated with this bug in the last 7 days.    

Repository breakdown:
* mozilla-central: 27

Platform breakdown:
* linux64: 26
* win64-asan-reporter: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1400258&startday=2018-07-23&endday=2018-07-29&tree=trunk

Comment 24

[Intermittent Failures Robot]

6 failures in 2773 pushes (0.002 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:
* try: 6

Platform breakdown:
* windows2012-32: 1
* windows2012-64-devedition: 1
* windows2012-64: 4

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1400258&startday=2018-09-24&endday=2018-09-30&tree=all

Comment 25

[Intermittent Failures Robot]

18 failures in 2978 pushes (0.006 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:
* mozilla-inbound: 12
* autoland: 6

Platform breakdown:
* osx-cross: 1
* linux64: 2
* linux32: 4
* windows2012-64: 6
* windows2012-32: 5

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

Comment 26

[Intermittent Failures Robot]

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

Repository breakdown:
* mozilla-central: 1

Platform breakdown:
* Android: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1400258&startday=2018-12-03&endday=2018-12-09&tree=all

Comment 27

[Intermittent Failures Robot]

2 failures in 2602 pushes (0.001 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 2

Platform breakdown:

• linux32: 2

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1400258&startday=2019-02-18&endday=2019-02-24&tree=all

Comment 28

[Daniel Varga [:dvarga]]

https://treeherder.mozilla.org/#/jobs?repo=mozilla-inbound&resultStatus=testfailed%2Cbusted%2Cexception&selectedJob=234386319&searchStr=windows%2C2012%2Cdebug%2Cbuild-signing-win32%2Fdebug%2C%28bs%29

Recent failure log:
2019-03-17T02:50:55 INFO - build_task_dependencies signing cSUzbTErSxCBNkm8wXeMZA
2019-03-17T02:50:55 INFO - find_sorted_task_dependencies signing cSUzbTErSxCBNkm8wXeMZA
2019-03-17T02:50:55 INFO - found dependencies: [('signing:parent', 'MUW-S9mASkOV71jDnCH9Qg'), ('signing:build', 'JrgR_f8qTduQW8cBW1wZlA'), ('signing:build', 'JrgR_f8qTduQW8cBW1wZlA')]
2019-03-17T02:50:56 DEBUG - signing:parent MUW-S9mASkOV71jDnCH9Qg is docker-worker
2019-03-17T02:50:56 DEBUG - makedirs(/builds/scriptworker/work/cot/MUW-S9mASkOV71jDnCH9Qg)
2019-03-17T02:50:56 INFO - build_task_dependencies signing:parent MUW-S9mASkOV71jDnCH9Qg
2019-03-17T02:50:56 INFO - find_sorted_task_dependencies signing:parent MUW-S9mASkOV71jDnCH9Qg
2019-03-17T02:50:56 INFO - found dependencies: [('signing:parent:parent', 'cKGHzJR4QP684BoKhmQBlQ')]
2019-03-17T02:50:56 DEBUG - signing:parent:parent cKGHzJR4QP684BoKhmQBlQ is docker-worker
2019-03-17T02:50:56 DEBUG - makedirs(/builds/scriptworker/work/cot/cKGHzJR4QP684BoKhmQBlQ)
2019-03-17T02:50:56 INFO - build_task_dependencies signing:parent:parent cKGHzJR4QP684BoKhmQBlQ
2019-03-17T02:50:56 INFO - find_sorted_task_dependencies signing:parent:parent cKGHzJR4QP684BoKhmQBlQ
2019-03-17T02:50:56 INFO - found dependencies: [('signing:parent:parent:parent', 'cKGHzJR4QP684BoKhmQBlQ')]
2019-03-17T02:50:56 DEBUG - signing:build JrgR_f8qTduQW8cBW1wZlA is generic-worker
2019-03-17T02:50:56 DEBUG - makedirs(/builds/scriptworker/work/cot/JrgR_f8qTduQW8cBW1wZlA)
2019-03-17T02:50:56 INFO - build_task_dependencies signing:build JrgR_f8qTduQW8cBW1wZlA
2019-03-17T02:50:56 INFO - find_sorted_task_dependencies signing:build JrgR_f8qTduQW8cBW1wZlA
2019-03-17T02:50:56 INFO - found dependencies: [('signing:build:parent', 'cKGHzJR4QP684BoKhmQBlQ')]
2019-03-17T02:50:56 INFO - Downloading https://queue.taskcluster.net/v1/task/MUW-S9mASkOV71jDnCH9Qg/artifacts/public%2FchainOfTrust.json.asc
2019-03-17T02:50:56 INFO - Downloading https://queue.taskcluster.net/v1/task/MUW-S9mASkOV71jDnCH9Qg/artifacts/public%2Fchain-of-trust.json
2019-03-17T02:50:56 INFO - Downloading https://queue.taskcluster.net/v1/task/cKGHzJR4QP684BoKhmQBlQ/artifacts/public%2FchainOfTrust.json.asc
2019-03-17T02:50:56 INFO - Downloading https://queue.taskcluster.net/v1/task/cKGHzJR4QP684BoKhmQBlQ/artifacts/public%2Fchain-of-trust.json
2019-03-17T02:50:56 INFO - Downloading https://queue.taskcluster.net/v1/task/JrgR_f8qTduQW8cBW1wZlA/artifacts/public%2FchainOfTrust.json.asc
2019-03-17T02:50:56 INFO - Downloading https://queue.taskcluster.net/v1/task/JrgR_f8qTduQW8cBW1wZlA/artifacts/public%2Fchain-of-trust.json
2019-03-17T02:50:56 DEBUG - 404 downloading https://queue.taskcluster.net/v1/task/MUW-S9mASkOV71jDnCH9Qg/artifacts/public%2FchainOfTrust.json.asc: 404; body={
"code": "ResourceNotFound",
"message": "Artifact not found\n\n---\n\n* method: getLatestArtifact\n* errorCode: ResourceNotFound\n* statusCode: 404\n* time: 2019-03-17T02:50:56.919Z",
"requestInfo": {
"method": "getLatestArtifact",
"params": {
"0": "public/chainOfTrust.json.asc",
"taskId": "MUW-S9mASkOV71jDnCH9Qg",
"name": "public/chainOfTrust.json.asc"
},
"payload": {},
"time": "2019-03-17T02:50:56.919Z"
}
}
2019-03-17T02:50:57 DEBUG - 404 downloading https://queue.taskcluster.net/v1/task/MUW-S9mASkOV71jDnCH9Qg/artifacts/public%2Fchain-of-trust.json: 404; body={
"code": "ResourceNotFound",
"message": "Artifact not found\n\n---\n\n* method: getLatestArtifact\n* errorCode: ResourceNotFound\n* statusCode: 404\n* time: 2019-03-17T02:50:57.232Z",
"requestInfo": {
"method": "getLatestArtifact",
"params": {
"0": "public/chain-of-trust.json",
"taskId": "MUW-S9mASkOV71jDnCH9Qg",
"name": "public/chain-of-trust.json"
},
"payload": {},
"time": "2019-03-17T02:50:57.232Z"
}
}
2019-03-17T02:50:57 DEBUG - makedirs(/builds/scriptworker/work/cot/JrgR_f8qTduQW8cBW1wZlA/public)
2019-03-17T02:50:57 INFO - Done
2019-03-17T02:50:57 DEBUG - makedirs(/builds/scriptworker/work/cot/cKGHzJR4QP684BoKhmQBlQ/public)
2019-03-17T02:50:57 INFO - Done
2019-03-17T02:50:57 INFO - Done
2019-03-17T02:50:57 INFO - Done
2019-03-17T02:50:57 CRITICAL - Chain of Trust verification error!
Traceback (most recent call last):

File "/builds/scriptworker/lib/python3.6/site-packages/scriptworker/cot/verify.py", line 2197, in verify_chain_of_trust
await download_cot(chain)
File "/builds/scriptworker/lib/python3.6/site-packages/scriptworker/cot/verify.py", line 646, in download_cot
mandatory_artifacts_paths = await raise_future_exceptions(mandatory_artifact_tasks)
File "/builds/scriptworker/lib/python3.6/site-packages/scriptworker/utils.py", line 327, in raise_future_exceptions
succeeded_results, _ = await _process_future_exceptions(tasks, raise_at_first_error=True)
File "/builds/scriptworker/lib/python3.6/site-packages/scriptworker/utils.py", line 361, in _process_future_exceptions
raise exc
File "/builds/scriptworker/lib/python3.6/site-packages/scriptworker/artifacts.py", line 308, in download_artifacts
await raise_future_exceptions(tasks)
File "/builds/scriptworker/lib/python3.6/site-packages/scriptworker/utils.py", line 327, in raise_future_exceptions
succeeded_results, _ = await _process_future_exceptions(tasks, raise_at_first_error=True)
File "/builds/scriptworker/lib/python3.6/site-packages/scriptworker/utils.py", line 361, in _process_future_exceptions
raise exc
File "/builds/scriptworker/lib/python3.6/site-packages/scriptworker/utils.py", line 261, in retry_async
return await func(*args, **kwargs)
File "/builds/scriptworker/lib/python3.6/site-packages/scriptworker/utils.py", line 558, in download_file
raise Download404("{} status {}!".format(loggable_url, resp.status))
scriptworker.exceptions.Download404: https://queue.taskcluster.net/v1/task/MUW-S9mASkOV71jDnCH9Qg/artifacts/public%2FchainOfTrust.json.asc status 404!
2019-03-17T02:50:57 ERROR - Hit ScriptWorkerException: 'https://queue.taskcluster.net/v1/task/MUW-S9mASkOV71jDnCH9Qg/artifacts/public%2FchainOfTrust.json.asc status 404!'
2019-03-17T02:50:57 DEBUG - "/builds/scriptworker/artifacts/public/logs/chain_of_trust.log" is encoded with "None" and has mime/type "text/plain"
2019-03-17T02:50:57 INFO - "/builds/scriptworker/artifacts/public/logs/chain_of_trust.log" can be gzip'd. Compressing...

Comment 29

[Intermittent Failures Robot]

8 failures in 2771 pushes (0.003 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-inbound: 8

Platform breakdown:

• windows2012-64: 4
• windows2012-32: 4

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1400258&startday=2019-03-11&endday=2019-03-17&tree=all

Comment 30

[Andreea Pavel [:apavel]]

Recent occurrences are from here: https://treeherder.mozilla.org/#/jobs?repo=autoland&revision=ebb28cae3bc2c3249af72d85893a6e0913e4c5fc&selectedJob=247817563&searchStr=build

Comment 31

[Intermittent Failures Robot]

11 failures in 4730 pushes (0.002 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 11

Platform breakdown:

• windows2012-32: 2
• windows2012-64: 2
• osx-shippable: 1
• windows2012-aarch64: 1
• android-em-7-0-x86_64: 1
• linux32-shippable: 1
• windows2012-32-shippable: 1
• windows2012-64-shippable: 1
• windows2012-aarch64-shippable: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1400258&startday=2019-05-20&endday=2019-05-26&tree=all

Comment 32

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 1

Platform breakdown:

• windows2012-aarch64: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1400258&startday=2020-02-17&endday=2020-02-23&tree=all

Comment 33

[Intermittent Failures Robot]

3 failures in 5488 pushes (0.001 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 3

Platform breakdown:

• windows2012-64: 2
• windows2012-32: 1

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

Comment 34

[Intermittent Failures Robot]

3 failures in 3445 pushes (0.001 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 3

Platform and build breakdown:

• windows2012-32: 2
  • opt: 1
  • debug: 1
• windows2012-64: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1400258&startday=2022-11-07&endday=2022-11-13&tree=all