Diff of the two buildlogs: -- --- b1/build.log 2020-07-20 05:27:43.736186148 +0000 +++ b2/build.log 2020-07-20 05:29:09.548900477 +0000 @@ -1,6 +1,6 @@ I: pbuilder: network access will be disabled during build -I: Current time: Sun Jul 19 17:26:14 -12 2020 -I: pbuilder-time-stamp: 1595222774 +I: Current time: Mon Jul 20 19:27:53 +14 2020 +I: pbuilder-time-stamp: 1595222873 I: Building the build Environment I: extracting base tarball [/var/cache/pbuilder/buster-reproducible-base.tgz] I: copying local configuration @@ -17,7 +17,7 @@ I: Extracting source gpgv: unknown type of key resource 'trustedkeys.kbx' gpgv: keyblock resource '/var/lib/jenkins/.gnupg/trustedkeys.kbx': General error -gpgv: Signature made Sat Oct 27 00:51:24 2018 -12 +gpgv: Signature made Sun Oct 28 02:51:24 2018 +14 gpgv: using RSA key 498A93056B052604FACBC8A329BFA0D079290ACA gpgv: Can't check signature: No public key dpkg-source: warning: failed to verify signature on ./golang-github-canonicalltd-raft-membership_0.0~git20180413.3846634-1.dsc @@ -26,136 +26,170 @@ dpkg-source: info: unpacking golang-github-canonicalltd-raft-membership_0.0~git20180413.3846634-1.debian.tar.xz I: using fakeroot in build. I: Installing the build-deps -I: user script /srv/workspace/pbuilder/32143/tmp/hooks/D02_print_environment starting +I: user script /srv/workspace/pbuilder/12186/tmp/hooks/D01_modify_environment starting +debug: Running on codethink-sled15-arm64. +I: Changing host+domainname to test build reproducibility +I: Adding a custom variable just for the fun of it... +I: Changing /bin/sh to bash +Removing 'diversion of /bin/sh to /bin/sh.distrib by dash' +Adding 'diversion of /bin/sh to /bin/sh.distrib by bash' +Removing 'diversion of /usr/share/man/man1/sh.1.gz to /usr/share/man/man1/sh.distrib.1.gz by dash' +Adding 'diversion of /usr/share/man/man1/sh.1.gz to /usr/share/man/man1/sh.distrib.1.gz by bash' +I: Setting pbuilder2's login shell to /bin/bash +I: Setting pbuilder2's GECOS to second user,second room,second work-phone,second home-phone,second other +I: user script /srv/workspace/pbuilder/12186/tmp/hooks/D01_modify_environment finished +I: user script /srv/workspace/pbuilder/12186/tmp/hooks/D02_print_environment starting I: set - BUILDDIR='/build' - BUILDUSERGECOS='first user,first room,first work-phone,first home-phone,first other' - BUILDUSERNAME='pbuilder1' - BUILD_ARCH='arm64' - DEBIAN_FRONTEND='noninteractive' + BASH=/bin/sh + BASHOPTS=checkwinsize:cmdhist:complete_fullquote:extquote:force_fignore:globasciiranges:hostcomplete:interactive_comments:progcomp:promptvars:sourcepath + BASH_ALIASES=() + BASH_ARGC=() + BASH_ARGV=() + BASH_CMDS=() + BASH_LINENO=([0]="12" [1]="0") + BASH_SOURCE=([0]="/tmp/hooks/D02_print_environment" [1]="/tmp/hooks/D02_print_environment") + BASH_VERSINFO=([0]="5" [1]="0" [2]="3" [3]="1" [4]="release" [5]="aarch64-unknown-linux-gnu") + BASH_VERSION='5.0.3(1)-release' + BUILDDIR=/build + BUILDUSERGECOS='second user,second room,second work-phone,second home-phone,second other' + BUILDUSERNAME=pbuilder2 + BUILD_ARCH=arm64 + DEBIAN_FRONTEND=noninteractive DEB_BUILD_OPTIONS='buildinfo=+all reproducible=+all parallel=8' - DISTRIBUTION='' - HOME='/var/lib/jenkins' - HOST_ARCH='arm64' + DIRSTACK=() + DISTRIBUTION= + EUID=0 + FUNCNAME=([0]="Echo" [1]="main") + GROUPS=() + HOME=/var/lib/jenkins + HOSTNAME=i-capture-the-hostname + HOSTTYPE=aarch64 + HOST_ARCH=arm64 IFS=' ' - LANG='C' - LANGUAGE='en_US:en' - LC_ALL='C' - MAIL='/var/mail/root' - OPTIND='1' - PATH='/usr/sbin:/usr/bin:/sbin:/bin:/usr/games' - PBCURRENTCOMMANDLINEOPERATION='build' - PBUILDER_OPERATION='build' - PBUILDER_PKGDATADIR='/usr/share/pbuilder' - PBUILDER_PKGLIBDIR='/usr/lib/pbuilder' - PBUILDER_SYSCONFDIR='/etc' - PPID='32143' - PS1='# ' - PS2='> ' + LANG=C + LANGUAGE=nl_BE:nl + LC_ALL=C + MACHTYPE=aarch64-unknown-linux-gnu + MAIL=/var/mail/root + OPTERR=1 + OPTIND=1 + OSTYPE=linux-gnu + PATH=/usr/sbin:/usr/bin:/sbin:/bin:/usr/games:/i/capture/the/path + PBCURRENTCOMMANDLINEOPERATION=build + PBUILDER_OPERATION=build + PBUILDER_PKGDATADIR=/usr/share/pbuilder + PBUILDER_PKGLIBDIR=/usr/lib/pbuilder + PBUILDER_SYSCONFDIR=/etc + PIPESTATUS=([0]="0") + POSIXLY_CORRECT=y + PPID=12186 PS4='+ ' - PWD='/' - SHELL='/bin/bash' - SHLVL='2' - SUDO_COMMAND='/usr/bin/timeout -k 18.1h 18h /usr/bin/ionice -c 3 /usr/bin/nice /usr/sbin/pbuilder --build --configfile /srv/reproducible-results/rbuild-debian/tmp.zCLKNACUmg/pbuilderrc_haZ6 --hookdir /etc/pbuilder/first-build-hooks --debbuildopts -b --basetgz /var/cache/pbuilder/buster-reproducible-base.tgz --buildresult /srv/reproducible-results/rbuild-debian/tmp.zCLKNACUmg/b1 --logfile b1/build.log golang-github-canonicalltd-raft-membership_0.0~git20180413.3846634-1.dsc' - SUDO_GID='117' - SUDO_UID='110' - SUDO_USER='jenkins' - TERM='unknown' - TZ='/usr/share/zoneinfo/Etc/GMT+12' - USER='root' - USERNAME='root' - _='/usr/bin/systemd-run' - http_proxy='http://192.168.101.16:3128' + PWD=/ + SHELL=/bin/bash + SHELLOPTS=braceexpand:errexit:hashall:interactive-comments:posix + SHLVL=3 + SUDO_COMMAND='/usr/bin/timeout -k 24.1h 24h /usr/bin/ionice -c 3 /usr/bin/nice -n 11 /usr/bin/unshare --uts -- /usr/sbin/pbuilder --build --configfile /srv/reproducible-results/rbuild-debian/tmp.zCLKNACUmg/pbuilderrc_U9kG --hookdir /etc/pbuilder/rebuild-hooks --debbuildopts -b --basetgz /var/cache/pbuilder/buster-reproducible-base.tgz --buildresult /srv/reproducible-results/rbuild-debian/tmp.zCLKNACUmg/b2 --logfile b2/build.log golang-github-canonicalltd-raft-membership_0.0~git20180413.3846634-1.dsc' + SUDO_GID=117 + SUDO_UID=110 + SUDO_USER=jenkins + TERM=unknown + TZ=/usr/share/zoneinfo/Etc/GMT-14 + UID=0 + USER=root + USERNAME=root + _='I: set' + http_proxy=http://192.168.101.16:3128 I: uname -a - Linux codethink-sled16-arm64 4.4.0-185-generic #215-Ubuntu SMP Mon Jun 8 21:55:24 UTC 2020 aarch64 GNU/Linux + Linux i-capture-the-hostname 4.4.0-185-generic #215-Ubuntu SMP Mon Jun 8 21:55:24 UTC 2020 aarch64 GNU/Linux I: ls -l /bin total 4928 - -rwxr-xr-x 1 root root 1216928 Apr 17 2019 bash - -rwxr-xr-x 3 root root 34808 Jul 10 2019 bunzip2 - -rwxr-xr-x 3 root root 34808 Jul 10 2019 bzcat - lrwxrwxrwx 1 root root 6 Jul 10 2019 bzcmp -> bzdiff - -rwxr-xr-x 1 root root 2227 Jul 10 2019 bzdiff - lrwxrwxrwx 1 root root 6 Jul 10 2019 bzegrep -> bzgrep - -rwxr-xr-x 1 root root 4877 Jun 24 2019 bzexe - lrwxrwxrwx 1 root root 6 Jul 10 2019 bzfgrep -> bzgrep - -rwxr-xr-x 1 root root 3641 Jul 10 2019 bzgrep - -rwxr-xr-x 3 root root 34808 Jul 10 2019 bzip2 - -rwxr-xr-x 1 root root 14264 Jul 10 2019 bzip2recover - lrwxrwxrwx 1 root root 6 Jul 10 2019 bzless -> bzmore - -rwxr-xr-x 1 root root 1297 Jul 10 2019 bzmore - -rwxr-xr-x 1 root root 35576 Feb 28 2019 cat - -rwxr-xr-x 1 root root 60256 Feb 28 2019 chgrp - -rwxr-xr-x 1 root root 56096 Feb 28 2019 chmod - -rwxr-xr-x 1 root root 64368 Feb 28 2019 chown - -rwxr-xr-x 1 root root 134632 Feb 28 2019 cp - -rwxr-xr-x 1 root root 129536 Jan 17 2019 dash - -rwxr-xr-x 1 root root 97136 Feb 28 2019 date - -rwxr-xr-x 1 root root 76736 Feb 28 2019 dd - -rwxr-xr-x 1 root root 93752 Feb 28 2019 df - -rwxr-xr-x 1 root root 138848 Feb 28 2019 dir - -rwxr-xr-x 1 root root 75984 Jan 9 2019 dmesg - lrwxrwxrwx 1 root root 8 Sep 26 2018 dnsdomainname -> hostname - lrwxrwxrwx 1 root root 8 Sep 26 2018 domainname -> hostname - -rwxr-xr-x 1 root root 31368 Feb 28 2019 echo - -rwxr-xr-x 1 root root 28 Jan 7 2019 egrep - -rwxr-xr-x 1 root root 27256 Feb 28 2019 false - -rwxr-xr-x 1 root root 28 Jan 7 2019 fgrep - -rwxr-xr-x 1 root root 68792 Jan 9 2019 findmnt - -rwsr-xr-x 1 root root 34824 Apr 22 07:38 fusermount - -rwxr-xr-x 1 root root 174304 Jan 7 2019 grep - -rwxr-xr-x 2 root root 2345 Jan 5 2019 gunzip - -rwxr-xr-x 1 root root 6375 Jan 5 2019 gzexe - -rwxr-xr-x 1 root root 89656 Jan 5 2019 gzip - -rwxr-xr-x 1 root root 18440 Sep 26 2018 hostname - -rwxr-xr-x 1 root root 64472 Feb 28 2019 ln - -rwxr-xr-x 1 root root 52544 Jul 26 2018 login - -rwxr-xr-x 1 root root 138848 Feb 28 2019 ls - -rwxr-xr-x 1 root root 108552 Jan 9 2019 lsblk - -rwxr-xr-x 1 root root 76840 Feb 28 2019 mkdir - -rwxr-xr-x 1 root root 64480 Feb 28 2019 mknod - -rwxr-xr-x 1 root root 39736 Feb 28 2019 mktemp - -rwxr-xr-x 1 root root 38840 Jan 9 2019 more - -rwsr-xr-x 1 root root 47112 Jan 9 2019 mount - -rwxr-xr-x 1 root root 14344 Jan 9 2019 mountpoint - -rwxr-xr-x 1 root root 138736 Feb 28 2019 mv - lrwxrwxrwx 1 root root 8 Sep 26 2018 nisdomainname -> hostname - lrwxrwxrwx 1 root root 14 Feb 14 2019 pidof -> /sbin/killall5 - -rwxr-xr-x 1 root root 35560 Feb 28 2019 pwd - lrwxrwxrwx 1 root root 4 Apr 17 2019 rbash -> bash - -rwxr-xr-x 1 root root 43712 Feb 28 2019 readlink - -rwxr-xr-x 1 root root 68440 Feb 28 2019 rm - -rwxr-xr-x 1 root root 39624 Feb 28 2019 rmdir - -rwxr-xr-x 1 root root 19144 Jan 21 2019 run-parts - -rwxr-xr-x 1 root root 114016 Dec 22 2018 sed - lrwxrwxrwx 1 root root 4 Jul 17 20:25 sh -> dash - -rwxr-xr-x 1 root root 31384 Feb 28 2019 sleep - -rwxr-xr-x 1 root root 72480 Feb 28 2019 stty - -rwsr-xr-x 1 root root 59424 Jan 9 2019 su - -rwxr-xr-x 1 root root 31416 Feb 28 2019 sync - -rwxr-xr-x 1 root root 449416 Apr 23 2019 tar - -rwxr-xr-x 1 root root 10560 Jan 21 2019 tempfile - -rwxr-xr-x 1 root root 88968 Feb 28 2019 touch - -rwxr-xr-x 1 root root 27256 Feb 28 2019 true - -rwxr-xr-x 1 root root 14264 Apr 22 07:38 ulockmgr_server - -rwsr-xr-x 1 root root 30728 Jan 9 2019 umount - -rwxr-xr-x 1 root root 31384 Feb 28 2019 uname - -rwxr-xr-x 2 root root 2345 Jan 5 2019 uncompress - -rwxr-xr-x 1 root root 138848 Feb 28 2019 vdir - -rwxr-xr-x 1 root root 34824 Jan 9 2019 wdctl - -rwxr-xr-x 1 root root 946 Jan 21 2019 which - lrwxrwxrwx 1 root root 8 Sep 26 2018 ypdomainname -> hostname - -rwxr-xr-x 1 root root 1983 Jan 5 2019 zcat - -rwxr-xr-x 1 root root 1677 Jan 5 2019 zcmp - -rwxr-xr-x 1 root root 5879 Jan 5 2019 zdiff - -rwxr-xr-x 1 root root 29 Jan 5 2019 zegrep - -rwxr-xr-x 1 root root 29 Jan 5 2019 zfgrep - -rwxr-xr-x 1 root root 2080 Jan 5 2019 zforce - -rwxr-xr-x 1 root root 7584 Jan 5 2019 zgrep - -rwxr-xr-x 1 root root 2205 Jan 5 2019 zless - -rwxr-xr-x 1 root root 1841 Jan 5 2019 zmore - -rwxr-xr-x 1 root root 4552 Jan 5 2019 znew -I: user script /srv/workspace/pbuilder/32143/tmp/hooks/D02_print_environment finished + -rwxr-xr-x 1 root root 1216928 Apr 18 2019 bash + -rwxr-xr-x 3 root root 34808 Jul 11 2019 bunzip2 + -rwxr-xr-x 3 root root 34808 Jul 11 2019 bzcat + lrwxrwxrwx 1 root root 6 Jul 11 2019 bzcmp -> bzdiff + -rwxr-xr-x 1 root root 2227 Jul 11 2019 bzdiff + lrwxrwxrwx 1 root root 6 Jul 11 2019 bzegrep -> bzgrep + -rwxr-xr-x 1 root root 4877 Jun 25 2019 bzexe + lrwxrwxrwx 1 root root 6 Jul 11 2019 bzfgrep -> bzgrep + -rwxr-xr-x 1 root root 3641 Jul 11 2019 bzgrep + -rwxr-xr-x 3 root root 34808 Jul 11 2019 bzip2 + -rwxr-xr-x 1 root root 14264 Jul 11 2019 bzip2recover + lrwxrwxrwx 1 root root 6 Jul 11 2019 bzless -> bzmore + -rwxr-xr-x 1 root root 1297 Jul 11 2019 bzmore + -rwxr-xr-x 1 root root 35576 Mar 1 2019 cat + -rwxr-xr-x 1 root root 60256 Mar 1 2019 chgrp + -rwxr-xr-x 1 root root 56096 Mar 1 2019 chmod + -rwxr-xr-x 1 root root 64368 Mar 1 2019 chown + -rwxr-xr-x 1 root root 134632 Mar 1 2019 cp + -rwxr-xr-x 1 root root 129536 Jan 18 2019 dash + -rwxr-xr-x 1 root root 97136 Mar 1 2019 date + -rwxr-xr-x 1 root root 76736 Mar 1 2019 dd + -rwxr-xr-x 1 root root 93752 Mar 1 2019 df + -rwxr-xr-x 1 root root 138848 Mar 1 2019 dir + -rwxr-xr-x 1 root root 75984 Jan 10 2019 dmesg + lrwxrwxrwx 1 root root 8 Sep 27 2018 dnsdomainname -> hostname + lrwxrwxrwx 1 root root 8 Sep 27 2018 domainname -> hostname + -rwxr-xr-x 1 root root 31368 Mar 1 2019 echo + -rwxr-xr-x 1 root root 28 Jan 8 2019 egrep + -rwxr-xr-x 1 root root 27256 Mar 1 2019 false + -rwxr-xr-x 1 root root 28 Jan 8 2019 fgrep + -rwxr-xr-x 1 root root 68792 Jan 10 2019 findmnt + -rwsr-xr-x 1 root root 34824 Apr 23 09:38 fusermount + -rwxr-xr-x 1 root root 174304 Jan 8 2019 grep + -rwxr-xr-x 2 root root 2345 Jan 6 2019 gunzip + -rwxr-xr-x 1 root root 6375 Jan 6 2019 gzexe + -rwxr-xr-x 1 root root 89656 Jan 6 2019 gzip + -rwxr-xr-x 1 root root 18440 Sep 27 2018 hostname + -rwxr-xr-x 1 root root 64472 Mar 1 2019 ln + -rwxr-xr-x 1 root root 52544 Jul 27 2018 login + -rwxr-xr-x 1 root root 138848 Mar 1 2019 ls + -rwxr-xr-x 1 root root 108552 Jan 10 2019 lsblk + -rwxr-xr-x 1 root root 76840 Mar 1 2019 mkdir + -rwxr-xr-x 1 root root 64480 Mar 1 2019 mknod + -rwxr-xr-x 1 root root 39736 Mar 1 2019 mktemp + -rwxr-xr-x 1 root root 38840 Jan 10 2019 more + -rwsr-xr-x 1 root root 47112 Jan 10 2019 mount + -rwxr-xr-x 1 root root 14344 Jan 10 2019 mountpoint + -rwxr-xr-x 1 root root 138736 Mar 1 2019 mv + lrwxrwxrwx 1 root root 8 Sep 27 2018 nisdomainname -> hostname + lrwxrwxrwx 1 root root 14 Feb 15 2019 pidof -> /sbin/killall5 + -rwxr-xr-x 1 root root 35560 Mar 1 2019 pwd + lrwxrwxrwx 1 root root 4 Apr 18 2019 rbash -> bash + -rwxr-xr-x 1 root root 43712 Mar 1 2019 readlink + -rwxr-xr-x 1 root root 68440 Mar 1 2019 rm + -rwxr-xr-x 1 root root 39624 Mar 1 2019 rmdir + -rwxr-xr-x 1 root root 19144 Jan 22 2019 run-parts + -rwxr-xr-x 1 root root 114016 Dec 23 2018 sed + lrwxrwxrwx 1 root root 4 Jul 20 19:28 sh -> bash + lrwxrwxrwx 1 root root 4 Jul 19 22:26 sh.distrib -> dash + -rwxr-xr-x 1 root root 31384 Mar 1 2019 sleep + -rwxr-xr-x 1 root root 72480 Mar 1 2019 stty + -rwsr-xr-x 1 root root 59424 Jan 10 2019 su + -rwxr-xr-x 1 root root 31416 Mar 1 2019 sync + -rwxr-xr-x 1 root root 449416 Apr 24 2019 tar + -rwxr-xr-x 1 root root 10560 Jan 22 2019 tempfile + -rwxr-xr-x 1 root root 88968 Mar 1 2019 touch + -rwxr-xr-x 1 root root 27256 Mar 1 2019 true + -rwxr-xr-x 1 root root 14264 Apr 23 09:38 ulockmgr_server + -rwsr-xr-x 1 root root 30728 Jan 10 2019 umount + -rwxr-xr-x 1 root root 31384 Mar 1 2019 uname + -rwxr-xr-x 2 root root 2345 Jan 6 2019 uncompress + -rwxr-xr-x 1 root root 138848 Mar 1 2019 vdir + -rwxr-xr-x 1 root root 34824 Jan 10 2019 wdctl + -rwxr-xr-x 1 root root 946 Jan 22 2019 which + lrwxrwxrwx 1 root root 8 Sep 27 2018 ypdomainname -> hostname + -rwxr-xr-x 1 root root 1983 Jan 6 2019 zcat + -rwxr-xr-x 1 root root 1677 Jan 6 2019 zcmp + -rwxr-xr-x 1 root root 5879 Jan 6 2019 zdiff + -rwxr-xr-x 1 root root 29 Jan 6 2019 zegrep + -rwxr-xr-x 1 root root 29 Jan 6 2019 zfgrep + -rwxr-xr-x 1 root root 2080 Jan 6 2019 zforce + -rwxr-xr-x 1 root root 7584 Jan 6 2019 zgrep + -rwxr-xr-x 1 root root 2205 Jan 6 2019 zless + -rwxr-xr-x 1 root root 1841 Jan 6 2019 zmore + -rwxr-xr-x 1 root root 4552 Jan 6 2019 znew +I: user script /srv/workspace/pbuilder/12186/tmp/hooks/D02_print_environment finished -> Attempting to satisfy build-dependencies -> Creating pbuilder-satisfydepends-dummy package Package: pbuilder-satisfydepends-dummy @@ -309,7 +343,7 @@ Get: 108 http://deb.debian.org/debian buster/main arm64 golang-github-hashicorp-go-msgpack-dev all 0.0~git20150518.0.fa3f638-6 [42.7 kB] Get: 109 http://deb.debian.org/debian buster/main arm64 golang-github-hashicorp-raft-dev all 1.0.0+git20180823.82694fb-3 [85.9 kB] Get: 110 http://deb.debian.org/debian buster/main arm64 golang-github-canonicalltd-raft-test-dev all 0.0~git20180628.c3345b5-1 [28.4 kB] -Fetched 84.2 MB in 5s (18.6 MB/s) +Fetched 84.2 MB in 3s (25.0 MB/s) debconf: delaying package configuration, since apt-utils is not installed Selecting previously unselected package libbsd0:arm64. (Reading database ... (Reading database ... 5% (Reading database ... 10% (Reading database ... 15% (Reading database ... 20% (Reading database ... 25% (Reading database ... 30% (Reading database ... 35% (Reading database ... 40% (Reading database ... 45% (Reading database ... 50% (Reading database ... 55% (Reading database ... 60% (Reading database ... 65% (Reading database ... 70% (Reading database ... 75% (Reading database ... 80% (Reading database ... 85% (Reading database ... 90% (Reading database ... 95% (Reading database ... 100% (Reading database ... 19168 files and directories currently installed.) @@ -772,7 +806,7 @@ fakeroot is already the newest version (1.23-1). 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. I: Building the package -I: Running cd /build/golang-github-canonicalltd-raft-membership-0.0~git20180413.3846634/ && env PATH="/usr/sbin:/usr/bin:/sbin:/bin:/usr/games" HOME="/nonexistent/first-build" dpkg-buildpackage -us -uc -b +I: Running cd /build/golang-github-canonicalltd-raft-membership-0.0~git20180413.3846634/ && env PATH="/usr/sbin:/usr/bin:/sbin:/bin:/usr/games:/i/capture/the/path" HOME="/nonexistent/second-build" dpkg-buildpackage -us -uc -b dpkg-buildpackage: info: source package golang-github-canonicalltd-raft-membership dpkg-buildpackage: info: source version 0.0~git20180413.3846634-1 dpkg-buildpackage: info: source distribution unstable @@ -791,51 +825,51 @@ dh_auto_configure -O--buildsystem=golang dh_auto_build -O--buildsystem=golang cd obj-aarch64-linux-gnu && go install -gcflags=all=\"-trimpath=/build/golang-github-canonicalltd-raft-membership-0.0\~git20180413.3846634/obj-aarch64-linux-gnu/src\" -asmflags=all=\"-trimpath=/build/golang-github-canonicalltd-raft-membership-0.0\~git20180413.3846634/obj-aarch64-linux-gnu/src\" -v -p 8 github.com/CanonicalLtd/raft-membership -runtime/internal/sys errors math/bits -internal/race internal/cpu -runtime/internal/atomic -unicode/utf8 +internal/race sync/atomic -math +unicode/utf8 +runtime/internal/sys unicode -container/list +runtime/internal/atomic +math internal/bytealg +container/list crypto/internal/subtle internal/testlog crypto/subtle encoding unicode/utf16 vendor/golang_org/x/net/dns/dnsmessage -github.com/hashicorp/golang-lru/simplelru internal/nettrace vendor/golang_org/x/crypto/cryptobyte/asn1 runtime/cgo +github.com/hashicorp/golang-lru/simplelru runtime strconv crypto/rc4 sync -io internal/singleflight -syscall -reflect +io math/rand +reflect +syscall crypto/cipher strings -bytes hash crypto/internal/randutil -hash/crc32 -crypto/hmac +bytes crypto +crypto/hmac +hash/crc32 +hash/crc64 crypto/sha512 crypto/md5 crypto/sha1 crypto/aes crypto/sha256 -hash/crc64 bufio vendor/golang_org/x/text/transform path @@ -847,45 +881,45 @@ sort os github.com/hashicorp/go-immutable-radix -encoding/base64 crypto/des -vendor/golang_org/x/crypto/curve25519 vendor/golang_org/x/crypto/poly1305 +encoding/base64 vendor/golang_org/x/crypto/internal/chacha20 +vendor/golang_org/x/crypto/curve25519 encoding/pem vendor/golang_org/x/crypto/chacha20poly1305 +os/signal path/filepath fmt -os/signal io/ioutil -context -log encoding/hex -encoding/json +log +context net/url compress/flate +encoding/json math/big vendor/golang_org/x/text/unicode/norm -vendor/golang_org/x/net/http2/hpack vendor/golang_org/x/text/unicode/bidi +vendor/golang_org/x/net/http2/hpack net mime mime/quotedprintable -compress/gzip -vendor/golang_org/x/text/secure/bidirule net/http/internal +vendor/golang_org/x/text/secure/bidirule text/template/parse +compress/gzip encoding/gob vendor/golang_org/x/net/idna text/template +crypto/dsa crypto/rand crypto/elliptic -crypto/dsa encoding/asn1 crypto/rsa +crypto/ecdsa crypto/x509/pkix vendor/golang_org/x/crypto/cryptobyte -crypto/ecdsa html/template vendor/golang_org/x/net/http/httpproxy net/textproto @@ -909,173 +943,228 @@ === RUN TestErrUnknownLeader_Error --- PASS: TestErrUnknownLeader_Error (0.00s) === RUN TestHandleChangeRequests_InvalidChangeRequestKind ---- PASS: TestHandleChangeRequests_InvalidChangeRequestKind (0.03s) - logger.go:44: 05:27:36.005778 [DEBUG] raft-test: setup: start (1 servers) - logger.go:44: 05:27:36.006013 [DEBUG] raft-test: setup: server 0: bootstrap - logger.go:44: 05:27:36.006174 [DEBUG] raft-test: setup: server 0: start - logger.go:44: 05:27:36.006404 [INFO] raft: Initial configuration (index=1): [{Suffrage:Voter ID:0 Address:0}] - logger.go:44: 05:27:36.006461 [DEBUG] raft-test: setup: done - logger.go:44: 05:27:36.006482 [DEBUG] raft-test: elect: start (server 0) - logger.go:44: 05:27:36.006585 [DEBUG] raft-test: server 0: establish outbound connection to all other nodes - logger.go:44: 05:27:36.006669 [DEBUG] raft-test: elect: server 0: wait to become leader within 1.5s - logger.go:44: 05:27:36.006682 [INFO] raft: Node at 0 [Follower] entering Follower state (Leader: "") - logger.go:44: 05:27:36.030381 [WARN] raft: Heartbeat timeout from "" reached, starting election - logger.go:44: 05:27:36.030516 [INFO] raft: Node at 0 [Candidate] entering Candidate state in term 2 - logger.go:44: 05:27:36.030568 [DEBUG] raft: Votes needed: 1 - logger.go:44: 05:27:36.030611 [DEBUG] raft: Vote granted from 0 in term 2. Tally: 1 - logger.go:44: 05:27:36.030625 [INFO] raft: Election won. Tally: 1 - logger.go:44: 05:27:36.030643 [INFO] raft: Node at 0 [Leader] entering Leader state - logger.go:44: 05:27:36.030717 [DEBUG] raft-test: server 0: leadership: acquired - logger.go:44: 05:27:36.030770 [DEBUG] raft-test: elect: server 0: wait for other servers to become followers within 40ms - logger.go:44: 05:27:36.030838 [DEBUG] raft-test: elect: done - logger.go:44: 05:27:36.030865 [DEBUG] raft-test: close: start - logger.go:44: 05:27:36.031051 [DEBUG] raft-test: close: server 0: shutdown done - logger.go:44: 05:27:36.031096 [DEBUG] raft-test: server 0: leadership: stop watching - logger.go:44: 05:27:36.031122 [DEBUG] raft-test: close: done +--- PASS: TestHandleChangeRequests_InvalidChangeRequestKind (0.02s) + logger.go:44: 05:29:00.384513 [DEBUG] raft-test: setup: start (1 servers) + logger.go:44: 05:29:00.384751 [DEBUG] raft-test: setup: server 0: bootstrap + logger.go:44: 05:29:00.384913 [DEBUG] raft-test: setup: server 0: start + logger.go:44: 05:29:00.385167 [INFO] raft: Initial configuration (index=1): [{Suffrage:Voter ID:0 Address:0}] + logger.go:44: 05:29:00.385230 [DEBUG] raft-test: setup: done + logger.go:44: 05:29:00.385251 [DEBUG] raft-test: elect: start (server 0) + logger.go:44: 05:29:00.385272 [DEBUG] raft-test: server 0: establish outbound connection to all other nodes + logger.go:44: 05:29:00.385309 [DEBUG] raft-test: elect: server 0: wait to become leader within 1.5s + logger.go:44: 05:29:00.385343 [INFO] raft: Node at 0 [Follower] entering Follower state (Leader: "") + logger.go:44: 05:29:00.406046 [WARN] raft: Heartbeat timeout from "" reached, starting election + logger.go:44: 05:29:00.406156 [INFO] raft: Node at 0 [Candidate] entering Candidate state in term 2 + logger.go:44: 05:29:00.406207 [DEBUG] raft: Votes needed: 1 + logger.go:44: 05:29:00.406241 [DEBUG] raft: Vote granted from 0 in term 2. Tally: 1 + logger.go:44: 05:29:00.406256 [INFO] raft: Election won. Tally: 1 + logger.go:44: 05:29:00.406275 [INFO] raft: Node at 0 [Leader] entering Leader state + logger.go:44: 05:29:00.406383 [DEBUG] raft-test: server 0: leadership: acquired + logger.go:44: 05:29:00.406430 [DEBUG] raft-test: elect: server 0: wait for other servers to become followers within 40ms + logger.go:44: 05:29:00.406494 [DEBUG] raft-test: elect: done + logger.go:44: 05:29:00.406524 [DEBUG] raft-test: close: start + logger.go:44: 05:29:00.406686 [DEBUG] raft-test: close: server 0: shutdown done + logger.go:44: 05:29:00.406752 [DEBUG] raft-test: server 0: leadership: stop watching + logger.go:44: 05:29:00.406789 [DEBUG] raft-test: close: done === RUN TestHandleChangeRequests_ErrUnknownLeader --- PASS: TestHandleChangeRequests_ErrUnknownLeader (0.00s) - logger.go:44: 05:27:36.031273 [DEBUG] raft-test: setup: start (3 servers) - logger.go:44: 05:27:36.031390 [DEBUG] raft-test: setup: server 0: bootstrap - logger.go:44: 05:27:36.031501 [DEBUG] raft-test: setup: server 1: bootstrap - logger.go:44: 05:27:36.031543 [DEBUG] raft-test: setup: server 2: bootstrap - logger.go:44: 05:27:36.031578 [DEBUG] raft-test: setup: server 0: start - logger.go:44: 05:27:36.031695 [INFO] raft: Initial configuration (index=1): [{Suffrage:Voter ID:0 Address:0} {Suffrage:Voter ID:1 Address:1} {Suffrage:Voter ID:2 Address:2}] - logger.go:44: 05:27:36.031741 [DEBUG] raft-test: setup: server 1: start - logger.go:44: 05:27:36.031821 [INFO] raft: Initial configuration (index=1): [{Suffrage:Voter ID:0 Address:0} {Suffrage:Voter ID:1 Address:1} {Suffrage:Voter ID:2 Address:2}] - logger.go:44: 05:27:36.031837 [INFO] raft: Node at 0 [Follower] entering Follower state (Leader: "") - logger.go:44: 05:27:36.031843 [DEBUG] raft-test: setup: server 2: start - logger.go:44: 05:27:36.031959 [INFO] raft: Node at 1 [Follower] entering Follower state (Leader: "") - logger.go:44: 05:27:36.032106 [INFO] raft: Initial configuration (index=1): [{Suffrage:Voter ID:0 Address:0} {Suffrage:Voter ID:1 Address:1} {Suffrage:Voter ID:2 Address:2}] - logger.go:44: 05:27:36.032155 [DEBUG] raft-test: setup: done - logger.go:44: 05:27:36.032224 [DEBUG] raft-test: close: start - logger.go:44: 05:27:36.032252 [INFO] raft: Node at 2 [Follower] entering Follower state (Leader: "") - logger.go:44: 05:27:36.032418 [DEBUG] raft-test: close: server 2: shutdown done - logger.go:44: 05:27:36.032506 [DEBUG] raft-test: close: server 0: shutdown done - logger.go:44: 05:27:36.032640 [DEBUG] raft-test: close: server 1: shutdown done - logger.go:44: 05:27:36.032669 [DEBUG] raft-test: server 0: leadership: stop watching - logger.go:44: 05:27:36.032706 [DEBUG] raft-test: server 1: leadership: stop watching - logger.go:44: 05:27:36.032723 [DEBUG] raft-test: server 2: leadership: stop watching - logger.go:44: 05:27:36.032736 [DEBUG] raft-test: close: done + logger.go:44: 05:29:00.406934 [DEBUG] raft-test: setup: start (3 servers) + logger.go:44: 05:29:00.407081 [DEBUG] raft-test: setup: server 0: bootstrap + logger.go:44: 05:29:00.407213 [DEBUG] raft-test: setup: server 1: bootstrap + logger.go:44: 05:29:00.407273 [DEBUG] raft-test: setup: server 2: bootstrap + logger.go:44: 05:29:00.407321 [DEBUG] raft-test: setup: server 0: start + logger.go:44: 05:29:00.407449 [INFO] raft: Initial configuration (index=1): [{Suffrage:Voter ID:0 Address:0} {Suffrage:Voter ID:1 Address:1} {Suffrage:Voter ID:2 Address:2}] + logger.go:44: 05:29:00.407509 [DEBUG] raft-test: setup: server 1: start + logger.go:44: 05:29:00.407580 [INFO] raft: Initial configuration (index=1): [{Suffrage:Voter ID:0 Address:0} {Suffrage:Voter ID:1 Address:1} {Suffrage:Voter ID:2 Address:2}] + logger.go:44: 05:29:00.407596 [INFO] raft: Node at 0 [Follower] entering Follower state (Leader: "") + logger.go:44: 05:29:00.407605 [DEBUG] raft-test: setup: server 2: start + logger.go:44: 05:29:00.407740 [INFO] raft: Initial configuration (index=1): [{Suffrage:Voter ID:0 Address:0} {Suffrage:Voter ID:1 Address:1} {Suffrage:Voter ID:2 Address:2}] + logger.go:44: 05:29:00.407647 [INFO] raft: Node at 1 [Follower] entering Follower state (Leader: "") + logger.go:44: 05:29:00.407768 [DEBUG] raft-test: setup: done + logger.go:44: 05:29:00.407958 [DEBUG] raft-test: close: start + logger.go:44: 05:29:00.407827 [INFO] raft: Node at 2 [Follower] entering Follower state (Leader: "") + logger.go:44: 05:29:00.408149 [DEBUG] raft-test: close: server 0: shutdown done + logger.go:44: 05:29:00.408205 [DEBUG] raft-test: close: server 1: shutdown done + logger.go:44: 05:29:00.408252 [DEBUG] raft-test: close: server 2: shutdown done + logger.go:44: 05:29:00.408278 [DEBUG] raft-test: server 0: leadership: stop watching + logger.go:44: 05:29:00.408314 [DEBUG] raft-test: server 1: leadership: stop watching + logger.go:44: 05:29:00.408351 [DEBUG] raft-test: server 2: leadership: stop watching + logger.go:44: 05:29:00.408369 [DEBUG] raft-test: close: done === RUN TestHandleChangeRequests_ErrDifferentLeader ---- PASS: TestHandleChangeRequests_ErrDifferentLeader (0.02s) - logger.go:44: 05:27:36.032819 [DEBUG] raft-test: setup: start (2 servers) - logger.go:44: 05:27:36.032901 [DEBUG] raft-test: setup: server 0: bootstrap - logger.go:44: 05:27:36.032970 [DEBUG] raft-test: setup: server 1: bootstrap - logger.go:44: 05:27:36.033000 [DEBUG] raft-test: setup: server 0: start - logger.go:44: 05:27:36.033054 [INFO] raft: Initial configuration (index=1): [{Suffrage:Voter ID:0 Address:0} {Suffrage:Voter ID:1 Address:1}] - logger.go:44: 05:27:36.033083 [DEBUG] raft-test: setup: server 1: start - logger.go:44: 05:27:36.033125 [INFO] raft: Initial configuration (index=1): [{Suffrage:Voter ID:0 Address:0} {Suffrage:Voter ID:1 Address:1}] - logger.go:44: 05:27:36.033142 [DEBUG] raft-test: setup: done - logger.go:44: 05:27:36.033164 [DEBUG] raft-test: elect: start (server 0) - logger.go:44: 05:27:36.033195 [DEBUG] raft-test: server 0: establish outbound connection to all other nodes - logger.go:44: 05:27:36.033232 [DEBUG] raft-test: elect: server 0: wait to become leader within 1.5s - logger.go:44: 05:27:36.033295 [INFO] raft: Node at 0 [Follower] entering Follower state (Leader: "") - logger.go:44: 05:27:36.033352 [INFO] raft: Node at 1 [Follower] entering Follower state (Leader: "") - logger.go:44: 05:27:36.049195 [WARN] raft: Heartbeat timeout from "" reached, starting election - logger.go:44: 05:27:36.049266 [INFO] raft: Node at 0 [Candidate] entering Candidate state in term 2 - logger.go:44: 05:27:36.049332 [DEBUG] raft: Votes needed: 2 - logger.go:44: 05:27:36.049353 [DEBUG] raft: Vote granted from 0 in term 2. Tally: 1 - logger.go:44: 05:27:36.049466 [DEBUG] raft: Vote granted from 1 in term 2. Tally: 2 - logger.go:44: 05:27:36.049480 [INFO] raft: Election won. Tally: 2 - logger.go:44: 05:27:36.049496 [INFO] raft: Node at 0 [Leader] entering Leader state - logger.go:44: 05:27:36.049533 [INFO] raft: Added peer 1, starting replication - logger.go:44: 05:27:36.049634 [DEBUG] raft-test: server 0: transport: append to 1: 1 entry [Noop:term=2,index=2] - logger.go:44: 05:27:36.049743 [INFO] raft: pipelining replication to peer {Voter 1 1} - logger.go:44: 05:27:36.049791 [DEBUG] raft-test: server 0: leadership: acquired - logger.go:44: 05:27:36.049817 [DEBUG] raft-test: elect: server 0: wait for other servers to become followers within 40ms - logger.go:44: 05:27:36.049904 [DEBUG] raft-test: elect: server 1: became follower - logger.go:44: 05:27:36.049919 [DEBUG] raft-test: elect: done - logger.go:44: 05:27:36.049940 [DEBUG] raft-test: close: start - logger.go:44: 05:27:36.050007 [INFO] raft: aborting pipeline replication to peer {Voter 1 1} - logger.go:44: 05:27:36.050046 [DEBUG] raft-test: close: server 0: shutdown done - logger.go:44: 05:27:36.050090 [DEBUG] raft-test: close: server 1: shutdown done - logger.go:44: 05:27:36.050108 [DEBUG] raft-test: server 0: leadership: stop watching - logger.go:44: 05:27:36.050135 [DEBUG] raft-test: server 1: leadership: stop watching - logger.go:44: 05:27:36.050147 [DEBUG] raft-test: close: done +--- PASS: TestHandleChangeRequests_ErrDifferentLeader (0.05s) + logger.go:44: 05:29:00.408464 [DEBUG] raft-test: setup: start (2 servers) + logger.go:44: 05:29:00.408553 [DEBUG] raft-test: setup: server 0: bootstrap + logger.go:44: 05:29:00.408624 [DEBUG] raft-test: setup: server 1: bootstrap + logger.go:44: 05:29:00.408661 [DEBUG] raft-test: setup: server 0: start + logger.go:44: 05:29:00.408723 [INFO] raft: Initial configuration (index=1): [{Suffrage:Voter ID:0 Address:0} {Suffrage:Voter ID:1 Address:1}] + logger.go:44: 05:29:00.408761 [DEBUG] raft-test: setup: server 1: start + logger.go:44: 05:29:00.408775 [INFO] raft: Node at 0 [Follower] entering Follower state (Leader: "") + logger.go:44: 05:29:00.408813 [INFO] raft: Initial configuration (index=1): [{Suffrage:Voter ID:0 Address:0} {Suffrage:Voter ID:1 Address:1}] + logger.go:44: 05:29:00.408836 [DEBUG] raft-test: setup: done + logger.go:44: 05:29:00.408848 [INFO] raft: Node at 1 [Follower] entering Follower state (Leader: "") + logger.go:44: 05:29:00.408859 [DEBUG] raft-test: elect: start (server 0) + logger.go:44: 05:29:00.408900 [DEBUG] raft-test: server 0: establish outbound connection to all other nodes + logger.go:44: 05:29:00.408922 [DEBUG] raft-test: elect: server 0: wait to become leader within 1.5s + logger.go:44: 05:29:00.438087 [WARN] raft: Heartbeat timeout from "" reached, starting election + logger.go:44: 05:29:00.438157 [INFO] raft: Node at 1 [Candidate] entering Candidate state in term 2 + logger.go:44: 05:29:00.438223 [DEBUG] raft: Votes needed: 2 + logger.go:44: 05:29:00.438244 [DEBUG] raft: Vote granted from 1 in term 2. Tally: 1 + logger.go:44: 05:29:00.438334 [ERR] raft: Failed to make RequestVote RPC to {Voter 0 0}: connectivity to server 0 is down + logger.go:44: 05:29:00.438438 [WARN] raft: Heartbeat timeout from "" reached, starting election + logger.go:44: 05:29:00.438479 [INFO] raft: Node at 0 [Candidate] entering Candidate state in term 2 + logger.go:44: 05:29:00.438515 [DEBUG] raft: Votes needed: 2 + logger.go:44: 05:29:00.438533 [DEBUG] raft: Vote granted from 0 in term 2. Tally: 1 + logger.go:44: 05:29:00.438617 [INFO] raft: Duplicate RequestVote for same term: 2 + logger.go:44: 05:29:00.454024 [WARN] raft: Election timeout reached, restarting election + logger.go:44: 05:29:00.454074 [INFO] raft: Node at 0 [Candidate] entering Candidate state in term 3 + logger.go:44: 05:29:00.454145 [DEBUG] raft: Votes needed: 2 + logger.go:44: 05:29:00.454164 [DEBUG] raft: Vote granted from 0 in term 3. Tally: 1 + logger.go:44: 05:29:00.454230 [INFO] raft: Node at 1 [Follower] entering Follower state (Leader: "") + logger.go:44: 05:29:00.454264 [DEBUG] raft: Vote granted from 1 in term 3. Tally: 2 + logger.go:44: 05:29:00.454278 [INFO] raft: Election won. Tally: 2 + logger.go:44: 05:29:00.454293 [INFO] raft: Node at 0 [Leader] entering Leader state + logger.go:44: 05:29:00.454318 [INFO] raft: Added peer 1, starting replication + logger.go:44: 05:29:00.454394 [DEBUG] raft-test: server 0: leadership: acquired + logger.go:44: 05:29:00.454435 [DEBUG] raft-test: server 0: transport: append to 1: 1 entry [Noop:term=3,index=2] + logger.go:44: 05:29:00.454447 [DEBUG] raft-test: elect: server 0: wait for other servers to become followers within 40ms + logger.go:44: 05:29:00.454585 [INFO] raft: pipelining replication to peer {Voter 1 1} + logger.go:44: 05:29:00.454644 [DEBUG] raft-test: elect: server 1: became follower + logger.go:44: 05:29:00.454713 [DEBUG] raft-test: elect: done + logger.go:44: 05:29:00.454737 [DEBUG] raft-test: close: start + logger.go:44: 05:29:00.454790 [INFO] raft: aborting pipeline replication to peer {Voter 1 1} + logger.go:44: 05:29:00.454897 [DEBUG] raft-test: close: server 0: shutdown done + logger.go:44: 05:29:00.454953 [DEBUG] raft-test: close: server 1: shutdown done + logger.go:44: 05:29:00.454977 [DEBUG] raft-test: server 0: leadership: stop watching + logger.go:44: 05:29:00.454997 [DEBUG] raft-test: server 1: leadership: stop watching + logger.go:44: 05:29:00.455022 [DEBUG] raft-test: close: done === RUN TestHandleChangeRequests_KnownPeer ---- PASS: TestHandleChangeRequests_KnownPeer (0.03s) - logger.go:44: 05:27:36.050259 [DEBUG] raft-test: setup: start (1 servers) - logger.go:44: 05:27:36.050321 [DEBUG] raft-test: setup: server 0: bootstrap - logger.go:44: 05:27:36.050406 [DEBUG] raft-test: setup: server 0: start - logger.go:44: 05:27:36.050487 [INFO] raft: Initial configuration (index=1): [{Suffrage:Voter ID:0 Address:0}] - logger.go:44: 05:27:36.050514 [DEBUG] raft-test: setup: done - logger.go:44: 05:27:36.050531 [DEBUG] raft-test: elect: start (server 0) - logger.go:44: 05:27:36.050559 [DEBUG] raft-test: server 0: establish outbound connection to all other nodes - logger.go:44: 05:27:36.050579 [DEBUG] raft-test: elect: server 0: wait to become leader within 1.5s - logger.go:44: 05:27:36.050608 [INFO] raft: Node at 0 [Follower] entering Follower state (Leader: "") - logger.go:44: 05:27:36.078509 [WARN] raft: Heartbeat timeout from "" reached, starting election - logger.go:44: 05:27:36.078619 [INFO] raft: Node at 0 [Candidate] entering Candidate state in term 2 - logger.go:44: 05:27:36.078671 [DEBUG] raft: Votes needed: 1 - logger.go:44: 05:27:36.078697 [DEBUG] raft: Vote granted from 0 in term 2. Tally: 1 - logger.go:44: 05:27:36.078709 [INFO] raft: Election won. Tally: 1 - logger.go:44: 05:27:36.078724 [INFO] raft: Node at 0 [Leader] entering Leader state - logger.go:44: 05:27:36.078830 [DEBUG] raft-test: server 0: leadership: acquired - logger.go:44: 05:27:36.078857 [DEBUG] raft-test: elect: server 0: wait for other servers to become followers within 40ms - logger.go:44: 05:27:36.078896 [DEBUG] raft-test: elect: done - logger.go:44: 05:27:36.079019 [INFO] raft: Updating configuration with AddStaging (0, 1.2.3.4) to [{Suffrage:Voter ID:0 Address:1.2.3.4}] - logger.go:44: 05:27:36.079102 [DEBUG] raft-test: close: start - logger.go:44: 05:27:36.079173 [DEBUG] raft-test: close: server 0: shutdown done - logger.go:44: 05:27:36.079193 [DEBUG] raft-test: server 0: leadership: stop watching - logger.go:44: 05:27:36.079206 [DEBUG] raft-test: close: done +--- PASS: TestHandleChangeRequests_KnownPeer (0.02s) + logger.go:44: 05:29:00.455174 [DEBUG] raft-test: setup: start (1 servers) + logger.go:44: 05:29:00.455239 [DEBUG] raft-test: setup: server 0: bootstrap + logger.go:44: 05:29:00.455329 [DEBUG] raft-test: setup: server 0: start + logger.go:44: 05:29:00.455402 [INFO] raft: Initial configuration (index=1): [{Suffrage:Voter ID:0 Address:0}] + logger.go:44: 05:29:00.455444 [DEBUG] raft-test: setup: done + logger.go:44: 05:29:00.455465 [DEBUG] raft-test: elect: start (server 0) + logger.go:44: 05:29:00.455478 [INFO] raft: Node at 0 [Follower] entering Follower state (Leader: "") + logger.go:44: 05:29:00.455487 [DEBUG] raft-test: server 0: establish outbound connection to all other nodes + logger.go:44: 05:29:00.455548 [DEBUG] raft-test: elect: server 0: wait to become leader within 1.5s + logger.go:44: 05:29:00.477891 [WARN] raft: Heartbeat timeout from "" reached, starting election + logger.go:44: 05:29:00.477959 [INFO] raft: Node at 0 [Candidate] entering Candidate state in term 2 + logger.go:44: 05:29:00.477988 [DEBUG] raft: Votes needed: 1 + logger.go:44: 05:29:00.478008 [DEBUG] raft: Vote granted from 0 in term 2. Tally: 1 + logger.go:44: 05:29:00.478020 [INFO] raft: Election won. Tally: 1 + logger.go:44: 05:29:00.478035 [INFO] raft: Node at 0 [Leader] entering Leader state + logger.go:44: 05:29:00.478211 [DEBUG] raft-test: server 0: leadership: acquired + logger.go:44: 05:29:00.478317 [DEBUG] raft-test: elect: server 0: wait for other servers to become followers within 40ms + logger.go:44: 05:29:00.478398 [DEBUG] raft-test: elect: done + logger.go:44: 05:29:00.478493 [INFO] raft: Updating configuration with AddStaging (0, 1.2.3.4) to [{Suffrage:Voter ID:0 Address:1.2.3.4}] + logger.go:44: 05:29:00.478643 [DEBUG] raft-test: close: start + logger.go:44: 05:29:00.478729 [DEBUG] raft-test: close: server 0: shutdown done + logger.go:44: 05:29:00.478752 [DEBUG] raft-test: server 0: leadership: stop watching + logger.go:44: 05:29:00.478765 [DEBUG] raft-test: close: done === RUN TestHandleChangeRequests_LeaveRequest ---- PASS: TestHandleChangeRequests_LeaveRequest (0.03s) - logger.go:44: 05:27:36.079353 [DEBUG] raft-test: setup: start (3 servers) - logger.go:44: 05:27:36.079455 [DEBUG] raft-test: setup: server 0: bootstrap - logger.go:44: 05:27:36.079536 [DEBUG] raft-test: setup: server 1: bootstrap - logger.go:44: 05:27:36.079573 [DEBUG] raft-test: setup: server 2: bootstrap - logger.go:44: 05:27:36.079616 [DEBUG] raft-test: setup: server 0: start - logger.go:44: 05:27:36.079708 [INFO] raft: Initial configuration (index=1): [{Suffrage:Voter ID:0 Address:0} {Suffrage:Voter ID:1 Address:1} {Suffrage:Voter ID:2 Address:2}] - logger.go:44: 05:27:36.079742 [DEBUG] raft-test: setup: server 1: start - logger.go:44: 05:27:36.079799 [INFO] raft: Initial configuration (index=1): [{Suffrage:Voter ID:0 Address:0} {Suffrage:Voter ID:1 Address:1} {Suffrage:Voter ID:2 Address:2}] - logger.go:44: 05:27:36.079818 [DEBUG] raft-test: setup: server 2: start - logger.go:44: 05:27:36.079867 [INFO] raft: Initial configuration (index=1): [{Suffrage:Voter ID:0 Address:0} {Suffrage:Voter ID:1 Address:1} {Suffrage:Voter ID:2 Address:2}] - logger.go:44: 05:27:36.079898 [DEBUG] raft-test: setup: done - logger.go:44: 05:27:36.079916 [DEBUG] raft-test: elect: start (server 0) - logger.go:44: 05:27:36.079947 [DEBUG] raft-test: server 0: establish outbound connection to all other nodes - logger.go:44: 05:27:36.079970 [DEBUG] raft-test: elect: server 0: wait to become leader within 1.5s - logger.go:44: 05:27:36.080007 [INFO] raft: Node at 0 [Follower] entering Follower state (Leader: "") - logger.go:44: 05:27:36.080042 [INFO] raft: Node at 1 [Follower] entering Follower state (Leader: "") - logger.go:44: 05:27:36.080099 [INFO] raft: Node at 2 [Follower] entering Follower state (Leader: "") - logger.go:44: 05:27:36.102744 [WARN] raft: Heartbeat timeout from "" reached, starting election - logger.go:44: 05:27:36.102827 [INFO] raft: Node at 0 [Candidate] entering Candidate state in term 2 - logger.go:44: 05:27:36.102901 [DEBUG] raft: Votes needed: 2 - logger.go:44: 05:27:36.102924 [DEBUG] raft: Vote granted from 0 in term 2. Tally: 1 - logger.go:44: 05:27:36.103002 [DEBUG] raft: Vote granted from 2 in term 2. Tally: 2 - logger.go:44: 05:27:36.103017 [INFO] raft: Election won. Tally: 2 - logger.go:44: 05:27:36.103044 [INFO] raft: Node at 0 [Leader] entering Leader state - logger.go:44: 05:27:36.103085 [INFO] raft: Added peer 1, starting replication - logger.go:44: 05:27:36.103108 [INFO] raft: Added peer 2, starting replication - logger.go:44: 05:27:36.103170 [DEBUG] raft-test: server 0: leadership: acquired - logger.go:44: 05:27:36.103192 [DEBUG] raft-test: server 0: transport: append to 2: 1 entry [Noop:term=2,index=2] - logger.go:44: 05:27:36.103208 [DEBUG] raft-test: elect: server 0: wait for other servers to become followers within 40ms - logger.go:44: 05:27:36.103222 [DEBUG] raft-test: server 0: transport: append to 1: 1 entry [Noop:term=2,index=2] - logger.go:44: 05:27:36.103442 [INFO] raft: pipelining replication to peer {Voter 1 1} - logger.go:44: 05:27:36.103331 [INFO] raft: pipelining replication to peer {Voter 2 2} - logger.go:44: 05:27:36.104470 [DEBUG] raft-test: elect: server 1: became follower - logger.go:44: 05:27:36.104501 [DEBUG] raft-test: elect: server 2: became follower - logger.go:44: 05:27:36.104512 [DEBUG] raft-test: elect: done - logger.go:44: 05:27:36.104609 [INFO] raft: Updating configuration with RemoveServer (2, ) to [{Suffrage:Voter ID:0 Address:0} {Suffrage:Voter ID:1 Address:1}] - logger.go:44: 05:27:36.104710 [DEBUG] raft-test: server 0: pipeline: append to 2: 1 entry [Other:term=2,index=3] - logger.go:44: 05:27:36.104739 [DEBUG] raft-test: server 0: pipeline: append to 1: 1 entry [Other:term=2,index=3] - logger.go:44: 05:27:36.104781 [DEBUG] raft-test: server 0: pipeline: append to 2: 0 entries - logger.go:44: 05:27:36.104722 [INFO] raft: Removed peer 2, stopping replication after 3 - logger.go:44: 05:27:36.104845 [DEBUG] raft-test: server 0: pipeline: append to 2: 0 entries - logger.go:44: 05:27:36.104875 [INFO] raft: aborting pipeline replication to peer {Voter 2 2} - logger.go:44: 05:27:36.104907 [DEBUG] raft-test: close: start - logger.go:44: 05:27:36.104973 [INFO] raft: aborting pipeline replication to peer {Voter 1 1} - logger.go:44: 05:27:36.105004 [DEBUG] raft-test: close: server 0: shutdown done - logger.go:44: 05:27:36.105041 [DEBUG] raft-test: close: server 2: shutdown done - logger.go:44: 05:27:36.105074 [DEBUG] raft-test: close: server 1: shutdown done - logger.go:44: 05:27:36.105090 [DEBUG] raft-test: server 0: leadership: stop watching - logger.go:44: 05:27:36.105117 [DEBUG] raft-test: server 1: leadership: stop watching - logger.go:44: 05:27:36.105139 [DEBUG] raft-test: server 2: leadership: stop watching - logger.go:44: 05:27:36.105151 [DEBUG] raft-test: close: done +--- PASS: TestHandleChangeRequests_LeaveRequest (0.07s) + logger.go:44: 05:29:00.478898 [DEBUG] raft-test: setup: start (3 servers) + logger.go:44: 05:29:00.479018 [DEBUG] raft-test: setup: server 0: bootstrap + logger.go:44: 05:29:00.479107 [DEBUG] raft-test: setup: server 1: bootstrap + logger.go:44: 05:29:00.479151 [DEBUG] raft-test: setup: server 2: bootstrap + logger.go:44: 05:29:00.479182 [DEBUG] raft-test: setup: server 0: start + logger.go:44: 05:29:00.479271 [INFO] raft: Initial configuration (index=1): [{Suffrage:Voter ID:0 Address:0} {Suffrage:Voter ID:1 Address:1} {Suffrage:Voter ID:2 Address:2}] + logger.go:44: 05:29:00.479321 [DEBUG] raft-test: setup: server 1: start + logger.go:44: 05:29:00.479383 [INFO] raft: Initial configuration (index=1): [{Suffrage:Voter ID:0 Address:0} {Suffrage:Voter ID:1 Address:1} {Suffrage:Voter ID:2 Address:2}] + logger.go:44: 05:29:00.479393 [INFO] raft: Node at 0 [Follower] entering Follower state (Leader: "") + logger.go:44: 05:29:00.479416 [DEBUG] raft-test: setup: server 2: start + logger.go:44: 05:29:00.479547 [INFO] raft: Initial configuration (index=1): [{Suffrage:Voter ID:0 Address:0} {Suffrage:Voter ID:1 Address:1} {Suffrage:Voter ID:2 Address:2}] + logger.go:44: 05:29:00.479576 [DEBUG] raft-test: setup: done + logger.go:44: 05:29:00.479602 [DEBUG] raft-test: elect: start (server 0) + logger.go:44: 05:29:00.479616 [INFO] raft: Node at 2 [Follower] entering Follower state (Leader: "") + logger.go:44: 05:29:00.479625 [DEBUG] raft-test: server 0: establish outbound connection to all other nodes + logger.go:44: 05:29:00.479691 [DEBUG] raft-test: elect: server 0: wait to become leader within 1.5s + logger.go:44: 05:29:00.479441 [INFO] raft: Node at 1 [Follower] entering Follower state (Leader: "") + logger.go:44: 05:29:00.498605 [WARN] raft: Heartbeat timeout from "" reached, starting election + logger.go:44: 05:29:00.498677 [INFO] raft: Node at 1 [Candidate] entering Candidate state in term 2 + logger.go:44: 05:29:00.498725 [DEBUG] raft: Votes needed: 2 + logger.go:44: 05:29:00.498745 [DEBUG] raft: Vote granted from 1 in term 2. Tally: 1 + logger.go:44: 05:29:00.498808 [ERR] raft: Failed to make RequestVote RPC to {Voter 2 2}: connectivity to server 2 is down + logger.go:44: 05:29:00.498809 [ERR] raft: Failed to make RequestVote RPC to {Voter 0 0}: connectivity to server 0 is down + logger.go:44: 05:29:00.502409 [WARN] raft: Heartbeat timeout from "" reached, starting election + logger.go:44: 05:29:00.502443 [INFO] raft: Node at 2 [Candidate] entering Candidate state in term 2 + logger.go:44: 05:29:00.502478 [DEBUG] raft: Votes needed: 2 + logger.go:44: 05:29:00.502510 [DEBUG] raft: Vote granted from 2 in term 2. Tally: 1 + logger.go:44: 05:29:00.502573 [ERR] raft: Failed to make RequestVote RPC to {Voter 1 1}: connectivity to server 1 is down + logger.go:44: 05:29:00.502589 [ERR] raft: Failed to make RequestVote RPC to {Voter 0 0}: connectivity to server 0 is down + logger.go:44: 05:29:00.504203 [WARN] raft: Heartbeat timeout from "" reached, starting election + logger.go:44: 05:29:00.504247 [INFO] raft: Node at 0 [Candidate] entering Candidate state in term 2 + logger.go:44: 05:29:00.504298 [DEBUG] raft: Votes needed: 2 + logger.go:44: 05:29:00.504318 [DEBUG] raft: Vote granted from 0 in term 2. Tally: 1 + logger.go:44: 05:29:00.504359 [INFO] raft: Duplicate RequestVote for same term: 2 + logger.go:44: 05:29:00.504370 [INFO] raft: Duplicate RequestVote for same term: 2 + logger.go:44: 05:29:00.517048 [WARN] raft: Election timeout reached, restarting election + logger.go:44: 05:29:00.517120 [INFO] raft: Node at 1 [Candidate] entering Candidate state in term 3 + logger.go:44: 05:29:00.517167 [DEBUG] raft: Votes needed: 2 + logger.go:44: 05:29:00.517193 [DEBUG] raft: Vote granted from 1 in term 3. Tally: 1 + logger.go:44: 05:29:00.517241 [ERR] raft: Failed to make RequestVote RPC to {Voter 2 2}: connectivity to server 2 is down + logger.go:44: 05:29:00.517260 [ERR] raft: Failed to make RequestVote RPC to {Voter 0 0}: connectivity to server 0 is down + logger.go:44: 05:29:00.529985 [WARN] raft: Election timeout reached, restarting election + logger.go:44: 05:29:00.530066 [INFO] raft: Node at 2 [Candidate] entering Candidate state in term 3 + logger.go:44: 05:29:00.530122 [DEBUG] raft: Votes needed: 2 + logger.go:44: 05:29:00.530166 [DEBUG] raft: Vote granted from 2 in term 3. Tally: 1 + logger.go:44: 05:29:00.530224 [ERR] raft: Failed to make RequestVote RPC to {Voter 1 1}: connectivity to server 1 is down + logger.go:44: 05:29:00.530225 [ERR] raft: Failed to make RequestVote RPC to {Voter 0 0}: connectivity to server 0 is down + logger.go:44: 05:29:00.530302 [WARN] raft: Election timeout reached, restarting election + logger.go:44: 05:29:00.530329 [INFO] raft: Node at 0 [Candidate] entering Candidate state in term 3 + logger.go:44: 05:29:00.530370 [DEBUG] raft: Votes needed: 2 + logger.go:44: 05:29:00.530389 [DEBUG] raft: Vote granted from 0 in term 3. Tally: 1 + logger.go:44: 05:29:00.530427 [INFO] raft: Duplicate RequestVote for same term: 3 + logger.go:44: 05:29:00.530438 [INFO] raft: Duplicate RequestVote for same term: 3 + logger.go:44: 05:29:00.540519 [WARN] raft: Election timeout reached, restarting election + logger.go:44: 05:29:00.540575 [INFO] raft: Node at 1 [Candidate] entering Candidate state in term 4 + logger.go:44: 05:29:00.540664 [DEBUG] raft: Votes needed: 2 + logger.go:44: 05:29:00.540685 [DEBUG] raft: Vote granted from 1 in term 4. Tally: 1 + logger.go:44: 05:29:00.540739 [ERR] raft: Failed to make RequestVote RPC to {Voter 2 2}: connectivity to server 2 is down + logger.go:44: 05:29:00.540745 [ERR] raft: Failed to make RequestVote RPC to {Voter 0 0}: connectivity to server 0 is down + logger.go:44: 05:29:00.546650 [WARN] raft: Election timeout reached, restarting election + logger.go:44: 05:29:00.546710 [INFO] raft: Node at 0 [Candidate] entering Candidate state in term 4 + logger.go:44: 05:29:00.546778 [DEBUG] raft: Votes needed: 2 + logger.go:44: 05:29:00.546803 [DEBUG] raft: Vote granted from 0 in term 4. Tally: 1 + logger.go:44: 05:29:00.546838 [INFO] raft: Duplicate RequestVote for same term: 4 + logger.go:44: 05:29:00.546879 [INFO] raft: Node at 2 [Follower] entering Follower state (Leader: "") + logger.go:44: 05:29:00.546932 [DEBUG] raft: Vote granted from 2 in term 4. Tally: 2 + logger.go:44: 05:29:00.546948 [INFO] raft: Election won. Tally: 2 + logger.go:44: 05:29:00.546966 [INFO] raft: Node at 0 [Leader] entering Leader state + logger.go:44: 05:29:00.547009 [INFO] raft: Added peer 1, starting replication + logger.go:44: 05:29:00.547035 [INFO] raft: Added peer 2, starting replication + logger.go:44: 05:29:00.547093 [DEBUG] raft-test: server 0: leadership: acquired + logger.go:44: 05:29:00.547130 [DEBUG] raft-test: server 0: transport: append to 2: 1 entry [Noop:term=4,index=2] + logger.go:44: 05:29:00.547133 [DEBUG] raft-test: server 0: transport: append to 1: 1 entry [Noop:term=4,index=2] + logger.go:44: 05:29:00.547275 [INFO] raft: pipelining replication to peer {Voter 2 2} + logger.go:44: 05:29:00.547297 [INFO] raft: Node at 1 [Follower] entering Follower state (Leader: "0") + logger.go:44: 05:29:00.547326 [INFO] raft: pipelining replication to peer {Voter 1 1} + logger.go:44: 05:29:00.547142 [DEBUG] raft-test: elect: server 0: wait for other servers to become followers within 40ms + logger.go:44: 05:29:00.547487 [DEBUG] raft-test: elect: server 1: became follower + logger.go:44: 05:29:00.547503 [DEBUG] raft-test: elect: server 2: became follower + logger.go:44: 05:29:00.547536 [DEBUG] raft-test: elect: done + logger.go:44: 05:29:00.547596 [INFO] raft: Updating configuration with RemoveServer (2, ) to [{Suffrage:Voter ID:0 Address:0} {Suffrage:Voter ID:1 Address:1}] + logger.go:44: 05:29:00.547679 [INFO] raft: Removed peer 2, stopping replication after 3 + logger.go:44: 05:29:00.547707 [DEBUG] raft-test: server 0: pipeline: append to 2: 1 entry [Other:term=4,index=3] + logger.go:44: 05:29:00.547716 [DEBUG] raft-test: server 0: pipeline: append to 1: 1 entry [Other:term=4,index=3] + logger.go:44: 05:29:00.547757 [DEBUG] raft-test: server 0: pipeline: append to 2: 0 entries + logger.go:44: 05:29:00.547871 [INFO] raft: aborting pipeline replication to peer {Voter 2 2} + logger.go:44: 05:29:00.547899 [DEBUG] raft-test: close: start + logger.go:44: 05:29:00.547975 [INFO] raft: aborting pipeline replication to peer {Voter 1 1} + logger.go:44: 05:29:00.548022 [DEBUG] raft-test: close: server 0: shutdown done + logger.go:44: 05:29:00.548099 [DEBUG] raft-test: close: server 1: shutdown done + logger.go:44: 05:29:00.548144 [DEBUG] raft-test: close: server 2: shutdown done + logger.go:44: 05:29:00.548181 [DEBUG] raft-test: server 1: leadership: stop watching + logger.go:44: 05:29:00.548211 [DEBUG] raft-test: server 2: leadership: stop watching + logger.go:44: 05:29:00.548230 [DEBUG] raft-test: server 0: leadership: stop watching + logger.go:44: 05:29:00.548248 [DEBUG] raft-test: close: done === RUN TestChangeRequestKind_String --- PASS: TestChangeRequestKind_String (0.00s) === RUN TestChangeRequest_ErrorTimeout --- PASS: TestChangeRequest_ErrorTimeout (0.00s) PASS -ok github.com/CanonicalLtd/raft-membership 0.111s +ok github.com/CanonicalLtd/raft-membership 0.175s create-stamp debian/debhelper-build-stamp fakeroot debian/rules binary dh binary --buildsystem=golang --with=golang @@ -1103,12 +1192,14 @@ dpkg-source --after-build . dpkg-buildpackage: info: binary-only upload (no source included) I: copying local configuration +I: user script /srv/workspace/pbuilder/12186/tmp/hooks/B01_cleanup starting +I: user script /srv/workspace/pbuilder/12186/tmp/hooks/B01_cleanup finished I: unmounting dev/ptmx filesystem I: unmounting dev/pts filesystem I: unmounting dev/shm filesystem I: unmounting proc filesystem I: unmounting sys filesystem I: cleaning the build env -I: removing directory /srv/workspace/pbuilder/32143 and its subdirectories -I: Current time: Sun Jul 19 17:27:42 -12 2020 -I: pbuilder-time-stamp: 1595222862 +I: removing directory /srv/workspace/pbuilder/12186 and its subdirectories +I: Current time: Mon Jul 20 19:29:06 +14 2020 +I: pbuilder-time-stamp: 1595222946