Server error

[includes08]

I keep on running into the following issue when following the installation wizard.

Server error
PostInstall.SetupException: Error starting database service: postgresql at PostInstall.SetupExecutor.StartDbService() at PostInstall.SetupExecutor.ExecuteSetup(SetupSettings setupSettings, Action1 stateChanged, Action1 errorNotifier) at PbxWebConfigTool.PbxSetupService.CreatePbxInternal(SetupSettings settings)

Any idea what this could be?

[sinegar]

Is this a fresh install or restore? Would you have information on the environment (host/docker) and more logs (console output and /var/lib/3cxpbx/Data/Logs/PbxConfigTool.log)?

[includes08]

Host AlmaLinux release 8.5 (Arctic Sphynx)
Docker Docker version 20.10.16, build aa7e414

Console output

First run. Configure instance ...
Check config tool logs in case of any issues /var/lib/3cxpbx/Data/Logs/PbxConfigTool.log
Run WebConfig on port :5015
Created symlink /etc/systemd/system/multi-user.target.wants/setup-3cx.service -> /etc/systemd/system/setup-3cx.service.
chown: invalid user: 'phonesystem:phonesystem'
Start systemd
First run. Configure instance ...
Check config tool logs in case of any issues /var/lib/3cxpbx/Data/Logs/PbxConfigTool.log
Run WebConfig on port :5015
chown: invalid user: 'phonesystem:phonesystem'
Start systemd

PbxConfigTool.log

  "Success": false,
  "ServerProcessSetupOperation": false,
  "ManagementConsoleHttpsUrl": null,
  "UserName": null,
Password Removed
  "ManagementConsoleIpUrl": null,
  "HostnameOrFullFqdn": null,
  "PublicIp": null,
  "Fqdn": null,
  "LicenseKey": null,
  "ErrorMessage": "PostInstall.SetupException: Error starting database service: postgresql\n   at PostInstall.SetupExecutor.StartDbService()\n   at PostInstall.SetupExecutor.ExecuteSetup(SetupSettings setupSettings, Action`1 stateChanged, Action`1 errorNotifier)\n   at PbxWebConfigTool.PbxSetupService.CreatePbxInternal(SetupSettings settings)",
  "LicenseActivated": false,
  "SelfSignedCertificatesGenerated": false,
  "ActivationEmail": null
}

2022/05/24 17:16:20.247|Dbg|0055|  GetInstallationResult
2022/05/24 17:16:20.248|Dbg|0055|  GetInstallationResult result = {
  "Success": false,
  "ServerProcessSetupOperation": false,
  "ManagementConsoleHttpsUrl": null,
  "UserName": null,
Password Removed
  "ManagementConsoleIpUrl": null,
  "HostnameOrFullFqdn": null,
  "PublicIp": null,
  "Fqdn": null,
  "LicenseKey": null,
  "ErrorMessage": "PostInstall.SetupException: Error starting database service: postgresql\n   at PostInstall.SetupExecutor.StartDbService()\n   at PostInstall.SetupExecutor.ExecuteSetup(SetupSettings setupSettings, Action`1 stateChanged, Action`1 errorNotifier)\n   at PbxWebConfigTool.PbxSetupService.CreatePbxInternal(SetupSettings settings)",
  "LicenseActivated": false,
  "SelfSignedCertificatesGenerated": false,
  "ActivationEmail": null
}

Postgresql Log

