Tox test build failing (can't reproduce, maybe related to GPG) #171
Comments
|
Probably related: |
|
Is it possible that the subprocess call to GPG is not completing successfully in certain cases, and is returning empty data? For instance: in-toto/in_toto/gpg/functions.py Lines 230 to 236 in ae8ddcd
https://docs.python.org/2/library/subprocess.html#subprocess.Popen.communicate |
|
I was able to trigger the following exception on my local machine: The affected lines are in coverage output: Lines 192 to 196 in ae8ddcd |
|
I'm unsure on how to move forward with this. One option would be to move to |
log.debug stdout and stderr from running gpg commands in a subprocess to troubleshoot: in-toto#171
Add log.debug stdout and stderr for all subprocess calls to gpg command to troubleshoot #171.
Add log.debug stdout and stderr for all subprocess calls to gpg command to troubleshoot in-toto#171 (failing ci builds).
|
Hooray, this is the first travis log that actually gives us some context (courtesy of #240) on these obscure failures. Unfortunately, it's still not obvious why the signature verification fails. |
|
I investigated the failing travis build a little further by manually parsing the relevant signature and key bytes, added to the log through the I tried both key and signature parsed from the failed test log with a corresponding signature and key respectively created outside of the failed test. I was able to use the key from the failed test to verify the separately created signature, which rules out that the error is related to the key export. However, verifying the signature from the failed test with a separately created key failed. FWIW, the signature bytes array from the failed test log is shorter ( (to be continued) |
|
@lukpueh @vladimir-v-diaz @SantiagoTorres Dang, you guys always happen upon the weirdest parts of gnupg: Subpacket 33 (Issuer Fingerprint) from [1]:
And here it is in the source [2]. That maths don't come out as perfect as I was expecting, but from what I can tell your missing bytes are because the older As for a solution, maybe update If that's not possible then we have to figure out how to prod older [1] https://lists.gnupg.org/pipermail/gnupg-users/2018-January/059881.html |
|
Yes, you're absolutely right. The different versions definitely account for the different lengths of the raw bytes (because of the missing subpackt 33 in older versions). I do wonder why the actual signature data, which does not include the subpackets, is also 2 bytes shorter. But maybe there was also a change between versions. At any rate, I don't think that the missing subpacket 33 is the reason for these failures. For one, we have a workaround if the signature only has subpacket 16 (see But thanks a lot for chiming in here. I could use some help on this. |
|
yeah, I do see the error log mentioning that subpacket 33 is missing. That in and by itself should be enough to be worried of using the wrong underlying gpg library. I wonder if somehow this is using <2.1 sometimes... |
|
On a related note, lukpueh. I'll dig into the signature itself and try to figure out what's exactly the discrepancy, I suspect it's just padding in PKCS1.5 |
|
Well, from experience Travis is known to have some pretty ancient defaults, heh |
|
@lukpueh Ah, I see. Yeah, that missing 2 bytes is very strange. |
|
From reviewing this, actually the math makes sense perfectly for the signature packet: This is 286 bytes, plus 24 bytes from the missing subpacket 33 (the subpacket 33 would be
I tried this, I ended up settling for mocking our signing method: newsig_obj = gpg_sign_object(signable_bytes)
# to trick the signing method into thinking longkeyid wasn't available
backup_keyid = newsig_obj['keyid']
newsig_obj['keyid'] = ''
newsig_obj['short_keyid'] = backup_keyid[-16:]
with mock.patch('in_toto.gpg.common.parse_signature_packet') as mocked_method:
mocked_method.return_value = newsig_obj
failing_signature_object = gpg_sign_object(signable_bytes, keyid=newkey_sub)
print(failing_signature_object)This will trigger our replacement method, which does actually work, it appears... Further
This doesn't happen to me if I manually embed the keyid myself: # embedded from the logs
pubkey_info = parse_pubkey_bundle(pubkey, subkey)
signature_obj = parse_signature_packet(sig)
signature_obj['keyid'] = subkey
gpg_verify_signature(signature_obj, pubkey_info, signable_bytes)
# passesI wonder if I'm doing something wrong. If I compare two raw exported signature packets I see that the vs funnily enough, I do see that those two signatures have that two-byte discrepancy when using our impl Now maybe I'm seeing things, but the probability of our tests failing look a little familiar* when I do this: >>> import in_toto.gpg.functions as f
>>> from test_data import signable_bytes
>>> from collections import Counter
>>> counter = Counter()
>>> for i in range(1,10000):
... sig = f.gpg_sign_object(signable_bytes)
... counter[len(sig['signature'])] += 1
...
...
>>> counter
Counter({512: 9833, 510: 166})
>>> 166/9833
0.016881928200955965I'm utterly confused, but also very curious to see if we're onto something.
|
|
Thanks, @SantiagoTorres for digging into this. I do think we are on to something. I updated your awesome script to see if signature length and verification failure are related. It seems that they are: >>> # In the in-toto project root (using the test keychain)
>>> import in_toto.gpg.functions as f
>>> from collections import Counter
>>> counter = Counter()
>>>
>>> keyid = "8465A1E2E0FB2B40ADB2478E18FB3F537E0C8A17"
>>> homedir = "tests/gpg_keyrings/rsa"
>>> pubkey = f.gpg_export_pubkey(keyid, homedir=homedir)
>>> data = b"hello"
>>>
>>> for i in range(1,1000):
>>> sig = f.gpg_sign_object(data, homedir=homedir)
>>> valid = f.gpg_verify_signature(sig, pubkey, data)
>>> counter[(len(sig['signature']), valid)] += 1
>>>
>>> print(counter)
Counter({(512, True): 9842, (510, False): 157})We see that signatures that fail are two bytes shorter, than signatures that pass. |
|
I wrote another test script to investigate failing/passing signatures and signature data length outside of our Python gpg interface. It repeatedly creates detached signatures for some test data, then verifies each signature and prints the (unique) results, i.e. pass or fail together with the signature data length. # In in-toto root
mkdir sigs
echo data > data.txt
# Create N signatures over data.txt and store them in `sigs` dir
for (( i=1; i<=10000; i++ ))
do
cat data.txt | gpg2 --detach-sign --digest-algo SHA256\
--default-key 8465A1E2E0FB2B40ADB2478E18FB3F537E0C8A17\
--homedir tests/gpg_keyrings/rsa > sigs/${i}.sig 2> /dev/null
done
# Verify each detached signature and echo (unique) results + signature length
for sig in sigs/*
do
gpg2 --homedir tests/gpg_keyrings/rsa\
--verify $sig data.txt &> /dev/null
echo $([[ $? -eq 0 ]] && echo "PASS" || echo "FAIL")\
$(cat $sig | gpg2 --list-packets | grep data)
done | sort | uniq
# Clean up
rm -rf sigs
rm data.txtHere's the result of a run on above script: PASS data: [2041 bits]
PASS data: [2043 bits]
PASS data: [2044 bits]
PASS data: [2045 bits]
PASS data: [2046 bits]
PASS data: [2047 bits]
PASS data: [2048 bits]I did a similar thing with our implementation and the Python snippet from above, where I patched |
|
Btw. I doubt that it has something to do with the gpg version and the presence or absence of subpacket 33, as above Python test snippet had a similar pass/fail ratio on a system with old gpg and a system with new gpg. I really think it has something to do with gpg returning an incomplete signature (i.e. where signature data length <= 2040 bits). I wonder why this only seems to happen when we run gpg in a Python subprocess. |
|
I'm manually replaying @lukpueh's bash script and can report that the signature timestamp does not seem to play a role. A few iterations of |
|
I also ran the results from the bash script (removing |
|
I think I am getting closer... Here's a Python script to reproduce my finding: import os
import in_toto.gpg.functions as gpgf
import in_toto.gpg.common as gpgc
import in_toto.process
# Works when being in the in-toto project repo root
IN_TOTO_TEST_GPG_KEYRING = "tests/gpg_keyrings/rsa"
# Signature copied from travis log
# https://travis-ci.org/in-toto/in-toto/jobs/455583004#L951
sig_raw = b'\x89\x01\x1b\x04\x00\x01\x08\x00\x06\x05\x02[\xed\xa0S\x00\n\t\x10\x9b\xe9\xdfQ1\xd9$\xe9\xcf\x99\x07\xf8\xd2C\xd1\xe5\x9cR\xfd/\x89U\x13\xe0S\x1d\xc4\x03\x0c\xa5\x9f\xec\x94I\xd9\xaf\xc5\xd7\xd7\x9b\'\x9e9\xd0\'H\x9d\x16\xbc\xa8\xf8\x9fmH\x16([\x1fpi\nj\x84Z\x90\xbb\x95[\x9b\x07\x98:\xd4y\xf8\x9e\xb4\xd7\xe7\x82\x7f\xefX\xfcx)\x7fz\x9e}\xd8\x8b\x14\xe1\xd0\r\xea\xd7\xe8z\x86\xfd\xd0\xbe\xe7\xd7\xa0UY\xdf\xed\xf7gM+1(\x07\x0bWMY\xb2G\xb7\x96?\xab\x91\xeef\x12\x89\x1f\x8ak\xd6\xf5\xbf\x92vB_\x0b\x86]\xfd\xa4\xe3\x83}\xa8\xedG\x9fk3\x841&\xb6\\\x0bKt\xceg\x99\x11\x9d\xc1pGi"\x01\r\xb5\\M\x12?\x1fuD\xe1\x95\x94\x9a\x1cr\xed>\xc9\xcf\x12~\x02\xea\xc9\xb5\x81\x06\xcd\xcd"\xfbM\xcd\xc0CClMw\x1d\xdb=#\x05\xdbO\xfb@\xe9\x94\xf1"\xa7[f`\x0f\x0c\x0e\xbb_\xfd\x19 2\xbf\x82\xf6\x14[\xf5\x1b\xc3\x17\x9b\x8c%h\x05>E\x0b\xe0t`$\xab}n\xdc@'
# Key and link data as used in the failing unittest, i.e.
# TestInTotoVerifyThresholdsGpgSubkeys.test_verify_link_signature_thresholds__S_S_S
content = b'{"_type":"link","byproducts":{},"command":[],"environment":{},"materials":{},"name":"name","products":{}}'
keyid = "c5a0abe6ec19d0d65f85e2c39be9df5131d924e9"
key = {'method': 'pgp+rsa-pkcsv1.5', 'type': 'rsa', 'hashes': ['pgp+SHA2'], 'keyid': '8465a1e2e0fb2b40adb2478e18fb3f537e0c8a17', 'keyval': {'private': '', 'public': {'e': '010001', 'n': 'da59409e6ede307a52f6851954a7bd4b9e309bd40a390f8c0de9722b6310110ef0b095bf1c473e33db97150edae05c63dda70c03902701b15f3c5c308947e1b06675b4f1112030f1145be84ae1562e9120c2d429b20d5056337cbc97fc8b5db5704a21db635d00b2157ed68a403c793e9958b77e00163f99b01809e08ee9099b99b117c086501e79eb947f760a0715bead0024c48d81f9000671c4306a93725965f3ff2dc9806eaf081357f0268cab8ba7582d2e95e51225a9dc7ed31a9568c45568d7917b05e7c954d561cd084291e77a7bdd69e3ac2f9091de55fe3f4e730147e880e2fc044c5f7c04c75ce33a3c0b52380f4d60309708c56185f3bce6703b'}}, 'subkeys': {'6a112fd3390b2e53afc2e57f8fc8e12099aeceea': {'method': 'pgp+rsa-pkcsv1.5', 'type': 'rsa', 'hashes': ['pgp+SHA2'], 'keyid': '6a112fd3390b2e53afc2e57f8fc8e12099aeceea', 'keyval': {'private': '', 'public': {'e': '010001', 'n': 'a40806286bfeb2bee9f36d9953ef2f83265f2b802024981775ce8498f6f08a6d7ea14dcecc1b82013b71e7d93d6ecb294f8880ee703e01a73cb45d8740221671a04f4b6cdf79f44438c7b8b8b4963d4308e0f40dbe18aee79e48fdf9fecb02661b76da7ba17a5dffa88afc8984743d3a033879a26384cce12350e25068ec38d4e3d7075176b6020882ca81a12d174df864dc59f11e19f98eec5e5e22d0ab6cc32bf1dd70cf4c2ca7c6aa1be48da0f94dcebc2f3c425d0d1e536e01f01ce5dfdc655f2994ccadd120469d55e2ad2f1e9c3483abcfefcf959d600a2ebb7990b46841b15d25537d8f1fbeda9347ffa466ccfcceca4567f9a7d84dd767fdf037fe97'}}}, 'c5a0abe6ec19d0d65f85e2c39be9df5131d924e9': {'method': 'pgp+rsa-pkcsv1.5', 'type': 'rsa', 'hashes': ['pgp+SHA2'], 'keyid': 'c5a0abe6ec19d0d65f85e2c39be9df5131d924e9', 'keyval': {'private': '', 'public': {'e': '010001', 'n': 'c152fc1f1535a6d3c1e8c0dece7f0a1d09324466e10e4ea51d5d7223ab125c1743393eebca73ccb1022d44c379fae30ef63b263d0a793882a7332ef06f28a4b9ae777f5d2d8d289167e86c162df1b9a9e127acb26803688556ecb08492d071f06caf88cea95571354349d8ef131eff03b0d259fae30ebf8dac9ab5acd6f26f4770fe2f30fcd0a3c54f03463a3094aa6524e39027a625108f04e12475da248fb3b536df61b0f6e2954739b8828c61171f66f8e176823e1c887e65fa0aec081013b2a50ed60515f7e3b3291ca443e1222b9b625005dba045a7208188fb88d436d473f6340348953e891354c7a5734bf64e6274e196db3074a7ce3607960baacb1b'}}}}}
# Create in-toto formatted signature from raw signature
sig = gpgc.parse_signature_packet(sig_raw)
sig["keyid"] = keyid
del sig["short_keyid"]
# Verify signature with in-toto (pyca cryptography)
result = gpgf.gpg_verify_signature(sig, key, content)
if not result:
print("FAIL (using pyca/cryptography)")
else:
print("PASS (using pyca/cryptography)") # It does not :'(
# Verify signature with gpg
with open("failing.sig", "wb") as f: f.write(sig_raw)
with open("content.txt", "wb") as f: f.write(content)
cmd = ["gpg2", "--homedir", IN_TOTO_TEST_GPG_KEYRING, "--verify", "failing.sig", "content.txt"]
in_toto.process.run(cmd)
# gpg: WARNING: unsafe permissions on homedir '[...]tests/gpg_keyrings/rsa'
# gpg: Signature made Thu Nov 15 17:35:31 2018 CET
# gpg: using RSA key 9BE9DF5131D924E9
# gpg: Good signature from "Joan Doe <test@donotuseth.is>" [ultimate]
# Clean up
os.remove("failing.sig")
os.remove("content.txt") |
|
I think I found a fix to this issue. I have a trove of reasons this makes sense but what led me to try this out was the following:
>>> (318/(99682+318))*100
0.318Other runs yielded:
After adding Lukas's changes, I could verify that indeed only signature verification fails when the signature is 510 bytes and 510 bytes only (corresponding to a 2040-bit signature). This led me to believe that this was related to a wrong handling of the MPI parsing routine in in_toto, but I discarded it after realizing that the bitlength of the signature actually matches what the --list-packages flag says. Instread, the issue seems to be a discrepancy in how MPI numbers are represented between the openssl and the gpg backends. It appears that the length of the signature varies as long as there are eight-or-more leading 0's in the signature. This yields the "shorter" signature in the gpg backend, which throws off the openssl pyca/cryptography backend. A simple solution to this issue is to add the leading zeroes when serializing the signature field to an in-toto compliant signature object: sig['signature'] = "00{}".format(sig['signature']I know it sounds dumb, but you can try it yourself today: import in_toto.gpg.functions as f
import in_toto.gpg.functions as f
from in_toto.gpg.common import (parse_pubkey_bundle, parse_signature_packet)
from test_data import signable_bytes, pubkey
from collections import Counter
master = "8DE91900FF8DB2F8A3B375F83A06AB9E509F3220" # use your own dumbly-generated key
counter = Counter()
fixed_signatures = Counter()
parsed_pubkey = f.gpg_export_pubkey(master)
for i in range(1,100001):
sig = f.gpg_sign_object(signable_bytes)
valid = f.gpg_verify_signature(sig, parsed_pubkey, signable_bytes)
counter[(len(sig['signature']), valid)] += 1
if not valid and len(sig['signature']) == 510:
sig['signature'] = "00{}".format(sig['signature'])
valid = f.gpg_verify_signature(sig, parsed_pubkey, signable_bytes)
fixed_signatures[valid] += 1
print("signatures computed {}".format(counter))
print("signatures fixed by 0-padding {}".format(fixed_signatures))Of course this is not the final fix, as we need to be more clever about it. Technically, there may be signatures with 16 leading 0 bits (and I think our computer should be awarded some bitcoin when this happens), and thus we will have to 0-pad on the leading signature in a more clever way. Expect a patch in the coming days about it :) |
|
@lukpueh @alyptik @aaaaalbert Please take a look 👍 |
It appears the specification for PKCSv1.5 doesn't say how long should a signature should be (i.e., should we zero-pad the signature or should we use the minimum number of bits required). In this case, signatures generated using gnupg would sometimes be 8*n bits shorter than the public key length, which would result in signatures that fail to verify due to missing leading zeroes (the leading zeroes existed at the bit level however). Zero-left-pad signature objects that do not match the length of the exponent `n` on a gpg rsa public key object before verification.
Add log.debug stdout and stderr for all subprocess calls to gpg command to troubleshoot in-toto#171 (failing ci builds).
It appears the specification for PKCSv1.5 doesn't say how long should a signature should be (i.e., should we zero-pad the signature or should we use the minimum number of bits required). In this case, signatures generated using gnupg would sometimes be 8*n bits shorter than the public key length, which would result in signatures that fail to verify due to missing leading zeroes (the leading zeroes existed at the bit level however). Zero-left-pad signature objects that do not match the length of the exponent `n` on a gpg rsa public key object before verification.
Add log.debug stdout and stderr for all subprocess calls to gpg command to troubleshoot in-toto/in-toto#171 (failing ci builds).
Add log.debug stdout and stderr for all subprocess calls to gpg command to troubleshoot in-toto/in-toto#171 (failing ci builds).
Add log.debug stdout and stderr for all subprocess calls to gpg command to troubleshoot in-toto/in-toto#171 (failing ci builds).
Add log.debug stdout and stderr for all subprocess calls to gpg command to troubleshoot in-toto/in-toto#171 (failing ci builds).
Add log.debug stdout and stderr for all subprocess calls to gpg command to troubleshoot in-toto/in-toto#171 (failing ci builds).
Description of issue or feature request:
I keep getting build errors for different tox jobs, locally and on Travis CI. But when I re-run tox (locally) or restart the Travis build (via web UI) the builds pass.
Here's parts of a local tox build for commit 7016b95 (PR #170) , where py3.6 failed:
I tried the following things, none of which could reproduce the problem:
-roption (forcing recreation of virtual environments)The problem first occurred on a Travis build adding Python3 support. Since I restarted the build manually and it passed afterwards the error message is lost.
The text was updated successfully, but these errors were encountered: