for-mac icon indicating copy to clipboard operation
for-mac copied to clipboard

virtiofs breaks initial startup of Postgres container

Open TylerADavis opened this issue 2 years ago • 47 comments

  • [X] I have tried with the latest version of Docker Desktop
  • [X] I have tried disabling enabled experimental features
  • [x] I have uploaded Diagnostics
  • Diagnostics ID: DE42E1FF-5DD7-437F-9D40-847D8862DBE5/20220408200124

Expected behavior

Enabling VirtioFS and Big Sur Virtualization framework does not cause changes in container behavior outside of speed.

Actual behavior

Program in container fails to start successfully when it depends on files mounted in shared volume. PostgreSQL complains LOG: could not open file "pg_wal/000000010000000000000001": No such file or directory and FATAL: could not open file "pg_wal/000000010000000000000001": No such file or directory. Disabling virtiofs and experimental virtualization framework allows the container to start without issue.

Information

  • macOS Version: macOS 12.3.1
  • Intel chip or Apple chip: Apple M1 Pro
  • Docker Desktop Version: 4.6.1

This may be a duplicate of #6219 or #6243, but I am not sure. I am trying to run a Postgres container using docker-compose up Postgres, with this docker-compose file. This service is set to mount postgresql's data to the host's ./data/postgres directory, enabling data persistence. When I run the container in a fresh directory without virtiofs and new virtualization framework, it starts just fine. However, if I try to start it from scratch with virtiofs enabled, it fails to start with the message above. I assume virtiofs is interfering with how long it takes for items to show up and be accessible once created. Please let me know if there is any additional information I can provide.

Output of /Applications/Docker.app/Contents/MacOS/com.docker.diagnose check

❯ /Applications/Docker.app/Contents/MacOS/com.docker.diagnose check
Starting diagnostics

[PASS] DD0027: is there available disk space on the host?
[PASS] DD0028: is there available VM disk space?
[PASS] DD0031: does the Docker API work?
[PASS] DD0004: is the Docker engine running?
[PASS] DD0011: are the LinuxKit services running?
[PASS] DD0016: is the LinuxKit VM running?
[PASS] DD0001: is the application running?
[PASS] DD0018: does the host support virtualization?
[PASS] DD0017: can a VM be started?
[PASS] DD0015: are the binary symlinks installed?
[PASS] DD0003: is the Docker CLI working?
[PASS] DD0013: is the $PATH ok?
[PASS] DD0007: is the backend responding?
[PASS] DD0014: are the backend processes running?
[PASS] DD0008: is the native API responding?
[PASS] DD0009: is the vpnkit API responding?
[PASS] DD0010: is the Docker API proxy responding?
[PASS] DD0012: is the VM networking working?
[PASS] DD0032: do Docker networks overlap with host IPs?
[SKIP] DD0030: is the image access management authorized?
[PASS] DD0019: is the com.docker.vmnetd process responding?
[PASS] DD0033: does the host have Internet access?

Steps to reproduce the behavior

  1. Enable virtiofs
  2. mkdir ~/cs143
  3. cd ~/cs143
  4. mkdir ~/cs143_shared
  5. wget curl https://gist.githubusercontent.com/TylerADavis/d1fb104553740bd6b48ea2bdadd6a59d/raw/adcf9d667d5a0c9a51a243be609644d46007a546/docker-compose.yml > docker-compose.yml
  6. docker-compose up Postgres
  7. Observe error message
  8. Disable virtiofs
  9. observe that docker-compose up postgres runs without issue

TylerADavis avatar Apr 08 '22 20:04 TylerADavis

Just realized that 4.7.0 was realized yesterday. I have updated Docker desktop and confirm that this issue persists.

TylerADavis avatar Apr 08 '22 20:04 TylerADavis

I've confirmed that enabling VirtioFS is what causes the error here. The Big Sur virtualization framework on its own is not enough to cause the failure.

