NS8: Configure NGINX fails

EddieA · May 14, 2023, 9:43pm

Running first time configure of nginx threw this:

{
  "context": {
    "action": "configure-module",
    "data": {
      "http2https": true,
      "path": "/sftpgo",
      "sftp_tcp_port": 3092,
      "sftpgo_service": true
    },
    "extra": {
      "description": "Configuring...",
      "title": "webserver1 configuration"
    },
    "id": "6a03c944-e345-42f5-812f-22974a03970b",
    "parent": "",
    "queue": "module/webserver1/tasks",
    "timestamp": "2023-05-14T21:29:28.449928762Z",
    "user": "admin"
  },
  "status": "aborted",
  "progress": 80,
  "subTasks": [
    {
      "context": {
        "action": "add-public-service",
        "data": {
          "ports": [
            "3092/tcp"
          ],
          "service": "webserver1"
        },
        "extra": {},
        "id": "4f35f3ee-a276-4a6b-9291-db9ab7792d87",
        "parent": "6a03c944-e345-42f5-812f-22974a03970b",
        "queue": "node/1/tasks",
        "timestamp": "2023-05-14T21:29:29.410030607Z",
        "user": "module/webserver1"
      },
      "status": "completed",
      "progress": 100,
      "subTasks": [],
      "result": {
        "error": "<7>firewall-cmd --permanent --new-service=webserver1\nsuccess\n<7>firewall-cmd --permanent --add-service=webserver1\nsuccess\n<7>firewall-cmd --permanent --service=webserver1 --add-port=3092/tcp\nsuccess\n<7>firewall-cmd --reload\nsuccess\n",
        "exit_code": 0,
        "file": "task/node/1/4f35f3ee-a276-4a6b-9291-db9ab7792d87",
        "output": ""
      }
    },
    {
      "context": {
        "action": "set-route",
        "data": {
          "http2https": true,
          "instance": "webserver1",
          "path": "/sftpgo",
          "url": "http://127.0.0.1:20011"
        },
        "extra": {},
        "id": "8ec8867b-dd48-42c1-ae03-0081a67b8784",
        "parent": "6a03c944-e345-42f5-812f-22974a03970b",
        "queue": "module/traefik1/tasks",
        "timestamp": "2023-05-14T21:29:31.925970825Z",
        "user": "module/webserver1"
      },
      "status": "completed",
      "progress": 100,
      "subTasks": [],
      "result": {
        "error": "",
        "exit_code": 0,
        "file": "task/module/traefik1/8ec8867b-dd48-42c1-ae03-0081a67b8784",
        "output": ""
      }
    }
  ],
  "validated": true,
  "result": {
    "error": "<7>dump_env() is deprecated and implemented as a no-op\n<7>systemctl --user restart webserver.service\n<7>systemctl --user enable sftpgo.service\nCreated symlink /home/webserver1/.config/systemd/user/default.target.wants/sftpgo.service → /home/webserver1/.config/systemd/user/sftpgo.service.\n<7>systemctl --user restart sftpgo.service\nTraceback (most recent call last):\n  File \"/home/webserver1/.config/actions/configure-module/60sftpgo_create_secret\", line 44, in <module>\n    res = conn.getresponse()\n  File \"/usr/lib64/python3.9/http/client.py\", line 1377, in getresponse\n    response.begin()\n  File \"/usr/lib64/python3.9/http/client.py\", line 320, in begin\n    version, status, reason = self._read_status()\n  File \"/usr/lib64/python3.9/http/client.py\", line 281, in _read_status\n    line = str(self.fp.readline(_MAXLINE + 1), \"iso-8859-1\")\n  File \"/usr/lib64/python3.9/socket.py\", line 704, in readinto\n    return self._sock.recv_into(b)\nConnectionResetError: [Errno 104] Connection reset by peer\n",
    "exit_code": 1,
    "file": "task/module/webserver1/6a03c944-e345-42f5-812f-22974a03970b",
    "output": ""
  }
}

Cheers.

EddieA · May 15, 2023, 2:43am

Just ran through this again and this time everything worked as it should. No idea what might have thrown it off last time.

Cheers.

giacomo · May 15, 2023, 10:14am

Let’s try to reproduce it.
Can you look at it @stephdl?

stephdl · May 15, 2023, 10:16am

On todo. Please what is the operating system you used ?

stephdl · May 15, 2023, 1:33pm

well I think that when we started the script 60sftpgo_create_secret, the container was not up enough quickly.

60sftpgo_create_secret\", line 44, in <module>\n res = conn.getresponse()\

We need to give him a bit more time in ns8-webserver/sftpgo.service at main · NethServer/ns8-webserver · GitHub and test if the container is up

ExecStartPost=/usr/bin/bash -c "while ! exec 3<>/dev/tcp/127.0.0.1/${SFTP_TCP_PORT} &>/dev/null; do sleep 3 ; done ; printf 'GET /ping\r\n\r\n' >&3"

otherwise we could test inside a loop in ns8-webserver/50start_services at main · NethServer/ns8-webserver · GitHub and once the loop is over we fail to start, the two approach are good for me

which one @giacomo ?

giacomo · May 15, 2023, 1:38pm

I’d go with this one.
The wait loop is not really beautiful, but this is the usual way to fix such things in the container world.

EddieA · June 1, 2023, 11:54pm

Except maybe not.

I just got the same “ConnectionResetError: [Errno 104] Connection reset by peer” error again:

Summary

{
  "context": {
    "action": "configure-module",
    "data": {
      "http2https": true,
      "path": "/sftpgo",
      "sftp_tcp_port": 3092,
      "sftpgo_service": true
    },
    "extra": {
      "description": "Configuring...",
      "title": "webserver1 configuration"
    },
    "id": "9e6f37e0-45f3-4927-8c70-647d12cb351f",
    "parent": "",
    "queue": "module/webserver1/tasks",
    "timestamp": "2023-06-01T23:29:12.482675576Z",
    "user": "admin"
  },
  "status": "aborted",
  "progress": 80,
  "subTasks": [
    {
      "context": {
        "action": "add-public-service",
        "data": {
          "ports": [
            "3092/tcp"
          ],
          "service": "webserver1"
        },
        "extra": {},
        "id": "656eb27f-fc16-4690-87bb-7330fa0495b3",
        "parent": "9e6f37e0-45f3-4927-8c70-647d12cb351f",
        "queue": "node/1/tasks",
        "timestamp": "2023-06-01T23:29:13.424705802Z",
        "user": "module/webserver1"
      },
      "status": "completed",
      "progress": 100,
      "subTasks": [],
      "result": {
        "error": "<7>firewall-cmd --permanent --new-service=webserver1\nsuccess\n<7>firewall-cmd --permanent --add-service=webserver1\nsuccess\n<7>firewall-cmd --permanent --service=webserver1 --add-port=3092/tcp\nsuccess\n<7>firewall-cmd --reload\nsuccess\n",
        "exit_code": 0,
        "file": "task/node/1/656eb27f-fc16-4690-87bb-7330fa0495b3",
        "output": ""
      }
    },
    {
      "context": {
        "action": "set-route",
        "data": {
          "http2https": true,
          "instance": "webserver1",
          "path": "/sftpgo",
          "url": "http://127.0.0.1:20011"
        },
        "extra": {},
        "id": "1f5fe03b-a6b2-492b-a4ee-91681d334394",
        "parent": "9e6f37e0-45f3-4927-8c70-647d12cb351f",
        "queue": "module/traefik1/tasks",
        "timestamp": "2023-06-01T23:29:15.542775245Z",
        "user": "module/webserver1"
      },
      "status": "completed",
      "progress": 100,
      "subTasks": [],
      "result": {
        "error": "",
        "exit_code": 0,
        "file": "task/module/traefik1/1f5fe03b-a6b2-492b-a4ee-91681d334394",
        "output": ""
      }
    }
  ],
  "validated": true,
  "result": {
    "error": "<7>dump_env() is deprecated and implemented as a no-op\n<7>systemctl --user restart webserver.service\n<7>systemctl --user enable sftpgo.service\nCreated symlink /home/webserver1/.config/systemd/user/default.target.wants/sftpgo.service → /home/webserver1/.config/systemd/user/sftpgo.service.\n<7>systemctl --user restart sftpgo.service\nTraceback (most recent call last):\n  File \"/home/webserver1/.config/actions/configure-module/60sftpgo_create_secret\", line 44, in <module>\n    res = conn.getresponse()\n  File \"/usr/lib64/python3.9/http/client.py\", line 1377, in getresponse\n    response.begin()\n  File \"/usr/lib64/python3.9/http/client.py\", line 320, in begin\n    version, status, reason = self._read_status()\n  File \"/usr/lib64/python3.9/http/client.py\", line 281, in _read_status\n    line = str(self.fp.readline(_MAXLINE + 1), \"iso-8859-1\")\n  File \"/usr/lib64/python3.9/socket.py\", line 704, in readinto\n    return self._sock.recv_into(b)\nConnectionResetError: [Errno 104] Connection reset by peer\n",
    "exit_code": 1,
    "file": "task/module/webserver1/9e6f37e0-45f3-4927-8c70-647d12cb351f",
    "output": ""
  }
}

And I did check that I have the latest service file with the loop.

Cheers.

stephdl · June 6, 2023, 1:29pm

if you use the same module, even updated it is probably normal it fails

I tested yesterday and I cannot reproduce the issue, please to help the developement go to journald to catch the error for instance

journalctl -t webserver1

EddieA · June 6, 2023, 3:57pm

Summary

