Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Windows TestFunctional/parallel/DockerEnv takes too long causes timeout error #10135

Closed
lingsamuel opened this issue Jan 13, 2021 · 0 comments · Fixed by #10137
Closed

Windows TestFunctional/parallel/DockerEnv takes too long causes timeout error #10135

lingsamuel opened this issue Jan 13, 2021 · 0 comments · Fixed by #10137
Labels
kind/failing-test Categorizes issue or PR as related to a consistently or frequently failing test. kind/flake Categorizes issue or PR as related to a flaky test.

Comments

@lingsamuel
Copy link
Contributor

lingsamuel commented Jan 13, 2021 •
edited
Loading

full.log

Sometimes DockerEnv test failed (powershell.exe -NoProfile -NonInteractive "./minikube-windows-amd64.exe -p functional-20210113052654-3348 docker-env | Invoke-Expression ;./minikube-windows-amd64.exe status -p functional-20210113052654-3348):

2021-01-13T03:16:56.9120811Z === CONT  TestFunctional/parallel/DockerEnv
2021-01-13T03:16:56.9129050Z     functional_test.go:170: (dbg) Non-zero exit: powershell.exe -NoProfile -NonInteractive "./minikube-windows-amd64.exe -p functional-20210113030855-13028 docker-env | Invoke-Expression ;./minikube-windows-amd64.exe status -p functional-20210113030855-13028": exit status 1 (30.1872674s)
2021-01-13T03:16:56.9134229Z         
2021-01-13T03:16:56.9135547Z         -- stdout --
2021-01-13T03:16:56.9138329Z         	functional-20210113030855-13028
2021-01-13T03:16:56.9140234Z         	type: Control Plane
2021-01-13T03:16:56.9148148Z         	host: Running
2021-01-13T03:16:56.9164538Z         	kubelet: Running
2021-01-13T03:16:56.9178195Z         	apiserver: Running
2021-01-13T03:16:56.9189443Z         	kubeconfig: Configured
2021-01-13T03:16:56.9199817Z         	timeToStop: Nonexistent
2021-01-13T03:16:56.9205806Z         	
2021-01-13T03:16:56.9212777Z         
2021-01-13T03:16:56.9220376Z         -- /stdout --
2021-01-13T03:16:56.9233312Z     functional_test.go:177: failed to run the command by deadline. exceeded timeout. powershell.exe -NoProfile -NonInteractive "./minikube-windows-amd64.exe -p functional-20210113030855-13028 docker-env | Invoke-Expression ;./minikube-windows-amd64.exe status -p functional-20210113030855-13028"

So in this debug pr I added one more step to view how long a docker-env and status taken. In windows both need 10s:


2021-01-12T14:17:56.5941489Z     functional_test.go:170: (dbg) Run:  ./minikube-windows-amd64.exe docker-env -p functional-20210112140056-2244 --alsologtostderr -v=8
2021-01-12T14:18:07.1033030Z     functional_test.go:170: (dbg) Done: ./minikube-windows-amd64.exe docker-env -p functional-20210112140056-2244 --alsologtostderr -v=8: (10.5097973s)
2021-01-12T14:18:07.1041076Z     functional_test.go:171: 
2021-01-12T14:18:07.1045038Z         -- stdout --
2021-01-12T14:18:07.1050790Z         	$Env:DOCKER_TLS_VERIFY = "1"
2021-01-12T14:18:07.1055445Z         	$Env:DOCKER_HOST = "tcp://192.168.13.2:2376"
2021-01-12T14:18:07.1062630Z         	$Env:DOCKER_CERT_PATH = "C:\Users\jenkins\actions-runner\_work\minikube\minikube\minikube_binaries\testhome\.minikube\certs"
2021-01-12T14:18:07.1066849Z         	$Env:MINIKUBE_ACTIVE_DOCKERD = "functional-20210112140056-2244"
2021-01-12T14:18:07.1072075Z         	# To point your shell to minikube's docker-daemon, run:
2021-01-12T14:18:07.1078548Z         	# & minikube -p functional-20210112140056-2244 docker-env | Invoke-Expression
2021-01-12T14:18:07.1082546Z         
2021-01-12T14:18:07.1088231Z         -- /stdout --
2021-01-12T14:18:07.1092594Z         ** stderr ** 
2021-01-12T14:18:07.1097340Z         	I0112 14:17:57.170699   15920 out.go:221] Setting OutFile to fd 1604 ...
2021-01-12T14:18:07.1102846Z         	I0112 14:17:57.254703   15920 out.go:268] TERM=,COLORTERM=, which probably does not support color
2021-01-12T14:18:07.1112013Z         	I0112 14:17:57.254703   15920 out.go:234] Setting ErrFile to fd 1616...
2021-01-12T14:18:07.1117094Z         	I0112 14:17:57.254703   15920 out.go:268] TERM=,COLORTERM=, which probably does not support color
2021-01-12T14:18:07.1122035Z         	I0112 14:17:57.313706   15920 mustload.go:66] Loading cluster: functional-20210112140056-2244
2021-01-12T14:18:07.1126593Z         	I0112 14:17:57.316706   15920 main.go:119] libmachine: [executing ==>] : C:\windows\System32\WindowsPowerShell\v1.0\powershell.exe -NoProfile -NonInteractive ( Hyper-V\Get-VM functional-20210112140056-2244 ).state
2021-01-12T14:18:07.1131285Z         	I0112 14:17:58.833778   15920 main.go:119] libmachine: [stdout =====>] : Running
2021-01-12T14:18:07.1137169Z         	
2021-01-12T14:18:07.1141848Z         	I0112 14:17:58.833778   15920 main.go:119] libmachine: [stderr =====>] : 
2021-01-12T14:18:07.1148406Z         	I0112 14:17:58.833778   15920 host.go:66] Checking if "functional-20210112140056-2244" exists ...
2021-01-12T14:18:07.1151683Z         	I0112 14:17:58.857780   15920 ssh_runner.go:149] Run: systemctl --version
2021-01-12T14:18:07.1160136Z         	I0112 14:17:58.857780   15920 main.go:119] libmachine: [executing ==>] : C:\windows\System32\WindowsPowerShell\v1.0\powershell.exe -NoProfile -NonInteractive ( Hyper-V\Get-VM functional-20210112140056-2244 ).state
2021-01-12T14:18:07.1163313Z         	I0112 14:18:00.388135   15920 main.go:119] libmachine: [stdout =====>] : Running
2021-01-12T14:18:07.1169097Z         	
2021-01-12T14:18:07.1172718Z         	I0112 14:18:00.388135   15920 main.go:119] libmachine: [stderr =====>] : 
2021-01-12T14:18:07.1179124Z         	I0112 14:18:00.388135   15920 main.go:119] libmachine: [executing ==>] : C:\windows\System32\WindowsPowerShell\v1.0\powershell.exe -NoProfile -NonInteractive (( Hyper-V\Get-VM functional-20210112140056-2244 ).networkadapters[0]).ipaddresses[0]
2021-01-12T14:18:07.1184720Z         	I0112 14:18:02.708714   15920 main.go:119] libmachine: [stdout =====>] : 192.168.13.2
2021-01-12T14:18:07.1188930Z         	
2021-01-12T14:18:07.1195134Z         	I0112 14:18:02.708714   15920 main.go:119] libmachine: [stderr =====>] : 
2021-01-12T14:18:07.1201594Z         	I0112 14:18:02.708714   15920 sshutil.go:48] new ssh client: &{IP:192.168.13.2 Port:22 SSHKeyPath:C:\Users\jenkins\actions-runner\_work\minikube\minikube\minikube_binaries\testhome\.minikube\machines\functional-20210112140056-2244\id_rsa Username:docker}
2021-01-12T14:18:07.1205998Z         	I0112 14:18:02.806652   15920 command_runner.go:123] > systemd 244 (244)
2021-01-12T14:18:07.1211341Z         	I0112 14:18:02.806652   15920 command_runner.go:123] > -PAM -AUDIT -SELINUX -IMA -APPARMOR -SMACK +SYSVINIT +UTMP -LIBCRYPTSETUP -GCRYPT -GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD -IDN2 -IDN -PCRE2 default-hierarchy=hybrid
2021-01-12T14:18:07.1217887Z         	I0112 14:18:02.806652   15920 ssh_runner.go:189] Completed: systemctl --version: (3.9488778s)
2021-01-12T14:18:07.1222941Z         	I0112 14:18:02.830653   15920 ssh_runner.go:149] Run: sudo systemctl is-active --quiet service docker
2021-01-12T14:18:07.1229905Z         	I0112 14:18:02.842683   15920 main.go:119] libmachine: [executing ==>] : C:\windows\System32\WindowsPowerShell\v1.0\powershell.exe -NoProfile -NonInteractive ( Hyper-V\Get-VM functional-20210112140056-2244 ).state
2021-01-12T14:18:07.1244100Z         	I0112 14:18:04.351426   15920 main.go:119] libmachine: [stdout =====>] : Running
2021-01-12T14:18:07.1244558Z         	
2021-01-12T14:18:07.1245718Z         	I0112 14:18:04.351426   15920 main.go:119] libmachine: [stderr =====>] : 
2021-01-12T14:18:07.1250361Z         	I0112 14:18:04.351426   15920 main.go:119] libmachine: [executing ==>] : C:\windows\System32\WindowsPowerShell\v1.0\powershell.exe -NoProfile -NonInteractive (( Hyper-V\Get-VM functional-20210112140056-2244 ).networkadapters[0]).ipaddresses[0]
2021-01-12T14:18:07.1254939Z         	I0112 14:18:06.699961   15920 main.go:119] libmachine: [stdout =====>] : 192.168.13.2
2021-01-12T14:18:07.1261176Z         	
2021-01-12T14:18:07.1269051Z         	I0112 14:18:06.699961   15920 main.go:119] libmachine: [stderr =====>] : 
2021-01-12T14:18:07.1271934Z         	I0112 14:18:06.728958   15920 docker-env.go:462] Testing Docker connectivity with: C:\Program Files\Docker\Docker\resources\bin\docker.exe version --format={{.Server}}
2021-01-12T14:18:07.1275667Z         
2021-01-12T14:18:07.1282253Z         ** /stderr **

