libgvm util g_message end up in stdout

[k3v3n]

Expected behavior

libgvm util g_message should be written to the configure log file from the gvmd_log.conf.

Starting Greenbone Vulnerability Manager...
libgvm util-Message: 14:57:14.268: Updated NVT cache from version 0 to 202204271008

Actual behavior

libgvm util g_message are written to stdout.

Steps to reproduce

Launch gvmd process with the following gvmd_log.conf:

[libgvm util]
prepend=%t %s %p
separator=:
prepend_time_format=%Y-%m-%d %Hh%M.%S %Z
file=/var/log/gvm/gvmd.log
level=64

GVM versions

gvm: (gvmd --version)

Greenbone Vulnerability Manager 21.4.5

openvas: (openvas --version)

OpenVAS 21.4.4

gvm-libs:

gvm-libs 21.4.4

Environment

Operating system:

Linux 41eef60f8f57 5.10.104-linuxkit #1 SMP Thu Mar 17 17:08:06 UTC 2022 x86_64 x86_64 x86_64 GNU/Linux

root@41eef60f8f57:/home/delve/warden/src# cat /etc/lsb-release
DISTRIB_ID=Ubuntu
DISTRIB_RELEASE=20.04
DISTRIB_CODENAME=focal
DISTRIB_DESCRIPTION="Ubuntu 20.04.4 LTS"

Installation method / source: (packages, source installation)

Logfiles

md   main:MESSAGE:2022-04-29 14h46.17 utc:157:    Greenbone Vulnerability Manager version 21.4.5 (DB revision 242)
md manage:   INFO:2022-04-29 14h46.17 utc:157:    Getting users.
md manage:WARNING:2022-04-29 14h46.17 utc:157: sql_exec_internal: PQexec failed: ERROR:  relation "public.meta" does not exist
LINE 1: SELECT value FROM public.meta WHERE name = 'database_version...
                          ^
 (7)
