Skip to content

Instantly share code, notes, and snippets.

@systay
Created June 18, 2021 05:55
Show Gist options
  • Star 0 You must be signed in to star a gist
  • Fork 0 You must be signed in to fork a gist
  • Save systay/35275ed8337a8c7a2e9dbc4cbd8c3053 to your computer and use it in GitHub Desktop.
Save systay/35275ed8337a8c7a2e9dbc4cbd8c3053 to your computer and use it in GitHub Desktop.
2021-06-18T05:20:15.8665971Z ##[section]Starting: Request a runner to run this job
2021-06-18T05:20:15.8930680Z Can't find any online and idle self-hosted runner in current repository that matches the required labels: 'ubuntu-18.04'
2021-06-18T05:20:15.9163032Z Can't find any online and idle self-hosted runner in current repository's organization account that matches the required labels: 'ubuntu-18.04'
2021-06-18T05:20:15.9737770Z Found online and idle hosted runner in current repository's organization account that matches the required labels: 'ubuntu-18.04'
2021-06-18T05:20:16.0681670Z ##[section]Finishing: Request a runner to run this job
2021-06-18T05:20:21.9347717Z Current runner version: '2.278.0'
2021-06-18T05:20:21.9375285Z ##[group]Operating System
2021-06-18T05:20:21.9376160Z Ubuntu
2021-06-18T05:20:21.9376616Z 18.04.5
2021-06-18T05:20:21.9377051Z LTS
2021-06-18T05:20:21.9377534Z ##[endgroup]
2021-06-18T05:20:21.9378049Z ##[group]Virtual Environment
2021-06-18T05:20:21.9378713Z Environment: ubuntu-18.04
2021-06-18T05:20:21.9379227Z Version: 20210614.1
2021-06-18T05:20:21.9380873Z Included Software: https://github.com/actions/virtual-environments/blob/ubuntu18/20210614.1/images/linux/Ubuntu1804-README.md
2021-06-18T05:20:21.9382281Z Image Release: https://github.com/actions/virtual-environments/releases/tag/ubuntu18%2F20210614.1
2021-06-18T05:20:21.9383138Z ##[endgroup]
2021-06-18T05:20:21.9385255Z ##[group]GITHUB_TOKEN Permissions
2021-06-18T05:20:21.9386833Z Actions: read
2021-06-18T05:20:21.9387592Z Checks: read
2021-06-18T05:20:21.9388228Z Contents: read
2021-06-18T05:20:21.9388814Z Deployments: read
2021-06-18T05:20:21.9389564Z Discussions: read
2021-06-18T05:20:21.9390579Z Issues: read
2021-06-18T05:20:21.9391408Z Metadata: read
2021-06-18T05:20:21.9392088Z Packages: read
2021-06-18T05:20:21.9392633Z PullRequests: read
2021-06-18T05:20:21.9393214Z RepositoryProjects: read
2021-06-18T05:20:21.9393868Z SecurityEvents: read
2021-06-18T05:20:21.9394380Z Statuses: read
2021-06-18T05:20:21.9395026Z ##[endgroup]
2021-06-18T05:20:21.9397958Z Prepare workflow directory
2021-06-18T05:20:22.0160911Z Prepare all required actions
2021-06-18T05:20:22.0172328Z Getting action download info
2021-06-18T05:20:22.4742354Z Download action repository 'actions/setup-go@v1'
2021-06-18T05:20:24.8197861Z Download action repository 'actions/checkout@v2'
2021-06-18T05:20:25.3433636Z ##[group]Run actions/setup-go@v1
2021-06-18T05:20:25.3434366Z with:
2021-06-18T05:20:25.3434915Z go-version: 1.15
2021-06-18T05:20:25.3436044Z ##[endgroup]
2021-06-18T05:20:27.5767838Z ##[group]Run echo '1024 65535' | sudo tee -a /proc/sys/net/ipv4/ip_local_port_range
2021-06-18T05:20:27.5768673Z echo '1024 65535' | sudo tee -a /proc/sys/net/ipv4/ip_local_port_range
2021-06-18T05:20:27.5804734Z shell: /bin/bash -e {0}
2021-06-18T05:20:27.5805088Z env:
2021-06-18T05:20:27.5805652Z GOROOT: /opt/hostedtoolcache/go/1.15.13/x64
2021-06-18T05:20:27.5806073Z ##[endgroup]
2021-06-18T05:20:27.6543828Z 1024 65535
2021-06-18T05:20:27.6602787Z ##[group]Run echo -e "$(ip addr show eth0 | grep "inet\b" | awk '{print $2}' | cut -d/ -f1)\t$(hostname -f) $(hostname -s)" | sudo tee -a /etc/hosts
2021-06-18T05:20:27.6605010Z echo -e "$(ip addr show eth0 | grep "inet\b" | awk '{print $2}' | cut -d/ -f1)\t$(hostname -f) $(hostname -s)" | sudo tee -a /etc/hosts
2021-06-18T05:20:27.6637120Z shell: /bin/bash -e {0}
2021-06-18T05:20:27.6637632Z env:
2021-06-18T05:20:27.6638065Z GOROOT: /opt/hostedtoolcache/go/1.15.13/x64
2021-06-18T05:20:27.6638501Z ##[endgroup]
2021-06-18T05:20:27.6804477Z 10.1.0.11 fv-az122-46.zf1tlrj3kn4expqppa1j4mpycf.xx.internal.cloudapp.net fv-az122-46
2021-06-18T05:20:27.6940873Z ##[group]Run actions/checkout@v2
2021-06-18T05:20:27.6941334Z with:
2021-06-18T05:20:27.6941714Z repository: vitessio/vitess
2021-06-18T05:20:27.6942571Z token: ***
2021-06-18T05:20:27.6943074Z ssh-strict: true
2021-06-18T05:20:27.6943526Z persist-credentials: true
2021-06-18T05:20:27.6943956Z clean: true
2021-06-18T05:20:27.6944292Z fetch-depth: 1
2021-06-18T05:20:27.6944640Z lfs: false
2021-06-18T05:20:27.6944970Z submodules: false
2021-06-18T05:20:27.6945311Z env:
2021-06-18T05:20:27.6945710Z GOROOT: /opt/hostedtoolcache/go/1.15.13/x64
2021-06-18T05:20:27.6946150Z ##[endgroup]
2021-06-18T05:20:27.8099190Z Syncing repository: vitessio/vitess
2021-06-18T05:20:27.8162277Z ##[group]Getting Git version info
2021-06-18T05:20:27.8163641Z Working directory is '/home/runner/work/vitess/vitess'
2021-06-18T05:20:27.8255660Z [command]/usr/bin/git version
2021-06-18T05:20:27.9815832Z git version 2.32.0
2021-06-18T05:20:27.9847017Z ##[endgroup]
2021-06-18T05:20:27.9855322Z Deleting the contents of '/home/runner/work/vitess/vitess'
2021-06-18T05:20:27.9860891Z ##[group]Initializing the repository
2021-06-18T05:20:27.9868325Z [command]/usr/bin/git init /home/runner/work/vitess/vitess
2021-06-18T05:20:28.0812289Z hint: Using 'master' as the name for the initial branch. This default branch name
2021-06-18T05:20:28.0815025Z hint: is subject to change. To configure the initial branch name to use in all
2021-06-18T05:20:28.0817113Z hint: of your new repositories, which will suppress this warning, call:
2021-06-18T05:20:28.0818019Z hint:
2021-06-18T05:20:28.0820226Z hint: git config --global init.defaultBranch <name>
2021-06-18T05:20:28.0821244Z hint:
2021-06-18T05:20:28.0822415Z hint: Names commonly chosen instead of 'master' are 'main', 'trunk' and
2021-06-18T05:20:28.0823823Z hint: 'development'. The just-created branch can be renamed via this command:
2021-06-18T05:20:28.0827181Z hint:
2021-06-18T05:20:28.0828628Z hint: git branch -m <name>
2021-06-18T05:20:28.0863239Z Initialized empty Git repository in /home/runner/work/vitess/vitess/.git/
2021-06-18T05:20:28.0864813Z [command]/usr/bin/git remote add origin https://github.com/vitessio/vitess
2021-06-18T05:20:28.1018583Z ##[endgroup]
2021-06-18T05:20:28.1019450Z ##[group]Disabling automatic garbage collection
2021-06-18T05:20:28.1021078Z [command]/usr/bin/git config --local gc.auto 0
2021-06-18T05:20:28.1134106Z ##[endgroup]
2021-06-18T05:20:28.1137583Z ##[group]Setting up auth
2021-06-18T05:20:28.1142956Z [command]/usr/bin/git config --local --name-only --get-regexp core\.sshCommand
2021-06-18T05:20:28.1183784Z [command]/usr/bin/git submodule foreach --recursive git config --local --name-only --get-regexp 'core\.sshCommand' && git config --local --unset-all 'core.sshCommand' || :
2021-06-18T05:20:28.3659008Z [command]/usr/bin/git config --local --name-only --get-regexp http\.https\:\/\/github\.com\/\.extraheader
2021-06-18T05:20:28.3718504Z [command]/usr/bin/git submodule foreach --recursive git config --local --name-only --get-regexp 'http\.https\:\/\/github\.com\/\.extraheader' && git config --local --unset-all 'http.https://github.com/.extraheader' || :
2021-06-18T05:20:28.3994787Z [command]/usr/bin/git config --local http.https://github.com/.extraheader AUTHORIZATION: basic ***
2021-06-18T05:20:28.4072359Z ##[endgroup]
2021-06-18T05:20:28.4073611Z ##[group]Fetching the repository
2021-06-18T05:20:28.4085516Z [command]/usr/bin/git -c protocol.version=2 fetch --no-tags --prune --progress --no-recurse-submodules --depth=1 origin +a0393f03f17e708f7bab38fcca05008ff4c08564:refs/remotes/pull/8325/merge
2021-06-18T05:20:29.0585960Z remote: Enumerating objects: 4243, done.
2021-06-18T05:20:29.0591086Z remote: Counting objects: 0% (1/4243)
2021-06-18T05:20:29.0594069Z remote: Counting objects: 1% (43/4243)
2021-06-18T05:20:29.0601369Z remote: Counting objects: 2% (85/4243)
2021-06-18T05:20:29.0609763Z remote: Counting objects: 3% (128/4243)
2021-06-18T05:20:29.0610674Z remote: Counting objects: 4% (170/4243)
2021-06-18T05:20:29.0611325Z remote: Counting objects: 5% (213/4243)
2021-06-18T05:20:29.0611914Z remote: Counting objects: 6% (255/4243)
2021-06-18T05:20:29.0612573Z remote: Counting objects: 7% (298/4243)
2021-06-18T05:20:29.0613238Z remote: Counting objects: 8% (340/4243)
2021-06-18T05:20:29.0613946Z remote: Counting objects: 9% (382/4243)
2021-06-18T05:20:29.0614547Z remote: Counting objects: 10% (425/4243)
2021-06-18T05:20:29.0615127Z remote: Counting objects: 11% (467/4243)
2021-06-18T05:20:29.0615723Z remote: Counting objects: 12% (510/4243)
2021-06-18T05:20:29.0616305Z remote: Counting objects: 13% (552/4243)
2021-06-18T05:20:29.0616903Z remote: Counting objects: 14% (595/4243)
2021-06-18T05:20:29.0617586Z remote: Counting objects: 15% (637/4243)
2021-06-18T05:20:29.0618186Z remote: Counting objects: 16% (679/4243)
2021-06-18T05:20:29.0618790Z remote: Counting objects: 17% (722/4243)
2021-06-18T05:20:29.0621224Z remote: Counting objects: 18% (764/4243)
2021-06-18T05:20:29.0621841Z remote: Counting objects: 19% (807/4243)
2021-06-18T05:20:29.0622570Z remote: Counting objects: 20% (849/4243)
2021-06-18T05:20:29.0623152Z remote: Counting objects: 21% (892/4243)
2021-06-18T05:20:29.0635088Z remote: Counting objects: 22% (934/4243)
2021-06-18T05:20:29.0635742Z remote: Counting objects: 23% (976/4243)
2021-06-18T05:20:29.0636526Z remote: Counting objects: 24% (1019/4243)
2021-06-18T05:20:29.0637101Z remote: Counting objects: 25% (1061/4243)
2021-06-18T05:20:29.0637691Z remote: Counting objects: 26% (1104/4243)
2021-06-18T05:20:29.0638724Z remote: Counting objects: 27% (1146/4243)
2021-06-18T05:20:29.0649071Z remote: Counting objects: 28% (1189/4243)
2021-06-18T05:20:29.0649816Z remote: Counting objects: 29% (1231/4243)
2021-06-18T05:20:29.0650572Z remote: Counting objects: 30% (1273/4243)
2021-06-18T05:20:29.0652467Z remote: Counting objects: 31% (1316/4243)
2021-06-18T05:20:29.0661759Z remote: Counting objects: 32% (1358/4243)
2021-06-18T05:20:29.0664604Z remote: Counting objects: 33% (1401/4243)
2021-06-18T05:20:29.0665146Z remote: Counting objects: 34% (1443/4243)
2021-06-18T05:20:29.0665872Z remote: Counting objects: 35% (1486/4243)
2021-06-18T05:20:29.0666604Z remote: Counting objects: 36% (1528/4243)
2021-06-18T05:20:29.0667211Z remote: Counting objects: 37% (1570/4243)
2021-06-18T05:20:29.0667817Z remote: Counting objects: 38% (1613/4243)
2021-06-18T05:20:29.0668399Z remote: Counting objects: 39% (1655/4243)
2021-06-18T05:20:29.0668996Z remote: Counting objects: 40% (1698/4243)
2021-06-18T05:20:29.0669739Z remote: Counting objects: 41% (1740/4243)
2021-06-18T05:20:29.0670611Z remote: Counting objects: 42% (1783/4243)
2021-06-18T05:20:29.0671114Z remote: Counting objects: 43% (1825/4243)
2021-06-18T05:20:29.0671630Z remote: Counting objects: 44% (1867/4243)
2021-06-18T05:20:29.0672354Z remote: Counting objects: 45% (1910/4243)
2021-06-18T05:20:29.0672863Z remote: Counting objects: 46% (1952/4243)
2021-06-18T05:20:29.0673390Z remote: Counting objects: 47% (1995/4243)
2021-06-18T05:20:29.0674124Z remote: Counting objects: 48% (2037/4243)
2021-06-18T05:20:29.0675025Z remote: Counting objects: 49% (2080/4243)
2021-06-18T05:20:29.0675964Z remote: Counting objects: 50% (2122/4243)
2021-06-18T05:20:29.0676566Z remote: Counting objects: 51% (2164/4243)
2021-06-18T05:20:29.0677150Z remote: Counting objects: 52% (2207/4243)
2021-06-18T05:20:29.0677753Z remote: Counting objects: 53% (2249/4243)
2021-06-18T05:20:29.0678350Z remote: Counting objects: 54% (2292/4243)
2021-06-18T05:20:29.0678933Z remote: Counting objects: 55% (2334/4243)
2021-06-18T05:20:29.0679709Z remote: Counting objects: 56% (2377/4243)
2021-06-18T05:20:29.0680327Z remote: Counting objects: 57% (2419/4243)
2021-06-18T05:20:29.0680934Z remote: Counting objects: 58% (2461/4243)
2021-06-18T05:20:29.0681523Z remote: Counting objects: 59% (2504/4243)
2021-06-18T05:20:29.0682125Z remote: Counting objects: 60% (2546/4243)
2021-06-18T05:20:29.0682708Z remote: Counting objects: 61% (2589/4243)
2021-06-18T05:20:29.0683344Z remote: Counting objects: 62% (2631/4243)
2021-06-18T05:20:29.0683946Z remote: Counting objects: 63% (2674/4243)
2021-06-18T05:20:29.0684531Z remote: Counting objects: 64% (2716/4243)
2021-06-18T05:20:29.0685129Z remote: Counting objects: 65% (2758/4243)
2021-06-18T05:20:29.0685719Z remote: Counting objects: 66% (2801/4243)
2021-06-18T05:20:29.0686321Z remote: Counting objects: 67% (2843/4243)
2021-06-18T05:20:29.0686910Z remote: Counting objects: 68% (2886/4243)
2021-06-18T05:20:29.0687512Z remote: Counting objects: 69% (2928/4243)
2021-06-18T05:20:29.0688197Z remote: Counting objects: 70% (2971/4243)
2021-06-18T05:20:29.0688803Z remote: Counting objects: 71% (3013/4243)
2021-06-18T05:20:29.0689410Z remote: Counting objects: 72% (3055/4243)
2021-06-18T05:20:29.0689996Z remote: Counting objects: 73% (3098/4243)
2021-06-18T05:20:29.0690668Z remote: Counting objects: 74% (3140/4243)
2021-06-18T05:20:29.0691260Z remote: Counting objects: 75% (3183/4243)
2021-06-18T05:20:29.0691869Z remote: Counting objects: 76% (3225/4243)
2021-06-18T05:20:29.0692470Z remote: Counting objects: 77% (3268/4243)
2021-06-18T05:20:29.0693105Z remote: Counting objects: 78% (3310/4243)
2021-06-18T05:20:29.0693707Z remote: Counting objects: 79% (3352/4243)
2021-06-18T05:20:29.0694293Z remote: Counting objects: 80% (3395/4243)
2021-06-18T05:20:29.0694897Z remote: Counting objects: 81% (3437/4243)
2021-06-18T05:20:29.0695561Z remote: Counting objects: 82% (3480/4243)
2021-06-18T05:20:29.0696161Z remote: Counting objects: 83% (3522/4243)
2021-06-18T05:20:29.0696747Z remote: Counting objects: 84% (3565/4243)
2021-06-18T05:20:29.0697347Z remote: Counting objects: 85% (3607/4243)
2021-06-18T05:20:29.0697947Z remote: Counting objects: 86% (3649/4243)
2021-06-18T05:20:29.0698530Z remote: Counting objects: 87% (3692/4243)
2021-06-18T05:20:29.0699131Z remote: Counting objects: 88% (3734/4243)
2021-06-18T05:20:29.0699898Z remote: Counting objects: 89% (3777/4243)
2021-06-18T05:20:29.0702158Z remote: Counting objects: 90% (3819/4243)
2021-06-18T05:20:29.0702819Z remote: Counting objects: 91% (3862/4243)
2021-06-18T05:20:29.0703428Z remote: Counting objects: 92% (3904/4243)
2021-06-18T05:20:29.0704015Z remote: Counting objects: 93% (3946/4243)
2021-06-18T05:20:29.0704629Z remote: Counting objects: 94% (3989/4243)
2021-06-18T05:20:29.0705240Z remote: Counting objects: 95% (4031/4243)
2021-06-18T05:20:29.0705835Z remote: Counting objects: 96% (4074/4243)
2021-06-18T05:20:29.0706435Z remote: Counting objects: 97% (4116/4243)
2021-06-18T05:20:29.0707038Z remote: Counting objects: 98% (4159/4243)
2021-06-18T05:20:29.0707622Z remote: Counting objects: 99% (4201/4243)
2021-06-18T05:20:29.0708224Z remote: Counting objects: 100% (4243/4243)
2021-06-18T05:20:29.0708838Z remote: Counting objects: 100% (4243/4243), done.
2021-06-18T05:20:29.0725498Z remote: Compressing objects: 0% (1/3622)
2021-06-18T05:20:29.0886385Z remote: Compressing objects: 1% (37/3622)
2021-06-18T05:20:29.0937956Z remote: Compressing objects: 2% (73/3622)
2021-06-18T05:20:29.0995044Z remote: Compressing objects: 3% (109/3622)
2021-06-18T05:20:29.1030488Z remote: Compressing objects: 4% (145/3622)
2021-06-18T05:20:29.1082474Z remote: Compressing objects: 5% (182/3622)
2021-06-18T05:20:29.1168878Z remote: Compressing objects: 6% (218/3622)
2021-06-18T05:20:29.1198448Z remote: Compressing objects: 7% (254/3622)
2021-06-18T05:20:29.1201214Z remote: Compressing objects: 8% (290/3622)
2021-06-18T05:20:29.1214243Z remote: Compressing objects: 9% (326/3622)
2021-06-18T05:20:29.1296527Z remote: Compressing objects: 10% (363/3622)
2021-06-18T05:20:29.1303855Z remote: Compressing objects: 11% (399/3622)
2021-06-18T05:20:29.1310774Z remote: Compressing objects: 12% (435/3622)
2021-06-18T05:20:29.1426732Z remote: Compressing objects: 13% (471/3622)
2021-06-18T05:20:29.1427418Z remote: Compressing objects: 14% (508/3622)
2021-06-18T05:20:29.1460682Z remote: Compressing objects: 15% (544/3622)
2021-06-18T05:20:29.1499918Z remote: Compressing objects: 16% (580/3622)
2021-06-18T05:20:29.1600847Z remote: Compressing objects: 17% (616/3622)
2021-06-18T05:20:29.1708775Z remote: Compressing objects: 18% (652/3622)
2021-06-18T05:20:29.1780038Z remote: Compressing objects: 19% (689/3622)
2021-06-18T05:20:29.1916995Z remote: Compressing objects: 20% (725/3622)
2021-06-18T05:20:29.2017645Z remote: Compressing objects: 21% (761/3622)
2021-06-18T05:20:29.2104828Z remote: Compressing objects: 22% (797/3622)
2021-06-18T05:20:29.2232729Z remote: Compressing objects: 23% (834/3622)
2021-06-18T05:20:29.2313499Z remote: Compressing objects: 24% (870/3622)
2021-06-18T05:20:29.2394228Z remote: Compressing objects: 25% (906/3622)
2021-06-18T05:20:29.2583302Z remote: Compressing objects: 26% (942/3622)
2021-06-18T05:20:29.2699990Z remote: Compressing objects: 27% (978/3622)
2021-06-18T05:20:29.2929646Z remote: Compressing objects: 28% (1015/3622)
2021-06-18T05:20:29.3074233Z remote: Compressing objects: 29% (1051/3622)
2021-06-18T05:20:29.3220285Z remote: Compressing objects: 30% (1087/3622)
2021-06-18T05:20:29.3357639Z remote: Compressing objects: 31% (1123/3622)
2021-06-18T05:20:29.3451591Z remote: Compressing objects: 32% (1160/3622)
2021-06-18T05:20:29.3536952Z remote: Compressing objects: 33% (1196/3622)
2021-06-18T05:20:29.3621227Z remote: Compressing objects: 34% (1232/3622)
2021-06-18T05:20:29.3768825Z remote: Compressing objects: 35% (1268/3622)
2021-06-18T05:20:29.3900307Z remote: Compressing objects: 36% (1304/3622)
2021-06-18T05:20:29.4007960Z remote: Compressing objects: 37% (1341/3622)
2021-06-18T05:20:29.4127723Z remote: Compressing objects: 38% (1377/3622)
2021-06-18T05:20:29.4261084Z remote: Compressing objects: 39% (1413/3622)
2021-06-18T05:20:29.4364263Z remote: Compressing objects: 40% (1449/3622)
2021-06-18T05:20:29.4447256Z remote: Compressing objects: 41% (1486/3622)
2021-06-18T05:20:29.4553300Z remote: Compressing objects: 42% (1522/3622)
2021-06-18T05:20:29.4682113Z remote: Compressing objects: 43% (1558/3622)
2021-06-18T05:20:29.4797787Z remote: Compressing objects: 44% (1594/3622)
2021-06-18T05:20:29.4909382Z remote: Compressing objects: 45% (1630/3622)
2021-06-18T05:20:29.5031965Z remote: Compressing objects: 46% (1667/3622)
2021-06-18T05:20:29.5160975Z remote: Compressing objects: 47% (1703/3622)
2021-06-18T05:20:29.5319578Z remote: Compressing objects: 48% (1739/3622)
2021-06-18T05:20:29.5394973Z remote: Compressing objects: 49% (1775/3622)
2021-06-18T05:20:29.5506534Z remote: Compressing objects: 50% (1811/3622)
2021-06-18T05:20:29.5595414Z remote: Compressing objects: 51% (1848/3622)
2021-06-18T05:20:29.5780213Z remote: Compressing objects: 52% (1884/3622)
2021-06-18T05:20:29.5854183Z remote: Compressing objects: 53% (1920/3622)
2021-06-18T05:20:29.6044330Z remote: Compressing objects: 54% (1956/3622)
2021-06-18T05:20:29.6159474Z remote: Compressing objects: 55% (1993/3622)
2021-06-18T05:20:29.6247926Z remote: Compressing objects: 56% (2029/3622)
2021-06-18T05:20:29.6368031Z remote: Compressing objects: 57% (2065/3622)
2021-06-18T05:20:29.6492141Z remote: Compressing objects: 58% (2101/3622)
2021-06-18T05:20:29.6558806Z remote: Compressing objects: 59% (2137/3622)
2021-06-18T05:20:29.6681515Z remote: Compressing objects: 60% (2174/3622)
2021-06-18T05:20:29.6762877Z remote: Compressing objects: 61% (2210/3622)
2021-06-18T05:20:29.6906009Z remote: Compressing objects: 62% (2246/3622)
2021-06-18T05:20:29.7012669Z remote: Compressing objects: 63% (2282/3622)
2021-06-18T05:20:29.7187046Z remote: Compressing objects: 64% (2319/3622)
2021-06-18T05:20:29.7314381Z remote: Compressing objects: 65% (2355/3622)
2021-06-18T05:20:29.7482562Z remote: Compressing objects: 66% (2391/3622)
2021-06-18T05:20:29.7511182Z remote: Compressing objects: 67% (2427/3622)
2021-06-18T05:20:29.7577621Z remote: Compressing objects: 68% (2463/3622)
2021-06-18T05:20:29.7635507Z remote: Compressing objects: 69% (2500/3622)
2021-06-18T05:20:29.7760359Z remote: Compressing objects: 70% (2536/3622)
2021-06-18T05:20:29.8327372Z remote: Compressing objects: 71% (2572/3622)
2021-06-18T05:20:29.8329694Z remote: Compressing objects: 72% (2608/3622)
2021-06-18T05:20:29.8341520Z remote: Compressing objects: 73% (2645/3622)
2021-06-18T05:20:29.8350297Z remote: Compressing objects: 74% (2681/3622)
2021-06-18T05:20:29.8371815Z remote: Compressing objects: 75% (2717/3622)
2021-06-18T05:20:29.8402092Z remote: Compressing objects: 76% (2753/3622)
2021-06-18T05:20:29.8415134Z remote: Compressing objects: 77% (2789/3622)
2021-06-18T05:20:29.8431439Z remote: Compressing objects: 78% (2826/3622)
2021-06-18T05:20:29.8567140Z remote: Compressing objects: 79% (2862/3622)
2021-06-18T05:20:29.8736944Z remote: Compressing objects: 80% (2898/3622)
2021-06-18T05:20:29.8845295Z remote: Compressing objects: 81% (2934/3622)
2021-06-18T05:20:29.8922686Z remote: Compressing objects: 82% (2971/3622)
2021-06-18T05:20:29.8958170Z remote: Compressing objects: 83% (3007/3622)
2021-06-18T05:20:29.8962693Z remote: Compressing objects: 84% (3043/3622)
2021-06-18T05:20:29.8965353Z remote: Compressing objects: 85% (3079/3622)
2021-06-18T05:20:29.8967949Z remote: Compressing objects: 86% (3115/3622)
2021-06-18T05:20:29.8971628Z remote: Compressing objects: 87% (3152/3622)
2021-06-18T05:20:29.8973425Z remote: Compressing objects: 88% (3188/3622)
2021-06-18T05:20:29.8976743Z remote: Compressing objects: 89% (3224/3622)
2021-06-18T05:20:29.8988416Z remote: Compressing objects: 90% (3260/3622)
2021-06-18T05:20:29.8989079Z remote: Compressing objects: 91% (3297/3622)
2021-06-18T05:20:29.8989669Z remote: Compressing objects: 92% (3333/3622)
2021-06-18T05:20:29.8991028Z remote: Compressing objects: 93% (3369/3622)
2021-06-18T05:20:29.8991561Z remote: Compressing objects: 94% (3405/3622)
2021-06-18T05:20:29.8997009Z remote: Compressing objects: 95% (3441/3622)
2021-06-18T05:20:29.8997686Z remote: Compressing objects: 96% (3478/3622)
2021-06-18T05:20:29.9041842Z remote: Compressing objects: 97% (3514/3622)
2021-06-18T05:20:29.9043468Z remote: Compressing objects: 98% (3550/3622)
2021-06-18T05:20:29.9044034Z remote: Compressing objects: 99% (3586/3622)
2021-06-18T05:20:29.9044581Z remote: Compressing objects: 100% (3622/3622)
2021-06-18T05:20:29.9045126Z remote: Compressing objects: 100% (3622/3622), done.
2021-06-18T05:20:29.9212799Z Receiving objects: 0% (1/4243)
2021-06-18T05:20:29.9218043Z Receiving objects: 1% (43/4243)
2021-06-18T05:20:29.9241125Z Receiving objects: 2% (85/4243)
2021-06-18T05:20:29.9646037Z Receiving objects: 3% (128/4243)
2021-06-18T05:20:29.9778522Z Receiving objects: 4% (170/4243)
2021-06-18T05:20:29.9806699Z Receiving objects: 5% (213/4243)
2021-06-18T05:20:29.9819542Z Receiving objects: 6% (255/4243)
2021-06-18T05:20:29.9829950Z Receiving objects: 7% (298/4243)
2021-06-18T05:20:29.9879187Z Receiving objects: 8% (340/4243)
2021-06-18T05:20:29.9882273Z Receiving objects: 9% (382/4243)
2021-06-18T05:20:29.9886197Z Receiving objects: 10% (425/4243)
2021-06-18T05:20:29.9929120Z Receiving objects: 11% (467/4243)
2021-06-18T05:20:29.9949771Z Receiving objects: 12% (510/4243)
2021-06-18T05:20:29.9981766Z Receiving objects: 13% (552/4243)
2021-06-18T05:20:29.9995862Z Receiving objects: 14% (595/4243)
2021-06-18T05:20:30.0016208Z Receiving objects: 15% (637/4243)
2021-06-18T05:20:30.0042128Z Receiving objects: 16% (679/4243)
2021-06-18T05:20:30.0054584Z Receiving objects: 17% (722/4243)
2021-06-18T05:20:30.0073537Z Receiving objects: 18% (764/4243)
2021-06-18T05:20:30.0097162Z Receiving objects: 19% (807/4243)
2021-06-18T05:20:30.0148537Z Receiving objects: 20% (849/4243)
2021-06-18T05:20:30.0186237Z Receiving objects: 21% (892/4243)
2021-06-18T05:20:30.0261168Z Receiving objects: 22% (934/4243)
2021-06-18T05:20:30.0261725Z Receiving objects: 23% (976/4243)
2021-06-18T05:20:30.0263987Z Receiving objects: 24% (1019/4243)
2021-06-18T05:20:30.0283584Z Receiving objects: 25% (1061/4243)
2021-06-18T05:20:30.0294486Z Receiving objects: 26% (1104/4243)
2021-06-18T05:20:30.0297257Z Receiving objects: 27% (1146/4243)
2021-06-18T05:20:30.0298369Z Receiving objects: 28% (1189/4243)
2021-06-18T05:20:30.0300854Z Receiving objects: 29% (1231/4243)
2021-06-18T05:20:30.0302926Z Receiving objects: 30% (1273/4243)
2021-06-18T05:20:30.0329680Z Receiving objects: 31% (1316/4243)
2021-06-18T05:20:30.0348321Z Receiving objects: 32% (1358/4243)
2021-06-18T05:20:30.0377872Z Receiving objects: 33% (1401/4243)
2021-06-18T05:20:30.0421301Z Receiving objects: 34% (1443/4243)
2021-06-18T05:20:30.0440919Z Receiving objects: 35% (1486/4243)
2021-06-18T05:20:30.0492206Z Receiving objects: 36% (1528/4243)
2021-06-18T05:20:30.0514747Z Receiving objects: 37% (1570/4243)
2021-06-18T05:20:30.0544634Z Receiving objects: 38% (1613/4243)
2021-06-18T05:20:30.0659382Z Receiving objects: 39% (1655/4243)
2021-06-18T05:20:30.0684470Z Receiving objects: 40% (1698/4243)
2021-06-18T05:20:30.0759114Z Receiving objects: 41% (1740/4243)
2021-06-18T05:20:30.0907346Z Receiving objects: 42% (1783/4243)
2021-06-18T05:20:30.0970148Z Receiving objects: 43% (1825/4243)
2021-06-18T05:20:30.1095549Z Receiving objects: 44% (1867/4243)
2021-06-18T05:20:30.1289397Z Receiving objects: 45% (1910/4243)
2021-06-18T05:20:30.1530243Z Receiving objects: 46% (1952/4243)
2021-06-18T05:20:30.1717646Z Receiving objects: 47% (1995/4243)
2021-06-18T05:20:30.1794408Z Receiving objects: 48% (2037/4243)
2021-06-18T05:20:30.1923204Z Receiving objects: 49% (2080/4243)
2021-06-18T05:20:30.2256638Z Receiving objects: 50% (2122/4243)
2021-06-18T05:20:30.2286793Z Receiving objects: 51% (2164/4243)
2021-06-18T05:20:30.2301574Z Receiving objects: 52% (2207/4243)
2021-06-18T05:20:30.2309451Z Receiving objects: 53% (2249/4243)
2021-06-18T05:20:30.2321322Z Receiving objects: 54% (2292/4243)
2021-06-18T05:20:30.2346564Z Receiving objects: 55% (2334/4243)
2021-06-18T05:20:30.2400285Z Receiving objects: 56% (2377/4243)
2021-06-18T05:20:30.2439442Z Receiving objects: 57% (2419/4243)
2021-06-18T05:20:30.2454542Z Receiving objects: 58% (2461/4243)
2021-06-18T05:20:30.2557434Z Receiving objects: 59% (2504/4243)
2021-06-18T05:20:30.2703007Z Receiving objects: 60% (2546/4243)
2021-06-18T05:20:30.8718021Z Receiving objects: 61% (2589/4243)
2021-06-18T05:20:30.8727032Z Receiving objects: 62% (2631/4243), 4.35 MiB | 4.97 MiB/s
2021-06-18T05:20:30.8761324Z Receiving objects: 63% (2674/4243), 4.35 MiB | 4.97 MiB/s
2021-06-18T05:20:30.8799039Z Receiving objects: 64% (2716/4243), 4.35 MiB | 4.97 MiB/s
2021-06-18T05:20:30.8839037Z Receiving objects: 65% (2758/4243), 4.35 MiB | 4.97 MiB/s
2021-06-18T05:20:30.8867052Z Receiving objects: 66% (2801/4243), 4.35 MiB | 4.97 MiB/s
2021-06-18T05:20:30.8897719Z Receiving objects: 67% (2843/4243), 4.35 MiB | 4.97 MiB/s
2021-06-18T05:20:30.8927175Z Receiving objects: 68% (2886/4243), 4.35 MiB | 4.97 MiB/s
2021-06-18T05:20:30.8957531Z Receiving objects: 69% (2928/4243), 4.35 MiB | 4.97 MiB/s
2021-06-18T05:20:30.8987742Z Receiving objects: 70% (2971/4243), 4.35 MiB | 4.97 MiB/s
2021-06-18T05:20:30.9019284Z Receiving objects: 71% (3013/4243), 4.35 MiB | 4.97 MiB/s
2021-06-18T05:20:30.9057797Z Receiving objects: 72% (3055/4243), 4.35 MiB | 4.97 MiB/s
2021-06-18T05:20:30.9101138Z Receiving objects: 73% (3098/4243), 4.35 MiB | 4.97 MiB/s
2021-06-18T05:20:30.9134518Z Receiving objects: 74% (3140/4243), 4.35 MiB | 4.97 MiB/s
2021-06-18T05:20:30.9148491Z Receiving objects: 75% (3183/4243), 4.35 MiB | 4.97 MiB/s
2021-06-18T05:20:30.9167968Z Receiving objects: 75% (3195/4243), 4.35 MiB | 4.97 MiB/s
2021-06-18T05:20:30.9201217Z Receiving objects: 76% (3225/4243), 4.35 MiB | 4.97 MiB/s
2021-06-18T05:20:30.9273198Z Receiving objects: 77% (3268/4243), 4.35 MiB | 4.97 MiB/s
2021-06-18T05:20:30.9350558Z Receiving objects: 78% (3310/4243), 4.35 MiB | 4.97 MiB/s
2021-06-18T05:20:30.9460944Z Receiving objects: 79% (3352/4243), 4.35 MiB | 4.97 MiB/s
2021-06-18T05:20:30.9540475Z Receiving objects: 80% (3395/4243), 4.35 MiB | 4.97 MiB/s
2021-06-18T05:20:30.9617043Z Receiving objects: 81% (3437/4243), 4.35 MiB | 4.97 MiB/s
2021-06-18T05:20:30.9664114Z Receiving objects: 82% (3480/4243), 4.35 MiB | 4.97 MiB/s
2021-06-18T05:20:30.9692275Z Receiving objects: 83% (3522/4243), 4.35 MiB | 4.97 MiB/s
2021-06-18T05:20:30.9757868Z Receiving objects: 84% (3565/4243), 4.35 MiB | 4.97 MiB/s
2021-06-18T05:20:30.9889820Z Receiving objects: 85% (3607/4243), 4.35 MiB | 4.97 MiB/s
2021-06-18T05:20:30.9917132Z Receiving objects: 86% (3649/4243), 4.35 MiB | 4.97 MiB/s
2021-06-18T05:20:31.7355478Z Receiving objects: 87% (3692/4243), 4.35 MiB | 4.97 MiB/s
2021-06-18T05:20:31.7364446Z Receiving objects: 88% (3734/4243), 8.43 MiB | 5.21 MiB/s
2021-06-18T05:20:31.7468910Z Receiving objects: 89% (3777/4243), 8.43 MiB | 5.21 MiB/s
2021-06-18T05:20:31.7529411Z Receiving objects: 90% (3819/4243), 8.43 MiB | 5.21 MiB/s
2021-06-18T05:20:31.7640796Z Receiving objects: 91% (3862/4243), 8.43 MiB | 5.21 MiB/s
2021-06-18T05:20:31.7653629Z Receiving objects: 92% (3904/4243), 8.43 MiB | 5.21 MiB/s
2021-06-18T05:20:31.7663709Z Receiving objects: 93% (3946/4243), 8.43 MiB | 5.21 MiB/s
2021-06-18T05:20:31.7827545Z Receiving objects: 94% (3989/4243), 8.43 MiB | 5.21 MiB/s
2021-06-18T05:20:31.7831574Z Receiving objects: 95% (4031/4243), 8.43 MiB | 5.21 MiB/s
2021-06-18T05:20:31.8194338Z Receiving objects: 96% (4074/4243), 8.43 MiB | 5.21 MiB/s
2021-06-18T05:20:31.8775816Z Receiving objects: 97% (4116/4243), 8.43 MiB | 5.21 MiB/s
2021-06-18T05:20:31.8777495Z remote: Total 4243 (delta 848), reused 1628 (delta 339), pack-reused 0
2021-06-18T05:20:31.8790624Z Receiving objects: 98% (4159/4243), 8.43 MiB | 5.21 MiB/s
2021-06-18T05:20:31.8803439Z Receiving objects: 99% (4201/4243), 8.43 MiB | 5.21 MiB/s
2021-06-18T05:20:31.8804339Z Receiving objects: 100% (4243/4243), 8.43 MiB | 5.21 MiB/s
2021-06-18T05:20:31.8805882Z Receiving objects: 100% (4243/4243), 18.38 MiB | 9.35 MiB/s, done.
2021-06-18T05:20:31.8807906Z Resolving deltas: 0% (0/848)
2021-06-18T05:20:31.8809206Z Resolving deltas: 1% (9/848)
2021-06-18T05:20:31.8810717Z Resolving deltas: 2% (17/848)
2021-06-18T05:20:31.8812037Z Resolving deltas: 3% (26/848)
2021-06-18T05:20:31.8812762Z Resolving deltas: 4% (34/848)
2021-06-18T05:20:31.8814225Z Resolving deltas: 5% (43/848)
2021-06-18T05:20:31.8815665Z Resolving deltas: 6% (51/848)
2021-06-18T05:20:31.8816394Z Resolving deltas: 7% (60/848)
2021-06-18T05:20:31.8818045Z Resolving deltas: 8% (68/848)
2021-06-18T05:20:31.8819397Z Resolving deltas: 9% (77/848)
2021-06-18T05:20:31.8824329Z Resolving deltas: 10% (85/848)
2021-06-18T05:20:31.8824784Z Resolving deltas: 11% (94/848)
2021-06-18T05:20:31.8825204Z Resolving deltas: 12% (102/848)
2021-06-18T05:20:31.8825612Z Resolving deltas: 13% (111/848)
2021-06-18T05:20:31.8826025Z Resolving deltas: 14% (119/848)
2021-06-18T05:20:31.8827537Z Resolving deltas: 15% (128/848)
2021-06-18T05:20:31.8828132Z Resolving deltas: 16% (136/848)
2021-06-18T05:20:31.8828667Z Resolving deltas: 17% (145/848)
2021-06-18T05:20:31.8829202Z Resolving deltas: 18% (153/848)
2021-06-18T05:20:31.8831120Z Resolving deltas: 19% (162/848)
2021-06-18T05:20:31.8831698Z Resolving deltas: 20% (170/848)
2021-06-18T05:20:31.8832244Z Resolving deltas: 21% (179/848)
2021-06-18T05:20:31.8832763Z Resolving deltas: 22% (187/848)
2021-06-18T05:20:31.8833286Z Resolving deltas: 23% (196/848)
2021-06-18T05:20:31.8834694Z Resolving deltas: 24% (204/848)
2021-06-18T05:20:31.8835558Z Resolving deltas: 25% (212/848)
2021-06-18T05:20:31.8837250Z Resolving deltas: 26% (221/848)
2021-06-18T05:20:31.8841370Z Resolving deltas: 27% (229/848)
2021-06-18T05:20:31.8843618Z Resolving deltas: 28% (238/848)
2021-06-18T05:20:31.8846093Z Resolving deltas: 29% (246/848)
2021-06-18T05:20:31.8846873Z Resolving deltas: 30% (255/848)
2021-06-18T05:20:31.8849048Z Resolving deltas: 31% (263/848)
2021-06-18T05:20:31.8849773Z Resolving deltas: 32% (272/848)
2021-06-18T05:20:31.8851359Z Resolving deltas: 33% (280/848)
2021-06-18T05:20:31.8853141Z Resolving deltas: 34% (289/848)
2021-06-18T05:20:31.8856023Z Resolving deltas: 35% (297/848)
2021-06-18T05:20:31.8860558Z Resolving deltas: 36% (306/848)
2021-06-18T05:20:31.8864406Z Resolving deltas: 37% (314/848)
2021-06-18T05:20:31.8868149Z Resolving deltas: 38% (323/848)
2021-06-18T05:20:31.8872018Z Resolving deltas: 39% (331/848)
2021-06-18T05:20:31.8875790Z Resolving deltas: 40% (340/848)
2021-06-18T05:20:31.8877267Z Resolving deltas: 41% (348/848)
2021-06-18T05:20:31.8881038Z Resolving deltas: 42% (357/848)
2021-06-18T05:20:31.8886193Z Resolving deltas: 43% (365/848)
2021-06-18T05:20:31.8892649Z Resolving deltas: 44% (374/848)
2021-06-18T05:20:31.8897990Z Resolving deltas: 45% (382/848)
2021-06-18T05:20:31.8900516Z Resolving deltas: 46% (391/848)
2021-06-18T05:20:31.8901345Z Resolving deltas: 47% (399/848)
2021-06-18T05:20:31.8902039Z Resolving deltas: 48% (408/848)
2021-06-18T05:20:31.8903428Z Resolving deltas: 49% (416/848)
2021-06-18T05:20:31.8904195Z Resolving deltas: 50% (424/848)
2021-06-18T05:20:31.8907944Z Resolving deltas: 51% (433/848)
2021-06-18T05:20:31.8913331Z Resolving deltas: 52% (441/848)
2021-06-18T05:20:31.8916576Z Resolving deltas: 53% (450/848)
2021-06-18T05:20:31.8941639Z Resolving deltas: 54% (458/848)
2021-06-18T05:20:31.8942434Z Resolving deltas: 55% (467/848)
2021-06-18T05:20:31.8943125Z Resolving deltas: 56% (475/848)
2021-06-18T05:20:31.8945372Z Resolving deltas: 57% (484/848)
2021-06-18T05:20:31.8946198Z Resolving deltas: 58% (492/848)
2021-06-18T05:20:31.8947028Z Resolving deltas: 59% (501/848)
2021-06-18T05:20:31.8951487Z Resolving deltas: 60% (509/848)
2021-06-18T05:20:31.8966533Z Resolving deltas: 61% (518/848)
2021-06-18T05:20:31.9016748Z Resolving deltas: 62% (526/848)
2021-06-18T05:20:31.9446733Z Resolving deltas: 63% (535/848)
2021-06-18T05:20:31.9447629Z Resolving deltas: 64% (543/848)
2021-06-18T05:20:31.9448546Z Resolving deltas: 65% (552/848)
2021-06-18T05:20:31.9449101Z Resolving deltas: 66% (560/848)
2021-06-18T05:20:31.9449658Z Resolving deltas: 67% (569/848)
2021-06-18T05:20:31.9450199Z Resolving deltas: 68% (577/848)
2021-06-18T05:20:31.9450756Z Resolving deltas: 69% (586/848)
2021-06-18T05:20:31.9451306Z Resolving deltas: 70% (594/848)
2021-06-18T05:20:31.9451850Z Resolving deltas: 71% (603/848)
2021-06-18T05:20:31.9452405Z Resolving deltas: 72% (611/848)
2021-06-18T05:20:31.9452946Z Resolving deltas: 73% (620/848)
2021-06-18T05:20:31.9453500Z Resolving deltas: 74% (628/848)
2021-06-18T05:20:31.9454056Z Resolving deltas: 75% (636/848)
2021-06-18T05:20:31.9454796Z Resolving deltas: 76% (645/848)
2021-06-18T05:20:31.9455429Z Resolving deltas: 77% (653/848)
2021-06-18T05:20:31.9455970Z Resolving deltas: 78% (662/848)
2021-06-18T05:20:31.9456533Z Resolving deltas: 79% (670/848)
2021-06-18T05:20:31.9457087Z Resolving deltas: 80% (679/848)
2021-06-18T05:20:31.9457632Z Resolving deltas: 81% (687/848)
2021-06-18T05:20:31.9458187Z Resolving deltas: 82% (696/848)
2021-06-18T05:20:31.9458726Z Resolving deltas: 83% (704/848)
2021-06-18T05:20:31.9459283Z Resolving deltas: 84% (713/848)
2021-06-18T05:20:31.9460071Z Resolving deltas: 85% (721/848)
2021-06-18T05:20:31.9460507Z Resolving deltas: 86% (730/848)
2021-06-18T05:20:31.9460947Z Resolving deltas: 87% (738/848)
2021-06-18T05:20:31.9461372Z Resolving deltas: 88% (747/848)
2021-06-18T05:20:31.9461815Z Resolving deltas: 89% (755/848)
2021-06-18T05:20:31.9462241Z Resolving deltas: 90% (764/848)
2021-06-18T05:20:31.9462680Z Resolving deltas: 91% (772/848)
2021-06-18T05:20:31.9463106Z Resolving deltas: 92% (781/848)
2021-06-18T05:20:31.9463558Z Resolving deltas: 93% (789/848)
2021-06-18T05:20:31.9464132Z Resolving deltas: 94% (798/848)
2021-06-18T05:20:31.9464554Z Resolving deltas: 95% (806/848)
2021-06-18T05:20:31.9464991Z Resolving deltas: 96% (815/848)
2021-06-18T05:20:31.9465415Z Resolving deltas: 97% (823/848)
2021-06-18T05:20:31.9465855Z Resolving deltas: 98% (832/848)
2021-06-18T05:20:31.9466279Z Resolving deltas: 99% (840/848)
2021-06-18T05:20:31.9466717Z Resolving deltas: 100% (848/848)
2021-06-18T05:20:31.9467167Z Resolving deltas: 100% (848/848), done.
2021-06-18T05:20:32.0403141Z From https://github.com/vitessio/vitess
2021-06-18T05:20:32.0404850Z * [new ref] a0393f03f17e708f7bab38fcca05008ff4c08564 -> pull/8325/merge
2021-06-18T05:20:32.0426743Z ##[endgroup]
2021-06-18T05:20:32.0427478Z ##[group]Determining the checkout info
2021-06-18T05:20:32.0430785Z ##[endgroup]
2021-06-18T05:20:32.0431371Z ##[group]Checking out the ref
2021-06-18T05:20:32.0436792Z [command]/usr/bin/git checkout --progress --force refs/remotes/pull/8325/merge
2021-06-18T05:20:32.4624037Z Note: switching to 'refs/remotes/pull/8325/merge'.
2021-06-18T05:20:32.4624433Z
2021-06-18T05:20:32.4625451Z You are in 'detached HEAD' state. You can look around, make experimental
2021-06-18T05:20:32.4626240Z changes and commit them, and you can discard any commits you make in this
2021-06-18T05:20:32.4626975Z state without impacting any branches by switching back to a branch.
2021-06-18T05:20:32.4636734Z
2021-06-18T05:20:32.4637322Z If you want to create a new branch to retain commits you create, you may
2021-06-18T05:20:32.4638358Z do so (now or later) by using -c with the switch command. Example:
2021-06-18T05:20:32.4638727Z
2021-06-18T05:20:32.4639276Z git switch -c <new-branch-name>
2021-06-18T05:20:32.4639584Z
2021-06-18T05:20:32.4640760Z Or undo this operation with:
2021-06-18T05:20:32.4641568Z
2021-06-18T05:20:32.4642224Z git switch -
2021-06-18T05:20:32.4642514Z
2021-06-18T05:20:32.4643294Z Turn off this advice by setting config variable advice.detachedHead to false
2021-06-18T05:20:32.4643886Z
2021-06-18T05:20:32.4644996Z HEAD is now at a0393f0 Merge f267c165b13bfe812fcb6191d82e424b9ce0cb8d into bd5bb8c0c98e2e6c7a04add9fedeac12c320c603
2021-06-18T05:20:32.4646936Z ##[endgroup]
2021-06-18T05:20:32.4695951Z [command]/usr/bin/git log -1 --format='%H'
2021-06-18T05:20:32.4730798Z 'a0393f03f17e708f7bab38fcca05008ff4c08564'
2021-06-18T05:20:32.4827766Z ##[group]Run sudo apt-get update
2021-06-18T05:20:32.4828271Z sudo apt-get update
2021-06-18T05:20:32.4828903Z sudo apt-get install -y mysql-server mysql-client make unzip g++ etcd curl git wget eatmydata
2021-06-18T05:20:32.4829532Z sudo service mysql stop
2021-06-18T05:20:32.4829915Z sudo service etcd stop
2021-06-18T05:20:32.4830477Z sudo ln -s /etc/apparmor.d/usr.sbin.mysqld /etc/apparmor.d/disable/
2021-06-18T05:20:32.4831155Z sudo apparmor_parser -R /etc/apparmor.d/usr.sbin.mysqld
2021-06-18T05:20:32.4831832Z go mod download
2021-06-18T05:20:32.4832347Z 
2021-06-18T05:20:32.4833490Z wget https://repo.percona.com/apt/percona-release_latest.$(lsb_release -sc)_all.deb
2021-06-18T05:20:32.4834375Z sudo apt-get install -y gnupg2
2021-06-18T05:20:32.4835063Z sudo dpkg -i percona-release_latest.$(lsb_release -sc)_all.deb
2021-06-18T05:20:32.4835902Z sudo apt-get update
2021-06-18T05:20:32.4836815Z sudo apt-get install percona-xtrabackup-24
2021-06-18T05:20:32.4872109Z shell: /bin/bash -e {0}
2021-06-18T05:20:32.4872444Z env:
2021-06-18T05:20:32.4872835Z GOROOT: /opt/hostedtoolcache/go/1.15.13/x64
2021-06-18T05:20:32.4873262Z ##[endgroup]
2021-06-18T05:20:32.7387575Z Hit:1 http://azure.archive.ubuntu.com/ubuntu bionic InRelease
2021-06-18T05:20:32.7389622Z Get:2 http://azure.archive.ubuntu.com/ubuntu bionic-updates InRelease [88.7 kB]
2021-06-18T05:20:32.7391048Z Get:3 http://azure.archive.ubuntu.com/ubuntu bionic-backports InRelease [74.6 kB]
2021-06-18T05:20:32.8031370Z Get:4 http://security.ubuntu.com/ubuntu bionic-security InRelease [88.7 kB]
2021-06-18T05:20:32.9391699Z Hit:5 http://ppa.launchpad.net/ondrej/php/ubuntu bionic InRelease
2021-06-18T05:20:32.9554227Z Get:6 https://packages.microsoft.com/ubuntu/18.04/prod bionic InRelease [4003 B]
2021-06-18T05:20:33.0809217Z Get:7 http://azure.archive.ubuntu.com/ubuntu bionic-updates/main amd64 Packages [2099 kB]
2021-06-18T05:20:33.1386990Z Get:8 http://azure.archive.ubuntu.com/ubuntu bionic-updates/universe amd64 Packages [1736 kB]
2021-06-18T05:20:33.2157934Z Hit:9 http://ppa.launchpad.net/ubuntu-toolchain-r/test/ubuntu bionic InRelease
2021-06-18T05:20:33.5328293Z Get:10 https://packages.microsoft.com/ubuntu/18.04/prod bionic/main amd64 Packages [192 kB]
2021-06-18T05:20:33.5532963Z Get:11 http://security.ubuntu.com/ubuntu bionic-security/main amd64 Packages [1753 kB]
2021-06-18T05:20:33.9623384Z Get:12 http://security.ubuntu.com/ubuntu bionic-security/main Translation-en [326 kB]
2021-06-18T05:20:33.9708478Z Get:13 http://security.ubuntu.com/ubuntu bionic-security/universe amd64 Packages [1128 kB]
2021-06-18T05:20:40.0961010Z Fetched 7489 kB in 2s (4079 kB/s)
2021-06-18T05:20:41.1341286Z Reading package lists...
2021-06-18T05:20:41.2439538Z Reading package lists...
2021-06-18T05:20:41.4033354Z Building dependency tree...
2021-06-18T05:20:41.4044859Z Reading state information...
2021-06-18T05:20:41.5434820Z eatmydata is already the newest version (105-6).
2021-06-18T05:20:41.5435635Z make is already the newest version (4.1-9.1ubuntu1).
2021-06-18T05:20:41.5436151Z make set to manually installed.
2021-06-18T05:20:41.5436869Z curl is already the newest version (7.58.0-2ubuntu3.13).
2021-06-18T05:20:41.5437590Z g++ is already the newest version (4:7.4.0-1ubuntu2.3).
2021-06-18T05:20:41.5439890Z g++ set to manually installed.
2021-06-18T05:20:41.5441040Z mysql-client is already the newest version (5.7.34-0ubuntu0.18.04.1).
2021-06-18T05:20:41.5442428Z mysql-server is already the newest version (5.7.34-0ubuntu0.18.04.1).
2021-06-18T05:20:41.5443261Z unzip is already the newest version (6.0-21ubuntu1.1).
2021-06-18T05:20:41.5443990Z wget is already the newest version (1.19.4-1ubuntu2.2).
2021-06-18T05:20:41.5444757Z git is already the newest version (1:2.32.0-1~ppa0~ubuntu18.04.1).
2021-06-18T05:20:41.5445397Z The following additional packages will be installed:
2021-06-18T05:20:41.5446461Z etcd-client etcd-server pipexec
2021-06-18T05:20:42.3211367Z The following NEW packages will be installed:
2021-06-18T05:20:42.3224109Z etcd etcd-client etcd-server pipexec
2021-06-18T05:20:42.3226671Z 0 upgraded, 4 newly installed, 0 to remove and 40 not upgraded.
2021-06-18T05:20:42.3227272Z Need to get 12.4 MB of archives.
2021-06-18T05:20:42.3228026Z After this operation, 52.2 MB of additional disk space will be used.
2021-06-18T05:20:42.3229179Z Get:1 http://azure.archive.ubuntu.com/ubuntu bionic/universe amd64 pipexec amd64 2.5.5-1 [16.8 kB]
2021-06-18T05:20:42.3230446Z Get:2 http://azure.archive.ubuntu.com/ubuntu bionic/universe amd64 etcd-client amd64 3.2.17+dfsg-1 [8137 kB]
2021-06-18T05:20:42.5042945Z Get:3 http://azure.archive.ubuntu.com/ubuntu bionic/universe amd64 etcd-server amd64 3.2.17+dfsg-1 [4285 kB]
2021-06-18T05:20:42.7621270Z Get:4 http://azure.archive.ubuntu.com/ubuntu bionic/universe amd64 etcd all 3.2.17+dfsg-1 [2516 B]
2021-06-18T05:20:43.2646878Z Fetched 12.4 MB in 1s (10.8 MB/s)
2021-06-18T05:20:43.3678937Z Selecting previously unselected package pipexec.
2021-06-18T05:20:43.4975184Z (Reading database ...
2021-06-18T05:20:43.4975809Z (Reading database ... 5%
2021-06-18T05:20:43.4976269Z (Reading database ... 10%
2021-06-18T05:20:43.4977018Z (Reading database ... 15%
2021-06-18T05:20:43.4977431Z (Reading database ... 20%
2021-06-18T05:20:43.4978135Z (Reading database ... 25%
2021-06-18T05:20:43.4978521Z (Reading database ... 30%
2021-06-18T05:20:43.4978892Z (Reading database ... 35%
2021-06-18T05:20:43.4979282Z (Reading database ... 40%
2021-06-18T05:20:43.4979942Z (Reading database ... 45%
2021-06-18T05:20:43.4980361Z (Reading database ... 50%
2021-06-18T05:20:44.3358226Z (Reading database ... 55%
2021-06-18T05:20:45.1230713Z (Reading database ... 60%
2021-06-18T05:20:45.8573204Z (Reading database ... 65%
2021-06-18T05:20:46.5337001Z (Reading database ... 70%
2021-06-18T05:20:47.2551117Z (Reading database ... 75%
2021-06-18T05:20:48.2780993Z (Reading database ... 80%
2021-06-18T05:20:49.1399605Z (Reading database ... 85%
2021-06-18T05:20:50.0131809Z (Reading database ... 90%
2021-06-18T05:20:51.0413974Z (Reading database ... 95%
2021-06-18T05:20:51.0414638Z (Reading database ... 100%
2021-06-18T05:20:51.0416046Z (Reading database ... 269073 files and directories currently installed.)
2021-06-18T05:20:51.0604294Z Preparing to unpack .../pipexec_2.5.5-1_amd64.deb ...
2021-06-18T05:20:51.0632250Z Unpacking pipexec (2.5.5-1) ...
2021-06-18T05:20:51.1477428Z Selecting previously unselected package etcd-client.
2021-06-18T05:20:51.1734143Z Preparing to unpack .../etcd-client_3.2.17+dfsg-1_amd64.deb ...
2021-06-18T05:20:51.1752713Z Unpacking etcd-client (3.2.17+dfsg-1) ...
2021-06-18T05:20:52.0021953Z Selecting previously unselected package etcd-server.
2021-06-18T05:20:52.0262739Z Preparing to unpack .../etcd-server_3.2.17+dfsg-1_amd64.deb ...
2021-06-18T05:20:52.0281009Z Unpacking etcd-server (3.2.17+dfsg-1) ...
2021-06-18T05:20:52.5062120Z Selecting previously unselected package etcd.
2021-06-18T05:20:52.5332228Z Preparing to unpack .../etcd_3.2.17+dfsg-1_all.deb ...
2021-06-18T05:20:52.5354730Z Unpacking etcd (3.2.17+dfsg-1) ...
2021-06-18T05:20:52.6002078Z Setting up pipexec (2.5.5-1) ...
2021-06-18T05:20:52.6062560Z Setting up etcd-client (3.2.17+dfsg-1) ...
2021-06-18T05:20:52.6121131Z Setting up etcd-server (3.2.17+dfsg-1) ...
2021-06-18T05:20:52.7010156Z Adding system user `etcd' (UID 115) ...
2021-06-18T05:20:52.7014688Z Adding new group `etcd' (GID 122) ...
2021-06-18T05:20:52.7226725Z Adding new user `etcd' (UID 115) with group `etcd' ...
2021-06-18T05:20:52.8464793Z Creating home directory `/var/lib/etcd/' ...
2021-06-18T05:20:53.4585457Z Setting up etcd (3.2.17+dfsg-1) ...
2021-06-18T05:20:53.4646289Z Processing triggers for systemd (237-3ubuntu10.47) ...
2021-06-18T05:20:53.6369377Z Processing triggers for man-db (2.8.3-2ubuntu0.1) ...
2021-06-18T05:20:55.1499615Z Processing triggers for ureadahead (0.100.0-21) ...
2021-06-18T05:21:15.3431099Z --2021-06-18 05:21:15-- https://repo.percona.com/apt/percona-release_latest.bionic_all.deb
2021-06-18T05:21:15.5285775Z Resolving repo.percona.com (repo.percona.com)... 167.71.118.3, 157.245.119.64, 167.99.233.229
2021-06-18T05:21:15.5524853Z Connecting to repo.percona.com (repo.percona.com)|167.71.118.3|:443... connected.
2021-06-18T05:21:15.6277472Z HTTP request sent, awaiting response... 200 OK
2021-06-18T05:21:15.6279369Z Length: 11766 (11K) [application/x-debian-package]
2021-06-18T05:21:15.6284804Z Saving to: ‘percona-release_latest.bionic_all.deb’
2021-06-18T05:21:15.6285250Z
2021-06-18T05:21:15.6287495Z 0K .......... . 100% 193M=0s
2021-06-18T05:21:15.6287856Z
2021-06-18T05:21:15.6290255Z 2021-06-18 05:21:15 (193 MB/s) - ‘percona-release_latest.bionic_all.deb’ saved [11766/11766]
2021-06-18T05:21:15.6290695Z
2021-06-18T05:21:15.7026698Z Reading package lists...
2021-06-18T05:21:15.8814132Z Building dependency tree...
2021-06-18T05:21:15.8829608Z Reading state information...
2021-06-18T05:21:16.0904552Z gnupg2 is already the newest version (2.2.4-1ubuntu1.4).
2021-06-18T05:21:16.0905891Z 0 upgraded, 0 newly installed, 0 to remove and 40 not upgraded.
2021-06-18T05:21:16.2046265Z Selecting previously unselected package percona-release.
2021-06-18T05:21:16.3078472Z (Reading database ... 269231 files and directories currently installed.)
2021-06-18T05:21:16.3237410Z Preparing to unpack percona-release_latest.bionic_all.deb ...
2021-06-18T05:21:16.3274690Z Unpacking percona-release (1.0-26.generic) ...
2021-06-18T05:21:16.3512270Z Setting up percona-release (1.0-26.generic) ...
2021-06-18T05:21:17.3966476Z * Enabling the Percona Original repository
2021-06-18T05:21:17.3982758Z <*> All done!
2021-06-18T05:21:17.3984267Z ==> Please run "apt-get update" to apply changes
2021-06-18T05:21:17.6130855Z * Enabling the Percona Release repository
2021-06-18T05:21:17.6146276Z <*> All done!
2021-06-18T05:21:17.6147841Z ==> Please run "apt-get update" to apply changes
2021-06-18T05:21:17.6178250Z The percona-release package now contains a percona-release script that can enable additional repositories for our newer products.
2021-06-18T05:21:17.6179488Z
2021-06-18T05:21:17.6180817Z For example, to enable the Percona Server 8.0 repository use:
2021-06-18T05:21:17.6181598Z
2021-06-18T05:21:17.6182725Z percona-release setup ps80
2021-06-18T05:21:17.6183548Z
2021-06-18T05:21:17.6186995Z Note: To avoid conflicts with older product versions, the percona-release setup command may disable our original repository for some products.
2021-06-18T05:21:17.6187963Z
2021-06-18T05:21:17.6188510Z For more information, please visit:
2021-06-18T05:21:17.6189704Z https://www.percona.com/doc/percona-repo-config/percona-release.html
2021-06-18T05:21:17.6190568Z
2021-06-18T05:21:17.7410338Z Hit:1 http://azure.archive.ubuntu.com/ubuntu bionic InRelease
2021-06-18T05:21:17.7415366Z Hit:2 http://azure.archive.ubuntu.com/ubuntu bionic-updates InRelease
2021-06-18T05:21:17.7419278Z Hit:3 http://azure.archive.ubuntu.com/ubuntu bionic-backports InRelease
2021-06-18T05:21:17.8644786Z Get:4 http://repo.percona.com/percona/apt bionic InRelease [15.8 kB]
2021-06-18T05:21:17.9077495Z Get:5 http://repo.percona.com/prel/apt bionic InRelease [9780 B]
2021-06-18T05:21:17.9535122Z Hit:6 http://security.ubuntu.com/ubuntu bionic-security InRelease
2021-06-18T05:21:18.0501351Z Hit:7 https://packages.microsoft.com/ubuntu/18.04/prod bionic InRelease
2021-06-18T05:21:18.1303114Z Hit:8 http://ppa.launchpad.net/ondrej/php/ubuntu bionic InRelease
2021-06-18T05:21:18.2047755Z Get:9 http://repo.percona.com/percona/apt bionic/main Sources [6657 B]
2021-06-18T05:21:18.2371247Z Get:10 http://repo.percona.com/percona/apt bionic/main amd64 Packages [27.0 kB]
2021-06-18T05:21:18.3106712Z Get:11 http://repo.percona.com/prel/apt bionic/main amd64 Packages [750 B]
2021-06-18T05:21:18.3932332Z Hit:12 http://ppa.launchpad.net/ubuntu-toolchain-r/test/ubuntu bionic InRelease
2021-06-18T05:21:21.4191221Z Fetched 60.0 kB in 1s (61.3 kB/s)
2021-06-18T05:21:22.4845317Z Reading package lists...
2021-06-18T05:21:22.6027184Z Reading package lists...
2021-06-18T05:21:22.7843108Z Building dependency tree...
2021-06-18T05:21:22.7858786Z Reading state information...
2021-06-18T05:21:22.9336422Z The following additional packages will be installed:
2021-06-18T05:21:22.9341528Z libcurl4-openssl-dev libdbd-mysql-perl libdbi-perl libev4
2021-06-18T05:21:22.9349362Z Suggested packages:
2021-06-18T05:21:22.9350385Z libcurl4-doc libidn11-dev libkrb5-dev libldap2-dev librtmp-dev libssh2-1-dev
2021-06-18T05:21:22.9351743Z libclone-perl libmldbm-perl libnet-daemon-perl libsql-statement-perl
2021-06-18T05:21:22.9744239Z The following NEW packages will be installed:
2021-06-18T05:21:22.9747023Z libcurl4-openssl-dev libdbd-mysql-perl libdbi-perl libev4
2021-06-18T05:21:22.9748943Z percona-xtrabackup-24
2021-06-18T05:21:22.9933529Z 0 upgraded, 5 newly installed, 0 to remove and 40 not upgraded.
2021-06-18T05:21:22.9934166Z Need to get 7750 kB of archives.
2021-06-18T05:21:22.9934804Z After this operation, 40.1 MB of additional disk space will be used.
2021-06-18T05:21:22.9936225Z Get:1 http://azure.archive.ubuntu.com/ubuntu bionic-updates/main amd64 libcurl4-openssl-dev amd64 7.58.0-2ubuntu3.13 [301 kB]
2021-06-18T05:21:23.0034507Z Get:2 http://azure.archive.ubuntu.com/ubuntu bionic-updates/main amd64 libdbi-perl amd64 1.640-1ubuntu0.2 [724 kB]
2021-06-18T05:21:23.0185372Z Get:3 http://azure.archive.ubuntu.com/ubuntu bionic/universe amd64 libdbd-mysql-perl amd64 4.046-1 [82.0 kB]
2021-06-18T05:21:23.0200245Z Get:4 http://azure.archive.ubuntu.com/ubuntu bionic/universe amd64 libev4 amd64 1:4.22-1 [26.3 kB]
2021-06-18T05:21:23.0372640Z Get:5 http://repo.percona.com/percona/apt bionic/main amd64 percona-xtrabackup-24 amd64 2.4.22-1.bionic [6617 kB]
2021-06-18T05:21:23.7957060Z Fetched 7750 kB in 0s (19.3 MB/s)
2021-06-18T05:21:23.8329088Z Selecting previously unselected package libcurl4-openssl-dev:amd64.
2021-06-18T05:21:23.8380308Z (Reading database ...
2021-06-18T05:21:23.8381130Z (Reading database ... 5%
2021-06-18T05:21:23.8381873Z (Reading database ... 10%
2021-06-18T05:21:23.8382597Z (Reading database ... 15%
2021-06-18T05:21:23.8383323Z (Reading database ... 20%
2021-06-18T05:21:23.8383998Z (Reading database ... 25%
2021-06-18T05:21:23.8384647Z (Reading database ... 30%
2021-06-18T05:21:23.8385315Z (Reading database ... 35%
2021-06-18T05:21:23.8386004Z (Reading database ... 40%
2021-06-18T05:21:23.8386685Z (Reading database ... 45%
2021-06-18T05:21:23.8387313Z (Reading database ... 50%
2021-06-18T05:21:23.8410772Z (Reading database ... 55%
2021-06-18T05:21:23.8433117Z (Reading database ... 60%
2021-06-18T05:21:23.8472623Z (Reading database ... 65%
2021-06-18T05:21:23.8542739Z (Reading database ... 70%
2021-06-18T05:21:24.8331094Z (Reading database ... 75%
2021-06-18T05:21:24.8337523Z (Reading database ... 80%
2021-06-18T05:21:24.8338302Z (Reading database ... 85%
2021-06-18T05:21:24.8339001Z (Reading database ... 90%
2021-06-18T05:21:24.8339630Z (Reading database ... 95%
2021-06-18T05:21:24.8341072Z (Reading database ... 100%
2021-06-18T05:21:24.8341872Z (Reading database ... 269236 files and directories currently installed.)
2021-06-18T05:21:24.8343555Z Preparing to unpack .../libcurl4-openssl-dev_7.58.0-2ubuntu3.13_amd64.deb ...
2021-06-18T05:21:24.8345112Z Unpacking libcurl4-openssl-dev:amd64 (7.58.0-2ubuntu3.13) ...
2021-06-18T05:21:24.8346236Z Selecting previously unselected package libdbi-perl.
2021-06-18T05:21:24.8347139Z Preparing to unpack .../libdbi-perl_1.640-1ubuntu0.2_amd64.deb ...
2021-06-18T05:21:24.8348019Z Unpacking libdbi-perl (1.640-1ubuntu0.2) ...
2021-06-18T05:21:24.8348981Z Selecting previously unselected package libdbd-mysql-perl.
2021-06-18T05:21:24.8349939Z Preparing to unpack .../libdbd-mysql-perl_4.046-1_amd64.deb ...
2021-06-18T05:21:24.8350772Z Unpacking libdbd-mysql-perl (4.046-1) ...
2021-06-18T05:21:24.8351403Z Selecting previously unselected package libev4.
2021-06-18T05:21:24.8352271Z Preparing to unpack .../libev4_1%3a4.22-1_amd64.deb ...
2021-06-18T05:21:24.8353124Z Unpacking libev4 (1:4.22-1) ...
2021-06-18T05:21:24.8354091Z Selecting previously unselected package percona-xtrabackup-24.
2021-06-18T05:21:24.8355139Z Preparing to unpack .../percona-xtrabackup-24_2.4.22-1.bionic_amd64.deb ...
2021-06-18T05:21:24.8356123Z Unpacking percona-xtrabackup-24 (2.4.22-1.bionic) ...
2021-06-18T05:21:25.1274186Z Setting up libev4 (1:4.22-1) ...
2021-06-18T05:21:25.1312667Z Setting up libcurl4-openssl-dev:amd64 (7.58.0-2ubuntu3.13) ...
2021-06-18T05:21:25.1348931Z Setting up libdbi-perl (1.640-1ubuntu0.2) ...
2021-06-18T05:21:25.1387345Z Setting up libdbd-mysql-perl (4.046-1) ...
2021-06-18T05:21:25.1495326Z Setting up percona-xtrabackup-24 (2.4.22-1.bionic) ...
2021-06-18T05:21:25.1543095Z Processing triggers for man-db (2.8.3-2ubuntu0.1) ...
2021-06-18T05:21:26.8611292Z Processing triggers for libc-bin (2.27-3ubuntu1.4) ...
2021-06-18T05:21:28.3922427Z ##[group]Run source build.env
2021-06-18T05:21:28.3923073Z source build.env
2021-06-18T05:21:28.3923756Z eatmydata -- go run test.go -docker=false -print-log -follow -shard onlineddl_vrepl_suite
2021-06-18T05:21:28.3955057Z shell: /bin/bash -e {0}
2021-06-18T05:21:28.3955412Z env:
2021-06-18T05:21:28.3955935Z GOROOT: /opt/hostedtoolcache/go/1.15.13/x64
2021-06-18T05:21:28.3956381Z ##[endgroup]
2021-06-18T05:21:36.0031429Z 2021/06/18 05:21:36 Output directory: _test/20210618-052136.5988
2021-06-18T05:21:36.0040345Z 2021/06/18 05:21:36 Running make build...
2021-06-18T05:24:19.8493397Z 2021/06/18 05:24:19 local.onlineddl_vrepl_suite: running (try 1/3)...
2021-06-18T05:24:19.8764460Z running tests for vitess.io/vitess/go/test/endtoend/onlineddl/vrepl_suite
2021-06-18T05:24:38.2375092Z I0618 05:24:38.237163 14561 cluster_process.go:633] Attempting to reserve port: 16001
2021-06-18T05:24:38.2384146Z I0618 05:24:38.238239 14561 cluster_process.go:641] Port 16001 is available, reserving..
2021-06-18T05:24:38.2386219Z I0618 05:24:38.238366 14561 cluster_process.go:475] Created cluster on /home/runner/work/vitess/vitess/vtdataroot/vt_367518308/vtroot_16001. ReusingVTDATAROOT=false
2021-06-18T05:24:38.2388029Z I0618 05:24:38.238422 14561 cluster_process.go:633] Attempting to reserve port: 16002
2021-06-18T05:24:38.2389189Z I0618 05:24:38.238448 14561 cluster_process.go:641] Port 16002 is available, reserving..
2021-06-18T05:24:38.2390115Z I0618 05:24:38.238460 14561 cluster_process.go:633] Attempting to reserve port: 16003
2021-06-18T05:24:38.2391217Z I0618 05:24:38.238475 14561 cluster_process.go:641] Port 16003 is available, reserving..
2021-06-18T05:24:38.2392141Z I0618 05:24:38.238486 14561 cluster_process.go:633] Attempting to reserve port: 16004
2021-06-18T05:24:38.2393298Z I0618 05:24:38.238546 14561 cluster_process.go:641] Port 16004 is available, reserving..
2021-06-18T05:24:38.2394234Z I0618 05:24:38.238567 14561 cluster_process.go:186] Starting topo server etcd2 on port: 16002
2021-06-18T05:24:38.2397778Z E0618 05:24:38.238696 14561 topo_process.go:92] Starting etcd with command: etcd --name global --data-dir /home/runner/work/vitess/vitess/vtdataroot/vt_367518308/vtroot_16001/topo_16002 --listen-client-urls http://localhost:16002 --advertise-client-urls http://localhost:16002 --initial-advertise-peer-urls http://localhost:16004 --listen-peer-urls http://localhost:16004 --initial-cluster global=http://localhost:16004 --enable-v2=true
2021-06-18T05:24:38.5496237Z I0618 05:24:38.549094 14561 cluster_process.go:193] Creating global and cell topo dirs
2021-06-18T05:24:38.5512639Z I0618 05:24:38.550939 14561 vtctl_process.go:55] Adding CellInfo for cell zone1 with command: vtctl -topo_implementation etcd2 -topo_global_server_address localhost:16002 -topo_global_root /vitess/global AddCellInfo -root /zone1 -server_address localhost:16002 zone1
2021-06-18T05:24:38.5945860Z I0618 05:24:38.594193 14561 cluster_process.go:633] Attempting to reserve port: 16005
2021-06-18T05:24:38.5946658Z I0618 05:24:38.594242 14561 cluster_process.go:641] Port 16005 is available, reserving..
2021-06-18T05:24:38.5947355Z I0618 05:24:38.594256 14561 cluster_process.go:633] Attempting to reserve port: 16006
2021-06-18T05:24:38.5948056Z I0618 05:24:38.594279 14561 cluster_process.go:641] Port 16006 is available, reserving..
2021-06-18T05:24:38.5948753Z I0618 05:24:38.594297 14561 cluster_process.go:215] Starting vtctld server on port: 16005
2021-06-18T05:24:38.5953863Z I0618 05:24:38.594414 14561 vtctld_process.go:86] Starting vtctld with command: vtctld -enable_queries -topo_implementation etcd2 -topo_global_server_address localhost:16002 -topo_global_root /vitess/global -cell zone1 -workflow_manager_init -workflow_manager_use_election -service_map grpc-vtctl -backup_storage_implementation file -file_backup_storage_root /home/runner/work/vitess/vitess/vtdataroot/vt_367518308/vtroot_16001/backups -wait_for_drain_sleep_rdonly 1s -wait_for_drain_sleep_replica 1s -online_ddl_check_interval 2s -log_dir /home/runner/work/vitess/vitess/vtdataroot/vt_367518308/vtroot_16001/tmp_16003 -port 16005 -grpc_port 16006 -schema_change_dir /tmp/schema_change_dir_3216 -schema_change_controller local -schema_change_check_interval 1 -online_ddl_check_interval 2s
2021-06-18T05:24:38.8984124Z I0618 05:24:38.898104 14561 cluster_process.go:244] Starting keyspace: ks
2021-06-18T05:24:38.8986682Z I0618 05:24:38.898148 14561 vtctl_process.go:72] Running CreateKeyspace with command: vtctl -topo_implementation etcd2 -topo_global_server_address localhost:16002 -topo_global_root /vitess/global CreateKeyspace ks
2021-06-18T05:24:38.9413057Z I0618 05:24:38.940979 14561 cluster_process.go:253] Starting shard: 1
2021-06-18T05:24:38.9413784Z I0618 05:24:38.940997 14561 cluster_process.go:633] Attempting to reserve port: 16007
2021-06-18T05:24:38.9414904Z I0618 05:24:38.941029 14561 cluster_process.go:641] Port 16007 is available, reserving..
2021-06-18T05:24:38.9416272Z I0618 05:24:38.941046 14561 cluster_process.go:633] Attempting to reserve port: 16008
2021-06-18T05:24:38.9417184Z I0618 05:24:38.941061 14561 cluster_process.go:641] Port 16008 is available, reserving..
2021-06-18T05:24:38.9417919Z I0618 05:24:38.941068 14561 cluster_process.go:633] Attempting to reserve port: 16009
2021-06-18T05:24:38.9419940Z I0618 05:24:38.941081 14561 cluster_process.go:641] Port 16009 is available, reserving..
2021-06-18T05:24:38.9420872Z I0618 05:24:38.941092 14561 cluster_process.go:272] Starting mysqlctl for table uid 3217, mysql port 16009
2021-06-18T05:24:38.9423023Z I0618 05:24:38.941111 14561 mysqlctl_process.go:124] Starting mysqlctl with command: [mysqlctl -log_dir /home/runner/work/vitess/vitess/vtdataroot/vt_367518308/vtroot_16001/tmp_16003 -tablet_uid 3217 -mysql_port 16009 init -init_db_sql_file /home/runner/work/vitess/vitess/config/init_db.sql start]
2021-06-18T05:24:44.1307569Z I0618 05:24:44.130318 14561 cluster_process.go:325] Starting vttablet for tablet uid 3217, grpc port 16008
2021-06-18T05:24:44.1313397Z I0618 05:24:44.130401 14561 vttablet_process.go:128] Running vttablet with command: vttablet -topo_implementation etcd2 -topo_global_server_address localhost:16002 -topo_global_root /vitess/global -log_queries_to_file /home/runner/work/vitess/vitess/vtdataroot/vt_367518308/vtroot_16001/tmp_16003/vt_0000003217_querylog.txt -tablet-path zone1-0000003217 -port 16007 -grpc_port 16008 -init_shard 1 -log_dir /home/runner/work/vitess/vitess/vtdataroot/vt_367518308/vtroot_16001/tmp_16003 -tablet_hostname localhost -init_keyspace ks -init_tablet_type replica -health_check_interval 5s -enable_replication_reporter -backup_storage_implementation file -file_backup_storage_root /home/runner/work/vitess/vitess/vtdataroot/vt_367518308/vtroot_16001/backups -service_map grpc-queryservice,grpc-tabletmanager,grpc-updatestream,grpc-throttler -vtctld_addr http://localhost:16005 -vtctld_addr http://localhost:16005 -vreplication_tablet_type replica -restore_from_backup -enable-lag-throttler -throttle_threshold 1s -heartbeat_enable -heartbeat_interval 250ms -migration_check_interval 5s
2021-06-18T05:24:49.5663128Z I0618 05:24:49.565936 14561 vtctlclient_process.go:177] Executing vtctlclient with command: vtctlclient -server localhost:16006 InitShardMaster -force -wait_replicas_timeout 31s ks/1 zone1-3217
2021-06-18T05:24:49.6115744Z I0618 05:24:49.611336 14561 cluster_process.go:368] Done creating keyspace: ks
2021-06-18T05:24:49.6118153Z I0618 05:24:49.611366 14561 cluster_process.go:633] Attempting to reserve port: 16010
2021-06-18T05:24:49.6119398Z I0618 05:24:49.611404 14561 cluster_process.go:641] Port 16010 is available, reserving..
2021-06-18T05:24:49.6120160Z I0618 05:24:49.611420 14561 cluster_process.go:633] Attempting to reserve port: 16011
2021-06-18T05:24:49.6120905Z I0618 05:24:49.611436 14561 cluster_process.go:641] Port 16011 is available, reserving..
2021-06-18T05:24:49.6121598Z I0618 05:24:49.611443 14561 cluster_process.go:633] Attempting to reserve port: 16012
2021-06-18T05:24:49.6122444Z I0618 05:24:49.611456 14561 cluster_process.go:641] Port 16012 is available, reserving..
2021-06-18T05:24:49.6128153Z I0618 05:24:49.611519 14561 vtgate_process.go:102] Running vtgate with command: vtgate -topo_implementation etcd2 -topo_global_server_address localhost:16002 -topo_global_root /vitess/global -log_dir /home/runner/work/vitess/vitess/vtdataroot/vt_367518308/vtroot_16001/tmp_16003 -log_queries_to_file /home/runner/work/vitess/vitess/vtdataroot/vt_367518308/vtroot_16001/tmp_16003/vtgate_querylog.txt -port 16010 -grpc_port 16011 -mysql_server_port 16012 -mysql_server_socket_path /home/runner/work/vitess/vitess/vtdataroot/vt_367518308/vtroot_16001/tmp_16003/mysql.sock -cell zone1 -cells_to_watch zone1 -tablet_types_to_wait MASTER,REPLICA -gateway_implementation tabletgateway -service_map grpc-tabletmanager,grpc-throttler,grpc-queryservice,grpc-updatestream,grpc-vtctl,grpc-vtworker,grpc-vtgateservice -mysql_auth_server_impl none
2021-06-18T05:25:19.6876570Z === RUN TestSchemaChange
2021-06-18T05:25:19.6880042Z === RUN TestSchemaChange/alter-charset-non-utf8
2021-06-18T05:25:29.7863931Z === RUN TestSchemaChange/alter-charset-non-utf8-80
2021-06-18T05:25:29.7877438Z ##[error] onlineddl_vrepl_suite_test.go:180: Skipping test due to ignore_versions=(5.5|5.6|5.7)
2021-06-18T05:25:29.7895724Z === RUN TestSchemaChange/autoinc-copy-deletes
2021-06-18T05:25:39.8505347Z === RUN TestSchemaChange/autoinc-copy-deletes-user-defined
2021-06-18T05:25:49.9085748Z === RUN TestSchemaChange/autoinc-copy-simple
2021-06-18T05:25:59.9650968Z === RUN TestSchemaChange/autoinc-zero-value
2021-06-18T05:26:10.0240086Z === RUN TestSchemaChange/bigint-change-nullable
2021-06-18T05:26:20.0809526Z === RUN TestSchemaChange/bit-add
2021-06-18T05:26:30.1351886Z === RUN TestSchemaChange/bit-dml
2021-06-18T05:26:40.1925704Z === RUN TestSchemaChange/convert-utf8mb4
2021-06-18T05:26:50.2562698Z === RUN TestSchemaChange/datetime
2021-06-18T05:27:00.3121573Z === RUN TestSchemaChange/datetime-1970
2021-06-18T05:27:10.3686954Z === RUN TestSchemaChange/datetime-submillis
2021-06-18T05:27:20.4299191Z === RUN TestSchemaChange/datetime-submillis-zeroleading
2021-06-18T05:27:30.4944206Z === RUN TestSchemaChange/datetime-to-timestamp
2021-06-18T05:27:40.5581442Z === RUN TestSchemaChange/datetime-to-timestamp-pk
2021-06-18T05:27:50.6133276Z === RUN TestSchemaChange/decimal
2021-06-18T05:28:00.6703116Z === RUN TestSchemaChange/drop-null-add-not-null
2021-06-18T05:28:10.7292143Z === RUN TestSchemaChange/enum
2021-06-18T05:28:19.7929891Z === RUN TestSchemaChange/enum-pk
2021-06-18T05:28:29.8552335Z === RUN TestSchemaChange/enum-to-varchar
2021-06-18T05:28:39.9129021Z === RUN TestSchemaChange/enum-to-varchar-rename
2021-06-18T05:28:49.9769771Z === RUN TestSchemaChange/fail-drop-pk
2021-06-18T05:28:55.0194629Z === RUN TestSchemaChange/fail-fk-child
2021-06-18T05:29:00.0588673Z === RUN TestSchemaChange/fail-fk-parent
2021-06-18T05:29:05.0998221Z === RUN TestSchemaChange/fail-float-unique-key
2021-06-18T05:29:10.1335074Z === RUN TestSchemaChange/fail-no-unique-key
2021-06-18T05:29:15.1653167Z === RUN TestSchemaChange/fail-nonexistent-column
2021-06-18T05:29:20.1992503Z === RUN TestSchemaChange/fail-rename-table
2021-06-18T05:29:20.2168332Z === RUN TestSchemaChange/fail-syntax-error
2021-06-18T05:29:20.2326204Z === RUN TestSchemaChange/gbk-charset
2021-06-18T05:29:30.3060796Z === RUN TestSchemaChange/generated-columns-add57
2021-06-18T05:29:40.3711305Z === RUN TestSchemaChange/generated-columns-rename57
2021-06-18T05:29:50.4282619Z === RUN TestSchemaChange/generated-columns57
2021-06-18T05:30:00.4850660Z === RUN TestSchemaChange/generated-columns57-unique
2021-06-18T05:30:10.5411430Z === RUN TestSchemaChange/geometry57
2021-06-18T05:30:20.5976694Z === RUN TestSchemaChange/json57
2021-06-18T05:30:30.6558448Z === RUN TestSchemaChange/json57dml
2021-06-18T05:30:40.7142551Z === RUN TestSchemaChange/keyword-column
2021-06-18T05:30:50.7707641Z === RUN TestSchemaChange/latin1
2021-06-18T05:30:59.8302391Z === RUN TestSchemaChange/latin1text
2021-06-18T05:31:09.8958851Z === RUN TestSchemaChange/mixed-charset
2021-06-18T05:31:19.9564258Z === RUN TestSchemaChange/modify-change-case
2021-06-18T05:31:30.0158683Z === RUN TestSchemaChange/rename
2021-06-18T05:31:40.0771513Z === RUN TestSchemaChange/rename-inserts-only
2021-06-18T05:31:50.1312599Z === RUN TestSchemaChange/rename-none-column
2021-06-18T05:32:00.1877650Z === RUN TestSchemaChange/rename-none-comment
2021-06-18T05:32:10.2412873Z === RUN TestSchemaChange/rename-reorder-column
2021-06-18T05:32:20.2949281Z === RUN TestSchemaChange/rename-reorder-columns
2021-06-18T05:32:30.3518037Z === RUN TestSchemaChange/reorder-columns
2021-06-18T05:32:40.4155909Z === RUN TestSchemaChange/spatial57
2021-06-18T05:32:50.4826672Z === RUN TestSchemaChange/swap-uk
2021-06-18T05:33:00.5430527Z === RUN TestSchemaChange/timestamp
2021-06-18T05:33:10.6134229Z === RUN TestSchemaChange/timestamp-datetime
2021-06-18T05:33:20.6721818Z === RUN TestSchemaChange/timestamp-to-datetime
2021-06-18T05:33:30.7317458Z === RUN TestSchemaChange/trivial
2021-06-18T05:33:40.7979531Z === RUN TestSchemaChange/tz
2021-06-18T05:33:47.8493224Z === RUN TestSchemaChange/tz-datetime
2021-06-18T05:33:55.9014707Z === RUN TestSchemaChange/tz-datetime-ts
2021-06-18T05:34:02.9594061Z === RUN TestSchemaChange/unsigned
2021-06-18T05:34:11.0172927Z === RUN TestSchemaChange/unsigned-modify
2021-06-18T05:34:20.0814175Z === RUN TestSchemaChange/unsigned-rename
2021-06-18T05:34:27.1305190Z === RUN TestSchemaChange/unsigned-reorder
2021-06-18T05:34:35.1840193Z === RUN TestSchemaChange/update-pk
2021-06-18T05:34:42.2357027Z onlineddl_vrepl_suite_test.go:290:
2021-06-18T05:34:42.2360208Z Error Trace: onlineddl_vrepl_suite_test.go:290
2021-06-18T05:34:42.2361366Z onlineddl_vrepl_suite_test.go:149
2021-06-18T05:34:42.2363007Z Error: Not equal:
2021-06-18T05:34:42.2365363Z expected: "1\t5\tdark grey\n2\t7\tyellow\n3\t11\tgreen\n3\t11\tred\n4\t13\tgreen\n5\t17\torange\n6\t11\tgreen\n6\t11\tred\n7\t13\tgreen\n8\t17\torange\n9\t11\tgreen\n9\t11\tred\n10\t13\tgreen\n11\t17\torange\n12\t11\tgreen\n12\t11\tred\n13\t13\tgreen\n14\t17\torange\n15\t11\tgreen\n15\t11\tred\n16\t13\tgreen\n17\t17\torange\n18\t11\tgreen\n18\t11\tred\n19\t13\tgreen\n20\t17\torange\n21\t11\tgreen\n21\t11\tred\n22\t13\tgreen\n23\t17\torange\n"
2021-06-18T05:34:42.2371335Z actual : "1\t5\tdark grey\n2\t7\tyellow\n3\t11\tgreen\n3\t11\tred\n4\t13\tgreen\n5\t17\torange\n6\t11\tgreen\n6\t11\tred\n7\t13\tgreen\n8\t17\torange\n9\t11\tgreen\n9\t11\tred\n10\t13\tgreen\n11\t17\tblue\n12\t11\tgreen\n12\t11\tred\n13\t13\tgreen\n14\t17\tblue\n15\t11\tgreen\n15\t11\tred\n16\t13\tgreen\n17\t17\tblue\n18\t11\tgreen\n18\t11\tred\n19\t13\tgreen\n20\t17\tblue\n21\t11\tgreen\n21\t11\tred\n22\t13\tgreen\n23\t17\tblue\n"
2021-06-18T05:34:42.2375571Z
2021-06-18T05:34:42.2376426Z Diff:
2021-06-18T05:34:42.2377758Z --- Expected
2021-06-18T05:34:42.2379340Z +++ Actual
2021-06-18T05:34:42.2381607Z @@ -13,3 +13,3 @@
2021-06-18T05:34:42.2387649Z 10 13 green
2021-06-18T05:34:42.2389004Z -11 17 orange
2021-06-18T05:34:42.2391785Z +11 17 blue
2021-06-18T05:34:42.2392646Z 12 11 green
2021-06-18T05:34:42.2394154Z @@ -17,3 +17,3 @@
2021-06-18T05:34:42.2396658Z 13 13 green
2021-06-18T05:34:42.2397885Z -14 17 orange
2021-06-18T05:34:42.2398522Z +14 17 blue
2021-06-18T05:34:42.2399670Z 15 11 green
2021-06-18T05:34:42.2401780Z @@ -21,3 +21,3 @@
2021-06-18T05:34:42.2402331Z 16 13 green
2021-06-18T05:34:42.2402918Z -17 17 orange
2021-06-18T05:34:42.2403524Z +17 17 blue
2021-06-18T05:34:42.2403906Z 18 11 green
2021-06-18T05:34:42.2412078Z @@ -25,3 +25,3 @@
2021-06-18T05:34:42.2412716Z 19 13 green
2021-06-18T05:34:42.2414114Z -20 17 orange
2021-06-18T05:34:42.2414563Z +20 17 blue
2021-06-18T05:34:42.2415278Z 21 11 green
2021-06-18T05:34:42.2416272Z @@ -29,3 +29,3 @@
2021-06-18T05:34:42.2416832Z 22 13 green
2021-06-18T05:34:42.2417348Z -23 17 orange
2021-06-18T05:34:42.2417734Z +23 17 blue
2021-06-18T05:34:42.2418078Z
2021-06-18T05:34:42.2418721Z Test: TestSchemaChange/update-pk
2021-06-18T05:34:42.2419996Z Messages: results mismatch: (select * from onlineddl_test_before ) and (select * from onlineddl_test_after )
2021-06-18T05:34:42.2420769Z === RUN TestSchemaChange/utf8
2021-06-18T05:34:50.2917287Z === RUN TestSchemaChange/utf8mb4
2021-06-18T05:34:57.3426715Z === RUN TestSchemaChange/varbinary
2021-06-18T05:35:05.4037430Z --- FAIL: TestSchemaChange (585.72s)
2021-06-18T05:35:05.4063086Z --- PASS: TestSchemaChange/alter-charset-non-utf8 (10.10s)
2021-06-18T05:35:05.4064930Z --- SKIP: TestSchemaChange/alter-charset-non-utf8-80 (0.00s)
2021-06-18T05:35:05.4066444Z --- PASS: TestSchemaChange/autoinc-copy-deletes (10.06s)
2021-06-18T05:35:05.4068012Z --- PASS: TestSchemaChange/autoinc-copy-deletes-user-defined (10.06s)
2021-06-18T05:35:05.4069518Z --- PASS: TestSchemaChange/autoinc-copy-simple (10.06s)
2021-06-18T05:35:05.4070890Z --- PASS: TestSchemaChange/autoinc-zero-value (10.06s)
2021-06-18T05:35:05.4072501Z --- PASS: TestSchemaChange/bigint-change-nullable (10.06s)
2021-06-18T05:35:05.4073891Z --- PASS: TestSchemaChange/bit-add (10.05s)
2021-06-18T05:35:05.4075800Z --- PASS: TestSchemaChange/bit-dml (10.06s)
2021-06-18T05:35:05.4077308Z --- PASS: TestSchemaChange/convert-utf8mb4 (10.06s)
2021-06-18T05:35:05.4090818Z --- PASS: TestSchemaChange/datetime (10.06s)
2021-06-18T05:35:05.4093564Z --- PASS: TestSchemaChange/datetime-1970 (10.06s)
2021-06-18T05:35:05.4095459Z --- PASS: TestSchemaChange/datetime-submillis (10.06s)
2021-06-18T05:35:05.4098881Z --- PASS: TestSchemaChange/datetime-submillis-zeroleading (10.06s)
2021-06-18T05:35:05.4103348Z --- PASS: TestSchemaChange/datetime-to-timestamp (10.06s)
2021-06-18T05:35:05.4106202Z --- PASS: TestSchemaChange/datetime-to-timestamp-pk (10.06s)
2021-06-18T05:35:05.4108521Z --- PASS: TestSchemaChange/decimal (10.06s)
2021-06-18T05:35:05.4115601Z --- PASS: TestSchemaChange/drop-null-add-not-null (10.06s)
2021-06-18T05:35:05.4117195Z --- PASS: TestSchemaChange/enum (9.06s)
2021-06-18T05:35:05.4117943Z --- PASS: TestSchemaChange/enum-pk (10.06s)
2021-06-18T05:35:05.4118695Z --- PASS: TestSchemaChange/enum-to-varchar (10.06s)
2021-06-18T05:35:05.4119569Z --- PASS: TestSchemaChange/enum-to-varchar-rename (10.06s)
2021-06-18T05:35:05.4120918Z --- PASS: TestSchemaChange/fail-drop-pk (5.04s)
2021-06-18T05:35:05.4121758Z --- PASS: TestSchemaChange/fail-fk-child (5.04s)
2021-06-18T05:35:05.4122527Z --- PASS: TestSchemaChange/fail-fk-parent (5.04s)
2021-06-18T05:35:05.4123856Z --- PASS: TestSchemaChange/fail-float-unique-key (5.03s)
2021-06-18T05:35:05.4124743Z --- PASS: TestSchemaChange/fail-no-unique-key (5.03s)
2021-06-18T05:35:05.4125850Z --- PASS: TestSchemaChange/fail-nonexistent-column (5.03s)
2021-06-18T05:35:05.4126780Z --- PASS: TestSchemaChange/fail-rename-table (0.02s)
2021-06-18T05:35:05.4127641Z --- PASS: TestSchemaChange/fail-syntax-error (0.02s)
2021-06-18T05:35:05.4128616Z --- PASS: TestSchemaChange/gbk-charset (10.07s)
2021-06-18T05:35:05.4129467Z --- PASS: TestSchemaChange/generated-columns-add57 (10.07s)
2021-06-18T05:35:05.4130795Z --- PASS: TestSchemaChange/generated-columns-rename57 (10.06s)
2021-06-18T05:35:05.4131829Z --- PASS: TestSchemaChange/generated-columns57 (10.06s)
2021-06-18T05:35:05.4132785Z --- PASS: TestSchemaChange/generated-columns57-unique (10.06s)
2021-06-18T05:35:05.4133654Z --- PASS: TestSchemaChange/geometry57 (10.06s)
2021-06-18T05:35:05.4134347Z --- PASS: TestSchemaChange/json57 (10.06s)
2021-06-18T05:35:05.4135060Z --- PASS: TestSchemaChange/json57dml (10.06s)
2021-06-18T05:35:05.4135799Z --- PASS: TestSchemaChange/keyword-column (10.06s)
2021-06-18T05:35:05.4136531Z --- PASS: TestSchemaChange/latin1 (9.06s)
2021-06-18T05:35:05.4137233Z --- PASS: TestSchemaChange/latin1text (10.07s)
2021-06-18T05:35:05.4137992Z --- PASS: TestSchemaChange/mixed-charset (10.06s)
2021-06-18T05:35:05.4138793Z --- PASS: TestSchemaChange/modify-change-case (10.06s)
2021-06-18T05:35:05.4140096Z --- PASS: TestSchemaChange/rename (10.06s)
2021-06-18T05:35:05.4140960Z --- PASS: TestSchemaChange/rename-inserts-only (10.05s)
2021-06-18T05:35:05.4141817Z --- PASS: TestSchemaChange/rename-none-column (10.06s)
2021-06-18T05:35:05.4142689Z --- PASS: TestSchemaChange/rename-none-comment (10.05s)
2021-06-18T05:35:05.4143568Z --- PASS: TestSchemaChange/rename-reorder-column (10.05s)
2021-06-18T05:35:05.4144491Z --- PASS: TestSchemaChange/rename-reorder-columns (10.06s)
2021-06-18T05:35:05.4145335Z --- PASS: TestSchemaChange/reorder-columns (10.06s)
2021-06-18T05:35:05.4146102Z --- PASS: TestSchemaChange/spatial57 (10.07s)
2021-06-18T05:35:05.4146816Z --- PASS: TestSchemaChange/swap-uk (10.06s)
2021-06-18T05:35:05.4147517Z --- PASS: TestSchemaChange/timestamp (10.07s)
2021-06-18T05:35:05.4148320Z --- PASS: TestSchemaChange/timestamp-datetime (10.06s)
2021-06-18T05:35:05.4149192Z --- PASS: TestSchemaChange/timestamp-to-datetime (10.06s)
2021-06-18T05:35:05.4149994Z --- PASS: TestSchemaChange/trivial (10.07s)
2021-06-18T05:35:05.4150651Z --- PASS: TestSchemaChange/tz (7.05s)
2021-06-18T05:35:05.4151362Z --- PASS: TestSchemaChange/tz-datetime (8.05s)
2021-06-18T05:35:05.4152120Z --- PASS: TestSchemaChange/tz-datetime-ts (7.06s)
2021-06-18T05:35:05.4152863Z --- PASS: TestSchemaChange/unsigned (8.06s)
2021-06-18T05:35:05.4153624Z --- PASS: TestSchemaChange/unsigned-modify (9.06s)
2021-06-18T05:35:05.4154409Z --- PASS: TestSchemaChange/unsigned-rename (7.05s)
2021-06-18T05:35:05.4155221Z --- PASS: TestSchemaChange/unsigned-reorder (8.05s)
2021-06-18T05:35:05.4155976Z --- FAIL: TestSchemaChange/update-pk (7.05s)
2021-06-18T05:35:05.4156674Z --- PASS: TestSchemaChange/utf8 (8.05s)
2021-06-18T05:35:05.4157344Z --- PASS: TestSchemaChange/utf8mb4 (7.05s)
2021-06-18T05:35:05.4158058Z --- PASS: TestSchemaChange/varbinary (8.06s)
2021-06-18T05:35:05.4158460Z FAIL
2021-06-18T05:35:09.6423639Z FAIL vitess.io/vitess/go/test/endtoend/onlineddl/vrepl_suite 631.417s
2021-06-18T05:35:09.6453542Z FAIL
2021-06-18T05:35:09.6789506Z 2021/06/18 05:35:09 local.onlineddl_vrepl_suite: saving test output to _test/20210618-052136.5988/local.onlineddl_vrepl_suite-1.1.log
2021-06-18T05:35:09.6790955Z 2021/06/18 05:35:09 local.onlineddl_vrepl_suite: FAILED (try 1/3) in 10m49.8s: exit status 1
2021-06-18T05:35:09.6792504Z 2021/06/18 05:35:09 Can't read stats file, starting new one.
2021-06-18T05:35:09.6793496Z 2021/06/18 05:35:09 local.onlineddl_vrepl_suite: running (try 2/3)...
2021-06-18T05:35:09.7054228Z running tests for vitess.io/vitess/go/test/endtoend/onlineddl/vrepl_suite
2021-06-18T05:35:11.2710867Z I0618 05:35:11.269921 16578 cluster_process.go:633] Attempting to reserve port: 16201
2021-06-18T05:35:11.2714769Z I0618 05:35:11.271315 16578 cluster_process.go:641] Port 16201 is available, reserving..
2021-06-18T05:35:11.2717818Z I0618 05:35:11.271562 16578 cluster_process.go:475] Created cluster on /home/runner/work/vitess/vitess/vtdataroot/vt_017657971/vtroot_16201. ReusingVTDATAROOT=false
2021-06-18T05:35:11.2721104Z I0618 05:35:11.271792 16578 cluster_process.go:633] Attempting to reserve port: 16202
2021-06-18T05:35:11.2722477Z I0618 05:35:11.271827 16578 cluster_process.go:641] Port 16202 is available, reserving..
2021-06-18T05:35:11.2723624Z I0618 05:35:11.271841 16578 cluster_process.go:633] Attempting to reserve port: 16203
2021-06-18T05:35:11.2725115Z I0618 05:35:11.271874 16578 cluster_process.go:641] Port 16203 is available, reserving..
2021-06-18T05:35:11.2727015Z I0618 05:35:11.271903 16578 cluster_process.go:633] Attempting to reserve port: 16204
2021-06-18T05:35:11.2728123Z I0618 05:35:11.271933 16578 cluster_process.go:641] Port 16204 is available, reserving..
2021-06-18T05:35:11.2729208Z I0618 05:35:11.272011 16578 cluster_process.go:186] Starting topo server etcd2 on port: 16202
2021-06-18T05:35:11.2733138Z E0618 05:35:11.272311 16578 topo_process.go:92] Starting etcd with command: etcd --name global --data-dir /home/runner/work/vitess/vitess/vtdataroot/vt_017657971/vtroot_16201/topo_16202 --listen-client-urls http://localhost:16202 --advertise-client-urls http://localhost:16202 --initial-advertise-peer-urls http://localhost:16204 --listen-peer-urls http://localhost:16204 --initial-cluster global=http://localhost:16204 --enable-v2=true
2021-06-18T05:35:12.1977053Z I0618 05:35:12.197200 16578 cluster_process.go:193] Creating global and cell topo dirs
2021-06-18T05:35:12.1997622Z I0618 05:35:12.199186 16578 vtctl_process.go:55] Adding CellInfo for cell zone1 with command: vtctl -topo_implementation etcd2 -topo_global_server_address localhost:16202 -topo_global_root /vitess/global AddCellInfo -root /zone1 -server_address localhost:16202 zone1
2021-06-18T05:35:12.2384397Z I0618 05:35:12.237855 16578 cluster_process.go:633] Attempting to reserve port: 16205
2021-06-18T05:35:12.2385840Z I0618 05:35:12.237903 16578 cluster_process.go:641] Port 16205 is available, reserving..
2021-06-18T05:35:12.2387508Z I0618 05:35:12.237916 16578 cluster_process.go:633] Attempting to reserve port: 16206
2021-06-18T05:35:12.2388626Z I0618 05:35:12.237933 16578 cluster_process.go:641] Port 16206 is available, reserving..
2021-06-18T05:35:12.2390081Z I0618 05:35:12.237999 16578 cluster_process.go:215] Starting vtctld server on port: 16205
2021-06-18T05:35:12.2398965Z I0618 05:35:12.238164 16578 vtctld_process.go:86] Starting vtctld with command: vtctld -enable_queries -topo_implementation etcd2 -topo_global_server_address localhost:16202 -topo_global_root /vitess/global -cell zone1 -workflow_manager_init -workflow_manager_use_election -service_map grpc-vtctl -backup_storage_implementation file -file_backup_storage_root /home/runner/work/vitess/vitess/vtdataroot/vt_017657971/vtroot_16201/backups -wait_for_drain_sleep_rdonly 1s -wait_for_drain_sleep_replica 1s -online_ddl_check_interval 2s -log_dir /home/runner/work/vitess/vitess/vtdataroot/vt_017657971/vtroot_16201/tmp_16203 -port 16205 -grpc_port 16206 -schema_change_dir /tmp/schema_change_dir_7493 -schema_change_controller local -schema_change_check_interval 1 -online_ddl_check_interval 2s
2021-06-18T05:35:12.5408919Z I0618 05:35:12.540528 16578 cluster_process.go:244] Starting keyspace: ks
2021-06-18T05:35:12.5411531Z I0618 05:35:12.540571 16578 vtctl_process.go:72] Running CreateKeyspace with command: vtctl -topo_implementation etcd2 -topo_global_server_address localhost:16202 -topo_global_root /vitess/global CreateKeyspace ks
2021-06-18T05:35:12.5815439Z I0618 05:35:12.581100 16578 cluster_process.go:253] Starting shard: 1
2021-06-18T05:35:12.5816564Z I0618 05:35:12.581136 16578 cluster_process.go:633] Attempting to reserve port: 16207
2021-06-18T05:35:12.5817482Z I0618 05:35:12.581170 16578 cluster_process.go:641] Port 16207 is available, reserving..
2021-06-18T05:35:12.5818368Z I0618 05:35:12.581187 16578 cluster_process.go:633] Attempting to reserve port: 16208
2021-06-18T05:35:12.5819237Z I0618 05:35:12.581205 16578 cluster_process.go:641] Port 16208 is available, reserving..
2021-06-18T05:35:12.5820809Z I0618 05:35:12.581219 16578 cluster_process.go:633] Attempting to reserve port: 16209
2021-06-18T05:35:12.5821934Z I0618 05:35:12.581235 16578 cluster_process.go:641] Port 16209 is available, reserving..
2021-06-18T05:35:12.5822928Z I0618 05:35:12.581251 16578 cluster_process.go:272] Starting mysqlctl for table uid 7494, mysql port 16209
2021-06-18T05:35:12.5824969Z I0618 05:35:12.581274 16578 mysqlctl_process.go:124] Starting mysqlctl with command: [mysqlctl -log_dir /home/runner/work/vitess/vitess/vtdataroot/vt_017657971/vtroot_16201/tmp_16203 -tablet_uid 7494 -mysql_port 16209 init -init_db_sql_file /home/runner/work/vitess/vitess/config/init_db.sql start]
2021-06-18T05:35:15.6266163Z I0618 05:35:15.626110 16578 cluster_process.go:325] Starting vttablet for tablet uid 7494, grpc port 16208
2021-06-18T05:35:15.6278405Z I0618 05:35:15.626224 16578 vttablet_process.go:128] Running vttablet with command: vttablet -topo_implementation etcd2 -topo_global_server_address localhost:16202 -topo_global_root /vitess/global -log_queries_to_file /home/runner/work/vitess/vitess/vtdataroot/vt_017657971/vtroot_16201/tmp_16203/vt_0000007494_querylog.txt -tablet-path zone1-0000007494 -port 16207 -grpc_port 16208 -init_shard 1 -log_dir /home/runner/work/vitess/vitess/vtdataroot/vt_017657971/vtroot_16201/tmp_16203 -tablet_hostname localhost -init_keyspace ks -init_tablet_type replica -health_check_interval 5s -enable_replication_reporter -backup_storage_implementation file -file_backup_storage_root /home/runner/work/vitess/vitess/vtdataroot/vt_017657971/vtroot_16201/backups -service_map grpc-queryservice,grpc-tabletmanager,grpc-updatestream,grpc-throttler -vtctld_addr http://localhost:16205 -vtctld_addr http://localhost:16205 -vreplication_tablet_type replica -restore_from_backup -enable-lag-throttler -throttle_threshold 1s -heartbeat_enable -heartbeat_interval 250ms -migration_check_interval 5s
2021-06-18T05:35:21.0654124Z I0618 05:35:21.064995 16578 vtctlclient_process.go:177] Executing vtctlclient with command: vtctlclient -server localhost:16206 InitShardMaster -force -wait_replicas_timeout 31s ks/1 zone1-7494
2021-06-18T05:35:21.1129642Z I0618 05:35:21.112144 16578 cluster_process.go:368] Done creating keyspace: ks
2021-06-18T05:35:21.1131026Z I0618 05:35:21.112412 16578 cluster_process.go:633] Attempting to reserve port: 16210
2021-06-18T05:35:21.1132105Z I0618 05:35:21.112468 16578 cluster_process.go:641] Port 16210 is available, reserving..
2021-06-18T05:35:21.1133139Z I0618 05:35:21.112482 16578 cluster_process.go:633] Attempting to reserve port: 16211
2021-06-18T05:35:21.1134165Z I0618 05:35:21.112500 16578 cluster_process.go:641] Port 16211 is available, reserving..
2021-06-18T05:35:21.1135178Z I0618 05:35:21.112508 16578 cluster_process.go:633] Attempting to reserve port: 16212
2021-06-18T05:35:21.1136174Z I0618 05:35:21.112523 16578 cluster_process.go:641] Port 16212 is available, reserving..
2021-06-18T05:35:21.1144292Z I0618 05:35:21.112602 16578 vtgate_process.go:102] Running vtgate with command: vtgate -topo_implementation etcd2 -topo_global_server_address localhost:16202 -topo_global_root /vitess/global -log_dir /home/runner/work/vitess/vitess/vtdataroot/vt_017657971/vtroot_16201/tmp_16203 -log_queries_to_file /home/runner/work/vitess/vitess/vtdataroot/vt_017657971/vtroot_16201/tmp_16203/vtgate_querylog.txt -port 16210 -grpc_port 16211 -mysql_server_port 16212 -mysql_server_socket_path /home/runner/work/vitess/vitess/vtdataroot/vt_017657971/vtroot_16201/tmp_16203/mysql.sock -cell zone1 -cells_to_watch zone1 -tablet_types_to_wait MASTER,REPLICA -gateway_implementation tabletgateway -service_map grpc-tabletmanager,grpc-throttler,grpc-queryservice,grpc-updatestream,grpc-vtctl,grpc-vtworker,grpc-vtgateservice -mysql_auth_server_impl none
2021-06-18T05:35:51.1927203Z === RUN TestSchemaChange
2021-06-18T05:35:51.1928900Z === RUN TestSchemaChange/alter-charset-non-utf8
2021-06-18T05:36:01.2592258Z === RUN TestSchemaChange/alter-charset-non-utf8-80
2021-06-18T05:36:01.2599163Z ##[error] onlineddl_vrepl_suite_test.go:180: Skipping test due to ignore_versions=(5.5|5.6|5.7)
2021-06-18T05:36:01.2602555Z === RUN TestSchemaChange/autoinc-copy-deletes
2021-06-18T05:36:11.3255017Z === RUN TestSchemaChange/autoinc-copy-deletes-user-defined
2021-06-18T05:36:21.3880565Z === RUN TestSchemaChange/autoinc-copy-simple
2021-06-18T05:36:31.4501383Z === RUN TestSchemaChange/autoinc-zero-value
2021-06-18T05:36:41.5082839Z === RUN TestSchemaChange/bigint-change-nullable
2021-06-18T05:36:51.5662584Z === RUN TestSchemaChange/bit-add
2021-06-18T05:37:02.1032215Z === RUN TestSchemaChange/bit-dml
2021-06-18T05:37:11.6861884Z === RUN TestSchemaChange/convert-utf8mb4
2021-06-18T05:37:21.7473517Z === RUN TestSchemaChange/datetime
2021-06-18T05:37:31.8088636Z === RUN TestSchemaChange/datetime-1970
2021-06-18T05:37:41.8706041Z === RUN TestSchemaChange/datetime-submillis
2021-06-18T05:37:51.9346310Z === RUN TestSchemaChange/datetime-submillis-zeroleading
2021-06-18T05:38:01.9940209Z === RUN TestSchemaChange/datetime-to-timestamp
2021-06-18T05:38:12.0560653Z === RUN TestSchemaChange/datetime-to-timestamp-pk
2021-06-18T05:38:22.1157606Z === RUN TestSchemaChange/decimal
2021-06-18T05:38:32.1734512Z === RUN TestSchemaChange/drop-null-add-not-null
2021-06-18T05:38:42.2307636Z === RUN TestSchemaChange/enum
2021-06-18T05:38:51.2858578Z === RUN TestSchemaChange/enum-pk
2021-06-18T05:39:01.3451520Z === RUN TestSchemaChange/enum-to-varchar
2021-06-18T05:39:11.4097819Z === RUN TestSchemaChange/enum-to-varchar-rename
2021-06-18T05:39:21.4725788Z === RUN TestSchemaChange/fail-drop-pk
2021-06-18T05:39:26.5065608Z === RUN TestSchemaChange/fail-fk-child
2021-06-18T05:39:31.5425029Z === RUN TestSchemaChange/fail-fk-parent
2021-06-18T05:39:36.5762451Z === RUN TestSchemaChange/fail-float-unique-key
2021-06-18T05:39:41.6075981Z === RUN TestSchemaChange/fail-no-unique-key
2021-06-18T05:39:46.6375037Z === RUN TestSchemaChange/fail-nonexistent-column
2021-06-18T05:39:51.6706343Z === RUN TestSchemaChange/fail-rename-table
2021-06-18T05:39:51.6883893Z === RUN TestSchemaChange/fail-syntax-error
2021-06-18T05:39:51.7037073Z === RUN TestSchemaChange/gbk-charset
2021-06-18T05:40:01.7626466Z === RUN TestSchemaChange/generated-columns-add57
2021-06-18T05:40:11.8242353Z === RUN TestSchemaChange/generated-columns-rename57
2021-06-18T05:40:21.8823717Z === RUN TestSchemaChange/generated-columns57
2021-06-18T05:40:31.9464576Z === RUN TestSchemaChange/generated-columns57-unique
2021-06-18T05:40:42.0044344Z === RUN TestSchemaChange/geometry57
2021-06-18T05:40:52.0740545Z === RUN TestSchemaChange/json57
2021-06-18T05:41:02.1350733Z === RUN TestSchemaChange/json57dml
2021-06-18T05:41:12.1992006Z === RUN TestSchemaChange/keyword-column
2021-06-18T05:41:22.2701064Z === RUN TestSchemaChange/latin1
2021-06-18T05:41:31.3289326Z === RUN TestSchemaChange/latin1text
2021-06-18T05:41:41.3872515Z === RUN TestSchemaChange/mixed-charset
2021-06-18T05:41:51.4483227Z === RUN TestSchemaChange/modify-change-case
2021-06-18T05:42:01.5070732Z === RUN TestSchemaChange/rename
2021-06-18T05:42:11.5709867Z === RUN TestSchemaChange/rename-inserts-only
2021-06-18T05:42:21.6293891Z === RUN TestSchemaChange/rename-none-column
2021-06-18T05:42:31.6894367Z === RUN TestSchemaChange/rename-none-comment
2021-06-18T05:42:41.7485440Z === RUN TestSchemaChange/rename-reorder-column
2021-06-18T05:42:51.8136466Z === RUN TestSchemaChange/rename-reorder-columns
2021-06-18T05:43:01.8783704Z === RUN TestSchemaChange/reorder-columns
2021-06-18T05:43:11.9397148Z === RUN TestSchemaChange/spatial57
2021-06-18T05:43:22.0063414Z === RUN TestSchemaChange/swap-uk
2021-06-18T05:43:32.0742133Z === RUN TestSchemaChange/timestamp
2021-06-18T05:43:42.1445180Z === RUN TestSchemaChange/timestamp-datetime
2021-06-18T05:43:52.2071620Z === RUN TestSchemaChange/timestamp-to-datetime
2021-06-18T05:44:02.2766145Z === RUN TestSchemaChange/trivial
2021-06-18T05:44:11.3409690Z === RUN TestSchemaChange/tz
2021-06-18T05:44:21.4062787Z === RUN TestSchemaChange/tz-datetime
2021-06-18T05:44:31.4675243Z === RUN TestSchemaChange/tz-datetime-ts
2021-06-18T05:44:41.5285025Z === RUN TestSchemaChange/unsigned
2021-06-18T05:44:51.5938215Z === RUN TestSchemaChange/unsigned-modify
2021-06-18T05:45:01.6603347Z === RUN TestSchemaChange/unsigned-rename
2021-06-18T05:45:11.7268290Z === RUN TestSchemaChange/unsigned-reorder
2021-06-18T05:45:21.7910652Z === RUN TestSchemaChange/update-pk
2021-06-18T05:45:31.8512643Z onlineddl_vrepl_suite_test.go:290:
2021-06-18T05:45:31.8520380Z Error Trace: onlineddl_vrepl_suite_test.go:290
2021-06-18T05:45:31.8522441Z onlineddl_vrepl_suite_test.go:149
2021-06-18T05:45:31.8523271Z Error: Not equal:
2021-06-18T05:45:31.8526093Z expected: "1\t5\tdark grey\n2\t7\tyellow\n3\t11\tgreen\n3\t11\tred\n4\t13\tgreen\n5\t17\torange\n6\t11\tgreen\n6\t11\tred\n7\t13\tgreen\n8\t17\torange\n9\t11\tgreen\n9\t11\tred\n10\t13\tgreen\n11\t17\torange\n12\t11\tgreen\n12\t11\tred\n13\t13\tgreen\n14\t17\torange\n15\t11\tgreen\n15\t11\tred\n16\t13\tgreen\n17\t17\torange\n18\t11\tgreen\n18\t11\tred\n19\t13\tgreen\n20\t17\torange\n21\t11\tgreen\n21\t11\tred\n22\t13\tgreen\n23\t17\torange\n24\t11\tgreen\n24\t11\tred\n25\t13\tgreen\n26\t17\torange\n27\t11\tgreen\n27\t11\tred\n28\t13\tgreen\n29\t17\torange\n30\t11\tgreen\n30\t11\tred\n31\t13\tgreen\n32\t17\torange\n"
2021-06-18T05:45:31.8532142Z actual : "1\t5\tdark grey\n2\t7\tyellow\n3\t11\tgreen\n3\t11\tred\n4\t13\tgreen\n5\t17\torange\n6\t11\tgreen\n6\t11\tred\n7\t13\tgreen\n8\t17\torange\n9\t11\tgreen\n9\t11\tred\n10\t13\tgreen\n11\t17\torange\n12\t11\tgreen\n12\t11\tred\n13\t13\tgreen\n14\t17\torange\n15\t11\tgreen\n15\t11\tred\n16\t13\tgreen\n17\t17\torange\n18\t11\tgreen\n18\t11\tred\n19\t13\tgreen\n20\t17\tblue\n21\t11\tgreen\n21\t11\tred\n22\t13\tgreen\n23\t17\tblue\n24\t11\tgreen\n24\t11\tred\n25\t13\tgreen\n26\t17\tblue\n27\t11\tgreen\n27\t11\tred\n28\t13\tgreen\n29\t17\tblue\n30\t11\tgreen\n30\t11\tred\n31\t13\tgreen\n32\t17\tblue\n"
2021-06-18T05:45:31.8549549Z
2021-06-18T05:45:31.8550250Z Diff:
2021-06-18T05:45:31.8551400Z --- Expected
2021-06-18T05:45:31.8552002Z +++ Actual
2021-06-18T05:45:31.8552892Z @@ -25,3 +25,3 @@
2021-06-18T05:45:31.8554597Z 19 13 green
2021-06-18T05:45:31.8555800Z -20 17 orange
2021-06-18T05:45:31.8556566Z +20 17 blue
2021-06-18T05:45:31.8557148Z 21 11 green
2021-06-18T05:45:31.8558419Z @@ -29,3 +29,3 @@
2021-06-18T05:45:31.8558987Z 22 13 green
2021-06-18T05:45:31.8559732Z -23 17 orange
2021-06-18T05:45:31.8560680Z +23 17 blue
2021-06-18T05:45:31.8561241Z 24 11 green
2021-06-18T05:45:31.8562198Z @@ -33,3 +33,3 @@
2021-06-18T05:45:31.8562779Z 25 13 green
2021-06-18T05:45:31.8563878Z -26 17 orange
2021-06-18T05:45:31.8564578Z +26 17 blue
2021-06-18T05:45:31.8565086Z 27 11 green
2021-06-18T05:45:31.8565787Z @@ -37,3 +37,3 @@
2021-06-18T05:45:31.8566322Z 28 13 green
2021-06-18T05:45:31.8567437Z -29 17 orange
2021-06-18T05:45:31.8568028Z +29 17 blue
2021-06-18T05:45:31.8568587Z 30 11 green
2021-06-18T05:45:31.8569589Z @@ -41,3 +41,3 @@
2021-06-18T05:45:31.8571227Z 31 13 green
2021-06-18T05:45:31.8573171Z -32 17 orange
2021-06-18T05:45:31.8574981Z +32 17 blue
2021-06-18T05:45:31.8588805Z
2021-06-18T05:45:31.8591073Z Test: TestSchemaChange/update-pk
2021-06-18T05:45:31.8594729Z Messages: results mismatch: (select * from onlineddl_test_before ) and (select * from onlineddl_test_after )
2021-06-18T05:45:31.8596202Z === RUN TestSchemaChange/utf8
2021-06-18T05:45:41.9220686Z === RUN TestSchemaChange/utf8mb4
2021-06-18T05:45:51.1960176Z panic: test timed out after 10m0s
2021-06-18T05:45:51.1966335Z
2021-06-18T05:45:51.1967053Z goroutine 5509 [running]:
2021-06-18T05:45:51.1967683Z testing.(*M).startAlarm.func1()
2021-06-18T05:45:51.1968462Z /opt/hostedtoolcache/go/1.15.13/x64/src/testing/testing.go:1618 +0xe5
2021-06-18T05:45:51.1969144Z created by time.goFunc
2021-06-18T05:45:51.1969824Z /opt/hostedtoolcache/go/1.15.13/x64/src/time/sleep.go:167 +0x45
2021-06-18T05:45:51.1970298Z
2021-06-18T05:45:51.1970833Z goroutine 1 [chan receive, 10 minutes]:
2021-06-18T05:45:51.1971526Z testing.(*T).Run(0xc000116f00, 0xff274f, 0x10, 0x10353b0, 0x4989a6)
2021-06-18T05:45:51.1972297Z /opt/hostedtoolcache/go/1.15.13/x64/src/testing/testing.go:1169 +0x2da
2021-06-18T05:45:51.1973426Z testing.runTests.func1(0xc000116d80)
2021-06-18T05:45:51.1974220Z /opt/hostedtoolcache/go/1.15.13/x64/src/testing/testing.go:1439 +0x78
2021-06-18T05:45:51.1974981Z testing.tRunner(0xc000116d80, 0xc00032fb38)
2021-06-18T05:45:51.1978434Z /opt/hostedtoolcache/go/1.15.13/x64/src/testing/testing.go:1123 +0xef
2021-06-18T05:45:51.1979800Z testing.runTests(0xc00034bd00, 0x18983d0, 0x1, 0x1, 0xc02b2aa3cb722358, 0x94febd1e89, 0x18cd900, 0x59)
2021-06-18T05:45:51.1981155Z /opt/hostedtoolcache/go/1.15.13/x64/src/testing/testing.go:1437 +0x2fe
2021-06-18T05:45:51.1982064Z testing.(*M).Run(0xc000342d80, 0x0)
2021-06-18T05:45:51.1982810Z /opt/hostedtoolcache/go/1.15.13/x64/src/testing/testing.go:1345 +0x1eb
2021-06-18T05:45:51.1983818Z vitess.io/vitess/go/test/endtoend/onlineddl/vrepl_suite.TestMain.func1(0xc000342d80, 0x0, 0x0, 0x0)
2021-06-18T05:45:51.1984949Z /home/runner/work/vitess/vitess/go/test/endtoend/onlineddl/vrepl_suite/onlineddl_vrepl_suite_test.go:124 +0x6fd
2021-06-18T05:45:51.1986007Z vitess.io/vitess/go/test/endtoend/onlineddl/vrepl_suite.TestMain(0xc000342d80)
2021-06-18T05:45:51.1987084Z /home/runner/work/vitess/vitess/go/test/endtoend/onlineddl/vrepl_suite/onlineddl_vrepl_suite_test.go:125 +0xb6
2021-06-18T05:45:51.1987994Z main.main()
2021-06-18T05:45:51.1988932Z _testmain.go:45 +0x165
2021-06-18T05:45:51.1989333Z
2021-06-18T05:45:51.1989866Z goroutine 19 [chan receive]:
2021-06-18T05:45:51.1990658Z github.com/golang/glog.(*loggingT).flushDaemon(0x18cdbc0)
2021-06-18T05:45:51.1992972Z /home/runner/go/pkg/mod/github.com/golang/glog@v0.0.0-20160126235308-23def4e6c14b/glog.go:882 +0x8b
2021-06-18T05:45:51.1996035Z created by github.com/golang/glog.init.0
2021-06-18T05:45:51.1998263Z /home/runner/go/pkg/mod/github.com/golang/glog@v0.0.0-20160126235308-23def4e6c14b/glog.go:410 +0x274
2021-06-18T05:45:51.1998826Z
2021-06-18T05:45:51.1999310Z goroutine 16 [select, 10 minutes]:
2021-06-18T05:45:51.2000551Z vitess.io/vitess/go/test/endtoend/cluster.(*LocalProcessCluster).CtrlCHandler(0xc000341800)
2021-06-18T05:45:51.2001506Z /home/runner/work/vitess/vitess/go/test/endtoend/cluster/cluster_process.go:167 +0x1a5
2021-06-18T05:45:51.2002312Z created by vitess.io/vitess/go/test/endtoend/cluster.NewCluster
2021-06-18T05:45:51.2003145Z /home/runner/work/vitess/vitess/go/test/endtoend/cluster/cluster_process.go:462 +0xd6
2021-06-18T05:45:51.2003772Z
2021-06-18T05:45:51.2004565Z goroutine 22 [syscall, 10 minutes]:
2021-06-18T05:45:51.2005112Z os/signal.signal_recv(0x0)
2021-06-18T05:45:51.2005814Z /opt/hostedtoolcache/go/1.15.13/x64/src/runtime/sigqueue.go:147 +0x9d
2021-06-18T05:45:51.2006432Z os/signal.loop()
2021-06-18T05:45:51.2007098Z /opt/hostedtoolcache/go/1.15.13/x64/src/os/signal/signal_unix.go:23 +0x25
2021-06-18T05:45:51.2008286Z created by os/signal.Notify.func1.1
2021-06-18T05:45:51.2008938Z /opt/hostedtoolcache/go/1.15.13/x64/src/os/signal/signal.go:150 +0x45
2021-06-18T05:45:51.2009308Z
2021-06-18T05:45:51.2009701Z goroutine 24 [syscall, 10 minutes]:
2021-06-18T05:45:51.2010307Z syscall.Syscall6(0xf7, 0x1, 0x40c9, 0xc000052610, 0x1000004, 0x0, 0x0, 0x0, 0x0, 0x0)
2021-06-18T05:45:51.2011503Z /opt/hostedtoolcache/go/1.15.13/x64/src/syscall/asm_linux_amd64.s:41 +0x5
2021-06-18T05:45:51.2012229Z os.(*Process).blockUntilWaitable(0xc0000a82a0, 0x0, 0x0, 0x0)
2021-06-18T05:45:51.2013728Z /opt/hostedtoolcache/go/1.15.13/x64/src/os/wait_waitid.go:32 +0xa6
2021-06-18T05:45:51.2014536Z os.(*Process).wait(0xc0000a82a0, 0x0, 0x0, 0x0)
2021-06-18T05:45:51.2015117Z /opt/hostedtoolcache/go/1.15.13/x64/src/os/exec_unix.go:22 +0x39
2021-06-18T05:45:51.2015624Z os.(*Process).Wait(...)
2021-06-18T05:45:51.2016137Z /opt/hostedtoolcache/go/1.15.13/x64/src/os/exec.go:125
2021-06-18T05:45:51.2016685Z os/exec.(*Cmd).Wait(0xc0002a49a0, 0x0, 0x0)
2021-06-18T05:45:51.2017260Z /opt/hostedtoolcache/go/1.15.13/x64/src/os/exec/exec.go:507 +0x65
2021-06-18T05:45:51.2018072Z vitess.io/vitess/go/test/endtoend/cluster.(*TopoProcess).SetupEtcd.func1(0xc000341968)
2021-06-18T05:45:51.2019105Z /home/runner/work/vitess/vitess/go/test/endtoend/cluster/topo_process.go:101 +0x32
2021-06-18T05:45:51.2020068Z created by vitess.io/vitess/go/test/endtoend/cluster.(*TopoProcess).SetupEtcd
2021-06-18T05:45:51.2020921Z /home/runner/work/vitess/vitess/go/test/endtoend/cluster/topo_process.go:100 +0x692
2021-06-18T05:45:51.2021345Z
2021-06-18T05:45:51.2021722Z goroutine 55 [select, 10 minutes]:
2021-06-18T05:45:51.2022266Z net/http.(*persistConn).readLoop(0xc0002b8120)
2021-06-18T05:45:51.2022931Z /opt/hostedtoolcache/go/1.15.13/x64/src/net/http/transport.go:2167 +0x9ac
2021-06-18T05:45:51.2023565Z created by net/http.(*Transport).dialConn
2021-06-18T05:45:51.2024217Z /opt/hostedtoolcache/go/1.15.13/x64/src/net/http/transport.go:1715 +0xcb7
2021-06-18T05:45:51.2024612Z
2021-06-18T05:45:51.2025001Z goroutine 56 [select, 10 minutes]:
2021-06-18T05:45:51.2025531Z net/http.(*persistConn).writeLoop(0xc0002b8120)
2021-06-18T05:45:51.2026215Z /opt/hostedtoolcache/go/1.15.13/x64/src/net/http/transport.go:2346 +0x11c
2021-06-18T05:45:51.2026841Z created by net/http.(*Transport).dialConn
2021-06-18T05:45:51.2027516Z /opt/hostedtoolcache/go/1.15.13/x64/src/net/http/transport.go:1716 +0xcdc
2021-06-18T05:45:51.2027910Z
2021-06-18T05:45:51.2028287Z goroutine 59 [syscall, 10 minutes]:
2021-06-18T05:45:51.2028974Z syscall.Syscall6(0xf7, 0x1, 0x40e0, 0xc00027a610, 0x1000004, 0x0, 0x0, 0xc00027a704, 0xc0003fc000, 0x0)
2021-06-18T05:45:51.2029710Z /opt/hostedtoolcache/go/1.15.13/x64/src/syscall/asm_linux_amd64.s:41 +0x5
2021-06-18T05:45:51.2030438Z os.(*Process).blockUntilWaitable(0xc000038870, 0xc0003d87b0, 0x0, 0x0)
2021-06-18T05:45:51.2031136Z /opt/hostedtoolcache/go/1.15.13/x64/src/os/wait_waitid.go:32 +0xa6
2021-06-18T05:45:51.2031766Z os.(*Process).wait(0xc000038870, 0x9, 0xc000088230, 0x1000000010000)
2021-06-18T05:45:51.2032381Z /opt/hostedtoolcache/go/1.15.13/x64/src/os/exec_unix.go:22 +0x39
2021-06-18T05:45:51.2032871Z os.(*Process).Wait(...)
2021-06-18T05:45:51.2033398Z /opt/hostedtoolcache/go/1.15.13/x64/src/os/exec.go:125
2021-06-18T05:45:51.2033939Z os/exec.(*Cmd).Wait(0xc0002a4dc0, 0x0, 0x0)
2021-06-18T05:45:51.2034535Z /opt/hostedtoolcache/go/1.15.13/x64/src/os/exec/exec.go:507 +0x65
2021-06-18T05:45:51.2035321Z vitess.io/vitess/go/test/endtoend/cluster.(*VtctldProcess).Setup.func1(0xc000341a20)
2021-06-18T05:45:51.2036186Z /home/runner/work/vitess/vitess/go/test/endtoend/cluster/vtctld_process.go:95 +0x32
2021-06-18T05:45:51.2037021Z created by vitess.io/vitess/go/test/endtoend/cluster.(*VtctldProcess).Setup
2021-06-18T05:45:51.2038032Z /home/runner/work/vitess/vitess/go/test/endtoend/cluster/vtctld_process.go:94 +0x7a5
2021-06-18T05:45:51.2039608Z
2021-06-18T05:45:51.2040082Z goroutine 57 [select, 10 minutes]:
2021-06-18T05:45:51.2040741Z net/http.(*persistConn).readLoop(0xc0001e6360)
2021-06-18T05:45:51.2041723Z /opt/hostedtoolcache/go/1.15.13/x64/src/net/http/transport.go:2167 +0x9ac
2021-06-18T05:45:51.2043197Z created by net/http.(*Transport).dialConn
2021-06-18T05:45:51.2043872Z /opt/hostedtoolcache/go/1.15.13/x64/src/net/http/transport.go:1715 +0xcb7
2021-06-18T05:45:51.2044262Z
2021-06-18T05:45:51.2044636Z goroutine 58 [select, 10 minutes]:
2021-06-18T05:45:51.2045310Z net/http.(*persistConn).writeLoop(0xc0001e6360)
2021-06-18T05:45:51.2046001Z /opt/hostedtoolcache/go/1.15.13/x64/src/net/http/transport.go:2346 +0x11c
2021-06-18T05:45:51.2046634Z created by net/http.(*Transport).dialConn
2021-06-18T05:45:51.2047288Z /opt/hostedtoolcache/go/1.15.13/x64/src/net/http/transport.go:1716 +0xcdc
2021-06-18T05:45:51.2048045Z
2021-06-18T05:45:51.2048457Z goroutine 49 [select, 10 minutes]:
2021-06-18T05:45:51.2049226Z net/http.(*persistConn).readLoop(0xc0001e6480)
2021-06-18T05:45:51.2049896Z /opt/hostedtoolcache/go/1.15.13/x64/src/net/http/transport.go:2167 +0x9ac
2021-06-18T05:45:51.2050528Z created by net/http.(*Transport).dialConn
2021-06-18T05:45:51.2051177Z /opt/hostedtoolcache/go/1.15.13/x64/src/net/http/transport.go:1715 +0xcb7
2021-06-18T05:45:51.2051567Z
2021-06-18T05:45:51.2052088Z goroutine 66 [select, 10 minutes]:
2021-06-18T05:45:51.2052620Z net/http.(*persistConn).writeLoop(0xc0001e6480)
2021-06-18T05:45:51.2053309Z /opt/hostedtoolcache/go/1.15.13/x64/src/net/http/transport.go:2346 +0x11c
2021-06-18T05:45:51.2054323Z created by net/http.(*Transport).dialConn
2021-06-18T05:45:51.2055081Z /opt/hostedtoolcache/go/1.15.13/x64/src/net/http/transport.go:1716 +0xcdc
2021-06-18T05:45:51.2055522Z
2021-06-18T05:45:51.2055999Z goroutine 70 [syscall, 10 minutes]:
2021-06-18T05:45:51.2056702Z syscall.Syscall6(0xf7, 0x1, 0x4336, 0xc000276610, 0x1000004, 0x0, 0x0, 0x0, 0x0, 0x0)
2021-06-18T05:45:51.2057820Z /opt/hostedtoolcache/go/1.15.13/x64/src/syscall/asm_linux_amd64.s:41 +0x5
2021-06-18T05:45:51.2058592Z os.(*Process).blockUntilWaitable(0xc0000a8570, 0xc0002767b8, 0x6086db, 0xc000342480)
2021-06-18T05:45:51.2059326Z /opt/hostedtoolcache/go/1.15.13/x64/src/os/wait_waitid.go:32 +0xa6
2021-06-18T05:45:51.2060106Z os.(*Process).wait(0xc0000a8570, 0xc0002c0fc0, 0xc000088460, 0x1000000010000)
2021-06-18T05:45:51.2060762Z /opt/hostedtoolcache/go/1.15.13/x64/src/os/exec_unix.go:22 +0x39
2021-06-18T05:45:51.2061252Z os.(*Process).Wait(...)
2021-06-18T05:45:51.2061782Z /opt/hostedtoolcache/go/1.15.13/x64/src/os/exec.go:125
2021-06-18T05:45:51.2062361Z os/exec.(*Cmd).Wait(0xc000221e40, 0xc0000a6010, 0xfe6297)
2021-06-18T05:45:51.2062982Z /opt/hostedtoolcache/go/1.15.13/x64/src/os/exec/exec.go:507 +0x65
2021-06-18T05:45:51.2063798Z vitess.io/vitess/go/test/endtoend/cluster.(*VttabletProcess).Setup.func1(0xc00028c480)
2021-06-18T05:45:51.2064677Z /home/runner/work/vitess/vitess/go/test/endtoend/cluster/vttablet_process.go:138 +0x45
2021-06-18T05:45:51.2065545Z created by vitess.io/vitess/go/test/endtoend/cluster.(*VttabletProcess).Setup
2021-06-18T05:45:51.2066402Z /home/runner/work/vitess/vitess/go/test/endtoend/cluster/vttablet_process.go:136 +0x929
2021-06-18T05:45:51.2066933Z
2021-06-18T05:45:51.2067316Z goroutine 86 [select, 10 minutes]:
2021-06-18T05:45:51.2067859Z net/http.(*persistConn).readLoop(0xc0002b85a0)
2021-06-18T05:45:51.2068531Z /opt/hostedtoolcache/go/1.15.13/x64/src/net/http/transport.go:2167 +0x9ac
2021-06-18T05:45:51.2069316Z created by net/http.(*Transport).dialConn
2021-06-18T05:45:51.2069979Z /opt/hostedtoolcache/go/1.15.13/x64/src/net/http/transport.go:1715 +0xcb7
2021-06-18T05:45:51.2070371Z
2021-06-18T05:45:51.2070760Z goroutine 87 [select, 10 minutes]:
2021-06-18T05:45:51.2071294Z net/http.(*persistConn).writeLoop(0xc0002b85a0)
2021-06-18T05:45:51.2071979Z /opt/hostedtoolcache/go/1.15.13/x64/src/net/http/transport.go:2346 +0x11c
2021-06-18T05:45:51.2072593Z created by net/http.(*Transport).dialConn
2021-06-18T05:45:51.2073259Z /opt/hostedtoolcache/go/1.15.13/x64/src/net/http/transport.go:1716 +0xcdc
2021-06-18T05:45:51.2073649Z
2021-06-18T05:45:51.2074026Z goroutine 92 [syscall, 10 minutes]:
2021-06-18T05:45:51.2074673Z syscall.Syscall6(0xf7, 0x1, 0x4357, 0xc000278610, 0x1000004, 0x0, 0x0, 0x0, 0x0, 0xc00037ea80)
2021-06-18T05:45:51.2075380Z /opt/hostedtoolcache/go/1.15.13/x64/src/syscall/asm_linux_amd64.s:41 +0x5
2021-06-18T05:45:51.2076133Z os.(*Process).blockUntilWaitable(0xc000038630, 0xc000000180, 0x4, 0xc0002787b0)
2021-06-18T05:45:51.2076959Z /opt/hostedtoolcache/go/1.15.13/x64/src/os/wait_waitid.go:32 +0xa6
2021-06-18T05:45:51.2077567Z os.(*Process).wait(0xc000038630, 0x0, 0x0, 0xc000010298)
2021-06-18T05:45:51.2078169Z /opt/hostedtoolcache/go/1.15.13/x64/src/os/exec_unix.go:22 +0x39
2021-06-18T05:45:51.2079582Z os.(*Process).Wait(...)
2021-06-18T05:45:51.2080132Z /opt/hostedtoolcache/go/1.15.13/x64/src/os/exec.go:125
2021-06-18T05:45:51.2080693Z os/exec.(*Cmd).Wait(0xc000221ce0, 0xc0002787b0, 0x0)
2021-06-18T05:45:51.2081302Z /opt/hostedtoolcache/go/1.15.13/x64/src/os/exec/exec.go:507 +0x65
2021-06-18T05:45:51.2082095Z vitess.io/vitess/go/test/endtoend/cluster.(*VtgateProcess).Setup.func1(0xc000290000)
2021-06-18T05:45:51.2082945Z /home/runner/work/vitess/vitess/go/test/endtoend/cluster/vtgate_process.go:111 +0x45
2021-06-18T05:45:51.2083787Z created by vitess.io/vitess/go/test/endtoend/cluster.(*VtgateProcess).Setup
2021-06-18T05:45:51.2084758Z /home/runner/work/vitess/vitess/go/test/endtoend/cluster/vtgate_process.go:109 +0x805
2021-06-18T05:45:51.2085198Z
2021-06-18T05:45:51.2085592Z goroutine 805 [select, 10 minutes]:
2021-06-18T05:45:51.2086131Z net/http.(*persistConn).writeLoop(0xc00031ea20)
2021-06-18T05:45:51.2086819Z /opt/hostedtoolcache/go/1.15.13/x64/src/net/http/transport.go:2346 +0x11c
2021-06-18T05:45:51.2087432Z created by net/http.(*Transport).dialConn
2021-06-18T05:45:51.2088513Z /opt/hostedtoolcache/go/1.15.13/x64/src/net/http/transport.go:1716 +0xcdc
2021-06-18T05:45:51.2088940Z
2021-06-18T05:45:51.2089586Z goroutine 5429 [sleep]:
2021-06-18T05:45:51.2090238Z time.Sleep(0x3b9aca00)
2021-06-18T05:45:51.2090875Z /opt/hostedtoolcache/go/1.15.13/x64/src/runtime/time.go:188 +0xbf
2021-06-18T05:45:51.2092205Z vitess.io/vitess/go/test/endtoend/onlineddl/vrepl_suite.waitForMigration(0xc000558180, 0xc00037d560, 0x24, 0x28fa6ae00, 0x0)
2021-06-18T05:45:51.2093339Z /home/runner/work/vitess/vitess/go/test/endtoend/onlineddl/vrepl_suite/onlineddl_vrepl_suite_test.go:325 +0x4a
2021-06-18T05:45:51.2094345Z vitess.io/vitess/go/test/endtoend/onlineddl/vrepl_suite.testSingle(0xc000558180, 0xc000667cf9, 0x7)
2021-06-18T05:45:51.2095373Z /home/runner/work/vitess/vitess/go/test/endtoend/onlineddl/vrepl_suite/onlineddl_vrepl_suite_test.go:243 +0x851
2021-06-18T05:45:51.2096454Z vitess.io/vitess/go/test/endtoend/onlineddl/vrepl_suite.TestSchemaChange.func1(0xc000558180)
2021-06-18T05:45:51.2098991Z /home/runner/work/vitess/vitess/go/test/endtoend/onlineddl/vrepl_suite/onlineddl_vrepl_suite_test.go:149 +0x45
2021-06-18T05:45:51.2100554Z testing.tRunner(0xc000558180, 0xc0003c43f0)
2021-06-18T05:45:51.2101492Z /opt/hostedtoolcache/go/1.15.13/x64/src/testing/testing.go:1123 +0xef
2021-06-18T05:45:51.2102243Z created by testing.(*T).Run
2021-06-18T05:45:51.2102854Z /opt/hostedtoolcache/go/1.15.13/x64/src/testing/testing.go:1168 +0x2b3
2021-06-18T05:45:51.2103264Z
2021-06-18T05:45:51.2103830Z goroutine 806 [chan receive]:
2021-06-18T05:45:51.2104806Z testing.(*T).Run(0xc000558180, 0xc000667cf9, 0x7, 0xc0003c43f0, 0x1)
2021-06-18T05:45:51.2105620Z /opt/hostedtoolcache/go/1.15.13/x64/src/testing/testing.go:1169 +0x2da
2021-06-18T05:45:51.2106664Z vitess.io/vitess/go/test/endtoend/onlineddl/vrepl_suite.TestSchemaChange(0xc000116f00)
2021-06-18T05:45:51.2108245Z /home/runner/work/vitess/vitess/go/test/endtoend/onlineddl/vrepl_suite/onlineddl_vrepl_suite_test.go:148 +0x288
2021-06-18T05:45:51.2108989Z testing.tRunner(0xc000116f00, 0x10353b0)
2021-06-18T05:45:51.2110027Z /opt/hostedtoolcache/go/1.15.13/x64/src/testing/testing.go:1123 +0xef
2021-06-18T05:45:51.2111035Z created by testing.(*T).Run
2021-06-18T05:45:51.2111753Z /opt/hostedtoolcache/go/1.15.13/x64/src/testing/testing.go:1168 +0x2b3
2021-06-18T05:45:51.2112214Z
2021-06-18T05:45:51.2112671Z goroutine 804 [select, 10 minutes]:
2021-06-18T05:45:51.2113678Z net/http.(*persistConn).readLoop(0xc00031ea20)
2021-06-18T05:45:51.2114909Z /opt/hostedtoolcache/go/1.15.13/x64/src/net/http/transport.go:2167 +0x9ac
2021-06-18T05:45:51.2115545Z created by net/http.(*Transport).dialConn
2021-06-18T05:45:51.2116374Z /opt/hostedtoolcache/go/1.15.13/x64/src/net/http/transport.go:1715 +0xcb7
2021-06-18T05:45:51.2117148Z FAIL vitess.io/vitess/go/test/endtoend/onlineddl/vrepl_suite 639.940s
2021-06-18T05:45:51.2119416Z FAIL
2021-06-18T05:45:51.2298220Z 2021/06/18 05:45:51 local.onlineddl_vrepl_suite: saving test output to _test/20210618-052136.5988/local.onlineddl_vrepl_suite-1.2.log
2021-06-18T05:45:51.2300972Z 2021/06/18 05:45:51 local.onlineddl_vrepl_suite: FAILED (try 2/3) in 10m41.5s: exit status 1
2021-06-18T05:45:51.2302121Z 2021/06/18 05:45:51 local.onlineddl_vrepl_suite: running (try 3/3)...
2021-06-18T05:45:51.2694510Z running tests for vitess.io/vitess/go/test/endtoend/onlineddl/vrepl_suite
2021-06-18T05:45:52.8453380Z I0618 05:45:52.844805 18818 cluster_process.go:633] Attempting to reserve port: 16401
2021-06-18T05:45:52.8465157Z I0618 05:45:52.846349 18818 cluster_process.go:641] Port 16401 is available, reserving..
2021-06-18T05:45:52.8469929Z I0618 05:45:52.846762 18818 cluster_process.go:475] Created cluster on /home/runner/work/vitess/vitess/vtdataroot/vt_895410998/vtroot_16401. ReusingVTDATAROOT=false
2021-06-18T05:45:52.8473800Z I0618 05:45:52.847211 18818 cluster_process.go:633] Attempting to reserve port: 16402
2021-06-18T05:45:52.8476321Z I0618 05:45:52.847517 18818 cluster_process.go:641] Port 16402 is available, reserving..
2021-06-18T05:45:52.8477461Z I0618 05:45:52.847542 18818 cluster_process.go:633] Attempting to reserve port: 16403
2021-06-18T05:45:52.8479889Z I0618 05:45:52.847877 18818 cluster_process.go:641] Port 16403 is available, reserving..
2021-06-18T05:45:52.8481018Z I0618 05:45:52.847901 18818 cluster_process.go:633] Attempting to reserve port: 16404
2021-06-18T05:45:52.8483393Z I0618 05:45:52.848229 18818 cluster_process.go:641] Port 16404 is available, reserving..
2021-06-18T05:45:52.8485606Z I0618 05:45:52.848451 18818 cluster_process.go:186] Starting topo server etcd2 on port: 16402
2021-06-18T05:45:52.8491161Z E0618 05:45:52.848757 18818 topo_process.go:92] Starting etcd with command: etcd --name global --data-dir /home/runner/work/vitess/vitess/vtdataroot/vt_895410998/vtroot_16401/topo_16402 --listen-client-urls http://localhost:16402 --advertise-client-urls http://localhost:16402 --initial-advertise-peer-urls http://localhost:16404 --listen-peer-urls http://localhost:16404 --initial-cluster global=http://localhost:16404 --enable-v2=true
2021-06-18T05:45:53.8699334Z I0618 05:45:53.868853 18818 cluster_process.go:193] Creating global and cell topo dirs
2021-06-18T05:45:53.8712741Z I0618 05:45:53.870904 18818 vtctl_process.go:55] Adding CellInfo for cell zone1 with command: vtctl -topo_implementation etcd2 -topo_global_server_address localhost:16402 -topo_global_root /vitess/global AddCellInfo -root /zone1 -server_address localhost:16402 zone1
2021-06-18T05:45:53.9106286Z I0618 05:45:53.910083 18818 cluster_process.go:633] Attempting to reserve port: 16405
2021-06-18T05:45:53.9107281Z I0618 05:45:53.910141 18818 cluster_process.go:641] Port 16405 is available, reserving..
2021-06-18T05:45:53.9108651Z I0618 05:45:53.910155 18818 cluster_process.go:633] Attempting to reserve port: 16406
2021-06-18T05:45:53.9109679Z I0618 05:45:53.910175 18818 cluster_process.go:641] Port 16406 is available, reserving..
2021-06-18T05:45:53.9110383Z I0618 05:45:53.910192 18818 cluster_process.go:215] Starting vtctld server on port: 16405
2021-06-18T05:45:53.9114340Z I0618 05:45:53.910309 18818 vtctld_process.go:86] Starting vtctld with command: vtctld -enable_queries -topo_implementation etcd2 -topo_global_server_address localhost:16402 -topo_global_root /vitess/global -cell zone1 -workflow_manager_init -workflow_manager_use_election -service_map grpc-vtctl -backup_storage_implementation file -file_backup_storage_root /home/runner/work/vitess/vitess/vtdataroot/vt_895410998/vtroot_16401/backups -wait_for_drain_sleep_rdonly 1s -wait_for_drain_sleep_replica 1s -online_ddl_check_interval 2s -log_dir /home/runner/work/vitess/vitess/vtdataroot/vt_895410998/vtroot_16401/tmp_16403 -port 16405 -grpc_port 16406 -schema_change_dir /tmp/schema_change_dir_7955 -schema_change_controller local -schema_change_check_interval 1 -online_ddl_check_interval 2s
2021-06-18T05:45:54.2148497Z I0618 05:45:54.214491 18818 cluster_process.go:244] Starting keyspace: ks
2021-06-18T05:45:54.2150369Z I0618 05:45:54.214526 18818 vtctl_process.go:72] Running CreateKeyspace with command: vtctl -topo_implementation etcd2 -topo_global_server_address localhost:16402 -topo_global_root /vitess/global CreateKeyspace ks
2021-06-18T05:45:54.2588811Z I0618 05:45:54.258527 18818 cluster_process.go:253] Starting shard: 1
2021-06-18T05:45:54.2589543Z I0618 05:45:54.258547 18818 cluster_process.go:633] Attempting to reserve port: 16407
2021-06-18T05:45:54.2591259Z I0618 05:45:54.258581 18818 cluster_process.go:641] Port 16407 is available, reserving..
2021-06-18T05:45:54.2592212Z I0618 05:45:54.258597 18818 cluster_process.go:633] Attempting to reserve port: 16408
2021-06-18T05:45:54.2592935Z I0618 05:45:54.258613 18818 cluster_process.go:641] Port 16408 is available, reserving..
2021-06-18T05:45:54.2593600Z I0618 05:45:54.258620 18818 cluster_process.go:633] Attempting to reserve port: 16409
2021-06-18T05:45:54.2594278Z I0618 05:45:54.258653 18818 cluster_process.go:641] Port 16409 is available, reserving..
2021-06-18T05:45:54.2595079Z I0618 05:45:54.258666 18818 cluster_process.go:272] Starting mysqlctl for table uid 7956, mysql port 16409
2021-06-18T05:45:54.2596920Z I0618 05:45:54.258687 18818 mysqlctl_process.go:124] Starting mysqlctl with command: [mysqlctl -log_dir /home/runner/work/vitess/vitess/vtdataroot/vt_895410998/vtroot_16401/tmp_16403 -tablet_uid 7956 -mysql_port 16409 init -init_db_sql_file /home/runner/work/vitess/vitess/config/init_db.sql start]
2021-06-18T05:45:57.3372640Z I0618 05:45:57.337002 18818 cluster_process.go:325] Starting vttablet for tablet uid 7956, grpc port 16408
2021-06-18T05:45:57.3380540Z I0618 05:45:57.337098 18818 vttablet_process.go:128] Running vttablet with command: vttablet -topo_implementation etcd2 -topo_global_server_address localhost:16402 -topo_global_root /vitess/global -log_queries_to_file /home/runner/work/vitess/vitess/vtdataroot/vt_895410998/vtroot_16401/tmp_16403/vt_0000007956_querylog.txt -tablet-path zone1-0000007956 -port 16407 -grpc_port 16408 -init_shard 1 -log_dir /home/runner/work/vitess/vitess/vtdataroot/vt_895410998/vtroot_16401/tmp_16403 -tablet_hostname localhost -init_keyspace ks -init_tablet_type replica -health_check_interval 5s -enable_replication_reporter -backup_storage_implementation file -file_backup_storage_root /home/runner/work/vitess/vitess/vtdataroot/vt_895410998/vtroot_16401/backups -service_map grpc-queryservice,grpc-tabletmanager,grpc-updatestream,grpc-throttler -vtctld_addr http://localhost:16405 -vtctld_addr http://localhost:16405 -vreplication_tablet_type replica -restore_from_backup -enable-lag-throttler -throttle_threshold 1s -heartbeat_enable -heartbeat_interval 250ms -migration_check_interval 5s
2021-06-18T05:46:02.4791446Z I0618 05:46:02.478723 18818 vtctlclient_process.go:177] Executing vtctlclient with command: vtctlclient -server localhost:16406 InitShardMaster -force -wait_replicas_timeout 31s ks/1 zone1-7956
2021-06-18T05:46:02.5304080Z I0618 05:46:02.530125 18818 cluster_process.go:368] Done creating keyspace: ks
2021-06-18T05:46:02.5306171Z I0618 05:46:02.530150 18818 cluster_process.go:633] Attempting to reserve port: 16410
2021-06-18T05:46:02.5307282Z I0618 05:46:02.530186 18818 cluster_process.go:641] Port 16410 is available, reserving..
2021-06-18T05:46:02.5308481Z I0618 05:46:02.530199 18818 cluster_process.go:633] Attempting to reserve port: 16411
2021-06-18T05:46:02.5309627Z I0618 05:46:02.530221 18818 cluster_process.go:641] Port 16411 is available, reserving..
2021-06-18T05:46:02.5310741Z I0618 05:46:02.530228 18818 cluster_process.go:633] Attempting to reserve port: 16412
2021-06-18T05:46:02.5312503Z I0618 05:46:02.530243 18818 cluster_process.go:641] Port 16412 is available, reserving..
2021-06-18T05:46:02.5320200Z I0618 05:46:02.530308 18818 vtgate_process.go:102] Running vtgate with command: vtgate -topo_implementation etcd2 -topo_global_server_address localhost:16402 -topo_global_root /vitess/global -log_dir /home/runner/work/vitess/vitess/vtdataroot/vt_895410998/vtroot_16401/tmp_16403 -log_queries_to_file /home/runner/work/vitess/vitess/vtdataroot/vt_895410998/vtroot_16401/tmp_16403/vtgate_querylog.txt -port 16410 -grpc_port 16411 -mysql_server_port 16412 -mysql_server_socket_path /home/runner/work/vitess/vitess/vtdataroot/vt_895410998/vtroot_16401/tmp_16403/mysql.sock -cell zone1 -cells_to_watch zone1 -tablet_types_to_wait MASTER,REPLICA -gateway_implementation tabletgateway -service_map grpc-tabletmanager,grpc-throttler,grpc-queryservice,grpc-updatestream,grpc-vtctl,grpc-vtworker,grpc-vtgateservice -mysql_auth_server_impl none
2021-06-18T05:46:32.6103752Z === RUN TestSchemaChange
2021-06-18T05:46:32.6106779Z === RUN TestSchemaChange/alter-charset-non-utf8
2021-06-18T05:46:42.6738788Z === RUN TestSchemaChange/alter-charset-non-utf8-80
2021-06-18T05:46:42.6753346Z ##[error] onlineddl_vrepl_suite_test.go:180: Skipping test due to ignore_versions=(5.5|5.6|5.7)
2021-06-18T05:46:42.6760273Z === RUN TestSchemaChange/autoinc-copy-deletes
2021-06-18T05:46:52.7344522Z === RUN TestSchemaChange/autoinc-copy-deletes-user-defined
2021-06-18T05:47:02.7913637Z === RUN TestSchemaChange/autoinc-copy-simple
2021-06-18T05:47:12.8534357Z === RUN TestSchemaChange/autoinc-zero-value
2021-06-18T05:47:22.9086056Z === RUN TestSchemaChange/bigint-change-nullable
2021-06-18T05:47:32.9657421Z === RUN TestSchemaChange/bit-add
2021-06-18T05:47:43.0248754Z === RUN TestSchemaChange/bit-dml
2021-06-18T05:47:53.0946697Z === RUN TestSchemaChange/convert-utf8mb4
2021-06-18T05:48:03.1607757Z === RUN TestSchemaChange/datetime
2021-06-18T05:48:13.2221985Z === RUN TestSchemaChange/datetime-1970
2021-06-18T05:48:23.2816084Z === RUN TestSchemaChange/datetime-submillis
2021-06-18T05:48:33.3443458Z === RUN TestSchemaChange/datetime-submillis-zeroleading
2021-06-18T05:48:43.4009194Z === RUN TestSchemaChange/datetime-to-timestamp
2021-06-18T05:48:53.4603333Z === RUN TestSchemaChange/datetime-to-timestamp-pk
2021-06-18T05:49:03.5313756Z === RUN TestSchemaChange/decimal
2021-06-18T05:49:13.6000942Z === RUN TestSchemaChange/drop-null-add-not-null
2021-06-18T05:49:23.6590030Z === RUN TestSchemaChange/enum
2021-06-18T05:49:32.7159401Z === RUN TestSchemaChange/enum-pk
2021-06-18T05:49:42.7737416Z === RUN TestSchemaChange/enum-to-varchar
2021-06-18T05:49:52.8322282Z === RUN TestSchemaChange/enum-to-varchar-rename
2021-06-18T05:50:02.8944728Z === RUN TestSchemaChange/fail-drop-pk
2021-06-18T05:50:07.9324680Z === RUN TestSchemaChange/fail-fk-child
2021-06-18T05:50:12.9648165Z === RUN TestSchemaChange/fail-fk-parent
2021-06-18T05:50:17.9978680Z === RUN TestSchemaChange/fail-float-unique-key
2021-06-18T05:50:23.0314338Z === RUN TestSchemaChange/fail-no-unique-key
2021-06-18T05:50:28.0667076Z === RUN TestSchemaChange/fail-nonexistent-column
2021-06-18T05:50:33.1054861Z === RUN TestSchemaChange/fail-rename-table
2021-06-18T05:50:33.1209004Z === RUN TestSchemaChange/fail-syntax-error
2021-06-18T05:50:33.1357399Z === RUN TestSchemaChange/gbk-charset
2021-06-18T05:50:43.1920463Z === RUN TestSchemaChange/generated-columns-add57
2021-06-18T05:50:53.2465680Z === RUN TestSchemaChange/generated-columns-rename57
2021-06-18T05:51:03.3024411Z === RUN TestSchemaChange/generated-columns57
2021-06-18T05:51:13.3621178Z === RUN TestSchemaChange/generated-columns57-unique
2021-06-18T05:51:23.4257696Z === RUN TestSchemaChange/geometry57
2021-06-18T05:51:33.4825975Z === RUN TestSchemaChange/json57
2021-06-18T05:51:40.9009444Z ##[error]The action has timed out.
2021-06-18T05:51:40.9099035Z Post job cleanup.
2021-06-18T05:51:41.0151766Z [command]/usr/bin/git version
2021-06-18T05:51:41.0209791Z git version 2.32.0
2021-06-18T05:51:41.0253033Z [command]/usr/bin/git config --local --name-only --get-regexp core\.sshCommand
2021-06-18T05:51:41.0292800Z [command]/usr/bin/git submodule foreach --recursive git config --local --name-only --get-regexp 'core\.sshCommand' && git config --local --unset-all 'core.sshCommand' || :
2021-06-18T05:51:41.0610951Z [command]/usr/bin/git config --local --name-only --get-regexp http\.https\:\/\/github\.com\/\.extraheader
2021-06-18T05:51:41.0623982Z http.https://github.com/.extraheader
2021-06-18T05:51:41.0636800Z [command]/usr/bin/git config --local --unset-all http.https://github.com/.extraheader
2021-06-18T05:51:41.0688614Z [command]/usr/bin/git submodule foreach --recursive git config --local --name-only --get-regexp 'http\.https\:\/\/github\.com\/\.extraheader' && git config --local --unset-all 'http.https://github.com/.extraheader' || :
2021-06-18T05:51:41.1007187Z Cleaning up orphan processes
2021-06-18T05:51:41.1324584Z Terminate orphan process: pid (5933) (go)
2021-06-18T05:51:41.1353551Z Terminate orphan process: pid (5988) (test)
2021-06-18T05:51:41.1387481Z Terminate orphan process: pid (16608) (vtctld)
2021-06-18T05:51:41.1413848Z Terminate orphan process: pid (17206) (vttablet)
2021-06-18T05:51:41.1436527Z Terminate orphan process: pid (17239) (vtgate)
2021-06-18T05:51:41.1505149Z Terminate orphan process: pid (18742) (e2e_go_test.sh)
2021-06-18T05:51:41.1526458Z Terminate orphan process: pid (18767) (go)
2021-06-18T05:51:41.1551368Z Terminate orphan process: pid (18818) (vrepl_suite.test)
2021-06-18T05:51:41.1577777Z Terminate orphan process: pid (18826) (etcd)
2021-06-18T05:51:41.1631024Z Terminate orphan process: pid (18847) (vtctld)
2021-06-18T05:51:41.1661881Z Terminate orphan process: pid (19451) (vttablet)
2021-06-18T05:51:41.1709823Z Terminate orphan process: pid (19488) (vtgate)
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment