Diff of the two buildlogs: -- --- b1/build.log 2021-08-11 14:21:37.887062330 +0000 +++ b2/build.log 2021-08-11 14:24:10.909385780 +0000 @@ -1,6 +1,6 @@ I: pbuilder: network access will be disabled during build -I: Current time: Tue Sep 13 08:42:50 -12 2022 -I: pbuilder-time-stamp: 1663101770 +I: Current time: Thu Aug 12 04:21:40 +14 2021 +I: pbuilder-time-stamp: 1628691700 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/30963/tmp/hooks/D02_print_environment starting +I: user script /srv/workspace/pbuilder/7728/tmp/hooks/D01_modify_environment starting +debug: Running on ionos11-amd64. +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/7728/tmp/hooks/D01_modify_environment finished +I: user script /srv/workspace/pbuilder/7728/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='amd64' - DEBIAN_FRONTEND='noninteractive' - DEB_BUILD_OPTIONS='buildinfo=+all reproducible=+all parallel=16' - DISTRIBUTION='' - HOME='/root' - HOST_ARCH='amd64' + 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]="x86_64-pc-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=amd64 + DEBIAN_FRONTEND=noninteractive + DEB_BUILD_OPTIONS='buildinfo=+all reproducible=+all parallel=15' + DIRSTACK=() + DISTRIBUTION= + EUID=0 + FUNCNAME=([0]="Echo" [1]="main") + GROUPS=() + HOME=/root + HOSTNAME=i-capture-the-hostname + HOSTTYPE=x86_64 + HOST_ARCH=amd64 IFS=' ' - INVOCATION_ID='bc03100c6ffc4001ac0a60810145a3f7' - 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='30963' - PS1='# ' - PS2='> ' + INVOCATION_ID=fe08e53bce694db8ab3d9f51ca6ed559 + LANG=C + LANGUAGE=et_EE:et + LC_ALL=C + MACHTYPE=x86_64-pc-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=7728 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.Qe5C69e4bI/pbuilderrc_xGAG --hookdir /etc/pbuilder/first-build-hooks --debbuildopts -b --basetgz /var/cache/pbuilder/buster-reproducible-base.tgz --buildresult /srv/reproducible-results/rbuild-debian/tmp.Qe5C69e4bI/b1 --logfile b1/build.log golang-github-canonicalltd-raft-membership_0.0~git20180413.3846634-1.dsc' - SUDO_GID='111' - SUDO_UID='106' - SUDO_USER='jenkins' - TERM='unknown' - TZ='/usr/share/zoneinfo/Etc/GMT+12' - USER='root' - _='/usr/bin/systemd-run' - http_proxy='http://85.184.249.68: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.Qe5C69e4bI/pbuilderrc_eNzz --hookdir /etc/pbuilder/rebuild-hooks --debbuildopts -b --basetgz /var/cache/pbuilder/buster-reproducible-base.tgz --buildresult /srv/reproducible-results/rbuild-debian/tmp.Qe5C69e4bI/b2 --logfile b2/build.log golang-github-canonicalltd-raft-membership_0.0~git20180413.3846634-1.dsc' + SUDO_GID=111 + SUDO_UID=106 + SUDO_USER=jenkins + TERM=unknown + TZ=/usr/share/zoneinfo/Etc/GMT-14 + UID=0 + USER=root + _='I: set' + http_proxy=http://78.137.99.97:3128 I: uname -a - Linux ionos15-amd64 5.10.0-0.bpo.8-amd64 #1 SMP Debian 5.10.46-2~bpo10+1 (2021-07-22) x86_64 GNU/Linux + Linux i-capture-the-hostname 4.19.0-17-amd64 #1 SMP Debian 4.19.194-3 (2021-07-18) x86_64 GNU/Linux I: ls -l /bin total 5116 - -rwxr-xr-x 1 root root 1168776 Apr 17 2019 bash - -rwxr-xr-x 3 root root 38984 Jul 10 2019 bunzip2 - -rwxr-xr-x 3 root root 38984 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 38984 Jul 10 2019 bzip2 - -rwxr-xr-x 1 root root 14328 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 43744 Feb 28 2019 cat - -rwxr-xr-x 1 root root 64320 Feb 28 2019 chgrp - -rwxr-xr-x 1 root root 64288 Feb 28 2019 chmod - -rwxr-xr-x 1 root root 72512 Feb 28 2019 chown - -rwxr-xr-x 1 root root 146880 Feb 28 2019 cp - -rwxr-xr-x 1 root root 121464 Jan 17 2019 dash - -rwxr-xr-x 1 root root 109408 Feb 28 2019 date - -rwxr-xr-x 1 root root 76712 Feb 28 2019 dd - -rwxr-xr-x 1 root root 93744 Feb 28 2019 df - -rwxr-xr-x 1 root root 138856 Feb 28 2019 dir - -rwxr-xr-x 1 root root 84288 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 39520 Feb 28 2019 echo - -rwxr-xr-x 1 root root 28 Jan 7 2019 egrep - -rwxr-xr-x 1 root root 35424 Feb 28 2019 false - -rwxr-xr-x 1 root root 28 Jan 7 2019 fgrep - -rwxr-xr-x 1 root root 68880 Jan 9 2019 findmnt - -rwsr-xr-x 1 root root 34896 Apr 22 2020 fusermount - -rwxr-xr-x 1 root root 198976 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 98048 Jan 5 2019 gzip - -rwxr-xr-x 1 root root 26696 Sep 26 2018 hostname - -rwxr-xr-x 1 root root 68552 Feb 28 2019 ln - -rwxr-xr-x 1 root root 56760 Jul 26 2018 login - -rwxr-xr-x 1 root root 138856 Feb 28 2019 ls - -rwxr-xr-x 1 root root 108624 Jan 9 2019 lsblk - -rwxr-xr-x 1 root root 89088 Feb 28 2019 mkdir - -rwxr-xr-x 1 root root 68544 Feb 28 2019 mknod - -rwxr-xr-x 1 root root 43808 Feb 28 2019 mktemp - -rwxr-xr-x 1 root root 43008 Jan 9 2019 more - -rwsr-xr-x 1 root root 51280 Jan 9 2019 mount - -rwxr-xr-x 1 root root 14408 Jan 9 2019 mountpoint - -rwxr-xr-x 1 root root 138728 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 39616 Feb 28 2019 pwd - lrwxrwxrwx 1 root root 4 Apr 17 2019 rbash -> bash - -rwxr-xr-x 1 root root 47776 Feb 28 2019 readlink - -rwxr-xr-x 1 root root 68416 Feb 28 2019 rm - -rwxr-xr-x 1 root root 47776 Feb 28 2019 rmdir - -rwxr-xr-x 1 root root 23312 Jan 21 2019 run-parts - -rwxr-xr-x 1 root root 122224 Dec 22 2018 sed - lrwxrwxrwx 1 root root 4 Sep 9 02:47 sh -> dash - -rwxr-xr-x 1 root root 39552 Feb 28 2019 sleep - -rwxr-xr-x 1 root root 80672 Feb 28 2019 stty - -rwsr-xr-x 1 root root 63568 Jan 9 2019 su - -rwxr-xr-x 1 root root 35488 Feb 28 2019 sync - -rwxr-xr-x 1 root root 445560 Apr 23 2019 tar - -rwxr-xr-x 1 root root 14440 Jan 21 2019 tempfile - -rwxr-xr-x 1 root root 97152 Feb 28 2019 touch - -rwxr-xr-x 1 root root 35424 Feb 28 2019 true - -rwxr-xr-x 1 root root 14328 Apr 22 2020 ulockmgr_server - -rwsr-xr-x 1 root root 34888 Jan 9 2019 umount - -rwxr-xr-x 1 root root 39584 Feb 28 2019 uname - -rwxr-xr-x 2 root root 2345 Jan 5 2019 uncompress - -rwxr-xr-x 1 root root 138856 Feb 28 2019 vdir - -rwxr-xr-x 1 root root 34896 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/30963/tmp/hooks/D02_print_environment finished + -rwxr-xr-x 1 root root 1168776 Apr 18 2019 bash + -rwxr-xr-x 3 root root 38984 Jul 11 2019 bunzip2 + -rwxr-xr-x 3 root root 38984 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 38984 Jul 11 2019 bzip2 + -rwxr-xr-x 1 root root 14328 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 43744 Mar 1 2019 cat + -rwxr-xr-x 1 root root 64320 Mar 1 2019 chgrp + -rwxr-xr-x 1 root root 64288 Mar 1 2019 chmod + -rwxr-xr-x 1 root root 72512 Mar 1 2019 chown + -rwxr-xr-x 1 root root 146880 Mar 1 2019 cp + -rwxr-xr-x 1 root root 121464 Jan 18 2019 dash + -rwxr-xr-x 1 root root 109408 Mar 1 2019 date + -rwxr-xr-x 1 root root 76712 Mar 1 2019 dd + -rwxr-xr-x 1 root root 93744 Mar 1 2019 df + -rwxr-xr-x 1 root root 138856 Mar 1 2019 dir + -rwxr-xr-x 1 root root 84288 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 39520 Mar 1 2019 echo + -rwxr-xr-x 1 root root 28 Jan 8 2019 egrep + -rwxr-xr-x 1 root root 35424 Mar 1 2019 false + -rwxr-xr-x 1 root root 28 Jan 8 2019 fgrep + -rwxr-xr-x 1 root root 68880 Jan 10 2019 findmnt + -rwsr-xr-x 1 root root 34896 Apr 23 2020 fusermount + -rwxr-xr-x 1 root root 198976 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 98048 Jan 6 2019 gzip + -rwxr-xr-x 1 root root 26696 Sep 27 2018 hostname + -rwxr-xr-x 1 root root 68552 Mar 1 2019 ln + -rwxr-xr-x 1 root root 56760 Jul 27 2018 login + -rwxr-xr-x 1 root root 138856 Mar 1 2019 ls + -rwxr-xr-x 1 root root 108624 Jan 10 2019 lsblk + -rwxr-xr-x 1 root root 89088 Mar 1 2019 mkdir + -rwxr-xr-x 1 root root 68544 Mar 1 2019 mknod + -rwxr-xr-x 1 root root 43808 Mar 1 2019 mktemp + -rwxr-xr-x 1 root root 43008 Jan 10 2019 more + -rwsr-xr-x 1 root root 51280 Jan 10 2019 mount + -rwxr-xr-x 1 root root 14408 Jan 10 2019 mountpoint + -rwxr-xr-x 1 root root 138728 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 39616 Mar 1 2019 pwd + lrwxrwxrwx 1 root root 4 Apr 18 2019 rbash -> bash + -rwxr-xr-x 1 root root 47776 Mar 1 2019 readlink + -rwxr-xr-x 1 root root 68416 Mar 1 2019 rm + -rwxr-xr-x 1 root root 47776 Mar 1 2019 rmdir + -rwxr-xr-x 1 root root 23312 Jan 22 2019 run-parts + -rwxr-xr-x 1 root root 122224 Dec 23 2018 sed + lrwxrwxrwx 1 root root 4 Aug 12 04:21 sh -> bash + lrwxrwxrwx 1 root root 4 Aug 7 22:24 sh.distrib -> dash + -rwxr-xr-x 1 root root 39552 Mar 1 2019 sleep + -rwxr-xr-x 1 root root 80672 Mar 1 2019 stty + -rwsr-xr-x 1 root root 63568 Jan 10 2019 su + -rwxr-xr-x 1 root root 35488 Mar 1 2019 sync + -rwxr-xr-x 1 root root 445560 Apr 24 2019 tar + -rwxr-xr-x 1 root root 14440 Jan 22 2019 tempfile + -rwxr-xr-x 1 root root 97152 Mar 1 2019 touch + -rwxr-xr-x 1 root root 35424 Mar 1 2019 true + -rwxr-xr-x 1 root root 14328 Apr 23 2020 ulockmgr_server + -rwsr-xr-x 1 root root 34888 Jan 10 2019 umount + -rwxr-xr-x 1 root root 39584 Mar 1 2019 uname + -rwxr-xr-x 2 root root 2345 Jan 6 2019 uncompress + -rwxr-xr-x 1 root root 138856 Mar 1 2019 vdir + -rwxr-xr-x 1 root root 34896 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/7728/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 amd64 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 amd64 golang-github-hashicorp-raft-dev all 1.0.0+git20180823.82694fb-3 [85.9 kB] Get: 110 http://deb.debian.org/debian buster/main amd64 golang-github-canonicalltd-raft-test-dev all 0.0~git20180628.c3345b5-1 [28.4 kB] -Fetched 90.3 MB in 2s (48.9 MB/s) +Fetched 90.3 MB in 2s (44.9 MB/s) debconf: delaying package configuration, since apt-utils is not installed Selecting previously unselected package libbsd0:amd64. (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 ... 19195 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,52 +824,52 @@ dh_autoreconf -O--buildsystem=golang dh_auto_configure -O--buildsystem=golang dh_auto_build -O--buildsystem=golang - cd obj-x86_64-linux-gnu && go install -gcflags=all=\"-trimpath=/build/golang-github-canonicalltd-raft-membership-0.0\~git20180413.3846634/obj-x86_64-linux-gnu/src\" -asmflags=all=\"-trimpath=/build/golang-github-canonicalltd-raft-membership-0.0\~git20180413.3846634/obj-x86_64-linux-gnu/src\" -v -p 16 github.com/CanonicalLtd/raft-membership + cd obj-x86_64-linux-gnu && go install -gcflags=all=\"-trimpath=/build/golang-github-canonicalltd-raft-membership-0.0\~git20180413.3846634/obj-x86_64-linux-gnu/src\" -asmflags=all=\"-trimpath=/build/golang-github-canonicalltd-raft-membership-0.0\~git20180413.3846634/obj-x86_64-linux-gnu/src\" -v -p 15 github.com/CanonicalLtd/raft-membership errors -internal/race runtime/internal/sys -internal/nettrace -sync/atomic encoding +math/bits unicode/utf8 -crypto/internal/subtle unicode container/list +crypto/internal/subtle crypto/subtle -vendor/golang_org/x/crypto/cryptobyte/asn1 +internal/cpu vendor/golang_org/x/net/dns/dnsmessage +internal/race unicode/utf16 -math/bits -runtime/cgo -internal/cpu +internal/nettrace runtime/internal/atomic +sync/atomic +vendor/golang_org/x/crypto/cryptobyte/asn1 vendor/golang_org/x/crypto/curve25519 -internal/testlog -github.com/hashicorp/golang-lru/simplelru +runtime/cgo internal/bytealg math +internal/testlog +github.com/hashicorp/golang-lru/simplelru runtime strconv crypto/rc4 sync io -reflect syscall -internal/singleflight math/rand +internal/singleflight +reflect bytes crypto/cipher strings hash crypto/internal/randutil +hash/crc32 crypto crypto/hmac -hash/crc32 hash/crc64 crypto/sha512 -crypto/sha1 crypto/md5 crypto/sha256 +crypto/sha1 crypto/aes bufio vendor/golang_org/x/text/transform @@ -843,52 +877,52 @@ html time internal/syscall/unix -internal/poll -encoding/binary sort -os +encoding/binary +internal/poll github.com/hashicorp/go-immutable-radix +os encoding/base64 crypto/des vendor/golang_org/x/crypto/internal/chacha20 vendor/golang_org/x/crypto/poly1305 vendor/golang_org/x/crypto/chacha20poly1305 encoding/pem -fmt path/filepath +fmt os/signal io/ioutil context -encoding/json -log math/big +log compress/flate encoding/hex net/url -vendor/golang_org/x/net/http2/hpack -mime mime/quotedprintable +vendor/golang_org/x/net/http2/hpack net/http/internal vendor/golang_org/x/text/unicode/norm -text/template/parse +encoding/json encoding/gob -vendor/golang_org/x/text/unicode/bidi +mime +text/template/parse net -vendor/golang_org/x/text/secure/bidirule +vendor/golang_org/x/text/unicode/bidi compress/gzip -vendor/golang_org/x/net/idna +vendor/golang_org/x/text/secure/bidirule text/template +vendor/golang_org/x/net/idna crypto/rand crypto/elliptic -encoding/asn1 crypto/dsa -html/template +encoding/asn1 crypto/rsa +html/template +crypto/ecdsa crypto/x509/pkix vendor/golang_org/x/crypto/cryptobyte -crypto/ecdsa -crypto/x509 net/textproto +crypto/x509 vendor/golang_org/x/net/http/httpproxy vendor/golang_org/x/net/http/httpguts mime/multipart @@ -901,7 +935,7 @@ github.com/hashicorp/raft github.com/CanonicalLtd/raft-membership dh_auto_test -O--buildsystem=golang - cd obj-x86_64-linux-gnu && go test -vet=off -v -p 16 github.com/CanonicalLtd/raft-membership + cd obj-x86_64-linux-gnu && go test -vet=off -v -p 15 github.com/CanonicalLtd/raft-membership === RUN TestErrDifferentLeader_Error --- PASS: TestErrDifferentLeader_Error (0.00s) === RUN TestErrDifferentLeader_Leader @@ -910,354 +944,416 @@ --- PASS: TestErrUnknownLeader_Error (0.00s) === RUN TestHandleChangeRequests_InvalidChangeRequestKind --- PASS: TestHandleChangeRequests_InvalidChangeRequestKind (0.03s) - logger.go:44: 20:44:27.470457 [DEBUG] raft-test: setup: start (1 servers) - logger.go:44: 20:44:27.470649 [DEBUG] raft-test: setup: server 0: bootstrap - logger.go:44: 20:44:27.470794 [DEBUG] raft-test: setup: server 0: start - logger.go:44: 20:44:27.470945 [INFO] raft: Initial configuration (index=1): [{Suffrage:Voter ID:0 Address:0}] - logger.go:44: 20:44:27.470993 [DEBUG] raft-test: setup: done - logger.go:44: 20:44:27.471010 [DEBUG] raft-test: elect: start (server 0) - logger.go:44: 20:44:27.473178 [INFO] raft: Node at 0 [Follower] entering Follower state (Leader: "") - logger.go:44: 20:44:27.474584 [DEBUG] raft-test: server 0: establish outbound connection to all other nodes - logger.go:44: 20:44:27.474635 [DEBUG] raft-test: elect: server 0: wait to become leader within 1.5s - logger.go:44: 20:44:27.500451 [WARN] raft: Heartbeat timeout from "" reached, starting election - logger.go:44: 20:44:27.500537 [INFO] raft: Node at 0 [Candidate] entering Candidate state in term 2 - logger.go:44: 20:44:27.500568 [DEBUG] raft: Votes needed: 1 - logger.go:44: 20:44:27.500590 [DEBUG] raft: Vote granted from 0 in term 2. Tally: 1 - logger.go:44: 20:44:27.500603 [INFO] raft: Election won. Tally: 1 - logger.go:44: 20:44:27.500618 [INFO] raft: Node at 0 [Leader] entering Leader state - logger.go:44: 20:44:27.500697 [DEBUG] raft-test: server 0: leadership: acquired - logger.go:44: 20:44:27.500720 [DEBUG] raft-test: elect: server 0: wait for other servers to become followers within 40ms - logger.go:44: 20:44:27.500790 [DEBUG] raft-test: elect: done - logger.go:44: 20:44:27.500809 [DEBUG] raft-test: close: start - logger.go:44: 20:44:27.504507 [DEBUG] raft-test: close: server 0: shutdown done - logger.go:44: 20:44:27.504563 [DEBUG] raft-test: server 0: leadership: stop watching - logger.go:44: 20:44:27.504579 [DEBUG] raft-test: close: done + logger.go:44: 14:24:02.624201 [DEBUG] raft-test: setup: start (1 servers) + logger.go:44: 14:24:02.624353 [DEBUG] raft-test: setup: server 0: bootstrap + logger.go:44: 14:24:02.624459 [DEBUG] raft-test: setup: server 0: start + logger.go:44: 14:24:02.624632 [INFO] raft: Initial configuration (index=1): [{Suffrage:Voter ID:0 Address:0}] + logger.go:44: 14:24:02.624666 [DEBUG] raft-test: setup: done + logger.go:44: 14:24:02.624681 [DEBUG] raft-test: elect: start (server 0) + logger.go:44: 14:24:02.625324 [INFO] raft: Node at 0 [Follower] entering Follower state (Leader: "") + logger.go:44: 14:24:02.629689 [DEBUG] raft-test: server 0: establish outbound connection to all other nodes + logger.go:44: 14:24:02.629813 [DEBUG] raft-test: elect: server 0: wait to become leader within 1.5s + logger.go:44: 14:24:02.645223 [WARN] raft: Heartbeat timeout from "" reached, starting election + logger.go:44: 14:24:02.645309 [INFO] raft: Node at 0 [Candidate] entering Candidate state in term 2 + logger.go:44: 14:24:02.645337 [DEBUG] raft: Votes needed: 1 + logger.go:44: 14:24:02.645356 [DEBUG] raft: Vote granted from 0 in term 2. Tally: 1 + logger.go:44: 14:24:02.645366 [INFO] raft: Election won. Tally: 1 + logger.go:44: 14:24:02.645381 [INFO] raft: Node at 0 [Leader] entering Leader state + logger.go:44: 14:24:02.645447 [DEBUG] raft-test: server 0: leadership: acquired + logger.go:44: 14:24:02.645467 [DEBUG] raft-test: elect: server 0: wait for other servers to become followers within 40ms + logger.go:44: 14:24:02.645498 [DEBUG] raft-test: elect: done + logger.go:44: 14:24:02.645514 [DEBUG] raft-test: close: start + logger.go:44: 14:24:02.649322 [DEBUG] raft-test: close: server 0: shutdown done + logger.go:44: 14:24:02.649368 [DEBUG] raft-test: server 0: leadership: stop watching + logger.go:44: 14:24:02.650091 [DEBUG] raft-test: close: done === RUN TestHandleChangeRequests_ErrUnknownLeader --- PASS: TestHandleChangeRequests_ErrUnknownLeader (0.00s) - logger.go:44: 20:44:27.504688 [DEBUG] raft-test: setup: start (3 servers) - logger.go:44: 20:44:27.504754 [DEBUG] raft-test: setup: server 0: bootstrap - logger.go:44: 20:44:27.504844 [DEBUG] raft-test: setup: server 1: bootstrap - logger.go:44: 20:44:27.504874 [DEBUG] raft-test: setup: server 2: bootstrap - logger.go:44: 20:44:27.504897 [DEBUG] raft-test: setup: server 0: start - logger.go:44: 20:44:27.504993 [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: 20:44:27.505019 [DEBUG] raft-test: setup: server 1: start - logger.go:44: 20:44:27.505054 [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: 20:44:27.505071 [DEBUG] raft-test: setup: server 2: start - logger.go:44: 20:44:27.505112 [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: 20:44:27.505132 [DEBUG] raft-test: setup: done - logger.go:44: 20:44:27.505164 [DEBUG] raft-test: close: start - logger.go:44: 20:44:27.505228 [INFO] raft: Node at 0 [Follower] entering Follower state (Leader: "") - logger.go:44: 20:44:27.505289 [INFO] raft: Node at 1 [Follower] entering Follower state (Leader: "") - logger.go:44: 20:44:27.505340 [DEBUG] raft-test: close: server 2: shutdown done - logger.go:44: 20:44:27.505364 [DEBUG] raft-test: close: server 0: shutdown done - logger.go:44: 20:44:27.505391 [DEBUG] raft-test: close: server 1: shutdown done - logger.go:44: 20:44:27.505403 [DEBUG] raft-test: server 2: leadership: stop watching - logger.go:44: 20:44:27.505420 [DEBUG] raft-test: server 0: leadership: stop watching - logger.go:44: 20:44:27.505440 [DEBUG] raft-test: server 1: leadership: stop watching - logger.go:44: 20:44:27.505448 [DEBUG] raft-test: close: done + logger.go:44: 14:24:02.650215 [DEBUG] raft-test: setup: start (3 servers) + logger.go:44: 14:24:02.650310 [DEBUG] raft-test: setup: server 0: bootstrap + logger.go:44: 14:24:02.650393 [DEBUG] raft-test: setup: server 1: bootstrap + logger.go:44: 14:24:02.650505 [DEBUG] raft-test: setup: server 2: bootstrap + logger.go:44: 14:24:02.650535 [DEBUG] raft-test: setup: server 0: start + logger.go:44: 14:24:02.650616 [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: 14:24:02.650640 [DEBUG] raft-test: setup: server 1: start + logger.go:44: 14:24:02.650682 [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: 14:24:02.650700 [DEBUG] raft-test: setup: server 2: start + logger.go:44: 14:24:02.650738 [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: 14:24:02.650754 [DEBUG] raft-test: setup: done + logger.go:44: 14:24:02.650774 [DEBUG] raft-test: close: start + logger.go:44: 14:24:02.650840 [DEBUG] raft-test: close: server 0: shutdown done + logger.go:44: 14:24:02.650878 [DEBUG] raft-test: close: server 1: shutdown done + logger.go:44: 14:24:02.650903 [DEBUG] raft-test: close: server 2: shutdown done + logger.go:44: 14:24:02.650929 [DEBUG] raft-test: server 0: leadership: stop watching + logger.go:44: 14:24:02.650949 [DEBUG] raft-test: server 1: leadership: stop watching + logger.go:44: 14:24:02.650962 [DEBUG] raft-test: server 2: leadership: stop watching + logger.go:44: 14:24:02.650974 [DEBUG] raft-test: close: done === RUN TestHandleChangeRequests_ErrDifferentLeader ---- PASS: TestHandleChangeRequests_ErrDifferentLeader (0.02s) - logger.go:44: 20:44:27.505492 [DEBUG] raft-test: setup: start (2 servers) - logger.go:44: 20:44:27.505532 [DEBUG] raft-test: setup: server 0: bootstrap - logger.go:44: 20:44:27.505570 [DEBUG] raft-test: setup: server 1: bootstrap - logger.go:44: 20:44:27.505606 [DEBUG] raft-test: setup: server 0: start - logger.go:44: 20:44:27.505641 [INFO] raft: Initial configuration (index=1): [{Suffrage:Voter ID:0 Address:0} {Suffrage:Voter ID:1 Address:1}] - logger.go:44: 20:44:27.505656 [DEBUG] raft-test: setup: server 1: start - logger.go:44: 20:44:27.505687 [INFO] raft: Initial configuration (index=1): [{Suffrage:Voter ID:0 Address:0} {Suffrage:Voter ID:1 Address:1}] - logger.go:44: 20:44:27.505700 [DEBUG] raft-test: setup: done - logger.go:44: 20:44:27.505712 [DEBUG] raft-test: elect: start (server 0) - logger.go:44: 20:44:27.505729 [DEBUG] raft-test: server 0: establish outbound connection to all other nodes - logger.go:44: 20:44:27.505745 [DEBUG] raft-test: elect: server 0: wait to become leader within 1.5s - logger.go:44: 20:44:27.505763 [INFO] raft: Node at 0 [Follower] entering Follower state (Leader: "") - logger.go:44: 20:44:27.505781 [INFO] raft: Node at 1 [Follower] entering Follower state (Leader: "") - logger.go:44: 20:44:27.528370 [WARN] raft: Heartbeat timeout from "" reached, starting election - logger.go:44: 20:44:27.528454 [INFO] raft: Node at 0 [Candidate] entering Candidate state in term 2 - logger.go:44: 20:44:27.528565 [DEBUG] raft: Votes needed: 2 - logger.go:44: 20:44:27.528582 [DEBUG] raft: Vote granted from 0 in term 2. Tally: 1 - logger.go:44: 20:44:27.528652 [DEBUG] raft: Vote granted from 1 in term 2. Tally: 2 - logger.go:44: 20:44:27.528662 [INFO] raft: Election won. Tally: 2 - logger.go:44: 20:44:27.528673 [INFO] raft: Node at 0 [Leader] entering Leader state - logger.go:44: 20:44:27.529469 [INFO] raft: Added peer 1, starting replication - logger.go:44: 20:44:27.529544 [DEBUG] raft-test: server 0: transport: append to 1: 1 entry [Noop:term=2,index=2] - logger.go:44: 20:44:27.529625 [INFO] raft: pipelining replication to peer {Voter 1 1} - logger.go:44: 20:44:27.529660 [DEBUG] raft-test: server 0: leadership: acquired - logger.go:44: 20:44:27.529678 [DEBUG] raft-test: elect: server 0: wait for other servers to become followers within 40ms - logger.go:44: 20:44:27.529730 [DEBUG] raft-test: elect: server 1: became follower - logger.go:44: 20:44:27.529740 [DEBUG] raft-test: elect: done - logger.go:44: 20:44:27.529754 [DEBUG] raft-test: close: start - logger.go:44: 20:44:27.529798 [INFO] raft: aborting pipeline replication to peer {Voter 1 1} - logger.go:44: 20:44:27.529819 [DEBUG] raft-test: close: server 0: shutdown done - logger.go:44: 20:44:27.529849 [DEBUG] raft-test: close: server 1: shutdown done - logger.go:44: 20:44:27.529864 [DEBUG] raft-test: server 0: leadership: stop watching - logger.go:44: 20:44:27.529882 [DEBUG] raft-test: server 1: leadership: stop watching - logger.go:44: 20:44:27.529891 [DEBUG] raft-test: close: done +--- PASS: TestHandleChangeRequests_ErrDifferentLeader (0.38s) + logger.go:44: 14:24:02.651033 [DEBUG] raft-test: setup: start (2 servers) + logger.go:44: 14:24:02.651080 [DEBUG] raft-test: setup: server 0: bootstrap + logger.go:44: 14:24:02.651130 [DEBUG] raft-test: setup: server 1: bootstrap + logger.go:44: 14:24:02.651158 [DEBUG] raft-test: setup: server 0: start + logger.go:44: 14:24:02.651197 [INFO] raft: Initial configuration (index=1): [{Suffrage:Voter ID:0 Address:0} {Suffrage:Voter ID:1 Address:1}] + logger.go:44: 14:24:02.651215 [DEBUG] raft-test: setup: server 1: start + logger.go:44: 14:24:02.651259 [INFO] raft: Initial configuration (index=1): [{Suffrage:Voter ID:0 Address:0} {Suffrage:Voter ID:1 Address:1}] + logger.go:44: 14:24:02.651275 [DEBUG] raft-test: setup: done + logger.go:44: 14:24:02.651291 [DEBUG] raft-test: elect: start (server 0) + logger.go:44: 14:24:02.651507 [DEBUG] raft-test: server 0: establish outbound connection to all other nodes + logger.go:44: 14:24:02.651564 [DEBUG] raft-test: elect: server 0: wait to become leader within 1.5s + logger.go:44: 14:24:02.651606 [INFO] raft: Node at 0 [Follower] entering Follower state (Leader: "") + logger.go:44: 14:24:02.651695 [INFO] raft: Node at 1 [Follower] entering Follower state (Leader: "") + logger.go:44: 14:24:02.675990 [WARN] raft: Heartbeat timeout from "" reached, starting election + logger.go:44: 14:24:02.676061 [INFO] raft: Node at 1 [Candidate] entering Candidate state in term 2 + logger.go:44: 14:24:02.676119 [DEBUG] raft: Votes needed: 2 + logger.go:44: 14:24:02.676139 [DEBUG] raft: Vote granted from 1 in term 2. Tally: 1 + logger.go:44: 14:24:02.676194 [ERR] raft: Failed to make RequestVote RPC to {Voter 0 0}: connectivity to server 0 is down + logger.go:44: 14:24:02.676226 [WARN] raft: Heartbeat timeout from "" reached, starting election + logger.go:44: 14:24:02.676244 [INFO] raft: Node at 0 [Candidate] entering Candidate state in term 2 + logger.go:44: 14:24:02.676280 [DEBUG] raft: Votes needed: 2 + logger.go:44: 14:24:02.676294 [DEBUG] raft: Vote granted from 0 in term 2. Tally: 1 + logger.go:44: 14:24:02.676340 [INFO] raft: Duplicate RequestVote for same term: 2 + logger.go:44: 14:24:02.697237 [WARN] raft: Election timeout reached, restarting election + logger.go:44: 14:24:02.697337 [INFO] raft: Node at 1 [Candidate] entering Candidate state in term 3 + logger.go:44: 14:24:02.697386 [DEBUG] raft: Votes needed: 2 + logger.go:44: 14:24:02.697403 [DEBUG] raft: Vote granted from 1 in term 3. Tally: 1 + logger.go:44: 14:24:02.697450 [ERR] raft: Failed to make RequestVote RPC to {Voter 0 0}: connectivity to server 0 is down + logger.go:44: 14:24:02.697475 [WARN] raft: Election timeout reached, restarting election + logger.go:44: 14:24:02.697490 [INFO] raft: Node at 0 [Candidate] entering Candidate state in term 3 + logger.go:44: 14:24:02.697507 [DEBUG] raft: Votes needed: 2 + logger.go:44: 14:24:02.697520 [DEBUG] raft: Vote granted from 0 in term 3. Tally: 1 + logger.go:44: 14:24:02.697562 [INFO] raft: Duplicate RequestVote for same term: 3 + logger.go:44: 14:24:02.725271 [WARN] raft: Election timeout reached, restarting election + logger.go:44: 14:24:02.725348 [INFO] raft: Node at 1 [Candidate] entering Candidate state in term 4 + logger.go:44: 14:24:02.725399 [DEBUG] raft: Votes needed: 2 + logger.go:44: 14:24:02.725416 [DEBUG] raft: Vote granted from 1 in term 4. Tally: 1 + logger.go:44: 14:24:02.725464 [ERR] raft: Failed to make RequestVote RPC to {Voter 0 0}: connectivity to server 0 is down + logger.go:44: 14:24:02.725274 [WARN] raft: Election timeout reached, restarting election + logger.go:44: 14:24:02.725498 [INFO] raft: Node at 0 [Candidate] entering Candidate state in term 4 + logger.go:44: 14:24:02.725515 [DEBUG] raft: Votes needed: 2 + logger.go:44: 14:24:02.725528 [DEBUG] raft: Vote granted from 0 in term 4. Tally: 1 + logger.go:44: 14:24:02.725572 [INFO] raft: Duplicate RequestVote for same term: 4 + logger.go:44: 14:24:02.744960 [WARN] raft: Election timeout reached, restarting election + logger.go:44: 14:24:02.745023 [INFO] raft: Node at 1 [Candidate] entering Candidate state in term 5 + logger.go:44: 14:24:02.745095 [DEBUG] raft: Votes needed: 2 + logger.go:44: 14:24:02.745113 [DEBUG] raft: Vote granted from 1 in term 5. Tally: 1 + logger.go:44: 14:24:02.745159 [ERR] raft: Failed to make RequestVote RPC to {Voter 0 0}: connectivity to server 0 is down + logger.go:44: 14:24:02.751511 [WARN] raft: Election timeout reached, restarting election + logger.go:44: 14:24:02.751598 [INFO] raft: Node at 0 [Candidate] entering Candidate state in term 5 + logger.go:44: 14:24:02.751635 [DEBUG] raft: Votes needed: 2 + logger.go:44: 14:24:02.751654 [DEBUG] raft: Vote granted from 0 in term 5. Tally: 1 + logger.go:44: 14:24:02.751714 [INFO] raft: Duplicate RequestVote for same term: 5 + logger.go:44: 14:24:02.766037 [WARN] raft: Election timeout reached, restarting election + logger.go:44: 14:24:02.766109 [INFO] raft: Node at 1 [Candidate] entering Candidate state in term 6 + logger.go:44: 14:24:02.766147 [DEBUG] raft: Votes needed: 2 + logger.go:44: 14:24:02.766167 [DEBUG] raft: Vote granted from 1 in term 6. Tally: 1 + logger.go:44: 14:24:02.766218 [ERR] raft: Failed to make RequestVote RPC to {Voter 0 0}: connectivity to server 0 is down + logger.go:44: 14:24:02.781121 [WARN] raft: Election timeout reached, restarting election + logger.go:44: 14:24:02.781190 [INFO] raft: Node at 0 [Candidate] entering Candidate state in term 6 + logger.go:44: 14:24:02.781263 [DEBUG] raft: Votes needed: 2 + logger.go:44: 14:24:02.781282 [DEBUG] raft: Vote granted from 0 in term 6. Tally: 1 + logger.go:44: 14:24:02.781337 [INFO] raft: Duplicate RequestVote for same term: 6 + logger.go:44: 14:24:02.785118 [WARN] raft: Election timeout reached, restarting election + logger.go:44: 14:24:02.785170 [INFO] raft: Node at 1 [Candidate] entering Candidate state in term 7 + logger.go:44: 14:24:02.785214 [DEBUG] raft: Votes needed: 2 + logger.go:44: 14:24:02.785230 [DEBUG] raft: Vote granted from 1 in term 7. Tally: 1 + logger.go:44: 14:24:02.785272 [ERR] raft: Failed to make RequestVote RPC to {Voter 0 0}: connectivity to server 0 is down + logger.go:44: 14:24:02.809167 [WARN] raft: Election timeout reached, restarting election + logger.go:44: 14:24:02.809232 [INFO] raft: Node at 0 [Candidate] entering Candidate state in term 7 + logger.go:44: 14:24:02.809272 [DEBUG] raft: Votes needed: 2 + logger.go:44: 14:24:02.809291 [DEBUG] raft: Vote granted from 0 in term 7. Tally: 1 + logger.go:44: 14:24:02.809350 [INFO] raft: Duplicate RequestVote for same term: 7 + logger.go:44: 14:24:02.821136 [WARN] raft: Election timeout reached, restarting election + logger.go:44: 14:24:02.821236 [INFO] raft: Node at 1 [Candidate] entering Candidate state in term 8 + logger.go:44: 14:24:02.821285 [DEBUG] raft: Votes needed: 2 + logger.go:44: 14:24:02.821302 [DEBUG] raft: Vote granted from 1 in term 8. Tally: 1 + logger.go:44: 14:24:02.821348 [ERR] raft: Failed to make RequestVote RPC to {Voter 0 0}: connectivity to server 0 is down + logger.go:44: 14:24:02.837162 [WARN] raft: Election timeout reached, restarting election + logger.go:44: 14:24:02.837227 [INFO] raft: Node at 0 [Candidate] entering Candidate state in term 8 + logger.go:44: 14:24:02.837264 [DEBUG] raft: Votes needed: 2 + logger.go:44: 14:24:02.837282 [DEBUG] raft: Vote granted from 0 in term 8. Tally: 1 + logger.go:44: 14:24:02.837353 [INFO] raft: Duplicate RequestVote for same term: 8 + logger.go:44: 14:24:02.853153 [WARN] raft: Election timeout reached, restarting election + logger.go:44: 14:24:02.853223 [INFO] raft: Node at 1 [Candidate] entering Candidate state in term 9 + logger.go:44: 14:24:02.853260 [DEBUG] raft: Votes needed: 2 + logger.go:44: 14:24:02.853277 [DEBUG] raft: Vote granted from 1 in term 9. Tally: 1 + logger.go:44: 14:24:02.853326 [ERR] raft: Failed to make RequestVote RPC to {Voter 0 0}: connectivity to server 0 is down + logger.go:44: 14:24:02.864553 [WARN] raft: Election timeout reached, restarting election + logger.go:44: 14:24:02.864619 [INFO] raft: Node at 0 [Candidate] entering Candidate state in term 9 + logger.go:44: 14:24:02.864661 [DEBUG] raft: Votes needed: 2 + logger.go:44: 14:24:02.864690 [DEBUG] raft: Vote granted from 0 in term 9. Tally: 1 + logger.go:44: 14:24:02.864748 [INFO] raft: Duplicate RequestVote for same term: 9 + logger.go:44: 14:24:02.877124 [WARN] raft: Election timeout reached, restarting election + logger.go:44: 14:24:02.877201 [INFO] raft: Node at 1 [Candidate] entering Candidate state in term 10 + logger.go:44: 14:24:02.877239 [DEBUG] raft: Votes needed: 2 + logger.go:44: 14:24:02.877256 [DEBUG] raft: Vote granted from 1 in term 10. Tally: 1 + logger.go:44: 14:24:02.877325 [ERR] raft: Failed to make RequestVote RPC to {Voter 0 0}: connectivity to server 0 is down + logger.go:44: 14:24:02.897416 [WARN] raft: Election timeout reached, restarting election + logger.go:44: 14:24:02.897504 [INFO] raft: Node at 0 [Candidate] entering Candidate state in term 10 + logger.go:44: 14:24:02.897565 [DEBUG] raft: Votes needed: 2 + logger.go:44: 14:24:02.897583 [DEBUG] raft: Vote granted from 0 in term 10. Tally: 1 + logger.go:44: 14:24:02.897639 [INFO] raft: Duplicate RequestVote for same term: 10 + logger.go:44: 14:24:02.913146 [WARN] raft: Election timeout reached, restarting election + logger.go:44: 14:24:02.913237 [INFO] raft: Node at 1 [Candidate] entering Candidate state in term 11 + logger.go:44: 14:24:02.913292 [DEBUG] raft: Votes needed: 2 + logger.go:44: 14:24:02.913309 [DEBUG] raft: Vote granted from 1 in term 11. Tally: 1 + logger.go:44: 14:24:02.913363 [ERR] raft: Failed to make RequestVote RPC to {Voter 0 0}: connectivity to server 0 is down + logger.go:44: 14:24:02.925819 [WARN] raft: Election timeout reached, restarting election + logger.go:44: 14:24:02.925886 [INFO] raft: Node at 0 [Candidate] entering Candidate state in term 11 + logger.go:44: 14:24:02.925933 [DEBUG] raft: Votes needed: 2 + logger.go:44: 14:24:02.925953 [DEBUG] raft: Vote granted from 0 in term 11. Tally: 1 + logger.go:44: 14:24:02.926008 [INFO] raft: Duplicate RequestVote for same term: 11 + logger.go:44: 14:24:02.942814 [WARN] raft: Election timeout reached, restarting election + logger.go:44: 14:24:02.942882 [INFO] raft: Node at 1 [Candidate] entering Candidate state in term 12 + logger.go:44: 14:24:02.942919 [DEBUG] raft: Votes needed: 2 + logger.go:44: 14:24:02.942936 [DEBUG] raft: Vote granted from 1 in term 12. Tally: 1 + logger.go:44: 14:24:02.942984 [ERR] raft: Failed to make RequestVote RPC to {Voter 0 0}: connectivity to server 0 is down + logger.go:44: 14:24:02.945190 [WARN] raft: Election timeout reached, restarting election + logger.go:44: 14:24:02.945248 [INFO] raft: Node at 0 [Candidate] entering Candidate state in term 12 + logger.go:44: 14:24:02.945291 [DEBUG] raft: Votes needed: 2 + logger.go:44: 14:24:02.945306 [DEBUG] raft: Vote granted from 0 in term 12. Tally: 1 + logger.go:44: 14:24:02.945358 [INFO] raft: Duplicate RequestVote for same term: 12 + logger.go:44: 14:24:02.965203 [WARN] raft: Election timeout reached, restarting election + logger.go:44: 14:24:02.965275 [INFO] raft: Node at 1 [Candidate] entering Candidate state in term 13 + logger.go:44: 14:24:02.965328 [DEBUG] raft: Votes needed: 2 + logger.go:44: 14:24:02.965348 [DEBUG] raft: Vote granted from 1 in term 13. Tally: 1 + logger.go:44: 14:24:02.965400 [ERR] raft: Failed to make RequestVote RPC to {Voter 0 0}: connectivity to server 0 is down + logger.go:44: 14:24:02.973127 [WARN] raft: Election timeout reached, restarting election + logger.go:44: 14:24:02.973191 [INFO] raft: Node at 0 [Candidate] entering Candidate state in term 13 + logger.go:44: 14:24:02.973232 [DEBUG] raft: Votes needed: 2 + logger.go:44: 14:24:02.973251 [DEBUG] raft: Vote granted from 0 in term 13. Tally: 1 + logger.go:44: 14:24:02.973311 [INFO] raft: Duplicate RequestVote for same term: 13 + logger.go:44: 14:24:03.001143 [WARN] raft: Election timeout reached, restarting election + logger.go:44: 14:24:03.001227 [INFO] raft: Node at 1 [Candidate] entering Candidate state in term 14 + logger.go:44: 14:24:03.001276 [DEBUG] raft: Votes needed: 2 + logger.go:44: 14:24:03.001292 [DEBUG] raft: Vote granted from 1 in term 14. Tally: 1 + logger.go:44: 14:24:03.001335 [ERR] raft: Failed to make RequestVote RPC to {Voter 0 0}: connectivity to server 0 is down + logger.go:44: 14:24:03.009112 [WARN] raft: Election timeout reached, restarting election + logger.go:44: 14:24:03.009173 [INFO] raft: Node at 0 [Candidate] entering Candidate state in term 14 + logger.go:44: 14:24:03.009218 [DEBUG] raft: Votes needed: 2 + logger.go:44: 14:24:03.009233 [DEBUG] raft: Vote granted from 0 in term 14. Tally: 1 + logger.go:44: 14:24:03.009282 [INFO] raft: Duplicate RequestVote for same term: 14 + logger.go:44: 14:24:03.029202 [WARN] raft: Election timeout reached, restarting election + logger.go:44: 14:24:03.029265 [INFO] raft: Node at 0 [Candidate] entering Candidate state in term 15 + logger.go:44: 14:24:03.029296 [DEBUG] raft: Votes needed: 2 + logger.go:44: 14:24:03.029309 [DEBUG] raft: Vote granted from 0 in term 15. Tally: 1 + logger.go:44: 14:24:03.029360 [INFO] raft: Node at 1 [Follower] entering Follower state (Leader: "") + logger.go:44: 14:24:03.029376 [DEBUG] raft: Vote granted from 1 in term 15. Tally: 2 + logger.go:44: 14:24:03.029384 [INFO] raft: Election won. Tally: 2 + logger.go:44: 14:24:03.029406 [INFO] raft: Node at 0 [Leader] entering Leader state + logger.go:44: 14:24:03.029424 [INFO] raft: Added peer 1, starting replication + logger.go:44: 14:24:03.029499 [DEBUG] raft-test: server 0: transport: append to 1: 1 entry [Noop:term=15,index=2] + logger.go:44: 14:24:03.029600 [INFO] raft: pipelining replication to peer {Voter 1 1} + logger.go:44: 14:24:03.029629 [DEBUG] raft-test: server 0: leadership: acquired + logger.go:44: 14:24:03.029644 [DEBUG] raft-test: elect: server 0: wait for other servers to become followers within 40ms + logger.go:44: 14:24:03.029681 [DEBUG] raft-test: elect: server 1: became follower + logger.go:44: 14:24:03.029689 [DEBUG] raft-test: elect: done + logger.go:44: 14:24:03.029701 [DEBUG] raft-test: close: start + logger.go:44: 14:24:03.029740 [INFO] raft: aborting pipeline replication to peer {Voter 1 1} + logger.go:44: 14:24:03.029757 [DEBUG] raft-test: close: server 0: shutdown done + logger.go:44: 14:24:03.029786 [DEBUG] raft-test: close: server 1: shutdown done + logger.go:44: 14:24:03.029798 [DEBUG] raft-test: server 0: leadership: stop watching + logger.go:44: 14:24:03.029812 [DEBUG] raft-test: server 1: leadership: stop watching + logger.go:44: 14:24:03.029819 [DEBUG] raft-test: close: done === RUN TestHandleChangeRequests_KnownPeer --- PASS: TestHandleChangeRequests_KnownPeer (0.03s) - logger.go:44: 20:44:27.529975 [DEBUG] raft-test: setup: start (1 servers) - logger.go:44: 20:44:27.530014 [DEBUG] raft-test: setup: server 0: bootstrap - logger.go:44: 20:44:27.530074 [DEBUG] raft-test: setup: server 0: start - logger.go:44: 20:44:27.530121 [INFO] raft: Initial configuration (index=1): [{Suffrage:Voter ID:0 Address:0}] - logger.go:44: 20:44:27.530136 [DEBUG] raft-test: setup: done - logger.go:44: 20:44:27.530149 [DEBUG] raft-test: elect: start (server 0) - logger.go:44: 20:44:27.530165 [DEBUG] raft-test: server 0: establish outbound connection to all other nodes - logger.go:44: 20:44:27.530178 [DEBUG] raft-test: elect: server 0: wait to become leader within 1.5s - logger.go:44: 20:44:27.530201 [INFO] raft: Node at 0 [Follower] entering Follower state (Leader: "") - logger.go:44: 20:44:27.560381 [WARN] raft: Heartbeat timeout from "" reached, starting election - logger.go:44: 20:44:27.560461 [INFO] raft: Node at 0 [Candidate] entering Candidate state in term 2 - logger.go:44: 20:44:27.560524 [DEBUG] raft: Votes needed: 1 - logger.go:44: 20:44:27.560543 [DEBUG] raft: Vote granted from 0 in term 2. Tally: 1 - logger.go:44: 20:44:27.560553 [INFO] raft: Election won. Tally: 1 - logger.go:44: 20:44:27.560566 [INFO] raft: Node at 0 [Leader] entering Leader state - logger.go:44: 20:44:27.560654 [DEBUG] raft-test: server 0: leadership: acquired - logger.go:44: 20:44:27.560677 [DEBUG] raft-test: elect: server 0: wait for other servers to become followers within 40ms - logger.go:44: 20:44:27.560706 [DEBUG] raft-test: elect: done - logger.go:44: 20:44:27.560850 [INFO] raft: Updating configuration with AddStaging (0, 1.2.3.4) to [{Suffrage:Voter ID:0 Address:1.2.3.4}] - logger.go:44: 20:44:27.560909 [DEBUG] raft-test: close: start - logger.go:44: 20:44:27.560952 [DEBUG] raft-test: close: server 0: shutdown done - logger.go:44: 20:44:27.560965 [DEBUG] raft-test: server 0: leadership: stop watching - logger.go:44: 20:44:27.560974 [DEBUG] raft-test: close: done + logger.go:44: 14:24:03.029906 [DEBUG] raft-test: setup: start (1 servers) + logger.go:44: 14:24:03.029938 [DEBUG] raft-test: setup: server 0: bootstrap + logger.go:44: 14:24:03.029999 [DEBUG] raft-test: setup: server 0: start + logger.go:44: 14:24:03.030053 [INFO] raft: Initial configuration (index=1): [{Suffrage:Voter ID:0 Address:0}] + logger.go:44: 14:24:03.030067 [DEBUG] raft-test: setup: done + logger.go:44: 14:24:03.030078 [DEBUG] raft-test: elect: start (server 0) + logger.go:44: 14:24:03.030092 [DEBUG] raft-test: server 0: establish outbound connection to all other nodes + logger.go:44: 14:24:03.030103 [DEBUG] raft-test: elect: server 0: wait to become leader within 1.5s + logger.go:44: 14:24:03.030124 [INFO] raft: Node at 0 [Follower] entering Follower state (Leader: "") + logger.go:44: 14:24:03.057147 [WARN] raft: Heartbeat timeout from "" reached, starting election + logger.go:44: 14:24:03.057211 [INFO] raft: Node at 0 [Candidate] entering Candidate state in term 2 + logger.go:44: 14:24:03.057277 [DEBUG] raft: Votes needed: 1 + logger.go:44: 14:24:03.057293 [DEBUG] raft: Vote granted from 0 in term 2. Tally: 1 + logger.go:44: 14:24:03.057303 [INFO] raft: Election won. Tally: 1 + logger.go:44: 14:24:03.057317 [INFO] raft: Node at 0 [Leader] entering Leader state + logger.go:44: 14:24:03.057421 [DEBUG] raft-test: server 0: leadership: acquired + logger.go:44: 14:24:03.057441 [DEBUG] raft-test: elect: server 0: wait for other servers to become followers within 40ms + logger.go:44: 14:24:03.057467 [DEBUG] raft-test: elect: done + logger.go:44: 14:24:03.057513 [INFO] raft: Updating configuration with AddStaging (0, 1.2.3.4) to [{Suffrage:Voter ID:0 Address:1.2.3.4}] + logger.go:44: 14:24:03.057565 [DEBUG] raft-test: close: start + logger.go:44: 14:24:03.057612 [DEBUG] raft-test: close: server 0: shutdown done + logger.go:44: 14:24:03.057626 [DEBUG] raft-test: server 0: leadership: stop watching + logger.go:44: 14:24:03.057636 [DEBUG] raft-test: close: done === RUN TestHandleChangeRequests_LeaveRequest ---- PASS: TestHandleChangeRequests_LeaveRequest (0.28s) - logger.go:44: 20:44:27.561079 [DEBUG] raft-test: setup: start (3 servers) - logger.go:44: 20:44:27.561154 [DEBUG] raft-test: setup: server 0: bootstrap - logger.go:44: 20:44:27.561216 [DEBUG] raft-test: setup: server 1: bootstrap - logger.go:44: 20:44:27.561251 [DEBUG] raft-test: setup: server 2: bootstrap - logger.go:44: 20:44:27.561274 [DEBUG] raft-test: setup: server 0: start - logger.go:44: 20:44:27.561332 [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: 20:44:27.561349 [DEBUG] raft-test: setup: server 1: start - logger.go:44: 20:44:27.561411 [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: 20:44:27.561426 [DEBUG] raft-test: setup: server 2: start - logger.go:44: 20:44:27.561461 [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: 20:44:27.561478 [DEBUG] raft-test: setup: done - logger.go:44: 20:44:27.561491 [DEBUG] raft-test: elect: start (server 0) - logger.go:44: 20:44:27.561514 [DEBUG] raft-test: server 0: establish outbound connection to all other nodes - logger.go:44: 20:44:27.561538 [DEBUG] raft-test: elect: server 0: wait to become leader within 1.5s - logger.go:44: 20:44:27.561565 [INFO] raft: Node at 0 [Follower] entering Follower state (Leader: "") - logger.go:44: 20:44:27.561620 [INFO] raft: Node at 1 [Follower] entering Follower state (Leader: "") - logger.go:44: 20:44:27.561669 [INFO] raft: Node at 2 [Follower] entering Follower state (Leader: "") - logger.go:44: 20:44:27.584374 [WARN] raft: Heartbeat timeout from "" reached, starting election - logger.go:44: 20:44:27.584435 [INFO] raft: Node at 2 [Candidate] entering Candidate state in term 2 - logger.go:44: 20:44:27.584502 [DEBUG] raft: Votes needed: 2 - logger.go:44: 20:44:27.584517 [DEBUG] raft: Vote granted from 2 in term 2. Tally: 1 - logger.go:44: 20:44:27.584559 [ERR] raft: Failed to make RequestVote RPC to {Voter 1 1}: connectivity to server 1 is down - logger.go:44: 20:44:27.584585 [ERR] raft: Failed to make RequestVote RPC to {Voter 0 0}: connectivity to server 0 is down - logger.go:44: 20:44:27.592365 [WARN] raft: Heartbeat timeout from "" reached, starting election - logger.go:44: 20:44:27.592428 [INFO] raft: Node at 0 [Candidate] entering Candidate state in term 2 - logger.go:44: 20:44:27.592497 [DEBUG] raft: Votes needed: 2 - logger.go:44: 20:44:27.592513 [DEBUG] raft: Vote granted from 0 in term 2. Tally: 1 - logger.go:44: 20:44:27.592564 [INFO] raft: Duplicate RequestVote for same term: 2 - logger.go:44: 20:44:27.592367 [WARN] raft: Heartbeat timeout from "" reached, starting election - logger.go:44: 20:44:27.592606 [INFO] raft: Node at 1 [Candidate] entering Candidate state in term 2 - logger.go:44: 20:44:27.592639 [DEBUG] raft: Votes needed: 2 - logger.go:44: 20:44:27.592652 [DEBUG] raft: Vote granted from 1 in term 2. Tally: 1 - logger.go:44: 20:44:27.592712 [ERR] raft: Failed to make RequestVote RPC to {Voter 2 2}: connectivity to server 2 is down - logger.go:44: 20:44:27.592749 [INFO] raft: Duplicate RequestVote for same term: 2 - logger.go:44: 20:44:27.592783 [ERR] raft: Failed to make RequestVote RPC to {Voter 0 0}: connectivity to server 0 is down - logger.go:44: 20:44:27.608416 [WARN] raft: Election timeout reached, restarting election - logger.go:44: 20:44:27.608487 [INFO] raft: Node at 2 [Candidate] entering Candidate state in term 3 - logger.go:44: 20:44:27.608529 [DEBUG] raft: Votes needed: 2 - logger.go:44: 20:44:27.608544 [DEBUG] raft: Vote granted from 2 in term 3. Tally: 1 - logger.go:44: 20:44:27.608593 [ERR] raft: Failed to make RequestVote RPC to {Voter 1 1}: connectivity to server 1 is down - logger.go:44: 20:44:27.608624 [ERR] raft: Failed to make RequestVote RPC to {Voter 0 0}: connectivity to server 0 is down - logger.go:44: 20:44:27.616332 [WARN] raft: Election timeout reached, restarting election - logger.go:44: 20:44:27.616394 [INFO] raft: Node at 1 [Candidate] entering Candidate state in term 3 - logger.go:44: 20:44:27.616429 [DEBUG] raft: Votes needed: 2 - logger.go:44: 20:44:27.616443 [DEBUG] raft: Vote granted from 1 in term 3. Tally: 1 - logger.go:44: 20:44:27.616486 [ERR] raft: Failed to make RequestVote RPC to {Voter 2 2}: connectivity to server 2 is down - logger.go:44: 20:44:27.616521 [ERR] raft: Failed to make RequestVote RPC to {Voter 0 0}: connectivity to server 0 is down - logger.go:44: 20:44:27.619664 [WARN] raft: Election timeout reached, restarting election - logger.go:44: 20:44:27.619705 [INFO] raft: Node at 0 [Candidate] entering Candidate state in term 3 - logger.go:44: 20:44:27.619755 [DEBUG] raft: Votes needed: 2 - logger.go:44: 20:44:27.619772 [DEBUG] raft: Vote granted from 0 in term 3. Tally: 1 - logger.go:44: 20:44:27.619820 [INFO] raft: Duplicate RequestVote for same term: 3 - logger.go:44: 20:44:27.619875 [INFO] raft: Duplicate RequestVote for same term: 3 - logger.go:44: 20:44:27.644348 [WARN] raft: Election timeout reached, restarting election - logger.go:44: 20:44:27.644429 [INFO] raft: Node at 2 [Candidate] entering Candidate state in term 4 - logger.go:44: 20:44:27.644535 [DEBUG] raft: Votes needed: 2 - logger.go:44: 20:44:27.644557 [DEBUG] raft: Vote granted from 2 in term 4. Tally: 1 - logger.go:44: 20:44:27.644613 [ERR] raft: Failed to make RequestVote RPC to {Voter 1 1}: connectivity to server 1 is down - logger.go:44: 20:44:27.644630 [WARN] raft: Election timeout reached, restarting election - logger.go:44: 20:44:27.644701 [INFO] raft: Node at 1 [Candidate] entering Candidate state in term 4 - logger.go:44: 20:44:27.644752 [DEBUG] raft: Votes needed: 2 - logger.go:44: 20:44:27.644767 [DEBUG] raft: Vote granted from 1 in term 4. Tally: 1 - logger.go:44: 20:44:27.644814 [ERR] raft: Failed to make RequestVote RPC to {Voter 2 2}: connectivity to server 2 is down - logger.go:44: 20:44:27.644649 [ERR] raft: Failed to make RequestVote RPC to {Voter 0 0}: connectivity to server 0 is down - logger.go:44: 20:44:27.644858 [ERR] raft: Failed to make RequestVote RPC to {Voter 0 0}: connectivity to server 0 is down - logger.go:44: 20:44:27.648352 [WARN] raft: Election timeout reached, restarting election - logger.go:44: 20:44:27.648411 [INFO] raft: Node at 0 [Candidate] entering Candidate state in term 4 - logger.go:44: 20:44:27.648443 [DEBUG] raft: Votes needed: 2 - logger.go:44: 20:44:27.648498 [DEBUG] raft: Vote granted from 0 in term 4. Tally: 1 - logger.go:44: 20:44:27.648555 [INFO] raft: Duplicate RequestVote for same term: 4 - logger.go:44: 20:44:27.648728 [INFO] raft: Duplicate RequestVote for same term: 4 - logger.go:44: 20:44:27.664376 [WARN] raft: Election timeout reached, restarting election - logger.go:44: 20:44:27.664470 [INFO] raft: Node at 1 [Candidate] entering Candidate state in term 5 - logger.go:44: 20:44:27.664512 [DEBUG] raft: Votes needed: 2 - logger.go:44: 20:44:27.664532 [DEBUG] raft: Vote granted from 1 in term 5. Tally: 1 - logger.go:44: 20:44:27.664586 [ERR] raft: Failed to make RequestVote RPC to {Voter 2 2}: connectivity to server 2 is down - logger.go:44: 20:44:27.664618 [ERR] raft: Failed to make RequestVote RPC to {Voter 0 0}: connectivity to server 0 is down - logger.go:44: 20:44:27.675710 [WARN] raft: Election timeout reached, restarting election - logger.go:44: 20:44:27.675775 [INFO] raft: Node at 2 [Candidate] entering Candidate state in term 5 - logger.go:44: 20:44:27.675817 [DEBUG] raft: Votes needed: 2 - logger.go:44: 20:44:27.675832 [DEBUG] raft: Vote granted from 2 in term 5. Tally: 1 - logger.go:44: 20:44:27.675879 [ERR] raft: Failed to make RequestVote RPC to {Voter 1 1}: connectivity to server 1 is down - logger.go:44: 20:44:27.675907 [ERR] raft: Failed to make RequestVote RPC to {Voter 0 0}: connectivity to server 0 is down - logger.go:44: 20:44:27.676376 [WARN] raft: Election timeout reached, restarting election - logger.go:44: 20:44:27.676444 [INFO] raft: Node at 0 [Candidate] entering Candidate state in term 5 - logger.go:44: 20:44:27.676482 [DEBUG] raft: Votes needed: 2 - logger.go:44: 20:44:27.676498 [DEBUG] raft: Vote granted from 0 in term 5. Tally: 1 - logger.go:44: 20:44:27.676554 [INFO] raft: Duplicate RequestVote for same term: 5 - logger.go:44: 20:44:27.676599 [INFO] raft: Duplicate RequestVote for same term: 5 - logger.go:44: 20:44:27.691812 [WARN] raft: Election timeout reached, restarting election - logger.go:44: 20:44:27.691891 [INFO] raft: Node at 2 [Candidate] entering Candidate state in term 6 - logger.go:44: 20:44:27.691948 [DEBUG] raft: Votes needed: 2 - logger.go:44: 20:44:27.691966 [DEBUG] raft: Vote granted from 2 in term 6. Tally: 1 - logger.go:44: 20:44:27.692014 [ERR] raft: Failed to make RequestVote RPC to {Voter 1 1}: connectivity to server 1 is down - logger.go:44: 20:44:27.692071 [ERR] raft: Failed to make RequestVote RPC to {Voter 0 0}: connectivity to server 0 is down - logger.go:44: 20:44:27.695165 [WARN] raft: Election timeout reached, restarting election - logger.go:44: 20:44:27.695225 [INFO] raft: Node at 1 [Candidate] entering Candidate state in term 6 - logger.go:44: 20:44:27.695271 [DEBUG] raft: Votes needed: 2 - logger.go:44: 20:44:27.695306 [DEBUG] raft: Vote granted from 1 in term 6. Tally: 1 - logger.go:44: 20:44:27.695347 [ERR] raft: Failed to make RequestVote RPC to {Voter 2 2}: connectivity to server 2 is down - logger.go:44: 20:44:27.695380 [ERR] raft: Failed to make RequestVote RPC to {Voter 0 0}: connectivity to server 0 is down - logger.go:44: 20:44:27.709515 [WARN] raft: Election timeout reached, restarting election - logger.go:44: 20:44:27.709593 [INFO] raft: Node at 0 [Candidate] entering Candidate state in term 6 - logger.go:44: 20:44:27.709639 [DEBUG] raft: Votes needed: 2 - logger.go:44: 20:44:27.709655 [DEBUG] raft: Vote granted from 0 in term 6. Tally: 1 - logger.go:44: 20:44:27.709736 [INFO] raft: Duplicate RequestVote for same term: 6 - logger.go:44: 20:44:27.709889 [INFO] raft: Duplicate RequestVote for same term: 6 - logger.go:44: 20:44:27.711380 [WARN] raft: Election timeout reached, restarting election - logger.go:44: 20:44:27.711417 [INFO] raft: Node at 1 [Candidate] entering Candidate state in term 7 - logger.go:44: 20:44:27.711451 [DEBUG] raft: Votes needed: 2 - logger.go:44: 20:44:27.711467 [DEBUG] raft: Vote granted from 1 in term 7. Tally: 1 - logger.go:44: 20:44:27.711509 [ERR] raft: Failed to make RequestVote RPC to {Voter 2 2}: connectivity to server 2 is down - logger.go:44: 20:44:27.711538 [ERR] raft: Failed to make RequestVote RPC to {Voter 0 0}: connectivity to server 0 is down - logger.go:44: 20:44:27.716379 [WARN] raft: Election timeout reached, restarting election - logger.go:44: 20:44:27.716453 [INFO] raft: Node at 2 [Candidate] entering Candidate state in term 7 - logger.go:44: 20:44:27.716500 [DEBUG] raft: Votes needed: 2 - logger.go:44: 20:44:27.716518 [DEBUG] raft: Vote granted from 2 in term 7. Tally: 1 - logger.go:44: 20:44:27.716569 [ERR] raft: Failed to make RequestVote RPC to {Voter 1 1}: connectivity to server 1 is down - logger.go:44: 20:44:27.716601 [ERR] raft: Failed to make RequestVote RPC to {Voter 0 0}: connectivity to server 0 is down - logger.go:44: 20:44:27.736395 [WARN] raft: Election timeout reached, restarting election - logger.go:44: 20:44:27.736473 [INFO] raft: Node at 0 [Candidate] entering Candidate state in term 7 - logger.go:44: 20:44:27.736527 [DEBUG] raft: Votes needed: 2 - logger.go:44: 20:44:27.736542 [DEBUG] raft: Vote granted from 0 in term 7. Tally: 1 - logger.go:44: 20:44:27.740384 [INFO] raft: Duplicate RequestVote for same term: 7 - logger.go:44: 20:44:27.740461 [INFO] raft: Duplicate RequestVote for same term: 7 - logger.go:44: 20:44:27.741185 [WARN] raft: Election timeout reached, restarting election - logger.go:44: 20:44:27.741212 [INFO] raft: Node at 1 [Candidate] entering Candidate state in term 8 - logger.go:44: 20:44:27.741259 [DEBUG] raft: Votes needed: 2 - logger.go:44: 20:44:27.741273 [DEBUG] raft: Vote granted from 1 in term 8. Tally: 1 - logger.go:44: 20:44:27.741310 [ERR] raft: Failed to make RequestVote RPC to {Voter 2 2}: connectivity to server 2 is down - logger.go:44: 20:44:27.741338 [ERR] raft: Failed to make RequestVote RPC to {Voter 0 0}: connectivity to server 0 is down - logger.go:44: 20:44:27.750242 [WARN] raft: Election timeout reached, restarting election - logger.go:44: 20:44:27.750310 [INFO] raft: Node at 2 [Candidate] entering Candidate state in term 8 - logger.go:44: 20:44:27.750345 [DEBUG] raft: Votes needed: 2 - logger.go:44: 20:44:27.750359 [DEBUG] raft: Vote granted from 2 in term 8. Tally: 1 - logger.go:44: 20:44:27.750412 [ERR] raft: Failed to make RequestVote RPC to {Voter 1 1}: connectivity to server 1 is down - logger.go:44: 20:44:27.750442 [ERR] raft: Failed to make RequestVote RPC to {Voter 0 0}: connectivity to server 0 is down - logger.go:44: 20:44:27.764432 [WARN] raft: Election timeout reached, restarting election - logger.go:44: 20:44:27.764498 [INFO] raft: Node at 0 [Candidate] entering Candidate state in term 8 - logger.go:44: 20:44:27.764546 [DEBUG] raft: Votes needed: 2 - logger.go:44: 20:44:27.764562 [DEBUG] raft: Vote granted from 0 in term 8. Tally: 1 - logger.go:44: 20:44:27.764651 [INFO] raft: Duplicate RequestVote for same term: 8 - logger.go:44: 20:44:27.764697 [INFO] raft: Duplicate RequestVote for same term: 8 - logger.go:44: 20:44:27.767888 [WARN] raft: Election timeout reached, restarting election - logger.go:44: 20:44:27.767939 [INFO] raft: Node at 2 [Candidate] entering Candidate state in term 9 - logger.go:44: 20:44:27.767971 [DEBUG] raft: Votes needed: 2 - logger.go:44: 20:44:27.767985 [DEBUG] raft: Vote granted from 2 in term 9. Tally: 1 - logger.go:44: 20:44:27.768025 [ERR] raft: Failed to make RequestVote RPC to {Voter 1 1}: connectivity to server 1 is down - logger.go:44: 20:44:27.768053 [ERR] raft: Failed to make RequestVote RPC to {Voter 0 0}: connectivity to server 0 is down - logger.go:44: 20:44:27.768367 [WARN] raft: Election timeout reached, restarting election - logger.go:44: 20:44:27.768403 [INFO] raft: Node at 1 [Candidate] entering Candidate state in term 9 - logger.go:44: 20:44:27.768423 [DEBUG] raft: Votes needed: 2 - logger.go:44: 20:44:27.768435 [DEBUG] raft: Vote granted from 1 in term 9. Tally: 1 - logger.go:44: 20:44:27.768462 [ERR] raft: Failed to make RequestVote RPC to {Voter 2 2}: connectivity to server 2 is down - logger.go:44: 20:44:27.768489 [ERR] raft: Failed to make RequestVote RPC to {Voter 0 0}: connectivity to server 0 is down - logger.go:44: 20:44:27.793001 [WARN] raft: Election timeout reached, restarting election - logger.go:44: 20:44:27.793065 [INFO] raft: Node at 0 [Candidate] entering Candidate state in term 9 - logger.go:44: 20:44:27.793100 [DEBUG] raft: Votes needed: 2 - logger.go:44: 20:44:27.793115 [DEBUG] raft: Vote granted from 0 in term 9. Tally: 1 - logger.go:44: 20:44:27.793171 [INFO] raft: Duplicate RequestVote for same term: 9 - logger.go:44: 20:44:27.793215 [INFO] raft: Duplicate RequestVote for same term: 9 - logger.go:44: 20:44:27.793720 [WARN] raft: Election timeout reached, restarting election - logger.go:44: 20:44:27.793745 [INFO] raft: Node at 2 [Candidate] entering Candidate state in term 10 - logger.go:44: 20:44:27.793765 [DEBUG] raft: Votes needed: 2 - logger.go:44: 20:44:27.793779 [DEBUG] raft: Vote granted from 2 in term 10. Tally: 1 - logger.go:44: 20:44:27.793816 [ERR] raft: Failed to make RequestVote RPC to {Voter 1 1}: connectivity to server 1 is down - logger.go:44: 20:44:27.793846 [ERR] raft: Failed to make RequestVote RPC to {Voter 0 0}: connectivity to server 0 is down - logger.go:44: 20:44:27.795286 [WARN] raft: Election timeout reached, restarting election - logger.go:44: 20:44:27.795374 [INFO] raft: Node at 1 [Candidate] entering Candidate state in term 10 - logger.go:44: 20:44:27.795432 [DEBUG] raft: Votes needed: 2 - logger.go:44: 20:44:27.795483 [DEBUG] raft: Vote granted from 1 in term 10. Tally: 1 - logger.go:44: 20:44:27.795531 [ERR] raft: Failed to make RequestVote RPC to {Voter 2 2}: connectivity to server 2 is down - logger.go:44: 20:44:27.795560 [ERR] raft: Failed to make RequestVote RPC to {Voter 0 0}: connectivity to server 0 is down - logger.go:44: 20:44:27.810390 [WARN] raft: Election timeout reached, restarting election - logger.go:44: 20:44:27.810457 [INFO] raft: Node at 2 [Candidate] entering Candidate state in term 11 - logger.go:44: 20:44:27.810496 [DEBUG] raft: Votes needed: 2 - logger.go:44: 20:44:27.810513 [DEBUG] raft: Vote granted from 2 in term 11. Tally: 1 - logger.go:44: 20:44:27.811068 [ERR] raft: Failed to make RequestVote RPC to {Voter 0 0}: connectivity to server 0 is down - logger.go:44: 20:44:27.811133 [ERR] raft: Failed to make RequestVote RPC to {Voter 1 1}: connectivity to server 1 is down - logger.go:44: 20:44:27.820727 [WARN] raft: Election timeout reached, restarting election - logger.go:44: 20:44:27.820835 [INFO] raft: Node at 0 [Candidate] entering Candidate state in term 10 - logger.go:44: 20:44:27.820888 [DEBUG] raft: Votes needed: 2 - logger.go:44: 20:44:27.820904 [DEBUG] raft: Vote granted from 0 in term 10. Tally: 1 - logger.go:44: 20:44:27.820966 [DEBUG] raft: Newer term discovered, fallback to follower - logger.go:44: 20:44:27.820982 [INFO] raft: Node at 0 [Follower] entering Follower state (Leader: "") - logger.go:44: 20:44:27.821015 [INFO] raft: Duplicate RequestVote for same term: 10 - logger.go:44: 20:44:27.823581 [WARN] raft: Election timeout reached, restarting election - logger.go:44: 20:44:27.823658 [INFO] raft: Node at 1 [Candidate] entering Candidate state in term 11 - logger.go:44: 20:44:27.823689 [DEBUG] raft: Votes needed: 2 - logger.go:44: 20:44:27.823702 [DEBUG] raft: Vote granted from 1 in term 11. Tally: 1 - logger.go:44: 20:44:27.823742 [ERR] raft: Failed to make RequestVote RPC to {Voter 2 2}: connectivity to server 2 is down - logger.go:44: 20:44:27.823768 [ERR] raft: Failed to make RequestVote RPC to {Voter 0 0}: connectivity to server 0 is down - logger.go:44: 20:44:27.840258 [WARN] raft: Election timeout reached, restarting election - logger.go:44: 20:44:27.840370 [INFO] raft: Node at 2 [Candidate] entering Candidate state in term 12 - logger.go:44: 20:44:27.840418 [DEBUG] raft: Votes needed: 2 - logger.go:44: 20:44:27.840436 [DEBUG] raft: Vote granted from 2 in term 12. Tally: 1 - logger.go:44: 20:44:27.840489 [ERR] raft: Failed to make RequestVote RPC to {Voter 1 1}: connectivity to server 1 is down - logger.go:44: 20:44:27.840526 [ERR] raft: Failed to make RequestVote RPC to {Voter 0 0}: connectivity to server 0 is down - logger.go:44: 20:44:27.843250 [WARN] raft: Heartbeat timeout from "" reached, starting election - logger.go:44: 20:44:27.843303 [INFO] raft: Node at 0 [Candidate] entering Candidate state in term 12 - logger.go:44: 20:44:27.843332 [DEBUG] raft: Votes needed: 2 - logger.go:44: 20:44:27.843346 [DEBUG] raft: Vote granted from 0 in term 12. Tally: 1 - logger.go:44: 20:44:27.843399 [INFO] raft: Duplicate RequestVote for same term: 12 - logger.go:44: 20:44:27.843447 [INFO] raft: Node at 1 [Follower] entering Follower state (Leader: "") - logger.go:44: 20:44:27.843466 [DEBUG] raft: Vote granted from 1 in term 12. Tally: 2 - logger.go:44: 20:44:27.843475 [INFO] raft: Election won. Tally: 2 - logger.go:44: 20:44:27.843486 [INFO] raft: Node at 0 [Leader] entering Leader state - logger.go:44: 20:44:27.843504 [INFO] raft: Added peer 1, starting replication - logger.go:44: 20:44:27.843570 [INFO] raft: Added peer 2, starting replication - logger.go:44: 20:44:27.843630 [DEBUG] raft-test: server 0: transport: append to 2: 1 entry [Noop:term=12,index=2] - logger.go:44: 20:44:27.843684 [INFO] raft: Node at 2 [Follower] entering Follower state (Leader: "0") - logger.go:44: 20:44:27.843721 [INFO] raft: pipelining replication to peer {Voter 2 2} - logger.go:44: 20:44:27.843770 [DEBUG] raft-test: server 0: leadership: acquired - logger.go:44: 20:44:27.843788 [DEBUG] raft-test: elect: server 0: wait for other servers to become followers within 40ms - logger.go:44: 20:44:27.843822 [DEBUG] raft-test: server 0: transport: append to 1: 1 entry [Noop:term=12,index=2] - logger.go:44: 20:44:27.843870 [INFO] raft: pipelining replication to peer {Voter 1 1} - logger.go:44: 20:44:27.843915 [DEBUG] raft-test: elect: server 1: became follower - logger.go:44: 20:44:27.843926 [DEBUG] raft-test: elect: server 2: became follower - logger.go:44: 20:44:27.843934 [DEBUG] raft-test: elect: done - logger.go:44: 20:44:27.843965 [INFO] raft: Updating configuration with RemoveServer (2, ) to [{Suffrage:Voter ID:0 Address:0} {Suffrage:Voter ID:1 Address:1}] - logger.go:44: 20:44:27.844014 [INFO] raft: Removed peer 2, stopping replication after 3 - logger.go:44: 20:44:27.844034 [DEBUG] raft-test: server 0: pipeline: append to 2: 1 entry [Other:term=12,index=3] - logger.go:44: 20:44:27.844057 [DEBUG] raft-test: server 0: pipeline: append to 2: 0 entries - logger.go:44: 20:44:27.844076 [INFO] raft: aborting pipeline replication to peer {Voter 2 2} - logger.go:44: 20:44:27.844100 [DEBUG] raft-test: server 0: pipeline: append to 1: 1 entry [Other:term=12,index=3] - logger.go:44: 20:44:27.844193 [DEBUG] raft-test: close: start - logger.go:44: 20:44:27.844229 [INFO] raft: aborting pipeline replication to peer {Voter 1 1} - logger.go:44: 20:44:27.844249 [DEBUG] raft-test: close: server 0: shutdown done - logger.go:44: 20:44:27.844471 [DEBUG] raft-test: close: server 1: shutdown done - logger.go:44: 20:44:27.844498 [DEBUG] raft-test: close: server 2: shutdown done - logger.go:44: 20:44:27.844514 [DEBUG] raft-test: server 0: leadership: stop watching - logger.go:44: 20:44:27.844533 [DEBUG] raft-test: server 1: leadership: stop watching - logger.go:44: 20:44:27.844552 [DEBUG] raft-test: server 2: leadership: stop watching - logger.go:44: 20:44:27.844561 [DEBUG] raft-test: close: done +--- PASS: TestHandleChangeRequests_LeaveRequest (0.16s) + logger.go:44: 14:24:03.057727 [DEBUG] raft-test: setup: start (3 servers) + logger.go:44: 14:24:03.057804 [DEBUG] raft-test: setup: server 0: bootstrap + logger.go:44: 14:24:03.057903 [DEBUG] raft-test: setup: server 1: bootstrap + logger.go:44: 14:24:03.057932 [DEBUG] raft-test: setup: server 2: bootstrap + logger.go:44: 14:24:03.057957 [DEBUG] raft-test: setup: server 0: start + logger.go:44: 14:24:03.058044 [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: 14:24:03.058062 [DEBUG] raft-test: setup: server 1: start + logger.go:44: 14:24:03.058106 [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: 14:24:03.058122 [DEBUG] raft-test: setup: server 2: start + logger.go:44: 14:24:03.058155 [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: 14:24:03.058170 [DEBUG] raft-test: setup: done + logger.go:44: 14:24:03.058183 [DEBUG] raft-test: elect: start (server 0) + logger.go:44: 14:24:03.058203 [DEBUG] raft-test: server 0: establish outbound connection to all other nodes + logger.go:44: 14:24:03.058221 [DEBUG] raft-test: elect: server 0: wait to become leader within 1.5s + logger.go:44: 14:24:03.058242 [INFO] raft: Node at 0 [Follower] entering Follower state (Leader: "") + logger.go:44: 14:24:03.058267 [INFO] raft: Node at 1 [Follower] entering Follower state (Leader: "") + logger.go:44: 14:24:03.058303 [INFO] raft: Node at 2 [Follower] entering Follower state (Leader: "") + logger.go:44: 14:24:03.078013 [WARN] raft: Heartbeat timeout from "" reached, starting election + logger.go:44: 14:24:03.078076 [INFO] raft: Node at 2 [Candidate] entering Candidate state in term 2 + logger.go:44: 14:24:03.078137 [DEBUG] raft: Votes needed: 2 + logger.go:44: 14:24:03.078156 [DEBUG] raft: Vote granted from 2 in term 2. Tally: 1 + logger.go:44: 14:24:03.078201 [ERR] raft: Failed to make RequestVote RPC to {Voter 1 1}: connectivity to server 1 is down + logger.go:44: 14:24:03.078237 [ERR] raft: Failed to make RequestVote RPC to {Voter 0 0}: connectivity to server 0 is down + logger.go:44: 14:24:03.089143 [WARN] raft: Heartbeat timeout from "" reached, starting election + logger.go:44: 14:24:03.089207 [INFO] raft: Node at 1 [Candidate] entering Candidate state in term 2 + logger.go:44: 14:24:03.089265 [DEBUG] raft: Votes needed: 2 + logger.go:44: 14:24:03.089278 [DEBUG] raft: Vote granted from 1 in term 2. Tally: 1 + logger.go:44: 14:24:03.089329 [ERR] raft: Failed to make RequestVote RPC to {Voter 2 2}: connectivity to server 2 is down + logger.go:44: 14:24:03.089178 [WARN] raft: Heartbeat timeout from "" reached, starting election + logger.go:44: 14:24:03.089356 [INFO] raft: Node at 0 [Candidate] entering Candidate state in term 2 + logger.go:44: 14:24:03.089382 [DEBUG] raft: Votes needed: 2 + logger.go:44: 14:24:03.089395 [DEBUG] raft: Vote granted from 0 in term 2. Tally: 1 + logger.go:44: 14:24:03.089431 [INFO] raft: Duplicate RequestVote for same term: 2 + logger.go:44: 14:24:03.089459 [ERR] raft: Failed to make RequestVote RPC to {Voter 0 0}: connectivity to server 0 is down + logger.go:44: 14:24:03.089490 [INFO] raft: Duplicate RequestVote for same term: 2 + logger.go:44: 14:24:03.101230 [WARN] raft: Election timeout reached, restarting election + logger.go:44: 14:24:03.101300 [INFO] raft: Node at 2 [Candidate] entering Candidate state in term 3 + logger.go:44: 14:24:03.101361 [DEBUG] raft: Votes needed: 2 + logger.go:44: 14:24:03.101379 [DEBUG] raft: Vote granted from 2 in term 3. Tally: 1 + logger.go:44: 14:24:03.101447 [ERR] raft: Failed to make RequestVote RPC to {Voter 1 1}: connectivity to server 1 is down + logger.go:44: 14:24:03.101481 [ERR] raft: Failed to make RequestVote RPC to {Voter 0 0}: connectivity to server 0 is down + logger.go:44: 14:24:03.105340 [WARN] raft: Election timeout reached, restarting election + logger.go:44: 14:24:03.105416 [INFO] raft: Node at 1 [Candidate] entering Candidate state in term 3 + logger.go:44: 14:24:03.105477 [DEBUG] raft: Votes needed: 2 + logger.go:44: 14:24:03.105494 [DEBUG] raft: Vote granted from 1 in term 3. Tally: 1 + logger.go:44: 14:24:03.105542 [ERR] raft: Failed to make RequestVote RPC to {Voter 2 2}: connectivity to server 2 is down + logger.go:44: 14:24:03.105576 [ERR] raft: Failed to make RequestVote RPC to {Voter 0 0}: connectivity to server 0 is down + logger.go:44: 14:24:03.109176 [WARN] raft: Election timeout reached, restarting election + logger.go:44: 14:24:03.109250 [INFO] raft: Node at 0 [Candidate] entering Candidate state in term 3 + logger.go:44: 14:24:03.109299 [DEBUG] raft: Votes needed: 2 + logger.go:44: 14:24:03.109317 [DEBUG] raft: Vote granted from 0 in term 3. Tally: 1 + logger.go:44: 14:24:03.109375 [INFO] raft: Duplicate RequestVote for same term: 3 + logger.go:44: 14:24:03.109436 [INFO] raft: Duplicate RequestVote for same term: 3 + logger.go:44: 14:24:03.121204 [WARN] raft: Election timeout reached, restarting election + logger.go:44: 14:24:03.121288 [INFO] raft: Node at 2 [Candidate] entering Candidate state in term 4 + logger.go:44: 14:24:03.121372 [DEBUG] raft: Votes needed: 2 + logger.go:44: 14:24:03.121389 [DEBUG] raft: Vote granted from 2 in term 4. Tally: 1 + logger.go:44: 14:24:03.121447 [ERR] raft: Failed to make RequestVote RPC to {Voter 1 1}: connectivity to server 1 is down + logger.go:44: 14:24:03.121482 [ERR] raft: Failed to make RequestVote RPC to {Voter 0 0}: connectivity to server 0 is down + logger.go:44: 14:24:03.121590 [WARN] raft: Election timeout reached, restarting election + logger.go:44: 14:24:03.121631 [INFO] raft: Node at 1 [Candidate] entering Candidate state in term 4 + logger.go:44: 14:24:03.121662 [DEBUG] raft: Votes needed: 2 + logger.go:44: 14:24:03.121681 [DEBUG] raft: Vote granted from 1 in term 4. Tally: 1 + logger.go:44: 14:24:03.121709 [ERR] raft: Failed to make RequestVote RPC to {Voter 2 2}: connectivity to server 2 is down + logger.go:44: 14:24:03.121739 [ERR] raft: Failed to make RequestVote RPC to {Voter 0 0}: connectivity to server 0 is down + logger.go:44: 14:24:03.135305 [WARN] raft: Election timeout reached, restarting election + logger.go:44: 14:24:03.135381 [INFO] raft: Node at 0 [Candidate] entering Candidate state in term 4 + logger.go:44: 14:24:03.135428 [DEBUG] raft: Votes needed: 2 + logger.go:44: 14:24:03.135446 [DEBUG] raft: Vote granted from 0 in term 4. Tally: 1 + logger.go:44: 14:24:03.135513 [INFO] raft: Duplicate RequestVote for same term: 4 + logger.go:44: 14:24:03.135570 [INFO] raft: Duplicate RequestVote for same term: 4 + logger.go:44: 14:24:03.149168 [WARN] raft: Election timeout reached, restarting election + logger.go:44: 14:24:03.149240 [INFO] raft: Node at 1 [Candidate] entering Candidate state in term 5 + logger.go:44: 14:24:03.149274 [DEBUG] raft: Votes needed: 2 + logger.go:44: 14:24:03.149300 [DEBUG] raft: Vote granted from 1 in term 5. Tally: 1 + logger.go:44: 14:24:03.149345 [ERR] raft: Failed to make RequestVote RPC to {Voter 2 2}: connectivity to server 2 is down + logger.go:44: 14:24:03.149370 [ERR] raft: Failed to make RequestVote RPC to {Voter 0 0}: connectivity to server 0 is down + logger.go:44: 14:24:03.153176 [WARN] raft: Election timeout reached, restarting election + logger.go:44: 14:24:03.153220 [INFO] raft: Node at 2 [Candidate] entering Candidate state in term 5 + logger.go:44: 14:24:03.153264 [DEBUG] raft: Votes needed: 2 + logger.go:44: 14:24:03.153278 [DEBUG] raft: Vote granted from 2 in term 5. Tally: 1 + logger.go:44: 14:24:03.153318 [ERR] raft: Failed to make RequestVote RPC to {Voter 1 1}: connectivity to server 1 is down + logger.go:44: 14:24:03.153373 [ERR] raft: Failed to make RequestVote RPC to {Voter 0 0}: connectivity to server 0 is down + logger.go:44: 14:24:03.157143 [WARN] raft: Election timeout reached, restarting election + logger.go:44: 14:24:03.157175 [INFO] raft: Node at 0 [Candidate] entering Candidate state in term 5 + logger.go:44: 14:24:03.157219 [DEBUG] raft: Votes needed: 2 + logger.go:44: 14:24:03.157234 [DEBUG] raft: Vote granted from 0 in term 5. Tally: 1 + logger.go:44: 14:24:03.157276 [INFO] raft: Duplicate RequestVote for same term: 5 + logger.go:44: 14:24:03.157315 [INFO] raft: Duplicate RequestVote for same term: 5 + logger.go:44: 14:24:03.168619 [WARN] raft: Election timeout reached, restarting election + logger.go:44: 14:24:03.168694 [INFO] raft: Node at 1 [Candidate] entering Candidate state in term 6 + logger.go:44: 14:24:03.168734 [DEBUG] raft: Votes needed: 2 + logger.go:44: 14:24:03.168751 [DEBUG] raft: Vote granted from 1 in term 6. Tally: 1 + logger.go:44: 14:24:03.168813 [ERR] raft: Failed to make RequestVote RPC to {Voter 2 2}: connectivity to server 2 is down + logger.go:44: 14:24:03.168845 [ERR] raft: Failed to make RequestVote RPC to {Voter 0 0}: connectivity to server 0 is down + logger.go:44: 14:24:03.168866 [WARN] raft: Election timeout reached, restarting election + logger.go:44: 14:24:03.168882 [INFO] raft: Node at 2 [Candidate] entering Candidate state in term 6 + logger.go:44: 14:24:03.168900 [DEBUG] raft: Votes needed: 2 + logger.go:44: 14:24:03.168927 [DEBUG] raft: Vote granted from 2 in term 6. Tally: 1 + logger.go:44: 14:24:03.168953 [ERR] raft: Failed to make RequestVote RPC to {Voter 1 1}: connectivity to server 1 is down + logger.go:44: 14:24:03.168981 [ERR] raft: Failed to make RequestVote RPC to {Voter 0 0}: connectivity to server 0 is down + logger.go:44: 14:24:03.173809 [WARN] raft: Election timeout reached, restarting election + logger.go:44: 14:24:03.173884 [INFO] raft: Node at 0 [Candidate] entering Candidate state in term 6 + logger.go:44: 14:24:03.173920 [DEBUG] raft: Votes needed: 2 + logger.go:44: 14:24:03.173938 [DEBUG] raft: Vote granted from 0 in term 6. Tally: 1 + logger.go:44: 14:24:03.173995 [INFO] raft: Duplicate RequestVote for same term: 6 + logger.go:44: 14:24:03.174042 [INFO] raft: Duplicate RequestVote for same term: 6 + logger.go:44: 14:24:03.193206 [WARN] raft: Election timeout reached, restarting election + logger.go:44: 14:24:03.193281 [INFO] raft: Node at 1 [Candidate] entering Candidate state in term 7 + logger.go:44: 14:24:03.193332 [DEBUG] raft: Votes needed: 2 + logger.go:44: 14:24:03.193352 [DEBUG] raft: Vote granted from 1 in term 7. Tally: 1 + logger.go:44: 14:24:03.193406 [ERR] raft: Failed to make RequestVote RPC to {Voter 2 2}: connectivity to server 2 is down + logger.go:44: 14:24:03.193439 [ERR] raft: Failed to make RequestVote RPC to {Voter 0 0}: connectivity to server 0 is down + logger.go:44: 14:24:03.197227 [WARN] raft: Election timeout reached, restarting election + logger.go:44: 14:24:03.197316 [INFO] raft: Node at 2 [Candidate] entering Candidate state in term 7 + logger.go:44: 14:24:03.197360 [DEBUG] raft: Votes needed: 2 + logger.go:44: 14:24:03.197375 [DEBUG] raft: Vote granted from 2 in term 7. Tally: 1 + logger.go:44: 14:24:03.197421 [ERR] raft: Failed to make RequestVote RPC to {Voter 1 1}: connectivity to server 1 is down + logger.go:44: 14:24:03.197465 [ERR] raft: Failed to make RequestVote RPC to {Voter 0 0}: connectivity to server 0 is down + logger.go:44: 14:24:03.201293 [WARN] raft: Election timeout reached, restarting election + logger.go:44: 14:24:03.201341 [INFO] raft: Node at 0 [Candidate] entering Candidate state in term 7 + logger.go:44: 14:24:03.201373 [DEBUG] raft: Votes needed: 2 + logger.go:44: 14:24:03.201389 [DEBUG] raft: Vote granted from 0 in term 7. Tally: 1 + logger.go:44: 14:24:03.201440 [INFO] raft: Duplicate RequestVote for same term: 7 + logger.go:44: 14:24:03.201494 [INFO] raft: Duplicate RequestVote for same term: 7 + logger.go:44: 14:24:03.215788 [WARN] raft: Election timeout reached, restarting election + logger.go:44: 14:24:03.215877 [INFO] raft: Node at 2 [Candidate] entering Candidate state in term 8 + logger.go:44: 14:24:03.215928 [DEBUG] raft: Votes needed: 2 + logger.go:44: 14:24:03.215944 [DEBUG] raft: Vote granted from 2 in term 8. Tally: 1 + logger.go:44: 14:24:03.215990 [ERR] raft: Failed to make RequestVote RPC to {Voter 1 1}: connectivity to server 1 is down + logger.go:44: 14:24:03.216022 [ERR] raft: Failed to make RequestVote RPC to {Voter 0 0}: connectivity to server 0 is down + logger.go:44: 14:24:03.219582 [WARN] raft: Election timeout reached, restarting election + logger.go:44: 14:24:03.219646 [INFO] raft: Node at 0 [Candidate] entering Candidate state in term 8 + logger.go:44: 14:24:03.219681 [DEBUG] raft: Votes needed: 2 + logger.go:44: 14:24:03.219696 [DEBUG] raft: Vote granted from 0 in term 8. Tally: 1 + logger.go:44: 14:24:03.219746 [INFO] raft: Duplicate RequestVote for same term: 8 + logger.go:44: 14:24:03.219798 [INFO] raft: Node at 1 [Follower] entering Follower state (Leader: "") + logger.go:44: 14:24:03.219816 [DEBUG] raft: Vote granted from 1 in term 8. Tally: 2 + logger.go:44: 14:24:03.219836 [INFO] raft: Election won. Tally: 2 + logger.go:44: 14:24:03.219848 [INFO] raft: Node at 0 [Leader] entering Leader state + logger.go:44: 14:24:03.219866 [INFO] raft: Added peer 1, starting replication + logger.go:44: 14:24:03.219881 [INFO] raft: Added peer 2, starting replication + logger.go:44: 14:24:03.219934 [DEBUG] raft-test: server 0: transport: append to 2: 1 entry [Noop:term=8,index=2] + logger.go:44: 14:24:03.219980 [INFO] raft: Node at 2 [Follower] entering Follower state (Leader: "0") + logger.go:44: 14:24:03.220009 [INFO] raft: pipelining replication to peer {Voter 2 2} + logger.go:44: 14:24:03.220040 [DEBUG] raft-test: server 0: leadership: acquired + logger.go:44: 14:24:03.220058 [DEBUG] raft-test: elect: server 0: wait for other servers to become followers within 40ms + logger.go:44: 14:24:03.220093 [DEBUG] raft-test: server 0: transport: append to 1: 1 entry [Noop:term=8,index=2] + logger.go:44: 14:24:03.220138 [INFO] raft: pipelining replication to peer {Voter 1 1} + logger.go:44: 14:24:03.220174 [DEBUG] raft-test: elect: server 1: became follower + logger.go:44: 14:24:03.220185 [DEBUG] raft-test: elect: server 2: became follower + logger.go:44: 14:24:03.220194 [DEBUG] raft-test: elect: done + logger.go:44: 14:24:03.220224 [INFO] raft: Updating configuration with RemoveServer (2, ) to [{Suffrage:Voter ID:0 Address:0} {Suffrage:Voter ID:1 Address:1}] + logger.go:44: 14:24:03.220329 [INFO] raft: Removed peer 2, stopping replication after 3 + logger.go:44: 14:24:03.220354 [DEBUG] raft-test: server 0: pipeline: append to 2: 1 entry [Other:term=8,index=3] + logger.go:44: 14:24:03.220377 [DEBUG] raft-test: server 0: pipeline: append to 2: 0 entries + logger.go:44: 14:24:03.220395 [INFO] raft: aborting pipeline replication to peer {Voter 2 2} + logger.go:44: 14:24:03.220431 [DEBUG] raft-test: server 0: pipeline: append to 1: 1 entry [Other:term=8,index=3] + logger.go:44: 14:24:03.220516 [DEBUG] raft-test: close: start + logger.go:44: 14:24:03.220551 [INFO] raft: aborting pipeline replication to peer {Voter 1 1} + logger.go:44: 14:24:03.220572 [DEBUG] raft-test: close: server 0: shutdown done + logger.go:44: 14:24:03.220597 [DEBUG] raft-test: close: server 1: shutdown done + logger.go:44: 14:24:03.220620 [DEBUG] raft-test: close: server 2: shutdown done + logger.go:44: 14:24:03.220631 [DEBUG] raft-test: server 0: leadership: stop watching + logger.go:44: 14:24:03.220650 [DEBUG] raft-test: server 1: leadership: stop watching + logger.go:44: 14:24:03.220667 [DEBUG] raft-test: server 2: leadership: stop watching + logger.go:44: 14:24:03.220677 [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.404s +ok github.com/CanonicalLtd/raft-membership 0.615s create-stamp debian/debhelper-build-stamp fakeroot debian/rules binary dh binary --buildsystem=golang --with=golang @@ -1285,12 +1381,14 @@ dpkg-source --after-build . dpkg-buildpackage: info: binary-only upload (no source included) I: copying local configuration +I: user script /srv/workspace/pbuilder/7728/tmp/hooks/B01_cleanup starting +I: user script /srv/workspace/pbuilder/7728/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/30963 and its subdirectories -I: Current time: Tue Sep 13 08:44:40 -12 2022 -I: pbuilder-time-stamp: 1663101880 +I: removing directory /srv/workspace/pbuilder/7728 and its subdirectories +I: Current time: Thu Aug 12 04:24:10 +14 2021 +I: pbuilder-time-stamp: 1628691850