md manage:WARNING:2022-04-29 14h46.17 utc:157: sql_exec_internal: SQL: SELECT value FROM public.meta WHERE name = 'database_version';
md manage:WARNING:2022-04-29 14h46.17 utc:157: sql_x: sql_exec_internal failed
md manage:MESSAGE:2022-04-29 14h46.17 utc:157: No SCAP database found
md manage:MESSAGE:2022-04-29 14h46.17 utc:157: No CERT database found
md   main:MESSAGE:2022-04-29 14h46.20 utc:162:    Greenbone Vulnerability Manager version 21.4.5 (DB revision 242)
md manage:   INFO:2022-04-29 14h46.20 utc:162:    Modifying setting.
md manage:MESSAGE:2022-04-29 14h46.20 utc:162: No SCAP database found
md manage:MESSAGE:2022-04-29 14h46.20 utc:162: No CERT database found
md   main:MESSAGE:2022-04-29 14h46.21 utc:165:    Greenbone Vulnerability Manager version 21.4.5 (DB revision 242)
md manage:   INFO:2022-04-29 14h46.21 utc:165:    Getting users.
md manage:MESSAGE:2022-04-29 14h46.21 utc:165: No SCAP database found
md manage:MESSAGE:2022-04-29 14h46.21 utc:165: No CERT database found
md   main:MESSAGE:2022-04-29 14h46.22 utc:169:    Greenbone Vulnerability Manager version 21.4.5 (DB revision 242)
md manage:   INFO:2022-04-29 14h46.22 utc:169:    Creating user.
md manage:MESSAGE:2022-04-29 14h46.22 utc:169: No SCAP database found
md manage:MESSAGE:2022-04-29 14h46.22 utc:169: No CERT database found
md   main:MESSAGE:2022-04-29 14h46.22 utc:172:    Greenbone Vulnerability Manager version 21.4.5 (DB revision 242)
md manage:MESSAGE:2022-04-29 14h46.22 utc:173: No SCAP database found
md manage:MESSAGE:2022-04-29 14h46.22 utc:173: No CERT database found
libgvm util:   INFO:2022-04-29 14h46.23 utc:173: starting key generation ...
libgvm util:   INFO:2022-04-29 14h46.23 utc:173: OpenPGP key 'GVM Credential Encryption' has been generated
md manage:   INFO:2022-04-29 14h46.23 utc:206: osp_scanner_feed_version: failed to get scanner_feed_version. OSPd OpenVAS is still starting
md manage:WARNING:2022-04-29 14h46.23 utc:205: update_scap: No SCAP db present, rebuilding SCAP db from scratch
md manage:   INFO:2022-04-29 14h46.23 utc:207: Initializing CERT database
md manage:   INFO:2022-04-29 14h46.23 UTC:207: sync_cert: Updating data from feed
md manage:   INFO:2022-04-29 14h46.23 UTC:207: update_dfn_xml: dfn-cert-2008.xml
md manage:   INFO:2022-04-29 14h46.23 UTC:207: Updating /var/lib/gvm/cert-data/dfn-cert-2008.xml
md manage:   INFO:2022-04-29 14h46.23 UTC:207: update_dfn_xml: dfn-cert-2020.xml
md manage:   INFO:2022-04-29 14h46.23 UTC:207: Updating /var/lib/gvm/cert-data/dfn-cert-2020.xml
md manage:   INFO:2022-04-29 14h46.23 utc:205: update_scap: Updating data from feed
md manage:   INFO:2022-04-29 14h46.23 utc:205: Updating CPEs
md manage:   INFO:2022-04-29 14h46.33 UTC:207: update_dfn_xml: dfn-cert-2021.xml
md manage:   INFO:2022-04-29 14h46.33 UTC:207: Updating /var/lib/gvm/cert-data/dfn-cert-2021.xml
md manage:   INFO:2022-04-29 14h46.42 UTC:207: update_dfn_xml: dfn-cert-2009.xml
md manage:   INFO:2022-04-29 14h46.42 UTC:207: Updating /var/lib/gvm/cert-data/dfn-cert-2009.xml
md manage:   INFO:2022-04-29 14h46.45 UTC:207: update_dfn_xml: dfn-cert-2022.xml
md manage:   INFO:2022-04-29 14h46.45 UTC:207: Updating /var/lib/gvm/cert-data/dfn-cert-2022.xml
md manage:   INFO:2022-04-29 14h46.48 UTC:207: update_dfn_xml: dfn-cert-2019.xml
md manage:   INFO:2022-04-29 14h46.48 UTC:207: Updating /var/lib/gvm/cert-data/dfn-cert-2019.xml
md manage:   INFO:2022-04-29 14h46.56 UTC:207: update_dfn_xml: dfn-cert-2018.xml
md manage:   INFO:2022-04-29 14h46.56 UTC:207: Updating /var/lib/gvm/cert-data/dfn-cert-2018.xml
md manage:   INFO:2022-04-29 14h47.07 UTC:207: update_dfn_xml: dfn-cert-2015.xml
md manage:   INFO:2022-04-29 14h47.07 UTC:207: Updating /var/lib/gvm/cert-data/dfn-cert-2015.xml
md manage:   INFO:2022-04-29 14h47.13 UTC:207: update_dfn_xml: dfn-cert-2014.xml
md manage:   INFO:2022-04-29 14h47.13 UTC:207: Updating /var/lib/gvm/cert-data/dfn-cert-2014.xml
md manage:   INFO:2022-04-29 14h47.18 UTC:207: update_dfn_xml: dfn-cert-2016.xml
md manage:   INFO:2022-04-29 14h47.18 UTC:207: Updating /var/lib/gvm/cert-data/dfn-cert-2016.xml
md manage:   INFO:2022-04-29 14h47.24 UTC:207: update_dfn_xml: dfn-cert-2017.xml
md manage:   INFO:2022-04-29 14h47.24 UTC:207: Updating /var/lib/gvm/cert-data/dfn-cert-2017.xml
md manage:   INFO:2022-04-29 14h47.30 UTC:207: update_dfn_xml: dfn-cert-2013.xml
md manage:   INFO:2022-04-29 14h47.30 UTC:207: Updating /var/lib/gvm/cert-data/dfn-cert-2013.xml
md manage:   INFO:2022-04-29 14h47.34 UTC:207: update_dfn_xml: dfn-cert-2012.xml
md manage:   INFO:2022-04-29 14h47.34 UTC:207: Updating /var/lib/gvm/cert-data/dfn-cert-2012.xml
md manage:   INFO:2022-04-29 14h47.37 UTC:207: update_dfn_xml: dfn-cert-2010.xml
md manage:   INFO:2022-04-29 14h47.37 UTC:207: Updating /var/lib/gvm/cert-data/dfn-cert-2010.xml
md manage:   INFO:2022-04-29 14h47.40 UTC:207: update_dfn_xml: dfn-cert-2011.xml
md manage:   INFO:2022-04-29 14h47.40 UTC:207: Updating /var/lib/gvm/cert-data/dfn-cert-2011.xml
md manage:   INFO:2022-04-29 14h47.43 UTC:207: Updating /var/lib/gvm/cert-data/CB-K13.xml
md manage:   INFO:2022-04-29 14h47.44 UTC:207: Updating /var/lib/gvm/cert-data/CB-K15.xml
md manage:   INFO:2022-04-29 14h47.48 UTC:207: Updating /var/lib/gvm/cert-data/CB-K14.xml
md manage:   INFO:2022-04-29 14h47.51 UTC:207: Updating /var/lib/gvm/cert-data/CB-K16.xml
md manage:   INFO:2022-04-29 14h47.57 UTC:207: Updating /var/lib/gvm/cert-data/CB-K17.xml
md manage:   INFO:2022-04-29 14h48.03 UTC:207: Updating /var/lib/gvm/cert-data/CB-K19.xml
md manage:   INFO:2022-04-29 14h48.06 UTC:207: Updating /var/lib/gvm/cert-data/CB-K18.xml
md manage:   INFO:2022-04-29 14h48.09 UTC:207: Updating /var/lib/gvm/cert-data/CB-K20.xml
md manage:   INFO:2022-04-29 14h48.13 UTC:207: Updating /var/lib/gvm/cert-data/CB-K21.xml
md manage:   INFO:2022-04-29 14h48.16 UTC:207: Updating /var/lib/gvm/cert-data/CB-K22.xml
md manage:   INFO:2022-04-29 14h48.17 UTC:207: SCAP database does not exist (yet), skipping CERT severity score update
md manage:   INFO:2022-04-29 14h48.17 UTC:207: sync_cert: Updating CERT info succeeded.
md manage:   INFO:2022-04-29 14h49.39 UTC:205: Updating /var/lib/gvm/scap-data/nvdcve-2.0-2019.xml
md manage:   INFO:2022-04-29 14h50.41 UTC:205: Updating /var/lib/gvm/scap-data/nvdcve-2.0-2018.xml
md manage:   INFO:2022-04-29 14h51.42 UTC:205: Updating /var/lib/gvm/scap-data/nvdcve-2.0-2008.xml
md manage:   INFO:2022-04-29 14h51.58 UTC:205: Updating /var/lib/gvm/scap-data/nvdcve-2.0-2020.xml
md manage:   INFO:2022-04-29 14h52.48 UTC:205: Updating /var/lib/gvm/scap-data/nvdcve-2.0-2021.xml
md manage:   INFO:2022-04-29 14h53.43 UTC:205: Updating /var/lib/gvm/scap-data/nvdcve-2.0-2009.xml
md manage:   INFO:2022-04-29 14h54.00 UTC:205: Updating /var/lib/gvm/scap-data/nvdcve-2.0-2022.xml
md manage:   INFO:2022-04-29 14h54.09 UTC:205: Updating /var/lib/gvm/scap-data/nvdcve-2.0-2013.xml
md manage:   INFO:2022-04-29 14h54.23 UTC:205: Updating /var/lib/gvm/scap-data/nvdcve-2.0-2007.xml
md manage:   INFO:2022-04-29 14h54.34 UTC:205: Updating /var/lib/gvm/scap-data/nvdcve-2.0-2006.xml
md manage:   INFO:2022-04-29 14h54.45 UTC:205: Updating /var/lib/gvm/scap-data/nvdcve-2.0-2012.xml
md manage:   INFO:2022-04-29 14h54.57 UTC:205: Updating /var/lib/gvm/scap-data/nvdcve-2.0-2004.xml
md manage:   INFO:2022-04-29 14h55.03 UTC:205: Updating /var/lib/gvm/scap-data/nvdcve-2.0-2010.xml
md manage:   INFO:2022-04-29 14h55.14 UTC:205: Updating /var/lib/gvm/scap-data/nvdcve-2.0-2011.xml
md manage:   INFO:2022-04-29 14h55.27 UTC:205: Updating /var/lib/gvm/scap-data/nvdcve-2.0-2005.xml
md manage:   INFO:2022-04-29 14h55.35 UTC:205: Updating /var/lib/gvm/scap-data/nvdcve-2.0-2015.xml
md manage:   INFO:2022-04-29 14h55.46 UTC:205: Updating /var/lib/gvm/scap-data/nvdcve-2.0-2014.xml
md manage:   INFO:2022-04-29 14h55.59 UTC:205: Updating /var/lib/gvm/scap-data/nvdcve-2.0-2016.xml
md manage:   INFO:2022-04-29 14h56.12 UTC:205: Updating /var/lib/gvm/scap-data/nvdcve-2.0-2002.xml
md manage:   INFO:2022-04-29 14h56.20 UTC:205: Updating /var/lib/gvm/scap-data/nvdcve-2.0-2003.xml
md manage:   INFO:2022-04-29 14h56.22 UTC:205: Updating /var/lib/gvm/scap-data/nvdcve-2.0-2017.xml
md manage:   INFO:2022-04-29 14h56.51 UTC:205: Updating OVAL data
md manage:   INFO:2022-04-29 14h56.57 UTC:205: Updating /var/lib/gvm/scap-data/oval/5.10/org.mitre.oval/c/oval.xml
md manage:   INFO:2022-04-29 14h56.57 UTC:205: Updating /var/lib/gvm/scap-data/oval/5.10/org.mitre.oval/m/oval.xml
md manage:   INFO:2022-04-29 14h56.57 UTC:205: Updating /var/lib/gvm/scap-data/oval/5.10/org.mitre.oval/v/family/ios.xml
md manage:   INFO:2022-04-29 14h56.57 UTC:205: Updating /var/lib/gvm/scap-data/oval/5.10/org.mitre.oval/v/family/pixos.xml
md manage:   INFO:2022-04-29 14h56.57 UTC:205: Updating /var/lib/gvm/scap-data/oval/5.10/org.mitre.oval/p/oval.xml
md manage:   INFO:2022-04-29 14h58.04 UTC:205: Updating /var/lib/gvm/scap-data/oval/5.10/org.mitre.oval/i/oval.xml
md manage:   INFO:2022-04-29 14h58.07 UTC:205: Updating /var/lib/gvm/scap-data/oval/5.10/org.mitre.oval/v/family/macos.xml
md manage:   INFO:2022-04-29 14h58.07 UTC:205: Updating /var/lib/gvm/scap-data/oval/5.10/org.mitre.oval/v/family/unix.xml
md manage:   INFO:2022-04-29 14h58.12 UTC:205: Updating /var/lib/gvm/scap-data/oval/5.10/org.mitre.oval/v/family/windows.xml
md manage:   INFO:2022-04-29 14h58.23 UTC:205: Updating user OVAL definitions.
md manage:   INFO:2022-04-29 14h58.23 UTC:205: Updating CVSS scores and CVE counts for CPEs
md manage:   INFO:2022-04-29 14h59.51 UTC:205: Updating CVSS scores for OVAL definitions
md manage:   INFO:2022-04-29 14h59.52 UTC:205: Updating placeholder CPEs
md manage:   INFO:2022-04-29 15h00.07 UTC:205: Updating Max CVSS for DFN-CERT
md manage:   INFO:2022-04-29 15h00.10 UTC:205: Updating DFN-CERT CVSS max succeeded.
md manage:   INFO:2022-04-29 15h00.10 UTC:205: Updating Max CVSS for CERT-Bund
md manage:   INFO:2022-04-29 15h00.12 UTC:205: Updating CERT-Bund CVSS max succeeded.
md manage:   INFO:2022-04-29 15h00.15 UTC:205: update_scap_end: Updating SCAP info succeeded
md manage:   INFO:2022-04-29 15h00.18 UTC:743: OSP service has different VT status (version 202204271008) from database (version (null), 0 VTs). Starting update ..