2021-01-13T06:44:38.1859318Z     functional_test.go:175: (dbg) Done: ./minikube-windows-amd64.exe status -p functional-20210113062608-9468 --alsologtostderr -v=8: (10.2040813s)
2021-01-13T06:44:38.1862782Z     functional_test.go:176: 
2021-01-13T06:44:38.1867836Z         -- stdout --
2021-01-13T06:44:38.1875493Z         	functional-20210113062608-9468
2021-01-13T06:44:38.1881736Z         	type: Control Plane
2021-01-13T06:44:38.1885947Z         	host: Running
2021-01-13T06:44:38.1891334Z         	kubelet: Running
2021-01-13T06:44:38.1895299Z         	apiserver: Running
2021-01-13T06:44:38.1901490Z         	kubeconfig: Configured
2021-01-13T06:44:38.1905644Z         	timeToStop: Nonexistent
2021-01-13T06:44:38.1912283Z         	
2021-01-13T06:44:38.1915879Z         
2021-01-13T06:44:38.1921856Z         -- /stdout --
2021-01-13T06:44:38.1927331Z         ** stderr ** 
2021-01-13T06:44:38.1941970Z         	I0113 06:44:28.546359   14280 out.go:225] Setting OutFile to fd 1572 ...
2021-01-13T06:44:38.1947245Z         	I0113 06:44:28.637305   14280 out.go:272] TERM=,COLORTERM=, which probably does not support color
2021-01-13T06:44:38.1952845Z         	I0113 06:44:28.637305   14280 out.go:238] Setting ErrFile to fd 1620...
2021-01-13T06:44:38.1958187Z         	I0113 06:44:28.637305   14280 out.go:272] TERM=,COLORTERM=, which probably does not support color
2021-01-13T06:44:38.1962603Z         	I0113 06:44:28.661320   14280 out.go:232] Setting JSON to false
2021-01-13T06:44:38.1968395Z         	I0113 06:44:28.661320   14280 mustload.go:66] Loading cluster: functional-20210113062608-9468
2021-01-13T06:44:38.1974590Z         	I0113 06:44:28.662341   14280 status.go:241] checking status of functional-20210113062608-9468 ...
2021-01-13T06:44:38.1979524Z         	I0113 06:44:28.664322   14280 main.go:119] libmachine: [executing ==>] : C:\windows\System32\WindowsPowerShell\v1.0\powershell.exe -NoProfile -NonInteractive ( Hyper-V\Get-VM functional-20210113062608-9468 ).state
2021-01-13T06:44:38.1982865Z         	I0113 06:44:30.202172   14280 main.go:119] libmachine: [stdout =====>] : Running
2021-01-13T06:44:38.1987308Z         	
2021-01-13T06:44:38.1993810Z         	I0113 06:44:30.202172   14280 main.go:119] libmachine: [stderr =====>] : 
2021-01-13T06:44:38.1997712Z         	I0113 06:44:30.202172   14280 status.go:317] functional-20210113062608-9468 host status = "Running" (err=<nil>)
2021-01-13T06:44:38.2004985Z         	I0113 06:44:30.202172   14280 host.go:66] Checking if "functional-20210113062608-9468" exists ...
2021-01-13T06:44:38.2011475Z         	I0113 06:44:30.204243   14280 main.go:119] libmachine: [executing ==>] : C:\windows\System32\WindowsPowerShell\v1.0\powershell.exe -NoProfile -NonInteractive ( Hyper-V\Get-VM functional-20210113062608-9468 ).state
2021-01-13T06:44:38.2016036Z         	I0113 06:44:31.720538   14280 main.go:119] libmachine: [stdout =====>] : Running
2021-01-13T06:44:38.2021343Z         	
2021-01-13T06:44:38.2030127Z         	I0113 06:44:31.720538   14280 main.go:119] libmachine: [stderr =====>] : 
2021-01-13T06:44:38.2035001Z         	I0113 06:44:31.720538   14280 main.go:119] libmachine: [executing ==>] : C:\windows\System32\WindowsPowerShell\v1.0\powershell.exe -NoProfile -NonInteractive (( Hyper-V\Get-VM functional-20210113062608-9468 ).networkadapters[0]).ipaddresses[0]
2021-01-13T06:44:38.2040707Z         	I0113 06:44:34.009389   14280 main.go:119] libmachine: [stdout =====>] : 192.168.13.13
2021-01-13T06:44:38.2047401Z         	
2021-01-13T06:44:38.2054899Z         	I0113 06:44:34.009389   14280 main.go:119] libmachine: [stderr =====>] : 
2021-01-13T06:44:38.2060557Z         	I0113 06:44:34.009389   14280 host.go:66] Checking if "functional-20210113062608-9468" exists ...
2021-01-13T06:44:38.2067094Z         	I0113 06:44:34.031398   14280 ssh_runner.go:149] Run: sh -c "df -h /var | awk 'NR==2{print $5}'"
2021-01-13T06:44:38.2074596Z         	I0113 06:44:34.031398   14280 main.go:119] libmachine: [executing ==>] : C:\windows\System32\WindowsPowerShell\v1.0\powershell.exe -NoProfile -NonInteractive ( Hyper-V\Get-VM functional-20210113062608-9468 ).state
2021-01-13T06:44:38.2078065Z         	I0113 06:44:35.531188   14280 main.go:119] libmachine: [stdout =====>] : Running
2021-01-13T06:44:38.2082066Z         	
2021-01-13T06:44:38.2088393Z         	I0113 06:44:35.531188   14280 main.go:119] libmachine: [stderr =====>] : 
2021-01-13T06:44:38.2095796Z         	I0113 06:44:35.531188   14280 main.go:119] libmachine: [executing ==>] : C:\windows\System32\WindowsPowerShell\v1.0\powershell.exe -NoProfile -NonInteractive (( Hyper-V\Get-VM functional-20210113062608-9468 ).networkadapters[0]).ipaddresses[0]
2021-01-13T06:44:38.2099236Z         	I0113 06:44:37.858164   14280 main.go:119] libmachine: [stdout =====>] : 192.168.13.13
2021-01-13T06:44:38.2107083Z         	
2021-01-13T06:44:38.2112567Z         	I0113 06:44:37.858164   14280 main.go:119] libmachine: [stderr =====>] : 
2021-01-13T06:44:38.2122152Z         	I0113 06:44:37.858164   14280 sshutil.go:48] new ssh client: &{IP:192.168.13.13 Port:22 SSHKeyPath:C:\Users\jenkins\actions-runner\_work\minikube\minikube\minikube_binaries\testhome\.minikube\machines\functional-20210113062608-9468\id_rsa Username:docker}
2021-01-13T06:44:38.2127802Z         	I0113 06:44:37.976815   14280 command_runner.go:123] > 18%!
2021-01-13T06:44:38.2133890Z         (MISSING)	I0113 06:44:37.977802   14280 ssh_runner.go:189] Completed: sh -c "df -h /var | awk 'NR==2{print $5}'": (3.9464103s)
2021-01-13T06:44:38.2139787Z         	I0113 06:44:37.998844   14280 ssh_runner.go:149] Run: systemctl --version
2021-01-13T06:44:38.2145017Z         	I0113 06:44:38.005805   14280 command_runner.go:123] > systemd 244 (244)
2021-01-13T06:44:38.2152872Z         	I0113 06:44:38.005805   14280 command_runner.go:123] > -PAM -AUDIT -SELINUX -IMA -APPARMOR -SMACK +SYSVINIT +UTMP -LIBCRYPTSETUP -GCRYPT -GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD -IDN2 -IDN -PCRE2 default-hierarchy=hybrid
2021-01-13T06:44:38.2159252Z         	I0113 06:44:38.026914   14280 ssh_runner.go:149] Run: sudo systemctl is-active --quiet service kubelet
2021-01-13T06:44:38.2166065Z         	I0113 06:44:38.044325   14280 kubeconfig.go:93] found "functional-20210113062608-9468" server: "https://192.168.13.13:8441"
2021-01-13T06:44:38.2171784Z         	I0113 06:44:38.044325   14280 api_server.go:146] Checking apiserver status ...
2021-01-13T06:44:38.2177662Z         	I0113 06:44:38.066357   14280 ssh_runner.go:149] Run: sudo pgrep -xnf kube-apiserver.*minikube.*
2021-01-13T06:44:38.2184201Z         	I0113 06:44:38.077334   14280 command_runner.go:123] > 9028
2021-01-13T06:44:38.2189168Z         	I0113 06:44:38.098324   14280 ssh_runner.go:149] Run: sudo egrep ^[0-9]+:freezer: /proc/9028/cgroup
2021-01-13T06:44:38.2195783Z         	I0113 06:44:38.105337   14280 command_runner.go:123] > 9:freezer:/kubepods.slice/kubepods-burstable.slice/kubepods-burstable-podfb4157a4b90b2fe40aba387b6e43370b.slice/docker-7b4c9b57bd7c56910d7220775f521fc8e5537fea95384b0c98230da91ecb4efe.scope
2021-01-13T06:44:38.2200697Z         	I0113 06:44:38.105337   14280 api_server.go:162] apiserver freezer: "9:freezer:/kubepods.slice/kubepods-burstable.slice/kubepods-burstable-podfb4157a4b90b2fe40aba387b6e43370b.slice/docker-7b4c9b57bd7c56910d7220775f521fc8e5537fea95384b0c98230da91ecb4efe.scope"
2021-01-13T06:44:38.2207599Z         	I0113 06:44:38.129309   14280 ssh_runner.go:149] Run: sudo cat /sys/fs/cgroup/freezer/kubepods.slice/kubepods-burstable.slice/kubepods-burstable-podfb4157a4b90b2fe40aba387b6e43370b.slice/docker-7b4c9b57bd7c56910d7220775f521fc8e5537fea95384b0c98230da91ecb4efe.scope/freezer.state
2021-01-13T06:44:38.2210596Z         	I0113 06:44:38.138363   14280 command_runner.go:123] > THAWED
2021-01-13T06:44:38.2213924Z         	I0113 06:44:38.138363   14280 api_server.go:184] freezer state: "THAWED"
2021-01-13T06:44:38.2218275Z         	I0113 06:44:38.139328   14280 api_server.go:221] Checking apiserver healthz at https://192.168.13.13:8441/healthz ...
2021-01-13T06:44:38.2223009Z         	I0113 06:44:38.153367   14280 api_server.go:241] https://192.168.13.13:8441/healthz returned 200:
2021-01-13T06:44:38.2228370Z         	ok
2021-01-13T06:44:38.2235146Z         	I0113 06:44:38.153367   14280 status.go:395] functional-20210113062608-9468 apiserver status = Running (err=<nil>)
2021-01-13T06:44:38.2245468Z         	I0113 06:44:38.153367   14280 status.go:243] functional-20210113062608-9468 status: &{Name:functional-20210113062608-9468 Host:Running Kubelet:Running APIServer:Running Kubeconfig:Configured Worker:false TimeToStop:Nonexistent}
2021-01-13T06:44:38.2247998Z         
2021-01-13T06:44:38.2254735Z         ** /stderr **

The timeout setting is 30s, shouldn't timeout. Here it takes 30.1872674s

/kind failing-test
/kind flake
@k8s-ci-robot k8s-ci-robot added kind/failing-test Categorizes issue or PR as related to a consistently or frequently failing test. kind/flake Categorizes issue or PR as related to a flaky test. labels Jan 13, 2021
This was referenced Jan 13, 2021
Open
Merged
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
kind/failing-test Categorizes issue or PR as related to a consistently or frequently failing test. kind/flake Categorizes issue or PR as related to a flaky test.
Projects
None yet
Milestone
No milestone
Development

Successfully merging a pull request may close this issue.

Increase functional test DockerEnv timeout lingsamuel/minikube
2 participants
@lingsamuel @k8s-ci-robot