Diff of the two buildlogs: -- --- b1/build.log 2021-02-15 17:29:40.860665950 +0000 +++ b2/build.log 2021-02-15 17:44:50.335530555 +0000 @@ -1,6 +1,6 @@ I: pbuilder: network access will be disabled during build -I: Current time: Sat Apr 22 18:14:57 -12 2023 -I: pbuilder-time-stamp: 1682230497 +I: Current time: Tue Feb 16 07:29:45 +14 2021 +I: pbuilder-time-stamp: 1613410185 I: Building the build Environment I: extracting base tarball [/var/cache/pbuilder/buster-reproducible-base.tgz] I: copying local configuration @@ -18,7 +18,7 @@ I: Extracting source gpgv: unknown type of key resource 'trustedkeys.kbx' gpgv: keyblock resource '/root/.gnupg/trustedkeys.kbx': General error -gpgv: Signature made Wed Nov 21 04:52:31 2018 -12 +gpgv: Signature made Thu Nov 22 06:52:31 2018 +14 gpgv: using RSA key 0740778A2DFC4A39C0C8BC8C8F2B113C6535C5A7 gpgv: Can't check signature: No public key dpkg-source: warning: failed to verify signature on ./golang-github-hashicorp-raft_1.0.0+git20180823.82694fb-3.dsc @@ -30,138 +30,172 @@ dpkg-source: info: applying test--skip-TestNetworkTransport_AppendEntriesPipeline_CloseStreams.patch I: using fakeroot in build. I: Installing the build-deps -I: user script /srv/workspace/pbuilder/14778/tmp/hooks/D02_print_environment starting +I: user script /srv/workspace/pbuilder/20251/tmp/hooks/D01_modify_environment starting +debug: Running on ionos2-i386. +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/20251/tmp/hooks/D01_modify_environment finished +I: user script /srv/workspace/pbuilder/20251/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='i386' - DEBIAN_FRONTEND='noninteractive' - DEB_BUILD_OPTIONS='buildinfo=+all reproducible=+all parallel=18' - DISTRIBUTION='' - HOME='/root' - HOST_ARCH='i386' + 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]="i686-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=i386 + DEBIAN_FRONTEND=noninteractive + DEB_BUILD_OPTIONS='buildinfo=+all reproducible=+all parallel=10' + DIRSTACK=() + DISTRIBUTION= + EUID=0 + FUNCNAME=([0]="Echo" [1]="main") + GROUPS=() + HOME=/root + HOSTNAME=i-capture-the-hostname + HOSTTYPE=i686 + HOST_ARCH=i386 IFS=' ' - INVOCATION_ID='9b3304796a4a45fbaaa25eda78296dec' - LANG='C' - LANGUAGE='en_US:en' - LC_ALL='C' - LD_LIBRARY_PATH='/usr/lib/libeatmydata' - LD_PRELOAD='libeatmydata.so' - 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='14778' - PS1='# ' - PS2='> ' + INVOCATION_ID=e9a5db0c1c8f4d229737dda6cbe31750 + LANG=C + LANGUAGE=de_CH:de + LC_ALL=C + LD_LIBRARY_PATH=/usr/lib/libeatmydata + LD_PRELOAD=libeatmydata.so + MACHTYPE=i686-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=20251 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.1opi1fljXi/pbuilderrc_aWWn --hookdir /etc/pbuilder/first-build-hooks --debbuildopts -b --basetgz /var/cache/pbuilder/buster-reproducible-base.tgz --buildresult /srv/reproducible-results/rbuild-debian/tmp.1opi1fljXi/b1 --logfile b1/build.log golang-github-hashicorp-raft_1.0.0+git20180823.82694fb-3.dsc' - SUDO_GID='112' - SUDO_UID='107' - 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.1opi1fljXi/pbuilderrc_6A8c --hookdir /etc/pbuilder/rebuild-hooks --debbuildopts -b --basetgz /var/cache/pbuilder/buster-reproducible-base.tgz --buildresult /srv/reproducible-results/rbuild-debian/tmp.1opi1fljXi/b2 --logfile b2/build.log golang-github-hashicorp-raft_1.0.0+git20180823.82694fb-3.dsc' + SUDO_GID=112 + SUDO_UID=107 + 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 ionos16-i386 4.19.0-14-amd64 #1 SMP Debian 4.19.171-2 (2021-01-30) x86_64 GNU/Linux + Linux i-capture-the-hostname 4.19.0-14-686-pae #1 SMP Debian 4.19.171-2 (2021-01-30) i686 GNU/Linux I: ls -l /bin total 5476 - -rwxr-xr-x 1 root root 1302248 Apr 17 2019 bash - -rwxr-xr-x 3 root root 38280 Jul 10 2019 bunzip2 - -rwxr-xr-x 3 root root 38280 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 38280 Jul 10 2019 bzip2 - -rwxr-xr-x 1 root root 17768 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 38692 Feb 28 2019 cat - -rwxr-xr-x 1 root root 75588 Feb 28 2019 chgrp - -rwxr-xr-x 1 root root 63268 Feb 28 2019 chmod - -rwxr-xr-x 1 root root 75588 Feb 28 2019 chown - -rwxr-xr-x 1 root root 153732 Feb 28 2019 cp - -rwxr-xr-x 1 root root 132820 Jan 17 2019 dash - -rwxr-xr-x 1 root root 120676 Feb 28 2019 date - -rwxr-xr-x 1 root root 92040 Feb 28 2019 dd - -rwxr-xr-x 1 root root 100620 Feb 28 2019 df - -rwxr-xr-x 1 root root 149736 Feb 28 2019 dir - -rwxr-xr-x 1 root root 79412 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 34532 Feb 28 2019 echo - -rwxr-xr-x 1 root root 28 Jan 7 2019 egrep - -rwxr-xr-x 1 root root 34532 Feb 28 2019 false - -rwxr-xr-x 1 root root 28 Jan 7 2019 fgrep - -rwxr-xr-x 1 root root 67700 Jan 9 2019 findmnt - -rwsr-xr-x 1 root root 30112 Apr 22 2020 fusermount - -rwxr-xr-x 1 root root 206392 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 100952 Jan 5 2019 gzip - -rwxr-xr-x 1 root root 21916 Sep 26 2018 hostname - -rwxr-xr-x 1 root root 79752 Feb 28 2019 ln - -rwxr-xr-x 1 root root 55400 Jul 26 2018 login - -rwxr-xr-x 1 root root 149736 Feb 28 2019 ls - -rwxr-xr-x 1 root root 112032 Jan 9 2019 lsblk - -rwxr-xr-x 1 root root 87972 Feb 28 2019 mkdir - -rwxr-xr-x 1 root root 79748 Feb 28 2019 mknod - -rwxr-xr-x 1 root root 46916 Feb 28 2019 mktemp - -rwxr-xr-x 1 root root 42348 Jan 9 2019 more - -rwsr-xr-x 1 root root 50592 Jan 9 2019 mount - -rwxr-xr-x 1 root root 13724 Jan 9 2019 mountpoint - -rwxr-xr-x 1 root root 157832 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 38660 Feb 28 2019 pwd - lrwxrwxrwx 1 root root 4 Apr 17 2019 rbash -> bash - -rwxr-xr-x 1 root root 46852 Feb 28 2019 readlink - -rwxr-xr-x 1 root root 75588 Feb 28 2019 rm - -rwxr-xr-x 1 root root 42756 Feb 28 2019 rmdir - -rwxr-xr-x 1 root root 22276 Jan 21 2019 run-parts - -rwxr-xr-x 1 root root 125036 Dec 22 2018 sed - lrwxrwxrwx 1 root root 4 Mar 12 2022 sh -> dash - -rwxr-xr-x 1 root root 34532 Feb 28 2019 sleep - -rwxr-xr-x 1 root root 79652 Feb 28 2019 stty - -rwsr-xr-x 1 root root 71072 Jan 9 2019 su - -rwxr-xr-x 1 root root 34564 Feb 28 2019 sync - -rwxr-xr-x 1 root root 504024 Apr 23 2019 tar - -rwxr-xr-x 1 root root 13860 Jan 21 2019 tempfile - -rwxr-xr-x 1 root root 104292 Feb 28 2019 touch - -rwxr-xr-x 1 root root 34532 Feb 28 2019 true - -rwxr-xr-x 1 root root 17768 Apr 22 2020 ulockmgr_server - -rwsr-xr-x 1 root root 30108 Jan 9 2019 umount - -rwxr-xr-x 1 root root 34532 Feb 28 2019 uname - -rwxr-xr-x 2 root root 2345 Jan 5 2019 uncompress - -rwxr-xr-x 1 root root 149736 Feb 28 2019 vdir - -rwxr-xr-x 1 root root 34208 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/14778/tmp/hooks/D02_print_environment finished + -rwxr-xr-x 1 root root 1302248 Apr 18 2019 bash + -rwxr-xr-x 3 root root 38280 Jul 11 2019 bunzip2 + -rwxr-xr-x 3 root root 38280 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 38280 Jul 11 2019 bzip2 + -rwxr-xr-x 1 root root 17768 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 38692 Mar 1 2019 cat + -rwxr-xr-x 1 root root 75588 Mar 1 2019 chgrp + -rwxr-xr-x 1 root root 63268 Mar 1 2019 chmod + -rwxr-xr-x 1 root root 75588 Mar 1 2019 chown + -rwxr-xr-x 1 root root 153732 Mar 1 2019 cp + -rwxr-xr-x 1 root root 132820 Jan 18 2019 dash + -rwxr-xr-x 1 root root 120676 Mar 1 2019 date + -rwxr-xr-x 1 root root 92040 Mar 1 2019 dd + -rwxr-xr-x 1 root root 100620 Mar 1 2019 df + -rwxr-xr-x 1 root root 149736 Mar 1 2019 dir + -rwxr-xr-x 1 root root 79412 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 34532 Mar 1 2019 echo + -rwxr-xr-x 1 root root 28 Jan 8 2019 egrep + -rwxr-xr-x 1 root root 34532 Mar 1 2019 false + -rwxr-xr-x 1 root root 28 Jan 8 2019 fgrep + -rwxr-xr-x 1 root root 67700 Jan 10 2019 findmnt + -rwsr-xr-x 1 root root 30112 Apr 23 2020 fusermount + -rwxr-xr-x 1 root root 206392 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 100952 Jan 6 2019 gzip + -rwxr-xr-x 1 root root 21916 Sep 27 2018 hostname + -rwxr-xr-x 1 root root 79752 Mar 1 2019 ln + -rwxr-xr-x 1 root root 55400 Jul 27 2018 login + -rwxr-xr-x 1 root root 149736 Mar 1 2019 ls + -rwxr-xr-x 1 root root 112032 Jan 10 2019 lsblk + -rwxr-xr-x 1 root root 87972 Mar 1 2019 mkdir + -rwxr-xr-x 1 root root 79748 Mar 1 2019 mknod + -rwxr-xr-x 1 root root 46916 Mar 1 2019 mktemp + -rwxr-xr-x 1 root root 42348 Jan 10 2019 more + -rwsr-xr-x 1 root root 50592 Jan 10 2019 mount + -rwxr-xr-x 1 root root 13724 Jan 10 2019 mountpoint + -rwxr-xr-x 1 root root 157832 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 38660 Mar 1 2019 pwd + lrwxrwxrwx 1 root root 4 Apr 18 2019 rbash -> bash + -rwxr-xr-x 1 root root 46852 Mar 1 2019 readlink + -rwxr-xr-x 1 root root 75588 Mar 1 2019 rm + -rwxr-xr-x 1 root root 42756 Mar 1 2019 rmdir + -rwxr-xr-x 1 root root 22276 Jan 22 2019 run-parts + -rwxr-xr-x 1 root root 125036 Dec 23 2018 sed + lrwxrwxrwx 1 root root 4 Feb 16 07:39 sh -> bash + lrwxrwxrwx 1 root root 4 Feb 7 22:26 sh.distrib -> dash + -rwxr-xr-x 1 root root 34532 Mar 1 2019 sleep + -rwxr-xr-x 1 root root 79652 Mar 1 2019 stty + -rwsr-xr-x 1 root root 71072 Jan 10 2019 su + -rwxr-xr-x 1 root root 34564 Mar 1 2019 sync + -rwxr-xr-x 1 root root 504024 Apr 24 2019 tar + -rwxr-xr-x 1 root root 13860 Jan 22 2019 tempfile + -rwxr-xr-x 1 root root 104292 Mar 1 2019 touch + -rwxr-xr-x 1 root root 34532 Mar 1 2019 true + -rwxr-xr-x 1 root root 17768 Apr 23 2020 ulockmgr_server + -rwsr-xr-x 1 root root 30108 Jan 10 2019 umount + -rwxr-xr-x 1 root root 34532 Mar 1 2019 uname + -rwxr-xr-x 2 root root 2345 Jan 6 2019 uncompress + -rwxr-xr-x 1 root root 149736 Mar 1 2019 vdir + -rwxr-xr-x 1 root root 34208 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/20251/tmp/hooks/D02_print_environment finished -> Attempting to satisfy build-dependencies -> Creating pbuilder-satisfydepends-dummy package Package: pbuilder-satisfydepends-dummy @@ -312,7 +346,7 @@ Get: 105 http://deb.debian.org/debian buster/main i386 libsasl2-dev i386 2.1.27+dfsg-1+deb10u1 [296 kB] Get: 106 http://deb.debian.org/debian buster/main i386 golang-gopkg-mgo.v2-dev all 2016.08.01-5 [194 kB] Get: 107 http://deb.debian.org/debian buster/main i386 golang-github-hashicorp-go-msgpack-dev all 0.0~git20150518.0.fa3f638-6 [42.7 kB] -Fetched 90.6 MB in 2s (56.2 MB/s) +Fetched 90.6 MB in 34s (2678 kB/s) debconf: delaying package configuration, since apt-utils is not installed Selecting previously unselected package libbsd0:i386. (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 ... 19234 files and directories currently installed.) @@ -763,7 +797,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-hashicorp-raft-1.0.0+git20180823.82694fb/ && 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-hashicorp-raft-1.0.0+git20180823.82694fb/ && 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-hashicorp-raft dpkg-buildpackage: info: source version 1.0.0+git20180823.82694fb-3 dpkg-buildpackage: info: source distribution unstable @@ -781,50 +815,50 @@ dh_autoreconf -O--buildsystem=golang dh_auto_configure -O--buildsystem=golang dh_auto_build -O--buildsystem=golang - cd obj-i686-linux-gnu && go install -gcflags=all=\"-trimpath=/build/golang-github-hashicorp-raft-1.0.0\+git20180823.82694fb/obj-i686-linux-gnu/src\" -asmflags=all=\"-trimpath=/build/golang-github-hashicorp-raft-1.0.0\+git20180823.82694fb/obj-i686-linux-gnu/src\" -v -p 18 github.com/hashicorp/raft github.com/hashicorp/raft/bench -errors -unicode/utf16 + cd obj-i686-linux-gnu && go install -gcflags=all=\"-trimpath=/build/golang-github-hashicorp-raft-1.0.0\+git20180823.82694fb/obj-i686-linux-gnu/src\" -asmflags=all=\"-trimpath=/build/golang-github-hashicorp-raft-1.0.0\+git20180823.82694fb/obj-i686-linux-gnu/src\" -v -p 10 github.com/hashicorp/raft github.com/hashicorp/raft/bench internal/race -internal/nettrace -crypto/subtle -math/bits -container/list -encoding unicode/utf8 -crypto/internal/subtle +errors unicode -runtime/internal/atomic +container/list internal/cpu -vendor/golang_org/x/net/dns/dnsmessage +math +runtime/internal/atomic runtime/internal/sys -runtime/cgo +crypto/internal/subtle +math/bits +crypto/subtle sync/atomic -vendor/golang_org/x/crypto/cryptobyte/asn1 github.com/hashicorp/golang-lru/simplelru -math +unicode/utf16 +encoding +internal/nettrace internal/testlog internal/bytealg +vendor/golang_org/x/net/dns/dnsmessage +vendor/golang_org/x/crypto/cryptobyte/asn1 +runtime/cgo runtime strconv crypto/rc4 sync -io internal/singleflight math/rand reflect +io syscall -crypto/internal/randutil hash +crypto/internal/randutil bytes -crypto/cipher strings crypto crypto/hmac hash/crc32 hash/crc64 -crypto/sha512 -crypto/sha1 crypto/md5 +crypto/sha1 +crypto/sha512 +crypto/cipher crypto/sha256 crypto/aes bufio @@ -834,54 +868,54 @@ internal/syscall/unix time internal/poll -encoding/binary sort +encoding/binary github.com/hashicorp/go-immutable-radix os -encoding/base64 -crypto/des vendor/golang_org/x/crypto/poly1305 vendor/golang_org/x/crypto/internal/chacha20 +encoding/base64 +crypto/des vendor/golang_org/x/crypto/curve25519 vendor/golang_org/x/crypto/chacha20poly1305 encoding/pem -path/filepath -runtime/debug os/signal +runtime/debug +path/filepath fmt io/ioutil -context -log encoding/hex -mime/quotedprintable net/url -compress/flate +context +vendor/golang_org/x/net/http2/hpack +vendor/golang_org/x/text/unicode/norm +log encoding/json -flag mime +compress/flate +math/big +mime/quotedprintable +vendor/golang_org/x/text/unicode/bidi net/http/internal +net encoding/gob -vendor/golang_org/x/text/unicode/norm -math/big -vendor/golang_org/x/net/http2/hpack +flag text/template/parse -vendor/golang_org/x/text/unicode/bidi runtime/trace -net -testing vendor/golang_org/x/text/secure/bidirule +testing compress/gzip -text/template vendor/golang_org/x/net/idna -html/template -crypto/rand +text/template crypto/dsa encoding/asn1 crypto/elliptic +crypto/rand crypto/rsa -crypto/ecdsa -crypto/x509/pkix vendor/golang_org/x/crypto/cryptobyte +crypto/x509/pkix +crypto/ecdsa +html/template vendor/golang_org/x/net/http/httpproxy net/textproto crypto/x509 @@ -896,7 +930,7 @@ github.com/hashicorp/raft github.com/hashicorp/raft/bench dh_auto_test -O--buildsystem=golang - cd obj-i686-linux-gnu && go test -vet=off -v -p 18 github.com/hashicorp/raft github.com/hashicorp/raft/bench + cd obj-i686-linux-gnu && go test -vet=off -v -p 10 github.com/hashicorp/raft github.com/hashicorp/raft/bench === RUN TestCommitment_setVoters --- PASS: TestCommitment_setVoters (0.00s) === RUN TestCommitment_match_max @@ -938,33 +972,33 @@ === RUN TestFileSnapshotSinkImpl --- PASS: TestFileSnapshotSinkImpl (0.00s) === RUN TestFileSS_CreateSnapshotMissingParentDir ---- PASS: TestFileSS_CreateSnapshotMissingParentDir (0.40s) - raft_test.go:101: 06:15:33.362016 [INFO] snapshot: Creating new snapshot at /tmp/raft072659488/raft938113279/snapshots/3-10-1682230533362.tmp +--- PASS: TestFileSS_CreateSnapshotMissingParentDir (0.08s) + raft_test.go:101: 17:44:03.412260 [INFO] snapshot: Creating new snapshot at /tmp/raft249990401/raft883157612/snapshots/3-10-1613411043412.tmp === RUN TestFileSS_CreateSnapshot ---- PASS: TestFileSS_CreateSnapshot (0.96s) - raft_test.go:101: 06:15:33.760276 [INFO] snapshot: Creating new snapshot at /tmp/raft184260178/snapshots/3-10-1682230533760.tmp - raft_test.go:101: 06:15:34.311569 [WARN] snapshot: Found temporary snapshot: 3-10-1682230533760.tmp +--- PASS: TestFileSS_CreateSnapshot (0.07s) + raft_test.go:101: 17:44:03.490692 [INFO] snapshot: Creating new snapshot at /tmp/raft690151131/snapshots/3-10-1613411043490.tmp + raft_test.go:101: 17:44:03.510197 [WARN] snapshot: Found temporary snapshot: 3-10-1613411043490.tmp === RUN TestFileSS_CancelSnapshot ---- PASS: TestFileSS_CancelSnapshot (0.05s) - raft_test.go:101: 06:15:34.720050 [INFO] snapshot: Creating new snapshot at /tmp/raft280616841/snapshots/3-10-1682230534720.tmp +--- PASS: TestFileSS_CancelSnapshot (0.02s) + raft_test.go:101: 17:44:03.558976 [INFO] snapshot: Creating new snapshot at /tmp/raft757071486/snapshots/3-10-1613411043558.tmp === RUN TestFileSS_Retention ---- PASS: TestFileSS_Retention (1.08s) - raft_test.go:101: 06:15:34.772680 [INFO] snapshot: Creating new snapshot at /tmp/raft930895700/snapshots/3-10-1682230534772.tmp - raft_test.go:101: 06:15:34.901100 [INFO] snapshot: Creating new snapshot at /tmp/raft930895700/snapshots/3-11-1682230534901.tmp - raft_test.go:101: 06:15:35.111781 [INFO] snapshot: Creating new snapshot at /tmp/raft930895700/snapshots/3-12-1682230535111.tmp - raft_test.go:101: 06:15:35.307296 [INFO] snapshot: reaping snapshot /tmp/raft930895700/snapshots/3-10-1682230534772 - raft_test.go:101: 06:15:35.307409 [INFO] snapshot: Creating new snapshot at /tmp/raft930895700/snapshots/3-13-1682230535307.tmp - raft_test.go:101: 06:15:35.685792 [INFO] snapshot: reaping snapshot /tmp/raft930895700/snapshots/3-11-1682230534901 - raft_test.go:101: 06:15:35.685909 [INFO] snapshot: Creating new snapshot at /tmp/raft930895700/snapshots/3-14-1682230535685.tmp - raft_test.go:101: 06:15:35.847537 [INFO] snapshot: reaping snapshot /tmp/raft930895700/snapshots/3-12-1682230535111 +--- PASS: TestFileSS_Retention (0.19s) + raft_test.go:101: 17:44:03.578488 [INFO] snapshot: Creating new snapshot at /tmp/raft384156101/snapshots/3-10-1613411043578.tmp + raft_test.go:101: 17:44:03.610181 [INFO] snapshot: Creating new snapshot at /tmp/raft384156101/snapshots/3-11-1613411043610.tmp + raft_test.go:101: 17:44:03.634189 [INFO] snapshot: Creating new snapshot at /tmp/raft384156101/snapshots/3-12-1613411043634.tmp + raft_test.go:101: 17:44:03.674216 [INFO] snapshot: reaping snapshot /tmp/raft384156101/snapshots/3-10-1613411043578 + raft_test.go:101: 17:44:03.674396 [INFO] snapshot: Creating new snapshot at /tmp/raft384156101/snapshots/3-13-1613411043674.tmp + raft_test.go:101: 17:44:03.722223 [INFO] snapshot: reaping snapshot /tmp/raft384156101/snapshots/3-11-1613411043610 + raft_test.go:101: 17:44:03.722410 [INFO] snapshot: Creating new snapshot at /tmp/raft384156101/snapshots/3-14-1613411043722.tmp + raft_test.go:101: 17:44:03.766192 [INFO] snapshot: reaping snapshot /tmp/raft384156101/snapshots/3-12-1613411043634 === RUN TestFileSS_BadPerm --- PASS: TestFileSS_BadPerm (0.00s) === RUN TestFileSS_MissingParentDir --- PASS: TestFileSS_MissingParentDir (0.00s) === RUN TestFileSS_Ordering ---- PASS: TestFileSS_Ordering (0.02s) - raft_test.go:101: 06:15:35.849121 [INFO] snapshot: Creating new snapshot at /tmp/raft021524103/snapshots/5-130350-1682230535849.tmp - raft_test.go:101: 06:15:35.861162 [INFO] snapshot: Creating new snapshot at /tmp/raft021524103/snapshots/36-204917-1682230535861.tmp +--- PASS: TestFileSS_Ordering (0.07s) + raft_test.go:101: 17:44:03.768549 [INFO] snapshot: Creating new snapshot at /tmp/raft087526804/snapshots/5-130350-1613411043768.tmp + raft_test.go:101: 17:44:03.810115 [INFO] snapshot: Creating new snapshot at /tmp/raft087526804/snapshots/36-204917-1613411043810.tmp === RUN TestDeferFutureSuccess --- PASS: TestDeferFutureSuccess (0.00s) === RUN TestDeferFutureError @@ -984,52 +1018,52 @@ === RUN TestLogCache --- PASS: TestLogCache (0.00s) === RUN TestNetworkTransport_CloseStreams ---- PASS: TestNetworkTransport_CloseStreams (0.00s) - raft_test.go:101: 06:15:35.874261 [DEBUG] raft-net: 127.0.0.1:45085 accepted connection from: 127.0.0.1:51532 - raft_test.go:101: 06:15:35.874313 [DEBUG] raft-net: 127.0.0.1:45085 accepted connection from: 127.0.0.1:51534 - raft_test.go:101: 06:15:35.874353 [DEBUG] raft-net: 127.0.0.1:45085 accepted connection from: 127.0.0.1:51536 - raft_test.go:101: 06:15:35.874372 [DEBUG] raft-net: 127.0.0.1:45085 accepted connection from: 127.0.0.1:51538 - raft_test.go:101: 06:15:35.874388 [DEBUG] raft-net: 127.0.0.1:45085 accepted connection from: 127.0.0.1:51540 - raft_test.go:101: 06:15:35.874826 [DEBUG] raft-net: 127.0.0.1:45085 accepted connection from: 127.0.0.1:51542 - raft_test.go:101: 06:15:35.874851 [DEBUG] raft-net: 127.0.0.1:45085 accepted connection from: 127.0.0.1:51544 - raft_test.go:101: 06:15:35.874867 [DEBUG] raft-net: 127.0.0.1:45085 accepted connection from: 127.0.0.1:51546 - raft_test.go:101: 06:15:35.874883 [DEBUG] raft-net: 127.0.0.1:45085 accepted connection from: 127.0.0.1:51548 - raft_test.go:101: 06:15:35.874899 [DEBUG] raft-net: 127.0.0.1:45085 accepted connection from: 127.0.0.1:51550 +--- PASS: TestNetworkTransport_CloseStreams (0.02s) + raft_test.go:101: 17:44:03.846385 [DEBUG] raft-net: 127.0.0.1:33005 accepted connection from: 127.0.0.1:53054 + raft_test.go:101: 17:44:03.850736 [DEBUG] raft-net: 127.0.0.1:33005 accepted connection from: 127.0.0.1:53056 + raft_test.go:101: 17:44:03.850787 [DEBUG] raft-net: 127.0.0.1:33005 accepted connection from: 127.0.0.1:53058 + raft_test.go:101: 17:44:03.850819 [DEBUG] raft-net: 127.0.0.1:33005 accepted connection from: 127.0.0.1:53060 + raft_test.go:101: 17:44:03.850844 [DEBUG] raft-net: 127.0.0.1:33005 accepted connection from: 127.0.0.1:53062 + raft_test.go:101: 17:44:03.852128 [DEBUG] raft-net: 127.0.0.1:33005 accepted connection from: 127.0.0.1:53064 + raft_test.go:101: 17:44:03.852152 [DEBUG] raft-net: 127.0.0.1:33005 accepted connection from: 127.0.0.1:53066 + raft_test.go:101: 17:44:03.852174 [DEBUG] raft-net: 127.0.0.1:33005 accepted connection from: 127.0.0.1:53068 + raft_test.go:101: 17:44:03.852196 [DEBUG] raft-net: 127.0.0.1:33005 accepted connection from: 127.0.0.1:53070 + raft_test.go:101: 17:44:03.852220 [DEBUG] raft-net: 127.0.0.1:33005 accepted connection from: 127.0.0.1:53072 === RUN TestNetworkTransport_StartStop --- PASS: TestNetworkTransport_StartStop (0.00s) === RUN TestNetworkTransport_Heartbeat_FastPath --- PASS: TestNetworkTransport_Heartbeat_FastPath (0.00s) - raft_test.go:101: 06:15:35.875575 [DEBUG] raft-net: 127.0.0.1:45793 accepted connection from: 127.0.0.1:58698 + raft_test.go:101: 17:44:03.852920 [DEBUG] raft-net: 127.0.0.1:39715 accepted connection from: 127.0.0.1:33038 === RUN TestNetworkTransport_AppendEntries --- PASS: TestNetworkTransport_AppendEntries (0.00s) - raft_test.go:101: 06:15:35.875884 [DEBUG] raft-net: 127.0.0.1:45809 accepted connection from: 127.0.0.1:53242 - raft_test.go:101: 06:15:35.876171 [DEBUG] raft-net: 127.0.0.1:38723 accepted connection from: 127.0.0.1:60324 + raft_test.go:101: 17:44:03.853255 [DEBUG] raft-net: 127.0.0.1:46261 accepted connection from: 127.0.0.1:59748 + raft_test.go:101: 17:44:03.853515 [DEBUG] raft-net: 127.0.0.1:36261 accepted connection from: 127.0.0.1:58366 === RUN TestNetworkTransport_AppendEntriesPipeline ---- PASS: TestNetworkTransport_AppendEntriesPipeline (0.00s) - raft_test.go:101: 06:15:35.876607 [DEBUG] raft-net: 127.0.0.1:33411 accepted connection from: 127.0.0.1:44054 - raft_test.go:101: 06:15:35.877146 [DEBUG] raft-net: 127.0.0.1:39585 accepted connection from: 127.0.0.1:46236 +--- PASS: TestNetworkTransport_AppendEntriesPipeline (0.05s) + raft_test.go:101: 17:44:03.853855 [DEBUG] raft-net: 127.0.0.1:45121 accepted connection from: 127.0.0.1:41478 + raft_test.go:101: 17:44:03.862109 [DEBUG] raft-net: 127.0.0.1:35711 accepted connection from: 127.0.0.1:52874 === RUN TestNetworkTransport_AppendEntriesPipeline_CloseStreams --- SKIP: TestNetworkTransport_AppendEntriesPipeline_CloseStreams (0.00s) net_transport_test.go:333: Disabled unreliable test === RUN TestNetworkTransport_RequestVote --- PASS: TestNetworkTransport_RequestVote (0.00s) - raft_test.go:101: 06:15:35.877846 [DEBUG] raft-net: 127.0.0.1:38737 accepted connection from: 127.0.0.1:39090 - raft_test.go:101: 06:15:35.878220 [DEBUG] raft-net: 127.0.0.1:34925 accepted connection from: 127.0.0.1:47416 + raft_test.go:101: 17:44:03.903227 [DEBUG] raft-net: 127.0.0.1:34525 accepted connection from: 127.0.0.1:40624 + raft_test.go:101: 17:44:03.903671 [DEBUG] raft-net: 127.0.0.1:40361 accepted connection from: 127.0.0.1:54410 === RUN TestNetworkTransport_InstallSnapshot --- PASS: TestNetworkTransport_InstallSnapshot (0.00s) - raft_test.go:101: 06:15:35.878674 [DEBUG] raft-net: 127.0.0.1:40271 accepted connection from: 127.0.0.1:50078 - raft_test.go:101: 06:15:35.878973 [DEBUG] raft-net: 127.0.0.1:40797 accepted connection from: 127.0.0.1:45690 + raft_test.go:101: 17:44:03.904213 [DEBUG] raft-net: 127.0.0.1:36583 accepted connection from: 127.0.0.1:43400 + raft_test.go:101: 17:44:03.905501 [DEBUG] raft-net: 127.0.0.1:46667 accepted connection from: 127.0.0.1:56886 === RUN TestNetworkTransport_EncodeDecode --- PASS: TestNetworkTransport_EncodeDecode (0.00s) === RUN TestNetworkTransport_EncodeDecode_AddressProvider --- PASS: TestNetworkTransport_EncodeDecode_AddressProvider (0.00s) === RUN TestNetworkTransport_PooledConn ---- PASS: TestNetworkTransport_PooledConn (0.00s) - raft_test.go:101: 06:15:35.879438 [DEBUG] raft-net: 127.0.0.1:35719 accepted connection from: 127.0.0.1:48736 - raft_test.go:101: 06:15:35.879463 [DEBUG] raft-net: 127.0.0.1:35719 accepted connection from: 127.0.0.1:48738 - raft_test.go:101: 06:15:35.879993 [DEBUG] raft-net: 127.0.0.1:35719 accepted connection from: 127.0.0.1:48740 - raft_test.go:101: 06:15:35.880019 [DEBUG] raft-net: 127.0.0.1:35719 accepted connection from: 127.0.0.1:48742 - raft_test.go:101: 06:15:35.880090 [DEBUG] raft-net: 127.0.0.1:35719 accepted connection from: 127.0.0.1:48744 +--- PASS: TestNetworkTransport_PooledConn (0.06s) + raft_test.go:101: 17:44:03.906369 [DEBUG] raft-net: 127.0.0.1:39257 accepted connection from: 127.0.0.1:47676 + raft_test.go:101: 17:44:03.913479 [DEBUG] raft-net: 127.0.0.1:39257 accepted connection from: 127.0.0.1:47678 + raft_test.go:101: 17:44:03.913531 [DEBUG] raft-net: 127.0.0.1:39257 accepted connection from: 127.0.0.1:47680 + raft_test.go:101: 17:44:03.913561 [DEBUG] raft-net: 127.0.0.1:39257 accepted connection from: 127.0.0.1:47682 + raft_test.go:101: 17:44:03.958056 [DEBUG] raft-net: 127.0.0.1:39257 accepted connection from: 127.0.0.1:47684 === RUN TestPeersJSON_BadConfiguration --- PASS: TestPeersJSON_BadConfiguration (0.00s) === RUN TestPeersJSON_ReadPeersJSON @@ -1037,229 +1071,285 @@ === RUN TestPeersJSON_ReadConfigJSON --- PASS: TestPeersJSON_ReadConfigJSON (0.00s) === RUN TestRaft_ProtocolVersion_RejectRPC -testLoggerAdapter verbose: cluster: 06:15:35.881571 [DEBUG] Fully Connecting -testLoggerAdapter verbose: server-a891c623-b649-3ede-ace9-cdb4bc9be634: 06:15:35.881693 [INFO] raft: Initial configuration (index=1): [{Suffrage:Voter ID:server-a891c623-b649-3ede-ace9-cdb4bc9be634 Address:a891c623-b649-3ede-ace9-cdb4bc9be634} {Suffrage:Voter ID:server-567822fc-f119-c613-6aee-508c0af83d92 Address:567822fc-f119-c613-6aee-508c0af83d92} {Suffrage:Voter ID:server-e92e9549-911c-301d-9db3-a5fb1d98cb68 Address:e92e9549-911c-301d-9db3-a5fb1d98cb68}] -testLoggerAdapter verbose: server-a891c623-b649-3ede-ace9-cdb4bc9be634: 06:15:35.881780 [INFO] raft: Node at a891c623-b649-3ede-ace9-cdb4bc9be634 [Follower] entering Follower state (Leader: "") -testLoggerAdapter verbose: server-567822fc-f119-c613-6aee-508c0af83d92: 06:15:35.881853 [INFO] raft: Initial configuration (index=1): [{Suffrage:Voter ID:server-a891c623-b649-3ede-ace9-cdb4bc9be634 Address:a891c623-b649-3ede-ace9-cdb4bc9be634} {Suffrage:Voter ID:server-567822fc-f119-c613-6aee-508c0af83d92 Address:567822fc-f119-c613-6aee-508c0af83d92} {Suffrage:Voter ID:server-e92e9549-911c-301d-9db3-a5fb1d98cb68 Address:e92e9549-911c-301d-9db3-a5fb1d98cb68}] -testLoggerAdapter verbose: server-567822fc-f119-c613-6aee-508c0af83d92: 06:15:35.881931 [INFO] raft: Node at 567822fc-f119-c613-6aee-508c0af83d92 [Follower] entering Follower state (Leader: "") -testLoggerAdapter verbose: server-e92e9549-911c-301d-9db3-a5fb1d98cb68: 06:15:35.881983 [INFO] raft: Initial configuration (index=1): [{Suffrage:Voter ID:server-a891c623-b649-3ede-ace9-cdb4bc9be634 Address:a891c623-b649-3ede-ace9-cdb4bc9be634} {Suffrage:Voter ID:server-567822fc-f119-c613-6aee-508c0af83d92 Address:567822fc-f119-c613-6aee-508c0af83d92} {Suffrage:Voter ID:server-e92e9549-911c-301d-9db3-a5fb1d98cb68 Address:e92e9549-911c-301d-9db3-a5fb1d98cb68}] -testLoggerAdapter verbose: cluster: 06:15:35.882016 [INFO] Starting stability test for raft state: Follower -testLoggerAdapter verbose: server-e92e9549-911c-301d-9db3-a5fb1d98cb68: 06:15:35.882042 [INFO] raft: Node at e92e9549-911c-301d-9db3-a5fb1d98cb68 [Follower] entering Follower state (Leader: "") -testLoggerAdapter verbose: server-a891c623-b649-3ede-ace9-cdb4bc9be634: 06:15:35.943618 [WARN] raft: Heartbeat timeout from "" reached, starting election -testLoggerAdapter verbose: server-a891c623-b649-3ede-ace9-cdb4bc9be634: 06:15:35.943669 [INFO] raft: Node at a891c623-b649-3ede-ace9-cdb4bc9be634 [Candidate] entering Candidate state in term 2 -testLoggerAdapter verbose: server-a891c623-b649-3ede-ace9-cdb4bc9be634: 06:15:35.943705 [DEBUG] raft: Votes needed: 2 -testLoggerAdapter verbose: server-a891c623-b649-3ede-ace9-cdb4bc9be634: 06:15:35.943721 [DEBUG] raft: Vote granted from server-a891c623-b649-3ede-ace9-cdb4bc9be634 in term 2. Tally: 1 -testLoggerAdapter verbose: server-a891c623-b649-3ede-ace9-cdb4bc9be634: 06:15:35.943759 [DEBUG] raft: Vote granted from server-e92e9549-911c-301d-9db3-a5fb1d98cb68 in term 2. Tally: 2 -testLoggerAdapter verbose: cluster: 06:15:35.943765 [DEBUG] Resetting stability timeout -testLoggerAdapter verbose: server-a891c623-b649-3ede-ace9-cdb4bc9be634: 06:15:35.943777 [INFO] raft: Election won. Tally: 2 -testLoggerAdapter verbose: cluster: 06:15:35.943793 [DEBUG] Resetting stability timeout -testLoggerAdapter verbose: server-a891c623-b649-3ede-ace9-cdb4bc9be634: 06:15:35.943803 [INFO] raft: Node at a891c623-b649-3ede-ace9-cdb4bc9be634 [Leader] entering Leader state -testLoggerAdapter verbose: cluster: 06:15:35.943809 [DEBUG] Resetting stability timeout -testLoggerAdapter verbose: server-a891c623-b649-3ede-ace9-cdb4bc9be634: 06:15:35.943820 [INFO] raft: Added peer server-567822fc-f119-c613-6aee-508c0af83d92, starting replication -testLoggerAdapter verbose: cluster: 06:15:35.943826 [DEBUG] Resetting stability timeout -testLoggerAdapter verbose: server-a891c623-b649-3ede-ace9-cdb4bc9be634: 06:15:35.943837 [INFO] raft: Added peer server-e92e9549-911c-301d-9db3-a5fb1d98cb68, starting replication -testLoggerAdapter verbose: server-a891c623-b649-3ede-ace9-cdb4bc9be634: 06:15:35.943932 [INFO] raft: pipelining replication to peer {Voter server-e92e9549-911c-301d-9db3-a5fb1d98cb68 e92e9549-911c-301d-9db3-a5fb1d98cb68} -testLoggerAdapter verbose: server-a891c623-b649-3ede-ace9-cdb4bc9be634: 06:15:35.943961 [INFO] raft: pipelining replication to peer {Voter server-567822fc-f119-c613-6aee-508c0af83d92 567822fc-f119-c613-6aee-508c0af83d92} -testLoggerAdapter verbose: cluster: 06:15:36.049195 [INFO] Stable state for Follower reached at 2023-04-23 06:15:35.943941179 +0000 UTC m=+2.585337260 (2 nodes), 61.90115ms from start of poll, 62.34384ms from cluster start. Timeout at 2023-04-23 06:15:36.049086763 +0000 UTC m=+2.690482802, 105.145542ms after stability -testLoggerAdapter verbose: cluster: 06:15:36.049224 [INFO] Starting stability test for raft state: Leader -testLoggerAdapter verbose: cluster: 06:15:36.154424 [INFO] Stable state for Leader reached at 2023-04-23 06:15:36.049235735 +0000 UTC m=+2.690631750 (1 nodes), 535ns from start of poll, 167.63833ms from cluster start. Timeout at 2023-04-23 06:15:36.154378755 +0000 UTC m=+2.795774795, 105.143045ms after stability -testLoggerAdapter verbose: server-a891c623-b649-3ede-ace9-cdb4bc9be634: 06:15:36.154499 [INFO] raft: aborting pipeline replication to peer {Voter server-e92e9549-911c-301d-9db3-a5fb1d98cb68 e92e9549-911c-301d-9db3-a5fb1d98cb68} -testLoggerAdapter verbose: server-a891c623-b649-3ede-ace9-cdb4bc9be634: 06:15:36.154509 [INFO] raft: aborting pipeline replication to peer {Voter server-567822fc-f119-c613-6aee-508c0af83d92 567822fc-f119-c613-6aee-508c0af83d92} ---- PASS: TestRaft_ProtocolVersion_RejectRPC (0.27s) - raft_test.go:97: cluster: 06:15:35.881571 [DEBUG] Fully Connecting - raft_test.go:97: server-a891c623-b649-3ede-ace9-cdb4bc9be634: 06:15:35.881693 [INFO] raft: Initial configuration (index=1): [{Suffrage:Voter ID:server-a891c623-b649-3ede-ace9-cdb4bc9be634 Address:a891c623-b649-3ede-ace9-cdb4bc9be634} {Suffrage:Voter ID:server-567822fc-f119-c613-6aee-508c0af83d92 Address:567822fc-f119-c613-6aee-508c0af83d92} {Suffrage:Voter ID:server-e92e9549-911c-301d-9db3-a5fb1d98cb68 Address:e92e9549-911c-301d-9db3-a5fb1d98cb68}] - raft_test.go:97: server-a891c623-b649-3ede-ace9-cdb4bc9be634: 06:15:35.881780 [INFO] raft: Node at a891c623-b649-3ede-ace9-cdb4bc9be634 [Follower] entering Follower state (Leader: "") - raft_test.go:97: server-567822fc-f119-c613-6aee-508c0af83d92: 06:15:35.881853 [INFO] raft: Initial configuration (index=1): [{Suffrage:Voter ID:server-a891c623-b649-3ede-ace9-cdb4bc9be634 Address:a891c623-b649-3ede-ace9-cdb4bc9be634} {Suffrage:Voter ID:server-567822fc-f119-c613-6aee-508c0af83d92 Address:567822fc-f119-c613-6aee-508c0af83d92} {Suffrage:Voter ID:server-e92e9549-911c-301d-9db3-a5fb1d98cb68 Address:e92e9549-911c-301d-9db3-a5fb1d98cb68}] - raft_test.go:97: server-567822fc-f119-c613-6aee-508c0af83d92: 06:15:35.881931 [INFO] raft: Node at 567822fc-f119-c613-6aee-508c0af83d92 [Follower] entering Follower state (Leader: "") - raft_test.go:97: server-e92e9549-911c-301d-9db3-a5fb1d98cb68: 06:15:35.881983 [INFO] raft: Initial configuration (index=1): [{Suffrage:Voter ID:server-a891c623-b649-3ede-ace9-cdb4bc9be634 Address:a891c623-b649-3ede-ace9-cdb4bc9be634} {Suffrage:Voter ID:server-567822fc-f119-c613-6aee-508c0af83d92 Address:567822fc-f119-c613-6aee-508c0af83d92} {Suffrage:Voter ID:server-e92e9549-911c-301d-9db3-a5fb1d98cb68 Address:e92e9549-911c-301d-9db3-a5fb1d98cb68}] - raft_test.go:97: cluster: 06:15:35.882016 [INFO] Starting stability test for raft state: Follower - raft_test.go:97: server-e92e9549-911c-301d-9db3-a5fb1d98cb68: 06:15:35.882042 [INFO] raft: Node at e92e9549-911c-301d-9db3-a5fb1d98cb68 [Follower] entering Follower state (Leader: "") - raft_test.go:97: server-a891c623-b649-3ede-ace9-cdb4bc9be634: 06:15:35.943618 [WARN] raft: Heartbeat timeout from "" reached, starting election - raft_test.go:97: server-a891c623-b649-3ede-ace9-cdb4bc9be634: 06:15:35.943669 [INFO] raft: Node at a891c623-b649-3ede-ace9-cdb4bc9be634 [Candidate] entering Candidate state in term 2 - raft_test.go:97: server-a891c623-b649-3ede-ace9-cdb4bc9be634: 06:15:35.943705 [DEBUG] raft: Votes needed: 2 - raft_test.go:97: server-a891c623-b649-3ede-ace9-cdb4bc9be634: 06:15:35.943721 [DEBUG] raft: Vote granted from server-a891c623-b649-3ede-ace9-cdb4bc9be634 in term 2. Tally: 1 - raft_test.go:97: server-a891c623-b649-3ede-ace9-cdb4bc9be634: 06:15:35.943759 [DEBUG] raft: Vote granted from server-e92e9549-911c-301d-9db3-a5fb1d98cb68 in term 2. Tally: 2 - raft_test.go:97: cluster: 06:15:35.943765 [DEBUG] Resetting stability timeout - raft_test.go:97: server-a891c623-b649-3ede-ace9-cdb4bc9be634: 06:15:35.943777 [INFO] raft: Election won. Tally: 2 - raft_test.go:97: cluster: 06:15:35.943793 [DEBUG] Resetting stability timeout - raft_test.go:97: server-a891c623-b649-3ede-ace9-cdb4bc9be634: 06:15:35.943803 [INFO] raft: Node at a891c623-b649-3ede-ace9-cdb4bc9be634 [Leader] entering Leader state - raft_test.go:97: cluster: 06:15:35.943809 [DEBUG] Resetting stability timeout - raft_test.go:97: server-a891c623-b649-3ede-ace9-cdb4bc9be634: 06:15:35.943820 [INFO] raft: Added peer server-567822fc-f119-c613-6aee-508c0af83d92, starting replication - raft_test.go:97: server-a891c623-b649-3ede-ace9-cdb4bc9be634: 06:15:35.943837 [INFO] raft: Added peer server-e92e9549-911c-301d-9db3-a5fb1d98cb68, starting replication - raft_test.go:97: cluster: 06:15:35.943826 [DEBUG] Resetting stability timeout - raft_test.go:97: server-a891c623-b649-3ede-ace9-cdb4bc9be634: 06:15:35.943932 [INFO] raft: pipelining replication to peer {Voter server-e92e9549-911c-301d-9db3-a5fb1d98cb68 e92e9549-911c-301d-9db3-a5fb1d98cb68} - raft_test.go:97: server-a891c623-b649-3ede-ace9-cdb4bc9be634: 06:15:35.943961 [INFO] raft: pipelining replication to peer {Voter server-567822fc-f119-c613-6aee-508c0af83d92 567822fc-f119-c613-6aee-508c0af83d92} - raft_test.go:97: cluster: 06:15:36.049195 [INFO] Stable state for Follower reached at 2023-04-23 06:15:35.943941179 +0000 UTC m=+2.585337260 (2 nodes), 61.90115ms from start of poll, 62.34384ms from cluster start. Timeout at 2023-04-23 06:15:36.049086763 +0000 UTC m=+2.690482802, 105.145542ms after stability - raft_test.go:97: cluster: 06:15:36.049224 [INFO] Starting stability test for raft state: Leader - raft_test.go:97: cluster: 06:15:36.154424 [INFO] Stable state for Leader reached at 2023-04-23 06:15:36.049235735 +0000 UTC m=+2.690631750 (1 nodes), 535ns from start of poll, 167.63833ms from cluster start. Timeout at 2023-04-23 06:15:36.154378755 +0000 UTC m=+2.795774795, 105.143045ms after stability - raft_test.go:97: server-a891c623-b649-3ede-ace9-cdb4bc9be634: 06:15:36.154499 [INFO] raft: aborting pipeline replication to peer {Voter server-e92e9549-911c-301d-9db3-a5fb1d98cb68 e92e9549-911c-301d-9db3-a5fb1d98cb68} - raft_test.go:97: server-a891c623-b649-3ede-ace9-cdb4bc9be634: 06:15:36.154509 [INFO] raft: aborting pipeline replication to peer {Voter server-567822fc-f119-c613-6aee-508c0af83d92 567822fc-f119-c613-6aee-508c0af83d92} +testLoggerAdapter verbose: cluster: 17:44:03.964256 [DEBUG] Fully Connecting +testLoggerAdapter verbose: server-5be6a2e5-3512-137a-392e-1f446235bc48: 17:44:03.964428 [INFO] raft: Initial configuration (index=1): [{Suffrage:Voter ID:server-5be6a2e5-3512-137a-392e-1f446235bc48 Address:5be6a2e5-3512-137a-392e-1f446235bc48} {Suffrage:Voter ID:server-df67a9f9-f6e1-295d-e292-1baafe116bdb Address:df67a9f9-f6e1-295d-e292-1baafe116bdb} {Suffrage:Voter ID:server-2796af15-5c34-599b-6b03-94d3864123f7 Address:2796af15-5c34-599b-6b03-94d3864123f7}] +testLoggerAdapter verbose: server-df67a9f9-f6e1-295d-e292-1baafe116bdb: 17:44:03.964543 [INFO] raft: Initial configuration (index=1): [{Suffrage:Voter ID:server-5be6a2e5-3512-137a-392e-1f446235bc48 Address:5be6a2e5-3512-137a-392e-1f446235bc48} {Suffrage:Voter ID:server-df67a9f9-f6e1-295d-e292-1baafe116bdb Address:df67a9f9-f6e1-295d-e292-1baafe116bdb} {Suffrage:Voter ID:server-2796af15-5c34-599b-6b03-94d3864123f7 Address:2796af15-5c34-599b-6b03-94d3864123f7}] +testLoggerAdapter verbose: server-2796af15-5c34-599b-6b03-94d3864123f7: 17:44:03.964658 [INFO] raft: Initial configuration (index=1): [{Suffrage:Voter ID:server-5be6a2e5-3512-137a-392e-1f446235bc48 Address:5be6a2e5-3512-137a-392e-1f446235bc48} {Suffrage:Voter ID:server-df67a9f9-f6e1-295d-e292-1baafe116bdb Address:df67a9f9-f6e1-295d-e292-1baafe116bdb} {Suffrage:Voter ID:server-2796af15-5c34-599b-6b03-94d3864123f7 Address:2796af15-5c34-599b-6b03-94d3864123f7}] +testLoggerAdapter verbose: cluster: 17:44:03.964690 [INFO] Starting stability test for raft state: Follower +testLoggerAdapter verbose: server-5be6a2e5-3512-137a-392e-1f446235bc48: 17:44:03.964801 [INFO] raft: Node at 5be6a2e5-3512-137a-392e-1f446235bc48 [Follower] entering Follower state (Leader: "") +testLoggerAdapter verbose: server-df67a9f9-f6e1-295d-e292-1baafe116bdb: 17:44:03.964856 [INFO] raft: Node at df67a9f9-f6e1-295d-e292-1baafe116bdb [Follower] entering Follower state (Leader: "") +testLoggerAdapter verbose: server-2796af15-5c34-599b-6b03-94d3864123f7: 17:44:03.964902 [INFO] raft: Node at 2796af15-5c34-599b-6b03-94d3864123f7 [Follower] entering Follower state (Leader: "") +testLoggerAdapter verbose: server-2796af15-5c34-599b-6b03-94d3864123f7: 17:44:04.026196 [WARN] raft: Heartbeat timeout from "" reached, starting election +testLoggerAdapter verbose: server-2796af15-5c34-599b-6b03-94d3864123f7: 17:44:04.026314 [INFO] raft: Node at 2796af15-5c34-599b-6b03-94d3864123f7 [Candidate] entering Candidate state in term 2 +testLoggerAdapter verbose: server-2796af15-5c34-599b-6b03-94d3864123f7: 17:44:04.026372 [DEBUG] raft: Votes needed: 2 +testLoggerAdapter verbose: server-2796af15-5c34-599b-6b03-94d3864123f7: 17:44:04.026398 [DEBUG] raft: Vote granted from server-2796af15-5c34-599b-6b03-94d3864123f7 in term 2. Tally: 1 +testLoggerAdapter verbose: server-2796af15-5c34-599b-6b03-94d3864123f7: 17:44:04.026468 [DEBUG] raft: Vote granted from server-df67a9f9-f6e1-295d-e292-1baafe116bdb in term 2. Tally: 2 +testLoggerAdapter verbose: server-2796af15-5c34-599b-6b03-94d3864123f7: 17:44:04.026510 [INFO] raft: Election won. Tally: 2 +testLoggerAdapter verbose: server-2796af15-5c34-599b-6b03-94d3864123f7: 17:44:04.026530 [INFO] raft: Node at 2796af15-5c34-599b-6b03-94d3864123f7 [Leader] entering Leader state +testLoggerAdapter verbose: server-2796af15-5c34-599b-6b03-94d3864123f7: 17:44:04.026563 [INFO] raft: Added peer server-5be6a2e5-3512-137a-392e-1f446235bc48, starting replication +testLoggerAdapter verbose: server-2796af15-5c34-599b-6b03-94d3864123f7: 17:44:04.026586 [INFO] raft: Added peer server-df67a9f9-f6e1-295d-e292-1baafe116bdb, starting replication +testLoggerAdapter verbose: server-2796af15-5c34-599b-6b03-94d3864123f7: 17:44:04.026687 [INFO] raft: pipelining replication to peer {Voter server-df67a9f9-f6e1-295d-e292-1baafe116bdb df67a9f9-f6e1-295d-e292-1baafe116bdb} +testLoggerAdapter verbose: cluster: 17:44:04.026717 [DEBUG] Resetting stability timeout +testLoggerAdapter verbose: cluster: 17:44:04.026741 [DEBUG] Resetting stability timeout +testLoggerAdapter verbose: cluster: 17:44:04.026762 [DEBUG] Resetting stability timeout +testLoggerAdapter verbose: server-2796af15-5c34-599b-6b03-94d3864123f7: 17:44:04.026856 [INFO] raft: pipelining replication to peer {Voter server-5be6a2e5-3512-137a-392e-1f446235bc48 5be6a2e5-3512-137a-392e-1f446235bc48} +testLoggerAdapter verbose: cluster: 17:44:04.026899 [DEBUG] Resetting stability timeout +testLoggerAdapter verbose: cluster: 17:44:04.135766 [INFO] Stable state for Follower reached at 2021-02-15 17:44:04.026922977 +0000 UTC m=+0.766078437 (2 nodes), 62.188326ms from start of poll, 62.637779ms from cluster start. Timeout at 2021-02-15 17:44:04.134020278 +0000 UTC m=+0.873172275, 107.093838ms after stability +testLoggerAdapter verbose: cluster: 17:44:04.135834 [INFO] Starting stability test for raft state: Leader +testLoggerAdapter verbose: cluster: 17:44:04.246195 [INFO] Stable state for Leader reached at 2021-02-15 17:44:04.135859488 +0000 UTC m=+0.875011351 (1 nodes), 3.118µs from start of poll, 171.570693ms from cluster start. Timeout at 2021-02-15 17:44:04.246061734 +0000 UTC m=+0.985215682, 110.204331ms after stability +testLoggerAdapter verbose: server-2796af15-5c34-599b-6b03-94d3864123f7: 17:44:04.246362 [INFO] raft: aborting pipeline replication to peer {Voter server-df67a9f9-f6e1-295d-e292-1baafe116bdb df67a9f9-f6e1-295d-e292-1baafe116bdb} +testLoggerAdapter verbose: server-2796af15-5c34-599b-6b03-94d3864123f7: 17:44:04.246414 [INFO] raft: aborting pipeline replication to peer {Voter server-5be6a2e5-3512-137a-392e-1f446235bc48 5be6a2e5-3512-137a-392e-1f446235bc48} +--- PASS: TestRaft_ProtocolVersion_RejectRPC (0.28s) + raft_test.go:97: cluster: 17:44:03.964256 [DEBUG] Fully Connecting + raft_test.go:97: server-5be6a2e5-3512-137a-392e-1f446235bc48: 17:44:03.964428 [INFO] raft: Initial configuration (index=1): [{Suffrage:Voter ID:server-5be6a2e5-3512-137a-392e-1f446235bc48 Address:5be6a2e5-3512-137a-392e-1f446235bc48} {Suffrage:Voter ID:server-df67a9f9-f6e1-295d-e292-1baafe116bdb Address:df67a9f9-f6e1-295d-e292-1baafe116bdb} {Suffrage:Voter ID:server-2796af15-5c34-599b-6b03-94d3864123f7 Address:2796af15-5c34-599b-6b03-94d3864123f7}] + raft_test.go:97: server-df67a9f9-f6e1-295d-e292-1baafe116bdb: 17:44:03.964543 [INFO] raft: Initial configuration (index=1): [{Suffrage:Voter ID:server-5be6a2e5-3512-137a-392e-1f446235bc48 Address:5be6a2e5-3512-137a-392e-1f446235bc48} {Suffrage:Voter ID:server-df67a9f9-f6e1-295d-e292-1baafe116bdb Address:df67a9f9-f6e1-295d-e292-1baafe116bdb} {Suffrage:Voter ID:server-2796af15-5c34-599b-6b03-94d3864123f7 Address:2796af15-5c34-599b-6b03-94d3864123f7}] + raft_test.go:97: server-2796af15-5c34-599b-6b03-94d3864123f7: 17:44:03.964658 [INFO] raft: Initial configuration (index=1): [{Suffrage:Voter ID:server-5be6a2e5-3512-137a-392e-1f446235bc48 Address:5be6a2e5-3512-137a-392e-1f446235bc48} {Suffrage:Voter ID:server-df67a9f9-f6e1-295d-e292-1baafe116bdb Address:df67a9f9-f6e1-295d-e292-1baafe116bdb} {Suffrage:Voter ID:server-2796af15-5c34-599b-6b03-94d3864123f7 Address:2796af15-5c34-599b-6b03-94d3864123f7}] + raft_test.go:97: cluster: 17:44:03.964690 [INFO] Starting stability test for raft state: Follower + raft_test.go:97: server-5be6a2e5-3512-137a-392e-1f446235bc48: 17:44:03.964801 [INFO] raft: Node at 5be6a2e5-3512-137a-392e-1f446235bc48 [Follower] entering Follower state (Leader: "") + raft_test.go:97: server-df67a9f9-f6e1-295d-e292-1baafe116bdb: 17:44:03.964856 [INFO] raft: Node at df67a9f9-f6e1-295d-e292-1baafe116bdb [Follower] entering Follower state (Leader: "") + raft_test.go:97: server-2796af15-5c34-599b-6b03-94d3864123f7: 17:44:03.964902 [INFO] raft: Node at 2796af15-5c34-599b-6b03-94d3864123f7 [Follower] entering Follower state (Leader: "") + raft_test.go:97: server-2796af15-5c34-599b-6b03-94d3864123f7: 17:44:04.026196 [WARN] raft: Heartbeat timeout from "" reached, starting election + raft_test.go:97: server-2796af15-5c34-599b-6b03-94d3864123f7: 17:44:04.026314 [INFO] raft: Node at 2796af15-5c34-599b-6b03-94d3864123f7 [Candidate] entering Candidate state in term 2 + raft_test.go:97: server-2796af15-5c34-599b-6b03-94d3864123f7: 17:44:04.026372 [DEBUG] raft: Votes needed: 2 + raft_test.go:97: server-2796af15-5c34-599b-6b03-94d3864123f7: 17:44:04.026398 [DEBUG] raft: Vote granted from server-2796af15-5c34-599b-6b03-94d3864123f7 in term 2. Tally: 1 + raft_test.go:97: server-2796af15-5c34-599b-6b03-94d3864123f7: 17:44:04.026468 [DEBUG] raft: Vote granted from server-df67a9f9-f6e1-295d-e292-1baafe116bdb in term 2. Tally: 2 + raft_test.go:97: server-2796af15-5c34-599b-6b03-94d3864123f7: 17:44:04.026510 [INFO] raft: Election won. Tally: 2 + raft_test.go:97: server-2796af15-5c34-599b-6b03-94d3864123f7: 17:44:04.026530 [INFO] raft: Node at 2796af15-5c34-599b-6b03-94d3864123f7 [Leader] entering Leader state + raft_test.go:97: server-2796af15-5c34-599b-6b03-94d3864123f7: 17:44:04.026563 [INFO] raft: Added peer server-5be6a2e5-3512-137a-392e-1f446235bc48, starting replication + raft_test.go:97: server-2796af15-5c34-599b-6b03-94d3864123f7: 17:44:04.026586 [INFO] raft: Added peer server-df67a9f9-f6e1-295d-e292-1baafe116bdb, starting replication + raft_test.go:97: server-2796af15-5c34-599b-6b03-94d3864123f7: 17:44:04.026687 [INFO] raft: pipelining replication to peer {Voter server-df67a9f9-f6e1-295d-e292-1baafe116bdb df67a9f9-f6e1-295d-e292-1baafe116bdb} + raft_test.go:97: cluster: 17:44:04.026717 [DEBUG] Resetting stability timeout + raft_test.go:97: cluster: 17:44:04.026741 [DEBUG] Resetting stability timeout + raft_test.go:97: cluster: 17:44:04.026762 [DEBUG] Resetting stability timeout + raft_test.go:97: server-2796af15-5c34-599b-6b03-94d3864123f7: 17:44:04.026856 [INFO] raft: pipelining replication to peer {Voter server-5be6a2e5-3512-137a-392e-1f446235bc48 5be6a2e5-3512-137a-392e-1f446235bc48} + raft_test.go:97: cluster: 17:44:04.026899 [DEBUG] Resetting stability timeout + raft_test.go:97: cluster: 17:44:04.135766 [INFO] Stable state for Follower reached at 2021-02-15 17:44:04.026922977 +0000 UTC m=+0.766078437 (2 nodes), 62.188326ms from start of poll, 62.637779ms from cluster start. Timeout at 2021-02-15 17:44:04.134020278 +0000 UTC m=+0.873172275, 107.093838ms after stability + raft_test.go:97: cluster: 17:44:04.135834 [INFO] Starting stability test for raft state: Leader + raft_test.go:97: cluster: 17:44:04.246195 [INFO] Stable state for Leader reached at 2021-02-15 17:44:04.135859488 +0000 UTC m=+0.875011351 (1 nodes), 3.118µs from start of poll, 171.570693ms from cluster start. Timeout at 2021-02-15 17:44:04.246061734 +0000 UTC m=+0.985215682, 110.204331ms after stability + raft_test.go:97: server-2796af15-5c34-599b-6b03-94d3864123f7: 17:44:04.246362 [INFO] raft: aborting pipeline replication to peer {Voter server-df67a9f9-f6e1-295d-e292-1baafe116bdb df67a9f9-f6e1-295d-e292-1baafe116bdb} + raft_test.go:97: server-2796af15-5c34-599b-6b03-94d3864123f7: 17:44:04.246414 [INFO] raft: aborting pipeline replication to peer {Voter server-5be6a2e5-3512-137a-392e-1f446235bc48 5be6a2e5-3512-137a-392e-1f446235bc48} === RUN TestRaft_ProtocolVersion_Upgrade_1_2 -testLoggerAdapter verbose: cluster: 06:15:36.155821 [DEBUG] Fully Connecting -testLoggerAdapter verbose: 28cda93a-8b14-a7c7-2fa2-6fa1557363be: 06:15:36.155984 [INFO] raft: Initial configuration (index=1): [{Suffrage:Voter ID:28cda93a-8b14-a7c7-2fa2-6fa1557363be Address:28cda93a-8b14-a7c7-2fa2-6fa1557363be} {Suffrage:Voter ID:fa891986-0caf-dd48-4def-be618f3ceb49 Address:fa891986-0caf-dd48-4def-be618f3ceb49}] -testLoggerAdapter verbose: 28cda93a-8b14-a7c7-2fa2-6fa1557363be: 06:15:36.156075 [INFO] raft: Node at 28cda93a-8b14-a7c7-2fa2-6fa1557363be [Follower] entering Follower state (Leader: "") -testLoggerAdapter verbose: fa891986-0caf-dd48-4def-be618f3ceb49: 06:15:36.156118 [INFO] raft: Initial configuration (index=1): [{Suffrage:Voter ID:28cda93a-8b14-a7c7-2fa2-6fa1557363be Address:28cda93a-8b14-a7c7-2fa2-6fa1557363be} {Suffrage:Voter ID:fa891986-0caf-dd48-4def-be618f3ceb49 Address:fa891986-0caf-dd48-4def-be618f3ceb49}] -testLoggerAdapter verbose: fa891986-0caf-dd48-4def-be618f3ceb49: 06:15:36.156174 [INFO] raft: Node at fa891986-0caf-dd48-4def-be618f3ceb49 [Follower] entering Follower state (Leader: "") -testLoggerAdapter verbose: cluster: 06:15:36.156299 [DEBUG] Fully Connecting -testLoggerAdapter verbose: b6ac1171-8027-b2bd-47e1-944b13f94c0d: 06:15:36.156364 [INFO] raft: Initial configuration (index=0): [] -testLoggerAdapter verbose: cluster: 06:15:36.156404 [DEBUG] Fully Connecting -testLoggerAdapter verbose: b6ac1171-8027-b2bd-47e1-944b13f94c0d: 06:15:36.156420 [INFO] raft: Node at b6ac1171-8027-b2bd-47e1-944b13f94c0d [Follower] entering Follower state (Leader: "") -testLoggerAdapter verbose: cluster: 06:15:36.156426 [INFO] Starting stability test for raft state: Leader -testLoggerAdapter verbose: 28cda93a-8b14-a7c7-2fa2-6fa1557363be: 06:15:36.208290 [WARN] raft: Heartbeat timeout from "" reached, starting election -testLoggerAdapter verbose: cluster: 06:15:36.208340 [DEBUG] Resetting stability timeout -testLoggerAdapter verbose: 28cda93a-8b14-a7c7-2fa2-6fa1557363be: 06:15:36.208376 [INFO] raft: Node at 28cda93a-8b14-a7c7-2fa2-6fa1557363be [Candidate] entering Candidate state in term 2 -testLoggerAdapter verbose: 28cda93a-8b14-a7c7-2fa2-6fa1557363be: 06:15:36.208420 [DEBUG] raft: Votes needed: 2 -testLoggerAdapter verbose: 28cda93a-8b14-a7c7-2fa2-6fa1557363be: 06:15:36.208434 [DEBUG] raft: Vote granted from 28cda93a-8b14-a7c7-2fa2-6fa1557363be in term 2. Tally: 1 -testLoggerAdapter verbose: 28cda93a-8b14-a7c7-2fa2-6fa1557363be: 06:15:36.208475 [DEBUG] raft: Vote granted from fa891986-0caf-dd48-4def-be618f3ceb49 in term 2. Tally: 2 -testLoggerAdapter verbose: 28cda93a-8b14-a7c7-2fa2-6fa1557363be: 06:15:36.208487 [INFO] raft: Election won. Tally: 2 -testLoggerAdapter verbose: 28cda93a-8b14-a7c7-2fa2-6fa1557363be: 06:15:36.208498 [INFO] raft: Node at 28cda93a-8b14-a7c7-2fa2-6fa1557363be [Leader] entering Leader state -testLoggerAdapter verbose: 28cda93a-8b14-a7c7-2fa2-6fa1557363be: 06:15:36.208515 [INFO] raft: Added peer fa891986-0caf-dd48-4def-be618f3ceb49, starting replication -testLoggerAdapter verbose: cluster: 06:15:36.208519 [DEBUG] Resetting stability timeout -testLoggerAdapter verbose: cluster: 06:15:36.208560 [DEBUG] Resetting stability timeout -testLoggerAdapter verbose: 28cda93a-8b14-a7c7-2fa2-6fa1557363be: 06:15:36.208595 [INFO] raft: pipelining replication to peer {Voter fa891986-0caf-dd48-4def-be618f3ceb49 fa891986-0caf-dd48-4def-be618f3ceb49} -testLoggerAdapter verbose: b6ac1171-8027-b2bd-47e1-944b13f94c0d: 06:15:36.239685 [WARN] raft: no known peers, aborting election -testLoggerAdapter verbose: cluster: 06:15:36.313749 [INFO] Stable state for Leader reached at 2023-04-23 06:15:36.208578194 +0000 UTC m=+2.849974263 (1 nodes), 52.133225ms from start of poll, 52.713629ms from cluster start. Timeout at 2023-04-23 06:15:36.313664267 +0000 UTC m=+2.955060323, 105.08606ms after stability -testLoggerAdapter verbose: cluster: 06:15:36.313791 [INFO] Starting stability test for raft state: Leader -testLoggerAdapter verbose: cluster: 06:15:36.418997 [INFO] Stable state for Leader reached at 2023-04-23 06:15:36.313802708 +0000 UTC m=+2.955198723 (1 nodes), 702ns from start of poll, 157.938089ms from cluster start. Timeout at 2023-04-23 06:15:36.418895207 +0000 UTC m=+3.060291291, 105.092568ms after stability -testLoggerAdapter verbose: cluster: 06:15:36.419043 [INFO] Starting stability test for raft state: Leader -testLoggerAdapter verbose: cluster: 06:15:36.524248 [INFO] Stable state for Leader reached at 2023-04-23 06:15:36.419055742 +0000 UTC m=+3.060451755 (1 nodes), 590ns from start of poll, 263.191121ms from cluster start. Timeout at 2023-04-23 06:15:36.524132456 +0000 UTC m=+3.165528505, 105.07675ms after stability -testLoggerAdapter verbose: 28cda93a-8b14-a7c7-2fa2-6fa1557363be: 06:15:36.524311 [INFO] raft: Updating configuration with AddStaging (b6ac1171-8027-b2bd-47e1-944b13f94c0d, b6ac1171-8027-b2bd-47e1-944b13f94c0d) to [{Suffrage:Voter ID:28cda93a-8b14-a7c7-2fa2-6fa1557363be Address:28cda93a-8b14-a7c7-2fa2-6fa1557363be} {Suffrage:Voter ID:fa891986-0caf-dd48-4def-be618f3ceb49 Address:fa891986-0caf-dd48-4def-be618f3ceb49} {Suffrage:Voter ID:b6ac1171-8027-b2bd-47e1-944b13f94c0d Address:b6ac1171-8027-b2bd-47e1-944b13f94c0d}] -testLoggerAdapter verbose: 28cda93a-8b14-a7c7-2fa2-6fa1557363be: 06:15:36.524359 [INFO] raft: Added peer b6ac1171-8027-b2bd-47e1-944b13f94c0d, starting replication -testLoggerAdapter verbose: b6ac1171-8027-b2bd-47e1-944b13f94c0d: 06:15:36.524401 [WARN] raft: Failed to get previous log: 3 log not found (last: 0) -testLoggerAdapter verbose: 28cda93a-8b14-a7c7-2fa2-6fa1557363be: 06:15:36.524437 [WARN] raft: AppendEntries to {Voter b6ac1171-8027-b2bd-47e1-944b13f94c0d b6ac1171-8027-b2bd-47e1-944b13f94c0d} rejected, sending older logs (next: 1) -testLoggerAdapter verbose: 28cda93a-8b14-a7c7-2fa2-6fa1557363be: 06:15:36.524485 [INFO] raft: pipelining replication to peer {Voter b6ac1171-8027-b2bd-47e1-944b13f94c0d b6ac1171-8027-b2bd-47e1-944b13f94c0d} -testLoggerAdapter verbose: cluster: 06:15:36.524536 [INFO] Starting stability test for raft state: Leader -testLoggerAdapter verbose: cluster: 06:15:36.629783 [INFO] Stable state for Leader reached at 2023-04-23 06:15:36.524571219 +0000 UTC m=+3.165967233 (1 nodes), 639ns from start of poll, 368.706599ms from cluster start. Timeout at 2023-04-23 06:15:36.629710294 +0000 UTC m=+3.271106342, 105.139109ms after stability -testLoggerAdapter verbose: cluster: 06:15:36.629818 [INFO] Starting stability test for raft state: Leader -testLoggerAdapter verbose: cluster: 06:15:36.735030 [INFO] Stable state for Leader reached at 2023-04-23 06:15:36.629837185 +0000 UTC m=+3.271233233 (1 nodes), 838ns from start of poll, 473.972599ms from cluster start. Timeout at 2023-04-23 06:15:36.734950122 +0000 UTC m=+3.376346139, 105.112906ms after stability -testLoggerAdapter verbose: 28cda93a-8b14-a7c7-2fa2-6fa1557363be: 06:15:36.735100 [INFO] raft: Updating configuration with RemoveServer (b6ac1171-8027-b2bd-47e1-944b13f94c0d, ) to [{Suffrage:Voter ID:28cda93a-8b14-a7c7-2fa2-6fa1557363be Address:28cda93a-8b14-a7c7-2fa2-6fa1557363be} {Suffrage:Voter ID:fa891986-0caf-dd48-4def-be618f3ceb49 Address:fa891986-0caf-dd48-4def-be618f3ceb49}] -testLoggerAdapter verbose: 28cda93a-8b14-a7c7-2fa2-6fa1557363be: 06:15:36.735187 [INFO] raft: Removed peer b6ac1171-8027-b2bd-47e1-944b13f94c0d, stopping replication after 4 -testLoggerAdapter verbose: 28cda93a-8b14-a7c7-2fa2-6fa1557363be: 06:15:36.735239 [INFO] raft: aborting pipeline replication to peer {Voter b6ac1171-8027-b2bd-47e1-944b13f94c0d b6ac1171-8027-b2bd-47e1-944b13f94c0d} -testLoggerAdapter verbose: 28cda93a-8b14-a7c7-2fa2-6fa1557363be: 06:15:36.735288 [INFO] raft: aborting pipeline replication to peer {Voter fa891986-0caf-dd48-4def-be618f3ceb49 fa891986-0caf-dd48-4def-be618f3ceb49} -testLoggerAdapter verbose: 28cda93a-8b14-a7c7-2fa2-6fa1557363be: 06:15:36.785445 [ERR] raft: Failed to heartbeat to b6ac1171-8027-b2bd-47e1-944b13f94c0d: command timed out ---- PASS: TestRaft_ProtocolVersion_Upgrade_1_2 (0.63s) - raft_test.go:97: cluster: 06:15:36.155821 [DEBUG] Fully Connecting - raft_test.go:97: 28cda93a-8b14-a7c7-2fa2-6fa1557363be: 06:15:36.155984 [INFO] raft: Initial configuration (index=1): [{Suffrage:Voter ID:28cda93a-8b14-a7c7-2fa2-6fa1557363be Address:28cda93a-8b14-a7c7-2fa2-6fa1557363be} {Suffrage:Voter ID:fa891986-0caf-dd48-4def-be618f3ceb49 Address:fa891986-0caf-dd48-4def-be618f3ceb49}] - raft_test.go:97: 28cda93a-8b14-a7c7-2fa2-6fa1557363be: 06:15:36.156075 [INFO] raft: Node at 28cda93a-8b14-a7c7-2fa2-6fa1557363be [Follower] entering Follower state (Leader: "") - raft_test.go:97: fa891986-0caf-dd48-4def-be618f3ceb49: 06:15:36.156118 [INFO] raft: Initial configuration (index=1): [{Suffrage:Voter ID:28cda93a-8b14-a7c7-2fa2-6fa1557363be Address:28cda93a-8b14-a7c7-2fa2-6fa1557363be} {Suffrage:Voter ID:fa891986-0caf-dd48-4def-be618f3ceb49 Address:fa891986-0caf-dd48-4def-be618f3ceb49}] - raft_test.go:97: fa891986-0caf-dd48-4def-be618f3ceb49: 06:15:36.156174 [INFO] raft: Node at fa891986-0caf-dd48-4def-be618f3ceb49 [Follower] entering Follower state (Leader: "") - raft_test.go:97: cluster: 06:15:36.156299 [DEBUG] Fully Connecting - raft_test.go:97: b6ac1171-8027-b2bd-47e1-944b13f94c0d: 06:15:36.156364 [INFO] raft: Initial configuration (index=0): [] - raft_test.go:97: cluster: 06:15:36.156404 [DEBUG] Fully Connecting - raft_test.go:97: b6ac1171-8027-b2bd-47e1-944b13f94c0d: 06:15:36.156420 [INFO] raft: Node at b6ac1171-8027-b2bd-47e1-944b13f94c0d [Follower] entering Follower state (Leader: "") - raft_test.go:97: cluster: 06:15:36.156426 [INFO] Starting stability test for raft state: Leader - raft_test.go:97: 28cda93a-8b14-a7c7-2fa2-6fa1557363be: 06:15:36.208290 [WARN] raft: Heartbeat timeout from "" reached, starting election - raft_test.go:97: cluster: 06:15:36.208340 [DEBUG] Resetting stability timeout - raft_test.go:97: 28cda93a-8b14-a7c7-2fa2-6fa1557363be: 06:15:36.208376 [INFO] raft: Node at 28cda93a-8b14-a7c7-2fa2-6fa1557363be [Candidate] entering Candidate state in term 2 - raft_test.go:97: 28cda93a-8b14-a7c7-2fa2-6fa1557363be: 06:15:36.208420 [DEBUG] raft: Votes needed: 2 - raft_test.go:97: 28cda93a-8b14-a7c7-2fa2-6fa1557363be: 06:15:36.208434 [DEBUG] raft: Vote granted from 28cda93a-8b14-a7c7-2fa2-6fa1557363be in term 2. Tally: 1 - raft_test.go:97: 28cda93a-8b14-a7c7-2fa2-6fa1557363be: 06:15:36.208475 [DEBUG] raft: Vote granted from fa891986-0caf-dd48-4def-be618f3ceb49 in term 2. Tally: 2 - raft_test.go:97: 28cda93a-8b14-a7c7-2fa2-6fa1557363be: 06:15:36.208487 [INFO] raft: Election won. Tally: 2 - raft_test.go:97: 28cda93a-8b14-a7c7-2fa2-6fa1557363be: 06:15:36.208498 [INFO] raft: Node at 28cda93a-8b14-a7c7-2fa2-6fa1557363be [Leader] entering Leader state - raft_test.go:97: 28cda93a-8b14-a7c7-2fa2-6fa1557363be: 06:15:36.208515 [INFO] raft: Added peer fa891986-0caf-dd48-4def-be618f3ceb49, starting replication - raft_test.go:97: cluster: 06:15:36.208519 [DEBUG] Resetting stability timeout - raft_test.go:97: cluster: 06:15:36.208560 [DEBUG] Resetting stability timeout - raft_test.go:97: 28cda93a-8b14-a7c7-2fa2-6fa1557363be: 06:15:36.208595 [INFO] raft: pipelining replication to peer {Voter fa891986-0caf-dd48-4def-be618f3ceb49 fa891986-0caf-dd48-4def-be618f3ceb49} - raft_test.go:97: b6ac1171-8027-b2bd-47e1-944b13f94c0d: 06:15:36.239685 [WARN] raft: no known peers, aborting election - raft_test.go:97: cluster: 06:15:36.313749 [INFO] Stable state for Leader reached at 2023-04-23 06:15:36.208578194 +0000 UTC m=+2.849974263 (1 nodes), 52.133225ms from start of poll, 52.713629ms from cluster start. Timeout at 2023-04-23 06:15:36.313664267 +0000 UTC m=+2.955060323, 105.08606ms after stability - raft_test.go:97: cluster: 06:15:36.313791 [INFO] Starting stability test for raft state: Leader - raft_test.go:97: cluster: 06:15:36.418997 [INFO] Stable state for Leader reached at 2023-04-23 06:15:36.313802708 +0000 UTC m=+2.955198723 (1 nodes), 702ns from start of poll, 157.938089ms from cluster start. Timeout at 2023-04-23 06:15:36.418895207 +0000 UTC m=+3.060291291, 105.092568ms after stability - raft_test.go:97: cluster: 06:15:36.419043 [INFO] Starting stability test for raft state: Leader - raft_test.go:97: cluster: 06:15:36.524248 [INFO] Stable state for Leader reached at 2023-04-23 06:15:36.419055742 +0000 UTC m=+3.060451755 (1 nodes), 590ns from start of poll, 263.191121ms from cluster start. Timeout at 2023-04-23 06:15:36.524132456 +0000 UTC m=+3.165528505, 105.07675ms after stability - raft_test.go:97: 28cda93a-8b14-a7c7-2fa2-6fa1557363be: 06:15:36.524311 [INFO] raft: Updating configuration with AddStaging (b6ac1171-8027-b2bd-47e1-944b13f94c0d, b6ac1171-8027-b2bd-47e1-944b13f94c0d) to [{Suffrage:Voter ID:28cda93a-8b14-a7c7-2fa2-6fa1557363be Address:28cda93a-8b14-a7c7-2fa2-6fa1557363be} {Suffrage:Voter ID:fa891986-0caf-dd48-4def-be618f3ceb49 Address:fa891986-0caf-dd48-4def-be618f3ceb49} {Suffrage:Voter ID:b6ac1171-8027-b2bd-47e1-944b13f94c0d Address:b6ac1171-8027-b2bd-47e1-944b13f94c0d}] - raft_test.go:97: 28cda93a-8b14-a7c7-2fa2-6fa1557363be: 06:15:36.524359 [INFO] raft: Added peer b6ac1171-8027-b2bd-47e1-944b13f94c0d, starting replication - raft_test.go:97: b6ac1171-8027-b2bd-47e1-944b13f94c0d: 06:15:36.524401 [WARN] raft: Failed to get previous log: 3 log not found (last: 0) - raft_test.go:97: 28cda93a-8b14-a7c7-2fa2-6fa1557363be: 06:15:36.524437 [WARN] raft: AppendEntries to {Voter b6ac1171-8027-b2bd-47e1-944b13f94c0d b6ac1171-8027-b2bd-47e1-944b13f94c0d} rejected, sending older logs (next: 1) - raft_test.go:97: 28cda93a-8b14-a7c7-2fa2-6fa1557363be: 06:15:36.524485 [INFO] raft: pipelining replication to peer {Voter b6ac1171-8027-b2bd-47e1-944b13f94c0d b6ac1171-8027-b2bd-47e1-944b13f94c0d} - raft_test.go:97: cluster: 06:15:36.524536 [INFO] Starting stability test for raft state: Leader - raft_test.go:97: cluster: 06:15:36.629783 [INFO] Stable state for Leader reached at 2023-04-23 06:15:36.524571219 +0000 UTC m=+3.165967233 (1 nodes), 639ns from start of poll, 368.706599ms from cluster start. Timeout at 2023-04-23 06:15:36.629710294 +0000 UTC m=+3.271106342, 105.139109ms after stability - raft_test.go:97: cluster: 06:15:36.629818 [INFO] Starting stability test for raft state: Leader - raft_test.go:97: cluster: 06:15:36.735030 [INFO] Stable state for Leader reached at 2023-04-23 06:15:36.629837185 +0000 UTC m=+3.271233233 (1 nodes), 838ns from start of poll, 473.972599ms from cluster start. Timeout at 2023-04-23 06:15:36.734950122 +0000 UTC m=+3.376346139, 105.112906ms after stability - raft_test.go:97: 28cda93a-8b14-a7c7-2fa2-6fa1557363be: 06:15:36.735100 [INFO] raft: Updating configuration with RemoveServer (b6ac1171-8027-b2bd-47e1-944b13f94c0d, ) to [{Suffrage:Voter ID:28cda93a-8b14-a7c7-2fa2-6fa1557363be Address:28cda93a-8b14-a7c7-2fa2-6fa1557363be} {Suffrage:Voter ID:fa891986-0caf-dd48-4def-be618f3ceb49 Address:fa891986-0caf-dd48-4def-be618f3ceb49}] - raft_test.go:97: 28cda93a-8b14-a7c7-2fa2-6fa1557363be: 06:15:36.735187 [INFO] raft: Removed peer b6ac1171-8027-b2bd-47e1-944b13f94c0d, stopping replication after 4 - raft_test.go:97: 28cda93a-8b14-a7c7-2fa2-6fa1557363be: 06:15:36.735239 [INFO] raft: aborting pipeline replication to peer {Voter b6ac1171-8027-b2bd-47e1-944b13f94c0d b6ac1171-8027-b2bd-47e1-944b13f94c0d} - raft_test.go:97: 28cda93a-8b14-a7c7-2fa2-6fa1557363be: 06:15:36.735288 [INFO] raft: aborting pipeline replication to peer {Voter fa891986-0caf-dd48-4def-be618f3ceb49 fa891986-0caf-dd48-4def-be618f3ceb49} - raft_test.go:97: 28cda93a-8b14-a7c7-2fa2-6fa1557363be: 06:15:36.785445 [ERR] raft: Failed to heartbeat to b6ac1171-8027-b2bd-47e1-944b13f94c0d: command timed out +testLoggerAdapter verbose: cluster: 17:44:04.247440 [DEBUG] Fully Connecting +testLoggerAdapter verbose: d1cf9a73-e326-217e-9d08-d1b502a885de: 17:44:04.247588 [INFO] raft: Initial configuration (index=1): [{Suffrage:Voter ID:d1cf9a73-e326-217e-9d08-d1b502a885de Address:d1cf9a73-e326-217e-9d08-d1b502a885de} {Suffrage:Voter ID:321e36b1-d014-3b02-01d3-44b8a0386033 Address:321e36b1-d014-3b02-01d3-44b8a0386033}] +testLoggerAdapter verbose: 321e36b1-d014-3b02-01d3-44b8a0386033: 17:44:04.247687 [INFO] raft: Initial configuration (index=1): [{Suffrage:Voter ID:d1cf9a73-e326-217e-9d08-d1b502a885de Address:d1cf9a73-e326-217e-9d08-d1b502a885de} {Suffrage:Voter ID:321e36b1-d014-3b02-01d3-44b8a0386033 Address:321e36b1-d014-3b02-01d3-44b8a0386033}] +testLoggerAdapter verbose: cluster: 17:44:04.247886 [DEBUG] Fully Connecting +testLoggerAdapter verbose: 2a790158-c6e4-a94e-8a8b-7218eea4dc62: 17:44:04.247940 [INFO] raft: Initial configuration (index=0): [] +testLoggerAdapter verbose: cluster: 17:44:04.248025 [DEBUG] Fully Connecting +testLoggerAdapter verbose: cluster: 17:44:04.248049 [INFO] Starting stability test for raft state: Leader +testLoggerAdapter verbose: d1cf9a73-e326-217e-9d08-d1b502a885de: 17:44:04.248105 [INFO] raft: Node at d1cf9a73-e326-217e-9d08-d1b502a885de [Follower] entering Follower state (Leader: "") +testLoggerAdapter verbose: 321e36b1-d014-3b02-01d3-44b8a0386033: 17:44:04.248150 [INFO] raft: Node at 321e36b1-d014-3b02-01d3-44b8a0386033 [Follower] entering Follower state (Leader: "") +testLoggerAdapter verbose: 2a790158-c6e4-a94e-8a8b-7218eea4dc62: 17:44:04.248191 [INFO] raft: Node at 2a790158-c6e4-a94e-8a8b-7218eea4dc62 [Follower] entering Follower state (Leader: "") +testLoggerAdapter verbose: d1cf9a73-e326-217e-9d08-d1b502a885de: 17:44:04.315370 [WARN] raft: Heartbeat timeout from "" reached, starting election +testLoggerAdapter verbose: d1cf9a73-e326-217e-9d08-d1b502a885de: 17:44:04.315459 [INFO] raft: Node at d1cf9a73-e326-217e-9d08-d1b502a885de [Candidate] entering Candidate state in term 2 +testLoggerAdapter verbose: d1cf9a73-e326-217e-9d08-d1b502a885de: 17:44:04.315507 [DEBUG] raft: Votes needed: 2 +testLoggerAdapter verbose: d1cf9a73-e326-217e-9d08-d1b502a885de: 17:44:04.315527 [DEBUG] raft: Vote granted from d1cf9a73-e326-217e-9d08-d1b502a885de in term 2. Tally: 1 +testLoggerAdapter verbose: d1cf9a73-e326-217e-9d08-d1b502a885de: 17:44:04.315598 [DEBUG] raft: Vote granted from 321e36b1-d014-3b02-01d3-44b8a0386033 in term 2. Tally: 2 +testLoggerAdapter verbose: d1cf9a73-e326-217e-9d08-d1b502a885de: 17:44:04.315617 [INFO] raft: Election won. Tally: 2 +testLoggerAdapter verbose: d1cf9a73-e326-217e-9d08-d1b502a885de: 17:44:04.315637 [INFO] raft: Node at d1cf9a73-e326-217e-9d08-d1b502a885de [Leader] entering Leader state +testLoggerAdapter verbose: d1cf9a73-e326-217e-9d08-d1b502a885de: 17:44:04.315661 [INFO] raft: Added peer 321e36b1-d014-3b02-01d3-44b8a0386033, starting replication +testLoggerAdapter verbose: d1cf9a73-e326-217e-9d08-d1b502a885de: 17:44:04.315765 [INFO] raft: pipelining replication to peer {Voter 321e36b1-d014-3b02-01d3-44b8a0386033 321e36b1-d014-3b02-01d3-44b8a0386033} +testLoggerAdapter verbose: cluster: 17:44:04.315792 [DEBUG] Resetting stability timeout +testLoggerAdapter verbose: cluster: 17:44:04.315821 [DEBUG] Resetting stability timeout +testLoggerAdapter verbose: cluster: 17:44:04.315841 [DEBUG] Resetting stability timeout +testLoggerAdapter verbose: 2a790158-c6e4-a94e-8a8b-7218eea4dc62: 17:44:04.317977 [WARN] raft: no known peers, aborting election +testLoggerAdapter verbose: cluster: 17:44:04.422333 [INFO] Stable state for Leader reached at 2021-02-15 17:44:04.315855537 +0000 UTC m=+1.055007505 (1 nodes), 67.786701ms from start of poll, 68.385232ms from cluster start. Timeout at 2021-02-15 17:44:04.421968374 +0000 UTC m=+1.161120484, 106.112979ms after stability +testLoggerAdapter verbose: cluster: 17:44:04.422402 [INFO] Starting stability test for raft state: Leader +testLoggerAdapter verbose: cluster: 17:44:04.530116 [INFO] Stable state for Leader reached at 2021-02-15 17:44:04.422428535 +0000 UTC m=+1.161580500 (1 nodes), 2.68µs from start of poll, 174.958227ms from cluster start. Timeout at 2021-02-15 17:44:04.530065732 +0000 UTC m=+1.269217590, 107.63709ms after stability +testLoggerAdapter verbose: cluster: 17:44:04.530220 [INFO] Starting stability test for raft state: Leader +testLoggerAdapter verbose: cluster: 17:44:04.642027 [INFO] Stable state for Leader reached at 2021-02-15 17:44:04.530240252 +0000 UTC m=+1.269392126 (1 nodes), 2.316µs from start of poll, 282.769853ms from cluster start. Timeout at 2021-02-15 17:44:04.637923719 +0000 UTC m=+1.377075584, 107.683458ms after stability +testLoggerAdapter verbose: d1cf9a73-e326-217e-9d08-d1b502a885de: 17:44:04.642157 [INFO] raft: Updating configuration with AddStaging (2a790158-c6e4-a94e-8a8b-7218eea4dc62, 2a790158-c6e4-a94e-8a8b-7218eea4dc62) to [{Suffrage:Voter ID:d1cf9a73-e326-217e-9d08-d1b502a885de Address:d1cf9a73-e326-217e-9d08-d1b502a885de} {Suffrage:Voter ID:321e36b1-d014-3b02-01d3-44b8a0386033 Address:321e36b1-d014-3b02-01d3-44b8a0386033} {Suffrage:Voter ID:2a790158-c6e4-a94e-8a8b-7218eea4dc62 Address:2a790158-c6e4-a94e-8a8b-7218eea4dc62}] +testLoggerAdapter verbose: d1cf9a73-e326-217e-9d08-d1b502a885de: 17:44:04.686043 [INFO] raft: Added peer 2a790158-c6e4-a94e-8a8b-7218eea4dc62, starting replication +testLoggerAdapter verbose: 2a790158-c6e4-a94e-8a8b-7218eea4dc62: 17:44:04.686262 [WARN] raft: Failed to get previous log: 3 log not found (last: 0) +testLoggerAdapter verbose: d1cf9a73-e326-217e-9d08-d1b502a885de: 17:44:04.686359 [WARN] raft: AppendEntries to {Voter 2a790158-c6e4-a94e-8a8b-7218eea4dc62 2a790158-c6e4-a94e-8a8b-7218eea4dc62} rejected, sending older logs (next: 1) +testLoggerAdapter verbose: d1cf9a73-e326-217e-9d08-d1b502a885de: 17:44:04.686545 [INFO] raft: pipelining replication to peer {Voter 2a790158-c6e4-a94e-8a8b-7218eea4dc62 2a790158-c6e4-a94e-8a8b-7218eea4dc62} +testLoggerAdapter verbose: 321e36b1-d014-3b02-01d3-44b8a0386033: 17:44:04.738091 [WARN] raft: Heartbeat timeout from "d1cf9a73-e326-217e-9d08-d1b502a885de" reached, starting election +testLoggerAdapter verbose: 321e36b1-d014-3b02-01d3-44b8a0386033: 17:44:04.738179 [INFO] raft: Node at 321e36b1-d014-3b02-01d3-44b8a0386033 [Candidate] entering Candidate state in term 3 +testLoggerAdapter verbose: 321e36b1-d014-3b02-01d3-44b8a0386033: 17:44:04.738210 [DEBUG] raft: Votes needed: 2 +testLoggerAdapter verbose: 321e36b1-d014-3b02-01d3-44b8a0386033: 17:44:04.738231 [DEBUG] raft: Vote granted from 321e36b1-d014-3b02-01d3-44b8a0386033 in term 3. Tally: 1 +testLoggerAdapter verbose: d1cf9a73-e326-217e-9d08-d1b502a885de: 17:44:04.738296 [WARN] raft: Rejecting vote request from 321e36b1-d014-3b02-01d3-44b8a0386033 since we have a leader: d1cf9a73-e326-217e-9d08-d1b502a885de +testLoggerAdapter verbose: d1cf9a73-e326-217e-9d08-d1b502a885de: 17:44:04.742328 [ERR] raft: peer {Voter 321e36b1-d014-3b02-01d3-44b8a0386033 321e36b1-d014-3b02-01d3-44b8a0386033} has newer term, stopping replication +testLoggerAdapter verbose: d1cf9a73-e326-217e-9d08-d1b502a885de: 17:44:04.742432 [INFO] raft: aborting pipeline replication to peer {Voter 321e36b1-d014-3b02-01d3-44b8a0386033 321e36b1-d014-3b02-01d3-44b8a0386033} +testLoggerAdapter verbose: d1cf9a73-e326-217e-9d08-d1b502a885de: 17:44:04.743513 [INFO] raft: Node at d1cf9a73-e326-217e-9d08-d1b502a885de [Follower] entering Follower state (Leader: "") +testLoggerAdapter verbose: d1cf9a73-e326-217e-9d08-d1b502a885de: 17:44:04.743546 [INFO] raft: aborting pipeline replication to peer {Voter 2a790158-c6e4-a94e-8a8b-7218eea4dc62 2a790158-c6e4-a94e-8a8b-7218eea4dc62} +testLoggerAdapter verbose: 321e36b1-d014-3b02-01d3-44b8a0386033: 17:44:04.821598 [WARN] raft: Election timeout reached, restarting election +testLoggerAdapter verbose: 321e36b1-d014-3b02-01d3-44b8a0386033: 17:44:04.821712 [INFO] raft: Node at 321e36b1-d014-3b02-01d3-44b8a0386033 [Candidate] entering Candidate state in term 4 +testLoggerAdapter verbose: 321e36b1-d014-3b02-01d3-44b8a0386033: 17:44:04.821757 [DEBUG] raft: Votes needed: 2 +testLoggerAdapter verbose: 321e36b1-d014-3b02-01d3-44b8a0386033: 17:44:04.821782 [DEBUG] raft: Vote granted from 321e36b1-d014-3b02-01d3-44b8a0386033 in term 4. Tally: 1 +testLoggerAdapter verbose: d1cf9a73-e326-217e-9d08-d1b502a885de: 17:44:04.821934 [WARN] raft: Rejecting vote request from 321e36b1-d014-3b02-01d3-44b8a0386033 since our last index is greater (3, 2) +testLoggerAdapter verbose: d1cf9a73-e326-217e-9d08-d1b502a885de: 17:44:04.834009 [WARN] raft: Heartbeat timeout from "" reached, starting election +testLoggerAdapter verbose: d1cf9a73-e326-217e-9d08-d1b502a885de: 17:44:04.834119 [INFO] raft: Node at d1cf9a73-e326-217e-9d08-d1b502a885de [Candidate] entering Candidate state in term 5 +testLoggerAdapter verbose: d1cf9a73-e326-217e-9d08-d1b502a885de: 17:44:04.834177 [DEBUG] raft: Votes needed: 2 +testLoggerAdapter verbose: d1cf9a73-e326-217e-9d08-d1b502a885de: 17:44:04.834196 [DEBUG] raft: Vote granted from d1cf9a73-e326-217e-9d08-d1b502a885de in term 5. Tally: 1 +testLoggerAdapter verbose: d1cf9a73-e326-217e-9d08-d1b502a885de: 17:44:04.834256 [DEBUG] raft: Vote granted from 2a790158-c6e4-a94e-8a8b-7218eea4dc62 in term 5. Tally: 2 +testLoggerAdapter verbose: d1cf9a73-e326-217e-9d08-d1b502a885de: 17:44:04.834271 [INFO] raft: Election won. Tally: 2 +testLoggerAdapter verbose: d1cf9a73-e326-217e-9d08-d1b502a885de: 17:44:04.834289 [INFO] raft: Node at d1cf9a73-e326-217e-9d08-d1b502a885de [Leader] entering Leader state +testLoggerAdapter verbose: d1cf9a73-e326-217e-9d08-d1b502a885de: 17:44:04.834309 [INFO] raft: Added peer 321e36b1-d014-3b02-01d3-44b8a0386033, starting replication +testLoggerAdapter verbose: d1cf9a73-e326-217e-9d08-d1b502a885de: 17:44:04.834330 [INFO] raft: Added peer 2a790158-c6e4-a94e-8a8b-7218eea4dc62, starting replication +testLoggerAdapter verbose: d1cf9a73-e326-217e-9d08-d1b502a885de: 17:44:04.834441 [INFO] raft: pipelining replication to peer {Voter 2a790158-c6e4-a94e-8a8b-7218eea4dc62 2a790158-c6e4-a94e-8a8b-7218eea4dc62} +testLoggerAdapter verbose: 321e36b1-d014-3b02-01d3-44b8a0386033: 17:44:04.834556 [INFO] raft: Node at 321e36b1-d014-3b02-01d3-44b8a0386033 [Follower] entering Follower state (Leader: "") +testLoggerAdapter verbose: 321e36b1-d014-3b02-01d3-44b8a0386033: 17:44:04.834598 [WARN] raft: Failed to get previous log: 3 log not found (last: 2) +testLoggerAdapter verbose: d1cf9a73-e326-217e-9d08-d1b502a885de: 17:44:04.834645 [WARN] raft: AppendEntries to {Voter 321e36b1-d014-3b02-01d3-44b8a0386033 321e36b1-d014-3b02-01d3-44b8a0386033} rejected, sending older logs (next: 3) +testLoggerAdapter verbose: d1cf9a73-e326-217e-9d08-d1b502a885de: 17:44:04.834712 [INFO] raft: pipelining replication to peer {Voter 321e36b1-d014-3b02-01d3-44b8a0386033 321e36b1-d014-3b02-01d3-44b8a0386033} +testLoggerAdapter verbose: cluster: 17:44:04.834774 [INFO] Starting stability test for raft state: Leader +testLoggerAdapter verbose: cluster: 17:44:04.834804 [DEBUG] Resetting stability timeout +testLoggerAdapter verbose: cluster: 17:44:04.942017 [INFO] Stable state for Leader reached at 2021-02-15 17:44:04.834818861 +0000 UTC m=+1.573970916 (1 nodes), 24.994µs from start of poll, 587.348643ms from cluster start. Timeout at 2021-02-15 17:44:04.941944582 +0000 UTC m=+1.681096683, 107.125767ms after stability +testLoggerAdapter verbose: cluster: 17:44:04.942093 [INFO] Starting stability test for raft state: Leader +testLoggerAdapter verbose: cluster: 17:44:05.051808 [INFO] Stable state for Leader reached at 2021-02-15 17:44:04.942121629 +0000 UTC m=+1.681273657 (1 nodes), 3.004µs from start of poll, 694.651384ms from cluster start. Timeout at 2021-02-15 17:44:05.050012152 +0000 UTC m=+1.789164102, 107.890445ms after stability +testLoggerAdapter verbose: d1cf9a73-e326-217e-9d08-d1b502a885de: 17:44:05.051906 [INFO] raft: Updating configuration with RemoveServer (2a790158-c6e4-a94e-8a8b-7218eea4dc62, ) to [{Suffrage:Voter ID:d1cf9a73-e326-217e-9d08-d1b502a885de Address:d1cf9a73-e326-217e-9d08-d1b502a885de} {Suffrage:Voter ID:321e36b1-d014-3b02-01d3-44b8a0386033 Address:321e36b1-d014-3b02-01d3-44b8a0386033}] +testLoggerAdapter verbose: d1cf9a73-e326-217e-9d08-d1b502a885de: 17:44:05.051973 [INFO] raft: Removed peer 2a790158-c6e4-a94e-8a8b-7218eea4dc62, stopping replication after 5 +testLoggerAdapter verbose: d1cf9a73-e326-217e-9d08-d1b502a885de: 17:44:05.052036 [INFO] raft: aborting pipeline replication to peer {Voter 2a790158-c6e4-a94e-8a8b-7218eea4dc62 2a790158-c6e4-a94e-8a8b-7218eea4dc62} +testLoggerAdapter verbose: d1cf9a73-e326-217e-9d08-d1b502a885de: 17:44:05.052211 [INFO] raft: aborting pipeline replication to peer {Voter 321e36b1-d014-3b02-01d3-44b8a0386033 321e36b1-d014-3b02-01d3-44b8a0386033} +--- PASS: TestRaft_ProtocolVersion_Upgrade_1_2 (0.81s) + raft_test.go:97: cluster: 17:44:04.247440 [DEBUG] Fully Connecting + raft_test.go:97: d1cf9a73-e326-217e-9d08-d1b502a885de: 17:44:04.247588 [INFO] raft: Initial configuration (index=1): [{Suffrage:Voter ID:d1cf9a73-e326-217e-9d08-d1b502a885de Address:d1cf9a73-e326-217e-9d08-d1b502a885de} {Suffrage:Voter ID:321e36b1-d014-3b02-01d3-44b8a0386033 Address:321e36b1-d014-3b02-01d3-44b8a0386033}] + raft_test.go:97: 321e36b1-d014-3b02-01d3-44b8a0386033: 17:44:04.247687 [INFO] raft: Initial configuration (index=1): [{Suffrage:Voter ID:d1cf9a73-e326-217e-9d08-d1b502a885de Address:d1cf9a73-e326-217e-9d08-d1b502a885de} {Suffrage:Voter ID:321e36b1-d014-3b02-01d3-44b8a0386033 Address:321e36b1-d014-3b02-01d3-44b8a0386033}] + raft_test.go:97: cluster: 17:44:04.247886 [DEBUG] Fully Connecting + raft_test.go:97: 2a790158-c6e4-a94e-8a8b-7218eea4dc62: 17:44:04.247940 [INFO] raft: Initial configuration (index=0): [] + raft_test.go:97: cluster: 17:44:04.248025 [DEBUG] Fully Connecting + raft_test.go:97: cluster: 17:44:04.248049 [INFO] Starting stability test for raft state: Leader + raft_test.go:97: d1cf9a73-e326-217e-9d08-d1b502a885de: 17:44:04.248105 [INFO] raft: Node at d1cf9a73-e326-217e-9d08-d1b502a885de [Follower] entering Follower state (Leader: "") + raft_test.go:97: 321e36b1-d014-3b02-01d3-44b8a0386033: 17:44:04.248150 [INFO] raft: Node at 321e36b1-d014-3b02-01d3-44b8a0386033 [Follower] entering Follower state (Leader: "") + raft_test.go:97: 2a790158-c6e4-a94e-8a8b-7218eea4dc62: 17:44:04.248191 [INFO] raft: Node at 2a790158-c6e4-a94e-8a8b-7218eea4dc62 [Follower] entering Follower state (Leader: "") + raft_test.go:97: d1cf9a73-e326-217e-9d08-d1b502a885de: 17:44:04.315370 [WARN] raft: Heartbeat timeout from "" reached, starting election + raft_test.go:97: d1cf9a73-e326-217e-9d08-d1b502a885de: 17:44:04.315459 [INFO] raft: Node at d1cf9a73-e326-217e-9d08-d1b502a885de [Candidate] entering Candidate state in term 2 + raft_test.go:97: d1cf9a73-e326-217e-9d08-d1b502a885de: 17:44:04.315507 [DEBUG] raft: Votes needed: 2 + raft_test.go:97: d1cf9a73-e326-217e-9d08-d1b502a885de: 17:44:04.315527 [DEBUG] raft: Vote granted from d1cf9a73-e326-217e-9d08-d1b502a885de in term 2. Tally: 1 + raft_test.go:97: d1cf9a73-e326-217e-9d08-d1b502a885de: 17:44:04.315598 [DEBUG] raft: Vote granted from 321e36b1-d014-3b02-01d3-44b8a0386033 in term 2. Tally: 2 + raft_test.go:97: d1cf9a73-e326-217e-9d08-d1b502a885de: 17:44:04.315617 [INFO] raft: Election won. Tally: 2 + raft_test.go:97: d1cf9a73-e326-217e-9d08-d1b502a885de: 17:44:04.315637 [INFO] raft: Node at d1cf9a73-e326-217e-9d08-d1b502a885de [Leader] entering Leader state + raft_test.go:97: d1cf9a73-e326-217e-9d08-d1b502a885de: 17:44:04.315661 [INFO] raft: Added peer 321e36b1-d014-3b02-01d3-44b8a0386033, starting replication + raft_test.go:97: d1cf9a73-e326-217e-9d08-d1b502a885de: 17:44:04.315765 [INFO] raft: pipelining replication to peer {Voter 321e36b1-d014-3b02-01d3-44b8a0386033 321e36b1-d014-3b02-01d3-44b8a0386033} + raft_test.go:97: cluster: 17:44:04.315792 [DEBUG] Resetting stability timeout + raft_test.go:97: cluster: 17:44:04.315821 [DEBUG] Resetting stability timeout + raft_test.go:97: cluster: 17:44:04.315841 [DEBUG] Resetting stability timeout + raft_test.go:97: 2a790158-c6e4-a94e-8a8b-7218eea4dc62: 17:44:04.317977 [WARN] raft: no known peers, aborting election + raft_test.go:97: cluster: 17:44:04.422333 [INFO] Stable state for Leader reached at 2021-02-15 17:44:04.315855537 +0000 UTC m=+1.055007505 (1 nodes), 67.786701ms from start of poll, 68.385232ms from cluster start. Timeout at 2021-02-15 17:44:04.421968374 +0000 UTC m=+1.161120484, 106.112979ms after stability + raft_test.go:97: cluster: 17:44:04.422402 [INFO] Starting stability test for raft state: Leader + raft_test.go:97: cluster: 17:44:04.530116 [INFO] Stable state for Leader reached at 2021-02-15 17:44:04.422428535 +0000 UTC m=+1.161580500 (1 nodes), 2.68µs from start of poll, 174.958227ms from cluster start. Timeout at 2021-02-15 17:44:04.530065732 +0000 UTC m=+1.269217590, 107.63709ms after stability + raft_test.go:97: cluster: 17:44:04.530220 [INFO] Starting stability test for raft state: Leader + raft_test.go:97: cluster: 17:44:04.642027 [INFO] Stable state for Leader reached at 2021-02-15 17:44:04.530240252 +0000 UTC m=+1.269392126 (1 nodes), 2.316µs from start of poll, 282.769853ms from cluster start. Timeout at 2021-02-15 17:44:04.637923719 +0000 UTC m=+1.377075584, 107.683458ms after stability + raft_test.go:97: d1cf9a73-e326-217e-9d08-d1b502a885de: 17:44:04.642157 [INFO] raft: Updating configuration with AddStaging (2a790158-c6e4-a94e-8a8b-7218eea4dc62, 2a790158-c6e4-a94e-8a8b-7218eea4dc62) to [{Suffrage:Voter ID:d1cf9a73-e326-217e-9d08-d1b502a885de Address:d1cf9a73-e326-217e-9d08-d1b502a885de} {Suffrage:Voter ID:321e36b1-d014-3b02-01d3-44b8a0386033 Address:321e36b1-d014-3b02-01d3-44b8a0386033} {Suffrage:Voter ID:2a790158-c6e4-a94e-8a8b-7218eea4dc62 Address:2a790158-c6e4-a94e-8a8b-7218eea4dc62}] + raft_test.go:97: d1cf9a73-e326-217e-9d08-d1b502a885de: 17:44:04.686043 [INFO] raft: Added peer 2a790158-c6e4-a94e-8a8b-7218eea4dc62, starting replication + raft_test.go:97: 2a790158-c6e4-a94e-8a8b-7218eea4dc62: 17:44:04.686262 [WARN] raft: Failed to get previous log: 3 log not found (last: 0) + raft_test.go:97: d1cf9a73-e326-217e-9d08-d1b502a885de: 17:44:04.686359 [WARN] raft: AppendEntries to {Voter 2a790158-c6e4-a94e-8a8b-7218eea4dc62 2a790158-c6e4-a94e-8a8b-7218eea4dc62} rejected, sending older logs (next: 1) + raft_test.go:97: d1cf9a73-e326-217e-9d08-d1b502a885de: 17:44:04.686545 [INFO] raft: pipelining replication to peer {Voter 2a790158-c6e4-a94e-8a8b-7218eea4dc62 2a790158-c6e4-a94e-8a8b-7218eea4dc62} + raft_test.go:97: 321e36b1-d014-3b02-01d3-44b8a0386033: 17:44:04.738091 [WARN] raft: Heartbeat timeout from "d1cf9a73-e326-217e-9d08-d1b502a885de" reached, starting election + raft_test.go:97: 321e36b1-d014-3b02-01d3-44b8a0386033: 17:44:04.738179 [INFO] raft: Node at 321e36b1-d014-3b02-01d3-44b8a0386033 [Candidate] entering Candidate state in term 3 + raft_test.go:97: 321e36b1-d014-3b02-01d3-44b8a0386033: 17:44:04.738210 [DEBUG] raft: Votes needed: 2 + raft_test.go:97: 321e36b1-d014-3b02-01d3-44b8a0386033: 17:44:04.738231 [DEBUG] raft: Vote granted from 321e36b1-d014-3b02-01d3-44b8a0386033 in term 3. Tally: 1 + raft_test.go:97: d1cf9a73-e326-217e-9d08-d1b502a885de: 17:44:04.738296 [WARN] raft: Rejecting vote request from 321e36b1-d014-3b02-01d3-44b8a0386033 since we have a leader: d1cf9a73-e326-217e-9d08-d1b502a885de + raft_test.go:97: d1cf9a73-e326-217e-9d08-d1b502a885de: 17:44:04.742328 [ERR] raft: peer {Voter 321e36b1-d014-3b02-01d3-44b8a0386033 321e36b1-d014-3b02-01d3-44b8a0386033} has newer term, stopping replication + raft_test.go:97: d1cf9a73-e326-217e-9d08-d1b502a885de: 17:44:04.742432 [INFO] raft: aborting pipeline replication to peer {Voter 321e36b1-d014-3b02-01d3-44b8a0386033 321e36b1-d014-3b02-01d3-44b8a0386033} + raft_test.go:97: d1cf9a73-e326-217e-9d08-d1b502a885de: 17:44:04.743513 [INFO] raft: Node at d1cf9a73-e326-217e-9d08-d1b502a885de [Follower] entering Follower state (Leader: "") + raft_test.go:97: d1cf9a73-e326-217e-9d08-d1b502a885de: 17:44:04.743546 [INFO] raft: aborting pipeline replication to peer {Voter 2a790158-c6e4-a94e-8a8b-7218eea4dc62 2a790158-c6e4-a94e-8a8b-7218eea4dc62} + raft_test.go:97: 321e36b1-d014-3b02-01d3-44b8a0386033: 17:44:04.821598 [WARN] raft: Election timeout reached, restarting election + raft_test.go:97: 321e36b1-d014-3b02-01d3-44b8a0386033: 17:44:04.821712 [INFO] raft: Node at 321e36b1-d014-3b02-01d3-44b8a0386033 [Candidate] entering Candidate state in term 4 + raft_test.go:97: 321e36b1-d014-3b02-01d3-44b8a0386033: 17:44:04.821757 [DEBUG] raft: Votes needed: 2 + raft_test.go:97: 321e36b1-d014-3b02-01d3-44b8a0386033: 17:44:04.821782 [DEBUG] raft: Vote granted from 321e36b1-d014-3b02-01d3-44b8a0386033 in term 4. Tally: 1 + raft_test.go:97: d1cf9a73-e326-217e-9d08-d1b502a885de: 17:44:04.821934 [WARN] raft: Rejecting vote request from 321e36b1-d014-3b02-01d3-44b8a0386033 since our last index is greater (3, 2) + raft_test.go:97: d1cf9a73-e326-217e-9d08-d1b502a885de: 17:44:04.834009 [WARN] raft: Heartbeat timeout from "" reached, starting election + raft_test.go:97: d1cf9a73-e326-217e-9d08-d1b502a885de: 17:44:04.834119 [INFO] raft: Node at d1cf9a73-e326-217e-9d08-d1b502a885de [Candidate] entering Candidate state in term 5 + raft_test.go:97: d1cf9a73-e326-217e-9d08-d1b502a885de: 17:44:04.834177 [DEBUG] raft: Votes needed: 2 + raft_test.go:97: d1cf9a73-e326-217e-9d08-d1b502a885de: 17:44:04.834196 [DEBUG] raft: Vote granted from d1cf9a73-e326-217e-9d08-d1b502a885de in term 5. Tally: 1 + raft_test.go:97: d1cf9a73-e326-217e-9d08-d1b502a885de: 17:44:04.834256 [DEBUG] raft: Vote granted from 2a790158-c6e4-a94e-8a8b-7218eea4dc62 in term 5. Tally: 2 + raft_test.go:97: d1cf9a73-e326-217e-9d08-d1b502a885de: 17:44:04.834271 [INFO] raft: Election won. Tally: 2 + raft_test.go:97: d1cf9a73-e326-217e-9d08-d1b502a885de: 17:44:04.834289 [INFO] raft: Node at d1cf9a73-e326-217e-9d08-d1b502a885de [Leader] entering Leader state + raft_test.go:97: d1cf9a73-e326-217e-9d08-d1b502a885de: 17:44:04.834309 [INFO] raft: Added peer 321e36b1-d014-3b02-01d3-44b8a0386033, starting replication + raft_test.go:97: d1cf9a73-e326-217e-9d08-d1b502a885de: 17:44:04.834330 [INFO] raft: Added peer 2a790158-c6e4-a94e-8a8b-7218eea4dc62, starting replication + raft_test.go:97: d1cf9a73-e326-217e-9d08-d1b502a885de: 17:44:04.834441 [INFO] raft: pipelining replication to peer {Voter 2a790158-c6e4-a94e-8a8b-7218eea4dc62 2a790158-c6e4-a94e-8a8b-7218eea4dc62} + raft_test.go:97: 321e36b1-d014-3b02-01d3-44b8a0386033: 17:44:04.834556 [INFO] raft: Node at 321e36b1-d014-3b02-01d3-44b8a0386033 [Follower] entering Follower state (Leader: "") + raft_test.go:97: 321e36b1-d014-3b02-01d3-44b8a0386033: 17:44:04.834598 [WARN] raft: Failed to get previous log: 3 log not found (last: 2) + raft_test.go:97: d1cf9a73-e326-217e-9d08-d1b502a885de: 17:44:04.834645 [WARN] raft: AppendEntries to {Voter 321e36b1-d014-3b02-01d3-44b8a0386033 321e36b1-d014-3b02-01d3-44b8a0386033} rejected, sending older logs (next: 3) + raft_test.go:97: d1cf9a73-e326-217e-9d08-d1b502a885de: 17:44:04.834712 [INFO] raft: pipelining replication to peer {Voter 321e36b1-d014-3b02-01d3-44b8a0386033 321e36b1-d014-3b02-01d3-44b8a0386033} + raft_test.go:97: cluster: 17:44:04.834774 [INFO] Starting stability test for raft state: Leader + raft_test.go:97: cluster: 17:44:04.834804 [DEBUG] Resetting stability timeout + raft_test.go:97: cluster: 17:44:04.942017 [INFO] Stable state for Leader reached at 2021-02-15 17:44:04.834818861 +0000 UTC m=+1.573970916 (1 nodes), 24.994µs from start of poll, 587.348643ms from cluster start. Timeout at 2021-02-15 17:44:04.941944582 +0000 UTC m=+1.681096683, 107.125767ms after stability + raft_test.go:97: cluster: 17:44:04.942093 [INFO] Starting stability test for raft state: Leader + raft_test.go:97: cluster: 17:44:05.051808 [INFO] Stable state for Leader reached at 2021-02-15 17:44:04.942121629 +0000 UTC m=+1.681273657 (1 nodes), 3.004µs from start of poll, 694.651384ms from cluster start. Timeout at 2021-02-15 17:44:05.050012152 +0000 UTC m=+1.789164102, 107.890445ms after stability + raft_test.go:97: d1cf9a73-e326-217e-9d08-d1b502a885de: 17:44:05.051906 [INFO] raft: Updating configuration with RemoveServer (2a790158-c6e4-a94e-8a8b-7218eea4dc62, ) to [{Suffrage:Voter ID:d1cf9a73-e326-217e-9d08-d1b502a885de Address:d1cf9a73-e326-217e-9d08-d1b502a885de} {Suffrage:Voter ID:321e36b1-d014-3b02-01d3-44b8a0386033 Address:321e36b1-d014-3b02-01d3-44b8a0386033}] + raft_test.go:97: d1cf9a73-e326-217e-9d08-d1b502a885de: 17:44:05.051973 [INFO] raft: Removed peer 2a790158-c6e4-a94e-8a8b-7218eea4dc62, stopping replication after 5 + raft_test.go:97: d1cf9a73-e326-217e-9d08-d1b502a885de: 17:44:05.052036 [INFO] raft: aborting pipeline replication to peer {Voter 2a790158-c6e4-a94e-8a8b-7218eea4dc62 2a790158-c6e4-a94e-8a8b-7218eea4dc62} + raft_test.go:97: d1cf9a73-e326-217e-9d08-d1b502a885de: 17:44:05.052211 [INFO] raft: aborting pipeline replication to peer {Voter 321e36b1-d014-3b02-01d3-44b8a0386033 321e36b1-d014-3b02-01d3-44b8a0386033} === RUN TestRaft_ProtocolVersion_Upgrade_2_3 -testLoggerAdapter verbose: cluster: 06:15:36.786017 [DEBUG] Fully Connecting -testLoggerAdapter verbose: a5daeebb-c76f-84d9-ec90-09a0d3c4f3d7: 06:15:36.786105 [INFO] raft: Initial configuration (index=1): [{Suffrage:Voter ID:a5daeebb-c76f-84d9-ec90-09a0d3c4f3d7 Address:a5daeebb-c76f-84d9-ec90-09a0d3c4f3d7} {Suffrage:Voter ID:31438db6-c531-4f30-44db-1bef241313a1 Address:31438db6-c531-4f30-44db-1bef241313a1}] -testLoggerAdapter verbose: 31438db6-c531-4f30-44db-1bef241313a1: 06:15:36.786187 [INFO] raft: Initial configuration (index=1): [{Suffrage:Voter ID:a5daeebb-c76f-84d9-ec90-09a0d3c4f3d7 Address:a5daeebb-c76f-84d9-ec90-09a0d3c4f3d7} {Suffrage:Voter ID:31438db6-c531-4f30-44db-1bef241313a1 Address:31438db6-c531-4f30-44db-1bef241313a1}] -testLoggerAdapter verbose: cluster: 06:15:36.786206 [INFO] Starting stability test for raft state: Follower -testLoggerAdapter verbose: 31438db6-c531-4f30-44db-1bef241313a1: 06:15:36.786236 [INFO] raft: Node at 31438db6-c531-4f30-44db-1bef241313a1 [Follower] entering Follower state (Leader: "") -testLoggerAdapter verbose: a5daeebb-c76f-84d9-ec90-09a0d3c4f3d7: 06:15:36.786234 [INFO] raft: Node at a5daeebb-c76f-84d9-ec90-09a0d3c4f3d7 [Follower] entering Follower state (Leader: "") -testLoggerAdapter verbose: a5daeebb-c76f-84d9-ec90-09a0d3c4f3d7: 06:15:36.856055 [WARN] raft: Heartbeat timeout from "" reached, starting election -testLoggerAdapter verbose: a5daeebb-c76f-84d9-ec90-09a0d3c4f3d7: 06:15:36.856102 [INFO] raft: Node at a5daeebb-c76f-84d9-ec90-09a0d3c4f3d7 [Candidate] entering Candidate state in term 2 -testLoggerAdapter verbose: cluster: 06:15:36.856120 [DEBUG] Resetting stability timeout -testLoggerAdapter verbose: a5daeebb-c76f-84d9-ec90-09a0d3c4f3d7: 06:15:36.856143 [DEBUG] raft: Votes needed: 2 -testLoggerAdapter verbose: a5daeebb-c76f-84d9-ec90-09a0d3c4f3d7: 06:15:36.856159 [DEBUG] raft: Vote granted from a5daeebb-c76f-84d9-ec90-09a0d3c4f3d7 in term 2. Tally: 1 -testLoggerAdapter verbose: a5daeebb-c76f-84d9-ec90-09a0d3c4f3d7: 06:15:36.856188 [DEBUG] raft: Vote granted from 31438db6-c531-4f30-44db-1bef241313a1 in term 2. Tally: 2 -testLoggerAdapter verbose: cluster: 06:15:36.856238 [DEBUG] Resetting stability timeout -testLoggerAdapter verbose: a5daeebb-c76f-84d9-ec90-09a0d3c4f3d7: 06:15:36.856277 [INFO] raft: Election won. Tally: 2 -testLoggerAdapter verbose: a5daeebb-c76f-84d9-ec90-09a0d3c4f3d7: 06:15:36.856304 [INFO] raft: Node at a5daeebb-c76f-84d9-ec90-09a0d3c4f3d7 [Leader] entering Leader state -testLoggerAdapter verbose: a5daeebb-c76f-84d9-ec90-09a0d3c4f3d7: 06:15:36.856339 [INFO] raft: Added peer 31438db6-c531-4f30-44db-1bef241313a1, starting replication -testLoggerAdapter verbose: cluster: 06:15:36.856391 [DEBUG] Resetting stability timeout -testLoggerAdapter verbose: a5daeebb-c76f-84d9-ec90-09a0d3c4f3d7: 06:15:36.856448 [INFO] raft: pipelining replication to peer {Voter 31438db6-c531-4f30-44db-1bef241313a1 31438db6-c531-4f30-44db-1bef241313a1} -testLoggerAdapter verbose: cluster: 06:15:36.961685 [INFO] Stable state for Follower reached at 2023-04-23 06:15:36.856424785 +0000 UTC m=+3.497820882 (1 nodes), 70.208828ms from start of poll, 70.385234ms from cluster start. Timeout at 2023-04-23 06:15:36.961583161 +0000 UTC m=+3.602979198, 105.158316ms after stability -testLoggerAdapter verbose: cluster: 06:15:36.961847 [DEBUG] Fully Connecting -testLoggerAdapter verbose: server-9a66d164-3bb1-8bed-6eba-db06840981a9: 06:15:36.961896 [INFO] raft: Initial configuration (index=0): [] -testLoggerAdapter verbose: cluster: 06:15:36.961931 [DEBUG] Fully Connecting -testLoggerAdapter verbose: cluster: 06:15:36.961952 [INFO] Starting stability test for raft state: Leader -testLoggerAdapter verbose: server-9a66d164-3bb1-8bed-6eba-db06840981a9: 06:15:36.961964 [INFO] raft: Node at 9a66d164-3bb1-8bed-6eba-db06840981a9 [Follower] entering Follower state (Leader: "") -testLoggerAdapter verbose: server-9a66d164-3bb1-8bed-6eba-db06840981a9: 06:15:37.049244 [WARN] raft: no known peers, aborting election -testLoggerAdapter verbose: cluster: 06:15:37.067159 [INFO] Stable state for Leader reached at 2023-04-23 06:15:36.961969047 +0000 UTC m=+3.603365086 (1 nodes), 599ns from start of poll, 175.929438ms from cluster start. Timeout at 2023-04-23 06:15:37.067080286 +0000 UTC m=+3.708476329, 105.111243ms after stability -testLoggerAdapter verbose: a5daeebb-c76f-84d9-ec90-09a0d3c4f3d7: 06:15:37.067214 [INFO] raft: Updating configuration with AddStaging (server-9a66d164-3bb1-8bed-6eba-db06840981a9, 9a66d164-3bb1-8bed-6eba-db06840981a9) to [{Suffrage:Voter ID:a5daeebb-c76f-84d9-ec90-09a0d3c4f3d7 Address:a5daeebb-c76f-84d9-ec90-09a0d3c4f3d7} {Suffrage:Voter ID:31438db6-c531-4f30-44db-1bef241313a1 Address:31438db6-c531-4f30-44db-1bef241313a1} {Suffrage:Voter ID:server-9a66d164-3bb1-8bed-6eba-db06840981a9 Address:9a66d164-3bb1-8bed-6eba-db06840981a9}] -testLoggerAdapter verbose: a5daeebb-c76f-84d9-ec90-09a0d3c4f3d7: 06:15:37.067265 [INFO] raft: Added peer server-9a66d164-3bb1-8bed-6eba-db06840981a9, starting replication -testLoggerAdapter verbose: server-9a66d164-3bb1-8bed-6eba-db06840981a9: 06:15:37.067313 [WARN] raft: Failed to get previous log: 3 log not found (last: 0) -testLoggerAdapter verbose: a5daeebb-c76f-84d9-ec90-09a0d3c4f3d7: 06:15:37.067347 [WARN] raft: AppendEntries to {Voter server-9a66d164-3bb1-8bed-6eba-db06840981a9 9a66d164-3bb1-8bed-6eba-db06840981a9} rejected, sending older logs (next: 1) -testLoggerAdapter verbose: a5daeebb-c76f-84d9-ec90-09a0d3c4f3d7: 06:15:37.067407 [INFO] raft: pipelining replication to peer {Voter server-9a66d164-3bb1-8bed-6eba-db06840981a9 9a66d164-3bb1-8bed-6eba-db06840981a9} -testLoggerAdapter verbose: cluster: 06:15:37.067459 [INFO] Starting stability test for raft state: Leader -testLoggerAdapter verbose: cluster: 06:15:37.172737 [INFO] Stable state for Leader reached at 2023-04-23 06:15:37.067489467 +0000 UTC m=+3.708885509 (1 nodes), 731ns from start of poll, 281.449861ms from cluster start. Timeout at 2023-04-23 06:15:37.172652781 +0000 UTC m=+3.814048834, 105.163325ms after stability -testLoggerAdapter verbose: cluster: 06:15:37.172772 [INFO] Starting stability test for raft state: Leader -testLoggerAdapter verbose: cluster: 06:15:37.277949 [INFO] Stable state for Leader reached at 2023-04-23 06:15:37.172788446 +0000 UTC m=+3.814184460 (1 nodes), 689ns from start of poll, 386.748812ms from cluster start. Timeout at 2023-04-23 06:15:37.277876047 +0000 UTC m=+3.919272083, 105.087623ms after stability -testLoggerAdapter verbose: a5daeebb-c76f-84d9-ec90-09a0d3c4f3d7: 06:15:37.277998 [INFO] raft: Updating configuration with RemoveServer (31438db6-c531-4f30-44db-1bef241313a1, ) to [{Suffrage:Voter ID:a5daeebb-c76f-84d9-ec90-09a0d3c4f3d7 Address:a5daeebb-c76f-84d9-ec90-09a0d3c4f3d7} {Suffrage:Voter ID:server-9a66d164-3bb1-8bed-6eba-db06840981a9 Address:9a66d164-3bb1-8bed-6eba-db06840981a9}] -testLoggerAdapter verbose: a5daeebb-c76f-84d9-ec90-09a0d3c4f3d7: 06:15:37.278043 [INFO] raft: Removed peer 31438db6-c531-4f30-44db-1bef241313a1, stopping replication after 4 -testLoggerAdapter verbose: a5daeebb-c76f-84d9-ec90-09a0d3c4f3d7: 06:15:37.278080 [INFO] raft: aborting pipeline replication to peer {Voter 31438db6-c531-4f30-44db-1bef241313a1 31438db6-c531-4f30-44db-1bef241313a1} -testLoggerAdapter verbose: a5daeebb-c76f-84d9-ec90-09a0d3c4f3d7: 06:15:37.278167 [INFO] raft: aborting pipeline replication to peer {Voter server-9a66d164-3bb1-8bed-6eba-db06840981a9 9a66d164-3bb1-8bed-6eba-db06840981a9} ---- PASS: TestRaft_ProtocolVersion_Upgrade_2_3 (0.49s) - raft_test.go:97: cluster: 06:15:36.786017 [DEBUG] Fully Connecting - raft_test.go:97: a5daeebb-c76f-84d9-ec90-09a0d3c4f3d7: 06:15:36.786105 [INFO] raft: Initial configuration (index=1): [{Suffrage:Voter ID:a5daeebb-c76f-84d9-ec90-09a0d3c4f3d7 Address:a5daeebb-c76f-84d9-ec90-09a0d3c4f3d7} {Suffrage:Voter ID:31438db6-c531-4f30-44db-1bef241313a1 Address:31438db6-c531-4f30-44db-1bef241313a1}] - raft_test.go:97: 31438db6-c531-4f30-44db-1bef241313a1: 06:15:36.786187 [INFO] raft: Initial configuration (index=1): [{Suffrage:Voter ID:a5daeebb-c76f-84d9-ec90-09a0d3c4f3d7 Address:a5daeebb-c76f-84d9-ec90-09a0d3c4f3d7} {Suffrage:Voter ID:31438db6-c531-4f30-44db-1bef241313a1 Address:31438db6-c531-4f30-44db-1bef241313a1}] - raft_test.go:97: cluster: 06:15:36.786206 [INFO] Starting stability test for raft state: Follower - raft_test.go:97: 31438db6-c531-4f30-44db-1bef241313a1: 06:15:36.786236 [INFO] raft: Node at 31438db6-c531-4f30-44db-1bef241313a1 [Follower] entering Follower state (Leader: "") - raft_test.go:97: a5daeebb-c76f-84d9-ec90-09a0d3c4f3d7: 06:15:36.786234 [INFO] raft: Node at a5daeebb-c76f-84d9-ec90-09a0d3c4f3d7 [Follower] entering Follower state (Leader: "") - raft_test.go:97: a5daeebb-c76f-84d9-ec90-09a0d3c4f3d7: 06:15:36.856055 [WARN] raft: Heartbeat timeout from "" reached, starting election - raft_test.go:97: a5daeebb-c76f-84d9-ec90-09a0d3c4f3d7: 06:15:36.856102 [INFO] raft: Node at a5daeebb-c76f-84d9-ec90-09a0d3c4f3d7 [Candidate] entering Candidate state in term 2 - raft_test.go:97: a5daeebb-c76f-84d9-ec90-09a0d3c4f3d7: 06:15:36.856143 [DEBUG] raft: Votes needed: 2 - raft_test.go:97: a5daeebb-c76f-84d9-ec90-09a0d3c4f3d7: 06:15:36.856159 [DEBUG] raft: Vote granted from a5daeebb-c76f-84d9-ec90-09a0d3c4f3d7 in term 2. Tally: 1 - raft_test.go:97: cluster: 06:15:36.856120 [DEBUG] Resetting stability timeout - raft_test.go:97: cluster: 06:15:36.856238 [DEBUG] Resetting stability timeout - raft_test.go:97: a5daeebb-c76f-84d9-ec90-09a0d3c4f3d7: 06:15:36.856188 [DEBUG] raft: Vote granted from 31438db6-c531-4f30-44db-1bef241313a1 in term 2. Tally: 2 - raft_test.go:97: a5daeebb-c76f-84d9-ec90-09a0d3c4f3d7: 06:15:36.856277 [INFO] raft: Election won. Tally: 2 - raft_test.go:97: a5daeebb-c76f-84d9-ec90-09a0d3c4f3d7: 06:15:36.856304 [INFO] raft: Node at a5daeebb-c76f-84d9-ec90-09a0d3c4f3d7 [Leader] entering Leader state - raft_test.go:97: a5daeebb-c76f-84d9-ec90-09a0d3c4f3d7: 06:15:36.856339 [INFO] raft: Added peer 31438db6-c531-4f30-44db-1bef241313a1, starting replication - raft_test.go:97: cluster: 06:15:36.856391 [DEBUG] Resetting stability timeout - raft_test.go:97: a5daeebb-c76f-84d9-ec90-09a0d3c4f3d7: 06:15:36.856448 [INFO] raft: pipelining replication to peer {Voter 31438db6-c531-4f30-44db-1bef241313a1 31438db6-c531-4f30-44db-1bef241313a1} - raft_test.go:97: cluster: 06:15:36.961685 [INFO] Stable state for Follower reached at 2023-04-23 06:15:36.856424785 +0000 UTC m=+3.497820882 (1 nodes), 70.208828ms from start of poll, 70.385234ms from cluster start. Timeout at 2023-04-23 06:15:36.961583161 +0000 UTC m=+3.602979198, 105.158316ms after stability - raft_test.go:97: cluster: 06:15:36.961847 [DEBUG] Fully Connecting - raft_test.go:97: server-9a66d164-3bb1-8bed-6eba-db06840981a9: 06:15:36.961896 [INFO] raft: Initial configuration (index=0): [] - raft_test.go:97: cluster: 06:15:36.961931 [DEBUG] Fully Connecting - raft_test.go:97: cluster: 06:15:36.961952 [INFO] Starting stability test for raft state: Leader - raft_test.go:97: server-9a66d164-3bb1-8bed-6eba-db06840981a9: 06:15:36.961964 [INFO] raft: Node at 9a66d164-3bb1-8bed-6eba-db06840981a9 [Follower] entering Follower state (Leader: "") - raft_test.go:97: server-9a66d164-3bb1-8bed-6eba-db06840981a9: 06:15:37.049244 [WARN] raft: no known peers, aborting election - raft_test.go:97: cluster: 06:15:37.067159 [INFO] Stable state for Leader reached at 2023-04-23 06:15:36.961969047 +0000 UTC m=+3.603365086 (1 nodes), 599ns from start of poll, 175.929438ms from cluster start. Timeout at 2023-04-23 06:15:37.067080286 +0000 UTC m=+3.708476329, 105.111243ms after stability - raft_test.go:97: a5daeebb-c76f-84d9-ec90-09a0d3c4f3d7: 06:15:37.067214 [INFO] raft: Updating configuration with AddStaging (server-9a66d164-3bb1-8bed-6eba-db06840981a9, 9a66d164-3bb1-8bed-6eba-db06840981a9) to [{Suffrage:Voter ID:a5daeebb-c76f-84d9-ec90-09a0d3c4f3d7 Address:a5daeebb-c76f-84d9-ec90-09a0d3c4f3d7} {Suffrage:Voter ID:31438db6-c531-4f30-44db-1bef241313a1 Address:31438db6-c531-4f30-44db-1bef241313a1} {Suffrage:Voter ID:server-9a66d164-3bb1-8bed-6eba-db06840981a9 Address:9a66d164-3bb1-8bed-6eba-db06840981a9}] - raft_test.go:97: a5daeebb-c76f-84d9-ec90-09a0d3c4f3d7: 06:15:37.067265 [INFO] raft: Added peer server-9a66d164-3bb1-8bed-6eba-db06840981a9, starting replication - raft_test.go:97: server-9a66d164-3bb1-8bed-6eba-db06840981a9: 06:15:37.067313 [WARN] raft: Failed to get previous log: 3 log not found (last: 0) - raft_test.go:97: a5daeebb-c76f-84d9-ec90-09a0d3c4f3d7: 06:15:37.067347 [WARN] raft: AppendEntries to {Voter server-9a66d164-3bb1-8bed-6eba-db06840981a9 9a66d164-3bb1-8bed-6eba-db06840981a9} rejected, sending older logs (next: 1) - raft_test.go:97: a5daeebb-c76f-84d9-ec90-09a0d3c4f3d7: 06:15:37.067407 [INFO] raft: pipelining replication to peer {Voter server-9a66d164-3bb1-8bed-6eba-db06840981a9 9a66d164-3bb1-8bed-6eba-db06840981a9} - raft_test.go:97: cluster: 06:15:37.067459 [INFO] Starting stability test for raft state: Leader - raft_test.go:97: cluster: 06:15:37.172737 [INFO] Stable state for Leader reached at 2023-04-23 06:15:37.067489467 +0000 UTC m=+3.708885509 (1 nodes), 731ns from start of poll, 281.449861ms from cluster start. Timeout at 2023-04-23 06:15:37.172652781 +0000 UTC m=+3.814048834, 105.163325ms after stability - raft_test.go:97: cluster: 06:15:37.172772 [INFO] Starting stability test for raft state: Leader - raft_test.go:97: cluster: 06:15:37.277949 [INFO] Stable state for Leader reached at 2023-04-23 06:15:37.172788446 +0000 UTC m=+3.814184460 (1 nodes), 689ns from start of poll, 386.748812ms from cluster start. Timeout at 2023-04-23 06:15:37.277876047 +0000 UTC m=+3.919272083, 105.087623ms after stability - raft_test.go:97: a5daeebb-c76f-84d9-ec90-09a0d3c4f3d7: 06:15:37.277998 [INFO] raft: Updating configuration with RemoveServer (31438db6-c531-4f30-44db-1bef241313a1, ) to [{Suffrage:Voter ID:a5daeebb-c76f-84d9-ec90-09a0d3c4f3d7 Address:a5daeebb-c76f-84d9-ec90-09a0d3c4f3d7} {Suffrage:Voter ID:server-9a66d164-3bb1-8bed-6eba-db06840981a9 Address:9a66d164-3bb1-8bed-6eba-db06840981a9}] - raft_test.go:97: a5daeebb-c76f-84d9-ec90-09a0d3c4f3d7: 06:15:37.278043 [INFO] raft: Removed peer 31438db6-c531-4f30-44db-1bef241313a1, stopping replication after 4 - raft_test.go:97: a5daeebb-c76f-84d9-ec90-09a0d3c4f3d7: 06:15:37.278080 [INFO] raft: aborting pipeline replication to peer {Voter 31438db6-c531-4f30-44db-1bef241313a1 31438db6-c531-4f30-44db-1bef241313a1} - raft_test.go:97: a5daeebb-c76f-84d9-ec90-09a0d3c4f3d7: 06:15:37.278167 [INFO] raft: aborting pipeline replication to peer {Voter server-9a66d164-3bb1-8bed-6eba-db06840981a9 9a66d164-3bb1-8bed-6eba-db06840981a9} +testLoggerAdapter verbose: cluster: 17:44:05.053185 [DEBUG] Fully Connecting +testLoggerAdapter verbose: 2e3520a7-d4f3-df62-f74f-f875c158c8c2: 17:44:05.053338 [INFO] raft: Initial configuration (index=1): [{Suffrage:Voter ID:2e3520a7-d4f3-df62-f74f-f875c158c8c2 Address:2e3520a7-d4f3-df62-f74f-f875c158c8c2} {Suffrage:Voter ID:78538eef-9660-adf3-716b-5fc722f8f1c7 Address:78538eef-9660-adf3-716b-5fc722f8f1c7}] +testLoggerAdapter verbose: 78538eef-9660-adf3-716b-5fc722f8f1c7: 17:44:05.053451 [INFO] raft: Initial configuration (index=1): [{Suffrage:Voter ID:2e3520a7-d4f3-df62-f74f-f875c158c8c2 Address:2e3520a7-d4f3-df62-f74f-f875c158c8c2} {Suffrage:Voter ID:78538eef-9660-adf3-716b-5fc722f8f1c7 Address:78538eef-9660-adf3-716b-5fc722f8f1c7}] +testLoggerAdapter verbose: cluster: 17:44:05.053482 [INFO] Starting stability test for raft state: Follower +testLoggerAdapter verbose: 2e3520a7-d4f3-df62-f74f-f875c158c8c2: 17:44:05.053536 [INFO] raft: Node at 2e3520a7-d4f3-df62-f74f-f875c158c8c2 [Follower] entering Follower state (Leader: "") +testLoggerAdapter verbose: 78538eef-9660-adf3-716b-5fc722f8f1c7: 17:44:05.053584 [INFO] raft: Node at 78538eef-9660-adf3-716b-5fc722f8f1c7 [Follower] entering Follower state (Leader: "") +testLoggerAdapter verbose: 78538eef-9660-adf3-716b-5fc722f8f1c7: 17:44:05.122073 [WARN] raft: Heartbeat timeout from "" reached, starting election +testLoggerAdapter verbose: 78538eef-9660-adf3-716b-5fc722f8f1c7: 17:44:05.122200 [INFO] raft: Node at 78538eef-9660-adf3-716b-5fc722f8f1c7 [Candidate] entering Candidate state in term 2 +testLoggerAdapter verbose: 78538eef-9660-adf3-716b-5fc722f8f1c7: 17:44:05.122247 [DEBUG] raft: Votes needed: 2 +testLoggerAdapter verbose: 78538eef-9660-adf3-716b-5fc722f8f1c7: 17:44:05.122268 [DEBUG] raft: Vote granted from 78538eef-9660-adf3-716b-5fc722f8f1c7 in term 2. Tally: 1 +testLoggerAdapter verbose: 78538eef-9660-adf3-716b-5fc722f8f1c7: 17:44:05.122329 [DEBUG] raft: Vote granted from 2e3520a7-d4f3-df62-f74f-f875c158c8c2 in term 2. Tally: 2 +testLoggerAdapter verbose: 78538eef-9660-adf3-716b-5fc722f8f1c7: 17:44:05.122349 [INFO] raft: Election won. Tally: 2 +testLoggerAdapter verbose: 78538eef-9660-adf3-716b-5fc722f8f1c7: 17:44:05.122370 [INFO] raft: Node at 78538eef-9660-adf3-716b-5fc722f8f1c7 [Leader] entering Leader state +testLoggerAdapter verbose: 78538eef-9660-adf3-716b-5fc722f8f1c7: 17:44:05.122398 [INFO] raft: Added peer 2e3520a7-d4f3-df62-f74f-f875c158c8c2, starting replication +testLoggerAdapter verbose: 78538eef-9660-adf3-716b-5fc722f8f1c7: 17:44:05.122527 [INFO] raft: pipelining replication to peer {Voter 2e3520a7-d4f3-df62-f74f-f875c158c8c2 2e3520a7-d4f3-df62-f74f-f875c158c8c2} +testLoggerAdapter verbose: cluster: 17:44:05.122559 [DEBUG] Resetting stability timeout +testLoggerAdapter verbose: cluster: 17:44:05.122585 [DEBUG] Resetting stability timeout +testLoggerAdapter verbose: cluster: 17:44:05.122608 [DEBUG] Resetting stability timeout +testLoggerAdapter verbose: cluster: 17:44:05.230583 [INFO] Stable state for Follower reached at 2021-02-15 17:44:05.12262368 +0000 UTC m=+1.861775695 (1 nodes), 69.11721ms from start of poll, 69.409102ms from cluster start. Timeout at 2021-02-15 17:44:05.229947186 +0000 UTC m=+1.969099188, 107.323493ms after stability +testLoggerAdapter verbose: cluster: 17:44:05.230899 [DEBUG] Fully Connecting +testLoggerAdapter verbose: server-3e85dc48-0016-d306-4794-7ff200d32aef: 17:44:05.230973 [INFO] raft: Initial configuration (index=0): [] +testLoggerAdapter verbose: cluster: 17:44:05.231001 [DEBUG] Fully Connecting +testLoggerAdapter verbose: cluster: 17:44:05.231021 [INFO] Starting stability test for raft state: Leader +testLoggerAdapter verbose: server-3e85dc48-0016-d306-4794-7ff200d32aef: 17:44:05.231072 [INFO] raft: Node at 3e85dc48-0016-d306-4794-7ff200d32aef [Follower] entering Follower state (Leader: "") +testLoggerAdapter verbose: server-3e85dc48-0016-d306-4794-7ff200d32aef: 17:44:05.298139 [WARN] raft: no known peers, aborting election +testLoggerAdapter verbose: cluster: 17:44:05.342115 [INFO] Stable state for Leader reached at 2021-02-15 17:44:05.231041125 +0000 UTC m=+1.970193025 (1 nodes), 2.289µs from start of poll, 177.826432ms from cluster start. Timeout at 2021-02-15 17:44:05.337970184 +0000 UTC m=+2.077122041, 106.929016ms after stability +testLoggerAdapter verbose: 78538eef-9660-adf3-716b-5fc722f8f1c7: 17:44:05.342230 [INFO] raft: Updating configuration with AddStaging (server-3e85dc48-0016-d306-4794-7ff200d32aef, 3e85dc48-0016-d306-4794-7ff200d32aef) to [{Suffrage:Voter ID:2e3520a7-d4f3-df62-f74f-f875c158c8c2 Address:2e3520a7-d4f3-df62-f74f-f875c158c8c2} {Suffrage:Voter ID:78538eef-9660-adf3-716b-5fc722f8f1c7 Address:78538eef-9660-adf3-716b-5fc722f8f1c7} {Suffrage:Voter ID:server-3e85dc48-0016-d306-4794-7ff200d32aef Address:3e85dc48-0016-d306-4794-7ff200d32aef}] +testLoggerAdapter verbose: 78538eef-9660-adf3-716b-5fc722f8f1c7: 17:44:05.342310 [INFO] raft: Added peer server-3e85dc48-0016-d306-4794-7ff200d32aef, starting replication +testLoggerAdapter verbose: server-3e85dc48-0016-d306-4794-7ff200d32aef: 17:44:05.342360 [WARN] raft: Failed to get previous log: 3 log not found (last: 0) +testLoggerAdapter verbose: 78538eef-9660-adf3-716b-5fc722f8f1c7: 17:44:05.342419 [WARN] raft: AppendEntries to {Voter server-3e85dc48-0016-d306-4794-7ff200d32aef 3e85dc48-0016-d306-4794-7ff200d32aef} rejected, sending older logs (next: 1) +testLoggerAdapter verbose: 78538eef-9660-adf3-716b-5fc722f8f1c7: 17:44:05.342505 [INFO] raft: pipelining replication to peer {Voter server-3e85dc48-0016-d306-4794-7ff200d32aef 3e85dc48-0016-d306-4794-7ff200d32aef} +testLoggerAdapter verbose: cluster: 17:44:05.342604 [INFO] Starting stability test for raft state: Leader +testLoggerAdapter verbose: cluster: 17:44:05.462090 [INFO] Stable state for Leader reached at 2021-02-15 17:44:05.342625367 +0000 UTC m=+2.081777270 (1 nodes), 2.151µs from start of poll, 289.410677ms from cluster start. Timeout at 2021-02-15 17:44:05.461967962 +0000 UTC m=+2.201120703, 119.343433ms after stability +testLoggerAdapter verbose: cluster: 17:44:05.462163 [INFO] Starting stability test for raft state: Leader +testLoggerAdapter verbose: cluster: 17:44:05.570110 [INFO] Stable state for Leader reached at 2021-02-15 17:44:05.462195602 +0000 UTC m=+2.201347510 (1 nodes), 2.777µs from start of poll, 408.980917ms from cluster start. Timeout at 2021-02-15 17:44:05.569943067 +0000 UTC m=+2.309095680, 107.74817ms after stability +testLoggerAdapter verbose: 78538eef-9660-adf3-716b-5fc722f8f1c7: 17:44:05.570215 [INFO] raft: Updating configuration with RemoveServer (2e3520a7-d4f3-df62-f74f-f875c158c8c2, ) to [{Suffrage:Voter ID:78538eef-9660-adf3-716b-5fc722f8f1c7 Address:78538eef-9660-adf3-716b-5fc722f8f1c7} {Suffrage:Voter ID:server-3e85dc48-0016-d306-4794-7ff200d32aef Address:3e85dc48-0016-d306-4794-7ff200d32aef}] +testLoggerAdapter verbose: 78538eef-9660-adf3-716b-5fc722f8f1c7: 17:44:05.570316 [INFO] raft: Removed peer 2e3520a7-d4f3-df62-f74f-f875c158c8c2, stopping replication after 4 +testLoggerAdapter verbose: 78538eef-9660-adf3-716b-5fc722f8f1c7: 17:44:05.570477 [INFO] raft: aborting pipeline replication to peer {Voter 2e3520a7-d4f3-df62-f74f-f875c158c8c2 2e3520a7-d4f3-df62-f74f-f875c158c8c2} +testLoggerAdapter verbose: 78538eef-9660-adf3-716b-5fc722f8f1c7: 17:44:05.570610 [INFO] raft: aborting pipeline replication to peer {Voter server-3e85dc48-0016-d306-4794-7ff200d32aef 3e85dc48-0016-d306-4794-7ff200d32aef} +--- PASS: TestRaft_ProtocolVersion_Upgrade_2_3 (0.52s) + raft_test.go:97: cluster: 17:44:05.053185 [DEBUG] Fully Connecting + raft_test.go:97: 2e3520a7-d4f3-df62-f74f-f875c158c8c2: 17:44:05.053338 [INFO] raft: Initial configuration (index=1): [{Suffrage:Voter ID:2e3520a7-d4f3-df62-f74f-f875c158c8c2 Address:2e3520a7-d4f3-df62-f74f-f875c158c8c2} {Suffrage:Voter ID:78538eef-9660-adf3-716b-5fc722f8f1c7 Address:78538eef-9660-adf3-716b-5fc722f8f1c7}] + raft_test.go:97: 78538eef-9660-adf3-716b-5fc722f8f1c7: 17:44:05.053451 [INFO] raft: Initial configuration (index=1): [{Suffrage:Voter ID:2e3520a7-d4f3-df62-f74f-f875c158c8c2 Address:2e3520a7-d4f3-df62-f74f-f875c158c8c2} {Suffrage:Voter ID:78538eef-9660-adf3-716b-5fc722f8f1c7 Address:78538eef-9660-adf3-716b-5fc722f8f1c7}] + raft_test.go:97: cluster: 17:44:05.053482 [INFO] Starting stability test for raft state: Follower + raft_test.go:97: 2e3520a7-d4f3-df62-f74f-f875c158c8c2: 17:44:05.053536 [INFO] raft: Node at 2e3520a7-d4f3-df62-f74f-f875c158c8c2 [Follower] entering Follower state (Leader: "") + raft_test.go:97: 78538eef-9660-adf3-716b-5fc722f8f1c7: 17:44:05.053584 [INFO] raft: Node at 78538eef-9660-adf3-716b-5fc722f8f1c7 [Follower] entering Follower state (Leader: "") + raft_test.go:97: 78538eef-9660-adf3-716b-5fc722f8f1c7: 17:44:05.122073 [WARN] raft: Heartbeat timeout from "" reached, starting election + raft_test.go:97: 78538eef-9660-adf3-716b-5fc722f8f1c7: 17:44:05.122200 [INFO] raft: Node at 78538eef-9660-adf3-716b-5fc722f8f1c7 [Candidate] entering Candidate state in term 2 + raft_test.go:97: 78538eef-9660-adf3-716b-5fc722f8f1c7: 17:44:05.122247 [DEBUG] raft: Votes needed: 2 + raft_test.go:97: 78538eef-9660-adf3-716b-5fc722f8f1c7: 17:44:05.122268 [DEBUG] raft: Vote granted from 78538eef-9660-adf3-716b-5fc722f8f1c7 in term 2. Tally: 1 + raft_test.go:97: 78538eef-9660-adf3-716b-5fc722f8f1c7: 17:44:05.122329 [DEBUG] raft: Vote granted from 2e3520a7-d4f3-df62-f74f-f875c158c8c2 in term 2. Tally: 2 + raft_test.go:97: 78538eef-9660-adf3-716b-5fc722f8f1c7: 17:44:05.122349 [INFO] raft: Election won. Tally: 2 + raft_test.go:97: 78538eef-9660-adf3-716b-5fc722f8f1c7: 17:44:05.122370 [INFO] raft: Node at 78538eef-9660-adf3-716b-5fc722f8f1c7 [Leader] entering Leader state + raft_test.go:97: 78538eef-9660-adf3-716b-5fc722f8f1c7: 17:44:05.122398 [INFO] raft: Added peer 2e3520a7-d4f3-df62-f74f-f875c158c8c2, starting replication + raft_test.go:97: 78538eef-9660-adf3-716b-5fc722f8f1c7: 17:44:05.122527 [INFO] raft: pipelining replication to peer {Voter 2e3520a7-d4f3-df62-f74f-f875c158c8c2 2e3520a7-d4f3-df62-f74f-f875c158c8c2} + raft_test.go:97: cluster: 17:44:05.122559 [DEBUG] Resetting stability timeout + raft_test.go:97: cluster: 17:44:05.122585 [DEBUG] Resetting stability timeout + raft_test.go:97: cluster: 17:44:05.122608 [DEBUG] Resetting stability timeout + raft_test.go:97: cluster: 17:44:05.230583 [INFO] Stable state for Follower reached at 2021-02-15 17:44:05.12262368 +0000 UTC m=+1.861775695 (1 nodes), 69.11721ms from start of poll, 69.409102ms from cluster start. Timeout at 2021-02-15 17:44:05.229947186 +0000 UTC m=+1.969099188, 107.323493ms after stability + raft_test.go:97: cluster: 17:44:05.230899 [DEBUG] Fully Connecting + raft_test.go:97: server-3e85dc48-0016-d306-4794-7ff200d32aef: 17:44:05.230973 [INFO] raft: Initial configuration (index=0): [] + raft_test.go:97: cluster: 17:44:05.231001 [DEBUG] Fully Connecting + raft_test.go:97: cluster: 17:44:05.231021 [INFO] Starting stability test for raft state: Leader + raft_test.go:97: server-3e85dc48-0016-d306-4794-7ff200d32aef: 17:44:05.231072 [INFO] raft: Node at 3e85dc48-0016-d306-4794-7ff200d32aef [Follower] entering Follower state (Leader: "") + raft_test.go:97: server-3e85dc48-0016-d306-4794-7ff200d32aef: 17:44:05.298139 [WARN] raft: no known peers, aborting election + raft_test.go:97: cluster: 17:44:05.342115 [INFO] Stable state for Leader reached at 2021-02-15 17:44:05.231041125 +0000 UTC m=+1.970193025 (1 nodes), 2.289µs from start of poll, 177.826432ms from cluster start. Timeout at 2021-02-15 17:44:05.337970184 +0000 UTC m=+2.077122041, 106.929016ms after stability + raft_test.go:97: 78538eef-9660-adf3-716b-5fc722f8f1c7: 17:44:05.342230 [INFO] raft: Updating configuration with AddStaging (server-3e85dc48-0016-d306-4794-7ff200d32aef, 3e85dc48-0016-d306-4794-7ff200d32aef) to [{Suffrage:Voter ID:2e3520a7-d4f3-df62-f74f-f875c158c8c2 Address:2e3520a7-d4f3-df62-f74f-f875c158c8c2} {Suffrage:Voter ID:78538eef-9660-adf3-716b-5fc722f8f1c7 Address:78538eef-9660-adf3-716b-5fc722f8f1c7} {Suffrage:Voter ID:server-3e85dc48-0016-d306-4794-7ff200d32aef Address:3e85dc48-0016-d306-4794-7ff200d32aef}] + raft_test.go:97: 78538eef-9660-adf3-716b-5fc722f8f1c7: 17:44:05.342310 [INFO] raft: Added peer server-3e85dc48-0016-d306-4794-7ff200d32aef, starting replication + raft_test.go:97: server-3e85dc48-0016-d306-4794-7ff200d32aef: 17:44:05.342360 [WARN] raft: Failed to get previous log: 3 log not found (last: 0) + raft_test.go:97: 78538eef-9660-adf3-716b-5fc722f8f1c7: 17:44:05.342419 [WARN] raft: AppendEntries to {Voter server-3e85dc48-0016-d306-4794-7ff200d32aef 3e85dc48-0016-d306-4794-7ff200d32aef} rejected, sending older logs (next: 1) + raft_test.go:97: 78538eef-9660-adf3-716b-5fc722f8f1c7: 17:44:05.342505 [INFO] raft: pipelining replication to peer {Voter server-3e85dc48-0016-d306-4794-7ff200d32aef 3e85dc48-0016-d306-4794-7ff200d32aef} + raft_test.go:97: cluster: 17:44:05.342604 [INFO] Starting stability test for raft state: Leader + raft_test.go:97: cluster: 17:44:05.462090 [INFO] Stable state for Leader reached at 2021-02-15 17:44:05.342625367 +0000 UTC m=+2.081777270 (1 nodes), 2.151µs from start of poll, 289.410677ms from cluster start. Timeout at 2021-02-15 17:44:05.461967962 +0000 UTC m=+2.201120703, 119.343433ms after stability + raft_test.go:97: cluster: 17:44:05.462163 [INFO] Starting stability test for raft state: Leader + raft_test.go:97: cluster: 17:44:05.570110 [INFO] Stable state for Leader reached at 2021-02-15 17:44:05.462195602 +0000 UTC m=+2.201347510 (1 nodes), 2.777µs from start of poll, 408.980917ms from cluster start. Timeout at 2021-02-15 17:44:05.569943067 +0000 UTC m=+2.309095680, 107.74817ms after stability + raft_test.go:97: 78538eef-9660-adf3-716b-5fc722f8f1c7: 17:44:05.570215 [INFO] raft: Updating configuration with RemoveServer (2e3520a7-d4f3-df62-f74f-f875c158c8c2, ) to [{Suffrage:Voter ID:78538eef-9660-adf3-716b-5fc722f8f1c7 Address:78538eef-9660-adf3-716b-5fc722f8f1c7} {Suffrage:Voter ID:server-3e85dc48-0016-d306-4794-7ff200d32aef Address:3e85dc48-0016-d306-4794-7ff200d32aef}] + raft_test.go:97: 78538eef-9660-adf3-716b-5fc722f8f1c7: 17:44:05.570316 [INFO] raft: Removed peer 2e3520a7-d4f3-df62-f74f-f875c158c8c2, stopping replication after 4 + raft_test.go:97: 78538eef-9660-adf3-716b-5fc722f8f1c7: 17:44:05.570477 [INFO] raft: aborting pipeline replication to peer {Voter 2e3520a7-d4f3-df62-f74f-f875c158c8c2 2e3520a7-d4f3-df62-f74f-f875c158c8c2} + raft_test.go:97: 78538eef-9660-adf3-716b-5fc722f8f1c7: 17:44:05.570610 [INFO] raft: aborting pipeline replication to peer {Voter server-3e85dc48-0016-d306-4794-7ff200d32aef 3e85dc48-0016-d306-4794-7ff200d32aef} === RUN TestTCPTransport_BadAddr --- PASS: TestTCPTransport_BadAddr (0.00s) === RUN TestTCPTransport_WithAdvertise @@ -1277,7 +1367,7 @@ === RUN TestTransport_EncodeDecode --- PASS: TestTransport_EncodeDecode (0.00s) === RUN TestRandomTimeout ---- PASS: TestRandomTimeout (0.00s) +--- PASS: TestRandomTimeout (0.01s) === RUN TestNewSeed --- PASS: TestNewSeed (0.00s) === RUN TestRandomTimeout_NoTime @@ -1287,11 +1377,11 @@ === RUN TestMax --- PASS: TestMax (0.00s) === RUN TestGenerateUUID ---- PASS: TestGenerateUUID (0.00s) +--- PASS: TestGenerateUUID (0.05s) === RUN TestBackoff --- PASS: TestBackoff (0.00s) PASS -ok github.com/hashicorp/raft 3.930s +ok github.com/hashicorp/raft 2.385s ? github.com/hashicorp/raft/bench [no test files] create-stamp debian/debhelper-build-stamp fakeroot debian/rules binary @@ -1321,12 +1411,14 @@ dpkg-source --after-build . dpkg-buildpackage: info: binary-only upload (no source included) I: copying local configuration +I: user script /srv/workspace/pbuilder/20251/tmp/hooks/B01_cleanup starting +I: user script /srv/workspace/pbuilder/20251/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/14778 and its subdirectories -I: Current time: Sat Apr 22 18:15:40 -12 2023 -I: pbuilder-time-stamp: 1682230540 +I: removing directory /srv/workspace/pbuilder/20251 and its subdirectories +I: Current time: Tue Feb 16 07:44:49 +14 2021 +I: pbuilder-time-stamp: 1613411089