test-remote-gpg-import.sh intermittently failing: Can't check signature: public key not found #2351

smcv · 2021-04-18T15:05:33Z

Seen intermittently on Debian 11 autobuilders with 2021.2 and 2021.1. #2313 mentions a similar-looking failure on Arch Linux.

A log, generated on Debian armhf (ARMv7 EABI hardfloat) using 2021.2 patched with #2350

ERROR: tests/test-remote-gpg-import.sh
======================================

# testlabel.txt: security.selinux: No such attribute
++ BUILT_WITH_ASAN=
++ test -n ''
++ test -n ''
++ test -z ''
++ test -z ''
++ CMD_PREFIX='env LD_PRELOAD=/<<PKGBUILDDIR>>/tests/libreaddir-rand.so'
++ test -n /<<PKGBUILDDIR>>
++ OSTREE_HTTPD=/<<PKGBUILDDIR>>/ostree-trivial-httpd
++ _have_user_xattrs=
++ _have_systemd_and_libmount=
++ _have_strace_fault_injection=
++ libtest_exit_cmds+=(libtest_cleanup_gpg)
++ ED25519PUBLIC=
++ ED25519SEED=
++ ED25519SECRET=
+ unset OSTREE_GPG_HOME
+ setup_fake_remote_repo1 archive
+ mode=archive
+ shift
+ commit_opts=
+ '[' 0 -eq 0 ']'
++ pwd
+ oldpwd=/var/tmp/tap-test.5Ur8lk
+ mkdir ostree-srv
+ cd ostree-srv
+ mkdir gnomerepo
+ ostree_repo_init gnomerepo --mode=archive
+ repo=gnomerepo
+ shift
+ env LD_PRELOAD=/<<PKGBUILDDIR>>/tests/libreaddir-rand.so ostree --repo=gnomerepo init --mode=archive
+ test -n 1
+ echo -e 'disable-xattrs=true\n'
+ mkdir gnomerepo-files
+ cd gnomerepo-files
+ echo first
+ mkdir baz
+ echo moo
+ echo alien
+ env LD_PRELOAD=/<<PKGBUILDDIR>>/tests/libreaddir-rand.so ostree --repo=/var/tmp/tap-test.5Ur8lk/ostree-srv/gnomerepo commit --add-metadata-string version=3.0 -b main -s 'A remote commit' -m 'Some Commit body'
+ mkdir baz/deeper
+ env LD_PRELOAD=/<<PKGBUILDDIR>>/tests/libreaddir-rand.so ostree --repo=/var/tmp/tap-test.5Ur8lk/ostree-srv/gnomerepo commit --add-metadata-string version=3.1 -b main -s 'Add deeper'
+ echo hi
+ mkdir baz/another/
+ echo x
+ env LD_PRELOAD=/<<PKGBUILDDIR>>/tests/libreaddir-rand.so ostree --repo=/var/tmp/tap-test.5Ur8lk/ostree-srv/gnomerepo commit --add-metadata-string version=3.2 -b main -s 'The rest'
+ cd ..
+ rm -rf gnomerepo-files
+ cd /var/tmp/tap-test.5Ur8lk
+ mkdir /var/tmp/tap-test.5Ur8lk/httpd
+ cd httpd
+ ln -s /var/tmp/tap-test.5Ur8lk/ostree-srv ostree
++ pwd
+ /<<PKGBUILDDIR>>/ostree-trivial-httpd --autoexit --log-file /var/tmp/tap-test.5Ur8lk/httpd/httpd.log --daemonize -p /var/tmp/tap-test.5Ur8lk/httpd-port
++ cat /var/tmp/tap-test.5Ur8lk/httpd-port
+ port=42077
+ echo http://127.0.0.1:42077
+ cd /var/tmp/tap-test.5Ur8lk
+ export 'OSTREE=env LD_PRELOAD=/<<PKGBUILDDIR>>/tests/libreaddir-rand.so ostree --repo=repo'
+ OSTREE='env LD_PRELOAD=/<<PKGBUILDDIR>>/tests/libreaddir-rand.so ostree --repo=repo'
+ num_non_gpg_tests=4
+ num_gpg_tests=2
+ num_tests=6
+ echo 1..6
+ cd /var/tmp/tap-test.5Ur8lk
+ mkdir repo
+ ostree_repo_init repo
+ repo=repo
+ shift
+ env LD_PRELOAD=/<<PKGBUILDDIR>>/tests/libreaddir-rand.so ostree --repo=repo init
+ test -n 1
+ echo -e 'disable-xattrs=true\n'
+ assert_not_has_file repo/R1.trustedkeys.gpg
+ test -f repo/R1.trustedkeys.gpg
++ cat httpd-address
+ env LD_PRELOAD=/<<PKGBUILDDIR>>/tests/libreaddir-rand.so ostree --repo=repo remote add R1 http://127.0.0.1:42077/ostree/gnomerepo
+ assert_not_has_file repo/R1.trustedkeys.gpg
+ test -f repo/R1.trustedkeys.gpg
+ env LD_PRELOAD=/<<PKGBUILDDIR>>/tests/libreaddir-rand.so ostree --repo=repo remote gpg-import --keyring /var/tmp/tap-test.5Ur8lk/gpghome/trusted/pubring.gpg R1 7FCA23D8472CDAFA
+ grep -o 'Imported [[:digit:]] GPG key'
+ assert_file_has_content result 'Imported 1 GPG key'
+ fpath=result
+ shift
+ for re in "$@"
+ grep -q -e 'Imported 1 GPG key' result
+ assert_has_file repo/R1.trustedkeys.gpg
+ test -f repo/R1.trustedkeys.gpg
+ env LD_PRELOAD=/<<PKGBUILDDIR>>/tests/libreaddir-rand.so ostree --repo=repo remote delete R1
+ assert_not_has_file repo/R1.trustedkeys.gpg
+ test -f repo/R1.trustedkeys.gpg
++ cat httpd-address
+ env LD_PRELOAD=/<<PKGBUILDDIR>>/tests/libreaddir-rand.so ostree --repo=repo remote add R1 http://127.0.0.1:42077/ostree/gnomerepo
+ env LD_PRELOAD=/<<PKGBUILDDIR>>/tests/libreaddir-rand.so ostree --repo=repo remote gpg-import --keyring /var/tmp/tap-test.5Ur8lk/gpghome/trusted/pubring.gpg R1 7FCA23D8472CDAFA
+ grep -o 'Imported [[:digit:]] GPG key'
+ assert_file_has_content result 'Imported 1 GPG key'
+ fpath=result
+ shift
+ for re in "$@"
+ grep -q -e 'Imported 1 GPG key' result
+ env LD_PRELOAD=/<<PKGBUILDDIR>>/tests/libreaddir-rand.so ostree --repo=repo remote gpg-import --keyring /var/tmp/tap-test.5Ur8lk/gpghome/trusted/pubring.gpg R1 D8228CFECA950D41 0D15FAE7DF444D67
+ grep -o 'Imported [[:digit:]] GPG key'
+ assert_file_has_content result 'Imported 2 GPG key'
+ fpath=result
+ shift
+ for re in "$@"
+ grep -q -e 'Imported 2 GPG key' result
+ env LD_PRELOAD=/<<PKGBUILDDIR>>/tests/libreaddir-rand.so ostree --repo=repo remote gpg-import --keyring /var/tmp/tap-test.5Ur8lk/gpghome/trusted/pubring.gpg R1 7FCA23D8472CDAFA 0D15FAE7DF444D67
+ grep -o 'Imported [[:digit:]] GPG key'
+ assert_file_has_content result 'Imported 0 GPG key'
+ fpath=result
+ shift
+ for re in "$@"
+ grep -q -e 'Imported 0 GPG key' result
+ env LD_PRELOAD=/<<PKGBUILDDIR>>/tests/libreaddir-rand.so ostree --repo=repo remote delete R1
++ cat httpd-address
+ env LD_PRELOAD=/<<PKGBUILDDIR>>/tests/libreaddir-rand.so ostree --repo=repo remote add R1 http://127.0.0.1:42077/ostree/gnomerepo
+ env LD_PRELOAD=/<<PKGBUILDDIR>>/tests/libreaddir-rand.so ostree --repo=repo remote gpg-import --keyring /var/tmp/tap-test.5Ur8lk/gpghome/trusted/pubring.gpg R1
+ grep -o 'Imported [[:digit:]] GPG key'
+ assert_file_has_content result 'Imported 3 GPG key'
+ fpath=result
+ shift
+ for re in "$@"
+ grep -q -e 'Imported 3 GPG key' result
+ env LD_PRELOAD=/<<PKGBUILDDIR>>/tests/libreaddir-rand.so ostree --repo=repo remote delete R1
++ cat httpd-address
+ env LD_PRELOAD=/<<PKGBUILDDIR>>/tests/libreaddir-rand.so ostree --repo=repo remote add R1 http://127.0.0.1:42077/ostree/gnomerepo
+ cat /var/tmp/tap-test.5Ur8lk/gpghome/key1.asc /var/tmp/tap-test.5Ur8lk/gpghome/key2.asc /var/tmp/tap-test.5Ur8lk/gpghome/key3.asc
+ grep -o 'Imported [[:digit:]] GPG key'
+ env LD_PRELOAD=/<<PKGBUILDDIR>>/tests/libreaddir-rand.so ostree --repo=repo remote gpg-import --stdin R1
+ assert_file_has_content result 'Imported 3 GPG key'
+ fpath=result
+ shift
+ for re in "$@"
+ grep -q -e 'Imported 3 GPG key' result
+ env LD_PRELOAD=/<<PKGBUILDDIR>>/tests/libreaddir-rand.so ostree --repo=repo remote delete R1
+ grep -o 'Imported [[:digit:]] GPG key'
++ cat httpd-address
+ env LD_PRELOAD=/<<PKGBUILDDIR>>/tests/libreaddir-rand.so ostree --repo=repo remote add --gpg-import /var/tmp/tap-test.5Ur8lk/gpghome/key1.asc R1 http://127.0.0.1:42077/ostree/gnomerepo
+ assert_file_has_content result 'Imported 1 GPG key'
+ fpath=result
+ shift
+ for re in "$@"
+ grep -q -e 'Imported 1 GPG key' result
+ grep -o 'Imported [[:digit:]] GPG key'
++ cat httpd-address
+ env LD_PRELOAD=/<<PKGBUILDDIR>>/tests/libreaddir-rand.so ostree --repo=repo remote add --gpg-import /var/tmp/tap-test.5Ur8lk/gpghome/key2.asc R2 http://127.0.0.1:42077/ostree/gnomerepo
+ assert_file_has_content result 'Imported 1 GPG key'
+ fpath=result
+ shift
+ for re in "$@"
+ grep -q -e 'Imported 1 GPG key' result
+ grep -o 'Imported [[:digit:]] GPG key'
++ cat httpd-address
+ env LD_PRELOAD=/<<PKGBUILDDIR>>/tests/libreaddir-rand.so ostree --repo=repo remote add --gpg-import /var/tmp/tap-test.5Ur8lk/gpghome/key3.asc R3 http://127.0.0.1:42077/ostree/gnomerepo
+ assert_file_has_content result 'Imported 1 GPG key'
+ fpath=result
+ shift
+ for re in "$@"
+ grep -q -e 'Imported 1 GPG key' result
+ env LD_PRELOAD=/<<PKGBUILDDIR>>/tests/libreaddir-rand.so ostree --repo=ostree-srv/gnomerepo checkout main workdir
+ echo shadow
+ env LD_PRELOAD=/<<PKGBUILDDIR>>/tests/libreaddir-rand.so ostree --repo=ostree-srv/gnomerepo commit -b main -s 'Add blinky' --gpg-sign 7FCA23D8472CDAFA --gpg-homedir /var/tmp/tap-test.5Ur8lk/gpghome workdir
+ env LD_PRELOAD=/<<PKGBUILDDIR>>/tests/libreaddir-rand.so ostree --repo=repo pull R2:main
+ env LD_PRELOAD=/<<PKGBUILDDIR>>/tests/libreaddir-rand.so ostree --repo=repo pull R3:main
+ env LD_PRELOAD=/<<PKGBUILDDIR>>/tests/libreaddir-rand.so ostree --repo=repo pull R1:main
+ echo speedy
+ env LD_PRELOAD=/<<PKGBUILDDIR>>/tests/libreaddir-rand.so ostree --repo=ostree-srv/gnomerepo commit -b main -s 'Add pinky' --gpg-sign D8228CFECA950D41 --gpg-homedir /var/tmp/tap-test.5Ur8lk/gpghome workdir
+ env LD_PRELOAD=/<<PKGBUILDDIR>>/tests/libreaddir-rand.so ostree --repo=repo pull R1:main
+ env LD_PRELOAD=/<<PKGBUILDDIR>>/tests/libreaddir-rand.so ostree --repo=repo pull R3:main
+ env LD_PRELOAD=/<<PKGBUILDDIR>>/tests/libreaddir-rand.so ostree --repo=repo pull R2:main
+ echo bashful
+ env LD_PRELOAD=/<<PKGBUILDDIR>>/tests/libreaddir-rand.so ostree --repo=ostree-srv/gnomerepo commit -b main -s 'Add inky' --gpg-sign 0D15FAE7DF444D67 --gpg-homedir /var/tmp/tap-test.5Ur8lk/gpghome workdir
+ env LD_PRELOAD=/<<PKGBUILDDIR>>/tests/libreaddir-rand.so ostree --repo=repo pull R1:main
+ env LD_PRELOAD=/<<PKGBUILDDIR>>/tests/libreaddir-rand.so ostree --repo=repo pull R2:main
+ env LD_PRELOAD=/<<PKGBUILDDIR>>/tests/libreaddir-rand.so ostree --repo=repo pull R3:main
+ echo ok
+ rm repo/refs/remotes/R1 repo/refs/remotes/R2 repo/refs/remotes/R3 -rf
+ env LD_PRELOAD=/<<PKGBUILDDIR>>/tests/libreaddir-rand.so ostree --repo=repo prune --refs-only
++ cat httpd-address
+ env LD_PRELOAD=/<<PKGBUILDDIR>>/tests/libreaddir-rand.so ostree --repo=repo remote add --set=gpgkeypath=/var/tmp/tap-test.5Ur8lk/gpghome/key3.asc R4 http://127.0.0.1:42077/ostree/gnomerepo
+ env LD_PRELOAD=/<<PKGBUILDDIR>>/tests/libreaddir-rand.so ostree --repo=repo pull R4:main
++ cat httpd-address
+ env LD_PRELOAD=/<<PKGBUILDDIR>>/tests/libreaddir-rand.so ostree --repo=repo remote add --set=gpgkeypath=/var/tmp/tap-test.5Ur8lk/gpghome/key1.asc,/var/tmp/tap-test.5Ur8lk/gpghome/key2.asc,/var/tmp/tap-test.5Ur8lk/gpghome/key3.asc R7 http://127.0.0.1:42077/ostree/gnomerepo
+ env LD_PRELOAD=/<<PKGBUILDDIR>>/tests/libreaddir-rand.so ostree --repo=repo pull R7:main
++ cat httpd-address
+ env LD_PRELOAD=/<<PKGBUILDDIR>>/tests/libreaddir-rand.so ostree --repo=repo remote add --set=gpgkeypath=/var/tmp/tap-test.5Ur8lk/gpghome/key1.asc,/var/tmp/tap-test.5Ur8lk/gpghome/key2.asc R8 http://127.0.0.1:42077/ostree/gnomerepo
+ env LD_PRELOAD=/<<PKGBUILDDIR>>/tests/libreaddir-rand.so ostree --repo=repo pull R8:main
+ assert_file_has_content err.txt 'public key not found'
+ fpath=err.txt
+ shift
+ for re in "$@"
+ grep -q -e 'public key not found' err.txt
++ cat httpd-address
+ env LD_PRELOAD=/<<PKGBUILDDIR>>/tests/libreaddir-rand.so ostree --repo=repo remote add --set=gpgkeypath=/var/tmp/tap-test.5Ur8lk/gpghome/ R9 http://127.0.0.1:42077/ostree/gnomerepo
+ env LD_PRELOAD=/<<PKGBUILDDIR>>/tests/libreaddir-rand.so ostree --repo=repo pull R9:main
++ cat httpd-address
+ env LD_PRELOAD=/<<PKGBUILDDIR>>/tests/libreaddir-rand.so ostree --repo=repo remote add --set=gpgkeypath=/var/tmp/tap-test.5Ur8lk/gpghome/INVALIDKEYDIRPATH/ R10 http://127.0.0.1:42077/ostree/gnomerepo
+ env LD_PRELOAD=/<<PKGBUILDDIR>>/tests/libreaddir-rand.so ostree --repo=repo pull R10:main
+ assert_file_has_content err.txt 'INVALIDKEYDIRPATH.*No such file or directory'
+ fpath=err.txt
+ shift
+ for re in "$@"
+ grep -q -e 'INVALIDKEYDIRPATH.*No such file or directory' err.txt
++ cat httpd-address
+ env LD_PRELOAD=/<<PKGBUILDDIR>>/tests/libreaddir-rand.so ostree --repo=repo remote add --set=gpgkeypath=/var/tmp/tap-test.5Ur8lk/gpghome/,/var/tmp/tap-test.5Ur8lk/gpghome/INVALIDKEYPATH.asc R11 http://127.0.0.1:42077/ostree/gnomerepo
+ env LD_PRELOAD=/<<PKGBUILDDIR>>/tests/libreaddir-rand.so ostree --repo=repo pull R11:main
+ assert_file_has_content err.txt 'INVALIDKEYPATH.*No such file or directory'
+ fpath=err.txt
+ shift
+ for re in "$@"
+ grep -q -e 'INVALIDKEYPATH.*No such file or directory' err.txt
++ cat httpd-address
+ env LD_PRELOAD=/<<PKGBUILDDIR>>/tests/libreaddir-rand.so ostree --repo=repo remote add --set=gpgkeypath=/var/tmp/tap-test.5Ur8lk/gpghome/,/var/tmp/tap-test.5Ur8lk/gpghome/key1.asc R12 http://127.0.0.1:42077/ostree/gnomerepo
+ env LD_PRELOAD=/<<PKGBUILDDIR>>/tests/libreaddir-rand.so ostree --repo=repo pull R12:main
++ cat httpd-address
+ env LD_PRELOAD=/<<PKGBUILDDIR>>/tests/libreaddir-rand.so ostree --repo=repo remote add --set=gpgkeypath=/var/tmp/tap-test.5Ur8lk/gpghome/INVALIDKEYDIRPATH/,/var/tmp/tap-test.5Ur8lk/gpghome/key3.asc R13 http://127.0.0.1:42077/ostree/gnomerepo
+ env LD_PRELOAD=/<<PKGBUILDDIR>>/tests/libreaddir-rand.so ostree --repo=repo pull R13:main
+ assert_file_has_content err.txt 'INVALIDKEYDIRPATH.*No such file or directory'
+ fpath=err.txt
+ shift
+ for re in "$@"
+ grep -q -e 'INVALIDKEYDIRPATH.*No such file or directory' err.txt
++ cat httpd-address
+ env LD_PRELOAD=/<<PKGBUILDDIR>>/tests/libreaddir-rand.so ostree --repo=repo remote add --set=gpgkeypath=/var/tmp/tap-test.5Ur8lk/gpghome/INVALIDKEYDIRPATH/,/var/tmp/tap-test.5Ur8lk/gpghome/INVALIDKEYPATH.asc R14 http://127.0.0.1:42077/ostree/gnomerepo
+ env LD_PRELOAD=/<<PKGBUILDDIR>>/tests/libreaddir-rand.so ostree --repo=repo pull R14:main
+ assert_file_has_content err.txt 'INVALIDKEYDIRPATH.*No such file or directory'
+ fpath=err.txt
+ shift
+ for re in "$@"
+ grep -q -e 'INVALIDKEYDIRPATH.*No such file or directory' err.txt
++ cat httpd-address
+ env LD_PRELOAD=/<<PKGBUILDDIR>>/tests/libreaddir-rand.so ostree --repo=repo remote add --set=gpgkeypath=/var/tmp/tap-test.5Ur8lk/gpghome R15 http://127.0.0.1:42077/ostree/gnomerepo
+ env LD_PRELOAD=/<<PKGBUILDDIR>>/tests/libreaddir-rand.so ostree --repo=repo pull R15:main
++ cat httpd-address
+ env LD_PRELOAD=/<<PKGBUILDDIR>>/tests/libreaddir-rand.so ostree --repo=repo remote add --set=gpgkeypath=,/var/tmp/tap-test.5Ur8lk/gpghome/INVALIDKEYPATH.asc R16 http://127.0.0.1:42077/ostree/gnomerepo
+ env LD_PRELOAD=/<<PKGBUILDDIR>>/tests/libreaddir-rand.so ostree --repo=repo pull R16:main
+ assert_file_has_content err.txt '().*No such file or directory'
+ fpath=err.txt
+ shift
+ for re in "$@"
+ grep -q -e '().*No such file or directory' err.txt
++ cat httpd-address
+ env LD_PRELOAD=/<<PKGBUILDDIR>>/tests/libreaddir-rand.so ostree --repo=repo remote add --set=gpgkeypath=/var/tmp/tap-test.5Ur8lk/gpghome/key3.asc, R17 http://127.0.0.1:42077/ostree/gnomerepo
+ env LD_PRELOAD=/<<PKGBUILDDIR>>/tests/libreaddir-rand.so ostree --repo=repo pull R17:main
++ cat httpd-address
+ env LD_PRELOAD=/<<PKGBUILDDIR>>/tests/libreaddir-rand.so ostree --repo=repo remote add '--set=gpgkeypath=/var/tmp/tap-test.5Ur8lk/gpghome/key1.asc;/var/tmp/tap-test.5Ur8lk/gpghome/key2.asc;/var/tmp/tap-test.5Ur8lk/gpghome/key3.asc' R18 http://127.0.0.1:42077/ostree/gnomerepo
+ env LD_PRELOAD=/<<PKGBUILDDIR>>/tests/libreaddir-rand.so ostree --repo=repo pull R18:main
++ cat httpd-address
+ env LD_PRELOAD=/<<PKGBUILDDIR>>/tests/libreaddir-rand.so ostree --repo=repo remote add '--set=gpgkeypath=/var/tmp/tap-test.5Ur8lk/gpghome/key1.asc,/var/tmp/tap-test.5Ur8lk/gpghome/key2.asc;/var/tmp/tap-test.5Ur8lk/gpghome/key3.asc' R19 http://127.0.0.1:42077/ostree/gnomerepo
+ env LD_PRELOAD=/<<PKGBUILDDIR>>/tests/libreaddir-rand.so ostree --repo=repo pull R19:main
+ assert_file_has_content err.txt '.*key value list contains more than one separator'
+ fpath=err.txt
+ shift
+ for re in "$@"
+ grep -q -e '.*key value list contains more than one separator' err.txt
+ rm repo/refs/remotes/R12 repo/refs/remotes/R15 repo/refs/remotes/R17 repo/refs/remotes/R18 repo/refs/remotes/R4 repo/refs/remotes/R7 repo/refs/remotes/R9 -rf
+ env LD_PRELOAD=/<<PKGBUILDDIR>>/tests/libreaddir-rand.so ostree --repo=repo prune --refs-only
++ cat httpd-address
+ env LD_PRELOAD=/<<PKGBUILDDIR>>/tests/libreaddir-rand.so ostree --repo=repo remote add --set=gpgkeypath=/var/tmp/tap-test.5Ur8lk/gpghome/INVALIDKEYPATH.asc R5 http://127.0.0.1:42077/ostree/gnomerepo
+ env LD_PRELOAD=/<<PKGBUILDDIR>>/tests/libreaddir-rand.so ostree --repo=repo pull R5:main
+ assert_file_has_content err.txt 'INVALIDKEYPATH.*No such file or directory'
+ fpath=err.txt
+ shift
+ for re in "$@"
+ grep -q -e 'INVALIDKEYPATH.*No such file or directory' err.txt
+ rm 'repo/refs/remotes/*' -rf
+ env LD_PRELOAD=/<<PKGBUILDDIR>>/tests/libreaddir-rand.so ostree --repo=repo prune --refs-only
++ cat httpd-address
+ env LD_PRELOAD=/<<PKGBUILDDIR>>/tests/libreaddir-rand.so ostree --repo=repo remote add --set=gpgkeypath=/var/tmp/tap-test.5Ur8lk/gpghome/key2.asc R6 http://127.0.0.1:42077/ostree/gnomerepo
+ env LD_PRELOAD=/<<PKGBUILDDIR>>/tests/libreaddir-rand.so ostree --repo=repo pull R6:main
+ assert_file_has_content err.txt 'public key not found'
+ fpath=err.txt
+ shift
+ for re in "$@"
+ grep -q -e 'public key not found' err.txt
+ echo ok
+ cd /var/tmp/tap-test.5Ur8lk
+ rm 'repo/refs/remotes/*' -rf
+ env LD_PRELOAD=/<<PKGBUILDDIR>>/tests/libreaddir-rand.so ostree --repo=repo prune --refs-only
++ date
+ echo Sun Apr 18 14:41:02 UTC 2021
+ env LD_PRELOAD=/<<PKGBUILDDIR>>/tests/libreaddir-rand.so ostree --repo=/var/tmp/tap-test.5Ur8lk/ostree-srv/gnomerepo commit -b main --gpg-sign 7FCA23D8472CDAFA --gpg-homedir /var/tmp/tap-test.5Ur8lk/gpghome workdir
++ env LD_PRELOAD=/<<PKGBUILDDIR>>/tests/libreaddir-rand.so ostree --repo=/var/tmp/tap-test.5Ur8lk/ostree-srv/gnomerepo rev-parse main
+ prevrev=7062a9c6db2ce3b69dc41cd14e3b5b72895843927ffdde8e34a2dd80f7753b9f
+ env LD_PRELOAD=/<<PKGBUILDDIR>>/tests/libreaddir-rand.so ostree --repo=repo pull R1:main
++ env LD_PRELOAD=/<<PKGBUILDDIR>>/tests/libreaddir-rand.so ostree --repo=repo rev-parse R1:main
+ assert_streq 7062a9c6db2ce3b69dc41cd14e3b5b72895843927ffdde8e34a2dd80f7753b9f 7062a9c6db2ce3b69dc41cd14e3b5b72895843927ffdde8e34a2dd80f7753b9f
+ test 7062a9c6db2ce3b69dc41cd14e3b5b72895843927ffdde8e34a2dd80f7753b9f = 7062a9c6db2ce3b69dc41cd14e3b5b72895843927ffdde8e34a2dd80f7753b9f
++ date
+ echo Sun Apr 18 14:41:02 UTC 2021
+ env LD_PRELOAD=/<<PKGBUILDDIR>>/tests/libreaddir-rand.so ostree --repo=/var/tmp/tap-test.5Ur8lk/ostree-srv/gnomerepo commit -b main --gpg-sign D8228CFECA950D41 --gpg-homedir /var/tmp/tap-test.5Ur8lk/gpghome workdir
+ env LD_PRELOAD=/<<PKGBUILDDIR>>/tests/libreaddir-rand.so ostree --repo=/var/tmp/tap-test.5Ur8lk/ostree-srv/gnomerepo static-delta generate main
modified: 0
new reachable: metadata=2 content regular=0 symlink=0
rollsum for 0/0 modified
part 1 n:1 compressed:389 uncompressed:355
uncompressed=355 compressed=389 loose=355
rollsum=0 objects, 0 bytes
bsdiff=0 objects
+ env LD_PRELOAD=/<<PKGBUILDDIR>>/tests/libreaddir-rand.so ostree --repo=/var/tmp/tap-test.5Ur8lk/ostree-srv/gnomerepo summary -u --gpg-sign 7FCA23D8472CDAFA --gpg-homedir /var/tmp/tap-test.5Ur8lk/gpghome
++ env LD_PRELOAD=/<<PKGBUILDDIR>>/tests/libreaddir-rand.so ostree --repo=/var/tmp/tap-test.5Ur8lk/ostree-srv/gnomerepo rev-parse main
+ newrev=f10c4613d2e9a8f414aab93cf4555d59ac87702efd6c831984f26c73193cd9d9
+ env LD_PRELOAD=/<<PKGBUILDDIR>>/tests/libreaddir-rand.so ostree --repo=repo pull --require-static-deltas R1:main
+ assert_file_has_content err.txt 'public key not found'
+ fpath=err.txt
+ shift
+ for re in "$@"
+ grep -q -e 'public key not found' err.txt
+ echo 'ok gpg untrusted signed commit for delta upgrades'
+ env LD_PRELOAD=/<<PKGBUILDDIR>>/tests/libreaddir-rand.so ostree --repo=/var/tmp/tap-test.5Ur8lk/ostree-srv/gnomerepo reset main 'main^'
+ env LD_PRELOAD=/<<PKGBUILDDIR>>/tests/libreaddir-rand.so ostree --repo=/var/tmp/tap-test.5Ur8lk/ostree-srv/gnomerepo commit -b main --gpg-sign 7FCA23D8472CDAFA --gpg-homedir /var/tmp/tap-test.5Ur8lk/gpghome workdir
+ env LD_PRELOAD=/<<PKGBUILDDIR>>/tests/libreaddir-rand.so ostree --repo=/var/tmp/tap-test.5Ur8lk/ostree-srv/gnomerepo static-delta generate main
modified: 0
new reachable: metadata=2 content regular=0 symlink=0
rollsum for 0/0 modified
part 1 n:1 compressed:389 uncompressed:355
uncompressed=355 compressed=389 loose=355
rollsum=0 objects, 0 bytes
bsdiff=0 objects
+ env LD_PRELOAD=/<<PKGBUILDDIR>>/tests/libreaddir-rand.so ostree --repo=/var/tmp/tap-test.5Ur8lk/ostree-srv/gnomerepo summary -u --gpg-sign 7FCA23D8472CDAFA --gpg-homedir /var/tmp/tap-test.5Ur8lk/gpghome
+ env LD_PRELOAD=/<<PKGBUILDDIR>>/tests/libreaddir-rand.so ostree --repo=repo pull --require-static-deltas R1:main
error: Commit f10c4613d2e9a8f414aab93cf4555d59ac87702efd6c831984f26c73193cd9d9: Signature made Sun Apr 18 14:41:02 2021 using RSA key ID D8228CFECA950D41
Can't check signature: public key not found
++ report_err
++ local exit_status=1
Unexpected nonzero exit status 1 while running: ${OSTREE} pull --require-static-deltas R1:main
+ run_exit_cmds
+ for expr in "${libtest_exit_cmds[@]}"
+ eval save_core
++ save_core
++ '[' -e core ']'
+ for expr in "${libtest_exit_cmds[@]}"
+ eval libtest_cleanup_gpg
++ libtest_cleanup_gpg
++ local gpg_homedir=/var/tmp/tap-test.5Ur8lk/gpghome
++ gpg-connect-agent --homedir /var/tmp/tap-test.5Ur8lk/gpghome killagent /bye
Copying gpghome to /var/tmp/tap-test.5Ur8lk
checking for xattrs.../usr/bin/setfattr
/var/tmp/tap-test.5Ur8lk /var/tmp/tap-test.5Ur8lk
Unable to retrieve SELinux label, assuming disabled
/var/tmp/tap-test.5Ur8lk
done
824550e7a45c4ce1a34a2f1354fd59170aa7d1f29135b35772e4dfcdb96c4136
c86cef8462b872060361066407f314cba48918ef5e55f84b16ec041db79c2efc
623cc7e05a55c900fa9c560e9fa2213ac39f8766634871d029bd58aaa2587c43
1..6
d13037a4d6493af57f2c6ade7764d4cf54f01962a19e34bdb3e3b4ac5b30722e
c788cc32fb4f252f02aee5506938abc1f475991cc0c3c476cb35c6df26e27f3a
746a1a6d888d95ca64f9e4be6ec9c4fe40cdfb3bbf78ac529d21890eb764dc1c
ok
PASS: tests/test-remote-gpg-import.sh 1
Total objects: 18
Deleted 18 objects, 1.4 kB freed
Total objects: 14
Deleted 14 objects, 757 bytes freed
Total objects: 0
No unreachable objects
ok
PASS: tests/test-remote-gpg-import.sh 2
Total objects: 0
No unreachable objects
7062a9c6db2ce3b69dc41cd14e3b5b72895843927ffdde8e34a2dd80f7753b9f
8 metadata, 9 content objects fetched; 1 KiB transferred in 0 seconds; 72 bytes content written
f10c4613d2e9a8f414aab93cf4555d59ac87702efd6c831984f26c73193cd9d9
Generating static delta:
  From: 7062a9c6db2ce3b69dc41cd14e3b5b72895843927ffdde8e34a2dd80f7753b9f
  To:   f10c4613d2e9a8f414aab93cf4555d59ac87702efd6c831984f26c73193cd9d9
