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.

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

Recurring issue with E2E tests #6463

Closed
rm3l opened this issue Jan 5, 2023 · 0 comments · Fixed by #6543
Closed

Recurring issue with E2E tests #6463

rm3l opened this issue Jan 5, 2023 · 0 comments · Fixed by #6543
Assignees
Labels
area/testing Issues or PRs related to testing, Quality Assurance or Quality Engineering kind/bug Categorizes issue or PR as related to a bug.
Milestone

Comments

@rm3l
Copy link
Member

rm3l commented Jan 5, 2023

/kind bug
/area testing

I noticed repeating failures on the end-to-end tests.
See https://prow.ci.openshift.org/view/gs/origin-ci-test/pr-logs/pull/redhat-developer_odo/6385/pull-ci-redhat-developer-odo-main-v4.11-integration-e2e/1610592571338264576 for an example, but the pattern seems very similar for each failure.

After a very first analysis of the logs, I think the issue is due to some kind of race condition:

  1. we start odo dev --random-ports => a new random port forwarding is created
  2. when we update the local application source code, the Dev session detects the changes and starts by stopping the running application
  3. While the application is stopped and odo dev is restarting it (this operation might take some time), the test sends an HTTP request to the port created in 1)
  4. Since the application is not completely restarted, odo dev fails to connect to the remote application port, and automatically restarts the port forwarding. odo dev gets a new random port (because of --random-ports)
  5. The test ends up failing due to the timeout being reached because it was eventually expecting a response on the port created in 1), but odo dev is no longer listening on this port.

Any logs, error output, etc?

