[Bug] Feed update issues

Describe the bug The feeds are not updated automatically, but when running the commands from /etc/periodic/daily/greenbone-nvt-sync manually as gvm user works as expected.

To Reproduce Have the container run for a couple of days and check the logs and the feed status

Expected behavior Feeds get regularly updated

docker-compose log

cs)
gvm    | 2021-10-23 02:02:51,542 INFO reaped unknown pid 21402 (exit status 0)
gvm    | 2021-10-23 02:02:51,542 INFO reaped unknown pid 21407 (exit status 0)
gvm    | error: gvm:1 duplicate log entry for /var/log/gvm/gsad.log
gvm    | error: found error in file gvm, skipping
gvm    | error: stat of /var/log/messages failed: No such file or directory
gvm    | 2021-10-23 02:13:34,160 INFO reaped unknown pid 21404 (exit status 0)
gvm    | Updating NVTs...
gvm    | su: must be suid to work properly
gvm    | Updating GVMd data...
gvm    | su: must be suid to work properly
gvm    | Updating SCAP data...
gvm    | su: must be suid to work properly
gvm    | Updating CERT data...
gvm    | su: must be suid to work properly
gvm    | 2021-10-23 06:06:30,644 INFO exited: GVMUpdate (exit status 0; expected)
gvm    | 2021-10-23 06:06:30,646 INFO spawned: 'GVMUpdate' with pid 26739
gvm    | 2021-10-23 06:06:40,660 INFO success: GVMUpdate entered RUNNING state, process has stayed up for > than 10 seconds (startsecs)
gvm    | Updating NVTs...
gvm    | su: must be suid to work properly
gvm    | Updating GVMd data...
gvm    | su: must be suid to work properly
gvm    | Updating SCAP data...
gvm    | su: must be suid to work properly
gvm    | Updating CERT data...
gvm    | su: must be suid to work properly
gvm    | 2021-10-23 14:06:45,663 INFO exited: GVMUpdate (exit status 0; expected)
gvm    | 2021-10-23 14:06:46,667 INFO spawned: 'GVMUpdate' with pid 4842
gvm    | 2021-10-23 14:06:56,681 INFO success: GVMUpdate entered RUNNING state, process has stayed up for > than 10 seconds (startsecs)
gvm    | su: must be suid to work properly
gvm    | Updating NVTs...
gvm    | Updating GVMd data...
gvm    | su: must be suid to work properly
gvm    | Updating SCAP data...
gvm    | su: must be suid to work properly
gvm    | Updating CERT data...
gvm    | su: must be suid to work properly
gvm    | 2021-10-23 22:07:01,687 INFO exited: GVMUpdate (exit status 0; expected)
gvm    | 2021-10-23 22:07:01,690 INFO spawned: 'GVMUpdate' with pid 15411
gvm    | 2021-10-23 22:07:11,704 INFO success: GVMUpdate entered RUNNING state, process has stayed up for > than 10 seconds (startsecs)
gvm    | error: gvm:1 duplicate log entry for /var/log/gvm/gsad.log
gvm    | error: found error in file gvm, skipping
gvm    | error: stat of /var/log/messages failed: No such file or directory

Host Device:

OS: debian
Version: 10.10

Image in use:

Output from docker image inspect <image> :

