Can't connect to exposed port (database)

[sergejbut]

/kind bug

Description

Can't connect to exposed port (database)

Steps to reproduce the issue:

1. sudo podman run --name some-mysql -e MYSQL_ROOT_PASSWORD=root -d -p 3309:3306 docker://mysql:8

2. sudo podman ps -a
   -> Port is exposed

3. Connect to the database: <host_ip>:3309, user:root, pass:root

Describe the results you received:
java.net.ConnectException: Connection refused: connect (I use IntelliJ to connect to the db)

Describe the results you expected:
Successfull connection

Additional information you deem important (e.g. issue happens only occasionally):

Output of podman version:

Version:            1.6.2
RemoteAPI Version:  1
Go Version:         go1.10.4
OS/Arch:            linux/amd64

Output of podman info --debug:

debug:
  compiler: gc
  git commit: ""
  go version: go1.10.4
  podman version: 1.6.2
host:
  BuildahVersion: 1.11.3
  CgroupVersion: v1
  Conmon:
    package: 'conmon: /usr/bin/conmon'
    path: /usr/bin/conmon
    version: 'conmon version 2.0.2, commit: unknown'
  Distribution:
    distribution: ubuntu
    version: "18.04"
  IDMappings:
    gidmap:
    - container_id: 0
      host_id: 1000
      size: 1
    - container_id: 1
      host_id: 100000
      size: 65536
    uidmap:
    - container_id: 0
      host_id: 1000
      size: 1
    - container_id: 1
      host_id: 100000
      size: 65536
  MemFree: 777121792
  MemTotal: 4133961728
  OCIRuntime:
    name: runc
    package: 'runc: /usr/sbin/runc'
    path: /usr/sbin/runc
    version: 'runc version spec: 1.0.1-dev'
  SwapFree: 554102784
  SwapTotal: 595521536
  arch: amd64
  cpus: 2
  eventlogger: journald
  hostname: vm1-VirtualBox
  kernel: 5.0.0-32-generic
  os: linux
  rootless: true
  slirp4netns:
    Executable: /usr/bin/slirp4netns
    Package: 'slirp4netns: /usr/bin/slirp4netns'
    Version: |-
      slirp4netns version 0.4.2
      commit: unknown
  uptime: 9h 4m 38.69s (Approximately 0.38 days)
registries:
  blocked: null
  insecure: null
  search: null
store:
  ConfigFile: /home/vm1/.config/containers/storage.conf
  ContainerStore:
    number: 0
  GraphDriverName: vfs
  GraphOptions: {}
  GraphRoot: /home/vm1/.local/share/containers/storage
  GraphStatus: {}
  ImageStore:
    number: 2
  RunRoot: /run/user/1000
  VolumePath: /home/vm1/.local/share/containers/storage/volumes

Package info (e.g. output of rpm -q podman or apt list podman):

Listing... Done
podman/bionic,now 1.6.2-1~ubuntu18.04~ppa1 amd64 [installed]

Additional environment details (AWS, VirtualBox, physical, etc.):
VirtualBox

[SemaiCZE]

I have the same issue with mariadb:10.4, running on physical Fedora 31, podman 1.6.2, root mode. Strange thing is that after some time, the connection becomes available. From the logs I got this (look at the times):

2019-11-26 21:42:37+00:00 [Note] [Entrypoint]: Temporary server started.
Warning: Unable to load '/usr/share/zoneinfo/leap-seconds.list' as time zone. Skipping it.
2019-11-26 21:49:42 10 [Warning] 'proxies_priv' entry '@% root@4f29bdea138f' ignored in --skip-name-resolve mode.

[rhatdan]

@mheon Is this a CNI issue?

[mheon]

Potentially? Hard to tell with only this.

Can you try with another protocol (HTTP server is usually easy) and verify if you can connect to that?

[SemaiCZE]

For example nginx works:

$ sudo podman run --name ngnx -p 8888:80 -d nginx:latest
$ curl -v "http://localhost:8888/"