ok gpg untrusted signed commit for delta upgrades
PASS: tests/test-remote-gpg-import.sh 3 gpg untrusted signed commit for delta upgrades
95ea4256e5270d54424c23d09ef7e6c63bcf6e28a8642565fc95b3e15e005973
Generating static delta:
  From: 7062a9c6db2ce3b69dc41cd14e3b5b72895843927ffdde8e34a2dd80f7753b9f
  To:   95ea4256e5270d54424c23d09ef7e6c63bcf6e28a8642565fc95b3e15e005973
OK closing connection
ERROR: tests/test-remote-gpg-import.sh - too few tests run (expected 6, got 3)
ERROR: tests/test-remote-gpg-import.sh - exited with status 1

Full log: https://buildd.debian.org/status/fetch.php?pkg=ostree&arch=armhf&ver=2021.2-1&stamp=1618756886&raw=0

ppc64el seems to have failed in the same way: https://buildd.debian.org/status/fetch.php?pkg=ostree&arch=ppc64el&ver=2021.2-1&stamp=1618756791&raw=0

amd64 had the same failure in 2021.1 but succeeded in 2021.2, so I think this is probably an intermittent bug (race condition?): https://buildd.debian.org/status/fetch.php?pkg=ostree&arch=amd64&ver=2021.1-1&stamp=1618432469&raw=0