[
{
    "Id": "sha256:d3b44077adbc97307db5eed1c992a045565f841d1e0a898524e81537fb10ed88",
    "RepoTags": [
        "securecompliance/gvm:21.4.3-v1-full"
    ],
    "RepoDigests": [
        "securecompliance/gvm@sha256:f7408205b87bc49eead2e34ea47ed6aaf9a286d6167f2bc17486dd0e87e5c026"
    ],
    "Parent": "",
    "Comment": "buildkit.dockerfile.v0",
    "Created": "2021-08-08T20:31:44.375679095Z",
    "Container": "",
    "ContainerConfig": {
        "Hostname": "",
        "Domainname": "",
        "User": "",
        "AttachStdin": false,
        "AttachStdout": false,
        "AttachStderr": false,
        "Tty": false,
        "OpenStdin": false,
        "StdinOnce": false,
        "Env": null,
        "Cmd": null,
        "Image": "",
        "Volumes": null,
        "WorkingDir": "",
        "Entrypoint": null,
        "OnBuild": null,
        "Labels": null
    },
    "DockerVersion": "",
    "Author": "",
    "Config": {
        "Hostname": "",
        "Domainname": "",
        "User": "",
        "AttachStdin": false,
        "AttachStdout": false,
        "AttachStderr": false,
        "ExposedPorts": {
            "22/tcp": {},
            "5432/tcp": {},
            "8081/tcp": {},
            "9392/tcp": {}
        },
        "Tty": false,
        "OpenStdin": false,
        "StdinOnce": false,
        "Env": [
            "PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin",
            "SUPVISD=supervisorctl",
            "USERNAME=admin",
            "PASSWORD=adminpassword",
            "PASSWORD_FILE=none",
            "TIMEOUT=15",
            "DEBUG=N",
            "RELAYHOST=smtp",
            "SMTPPORT=25",
            "AUTO_SYNC=true",
            "HTTPS=true",
            "CERTIFICATE=none",
            "CERTIFICATE_KEY=none",
            "TZ=Etc/UTC",
            "SSHD=false",
            "DB_PASSWORD=none",
            "DB_PASSWORD_FILE=none",
            "LANG=en_US.UTF-8",
            "LANGUAGE=en_US.UTF-8",
            "LC_ALL=en_US.UTF-8",
            "MUSL_LOCPATH=/usr/share/i18n/locales/musl",
            "SETUP=0",
            "OPT_PDF=1"
        ],
        "Cmd": [
            "/usr/bin/supervisord",
            "-n",
            "-c",
            "/etc/supervisord.conf"
        ],
        "ArgsEscaped": true,
        "Image": "",
        "Volumes": {
            "/etc/ssh": {},
            "/opt/database": {},
            "/var/lib/gvm": {},
            "/var/lib/openvas/plugins": {}
        },
        "WorkingDir": "",
        "Entrypoint": [
            "/entrypoint.sh"
        ],
        "OnBuild": null,
        "Labels": {
            "org.opencontainers.image.created": "2021-08-08T20:30:08.746Z",
            "org.opencontainers.image.description": "Greenbone Vulnerability Management Docker Image with OpenVAS",
            "org.opencontainers.image.licenses": "MIT",
            "org.opencontainers.image.revision": "45166f1b9bc1c5314303b99ee1a94bb7552bc153",
            "org.opencontainers.image.source": "https://github.com/Secure-Compliance-Solutions-LLC/GVM-Docker",
            "org.opencontainers.image.title": "GVM-Docker",
            "org.opencontainers.image.url": "https://github.com/Secure-Compliance-Solutions-LLC/GVM-Docker",
            "org.opencontainers.image.version": "21.4.3-v1-full"
        }
    },
    "Architecture": "amd64",
    "Os": "linux",
    "Size": 2555992137,
    "VirtualSize": 2555992137,
    "GraphDriver": {
        "Data": {
            "LowerDir": "/var/lib/docker/overlay2/8871a5cbf7af89379cce63d97316e7c22664b40e58969ab6f6753b07484f2150/diff:/var/lib/docker/overlay2/94eea910355288230a0b44dacb0027f076b063c15515b08e786cbdbd5efb8c6a/diff:/var/lib/docker/overlay2/ef266cd31c57244f37a7604e50de0413b28388ab98af7d5a69e858ed6fc9cad7/diff:/var/lib/docker/overlay2/96b09d86b35425f697c56475c3421e3a3fb23f0e8fb7d81b2c0e2dd945063c67/diff:/var/lib/docker/overlay2/7418f58c209ddece5495870efa62a3343bd48884ba09236b7de661a14d568ca6/diff:/var/lib/docker/overlay2/a7258d55c4a74e2a2d3aac46b73b6b36e59a7b894438bad04ed81d469b5d4f5a/diff:/var/lib/docker/overlay2/dddb30c345de54ab84fff3b862bf4de327f48e09162a3df7ff00d91debbca2a6/diff:/var/lib/docker/overlay2/218d6297eaa89f84d7121164767f1274e451e6932de5b0db743d8ba3a7a5fc62/diff:/var/lib/docker/overlay2/9741efdc7dc713b4218092e04253559bf94652284dfb4898fb36f610954ac5e0/diff:/var/lib/docker/overlay2/11981a194b3d2da31382a733889d9103fa1f836d16d1a6c24db9148d6e4c2bed/diff:/var/lib/docker/overlay2/94aad9588e0154d1f9c9aca3ff315260fef3651f7f72e5606bf484cb5f2d89e4/diff:/var/lib/docker/overlay2/c94dcbd6ba86c08b370bd1fd70a843657d79fcf1e60a0baa2ebea6aa28a90957/diff:/var/lib/docker/overlay2/75356f85babe1e0ed03518b53d79a97177ef66e7f2c7de8df3ea4f1ee65f1bce/diff:/var/lib/docker/overlay2/ca6496b2c87a683ff2ed343437ffd6fd07f3998f7434ba28a0906aea5c4fadac/diff",
            "MergedDir": "/var/lib/docker/overlay2/bfcd780172b38706bedf3ff4e3148e0e9156d8b6a6215cfb2bb634a58324eb4a/merged",
            "UpperDir": "/var/lib/docker/overlay2/bfcd780172b38706bedf3ff4e3148e0e9156d8b6a6215cfb2bb634a58324eb4a/diff",
            "WorkDir": "/var/lib/docker/overlay2/bfcd780172b38706bedf3ff4e3148e0e9156d8b6a6215cfb2bb634a58324eb4a/work"
        },
        "Name": "overlay2"
    },
    "RootFS": {
        "Type": "layers",
        "Layers": [
            "sha256:bc276c40b172b1c5467277d36db5308a203a48262d5f278766cf083947d05466",
            "sha256:0c4ac070c4f03cca7c16a747fd9d467b485c061795399010bd3100581ec41c0a",
            "sha256:5d6bbd2dcce5feb5424d1e3ee6b44049d37071d175d18eb303a73a79916848d8",
            "sha256:16695a3a00062961220ed6f18b64cfd35358523af07e29a8883d0cafa5c96527",
            "sha256:a59e5a6ab44c1b2ed1afea4e2f931ef547f4bf63c6fdd8285b67fe8a5a2ce99f",
            "sha256:9036d1e8e0173202f37107495ca936ea7212936b6ee822bc0b9382e486a99e3d",
            "sha256:ee290c784570e9d71576d06e5c05cb1174d72c1c2b280d4cfa8018ccda0fed88",
            "sha256:b0a7804131f6cd5ae9b6527379c0a374fa76e960f2201e4d3dd2df94bb3cdde6",
            "sha256:2e640983d7088266c796b233ed6c949e118a8b043108b1e3c98e74413fec2383",
            "sha256:a9ae95a9e54ee4eeb73c72bf88e5d799274f94daa6f984924531d12633469129",
            "sha256:02b18ec11a49495185b7cef99d3ed5a332123c17fd699a460cbd7bfda57d0cae",
            "sha256:1a0a0799c42ce65f726c5454d3d6656b80dd854dbb05747e6d43f497e124535a",
            "sha256:93ce1cb27fbd99165639d00f5b8626d938ccf9de99aecbddb21c9a474eede731",
            "sha256:400961d21e828e6818ec762b1dcd997b800b49ed1ee29eb00b1e471b2a606d43",
            "sha256:a56dbb6f819a457d81aea41e220592ccb882ac65beeac9dd4e8c9eb55df5d0a3"
        ]
    },
    "Metadata": {
        "LastTagTime": "0001-01-01T00:00:00Z"
    }
}
]