But mariadb does not work:

$ sudo podman run --name some-mysql -e MYSQL_ROOT_PASSWORD=root -d -p 3309:3306 mariadb:10.4
$ mysql --port=3309 --password=root --user=root -h 127.0.0.1
ERROR 2002 (HY000): Can't connect to MySQL server on '127.0.0.1' (115)

After some time, it suddenly becomes available:

$ mysql --port=3309 --password=root --user=root -h 127.0.0.1
Welcome to the MariaDB monitor.  Commands end with ; or \g.
Your MariaDB connection id is 8
Server version: 10.4.10-MariaDB-1:10.4.10+maria~bionic mariadb.org binary distribution

Copyright (c) 2000, 2018, Oracle, MariaDB Corporation Ab and others.

Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.

MariaDB [(none)]> 

Complete log from mariadb container:

2019-12-03 11:35:46+00:00 [Note] [Entrypoint]: Entrypoint script for MySQL Server  started.
2019-12-03 11:35:47+00:00 [Note] [Entrypoint]: Switching to dedicated user 'mysql'
2019-12-03 11:35:47+00:00 [Note] [Entrypoint]: Entrypoint script for MySQL Server  started.
2019-12-03 11:35:47+00:00 [Note] [Entrypoint]: Initializing database files


PLEASE REMEMBER TO SET A PASSWORD FOR THE MariaDB root USER !
To do so, start the server, then issue the following commands:

'/usr/bin/mysqladmin' -u root password 'new-password'
'/usr/bin/mysqladmin' -u root -h  password 'new-password'

Alternatively you can run:
'/usr/bin/mysql_secure_installation'

which will also give you the option of removing the test
databases and anonymous user created by default.  This is
strongly recommended for production servers.

See the MariaDB Knowledgebase at http://mariadb.com/kb or the
MySQL manual for more instructions.

Please report any problems at http://mariadb.org/jira

The latest information about MariaDB is available at http://mariadb.org/.
You can find additional information about the MySQL part at:
http://dev.mysql.com
Consider joining MariaDB's strong and vibrant community:
https://mariadb.org/get-involved/

2019-12-03 11:35:51+00:00 [Note] [Entrypoint]: Database files initialized
2019-12-03 11:35:51+00:00 [Note] [Entrypoint]: Starting temporary server
2019-12-03 11:35:51+00:00 [Note] [Entrypoint]: Waiting for server startup
2019-12-03 11:35:51 0 [Note] mysqld (mysqld 10.4.10-MariaDB-1:10.4.10+maria~bionic) starting as process 117 ...
2019-12-03 11:35:51 0 [Note] InnoDB: Using Linux native AIO
2019-12-03 11:35:51 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2019-12-03 11:35:51 0 [Note] InnoDB: Uses event mutexes
2019-12-03 11:35:51 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
2019-12-03 11:35:51 0 [Note] InnoDB: Number of pools: 1
2019-12-03 11:35:51 0 [Note] InnoDB: Using SSE2 crc32 instructions
2019-12-03 11:35:51 0 [Note] mysqld: O_TMPFILE is not supported on /tmp (disabling future attempts)
2019-12-03 11:35:51 0 [Note] InnoDB: Initializing buffer pool, total size = 256M, instances = 1, chunk size = 128M
2019-12-03 11:35:51 0 [Note] InnoDB: Completed initialization of buffer pool
2019-12-03 11:35:51 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
2019-12-03 11:35:51 0 [Note] InnoDB: 128 out of 128 rollback segments are active.
2019-12-03 11:35:51 0 [Note] InnoDB: Creating shared tablespace for temporary tables
2019-12-03 11:35:51 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
2019-12-03 11:35:51 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
2019-12-03 11:35:51 0 [Note] InnoDB: 10.4.10 started; log sequence number 139827; transaction id 21
2019-12-03 11:35:51 0 [Note] InnoDB: Loading buffer pool(s) from /var/lib/mysql/ib_buffer_pool
2019-12-03 11:35:51 0 [Note] Plugin 'FEEDBACK' is disabled.
2019-12-03 11:35:51 0 [Warning] 'user' entry 'root@b6b79f675c19' ignored in --skip-name-resolve mode.
2019-12-03 11:35:51 0 [Warning] 'user' entry '@b6b79f675c19' ignored in --skip-name-resolve mode.
2019-12-03 11:35:51 0 [Warning] 'proxies_priv' entry '@% root@b6b79f675c19' ignored in --skip-name-resolve mode.
2019-12-03 11:35:51 0 [Note] Reading of all Master_info entries succeeded
2019-12-03 11:35:51 0 [Note] Added new Master_info '' to hash table
2019-12-03 11:35:51 0 [Note] mysqld: ready for connections.
Version: '10.4.10-MariaDB-1:10.4.10+maria~bionic'  socket: '/var/run/mysqld/mysqld.sock'  port: 0  mariadb.org binary distribution
2019-12-03 11:35:51 0 [Note] InnoDB: Buffer pool(s) load completed at 191203 11:35:51
2019-12-03 11:35:52+00:00 [Note] [Entrypoint]: Temporary server started.
Warning: Unable to load '/usr/share/zoneinfo/leap-seconds.list' as time zone. Skipping it.
2019-12-03 11:37:42 10 [Warning] 'proxies_priv' entry '@% root@b6b79f675c19' ignored in --skip-name-resolve mode.