The text was updated successfully, but these errors were encountered:

dbnicholson · 2021-04-19T15:31:13Z

I think this is also a case of the wrong summary being used like in #2245 when the builder is too fast and the previous and current summaries have the same HTTP Last-Modified header. The delta index is read from the summary file, so I think it's still looking at the previous summary and then trying to fetch the commit that was signed with the other key.

I bet the following fixes it:

diff --git a/tests/test-remote-gpg-import.sh b/tests/test-remote-gpg-import.sh
index cf13b499..6f62ad91 100755
--- a/tests/test-remote-gpg-import.sh
+++ b/tests/test-remote-gpg-import.sh
@@ -282,6 +282,7 @@ ${CMD_PREFIX} ostree  --repo=${test_tmpdir}/ostree-srv/gnomerepo reset main{,^}
 ${CMD_PREFIX} ostree  --repo=${test_tmpdir}/ostree-srv/gnomerepo commit -b main --gpg-sign ${TEST_GPG_KEYID_1} --gpg-homedir ${test_tmpdir}/gpghome workdir
 ${CMD_PREFIX} ostree --repo=${test_tmpdir}/ostree-srv/gnomerepo static-delta generate main
 ${CMD_PREFIX} ostree --repo=${test_tmpdir}/ostree-srv/gnomerepo summary -u --gpg-sign ${TEST_GPG_KEYID_1} --gpg-homedir ${test_tmpdir}/gpghome