TylerADavis avatar Apr 08 '22 20:04 TylerADavis

Can confirm. But this staging release mentioned here seems to fix it: https://github.com/docker/roadmap/issues/7#issuecomment-1073730051

Atomzwieback avatar Apr 09 '22 10:04 Atomzwieback

I also have this problem and latest build does not seem to fix this.

OgulcanCelik avatar Apr 10 '22 00:04 OgulcanCelik

This can be fixed by PGDATA env variable mentioned on: https://github.com/docker-library/postgres/issues/435#issuecomment-611613071

Also I was mounting /var/lib/postgresql/pgdata but changed it to one dir above to /var/lib/postgresql

version: '3'
services:
  postgres:
    image: postgres
    restart: on-failure
    environment:
      - POSTGRES_USER=postgres
      - POSTGRES_PASSWORD=password
      - PGDATA=/var/lib/postgresql/data/pgdata
      - POSTGRES_DB=postgres
    volumes:
      - ./postgres_data:/var/lib/postgresql
    ports:
      - 5432:5432

OgulcanCelik avatar Apr 10 '22 12:04 OgulcanCelik

This can be fixed by PGDATA env variable mentioned on: docker-library/postgres#435 (comment)

Also I was mounting /var/lib/postgresql/pgdata but changed it to one dir above to /var/lib/postgresql

version: '3'
services:
  postgres:
    image: postgres
    restart: on-failure
    environment:
      - POSTGRES_USER=postgres
      - POSTGRES_PASSWORD=password
      - PGDATA=/var/lib/postgresql/data/pgdata
      - POSTGRES_DB=postgres
    volumes:
      - ./postgres_data:/var/lib/postgresql
    ports:
      - 5432:5432

Hi, I tried this method. But when I list "postgres_data", I find an empty "pgdata" folder. And if I try to stop, destroy & recreate my container, it's empty

Does someone obtain this behavior?

Thanks

WD-Mauro avatar Apr 11 '22 08:04 WD-Mauro

I had the same issue.

@OgulcanCelik's suggestion did the trick. In my case I changed

    volumes:
      - ./db/.pgdata:/var/lib/postgresql/data

to

    volumes:
      - ./db/.pgdata:/var/lib/postgresql

and it started working.

haxoza avatar Apr 13 '22 16:04 haxoza

I had the same problem with Docker Desktop for Mac 4.7.0 and the postgres:11.7 container:

  • startup of postgres fails with "could not open file" when mounting /var/lib/postgresql/data in the container to a host directory
  • the error only occurs with VirtioFS
  • the error only occurs on initial start when the volume is empty, the container works fine when the database has already been initialized (there was data corruption later, I think writing to an existing database does not work)
  • the initial error does not occur when mounting /var/lib/postgresql in the container to the host as @OgulcanCelik suggested, but the contents of the data directory /var/lib/postgresql/data are not saved in the host filesystem

It seems that VirtioFS has a bug with some filesystem operations in the initialization script of Postgres.

robcast avatar Apr 16 '22 17:04 robcast

The same on Docker Desktop for Mac 4.7.1 with postgres:14-alpine

Miha-ha avatar Apr 25 '22 09:04 Miha-ha

I have the same issue with Docker Desktop for Mac 4.7.1 with postgres:11-alpine =S

phasath avatar May 05 '22 04:05 phasath

Still having this issue with Docker Desktop for Mac 4.8.0, MacOS 12.3.1 (M1), postgres 13.6-bullseye image when initialising a new database.

The db section of my compose file includes:

environment:
  - PGDATA=/data/pgdata
volumes:
  - ./data:/data

Tried various permutations on the (sub)directories with same result.

tunecrew avatar May 06 '22 15:05 tunecrew

Same on Docker Desktop for Mac 4.8.1 😞

barrenechea avatar May 09 '22 15:05 barrenechea