2022-03-02 09:44:59.369 UTC [4250] LOG:  database system was shut down at 2022-03-02 09:44:56 UTC
2022-03-02 09:44:59.374 UTC [4249] LOG:  database system is ready to accept connections
2022-03-02 09:44:59.945 UTC [4257] [unknown]@[unknown] LOG:  incomplete startup packet
2022-03-02 09:45:04.694 UTC [4750] postgres@postgres ERROR:  database "database_single" does not exist
2022-03-02 09:45:04.694 UTC [4750] postgres@postgres STATEMENT:  drop database database_single;
2022-03-02 09:45:04.695 UTC [4750] postgres@postgres ERROR:  database "masterprofiles" does not exist
2022-03-02 09:45:04.695 UTC [4750] postgres@postgres STATEMENT:  drop database masterprofiles;
2022-03-02 09:45:04.695 UTC [4750] postgres@postgres ERROR:  role "logsreader_single" does not exist
2022-03-02 09:45:04.695 UTC [4750] postgres@postgres STATEMENT:  drop user logsreader_single;
2022-03-02 09:45:04.696 UTC [4750] postgres@postgres ERROR:  role "myphone_single" does not exist
2022-03-02 09:45:04.696 UTC [4750] postgres@postgres STATEMENT:  drop user myphone_single;
2022-05-22 13:07:17.812 UTC [51] LOG:  listening on IPv4 address "127.0.0.1", port 5432
2022-05-22 13:07:17.812 UTC [51] LOG:  could not bind IPv6 address "::1": Cannot assign requested address
2022-05-22 13:07:17.812 UTC [51] HINT:  Is another postmaster already running on port 5432? If not, wait a few seconds and retry.
2022-05-22 13:07:17.812 UTC [51] LOG:  listening on Unix socket "/var/run/postgresql/.s.PGSQL.5432"
2022-05-22 13:07:17.816 UTC [52] LOG:  database system was interrupted; last known up at 2022-03-02 09:44:59 UTC
2022-05-22 13:07:17.957 UTC [52] LOG:  database system was not properly shut down; automatic recovery in progress
2022-05-22 13:07:17.959 UTC [52] LOG:  redo starts at 0/16564F8
2022-05-22 13:07:17.959 UTC [52] LOG:  invalid record length at 0/1657018: wanted 24, got 0
2022-05-22 13:07:17.959 UTC [52] LOG:  redo done at 0/1656FB0
2022-05-22 13:07:17.959 UTC [52] LOG:  last completed transaction was at log time 2022-03-02 09:45:04.695565+00
2022-05-22 13:07:17.964 UTC [51] LOG:  database system is ready to accept connections
2022-05-22 13:07:18.508 UTC [59] [unknown]@[unknown] LOG:  incomplete startup packet
2022-05-23 14:07:33.141 UTC [2011] postgres@postgres ERROR:  database "database_single" does not exist
2022-05-23 14:07:33.141 UTC [2011] postgres@postgres STATEMENT:  drop database database_single;
2022-05-23 14:07:33.141 UTC [2011] postgres@postgres ERROR:  database "masterprofiles" does not exist
2022-05-23 14:07:33.141 UTC [2011] postgres@postgres STATEMENT:  drop database masterprofiles;
2022-05-23 14:07:33.142 UTC [2011] postgres@postgres ERROR:  role "logsreader_single" does not exist
2022-05-23 14:07:33.142 UTC [2011] postgres@postgres STATEMENT:  drop user logsreader_single;
2022-05-23 14:07:33.142 UTC [2011] postgres@postgres ERROR:  role "myphone_single" does not exist
2022-05-23 14:07:33.142 UTC [2011] postgres@postgres STATEMENT:  drop user myphone_single;
2022-05-23 14:07:38.357 UTC [2065] postgres@postgres ERROR:  database "database_single" does not exist
2022-05-23 14:07:38.357 UTC [2065] postgres@postgres STATEMENT:  drop database database_single;
2022-05-23 14:07:38.357 UTC [2065] postgres@postgres ERROR:  database "masterprofiles" does not exist
2022-05-23 14:07:38.357 UTC [2065] postgres@postgres STATEMENT:  drop database masterprofiles;
2022-05-23 14:07:38.358 UTC [2065] postgres@postgres ERROR:  role "phonesystem" does not exist
2022-05-23 14:07:38.358 UTC [2065] postgres@postgres STATEMENT:  drop user phonesystem;
2022-05-23 14:07:38.358 UTC [2065] postgres@postgres ERROR:  role "logsreader_single" does not exist
2022-05-23 14:07:38.358 UTC [2065] postgres@postgres STATEMENT:  drop user logsreader_single;
2022-05-23 14:07:38.358 UTC [2065] postgres@postgres ERROR:  role "myphone_single" does not exist
2022-05-23 14:07:38.358 UTC [2065] postgres@postgres STATEMENT:  drop user myphone_single;
2022-05-23 14:09:32.583 UTC [51] LOG:  listening on IPv4 address "127.0.0.1", port 5432
2022-05-23 14:09:32.583 UTC [51] LOG:  could not bind IPv6 address "::1": Cannot assign requested address
2022-05-23 14:09:32.583 UTC [51] HINT:  Is another postmaster already running on port 5432? If not, wait a few seconds and retry.
2022-05-23 14:09:32.583 UTC [51] LOG:  listening on Unix socket "/var/run/postgresql/.s.PGSQL.5432"
2022-05-23 14:09:32.589 UTC [52] LOG:  database system was interrupted; last known up at 2022-05-23 14:07:37 UTC
2022-05-23 14:09:32.598 UTC [52] LOG:  database system was not properly shut down; automatic recovery in progress
2022-05-23 14:09:32.599 UTC [52] LOG:  redo starts at 0/1658610
2022-05-23 14:09:32.599 UTC [52] LOG:  invalid record length at 0/16586F0: wanted 24, got 0
2022-05-23 14:09:32.599 UTC [52] LOG:  redo done at 0/16586B8
2022-05-23 14:09:32.602 UTC [51] LOG:  database system is ready to accept connections
2022-05-23 14:09:33.179 UTC [59] [unknown]@[unknown] LOG:  incomplete startup packet

