1672107 - Intermittent iscript.exceptions.IScriptError: ('%s in %s exited %s!\n%s', ['codesign', '-s', '43AQ936H96', '-fv', '--keychain', '/builds/scriptworker/certs/release-signing.keychain', '--requirement', '=designated =>

Status: RESOLVED WONTFIX

(Release Engineering :: Release Automation, defect, P5)

Description

[Treeherder Bug Filer]

Filed by: archaeopteryx [at] coole-files.de
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=319092667&repo=mozilla-beta
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/FcHX5PpKTgeVfhnF4tT3aw/runs/0/artifacts/public/logs/live_backing.log

---

2020-10-20 06:14:26,410 - scriptworker_client.aio - DEBUG - retry_async: run_command: sleeping 111.73066875121728 seconds before retry
2020-10-20 06:15:37,679 - scriptworker_client.utils - INFO - Running ['codesign', '-s', '43AQ936H96', '-fv', '--keychain', '/builds/scriptworker/certs/release-signing.keychain', '--requirement', '=designated => ( (anchor apple generic and certificate leaf[field.1.2.840.113635.100.6.1.9] ) or (anchor apple generic and certificate 1[field.1.2.840.113635.100.6.2.6] and certificate leaf[field.1.2.840.113635.100.6.1.13] and certificate leaf[subject.OU] = "43AQ936H96"))', '-o', 'runtime', '--entitlements', '/builds/scriptworker/work/browser.entitlements.txt', 'plugin-container.app'] in /builds/scriptworker/work/1/Firefox.app/Contents/MacOS ...
2020-10-20 06:15:37,735 - scriptworker_client.utils - INFO - plugin-container.app: replacing existing signature
2020-10-20 06:15:37,819 - scriptworker_client.utils - INFO - plugin-container.app: signed app bundle with Mach-O thin (x86_64) [org.mozilla.plugincontainer]
2020-10-20 06:15:37,820 - scriptworker_client.utils - INFO - plugin-container.app: timestamps differ by 182 seconds - check your system clock
2020-10-20 06:15:37,822 - scriptworker_client.aio - WARNING - retry_async: run_command: too many retries!
2020-10-20 06:15:45,979 - scriptworker_client.utils - INFO - Running ['codesign', '-s', '43AQ936H96', '-fv', '--keychain', '/builds/scriptworker/certs/release-signing.keychain', '--requirement', '=designated => ( (anchor apple generic and certificate leaf[field.1.2.840.113635.100.6.1.9] ) or (anchor apple generic and certificate 1[field.1.2.840.113635.100.6.2.6] and certificate leaf[field.1.2.840.113635.100.6.1.13] and certificate leaf[subject.OU] = "43AQ936H96"))', '-o', 'runtime', '--entitlements', '/builds/scriptworker/work/browser.entitlements.txt', 'plugin-container.app'] in /builds/scriptworker/work/3/Firefox.app/Contents/MacOS ...
2020-10-20 06:15:46,033 - scriptworker_client.utils - INFO - plugin-container.app: replacing existing signature
2020-10-20 06:15:46,101 - scriptworker_client.utils - INFO - plugin-container.app: signed app bundle with Mach-O thin (x86_64) [org.mozilla.plugincontainer]
2020-10-20 06:15:46,102 - scriptworker_client.utils - INFO - plugin-container.app: timestamps differ by 182 seconds - check your system clock
2020-10-20 06:15:46,104 - scriptworker_client.aio - WARNING - retry_async: run_command: too many retries!
2020-10-20 06:16:01,179 - scriptworker_client.utils - INFO - Running ['codesign', '-s', '43AQ936H96', '-fv', '--keychain', '/builds/scriptworker/certs/release-signing.keychain', '--requirement', '=designated => ( (anchor apple generic and certificate leaf[field.1.2.840.113635.100.6.1.9] ) or (anchor apple generic and certificate 1[field.1.2.840.113635.100.6.2.6] and certificate leaf[field.1.2.840.113635.100.6.1.13] and certificate leaf[subject.OU] = "43AQ936H96"))', '-o', 'runtime', '--entitlements', '/builds/scriptworker/work/browser.entitlements.txt', 'plugin-container.app'] in /builds/scriptworker/work/0/Firefox.app/Contents/MacOS ...
2020-10-20 06:16:01,232 - scriptworker_client.utils - INFO - plugin-container.app: replacing existing signature
2020-10-20 06:16:01,348 - scriptworker_client.utils - INFO - plugin-container.app: signed app bundle with Mach-O thin (x86_64) [org.mozilla.plugincontainer]
2020-10-20 06:16:01,349 - scriptworker_client.utils - INFO - plugin-container.app: timestamps differ by 183 seconds - check your system clock
2020-10-20 06:16:01,350 - scriptworker_client.aio - WARNING - retry_async: run_command: too many retries!
2020-10-20 06:16:04,029 - scriptworker_client.utils - INFO - Running ['codesign', '-s', '43AQ936H96', '-fv', '--keychain', '/builds/scriptworker/certs/release-signing.keychain', '--requirement', '=designated => ( (anchor apple generic and certificate leaf[field.1.2.840.113635.100.6.1.9] ) or (anchor apple generic and certificate 1[field.1.2.840.113635.100.6.2.6] and certificate leaf[field.1.2.840.113635.100.6.1.13] and certificate leaf[subject.OU] = "43AQ936H96"))', '-o', 'runtime', '--entitlements', '/builds/scriptworker/work/browser.entitlements.txt', 'plugin-container.app'] in /builds/scriptworker/work/4/Firefox.app/Contents/MacOS ...
2020-10-20 06:16:04,083 - scriptworker_client.utils - INFO - plugin-container.app: replacing existing signature
2020-10-20 06:16:04,147 - scriptworker_client.utils - INFO - plugin-container.app: signed app bundle with Mach-O thin (x86_64) [org.mozilla.plugincontainer]
2020-10-20 06:16:04,148 - scriptworker_client.utils - INFO - plugin-container.app: timestamps differ by 183 seconds - check your system clock
2020-10-20 06:16:04,150 - scriptworker_client.aio - WARNING - retry_async: run_command: too many retries!
2020-10-20 06:16:18,279 - scriptworker_client.utils - INFO - Running ['codesign', '-s', '43AQ936H96', '-fv', '--keychain', '/builds/scriptworker/certs/release-signing.keychain', '--requirement', '=designated => ( (anchor apple generic and certificate leaf[field.1.2.840.113635.100.6.1.9] ) or (anchor apple generic and certificate 1[field.1.2.840.113635.100.6.2.6] and certificate leaf[field.1.2.840.113635.100.6.1.13] and certificate leaf[subject.OU] = "43AQ936H96"))', '-o', 'runtime', '--entitlements', '/builds/scriptworker/work/browser.entitlements.txt', 'plugin-container.app'] in /builds/scriptworker/work/2/Firefox.app/Contents/MacOS ...
2020-10-20 06:16:18,332 - scriptworker_client.utils - INFO - plugin-container.app: replacing existing signature
2020-10-20 06:16:18,398 - scriptworker_client.utils - INFO - plugin-container.app: signed app bundle with Mach-O thin (x86_64) [org.mozilla.plugincontainer]
2020-10-20 06:16:18,398 - scriptworker_client.utils - INFO - plugin-container.app: timestamps differ by 183 seconds - check your system clock
2020-10-20 06:16:18,400 - scriptworker_client.aio - WARNING - retry_async: run_command: too many retries!
2020-10-20 06:16:18,401 - scriptworker_client.client - ERROR - Failed to run async_main
Traceback (most recent call last):
  File "/builds/scriptworker/virtualenv/src/scriptworker-client/scriptworker_client/src/scriptworker_client/client.py", line 182, in _handle_asyncio_loop
    await async_main(config, task)
  File "/builds/scriptworker/virtualenv/src/iscript/iscript/src/iscript/script.py", line 38, in async_main
    await notarize_1_behavior(config, task)
  File "/builds/scriptworker/virtualenv/src/iscript/iscript/src/iscript/mac.py", line 1104, in notarize_1_behavior
    await sign_all_apps(config, key_config, entitlements_path, all_paths)
  File "/builds/scriptworker/virtualenv/src/iscript/iscript/src/iscript/mac.py", line 557, in sign_all_apps
    await raise_future_exceptions(futures)
  File "/builds/scriptworker/virtualenv/src/scriptworker-client/scriptworker_client/src/scriptworker_client/aio.py", line 65, in raise_future_exceptions
    raise exceptions[0]
  File "/builds/scriptworker/virtualenv/src/iscript/iscript/src/iscript/mac.py", line 231, in sign_app
    await sign_app(key_config, abs_dir, entitlements_path)
  File "/builds/scriptworker/virtualenv/src/iscript/iscript/src/iscript/mac.py", line 257, in sign_app
    await retry_async(
  File "/builds/scriptworker/virtualenv/src/scriptworker-client/scriptworker_client/src/scriptworker_client/aio.py", line 322, in retry_async
    return await func(*args, **kwargs)
  File "/builds/scriptworker/virtualenv/src/scriptworker-client/scriptworker_client/src/scriptworker_client/utils.py", line 232, in run_command
    raise exception(
iscript.exceptions.IScriptError: ('%s in %s exited %s!\n%s', ['codesign', '-s', '43AQ936H96', '-fv', '--keychain', '/builds/scriptworker/certs/release-signing.keychain', '--requirement', '=designated => ( (anchor apple generic and certificate leaf[field.1.2.840.113635.100.6.1.9] ) or (anchor apple generic and certificate 1[field.1.2.840.113635.100.6.2.6] and certificate leaf[field.1.2.840.113635.100.6.1.13] and certificate leaf[subject.OU] = "43AQ936H96"))', '-o', 'runtime', '--entitlements', '/builds/scriptworker/work/browser.entitlements.txt', 'plugin-container.app'], '/builds/scriptworker/work/0/Firefox.app/Contents/MacOS', 1, 'plugin-container.app: replacing existing signature\nplugin-container.app: signed app bundle with Mach-O thin (x86_64) [org.mozilla.plugincontainer]\nplugin-container.app: timestamps differ by 183 seconds - check your system clock\n')
exit code: 1```

Comment 1

[Julien Cristau [:jcristau]]

4 failures happened on mac-v3-signing2.srv.releng.mdc1.mozilla.com

tc says the task referenced in comment 0 started 2020-10-20T06:11:25.522Z and ended 2020-10-20T06:19:24.630Z whereas the messages in the log start 2020-10-20 06:08:42 and end 2020-10-20 06:16:18 which seems consistent with the system clock being ~3 minutes off.

Comment 2

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-beta: 4
• mozilla-central: 2

Platform breakdown:

• osx-shippable: 4
• osx-cross-devedition: 2

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1672107&startday=2020-10-19&endday=2020-10-25&tree=all

Comment 3

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-central: 1

Platform breakdown:

• osx-shippable: 1

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

Comment 4

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-beta: 1

Platform and build breakdown:

• osx-shippable: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1672107&startday=2021-02-01&endday=2021-02-07&tree=all

Comment 5

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-release: 1

Platform and build breakdown:

• osx-shippable: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1672107&startday=2021-02-15&endday=2021-02-21&tree=all

Comment 6

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-central: 1

Platform and build breakdown:

• osx-shippable: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1672107&startday=2021-08-09&endday=2021-08-15&tree=all

Comment 7

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-central: 1

Platform and build breakdown:

• osx-shippable: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1672107&startday=2021-11-08&endday=2021-11-14&tree=all

Comment 8

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-central: 1

Platform and build breakdown:

• osx-shippable: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1672107&startday=2022-01-17&endday=2022-01-23&tree=all

Comment 9

[Julien Cristau [:jcristau]]

The initial failure here was a bad clock on a mac signer. The recent ones look unrelated, e.g.:

2021-11-10 00:12:58,633 - scriptworker_client.utils - INFO - Running ['codesign', '-s', '43AQ936H96', '-fv', '--keychain', '/builds/scriptworker/certs/nightly-signing.keychain', '--requirement', '=designated => ( (anchor apple generic and certificate leaf[field.1.2.840.113635.100.6.1.9] ) or (anchor apple generic and certificate 1[field.1.2.840.113635.100.6.2.6] and certificate leaf[field.1.2.840.113635.100.6.1.13] and certificate leaf[subject.OU] = "43AQ936H96"))', '-o', 'runtime', '--entitlements', '/builds/scriptworker/work/browser.entitlements.txt', 'Firefox Nightly.app'] in /builds/scriptworker/work/3 ...
2021-11-10 00:12:58,690 - scriptworker_client.utils - INFO - Firefox Nightly.app: replacing existing signature
2021-11-10 00:12:58,693 - scriptworker_client.utils - INFO - Firefox Nightly.app: invalid or unsupported format for signature
2021-11-10 00:12:58,693 - scriptworker_client.utils - INFO - In subcomponent: /builds/scriptworker/work/3/Firefox Nightly.app/Contents/MacOS/firefox.cstemp
2021-11-10 00:12:58,695 - scriptworker_client.aio - WARNING - retry_async: run_command: too many retries!
2021-11-10 00:12:58,695 - scriptworker_client.client - ERROR - Failed to run async_main; exiting 1

Comment 10

[Julien Cristau [:jcristau]]

For some reason one of the tools leaves a temporary file behind, which codesign dislikes, so retrying doesn't help. Should we be deleting any lingering cstemp files?

Comment 11

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-central: 1

Platform and build breakdown:

• osx-shippable: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1672107&startday=2022-05-09&endday=2022-05-15&tree=all

Comment 12

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-central: 1

Platform and build breakdown:

• osx-shippable: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1672107&startday=2022-08-08&endday=2022-08-14&tree=all

Comment 13

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-central: 1

Platform and build breakdown:

• osx-shippable: 1
  • opt: 1

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

Comment 14

[BugBot [:suhaib / :marco]]

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit BugBot documentation.

Comment 15

[Treeherder Bug Filer]

New failure instance: https://treeherder.mozilla.org/logviewer?job_id=423047245&repo=mozilla-beta

Comment 16

[Heitor Neiva [:hneiva]]

We're planning on updating the signing code soon-ish with the hardened entitlement signing project. If the bug persists after that we'll dig more into it.
Given this only shows up very rarely and a rerun seems to fix it, it's a low priority atm.

Comment 17

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-beta: 1

Platform and build breakdown:

• osx-cross-devedition: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1672107&startday=2023-07-17&endday=2023-07-23&tree=all

Comment 18

[Intermittent Failures Robot]

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

Repository breakdown:

• comm-central: 1

Platform and build breakdown:

• osx-shippable: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1672107&startday=2023-08-14&endday=2023-08-20&tree=all