1763323 - Almost permafailing windows signing pyasn1.error.SubstrateUnderrunError: Short octet stream on tag decoding

Status: RESOLVED WORKSFORME

(Release Engineering :: Release Automation, defect)

Description

[Iulian Moraru]

The failure summary is empty in treeherder.
Push with failures
Failure log

2022-04-06 06:44:06,916 - winsign.sign - DEBUG - Re-signing with real keys
2022-04-06 06:44:06,925 - winsign.asn1 - DEBUG - Digest to sign is: b'1b876647a95bd9ecbf0918b5fd5a4d6895d5c4a8fd129fc4bc173f911c657442'
2022-04-06 06:44:06,926 - signingscript.sign - DEBUG - make_signing_req took 0.00s; RSS:131556 (+0)
2022-04-06 06:44:06,927 - signingscript.sign - DEBUG - req_size: 58
2022-04-06 06:44:07,010 - signingscript.sign - DEBUG - Autograph response: 201
2022-04-06 06:44:07,010 - signingscript.sign - DEBUG - call_autograph took 0.08s; RSS:131556 (+0)
2022-04-06 06:44:07,011 - signingscript.sign - DEBUG - sign_with_autograph took 0.09s; RSS:131556 (+0)
2022-04-06 06:44:07,011 - signingscript.sign - DEBUG - sign_hash_with_autograph took 0.09s; RSS:131556 (+0)
2022-04-06 06:44:07,212 - winsign.sign - DEBUG - Attaching new signature
2022-04-06 06:44:07,213 - winsign.osslsigncode - DEBUG - running: ['osslsigncode', 'attach-signature', '-sigin', PosixPath('/tmp/tmp24oc3ft4/sigfile'), '-CAfile', '/app/signingscript/src/signingscript/data/authenticode_dep_ca.crt', '-untrusted', '/usr/lib/ssl/certs/ca-certificates.crt', '-in', PosixPath('/app/workdir/zip0xxo78w6/firefox/maintenanceservice.exe'), '-out', PosixPath('/app/workdir/zip0xxo78w6/firefox/maintenanceservice.exe-new')]
2022-04-06 06:44:07,239 - winsign.sign - DEBUG - Done!
2022-04-06 06:44:07,241 - signingscript.sign - DEBUG - sign_authenticode_file took 165.34s; RSS:131556 (+0)
2022-04-06 06:44:08,174 - winsign.sign - DEBUG - Generating dummy signature
2022-04-06 06:44:08,176 - winsign.osslsigncode - DEBUG - running: ['osslsigncode', 'sign', '-certs', PosixPath('/tmp/tmpcaizjtur/cert.pem'), '-key', PosixPath('/tmp/tmpcaizjtur/cert.pem'), '-h', 'sha256', '-in', PosixPath('/app/workdir/zip0xxo78w6/firefox/gmp-clearkey/0.1/clearkey.dll'), '-out', PosixPath('/tmp/tmpcaizjtur/signed1.dll'), '-i', 'https://mozilla.org']
2022-04-06 06:44:08,194 - winsign.osslsigncode - DEBUG - running: ['osslsigncode', 'extract-signature', '-in', PosixPath('/tmp/tmpcaizjtur/signed1.dll'), '-out', PosixPath('/tmp/tmpcaizjtur/signature')]
2022-04-06 06:44:08,220 - winsign.sign - DEBUG - Re-signing with real keys
2022-04-06 06:44:08,228 - winsign.asn1 - DEBUG - Digest to sign is: b'a353fc3041cadffe37de9eab4abeba06bdcdd24648a1bd6247816f843bfe3e98'
2022-04-06 06:44:08,228 - signingscript.sign - DEBUG - make_signing_req took 0.00s; RSS:131556 (+0)
2022-04-06 06:44:08,230 - signingscript.sign - DEBUG - req_size: 58
2022-04-06 06:44:08,266 - signingscript.sign - DEBUG - Autograph response: 201
2022-04-06 06:44:08,266 - signingscript.sign - DEBUG - call_autograph took 0.04s; RSS:131556 (+0)
2022-04-06 06:44:08,266 - signingscript.sign - DEBUG - sign_with_autograph took 0.04s; RSS:131556 (+0)
2022-04-06 06:44:08,266 - signingscript.sign - DEBUG - sign_hash_with_autograph took 0.04s; RSS:131556 (+0)
2022-04-06 06:44:08,452 - winsign.sign - DEBUG - Attaching new signature
2022-04-06 06:44:08,454 - winsign.osslsigncode - DEBUG - running: ['osslsigncode', 'attach-signature', '-sigin', PosixPath('/tmp/tmpr0zymlup/sigfile'), '-CAfile', '/app/signingscript/src/signingscript/data/authenticode_dep_ca.crt', '-untrusted', '/usr/lib/ssl/certs/ca-certificates.crt', '-in', PosixPath('/app/workdir/zip0xxo78w6/firefox/gmp-clearkey/0.1/clearkey.dll'), '-out', PosixPath('/app/workdir/zip0xxo78w6/firefox/gmp-clearkey/0.1/clearkey.dll-new')]
2022-04-06 06:44:08,481 - winsign.sign - DEBUG - Done!
2022-04-06 06:44:08,482 - signingscript.sign - DEBUG - sign_authenticode_file took 165.70s; RSS:131556 (+0)
2022-04-06 06:44:32,879 - winsign.sign - DEBUG - Generating dummy signature
2022-04-06 06:44:32,880 - winsign.osslsigncode - DEBUG - running: ['osslsigncode', 'sign', '-certs', PosixPath('/tmp/tmp7_0scbri/cert.pem'), '-key', PosixPath('/tmp/tmp7_0scbri/cert.pem'), '-h', 'sha256', '-in', PosixPath('/app/workdir/zip0xxo78w6/firefox/xul.dll'), '-out', PosixPath('/tmp/tmp7_0scbri/signed1.dll'), '-i', 'https://mozilla.org']
2022-04-06 06:44:33,471 - winsign.osslsigncode - DEBUG - running: ['osslsigncode', 'extract-signature', '-in', PosixPath('/tmp/tmp7_0scbri/signed1.dll'), '-out', PosixPath('/tmp/tmp7_0scbri/signature')]
2022-04-06 06:44:33,507 - winsign.sign - DEBUG - Re-signing with real keys
2022-04-06 06:44:33,515 - winsign.asn1 - DEBUG - Digest to sign is: b'8f83c263a42e312be83d941c6e617b118e1b236a698c4e0fc71e1880fb82c3e3'
2022-04-06 06:44:33,516 - signingscript.sign - DEBUG - make_signing_req took 0.00s; RSS:131556 (+0)
2022-04-06 06:44:33,517 - signingscript.sign - DEBUG - req_size: 58
2022-04-06 06:44:33,591 - signingscript.sign - DEBUG - Autograph response: 201
2022-04-06 06:44:33,591 - signingscript.sign - DEBUG - call_autograph took 0.08s; RSS:131556 (+0)
2022-04-06 06:44:33,591 - signingscript.sign - DEBUG - sign_with_autograph took 0.08s; RSS:131556 (+0)
2022-04-06 06:44:33,591 - signingscript.sign - DEBUG - sign_hash_with_autograph took 0.08s; RSS:131556 (+0)
2022-04-06 06:44:33,710 - scriptworker.utils - WARNING - retry_async: _winsign_helper: too many retries!
2022-04-06 06:44:33,710 - signingscript.sign - DEBUG - sign_authenticode_file took 192.48s; RSS:131556 (+0)
2022-04-06 06:44:33,710 - signingscript.sign - DEBUG - sign_authenticode_zip took 194.75s; RSS:131556 (+0)
Traceback (most recent call last):
  File "/app/bin/signingscript", line 8, in <module>
    sys.exit(main())
  File "/app/lib/python3.9/site-packages/signingscript/script.py", line 82, in main
    return scriptworker.client.sync_main(async_main, default_config=get_default_config())
  File "/app/lib/python3.9/site-packages/scriptworker/client.py", line 166, in sync_main
    loop.run_until_complete(_handle_asyncio_loop(async_main, context))
  File "/usr/local/lib/python3.9/asyncio/base_events.py", line 642, in run_until_complete
    return future.result()
  File "/app/lib/python3.9/site-packages/scriptworker/client.py", line 205, in _handle_asyncio_loop
    await async_main(context)
  File "/app/lib/python3.9/site-packages/signingscript/script.py", line 42, in async_main
    output_files = await sign(context, os.path.join(work_dir, path), path_dict["formats"], authenticode_comment=path_dict.get("comment"))
  File "/app/lib/python3.9/site-packages/signingscript/task.py", line 151, in sign
    output = await signing_func(context, output, fmt, **kwargs)
  File "/app/lib/python3.9/site-packages/signingscript/sign.py", line 95, in wrapped
    return await f(*args, **kwargs)
  File "/app/lib/python3.9/site-packages/signingscript/sign.py", line 1393, in sign_authenticode_zip
    [f.result() for f in done]
  File "/app/lib/python3.9/site-packages/signingscript/sign.py", line 1393, in <listcomp>
    [f.result() for f in done]
  File "/app/lib/python3.9/site-packages/signingscript/sign.py", line 95, in wrapped
    return await f(*args, **kwargs)
  File "/app/lib/python3.9/site-packages/signingscript/sign.py", line 1338, in sign_authenticode_file
    await retry_async(
  File "/app/lib/python3.9/site-packages/scriptworker/utils.py", line 273, in retry_async
    _check_number_of_attempts(attempt, attempts, func, "retry_async")
  File "/app/lib/python3.9/site-packages/scriptworker/utils.py", line 268, in retry_async
    return await func(*args, **kwargs)
  File "/app/lib/python3.9/site-packages/signingscript/sign.py", line 1276, in _winsign_helper
    if not await winsign.sign.sign_file(*args, **kwargs):
  File "/app/lib/python3.9/site-packages/winsign/sign.py", line 128, in sign_file
    sig = await winsign.timestamp.add_old_timestamp(sig, timestamp_url)
  File "/app/lib/python3.9/site-packages/winsign/timestamp.py", line 182, in add_old_timestamp
    ts = await get_old_timestamp(signature, timestamp_url)
  File "/app/lib/python3.9/site-packages/winsign/timestamp.py", line 141, in get_old_timestamp
    ci, _ = der_decode(base64.b64decode(await resp.read()), ContentInfo())
  File "/app/lib/python3.9/site-packages/pyasn1/codec/ber/decoder.py", line 1337, in __call__
    raise error.SubstrateUnderrunError(
pyasn1.error.SubstrateUnderrunError: Short octet stream on tag decoding
exit code: 1

Comment 1

[Julien Cristau [:jcristau]]

Looks similar to yesterday's digicert incident (https://status.digicert.com/incidents/64vmbtb8m91x) except today their status page doesn't list anything (yet?).
Running winsign's test_osslsigncode.py locally against timestamp.digicert.com I see the same errors as in automation.

Comment 2

[Julien Cristau [:jcristau]]

Resetting status flags because this is not an in-tree issue, and would affect signing across all branches and products.

Comment 3

[Julien Cristau [:jcristau]]

Looks like digicert recovered.

Comment 4

[Intermittent Failures Robot]

21 failures in 546 pushes (0.038 failures/push) were associated with this bug yesterday.

Repository breakdown:

• mozilla-central: 3
• autoland: 18

Platform and build breakdown:

• windows2012-64-shippable: 4
  • opt: 4
• windows2012-32-shippable: 2
  • opt: 2
• windows2012-aarch64-shippable: 2
  • opt: 2
• windows2012-32: 5
  • debug: 1
  • opt: 4
• windows2012-64: 4
  • opt: 4
• windows2012-aarch64: 4
  • opt: 4

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

Comment 5

[Andreea Pavel [:apavel]]

I assume this can be closed for now. Feel free to reopen if I'm mistaken.
Thank you.

Comment 6

[Intermittent Failures Robot]

21 failures in 2922 pushes (0.007 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 18
• mozilla-central: 3

Platform and build breakdown:

• windows2012-32: 5
  • debug: 1
  • opt: 4
• windows2012-64: 4
  • opt: 4
• windows2012-aarch64: 4
  • opt: 4
• windows2012-64-shippable: 4
  • opt: 4
• windows2012-32-shippable: 2
  • opt: 2
• windows2012-aarch64-shippable: 2
  • opt: 2

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