If you need more information, let me know.

[sinegar]

That looks very strange. Particularly the “chown: invalid user: 'phonesystem:phonesystem'” as the user should be part of the image…

How do you run the container (e.g. docker run or compose)? Would you share the command line and/or config?

Lastly, would you share the output of “docker info”?

[includes08]

Docker compose conf

networks:
  web:
    external: true
  internal:
    external: false

services:
  portainer:
    image: ghcr.io/izer-xyz/3cx:latest
    container_name: 3cx
    restart: unless-stopped
    security_opt:
      - no-new-privileges:true
    tmpfs:
      - /tmp
      - /run
      - /run/lock
    volumes:
      - /sys/fs/cgroup:/sys/fs/cgroup:ro
    labels:
      - traefik.http.routers.3cx.rule=Host(`3cx.dckr.address`)
      - traefik.http.routers.3cx.entrypoints=websecure
      - traefik.http.routers.3cx.tls=true
      - traefik.http.routers.3cx.tls.certresolver=lets-encrypt
      - traefik.http.services.3cx.loadbalancer.server.port=5001
    networks:
      - internal
      - web
    ports:
      - 5000:5000
      - 5001:5001
      - 5060:5060
      - 5060:5060/udp
      - 5090:5090
      - 5090:5090/udp

Docker Info

 Context:    default
 Debug Mode: false
 Plugins:
  app: Docker App (Docker Inc., v0.9.1-beta3)
  buildx: Docker Buildx (Docker Inc., v0.8.2-docker)
  compose: Docker Compose (Docker Inc., v2.5.0)
  scan: Docker Scan (Docker Inc., v0.17.0)

Server:
 Containers: 4
  Running: 4
  Paused: 0
  Stopped: 0
 Images: 7
 Server Version: 20.10.16
 Storage Driver: overlay2
  Backing Filesystem: xfs
  Supports d_type: true
  Native Overlay Diff: true
  userxattr: false
 Logging Driver: json-file
 Cgroup Driver: cgroupfs
 Cgroup Version: 1
 Plugins:
  Volume: local
  Network: bridge host ipvlan macvlan null overlay
  Log: awslogs fluentd gcplogs gelf journald json-file local logentries splunk syslo      g
 Swarm: inactive
 Runtimes: runc io.containerd.runc.v2 io.containerd.runtime.v1.linux
 Default Runtime: runc
 Init Binary: docker-init
 containerd version: 212e8b6fa2f44b9c21b2798135fc6fb7c53efc16
 runc version: v1.1.1-0-g52de29d
 init version: de40ad0
 Security Options:
  seccomp
   Profile: default
 Kernel Version: 4.18.0-348.el8.x86_64
 Operating System: AlmaLinux 8.5 (Arctic Sphynx)
 OSType: linux
 Architecture: x86_64
 CPUs: 4
 Total Memory: 7.585GiB
 Name: dckr01
 ID: UAMI:KNYE:VZVL:DRRW:NB7W:PTYV:SS6N:VEYD:AQSH:RBY3:MDIM:DOFC
 Docker Root Dir: /var/lib/docker
 Debug Mode: false
 Registry: https://index.docker.io/v1/
 Labels:
 Experimental: false
 Insecure Registries:
  127.0.0.0/8
 Live Restore Enabled: false