Additional context Add any other context about the problem here.

Just had another review of the logs and the updates seem to be working mostly

md manage:   INFO:2021-11-11 23h46.16 utc:6153: OSP service has different VT status (version 202111111129) from database (version 202110
221034, 77259 VTs). Starting update ...
md manage:   INFO:2021-11-11 23h46.16 utc:6152: update_scap: Updating data from feed
md manage:   INFO:2021-11-11 23h46.16 utc:6152: Updating CPEs
md manage:   INFO:2021-11-11 23h47.06 utc:6153: Updating VTs in database ... 312 new VTs, 152 changed VTs
md manage:WARNING:2021-11-11 23h47.07 utc:6153: update_nvts_from_vts: SHA-256 hash of the VTs in the database (540d7b2ba8df1074cac155c9e
c601dc0ee7a588bd883cd9200f145ab07de2110) does not match the one from the scanner (e6dbf5c420c5ff579f37ab8c13308d45f3e59699d23e838afc63cc
1def12d24d).
md   main:MESSAGE:2021-11-11 23h47.07 utc:6153: Rebuilding all NVTs because of a hash value mismatch
md manage:   INFO:2021-11-11 23h48.50 utc:6152: Updating /var/lib/gvm/scap-data/nvdcve-2.0-2004.xml
md manage:   INFO:2021-11-11 23h48.56 utc:6152: Updating /var/lib/gvm/scap-data/nvdcve-2.0-2003.xml
...

