Diff of the two buildlogs: -- --- b1/build.log 2021-07-03 09:25:57.329351544 +0000 +++ b2/build.log 2021-07-03 09:26:54.183226705 +0000 @@ -1,6 +1,6 @@ I: pbuilder: network access will be disabled during build -I: Current time: Fri Aug 5 03:48:05 -12 2022 -I: pbuilder-time-stamp: 1659714485 +I: Current time: Sat Jul 3 23:25:58 +14 2021 +I: pbuilder-time-stamp: 1625304358 I: Building the build Environment I: extracting base tarball [/var/cache/pbuilder/buster-reproducible-base.tgz] I: copying local configuration @@ -17,7 +17,7 @@ I: Extracting source gpgv: unknown type of key resource 'trustedkeys.kbx' gpgv: keyblock resource '/root/.gnupg/trustedkeys.kbx': General error -gpgv: Signature made 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 @@ -29,136 +29,170 @@ 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/53500/tmp/hooks/D02_print_environment starting +I: user script /srv/workspace/pbuilder/16591/tmp/hooks/D01_modify_environment starting +debug: Running on ionos1-amd64. +I: Changing host+domainname to test build reproducibility +I: Adding a custom variable just for the fun of it... +I: Changing /bin/sh to bash +Removing 'diversion of /bin/sh to /bin/sh.distrib by dash' +Adding 'diversion of /bin/sh to /bin/sh.distrib by bash' +Removing 'diversion of /usr/share/man/man1/sh.1.gz to /usr/share/man/man1/sh.distrib.1.gz by dash' +Adding 'diversion of /usr/share/man/man1/sh.1.gz to /usr/share/man/man1/sh.distrib.1.gz by bash' +I: Setting pbuilder2's login shell to /bin/bash +I: Setting pbuilder2's GECOS to second user,second room,second work-phone,second home-phone,second other +I: user script /srv/workspace/pbuilder/16591/tmp/hooks/D01_modify_environment finished +I: user script /srv/workspace/pbuilder/16591/tmp/hooks/D02_print_environment starting I: set - BUILDDIR='/build' - BUILDUSERGECOS='first user,first room,first work-phone,first home-phone,first other' - BUILDUSERNAME='pbuilder1' - BUILD_ARCH='amd64' - DEBIAN_FRONTEND='noninteractive' - DEB_BUILD_OPTIONS='buildinfo=+all reproducible=+all parallel=16' - DISTRIBUTION='' - HOME='/root' - HOST_ARCH='amd64' + BASH=/bin/sh + BASHOPTS=checkwinsize:cmdhist:complete_fullquote:extquote:force_fignore:globasciiranges:hostcomplete:interactive_comments:progcomp:promptvars:sourcepath + BASH_ALIASES=() + BASH_ARGC=() + BASH_ARGV=() + BASH_CMDS=() + BASH_LINENO=([0]="12" [1]="0") + BASH_SOURCE=([0]="/tmp/hooks/D02_print_environment" [1]="/tmp/hooks/D02_print_environment") + BASH_VERSINFO=([0]="5" [1]="0" [2]="3" [3]="1" [4]="release" [5]="x86_64-pc-linux-gnu") + BASH_VERSION='5.0.3(1)-release' + BUILDDIR=/build + BUILDUSERGECOS='second user,second room,second work-phone,second home-phone,second other' + BUILDUSERNAME=pbuilder2 + BUILD_ARCH=amd64 + DEBIAN_FRONTEND=noninteractive + DEB_BUILD_OPTIONS='buildinfo=+all reproducible=+all parallel=15' + DIRSTACK=() + DISTRIBUTION= + EUID=0 + FUNCNAME=([0]="Echo" [1]="main") + GROUPS=() + HOME=/root + HOSTNAME=i-capture-the-hostname + HOSTTYPE=x86_64 + HOST_ARCH=amd64 IFS=' ' - INVOCATION_ID='6c5070440b5042629e5600b1c3ed4b7d' - LANG='C' - LANGUAGE='en_US:en' - LC_ALL='C' - MAIL='/var/mail/root' - OPTIND='1' - PATH='/usr/sbin:/usr/bin:/sbin:/bin:/usr/games' - PBCURRENTCOMMANDLINEOPERATION='build' - PBUILDER_OPERATION='build' - PBUILDER_PKGDATADIR='/usr/share/pbuilder' - PBUILDER_PKGLIBDIR='/usr/lib/pbuilder' - PBUILDER_SYSCONFDIR='/etc' - PPID='53500' - PS1='# ' - PS2='> ' + INVOCATION_ID=843b42f9daf0477ba503e24c924348c8 + LANG=C + LANGUAGE=et_EE:et + LC_ALL=C + MACHTYPE=x86_64-pc-linux-gnu + MAIL=/var/mail/root + OPTERR=1 + OPTIND=1 + OSTYPE=linux-gnu + PATH=/usr/sbin:/usr/bin:/sbin:/bin:/usr/games:/i/capture/the/path + PBCURRENTCOMMANDLINEOPERATION=build + PBUILDER_OPERATION=build + PBUILDER_PKGDATADIR=/usr/share/pbuilder + PBUILDER_PKGLIBDIR=/usr/lib/pbuilder + PBUILDER_SYSCONFDIR=/etc + PIPESTATUS=([0]="0") + POSIXLY_CORRECT=y + PPID=16591 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.ZOYU0m4tky/pbuilderrc_gBq6 --hookdir /etc/pbuilder/first-build-hooks --debbuildopts -b --basetgz /var/cache/pbuilder/buster-reproducible-base.tgz --buildresult /srv/reproducible-results/rbuild-debian/tmp.ZOYU0m4tky/b1 --logfile b1/build.log golang-github-hashicorp-raft_1.0.0+git20180823.82694fb-3.dsc' - SUDO_GID='110' - SUDO_UID='105' - 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.ZOYU0m4tky/pbuilderrc_F3Ez --hookdir /etc/pbuilder/rebuild-hooks --debbuildopts -b --basetgz /var/cache/pbuilder/buster-reproducible-base.tgz --buildresult /srv/reproducible-results/rbuild-debian/tmp.ZOYU0m4tky/b2 --logfile b2/build.log golang-github-hashicorp-raft_1.0.0+git20180823.82694fb-3.dsc' + SUDO_GID=110 + SUDO_UID=105 + 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 ionos5-amd64 5.10.0-0.bpo.7-amd64 #1 SMP Debian 5.10.40-1~bpo10+1 (2021-06-04) x86_64 GNU/Linux + Linux i-capture-the-hostname 4.19.0-17-amd64 #1 SMP Debian 4.19.194-2 (2021-06-21) x86_64 GNU/Linux I: ls -l /bin total 5116 - -rwxr-xr-x 1 root root 1168776 Apr 17 2019 bash - -rwxr-xr-x 3 root root 38984 Jul 10 2019 bunzip2 - -rwxr-xr-x 3 root root 38984 Jul 10 2019 bzcat - lrwxrwxrwx 1 root root 6 Jul 10 2019 bzcmp -> bzdiff - -rwxr-xr-x 1 root root 2227 Jul 10 2019 bzdiff - lrwxrwxrwx 1 root root 6 Jul 10 2019 bzegrep -> bzgrep - -rwxr-xr-x 1 root root 4877 Jun 24 2019 bzexe - lrwxrwxrwx 1 root root 6 Jul 10 2019 bzfgrep -> bzgrep - -rwxr-xr-x 1 root root 3641 Jul 10 2019 bzgrep - -rwxr-xr-x 3 root root 38984 Jul 10 2019 bzip2 - -rwxr-xr-x 1 root root 14328 Jul 10 2019 bzip2recover - lrwxrwxrwx 1 root root 6 Jul 10 2019 bzless -> bzmore - -rwxr-xr-x 1 root root 1297 Jul 10 2019 bzmore - -rwxr-xr-x 1 root root 43744 Feb 28 2019 cat - -rwxr-xr-x 1 root root 64320 Feb 28 2019 chgrp - -rwxr-xr-x 1 root root 64288 Feb 28 2019 chmod - -rwxr-xr-x 1 root root 72512 Feb 28 2019 chown - -rwxr-xr-x 1 root root 146880 Feb 28 2019 cp - -rwxr-xr-x 1 root root 121464 Jan 17 2019 dash - -rwxr-xr-x 1 root root 109408 Feb 28 2019 date - -rwxr-xr-x 1 root root 76712 Feb 28 2019 dd - -rwxr-xr-x 1 root root 93744 Feb 28 2019 df - -rwxr-xr-x 1 root root 138856 Feb 28 2019 dir - -rwxr-xr-x 1 root root 84288 Jan 9 2019 dmesg - lrwxrwxrwx 1 root root 8 Sep 26 2018 dnsdomainname -> hostname - lrwxrwxrwx 1 root root 8 Sep 26 2018 domainname -> hostname - -rwxr-xr-x 1 root root 39520 Feb 28 2019 echo - -rwxr-xr-x 1 root root 28 Jan 7 2019 egrep - -rwxr-xr-x 1 root root 35424 Feb 28 2019 false - -rwxr-xr-x 1 root root 28 Jan 7 2019 fgrep - -rwxr-xr-x 1 root root 68880 Jan 9 2019 findmnt - -rwsr-xr-x 1 root root 34896 Apr 22 2020 fusermount - -rwxr-xr-x 1 root root 198976 Jan 7 2019 grep - -rwxr-xr-x 2 root root 2345 Jan 5 2019 gunzip - -rwxr-xr-x 1 root root 6375 Jan 5 2019 gzexe - -rwxr-xr-x 1 root root 98048 Jan 5 2019 gzip - -rwxr-xr-x 1 root root 26696 Sep 26 2018 hostname - -rwxr-xr-x 1 root root 68552 Feb 28 2019 ln - -rwxr-xr-x 1 root root 56760 Jul 26 2018 login - -rwxr-xr-x 1 root root 138856 Feb 28 2019 ls - -rwxr-xr-x 1 root root 108624 Jan 9 2019 lsblk - -rwxr-xr-x 1 root root 89088 Feb 28 2019 mkdir - -rwxr-xr-x 1 root root 68544 Feb 28 2019 mknod - -rwxr-xr-x 1 root root 43808 Feb 28 2019 mktemp - -rwxr-xr-x 1 root root 43008 Jan 9 2019 more - -rwsr-xr-x 1 root root 51280 Jan 9 2019 mount - -rwxr-xr-x 1 root root 14408 Jan 9 2019 mountpoint - -rwxr-xr-x 1 root root 138728 Feb 28 2019 mv - lrwxrwxrwx 1 root root 8 Sep 26 2018 nisdomainname -> hostname - lrwxrwxrwx 1 root root 14 Feb 14 2019 pidof -> /sbin/killall5 - -rwxr-xr-x 1 root root 39616 Feb 28 2019 pwd - lrwxrwxrwx 1 root root 4 Apr 17 2019 rbash -> bash - -rwxr-xr-x 1 root root 47776 Feb 28 2019 readlink - -rwxr-xr-x 1 root root 68416 Feb 28 2019 rm - -rwxr-xr-x 1 root root 47776 Feb 28 2019 rmdir - -rwxr-xr-x 1 root root 23312 Jan 21 2019 run-parts - -rwxr-xr-x 1 root root 122224 Dec 22 2018 sed - lrwxrwxrwx 1 root root 4 Jul 24 02:46 sh -> dash - -rwxr-xr-x 1 root root 39552 Feb 28 2019 sleep - -rwxr-xr-x 1 root root 80672 Feb 28 2019 stty - -rwsr-xr-x 1 root root 63568 Jan 9 2019 su - -rwxr-xr-x 1 root root 35488 Feb 28 2019 sync - -rwxr-xr-x 1 root root 445560 Apr 23 2019 tar - -rwxr-xr-x 1 root root 14440 Jan 21 2019 tempfile - -rwxr-xr-x 1 root root 97152 Feb 28 2019 touch - -rwxr-xr-x 1 root root 35424 Feb 28 2019 true - -rwxr-xr-x 1 root root 14328 Apr 22 2020 ulockmgr_server - -rwsr-xr-x 1 root root 34888 Jan 9 2019 umount - -rwxr-xr-x 1 root root 39584 Feb 28 2019 uname - -rwxr-xr-x 2 root root 2345 Jan 5 2019 uncompress - -rwxr-xr-x 1 root root 138856 Feb 28 2019 vdir - -rwxr-xr-x 1 root root 34896 Jan 9 2019 wdctl - -rwxr-xr-x 1 root root 946 Jan 21 2019 which - lrwxrwxrwx 1 root root 8 Sep 26 2018 ypdomainname -> hostname - -rwxr-xr-x 1 root root 1983 Jan 5 2019 zcat - -rwxr-xr-x 1 root root 1677 Jan 5 2019 zcmp - -rwxr-xr-x 1 root root 5879 Jan 5 2019 zdiff - -rwxr-xr-x 1 root root 29 Jan 5 2019 zegrep - -rwxr-xr-x 1 root root 29 Jan 5 2019 zfgrep - -rwxr-xr-x 1 root root 2080 Jan 5 2019 zforce - -rwxr-xr-x 1 root root 7584 Jan 5 2019 zgrep - -rwxr-xr-x 1 root root 2205 Jan 5 2019 zless - -rwxr-xr-x 1 root root 1841 Jan 5 2019 zmore - -rwxr-xr-x 1 root root 4552 Jan 5 2019 znew -I: user script /srv/workspace/pbuilder/53500/tmp/hooks/D02_print_environment finished + -rwxr-xr-x 1 root root 1168776 Apr 18 2019 bash + -rwxr-xr-x 3 root root 38984 Jul 11 2019 bunzip2 + -rwxr-xr-x 3 root root 38984 Jul 11 2019 bzcat + lrwxrwxrwx 1 root root 6 Jul 11 2019 bzcmp -> bzdiff + -rwxr-xr-x 1 root root 2227 Jul 11 2019 bzdiff + lrwxrwxrwx 1 root root 6 Jul 11 2019 bzegrep -> bzgrep + -rwxr-xr-x 1 root root 4877 Jun 25 2019 bzexe + lrwxrwxrwx 1 root root 6 Jul 11 2019 bzfgrep -> bzgrep + -rwxr-xr-x 1 root root 3641 Jul 11 2019 bzgrep + -rwxr-xr-x 3 root root 38984 Jul 11 2019 bzip2 + -rwxr-xr-x 1 root root 14328 Jul 11 2019 bzip2recover + lrwxrwxrwx 1 root root 6 Jul 11 2019 bzless -> bzmore + -rwxr-xr-x 1 root root 1297 Jul 11 2019 bzmore + -rwxr-xr-x 1 root root 43744 Mar 1 2019 cat + -rwxr-xr-x 1 root root 64320 Mar 1 2019 chgrp + -rwxr-xr-x 1 root root 64288 Mar 1 2019 chmod + -rwxr-xr-x 1 root root 72512 Mar 1 2019 chown + -rwxr-xr-x 1 root root 146880 Mar 1 2019 cp + -rwxr-xr-x 1 root root 121464 Jan 18 2019 dash + -rwxr-xr-x 1 root root 109408 Mar 1 2019 date + -rwxr-xr-x 1 root root 76712 Mar 1 2019 dd + -rwxr-xr-x 1 root root 93744 Mar 1 2019 df + -rwxr-xr-x 1 root root 138856 Mar 1 2019 dir + -rwxr-xr-x 1 root root 84288 Jan 10 2019 dmesg + lrwxrwxrwx 1 root root 8 Sep 27 2018 dnsdomainname -> hostname + lrwxrwxrwx 1 root root 8 Sep 27 2018 domainname -> hostname + -rwxr-xr-x 1 root root 39520 Mar 1 2019 echo + -rwxr-xr-x 1 root root 28 Jan 8 2019 egrep + -rwxr-xr-x 1 root root 35424 Mar 1 2019 false + -rwxr-xr-x 1 root root 28 Jan 8 2019 fgrep + -rwxr-xr-x 1 root root 68880 Jan 10 2019 findmnt + -rwsr-xr-x 1 root root 34896 Apr 23 2020 fusermount + -rwxr-xr-x 1 root root 198976 Jan 8 2019 grep + -rwxr-xr-x 2 root root 2345 Jan 6 2019 gunzip + -rwxr-xr-x 1 root root 6375 Jan 6 2019 gzexe + -rwxr-xr-x 1 root root 98048 Jan 6 2019 gzip + -rwxr-xr-x 1 root root 26696 Sep 27 2018 hostname + -rwxr-xr-x 1 root root 68552 Mar 1 2019 ln + -rwxr-xr-x 1 root root 56760 Jul 27 2018 login + -rwxr-xr-x 1 root root 138856 Mar 1 2019 ls + -rwxr-xr-x 1 root root 108624 Jan 10 2019 lsblk + -rwxr-xr-x 1 root root 89088 Mar 1 2019 mkdir + -rwxr-xr-x 1 root root 68544 Mar 1 2019 mknod + -rwxr-xr-x 1 root root 43808 Mar 1 2019 mktemp + -rwxr-xr-x 1 root root 43008 Jan 10 2019 more + -rwsr-xr-x 1 root root 51280 Jan 10 2019 mount + -rwxr-xr-x 1 root root 14408 Jan 10 2019 mountpoint + -rwxr-xr-x 1 root root 138728 Mar 1 2019 mv + lrwxrwxrwx 1 root root 8 Sep 27 2018 nisdomainname -> hostname + lrwxrwxrwx 1 root root 14 Feb 15 2019 pidof -> /sbin/killall5 + -rwxr-xr-x 1 root root 39616 Mar 1 2019 pwd + lrwxrwxrwx 1 root root 4 Apr 18 2019 rbash -> bash + -rwxr-xr-x 1 root root 47776 Mar 1 2019 readlink + -rwxr-xr-x 1 root root 68416 Mar 1 2019 rm + -rwxr-xr-x 1 root root 47776 Mar 1 2019 rmdir + -rwxr-xr-x 1 root root 23312 Jan 22 2019 run-parts + -rwxr-xr-x 1 root root 122224 Dec 23 2018 sed + lrwxrwxrwx 1 root root 4 Jul 3 23:26 sh -> bash + lrwxrwxrwx 1 root root 4 Jun 21 22:24 sh.distrib -> dash + -rwxr-xr-x 1 root root 39552 Mar 1 2019 sleep + -rwxr-xr-x 1 root root 80672 Mar 1 2019 stty + -rwsr-xr-x 1 root root 63568 Jan 10 2019 su + -rwxr-xr-x 1 root root 35488 Mar 1 2019 sync + -rwxr-xr-x 1 root root 445560 Apr 24 2019 tar + -rwxr-xr-x 1 root root 14440 Jan 22 2019 tempfile + -rwxr-xr-x 1 root root 97152 Mar 1 2019 touch + -rwxr-xr-x 1 root root 35424 Mar 1 2019 true + -rwxr-xr-x 1 root root 14328 Apr 23 2020 ulockmgr_server + -rwsr-xr-x 1 root root 34888 Jan 10 2019 umount + -rwxr-xr-x 1 root root 39584 Mar 1 2019 uname + -rwxr-xr-x 2 root root 2345 Jan 6 2019 uncompress + -rwxr-xr-x 1 root root 138856 Mar 1 2019 vdir + -rwxr-xr-x 1 root root 34896 Jan 10 2019 wdctl + -rwxr-xr-x 1 root root 946 Jan 22 2019 which + lrwxrwxrwx 1 root root 8 Sep 27 2018 ypdomainname -> hostname + -rwxr-xr-x 1 root root 1983 Jan 6 2019 zcat + -rwxr-xr-x 1 root root 1677 Jan 6 2019 zcmp + -rwxr-xr-x 1 root root 5879 Jan 6 2019 zdiff + -rwxr-xr-x 1 root root 29 Jan 6 2019 zegrep + -rwxr-xr-x 1 root root 29 Jan 6 2019 zfgrep + -rwxr-xr-x 1 root root 2080 Jan 6 2019 zforce + -rwxr-xr-x 1 root root 7584 Jan 6 2019 zgrep + -rwxr-xr-x 1 root root 2205 Jan 6 2019 zless + -rwxr-xr-x 1 root root 1841 Jan 6 2019 zmore + -rwxr-xr-x 1 root root 4552 Jan 6 2019 znew +I: user script /srv/workspace/pbuilder/16591/tmp/hooks/D02_print_environment finished -> Attempting to satisfy build-dependencies -> Creating pbuilder-satisfydepends-dummy package Package: pbuilder-satisfydepends-dummy @@ -309,7 +343,7 @@ Get: 105 http://deb.debian.org/debian buster/main amd64 libsasl2-dev amd64 2.1.27+dfsg-1+deb10u1 [283 kB] Get: 106 http://deb.debian.org/debian buster/main amd64 golang-gopkg-mgo.v2-dev all 2016.08.01-5 [194 kB] Get: 107 http://deb.debian.org/debian buster/main amd64 golang-github-hashicorp-go-msgpack-dev all 0.0~git20150518.0.fa3f638-6 [42.7 kB] -Fetched 90.1 MB in 1s (79.0 MB/s) +Fetched 90.1 MB in 1s (85.0 MB/s) debconf: delaying package configuration, since apt-utils is not installed Selecting previously unselected package libbsd0:amd64. (Reading database ... (Reading database ... 5% (Reading database ... 10% (Reading database ... 15% (Reading database ... 20% (Reading database ... 25% (Reading database ... 30% (Reading database ... 35% (Reading database ... 40% (Reading database ... 45% (Reading database ... 50% (Reading database ... 55% (Reading database ... 60% (Reading database ... 65% (Reading database ... 70% (Reading database ... 75% (Reading database ... 80% (Reading database ... 85% (Reading database ... 90% (Reading database ... 95% (Reading database ... 100% (Reading database ... 19195 files and directories currently installed.) @@ -760,7 +794,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 @@ -778,112 +812,112 @@ dh_autoreconf -O--buildsystem=golang dh_auto_configure -O--buildsystem=golang dh_auto_build -O--buildsystem=golang - cd obj-x86_64-linux-gnu && go install -gcflags=all=\"-trimpath=/build/golang-github-hashicorp-raft-1.0.0\+git20180823.82694fb/obj-x86_64-linux-gnu/src\" -asmflags=all=\"-trimpath=/build/golang-github-hashicorp-raft-1.0.0\+git20180823.82694fb/obj-x86_64-linux-gnu/src\" -v -p 16 github.com/hashicorp/raft github.com/hashicorp/raft/bench + cd obj-x86_64-linux-gnu && go install -gcflags=all=\"-trimpath=/build/golang-github-hashicorp-raft-1.0.0\+git20180823.82694fb/obj-x86_64-linux-gnu/src\" -asmflags=all=\"-trimpath=/build/golang-github-hashicorp-raft-1.0.0\+git20180823.82694fb/obj-x86_64-linux-gnu/src\" -v -p 15 github.com/hashicorp/raft github.com/hashicorp/raft/bench +math/bits +unicode/utf16 errors +crypto/subtle internal/race runtime/internal/sys -unicode/utf8 +unicode +encoding crypto/internal/subtle sync/atomic -internal/nettrace runtime/internal/atomic -container/list -unicode internal/cpu -encoding -unicode/utf16 vendor/golang_org/x/crypto/cryptobyte/asn1 -math/bits -crypto/subtle -runtime/cgo +internal/nettrace vendor/golang_org/x/net/dns/dnsmessage +unicode/utf8 +container/list vendor/golang_org/x/crypto/curve25519 +runtime/cgo internal/testlog internal/bytealg -github.com/hashicorp/golang-lru/simplelru math +github.com/hashicorp/golang-lru/simplelru runtime strconv crypto/rc4 sync io -internal/singleflight +syscall math/rand +internal/singleflight reflect -syscall -hash -crypto/internal/randutil bytes crypto/cipher +hash +crypto/internal/randutil strings hash/crc32 -hash/crc64 crypto crypto/hmac +hash/crc64 crypto/sha512 crypto/md5 crypto/sha1 crypto/sha256 crypto/aes -vendor/golang_org/x/text/transform bufio +vendor/golang_org/x/text/transform path html internal/syscall/unix time +internal/poll encoding/binary sort -internal/poll +os github.com/hashicorp/go-immutable-radix encoding/base64 +crypto/des vendor/golang_org/x/crypto/internal/chacha20 vendor/golang_org/x/crypto/poly1305 -crypto/des -os vendor/golang_org/x/crypto/chacha20poly1305 encoding/pem os/signal -runtime/debug path/filepath +runtime/debug fmt io/ioutil context -math/big log -encoding/hex compress/flate -net/url +encoding/hex encoding/json -vendor/golang_org/x/text/unicode/norm +net/url vendor/golang_org/x/net/http2/hpack -mime mime/quotedprintable +math/big net/http/internal +mime text/template/parse -encoding/gob flag +encoding/gob +vendor/golang_org/x/text/unicode/norm runtime/trace net vendor/golang_org/x/text/unicode/bidi testing -vendor/golang_org/x/text/secure/bidirule compress/gzip +vendor/golang_org/x/text/secure/bidirule text/template vendor/golang_org/x/net/idna crypto/rand -encoding/asn1 crypto/elliptic +encoding/asn1 crypto/dsa -html/template crypto/rsa +html/template crypto/ecdsa crypto/x509/pkix vendor/golang_org/x/crypto/cryptobyte vendor/golang_org/x/net/http/httpproxy net/textproto crypto/x509 -mime/multipart vendor/golang_org/x/net/http/httpguts +mime/multipart crypto/tls net/http/httptrace net/http @@ -893,7 +927,7 @@ github.com/hashicorp/raft github.com/hashicorp/raft/bench dh_auto_test -O--buildsystem=golang - cd obj-x86_64-linux-gnu && go test -vet=off -v -p 16 github.com/hashicorp/raft github.com/hashicorp/raft/bench + cd obj-x86_64-linux-gnu && go test -vet=off -v -p 15 github.com/hashicorp/raft github.com/hashicorp/raft/bench === RUN TestCommitment_setVoters --- PASS: TestCommitment_setVoters (0.00s) === RUN TestCommitment_match_max @@ -936,32 +970,32 @@ --- PASS: TestFileSnapshotSinkImpl (0.00s) === RUN TestFileSS_CreateSnapshotMissingParentDir --- PASS: TestFileSS_CreateSnapshotMissingParentDir (0.00s) - raft_test.go:101: 15:48:51.051602 [INFO] snapshot: Creating new snapshot at /tmp/raft673608179/raft009262262/snapshots/3-10-1659714531051.tmp + raft_test.go:101: 09:26:48.134975 [INFO] snapshot: Creating new snapshot at /tmp/raft778087365/raft166023264/snapshots/3-10-1625304408134.tmp === RUN TestFileSS_CreateSnapshot --- PASS: TestFileSS_CreateSnapshot (0.00s) - raft_test.go:101: 15:48:51.052331 [INFO] snapshot: Creating new snapshot at /tmp/raft642934429/snapshots/3-10-1659714531052.tmp - raft_test.go:101: 15:48:51.052486 [WARN] snapshot: Found temporary snapshot: 3-10-1659714531052.tmp + raft_test.go:101: 09:26:48.135534 [INFO] snapshot: Creating new snapshot at /tmp/raft015221823/snapshots/3-10-1625304408135.tmp + raft_test.go:101: 09:26:48.135634 [WARN] snapshot: Found temporary snapshot: 3-10-1625304408135.tmp === RUN TestFileSS_CancelSnapshot --- PASS: TestFileSS_CancelSnapshot (0.00s) - raft_test.go:101: 15:48:51.054084 [INFO] snapshot: Creating new snapshot at /tmp/raft356758360/snapshots/3-10-1659714531054.tmp + raft_test.go:101: 09:26:48.136640 [INFO] snapshot: Creating new snapshot at /tmp/raft941254802/snapshots/3-10-1625304408136.tmp === RUN TestFileSS_Retention --- PASS: TestFileSS_Retention (0.00s) - raft_test.go:101: 15:48:51.054550 [INFO] snapshot: Creating new snapshot at /tmp/raft994336983/snapshots/3-10-1659714531054.tmp - raft_test.go:101: 15:48:51.054880 [INFO] snapshot: Creating new snapshot at /tmp/raft994336983/snapshots/3-11-1659714531054.tmp - raft_test.go:101: 15:48:51.055168 [INFO] snapshot: Creating new snapshot at /tmp/raft994336983/snapshots/3-12-1659714531055.tmp - raft_test.go:101: 15:48:51.055514 [INFO] snapshot: reaping snapshot /tmp/raft994336983/snapshots/3-10-1659714531054 - raft_test.go:101: 15:48:51.055632 [INFO] snapshot: Creating new snapshot at /tmp/raft994336983/snapshots/3-13-1659714531055.tmp - raft_test.go:101: 15:48:51.056064 [INFO] snapshot: reaping snapshot /tmp/raft994336983/snapshots/3-11-1659714531054 - raft_test.go:101: 15:48:51.056181 [INFO] snapshot: Creating new snapshot at /tmp/raft994336983/snapshots/3-14-1659714531056.tmp - raft_test.go:101: 15:48:51.056629 [INFO] snapshot: reaping snapshot /tmp/raft994336983/snapshots/3-12-1659714531055 + raft_test.go:101: 09:26:48.136893 [INFO] snapshot: Creating new snapshot at /tmp/raft431699145/snapshots/3-10-1625304408136.tmp + raft_test.go:101: 09:26:48.137097 [INFO] snapshot: Creating new snapshot at /tmp/raft431699145/snapshots/3-11-1625304408137.tmp + raft_test.go:101: 09:26:48.137289 [INFO] snapshot: Creating new snapshot at /tmp/raft431699145/snapshots/3-12-1625304408137.tmp + raft_test.go:101: 09:26:48.137546 [INFO] snapshot: reaping snapshot /tmp/raft431699145/snapshots/3-10-1625304408136 + raft_test.go:101: 09:26:48.137623 [INFO] snapshot: Creating new snapshot at /tmp/raft431699145/snapshots/3-13-1625304408137.tmp + raft_test.go:101: 09:26:48.137852 [INFO] snapshot: reaping snapshot /tmp/raft431699145/snapshots/3-11-1625304408137 + raft_test.go:101: 09:26:48.137912 [INFO] snapshot: Creating new snapshot at /tmp/raft431699145/snapshots/3-14-1625304408137.tmp + raft_test.go:101: 09:26:48.138125 [INFO] snapshot: reaping snapshot /tmp/raft431699145/snapshots/3-12-1625304408137 === RUN TestFileSS_BadPerm --- PASS: TestFileSS_BadPerm (0.00s) === RUN TestFileSS_MissingParentDir --- PASS: TestFileSS_MissingParentDir (0.00s) === RUN TestFileSS_Ordering --- PASS: TestFileSS_Ordering (0.00s) - raft_test.go:101: 15:48:51.058083 [INFO] snapshot: Creating new snapshot at /tmp/raft735871262/snapshots/5-130350-1659714531058.tmp - raft_test.go:101: 15:48:51.058546 [INFO] snapshot: Creating new snapshot at /tmp/raft735871262/snapshots/36-204917-1659714531058.tmp + raft_test.go:101: 09:26:48.138870 [INFO] snapshot: Creating new snapshot at /tmp/raft145021448/snapshots/5-130350-1625304408138.tmp + raft_test.go:101: 09:26:48.139067 [INFO] snapshot: Creating new snapshot at /tmp/raft145021448/snapshots/36-204917-1625304408139.tmp === RUN TestDeferFutureSuccess --- PASS: TestDeferFutureSuccess (0.00s) === RUN TestDeferFutureError @@ -982,51 +1016,51 @@ --- PASS: TestLogCache (0.00s) === RUN TestNetworkTransport_CloseStreams --- PASS: TestNetworkTransport_CloseStreams (0.01s) - raft_test.go:101: 15:48:51.062721 [DEBUG] raft-net: 127.0.0.1:35071 accepted connection from: 127.0.0.1:52412 - raft_test.go:101: 15:48:51.062824 [DEBUG] raft-net: 127.0.0.1:35071 accepted connection from: 127.0.0.1:52414 - raft_test.go:101: 15:48:51.062865 [DEBUG] raft-net: 127.0.0.1:35071 accepted connection from: 127.0.0.1:52416 - raft_test.go:101: 15:48:51.062918 [DEBUG] raft-net: 127.0.0.1:35071 accepted connection from: 127.0.0.1:52418 - raft_test.go:101: 15:48:51.062962 [DEBUG] raft-net: 127.0.0.1:35071 accepted connection from: 127.0.0.1:52420 - raft_test.go:101: 15:48:51.065260 [DEBUG] raft-net: 127.0.0.1:35071 accepted connection from: 127.0.0.1:52422 - raft_test.go:101: 15:48:51.066508 [DEBUG] raft-net: 127.0.0.1:35071 accepted connection from: 127.0.0.1:52424 - raft_test.go:101: 15:48:51.066544 [DEBUG] raft-net: 127.0.0.1:35071 accepted connection from: 127.0.0.1:52426 - raft_test.go:101: 15:48:51.066583 [DEBUG] raft-net: 127.0.0.1:35071 accepted connection from: 127.0.0.1:52428 - raft_test.go:101: 15:48:51.066615 [DEBUG] raft-net: 127.0.0.1:35071 accepted connection from: 127.0.0.1:52430 + raft_test.go:101: 09:26:48.142346 [DEBUG] raft-net: 127.0.0.1:40267 accepted connection from: 127.0.0.1:49614 + raft_test.go:101: 09:26:48.142510 [DEBUG] raft-net: 127.0.0.1:40267 accepted connection from: 127.0.0.1:49616 + raft_test.go:101: 09:26:48.142790 [DEBUG] raft-net: 127.0.0.1:40267 accepted connection from: 127.0.0.1:49618 + raft_test.go:101: 09:26:48.142818 [DEBUG] raft-net: 127.0.0.1:40267 accepted connection from: 127.0.0.1:49620 + raft_test.go:101: 09:26:48.143075 [DEBUG] raft-net: 127.0.0.1:40267 accepted connection from: 127.0.0.1:49622 + raft_test.go:101: 09:26:48.145646 [DEBUG] raft-net: 127.0.0.1:40267 accepted connection from: 127.0.0.1:49624 + raft_test.go:101: 09:26:48.145737 [DEBUG] raft-net: 127.0.0.1:40267 accepted connection from: 127.0.0.1:49626 + raft_test.go:101: 09:26:48.145784 [DEBUG] raft-net: 127.0.0.1:40267 accepted connection from: 127.0.0.1:49628 + raft_test.go:101: 09:26:48.145828 [DEBUG] raft-net: 127.0.0.1:40267 accepted connection from: 127.0.0.1:49632 + raft_test.go:101: 09:26:48.145872 [DEBUG] raft-net: 127.0.0.1:40267 accepted connection from: 127.0.0.1:49630 === RUN TestNetworkTransport_StartStop --- PASS: TestNetworkTransport_StartStop (0.00s) === RUN TestNetworkTransport_Heartbeat_FastPath --- PASS: TestNetworkTransport_Heartbeat_FastPath (0.00s) - raft_test.go:101: 15:48:51.067787 [DEBUG] raft-net: 127.0.0.1:35111 accepted connection from: 127.0.0.1:53250 + raft_test.go:101: 09:26:48.147256 [DEBUG] raft-net: 127.0.0.1:44121 accepted connection from: 127.0.0.1:33292 === RUN TestNetworkTransport_AppendEntries --- PASS: TestNetworkTransport_AppendEntries (0.00s) - raft_test.go:101: 15:48:51.068649 [DEBUG] raft-net: 127.0.0.1:44557 accepted connection from: 127.0.0.1:53796 - raft_test.go:101: 15:48:51.069361 [DEBUG] raft-net: 127.0.0.1:44711 accepted connection from: 127.0.0.1:54838 + raft_test.go:101: 09:26:48.148129 [DEBUG] raft-net: 127.0.0.1:36149 accepted connection from: 127.0.0.1:50292 + raft_test.go:101: 09:26:48.148677 [DEBUG] raft-net: 127.0.0.1:41965 accepted connection from: 127.0.0.1:59032 === RUN TestNetworkTransport_AppendEntriesPipeline --- PASS: TestNetworkTransport_AppendEntriesPipeline (0.00s) - raft_test.go:101: 15:48:51.070074 [DEBUG] raft-net: 127.0.0.1:34831 accepted connection from: 127.0.0.1:60980 - raft_test.go:101: 15:48:51.071233 [DEBUG] raft-net: 127.0.0.1:39353 accepted connection from: 127.0.0.1:53462 + raft_test.go:101: 09:26:48.149501 [DEBUG] raft-net: 127.0.0.1:44219 accepted connection from: 127.0.0.1:38750 + raft_test.go:101: 09:26:48.150715 [DEBUG] raft-net: 127.0.0.1:37041 accepted connection from: 127.0.0.1:38540 === 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: 15:48:51.073631 [DEBUG] raft-net: 127.0.0.1:36279 accepted connection from: 127.0.0.1:46662 - raft_test.go:101: 15:48:51.074969 [DEBUG] raft-net: 127.0.0.1:35775 accepted connection from: 127.0.0.1:49530 + raft_test.go:101: 09:26:48.151915 [DEBUG] raft-net: 127.0.0.1:44125 accepted connection from: 127.0.0.1:40800 + raft_test.go:101: 09:26:48.152333 [DEBUG] raft-net: 127.0.0.1:33357 accepted connection from: 127.0.0.1:53622 === RUN TestNetworkTransport_InstallSnapshot --- PASS: TestNetworkTransport_InstallSnapshot (0.00s) - raft_test.go:101: 15:48:51.075787 [DEBUG] raft-net: 127.0.0.1:40875 accepted connection from: 127.0.0.1:59846 - raft_test.go:101: 15:48:51.076479 [DEBUG] raft-net: 127.0.0.1:35311 accepted connection from: 127.0.0.1:44550 + raft_test.go:101: 09:26:48.153014 [DEBUG] raft-net: 127.0.0.1:38699 accepted connection from: 127.0.0.1:40220 + raft_test.go:101: 09:26:48.153478 [DEBUG] raft-net: 127.0.0.1:38909 accepted connection from: 127.0.0.1:52386 === 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: 15:48:51.077555 [DEBUG] raft-net: 127.0.0.1:43313 accepted connection from: 127.0.0.1:32978 - raft_test.go:101: 15:48:51.077603 [DEBUG] raft-net: 127.0.0.1:43313 accepted connection from: 127.0.0.1:32976 - raft_test.go:101: 15:48:51.077648 [DEBUG] raft-net: 127.0.0.1:43313 accepted connection from: 127.0.0.1:32980 - raft_test.go:101: 15:48:51.077691 [DEBUG] raft-net: 127.0.0.1:43313 accepted connection from: 127.0.0.1:32982 - raft_test.go:101: 15:48:51.077719 [DEBUG] raft-net: 127.0.0.1:43313 accepted connection from: 127.0.0.1:32984 + raft_test.go:101: 09:26:48.154334 [DEBUG] raft-net: 127.0.0.1:45803 accepted connection from: 127.0.0.1:45476 + raft_test.go:101: 09:26:48.154381 [DEBUG] raft-net: 127.0.0.1:45803 accepted connection from: 127.0.0.1:45478 + raft_test.go:101: 09:26:48.154413 [DEBUG] raft-net: 127.0.0.1:45803 accepted connection from: 127.0.0.1:45480 + raft_test.go:101: 09:26:48.154446 [DEBUG] raft-net: 127.0.0.1:45803 accepted connection from: 127.0.0.1:45482 + raft_test.go:101: 09:26:48.154471 [DEBUG] raft-net: 127.0.0.1:45803 accepted connection from: 127.0.0.1:45484 === RUN TestPeersJSON_BadConfiguration --- PASS: TestPeersJSON_BadConfiguration (0.00s) === RUN TestPeersJSON_ReadPeersJSON @@ -1034,227 +1068,227 @@ === RUN TestPeersJSON_ReadConfigJSON --- PASS: TestPeersJSON_ReadConfigJSON (0.00s) === RUN TestRaft_ProtocolVersion_RejectRPC -testLoggerAdapter verbose: cluster: 15:48:51.079556 [DEBUG] Fully Connecting -testLoggerAdapter verbose: server-991773e1-aab3-17a7-5105-876e9f30794e: 15:48:51.079787 [INFO] raft: Initial configuration (index=1): [{Suffrage:Voter ID:server-991773e1-aab3-17a7-5105-876e9f30794e Address:991773e1-aab3-17a7-5105-876e9f30794e} {Suffrage:Voter ID:server-47c7f5e3-12f6-7a30-5769-0e438aa252e1 Address:47c7f5e3-12f6-7a30-5769-0e438aa252e1} {Suffrage:Voter ID:server-940d28e1-7277-774e-5e9a-b6d37689cf60 Address:940d28e1-7277-774e-5e9a-b6d37689cf60}] -testLoggerAdapter verbose: server-47c7f5e3-12f6-7a30-5769-0e438aa252e1: 15:48:51.079978 [INFO] raft: Initial configuration (index=1): [{Suffrage:Voter ID:server-991773e1-aab3-17a7-5105-876e9f30794e Address:991773e1-aab3-17a7-5105-876e9f30794e} {Suffrage:Voter ID:server-47c7f5e3-12f6-7a30-5769-0e438aa252e1 Address:47c7f5e3-12f6-7a30-5769-0e438aa252e1} {Suffrage:Voter ID:server-940d28e1-7277-774e-5e9a-b6d37689cf60 Address:940d28e1-7277-774e-5e9a-b6d37689cf60}] -testLoggerAdapter verbose: server-991773e1-aab3-17a7-5105-876e9f30794e: 15:48:51.080010 [INFO] raft: Node at 991773e1-aab3-17a7-5105-876e9f30794e [Follower] entering Follower state (Leader: "") -testLoggerAdapter verbose: server-47c7f5e3-12f6-7a30-5769-0e438aa252e1: 15:48:51.080063 [INFO] raft: Node at 47c7f5e3-12f6-7a30-5769-0e438aa252e1 [Follower] entering Follower state (Leader: "") -testLoggerAdapter verbose: server-940d28e1-7277-774e-5e9a-b6d37689cf60: 15:48:51.080140 [INFO] raft: Initial configuration (index=1): [{Suffrage:Voter ID:server-991773e1-aab3-17a7-5105-876e9f30794e Address:991773e1-aab3-17a7-5105-876e9f30794e} {Suffrage:Voter ID:server-47c7f5e3-12f6-7a30-5769-0e438aa252e1 Address:47c7f5e3-12f6-7a30-5769-0e438aa252e1} {Suffrage:Voter ID:server-940d28e1-7277-774e-5e9a-b6d37689cf60 Address:940d28e1-7277-774e-5e9a-b6d37689cf60}] -testLoggerAdapter verbose: cluster: 15:48:51.080180 [INFO] Starting stability test for raft state: Follower -testLoggerAdapter verbose: server-940d28e1-7277-774e-5e9a-b6d37689cf60: 15:48:51.080264 [INFO] raft: Node at 940d28e1-7277-774e-5e9a-b6d37689cf60 [Follower] entering Follower state (Leader: "") -testLoggerAdapter verbose: server-940d28e1-7277-774e-5e9a-b6d37689cf60: 15:48:51.142055 [WARN] raft: Heartbeat timeout from "" reached, starting election -testLoggerAdapter verbose: server-940d28e1-7277-774e-5e9a-b6d37689cf60: 15:48:51.142205 [INFO] raft: Node at 940d28e1-7277-774e-5e9a-b6d37689cf60 [Candidate] entering Candidate state in term 2 -testLoggerAdapter verbose: server-940d28e1-7277-774e-5e9a-b6d37689cf60: 15:48:51.142302 [DEBUG] raft: Votes needed: 2 -testLoggerAdapter verbose: server-940d28e1-7277-774e-5e9a-b6d37689cf60: 15:48:51.142337 [DEBUG] raft: Vote granted from server-940d28e1-7277-774e-5e9a-b6d37689cf60 in term 2. Tally: 1 -testLoggerAdapter verbose: cluster: 15:48:51.142419 [DEBUG] Resetting stability timeout -testLoggerAdapter verbose: server-940d28e1-7277-774e-5e9a-b6d37689cf60: 15:48:51.142452 [DEBUG] raft: Vote granted from server-47c7f5e3-12f6-7a30-5769-0e438aa252e1 in term 2. Tally: 2 -testLoggerAdapter verbose: cluster: 15:48:51.142511 [DEBUG] Resetting stability timeout -testLoggerAdapter verbose: server-940d28e1-7277-774e-5e9a-b6d37689cf60: 15:48:51.142599 [INFO] raft: Election won. Tally: 2 -testLoggerAdapter verbose: server-940d28e1-7277-774e-5e9a-b6d37689cf60: 15:48:51.142702 [INFO] raft: Node at 940d28e1-7277-774e-5e9a-b6d37689cf60 [Leader] entering Leader state -testLoggerAdapter verbose: cluster: 15:48:51.142719 [DEBUG] Resetting stability timeout -testLoggerAdapter verbose: server-940d28e1-7277-774e-5e9a-b6d37689cf60: 15:48:51.142758 [INFO] raft: Added peer server-991773e1-aab3-17a7-5105-876e9f30794e, starting replication -testLoggerAdapter verbose: server-940d28e1-7277-774e-5e9a-b6d37689cf60: 15:48:51.142796 [INFO] raft: Added peer server-47c7f5e3-12f6-7a30-5769-0e438aa252e1, starting replication -testLoggerAdapter verbose: cluster: 15:48:51.142825 [DEBUG] Resetting stability timeout -testLoggerAdapter verbose: server-940d28e1-7277-774e-5e9a-b6d37689cf60: 15:48:51.142968 [INFO] raft: pipelining replication to peer {Voter server-991773e1-aab3-17a7-5105-876e9f30794e 991773e1-aab3-17a7-5105-876e9f30794e} -testLoggerAdapter verbose: server-940d28e1-7277-774e-5e9a-b6d37689cf60: 15:48:51.142994 [INFO] raft: pipelining replication to peer {Voter server-47c7f5e3-12f6-7a30-5769-0e438aa252e1 47c7f5e3-12f6-7a30-5769-0e438aa252e1} -testLoggerAdapter verbose: cluster: 15:48:51.248125 [INFO] Stable state for Follower reached at 2022-08-05 15:48:51.14286417 +0000 UTC m=+0.098053786 (2 nodes), 62.626585ms from start of poll, 63.265245ms from cluster start. Timeout at 2022-08-05 15:48:51.247990018 +0000 UTC m=+0.203179671, 105.125885ms after stability -testLoggerAdapter verbose: cluster: 15:48:51.248237 [INFO] Starting stability test for raft state: Leader -testLoggerAdapter verbose: cluster: 15:48:51.353524 [INFO] Stable state for Leader reached at 2022-08-05 15:48:51.24828432 +0000 UTC m=+0.203473889 (1 nodes), 1.164µs from start of poll, 168.685348ms from cluster start. Timeout at 2022-08-05 15:48:51.353439299 +0000 UTC m=+0.308628903, 105.155014ms after stability -testLoggerAdapter verbose: server-940d28e1-7277-774e-5e9a-b6d37689cf60: 15:48:51.353647 [INFO] raft: aborting pipeline replication to peer {Voter server-991773e1-aab3-17a7-5105-876e9f30794e 991773e1-aab3-17a7-5105-876e9f30794e} -testLoggerAdapter verbose: server-940d28e1-7277-774e-5e9a-b6d37689cf60: 15:48:51.353697 [INFO] raft: aborting pipeline replication to peer {Voter server-47c7f5e3-12f6-7a30-5769-0e438aa252e1 47c7f5e3-12f6-7a30-5769-0e438aa252e1} ---- PASS: TestRaft_ProtocolVersion_RejectRPC (0.27s) - raft_test.go:97: cluster: 15:48:51.079556 [DEBUG] Fully Connecting - raft_test.go:97: server-991773e1-aab3-17a7-5105-876e9f30794e: 15:48:51.079787 [INFO] raft: Initial configuration (index=1): [{Suffrage:Voter ID:server-991773e1-aab3-17a7-5105-876e9f30794e Address:991773e1-aab3-17a7-5105-876e9f30794e} {Suffrage:Voter ID:server-47c7f5e3-12f6-7a30-5769-0e438aa252e1 Address:47c7f5e3-12f6-7a30-5769-0e438aa252e1} {Suffrage:Voter ID:server-940d28e1-7277-774e-5e9a-b6d37689cf60 Address:940d28e1-7277-774e-5e9a-b6d37689cf60}] - raft_test.go:97: server-47c7f5e3-12f6-7a30-5769-0e438aa252e1: 15:48:51.079978 [INFO] raft: Initial configuration (index=1): [{Suffrage:Voter ID:server-991773e1-aab3-17a7-5105-876e9f30794e Address:991773e1-aab3-17a7-5105-876e9f30794e} {Suffrage:Voter ID:server-47c7f5e3-12f6-7a30-5769-0e438aa252e1 Address:47c7f5e3-12f6-7a30-5769-0e438aa252e1} {Suffrage:Voter ID:server-940d28e1-7277-774e-5e9a-b6d37689cf60 Address:940d28e1-7277-774e-5e9a-b6d37689cf60}] - raft_test.go:97: server-991773e1-aab3-17a7-5105-876e9f30794e: 15:48:51.080010 [INFO] raft: Node at 991773e1-aab3-17a7-5105-876e9f30794e [Follower] entering Follower state (Leader: "") - raft_test.go:97: server-47c7f5e3-12f6-7a30-5769-0e438aa252e1: 15:48:51.080063 [INFO] raft: Node at 47c7f5e3-12f6-7a30-5769-0e438aa252e1 [Follower] entering Follower state (Leader: "") - raft_test.go:97: server-940d28e1-7277-774e-5e9a-b6d37689cf60: 15:48:51.080140 [INFO] raft: Initial configuration (index=1): [{Suffrage:Voter ID:server-991773e1-aab3-17a7-5105-876e9f30794e Address:991773e1-aab3-17a7-5105-876e9f30794e} {Suffrage:Voter ID:server-47c7f5e3-12f6-7a30-5769-0e438aa252e1 Address:47c7f5e3-12f6-7a30-5769-0e438aa252e1} {Suffrage:Voter ID:server-940d28e1-7277-774e-5e9a-b6d37689cf60 Address:940d28e1-7277-774e-5e9a-b6d37689cf60}] - raft_test.go:97: cluster: 15:48:51.080180 [INFO] Starting stability test for raft state: Follower - raft_test.go:97: server-940d28e1-7277-774e-5e9a-b6d37689cf60: 15:48:51.080264 [INFO] raft: Node at 940d28e1-7277-774e-5e9a-b6d37689cf60 [Follower] entering Follower state (Leader: "") - raft_test.go:97: server-940d28e1-7277-774e-5e9a-b6d37689cf60: 15:48:51.142055 [WARN] raft: Heartbeat timeout from "" reached, starting election - raft_test.go:97: server-940d28e1-7277-774e-5e9a-b6d37689cf60: 15:48:51.142205 [INFO] raft: Node at 940d28e1-7277-774e-5e9a-b6d37689cf60 [Candidate] entering Candidate state in term 2 - raft_test.go:97: server-940d28e1-7277-774e-5e9a-b6d37689cf60: 15:48:51.142302 [DEBUG] raft: Votes needed: 2 - raft_test.go:97: server-940d28e1-7277-774e-5e9a-b6d37689cf60: 15:48:51.142337 [DEBUG] raft: Vote granted from server-940d28e1-7277-774e-5e9a-b6d37689cf60 in term 2. Tally: 1 - raft_test.go:97: cluster: 15:48:51.142419 [DEBUG] Resetting stability timeout - raft_test.go:97: server-940d28e1-7277-774e-5e9a-b6d37689cf60: 15:48:51.142452 [DEBUG] raft: Vote granted from server-47c7f5e3-12f6-7a30-5769-0e438aa252e1 in term 2. Tally: 2 - raft_test.go:97: server-940d28e1-7277-774e-5e9a-b6d37689cf60: 15:48:51.142599 [INFO] raft: Election won. Tally: 2 - raft_test.go:97: cluster: 15:48:51.142511 [DEBUG] Resetting stability timeout - raft_test.go:97: server-940d28e1-7277-774e-5e9a-b6d37689cf60: 15:48:51.142702 [INFO] raft: Node at 940d28e1-7277-774e-5e9a-b6d37689cf60 [Leader] entering Leader state - raft_test.go:97: cluster: 15:48:51.142719 [DEBUG] Resetting stability timeout - raft_test.go:97: server-940d28e1-7277-774e-5e9a-b6d37689cf60: 15:48:51.142758 [INFO] raft: Added peer server-991773e1-aab3-17a7-5105-876e9f30794e, starting replication - raft_test.go:97: server-940d28e1-7277-774e-5e9a-b6d37689cf60: 15:48:51.142796 [INFO] raft: Added peer server-47c7f5e3-12f6-7a30-5769-0e438aa252e1, starting replication - raft_test.go:97: cluster: 15:48:51.142825 [DEBUG] Resetting stability timeout - raft_test.go:97: server-940d28e1-7277-774e-5e9a-b6d37689cf60: 15:48:51.142968 [INFO] raft: pipelining replication to peer {Voter server-991773e1-aab3-17a7-5105-876e9f30794e 991773e1-aab3-17a7-5105-876e9f30794e} - raft_test.go:97: server-940d28e1-7277-774e-5e9a-b6d37689cf60: 15:48:51.142994 [INFO] raft: pipelining replication to peer {Voter server-47c7f5e3-12f6-7a30-5769-0e438aa252e1 47c7f5e3-12f6-7a30-5769-0e438aa252e1} - raft_test.go:97: cluster: 15:48:51.248125 [INFO] Stable state for Follower reached at 2022-08-05 15:48:51.14286417 +0000 UTC m=+0.098053786 (2 nodes), 62.626585ms from start of poll, 63.265245ms from cluster start. Timeout at 2022-08-05 15:48:51.247990018 +0000 UTC m=+0.203179671, 105.125885ms after stability - raft_test.go:97: cluster: 15:48:51.248237 [INFO] Starting stability test for raft state: Leader - raft_test.go:97: cluster: 15:48:51.353524 [INFO] Stable state for Leader reached at 2022-08-05 15:48:51.24828432 +0000 UTC m=+0.203473889 (1 nodes), 1.164µs from start of poll, 168.685348ms from cluster start. Timeout at 2022-08-05 15:48:51.353439299 +0000 UTC m=+0.308628903, 105.155014ms after stability - raft_test.go:97: server-940d28e1-7277-774e-5e9a-b6d37689cf60: 15:48:51.353647 [INFO] raft: aborting pipeline replication to peer {Voter server-991773e1-aab3-17a7-5105-876e9f30794e 991773e1-aab3-17a7-5105-876e9f30794e} - raft_test.go:97: server-940d28e1-7277-774e-5e9a-b6d37689cf60: 15:48:51.353697 [INFO] raft: aborting pipeline replication to peer {Voter server-47c7f5e3-12f6-7a30-5769-0e438aa252e1 47c7f5e3-12f6-7a30-5769-0e438aa252e1} +testLoggerAdapter verbose: cluster: 09:26:48.157946 [DEBUG] Fully Connecting +testLoggerAdapter verbose: server-f40a2347-4f36-18f7-ed70-d996449d0e4c: 09:26:48.158171 [INFO] raft: Initial configuration (index=1): [{Suffrage:Voter ID:server-f40a2347-4f36-18f7-ed70-d996449d0e4c Address:f40a2347-4f36-18f7-ed70-d996449d0e4c} {Suffrage:Voter ID:server-17e9c9ae-2a05-5f91-ad16-a469e582e6d4 Address:17e9c9ae-2a05-5f91-ad16-a469e582e6d4} {Suffrage:Voter ID:server-42fbf9f1-ba04-964f-2e1a-35d394e3fb93 Address:42fbf9f1-ba04-964f-2e1a-35d394e3fb93}] +testLoggerAdapter verbose: server-17e9c9ae-2a05-5f91-ad16-a469e582e6d4: 09:26:48.158377 [INFO] raft: Initial configuration (index=1): [{Suffrage:Voter ID:server-f40a2347-4f36-18f7-ed70-d996449d0e4c Address:f40a2347-4f36-18f7-ed70-d996449d0e4c} {Suffrage:Voter ID:server-17e9c9ae-2a05-5f91-ad16-a469e582e6d4 Address:17e9c9ae-2a05-5f91-ad16-a469e582e6d4} {Suffrage:Voter ID:server-42fbf9f1-ba04-964f-2e1a-35d394e3fb93 Address:42fbf9f1-ba04-964f-2e1a-35d394e3fb93}] +testLoggerAdapter verbose: server-f40a2347-4f36-18f7-ed70-d996449d0e4c: 09:26:48.158448 [INFO] raft: Node at f40a2347-4f36-18f7-ed70-d996449d0e4c [Follower] entering Follower state (Leader: "") +testLoggerAdapter verbose: server-17e9c9ae-2a05-5f91-ad16-a469e582e6d4: 09:26:48.158536 [INFO] raft: Node at 17e9c9ae-2a05-5f91-ad16-a469e582e6d4 [Follower] entering Follower state (Leader: "") +testLoggerAdapter verbose: server-42fbf9f1-ba04-964f-2e1a-35d394e3fb93: 09:26:48.158579 [INFO] raft: Initial configuration (index=1): [{Suffrage:Voter ID:server-f40a2347-4f36-18f7-ed70-d996449d0e4c Address:f40a2347-4f36-18f7-ed70-d996449d0e4c} {Suffrage:Voter ID:server-17e9c9ae-2a05-5f91-ad16-a469e582e6d4 Address:17e9c9ae-2a05-5f91-ad16-a469e582e6d4} {Suffrage:Voter ID:server-42fbf9f1-ba04-964f-2e1a-35d394e3fb93 Address:42fbf9f1-ba04-964f-2e1a-35d394e3fb93}] +testLoggerAdapter verbose: cluster: 09:26:48.158674 [INFO] Starting stability test for raft state: Follower +testLoggerAdapter verbose: server-42fbf9f1-ba04-964f-2e1a-35d394e3fb93: 09:26:48.158727 [INFO] raft: Node at 42fbf9f1-ba04-964f-2e1a-35d394e3fb93 [Follower] entering Follower state (Leader: "") +testLoggerAdapter verbose: server-f40a2347-4f36-18f7-ed70-d996449d0e4c: 09:26:48.209933 [WARN] raft: Heartbeat timeout from "" reached, starting election +testLoggerAdapter verbose: server-f40a2347-4f36-18f7-ed70-d996449d0e4c: 09:26:48.210087 [INFO] raft: Node at f40a2347-4f36-18f7-ed70-d996449d0e4c [Candidate] entering Candidate state in term 2 +testLoggerAdapter verbose: cluster: 09:26:48.210145 [DEBUG] Resetting stability timeout +testLoggerAdapter verbose: cluster: 09:26:48.210237 [DEBUG] Resetting stability timeout +testLoggerAdapter verbose: server-f40a2347-4f36-18f7-ed70-d996449d0e4c: 09:26:48.210169 [DEBUG] raft: Votes needed: 2 +testLoggerAdapter verbose: server-f40a2347-4f36-18f7-ed70-d996449d0e4c: 09:26:48.210340 [DEBUG] raft: Vote granted from server-f40a2347-4f36-18f7-ed70-d996449d0e4c in term 2. Tally: 1 +testLoggerAdapter verbose: server-f40a2347-4f36-18f7-ed70-d996449d0e4c: 09:26:48.210393 [DEBUG] raft: Vote granted from server-42fbf9f1-ba04-964f-2e1a-35d394e3fb93 in term 2. Tally: 2 +testLoggerAdapter verbose: server-f40a2347-4f36-18f7-ed70-d996449d0e4c: 09:26:48.210451 [INFO] raft: Election won. Tally: 2 +testLoggerAdapter verbose: server-f40a2347-4f36-18f7-ed70-d996449d0e4c: 09:26:48.210503 [INFO] raft: Node at f40a2347-4f36-18f7-ed70-d996449d0e4c [Leader] entering Leader state +testLoggerAdapter verbose: cluster: 09:26:48.210385 [DEBUG] Resetting stability timeout +testLoggerAdapter verbose: cluster: 09:26:48.210643 [DEBUG] Resetting stability timeout +testLoggerAdapter verbose: server-f40a2347-4f36-18f7-ed70-d996449d0e4c: 09:26:48.210549 [INFO] raft: Added peer server-17e9c9ae-2a05-5f91-ad16-a469e582e6d4, starting replication +testLoggerAdapter verbose: server-f40a2347-4f36-18f7-ed70-d996449d0e4c: 09:26:48.210752 [INFO] raft: Added peer server-42fbf9f1-ba04-964f-2e1a-35d394e3fb93, starting replication +testLoggerAdapter verbose: server-f40a2347-4f36-18f7-ed70-d996449d0e4c: 09:26:48.211173 [INFO] raft: pipelining replication to peer {Voter server-42fbf9f1-ba04-964f-2e1a-35d394e3fb93 42fbf9f1-ba04-964f-2e1a-35d394e3fb93} +testLoggerAdapter verbose: server-f40a2347-4f36-18f7-ed70-d996449d0e4c: 09:26:48.211193 [INFO] raft: pipelining replication to peer {Voter server-17e9c9ae-2a05-5f91-ad16-a469e582e6d4 17e9c9ae-2a05-5f91-ad16-a469e582e6d4} +testLoggerAdapter verbose: cluster: 09:26:48.315937 [INFO] Stable state for Follower reached at 2021-07-03 09:26:48.210677082 +0000 UTC m=+0.081789673 (2 nodes), 51.967933ms from start of poll, 52.687617ms from cluster start. Timeout at 2021-07-03 09:26:48.315822092 +0000 UTC m=+0.186934666, 105.144993ms after stability +testLoggerAdapter verbose: cluster: 09:26:48.316006 [INFO] Starting stability test for raft state: Leader +testLoggerAdapter verbose: cluster: 09:26:48.421268 [INFO] Stable state for Leader reached at 2021-07-03 09:26:48.316026544 +0000 UTC m=+0.187139050 (1 nodes), 987ns from start of poll, 158.036994ms from cluster start. Timeout at 2021-07-03 09:26:48.421173281 +0000 UTC m=+0.292285855, 105.146805ms after stability +testLoggerAdapter verbose: server-f40a2347-4f36-18f7-ed70-d996449d0e4c: 09:26:48.421424 [INFO] raft: aborting pipeline replication to peer {Voter server-42fbf9f1-ba04-964f-2e1a-35d394e3fb93 42fbf9f1-ba04-964f-2e1a-35d394e3fb93} +testLoggerAdapter verbose: server-f40a2347-4f36-18f7-ed70-d996449d0e4c: 09:26:48.421466 [INFO] raft: aborting pipeline replication to peer {Voter server-17e9c9ae-2a05-5f91-ad16-a469e582e6d4 17e9c9ae-2a05-5f91-ad16-a469e582e6d4} +--- PASS: TestRaft_ProtocolVersion_RejectRPC (0.26s) + raft_test.go:97: cluster: 09:26:48.157946 [DEBUG] Fully Connecting + raft_test.go:97: server-f40a2347-4f36-18f7-ed70-d996449d0e4c: 09:26:48.158171 [INFO] raft: Initial configuration (index=1): [{Suffrage:Voter ID:server-f40a2347-4f36-18f7-ed70-d996449d0e4c Address:f40a2347-4f36-18f7-ed70-d996449d0e4c} {Suffrage:Voter ID:server-17e9c9ae-2a05-5f91-ad16-a469e582e6d4 Address:17e9c9ae-2a05-5f91-ad16-a469e582e6d4} {Suffrage:Voter ID:server-42fbf9f1-ba04-964f-2e1a-35d394e3fb93 Address:42fbf9f1-ba04-964f-2e1a-35d394e3fb93}] + raft_test.go:97: server-17e9c9ae-2a05-5f91-ad16-a469e582e6d4: 09:26:48.158377 [INFO] raft: Initial configuration (index=1): [{Suffrage:Voter ID:server-f40a2347-4f36-18f7-ed70-d996449d0e4c Address:f40a2347-4f36-18f7-ed70-d996449d0e4c} {Suffrage:Voter ID:server-17e9c9ae-2a05-5f91-ad16-a469e582e6d4 Address:17e9c9ae-2a05-5f91-ad16-a469e582e6d4} {Suffrage:Voter ID:server-42fbf9f1-ba04-964f-2e1a-35d394e3fb93 Address:42fbf9f1-ba04-964f-2e1a-35d394e3fb93}] + raft_test.go:97: server-f40a2347-4f36-18f7-ed70-d996449d0e4c: 09:26:48.158448 [INFO] raft: Node at f40a2347-4f36-18f7-ed70-d996449d0e4c [Follower] entering Follower state (Leader: "") + raft_test.go:97: server-17e9c9ae-2a05-5f91-ad16-a469e582e6d4: 09:26:48.158536 [INFO] raft: Node at 17e9c9ae-2a05-5f91-ad16-a469e582e6d4 [Follower] entering Follower state (Leader: "") + raft_test.go:97: server-42fbf9f1-ba04-964f-2e1a-35d394e3fb93: 09:26:48.158579 [INFO] raft: Initial configuration (index=1): [{Suffrage:Voter ID:server-f40a2347-4f36-18f7-ed70-d996449d0e4c Address:f40a2347-4f36-18f7-ed70-d996449d0e4c} {Suffrage:Voter ID:server-17e9c9ae-2a05-5f91-ad16-a469e582e6d4 Address:17e9c9ae-2a05-5f91-ad16-a469e582e6d4} {Suffrage:Voter ID:server-42fbf9f1-ba04-964f-2e1a-35d394e3fb93 Address:42fbf9f1-ba04-964f-2e1a-35d394e3fb93}] + raft_test.go:97: cluster: 09:26:48.158674 [INFO] Starting stability test for raft state: Follower + raft_test.go:97: server-42fbf9f1-ba04-964f-2e1a-35d394e3fb93: 09:26:48.158727 [INFO] raft: Node at 42fbf9f1-ba04-964f-2e1a-35d394e3fb93 [Follower] entering Follower state (Leader: "") + raft_test.go:97: server-f40a2347-4f36-18f7-ed70-d996449d0e4c: 09:26:48.209933 [WARN] raft: Heartbeat timeout from "" reached, starting election + raft_test.go:97: server-f40a2347-4f36-18f7-ed70-d996449d0e4c: 09:26:48.210087 [INFO] raft: Node at f40a2347-4f36-18f7-ed70-d996449d0e4c [Candidate] entering Candidate state in term 2 + raft_test.go:97: cluster: 09:26:48.210145 [DEBUG] Resetting stability timeout + raft_test.go:97: cluster: 09:26:48.210237 [DEBUG] Resetting stability timeout + raft_test.go:97: server-f40a2347-4f36-18f7-ed70-d996449d0e4c: 09:26:48.210169 [DEBUG] raft: Votes needed: 2 + raft_test.go:97: server-f40a2347-4f36-18f7-ed70-d996449d0e4c: 09:26:48.210340 [DEBUG] raft: Vote granted from server-f40a2347-4f36-18f7-ed70-d996449d0e4c in term 2. Tally: 1 + raft_test.go:97: server-f40a2347-4f36-18f7-ed70-d996449d0e4c: 09:26:48.210393 [DEBUG] raft: Vote granted from server-42fbf9f1-ba04-964f-2e1a-35d394e3fb93 in term 2. Tally: 2 + raft_test.go:97: server-f40a2347-4f36-18f7-ed70-d996449d0e4c: 09:26:48.210451 [INFO] raft: Election won. Tally: 2 + raft_test.go:97: server-f40a2347-4f36-18f7-ed70-d996449d0e4c: 09:26:48.210503 [INFO] raft: Node at f40a2347-4f36-18f7-ed70-d996449d0e4c [Leader] entering Leader state + raft_test.go:97: cluster: 09:26:48.210385 [DEBUG] Resetting stability timeout + raft_test.go:97: cluster: 09:26:48.210643 [DEBUG] Resetting stability timeout + raft_test.go:97: server-f40a2347-4f36-18f7-ed70-d996449d0e4c: 09:26:48.210549 [INFO] raft: Added peer server-17e9c9ae-2a05-5f91-ad16-a469e582e6d4, starting replication + raft_test.go:97: server-f40a2347-4f36-18f7-ed70-d996449d0e4c: 09:26:48.210752 [INFO] raft: Added peer server-42fbf9f1-ba04-964f-2e1a-35d394e3fb93, starting replication + raft_test.go:97: server-f40a2347-4f36-18f7-ed70-d996449d0e4c: 09:26:48.211173 [INFO] raft: pipelining replication to peer {Voter server-42fbf9f1-ba04-964f-2e1a-35d394e3fb93 42fbf9f1-ba04-964f-2e1a-35d394e3fb93} + raft_test.go:97: server-f40a2347-4f36-18f7-ed70-d996449d0e4c: 09:26:48.211193 [INFO] raft: pipelining replication to peer {Voter server-17e9c9ae-2a05-5f91-ad16-a469e582e6d4 17e9c9ae-2a05-5f91-ad16-a469e582e6d4} + raft_test.go:97: cluster: 09:26:48.315937 [INFO] Stable state for Follower reached at 2021-07-03 09:26:48.210677082 +0000 UTC m=+0.081789673 (2 nodes), 51.967933ms from start of poll, 52.687617ms from cluster start. Timeout at 2021-07-03 09:26:48.315822092 +0000 UTC m=+0.186934666, 105.144993ms after stability + raft_test.go:97: cluster: 09:26:48.316006 [INFO] Starting stability test for raft state: Leader + raft_test.go:97: cluster: 09:26:48.421268 [INFO] Stable state for Leader reached at 2021-07-03 09:26:48.316026544 +0000 UTC m=+0.187139050 (1 nodes), 987ns from start of poll, 158.036994ms from cluster start. Timeout at 2021-07-03 09:26:48.421173281 +0000 UTC m=+0.292285855, 105.146805ms after stability + raft_test.go:97: server-f40a2347-4f36-18f7-ed70-d996449d0e4c: 09:26:48.421424 [INFO] raft: aborting pipeline replication to peer {Voter server-42fbf9f1-ba04-964f-2e1a-35d394e3fb93 42fbf9f1-ba04-964f-2e1a-35d394e3fb93} + raft_test.go:97: server-f40a2347-4f36-18f7-ed70-d996449d0e4c: 09:26:48.421466 [INFO] raft: aborting pipeline replication to peer {Voter server-17e9c9ae-2a05-5f91-ad16-a469e582e6d4 17e9c9ae-2a05-5f91-ad16-a469e582e6d4} === RUN TestRaft_ProtocolVersion_Upgrade_1_2 -testLoggerAdapter verbose: cluster: 15:48:51.354133 [DEBUG] Fully Connecting -testLoggerAdapter verbose: 00815e63-a9a8-435a-2f1d-ba1a8309426f: 15:48:51.354279 [INFO] raft: Initial configuration (index=1): [{Suffrage:Voter ID:00815e63-a9a8-435a-2f1d-ba1a8309426f Address:00815e63-a9a8-435a-2f1d-ba1a8309426f} {Suffrage:Voter ID:8b8d2ced-dde1-a623-c0ea-69da7acd93ef Address:8b8d2ced-dde1-a623-c0ea-69da7acd93ef}] -testLoggerAdapter verbose: 8b8d2ced-dde1-a623-c0ea-69da7acd93ef: 15:48:51.354396 [INFO] raft: Initial configuration (index=1): [{Suffrage:Voter ID:00815e63-a9a8-435a-2f1d-ba1a8309426f Address:00815e63-a9a8-435a-2f1d-ba1a8309426f} {Suffrage:Voter ID:8b8d2ced-dde1-a623-c0ea-69da7acd93ef Address:8b8d2ced-dde1-a623-c0ea-69da7acd93ef}] -testLoggerAdapter verbose: 00815e63-a9a8-435a-2f1d-ba1a8309426f: 15:48:51.354475 [INFO] raft: Node at 00815e63-a9a8-435a-2f1d-ba1a8309426f [Follower] entering Follower state (Leader: "") -testLoggerAdapter verbose: 8b8d2ced-dde1-a623-c0ea-69da7acd93ef: 15:48:51.354558 [INFO] raft: Node at 8b8d2ced-dde1-a623-c0ea-69da7acd93ef [Follower] entering Follower state (Leader: "") -testLoggerAdapter verbose: cluster: 15:48:51.354499 [DEBUG] Fully Connecting -testLoggerAdapter verbose: 79f5b43b-d4a2-4df6-a5fd-10dc3f61c44d: 15:48:51.354817 [INFO] raft: Initial configuration (index=0): [] -testLoggerAdapter verbose: cluster: 15:48:51.354900 [DEBUG] Fully Connecting -testLoggerAdapter verbose: cluster: 15:48:51.354966 [INFO] Starting stability test for raft state: Leader -testLoggerAdapter verbose: 79f5b43b-d4a2-4df6-a5fd-10dc3f61c44d: 15:48:51.354981 [INFO] raft: Node at 79f5b43b-d4a2-4df6-a5fd-10dc3f61c44d [Follower] entering Follower state (Leader: "") -testLoggerAdapter verbose: 79f5b43b-d4a2-4df6-a5fd-10dc3f61c44d: 15:48:51.415429 [WARN] raft: no known peers, aborting election -testLoggerAdapter verbose: 00815e63-a9a8-435a-2f1d-ba1a8309426f: 15:48:51.427297 [WARN] raft: Heartbeat timeout from "" reached, starting election -testLoggerAdapter verbose: 00815e63-a9a8-435a-2f1d-ba1a8309426f: 15:48:51.427463 [INFO] raft: Node at 00815e63-a9a8-435a-2f1d-ba1a8309426f [Candidate] entering Candidate state in term 2 -testLoggerAdapter verbose: cluster: 15:48:51.427519 [DEBUG] Resetting stability timeout -testLoggerAdapter verbose: 00815e63-a9a8-435a-2f1d-ba1a8309426f: 15:48:51.427595 [DEBUG] raft: Votes needed: 2 -testLoggerAdapter verbose: 00815e63-a9a8-435a-2f1d-ba1a8309426f: 15:48:51.427650 [DEBUG] raft: Vote granted from 00815e63-a9a8-435a-2f1d-ba1a8309426f in term 2. Tally: 1 -testLoggerAdapter verbose: 00815e63-a9a8-435a-2f1d-ba1a8309426f: 15:48:51.427882 [DEBUG] raft: Vote granted from 8b8d2ced-dde1-a623-c0ea-69da7acd93ef in term 2. Tally: 2 -testLoggerAdapter verbose: 00815e63-a9a8-435a-2f1d-ba1a8309426f: 15:48:51.427924 [INFO] raft: Election won. Tally: 2 -testLoggerAdapter verbose: 00815e63-a9a8-435a-2f1d-ba1a8309426f: 15:48:51.427976 [INFO] raft: Node at 00815e63-a9a8-435a-2f1d-ba1a8309426f [Leader] entering Leader state -testLoggerAdapter verbose: 00815e63-a9a8-435a-2f1d-ba1a8309426f: 15:48:51.428043 [INFO] raft: Added peer 8b8d2ced-dde1-a623-c0ea-69da7acd93ef, starting replication -testLoggerAdapter verbose: cluster: 15:48:51.427966 [DEBUG] Resetting stability timeout -testLoggerAdapter verbose: 00815e63-a9a8-435a-2f1d-ba1a8309426f: 15:48:51.428230 [INFO] raft: pipelining replication to peer {Voter 8b8d2ced-dde1-a623-c0ea-69da7acd93ef 8b8d2ced-dde1-a623-c0ea-69da7acd93ef} -testLoggerAdapter verbose: cluster: 15:48:51.428271 [DEBUG] Resetting stability timeout -testLoggerAdapter verbose: cluster: 15:48:51.533559 [INFO] Stable state for Leader reached at 2022-08-05 15:48:51.42831827 +0000 UTC m=+0.383507896 (1 nodes), 73.3173ms from start of poll, 74.142285ms from cluster start. Timeout at 2022-08-05 15:48:51.533427218 +0000 UTC m=+0.488616811, 105.108915ms after stability -testLoggerAdapter verbose: cluster: 15:48:51.533654 [INFO] Starting stability test for raft state: Leader -testLoggerAdapter verbose: cluster: 15:48:51.638949 [INFO] Stable state for Leader reached at 2022-08-05 15:48:51.533684965 +0000 UTC m=+0.488874560 (1 nodes), 1.99µs from start of poll, 179.508949ms from cluster start. Timeout at 2022-08-05 15:48:51.638823941 +0000 UTC m=+0.594013545, 105.138985ms after stability -testLoggerAdapter verbose: cluster: 15:48:51.639055 [INFO] Starting stability test for raft state: Leader -testLoggerAdapter verbose: cluster: 15:48:51.744384 [INFO] Stable state for Leader reached at 2022-08-05 15:48:51.639092351 +0000 UTC m=+0.594281950 (1 nodes), 1.964µs from start of poll, 284.916339ms from cluster start. Timeout at 2022-08-05 15:48:51.744250716 +0000 UTC m=+0.699440320, 105.15837ms after stability -testLoggerAdapter verbose: 00815e63-a9a8-435a-2f1d-ba1a8309426f: 15:48:51.744543 [INFO] raft: Updating configuration with AddStaging (79f5b43b-d4a2-4df6-a5fd-10dc3f61c44d, 79f5b43b-d4a2-4df6-a5fd-10dc3f61c44d) to [{Suffrage:Voter ID:00815e63-a9a8-435a-2f1d-ba1a8309426f Address:00815e63-a9a8-435a-2f1d-ba1a8309426f} {Suffrage:Voter ID:8b8d2ced-dde1-a623-c0ea-69da7acd93ef Address:8b8d2ced-dde1-a623-c0ea-69da7acd93ef} {Suffrage:Voter ID:79f5b43b-d4a2-4df6-a5fd-10dc3f61c44d Address:79f5b43b-d4a2-4df6-a5fd-10dc3f61c44d}] -testLoggerAdapter verbose: 00815e63-a9a8-435a-2f1d-ba1a8309426f: 15:48:51.744645 [INFO] raft: Added peer 79f5b43b-d4a2-4df6-a5fd-10dc3f61c44d, starting replication -testLoggerAdapter verbose: 79f5b43b-d4a2-4df6-a5fd-10dc3f61c44d: 15:48:51.744754 [WARN] raft: Failed to get previous log: 3 log not found (last: 0) -testLoggerAdapter verbose: 00815e63-a9a8-435a-2f1d-ba1a8309426f: 15:48:51.744841 [WARN] raft: AppendEntries to {Voter 79f5b43b-d4a2-4df6-a5fd-10dc3f61c44d 79f5b43b-d4a2-4df6-a5fd-10dc3f61c44d} rejected, sending older logs (next: 1) -testLoggerAdapter verbose: 00815e63-a9a8-435a-2f1d-ba1a8309426f: 15:48:51.744964 [INFO] raft: pipelining replication to peer {Voter 79f5b43b-d4a2-4df6-a5fd-10dc3f61c44d 79f5b43b-d4a2-4df6-a5fd-10dc3f61c44d} -testLoggerAdapter verbose: cluster: 15:48:51.745016 [INFO] Starting stability test for raft state: Leader -testLoggerAdapter verbose: cluster: 15:48:51.850387 [INFO] Stable state for Leader reached at 2022-08-05 15:48:51.745081866 +0000 UTC m=+0.700271461 (1 nodes), 1.36µs from start of poll, 390.90585ms from cluster start. Timeout at 2022-08-05 15:48:51.850237916 +0000 UTC m=+0.805427513, 105.156052ms after stability -testLoggerAdapter verbose: cluster: 15:48:51.850482 [INFO] Starting stability test for raft state: Leader -testLoggerAdapter verbose: cluster: 15:48:51.955777 [INFO] Stable state for Leader reached at 2022-08-05 15:48:51.850532201 +0000 UTC m=+0.805721806 (1 nodes), 2.932µs from start of poll, 496.356195ms from cluster start. Timeout at 2022-08-05 15:48:51.955669075 +0000 UTC m=+0.910858680, 105.136874ms after stability -testLoggerAdapter verbose: 00815e63-a9a8-435a-2f1d-ba1a8309426f: 15:48:51.955916 [INFO] raft: Updating configuration with RemoveServer (79f5b43b-d4a2-4df6-a5fd-10dc3f61c44d, ) to [{Suffrage:Voter ID:00815e63-a9a8-435a-2f1d-ba1a8309426f Address:00815e63-a9a8-435a-2f1d-ba1a8309426f} {Suffrage:Voter ID:8b8d2ced-dde1-a623-c0ea-69da7acd93ef Address:8b8d2ced-dde1-a623-c0ea-69da7acd93ef}] -testLoggerAdapter verbose: 00815e63-a9a8-435a-2f1d-ba1a8309426f: 15:48:51.956009 [INFO] raft: Removed peer 79f5b43b-d4a2-4df6-a5fd-10dc3f61c44d, stopping replication after 4 -testLoggerAdapter verbose: 00815e63-a9a8-435a-2f1d-ba1a8309426f: 15:48:51.956080 [INFO] raft: aborting pipeline replication to peer {Voter 79f5b43b-d4a2-4df6-a5fd-10dc3f61c44d 79f5b43b-d4a2-4df6-a5fd-10dc3f61c44d} -testLoggerAdapter verbose: 00815e63-a9a8-435a-2f1d-ba1a8309426f: 15:48:51.956305 [INFO] raft: aborting pipeline replication to peer {Voter 8b8d2ced-dde1-a623-c0ea-69da7acd93ef 8b8d2ced-dde1-a623-c0ea-69da7acd93ef} ---- PASS: TestRaft_ProtocolVersion_Upgrade_1_2 (0.60s) - raft_test.go:97: cluster: 15:48:51.354133 [DEBUG] Fully Connecting - raft_test.go:97: 00815e63-a9a8-435a-2f1d-ba1a8309426f: 15:48:51.354279 [INFO] raft: Initial configuration (index=1): [{Suffrage:Voter ID:00815e63-a9a8-435a-2f1d-ba1a8309426f Address:00815e63-a9a8-435a-2f1d-ba1a8309426f} {Suffrage:Voter ID:8b8d2ced-dde1-a623-c0ea-69da7acd93ef Address:8b8d2ced-dde1-a623-c0ea-69da7acd93ef}] - raft_test.go:97: 8b8d2ced-dde1-a623-c0ea-69da7acd93ef: 15:48:51.354396 [INFO] raft: Initial configuration (index=1): [{Suffrage:Voter ID:00815e63-a9a8-435a-2f1d-ba1a8309426f Address:00815e63-a9a8-435a-2f1d-ba1a8309426f} {Suffrage:Voter ID:8b8d2ced-dde1-a623-c0ea-69da7acd93ef Address:8b8d2ced-dde1-a623-c0ea-69da7acd93ef}] - raft_test.go:97: 00815e63-a9a8-435a-2f1d-ba1a8309426f: 15:48:51.354475 [INFO] raft: Node at 00815e63-a9a8-435a-2f1d-ba1a8309426f [Follower] entering Follower state (Leader: "") - raft_test.go:97: 8b8d2ced-dde1-a623-c0ea-69da7acd93ef: 15:48:51.354558 [INFO] raft: Node at 8b8d2ced-dde1-a623-c0ea-69da7acd93ef [Follower] entering Follower state (Leader: "") - raft_test.go:97: cluster: 15:48:51.354499 [DEBUG] Fully Connecting - raft_test.go:97: 79f5b43b-d4a2-4df6-a5fd-10dc3f61c44d: 15:48:51.354817 [INFO] raft: Initial configuration (index=0): [] - raft_test.go:97: cluster: 15:48:51.354900 [DEBUG] Fully Connecting - raft_test.go:97: cluster: 15:48:51.354966 [INFO] Starting stability test for raft state: Leader - raft_test.go:97: 79f5b43b-d4a2-4df6-a5fd-10dc3f61c44d: 15:48:51.354981 [INFO] raft: Node at 79f5b43b-d4a2-4df6-a5fd-10dc3f61c44d [Follower] entering Follower state (Leader: "") - raft_test.go:97: 79f5b43b-d4a2-4df6-a5fd-10dc3f61c44d: 15:48:51.415429 [WARN] raft: no known peers, aborting election - raft_test.go:97: 00815e63-a9a8-435a-2f1d-ba1a8309426f: 15:48:51.427297 [WARN] raft: Heartbeat timeout from "" reached, starting election - raft_test.go:97: 00815e63-a9a8-435a-2f1d-ba1a8309426f: 15:48:51.427463 [INFO] raft: Node at 00815e63-a9a8-435a-2f1d-ba1a8309426f [Candidate] entering Candidate state in term 2 - raft_test.go:97: cluster: 15:48:51.427519 [DEBUG] Resetting stability timeout - raft_test.go:97: 00815e63-a9a8-435a-2f1d-ba1a8309426f: 15:48:51.427595 [DEBUG] raft: Votes needed: 2 - raft_test.go:97: 00815e63-a9a8-435a-2f1d-ba1a8309426f: 15:48:51.427650 [DEBUG] raft: Vote granted from 00815e63-a9a8-435a-2f1d-ba1a8309426f in term 2. Tally: 1 - raft_test.go:97: 00815e63-a9a8-435a-2f1d-ba1a8309426f: 15:48:51.427882 [DEBUG] raft: Vote granted from 8b8d2ced-dde1-a623-c0ea-69da7acd93ef in term 2. Tally: 2 - raft_test.go:97: 00815e63-a9a8-435a-2f1d-ba1a8309426f: 15:48:51.427924 [INFO] raft: Election won. Tally: 2 - raft_test.go:97: 00815e63-a9a8-435a-2f1d-ba1a8309426f: 15:48:51.427976 [INFO] raft: Node at 00815e63-a9a8-435a-2f1d-ba1a8309426f [Leader] entering Leader state - raft_test.go:97: 00815e63-a9a8-435a-2f1d-ba1a8309426f: 15:48:51.428043 [INFO] raft: Added peer 8b8d2ced-dde1-a623-c0ea-69da7acd93ef, starting replication - raft_test.go:97: cluster: 15:48:51.427966 [DEBUG] Resetting stability timeout - raft_test.go:97: 00815e63-a9a8-435a-2f1d-ba1a8309426f: 15:48:51.428230 [INFO] raft: pipelining replication to peer {Voter 8b8d2ced-dde1-a623-c0ea-69da7acd93ef 8b8d2ced-dde1-a623-c0ea-69da7acd93ef} - raft_test.go:97: cluster: 15:48:51.428271 [DEBUG] Resetting stability timeout - raft_test.go:97: cluster: 15:48:51.533559 [INFO] Stable state for Leader reached at 2022-08-05 15:48:51.42831827 +0000 UTC m=+0.383507896 (1 nodes), 73.3173ms from start of poll, 74.142285ms from cluster start. Timeout at 2022-08-05 15:48:51.533427218 +0000 UTC m=+0.488616811, 105.108915ms after stability - raft_test.go:97: cluster: 15:48:51.533654 [INFO] Starting stability test for raft state: Leader - raft_test.go:97: cluster: 15:48:51.638949 [INFO] Stable state for Leader reached at 2022-08-05 15:48:51.533684965 +0000 UTC m=+0.488874560 (1 nodes), 1.99µs from start of poll, 179.508949ms from cluster start. Timeout at 2022-08-05 15:48:51.638823941 +0000 UTC m=+0.594013545, 105.138985ms after stability - raft_test.go:97: cluster: 15:48:51.639055 [INFO] Starting stability test for raft state: Leader - raft_test.go:97: cluster: 15:48:51.744384 [INFO] Stable state for Leader reached at 2022-08-05 15:48:51.639092351 +0000 UTC m=+0.594281950 (1 nodes), 1.964µs from start of poll, 284.916339ms from cluster start. Timeout at 2022-08-05 15:48:51.744250716 +0000 UTC m=+0.699440320, 105.15837ms after stability - raft_test.go:97: 00815e63-a9a8-435a-2f1d-ba1a8309426f: 15:48:51.744543 [INFO] raft: Updating configuration with AddStaging (79f5b43b-d4a2-4df6-a5fd-10dc3f61c44d, 79f5b43b-d4a2-4df6-a5fd-10dc3f61c44d) to [{Suffrage:Voter ID:00815e63-a9a8-435a-2f1d-ba1a8309426f Address:00815e63-a9a8-435a-2f1d-ba1a8309426f} {Suffrage:Voter ID:8b8d2ced-dde1-a623-c0ea-69da7acd93ef Address:8b8d2ced-dde1-a623-c0ea-69da7acd93ef} {Suffrage:Voter ID:79f5b43b-d4a2-4df6-a5fd-10dc3f61c44d Address:79f5b43b-d4a2-4df6-a5fd-10dc3f61c44d}] - raft_test.go:97: 00815e63-a9a8-435a-2f1d-ba1a8309426f: 15:48:51.744645 [INFO] raft: Added peer 79f5b43b-d4a2-4df6-a5fd-10dc3f61c44d, starting replication - raft_test.go:97: 79f5b43b-d4a2-4df6-a5fd-10dc3f61c44d: 15:48:51.744754 [WARN] raft: Failed to get previous log: 3 log not found (last: 0) - raft_test.go:97: 00815e63-a9a8-435a-2f1d-ba1a8309426f: 15:48:51.744841 [WARN] raft: AppendEntries to {Voter 79f5b43b-d4a2-4df6-a5fd-10dc3f61c44d 79f5b43b-d4a2-4df6-a5fd-10dc3f61c44d} rejected, sending older logs (next: 1) - raft_test.go:97: 00815e63-a9a8-435a-2f1d-ba1a8309426f: 15:48:51.744964 [INFO] raft: pipelining replication to peer {Voter 79f5b43b-d4a2-4df6-a5fd-10dc3f61c44d 79f5b43b-d4a2-4df6-a5fd-10dc3f61c44d} - raft_test.go:97: cluster: 15:48:51.745016 [INFO] Starting stability test for raft state: Leader - raft_test.go:97: cluster: 15:48:51.850387 [INFO] Stable state for Leader reached at 2022-08-05 15:48:51.745081866 +0000 UTC m=+0.700271461 (1 nodes), 1.36µs from start of poll, 390.90585ms from cluster start. Timeout at 2022-08-05 15:48:51.850237916 +0000 UTC m=+0.805427513, 105.156052ms after stability - raft_test.go:97: cluster: 15:48:51.850482 [INFO] Starting stability test for raft state: Leader - raft_test.go:97: cluster: 15:48:51.955777 [INFO] Stable state for Leader reached at 2022-08-05 15:48:51.850532201 +0000 UTC m=+0.805721806 (1 nodes), 2.932µs from start of poll, 496.356195ms from cluster start. Timeout at 2022-08-05 15:48:51.955669075 +0000 UTC m=+0.910858680, 105.136874ms after stability - raft_test.go:97: 00815e63-a9a8-435a-2f1d-ba1a8309426f: 15:48:51.955916 [INFO] raft: Updating configuration with RemoveServer (79f5b43b-d4a2-4df6-a5fd-10dc3f61c44d, ) to [{Suffrage:Voter ID:00815e63-a9a8-435a-2f1d-ba1a8309426f Address:00815e63-a9a8-435a-2f1d-ba1a8309426f} {Suffrage:Voter ID:8b8d2ced-dde1-a623-c0ea-69da7acd93ef Address:8b8d2ced-dde1-a623-c0ea-69da7acd93ef}] - raft_test.go:97: 00815e63-a9a8-435a-2f1d-ba1a8309426f: 15:48:51.956009 [INFO] raft: Removed peer 79f5b43b-d4a2-4df6-a5fd-10dc3f61c44d, stopping replication after 4 - raft_test.go:97: 00815e63-a9a8-435a-2f1d-ba1a8309426f: 15:48:51.956080 [INFO] raft: aborting pipeline replication to peer {Voter 79f5b43b-d4a2-4df6-a5fd-10dc3f61c44d 79f5b43b-d4a2-4df6-a5fd-10dc3f61c44d} - raft_test.go:97: 00815e63-a9a8-435a-2f1d-ba1a8309426f: 15:48:51.956305 [INFO] raft: aborting pipeline replication to peer {Voter 8b8d2ced-dde1-a623-c0ea-69da7acd93ef 8b8d2ced-dde1-a623-c0ea-69da7acd93ef} +testLoggerAdapter verbose: cluster: 09:26:48.422372 [DEBUG] Fully Connecting +testLoggerAdapter verbose: 4fa20b49-a074-36c0-9144-2673273e703d: 09:26:48.422638 [INFO] raft: Initial configuration (index=1): [{Suffrage:Voter ID:4fa20b49-a074-36c0-9144-2673273e703d Address:4fa20b49-a074-36c0-9144-2673273e703d} {Suffrage:Voter ID:a7be8255-33da-5143-39e5-2148497f5cf7 Address:a7be8255-33da-5143-39e5-2148497f5cf7}] +testLoggerAdapter verbose: 4fa20b49-a074-36c0-9144-2673273e703d: 09:26:48.422764 [INFO] raft: Node at 4fa20b49-a074-36c0-9144-2673273e703d [Follower] entering Follower state (Leader: "") +testLoggerAdapter verbose: a7be8255-33da-5143-39e5-2148497f5cf7: 09:26:48.422825 [INFO] raft: Initial configuration (index=1): [{Suffrage:Voter ID:4fa20b49-a074-36c0-9144-2673273e703d Address:4fa20b49-a074-36c0-9144-2673273e703d} {Suffrage:Voter ID:a7be8255-33da-5143-39e5-2148497f5cf7 Address:a7be8255-33da-5143-39e5-2148497f5cf7}] +testLoggerAdapter verbose: a7be8255-33da-5143-39e5-2148497f5cf7: 09:26:48.422912 [INFO] raft: Node at a7be8255-33da-5143-39e5-2148497f5cf7 [Follower] entering Follower state (Leader: "") +testLoggerAdapter verbose: cluster: 09:26:48.422988 [DEBUG] Fully Connecting +testLoggerAdapter verbose: cafe44b2-5ed5-6d4c-991c-9e1fb7a9f6b6: 09:26:48.423067 [INFO] raft: Initial configuration (index=0): [] +testLoggerAdapter verbose: cluster: 09:26:48.423128 [DEBUG] Fully Connecting +testLoggerAdapter verbose: cluster: 09:26:48.423169 [INFO] Starting stability test for raft state: Leader +testLoggerAdapter verbose: cafe44b2-5ed5-6d4c-991c-9e1fb7a9f6b6: 09:26:48.423177 [INFO] raft: Node at cafe44b2-5ed5-6d4c-991c-9e1fb7a9f6b6 [Follower] entering Follower state (Leader: "") +testLoggerAdapter verbose: cafe44b2-5ed5-6d4c-991c-9e1fb7a9f6b6: 09:26:48.482348 [WARN] raft: no known peers, aborting election +testLoggerAdapter verbose: 4fa20b49-a074-36c0-9144-2673273e703d: 09:26:48.495675 [WARN] raft: Heartbeat timeout from "" reached, starting election +testLoggerAdapter verbose: 4fa20b49-a074-36c0-9144-2673273e703d: 09:26:48.495775 [INFO] raft: Node at 4fa20b49-a074-36c0-9144-2673273e703d [Candidate] entering Candidate state in term 2 +testLoggerAdapter verbose: 4fa20b49-a074-36c0-9144-2673273e703d: 09:26:48.495872 [DEBUG] raft: Votes needed: 2 +testLoggerAdapter verbose: 4fa20b49-a074-36c0-9144-2673273e703d: 09:26:48.495916 [DEBUG] raft: Vote granted from 4fa20b49-a074-36c0-9144-2673273e703d in term 2. Tally: 1 +testLoggerAdapter verbose: cluster: 09:26:48.495958 [DEBUG] Resetting stability timeout +testLoggerAdapter verbose: 4fa20b49-a074-36c0-9144-2673273e703d: 09:26:48.496151 [DEBUG] raft: Vote granted from a7be8255-33da-5143-39e5-2148497f5cf7 in term 2. Tally: 2 +testLoggerAdapter verbose: 4fa20b49-a074-36c0-9144-2673273e703d: 09:26:48.496202 [INFO] raft: Election won. Tally: 2 +testLoggerAdapter verbose: cluster: 09:26:48.496228 [DEBUG] Resetting stability timeout +testLoggerAdapter verbose: 4fa20b49-a074-36c0-9144-2673273e703d: 09:26:48.496252 [INFO] raft: Node at 4fa20b49-a074-36c0-9144-2673273e703d [Leader] entering Leader state +testLoggerAdapter verbose: cluster: 09:26:48.496296 [DEBUG] Resetting stability timeout +testLoggerAdapter verbose: 4fa20b49-a074-36c0-9144-2673273e703d: 09:26:48.496303 [INFO] raft: Added peer a7be8255-33da-5143-39e5-2148497f5cf7, starting replication +testLoggerAdapter verbose: 4fa20b49-a074-36c0-9144-2673273e703d: 09:26:48.496597 [INFO] raft: pipelining replication to peer {Voter a7be8255-33da-5143-39e5-2148497f5cf7 a7be8255-33da-5143-39e5-2148497f5cf7} +testLoggerAdapter verbose: cluster: 09:26:48.601563 [INFO] Stable state for Leader reached at 2021-07-03 09:26:48.4963384 +0000 UTC m=+0.367451001 (1 nodes), 73.14516ms from start of poll, 73.888062ms from cluster start. Timeout at 2021-07-03 09:26:48.601433047 +0000 UTC m=+0.472545545, 105.094544ms after stability +testLoggerAdapter verbose: cluster: 09:26:48.601635 [INFO] Starting stability test for raft state: Leader +testLoggerAdapter verbose: cluster: 09:26:48.706899 [INFO] Stable state for Leader reached at 2021-07-03 09:26:48.601653661 +0000 UTC m=+0.472766156 (1 nodes), 994ns from start of poll, 179.203217ms from cluster start. Timeout at 2021-07-03 09:26:48.706813471 +0000 UTC m=+0.577926036, 105.15988ms after stability +testLoggerAdapter verbose: cluster: 09:26:48.706979 [INFO] Starting stability test for raft state: Leader +testLoggerAdapter verbose: cluster: 09:26:48.812240 [INFO] Stable state for Leader reached at 2021-07-03 09:26:48.706998906 +0000 UTC m=+0.578111400 (1 nodes), 936ns from start of poll, 284.548461ms from cluster start. Timeout at 2021-07-03 09:26:48.812110038 +0000 UTC m=+0.683222601, 105.111201ms after stability +testLoggerAdapter verbose: 4fa20b49-a074-36c0-9144-2673273e703d: 09:26:48.812670 [INFO] raft: Updating configuration with AddStaging (cafe44b2-5ed5-6d4c-991c-9e1fb7a9f6b6, cafe44b2-5ed5-6d4c-991c-9e1fb7a9f6b6) to [{Suffrage:Voter ID:4fa20b49-a074-36c0-9144-2673273e703d Address:4fa20b49-a074-36c0-9144-2673273e703d} {Suffrage:Voter ID:a7be8255-33da-5143-39e5-2148497f5cf7 Address:a7be8255-33da-5143-39e5-2148497f5cf7} {Suffrage:Voter ID:cafe44b2-5ed5-6d4c-991c-9e1fb7a9f6b6 Address:cafe44b2-5ed5-6d4c-991c-9e1fb7a9f6b6}] +testLoggerAdapter verbose: 4fa20b49-a074-36c0-9144-2673273e703d: 09:26:48.812858 [INFO] raft: Added peer cafe44b2-5ed5-6d4c-991c-9e1fb7a9f6b6, starting replication +testLoggerAdapter verbose: cafe44b2-5ed5-6d4c-991c-9e1fb7a9f6b6: 09:26:48.812984 [WARN] raft: Failed to get previous log: 3 log not found (last: 0) +testLoggerAdapter verbose: 4fa20b49-a074-36c0-9144-2673273e703d: 09:26:48.813079 [WARN] raft: AppendEntries to {Voter cafe44b2-5ed5-6d4c-991c-9e1fb7a9f6b6 cafe44b2-5ed5-6d4c-991c-9e1fb7a9f6b6} rejected, sending older logs (next: 1) +testLoggerAdapter verbose: 4fa20b49-a074-36c0-9144-2673273e703d: 09:26:48.813247 [INFO] raft: pipelining replication to peer {Voter cafe44b2-5ed5-6d4c-991c-9e1fb7a9f6b6 cafe44b2-5ed5-6d4c-991c-9e1fb7a9f6b6} +testLoggerAdapter verbose: cluster: 09:26:48.818410 [INFO] Starting stability test for raft state: Leader +testLoggerAdapter verbose: cluster: 09:26:48.923744 [INFO] Stable state for Leader reached at 2021-07-03 09:26:48.818493842 +0000 UTC m=+0.689606406 (1 nodes), 1.317µs from start of poll, 396.043467ms from cluster start. Timeout at 2021-07-03 09:26:48.923625989 +0000 UTC m=+0.794738563, 105.132157ms after stability +testLoggerAdapter verbose: cluster: 09:26:48.923819 [INFO] Starting stability test for raft state: Leader +testLoggerAdapter verbose: cluster: 09:26:49.029115 [INFO] Stable state for Leader reached at 2021-07-03 09:26:48.923857487 +0000 UTC m=+0.794970050 (1 nodes), 1.363µs from start of poll, 501.407111ms from cluster start. Timeout at 2021-07-03 09:26:49.02900627 +0000 UTC m=+0.900118848, 105.148798ms after stability +testLoggerAdapter verbose: 4fa20b49-a074-36c0-9144-2673273e703d: 09:26:49.029289 [INFO] raft: Updating configuration with RemoveServer (cafe44b2-5ed5-6d4c-991c-9e1fb7a9f6b6, ) to [{Suffrage:Voter ID:4fa20b49-a074-36c0-9144-2673273e703d Address:4fa20b49-a074-36c0-9144-2673273e703d} {Suffrage:Voter ID:a7be8255-33da-5143-39e5-2148497f5cf7 Address:a7be8255-33da-5143-39e5-2148497f5cf7}] +testLoggerAdapter verbose: 4fa20b49-a074-36c0-9144-2673273e703d: 09:26:49.029425 [INFO] raft: Removed peer cafe44b2-5ed5-6d4c-991c-9e1fb7a9f6b6, stopping replication after 4 +testLoggerAdapter verbose: 4fa20b49-a074-36c0-9144-2673273e703d: 09:26:49.029510 [INFO] raft: aborting pipeline replication to peer {Voter cafe44b2-5ed5-6d4c-991c-9e1fb7a9f6b6 cafe44b2-5ed5-6d4c-991c-9e1fb7a9f6b6} +testLoggerAdapter verbose: 4fa20b49-a074-36c0-9144-2673273e703d: 09:26:49.029593 [INFO] raft: aborting pipeline replication to peer {Voter a7be8255-33da-5143-39e5-2148497f5cf7 a7be8255-33da-5143-39e5-2148497f5cf7} +--- PASS: TestRaft_ProtocolVersion_Upgrade_1_2 (0.61s) + raft_test.go:97: cluster: 09:26:48.422372 [DEBUG] Fully Connecting + raft_test.go:97: 4fa20b49-a074-36c0-9144-2673273e703d: 09:26:48.422638 [INFO] raft: Initial configuration (index=1): [{Suffrage:Voter ID:4fa20b49-a074-36c0-9144-2673273e703d Address:4fa20b49-a074-36c0-9144-2673273e703d} {Suffrage:Voter ID:a7be8255-33da-5143-39e5-2148497f5cf7 Address:a7be8255-33da-5143-39e5-2148497f5cf7}] + raft_test.go:97: 4fa20b49-a074-36c0-9144-2673273e703d: 09:26:48.422764 [INFO] raft: Node at 4fa20b49-a074-36c0-9144-2673273e703d [Follower] entering Follower state (Leader: "") + raft_test.go:97: a7be8255-33da-5143-39e5-2148497f5cf7: 09:26:48.422825 [INFO] raft: Initial configuration (index=1): [{Suffrage:Voter ID:4fa20b49-a074-36c0-9144-2673273e703d Address:4fa20b49-a074-36c0-9144-2673273e703d} {Suffrage:Voter ID:a7be8255-33da-5143-39e5-2148497f5cf7 Address:a7be8255-33da-5143-39e5-2148497f5cf7}] + raft_test.go:97: a7be8255-33da-5143-39e5-2148497f5cf7: 09:26:48.422912 [INFO] raft: Node at a7be8255-33da-5143-39e5-2148497f5cf7 [Follower] entering Follower state (Leader: "") + raft_test.go:97: cluster: 09:26:48.422988 [DEBUG] Fully Connecting + raft_test.go:97: cafe44b2-5ed5-6d4c-991c-9e1fb7a9f6b6: 09:26:48.423067 [INFO] raft: Initial configuration (index=0): [] + raft_test.go:97: cluster: 09:26:48.423128 [DEBUG] Fully Connecting + raft_test.go:97: cluster: 09:26:48.423169 [INFO] Starting stability test for raft state: Leader + raft_test.go:97: cafe44b2-5ed5-6d4c-991c-9e1fb7a9f6b6: 09:26:48.423177 [INFO] raft: Node at cafe44b2-5ed5-6d4c-991c-9e1fb7a9f6b6 [Follower] entering Follower state (Leader: "") + raft_test.go:97: cafe44b2-5ed5-6d4c-991c-9e1fb7a9f6b6: 09:26:48.482348 [WARN] raft: no known peers, aborting election + raft_test.go:97: 4fa20b49-a074-36c0-9144-2673273e703d: 09:26:48.495675 [WARN] raft: Heartbeat timeout from "" reached, starting election + raft_test.go:97: 4fa20b49-a074-36c0-9144-2673273e703d: 09:26:48.495775 [INFO] raft: Node at 4fa20b49-a074-36c0-9144-2673273e703d [Candidate] entering Candidate state in term 2 + raft_test.go:97: 4fa20b49-a074-36c0-9144-2673273e703d: 09:26:48.495872 [DEBUG] raft: Votes needed: 2 + raft_test.go:97: 4fa20b49-a074-36c0-9144-2673273e703d: 09:26:48.495916 [DEBUG] raft: Vote granted from 4fa20b49-a074-36c0-9144-2673273e703d in term 2. Tally: 1 + raft_test.go:97: cluster: 09:26:48.495958 [DEBUG] Resetting stability timeout + raft_test.go:97: 4fa20b49-a074-36c0-9144-2673273e703d: 09:26:48.496151 [DEBUG] raft: Vote granted from a7be8255-33da-5143-39e5-2148497f5cf7 in term 2. Tally: 2 + raft_test.go:97: 4fa20b49-a074-36c0-9144-2673273e703d: 09:26:48.496202 [INFO] raft: Election won. Tally: 2 + raft_test.go:97: cluster: 09:26:48.496228 [DEBUG] Resetting stability timeout + raft_test.go:97: 4fa20b49-a074-36c0-9144-2673273e703d: 09:26:48.496252 [INFO] raft: Node at 4fa20b49-a074-36c0-9144-2673273e703d [Leader] entering Leader state + raft_test.go:97: cluster: 09:26:48.496296 [DEBUG] Resetting stability timeout + raft_test.go:97: 4fa20b49-a074-36c0-9144-2673273e703d: 09:26:48.496303 [INFO] raft: Added peer a7be8255-33da-5143-39e5-2148497f5cf7, starting replication + raft_test.go:97: 4fa20b49-a074-36c0-9144-2673273e703d: 09:26:48.496597 [INFO] raft: pipelining replication to peer {Voter a7be8255-33da-5143-39e5-2148497f5cf7 a7be8255-33da-5143-39e5-2148497f5cf7} + raft_test.go:97: cluster: 09:26:48.601563 [INFO] Stable state for Leader reached at 2021-07-03 09:26:48.4963384 +0000 UTC m=+0.367451001 (1 nodes), 73.14516ms from start of poll, 73.888062ms from cluster start. Timeout at 2021-07-03 09:26:48.601433047 +0000 UTC m=+0.472545545, 105.094544ms after stability + raft_test.go:97: cluster: 09:26:48.601635 [INFO] Starting stability test for raft state: Leader + raft_test.go:97: cluster: 09:26:48.706899 [INFO] Stable state for Leader reached at 2021-07-03 09:26:48.601653661 +0000 UTC m=+0.472766156 (1 nodes), 994ns from start of poll, 179.203217ms from cluster start. Timeout at 2021-07-03 09:26:48.706813471 +0000 UTC m=+0.577926036, 105.15988ms after stability + raft_test.go:97: cluster: 09:26:48.706979 [INFO] Starting stability test for raft state: Leader + raft_test.go:97: cluster: 09:26:48.812240 [INFO] Stable state for Leader reached at 2021-07-03 09:26:48.706998906 +0000 UTC m=+0.578111400 (1 nodes), 936ns from start of poll, 284.548461ms from cluster start. Timeout at 2021-07-03 09:26:48.812110038 +0000 UTC m=+0.683222601, 105.111201ms after stability + raft_test.go:97: 4fa20b49-a074-36c0-9144-2673273e703d: 09:26:48.812670 [INFO] raft: Updating configuration with AddStaging (cafe44b2-5ed5-6d4c-991c-9e1fb7a9f6b6, cafe44b2-5ed5-6d4c-991c-9e1fb7a9f6b6) to [{Suffrage:Voter ID:4fa20b49-a074-36c0-9144-2673273e703d Address:4fa20b49-a074-36c0-9144-2673273e703d} {Suffrage:Voter ID:a7be8255-33da-5143-39e5-2148497f5cf7 Address:a7be8255-33da-5143-39e5-2148497f5cf7} {Suffrage:Voter ID:cafe44b2-5ed5-6d4c-991c-9e1fb7a9f6b6 Address:cafe44b2-5ed5-6d4c-991c-9e1fb7a9f6b6}] + raft_test.go:97: 4fa20b49-a074-36c0-9144-2673273e703d: 09:26:48.812858 [INFO] raft: Added peer cafe44b2-5ed5-6d4c-991c-9e1fb7a9f6b6, starting replication + raft_test.go:97: cafe44b2-5ed5-6d4c-991c-9e1fb7a9f6b6: 09:26:48.812984 [WARN] raft: Failed to get previous log: 3 log not found (last: 0) + raft_test.go:97: 4fa20b49-a074-36c0-9144-2673273e703d: 09:26:48.813079 [WARN] raft: AppendEntries to {Voter cafe44b2-5ed5-6d4c-991c-9e1fb7a9f6b6 cafe44b2-5ed5-6d4c-991c-9e1fb7a9f6b6} rejected, sending older logs (next: 1) + raft_test.go:97: 4fa20b49-a074-36c0-9144-2673273e703d: 09:26:48.813247 [INFO] raft: pipelining replication to peer {Voter cafe44b2-5ed5-6d4c-991c-9e1fb7a9f6b6 cafe44b2-5ed5-6d4c-991c-9e1fb7a9f6b6} + raft_test.go:97: cluster: 09:26:48.818410 [INFO] Starting stability test for raft state: Leader + raft_test.go:97: cluster: 09:26:48.923744 [INFO] Stable state for Leader reached at 2021-07-03 09:26:48.818493842 +0000 UTC m=+0.689606406 (1 nodes), 1.317µs from start of poll, 396.043467ms from cluster start. Timeout at 2021-07-03 09:26:48.923625989 +0000 UTC m=+0.794738563, 105.132157ms after stability + raft_test.go:97: cluster: 09:26:48.923819 [INFO] Starting stability test for raft state: Leader + raft_test.go:97: cluster: 09:26:49.029115 [INFO] Stable state for Leader reached at 2021-07-03 09:26:48.923857487 +0000 UTC m=+0.794970050 (1 nodes), 1.363µs from start of poll, 501.407111ms from cluster start. Timeout at 2021-07-03 09:26:49.02900627 +0000 UTC m=+0.900118848, 105.148798ms after stability + raft_test.go:97: 4fa20b49-a074-36c0-9144-2673273e703d: 09:26:49.029289 [INFO] raft: Updating configuration with RemoveServer (cafe44b2-5ed5-6d4c-991c-9e1fb7a9f6b6, ) to [{Suffrage:Voter ID:4fa20b49-a074-36c0-9144-2673273e703d Address:4fa20b49-a074-36c0-9144-2673273e703d} {Suffrage:Voter ID:a7be8255-33da-5143-39e5-2148497f5cf7 Address:a7be8255-33da-5143-39e5-2148497f5cf7}] + raft_test.go:97: 4fa20b49-a074-36c0-9144-2673273e703d: 09:26:49.029425 [INFO] raft: Removed peer cafe44b2-5ed5-6d4c-991c-9e1fb7a9f6b6, stopping replication after 4 + raft_test.go:97: 4fa20b49-a074-36c0-9144-2673273e703d: 09:26:49.029510 [INFO] raft: aborting pipeline replication to peer {Voter cafe44b2-5ed5-6d4c-991c-9e1fb7a9f6b6 cafe44b2-5ed5-6d4c-991c-9e1fb7a9f6b6} + raft_test.go:97: 4fa20b49-a074-36c0-9144-2673273e703d: 09:26:49.029593 [INFO] raft: aborting pipeline replication to peer {Voter a7be8255-33da-5143-39e5-2148497f5cf7 a7be8255-33da-5143-39e5-2148497f5cf7} === RUN TestRaft_ProtocolVersion_Upgrade_2_3 -testLoggerAdapter verbose: cluster: 15:48:51.957151 [DEBUG] Fully Connecting -testLoggerAdapter verbose: 3642979d-8efe-bd9b-8919-b33accb62607: 15:48:51.957388 [INFO] raft: Initial configuration (index=1): [{Suffrage:Voter ID:3642979d-8efe-bd9b-8919-b33accb62607 Address:3642979d-8efe-bd9b-8919-b33accb62607} {Suffrage:Voter ID:64954d74-694e-ddfa-81f6-bb966199b3b8 Address:64954d74-694e-ddfa-81f6-bb966199b3b8}] -testLoggerAdapter verbose: 3642979d-8efe-bd9b-8919-b33accb62607: 15:48:51.957520 [INFO] raft: Node at 3642979d-8efe-bd9b-8919-b33accb62607 [Follower] entering Follower state (Leader: "") -testLoggerAdapter verbose: 64954d74-694e-ddfa-81f6-bb966199b3b8: 15:48:51.957574 [INFO] raft: Initial configuration (index=1): [{Suffrage:Voter ID:3642979d-8efe-bd9b-8919-b33accb62607 Address:3642979d-8efe-bd9b-8919-b33accb62607} {Suffrage:Voter ID:64954d74-694e-ddfa-81f6-bb966199b3b8 Address:64954d74-694e-ddfa-81f6-bb966199b3b8}] -testLoggerAdapter verbose: cluster: 15:48:51.957679 [INFO] Starting stability test for raft state: Follower -testLoggerAdapter verbose: 64954d74-694e-ddfa-81f6-bb966199b3b8: 15:48:51.957765 [INFO] raft: Node at 64954d74-694e-ddfa-81f6-bb966199b3b8 [Follower] entering Follower state (Leader: "") -testLoggerAdapter verbose: 3642979d-8efe-bd9b-8919-b33accb62607: 15:48:52.034784 [WARN] raft: Heartbeat timeout from "" reached, starting election -testLoggerAdapter verbose: 3642979d-8efe-bd9b-8919-b33accb62607: 15:48:52.034893 [INFO] raft: Node at 3642979d-8efe-bd9b-8919-b33accb62607 [Candidate] entering Candidate state in term 2 -testLoggerAdapter verbose: 3642979d-8efe-bd9b-8919-b33accb62607: 15:48:52.034942 [DEBUG] raft: Votes needed: 2 -testLoggerAdapter verbose: 3642979d-8efe-bd9b-8919-b33accb62607: 15:48:52.034963 [DEBUG] raft: Vote granted from 3642979d-8efe-bd9b-8919-b33accb62607 in term 2. Tally: 1 -testLoggerAdapter verbose: 3642979d-8efe-bd9b-8919-b33accb62607: 15:48:52.035022 [DEBUG] raft: Vote granted from 64954d74-694e-ddfa-81f6-bb966199b3b8 in term 2. Tally: 2 -testLoggerAdapter verbose: cluster: 15:48:52.035022 [DEBUG] Resetting stability timeout -testLoggerAdapter verbose: cluster: 15:48:52.035123 [DEBUG] Resetting stability timeout -testLoggerAdapter verbose: 3642979d-8efe-bd9b-8919-b33accb62607: 15:48:52.035040 [INFO] raft: Election won. Tally: 2 -testLoggerAdapter verbose: 3642979d-8efe-bd9b-8919-b33accb62607: 15:48:52.035206 [INFO] raft: Node at 3642979d-8efe-bd9b-8919-b33accb62607 [Leader] entering Leader state -testLoggerAdapter verbose: 3642979d-8efe-bd9b-8919-b33accb62607: 15:48:52.035253 [INFO] raft: Added peer 64954d74-694e-ddfa-81f6-bb966199b3b8, starting replication -testLoggerAdapter verbose: cluster: 15:48:52.035279 [DEBUG] Resetting stability timeout -testLoggerAdapter verbose: 3642979d-8efe-bd9b-8919-b33accb62607: 15:48:52.035396 [INFO] raft: pipelining replication to peer {Voter 64954d74-694e-ddfa-81f6-bb966199b3b8 64954d74-694e-ddfa-81f6-bb966199b3b8} -testLoggerAdapter verbose: cluster: 15:48:52.140525 [INFO] Stable state for Follower reached at 2022-08-05 15:48:52.035296399 +0000 UTC m=+0.990485933 (1 nodes), 77.580548ms from start of poll, 78.099916ms from cluster start. Timeout at 2022-08-05 15:48:52.140410667 +0000 UTC m=+1.095600241, 105.114308ms after stability -testLoggerAdapter verbose: cluster: 15:48:52.140805 [DEBUG] Fully Connecting -testLoggerAdapter verbose: server-6bdfb963-9be0-b8d4-3380-62e34b10c3bb: 15:48:52.140913 [INFO] raft: Initial configuration (index=0): [] -testLoggerAdapter verbose: cluster: 15:48:52.140982 [DEBUG] Fully Connecting -testLoggerAdapter verbose: cluster: 15:48:52.141017 [INFO] Starting stability test for raft state: Leader -testLoggerAdapter verbose: server-6bdfb963-9be0-b8d4-3380-62e34b10c3bb: 15:48:52.141044 [INFO] raft: Node at 6bdfb963-9be0-b8d4-3380-62e34b10c3bb [Follower] entering Follower state (Leader: "") -testLoggerAdapter verbose: server-6bdfb963-9be0-b8d4-3380-62e34b10c3bb: 15:48:52.236812 [WARN] raft: no known peers, aborting election -testLoggerAdapter verbose: cluster: 15:48:52.246323 [INFO] Stable state for Leader reached at 2022-08-05 15:48:52.141050527 +0000 UTC m=+1.096240100 (1 nodes), 1.012µs from start of poll, 183.854083ms from cluster start. Timeout at 2022-08-05 15:48:52.24616256 +0000 UTC m=+1.201352140, 105.11204ms after stability -testLoggerAdapter verbose: 3642979d-8efe-bd9b-8919-b33accb62607: 15:48:52.246564 [INFO] raft: Updating configuration with AddStaging (server-6bdfb963-9be0-b8d4-3380-62e34b10c3bb, 6bdfb963-9be0-b8d4-3380-62e34b10c3bb) to [{Suffrage:Voter ID:3642979d-8efe-bd9b-8919-b33accb62607 Address:3642979d-8efe-bd9b-8919-b33accb62607} {Suffrage:Voter ID:64954d74-694e-ddfa-81f6-bb966199b3b8 Address:64954d74-694e-ddfa-81f6-bb966199b3b8} {Suffrage:Voter ID:server-6bdfb963-9be0-b8d4-3380-62e34b10c3bb Address:6bdfb963-9be0-b8d4-3380-62e34b10c3bb}] -testLoggerAdapter verbose: 3642979d-8efe-bd9b-8919-b33accb62607: 15:48:52.246710 [INFO] raft: Added peer server-6bdfb963-9be0-b8d4-3380-62e34b10c3bb, starting replication -testLoggerAdapter verbose: server-6bdfb963-9be0-b8d4-3380-62e34b10c3bb: 15:48:52.246830 [WARN] raft: Failed to get previous log: 3 log not found (last: 0) -testLoggerAdapter verbose: 3642979d-8efe-bd9b-8919-b33accb62607: 15:48:52.246922 [WARN] raft: AppendEntries to {Voter server-6bdfb963-9be0-b8d4-3380-62e34b10c3bb 6bdfb963-9be0-b8d4-3380-62e34b10c3bb} rejected, sending older logs (next: 1) -testLoggerAdapter verbose: 3642979d-8efe-bd9b-8919-b33accb62607: 15:48:52.247058 [INFO] raft: pipelining replication to peer {Voter server-6bdfb963-9be0-b8d4-3380-62e34b10c3bb 6bdfb963-9be0-b8d4-3380-62e34b10c3bb} -testLoggerAdapter verbose: cluster: 15:48:52.247093 [INFO] Starting stability test for raft state: Leader -testLoggerAdapter verbose: cluster: 15:48:52.352361 [INFO] Stable state for Leader reached at 2022-08-05 15:48:52.247161583 +0000 UTC m=+1.202351176 (1 nodes), 1.79µs from start of poll, 289.965159ms from cluster start. Timeout at 2022-08-05 15:48:52.352241436 +0000 UTC m=+1.307430985, 105.079809ms after stability -testLoggerAdapter verbose: cluster: 15:48:52.352432 [INFO] Starting stability test for raft state: Leader -testLoggerAdapter verbose: cluster: 15:48:52.457686 [INFO] Stable state for Leader reached at 2022-08-05 15:48:52.352456182 +0000 UTC m=+1.307645731 (1 nodes), 951ns from start of poll, 395.259714ms from cluster start. Timeout at 2022-08-05 15:48:52.457583416 +0000 UTC m=+1.412772990, 105.127259ms after stability -testLoggerAdapter verbose: 3642979d-8efe-bd9b-8919-b33accb62607: 15:48:52.457823 [INFO] raft: Updating configuration with RemoveServer (64954d74-694e-ddfa-81f6-bb966199b3b8, ) to [{Suffrage:Voter ID:3642979d-8efe-bd9b-8919-b33accb62607 Address:3642979d-8efe-bd9b-8919-b33accb62607} {Suffrage:Voter ID:server-6bdfb963-9be0-b8d4-3380-62e34b10c3bb Address:6bdfb963-9be0-b8d4-3380-62e34b10c3bb}] -testLoggerAdapter verbose: 3642979d-8efe-bd9b-8919-b33accb62607: 15:48:52.457925 [INFO] raft: Removed peer 64954d74-694e-ddfa-81f6-bb966199b3b8, stopping replication after 4 -testLoggerAdapter verbose: 3642979d-8efe-bd9b-8919-b33accb62607: 15:48:52.458046 [INFO] raft: aborting pipeline replication to peer {Voter 64954d74-694e-ddfa-81f6-bb966199b3b8 64954d74-694e-ddfa-81f6-bb966199b3b8} -testLoggerAdapter verbose: 3642979d-8efe-bd9b-8919-b33accb62607: 15:48:52.458199 [INFO] raft: aborting pipeline replication to peer {Voter server-6bdfb963-9be0-b8d4-3380-62e34b10c3bb 6bdfb963-9be0-b8d4-3380-62e34b10c3bb} ---- PASS: TestRaft_ProtocolVersion_Upgrade_2_3 (0.50s) - raft_test.go:97: cluster: 15:48:51.957151 [DEBUG] Fully Connecting - raft_test.go:97: 3642979d-8efe-bd9b-8919-b33accb62607: 15:48:51.957388 [INFO] raft: Initial configuration (index=1): [{Suffrage:Voter ID:3642979d-8efe-bd9b-8919-b33accb62607 Address:3642979d-8efe-bd9b-8919-b33accb62607} {Suffrage:Voter ID:64954d74-694e-ddfa-81f6-bb966199b3b8 Address:64954d74-694e-ddfa-81f6-bb966199b3b8}] - raft_test.go:97: 3642979d-8efe-bd9b-8919-b33accb62607: 15:48:51.957520 [INFO] raft: Node at 3642979d-8efe-bd9b-8919-b33accb62607 [Follower] entering Follower state (Leader: "") - raft_test.go:97: 64954d74-694e-ddfa-81f6-bb966199b3b8: 15:48:51.957574 [INFO] raft: Initial configuration (index=1): [{Suffrage:Voter ID:3642979d-8efe-bd9b-8919-b33accb62607 Address:3642979d-8efe-bd9b-8919-b33accb62607} {Suffrage:Voter ID:64954d74-694e-ddfa-81f6-bb966199b3b8 Address:64954d74-694e-ddfa-81f6-bb966199b3b8}] - raft_test.go:97: cluster: 15:48:51.957679 [INFO] Starting stability test for raft state: Follower - raft_test.go:97: 64954d74-694e-ddfa-81f6-bb966199b3b8: 15:48:51.957765 [INFO] raft: Node at 64954d74-694e-ddfa-81f6-bb966199b3b8 [Follower] entering Follower state (Leader: "") - raft_test.go:97: 3642979d-8efe-bd9b-8919-b33accb62607: 15:48:52.034784 [WARN] raft: Heartbeat timeout from "" reached, starting election - raft_test.go:97: 3642979d-8efe-bd9b-8919-b33accb62607: 15:48:52.034893 [INFO] raft: Node at 3642979d-8efe-bd9b-8919-b33accb62607 [Candidate] entering Candidate state in term 2 - raft_test.go:97: 3642979d-8efe-bd9b-8919-b33accb62607: 15:48:52.034942 [DEBUG] raft: Votes needed: 2 - raft_test.go:97: 3642979d-8efe-bd9b-8919-b33accb62607: 15:48:52.034963 [DEBUG] raft: Vote granted from 3642979d-8efe-bd9b-8919-b33accb62607 in term 2. Tally: 1 - raft_test.go:97: 3642979d-8efe-bd9b-8919-b33accb62607: 15:48:52.035022 [DEBUG] raft: Vote granted from 64954d74-694e-ddfa-81f6-bb966199b3b8 in term 2. Tally: 2 - raft_test.go:97: cluster: 15:48:52.035022 [DEBUG] Resetting stability timeout - raft_test.go:97: cluster: 15:48:52.035123 [DEBUG] Resetting stability timeout - raft_test.go:97: 3642979d-8efe-bd9b-8919-b33accb62607: 15:48:52.035040 [INFO] raft: Election won. Tally: 2 - raft_test.go:97: 3642979d-8efe-bd9b-8919-b33accb62607: 15:48:52.035206 [INFO] raft: Node at 3642979d-8efe-bd9b-8919-b33accb62607 [Leader] entering Leader state - raft_test.go:97: 3642979d-8efe-bd9b-8919-b33accb62607: 15:48:52.035253 [INFO] raft: Added peer 64954d74-694e-ddfa-81f6-bb966199b3b8, starting replication - raft_test.go:97: cluster: 15:48:52.035279 [DEBUG] Resetting stability timeout - raft_test.go:97: 3642979d-8efe-bd9b-8919-b33accb62607: 15:48:52.035396 [INFO] raft: pipelining replication to peer {Voter 64954d74-694e-ddfa-81f6-bb966199b3b8 64954d74-694e-ddfa-81f6-bb966199b3b8} - raft_test.go:97: cluster: 15:48:52.140525 [INFO] Stable state for Follower reached at 2022-08-05 15:48:52.035296399 +0000 UTC m=+0.990485933 (1 nodes), 77.580548ms from start of poll, 78.099916ms from cluster start. Timeout at 2022-08-05 15:48:52.140410667 +0000 UTC m=+1.095600241, 105.114308ms after stability - raft_test.go:97: cluster: 15:48:52.140805 [DEBUG] Fully Connecting - raft_test.go:97: server-6bdfb963-9be0-b8d4-3380-62e34b10c3bb: 15:48:52.140913 [INFO] raft: Initial configuration (index=0): [] - raft_test.go:97: cluster: 15:48:52.140982 [DEBUG] Fully Connecting - raft_test.go:97: cluster: 15:48:52.141017 [INFO] Starting stability test for raft state: Leader - raft_test.go:97: server-6bdfb963-9be0-b8d4-3380-62e34b10c3bb: 15:48:52.141044 [INFO] raft: Node at 6bdfb963-9be0-b8d4-3380-62e34b10c3bb [Follower] entering Follower state (Leader: "") - raft_test.go:97: server-6bdfb963-9be0-b8d4-3380-62e34b10c3bb: 15:48:52.236812 [WARN] raft: no known peers, aborting election - raft_test.go:97: cluster: 15:48:52.246323 [INFO] Stable state for Leader reached at 2022-08-05 15:48:52.141050527 +0000 UTC m=+1.096240100 (1 nodes), 1.012µs from start of poll, 183.854083ms from cluster start. Timeout at 2022-08-05 15:48:52.24616256 +0000 UTC m=+1.201352140, 105.11204ms after stability - raft_test.go:97: 3642979d-8efe-bd9b-8919-b33accb62607: 15:48:52.246564 [INFO] raft: Updating configuration with AddStaging (server-6bdfb963-9be0-b8d4-3380-62e34b10c3bb, 6bdfb963-9be0-b8d4-3380-62e34b10c3bb) to [{Suffrage:Voter ID:3642979d-8efe-bd9b-8919-b33accb62607 Address:3642979d-8efe-bd9b-8919-b33accb62607} {Suffrage:Voter ID:64954d74-694e-ddfa-81f6-bb966199b3b8 Address:64954d74-694e-ddfa-81f6-bb966199b3b8} {Suffrage:Voter ID:server-6bdfb963-9be0-b8d4-3380-62e34b10c3bb Address:6bdfb963-9be0-b8d4-3380-62e34b10c3bb}] - raft_test.go:97: 3642979d-8efe-bd9b-8919-b33accb62607: 15:48:52.246710 [INFO] raft: Added peer server-6bdfb963-9be0-b8d4-3380-62e34b10c3bb, starting replication - raft_test.go:97: server-6bdfb963-9be0-b8d4-3380-62e34b10c3bb: 15:48:52.246830 [WARN] raft: Failed to get previous log: 3 log not found (last: 0) - raft_test.go:97: 3642979d-8efe-bd9b-8919-b33accb62607: 15:48:52.246922 [WARN] raft: AppendEntries to {Voter server-6bdfb963-9be0-b8d4-3380-62e34b10c3bb 6bdfb963-9be0-b8d4-3380-62e34b10c3bb} rejected, sending older logs (next: 1) - raft_test.go:97: 3642979d-8efe-bd9b-8919-b33accb62607: 15:48:52.247058 [INFO] raft: pipelining replication to peer {Voter server-6bdfb963-9be0-b8d4-3380-62e34b10c3bb 6bdfb963-9be0-b8d4-3380-62e34b10c3bb} - raft_test.go:97: cluster: 15:48:52.247093 [INFO] Starting stability test for raft state: Leader - raft_test.go:97: cluster: 15:48:52.352361 [INFO] Stable state for Leader reached at 2022-08-05 15:48:52.247161583 +0000 UTC m=+1.202351176 (1 nodes), 1.79µs from start of poll, 289.965159ms from cluster start. Timeout at 2022-08-05 15:48:52.352241436 +0000 UTC m=+1.307430985, 105.079809ms after stability - raft_test.go:97: cluster: 15:48:52.352432 [INFO] Starting stability test for raft state: Leader - raft_test.go:97: cluster: 15:48:52.457686 [INFO] Stable state for Leader reached at 2022-08-05 15:48:52.352456182 +0000 UTC m=+1.307645731 (1 nodes), 951ns from start of poll, 395.259714ms from cluster start. Timeout at 2022-08-05 15:48:52.457583416 +0000 UTC m=+1.412772990, 105.127259ms after stability - raft_test.go:97: 3642979d-8efe-bd9b-8919-b33accb62607: 15:48:52.457823 [INFO] raft: Updating configuration with RemoveServer (64954d74-694e-ddfa-81f6-bb966199b3b8, ) to [{Suffrage:Voter ID:3642979d-8efe-bd9b-8919-b33accb62607 Address:3642979d-8efe-bd9b-8919-b33accb62607} {Suffrage:Voter ID:server-6bdfb963-9be0-b8d4-3380-62e34b10c3bb Address:6bdfb963-9be0-b8d4-3380-62e34b10c3bb}] - raft_test.go:97: 3642979d-8efe-bd9b-8919-b33accb62607: 15:48:52.457925 [INFO] raft: Removed peer 64954d74-694e-ddfa-81f6-bb966199b3b8, stopping replication after 4 - raft_test.go:97: 3642979d-8efe-bd9b-8919-b33accb62607: 15:48:52.458046 [INFO] raft: aborting pipeline replication to peer {Voter 64954d74-694e-ddfa-81f6-bb966199b3b8 64954d74-694e-ddfa-81f6-bb966199b3b8} - raft_test.go:97: 3642979d-8efe-bd9b-8919-b33accb62607: 15:48:52.458199 [INFO] raft: aborting pipeline replication to peer {Voter server-6bdfb963-9be0-b8d4-3380-62e34b10c3bb 6bdfb963-9be0-b8d4-3380-62e34b10c3bb} +testLoggerAdapter verbose: cluster: 09:26:49.030090 [DEBUG] Fully Connecting +testLoggerAdapter verbose: 37d85294-4840-ea4e-3912-8d05a98cc527: 09:26:49.030243 [INFO] raft: Initial configuration (index=1): [{Suffrage:Voter ID:37d85294-4840-ea4e-3912-8d05a98cc527 Address:37d85294-4840-ea4e-3912-8d05a98cc527} {Suffrage:Voter ID:76e15a93-b29c-de2c-f9e0-801b1a90373e Address:76e15a93-b29c-de2c-f9e0-801b1a90373e}] +testLoggerAdapter verbose: 76e15a93-b29c-de2c-f9e0-801b1a90373e: 09:26:49.030350 [INFO] raft: Initial configuration (index=1): [{Suffrage:Voter ID:37d85294-4840-ea4e-3912-8d05a98cc527 Address:37d85294-4840-ea4e-3912-8d05a98cc527} {Suffrage:Voter ID:76e15a93-b29c-de2c-f9e0-801b1a90373e Address:76e15a93-b29c-de2c-f9e0-801b1a90373e}] +testLoggerAdapter verbose: cluster: 09:26:49.030380 [INFO] Starting stability test for raft state: Follower +testLoggerAdapter verbose: 37d85294-4840-ea4e-3912-8d05a98cc527: 09:26:49.030383 [INFO] raft: Node at 37d85294-4840-ea4e-3912-8d05a98cc527 [Follower] entering Follower state (Leader: "") +testLoggerAdapter verbose: 76e15a93-b29c-de2c-f9e0-801b1a90373e: 09:26:49.030416 [INFO] raft: Node at 76e15a93-b29c-de2c-f9e0-801b1a90373e [Follower] entering Follower state (Leader: "") +testLoggerAdapter verbose: 37d85294-4840-ea4e-3912-8d05a98cc527: 09:26:49.094835 [WARN] raft: Heartbeat timeout from "" reached, starting election +testLoggerAdapter verbose: 37d85294-4840-ea4e-3912-8d05a98cc527: 09:26:49.094952 [INFO] raft: Node at 37d85294-4840-ea4e-3912-8d05a98cc527 [Candidate] entering Candidate state in term 2 +testLoggerAdapter verbose: 37d85294-4840-ea4e-3912-8d05a98cc527: 09:26:49.095017 [DEBUG] raft: Votes needed: 2 +testLoggerAdapter verbose: 37d85294-4840-ea4e-3912-8d05a98cc527: 09:26:49.095042 [DEBUG] raft: Vote granted from 37d85294-4840-ea4e-3912-8d05a98cc527 in term 2. Tally: 1 +testLoggerAdapter verbose: cluster: 09:26:49.095096 [DEBUG] Resetting stability timeout +testLoggerAdapter verbose: cluster: 09:26:49.095183 [DEBUG] Resetting stability timeout +testLoggerAdapter verbose: 37d85294-4840-ea4e-3912-8d05a98cc527: 09:26:49.095109 [DEBUG] raft: Vote granted from 76e15a93-b29c-de2c-f9e0-801b1a90373e in term 2. Tally: 2 +testLoggerAdapter verbose: 37d85294-4840-ea4e-3912-8d05a98cc527: 09:26:49.095291 [INFO] raft: Election won. Tally: 2 +testLoggerAdapter verbose: 37d85294-4840-ea4e-3912-8d05a98cc527: 09:26:49.095374 [INFO] raft: Node at 37d85294-4840-ea4e-3912-8d05a98cc527 [Leader] entering Leader state +testLoggerAdapter verbose: 37d85294-4840-ea4e-3912-8d05a98cc527: 09:26:49.095449 [INFO] raft: Added peer 76e15a93-b29c-de2c-f9e0-801b1a90373e, starting replication +testLoggerAdapter verbose: cluster: 09:26:49.095468 [DEBUG] Resetting stability timeout +testLoggerAdapter verbose: 37d85294-4840-ea4e-3912-8d05a98cc527: 09:26:49.095638 [INFO] raft: pipelining replication to peer {Voter 76e15a93-b29c-de2c-f9e0-801b1a90373e 76e15a93-b29c-de2c-f9e0-801b1a90373e} +testLoggerAdapter verbose: cluster: 09:26:49.200735 [INFO] Stable state for Follower reached at 2021-07-03 09:26:49.095488592 +0000 UTC m=+0.966601107 (1 nodes), 65.095054ms from start of poll, 65.377798ms from cluster start. Timeout at 2021-07-03 09:26:49.200608037 +0000 UTC m=+1.071720628, 105.119521ms after stability +testLoggerAdapter verbose: cluster: 09:26:49.201053 [DEBUG] Fully Connecting +testLoggerAdapter verbose: server-c995a658-761f-cec0-34f2-6c75d317cc78: 09:26:49.201172 [INFO] raft: Initial configuration (index=0): [] +testLoggerAdapter verbose: cluster: 09:26:49.201241 [DEBUG] Fully Connecting +testLoggerAdapter verbose: cluster: 09:26:49.201295 [INFO] Starting stability test for raft state: Leader +testLoggerAdapter verbose: server-c995a658-761f-cec0-34f2-6c75d317cc78: 09:26:49.201329 [INFO] raft: Node at c995a658-761f-cec0-34f2-6c75d317cc78 [Follower] entering Follower state (Leader: "") +testLoggerAdapter verbose: server-c995a658-761f-cec0-34f2-6c75d317cc78: 09:26:49.260886 [WARN] raft: no known peers, aborting election +testLoggerAdapter verbose: cluster: 09:26:49.306625 [INFO] Stable state for Leader reached at 2021-07-03 09:26:49.201330486 +0000 UTC m=+1.072443060 (1 nodes), 1.148µs from start of poll, 171.219751ms from cluster start. Timeout at 2021-07-03 09:26:49.306507393 +0000 UTC m=+1.177620009, 105.176949ms after stability +testLoggerAdapter verbose: 37d85294-4840-ea4e-3912-8d05a98cc527: 09:26:49.306761 [INFO] raft: Updating configuration with AddStaging (server-c995a658-761f-cec0-34f2-6c75d317cc78, c995a658-761f-cec0-34f2-6c75d317cc78) to [{Suffrage:Voter ID:37d85294-4840-ea4e-3912-8d05a98cc527 Address:37d85294-4840-ea4e-3912-8d05a98cc527} {Suffrage:Voter ID:76e15a93-b29c-de2c-f9e0-801b1a90373e Address:76e15a93-b29c-de2c-f9e0-801b1a90373e} {Suffrage:Voter ID:server-c995a658-761f-cec0-34f2-6c75d317cc78 Address:c995a658-761f-cec0-34f2-6c75d317cc78}] +testLoggerAdapter verbose: 37d85294-4840-ea4e-3912-8d05a98cc527: 09:26:49.306855 [INFO] raft: Added peer server-c995a658-761f-cec0-34f2-6c75d317cc78, starting replication +testLoggerAdapter verbose: server-c995a658-761f-cec0-34f2-6c75d317cc78: 09:26:49.306935 [WARN] raft: Failed to get previous log: 3 log not found (last: 0) +testLoggerAdapter verbose: 37d85294-4840-ea4e-3912-8d05a98cc527: 09:26:49.306969 [WARN] raft: AppendEntries to {Voter server-c995a658-761f-cec0-34f2-6c75d317cc78 c995a658-761f-cec0-34f2-6c75d317cc78} rejected, sending older logs (next: 1) +testLoggerAdapter verbose: 37d85294-4840-ea4e-3912-8d05a98cc527: 09:26:49.307059 [INFO] raft: pipelining replication to peer {Voter server-c995a658-761f-cec0-34f2-6c75d317cc78 c995a658-761f-cec0-34f2-6c75d317cc78} +testLoggerAdapter verbose: cluster: 09:26:49.307259 [INFO] Starting stability test for raft state: Leader +testLoggerAdapter verbose: cluster: 09:26:49.412589 [INFO] Stable state for Leader reached at 2021-07-03 09:26:49.307330776 +0000 UTC m=+1.178443339 (1 nodes), 1.163µs from start of poll, 277.22003ms from cluster start. Timeout at 2021-07-03 09:26:49.412450177 +0000 UTC m=+1.283562679, 105.11934ms after stability +testLoggerAdapter verbose: cluster: 09:26:49.412647 [INFO] Starting stability test for raft state: Leader +testLoggerAdapter verbose: cluster: 09:26:49.517883 [INFO] Stable state for Leader reached at 2021-07-03 09:26:49.41267624 +0000 UTC m=+1.283788803 (1 nodes), 963ns from start of poll, 382.565494ms from cluster start. Timeout at 2021-07-03 09:26:49.517799667 +0000 UTC m=+1.388912263, 105.12346ms after stability +testLoggerAdapter verbose: 37d85294-4840-ea4e-3912-8d05a98cc527: 09:26:49.517980 [INFO] raft: Updating configuration with RemoveServer (76e15a93-b29c-de2c-f9e0-801b1a90373e, ) to [{Suffrage:Voter ID:37d85294-4840-ea4e-3912-8d05a98cc527 Address:37d85294-4840-ea4e-3912-8d05a98cc527} {Suffrage:Voter ID:server-c995a658-761f-cec0-34f2-6c75d317cc78 Address:c995a658-761f-cec0-34f2-6c75d317cc78}] +testLoggerAdapter verbose: 37d85294-4840-ea4e-3912-8d05a98cc527: 09:26:49.518071 [INFO] raft: Removed peer 76e15a93-b29c-de2c-f9e0-801b1a90373e, stopping replication after 4 +testLoggerAdapter verbose: 37d85294-4840-ea4e-3912-8d05a98cc527: 09:26:49.518140 [INFO] raft: aborting pipeline replication to peer {Voter 76e15a93-b29c-de2c-f9e0-801b1a90373e 76e15a93-b29c-de2c-f9e0-801b1a90373e} +testLoggerAdapter verbose: 37d85294-4840-ea4e-3912-8d05a98cc527: 09:26:49.518319 [INFO] raft: aborting pipeline replication to peer {Voter server-c995a658-761f-cec0-34f2-6c75d317cc78 c995a658-761f-cec0-34f2-6c75d317cc78} +--- PASS: TestRaft_ProtocolVersion_Upgrade_2_3 (0.49s) + raft_test.go:97: cluster: 09:26:49.030090 [DEBUG] Fully Connecting + raft_test.go:97: 37d85294-4840-ea4e-3912-8d05a98cc527: 09:26:49.030243 [INFO] raft: Initial configuration (index=1): [{Suffrage:Voter ID:37d85294-4840-ea4e-3912-8d05a98cc527 Address:37d85294-4840-ea4e-3912-8d05a98cc527} {Suffrage:Voter ID:76e15a93-b29c-de2c-f9e0-801b1a90373e Address:76e15a93-b29c-de2c-f9e0-801b1a90373e}] + raft_test.go:97: 76e15a93-b29c-de2c-f9e0-801b1a90373e: 09:26:49.030350 [INFO] raft: Initial configuration (index=1): [{Suffrage:Voter ID:37d85294-4840-ea4e-3912-8d05a98cc527 Address:37d85294-4840-ea4e-3912-8d05a98cc527} {Suffrage:Voter ID:76e15a93-b29c-de2c-f9e0-801b1a90373e Address:76e15a93-b29c-de2c-f9e0-801b1a90373e}] + raft_test.go:97: cluster: 09:26:49.030380 [INFO] Starting stability test for raft state: Follower + raft_test.go:97: 37d85294-4840-ea4e-3912-8d05a98cc527: 09:26:49.030383 [INFO] raft: Node at 37d85294-4840-ea4e-3912-8d05a98cc527 [Follower] entering Follower state (Leader: "") + raft_test.go:97: 76e15a93-b29c-de2c-f9e0-801b1a90373e: 09:26:49.030416 [INFO] raft: Node at 76e15a93-b29c-de2c-f9e0-801b1a90373e [Follower] entering Follower state (Leader: "") + raft_test.go:97: 37d85294-4840-ea4e-3912-8d05a98cc527: 09:26:49.094835 [WARN] raft: Heartbeat timeout from "" reached, starting election + raft_test.go:97: 37d85294-4840-ea4e-3912-8d05a98cc527: 09:26:49.094952 [INFO] raft: Node at 37d85294-4840-ea4e-3912-8d05a98cc527 [Candidate] entering Candidate state in term 2 + raft_test.go:97: 37d85294-4840-ea4e-3912-8d05a98cc527: 09:26:49.095017 [DEBUG] raft: Votes needed: 2 + raft_test.go:97: 37d85294-4840-ea4e-3912-8d05a98cc527: 09:26:49.095042 [DEBUG] raft: Vote granted from 37d85294-4840-ea4e-3912-8d05a98cc527 in term 2. Tally: 1 + raft_test.go:97: cluster: 09:26:49.095096 [DEBUG] Resetting stability timeout + raft_test.go:97: cluster: 09:26:49.095183 [DEBUG] Resetting stability timeout + raft_test.go:97: 37d85294-4840-ea4e-3912-8d05a98cc527: 09:26:49.095109 [DEBUG] raft: Vote granted from 76e15a93-b29c-de2c-f9e0-801b1a90373e in term 2. Tally: 2 + raft_test.go:97: 37d85294-4840-ea4e-3912-8d05a98cc527: 09:26:49.095291 [INFO] raft: Election won. Tally: 2 + raft_test.go:97: 37d85294-4840-ea4e-3912-8d05a98cc527: 09:26:49.095374 [INFO] raft: Node at 37d85294-4840-ea4e-3912-8d05a98cc527 [Leader] entering Leader state + raft_test.go:97: 37d85294-4840-ea4e-3912-8d05a98cc527: 09:26:49.095449 [INFO] raft: Added peer 76e15a93-b29c-de2c-f9e0-801b1a90373e, starting replication + raft_test.go:97: cluster: 09:26:49.095468 [DEBUG] Resetting stability timeout + raft_test.go:97: 37d85294-4840-ea4e-3912-8d05a98cc527: 09:26:49.095638 [INFO] raft: pipelining replication to peer {Voter 76e15a93-b29c-de2c-f9e0-801b1a90373e 76e15a93-b29c-de2c-f9e0-801b1a90373e} + raft_test.go:97: cluster: 09:26:49.200735 [INFO] Stable state for Follower reached at 2021-07-03 09:26:49.095488592 +0000 UTC m=+0.966601107 (1 nodes), 65.095054ms from start of poll, 65.377798ms from cluster start. Timeout at 2021-07-03 09:26:49.200608037 +0000 UTC m=+1.071720628, 105.119521ms after stability + raft_test.go:97: cluster: 09:26:49.201053 [DEBUG] Fully Connecting + raft_test.go:97: server-c995a658-761f-cec0-34f2-6c75d317cc78: 09:26:49.201172 [INFO] raft: Initial configuration (index=0): [] + raft_test.go:97: cluster: 09:26:49.201241 [DEBUG] Fully Connecting + raft_test.go:97: cluster: 09:26:49.201295 [INFO] Starting stability test for raft state: Leader + raft_test.go:97: server-c995a658-761f-cec0-34f2-6c75d317cc78: 09:26:49.201329 [INFO] raft: Node at c995a658-761f-cec0-34f2-6c75d317cc78 [Follower] entering Follower state (Leader: "") + raft_test.go:97: server-c995a658-761f-cec0-34f2-6c75d317cc78: 09:26:49.260886 [WARN] raft: no known peers, aborting election + raft_test.go:97: cluster: 09:26:49.306625 [INFO] Stable state for Leader reached at 2021-07-03 09:26:49.201330486 +0000 UTC m=+1.072443060 (1 nodes), 1.148µs from start of poll, 171.219751ms from cluster start. Timeout at 2021-07-03 09:26:49.306507393 +0000 UTC m=+1.177620009, 105.176949ms after stability + raft_test.go:97: 37d85294-4840-ea4e-3912-8d05a98cc527: 09:26:49.306761 [INFO] raft: Updating configuration with AddStaging (server-c995a658-761f-cec0-34f2-6c75d317cc78, c995a658-761f-cec0-34f2-6c75d317cc78) to [{Suffrage:Voter ID:37d85294-4840-ea4e-3912-8d05a98cc527 Address:37d85294-4840-ea4e-3912-8d05a98cc527} {Suffrage:Voter ID:76e15a93-b29c-de2c-f9e0-801b1a90373e Address:76e15a93-b29c-de2c-f9e0-801b1a90373e} {Suffrage:Voter ID:server-c995a658-761f-cec0-34f2-6c75d317cc78 Address:c995a658-761f-cec0-34f2-6c75d317cc78}] + raft_test.go:97: 37d85294-4840-ea4e-3912-8d05a98cc527: 09:26:49.306855 [INFO] raft: Added peer server-c995a658-761f-cec0-34f2-6c75d317cc78, starting replication + raft_test.go:97: server-c995a658-761f-cec0-34f2-6c75d317cc78: 09:26:49.306935 [WARN] raft: Failed to get previous log: 3 log not found (last: 0) + raft_test.go:97: 37d85294-4840-ea4e-3912-8d05a98cc527: 09:26:49.306969 [WARN] raft: AppendEntries to {Voter server-c995a658-761f-cec0-34f2-6c75d317cc78 c995a658-761f-cec0-34f2-6c75d317cc78} rejected, sending older logs (next: 1) + raft_test.go:97: 37d85294-4840-ea4e-3912-8d05a98cc527: 09:26:49.307059 [INFO] raft: pipelining replication to peer {Voter server-c995a658-761f-cec0-34f2-6c75d317cc78 c995a658-761f-cec0-34f2-6c75d317cc78} + raft_test.go:97: cluster: 09:26:49.307259 [INFO] Starting stability test for raft state: Leader + raft_test.go:97: cluster: 09:26:49.412589 [INFO] Stable state for Leader reached at 2021-07-03 09:26:49.307330776 +0000 UTC m=+1.178443339 (1 nodes), 1.163µs from start of poll, 277.22003ms from cluster start. Timeout at 2021-07-03 09:26:49.412450177 +0000 UTC m=+1.283562679, 105.11934ms after stability + raft_test.go:97: cluster: 09:26:49.412647 [INFO] Starting stability test for raft state: Leader + raft_test.go:97: cluster: 09:26:49.517883 [INFO] Stable state for Leader reached at 2021-07-03 09:26:49.41267624 +0000 UTC m=+1.283788803 (1 nodes), 963ns from start of poll, 382.565494ms from cluster start. Timeout at 2021-07-03 09:26:49.517799667 +0000 UTC m=+1.388912263, 105.12346ms after stability + raft_test.go:97: 37d85294-4840-ea4e-3912-8d05a98cc527: 09:26:49.517980 [INFO] raft: Updating configuration with RemoveServer (76e15a93-b29c-de2c-f9e0-801b1a90373e, ) to [{Suffrage:Voter ID:37d85294-4840-ea4e-3912-8d05a98cc527 Address:37d85294-4840-ea4e-3912-8d05a98cc527} {Suffrage:Voter ID:server-c995a658-761f-cec0-34f2-6c75d317cc78 Address:c995a658-761f-cec0-34f2-6c75d317cc78}] + raft_test.go:97: 37d85294-4840-ea4e-3912-8d05a98cc527: 09:26:49.518071 [INFO] raft: Removed peer 76e15a93-b29c-de2c-f9e0-801b1a90373e, stopping replication after 4 + raft_test.go:97: 37d85294-4840-ea4e-3912-8d05a98cc527: 09:26:49.518140 [INFO] raft: aborting pipeline replication to peer {Voter 76e15a93-b29c-de2c-f9e0-801b1a90373e 76e15a93-b29c-de2c-f9e0-801b1a90373e} + raft_test.go:97: 37d85294-4840-ea4e-3912-8d05a98cc527: 09:26:49.518319 [INFO] raft: aborting pipeline replication to peer {Voter server-c995a658-761f-cec0-34f2-6c75d317cc78 c995a658-761f-cec0-34f2-6c75d317cc78} === RUN TestTCPTransport_BadAddr --- PASS: TestTCPTransport_BadAddr (0.00s) === RUN TestTCPTransport_WithAdvertise @@ -1286,7 +1320,7 @@ === RUN TestBackoff --- PASS: TestBackoff (0.00s) PASS -ok github.com/hashicorp/raft 1.435s +ok github.com/hashicorp/raft 1.412s ? github.com/hashicorp/raft/bench [no test files] create-stamp debian/debhelper-build-stamp fakeroot debian/rules binary @@ -1316,12 +1350,14 @@ dpkg-source --after-build . dpkg-buildpackage: info: binary-only upload (no source included) I: copying local configuration +I: user script /srv/workspace/pbuilder/16591/tmp/hooks/B01_cleanup starting +I: user script /srv/workspace/pbuilder/16591/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/53500 and its subdirectories -I: Current time: Fri Aug 5 03:48:57 -12 2022 -I: pbuilder-time-stamp: 1659714537 +I: removing directory /srv/workspace/pbuilder/16591 and its subdirectories +I: Current time: Sat Jul 3 23:26:53 +14 2021 +I: pbuilder-time-stamp: 1625304413