2019-12-03 11:37:42+00:00 [Note] [Entrypoint]: Stopping temporary server
2019-12-03 11:37:42 0 [Note] mysqld (initiated by: root[root] @ localhost []): Normal shutdown
2019-12-03 11:37:42 0 [Note] Event Scheduler: Purging the queue. 0 events
2019-12-03 11:37:42 0 [Note] InnoDB: FTS optimize thread exiting.
2019-12-03 11:37:43 0 [Note] InnoDB: Starting shutdown...
2019-12-03 11:37:43 0 [Note] InnoDB: Dumping buffer pool(s) to /var/lib/mysql/ib_buffer_pool
2019-12-03 11:37:43 0 [Note] InnoDB: Buffer pool(s) dump completed at 191203 11:37:43
2019-12-03 11:37:44 0 [Note] InnoDB: Shutdown completed; log sequence number 20319934; transaction id 14676
2019-12-03 11:37:44 0 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1"
2019-12-03 11:37:44 0 [Note] mysqld: Shutdown complete

2019-12-03 11:37:44+00:00 [Note] [Entrypoint]: Temporary server stopped

2019-12-03 11:37:44+00:00 [Note] [Entrypoint]: MySQL init process done. Ready for start up.

2019-12-03 11:37:45 0 [Note] mysqld (mysqld 10.4.10-MariaDB-1:10.4.10+maria~bionic) starting as process 1 ...
2019-12-03 11:37:45 0 [Note] InnoDB: Using Linux native AIO
2019-12-03 11:37:45 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2019-12-03 11:37:45 0 [Note] InnoDB: Uses event mutexes
2019-12-03 11:37:45 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
2019-12-03 11:37:45 0 [Note] InnoDB: Number of pools: 1
2019-12-03 11:37:45 0 [Note] InnoDB: Using SSE2 crc32 instructions
2019-12-03 11:37:45 0 [Note] mysqld: O_TMPFILE is not supported on /tmp (disabling future attempts)
2019-12-03 11:37:45 0 [Note] InnoDB: Initializing buffer pool, total size = 256M, instances = 1, chunk size = 128M
2019-12-03 11:37:45 0 [Note] InnoDB: Completed initialization of buffer pool
2019-12-03 11:37:45 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
2019-12-03 11:37:45 0 [Note] InnoDB: 128 out of 128 rollback segments are active.
2019-12-03 11:37:45 0 [Note] InnoDB: Creating shared tablespace for temporary tables
2019-12-03 11:37:45 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
2019-12-03 11:37:45 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
2019-12-03 11:37:45 0 [Note] InnoDB: Waiting for purge to start
2019-12-03 11:37:45 0 [Note] InnoDB: 10.4.10 started; log sequence number 20319934; transaction id 14676
2019-12-03 11:37:45 0 [Note] InnoDB: Loading buffer pool(s) from /var/lib/mysql/ib_buffer_pool
2019-12-03 11:37:45 0 [Note] Plugin 'FEEDBACK' is disabled.
2019-12-03 11:37:45 0 [Note] Server socket created on IP: '::'.
2019-12-03 11:37:45 0 [Warning] 'proxies_priv' entry '@% root@b6b79f675c19' ignored in --skip-name-resolve mode.
2019-12-03 11:37:45 0 [Note] Reading of all Master_info entries succeeded
2019-12-03 11:37:45 0 [Note] Added new Master_info '' to hash table
2019-12-03 11:37:45 0 [Note] mysqld: ready for connections.
Version: '10.4.10-MariaDB-1:10.4.10+maria~bionic'  socket: '/var/run/mysqld/mysqld.sock'  port: 3306  mariadb.org binary distribution
2019-12-03 11:37:45 0 [Note] InnoDB: Buffer pool(s) load completed at 191203 11:37:45