MacOS 12.4 resolves this for me - although VirtioFS seems to be killing my inter-container communications afterwards, so it is still a no-go.

tunecrew avatar May 18 '22 15:05 tunecrew

MacOS 12.4 Docker Desktop 4.8.2 (79419)

Starting a Postgres with an empty data folder: local-pg-1 | 2022-05-19T05:32:27.532614737Z The files belonging to this database system will be owned by user "postgres". local-pg-1 | 2022-05-19T05:32:27.532685816Z This user must also own the server process. local-pg-1 | 2022-05-19T05:32:27.532703697Z local-pg-1 | 2022-05-19T05:32:27.532715675Z The database cluster will be initialized with locale "en_US.utf8". local-pg-1 | 2022-05-19T05:32:27.532722471Z The default database encoding has accordingly been set to "UTF8". local-pg-1 | 2022-05-19T05:32:27.532733838Z The default text search configuration will be set to "english". local-pg-1 | 2022-05-19T05:32:27.532743068Z local-pg-1 | 2022-05-19T05:32:27.532748297Z Data page checksums are disabled. local-pg-1 | 2022-05-19T05:32:27.533043509Z local-pg-1 | 2022-05-19T05:32:27.534201568Z fixing permissions on existing directory /var/lib/postgresql/data ... ok local-pg-1 | 2022-05-19T05:32:27.554377671Z creating subdirectories ... ok local-pg-1 | 2022-05-19T05:32:27.565615497Z selecting dynamic shared memory implementation ... posix local-pg-1 | 2022-05-19T05:32:27.614942313Z selecting default max_connections ... 100 local-pg-1 | 2022-05-19T05:32:27.657016799Z selecting default shared_buffers ... 128MB local-pg-1 | 2022-05-19T05:32:28.169747869Z selecting default time zone ... UTC local-pg-1 | 2022-05-19T05:32:28.201547956Z creating configuration files ... ok local-pg-1 | 2022-05-19T05:32:30.838963387Z running bootstrap script ... ok local-pg-1 | 2022-05-19T05:32:31.970048368Z sh: locale: not found local-pg-1 | 2022-05-19T05:32:31.977715960Z 2022-05-19 05:32:31.977 UTC [32] WARNING: no usable system locales were found local-pg-1 | 2022-05-19T05:32:37.517561745Z performing post-bootstrap initialization ... ok local-pg-1 | 2022-05-19T05:32:38.889777268Z initdb: warning: enabling "trust" authentication for local connections local-pg-1 | 2022-05-19T05:32:38.889814185Z You can change this by editing pg_hba.conf or using the option -A, or local-pg-1 | 2022-05-19T05:32:38.889820344Z --auth-local and --auth-host, the next time you run initdb. local-pg-1 | 2022-05-19T05:32:38.889785307Z syncing data to disk ... ok local-pg-1 | 2022-05-19T05:32:38.889832132Z local-pg-1 | 2022-05-19T05:32:38.889835393Z local-pg-1 | 2022-05-19T05:32:38.889838409Z Success. You can now start the database server using: local-pg-1 | 2022-05-19T05:32:38.889841545Z local-pg-1 | 2022-05-19T05:32:38.889844520Z pg_ctl -D /var/lib/postgresql/data -l logfile start local-pg-1 | 2022-05-19T05:32:38.889848258Z local-pg-1 | 2022-05-19T05:32:38.933962644Z waiting for server to start....2022-05-19 05:32:38.933 UTC [38] FATAL: data directory "/var/lib/postgresql/data" has wrong ownership local-pg-1 | 2022-05-19T05:32:38.934041494Z 2022-05-19 05:32:38.933 UTC [38] HINT: The server must be started by the user that owns the data directory. local-pg-1 | 2022-05-19T05:32:39.021674471Z pg_ctl: could not start server local-pg-1 | 2022-05-19T05:32:39.021820412Z Examine the log output. local-pg-1 | 2022-05-19T05:32:39.021774328Z stopped waiting