[sinegar]

All looks okay. I will have to try to reproduce with a clean install when I have some time (maybe this weekend).

In the mean time would you mind posting the full console log (with the services starting). Something like this:

irst run. Configure instance ...
Check config tool logs in case of any issues /var/lib/3cxpbx/Data/Logs/PbxConfigTool.log
Run WebConfig on port :5015
Created symlink /etc/systemd/system/multi-user.target.wants/setup-3cx.service -> /etc/systemd/system/setup-3cx.service.
chown: invalid user: 'phonesystem:phonesystem'
Start systemd

Welcome to Debian GNU/Linux 10 (buster)!

[  OK  ] Listening on Journal Socket.
[  OK  ] Reached target Slices.
[  OK  ] Reached target Network is Online.
[  OK  ] Started Dispatch Password Requests to Console Directory Watch.
[  OK  ] Reached target Paths.
[  OK  ] Listening on Journal Socket (/dev/log).
[  OK  ] Reached target Sockets.
         Starting Journal Service...
[  OK  ] Reached target Local File Systems.
[  OK  ] Reached target Swap.
[  OK  ] Reached target Local Encrypted Volumes.
         Starting Create System Users...
[  OK  ] Started Journal Service.
         Starting Flush Journal to Persistent Storage...
[  OK  ] Started Create System Users.
[  OK  ] Reached target System Initialization.
[  OK  ] Started Daily Cleanup of Temporary Directories.
[  OK  ] Reached target Timers.
[  OK  ] Reached target Basic System.
         Starting A high performance web server and a reverse proxy server...
         Starting Setup 3CX...
[  OK  ] Started Flush Journal to Persistent Storage.
[  OK  ] Created slice system-postgresql.slice.
         Starting PostgreSQL Cluster 11-main...
[  OK  ] Started A high performance web server and a reverse proxy server.
[  OK  ] Started PostgreSQL Cluster 11-main.
         Starting PostgreSQL RDBMS...
[  OK  ] Started PostgreSQL RDBMS.
[  OK  ] Started Setup 3CX.
[  OK  ] Reached target Multi-User System.
[  OK  ] Reached target Graphical Interface.

[sinegar]

I did a clean install and all worked.

Would you post the console log after “start systemd”?

And also the output of (after starting a fresh container):

docker exec -it [id] sh -c "ps eax"
docker exec -it [id] sh -c "netstat -ln"

[DjSni]

Hi,

i have the same error. But the system isn't starting.
System: UnRAID 6.10.2
Docker: 20.10.14

Check config tool logs in case of any issues /var/lib/3cxpbx/Data/Logs/PbxConfigTool.log
Run WebConfig on port :5015
Created symlink /etc/systemd/system/multi-user.target.wants/setup-3cx.service -> /etc/systemd/system/setup-3cx.service.
chown: invalid user: 'phonesystem:phonesystem'
Start systemd

Can´t attach logs, there is no /var/lib/3cxpbx path...

[sinegar]

If Start systemd is the last message it seems systemd isn’t starting…

Does the container quit right away? Is AppArmor enabled on the host?

Would you provide the output of the following commands ([id] is the 3cx container id):

docker info
docker exec -it [id] sh -c "ps eax"
docker exec -it [id] sh -c "netstat -ln"

[DjSni]

Hello,

Yes, this is the last display after which the container is immediately terminated. I cannot say exactly whether AppArmor is activated.

Client:
 Context:    default
 Debug Mode: false