[mheon]

Aha. So this is very specifically MySQL/MariaDB. Interesting.

[rhatdan]

Could it be that mariadb is not listing on the port right a way and takes some time to finish starting. And you are checking too quickly.

[SemaiCZE]

I don't think that it should start 2 minutes. With Docker it's ready right away and with Podman on CentOS 7 it worked for me without the delay too. Because this bug affects two different images I think that it is caused by Podman. Hope you guys can find it :)

[rhatdan]

@mheon is this likely ours or CNI?

[mheon]

Has to be CNI - we've already finished all CNI config before we start the container, from our perspective.

[github-actions]

This issue had no activity for 30 days. In the absence of activity or the "do-not-close" label, the issue will be automatically closed within 7 days.

[rhatdan]

@SemaiCZE Are you still seeing this issue?

[SemaiCZE]

@rhatdan yes, I didn't get any update of related components yet. Is it fixed in upstream? And which package is related? podman or containerd.io or something else?

[rhatdan]

I would hope the fix was in CNI.

[mheon]

If it is fixed, it would probably be containernetworking-plugins, but I have not seen any updated versions of that drop recently.

[baude]

Ok, I have this one nailed down. It is mariadb specific and not the fault of podman or cni. In one terminal, run top. In another, run the command as provided ... and in another terminal, run a podman container log -f. What you will observe is this:

In the container, by way of top, the mysqld binary is chewing up CPU presumably to get setup. The maria db logs are as follows:

2020-01-27 21:52:54+00:00 [Note] [Entrypoint]: Entrypoint script for MySQL Server 1:10.4.11+maria~bionic started.
2020-01-27 21:52:55+00:00 [Note] [Entrypoint]: Switching to dedicated user 'mysql'
2020-01-27 21:52:55+00:00 [Note] [Entrypoint]: Entrypoint script for MySQL Server 1:10.4.11+maria~bionic started.
2020-01-27 21:52:55+00:00 [Note] [Entrypoint]: Initializing database files


PLEASE REMEMBER TO SET A PASSWORD FOR THE MariaDB root USER !
To do so, start the server, then issue the following commands:

'/usr/bin/mysqladmin' -u root password 'new-password'
'/usr/bin/mysqladmin' -u root -h  password 'new-password'

Alternatively you can run:
'/usr/bin/mysql_secure_installation'

which will also give you the option of removing the test
databases and anonymous user created by default.  This is
strongly recommended for production servers.

See the MariaDB Knowledgebase at http://mariadb.com/kb or the
MySQL manual for more instructions.

Please report any problems at http://mariadb.org/jira