+rm -rf repo/tmp/cache/summaries
 ${OSTREE} pull --require-static-deltas R1:main
 
 echo "ok gpg trusted signed commit for delta upgrades"

Given there's been a few of these issues, I think we should either add a libtest helper function to wipe cached summaries or add an environment variable in the pull code that skips using the cached summaries.

dbnicholson · 2021-04-19T15:53:07Z

Oh, I realized another source of these problems (and why I never see them locally). The pull code will send an If-None-Match header with the ETag of the cached summary, but it stores the ETag in an xattr. So, if your test is run on a file system that doesn't support xattrs, then you won't get the ETag matching that would eliminate this type of issue. @smcv any idea if the debian autobuilders use filesystems that support xattrs?

smcv · 2021-04-19T16:14:37Z

any idea if the debian autobuilders use filesystems that support xattrs?

It's officially undefined. Autobuilders with a lot of RAM probably use tmpfs for speed, autobuilders with less RAM probably use ext4 (or maybe some other "sufficiently Unix" filesystem like btrfs or xfs).

If the log says

SKIP: tests/test-basic-c 4 /xattrs-devino-cache # SKIP this test requires full xattr support

then I assume that means they're running on something without xattrs?

dbnicholson · 2021-04-19T16:31:57Z

Yeah, probably. The "requires full xattr support" message means that either it can't set security.selinux or user.test extended attributes on a file in the current directory. In particular the ETag is stored in a user xattr (user.etag), and tmpfs doesn't support that because they could be abused to allocate arbitrary amounts of RAM since xattrs aren't swappable.