[cfi-gb]

with the following gvm_log.conf:

Is this a typo or have you really tried to configure this in a gvm_log.conf? Because there is no such file in GVM, only the following provides logging configuration for GVM:

• /etc/gvm/gsad_log.conf
• /etc/gvm/gvmd_log.conf
• /etc/openvas/openvas_log.conf

As the related Updated NVT cache from version 0 to 202204271008 message seems to be originating from the following:

gvm-libs/util/nvticache.c

Lines 192 to 210 in 9bb86d2

	nvticache_save (void)
	{
	char *feed_version, *old_version;
	if (cache_kb && !cache_saved)
	{
	kb_save (cache_kb);
	cache_saved = 1;
	}
	old_version = nvticache_feed_version ();
	feed_version = nvt_feed_version ();
	if (feed_version && g_strcmp0 (old_version, feed_version))
	{
	kb_item_set_str (cache_kb, NVTICACHE_STR, feed_version, 0);
	g_message ("Updated NVT cache from version %s to %s", old_version,
	feed_version);
	}
	g_free (old_version);
	g_free (feed_version);
	}

which is in turn only called within the scanner here:

https://github.com/greenbone/openvas-scanner/blob/1946740e7cb45d7bd01174d3f5f16dbea84c5b18/src/pluginload.c#L395

