Diff of the two buildlogs: -- --- b1/build.log 2021-02-16 05:31:49.449794460 +0000 +++ b2/build.log 2021-02-16 05:40:00.082114992 +0000 @@ -1,6 +1,6 @@ I: pbuilder: network access will be disabled during build -I: Current time: Mon Feb 15 17:28:36 -12 2021 -I: pbuilder-time-stamp: 1613453316 +I: Current time: Tue Feb 16 19:32:02 +14 2021 +I: pbuilder-time-stamp: 1613453522 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 '/root/.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/1598/tmp/hooks/D02_print_environment starting +I: user script /srv/workspace/pbuilder/15936/tmp/hooks/D01_modify_environment starting +debug: Running on odxu4a. +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/15936/tmp/hooks/D01_modify_environment finished +I: user script /srv/workspace/pbuilder/15936/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='armhf' - DEBIAN_FRONTEND='noninteractive' - DEB_BUILD_OPTIONS='buildinfo=+all reproducible=+all parallel=3' - DISTRIBUTION='' - HOME='/root' - HOST_ARCH='armhf' + 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]="arm-unknown-linux-gnueabihf") + 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=armhf + DEBIAN_FRONTEND=noninteractive + DEB_BUILD_OPTIONS='buildinfo=+all reproducible=+all parallel=6' + DIRSTACK=() + DISTRIBUTION= + EUID=0 + FUNCNAME=([0]="Echo" [1]="main") + GROUPS=() + HOME=/root + HOSTNAME=i-capture-the-hostname + HOSTTYPE=arm + HOST_ARCH=armhf IFS=' ' - INVOCATION_ID='f7f25eb6c2084fb698c0a226746da189' - 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='1598' - PS1='# ' - PS2='> ' + INVOCATION_ID=262dea5cb6f945e897f494ea088212e3 + LANG=C + LANGUAGE=it_CH:it + LC_ALL=C + MACHTYPE=arm-unknown-linux-gnueabihf + MAIL=/var/mail/root + OPTERR=1 + OPTIND=1 + OSTYPE=linux-gnueabihf + 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=15936 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.cxDe2xkWol/pbuilderrc_lsHx --hookdir /etc/pbuilder/first-build-hooks --debbuildopts -b --basetgz /var/cache/pbuilder/buster-reproducible-base.tgz --buildresult /srv/reproducible-results/rbuild-debian/tmp.cxDe2xkWol/b1 --logfile b1/build.log golang-github-canonicalltd-raft-membership_0.0~git20180413.3846634-1.dsc' - SUDO_GID='114' - SUDO_UID='109' - SUDO_USER='jenkins' - TERM='unknown' - TZ='/usr/share/zoneinfo/Etc/GMT+12' - USER='root' - _='/usr/bin/systemd-run' - http_proxy='http://10.0.0.15:8000/' + 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.cxDe2xkWol/pbuilderrc_UH9K --hookdir /etc/pbuilder/rebuild-hooks --debbuildopts -b --basetgz /var/cache/pbuilder/buster-reproducible-base.tgz --buildresult /srv/reproducible-results/rbuild-debian/tmp.cxDe2xkWol/b2 --logfile b2/build.log golang-github-canonicalltd-raft-membership_0.0~git20180413.3846634-1.dsc' + SUDO_GID=114 + SUDO_UID=110 + SUDO_USER=jenkins + TERM=unknown + TZ=/usr/share/zoneinfo/Etc/GMT-14 + UID=0 + USER=root + _='I: set' + http_proxy=http://10.0.0.15:8000/ I: uname -a - Linux jtx1a 4.19.0-14-arm64 #1 SMP Debian 4.19.171-2 (2021-01-30) aarch64 GNU/Linux + Linux i-capture-the-hostname 5.9.0-0.bpo.5-armmp-lpae #1 SMP Debian 5.9.15-1~bpo10+1 (2020-12-31) armv7l GNU/Linux I: ls -l /bin total 3328 - -rwxr-xr-x 1 root root 767656 Apr 17 2019 bash - -rwxr-xr-x 3 root root 26052 Jul 10 2019 bunzip2 - -rwxr-xr-x 3 root root 26052 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 26052 Jul 10 2019 bzip2 - -rwxr-xr-x 1 root root 9636 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 22432 Feb 28 2019 cat - -rwxr-xr-x 1 root root 38868 Feb 28 2019 chgrp - -rwxr-xr-x 1 root root 38836 Feb 28 2019 chmod - -rwxr-xr-x 1 root root 42972 Feb 28 2019 chown - -rwxr-xr-x 1 root root 88376 Feb 28 2019 cp - -rwxr-xr-x 1 root root 75516 Jan 17 2019 dash - -rwxr-xr-x 1 root root 71648 Feb 28 2019 date - -rwxr-xr-x 1 root root 51212 Feb 28 2019 dd - -rwxr-xr-x 1 root root 55672 Feb 28 2019 df - -rwxr-xr-x 1 root root 88444 Feb 28 2019 dir - -rwxr-xr-x 1 root root 54872 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 22364 Feb 28 2019 echo - -rwxr-xr-x 1 root root 28 Jan 7 2019 egrep - -rwxr-xr-x 1 root root 18260 Feb 28 2019 false - -rwxr-xr-x 1 root root 28 Jan 7 2019 fgrep - -rwxr-xr-x 1 root root 47356 Jan 9 2019 findmnt - -rwsr-xr-x 1 root root 21980 Apr 22 2020 fusermount - -rwxr-xr-x 1 root root 124508 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 64232 Jan 5 2019 gzip - -rwxr-xr-x 1 root root 13784 Sep 26 2018 hostname - -rwxr-xr-x 1 root root 43044 Feb 28 2019 ln - -rwxr-xr-x 1 root root 34932 Jul 26 2018 login - -rwxr-xr-x 1 root root 88444 Feb 28 2019 ls - -rwxr-xr-x 1 root root 67036 Jan 9 2019 lsblk - -rwxr-xr-x 1 root root 47168 Feb 28 2019 mkdir - -rwxr-xr-x 1 root root 43040 Feb 28 2019 mknod - -rwxr-xr-x 1 root root 26552 Feb 28 2019 mktemp - -rwxr-xr-x 1 root root 26024 Jan 9 2019 more - -rwsr-xr-x 1 root root 34268 Jan 9 2019 mount - -rwxr-xr-x 1 root root 9688 Jan 9 2019 mountpoint - -rwxr-xr-x 1 root root 84284 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 22416 Feb 28 2019 pwd - lrwxrwxrwx 1 root root 4 Apr 17 2019 rbash -> bash - -rwxr-xr-x 1 root root 26504 Feb 28 2019 readlink - -rwxr-xr-x 1 root root 42968 Feb 28 2019 rm - -rwxr-xr-x 1 root root 26496 Feb 28 2019 rmdir - -rwxr-xr-x 1 root root 14136 Jan 21 2019 run-parts - -rwxr-xr-x 1 root root 76012 Dec 22 2018 sed - lrwxrwxrwx 1 root root 4 Feb 11 06:32 sh -> dash - -rwxr-xr-x 1 root root 22384 Feb 28 2019 sleep - -rwxr-xr-x 1 root root 51124 Feb 28 2019 stty - -rwsr-xr-x 1 root root 42472 Jan 9 2019 su - -rwxr-xr-x 1 root root 22392 Feb 28 2019 sync - -rwxr-xr-x 1 root root 283324 Apr 23 2019 tar - -rwxr-xr-x 1 root root 9808 Jan 21 2019 tempfile - -rwxr-xr-x 1 root root 63464 Feb 28 2019 touch - -rwxr-xr-x 1 root root 18260 Feb 28 2019 true - -rwxr-xr-x 1 root root 9636 Apr 22 2020 ulockmgr_server - -rwsr-xr-x 1 root root 21976 Jan 9 2019 umount - -rwxr-xr-x 1 root root 22380 Feb 28 2019 uname - -rwxr-xr-x 2 root root 2345 Jan 5 2019 uncompress - -rwxr-xr-x 1 root root 88444 Feb 28 2019 vdir - -rwxr-xr-x 1 root root 21980 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/1598/tmp/hooks/D02_print_environment finished + -rwxr-xr-x 1 root root 767656 Apr 18 2019 bash + -rwxr-xr-x 3 root root 26052 Jul 11 2019 bunzip2 + -rwxr-xr-x 3 root root 26052 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 26052 Jul 11 2019 bzip2 + -rwxr-xr-x 1 root root 9636 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 22432 Mar 1 2019 cat + -rwxr-xr-x 1 root root 38868 Mar 1 2019 chgrp + -rwxr-xr-x 1 root root 38836 Mar 1 2019 chmod + -rwxr-xr-x 1 root root 42972 Mar 1 2019 chown + -rwxr-xr-x 1 root root 88376 Mar 1 2019 cp + -rwxr-xr-x 1 root root 75516 Jan 18 2019 dash + -rwxr-xr-x 1 root root 71648 Mar 1 2019 date + -rwxr-xr-x 1 root root 51212 Mar 1 2019 dd + -rwxr-xr-x 1 root root 55672 Mar 1 2019 df + -rwxr-xr-x 1 root root 88444 Mar 1 2019 dir + -rwxr-xr-x 1 root root 54872 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 22364 Mar 1 2019 echo + -rwxr-xr-x 1 root root 28 Jan 8 2019 egrep + -rwxr-xr-x 1 root root 18260 Mar 1 2019 false + -rwxr-xr-x 1 root root 28 Jan 8 2019 fgrep + -rwxr-xr-x 1 root root 47356 Jan 10 2019 findmnt + -rwsr-xr-x 1 root root 21980 Apr 23 2020 fusermount + -rwxr-xr-x 1 root root 124508 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 64232 Jan 6 2019 gzip + -rwxr-xr-x 1 root root 13784 Sep 27 2018 hostname + -rwxr-xr-x 1 root root 43044 Mar 1 2019 ln + -rwxr-xr-x 1 root root 34932 Jul 27 2018 login + -rwxr-xr-x 1 root root 88444 Mar 1 2019 ls + -rwxr-xr-x 1 root root 67036 Jan 10 2019 lsblk + -rwxr-xr-x 1 root root 47168 Mar 1 2019 mkdir + -rwxr-xr-x 1 root root 43040 Mar 1 2019 mknod + -rwxr-xr-x 1 root root 26552 Mar 1 2019 mktemp + -rwxr-xr-x 1 root root 26024 Jan 10 2019 more + -rwsr-xr-x 1 root root 34268 Jan 10 2019 mount + -rwxr-xr-x 1 root root 9688 Jan 10 2019 mountpoint + -rwxr-xr-x 1 root root 84284 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 22416 Mar 1 2019 pwd + lrwxrwxrwx 1 root root 4 Apr 18 2019 rbash -> bash + -rwxr-xr-x 1 root root 26504 Mar 1 2019 readlink + -rwxr-xr-x 1 root root 42968 Mar 1 2019 rm + -rwxr-xr-x 1 root root 26496 Mar 1 2019 rmdir + -rwxr-xr-x 1 root root 14136 Jan 22 2019 run-parts + -rwxr-xr-x 1 root root 76012 Dec 23 2018 sed + lrwxrwxrwx 1 root root 4 Feb 16 19:33 sh -> bash + lrwxrwxrwx 1 root root 4 Feb 7 22:26 sh.distrib -> dash + -rwxr-xr-x 1 root root 22384 Mar 1 2019 sleep + -rwxr-xr-x 1 root root 51124 Mar 1 2019 stty + -rwsr-xr-x 1 root root 42472 Jan 10 2019 su + -rwxr-xr-x 1 root root 22392 Mar 1 2019 sync + -rwxr-xr-x 1 root root 283324 Apr 24 2019 tar + -rwxr-xr-x 1 root root 9808 Jan 22 2019 tempfile + -rwxr-xr-x 1 root root 63464 Mar 1 2019 touch + -rwxr-xr-x 1 root root 18260 Mar 1 2019 true + -rwxr-xr-x 1 root root 9636 Apr 23 2020 ulockmgr_server + -rwsr-xr-x 1 root root 21976 Jan 10 2019 umount + -rwxr-xr-x 1 root root 22380 Mar 1 2019 uname + -rwxr-xr-x 2 root root 2345 Jan 6 2019 uncompress + -rwxr-xr-x 1 root root 88444 Mar 1 2019 vdir + -rwxr-xr-x 1 root root 21980 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/15936/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 armhf 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 armhf golang-github-hashicorp-raft-dev all 1.0.0+git20180823.82694fb-3 [85.9 kB] Get: 110 http://deb.debian.org/debian buster/main armhf golang-github-canonicalltd-raft-test-dev all 0.0~git20180628.c3345b5-1 [28.4 kB] -Fetched 85.2 MB in 8s (11.2 MB/s) +Fetched 85.2 MB in 10s (8858 kB/s) debconf: delaying package configuration, since apt-utils is not installed Selecting previously unselected package libbsd0:armhf. (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 ... 18932 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 @@ -790,118 +824,118 @@ dh_autoreconf -O--buildsystem=golang dh_auto_configure -O--buildsystem=golang dh_auto_build -O--buildsystem=golang - cd obj-arm-linux-gnueabihf && go install -gcflags=all=\"-trimpath=/build/golang-github-canonicalltd-raft-membership-0.0\~git20180413.3846634/obj-arm-linux-gnueabihf/src\" -asmflags=all=\"-trimpath=/build/golang-github-canonicalltd-raft-membership-0.0\~git20180413.3846634/obj-arm-linux-gnueabihf/src\" -v -p 3 github.com/CanonicalLtd/raft-membership -internal/cpu + cd obj-arm-linux-gnueabihf && go install -gcflags=all=\"-trimpath=/build/golang-github-canonicalltd-raft-membership-0.0\~git20180413.3846634/obj-arm-linux-gnueabihf/src\" -asmflags=all=\"-trimpath=/build/golang-github-canonicalltd-raft-membership-0.0\~git20180413.3846634/obj-arm-linux-gnueabihf/src\" -v -p 6 github.com/CanonicalLtd/raft-membership internal/race errors runtime/internal/sys +internal/cpu sync/atomic -internal/bytealg -runtime/internal/atomic -math -internal/testlog math/bits -runtime unicode/utf8 -unicode -strconv +math +runtime/internal/atomic +internal/bytealg +internal/testlog container/list +unicode crypto/internal/subtle crypto/subtle encoding unicode/utf16 -github.com/hashicorp/golang-lru/simplelru vendor/golang_org/x/net/dns/dnsmessage +runtime internal/nettrace +github.com/hashicorp/golang-lru/simplelru runtime/cgo -crypto/rc4 vendor/golang_org/x/crypto/cryptobyte/asn1 +strconv +crypto/rc4 sync io +math/rand +internal/singleflight reflect syscall -bytes -bufio +hash crypto/cipher -time -internal/syscall/unix -crypto/aes -math/rand +bytes strings -internal/singleflight -hash hash/crc32 crypto -internal/poll crypto/internal/randutil crypto/sha512 +crypto/aes +crypto/hmac +bufio +crypto/md5 +crypto/sha1 +crypto/sha256 +vendor/golang_org/x/text/transform +path +html +hash/crc64 +internal/syscall/unix +time +internal/poll encoding/binary sort os github.com/hashicorp/go-immutable-radix encoding/base64 -crypto/des -crypto/hmac -crypto/md5 -crypto/sha1 -crypto/sha256 -fmt -encoding/pem -path/filepath vendor/golang_org/x/crypto/internal/chacha20 +crypto/des vendor/golang_org/x/crypto/poly1305 -vendor/golang_org/x/crypto/chacha20poly1305 -io/ioutil vendor/golang_org/x/crypto/curve25519 -vendor/golang_org/x/text/transform -path +vendor/golang_org/x/crypto/chacha20poly1305 +encoding/pem os/signal -hash/crc64 -html +path/filepath +fmt +io/ioutil context -math/big -encoding/json log -net -compress/flate -crypto/rand -compress/gzip -crypto/elliptic -encoding/asn1 -crypto/rsa -crypto/ecdsa -crypto/dsa encoding/hex -vendor/golang_org/x/crypto/cryptobyte -crypto/x509/pkix +encoding/json +compress/flate +math/big net/url +net vendor/golang_org/x/text/unicode/bidi vendor/golang_org/x/text/unicode/norm vendor/golang_org/x/text/secure/bidirule vendor/golang_org/x/net/http2/hpack +compress/gzip mime -vendor/golang_org/x/net/idna mime/quotedprintable net/http/internal encoding/gob -crypto/x509 -net/textproto -vendor/golang_org/x/net/http/httpguts -vendor/golang_org/x/net/http/httpproxy -mime/multipart text/template/parse -crypto/tls +vendor/golang_org/x/net/idna +crypto/rand +crypto/elliptic +encoding/asn1 +crypto/rsa +crypto/dsa text/template +crypto/ecdsa +crypto/x509/pkix +vendor/golang_org/x/crypto/cryptobyte html/template +vendor/golang_org/x/net/http/httpproxy +net/textproto +crypto/x509 +mime/multipart +vendor/golang_org/x/net/http/httpguts +crypto/tls net/http/httptrace net/http -net/rpc github.com/armon/go-metrics +net/rpc github.com/hashicorp/go-msgpack/codec github.com/hashicorp/raft github.com/CanonicalLtd/raft-membership dh_auto_test -O--buildsystem=golang - cd obj-arm-linux-gnueabihf && go test -vet=off -v -p 3 github.com/CanonicalLtd/raft-membership + cd obj-arm-linux-gnueabihf && go test -vet=off -v -p 6 github.com/CanonicalLtd/raft-membership === RUN TestErrDifferentLeader_Error --- PASS: TestErrDifferentLeader_Error (0.00s) === RUN TestErrDifferentLeader_Leader @@ -909,183 +943,357 @@ === RUN TestErrUnknownLeader_Error --- PASS: TestErrUnknownLeader_Error (0.00s) === RUN TestHandleChangeRequests_InvalidChangeRequestKind ---- PASS: TestHandleChangeRequests_InvalidChangeRequestKind (0.03s) - logger.go:44: 05:31:34.954893 [DEBUG] raft-test: setup: start (1 servers) - logger.go:44: 05:31:34.955517 [DEBUG] raft-test: setup: server 0: bootstrap - logger.go:44: 05:31:34.955739 [DEBUG] raft-test: setup: server 0: start - logger.go:44: 05:31:34.956054 [INFO] raft: Initial configuration (index=1): [{Suffrage:Voter ID:0 Address:0}] - logger.go:44: 05:31:34.956135 [DEBUG] raft-test: setup: done - logger.go:44: 05:31:34.956181 [DEBUG] raft-test: elect: start (server 0) - logger.go:44: 05:31:34.956222 [DEBUG] raft-test: server 0: establish outbound connection to all other nodes - logger.go:44: 05:31:34.956241 [INFO] raft: Node at 0 [Follower] entering Follower state (Leader: "") - logger.go:44: 05:31:34.956273 [DEBUG] raft-test: elect: server 0: wait to become leader within 1.5s - logger.go:44: 05:31:34.986060 [WARN] raft: Heartbeat timeout from "" reached, starting election - logger.go:44: 05:31:34.986189 [INFO] raft: Node at 0 [Candidate] entering Candidate state in term 2 - logger.go:44: 05:31:34.986258 [DEBUG] raft: Votes needed: 1 - logger.go:44: 05:31:34.986322 [DEBUG] raft: Vote granted from 0 in term 2. Tally: 1 - logger.go:44: 05:31:34.986352 [INFO] raft: Election won. Tally: 1 - logger.go:44: 05:31:34.986391 [INFO] raft: Node at 0 [Leader] entering Leader state - logger.go:44: 05:31:34.986525 [DEBUG] raft-test: server 0: leadership: acquired - logger.go:44: 05:31:34.986628 [DEBUG] raft-test: elect: server 0: wait for other servers to become followers within 40ms - logger.go:44: 05:31:34.986706 [DEBUG] raft-test: elect: done - logger.go:44: 05:31:34.986750 [DEBUG] raft-test: close: start - logger.go:44: 05:31:34.987554 [DEBUG] raft-test: close: server 0: shutdown done - logger.go:44: 05:31:34.987622 [DEBUG] raft-test: server 0: leadership: stop watching - logger.go:44: 05:31:34.987667 [DEBUG] raft-test: close: done +--- PASS: TestHandleChangeRequests_InvalidChangeRequestKind (0.05s) + logger.go:44: 05:38:52.108866 [DEBUG] raft-test: setup: start (1 servers) + logger.go:44: 05:38:52.125450 [DEBUG] raft-test: setup: server 0: bootstrap + logger.go:44: 05:38:52.125660 [DEBUG] raft-test: setup: server 0: start + logger.go:44: 05:38:52.126131 [INFO] raft: Initial configuration (index=1): [{Suffrage:Voter ID:0 Address:0}] + logger.go:44: 05:38:52.126252 [DEBUG] raft-test: setup: done + logger.go:44: 05:38:52.126297 [DEBUG] raft-test: elect: start (server 0) + logger.go:44: 05:38:52.129119 [DEBUG] raft-test: server 0: establish outbound connection to all other nodes + logger.go:44: 05:38:52.129423 [DEBUG] raft-test: elect: server 0: wait to become leader within 1.5s + logger.go:44: 05:38:52.129466 [INFO] raft: Node at 0 [Follower] entering Follower state (Leader: "") + logger.go:44: 05:38:52.153232 [WARN] raft: Heartbeat timeout from "" reached, starting election + logger.go:44: 05:38:52.153349 [INFO] raft: Node at 0 [Candidate] entering Candidate state in term 2 + logger.go:44: 05:38:52.153420 [DEBUG] raft: Votes needed: 1 + logger.go:44: 05:38:52.153467 [DEBUG] raft: Vote granted from 0 in term 2. Tally: 1 + logger.go:44: 05:38:52.153496 [INFO] raft: Election won. Tally: 1 + logger.go:44: 05:38:52.153541 [INFO] raft: Node at 0 [Leader] entering Leader state + logger.go:44: 05:38:52.153711 [DEBUG] raft-test: server 0: leadership: acquired + logger.go:44: 05:38:52.153817 [DEBUG] raft-test: elect: server 0: wait for other servers to become followers within 40ms + logger.go:44: 05:38:52.153957 [DEBUG] raft-test: elect: done + logger.go:44: 05:38:52.154001 [DEBUG] raft-test: close: start + logger.go:44: 05:38:52.154162 [DEBUG] raft-test: close: server 0: shutdown done + logger.go:44: 05:38:52.154216 [DEBUG] raft-test: server 0: leadership: stop watching + logger.go:44: 05:38:52.154295 [DEBUG] raft-test: close: done === RUN TestHandleChangeRequests_ErrUnknownLeader --- PASS: TestHandleChangeRequests_ErrUnknownLeader (0.00s) - logger.go:44: 05:31:34.987841 [DEBUG] raft-test: setup: start (3 servers) - logger.go:44: 05:31:34.988076 [DEBUG] raft-test: setup: server 0: bootstrap - logger.go:44: 05:31:34.988238 [DEBUG] raft-test: setup: server 1: bootstrap - logger.go:44: 05:31:34.988324 [DEBUG] raft-test: setup: server 2: bootstrap - logger.go:44: 05:31:34.988395 [DEBUG] raft-test: setup: server 0: start - logger.go:44: 05:31:34.988558 [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:31:34.988625 [DEBUG] raft-test: setup: server 1: start - logger.go:44: 05:31:34.988684 [INFO] raft: Node at 0 [Follower] entering Follower state (Leader: "") - logger.go:44: 05:31:34.988867 [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:31:34.988965 [DEBUG] raft-test: setup: server 2: start - logger.go:44: 05:31:34.989026 [INFO] raft: Node at 1 [Follower] entering Follower state (Leader: "") - logger.go:44: 05:31:34.989077 [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:31:34.989245 [DEBUG] raft-test: setup: done - logger.go:44: 05:31:34.989293 [INFO] raft: Node at 2 [Follower] entering Follower state (Leader: "") - logger.go:44: 05:31:34.989300 [DEBUG] raft-test: close: start - logger.go:44: 05:31:34.989442 [DEBUG] raft-test: close: server 0: shutdown done - logger.go:44: 05:31:34.989524 [DEBUG] raft-test: close: server 1: shutdown done - logger.go:44: 05:31:34.989622 [DEBUG] raft-test: close: server 2: shutdown done - logger.go:44: 05:31:34.989666 [DEBUG] raft-test: server 0: leadership: stop watching - logger.go:44: 05:31:34.989764 [DEBUG] raft-test: server 1: leadership: stop watching - logger.go:44: 05:31:34.989835 [DEBUG] raft-test: server 2: leadership: stop watching - logger.go:44: 05:31:34.989898 [DEBUG] raft-test: close: done + logger.go:44: 05:38:52.154491 [DEBUG] raft-test: setup: start (3 servers) + logger.go:44: 05:38:52.154719 [DEBUG] raft-test: setup: server 0: bootstrap + logger.go:44: 05:38:52.154855 [DEBUG] raft-test: setup: server 1: bootstrap + logger.go:44: 05:38:52.154930 [DEBUG] raft-test: setup: server 2: bootstrap + logger.go:44: 05:38:52.155004 [DEBUG] raft-test: setup: server 0: start + logger.go:44: 05:38:52.155159 [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:38:52.155228 [DEBUG] raft-test: setup: server 1: start + logger.go:44: 05:38:52.155361 [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:38:52.155416 [DEBUG] raft-test: setup: server 2: start + logger.go:44: 05:38:52.155538 [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:38:52.155589 [DEBUG] raft-test: setup: done + logger.go:44: 05:38:52.155636 [DEBUG] raft-test: close: start + logger.go:44: 05:38:52.155769 [DEBUG] raft-test: close: server 0: shutdown done + logger.go:44: 05:38:52.155905 [DEBUG] raft-test: close: server 1: shutdown done + logger.go:44: 05:38:52.156006 [DEBUG] raft-test: close: server 2: shutdown done + logger.go:44: 05:38:52.156050 [DEBUG] raft-test: server 0: leadership: stop watching + logger.go:44: 05:38:52.156122 [DEBUG] raft-test: server 1: leadership: stop watching + logger.go:44: 05:38:52.156181 [DEBUG] raft-test: server 2: leadership: stop watching + logger.go:44: 05:38:52.156230 [DEBUG] raft-test: close: done === RUN TestHandleChangeRequests_ErrDifferentLeader ---- PASS: TestHandleChangeRequests_ErrDifferentLeader (0.04s) - logger.go:44: 05:31:34.990055 [DEBUG] raft-test: setup: start (2 servers) - logger.go:44: 05:31:34.990207 [DEBUG] raft-test: setup: server 0: bootstrap - logger.go:44: 05:31:34.990292 [DEBUG] raft-test: setup: server 1: bootstrap - logger.go:44: 05:31:34.990365 [DEBUG] raft-test: setup: server 0: start - logger.go:44: 05:31:34.990478 [INFO] raft: Initial configuration (index=1): [{Suffrage:Voter ID:0 Address:0} {Suffrage:Voter ID:1 Address:1}] - logger.go:44: 05:31:34.990537 [DEBUG] raft-test: setup: server 1: start - logger.go:44: 05:31:34.990586 [INFO] raft: Node at 0 [Follower] entering Follower state (Leader: "") - logger.go:44: 05:31:34.990634 [INFO] raft: Initial configuration (index=1): [{Suffrage:Voter ID:0 Address:0} {Suffrage:Voter ID:1 Address:1}] - logger.go:44: 05:31:34.990694 [DEBUG] raft-test: setup: done - logger.go:44: 05:31:34.990735 [DEBUG] raft-test: elect: start (server 0) - logger.go:44: 05:31:34.990773 [DEBUG] raft-test: server 0: establish outbound connection to all other nodes - logger.go:44: 05:31:34.990797 [INFO] raft: Node at 1 [Follower] entering Follower state (Leader: "") - logger.go:44: 05:31:34.990819 [DEBUG] raft-test: elect: server 0: wait to become leader within 1.5s - logger.go:44: 05:31:35.008951 [WARN] raft: Heartbeat timeout from "" reached, starting election - logger.go:44: 05:31:35.009013 [INFO] raft: Node at 1 [Candidate] entering Candidate state in term 2 - logger.go:44: 05:31:35.009097 [DEBUG] raft: Votes needed: 2 - logger.go:44: 05:31:35.009137 [DEBUG] raft: Vote granted from 1 in term 2. Tally: 1 - logger.go:44: 05:31:35.009196 [ERR] raft: Failed to make RequestVote RPC to {Voter 0 0}: connectivity to server 0 is down - logger.go:44: 05:31:35.012455 [WARN] raft: Heartbeat timeout from "" reached, starting election - logger.go:44: 05:31:35.012509 [INFO] raft: Node at 0 [Candidate] entering Candidate state in term 2 - logger.go:44: 05:31:35.012568 [DEBUG] raft: Votes needed: 2 - logger.go:44: 05:31:35.012606 [DEBUG] raft: Vote granted from 0 in term 2. Tally: 1 - logger.go:44: 05:31:35.012686 [INFO] raft: Duplicate RequestVote for same term: 2 - logger.go:44: 05:31:35.029897 [WARN] raft: Election timeout reached, restarting election - logger.go:44: 05:31:35.029944 [INFO] raft: Node at 0 [Candidate] entering Candidate state in term 3 - logger.go:44: 05:31:35.030025 [DEBUG] raft: Votes needed: 2 - logger.go:44: 05:31:35.030068 [DEBUG] raft: Vote granted from 0 in term 3. Tally: 1 - logger.go:44: 05:31:35.030122 [INFO] raft: Node at 1 [Follower] entering Follower state (Leader: "") - logger.go:44: 05:31:35.030192 [DEBUG] raft: Vote granted from 1 in term 3. Tally: 2 - logger.go:44: 05:31:35.030223 [INFO] raft: Election won. Tally: 2 - logger.go:44: 05:31:35.030260 [INFO] raft: Node at 0 [Leader] entering Leader state - logger.go:44: 05:31:35.030312 [INFO] raft: Added peer 1, starting replication - logger.go:44: 05:31:35.030381 [DEBUG] raft-test: server 0: leadership: acquired - logger.go:44: 05:31:35.030459 [DEBUG] raft-test: elect: server 0: wait for other servers to become followers within 40ms - logger.go:44: 05:31:35.030494 [DEBUG] raft-test: server 0: transport: append to 1: 1 entry [Noop:term=3,index=2] - logger.go:44: 05:31:35.030681 [INFO] raft: pipelining replication to peer {Voter 1 1} - logger.go:44: 05:31:35.031638 [DEBUG] raft-test: elect: server 1: became follower - logger.go:44: 05:31:35.031673 [DEBUG] raft-test: elect: done - logger.go:44: 05:31:35.031720 [DEBUG] raft-test: close: start - logger.go:44: 05:31:35.031813 [INFO] raft: aborting pipeline replication to peer {Voter 1 1} - logger.go:44: 05:31:35.031894 [DEBUG] raft-test: close: server 0: shutdown done - logger.go:44: 05:31:35.031978 [DEBUG] raft-test: close: server 1: shutdown done - logger.go:44: 05:31:35.032023 [DEBUG] raft-test: server 0: leadership: stop watching - logger.go:44: 05:31:35.032072 [DEBUG] raft-test: server 1: leadership: stop watching - logger.go:44: 05:31:35.032137 [DEBUG] raft-test: close: done +--- PASS: TestHandleChangeRequests_ErrDifferentLeader (0.27s) + logger.go:44: 05:38:52.156403 [DEBUG] raft-test: setup: start (2 servers) + logger.go:44: 05:38:52.156552 [DEBUG] raft-test: setup: server 0: bootstrap + logger.go:44: 05:38:52.156666 [DEBUG] raft-test: setup: server 1: bootstrap + logger.go:44: 05:38:52.156731 [DEBUG] raft-test: setup: server 0: start + logger.go:44: 05:38:52.156869 [INFO] raft: Initial configuration (index=1): [{Suffrage:Voter ID:0 Address:0} {Suffrage:Voter ID:1 Address:1}] + logger.go:44: 05:38:52.161110 [DEBUG] raft-test: setup: server 1: start + logger.go:44: 05:38:52.161272 [INFO] raft: Initial configuration (index=1): [{Suffrage:Voter ID:0 Address:0} {Suffrage:Voter ID:1 Address:1}] + logger.go:44: 05:38:52.161323 [DEBUG] raft-test: setup: done + logger.go:44: 05:38:52.161363 [DEBUG] raft-test: elect: start (server 0) + logger.go:44: 05:38:52.161427 [DEBUG] raft-test: server 0: establish outbound connection to all other nodes + logger.go:44: 05:38:52.161479 [DEBUG] raft-test: elect: server 0: wait to become leader within 1.5s + logger.go:44: 05:38:52.161607 [INFO] raft: Node at 0 [Follower] entering Follower state (Leader: "") + logger.go:44: 05:38:52.161826 [INFO] raft: Node at 1 [Follower] entering Follower state (Leader: "") + logger.go:44: 05:38:52.181203 [WARN] raft: Heartbeat timeout from "" reached, starting election + logger.go:44: 05:38:52.181493 [INFO] raft: Node at 1 [Candidate] entering Candidate state in term 2 + logger.go:44: 05:38:52.181586 [DEBUG] raft: Votes needed: 2 + logger.go:44: 05:38:52.181672 [DEBUG] raft: Vote granted from 1 in term 2. Tally: 1 + logger.go:44: 05:38:52.181746 [ERR] raft: Failed to make RequestVote RPC to {Voter 0 0}: connectivity to server 0 is down + logger.go:44: 05:38:52.189371 [WARN] raft: Heartbeat timeout from "" reached, starting election + logger.go:44: 05:38:52.189759 [INFO] raft: Node at 0 [Candidate] entering Candidate state in term 2 + logger.go:44: 05:38:52.190016 [DEBUG] raft: Votes needed: 2 + logger.go:44: 05:38:52.190158 [DEBUG] raft: Vote granted from 0 in term 2. Tally: 1 + logger.go:44: 05:38:52.190393 [INFO] raft: Duplicate RequestVote for same term: 2 + logger.go:44: 05:38:52.201058 [WARN] raft: Election timeout reached, restarting election + logger.go:44: 05:38:52.201168 [INFO] raft: Node at 1 [Candidate] entering Candidate state in term 3 + logger.go:44: 05:38:52.201336 [DEBUG] raft: Votes needed: 2 + logger.go:44: 05:38:52.201385 [DEBUG] raft: Vote granted from 1 in term 3. Tally: 1 + logger.go:44: 05:38:52.201451 [ERR] raft: Failed to make RequestVote RPC to {Voter 0 0}: connectivity to server 0 is down + logger.go:44: 05:38:52.217053 [WARN] raft: Election timeout reached, restarting election + logger.go:44: 05:38:52.217178 [INFO] raft: Node at 0 [Candidate] entering Candidate state in term 3 + logger.go:44: 05:38:52.217283 [DEBUG] raft: Votes needed: 2 + logger.go:44: 05:38:52.217335 [DEBUG] raft: Vote granted from 0 in term 3. Tally: 1 + logger.go:44: 05:38:52.217447 [INFO] raft: Duplicate RequestVote for same term: 3 + logger.go:44: 05:38:52.233060 [WARN] raft: Election timeout reached, restarting election + logger.go:44: 05:38:52.233307 [INFO] raft: Node at 1 [Candidate] entering Candidate state in term 4 + logger.go:44: 05:38:52.233642 [DEBUG] raft: Votes needed: 2 + logger.go:44: 05:38:52.233783 [DEBUG] raft: Vote granted from 1 in term 4. Tally: 1 + logger.go:44: 05:38:52.234049 [ERR] raft: Failed to make RequestVote RPC to {Voter 0 0}: connectivity to server 0 is down + logger.go:44: 05:38:52.245045 [WARN] raft: Election timeout reached, restarting election + logger.go:44: 05:38:52.245149 [INFO] raft: Node at 0 [Candidate] entering Candidate state in term 4 + logger.go:44: 05:38:52.245227 [DEBUG] raft: Votes needed: 2 + logger.go:44: 05:38:52.245273 [DEBUG] raft: Vote granted from 0 in term 4. Tally: 1 + logger.go:44: 05:38:52.245360 [INFO] raft: Duplicate RequestVote for same term: 4 + logger.go:44: 05:38:52.251301 [WARN] raft: Election timeout reached, restarting election + logger.go:44: 05:38:52.251399 [INFO] raft: Node at 1 [Candidate] entering Candidate state in term 5 + logger.go:44: 05:38:52.251553 [DEBUG] raft: Votes needed: 2 + logger.go:44: 05:38:52.251601 [DEBUG] raft: Vote granted from 1 in term 5. Tally: 1 + logger.go:44: 05:38:52.253104 [ERR] raft: Failed to make RequestVote RPC to {Voter 0 0}: connectivity to server 0 is down + logger.go:44: 05:38:52.273152 [WARN] raft: Election timeout reached, restarting election + logger.go:44: 05:38:52.273348 [INFO] raft: Node at 0 [Candidate] entering Candidate state in term 5 + logger.go:44: 05:38:52.273525 [DEBUG] raft: Votes needed: 2 + logger.go:44: 05:38:52.273632 [DEBUG] raft: Vote granted from 0 in term 5. Tally: 1 + logger.go:44: 05:38:52.277122 [WARN] raft: Election timeout reached, restarting election + logger.go:44: 05:38:52.277481 [INFO] raft: Node at 1 [Candidate] entering Candidate state in term 6 + logger.go:44: 05:38:52.277754 [DEBUG] raft: Votes needed: 2 + logger.go:44: 05:38:52.277862 [DEBUG] raft: Vote granted from 1 in term 6. Tally: 1 + logger.go:44: 05:38:52.277932 [DEBUG] raft: Newer term discovered, fallback to follower + logger.go:44: 05:38:52.277980 [INFO] raft: Node at 0 [Follower] entering Follower state (Leader: "") + logger.go:44: 05:38:52.278054 [ERR] raft: Failed to make RequestVote RPC to {Voter 0 0}: connectivity to server 0 is down + logger.go:44: 05:38:52.304993 [WARN] raft: Election timeout reached, restarting election + logger.go:44: 05:38:52.305094 [INFO] raft: Node at 1 [Candidate] entering Candidate state in term 7 + logger.go:44: 05:38:52.305198 [DEBUG] raft: Votes needed: 2 + logger.go:44: 05:38:52.305243 [DEBUG] raft: Vote granted from 1 in term 7. Tally: 1 + logger.go:44: 05:38:52.305282 [WARN] raft: Heartbeat timeout from "" reached, starting election + logger.go:44: 05:38:52.305448 [INFO] raft: Node at 0 [Candidate] entering Candidate state in term 7 + logger.go:44: 05:38:52.305591 [DEBUG] raft: Votes needed: 2 + logger.go:44: 05:38:52.305691 [DEBUG] raft: Vote granted from 0 in term 7. Tally: 1 + logger.go:44: 05:38:52.309075 [INFO] raft: Duplicate RequestVote for same term: 7 + logger.go:44: 05:38:52.309103 [ERR] raft: Failed to make RequestVote RPC to {Voter 0 0}: connectivity to server 0 is down + logger.go:44: 05:38:52.329055 [WARN] raft: Election timeout reached, restarting election + logger.go:44: 05:38:52.329151 [INFO] raft: Node at 1 [Candidate] entering Candidate state in term 8 + logger.go:44: 05:38:52.329223 [DEBUG] raft: Votes needed: 2 + logger.go:44: 05:38:52.329269 [DEBUG] raft: Vote granted from 1 in term 8. Tally: 1 + logger.go:44: 05:38:52.329331 [ERR] raft: Failed to make RequestVote RPC to {Voter 0 0}: connectivity to server 0 is down + logger.go:44: 05:38:52.337050 [WARN] raft: Election timeout reached, restarting election + logger.go:44: 05:38:52.337153 [INFO] raft: Node at 0 [Candidate] entering Candidate state in term 8 + logger.go:44: 05:38:52.337233 [DEBUG] raft: Votes needed: 2 + logger.go:44: 05:38:52.337281 [DEBUG] raft: Vote granted from 0 in term 8. Tally: 1 + logger.go:44: 05:38:52.337374 [INFO] raft: Duplicate RequestVote for same term: 8 + logger.go:44: 05:38:52.364352 [WARN] raft: Election timeout reached, restarting election + logger.go:44: 05:38:52.364450 [INFO] raft: Node at 0 [Candidate] entering Candidate state in term 9 + logger.go:44: 05:38:52.364541 [DEBUG] raft: Votes needed: 2 + logger.go:44: 05:38:52.364591 [DEBUG] raft: Vote granted from 0 in term 9. Tally: 1 + logger.go:44: 05:38:52.364683 [WARN] raft: Election timeout reached, restarting election + logger.go:44: 05:38:52.364725 [INFO] raft: Node at 1 [Candidate] entering Candidate state in term 9 + logger.go:44: 05:38:52.364783 [DEBUG] raft: Votes needed: 2 + logger.go:44: 05:38:52.364833 [INFO] raft: Duplicate RequestVote for same term: 9 + logger.go:44: 05:38:52.364949 [DEBUG] raft: Vote granted from 1 in term 9. Tally: 1 + logger.go:44: 05:38:52.365098 [ERR] raft: Failed to make RequestVote RPC to {Voter 0 0}: connectivity to server 0 is down + logger.go:44: 05:38:52.389025 [WARN] raft: Election timeout reached, restarting election + logger.go:44: 05:38:52.389148 [INFO] raft: Node at 0 [Candidate] entering Candidate state in term 10 + logger.go:44: 05:38:52.389250 [DEBUG] raft: Votes needed: 2 + logger.go:44: 05:38:52.389298 [DEBUG] raft: Vote granted from 0 in term 10. Tally: 1 + logger.go:44: 05:38:52.393196 [WARN] raft: Election timeout reached, restarting election + logger.go:44: 05:38:52.393312 [INFO] raft: Node at 1 [Candidate] entering Candidate state in term 10 + logger.go:44: 05:38:52.393463 [DEBUG] raft: Votes needed: 2 + logger.go:44: 05:38:52.393511 [DEBUG] raft: Vote granted from 1 in term 10. Tally: 1 + logger.go:44: 05:38:52.393565 [INFO] raft: Duplicate RequestVote for same term: 10 + logger.go:44: 05:38:52.393673 [ERR] raft: Failed to make RequestVote RPC to {Voter 0 0}: connectivity to server 0 is down + logger.go:44: 05:38:52.421041 [WARN] raft: Election timeout reached, restarting election + logger.go:44: 05:38:52.421148 [INFO] raft: Node at 0 [Candidate] entering Candidate state in term 11 + logger.go:44: 05:38:52.421227 [DEBUG] raft: Votes needed: 2 + logger.go:44: 05:38:52.421275 [DEBUG] raft: Vote granted from 0 in term 11. Tally: 1 + logger.go:44: 05:38:52.421480 [INFO] raft: Node at 1 [Follower] entering Follower state (Leader: "") + logger.go:44: 05:38:52.421548 [DEBUG] raft: Vote granted from 1 in term 11. Tally: 2 + logger.go:44: 05:38:52.421591 [INFO] raft: Election won. Tally: 2 + logger.go:44: 05:38:52.421628 [INFO] raft: Node at 0 [Leader] entering Leader state + logger.go:44: 05:38:52.421671 [INFO] raft: Added peer 1, starting replication + logger.go:44: 05:38:52.421877 [DEBUG] raft-test: server 0: transport: append to 1: 1 entry [Noop:term=11,index=2] + logger.go:44: 05:38:52.422032 [INFO] raft: pipelining replication to peer {Voter 1 1} + logger.go:44: 05:38:52.422113 [DEBUG] raft-test: server 0: leadership: acquired + logger.go:44: 05:38:52.422196 [DEBUG] raft-test: elect: server 0: wait for other servers to become followers within 40ms + logger.go:44: 05:38:52.422306 [DEBUG] raft-test: elect: server 1: became follower + logger.go:44: 05:38:52.422336 [DEBUG] raft-test: elect: done + logger.go:44: 05:38:52.422377 [DEBUG] raft-test: close: start + logger.go:44: 05:38:52.422505 [INFO] raft: aborting pipeline replication to peer {Voter 1 1} + logger.go:44: 05:38:52.422620 [DEBUG] raft-test: close: server 0: shutdown done + logger.go:44: 05:38:52.422729 [DEBUG] raft-test: close: server 1: shutdown done + logger.go:44: 05:38:52.422770 [DEBUG] raft-test: server 0: leadership: stop watching + logger.go:44: 05:38:52.422807 [DEBUG] raft-test: server 1: leadership: stop watching + logger.go:44: 05:38:52.422857 [DEBUG] raft-test: close: done === RUN TestHandleChangeRequests_KnownPeer ---- PASS: TestHandleChangeRequests_KnownPeer (0.02s) - logger.go:44: 05:31:35.032318 [DEBUG] raft-test: setup: start (1 servers) - logger.go:44: 05:31:35.032437 [DEBUG] raft-test: setup: server 0: bootstrap - logger.go:44: 05:31:35.032513 [DEBUG] raft-test: setup: server 0: start - logger.go:44: 05:31:35.032623 [INFO] raft: Initial configuration (index=1): [{Suffrage:Voter ID:0 Address:0}] - logger.go:44: 05:31:35.032708 [DEBUG] raft-test: setup: done - logger.go:44: 05:31:35.032752 [DEBUG] raft-test: elect: start (server 0) - logger.go:44: 05:31:35.032792 [DEBUG] raft-test: server 0: establish outbound connection to all other nodes - logger.go:44: 05:31:35.032835 [DEBUG] raft-test: elect: server 0: wait to become leader within 1.5s - logger.go:44: 05:31:35.032767 [INFO] raft: Node at 0 [Follower] entering Follower state (Leader: "") - logger.go:44: 05:31:35.054029 [WARN] raft: Heartbeat timeout from "" reached, starting election - logger.go:44: 05:31:35.054083 [INFO] raft: Node at 0 [Candidate] entering Candidate state in term 2 - logger.go:44: 05:31:35.054138 [DEBUG] raft: Votes needed: 1 - logger.go:44: 05:31:35.054178 [DEBUG] raft: Vote granted from 0 in term 2. Tally: 1 - logger.go:44: 05:31:35.054206 [INFO] raft: Election won. Tally: 1 - logger.go:44: 05:31:35.054243 [INFO] raft: Node at 0 [Leader] entering Leader state - logger.go:44: 05:31:35.054350 [DEBUG] raft-test: server 0: leadership: acquired - logger.go:44: 05:31:35.054433 [DEBUG] raft-test: elect: server 0: wait for other servers to become followers within 40ms - logger.go:44: 05:31:35.054506 [DEBUG] raft-test: elect: done - logger.go:44: 05:31:35.054599 [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:31:35.055329 [DEBUG] raft-test: close: start - logger.go:44: 05:31:35.055432 [DEBUG] raft-test: close: server 0: shutdown done - logger.go:44: 05:31:35.055490 [DEBUG] raft-test: server 0: leadership: stop watching - logger.go:44: 05:31:35.055561 [DEBUG] raft-test: close: done +--- PASS: TestHandleChangeRequests_KnownPeer (0.03s) + logger.go:44: 05:38:52.423088 [DEBUG] raft-test: setup: start (1 servers) + logger.go:44: 05:38:52.423227 [DEBUG] raft-test: setup: server 0: bootstrap + logger.go:44: 05:38:52.423350 [DEBUG] raft-test: setup: server 0: start + logger.go:44: 05:38:52.423554 [INFO] raft: Initial configuration (index=1): [{Suffrage:Voter ID:0 Address:0}] + logger.go:44: 05:38:52.423628 [DEBUG] raft-test: setup: done + logger.go:44: 05:38:52.423667 [DEBUG] raft-test: elect: start (server 0) + logger.go:44: 05:38:52.423731 [DEBUG] raft-test: server 0: establish outbound connection to all other nodes + logger.go:44: 05:38:52.423794 [DEBUG] raft-test: elect: server 0: wait to become leader within 1.5s + logger.go:44: 05:38:52.423913 [INFO] raft: Node at 0 [Follower] entering Follower state (Leader: "") + logger.go:44: 05:38:52.445466 [WARN] raft: Heartbeat timeout from "" reached, starting election + logger.go:44: 05:38:52.445566 [INFO] raft: Node at 0 [Candidate] entering Candidate state in term 2 + logger.go:44: 05:38:52.445698 [DEBUG] raft: Votes needed: 1 + logger.go:44: 05:38:52.445747 [DEBUG] raft: Vote granted from 0 in term 2. Tally: 1 + logger.go:44: 05:38:52.445775 [INFO] raft: Election won. Tally: 1 + logger.go:44: 05:38:52.445816 [INFO] raft: Node at 0 [Leader] entering Leader state + logger.go:44: 05:38:52.445985 [DEBUG] raft-test: server 0: leadership: acquired + logger.go:44: 05:38:52.446076 [DEBUG] raft-test: elect: server 0: wait for other servers to become followers within 40ms + logger.go:44: 05:38:52.446148 [DEBUG] raft-test: elect: done + logger.go:44: 05:38:52.446405 [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:38:52.446594 [DEBUG] raft-test: close: start + logger.go:44: 05:38:52.453259 [DEBUG] raft-test: close: server 0: shutdown done + logger.go:44: 05:38:52.453482 [DEBUG] raft-test: server 0: leadership: stop watching + logger.go:44: 05:38:52.453643 [DEBUG] raft-test: close: done === RUN TestHandleChangeRequests_LeaveRequest ---- PASS: TestHandleChangeRequests_LeaveRequest (0.02s) - logger.go:44: 05:31:35.055728 [DEBUG] raft-test: setup: start (3 servers) - logger.go:44: 05:31:35.055923 [DEBUG] raft-test: setup: server 0: bootstrap - logger.go:44: 05:31:35.056022 [DEBUG] raft-test: setup: server 1: bootstrap - logger.go:44: 05:31:35.056102 [DEBUG] raft-test: setup: server 2: bootstrap - logger.go:44: 05:31:35.056172 [DEBUG] raft-test: setup: server 0: start - logger.go:44: 05:31:35.056321 [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:31:35.056379 [DEBUG] raft-test: setup: server 1: start - logger.go:44: 05:31:35.056429 [INFO] raft: Node at 0 [Follower] entering Follower state (Leader: "") - logger.go:44: 05:31:35.056494 [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:31:35.056550 [DEBUG] raft-test: setup: server 2: start - logger.go:44: 05:31:35.056596 [INFO] raft: Node at 1 [Follower] entering Follower state (Leader: "") - logger.go:44: 05:31:35.056652 [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:31:35.056709 [DEBUG] raft-test: setup: done - logger.go:44: 05:31:35.056750 [DEBUG] raft-test: elect: start (server 0) - logger.go:44: 05:31:35.056789 [DEBUG] raft-test: server 0: establish outbound connection to all other nodes - logger.go:44: 05:31:35.056840 [DEBUG] raft-test: elect: server 0: wait to become leader within 1.5s - logger.go:44: 05:31:35.056761 [INFO] raft: Node at 2 [Follower] entering Follower state (Leader: "") - logger.go:44: 05:31:35.073050 [WARN] raft: Heartbeat timeout from "" reached, starting election - logger.go:44: 05:31:35.073121 [INFO] raft: Node at 0 [Candidate] entering Candidate state in term 2 - logger.go:44: 05:31:35.073193 [DEBUG] raft: Votes needed: 2 - logger.go:44: 05:31:35.073235 [DEBUG] raft: Vote granted from 0 in term 2. Tally: 1 - logger.go:44: 05:31:35.073271 [DEBUG] raft: Vote granted from 1 in term 2. Tally: 2 - logger.go:44: 05:31:35.073298 [INFO] raft: Election won. Tally: 2 - logger.go:44: 05:31:35.073337 [INFO] raft: Node at 0 [Leader] entering Leader state - logger.go:44: 05:31:35.073382 [INFO] raft: Added peer 1, starting replication - logger.go:44: 05:31:35.073429 [INFO] raft: Added peer 2, starting replication - logger.go:44: 05:31:35.073471 [DEBUG] raft-test: server 0: leadership: acquired - logger.go:44: 05:31:35.073549 [DEBUG] raft-test: elect: server 0: wait for other servers to become followers within 40ms - logger.go:44: 05:31:35.073558 [DEBUG] raft-test: server 0: transport: append to 1: 1 entry [Noop:term=2,index=2] - logger.go:44: 05:31:35.073572 [DEBUG] raft-test: server 0: transport: append to 2: 1 entry [Noop:term=2,index=2] - logger.go:44: 05:31:35.073746 [INFO] raft: pipelining replication to peer {Voter 1 1} - logger.go:44: 05:31:35.073843 [INFO] raft: pipelining replication to peer {Voter 2 2} - logger.go:44: 05:31:35.074718 [DEBUG] raft-test: elect: server 1: became follower - logger.go:44: 05:31:35.074758 [DEBUG] raft-test: elect: server 2: became follower - logger.go:44: 05:31:35.074786 [DEBUG] raft-test: elect: done - logger.go:44: 05:31:35.074874 [INFO] raft: Updating configuration with RemoveServer (2, ) to [{Suffrage:Voter ID:0 Address:0} {Suffrage:Voter ID:1 Address:1}] - logger.go:44: 05:31:35.075005 [DEBUG] raft-test: server 0: pipeline: append to 2: 1 entry [Other:term=2,index=3] - logger.go:44: 05:31:35.075076 [DEBUG] raft-test: server 0: pipeline: append to 1: 1 entry [Other:term=2,index=3] - logger.go:44: 05:31:35.075018 [INFO] raft: Removed peer 2, stopping replication after 3 - logger.go:44: 05:31:35.075207 [DEBUG] raft-test: server 0: pipeline: append to 2: 0 entries - logger.go:44: 05:31:35.075276 [INFO] raft: aborting pipeline replication to peer {Voter 2 2} - logger.go:44: 05:31:35.075285 [DEBUG] raft-test: close: start - logger.go:44: 05:31:35.075415 [INFO] raft: aborting pipeline replication to peer {Voter 1 1} - logger.go:44: 05:31:35.075503 [DEBUG] raft-test: close: server 0: shutdown done - logger.go:44: 05:31:35.075582 [DEBUG] raft-test: close: server 1: shutdown done - logger.go:44: 05:31:35.075668 [DEBUG] raft-test: close: server 2: shutdown done - logger.go:44: 05:31:35.075719 [DEBUG] raft-test: server 0: leadership: stop watching - logger.go:44: 05:31:35.075766 [DEBUG] raft-test: server 1: leadership: stop watching - logger.go:44: 05:31:35.075838 [DEBUG] raft-test: server 2: leadership: stop watching - logger.go:44: 05:31:35.075900 [DEBUG] raft-test: close: done +--- PASS: TestHandleChangeRequests_LeaveRequest (0.17s) + logger.go:44: 05:38:52.454173 [DEBUG] raft-test: setup: start (3 servers) + logger.go:44: 05:38:52.454799 [DEBUG] raft-test: setup: server 0: bootstrap + logger.go:44: 05:38:52.455155 [DEBUG] raft-test: setup: server 1: bootstrap + logger.go:44: 05:38:52.455487 [DEBUG] raft-test: setup: server 2: bootstrap + logger.go:44: 05:38:52.455755 [DEBUG] raft-test: setup: server 0: start + logger.go:44: 05:38:52.456293 [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:38:52.456460 [DEBUG] raft-test: setup: server 1: start + logger.go:44: 05:38:52.456810 [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:38:52.457053 [DEBUG] raft-test: setup: server 2: start + logger.go:44: 05:38:52.457251 [INFO] raft: Node at 0 [Follower] entering Follower state (Leader: "") + logger.go:44: 05:38:52.457374 [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:38:52.457478 [INFO] raft: Node at 1 [Follower] entering Follower state (Leader: "") + logger.go:44: 05:38:52.457488 [DEBUG] raft-test: setup: done + logger.go:44: 05:38:52.457701 [DEBUG] raft-test: elect: start (server 0) + logger.go:44: 05:38:52.457805 [DEBUG] raft-test: server 0: establish outbound connection to all other nodes + logger.go:44: 05:38:52.457924 [DEBUG] raft-test: elect: server 0: wait to become leader within 1.5s + logger.go:44: 05:38:52.457644 [INFO] raft: Node at 2 [Follower] entering Follower state (Leader: "") + logger.go:44: 05:38:52.485136 [WARN] raft: Heartbeat timeout from "" reached, starting election + logger.go:44: 05:38:52.485421 [INFO] raft: Node at 1 [Candidate] entering Candidate state in term 2 + logger.go:44: 05:38:52.485648 [DEBUG] raft: Votes needed: 2 + logger.go:44: 05:38:52.485771 [DEBUG] raft: Vote granted from 1 in term 2. Tally: 1 + logger.go:44: 05:38:52.485905 [ERR] raft: Failed to make RequestVote RPC to {Voter 2 2}: connectivity to server 2 is down + logger.go:44: 05:38:52.485136 [WARN] raft: Heartbeat timeout from "" reached, starting election + logger.go:44: 05:38:52.486332 [INFO] raft: Node at 2 [Candidate] entering Candidate state in term 2 + logger.go:44: 05:38:52.486554 [DEBUG] raft: Votes needed: 2 + logger.go:44: 05:38:52.486666 [DEBUG] raft: Vote granted from 2 in term 2. Tally: 1 + logger.go:44: 05:38:52.486744 [ERR] raft: Failed to make RequestVote RPC to {Voter 0 0}: connectivity to server 0 is down + logger.go:44: 05:38:52.486808 [ERR] raft: Failed to make RequestVote RPC to {Voter 1 1}: connectivity to server 1 is down + logger.go:44: 05:38:52.486678 [ERR] raft: Failed to make RequestVote RPC to {Voter 0 0}: connectivity to server 0 is down + logger.go:44: 05:38:52.489178 [WARN] raft: Heartbeat timeout from "" reached, starting election + logger.go:44: 05:38:52.489421 [INFO] raft: Node at 0 [Candidate] entering Candidate state in term 2 + logger.go:44: 05:38:52.489657 [DEBUG] raft: Votes needed: 2 + logger.go:44: 05:38:52.489755 [DEBUG] raft: Vote granted from 0 in term 2. Tally: 1 + logger.go:44: 05:38:52.489909 [INFO] raft: Duplicate RequestVote for same term: 2 + logger.go:44: 05:38:52.490095 [INFO] raft: Duplicate RequestVote for same term: 2 + logger.go:44: 05:38:52.513280 [WARN] raft: Election timeout reached, restarting election + logger.go:44: 05:38:52.513487 [INFO] raft: Node at 1 [Candidate] entering Candidate state in term 3 + logger.go:44: 05:38:52.513686 [DEBUG] raft: Votes needed: 2 + logger.go:44: 05:38:52.513798 [DEBUG] raft: Vote granted from 1 in term 3. Tally: 1 + logger.go:44: 05:38:52.513996 [ERR] raft: Failed to make RequestVote RPC to {Voter 2 2}: connectivity to server 2 is down + logger.go:44: 05:38:52.514191 [ERR] raft: Failed to make RequestVote RPC to {Voter 0 0}: connectivity to server 0 is down + logger.go:44: 05:38:52.514733 [WARN] raft: Election timeout reached, restarting election + logger.go:44: 05:38:52.514897 [INFO] raft: Node at 2 [Candidate] entering Candidate state in term 3 + logger.go:44: 05:38:52.515075 [DEBUG] raft: Votes needed: 2 + logger.go:44: 05:38:52.515211 [DEBUG] raft: Vote granted from 2 in term 3. Tally: 1 + logger.go:44: 05:38:52.515378 [ERR] raft: Failed to make RequestVote RPC to {Voter 1 1}: connectivity to server 1 is down + logger.go:44: 05:38:52.515565 [ERR] raft: Failed to make RequestVote RPC to {Voter 0 0}: connectivity to server 0 is down + logger.go:44: 05:38:52.517007 [WARN] raft: Election timeout reached, restarting election + logger.go:44: 05:38:52.517118 [INFO] raft: Node at 0 [Candidate] entering Candidate state in term 3 + logger.go:44: 05:38:52.517211 [DEBUG] raft: Votes needed: 2 + logger.go:44: 05:38:52.517289 [DEBUG] raft: Vote granted from 0 in term 3. Tally: 1 + logger.go:44: 05:38:52.521177 [INFO] raft: Duplicate RequestVote for same term: 3 + logger.go:44: 05:38:52.521177 [INFO] raft: Duplicate RequestVote for same term: 3 + logger.go:44: 05:38:52.533273 [WARN] raft: Election timeout reached, restarting election + logger.go:44: 05:38:52.533516 [INFO] raft: Node at 1 [Candidate] entering Candidate state in term 4 + logger.go:44: 05:38:52.533895 [DEBUG] raft: Votes needed: 2 + logger.go:44: 05:38:52.534019 [DEBUG] raft: Vote granted from 1 in term 4. Tally: 1 + logger.go:44: 05:38:52.534155 [ERR] raft: Failed to make RequestVote RPC to {Voter 2 2}: connectivity to server 2 is down + logger.go:44: 05:38:52.534288 [WARN] raft: Election timeout reached, restarting election + logger.go:44: 05:38:52.534381 [INFO] raft: Node at 2 [Candidate] entering Candidate state in term 4 + logger.go:44: 05:38:52.534573 [DEBUG] raft: Votes needed: 2 + logger.go:44: 05:38:52.534680 [DEBUG] raft: Vote granted from 2 in term 4. Tally: 1 + logger.go:44: 05:38:52.534812 [ERR] raft: Failed to make RequestVote RPC to {Voter 1 1}: connectivity to server 1 is down + logger.go:44: 05:38:52.534967 [ERR] raft: Failed to make RequestVote RPC to {Voter 0 0}: connectivity to server 0 is down + logger.go:44: 05:38:52.535200 [ERR] raft: Failed to make RequestVote RPC to {Voter 0 0}: connectivity to server 0 is down + logger.go:44: 05:38:52.545212 [WARN] raft: Election timeout reached, restarting election + logger.go:44: 05:38:52.545475 [INFO] raft: Node at 0 [Candidate] entering Candidate state in term 4 + logger.go:44: 05:38:52.545722 [DEBUG] raft: Votes needed: 2 + logger.go:44: 05:38:52.545858 [DEBUG] raft: Vote granted from 0 in term 4. Tally: 1 + logger.go:44: 05:38:52.546099 [INFO] raft: Duplicate RequestVote for same term: 4 + logger.go:44: 05:38:52.546609 [INFO] raft: Duplicate RequestVote for same term: 4 + logger.go:44: 05:38:52.553237 [WARN] raft: Election timeout reached, restarting election + logger.go:44: 05:38:52.553454 [INFO] raft: Node at 1 [Candidate] entering Candidate state in term 5 + logger.go:44: 05:38:52.553633 [DEBUG] raft: Votes needed: 2 + logger.go:44: 05:38:52.553747 [DEBUG] raft: Vote granted from 1 in term 5. Tally: 1 + logger.go:44: 05:38:52.553888 [ERR] raft: Failed to make RequestVote RPC to {Voter 2 2}: connectivity to server 2 is down + logger.go:44: 05:38:52.554059 [ERR] raft: Failed to make RequestVote RPC to {Voter 0 0}: connectivity to server 0 is down + logger.go:44: 05:38:52.563341 [WARN] raft: Election timeout reached, restarting election + logger.go:44: 05:38:52.563644 [INFO] raft: Node at 2 [Candidate] entering Candidate state in term 5 + logger.go:44: 05:38:52.563844 [DEBUG] raft: Votes needed: 2 + logger.go:44: 05:38:52.563962 [DEBUG] raft: Vote granted from 2 in term 5. Tally: 1 + logger.go:44: 05:38:52.564098 [ERR] raft: Failed to make RequestVote RPC to {Voter 1 1}: connectivity to server 1 is down + logger.go:44: 05:38:52.564269 [ERR] raft: Failed to make RequestVote RPC to {Voter 0 0}: connectivity to server 0 is down + logger.go:44: 05:38:52.573084 [WARN] raft: Election timeout reached, restarting election + logger.go:44: 05:38:52.573280 [INFO] raft: Node at 0 [Candidate] entering Candidate state in term 5 + logger.go:44: 05:38:52.573474 [DEBUG] raft: Votes needed: 2 + logger.go:44: 05:38:52.573570 [DEBUG] raft: Vote granted from 0 in term 5. Tally: 1 + logger.go:44: 05:38:52.573735 [INFO] raft: Duplicate RequestVote for same term: 5 + logger.go:44: 05:38:52.573961 [INFO] raft: Duplicate RequestVote for same term: 5 + logger.go:44: 05:38:52.589056 [WARN] raft: Election timeout reached, restarting election + logger.go:44: 05:38:52.589273 [INFO] raft: Node at 1 [Candidate] entering Candidate state in term 6 + logger.go:44: 05:38:52.589530 [DEBUG] raft: Votes needed: 2 + logger.go:44: 05:38:52.589658 [DEBUG] raft: Vote granted from 1 in term 6. Tally: 1 + logger.go:44: 05:38:52.589802 [ERR] raft: Failed to make RequestVote RPC to {Voter 2 2}: connectivity to server 2 is down + logger.go:44: 05:38:52.589278 [WARN] raft: Election timeout reached, restarting election + logger.go:44: 05:38:52.590023 [INFO] raft: Node at 2 [Candidate] entering Candidate state in term 6 + logger.go:44: 05:38:52.590436 [DEBUG] raft: Votes needed: 2 + logger.go:44: 05:38:52.590560 [DEBUG] raft: Vote granted from 2 in term 6. Tally: 1 + logger.go:44: 05:38:52.590843 [ERR] raft: Failed to make RequestVote RPC to {Voter 1 1}: connectivity to server 1 is down + logger.go:44: 05:38:52.591024 [ERR] raft: Failed to make RequestVote RPC to {Voter 0 0}: connectivity to server 0 is down + logger.go:44: 05:38:52.591175 [ERR] raft: Failed to make RequestVote RPC to {Voter 0 0}: connectivity to server 0 is down + logger.go:44: 05:38:52.593096 [WARN] raft: Election timeout reached, restarting election + logger.go:44: 05:38:52.593425 [INFO] raft: Node at 0 [Candidate] entering Candidate state in term 6 + logger.go:44: 05:38:52.593642 [DEBUG] raft: Votes needed: 2 + logger.go:44: 05:38:52.593787 [DEBUG] raft: Vote granted from 0 in term 6. Tally: 1 + logger.go:44: 05:38:52.594013 [INFO] raft: Duplicate RequestVote for same term: 6 + logger.go:44: 05:38:52.594233 [INFO] raft: Duplicate RequestVote for same term: 6 + logger.go:44: 05:38:52.617015 [WARN] raft: Election timeout reached, restarting election + logger.go:44: 05:38:52.617096 [WARN] raft: Election timeout reached, restarting election + logger.go:44: 05:38:52.617608 [INFO] raft: Node at 0 [Candidate] entering Candidate state in term 7 + logger.go:44: 05:38:52.617845 [DEBUG] raft: Votes needed: 2 + logger.go:44: 05:38:52.618075 [DEBUG] raft: Vote granted from 0 in term 7. Tally: 1 + logger.go:44: 05:38:52.618380 [INFO] raft: Node at 2 [Follower] entering Follower state (Leader: "") + logger.go:44: 05:38:52.618616 [DEBUG] raft: Vote granted from 2 in term 7. Tally: 2 + logger.go:44: 05:38:52.618702 [INFO] raft: Election won. Tally: 2 + logger.go:44: 05:38:52.618892 [INFO] raft: Node at 0 [Leader] entering Leader state + logger.go:44: 05:38:52.619009 [INFO] raft: Added peer 1, starting replication + logger.go:44: 05:38:52.619108 [INFO] raft: Added peer 2, starting replication + logger.go:44: 05:38:52.619450 [DEBUG] raft-test: server 0: transport: append to 2: 1 entry [Noop:term=7,index=2] + logger.go:44: 05:38:52.619779 [INFO] raft: pipelining replication to peer {Voter 2 2} + logger.go:44: 05:38:52.617119 [INFO] raft: Node at 1 [Candidate] entering Candidate state in term 7 + logger.go:44: 05:38:52.620101 [DEBUG] raft: Votes needed: 2 + logger.go:44: 05:38:52.620224 [DEBUG] raft: Vote granted from 1 in term 7. Tally: 1 + logger.go:44: 05:38:52.620376 [ERR] raft: Failed to make RequestVote RPC to {Voter 2 2}: connectivity to server 2 is down + logger.go:44: 05:38:52.620597 [INFO] raft: Duplicate RequestVote for same term: 7 + logger.go:44: 05:38:52.620859 [DEBUG] raft-test: server 0: leadership: acquired + logger.go:44: 05:38:52.621323 [DEBUG] raft-test: server 0: transport: append to 1: 1 entry [Noop:term=7,index=2] + logger.go:44: 05:38:52.621323 [DEBUG] raft-test: elect: server 0: wait for other servers to become followers within 40ms + logger.go:44: 05:38:52.621741 [INFO] raft: pipelining replication to peer {Voter 1 1} + logger.go:44: 05:38:52.621771 [DEBUG] raft-test: elect: server 1: became follower + logger.go:44: 05:38:52.622002 [DEBUG] raft-test: elect: server 2: became follower + logger.go:44: 05:38:52.622067 [DEBUG] raft-test: elect: done + logger.go:44: 05:38:52.622298 [INFO] raft: Updating configuration with RemoveServer (2, ) to [{Suffrage:Voter ID:0 Address:0} {Suffrage:Voter ID:1 Address:1}] + logger.go:44: 05:38:52.622634 [INFO] raft: Removed peer 2, stopping replication after 3 + logger.go:44: 05:38:52.622815 [DEBUG] raft-test: server 0: pipeline: append to 1: 1 entry [Other:term=7,index=3] + logger.go:44: 05:38:52.621613 [INFO] raft: Node at 1 [Follower] entering Follower state (Leader: "0") + logger.go:44: 05:38:52.623558 [DEBUG] raft-test: close: start + logger.go:44: 05:38:52.621113 [ERR] raft: Failed to make RequestVote RPC to {Voter 0 0}: connectivity to server 0 is down + logger.go:44: 05:38:52.623959 [INFO] raft: aborting pipeline replication to peer {Voter 1 1} + logger.go:44: 05:38:52.625093 [DEBUG] raft-test: server 0: transport: append to 2: 0 entries + logger.go:44: 05:38:52.625108 [DEBUG] raft-test: server 0: pipeline: append to 2: 1 entry [Other:term=7,index=3] + logger.go:44: 05:38:52.625745 [DEBUG] raft-test: server 0: pipeline: append to 2: 0 entries + logger.go:44: 05:38:52.625954 [DEBUG] raft-test: server 0: pipeline: append to 2: 0 entries + logger.go:44: 05:38:52.626175 [INFO] raft: aborting pipeline replication to peer {Voter 2 2} + logger.go:44: 05:38:52.626729 [DEBUG] raft-test: close: server 0: shutdown done + logger.go:44: 05:38:52.626968 [DEBUG] raft-test: close: server 2: shutdown done + logger.go:44: 05:38:52.627202 [DEBUG] raft-test: close: server 1: shutdown done + logger.go:44: 05:38:52.627307 [DEBUG] raft-test: server 0: leadership: stop watching + logger.go:44: 05:38:52.627402 [DEBUG] raft-test: server 1: leadership: stop watching + logger.go:44: 05:38:52.627563 [DEBUG] raft-test: server 2: leadership: stop watching + logger.go:44: 05:38:52.627677 [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.140s +ok github.com/CanonicalLtd/raft-membership 0.657s create-stamp debian/debhelper-build-stamp fakeroot debian/rules binary dh binary --buildsystem=golang --with=golang @@ -1113,12 +1321,14 @@ dpkg-source --after-build . dpkg-buildpackage: info: binary-only upload (no source included) I: copying local configuration +I: user script /srv/workspace/pbuilder/15936/tmp/hooks/B01_cleanup starting +I: user script /srv/workspace/pbuilder/15936/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/1598 and its subdirectories -I: Current time: Mon Feb 15 17:31:45 -12 2021 -I: pbuilder-time-stamp: 1613453505 +I: removing directory /srv/workspace/pbuilder/15936 and its subdirectories +I: Current time: Tue Feb 16 19:39:55 +14 2021 +I: pbuilder-time-stamp: 1613453995