So, yeah, I'm guessing that some of the builders use a tmpfs on /var/tmp.

I'm inclined to think that the best course is to have an environment variable for the pull code that skips caching summaries. By default that's disabled for normal operation, but the test suite would enable it and then the few tests where the caching behavior itself is being tested would disable it again and arrange to make sure that the last modified time is always different for the case when the etag xattr can't be used.

Several tests generate summaries and then expect to use the generated summary immediately. However, this can cause intermittent test failures when they inadvertantly get a cached summary file. This typically happens when the test is run on a filesystem that doesn't support user extended attributes. In that case, the caching code can only use the last modified time, which only has 1 second granularity. If tests don't carefully manage the summary modification times or the repo cache then they are likely subject to races in some test environments. This introduces an environment variable `OSTREE_SKIP_CACHE` that prevents the repo from using a cache directory. This is enabled by default in tests and disabled for tests that are a explicitly trying to test the caching behavior. Fixes: ostreedev#2313 Fixes: ostreedev#2351

smcv · 2021-04-19T17:23:08Z

I think this is probably an intermittent bug (race condition?)

I retried the failed builds and they succeeded, which is consistent with this being a caching bug that doesn't always trigger.

dbnicholson mentioned this issue Apr 19, 2021

tests: Test without a cache directory by default #2352

Merged

cgwalters closed this as completed in #2352 Apr 20, 2021

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

test-remote-gpg-import.sh intermittently failing: Can't check signature: public key not found #2351

test-remote-gpg-import.sh intermittently failing: Can't check signature: public key not found #2351

smcv commented Apr 18, 2021

dbnicholson commented Apr 19, 2021

dbnicholson commented Apr 19, 2021

smcv commented Apr 19, 2021

dbnicholson commented Apr 19, 2021

smcv commented Apr 19, 2021

test-remote-gpg-import.sh intermittently failing: Can't check signature: public key not found #2351

test-remote-gpg-import.sh intermittently failing: Can't check signature: public key not found #2351

Comments

smcv commented Apr 18, 2021

dbnicholson commented Apr 19, 2021

dbnicholson commented Apr 19, 2021

smcv commented Apr 19, 2021

dbnicholson commented Apr 19, 2021

smcv commented Apr 19, 2021