Some issues still seem to occur and filling up the logs, or better said the docker logs (The log facility is not working as expected)

<28>Nov 12 07:46:24 greenbone-nvt-sync: The log facility is not working as expected. All messages will be written to the standard error stream.
<29>Nov 12 07:46:24 greenbone-nvt-sync: No Greenbone Security Feed access key found, falling back to Greenbone Community Feed
<29>Nov 12 07:46:29 greenbone-nvt-sync: Configured NVT rsync feed: rsync://feed.community.greenbone.net:/nvt-feed
rsync: [Receiver] failed to connect to feed.community.greenbone.net (45.135.106.143): Operation timed out (110)
rsync: [Receiver] failed to connect to feed.community.greenbone.net (2a0e:6b40:20:106:20c:29ff:fe7f:d2ae): Address not available (99)
rsync error: error in socket IO (code 10) at clientserver.c(137) [Receiver=3.2.3]
<27>Nov 12 07:47:00 greenbone-nvt-sync: rsync failed.
Updating GVMd data...
rsync: [Receiver] failed to connect to feed.community.greenbone.net (45.135.106.143): Operation timed out (110)
rsync: [Receiver] failed to connect to feed.community.greenbone.net (2a0e:6b40:20:106:20c:29ff:fe7f:d2ae): Address not available (99)
rsync error: error in socket IO (code 10) at clientserver.c(137) [Receiver=3.2.3]
Updating SCAP data...
rsync: [Receiver] failed to connect to feed.community.greenbone.net (45.135.106.143): Operation timed out (110)
rsync: [Receiver] failed to connect to feed.community.greenbone.net (2a0e:6b40:20:106:20c:29ff:fe7f:d2ae): Address not available (99)
rsync error: error in socket IO (code 10) at clientserver.c(137) [Receiver=3.2.3]
Updating CERT data...
rsync: [Receiver] failed to connect to feed.community.greenbone.net (45.135.106.143): Operation timed out (110)
rsync: [Receiver] failed to connect to feed.community.greenbone.net (2a0e:6b40:20:106:20c:29ff:fe7f:d2ae): Address not available (99)
rsync error: error in socket IO (code 10) at clientserver.c(137) [Receiver=3.2.3]
2021-11-12 07:49:04,836 INFO exited: GVMUpdate (exit status 0; expected)
2021-11-12 07:49:05,839 INFO spawned: 'GVMUpdate' with pid 15942
2021-11-12 07:49:15,853 INFO success: GVMUpdate entered RUNNING state, process has stayed up for > than 10 seconds (startsecs)

Based on the Information, that the community feeds are only updated once a day and greenbone-nvt-sync seems to be triggered every ~ 8 hours, there might be some server side protection mechanisms in place which are causing this one. But this is just a wild guess, but nevertheless out of scope of this Bug report.

Once #297 is merged, I think we should be good to close this Issue. :1st_place_medal:

Secure-Compliance-Solutions-LLC / GVM-Docker

[Bug] Feed update issues #293