the configuration would need to be done in the openvas_log.conf.

[k3v3n]

Thank you. Indeed it was a typo that I fixed in my original comment. My config files are the followingf.

• /etc/gvm/gvmd_log.conf
• /etc/openvas/openvas_log.conf

Even though my openvas config contain the following

[sd   main]
prepend=%t %p
prepend_time_format=%Y-%m-%d %Hh%M.%S %Z
file=/var/log/gvm/openvas.log
level=64

The output of the scanner is always redirected to the stdout.

[Kraemii]

Hey @k3v3n
Sorry for the late feedback.
Is this all that is in your openvas_log.conf? Normally it contains a lot more than just the setting for main. The standard openvas_log.conf should look like:

[sd   main]
prepend=%t %s %p
separator=:
prepend_time_format=%Y-%m-%d %Hh%M.%S %Z
file=/var/log/gvm/openvas.log
level=127

[lib  misc]
prepend=%t %s %p
separator=:
prepend_time_format=%Y-%m-%d %Hh%M.%S %Z
file=/var/log/gvm/openvas.log
level=127

[lib  nasl]
prepend=%t %s %p
separator=:
prepend_time_format=%Y-%m-%d %Hh%M.%S %Z
file=/var/log/gvm/openvas.log
level=127

[libgvm base]
prepend=%t %s %p
separator=:
prepend_time_format=%Y-%m-%d %Hh%M.%S %Z
file=/var/log/gvm/openvas.log
level=127

[libgvm boreas]
prepend=%t %s %p
separator=:
prepend_time_format=%Y-%m-%d %Hh%M.%S %Z
file=/var/log/gvm/openvas.log
level=127

[libgvm util]
prepend=%t %s %p
separator=:
prepend_time_format=%Y-%m-%d %Hh%M.%S %Z
file=/var/log/gvm/openvas.log
level=127

[*]
prepend=%t %s %p
separator=:
prepend_time_format=%Y-%m-%d %Hh%M.%S %Z
file=/var/log/gvm/openvas.log
level=127

If no configuration for the corresponding log domain is given it will use the stdout by default.
The log domain for this specific information is libgvm util:

gvm-libs/util/nvticache.c

Line 47 in 9bb86d2

#define G_LOG_DOMAIN "libgvm util"

[mattmundell]

I'm closing this because it's old and seems to work for everyone else. Open again if you still have the issue @k3v3n. Might help to share your build commands.