Almost all program that send log lines to syslog uses the format: <PROGRAM>[<PID>]: <MESSAGE> vdsm is one of the few that don't follows this convention: vdsm <QUALIFIER> <LEVEL> <MESSAGE> I see qualifier being vds, MOM in some lines. both qualifier and level can be managed as being custom part of the MESSAGE. But instead of the single 'vdsm' string, 'vdsm<pid>:' would be much better, to make parsing of syslogline easier.
We don't send logs to syslog, but to vdsm.log - does it go to syslog for some reason?
I have log lines like: vdsm root WARN File: /var/lib/libvirt/qemu/channels/61a6de0a-2a21-4e90-bc20-29e3f0cd0ad8.com.redhat.rhevm.vdsm already removed vdsm throttled WARN MOM not available. vdsm jsonrpc.JsonRpcServer ERROR Internal server error#012Traceback (most recent call last):#012 File "/usr/lib/python2.7/site-packages/yajsonrpc/__init__.py", line 572, in _handle_request#012 res = method(**params)#012 File "/usr/lib/python2.7/site-packages/vdsm/rpc/Bridge.py", line 202, in _dynamicMethod#012 result = fn(*methodArgs)#012 File "/usr/share/vdsm/API.py", line 1454, in getAllVmIoTunePolicies#012 io_tune_policies_dict = self._cif.getAllVmIoTunePolicies()#012 File "/usr/share/vdsm/clientIF.py", line 448, in getAllVmIoTunePolicies#012 'current_values': v.getIoTune()}#012 File "/usr/share/vdsm/virt/vm.py", line 2811, in getIoTune#012 result = self.getIoTuneResponse()#012 File "/usr/share/vdsm/virt/vm.py", line 2830, in getIoTuneResponse#012 res = self._dom.blockIoTune(#012 File "/usr/lib/python2.7/site-packages/vdsm/virt/virdomain.py", line 47, in __getattr__#012 % self.vmid)#012NotConnectedError: VM u'7ea10f81-9869-434c-a268-ae7041abbea3' was not started yet or was shut down I see those kind of line on almost all my host.
We have been using syslog since http://gerrit.ovirt.org/4247 and it has been a mess since then. A serious cleanup must be done regarding what we log, where and how. But the minor tweak requested by Fabrice is doable.
We are forwarding only warnings and above to syslog and we have defined following format: vdsm %(name)s %(levelname)s %(message)s everything before vdsm is added automatically by syslog. So aren't we following the correct format? vdsm <QUALIFIER> <LEVEL> <MESSAGE> Example from above mentioned error messages: vdsm jsonrpc.JsonRpcServer ERROR Internal server error#012Traceback .... vdsm root WARN File: ... vdsm throttled WARN MOM not available. So the only thing missing is PID. Yaniv, is it possible to add it to syslog message only?
It should be vdsm[<PID>]:, don't forget the :
We are using default python package to report to syslog. I didn't touch the format, but we ofcourse can tweak it and change to whatever we desire. we use it very rarely - before we set up the logger in vdsm/vdsm and in vdsm-tool failure when module fails to be loaded. The pid is not much relevant, as just after we post the log we crash automatically.. so I don't see any advantage here
Apparently I missed the print that you posted in comment #2 - you're totally right, we have syslog formatter in our logger.conf which reports WARN and higher vds and root logs in the format - vdsm %(name)s %(levelname)s %(message)s As I said in comment #6 we also have direct call to syslog when the logger is not available - this will be redundant to change. The former can be modified easily to vdsm[%(process)d]: %(levelname)s %(message)s I'll post a patch for that for 4.2
ok, vdsm-4.20.3-198.git58f6f40.el7.centos.x86_64 # egrep 'vdsm\[[[:digit:]]+\]:' /var/log/messages | tail -n 5 Oct 27 12:39:57 10-37-138-251 vdsm[14528]: WARN cannot read eth0 speed Oct 27 12:40:12 10-37-138-251 vdsm[14528]: WARN cannot read eth0 speed Oct 27 12:40:27 10-37-138-251 vdsm[14528]: WARN cannot read eth0 speed Oct 27 12:40:42 10-37-138-251 vdsm[14528]: WARN cannot read eth0 speed Oct 27 12:40:57 10-37-138-251 vdsm[14528]: WARN cannot read eth0 speed # grep WARN /var/log/vdsm/vdsm.log | tail -n 5 2017-10-27 12:39:57,475+0200 WARN (periodic/3) [root] cannot read eth0 speed (nic:41) 2017-10-27 12:40:12,517+0200 WARN (periodic/2) [root] cannot read eth0 speed (nic:41) 2017-10-27 12:40:27,568+0200 WARN (periodic/2) [root] cannot read eth0 speed (nic:41) 2017-10-27 12:40:42,623+0200 WARN (periodic/1) [root] cannot read eth0 speed (nic:41) 2017-10-27 12:40:57,668+0200 WARN (periodic/0) [root] cannot read eth0 speed (nic:41)
This bugzilla is included in oVirt 4.2.0 release, published on Dec 20th 2017. Since the problem described in this bug report should be resolved in oVirt 4.2.0 release, published on Dec 20th 2017, it has been closed with a resolution of CURRENT RELEASE. If the solution does not work for you, please open a new bug report.