Server:
 Containers: 37
  Running: 16
  Paused: 0
  Stopped: 21
 Images: 36
 Server Version: 20.10.14
 Storage Driver: btrfs
  Build Version: Btrfs v4.20.1 
  Library Version: 102
 Logging Driver: json-file
 Cgroup Driver: cgroupfs
 Cgroup Version: 1
 Plugins:
  Volume: local
  Network: bridge host ipvlan macvlan null overlay
  Log: awslogs fluentd gcplogs gelf journald json-file local logentries splunk syslog
 Swarm: inactive
 Runtimes: io.containerd.runc.v2 io.containerd.runtime.v1.linux runc
 Default Runtime: runc
 Init Binary: docker-init
 containerd version: 3df54a852345ae127d1fa3092b95168e4a88e2f8
 runc version: v1.0.3-0-gf46b6ba2
 init version: de40ad0
 Security Options:
  seccomp
   Profile: default
 Kernel Version: 5.15.43-Unraid
 Operating System: Slackware 15.0 x86_64
 OSType: linux
 Architecture: x86_64
 CPUs: 12
 Total Memory: 62.55GiB
 Name: XXXXX
 ID: QXDN:LSG3:EJPH:LMOY:UBKS:6OB6:Q7OX:2EGY:JOI3:LYER:MK53:GDTN
 Docker Root Dir: /var/lib/docker
 Debug Mode: false
 Registry: https://index.docker.io/v1/
 Labels:
 Experimental: false
 Insecure Registries:
  127.0.0.0/8
 Live Restore Enabled: false
 Product License: Community Engine

The container is on too short so then I always get the error message Error response from daemon: Container c1c3389e785bff1a1009d731c9984ce8b04fbcd0724222fcbd1c1967731382bd is not running I get

[sinegar]

Thanks. I will send you command line to try to get more info on what's going on but need to test first when I have some time (probably later this week).

[sinegar]

Would you try to run this command and send the output?

docker run -it --rm --tmpfs /run --tmpfs /run/lock -v /sys/fs/cgroup:/sys/fs/cgroup:ro ghcr.io/izer-xyz/3cx:latest /lib/systemd/systemd --log-level=debug --log-target=console --show-status=true

[DjSni]

Unable to find image 'ghcr.io/izer-xyz/3cx:latest' locally
latest: Pulling from izer-xyz/3cx
Digest: sha256:348699118db4b80270c3b4b1864f0d09d71025f4b8520e42c07fa8edaf567386
Status: Downloaded newer image for ghcr.io/izer-xyz/3cx:latest
Failed to parse kernel command line, ignoring: Cannot allocate memory
systemd 241 running in system mode. (+PAM +AUDIT +SELINUX +IMA +APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD -IDN2 +IDN -PCRE2 default-hierarchy=hybrid)
Detected virtualization docker.
Detected architecture x86-64.
Mounting cgroup to /sys/fs/cgroup/net_cls,net_prio of type cgroup with options net_cls,net_prio.
Failed to mount cgroup at /sys/fs/cgroup/net_cls,net_prio: Operation not permitted
Failed to create symlink /sys/fs/cgroup/net_cls: File exists
Failed to create symlink /sys/fs/cgroup/net_prio: File exists
Mounting cgroup to /sys/fs/cgroup/cpu,cpuacct of type cgroup with options cpu,cpuacct.
Failed to mount cgroup at /sys/fs/cgroup/cpu,cpuacct: Operation not permitted
Failed to create symlink /sys/fs/cgroup/cpu: File exists
Failed to create symlink /sys/fs/cgroup/cpuacct: File exists

Welcome to Debian GNU/Linux 10 (buster)!

Set hostname to <d6e89be65977>.
Failed to add address 127.0.0.1 to loopback interface: Operation not permitted
Failed to add address ::1 to loopback interface: Operation not permitted
Failed to bring loopback interface up: Operation not permitted
Failed to bump AF_UNIX datagram queue length, ignoring: Read-only file system
Setting 'fs/file-max' to '9223372036854775807'.
Failed to bump fs.file-max, ignoring: Read-only file system
RLIMIT_MEMLOCK is already as high or higher than we need it, not bumping.
Failed to read /proc/cmdline: Cannot allocate memory
Cannot determine cgroup we are running in: No data available
Failed to allocate manager object: No data available
[!!!!!!] Failed to allocate manager object.
Exiting PID 1...