The latest information about MariaDB is available at http://mariadb.org/.
You can find additional information about the MySQL part at:
http://dev.mysql.com
Consider joining MariaDB's strong and vibrant community:
https://mariadb.org/get-involved/

2020-01-27 21:52:58+00:00 [Note] [Entrypoint]: Database files initialized
2020-01-27 21:52:58+00:00 [Note] [Entrypoint]: Starting temporary server
2020-01-27 21:52:58+00:00 [Note] [Entrypoint]: Waiting for server startup
2020-01-27 21:52:58 0 [Note] mysqld (mysqld 10.4.11-MariaDB-1:10.4.11+maria~bionic) starting as process 117 ...
2020-01-27 21:52:58 0 [Note] InnoDB: Using Linux native AIO
2020-01-27 21:52:58 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2020-01-27 21:52:58 0 [Note] InnoDB: Uses event mutexes
2020-01-27 21:52:58 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
2020-01-27 21:52:58 0 [Note] InnoDB: Number of pools: 1
2020-01-27 21:52:58 0 [Note] InnoDB: Using SSE2 crc32 instructions
2020-01-27 21:52:58 0 [Note] mysqld: O_TMPFILE is not supported on /tmp (disabling future attempts)
2020-01-27 21:52:58 0 [Note] InnoDB: Initializing buffer pool, total size = 256M, instances = 1, chunk size = 128M
2020-01-27 21:52:58 0 [Note] InnoDB: Completed initialization of buffer pool
2020-01-27 21:52:58 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
2020-01-27 21:52:58 0 [Note] InnoDB: 128 out of 128 rollback segments are active.
2020-01-27 21:52:58 0 [Note] InnoDB: Creating shared tablespace for temporary tables
2020-01-27 21:52:58 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
2020-01-27 21:52:58 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
2020-01-27 21:52:58 0 [Note] InnoDB: 10.4.11 started; log sequence number 60972; transaction id 21
2020-01-27 21:52:58 0 [Note] InnoDB: Loading buffer pool(s) from /var/lib/mysql/ib_buffer_pool
2020-01-27 21:52:58 0 [Note] Plugin 'FEEDBACK' is disabled.
2020-01-27 21:52:58 0 [Warning] 'user' entry 'root@4729f11f0714' ignored in --skip-name-resolve mode.
2020-01-27 21:52:58 0 [Warning] 'user' entry '@4729f11f0714' ignored in --skip-name-resolve mode.
2020-01-27 21:52:58 0 [Warning] 'proxies_priv' entry '@% root@4729f11f0714' ignored in --skip-name-resolve mode.
2020-01-27 21:52:58 0 [Note] InnoDB: Buffer pool(s) load completed at 200127 21:52:58
2020-01-27 21:52:58 0 [Note] Reading of all Master_info entries succeeded
2020-01-27 21:52:58 0 [Note] Added new Master_info '' to hash table
2020-01-27 21:52:58 0 [Note] mysqld: ready for connections.
Version: '10.4.11-MariaDB-1:10.4.11+maria~bionic'  socket: '/var/run/mysqld/mysqld.sock'  port: 0  mariadb.org binary distribution
2020-01-27 21:52:59+00:00 [Note] [Entrypoint]: Temporary server started.

Then, as observed, after a short time, the mysqld drops in cpu, and the log furthers:

2020-01-27 21:53:38 10 [Warning] 'proxies_priv' entry '@% root@4729f11f0714' ignored in --skip-name-resolve mode.

2020-01-27 21:53:38+00:00 [Note] [Entrypoint]: Stopping temporary server
2020-01-27 21:53:38 0 [Note] mysqld (initiated by: root[root] @ localhost []): Normal shutdown
2020-01-27 21:53:38 0 [Note] Event Scheduler: Purging the queue. 0 events
2020-01-27 21:53:38 0 [Note] InnoDB: FTS optimize thread exiting.
2020-01-27 21:53:38 0 [Note] InnoDB: Starting shutdown...
2020-01-27 21:53:38 0 [Note] InnoDB: Dumping buffer pool(s) to /var/lib/mysql/ib_buffer_pool
2020-01-27 21:53:38 0 [Note] InnoDB: Buffer pool(s) dump completed at 200127 21:53:38
2020-01-27 21:53:40 0 [Note] InnoDB: Shutdown completed; log sequence number 19887082; transaction id 14632
2020-01-27 21:53:40 0 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1"
2020-01-27 21:53:40 0 [Note] mysqld: Shutdown complete

