Wait until expected ports are opened before starting port-forwarding

[feloy]

/kind bug

This test fails in a non reproducible way.

odo dev command tests 
> when running applications listening on the container loopback interface running on Podman 
> when ignoring localhost 
> [It] should port-forward successfully [podman]

2023-03-20T09:37:44.0850889Z • [FAILED] [42.407 seconds]
2023-03-20T09:37:44.0851773Z odo dev command tests when running applications listening on the container loopback interface running on Podman when ignoring localhost [It] should port-forward successfully [podman]
2023-03-20T09:37:44.0852570Z /home/runner/work/odo/odo/tests/integration/cmd_dev_test.go:3480
[...]
2023-03-20T09:37:44.2376040Z   [odo] I0320 09:37:29.244653   99689 exec.go:39] Executing command [/bin/sh -c cat /proc/net/tcp /proc/net/udp /proc/net/tcp6 /proc/net/udp6] for pod: wvvjvn-app in container: runtime
2023-03-20T09:37:44.2377012Z   [odo] I0320 09:37:29.244734   99689 exec.go:25] executing [podman exec --interactive wvvjvn-app-runtime /bin/sh -c cat /proc/net/tcp /proc/net/udp /proc/net/tcp6 /proc/net/udp6]
2023-03-20T09:37:44.2377591Z   [odo]  -  Forwarding from 127.0.0.1:21446 -> 3000
2023-03-20T09:37:44.2378181Z   [odo]  -  Forwarding from 127.0.0.1:23811 -> 3001
2023-03-20T09:37:44.2378455Z   [odo] 
2023-03-20T09:37:44.2378746Z   [odo] ↪ Dev mode
2023-03-20T09:37:44.2378996Z   [odo]  Status:
2023-03-20T09:37:44.2379391Z   [odo]  Watching for changes in the current directory /tmp/3750729805
2023-03-20T09:37:44.2382213Z   [odo] 
2023-03-20T09:37:44.2382536Z   [odo]  Keyboard Commands:
2023-03-20T09:37:44.2383033Z   [odo] [Ctrl+c] - Exit and delete resources from podman
2023-03-20T09:37:44.2383575Z   [odo]      [p] - Manually apply local changes to the application on podman
2023-03-20T09:37:44.2385019Z   [odo] I0320 09:37:29.739337   99689 exec.go:88]   sl  local_address rem_address   st tx_queue rx_queue tr tm->when retrnsmt   uid  timeout inode                                                     
2023-03-20T09:37:44.2427956Z   [odo] I0320 09:37:29.739357   99689 exec.go:88]    0: 6402000A:AE0E 23101068:01BB 06 00000000:00000000 03:0000144A 00000000     0        0 0 3 0000000000000000                                      
2023-03-20T09:37:44.2428800Z   [odo] I0320 09:37:29.739363   99689 exec.go:88]    1: 6402000A:ADF2 23101068:01BB 06 00000000:00000000 03:0000144A 00000000     0        0 0 3 0000000000000000                                      
2023-03-20T09:37:44.2429677Z   [odo] I0320 09:37:29.739367   99689 exec.go:88]    2: 6402000A:8362 23161068:01BB 01 00000000:00000000 00:00000000 00000000  1001        0 290188 1 0000000000000000 20 4 0 10 -1                    
2023-03-20T09:37:44.2430223Z   [odo] I0320 09:37:29.739374   99689 exec.go:88]    3: 6402000A:ADD4 23101068:01BB 06 00000000:00000000 03:0000144A 00000000     0        0 0 3 0000000000000000                                      
2023-03-20T09:37:44.2430794Z   [odo] I0320 09:37:29.739378   99689 exec.go:88]    4: 6402000A:ADCA 23101068:01BB 06 00000000:00000000 03:0000144A 00000000     0        0 0 3 0000000000000000                                      
2023-03-20T09:37:44.2431626Z   [odo] I0320 09:37:29.739382   99689 exec.go:88]    5: 6402000A:ADB6 23101068:01BB 06 00000000:00000000 03:0000144A 00000000     0        0 0 3 0000000000000000                                      
2023-03-20T09:37:44.2432231Z   [odo] I0320 09:37:29.739385   99689 exec.go:88]    6: 6402000A:AE06 23101068:01BB 06 00000000:00000000 03:0000144A 00000000     0        0 0 3 0000000000000000                                      
2023-03-20T09:37:44.2432825Z   [odo] I0320 09:37:29.739388   99689 exec.go:88]    7: 6402000A:ADCC 23101068:01BB 06 00000000:00000000 03:0000144A 00000000     0        0 0 3 0000000000000000                                      
2023-03-20T09:37:44.2433402Z   [odo] I0320 09:37:29.739393   99689 exec.go:88]    8: 6402000A:ADE2 23101068:01BB 06 00000000:00000000 03:0000144A 00000000     0        0 0 3 0000000000000000                                      
2023-03-20T09:37:44.2433994Z   [odo] I0320 09:37:29.739396   99689 exec.go:88]    9: 6402000A:AE20 23101068:01BB 06 00000000:00000000 03:0000144A 00000000     0        0 0 3 0000000000000000                                      
2023-03-20T09:37:44.2434925Z   [odo] I0320 09:37:29.739400   99689 exec.go:88]   10: 6402000A:AE12 23101068:01BB 06 00000000:00000000 03:0000144A 00000000     0        0 0 3 0000000000000000                                      
2023-03-20T09:37:44.2435712Z   [odo] I0320 09:37:29.739403   99689 exec.go:88]   11: 6402000A:ADBE 23101068:01BB 06 00000000:00000000 03:0000144A 00000000     0        0 0 3 0000000000000000                                      
2023-03-20T09:37:44.2436434Z   [odo] I0320 09:37:29.739407   99689 exec.go:88]   12: 6402000A:ADA4 23101068:01BB 06 00000000:00000000 03:0000144A 00000000     0        0 0 3 0000000000000000                                      
2023-03-20T09:37:44.2436975Z   [odo] I0320 09:37:29.739410   99689 exec.go:88]   13: 6402000A:ADAE 23101068:01BB 06 00000000:00000000 03:0000144A 00000000     0        0 0 3 0000000000000000                                      
2023-03-20T09:37:44.2437523Z   [odo] I0320 09:37:29.739413   99689 exec.go:88]   14: 6402000A:ADF8 23101068:01BB 06 00000000:00000000 03:0000144A 00000000     0        0 0 3 0000000000000000                                      
2023-03-20T09:37:44.2438078Z   [odo] I0320 09:37:29.739416   99689 exec.go:88]   15: 6402000A:AE0C 23101068:01BB 06 00000000:00000000 03:0000144A 00000000     0        0 0 3 0000000000000000                                      
2023-03-20T09:37:44.2468211Z   [odo] I0320 09:37:29.739422   99689 exec.go:88]   16: 6402000A:A51C 23171068:01BB 01 00000000:00000000 02:00000000 00000000  1001        0 290187 2 0000000000000000 20 4 0 10 -1                    
2023-03-20T09:37:44.2469520Z   [odo] I0320 09:37:29.739426   99689 exec.go:88]    sl  local_address rem_address   st tx_queue rx_queue tr tm->when retrnsmt   uid  timeout inode ref pointer drops            
2023-03-20T09:37:44.2470629Z   [odo] I0320 09:37:29.739429   99689 exec.go:88]   sl  local_address                         remote_address                        st tx_queue rx_queue tr tm->when retrnsmt   uid  timeout inode
2023-03-20T09:37:44.2471653Z   [odo] I0320 09:37:29.739434   99689 exec.go:88]   sl  local_address                         remote_address                        st tx_queue rx_queue tr tm->when retrnsmt   uid  timeout inode ref pointer drops