[DjSni]

if i use docker run -it --rm --tmpfs /run --tmpfs /run/lock -v /sys/fs/cgroup:/sys/fs/cgroup:ro izerxyz/3cx:latest /lib/systemd/systemd --log-level=debug --log-target=console --show-status=true

Failed to parse kernel command line, ignoring: Cannot allocate memory
systemd 241 running in system mode. (+PAM +AUDIT +SELINUX +IMA +APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD -IDN2 +IDN -PCRE2 default-hierarchy=hybrid)
Detected virtualization docker.
Detected architecture x86-64.
Mounting cgroup to /sys/fs/cgroup/cpu,cpuacct of type cgroup with options cpu,cpuacct.
Failed to mount cgroup at /sys/fs/cgroup/cpu,cpuacct: Operation not permitted
Failed to create symlink /sys/fs/cgroup/cpuacct: File exists
Failed to create symlink /sys/fs/cgroup/cpu: File exists
Mounting cgroup to /sys/fs/cgroup/net_cls,net_prio of type cgroup with options net_cls,net_prio.
Failed to mount cgroup at /sys/fs/cgroup/net_cls,net_prio: Operation not permitted
Failed to create symlink /sys/fs/cgroup/net_prio: File exists
Failed to create symlink /sys/fs/cgroup/net_cls: File exists

Welcome to Debian GNU/Linux 10 (buster)!

Set hostname to <bc683044a4c9>.
Failed to add address 127.0.0.1 to loopback interface: Operation not permitted
Failed to add address ::1 to loopback interface: Operation not permitted
Failed to bring loopback interface up: Operation not permitted
Failed to bump AF_UNIX datagram queue length, ignoring: Read-only file system
Setting 'fs/file-max' to '9223372036854775807'.
Failed to bump fs.file-max, ignoring: Read-only file system
RLIMIT_MEMLOCK is already as high or higher than we need it, not bumping.
Failed to read /proc/cmdline: Cannot allocate memory
Cannot determine cgroup we are running in: No data available
Failed to allocate manager object: No data available
[!!!!!!] Failed to allocate manager object.
Exiting PID 1...

[sinegar]

The container doesn’t seem to have access to the host /sys/fs/cgroup which is needed by systemd.

Do you get any errors when you run this?

docker run -it --rm --tmpfs /run --tmpfs /run/lock -v /sys/fs/cgroup:/sys/fs/cgroup:ro ghcr.io/izer-xyz/3cx:latest ls -la /sys/fs/cgroup

[DjSni]

i found this -> https://forums.unraid.net/bug-reports/stable-releases/6102-docker-error-r1970/

my out:

total 0
drwxr-xr-x 15 root root 320 Jun  5 08:38 .
drwxr-xr-x  8 root root   0 Jun  6 10:43 ..
dr-xr-xr-x  6 root root   0 Jun  5 08:38 blkio
dr-xr-xr-x  6 root root   0 Jun  5 08:38 cpu
dr-xr-xr-x  6 root root   0 Jun  5 08:38 cpuacct
dr-xr-xr-x  6 root root   0 Jun  5 08:38 cpuset
dr-xr-xr-x  6 root root   0 Jun  5 08:38 devices
dr-xr-xr-x  6 root root   0 Jun  5 08:38 elogind
dr-xr-xr-x  6 root root   0 Jun  5 08:38 freezer
dr-xr-xr-x  6 root root   0 Jun  5 08:38 hugetlb
dr-xr-xr-x  6 root root   0 Jun  5 08:38 memory
dr-xr-xr-x  6 root root   0 Jun  5 08:38 net_cls
dr-xr-xr-x  6 root root   0 Jun  5 08:38 net_prio
dr-xr-xr-x  6 root root   0 Jun  5 08:38 perf_event
dr-xr-xr-x  6 root root   0 Jun  5 08:38 pids
lrwxrwxrwx  1 root root   7 Jun  5 08:38 systemd -> elogind