2020-01-27 21:53:40+00:00 [Note] [Entrypoint]: Temporary server stopped

2020-01-27 21:53:40+00:00 [Note] [Entrypoint]: MySQL init process done. Ready for start up.

2020-01-27 21:53:40 0 [Note] mysqld (mysqld 10.4.11-MariaDB-1:10.4.11+maria~bionic) starting as process 1 ...
2020-01-27 21:53:40 0 [Note] InnoDB: Using Linux native AIO
2020-01-27 21:53:40 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2020-01-27 21:53:40 0 [Note] InnoDB: Uses event mutexes
2020-01-27 21:53:40 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
2020-01-27 21:53:40 0 [Note] InnoDB: Number of pools: 1
2020-01-27 21:53:40 0 [Note] InnoDB: Using SSE2 crc32 instructions
2020-01-27 21:53:40 0 [Note] mysqld: O_TMPFILE is not supported on /tmp (disabling future attempts)
2020-01-27 21:53:40 0 [Note] InnoDB: Initializing buffer pool, total size = 256M, instances = 1, chunk size = 128M
2020-01-27 21:53:40 0 [Note] InnoDB: Completed initialization of buffer pool
2020-01-27 21:53:40 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
2020-01-27 21:53:40 0 [Note] InnoDB: 128 out of 128 rollback segments are active.
2020-01-27 21:53:40 0 [Note] InnoDB: Creating shared tablespace for temporary tables
2020-01-27 21:53:40 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
2020-01-27 21:53:40 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
2020-01-27 21:53:40 0 [Note] InnoDB: Waiting for purge to start
2020-01-27 21:53:40 0 [Note] InnoDB: 10.4.11 started; log sequence number 19887082; transaction id 14632
2020-01-27 21:53:40 0 [Note] InnoDB: Loading buffer pool(s) from /var/lib/mysql/ib_buffer_pool
2020-01-27 21:53:40 0 [Note] Plugin 'FEEDBACK' is disabled.
2020-01-27 21:53:40 0 [Note] Server socket created on IP: '::'.
2020-01-27 21:53:40 0 [Warning] 'proxies_priv' entry '@% root@4729f11f0714' ignored in --skip-name-resolve mode.
2020-01-27 21:53:40 0 [Note] InnoDB: Buffer pool(s) load completed at 200127 21:53:40
2020-01-27 21:53:40 0 [Note] Reading of all Master_info entries succeeded
2020-01-27 21:53:40 0 [Note] Added new Master_info '' to hash table
2020-01-27 21:53:40 0 [Note] mysqld: ready for connections.
Version: '10.4.11-MariaDB-1:10.4.11+maria~bionic'  socket: '/var/run/mysqld/mysqld.sock'  port: 3306  mariadb.org binary distribution

Once the "ready" message appears, the port works. So to put this to bed, all of the container and network plumbing are in fact working. We are simply waiting for maria db to complete its initial setup and bind to the port.

[mindon]

under MacBook Pro, the connection refused. the podman remote host container shows following error:

tcpproxy: for incoming conn 127.0.0.1:52129, error dialing "192.168.127.2:3306": connect tcp 192.168.127.2:3306: connection was refused

but podman exec -it mariadb /usr/bin/mysql -uroot -p works

[mauruco]

I got it running with the --network flag.
podman run
--network=host
--name mysql
--detach --interactive --tty
-e MYSQL_ROOT_PASSWORD=my-secret-pw -d docker.io/mysql:5.7.31