Miha-ha avatar May 19 '22 05:05 Miha-ha

If you're still facing this issue, I recommend you to upgrade your macOS to 12.4 release. Tried it with Docker Desktop for Mac 4.8.2 and VirtioFS enabled, it worked for me.

ajeetraina avatar May 25 '22 12:05 ajeetraina

With macOS 12.4 and Docker Desktop 4.8.2 I am no longer able to reproduce this error using the steps in my original post.

Edit: See https://github.com/docker/for-mac/issues/6270#issuecomment-1138663903, this isn't fully resolved for me

TylerADavis avatar May 25 '22 22:05 TylerADavis

Update - I have an M1 Mac Mini and an M1 MBP configure identically - MacOS 12.4, Docker 4.8.2.

With VirtioFS enabled, I experience the following:

  • Starting Postgres w/ an empty data dir works, and it initialises as expected
  • Restarting the container results in:
db-dev       | 2022-05-26 14:46:41.643 UTC [1] FATAL:  data directory "/data/dev" has wrong ownership
db-dev       | 2022-05-26 14:46:41.643 UTC [1] HINT:  The server must be started by the user that owns the data directory.
db-dev exited with code 1
  • Except (annoyingly) on the MBP but not the Mini, it will actually restart successfully maybe every second or third time

I have tried mapping the PGDATA env variable in my compose file one level below the volume mapping, this doesn't have any effect on the aforementioned behaviour.

tunecrew avatar May 26 '22 14:05 tunecrew

@tunecrew thanks for mentioning that, I'm seeing the same behavior actually. Starting with the initial empty data dir works, but subsequent launches work only intermittently.

TylerADavis avatar May 26 '22 18:05 TylerADavis

Not fixed by Docker 4.9

Update - I have an M1 Mac Mini and an M1 MBP configure identically - MacOS 12.4, Docker 4.8.2.

With VirtioFS enabled, I experience the following:

  • Starting Postgres w/ an empty data dir works, and it initialises as expected
  • Restarting the container results in:
db-dev       | 2022-05-26 14:46:41.643 UTC [1] FATAL:  data directory "/data/dev" has wrong ownership
db-dev       | 2022-05-26 14:46:41.643 UTC [1] HINT:  The server must be started by the user that owns the data directory.
db-dev exited with code 1
  • Except (annoyingly) on the MBP but not the Mini, it will actually restart successfully maybe every second or third time

I have tried mapping the PGDATA env variable in my compose file one level below the volume mapping, this doesn't have any effect on the aforementioned behaviour.

tunecrew avatar Jun 03 '22 15:06 tunecrew

MacOs 12.4, Docker 4.9.0 Still facing this issue when second start the container.

huanghuanghuhu avatar Jun 16 '22 08:06 huanghuanghuhu

MacOs 12.4, Docker 4.10.1 Still facing this issue when second start the container.

timur-gilauri avatar Jul 20 '22 11:07 timur-gilauri

Same thing with mongodb container

ddzobov avatar Jul 27 '22 20:07 ddzobov

Still same issue on MacOS 12.4, Docker 4.11.1

stijnjanmaat avatar Aug 15 '22 14:08 stijnjanmaat

Hi folks, You might want to try switching from bind mount to a docker volume (see here for more information: Docker Volumes)

You can do the following to switch:

  1. Backup your database
  2. Change your docker compose as follows (this example only shows the changes, the volume name can be whatever you prefer, but has to be unique within your docker installation):
#OLD
services:
  db:
    volumes:
      - ./db:/var/lib/mysql
#NEW
volumes:
  my_db_data:
services:
  db:
    volumes:  
      - my_db_data:/var/lib/mysql
  1. Restore your database

richterd avatar Aug 17 '22 07:08 richterd

This is just a workaround, not a actual fix of the problem.

wolflu05 avatar Aug 17 '22 07:08 wolflu05