Jun 01 23:22:47 node.ns8.test webserver1[34747]: task/module/webserver1/af1a56ee-884c-44d7-98b1-59077018e741: create-module/05pullimages is starting
Jun 01 23:22:47 node.ns8.test webserver1[34747]: Add to module/webserver1 environment NGINX_IMAGE=docker.io/nginx:1.20-alpine
Jun 01 23:22:47 node.ns8.test webserver1[34747]: Add to module/webserver1 environment SFTPGO_IMAGE=docker.io/drakkan/sftpgo:v2.2-alpine
Jun 01 23:22:47 node.ns8.test webserver1[34747]: dump_env() is deprecated and implemented as a no-op
Jun 01 23:22:47 node.ns8.test webserver1[34747]: podman-pull-missing docker.io/nginx:1.20-alpine docker.io/drakkan/sftpgo:v2.2-alpine
Jun 01 23:22:49 node.ns8.test webserver1[34747]: Trying to pull docker.io/library/nginx:1.20-alpine...
Jun 01 23:22:50 node.ns8.test webserver1[34747]: Getting image source signatures
Jun 01 23:22:50 node.ns8.test webserver1[34747]: Copying blob sha256:7051f5a2f4b122618ec9ebf106f51756138b1c3a79779e92e3d2c9b0e386dc6c
Jun 01 23:22:50 node.ns8.test webserver1[34747]: Copying blob sha256:a1484661dfe6f3eb83e07dd13dddb7979632cceefb8727ed92fd7ade42ca80af
Jun 01 23:22:50 node.ns8.test webserver1[34747]: Copying blob sha256:8663204ce13b2961da55026a2034abb9e5afaaccf6a9cfb44ad71406dcd07c7b
Jun 01 23:22:50 node.ns8.test webserver1[34747]: Copying blob sha256:2f78a3560d105ad7a9929fde717e9d40dfe85e8dd01d5b470a0d769232b1450c
Jun 01 23:22:50 node.ns8.test webserver1[34747]: Copying blob sha256:a517401f7a948ad8515280ff185a1045d47df79cd9aea6760f732568ee8e0193
Jun 01 23:22:50 node.ns8.test webserver1[34747]: Copying blob sha256:294d17c34d1392240dac72346cbe9dbc86515f883a190bf1409691b3518735d2
Jun 01 23:22:53 node.ns8.test webserver1[34747]: Copying config sha256:6cf0c840a5a456151810814231943a691d54afc5ee58a2e447d5f259e5e23ab2
Jun 01 23:22:54 node.ns8.test webserver1[34747]: Writing manifest to image destination
Jun 01 23:22:54 node.ns8.test webserver1[34747]: Storing signatures
Jun 01 23:22:54 node.ns8.test webserver1[34747]: 6cf0c840a5a456151810814231943a691d54afc5ee58a2e447d5f259e5e23ab2
Jun 01 23:22:54 node.ns8.test webserver1[34747]: Trying to pull docker.io/drakkan/sftpgo:v2.2-alpine...
Jun 01 23:22:56 node.ns8.test webserver1[34747]: Getting image source signatures
Jun 01 23:22:56 node.ns8.test webserver1[34747]: Copying blob sha256:10b33ff7b6b9092df6d4a0b5b69af35003b0feb9ad5956907dd0c74505dbf1f1
Jun 01 23:22:56 node.ns8.test webserver1[34747]: Copying blob sha256:d24496e320fab97d85e6dac73c5bbe992caaf1e585798481165d6f718cc05585
Jun 01 23:22:56 node.ns8.test webserver1[34747]: Copying blob sha256:df9b9388f04ad6279a7410b85cedfdcb2208c0a003da7ab5613af71079148139
Jun 01 23:22:56 node.ns8.test webserver1[34747]: Copying blob sha256:eefba077a1fa46b47ef4abae5621294f71cdf6e1c0f9a3e7fce7a4d770d5afb8
Jun 01 23:22:56 node.ns8.test webserver1[34747]: Copying blob sha256:8dc41ea9d07c936926f7a462e5cc722475afc87ef8b574c36ca73def19d7f1c2
Jun 01 23:22:56 node.ns8.test webserver1[34747]: Copying blob sha256:a2be31771dfb74ecb48413fd787ff66646102475922be90475e2c64640050990
Jun 01 23:22:56 node.ns8.test webserver1[34747]: Copying blob sha256:ec10705586d43a6a059fb9b5bd673f3bddee0c10fae8e5143fe8c7209c3fcffa
Jun 01 23:22:57 node.ns8.test webserver1[34747]: Copying blob sha256:bbbcdf756540a6d28f61e8cd33398e6a893ffe22bca43e4cfc59654a93472085
Jun 01 23:22:57 node.ns8.test webserver1[34747]: Copying blob sha256:0ba5f85b26ba194fb9a55fcee55a1fa3d23de42cf4b46d380a2abc3ccc91eb49
Jun 01 23:22:57 node.ns8.test webserver1[34747]: Copying blob sha256:60a2a37da7a4f4281e9af52544361d0c3462a8da81191fff972abd1011f66508
Jun 01 23:22:57 node.ns8.test webserver1[34747]: Copying blob sha256:64126d6e7707f65e1c4378370393cee5ab044147ef71e7c2a5bffae1b46880fa
Jun 01 23:22:58 node.ns8.test webserver1[34747]: Copying blob sha256:1017af048093c70404c43ff943881a7b6b1069dbf80563765f1ed92842c878fe
Jun 01 23:22:58 node.ns8.test webserver1[34747]: Copying blob sha256:b1a02e964291fe2ecf0c7d154e7385d2d69fde9716cf26c8f3bf75f75b86e739
Jun 01 23:22:58 node.ns8.test webserver1[34747]: Copying blob sha256:4f4fb700ef54461cfa02571ae0db9a0dc1e0cdb5577484a6d75e68dc38e8acc1
Jun 01 23:23:01 node.ns8.test webserver1[34747]: Copying config sha256:19b3e0e71dda50fc4731a6a370b34a9c11a4dc6d3dbb994621e0ba4b6b6d550b
Jun 01 23:23:01 node.ns8.test webserver1[34747]: Writing manifest to image destination
Jun 01 23:23:01 node.ns8.test webserver1[34747]: Storing signatures
Jun 01 23:23:02 node.ns8.test webserver1[34747]: 19b3e0e71dda50fc4731a6a370b34a9c11a4dc6d3dbb994621e0ba4b6b6d550b
Jun 01 23:23:02 node.ns8.test webserver1[34747]: task/module/webserver1/af1a56ee-884c-44d7-98b1-59077018e741: create-module/10configure is starting
Jun 01 23:23:02 node.ns8.test webserver1[34747]: dump_env() is deprecated and implemented as a no-op
Jun 01 23:23:02 node.ns8.test webserver1[34747]: task/module/webserver1/af1a56ee-884c-44d7-98b1-59077018e741: create-module/10log_tag is starting
Jun 01 23:23:02 node.ns8.test webserver1[34747]: task/module/webserver1/af1a56ee-884c-44d7-98b1-59077018e741: create-module/10selfadm_role is starting
Jun 01 23:23:03 node.ns8.test webserver1[34747]: 1
Jun 01 23:23:03 node.ns8.test webserver1[34747]: task/module/webserver1/af1a56ee-884c-44d7-98b1-59077018e741: create-module/50start_services is starting
Jun 01 23:23:03 node.ns8.test webserver1[34747]: Created symlink /home/webserver1/.config/systemd/user/default.target.wants/webserver.service → /home/webserver1/.config/systemd/user/webserver.service.
Jun 01 23:23:05 node.ns8.test webserver1[34747]: task/module/webserver1/af1a56ee-884c-44d7-98b1-59077018e741: action "create-module" status is "completed" (0) at step 50start_services
Jun 01 23:23:06 node.ns8.test webserver1[35063]: /docker-entrypoint.sh: /docker-entrypoint.d/ is not empty, will attempt to perform configuration
Jun 01 23:23:06 node.ns8.test webserver1[35063]: /docker-entrypoint.sh: Looking for shell scripts in /docker-entrypoint.d/
Jun 01 23:23:06 node.ns8.test webserver1[35063]: /docker-entrypoint.sh: Launching /docker-entrypoint.d/10-listen-on-ipv6-by-default.sh
Jun 01 23:23:06 node.ns8.test webserver1[35063]: 10-listen-on-ipv6-by-default.sh: info: /etc/nginx/conf.d/default.conf is not a file or does not exist
Jun 01 23:23:06 node.ns8.test webserver1[35063]: /docker-entrypoint.sh: Launching /docker-entrypoint.d/20-envsubst-on-templates.sh
Jun 01 23:23:06 node.ns8.test webserver1[35063]: /docker-entrypoint.sh: Launching /docker-entrypoint.d/30-tune-worker-processes.sh
Jun 01 23:23:06 node.ns8.test webserver1[35063]: /docker-entrypoint.sh: Configuration complete; ready for start up
Jun 01 23:23:06 node.ns8.test webserver1[35063]: 2023/06/01 23:23:06 [notice] 1#1: using the "epoll" event method
Jun 01 23:23:06 node.ns8.test webserver1[35063]: 2023/06/01 23:23:06 [notice] 1#1: nginx/1.20.2
Jun 01 23:23:06 node.ns8.test webserver1[35063]: 2023/06/01 23:23:06 [notice] 1#1: built by gcc 10.3.1 20210424 (Alpine 10.3.1_git20210424)
Jun 01 23:23:06 node.ns8.test webserver1[35063]: 2023/06/01 23:23:06 [notice] 1#1: OS: Linux 5.14.0-162.23.1.el9_1.x86_64
Jun 01 23:23:06 node.ns8.test webserver1[35063]: 2023/06/01 23:23:06 [notice] 1#1: getrlimit(RLIMIT_NOFILE): 524288:524288
Jun 01 23:23:06 node.ns8.test webserver1[35063]: 2023/06/01 23:23:06 [notice] 1#1: start worker processes
Jun 01 23:23:06 node.ns8.test webserver1[35063]: 2023/06/01 23:23:06 [notice] 1#1: start worker process 17
Jun 01 23:23:06 node.ns8.test webserver1[35063]: 2023/06/01 23:23:06 [notice] 1#1: start worker process 18
Jun 01 23:28:53 node.ns8.test webserver1[34747]: task/module/webserver1/b8f5862f-b2b2-44c7-a6d4-5fe24ed1aff1: get-name/50get_name is starting
Jun 01 23:28:53 node.ns8.test webserver1[34747]: task/module/webserver1/b8f5862f-b2b2-44c7-a6d4-5fe24ed1aff1: action "get-name" status is "completed" (0) at step 50get_name
Jun 01 23:28:54 node.ns8.test webserver1[34747]: task/module/webserver1/0c72c9fe-4933-4b8f-8918-879dd868a2a3: get-configuration/20read is starting
Jun 01 23:28:54 node.ns8.test webserver1[34747]: task/module/webserver1/0c72c9fe-4933-4b8f-8918-879dd868a2a3: action "get-configuration" status is "completed" (0) at step validate-output.json
Jun 01 23:29:12 node.ns8.test webserver1[34747]: task/module/webserver1/9e6f37e0-45f3-4927-8c70-647d12cb351f: configure-module/01_validate_web_path is starting
Jun 01 23:29:12 node.ns8.test webserver1[34747]: task/module/webserver1/9e6f37e0-45f3-4927-8c70-647d12cb351f: configure-module/02_validate_sftp_port is starting
Jun 01 23:29:13 node.ns8.test webserver1[34747]: task/module/webserver1/9e6f37e0-45f3-4927-8c70-647d12cb351f: configure-module/05Firewall is starting
Jun 01 23:29:15 node.ns8.test webserver1[34747]: task/module/webserver1/9e6f37e0-45f3-4927-8c70-647d12cb351f: configure-module/10settings is starting
Jun 01 23:29:15 node.ns8.test webserver1[34747]: task/module/webserver1/9e6f37e0-45f3-4927-8c70-647d12cb351f: configure-module/20traefik is starting
Jun 01 23:29:15 node.ns8.test webserver1[34747]: dump_env() is deprecated and implemented as a no-op
Jun 01 23:29:17 node.ns8.test webserver1[34747]: task/module/webserver1/9e6f37e0-45f3-4927-8c70-647d12cb351f: configure-module/50start_services is starting
Jun 01 23:29:17 node.ns8.test webserver1[34747]: systemctl --user restart webserver.service
Jun 01 23:29:17 node.ns8.test webserver1[35063]: 2023/06/01 23:29:17 [notice] 1#1: signal 3 (SIGQUIT) received, shutting down
Jun 01 23:29:17 node.ns8.test webserver1[35063]: 2023/06/01 23:29:17 [notice] 18#18: gracefully shutting down
Jun 01 23:29:17 node.ns8.test webserver1[35063]: 2023/06/01 23:29:17 [notice] 18#18: exiting
Jun 01 23:29:17 node.ns8.test webserver1[35063]: 2023/06/01 23:29:17 [notice] 18#18: exit
Jun 01 23:29:17 node.ns8.test webserver1[35063]: 2023/06/01 23:29:17 [notice] 17#17: gracefully shutting down
Jun 01 23:29:17 node.ns8.test webserver1[35063]: 2023/06/01 23:29:17 [notice] 17#17: exiting
Jun 01 23:29:17 node.ns8.test webserver1[35063]: 2023/06/01 23:29:17 [notice] 17#17: exit
Jun 01 23:29:17 node.ns8.test webserver1[35063]: 2023/06/01 23:29:17 [notice] 1#1: signal 17 (SIGCHLD) received from 18
Jun 01 23:29:17 node.ns8.test webserver1[35063]: 2023/06/01 23:29:17 [notice] 1#1: worker process 18 exited with code 0
Jun 01 23:29:17 node.ns8.test webserver1[35063]: 2023/06/01 23:29:17 [notice] 1#1: signal 29 (SIGIO) received
Jun 01 23:29:17 node.ns8.test webserver1[35063]: 2023/06/01 23:29:17 [notice] 1#1: signal 17 (SIGCHLD) received from 17
Jun 01 23:29:17 node.ns8.test webserver1[35063]: 2023/06/01 23:29:17 [notice] 1#1: worker process 17 exited with code 0
Jun 01 23:29:17 node.ns8.test webserver1[35063]: 2023/06/01 23:29:17 [notice] 1#1: exit
Jun 01 23:29:19 node.ns8.test webserver1[34747]: systemctl --user enable sftpgo.service
Jun 01 23:29:19 node.ns8.test webserver1[34747]: Created symlink /home/webserver1/.config/systemd/user/default.target.wants/sftpgo.service → /home/webserver1/.config/systemd/user/sftpgo.service.
Jun 01 23:29:19 node.ns8.test webserver1[34747]: systemctl --user restart sftpgo.service
Jun 01 23:29:19 node.ns8.test webserver1[35526]: /docker-entrypoint.sh: /docker-entrypoint.d/ is not empty, will attempt to perform configuration
Jun 01 23:29:19 node.ns8.test webserver1[35526]: /docker-entrypoint.sh: Looking for shell scripts in /docker-entrypoint.d/
Jun 01 23:29:19 node.ns8.test webserver1[35526]: /docker-entrypoint.sh: Launching /docker-entrypoint.d/10-listen-on-ipv6-by-default.sh
Jun 01 23:29:19 node.ns8.test webserver1[35526]: 10-listen-on-ipv6-by-default.sh: info: /etc/nginx/conf.d/default.conf is not a file or does not exist
Jun 01 23:29:19 node.ns8.test webserver1[35526]: /docker-entrypoint.sh: Launching /docker-entrypoint.d/20-envsubst-on-templates.sh
Jun 01 23:29:19 node.ns8.test webserver1[35526]: /docker-entrypoint.sh: Launching /docker-entrypoint.d/30-tune-worker-processes.sh
Jun 01 23:29:19 node.ns8.test webserver1[35526]: /docker-entrypoint.sh: Configuration complete; ready for start up
Jun 01 23:29:19 node.ns8.test webserver1[35526]: 2023/06/01 23:29:19 [notice] 1#1: using the "epoll" event method
Jun 01 23:29:19 node.ns8.test webserver1[35526]: 2023/06/01 23:29:19 [notice] 1#1: nginx/1.20.2
Jun 01 23:29:19 node.ns8.test webserver1[35526]: 2023/06/01 23:29:19 [notice] 1#1: built by gcc 10.3.1 20210424 (Alpine 10.3.1_git20210424)
Jun 01 23:29:19 node.ns8.test webserver1[35526]: 2023/06/01 23:29:19 [notice] 1#1: OS: Linux 5.14.0-162.23.1.el9_1.x86_64
Jun 01 23:29:19 node.ns8.test webserver1[35526]: 2023/06/01 23:29:19 [notice] 1#1: getrlimit(RLIMIT_NOFILE): 524288:524288
Jun 01 23:29:19 node.ns8.test webserver1[35526]: 2023/06/01 23:29:19 [notice] 1#1: start worker processes
Jun 01 23:29:19 node.ns8.test webserver1[35526]: 2023/06/01 23:29:19 [notice] 1#1: start worker process 17
Jun 01 23:29:19 node.ns8.test webserver1[35526]: 2023/06/01 23:29:19 [notice] 1#1: start worker process 18
Jun 01 23:29:20 node.ns8.test webserver1[35559]: {"level":"info","time":"2023-06-01T23:29:20.529","sender":"service","message":"starting SFTPGo 2.2.3-c40a48c6-2022-04-30T11:45:12Z +metrics +azblob +gcs +s3 +bolt +mysql +pgsql +sqlite +portable, config dir: ., config file: , log max size: 10 log max backups: 5 log max age: 28 log verbose: true, log compress: false, log utc time: false, load data from: \"/etc/sftpgo/admin.json\""}
Jun 01 23:29:20 node.ns8.test webserver1[35559]: {"level":"debug","time":"2023-06-01T23:29:20.533","sender":"config","message":"config file used: '\"/etc/sftpgo/sftpgo.json\"', config loaded: {Common:{IdleTimeout:15 UploadMode:0 Actions:{ExecuteOn:[] ExecuteSync:[] Hook:} SetstatMode:0 TempPath: ProxyProtocol:0 ProxyAllowed:[] StartupHook: PostConnectHook: PostDisconnectHook: DataRetentionHook: MaxTotalConnections:0 MaxPerHostConnections:20 DefenderConfig:{Enabled:false Driver:memory BanTime:30 BanTimeIncrement:50 Threshold:15 ScoreInvalid:2 ScoreValid:1 ScoreLimitExceeded:3 ObservationTime:30 EntriesSoftLimit:100 EntriesHardLimit:150 SafeListFile: BlockListFile:} RateLimitersConfig:[{Average:0 Period:1000 Burst:1 Type:2 Protocols:[SSH FTP DAV HTTP] AllowList:[] GenerateDefenderEvents:false EntriesSoftLimit:100 EntriesHardLimit:150}] idleTimeoutAsDuration:0 idleLoginTimeout:0 defender:<nil>} SFTPD:{Banner:SFTPGo_2.2.3 Bindings:[{Address: Port:2022 ApplyProxyConfig:true}] MaxAuthTries:0 Actions:{ExecuteOn:[] ExecuteSync:[] Hook:} HostKeys:[] KexAlgorithms:[] Ciphers:[] MACs:[] TrustedUserCAKeys:[] LoginBannerFile: EnabledSSHCommands:[md5sum sha1sum cd pwd scp] KeyboardInteractiveAuthentication:false KeyboardInteractiveHook: PasswordAuthentication:true FolderPrefix: certChecker:<nil> parsedUserCAKeys:[]} FTPD:{Bindings:[{Address: Port:0 ApplyProxyConfig:true TLSMode:0 ForcePassiveIP: PassiveIPOverrides:[] ClientAuthType:0 TLSCipherSuites:[] PassiveConnectionsSecurity:0 ActiveConnectionsSecurity:0 Debug:false ciphers:[]}] Banner:SFTPGo 2.2.3 ready BannerFile: CertificateFile: CertificateKeyFile: CACertificates:[] CARevocationLists:[] ActiveTransfersPortNon20:true DisableActiveMode:false EnableSite:false HASHSupport:0 CombineSupport:0 PassivePortRange:{Start:50000 End:50100}} WebDAVD:{Bindings:[{Address: Port:0 EnableHTTPS:false ClientAuthType:0 TLSCipherSuites:[] Prefix: ProxyAllowed:[] allowHeadersFrom:[]}] CertificateFile: CertificateKeyFile: CACertificates:[] CARevocationLists:[] Cors:{AllowedOrigins:[] AllowedMethods:[] AllowedHeaders:[] ExposedHeaders:[] AllowCredentials:false Enabled:false MaxAge:0} Cache:{Users:{ExpirationTime:0 MaxSize:50} MimeTypes:{Enabled:true MaxSize:1000}}} ProviderConf:{Driver:sqlite Name:sftpgo.db Host: Port:0 Username: Password:[redacted] SSLMode:0 ConnectionString: SQLTablesPrefix: TrackQuota:2 PoolSize:0 UsersBaseDir:/srv/sftpgo/data Actions:{ExecuteOn:[] ExecuteFor:[] Hook:} ExternalAuthHook: ExternalAuthScope:0 CredentialsPath:credentials PreLoginHook: PostLoginHook: PostLoginScope:0 CheckPasswordHook: CheckPasswordScope:0 UpdateMode:0 PasswordHashing:{BcryptOptions:{Cost:10} Argon2Options:{Memory:65536 Iterations:1 Parallelism:2} Algo:bcrypt} PreferDatabaseCredentials:false SkipNaturalKeysValidation:false PasswordValidation:{Admins:{MinEntropy:0} Users:{MinEntropy:0}} PasswordCaching:true DelayedQuotaUpdate:0 CreateDefaultAdmin:false IsShared:0} HTTPDConfig:{Bindings:[{Address: Port:8080 EnableWebAdmin:true EnableWebClient:true EnableHTTPS:false ClientAuthType:0 TLSCipherSuites:[] ProxyAllowed:[] HideLoginURL:0 RenderOpenAPI:true WebClientIntegrations:[] allowHeadersFrom:[]}] TemplatesPath:/usr/share/sftpgo/templates StaticFilesPath:/usr/share/sftpgo/static BackupsPath:/srv/sftpgo/backups OpenAPIPath:/usr/share/sftpgo/openapi WebRoot:/sftpgo CertificateFile: CertificateKeyFile: CACertificates:[] CARevocationLists:[] SigningPassphrase:[redacted] MaxUploadFileSize:1048576000 Cors:{AllowedOrigins:[] AllowedMethods:[] AllowedHeaders:[] ExposedHeaders:[] AllowCredentials:false Enabled:false MaxAge:0} Setup:{InstallationCode:[redacted] InstallationCodeHint:Installation code}} HTTPConfig:{Timeout:20 RetryWaitMin:2 RetryWaitMax:30 RetryMax:3 CACertificates:[] Certificates:[] SkipTLSVerify:false Headers:[] customTransport:<nil> tlsConfig:<nil>} KMSConfig:{Secrets:{URL: MasterKeyPath: MasterKeyString: masterKey:}} MFAConfig:{TOTP:[{Name:Default Issuer:SFTPGo Algo:sha1 algo:0}]} TelemetryConfig:{BindPort:0 BindAddress:127.0.0.1 EnableProfiler:false AuthUserFile: CertificateFile: CertificateKeyFile: TLSCipherSuites:[]} PluginsConfig:[] SMTPConfig:{Host: Port:25 From: User: Password:[redacted] AuthType:0 Encryption:0 Domain: TemplatesPath:/usr/share/sftpgo/templates}}"}
Jun 01 23:29:20 node.ns8.test webserver1[35559]: {"level":"info","time":"2023-06-01T23:29:20.534","sender":"kms","message":"secret provider registered for scheme: \"builtin\", encrypted status: \"AES-256-GCM\""}
Jun 01 23:29:20 node.ns8.test webserver1[35559]: {"level":"info","time":"2023-06-01T23:29:20.534","sender":"kms","message":"secret provider registered for scheme: \"local\", encrypted status: \"Secretbox\""}
Jun 01 23:29:20 node.ns8.test webserver1[35559]: {"level":"debug","time":"2023-06-01T23:29:20.534","sender":"plugins","message":"initialize"}
Jun 01 23:29:20 node.ns8.test webserver1[35559]: {"level":"debug","time":"2023-06-01T23:29:20.534","sender":"smtp","message":"configuration disabled, email capabilities will not be available"}
Jun 01 23:29:20 node.ns8.test webserver1[35559]: {"level":"debug","time":"2023-06-01T23:29:20.534","sender":"dataprovider_sqlite","message":"sqlite database handle created, connection string: \"file:sftpgo.db?cache=shared&_foreign_keys=1\""}
Jun 01 23:29:20 node.ns8.test webserver1[35559]: {"level":"error","time":"2023-06-01T23:29:20.534","sender":"dataprovider_sqlite","message":"error preparing database query \"SELECT version from schema_version LIMIT 1\": no such table: schema_version"}
Jun 01 23:29:20 node.ns8.test webserver1[34747]: task/module/webserver1/9e6f37e0-45f3-4927-8c70-647d12cb351f: configure-module/60sftpgo_create_secret is starting
Jun 01 23:29:21 node.ns8.test webserver1[35559]: {"level":"info","time":"2023-06-01T23:29:21.044","sender":"dataprovider_sqlite","message":"updating database version: 10 -> 11"}
Jun 01 23:29:21 node.ns8.test webserver1[35559]: {"level":"info","time":"2023-06-01T23:29:21.162","sender":"dataprovider_sqlite","message":"updating database version: 11 -> 12"}
Jun 01 23:29:21 node.ns8.test webserver1[34747]: Traceback (most recent call last):
Jun 01 23:29:21 node.ns8.test webserver1[34747]:   File "/home/webserver1/.config/actions/configure-module/60sftpgo_create_secret", line 44, in <module>
Jun 01 23:29:21 node.ns8.test webserver1[34747]:     res = conn.getresponse()
Jun 01 23:29:21 node.ns8.test webserver1[34747]:   File "/usr/lib64/python3.9/http/client.py", line 1377, in getresponse
Jun 01 23:29:21 node.ns8.test webserver1[34747]:     response.begin()
Jun 01 23:29:21 node.ns8.test webserver1[34747]:   File "/usr/lib64/python3.9/http/client.py", line 320, in begin
Jun 01 23:29:21 node.ns8.test webserver1[34747]:     version, status, reason = self._read_status()
Jun 01 23:29:21 node.ns8.test webserver1[34747]:   File "/usr/lib64/python3.9/http/client.py", line 281, in _read_status
Jun 01 23:29:21 node.ns8.test webserver1[34747]:     line = str(self.fp.readline(_MAXLINE + 1), "iso-8859-1")
Jun 01 23:29:21 node.ns8.test webserver1[34747]:   File "/usr/lib64/python3.9/socket.py", line 704, in readinto
Jun 01 23:29:21 node.ns8.test webserver1[35559]: {"level":"info","time":"2023-06-01T23:29:21.246","sender":"dataprovider_sqlite","message":"updating database version: 12 -> 13"}
Jun 01 23:29:21 node.ns8.test webserver1[34747]:     return self._sock.recv_into(b)
Jun 01 23:29:21 node.ns8.test webserver1[34747]: ConnectionResetError: [Errno 104] Connection reset by peer
Jun 01 23:29:21 node.ns8.test webserver1[34747]: task/module/webserver1/9e6f37e0-45f3-4927-8c70-647d12cb351f: action "configure-module" status is "aborted" (1) at step 60sftpgo_create_secret
Jun 01 23:29:21 node.ns8.test webserver1[35559]: {"level":"info","time":"2023-06-01T23:29:21.395","sender":"dataprovider_sqlite","message":"updating database version: 13 -> 14"}
Jun 01 23:29:21 node.ns8.test webserver1[35559]: {"level":"info","time":"2023-06-01T23:29:21.543","sender":"dataprovider_sqlite","message":"updating database version: 14 -> 15"}
Jun 01 23:29:21 node.ns8.test webserver1[35559]: {"level":"debug","time":"2023-06-01T23:29:21.621","sender":"dataprovider_sqlite","message":"delayed quota update loop started, wait time: 0s"}
Jun 01 23:29:21 node.ns8.test webserver1[35559]: {"level":"debug","time":"2023-06-01T23:29:21.621","sender":"dataprovider_sqlite","message":"delayed quota update loop ended, wait time: 0s"}
Jun 01 23:29:21 node.ns8.test webserver1[35559]: {"level":"debug","time":"2023-06-01T23:29:21.687","sender":"httpd","message":"adding new admin: {ID:1 Status:1 Username:admin Password:[**redacted**] Email: Permissions:[*] Filters:{AllowList:[] AllowAPIKeyAuth:true TOTPConfig:{Enabled:false ConfigName: Secret:0xc000584000} RecoveryCodes:[]} Description: AdditionalInfo: CreatedAt:0 UpdatedAt:0 LastLogin:0}, dump file: \"/etc/sftpgo/admin.json\", error: <nil>"}
Jun 01 23:29:21 node.ns8.test webserver1[35559]: {"level":"info","time":"2023-06-01T23:29:21.688","sender":"service","message":"data loaded from file \"/etc/sftpgo/admin.json\" mode: 1, quota scan 0"}
Jun 01 23:29:21 node.ns8.test webserver1[35559]: {"level":"info","time":"2023-06-01T23:29:21.688","sender":"service","message":"FTP server not started, disabled in config file"}
Jun 01 23:29:21 node.ns8.test webserver1[35559]: {"level":"info","time":"2023-06-01T23:29:21.688","sender":"service","message":"WebDAV server not started, disabled in config file"}
Jun 01 23:29:21 node.ns8.test webserver1[35559]: {"level":"info","time":"2023-06-01T23:29:21.688","sender":"service","message":"telemetry server not started, disabled in config file"}
Jun 01 23:29:21 node.ns8.test webserver1[35559]: {"level":"info","time":"2023-06-01T23:29:21.688","sender":"service","message":"initializing SFTP server with config {Banner:SFTPGo_2.2.3 Bindings:[{Address: Port:2022 ApplyProxyConfig:true}] MaxAuthTries:0 Actions:{ExecuteOn:[] ExecuteSync:[] Hook:} HostKeys:[] KexAlgorithms:[] Ciphers:[] MACs:[] TrustedUserCAKeys:[] LoginBannerFile: EnabledSSHCommands:[md5sum sha1sum cd pwd scp] KeyboardInteractiveAuthentication:false KeyboardInteractiveHook: PasswordAuthentication:true FolderPrefix: certChecker:<nil> parsedUserCAKeys:[]}"}
Jun 01 23:29:21 node.ns8.test webserver1[35559]: {"level":"info","time":"2023-06-01T23:29:21.688","sender":"sftpd","message":"No host keys configured and \"id_rsa\" does not exist; try to create a new host key"}
Jun 01 23:29:21 node.ns8.test webserver1[35559]: {"level":"info","time":"2023-06-01T23:29:21.688","sender":"httpd","message":"initializing HTTP server with config {Bindings:[{Address: Port:8080 EnableWebAdmin:true EnableWebClient:true EnableHTTPS:false ClientAuthType:0 TLSCipherSuites:[] ProxyAllowed:[] HideLoginURL:0 RenderOpenAPI:true WebClientIntegrations:[] allowHeadersFrom:[]}] TemplatesPath:/usr/share/sftpgo/templates StaticFilesPath:/usr/share/sftpgo/static BackupsPath:/srv/sftpgo/backups OpenAPIPath:/usr/share/sftpgo/openapi WebRoot:/sftpgo CertificateFile: CertificateKeyFile: CACertificates:[] CARevocationLists:[] SigningPassphrase:[redacted] MaxUploadFileSize:1048576000 Cors:{AllowedOrigins:[] AllowedMethods:[] AllowedHeaders:[] ExposedHeaders:[] AllowCredentials:false Enabled:false MaxAge:0} Setup:{InstallationCode:[redacted] InstallationCodeHint:Installation code}}"}
Jun 01 23:29:21 node.ns8.test webserver1[35559]: {"level":"info","time":"2023-06-01T23:29:21.714","sender":"httpd","message":"server listener registered, address: [::]:8080 TLS enabled: false"}
Jun 01 23:29:22 node.ns8.test webserver1[35559]: {"level":"info","time":"2023-06-01T23:29:22.503","sender":"sftpd","message":"No host keys configured and \"id_ecdsa\" does not exist; try to create a new host key"}
Jun 01 23:29:22 node.ns8.test webserver1[35559]: {"level":"info","time":"2023-06-01T23:29:22.504","sender":"sftpd","message":"No host keys configured and \"id_ed25519\" does not exist; try to create a new host key"}
Jun 01 23:29:22 node.ns8.test webserver1[35559]: {"level":"info","time":"2023-06-01T23:29:22.506","sender":"sftpd","message":"Loading private host key \"id_rsa\""}
Jun 01 23:29:22 node.ns8.test webserver1[35559]: {"level":"info","time":"2023-06-01T23:29:22.507","sender":"sftpd","message":"Host key \"id_rsa\" loaded, type \"ssh-rsa\", fingerprint \"SHA256:8WqjztrkH8rBIXjrp1KTS7SgrAcpuwLIC2n2qb/jhIM\""}
Jun 01 23:29:22 node.ns8.test webserver1[35559]: {"level":"info","time":"2023-06-01T23:29:22.507","sender":"sftpd","message":"Loading private host key \"id_ecdsa\""}
Jun 01 23:29:22 node.ns8.test webserver1[35559]: {"level":"info","time":"2023-06-01T23:29:22.507","sender":"sftpd","message":"Host key \"id_ecdsa\" loaded, type \"ecdsa-sha2-nistp256\", fingerprint \"SHA256:F1HhD0r4ZRO2c08Dq0EOJS8MoNrq190ni10BUGeehS8\""}
Jun 01 23:29:22 node.ns8.test webserver1[35559]: {"level":"info","time":"2023-06-01T23:29:22.507","sender":"sftpd","message":"Loading private host key \"id_ed25519\""}
Jun 01 23:29:22 node.ns8.test webserver1[35559]: {"level":"info","time":"2023-06-01T23:29:22.508","sender":"sftpd","message":"Host key \"id_ed25519\" loaded, type \"ssh-ed25519\", fingerprint \"SHA256:LClcWw8zvY0W8m0n2WNyO1UtO9NvNzIshD3j5hpe/O0\""}
Jun 01 23:29:22 node.ns8.test webserver1[35559]: {"level":"debug","time":"2023-06-01T23:29:22.508","sender":"sftpd","message":"enabled SSH commands [md5sum sha1sum cd pwd scp]"}
Jun 01 23:29:22 node.ns8.test webserver1[35559]: {"level":"info","time":"2023-06-01T23:29:22.508","sender":"sftpd","message":"server listener registered, address: [::]:2022"}
Jun 01 23:30:59 node.ns8.test webserver1[34747]: task/module/webserver1/cbad01db-3f5a-4e40-b352-e6047493f963: configure-module/01_validate_web_path is starting
Jun 01 23:30:59 node.ns8.test webserver1[34747]: task/module/webserver1/cbad01db-3f5a-4e40-b352-e6047493f963: configure-module/02_validate_sftp_port is starting
Jun 01 23:30:59 node.ns8.test webserver1[34747]: task/module/webserver1/cbad01db-3f5a-4e40-b352-e6047493f963: configure-module/05Firewall is starting
Jun 01 23:30:59 node.ns8.test webserver1[34747]: task/module/webserver1/cbad01db-3f5a-4e40-b352-e6047493f963: configure-module/10settings is starting
Jun 01 23:30:59 node.ns8.test webserver1[34747]: task/module/webserver1/cbad01db-3f5a-4e40-b352-e6047493f963: configure-module/20traefik is starting
Jun 01 23:31:00 node.ns8.test webserver1[34747]: dump_env() is deprecated and implemented as a no-op
Jun 01 23:31:05 node.ns8.test webserver1[34747]: Traceback (most recent call last):
Jun 01 23:31:05 node.ns8.test webserver1[34747]:   File "/home/webserver1/.config/actions/configure-module/20traefik", line 54, in <module>
Jun 01 23:31:05 node.ns8.test webserver1[34747]:     response = agent.tasks.run(
Jun 01 23:31:05 node.ns8.test webserver1[34747]:   File "/usr/local/agent/pypkg/agent/tasks/run.py", line 39, in run
Jun 01 23:31:05 node.ns8.test webserver1[34747]:     results = runp([taskrq], **kwargs)
Jun 01 23:31:05 node.ns8.test webserver1[34747]:   File "/usr/local/agent/pypkg/agent/tasks/run.py", line 50, in runp
Jun 01 23:31:05 node.ns8.test webserver1[34747]:     return asyncio.run(_runp(tasks, **kwargs))
Jun 01 23:31:05 node.ns8.test webserver1[34747]:   File "/usr/lib64/python3.9/asyncio/runners.py", line 44, in run
Jun 01 23:31:05 node.ns8.test webserver1[34747]:     return loop.run_until_complete(main)
Jun 01 23:31:05 node.ns8.test webserver1[34747]:   File "/usr/lib64/python3.9/asyncio/base_events.py", line 647, in run_until_complete
Jun 01 23:31:05 node.ns8.test webserver1[34747]:     return future.result()
Jun 01 23:31:05 node.ns8.test webserver1[34747]:   File "/usr/local/agent/pypkg/agent/tasks/run.py", line 120, in _runp
Jun 01 23:31:05 node.ns8.test webserver1[34747]:     return await asyncio.gather(*runners, return_exceptions=(len(tasks) > 1))
Jun 01 23:31:05 node.ns8.test webserver1[34747]:   File "/usr/local/agent/pypkg/agent/tasks/run.py", line 129, in _run_with_protocol
Jun 01 23:31:05 node.ns8.test webserver1[34747]:     return await run_apiclient(taskrq, **pconn)
Jun 01 23:31:05 node.ns8.test webserver1[34747]:   File "/usr/local/agent/pypkg/agent/tasks/apiclient.py", line 47, in run_apiclient
Jun 01 23:31:05 node.ns8.test webserver1[34747]:     taskctx['status_path'] = await _retry_request(_apost_task, taskrq, client=client, theaders=theaders, **kwargs)
Jun 01 23:31:05 node.ns8.test webserver1[34747]:   File "/usr/local/agent/pypkg/agent/tasks/apiclient.py", line 191, in _retry_request
Jun 01 23:31:05 node.ns8.test webserver1[34747]:     raise exhttp
Jun 01 23:31:05 node.ns8.test webserver1[34747]:   File "/usr/local/agent/pypkg/agent/tasks/apiclient.py", line 166, in _retry_request
Jun 01 23:31:05 node.ns8.test webserver1[34747]:     retval = await request_procedure(*args, **kwargs)
Jun 01 23:31:05 node.ns8.test webserver1[34747]:   File "/usr/local/agent/pypkg/agent/tasks/apiclient.py", line 258, in _apost_task
Jun 01 23:31:05 node.ns8.test webserver1[34747]:     jresp = await resp.json()
Jun 01 23:31:05 node.ns8.test webserver1[34747]:   File "/usr/local/agent/pyenv/lib64/python3.9/site-packages/aiohttp/client_reqrep.py", line 1097, in json
Jun 01 23:31:05 node.ns8.test webserver1[34747]:     raise ContentTypeError(
Jun 01 23:31:05 node.ns8.test webserver1[34747]: aiohttp.client_exceptions.ContentTypeError: 0, message='Attempt to decode JSON with unexpected mimetype: ', url=URL('http://cluster-leader:9311/api/module/traefik1/tasks')
Jun 01 23:31:05 node.ns8.test webserver1[34747]: task/module/webserver1/cbad01db-3f5a-4e40-b352-e6047493f963: action "configure-module" status is "aborted" (1) at step 20traefik

I had to truncate a few lines from the end to fit with the posting requirements.

Cheers.

stephdl · June 6, 2023, 4:14pm

install please a new module you do not have the last version

EddieA · June 6, 2023, 4:25pm

K, I’ll try re-installing a few times with the latest.

Cheers.

EddieA · June 7, 2023, 1:29am

Nope, still getting errors:

Summary

{
  "context": {
    "action": "configure-module",
    "data": {
      "http2https": true,
      "path": "/sftpgo",
      "sftp_tcp_port": 3092,
      "sftpgo_service": true
    },
    "extra": {
      "description": "Configuring...",
      "title": "webserver1 configuration"
    },
    "id": "f376f6b7-600f-4540-bbd8-d2ef539b5d8e",
    "parent": "",
    "queue": "module/webserver1/tasks",
    "timestamp": "2023-06-07T01:21:19.393445417Z",
    "user": "admin"
  },
  "status": "aborted",
  "progress": 80,
  "subTasks": [
    {
      "context": {
        "action": "set-route",
        "data": {
          "http2https": true,
          "instance": "webserver1",
          "path": "/sftpgo",
          "url": "http://127.0.0.1:20011"
        },
        "extra": {},
        "id": "a6a250d0-73bb-44db-ba77-9b8e7975784f",
        "parent": "f376f6b7-600f-4540-bbd8-d2ef539b5d8e",
        "queue": "module/traefik1/tasks",
        "timestamp": "2023-06-07T01:21:25.063281784Z",
        "user": "module/webserver1"
      },
      "status": "completed",
      "progress": 100,
      "subTasks": [],
      "result": {
        "error": "",
        "exit_code": 0,
        "file": "task/module/traefik1/a6a250d0-73bb-44db-ba77-9b8e7975784f",
        "output": ""
      }
    },
    {
      "context": {
        "action": "add-public-service",
        "data": {
          "ports": [
            "3092/tcp"
          ],
          "service": "webserver1"
        },
        "extra": {},
        "id": "8b9b25c9-9d7a-4ca7-b3c9-0d4969cb32b9",
        "parent": "f376f6b7-600f-4540-bbd8-d2ef539b5d8e",
        "queue": "node/1/tasks",
        "timestamp": "2023-06-07T01:21:20.378288337Z",
        "user": "module/webserver1"
      },
      "status": "completed",
      "progress": 100,
      "subTasks": [],
      "result": {
        "error": "<7>firewall-cmd --permanent --new-service=webserver1\nsuccess\n<7>firewall-cmd --permanent --add-service=webserver1\nsuccess\n<7>firewall-cmd --permanent --service=webserver1 --add-port=3092/tcp\nsuccess\n<7>firewall-cmd --reload\nsuccess\n",
        "exit_code": 0,
        "file": "task/node/1/8b9b25c9-9d7a-4ca7-b3c9-0d4969cb32b9",
        "output": ""
      }
    }
  ],
  "validated": true,
  "result": {
    "error": "<7>dump_env() is deprecated and implemented as a no-op\n<7>systemctl --user restart webserver.service\n<7>systemctl --user enable sftpgo.service\nCreated symlink /home/webserver1/.config/systemd/user/default.target.wants/sftpgo.service → /home/webserver1/.config/systemd/user/sftpgo.service.\n<7>systemctl --user restart sftpgo.service\nTraceback (most recent call last):\n  File \"/home/webserver1/.config/actions/configure-module/60sftpgo_create_secret\", line 44, in <module>\n    res = conn.getresponse()\n  File \"/usr/lib64/python3.9/http/client.py\", line 1377, in getresponse\n    response.begin()\n  File \"/usr/lib64/python3.9/http/client.py\", line 320, in begin\n    version, status, reason = self._read_status()\n  File \"/usr/lib64/python3.9/http/client.py\", line 281, in _read_status\n    line = str(self.fp.readline(_MAXLINE + 1), \"iso-8859-1\")\n  File \"/usr/lib64/python3.9/socket.py\", line 704, in readinto\n    return self._sock.recv_into(b)\nConnectionResetError: [Errno 104] Connection reset by peer\n",
    "exit_code": 1,
    "file": "task/module/webserver1/f376f6b7-600f-4540-bbd8-d2ef539b5d8e",
    "output": ""
  }
}

Continued in next post.

Cheers.

EddieA · June 7, 2023, 1:31am

Summary

Jun 07 01:20:44 node.ns8.test webserver1[11656]: task/module/webserver1/d050448b-2412-4156-8884-a7d066a8edd3: create-module/05pullimages is starting
Jun 07 01:20:44 node.ns8.test webserver1[11656]: Add to module/webserver1 environment NGINX_IMAGE=docker.io/nginx:1.24-alpine
Jun 07 01:20:44 node.ns8.test webserver1[11656]: Add to module/webserver1 environment SFTPGO_IMAGE=docker.io/drakkan/sftpgo:v2.5.1-alpine
Jun 07 01:20:44 node.ns8.test webserver1[11656]: dump_env() is deprecated and implemented as a no-op
Jun 07 01:20:44 node.ns8.test webserver1[11656]: podman-pull-missing docker.io/nginx:1.24-alpine docker.io/drakkan/sftpgo:v2.5.1-alpine
Jun 07 01:20:45 node.ns8.test webserver1[11656]: Trying to pull docker.io/library/nginx:1.24-alpine...
Jun 07 01:20:46 node.ns8.test webserver1[11656]: Getting image source signatures
Jun 07 01:20:46 node.ns8.test webserver1[11656]: Copying blob sha256:b6b60f9051a8186751b35d6f9e0a792edcd47b24b1d4d53be0ee383e3e1ecaf1
Jun 07 01:20:46 node.ns8.test webserver1[11656]: Copying blob sha256:81234aecc257822106327b49f7dc428d0b5b2f67577ad4b745188672a5029f12
Jun 07 01:20:46 node.ns8.test webserver1[11656]: Copying blob sha256:f56be85fc22e46face30e2c3de3f7fe7c15f8fd7c4e5add29d7f64b87abdaa09
Jun 07 01:20:46 node.ns8.test webserver1[11656]: Copying blob sha256:f7c8639dc75ec36e3531791446072f73c7e6a786bbd6a3f03f6fb822e3576047
Jun 07 01:20:46 node.ns8.test webserver1[11656]: Copying blob sha256:bb5936af66b7c9c110b4c59af7d7595547529732b6691edc46c6798687f21d0a
Jun 07 01:20:46 node.ns8.test webserver1[11656]: Copying blob sha256:d0071b96733a839c3dc75a8a186bba103b8b455ce4980398e1b36e57d1850734
Jun 07 01:20:47 node.ns8.test webserver1[11656]: Copying blob sha256:44286d6df86930644852ebe4f9a5909bdbe1547585fb5c12dc875dee18068db6
Jun 07 01:20:53 node.ns8.test webserver1[11656]: Copying config sha256:1266a3a46e967b44a063058d2efa42097e2a55be287a62f9a6343b231f585f9d
Jun 07 01:20:53 node.ns8.test webserver1[11656]: Writing manifest to image destination
Jun 07 01:20:53 node.ns8.test webserver1[11656]: Storing signatures
Jun 07 01:20:53 node.ns8.test webserver1[11656]: 1266a3a46e967b44a063058d2efa42097e2a55be287a62f9a6343b231f585f9d
Jun 07 01:20:53 node.ns8.test webserver1[11656]: Trying to pull docker.io/drakkan/sftpgo:v2.5.1-alpine...
Jun 07 01:20:55 node.ns8.test webserver1[11656]: Getting image source signatures
Jun 07 01:20:55 node.ns8.test webserver1[11656]: Copying blob sha256:740eba7c0b1fe98061ecda5d90af8eea2241ce4560d4feda64b383980ac788cd
Jun 07 01:20:55 node.ns8.test webserver1[11656]: Copying blob sha256:3898a60ae422940146d0e02406c65836823da231d61a190b3bfb162b8968b585
Jun 07 01:20:55 node.ns8.test webserver1[11656]: Copying blob sha256:8a49fdb3b6a5ff2bd8ec6a86c05b2922a0f7454579ecc07637e94dfd1d0639b6
Jun 07 01:20:55 node.ns8.test webserver1[11656]: Copying blob sha256:5cff7586f2c86559c2c4369f9e07c470650009841da5bab0f206878e6097e523
Jun 07 01:20:55 node.ns8.test webserver1[11656]: Copying blob sha256:495ae28678ca68b4f1906acf2c4acb49ccb4812bca9356686dcc3d3ac1ffa4ee
Jun 07 01:20:55 node.ns8.test webserver1[11656]: Copying blob sha256:a6f2037144d7d830e84c4f05aa9eda7d2383e86d953518453e24c6b036848988
Jun 07 01:20:56 node.ns8.test webserver1[11656]: Copying blob sha256:810d85ad67625deb2f0f3ebe9d22da1a93cbd1346e7977923591ec098afc78c6
Jun 07 01:20:56 node.ns8.test webserver1[11656]: Copying blob sha256:4ebd00ad7397305afa7fed279837d0ec0481542cc5e49da259342ec907853f5f
Jun 07 01:20:56 node.ns8.test webserver1[11656]: Copying blob sha256:1b65d29662e26f20d294453d88d822437abfbcb0322907ef2cbe7c754cc55cd8
Jun 07 01:20:56 node.ns8.test webserver1[11656]: Copying blob sha256:4cc6b78db92af2cada9d763f8377f39c5f879ceebcc9e78e4fe866ad579d68b4
Jun 07 01:20:57 node.ns8.test webserver1[11656]: Copying blob sha256:e571d5b25a1bac80c80f072c11f6552d3a02ce2478cee77ce64252f626fd18b5
Jun 07 01:20:57 node.ns8.test webserver1[11656]: Copying blob sha256:247ce4102613bda7f206e00ddbe2535bbe7d9a0086c6a7b15d2a7b990cfc8426
Jun 07 01:20:58 node.ns8.test webserver1[11656]: Copying blob sha256:579e14b51d82db0b1783639ce54b2cfade152125d1babc0bdadd292381fce898
Jun 07 01:20:58 node.ns8.test webserver1[11656]: Copying blob sha256:4f4fb700ef54461cfa02571ae0db9a0dc1e0cdb5577484a6d75e68dc38e8acc1
Jun 07 01:21:01 node.ns8.test webserver1[11656]: Copying config sha256:7f0a1f44b0c7feceaa04f0c725194849735eaaee4f99a016ed308ae6e98db0f9
Jun 07 01:21:01 node.ns8.test webserver1[11656]: Writing manifest to image destination
Jun 07 01:21:01 node.ns8.test webserver1[11656]: Storing signatures
Jun 07 01:21:03 node.ns8.test webserver1[11656]: 7f0a1f44b0c7feceaa04f0c725194849735eaaee4f99a016ed308ae6e98db0f9
Jun 07 01:21:03 node.ns8.test webserver1[11656]: task/module/webserver1/d050448b-2412-4156-8884-a7d066a8edd3: create-module/10configure is starting
Jun 07 01:21:03 node.ns8.test webserver1[11656]: dump_env() is deprecated and implemented as a no-op
Jun 07 01:21:03 node.ns8.test webserver1[11656]: task/module/webserver1/d050448b-2412-4156-8884-a7d066a8edd3: create-module/10log_tag is starting
Jun 07 01:21:03 node.ns8.test webserver1[11656]: task/module/webserver1/d050448b-2412-4156-8884-a7d066a8edd3: create-module/10selfadm_role is starting
Jun 07 01:21:03 node.ns8.test webserver1[11656]: 1
Jun 07 01:21:03 node.ns8.test webserver1[11656]: task/module/webserver1/d050448b-2412-4156-8884-a7d066a8edd3: create-module/50start_services is starting
Jun 07 01:21:03 node.ns8.test webserver1[11656]: Created symlink /home/webserver1/.config/systemd/user/default.target.wants/webserver.service → /home/webserver1/.config/systemd/user/webserver.service.
Jun 07 01:21:06 node.ns8.test webserver1[11656]: task/module/webserver1/d050448b-2412-4156-8884-a7d066a8edd3: action "create-module" status is "completed" (0) at step 50start_services
Jun 07 01:21:07 node.ns8.test webserver1[11969]: /docker-entrypoint.sh: /docker-entrypoint.d/ is not empty, will attempt to perform configuration
Jun 07 01:21:07 node.ns8.test webserver1[11969]: /docker-entrypoint.sh: Looking for shell scripts in /docker-entrypoint.d/
Jun 07 01:21:07 node.ns8.test webserver1[11969]: /docker-entrypoint.sh: Launching /docker-entrypoint.d/10-listen-on-ipv6-by-default.sh
Jun 07 01:21:07 node.ns8.test webserver1[11969]: 10-listen-on-ipv6-by-default.sh: info: /etc/nginx/conf.d/default.conf is not a file or does not exist
Jun 07 01:21:07 node.ns8.test webserver1[11969]: /docker-entrypoint.sh: Launching /docker-entrypoint.d/20-envsubst-on-templates.sh
Jun 07 01:21:07 node.ns8.test webserver1[11969]: /docker-entrypoint.sh: Launching /docker-entrypoint.d/30-tune-worker-processes.sh
Jun 07 01:21:07 node.ns8.test webserver1[11969]: /docker-entrypoint.sh: Configuration complete; ready for start up
Jun 07 01:21:07 node.ns8.test webserver1[11969]: 2023/06/07 01:21:07 [notice] 1#1: using the "epoll" event method
Jun 07 01:21:07 node.ns8.test webserver1[11969]: 2023/06/07 01:21:07 [notice] 1#1: nginx/1.24.0
Jun 07 01:21:07 node.ns8.test webserver1[11969]: 2023/06/07 01:21:07 [notice] 1#1: built by gcc 12.2.1 20220924 (Alpine 12.2.1_git20220924-r4)
Jun 07 01:21:07 node.ns8.test webserver1[11969]: 2023/06/07 01:21:07 [notice] 1#1: OS: Linux 5.14.0-162.23.1.el9_1.x86_64
Jun 07 01:21:07 node.ns8.test webserver1[11969]: 2023/06/07 01:21:07 [notice] 1#1: getrlimit(RLIMIT_NOFILE): 524288:524288
Jun 07 01:21:07 node.ns8.test webserver1[11969]: 2023/06/07 01:21:07 [notice] 1#1: start worker processes
Jun 07 01:21:07 node.ns8.test webserver1[11969]: 2023/06/07 01:21:07 [notice] 1#1: start worker process 15
Jun 07 01:21:07 node.ns8.test webserver1[11969]: 2023/06/07 01:21:07 [notice] 1#1: start worker process 16
Jun 07 01:21:11 node.ns8.test webserver1[11656]: task/module/webserver1/133ec742-4ca1-41a5-af09-7333d7fdb77f: get-name/50get_name is starting
Jun 07 01:21:11 node.ns8.test webserver1[11656]: task/module/webserver1/ec541092-e4b4-4a1f-89e4-fb5763c0d206: get-configuration/20read is starting
Jun 07 01:21:11 node.ns8.test webserver1[11656]: task/module/webserver1/ec541092-e4b4-4a1f-89e4-fb5763c0d206: action "get-configuration" status is "completed" (0) at step validate-output.json
Jun 07 01:21:11 node.ns8.test webserver1[11656]: task/module/webserver1/133ec742-4ca1-41a5-af09-7333d7fdb77f: action "get-name" status is "completed" (0) at step 50get_name
Jun 07 01:21:19 node.ns8.test webserver1[11656]: task/module/webserver1/f376f6b7-600f-4540-bbd8-d2ef539b5d8e: configure-module/01_validate_web_path is starting
Jun 07 01:21:19 node.ns8.test webserver1[11656]: task/module/webserver1/f376f6b7-600f-4540-bbd8-d2ef539b5d8e: configure-module/02_validate_sftp_port is starting
Jun 07 01:21:19 node.ns8.test webserver1[11656]: task/module/webserver1/f376f6b7-600f-4540-bbd8-d2ef539b5d8e: configure-module/05Firewall is starting
Jun 07 01:21:24 node.ns8.test webserver1[11656]: task/module/webserver1/f376f6b7-600f-4540-bbd8-d2ef539b5d8e: configure-module/10settings is starting
Jun 07 01:21:24 node.ns8.test webserver1[11656]: task/module/webserver1/f376f6b7-600f-4540-bbd8-d2ef539b5d8e: configure-module/20traefik is starting
Jun 07 01:21:24 node.ns8.test webserver1[11656]: dump_env() is deprecated and implemented as a no-op
Jun 07 01:21:28 node.ns8.test webserver1[11656]: task/module/webserver1/f376f6b7-600f-4540-bbd8-d2ef539b5d8e: configure-module/50start_services is starting
Jun 07 01:21:28 node.ns8.test webserver1[11656]: systemctl --user restart webserver.service
Jun 07 01:21:28 node.ns8.test webserver1[11969]: 2023/06/07 01:21:28 [notice] 1#1: signal 3 (SIGQUIT) received, shutting down
Jun 07 01:21:28 node.ns8.test webserver1[11969]: 2023/06/07 01:21:28 [notice] 15#15: gracefully shutting down
Jun 07 01:21:28 node.ns8.test webserver1[11969]: 2023/06/07 01:21:28 [notice] 15#15: exiting
Jun 07 01:21:28 node.ns8.test webserver1[11969]: 2023/06/07 01:21:28 [notice] 16#16: gracefully shutting down
Jun 07 01:21:28 node.ns8.test webserver1[11969]: 2023/06/07 01:21:28 [notice] 16#16: exiting
Jun 07 01:21:28 node.ns8.test webserver1[11969]: 2023/06/07 01:21:28 [notice] 16#16: exit
Jun 07 01:21:28 node.ns8.test webserver1[11969]: 2023/06/07 01:21:28 [notice] 15#15: exit
Jun 07 01:21:28 node.ns8.test webserver1[11969]: 2023/06/07 01:21:28 [notice] 1#1: signal 17 (SIGCHLD) received from 16
Jun 07 01:21:28 node.ns8.test webserver1[11969]: 2023/06/07 01:21:28 [notice] 1#1: worker process 16 exited with code 0
Jun 07 01:21:28 node.ns8.test webserver1[11969]: 2023/06/07 01:21:28 [notice] 1#1: signal 29 (SIGIO) received
Jun 07 01:21:28 node.ns8.test webserver1[11969]: 2023/06/07 01:21:28 [notice] 1#1: signal 17 (SIGCHLD) received from 15
Jun 07 01:21:28 node.ns8.test webserver1[11969]: 2023/06/07 01:21:28 [notice] 1#1: worker process 15 exited with code 0
Jun 07 01:21:28 node.ns8.test webserver1[11969]: 2023/06/07 01:21:28 [notice] 1#1: exit
Jun 07 01:21:30 node.ns8.test webserver1[11656]: systemctl --user enable sftpgo.service
Jun 07 01:21:30 node.ns8.test webserver1[11656]: Created symlink /home/webserver1/.config/systemd/user/default.target.wants/sftpgo.service → /home/webserver1/.config/systemd/user/sftpgo.service.
Jun 07 01:21:30 node.ns8.test webserver1[11656]: systemctl --user restart sftpgo.service
Jun 07 01:21:30 node.ns8.test webserver1[12411]: /docker-entrypoint.sh: /docker-entrypoint.d/ is not empty, will attempt to perform configuration
Jun 07 01:21:30 node.ns8.test webserver1[12411]: /docker-entrypoint.sh: Looking for shell scripts in /docker-entrypoint.d/
Jun 07 01:21:30 node.ns8.test webserver1[12411]: /docker-entrypoint.sh: Launching /docker-entrypoint.d/10-listen-on-ipv6-by-default.sh
Jun 07 01:21:30 node.ns8.test webserver1[12411]: 10-listen-on-ipv6-by-default.sh: info: /etc/nginx/conf.d/default.conf is not a file or does not exist
Jun 07 01:21:30 node.ns8.test webserver1[12411]: /docker-entrypoint.sh: Launching /docker-entrypoint.d/20-envsubst-on-templates.sh
Jun 07 01:21:30 node.ns8.test webserver1[12411]: /docker-entrypoint.sh: Launching /docker-entrypoint.d/30-tune-worker-processes.sh
Jun 07 01:21:30 node.ns8.test webserver1[12411]: /docker-entrypoint.sh: Configuration complete; ready for start up
Jun 07 01:21:30 node.ns8.test webserver1[12411]: 2023/06/07 01:21:30 [notice] 1#1: using the "epoll" event method
Jun 07 01:21:30 node.ns8.test webserver1[12411]: 2023/06/07 01:21:30 [notice] 1#1: nginx/1.24.0
Jun 07 01:21:30 node.ns8.test webserver1[12411]: 2023/06/07 01:21:30 [notice] 1#1: built by gcc 12.2.1 20220924 (Alpine 12.2.1_git20220924-r4)
Jun 07 01:21:30 node.ns8.test webserver1[12411]: 2023/06/07 01:21:30 [notice] 1#1: OS: Linux 5.14.0-162.23.1.el9_1.x86_64
Jun 07 01:21:30 node.ns8.test webserver1[12411]: 2023/06/07 01:21:30 [notice] 1#1: getrlimit(RLIMIT_NOFILE): 524288:524288
Jun 07 01:21:30 node.ns8.test webserver1[12411]: 2023/06/07 01:21:30 [notice] 1#1: start worker processes
Jun 07 01:21:30 node.ns8.test webserver1[12411]: 2023/06/07 01:21:30 [notice] 1#1: start worker process 15
Jun 07 01:21:30 node.ns8.test webserver1[12411]: 2023/06/07 01:21:30 [notice] 1#1: start worker process 16
Jun 07 01:21:31 node.ns8.test webserver1[12441]: {"level":"info","time":"2023-06-07T01:21:31.292","sender":"service","message":"starting SFTPGo 2.5.1-5b4a1bda-2023-05-20T17:11:03Z +metrics +azblob +gcs +s3 +bolt +mysql +pgsql +sqlite -unixcrypt +portable, config dir: ., config file: , log max size: 10 log max backups: 5 log max age: 28 log level: debug, log compress: false, log utc time: false, load data from: \"/etc/sftpgo/admin.json\", grace time: 0 secs"}
Jun 07 01:21:31 node.ns8.test webserver1[12441]: {"level":"info","time":"2023-06-07T01:21:31.292","sender":"config","message":"unable to read env files from \"env.d\": open env.d: no such file or directory"}
Jun 07 01:21:31 node.ns8.test webserver1[12441]: {"level":"debug","time":"2023-06-07T01:21:31.299","sender":"config","message":"config file used: '\"/etc/sftpgo/sftpgo.json\"', config loaded: {Common:{IdleTimeout:15 UploadMode:0 Actions:{ExecuteOn:[] ExecuteSync:[] Hook:} SetstatMode:0 RenameMode:0 TempPath: ProxyProtocol:0 ProxyAllowed:[] ProxySkipped:[] StartupHook: PostConnectHook: PostDisconnectHook: DataRetentionHook: MaxTotalConnections:0 MaxPerHostConnections:20 AllowListStatus:0 AllowSelfConnections:0 DefenderConfig:{Enabled:false Driver:memory BanTime:30 BanTimeIncrement:50 Threshold:15 ScoreInvalid:2 ScoreValid:1 ScoreLimitExceeded:3 ScoreNoAuth:0 ObservationTime:30 EntriesSoftLimit:100 EntriesHardLimit:150} RateLimitersConfig:[{Average:0 Period:1000 Burst:1 Type:2 Protocols:[SSH FTP DAV HTTP] GenerateDefenderEvents:false EntriesSoftLimit:100 EntriesHardLimit:150}] idleTimeoutAsDuration:0 idleLoginTimeout:0 defender:<nil> allowList:<nil> rateLimitersList:<nil> proxyAllowed:[] proxySkipped:[]} ACME:{Email: KeyType:4096 CertsPath:certs CAEndpoint:https://acme-v02.api.letsencrypt.org/directory Domains:[] RenewDays:30 HTTP01Challenge:{Port:80 WebRoot: ProxyHeader:} TLSALPN01Challenge:{Port:0} accountConfigPath: accountKeyPath: lockPath: tempDir:} SFTPD:{Banner:SFTPGo_2.5.1 Bindings:[{Address: Port:2022 ApplyProxyConfig:true}] MaxAuthTries:0 HostKeys:[] HostCertificates:[] HostKeyAlgorithms:[] Moduli:[] KexAlgorithms:[] Ciphers:[] MACs:[] TrustedUserCAKeys:[] RevokedUserCertsFile: LoginBannerFile: EnabledSSHCommands:[md5sum sha1sum sha256sum cd pwd scp] KeyboardInteractiveAuthentication:true KeyboardInteractiveHook: PasswordAuthentication:true FolderPrefix: certChecker:<nil> parsedUserCAKeys:[]} FTPD:{Bindings:[{Address: Port:0 ApplyProxyConfig:true TLSMode:0 CertificateFile: CertificateKeyFile: MinTLSVersion:12 ForcePassiveIP: PassiveIPOverrides:[] PassiveHost: ClientAuthType:0 TLSCipherSuites:[] PassiveConnectionsSecurity:0 ActiveConnectionsSecurity:0 Debug:false ciphers:[]}] Banner:SFTPGo 2.5.1 ready BannerFile: CertificateFile: CertificateKeyFile: CACertificates:[] CARevocationLists:[] ActiveTransfersPortNon20:true DisableActiveMode:false EnableSite:false HASHSupport:0 CombineSupport:0 PassivePortRange:{Start:50000 End:50100} acmeDomain:} WebDAVD:{Bindings:[{Address: Port:0 EnableHTTPS:false CertificateFile: CertificateKeyFile: MinTLSVersion:12 ClientAuthType:0 TLSCipherSuites:[] Prefix: ProxyAllowed:[] ClientIPProxyHeader: ClientIPHeaderDepth:0 DisableWWWAuthHeader:false allowHeadersFrom:[]}] CertificateFile: CertificateKeyFile: CACertificates:[] CARevocationLists:[] Cors:{AllowedOrigins:[] AllowedMethods:[] AllowedHeaders:[] ExposedHeaders:[] AllowCredentials:false Enabled:false MaxAge:0 OptionsPassthrough:false OptionsSuccessStatus:0 AllowPrivateNetwork:false} Cache:{Users:{ExpirationTime:0 MaxSize:50} MimeTypes:{Enabled:true MaxSize:1000 CustomMappings:[]}} acmeDomain:} ProviderConf:{Driver:sqlite Name:sftpgo.db Host: Port:0 Username: Password: SSLMode:0 DisableSNI:false TargetSessionAttrs: RootCert: ClientCert: ClientKey: ConnectionString: SQLTablesPrefix: TrackQuota:2 PoolSize:0 UsersBaseDir:/srv/sftpgo/data Actions:{ExecuteOn:[] ExecuteFor:[] Hook:} ExternalAuthHook: ExternalAuthScope:0 PreLoginHook: PostLoginHook: PostLoginScope:0 CheckPasswordHook: CheckPasswordScope:0 UpdateMode:0 PasswordHashing:{BcryptOptions:{Cost:10} Argon2Options:{Memory:65536 Iterations:1 Parallelism:2} Algo:bcrypt} PasswordValidation:{Admins:{MinEntropy:0} Users:{MinEntropy:0}} PasswordCaching:true DelayedQuotaUpdate:0 CreateDefaultAdmin:false NamingRules:5 IsShared:0 Node:{Host: Port:0 Proto:http} BackupsPath:/srv/sftpgo/backups} HTTPDConfig:{Bindings:[{Address: Port:8080 EnableWebAdmin:true EnableWebClient:true EnableRESTAPI:true EnabledLoginMethods:0 EnableHTTPS:false CertificateFile: CertificateKeyFile: MinTLSVersion:12 ClientAuthType:0 TLSCipherSuites:[] ProxyAllowed:[] ClientIPProxyHeader: ClientIPHeaderDepth:0 HideLoginURL:0 RenderOpenAPI:true WebClientIntegrations:[] OIDC:{ClientID: ClientSecret: ConfigURL: RedirectBaseURL: UsernameField: RoleField: ImplicitRoles:false Scopes:[openid profile email] CustomFields:[] InsecureSkipSignatureCheck:false Debug:false provider:<nil> verifier:<nil> providerLogoutURL: oauth2Config:<nil>} Security:{Enabled:false AllowedHosts:[] AllowedHostsAreRegex:false HostsProxyHeaders:[] HTTPSRedirect:false HTTPSHost: HTTPSProxyHeaders:[] STSSeconds:0 STSIncludeSubdomains:false STSPreload:false ContentTypeNosniff:false ContentSecurityPolicy: PermissionsPolicy: CrossOriginOpenerPolicy: ExpectCTHeader: proxyHeaders:[]} Branding:{WebAdmin:{Name: ShortName: LogoPath: LoginImagePath: FaviconPath: DisclaimerName: DisclaimerPath: DefaultCSS: ExtraCSS:[]} WebClient:{Name: ShortName: LogoPath: LoginImagePath: FaviconPath: DisclaimerName: DisclaimerPath: DefaultCSS: ExtraCSS:[]}} allowHeadersFrom:[]}] TemplatesPath:templates StaticFilesPath:static OpenAPIPath:openapi WebRoot:/sftpgo CertificateFile: CertificateKeyFile: CACertificates:[] CARevocationLists:[] SigningPassphrase: TokenValidation:0 MaxUploadFileSize:0 Cors:{AllowedOrigins:[] AllowedMethods:[] AllowedHeaders:[] ExposedHeaders:[] AllowCredentials:false Enabled:false MaxAge:0 OptionsPassthrough:false OptionsSuccessStatus:0 AllowPrivateNetwork:false} Setup:{InstallationCode: InstallationCodeHint:Installation code} HideSupportLink:false acmeDomain:} HTTPConfig:{Timeout:20 RetryWaitMin:2 RetryWaitMax:30 RetryMax:3 CACertificates:[] Certificates:[] SkipTLSVerify:false Headers:[] customTransport:<nil>} CommandConfig:{Timeout:30 Env:[] Commands:[]} KMSConfig:{Secrets:{URL: MasterKeyPath: MasterKeyString: masterKey:}} MFAConfig:{TOTP:[{Name:Default Issuer:SFTPGo Algo:sha1 algo:0}]} TelemetryConfig:{BindPort:0 BindAddress:127.0.0.1 EnableProfiler:false AuthUserFile: CertificateFile: CertificateKeyFile: TLSCipherSuites:[] MinTLSVersion:12} PluginsConfig:[] SMTPConfig:{Host: Port:25 From: User: Password: AuthType:0 Encryption:0 Domain: TemplatesPath:templates}}"}
Jun 07 01:21:31 node.ns8.test webserver1[12441]: {"level":"info","time":"2023-06-07T01:21:31.299","sender":"kms","message":"secret provider registered for scheme: \"builtin\", encrypted status: \"AES-256-GCM\""}
Jun 07 01:21:31 node.ns8.test webserver1[12441]: {"level":"info","time":"2023-06-07T01:21:31.299","sender":"kms","message":"secret provider registered for scheme: \"local\", encrypted status: \"Secretbox\""}
Jun 07 01:21:31 node.ns8.test webserver1[12441]: {"level":"debug","time":"2023-06-07T01:21:31.299","sender":"dataprovider","message":"absolute backup path \"/srv/sftpgo/backups\""}
Jun 07 01:21:31 node.ns8.test webserver1[12441]: {"level":"debug","time":"2023-06-07T01:21:31.299","sender":"dataprovider_sqlite","message":"sqlite database handle created, connection string: \"file:sftpgo.db?cache=shared&_foreign_keys=1\""}
Jun 07 01:21:31 node.ns8.test webserver1[12441]: {"level":"error","time":"2023-06-07T01:21:31.300","sender":"dataprovider_sqlite","message":"error preparing database query \"SELECT version from schema_version LIMIT 1\": no such table: schema_version"}
Jun 07 01:21:31 node.ns8.test webserver1[12441]: {"level":"info","time":"2023-06-07T01:21:31.300","sender":"dataprovider_sqlite","message":"creating initial database schema, version 23"}

To be continued:

Cheers.

EddieA · June 7, 2023, 1:31am

Remainder of log:

Summary

Jun 07 01:21:31 node.ns8.test webserver1[12441]: {"level":"error","time":"2023-06-07T01:21:31.300","sender":"dataprovider_sqlite","message":"error preparing database query \"SELECT version from schema_version LIMIT 1\": no such table: schema_version"}
Jun 07 01:21:31 node.ns8.test webserver1[11656]: task/module/webserver1/f376f6b7-600f-4540-bbd8-d2ef539b5d8e: configure-module/60sftpgo_create_secret is starting
Jun 07 01:21:31 node.ns8.test webserver1[12441]: {"level":"info","time":"2023-06-07T01:21:31.518","sender":"dataprovider_sqlite","message":"updating database schema version: 23 -> 24"}
Jun 07 01:21:31 node.ns8.test webserver1[11656]: Traceback (most recent call last):
Jun 07 01:21:31 node.ns8.test webserver1[11656]:   File "/home/webserver1/.config/actions/configure-module/60sftpgo_create_secret", line 44, in <module>
Jun 07 01:21:31 node.ns8.test webserver1[11656]:     res = conn.getresponse()
Jun 07 01:21:31 node.ns8.test webserver1[11656]:   File "/usr/lib64/python3.9/http/client.py", line 1377, in getresponse
Jun 07 01:21:31 node.ns8.test webserver1[12441]: {"level":"info","time":"2023-06-07T01:21:31.625","sender":"dataprovider_sqlite","message":"updating database schema version: 24 -> 25"}
Jun 07 01:21:31 node.ns8.test webserver1[11656]:     response.begin()
Jun 07 01:21:31 node.ns8.test webserver1[11656]:   File "/usr/lib64/python3.9/http/client.py", line 320, in begin
Jun 07 01:21:31 node.ns8.test webserver1[11656]:     version, status, reason = self._read_status()
Jun 07 01:21:31 node.ns8.test webserver1[11656]:   File "/usr/lib64/python3.9/http/client.py", line 281, in _read_status
Jun 07 01:21:31 node.ns8.test webserver1[11656]:     line = str(self.fp.readline(_MAXLINE + 1), "iso-8859-1")
Jun 07 01:21:31 node.ns8.test webserver1[11656]:   File "/usr/lib64/python3.9/socket.py", line 704, in readinto
Jun 07 01:21:31 node.ns8.test webserver1[11656]:     return self._sock.recv_into(b)
Jun 07 01:21:31 node.ns8.test webserver1[11656]: ConnectionResetError: [Errno 104] Connection reset by peer
Jun 07 01:21:31 node.ns8.test webserver1[11656]: task/module/webserver1/f376f6b7-600f-4540-bbd8-d2ef539b5d8e: action "configure-module" status is "aborted" (1) at step 60sftpgo_create_secret
Jun 07 01:21:31 node.ns8.test webserver1[12441]: {"level":"info","time":"2023-06-07T01:21:31.692","sender":"dataprovider_sqlite","message":"updating database schema version: 25 -> 26"}
Jun 07 01:21:31 node.ns8.test webserver1[12441]: {"level":"info","time":"2023-06-07T01:21:31.809","sender":"dataprovider_sqlite","message":"updating database schema version: 26 -> 27"}
Jun 07 01:21:31 node.ns8.test webserver1[12441]: {"level":"info","time":"2023-06-07T01:21:31.950","sender":"dataprovider_sqlite","message":"updating database schema version: 27 -> 28"}
Jun 07 01:21:32 node.ns8.test webserver1[12441]: {"level":"debug","time":"2023-06-07T01:21:32.042","sender":"plugins","message":"initialize"}
Jun 07 01:21:32 node.ns8.test webserver1[12441]: {"level":"debug","time":"2023-06-07T01:21:32.042","sender":"dataprovider_sqlite","message":"delayed quota update loop started, wait time: 0s"}
Jun 07 01:21:32 node.ns8.test webserver1[12441]: {"level":"debug","time":"2023-06-07T01:21:32.042","sender":"dataprovider_sqlite","message":"delayed quota update loop ended, wait time: 0s"}
Jun 07 01:21:32 node.ns8.test webserver1[12441]: {"level":"debug","time":"2023-06-07T01:21:32.042","sender":"util","message":"found share data path for name \"templates\": \"/usr/share/sftpgo/templates\""}
Jun 07 01:21:32 node.ns8.test webserver1[12441]: {"level":"debug","time":"2023-06-07T01:21:32.042","sender":"smtp","message":"loading templates from \"/usr/share/sftpgo/templates/email\""}
Jun 07 01:21:32 node.ns8.test webserver1[12441]: {"level":"debug","time":"2023-06-07T01:21:32.043","sender":"smtp","message":"activating initial config"}
Jun 07 01:21:32 node.ns8.test webserver1[12441]: {"level":"debug","time":"2023-06-07T01:21:32.043","sender":"smtp","message":"configuration disabled, email capabilities will not be available"}
Jun 07 01:21:32 node.ns8.test webserver1[12441]: {"level":"debug","time":"2023-06-07T01:21:32.043","sender":"eventmanager","message":"loading updated rules"}
Jun 07 01:21:32 node.ns8.test webserver1[12441]: {"level":"debug","time":"2023-06-07T01:21:32.044","sender":"eventmanager","message":"recently updated event rules loaded: 0"}
Jun 07 01:21:32 node.ns8.test webserver1[12441]: {"level":"debug","time":"2023-06-07T01:21:32.044","sender":"eventmanager","message":"event rules updated, fs events: 0, provider events: 0, schedules: 0, ip blocked events: 0, certificate events: 0, IDP login events: 0"}
Jun 07 01:21:32 node.ns8.test webserver1[12441]: {"level":"info","time":"2023-06-07T01:21:32.044","sender":"common","message":"scheduled overquota transfers check, schedule \"@every 1m0s\""}
Jun 07 01:21:32 node.ns8.test webserver1[12441]: {"level":"info","time":"2023-06-07T01:21:32.044","sender":"common","message":"scheduled idle connections check, schedule \"@every 3m0s\""}
Jun 07 01:21:32 node.ns8.test webserver1[12441]: {"level":"info","time":"2023-06-07T01:21:32.044","sender":"common","message":"using memory transfer checker"}
Jun 07 01:21:32 node.ns8.test webserver1[12441]: {"level":"info","time":"2023-06-07T01:21:32.044","sender":"acme","message":"no domains configured, acme disabled"}
Jun 07 01:21:32 node.ns8.test webserver1[12441]: {"level":"debug","time":"2023-06-07T01:21:32.142","sender":"httpd","message":"adding new admin \"admin\", dump file: \"/etc/sftpgo/admin.json\", error: <nil>"}
Jun 07 01:21:32 node.ns8.test webserver1[12441]: {"level":"info","time":"2023-06-07T01:21:32.142","sender":"service","message":"data loaded from file \"/etc/sftpgo/admin.json\" mode: 1"}
Jun 07 01:21:32 node.ns8.test webserver1[12441]: {"level":"info","time":"2023-06-07T01:21:32.142","sender":"service","message":"FTP server not started, disabled in config file"}
Jun 07 01:21:32 node.ns8.test webserver1[12441]: {"level":"info","time":"2023-06-07T01:21:32.142","sender":"service","message":"WebDAV server not started, disabled in config file"}
Jun 07 01:21:32 node.ns8.test webserver1[12441]: {"level":"info","time":"2023-06-07T01:21:32.142","sender":"service","message":"telemetry server not started, disabled in config file"}
Jun 07 01:21:32 node.ns8.test webserver1[12441]: {"level":"info","time":"2023-06-07T01:21:32.142","sender":"service","message":"initializing SFTP server with config {Banner:SFTPGo_2.5.1 Bindings:[{Address: Port:2022 ApplyProxyConfig:true}] MaxAuthTries:0 HostKeys:[] HostCertificates:[] HostKeyAlgorithms:[] Moduli:[] KexAlgorithms:[] Ciphers:[] MACs:[] TrustedUserCAKeys:[] RevokedUserCertsFile: LoginBannerFile: EnabledSSHCommands:[md5sum sha1sum sha256sum cd pwd scp] KeyboardInteractiveAuthentication:true KeyboardInteractiveHook: PasswordAuthentication:true FolderPrefix: certChecker:<nil> parsedUserCAKeys:[]}"}
Jun 07 01:21:32 node.ns8.test webserver1[12441]: {"level":"info","time":"2023-06-07T01:21:32.143","sender":"sftpd","message":"No host keys configured and \"id_rsa\" does not exist; try to create a new host key"}
Jun 07 01:21:32 node.ns8.test webserver1[12441]: {"level":"info","time":"2023-06-07T01:21:32.143","sender":"httpd","message":"initializing HTTP server with config {Bindings:[{Address: Port:8080 EnableWebAdmin:true EnableWebClient:true EnableRESTAPI:true EnabledLoginMethods:0 EnableHTTPS:false CertificateFile: CertificateKeyFile: MinTLSVersion:12 ClientAuthType:0 TLSCipherSuites:[] ProxyAllowed:[] ClientIPProxyHeader: ClientIPHeaderDepth:0 HideLoginURL:0 RenderOpenAPI:true WebClientIntegrations:[] OIDC:{ClientID: ClientSecret: ConfigURL: RedirectBaseURL: UsernameField: RoleField: ImplicitRoles:false Scopes:[openid profile email] CustomFields:[] InsecureSkipSignatureCheck:false Debug:false provider:<nil> verifier:<nil> providerLogoutURL: oauth2Config:<nil>} Security:{Enabled:false AllowedHosts:[] AllowedHostsAreRegex:false HostsProxyHeaders:[] HTTPSRedirect:false HTTPSHost: HTTPSProxyHeaders:[] STSSeconds:0 STSIncludeSubdomains:false STSPreload:false ContentTypeNosniff:false ContentSecurityPolicy: PermissionsPolicy: CrossOriginOpenerPolicy: ExpectCTHeader: proxyHeaders:[]} Branding:{WebAdmin:{Name: ShortName: LogoPath: LoginImagePath: FaviconPath: DisclaimerName: DisclaimerPath: DefaultCSS: ExtraCSS:[]} WebClient:{Name: ShortName: LogoPath: LoginImagePath: FaviconPath: DisclaimerName: DisclaimerPath: DefaultCSS: ExtraCSS:[]}} allowHeadersFrom:[]}] TemplatesPath:templates StaticFilesPath:static OpenAPIPath:openapi WebRoot:/sftpgo CertificateFile: CertificateKeyFile: CACertificates:[] CARevocationLists:[] SigningPassphrase: TokenValidation:0 MaxUploadFileSize:0 Cors:{AllowedOrigins:[] AllowedMethods:[] AllowedHeaders:[] ExposedHeaders:[] AllowCredentials:false Enabled:false MaxAge:0 OptionsPassthrough:false OptionsSuccessStatus:0 AllowPrivateNetwork:false} Setup:{InstallationCode: InstallationCodeHint:Installation code} HideSupportLink:false acmeDomain:}"}
Jun 07 01:21:32 node.ns8.test webserver1[12441]: {"level":"info","time":"2023-06-07T01:21:32.143","sender":"httpd","message":"using memory reset code manager"}
Jun 07 01:21:32 node.ns8.test webserver1[12441]: {"level":"info","time":"2023-06-07T01:21:32.143","sender":"httpd","message":"using memory OIDC manager"}
Jun 07 01:21:32 node.ns8.test webserver1[12441]: {"level":"debug","time":"2023-06-07T01:21:32.143","sender":"util","message":"found share data path for name \"static\": \"/usr/share/sftpgo/static\""}
Jun 07 01:21:32 node.ns8.test webserver1[12441]: {"level":"debug","time":"2023-06-07T01:21:32.143","sender":"util","message":"found share data path for name \"templates\": \"/usr/share/sftpgo/templates\""}
Jun 07 01:21:32 node.ns8.test webserver1[12441]: {"level":"debug","time":"2023-06-07T01:21:32.143","sender":"util","message":"found share data path for name \"openapi\": \"/usr/share/sftpgo/openapi\""}
Jun 07 01:21:32 node.ns8.test webserver1[12441]: {"level":"info","time":"2023-06-07T01:21:32.173","sender":"httpd","message":"server listener registered, address: [::]:8080 TLS enabled: false"}
Jun 07 01:21:36 node.ns8.test webserver1[12441]: {"level":"info","time":"2023-06-07T01:21:36.439","sender":"sftpd","message":"No host keys configured and \"id_ecdsa\" does not exist; try to create a new host key"}
Jun 07 01:21:36 node.ns8.test webserver1[12441]: {"level":"info","time":"2023-06-07T01:21:36.439","sender":"sftpd","message":"No host keys configured and \"id_ed25519\" does not exist; try to create a new host key"}
Jun 07 01:21:36 node.ns8.test webserver1[12441]: {"level":"info","time":"2023-06-07T01:21:36.441","sender":"sftpd","message":"Loading private host key \"id_rsa\""}
Jun 07 01:21:36 node.ns8.test webserver1[12441]: {"level":"info","time":"2023-06-07T01:21:36.442","sender":"sftpd","message":"Host key \"id_rsa\" loaded, type \"ssh-rsa\", fingerprint \"SHA256:oZTNjVNqAaRUZvSSSTSd78OJbwUE4j1PryqssDfutkw\""}
Jun 07 01:21:36 node.ns8.test webserver1[12441]: {"level":"info","time":"2023-06-07T01:21:36.442","sender":"sftpd","message":"Loading private host key \"id_ecdsa\""}
Jun 07 01:21:36 node.ns8.test webserver1[12441]: {"level":"info","time":"2023-06-07T01:21:36.442","sender":"sftpd","message":"Host key \"id_ecdsa\" loaded, type \"ecdsa-sha2-nistp256\", fingerprint \"SHA256:wBrJ8qZEmncuaIDDHI5cZLmUswYDENA94ZssM3Nc4nc\""}
Jun 07 01:21:36 node.ns8.test webserver1[12441]: {"level":"info","time":"2023-06-07T01:21:36.442","sender":"sftpd","message":"Loading private host key \"id_ed25519\""}
Jun 07 01:21:36 node.ns8.test webserver1[12441]: {"level":"info","time":"2023-06-07T01:21:36.442","sender":"sftpd","message":"Host key \"id_ed25519\" loaded, type \"ssh-ed25519\", fingerprint \"SHA256:JBBkCwdzh5leJvJLebEuF8Gs1njH4ncGaEm44BIE598\""}
Jun 07 01:21:36 node.ns8.test webserver1[12441]: {"level":"debug","time":"2023-06-07T01:21:36.442","sender":"sftpd","message":"enabled SSH commands [md5sum sha1sum sha256sum cd pwd scp]"}
Jun 07 01:21:36 node.ns8.test webserver1[12441]: {"level":"info","time":"2023-06-07T01:21:36.442","sender":"sftpd","message":"server listener registered, address: [::]:2022"}

Cheers.

stephdl · June 7, 2023, 3:48am

Could you try with a new server ?
I cannot reproduce the issue

Edit what is the operating system you use ?

I use rocky linux 9.2

How many node on the cluster, do you try to install on the leader or on the worker

EddieA · June 7, 2023, 4:17am

It was a new server, because after a failed install there is no way to do another install, so each test is a new install.

I’m using Markus’s pre-built Rocky 9.1.

Single node, so install on leader.

Cheers.

stephdl · June 7, 2023, 4:20am

Could you try a rocky minimal install then launch the script manually to initiate the cluster

I guess some issues

Btw 9.1 could have some selinux issue we need 9.2, try to upgrade before to install

@mrmarkuz could you check on your iso if you could reproduce the issue

Install webserver
Configure the module

stephdl · June 7, 2023, 4:25am

You could install how many webserver you want on a single node

Only the external port and the web path of sftpgo must be different. We have validators to avoid that

stephdl · June 7, 2023, 4:39am

Reading this Installation — NS8 documentation

The prebuilt could have some downside

EddieA · June 7, 2023, 4:40am

Sure. (Although if that builds the initial cluster differently than using the web UI, you could have even more issues. )

Will try that both ways, with the minimal install you’re now suggesting and also updating Markus’s image before starting on the Cluster.

Cheers.