When executed locally, I have the following logs. Note that podman exec --interactive nodejs-with-endpoint-on-loopback-app-runtime /bin/sh -c cat /proc/net/tcp /proc/net/udp /proc/net/tcp6 /proc/net/udp6 is executed before the ports forwardings are displayed, when it is executed after when the test fails.

I0320 10:50:21.113820   80359 exec.go:39] Executing command [/bin/sh -c cat /proc/net/tcp /proc/net/udp /proc/net/tcp6 /proc/net/udp6] for pod: nodejs-with-endpoint-on-loopback-app in container: runtime
I0320 10:50:21.113893   80359 exec.go:25] executing [podman exec --interactive nodejs-with-endpoint-on-loopback-app-runtime /bin/sh -c cat /proc/net/tcp /proc/net/udp /proc/net/tcp6 /proc/net/udp6]
I0320 10:50:21.178408   80359 exec.go:88]   sl  local_address rem_address   st tx_queue rx_queue tr tm->when retrnsmt   uid  timeout inode                                                     
I0320 10:50:21.178425   80359 exec.go:88]    0: 00000000:0BB8 00000000:0000 0A 00000000:00000000 00:00000000 00000000  1001        0 155881 1 000000003c5428fa 100 0 0 10 0                    
I0320 10:50:21.178431   80359 exec.go:88]    1: 0100007F:0BB9 00000000:0000 0A 00000000:00000000 00:00000000 00000000  1001        0 155882 1 00000000f9c5313c 100 0 0 10 0                    
I0320 10:50:21.178436   80359 exec.go:88]    2: 0300590A:B852 23151068:01BB 06 00000000:00000000 03:00001542 00000000     0        0 0 3 000000002c9abe44                                      
I0320 10:50:21.178444   80359 exec.go:88]    3: 0300590A:B82C 23151068:01BB 06 00000000:00000000 03:00001542 00000000     0        0 0 3 00000000fe0d42b9                                      
I0320 10:50:21.178449   80359 exec.go:88]    4: 0300590A:B808 23151068:01BB 06 00000000:00000000 03:00001542 00000000     0        0 0 3 00000000111fdf8d                                      
I0320 10:50:21.178452   80359 exec.go:88]    5: 0300590A:B7F8 23151068:01BB 06 00000000:00000000 03:00001542 00000000     0        0 0 3 00000000e93499bc                                      
I0320 10:50:21.178457   80359 exec.go:88]    6: 0300590A:B846 23151068:01BB 06 00000000:00000000 03:00001542 00000000     0        0 0 3 00000000d00f00c5                                      
I0320 10:50:21.178461   80359 exec.go:88]    7: 0300590A:B872 23151068:01BB 06 00000000:00000000 03:00001542 00000000     0        0 0 3 0000000085cd9ea2                                      
I0320 10:50:21.178468   80359 exec.go:88]    8: 0300590A:B810 23151068:01BB 06 00000000:00000000 03:00001542 00000000     0        0 0 3 00000000317055be                                      
I0320 10:50:21.178473   80359 exec.go:88]    9: 0300590A:B81E 23151068:01BB 06 00000000:00000000 03:00001542 00000000     0        0 0 3 000000009067ef17                                      
I0320 10:50:21.178477   80359 exec.go:88]   10: 0300590A:B876 23151068:01BB 06 00000000:00000000 03:00001542 00000000     0        0 0 3 00000000cd582e0d                                      
I0320 10:50:21.178482   80359 exec.go:88]   11: 0300590A:B86C 23151068:01BB 06 00000000:00000000 03:00001542 00000000     0        0 0 3 00000000ed8cef60                                      
I0320 10:50:21.178492   80359 exec.go:88]   12: 0300590A:B86A 23151068:01BB 06 00000000:00000000 03:00001542 00000000     0        0 0 3 00000000cc04c2e3                                      
I0320 10:50:21.178495   80359 exec.go:88]   13: 0300590A:B802 23151068:01BB 06 00000000:00000000 03:00001542 00000000     0        0 0 3 00000000c7c5e1a6                                      
I0320 10:50:21.178498   80359 exec.go:88]   14: 0300590A:B85C 23151068:01BB 06 00000000:00000000 03:00001542 00000000     0        0 0 3 00000000cfbe67db                                      
I0320 10:50:21.178500   80359 exec.go:88]   15: 0300590A:B7F0 23151068:01BB 06 00000000:00000000 03:00001542 00000000     0        0 0 3 0000000073e52841                                      
I0320 10:50:21.178504   80359 exec.go:88]   16: 0300590A:B83C 23151068:01BB 06 00000000:00000000 03:00001542 00000000     0        0 0 3 000000000ec35500                                      
I0320 10:50:21.178507   80359 exec.go:88]    sl  local_address rem_address   st tx_queue rx_queue tr tm->when retrnsmt   uid  timeout inode ref pointer drops            
I0320 10:50:21.178510   80359 exec.go:88]   sl  local_address                         remote_address                        st tx_queue rx_queue tr tm->when retrnsmt   uid  timeout inode
I0320 10:50:21.178514   80359 exec.go:88]   sl  local_address                         remote_address                        st tx_queue rx_queue tr tm->when retrnsmt   uid  timeout inode ref pointer drops
 ⚠  Detected that the following port(s) can be reached only via the container loopback interface: admin (3001).
Port forwarding on Podman currently does not work with applications listening on the loopback interface.
Either change the application to make those port(s) reachable on all interfaces (0.0.0.0), or rerun 'odo dev' with '--forward-localhost' to make port-forwarding work with such ports.
 -  Forwarding from 127.0.0.1:20001 -> 3000
 -  Forwarding from 127.0.0.1:20002 -> 3001

↪ Dev mode
 Status:
 Watching for changes in the current directory /home/phmartin/Documents/tests/6602

 Keyboard Commands:
[Ctrl+c] - Exit and delete resources from podman
     [p] - Manually apply local changes to the application on podman

[rm3l]

As discussed with Philippe, the port detector did not detect any ports bound on localhost because the application sometimes took time to start. So users might run into the same issue.

We think this issue could be fixed by waiting, after executing the application, until the ports are really open (or until a timeout has been reached) before proceeding, now that we are able to get information about the active connections/ports in the container; this should be done not only on Podman, but also on K8s (where we had similar issues in our tests - see #6463).