Relevant log lines
✓  Syncing files into the container [1s]
    [odo] I0104 12:55:01.058124   94024 kubeexec.go:43] GetProcessInfoForCommand for "run"
    [odo] I0104 12:55:01.058136   94024 exec.go:39] Executing command [/bin/sh -c cat /opt/odo/.odo_cmd_run.pid || true] for pod: jdqfza-app-bc454889b-zrbjs in container: runtime
    [odo] 50
    [odo] I0104 12:55:01.516905   94024 exec.go:39] Executing command [/bin/sh -c kill -0 50; echo $?] for pod: jdqfza-app-bc454889b-zrbjs in container: runtime
    [odo] 0
    [odo] I0104 12:55:01.980878   94024 adapter.go:313] running=true, execRequired=true
    [odo]  •  Building your application in container on cluster (command: install)  ...
    [odo] I0104 12:55:01.980915   94024 exec.go:39] Executing command [/bin/sh -c cd /project && (npm install) 1>>/proc/1/fd/1 2>>/proc/1/fd/2] for pod: jdqfza-app-bc454889b-zrbjs in container: runtime
    [odo] 
 ✓  Building your application in container on cluster (command: install) [1s]
    [odo] I0104 12:55:03.259193   94024 execute_run.go:57] restart required for command run
    [odo] I0104 12:55:03.259202   94024 kubeexec.go:130] StopProcessForCommand for "run"
    [odo] I0104 12:55:03.259213   94024 exec.go:39] Executing command [/bin/sh -c cat /opt/odo/.odo_cmd_run.pid || true] for pod: jdqfza-app-bc454889b-zrbjs in container: runtime
    [odo] 50
    [odo] I0104 12:55:03.715592   94024 exec.go:39] Executing command [/bin/sh -c cat /proc/50/task/50/children || true] for pod: jdqfza-app-bc454889b-zrbjs in container: runtime
    [odo] 56 
    [odo] I0104 12:55:04.186340   94024 exec.go:39] Executing command [/bin/sh -c cat /proc/56/task/56/children || true] for pod: jdqfza-app-bc454889b-zrbjs in container: runtime
    [odo] 67 
    [odo] I0104 12:55:04.668010   94024 exec.go:39] Executing command [/bin/sh -c cat /proc/67/task/67/children || true] for pod: jdqfza-app-bc454889b-zrbjs in container: runtime
    [odo] I0104 12:55:05.128871   94024 kubeexec.go:182] Found 2 children (either direct and indirect) for parent process 50: [67 56]
    [odo] I0104 12:55:05.128894   94024 exec.go:39] Executing command [/bin/sh -c kill 67 || true] for pod: jdqfza-app-bc454889b-zrbjs in container: runtime
    [odo] I0104 12:55:05.585587   94024 retry.go:48] waiting for 2 second(s) before trying task "status for remote process 67"
    [odo] I0104 12:55:05.589454   94024 kubeexec.go:43] GetProcessInfoForCommand for "run"
    [odo] I0104 12:55:05.589471   94024 exec.go:39] Executing command [/bin/sh -c cat /opt/odo/.odo_cmd_run.pid || true] for pod: jdqfza-app-bc454889b-zrbjs in container: runtime
    [odo] E0104 12:55:05.650985   94024 portforward.go:406] an error occurred forwarding 41895 -> 3000: error forwarding port 3000 to pod d8daca1fc2acda9b3eaa303137b07e534ca9981ef5598b4c6287d32125ad856e, uid : port forward into network namespace "/var/run/netns/c9823af2-b2af-4ca6-8ff4-7a80a678bac9": failed to connect to localhost:3000 inside namespace d8daca1fc2acda9b3eaa303137b07e534ca9981ef5598b4c6287d32125ad856e: dial tcp [::1]:3000: connect: connection refused
    error while trying to GET "127.0.0.1:41895": Get "http://127.0.0.1:41895/": EOF
    [odo] E0104 12:55:05.651234   94024 portforward.go:234] lost connection to pod
    [odo]  -  Forwarding from 127.0.0.1:44689 -> 3000
    [odo] 
    [odo] 50
    [odo] 0
    [odo] I0104 12:55:06.024355   94024 exec.go:39] Executing command [/bin/sh -c kill -0 50; echo $?] for pod: jdqfza-app-bc454889b-zrbjs in container: runtime
    [odo] 1
    [odo] /bin/sh: line 0: kill: (50) - No such process
    [odo] 
 ✓  Finished executing the application (command: run) [21s]
    [odo] I0104 12:55:07.586031   94024 exec.go:39] Executing command [/bin/sh -c kill -0 67; echo $?] for pod: jdqfza-app-bc454889b-zrbjs in container: runtime
    [odo] 1
    [odo] /bin/sh: line 0: kill: (67) - No such process
    [odo] I0104 12:55:08.067512   94024 exec.go:39] Executing command [/bin/sh -c kill 56 || true] for pod: jdqfza-app-bc454889b-zrbjs in container: runtime
    [odo] /bin/sh: line 0: kill: (56) - No such process
    [odo] I0104 12:55:08.515835   94024 retry.go:48] waiting for 2 second(s) before trying task "status for remote process 56"
    [odo] I0104 12:55:10.516229   94024 exec.go:39] Executing command [/bin/sh -c kill -0 56; echo $?] for pod: jdqfza-app-bc454889b-zrbjs in container: runtime
    [odo] /bin/sh: line 0: kill: (56) - No such process
    [odo] 1
    [odo] I0104 12:55:10.957647   94024 exec.go:39] Executing command [/bin/sh -c rm -f /opt/odo/.odo_cmd_run.pid] for pod: jdqfza-app-bc454889b-zrbjs in container: runtime
    [odo] I0104 12:55:11.436935   94024 kubeexec.go:62] StartProcessForCommand for "run"
    [odo] I0104 12:55:11.436963   94024 retry.go:48] waiting for 5 second(s) before trying task "process for command \"run\""
    [odo]  •  Executing the application (command: run)  ...
    [odo] I0104 12:55:11.436994   94024 exec.go:39] Executing command [/bin/sh -c echo $$ > /opt/odo/.odo_cmd_run.pid && cd /project &&  (npm start) 1>>/proc/1/fd/1 2>>/proc/1/fd/2; echo $? >> /opt/odo/.odo_cmd_run.pid] for pod: jdqfza-app-bc454889b-zrbjs in container: runtime
    [odo] I0104 12:55:16.437812   94024 execute_run.go:97] checking if process for command "run" is running
    [odo] I0104 12:55:16.437837   94024 kubeexec.go:43] GetProcessInfoForCommand for "run"
    [odo] I0104 12:55:16.437849   94024 exec.go:39] Executing command [/bin/sh -c cat /opt/odo/.odo_cmd_run.pid || true] for pod: jdqfza-app-bc454889b-zrbjs in container: runtime
    [odo] 223
    [odo] I0104 12:55:16.901472   94024 exec.go:39] Executing command [/bin/sh -c kill -0 223; echo $?] for pod: jdqfza-app-bc454889b-zrbjs in container: runtime
    [odo] 0
    [odo] I0104 12:55:17.348782   94024 kubeexec.go:43] GetProcessInfoForCommand for "run"
    [odo] I0104 12:55:17.348802   94024 exec.go:39] Executing command [/bin/sh -c cat /opt/odo/.odo_cmd_run.pid || true] for pod: jdqfza-app-bc454889b-zrbjs in container: runtime
    [odo] 223
    [odo] I0104 12:55:17.896727   94024 exec.go:39] Executing command [/bin/sh -c kill -0 223; echo $?] for pod: jdqfza-app-bc454889b-zrbjs in container: runtime
    [odo] 0
    [odo] 
    [odo] ↪ Dev mode
    [odo]  Status:
    [odo]  Watching for changes in the current directory /tmp/2166066627
    [odo] 
    [odo]  Keyboard Commands:
    [odo] [Ctrl+c] - Exit and delete resources from the cluster
    [odo]      [p] - Manually apply local changes to the application on the cluster
@openshift-ci openshift-ci bot added kind/bug Categorizes issue or PR as related to a bug. area/testing Issues or PRs related to testing, Quality Assurance or Quality Engineering labels Jan 5, 2023
@github-actions github-actions bot added the needs-triage Indicates an issue or PR lacks a `triage/*` and requires one. label Jan 5, 2023
@rm3l rm3l added this to odo Project Jan 5, 2023
@rm3l rm3l changed the title Repeating issue with E2E tests Recurring issue with E2E tests Jan 9, 2023
@rm3l rm3l self-assigned this Jan 25, 2023
@rm3l rm3l moved this to In Review 👀 in odo Project Jan 27, 2023
@rm3l rm3l removed the needs-triage Indicates an issue or PR lacks a `triage/*` and requires one. label Jan 27, 2023
@github-project-automation github-project-automation bot moved this from In Review 👀 to Done ✅ in odo Project Jan 27, 2023
@rm3l rm3l added this to the v3.7.0 🚀 milestone Jan 30, 2023
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
area/testing Issues or PRs related to testing, Quality Assurance or Quality Engineering kind/bug Categorizes issue or PR as related to a bug.
Projects
Archived in project
Development

Successfully merging a pull request may close this issue.

1 participant