1654250 - Intermittent iscript.exceptions.IScriptError: ('%s in %s exited %s!\n%s', ['pkgbuild', '--keychain', '/builds/scriptworker/certs/nightly-signing.keychain', '--install-location', '/Applications', '--component', '/builds/scriptworker/work/4/Firefox Nightly.

Status: RESOLVED FIXED

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

Description

[Treeherder Bug Filer]

Filed by: rmaries [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=310537015&repo=mozilla-central
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/eN0eMXn9Qo2OcINEOUxxng/runs/0/artifacts/public/logs/live_backing.log

---

2020-07-21 11:56:01,251 - scriptworker_client.utils - INFO - pkgbuild: Wrote package to /builds/scriptworker/work/3/Firefox Nightly.pkg
2020-07-21 11:56:01,253 - scriptworker_client.utils - INFO - ['pkgbuild', '--keychain', '/builds/scriptworker/certs/nightly-signing.keychain', '--install-location', '/Applications', '--component', '/builds/scriptworker/work/3/Firefox Nightly.app', '/builds/scriptworker/work/3/Firefox Nightly.pkg', '--sign', '43AQ936H96'] in /builds/scriptworker/work/3 exited 0
2020-07-21 11:56:12,923 - 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 1110, in notarize_1_behavior
await create_pkg_files(config, key_config, all_paths)
File "/builds/scriptworker/virtualenv/src/iscript/iscript/src/iscript/mac.py", line 950, in create_pkg_files
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/scriptworker-client/scriptworker_client/src/scriptworker_client/aio.py", line 91, in semaphore_wrapper
return await coro
File "/builds/scriptworker/virtualenv/src/scriptworker-client/scriptworker_client/src/scriptworker_client/utils.py", line 233, in run_command
"%s in %s exited %s!\n%s", log_cmd, cwd, exitcode, log_contents
iscript.exceptions.IScriptError: ('%s in %s exited %s!\n%s', ['pkgbuild', '--keychain', '/builds/scriptworker/certs/nightly-signing.keychain', '--install-location', '/Applications', '--component', '/builds/scriptworker/work/4/Firefox Nightly.app', '/builds/scriptworker/work/4/Firefox Nightly.pkg', '--sign', '43AQ936H96'], '/builds/scriptworker/work/4', -11, '')
exit code: 1

Comment 1

[Nick Thomas [:nthomas] (UTC+12)]

Task eN0eMXn9Qo2OcINEOUxxng run 0 ran on mac-v3-signing8, which doesn't have any other recent failures. I haven't been able to find any information on what a -11 exit status means for pkgbuild, so waves hands I/O error ?

Comment 2

[Tom Prince [:tomprince]]

My guess is that a negative exit status corresponds to a signal, so I think corresponds to SEGV.

Comment 3

[Intermittent Failures Robot]

1 failures in 4310 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=1654250&startday=2020-07-20&endday=2020-07-26&tree=all

Comment 4

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-central: 2

Platform breakdown:

• osx-shippable: 2

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

Comment 5

[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=1654250&startday=2020-11-02&endday=2020-11-08&tree=all

Comment 6

[Intermittent Failures Robot]

1 failures in 3712 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/bugdetails?bug=1654250&startday=2020-11-30&endday=2020-12-06&tree=all

Comment 7

[Intermittent Failures Robot]

1 failures in 3421 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/bugdetails?bug=1654250&startday=2020-12-14&endday=2020-12-20&tree=all

Comment 8

[Intermittent Failures Robot]

1 failures in 1450 pushes (0.001 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/bugdetails?bug=1654250&startday=2020-12-21&endday=2020-12-27&tree=all

Comment 9

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-central: 1
• mozilla-beta: 1

Platform breakdown:

• osx-shippable: 2

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

Comment 10

[Intermittent Failures Robot]

1 failures in 3891 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=1654250&startday=2021-01-25&endday=2021-01-31&tree=all

Comment 11

[Aki Sasaki (not active)]

I think this may be scriptworker exiting? In theory we should be marking these intermittent-task per this block, but perhaps we need to actually exit iscript with the -11 error code.

Comment 12

[Aki Sasaki (not active)]

Attachment: [scriptworker_client] surface some exit codes from run_command

I think we're hitting -11 exit codes in iscript when we restart scriptworker. Scriptworker would turn a -11 exit code into an intermittent-task, which would automatically retry the task. However, run_command turns that -11 exit code into an exit code of 1, which is failed.

Let's surface the -11 and -15 exit codes if they show up in run_command.

Comment 13

[Aki Sasaki (not active)]

Attachment: [scriptworker] add 245 and 241 to intermittent task statuses

Alternately we could map these to -11 and -15 on the scriptworker_client side.

Comment 14

[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-central: 1

Platform and build breakdown:

• osx-shippable: 1
  • opt: 1

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

Comment 15

[Andreea Pavel [:apavel]]

Recent failure : https://treeherder.mozilla.org/logviewer?job_id=329337969&repo=mozilla-central&lineNumber=490

2021-02-09 11:22:26,672 - scriptworker_client.utils - INFO - /builds/scriptworker/work/0/Firefox Nightly.app: satisfies its Designated Requirement
2021-02-09 11:22:26,674 - scriptworker_client.utils - INFO - ['codesign', '-vvv', '--deep', '--strict', '/builds/scriptworker/work/0/Firefox Nightly.app'] in /builds/scriptworker/work/0 exited 0
2021-02-09 11:22:26,675 - iscript.mac - INFO - Unlocking signing keychain /builds/scriptworker/certs/nightly-signing.keychain
2021-02-09 11:22:26,973 - scriptworker_client.utils - INFO - Running ['security', 'list-keychains', '-s', '/builds/scriptworker/certs/nightly-signing.keychain', '/Users/cltbld/Library/Keychains/login.keychain-db', '/Library/Keychains/System.keychain'] in /builds/scriptworker/work ...
2021-02-09 11:22:27,043 - scriptworker_client.utils - INFO - ['security', 'list-keychains', '-s', '/builds/scriptworker/certs/nightly-signing.keychain', '/Users/cltbld/Library/Keychains/login.keychain-db', '/Library/Keychains/System.keychain'] in /builds/scriptworker/work exited 0
2021-02-09 11:22:27,044 - iscript.mac - INFO - Creating PKG files
2021-02-09 11:22:27,044 - scriptworker_client.utils - INFO - Running ['pkgbuild', '--install-location', '/Applications', '--keychain', '/builds/scriptworker/certs/nightly-signing.keychain', '--sign', '43AQ936H96', '--component', '/builds/scriptworker/work/0/Firefox Nightly.app', '/builds/scriptworker/work/0/Firefox Nightly.tmp1.pkg'] in /builds/scriptworker/work/0 ...
2021-02-09 11:22:54,817 - scriptworker_client.client - ERROR - Failed to run async_main
Traceback (most recent call last):
File "/builds/scriptworker/virtualenv/lib/python3.8/site-packages/scriptworker_client-1.0.0-py3.8.egg/scriptworker_client/client.py", line 182, in _handle_asyncio_loop
await async_main(config, task)
File "/builds/scriptworker/virtualenv/lib/python3.8/site-packages/iscript-1.0.1-py3.8.egg/iscript/script.py", line 39, in async_main
await notarize_1_behavior(config, task)
File "/builds/scriptworker/virtualenv/lib/python3.8/site-packages/iscript-1.0.1-py3.8.egg/iscript/mac.py", line 1219, in notarize_1_behavior
await create_pkg_files(config, sign_config, all_paths)
File "/builds/scriptworker/virtualenv/lib/python3.8/site-packages/iscript-1.0.1-py3.8.egg/iscript/mac.py", line 985, in create_pkg_files
await raise_future_exceptions(futures)
File "/builds/scriptworker/virtualenv/lib/python3.8/site-packages/scriptworker_client-1.0.0-py3.8.egg/scriptworker_client/aio.py", line 65, in raise_future_exceptions
raise exceptions[0]
File "/builds/scriptworker/virtualenv/lib/python3.8/site-packages/scriptworker_client-1.0.0-py3.8.egg/scriptworker_client/aio.py", line 91, in semaphore_wrapper
return await coro
File "/builds/scriptworker/virtualenv/lib/python3.8/site-packages/scriptworker_client-1.0.0-py3.8.egg/scriptworker_client/utils.py", line 245, in run_command
raise exception(
iscript.exceptions.IScriptError: ('%s in %s exited %s!\n%s', ['pkgbuild', '--install-location', '/Applications', '--keychain', '/builds/scriptworker/certs/nightly-signing.keychain', '--sign', '43AQ936H96', '--component', '/builds/scriptworker/work/0/Firefox Nightly.app', '/builds/scriptworker/work/0/Firefox Nightly.tmp1.pkg'], '/builds/scriptworker/work/0', -11, '')
exit code: 1

Comment 16

[Intermittent Failures Robot]

1 failures in 4322 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=1654250&startday=2021-02-08&endday=2021-02-14&tree=all

Comment 17

[Sebastian Hengst [:aryx] (needinfo me if it's about an intermittent or backout)]

Are the 4 recent failures related to CoT update yesterday?

Comment 18

[Sebastian Hengst [:aryx] (needinfo me if it's about an intermittent or backout)]

Regarding comment 17, https://firefox-ci-tc.services.mozilla.com/provisioners/scriptworker-prov-v1/worker-types/signing-mac-v1/workers/mdc2/mac-v3-signing11 fails all its notarization tasks.

Comment 19

[Aki Sasaki (not active)]

(In reply to Sebastian Hengst [:aryx] (needinfo on intermittent or backout) from comment #17)

Are the 4 recent failures related to CoT update yesterday?

Very likely.

(In reply to Sebastian Hengst [:aryx] (needinfo on intermittent or backout) from comment #18)

Regarding comment 17, https://firefox-ci-tc.services.mozilla.com/provisioners/scriptworker-prov-v1/worker-types/signing-mac-v1/workers/mdc2/mac-v3-signing11 fails all its notarization tasks.

Ok. I was testing on this box, repuppetized, and unquarantined. I may have left behind something that is breaking things; I'll reimage.

Comment 20

[Aki Sasaki (not active)]

Attachment: [ronin_puppet] deploy iscript and scriptworker fixes

Comment 21

[Aki Sasaki (not active)]

Reimaged mac-v3-signing11.

Comment 22

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-central: 10

Platform and build breakdown:

• osx-shippable: 10
  • opt: 10

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

Comment 23

[Aki Sasaki (not active)]

In theory, we should stop seeing this bug; I rolled out the -11 error code intermittent-task patches to the mac signers.
(In doing so, I could have triggered more instances of this error, but from now on we should be good.)