MacOS 12.5.1 (M1), Docker Desktop 4.11.1. Still facing the same issue.

NumanIbnMazid avatar Aug 31 '22 07:08 NumanIbnMazid

MacOS 12.5.1 (M1), Docker Desktop 4.12.0. Not fixed.

tunecrew avatar Sep 01 '22 18:09 tunecrew

MacOS 12.5.1 (Intel), Docker Desktop 4.12.0. Not fixed.

tagplus5 avatar Sep 06 '22 13:09 tagplus5

Kind of working, but only because I have restart: always in my docker-compose.yml

fails several times during startup, then eventually works:

(MacOS 12.5.1 (Intel), Docker Desktop 4.13.1)

postgres-db-1  | PostgreSQL Database directory appears to contain a database; Skipping initialization
postgres-db-1  | 
postgres-db-1  | 2022-11-07 11:33:21.071 UTC [1] FATAL:  data directory "/var/lib/postgresql/data/pgdata" has wrong ownership
postgres-db-1  | 2022-11-07 11:33:21.071 UTC [1] HINT:  The server must be started by the user that owns the data directory.
postgres-db-1 exited with code 1
postgres-db-1  | 
postgres-db-1  | PostgreSQL Database directory appears to contain a database; Skipping initialization
postgres-db-1  | 
postgres-db-1  | 2022-11-07 11:33:24.807 UTC [1] FATAL:  data directory "/var/lib/postgresql/data/pgdata" has wrong ownership
postgres-db-1  | 2022-11-07 11:33:24.807 UTC [1] HINT:  The server must be started by the user that owns the data directory.
postgres-db-1 exited with code 1
postgres-db-1  | 
postgres-db-1  | PostgreSQL Database directory appears to contain a database; Skipping initialization
postgres-db-1  | 
postgres-db-1  | 2022-11-07 11:33:29.409 UTC [1] FATAL:  data directory "/var/lib/postgresql/data/pgdata" has wrong ownership
postgres-db-1  | 2022-11-07 11:33:29.409 UTC [1] HINT:  The server must be started by the user that owns the data directory.
postgres-db-1 exited with code 1
postgres-db-1  | 
postgres-db-1  | PostgreSQL Database directory appears to contain a database; Skipping initialization
postgres-db-1  | 
postgres-db-1  | 2022-11-07 11:33:34.530 UTC [1] LOG:  starting PostgreSQL 12.5 (Debian 12.5-1.pgdg100+1) on x86_64-pc-linux-gnu, compiled by gcc (Debian 8.3.0-6) 8.3.0, 64-bit
postgres-db-1  | 2022-11-07 11:33:34.531 UTC [1] LOG:  listening on IPv4 address "0.0.0.0", port 5432
postgres-db-1  | 2022-11-07 11:33:34.531 UTC [1] LOG:  listening on IPv6 address "::", port 5432
postgres-db-1  | 2022-11-07 11:33:34.534 UTC [1] LOG:  listening on Unix socket "/var/run/postgresql/.s.PGSQL.5432"
postgres-db-1  | 2022-11-07 11:33:34.585 UTC [30] LOG:  database system was shut down at 2022-11-07 11:30:49 UTC
postgres-db-1  | 2022-11-07 11:33:34.606 UTC [1] LOG:  database system is ready to accept connections

sgbett avatar Nov 07 '22 11:11 sgbett

MacOS 13.0.1 (M1), Docker Desktop 4.13.1. Not fixed.

EDIT: In the new version of Docker Desktop - 4.14.1 I still have the problem:

2022-11-21 12:21:20 2022-11-21 10:21:20.812 UTC [1] FATAL:  data directory "/data/postgres" has wrong ownership
2022-11-21 12:21:20 2022-11-21 10:21:20.812 UTC [1] HINT:  The server must be started by the user that owns the data directory.

GeorgiKeranov avatar Nov 16 '22 13:11 GeorgiKeranov