Broken build in master

[ronaldtse]

Only one test failed on a macOS machine.

https://travis-ci.org/riboseinc/rnp/builds/519291522

From https://travis-ci.org/riboseinc/rnp/jobs/519291532

Test project /Users/travis/local-builds/rnp-build

    Start 1: setupTestData

1/3 Test #1: setupTestData ....................   Passed    0.11 sec

    Start 2: rnp_tests

    Start 3: cli_tests

2/3 Test #2: rnp_tests ........................   Passed  1487.87 sec

3/3 Test #3: cli_tests ........................***Failed  1585.82 sec

[ni4]

@ronaldtse Yeah, investigating this now. Possibly broke something with armored stream processing changes, or some kind of other randomish error.

[ni4]

It seems something happened with the time on job:

/Users/travis/local-installs/gpg-install/bin/gpg --homedir /var/folders/nz/vv4_9tw56nv9k3tkvyszvwg80000gn/T/rnpctmpwZpjgC/.gpg --armor -e -z 4 --compress-algo 2 -r encryption@rnp --batch --trust-model always --output /var/folders/nz/vv4_9tw56nv9k3tkvyszvwg80000gn/T/rnpctmpwZpjgC/cleartext.gpg /var/folders/nz/vv4_9tw56nv9k3tkvyszvwg80000gn/T/rnpctmpwZpjgC/cleartext.txt

gpg: key 38B56B9B6D75723A was created 332 seconds in the future (time warp or clock problem)

@dewyatt Do you have any idea whether we should deeper debug this or just consider as random travis failure and safely ignore?

[dewyatt]

@ni4 I do think it's likely just travis being flaky, it passed when I re-ran it.

[dewyatt]

I'm thinking let's close this for now and re-open it if we see this behavior continue. I don't know much about the macOS backend setup travis is using, but it does seem as if maybe the clock jumped. If we continue to have this problem, we may want to add an ntpdate/sntp call to before_install.sh or similar.

[ronaldtse]

Seems like a time drift indeed. Thanks guys!

[dewyatt]

Re-opening since I've been continuing to see issues on macOS CI builds: https://gist.github.com/dewyatt/248b549d71299fa8c6510a0e2266c25b

I've seen at least two that appear to be time related:

[ RUN      ] s2k_iteration_tuning
[  ERROR   ] --- static_cast<double>(iters_100) / iters_10 > 6
[   LINE   ] --- /Users/travis/build/riboseinc/rnp/src/tests/cipher.cpp:749: error: Failure!
[  FAILED  ] s2k_iteration_tuning

/Users/travis/local-installs/gpg-install/bin/gpg --homedir /var/folders/nz/vv4_9tw56nv9k3tkvyszvwg80000gn/T/rnpctmpLRxKJi/.gpg --armor --pinentry-mode=loopback -z 6 --compress-algo 2 --batch --yes --passphrase password --trust-model always -u signing@gpg -o /var/folders/nz/vv4_9tw56nv9k3tkvyszvwg80000gn/T/rnpctmpLRxKJi/cleartext.sig -s /var/folders/nz/vv4_9tw56nv9k3tkvyszvwg80000gn/T/rnpctmpLRxKJi/cleartext.txt
gpg: key 796EB7B79958CDD7 was created 157 seconds in the future (time warp or clock problem)
gpg: key 796EB7B79958CDD7 was created 157 seconds in the future (time warp or clock problem)
gpg: skipped "signing@gpg": Unusable secret key
gpg: signing failed: Unusable secret key
gpg signing failed

And one that I can't see as being related to time:

/Users/travis/local-installs/gpg-install/bin/gpg --homedir /var/folders/nz/vv4_9tw56nv9k3tkvyszvwg80000gn/T/rnpctmp2N75d0/.gpg --armor -c --cipher-algo blowfish -z 9 --s2k-count 65536 --batch --passphrase password --output /var/folders/nz/vv4_9tw56nv9k3tkvyszvwg80000gn/T/rnpctmp2N75d0/cleartext.gpg /var/folders/nz/vv4_9tw56nv9k3tkvyszvwg80000gn/T/rnpctmp2N75d0/cleartext.txt

gpg: cipher_encrypt: key not set
[repeats]

(cipher_encrypt is in libgcrypt, so it seems like maybe it could be a gnupg bug (doubt) or memory corruption)

All of these occurred on different hosts in the macstadium backend that Travis uses.

[skalee]

Is there a chance that supporting OS X in gpg-build-scripts (riboseinc/gpg-build-scripts#31 and riboseinc/gpg-build-scripts#32) will help?

[dewyatt]

@skalee Not likely as it affects rnp too.

I saw some more today:

/Users/travis/local-builds/rnp-build/src/rnp/rnp --homedir /var/folders/nz/vv4_9tw56nv9k3tkvyszvwg80000gn/T/rnpctmpkQgRH5/.rnp -r encryption@rnp --encrypt /var/folders/nz/vv4_9tw56nv9k3tkvyszvwg80000gn/T/rnpctmpkQgRH5/cleartext.txt --output /var/folders/nz/vv4_9tw56nv9k3tkvyszvwg80000gn/T/rnpctmpkQgRH5/cleartext.rnp

[signature_check() /Users/travis/build/riboseinc/rnp/src/librepgp/stream-sig.cpp:1108] signature created 162 seconds in future
[signature_check() /Users/travis/build/riboseinc/rnp/src/librepgp/stream-sig.cpp:1108] signature created 166 seconds in future
[signature_check() /Users/travis/build/riboseinc/rnp/src/librepgp/stream-sig.cpp:1099] invalid or untrusted key
[signature_check() /Users/travis/build/riboseinc/rnp/src/librepgp/stream-sig.cpp:1108] signature created 168 seconds in future
[encrypted_add_recipient() /Users/travis/build/riboseinc/rnp/src/librepgp/stream-write.cpp:510] attempt to use invalid key as recipient
[rnp_protect_file() /Users/travis/build/riboseinc/rnp/src/rnp/rnpcli.cpp:1156] failed with error code 0x12000006

rnp encryption failed

[ RUN      ] rnpkeys_generatekey_testSignature
[signature_check() /Users/travis/build/riboseinc/rnp/src/librepgp/stream-sig.cpp:1108] signature created 303 seconds in future
[signature_check() /Users/travis/build/riboseinc/rnp/src/librepgp/stream-sig.cpp:1099] invalid or untrusted key
[signature_check() /Users/travis/build/riboseinc/rnp/src/librepgp/stream-sig.cpp:1120] key is newer than signature
[validate_pgp_key_signature() /Users/travis/build/riboseinc/rnp/src/librepgp/stream-key.cpp:1563] bad signature

[ronaldtse]

master is passing, closing this.