On Thu, Jan 09, 2014 at 01:39:08PM +0000, Sven Kieske wrote:

Hi,

I also guess this gets so large because of the loglevels in /etc/vdsm/logger.conf

this seems to be the default:

[logger_root] level=DEBUG handlers=syslog,logfile propagate=0

[logger_vds] level=DEBUG handlers=syslog,logfile qualname=vds propagate=0

[logger_Storage] level=DEBUG handlers=logfile qualname=Storage propagate=0

[logger_metadata] level=WARNING handlers=metadata qualname=irs.metadata propagate=0

[handler_syslog] level=WARNING class=handlers.SysLogHandler formatter=sysform args=('/dev/log', handlers.SysLogHandler.LOG_USER)

[handler_logfile] class=logging.handlers.WatchedFileHandler args=('/var/log/vdsm/vdsm.log',) filters=storage.misc.TracebackRepeatFilter level=DEBUG formatter=long

[handler_metadata] class=logging.handlers.WatchedFileHandler args=('/var/log/vdsm/metadata.log',) level=WARNING formatter=long

which is "debug" level for most loggers.

Question to the devs:

Is this really needed as a default in a production environment?

my vdsm is a little bit older btw:

vdsm-4.12.1-4.el6.x86_64 vdsm-cli-4.12.1-4.el6.noarch vdsm-python-4.12.1-4.el6.x86_64 vdsm-python-cpopen-4.12.1-4.el6.x86_64 vdsm-xmlrpc-4.12.1-4.el6.noarch

did this change in vdsm 4.13. ?

No change yet.

Am 09.01.2014 14:26, schrieb Karli Sjöberg:

...

Hi!

I just noticed my Hypervisor nodes starting to complain about disks almost being full. I started investigation and noticed that: # du -h /var/log/libvirtd.log 100G /var/log/libvirtd.log

And many Hosts system partition had indeed become full:S

Why weren´t the file rotated? Well: # ls -lah /var/log/libvirtd.log.* | wc -l 100

And the rotate policy says: /etc/logrotate.d/libvirtd ## beginning of configuration section by vdsm /var/log/libvirt/libvirtd.log { rotate 100 missingok copytruncate size 15M compress compresscmd /usr/bin/xz uncompresscmd /usr/bin/unxz compressext .xz }

Now, I just handled it by changing "100" to "1000" but I think that a

I do not understand this issue, Karli. After 100 log files have been created, the oldest one should have been removed and replaced by the newest one. logrotate is expected to be called every 15 minutes, so it should not have stayed above 15M for so long. Do you see any error when running `/usr/sbin/logrotate /etc/logrotate.d/libvirtd` as root?

...

better default needs to be placed in general, don´t you? # rpm -qa | grep vdsm vdsm-python-4.13.0-11.el6.x86_64 vdsm-python-cpopen-4.13.0-11.el6.x86_64 vdsm-4.13.0-11.el6.x86_64 vdsm-xmlrpc-4.13.0-11.el6.noarch vdsm-cli-4.13.0-11.el6.noarch

The question of how much logging we should keep is a tough one. I, as a developer, would like to have as much as possible. For long-running busy systems, it has happened to me that the core bug was spotted in vdsm.log.67 or so. However, I understand that verbosity has its price. To understand whether we are stable enough to change the defaults, I need volunteers: people who are willing to change their log level to INFO or WARNING, and see if they miss useful information from their logs. When you make you log level higher, you can lower the number of kept log files, as they would not be filled as quick. Would you, users@, help me with hard data? Dan.

________________________________________ Från: users-bounces@ovirt.org [users-bounces@ovirt.org] för Karli Sjöberg [Karli.Sjoberg@slu.se] Skickat: den 9 januari 2014 17:53 Till: Dan Kenigsberg; Sven Kieske Kopia: users@ovirt.org Ämne: Re: [Users] VSDM´s logrotate makes Hosts fill up var eventually ________________________________________ Från: users-bounces@ovirt.org [users-bounces@ovirt.org] för Dan Kenigsberg [danken@redhat.com] Skickat: den 9 januari 2014 17:33 Till: Sven Kieske Kopia: users@ovirt.org Ämne: Re: [Users] VSDM´s logrotate makes Hosts fill up var eventually On Thu, Jan 09, 2014 at 01:39:08PM +0000, Sven Kieske wrote:

Hi,

I also guess this gets so large because of the loglevels in /etc/vdsm/logger.conf

this seems to be the default:

[logger_root] level=DEBUG handlers=syslog,logfile propagate=0

[logger_vds] level=DEBUG handlers=syslog,logfile qualname=vds propagate=0

[logger_Storage] level=DEBUG handlers=logfile qualname=Storage propagate=0

[logger_metadata] level=WARNING handlers=metadata qualname=irs.metadata propagate=0

[handler_syslog] level=WARNING class=handlers.SysLogHandler formatter=sysform args=('/dev/log', handlers.SysLogHandler.LOG_USER)

[handler_logfile] class=logging.handlers.WatchedFileHandler args=('/var/log/vdsm/vdsm.log',) filters=storage.misc.TracebackRepeatFilter level=DEBUG formatter=long

[handler_metadata] class=logging.handlers.WatchedFileHandler args=('/var/log/vdsm/metadata.log',) level=WARNING formatter=long

which is "debug" level for most loggers.

Question to the devs:

Is this really needed as a default in a production environment?

my vdsm is a little bit older btw:

vdsm-4.12.1-4.el6.x86_64 vdsm-cli-4.12.1-4.el6.noarch vdsm-python-4.12.1-4.el6.x86_64 vdsm-python-cpopen-4.12.1-4.el6.x86_64 vdsm-xmlrpc-4.12.1-4.el6.noarch

did this change in vdsm 4.13. ?

No change yet.

Am 09.01.2014 14:26, schrieb Karli Sjöberg:

...

Hi!

I just noticed my Hypervisor nodes starting to complain about disks almost being full. I started investigation and noticed that: # du -h /var/log/libvirtd.log 100G /var/log/libvirtd.log

And many Hosts system partition had indeed become full:S

Why weren´t the file rotated? Well: # ls -lah /var/log/libvirtd.log.* | wc -l 100

And the rotate policy says: /etc/logrotate.d/libvirtd ## beginning of configuration section by vdsm /var/log/libvirt/libvirtd.log { rotate 100 missingok copytruncate size 15M compress compresscmd /usr/bin/xz uncompresscmd /usr/bin/unxz compressext .xz }

Now, I just handled it by changing "100" to "1000" but I think that a

I do not understand this issue, Karli. After 100 log files have been created, the oldest one should have been removed and replaced by the newest one. logrotate is expected to be called every 15 minutes, so it should not have stayed above 15M for so long. Do you see any error when running `/usr/sbin/logrotate /etc/logrotate.d/libvirtd` as root? What the funk, it doesn´t do anything, complains nothing like it´s done what it´s supposed to, and no errors in "/var/log/messages" either... Oh, and here´s the output: # du -h /var/log/libvirtd.log 1.1G /var/log/libvirtd.log # /usr/sbin/logrotate -d -v /etc/logrotate.d/libvirtd reading config file /etc/logrotate.d/libvirtd reading config info for /var/log/libvirt/libvirtd.log compress_prog is now /usr/bin/xz uncompress_prog is now /usr/bin/unxz compress_ext is now .xz Handling 1 logs rotating pattern: /var/log/libvirt/libvirtd.log 15728640 bytes (1000 rotations) empty log files are rotated, old logs are removed considering log /var/log/libvirt/libvirtd.log log does not need rotating Really, are you sure about that? /K

...

better default needs to be placed in general, don´t you? # rpm -qa | grep vdsm vdsm-python-4.13.0-11.el6.x86_64 vdsm-python-cpopen-4.13.0-11.el6.x86_64 vdsm-4.13.0-11.el6.x86_64 vdsm-xmlrpc-4.13.0-11.el6.noarch vdsm-cli-4.13.0-11.el6.noarch

The question of how much logging we should keep is a tough one. I, as a developer, would like to have as much as possible. For long-running busy systems, it has happened to me that the core bug was spotted in vdsm.log.67 or so. However, I understand that verbosity has its price. To understand whether we are stable enough to change the defaults, I need volunteers: people who are willing to change their log level to INFO or WARNING, and see if they miss useful information from their logs. When you make you log level higher, you can lower the number of kept log files, as they would not be filled as quick. Would you, users@, help me with hard data? Well, I understand that having more data of course helps when there´s an issue, however having lots of data isn´t helping in this particular case;P Seriously though, it´s not bothering me having lots of logs. I don´t mind the DEBUG mode, and as long as rotate _does what it´s supposed to_ (but that´s besides the point) it´s not taking up that much space to argue about either so for me it´s cool (normally). Dan. _______________________________________________ Users mailing list Users@ovirt.org http://lists.ovirt.org/mailman/listinfo/users _______________________________________________ Users mailing list Users@ovirt.org http://lists.ovirt.org/mailman/listinfo/users

Hi Sven Skickat från min iPhone

9 jan 2014 kl. 18:23 skrev "Sven Kieske" <S.Kieske@mittwald.de>:

Hi Karli,

no offense, but, please do use proper quoting (well, any quoting at all :-) ), I can not see what yoou did write in your second mail and what's quoted from Dan.

I know, I know, it's that stupid M$ exchange webmail that refuses to indent anything:( Only using it from home when I absolutely have to. /K

Thank you! -- Mit freundlichen Grüßen / Regards

Sven Kieske

Systemadministrator Mittwald CM Service GmbH & Co. KG Königsberger Straße 6 32339 Espelkamp T: +49-5772-293-100 F: +49-5772-293-333 https://www.mittwald.de Geschäftsführer: Robert Meyer St.Nr.: 331/5721/1033, USt-IdNr.: DE814773217, HRA 6640, AG Bad Oeynhausen Komplementärin: Robert Meyer Verwaltungs GmbH, HRB 13260, AG Bad Oeynhausen _______________________________________________ Users mailing list Users@ovirt.org http://lists.ovirt.org/mailman/listinfo/users

On Fri, 2014-01-10 at 12:23 +0000, Dan Kenigsberg wrote:

On Thu, Jan 09, 2014 at 05:01:12PM +0000, Karli Sjöberg wrote:

...

...

...

And the rotate policy says: /etc/logrotate.d/libvirtd ## beginning of configuration section by vdsm /var/log/libvirt/libvirtd.log { rotate 100 missingok copytruncate size 15M compress compresscmd /usr/bin/xz uncompresscmd /usr/bin/unxz compressext .xz }

Now, I just handled it by changing "100" to "1000" but I think that a

I do not understand this issue, Karli. After 100 log files have been created, the oldest one should have been removed and replaced by the newest one. logrotate is expected to be called every 15 minutes, so it should not have stayed above 15M for so long. Do you see any error when running `/usr/sbin/logrotate /etc/logrotate.d/libvirtd` as root?

What the funk, it doesn´t do anything, complains nothing like it´s done what it´s supposed to, and no errors in "/var/log/messages" either...

Oh, and here´s the output: # du -h /var/log/libvirtd.log 1.1G /var/log/libvirtd.log # /usr/sbin/logrotate -d -v /etc/logrotate.d/libvirtd reading config file /etc/logrotate.d/libvirtd reading config info for /var/log/libvirt/libvirtd.log compress_prog is now /usr/bin/xz uncompress_prog is now /usr/bin/unxz compress_ext is now .xz

Handling 1 logs

rotating pattern: /var/log/libvirt/libvirtd.log 15728640 bytes (1000 rotations) empty log files are rotated, old logs are removed considering log /var/log/libvirt/libvirtd.log log does not need rotating

Really, are you sure about that?

/K

I really do not know what to say - it seems like an awkward logrotate bug. Maybe if you play with arguments a bit (avoid compression? change size?) it could be convinced to work. Otherwise it sounds like gdb time...

Ah man, now I see it, it´s not rotating the right file, look: # grep libvirtd /etc/logrotate.d/libvirtd /var/log/libvirt/libvirtd.log { # grep libvirtd.log /etc/libvirt/libvirtd.conf log_outputs="1:file:/var/log/libvirtd.log" Bug? -- Med Vänliga Hälsningar ------------------------------------------------------------------------------- Karli Sjöberg Swedish University of Agricultural Sciences Box 7079 (Visiting Address Kronåsvägen 8) S-750 07 Uppsala, Sweden Phone: +46-(0)18-67 15 66 karli.sjoberg@slu.se

On Fri, Jan 10, 2014 at 2:04 PM, Markus Stockhausen wrote:

...

Ah man, now I see it, it´s not rotating the right file, look: # grep libvirtd /etc/logrotate.d/libvirtd /var/log/libvirt/libvirtd.log { # grep libvirtd.log /etc/libvirt/libvirtd.conf log_outputs="1:file:/var/log/libvirtd.log"

Bug?

I would say no - at least for Fedora 19 nodes. In our environment (3.3.2) /var/log/libvirtd.log does not exist and everything is smoothly rotating in directory /var/log/libvirt

Maybe /var/log/libvirtd.log is an old file?

Markus

In its default config for my f19 nodes, the logging section of libvirtd is empty and no other customization in /etc/sysconfig/libvirtd regaridng log files; so based on log location and contents, it seems it defaults to "debug" level, such as: log_outputs="1:file:/var/log/libvirt/libvirtd.log" So you can comment out your line or put the one above. Or put other numerical numbers if you want a different level: # 1: DEBUG # 2: INFO # 3: WARNING # 4: ERROR Gianluca

On Fri, 2014-01-10 at 13:24 +0000, Sven Kieske wrote:

I got:

/var/log/libvirt/libvirtd.log

grep libvirtd.log /etc/libvirt/libvirtd.conf log_outputs="1:file:/var/log/libvirt/libvirtd.log"

on my centos 6.4 node

vdsm version as stated in my first mail in this thread.

Mmm, that´s strange; one, and only one of my Hosts have: log_outputs="1:file:/var/log/libvirt/libvirtd.log" And the rest all have: log_outputs="1:file:/var/log/libvirtd.log" I´ve compared versions of both vdsm and libvirt, and they are the same on all of them. ?

Am 10.01.2014 14:04, schrieb Markus Stockhausen:

...

...

Ah man, now I see it, it´s not rotating the right file, look: # grep libvirtd /etc/logrotate.d/libvirtd /var/log/libvirt/libvirtd.log { # grep libvirtd.log /etc/libvirt/libvirtd.conf log_outputs="1:file:/var/log/libvirtd.log"

Bug?

I would say no - at least for Fedora 19 nodes. In our environment (3.3.2) /var/log/libvirtd.log does not exist and everything is smoothly rotating in directory /var/log/libvirt

Maybe /var/log/libvirtd.log is an old file?

Markus

-- Mit freundlichen Grüßen / Regards

Sven Kieske

Systemadministrator Mittwald CM Service GmbH & Co. KG Königsberger Straße 6 32339 Espelkamp T: +49-5772-293-100 F: +49-5772-293-333 https://www.mittwald.de Geschäftsführer: Robert Meyer St.Nr.: 331/5721/1033, USt-IdNr.: DE814773217, HRA 6640, AG Bad Oeynhausen Komplementärin: Robert Meyer Verwaltungs GmbH, HRB 13260, AG Bad Oeynhausen _______________________________________________ Users mailing list Users@ovirt.org http://lists.ovirt.org/mailman/listinfo/users

-- Med Vänliga Hälsningar ------------------------------------------------------------------------------- Karli Sjöberg Swedish University of Agricultural Sciences Box 7079 (Visiting Address Kronåsvägen 8) S-750 07 Uppsala, Sweden Phone: +46-(0)18-67 15 66 karli.sjoberg@slu.se

On Jan 9, 2014, at 10:33 AM, Dan Kenigsberg <danken@redhat.com> wrote:

The question of how much logging we should keep is a tough one. I, as a developer, would like to have as much as possible. For long-running busy systems, it has happened to me that the core bug was spotted in vdsm.log.67 or so.

However, I understand that verbosity has its price. To understand whether we are stable enough to change the defaults, I need volunteers: people who are willing to change their log level to INFO or WARNING, and see if they miss useful information from their logs.

When you make you log level higher, you can lower the number of kept log files, as they would not be filled as quick.

Would you, users@, help me with hard data?

I played with turning the verbosity down and keeping fewer logs, but in the end I wound up adjusting the drive layout on my nodes (running centos with vdsdm added, not “pure” ovirt nodes). If a VM crashes and leaves cores, I can run into problem, but monitoring alerts me and I can take action. It does seem a bit much though, maybe an easy switch in the GUI to allow setting it to DEBUG when needed, and start off at WARNING for my production nodes? I think this feeling is in part because it takes a bit of work me, an experienced power admin but not developer, to dig stuff out of the logs myself, and most of it is not useful to me. So the volume is a bit much. Of course, like all logs, they’re invaluable sometimes, and you never know when you’ll need them, so… -Darrell

On Thu, Jan 9, 2014 at 5:33 PM, Dan Kenigsberg wrote:

The question of how much logging we should keep is a tough one. I, as a developer, would like to have as much as possible. For long-running busy systems, it has happened to me that the core bug was spotted in vdsm.log.67 or so.

However, I understand that verbosity has its price. To understand whether we are stable enough to change the defaults, I need volunteers: people who are willing to change their log level to INFO or WARNING, and see if they miss useful information from their logs.

When you make you log level higher, you can lower the number of kept log files, as they would not be filled as quick.

Would you, users@, help me with hard data?

Dan.

I can't tell about missing information because at the moment I didn't had big problmes since in my case I put logging to INFO where there was DEBUG on 17 December for both vdsm and supervdsm. This is a very calm infra composed by two nodes f19 oVirt 3.3.2 stable repo and GlusterFS datcenter. Only 3 VMS running about everytime Rotation has not yet overwritten old log files Under /var/log/vdsm now # du -sh . 137M . # ll supervdsm.log*|wc -l 106 # ll vdsm.log*|wc -l 113 For vdsm logs: before I had 5 daily generated files for an overall of about 100Mb uncompressed, now one file per day of about 14Mb uncompressed A newer log -rw-r--r--. 1 vdsm kvm 429380 Jan 7 12:00 vdsm.log.1.xz A before change log sequence -rw-r--r--. 1 vdsm kvm 660280 Dec 8 22:01 vdsm.log.36.xz -rw-r--r--. 1 vdsm kvm 659672 Dec 8 17:01 vdsm.log.37.xz -rw-r--r--. 1 vdsm kvm 662584 Dec 8 12:01 vdsm.log.38.xz -rw-r--r--. 1 vdsm kvm 655232 Dec 8 07:01 vdsm.log.39.xz -rw-r--r--. 1 vdsm kvm 657832 Dec 8 02:00 vdsm.log.40.xz For supervdsm logs no rotation yet after change, because size is set to 15M in logrotate conf files: Before change I had one file a day (uncompressed daily size was about 17-20Mb) # ls -lt super* -rw-r--r--. 1 root root 12620463 Jan 7 12:57 supervdsm.log -rw-r--r--. 1 root root 342736 Dec 16 16:01 supervdsm.log.1.xz -rw-r--r--. 1 root root 328952 Dec 15 14:00 supervdsm.log.2.xz -rw-r--r--. 1 root root 343360 Dec 14 13:01 supervdsm.log.3.xz -rw-r--r--. 1 root root 339244 Dec 13 11:00 supervdsm.log.4.xz -rw-r--r--. 1 root root 349012 Dec 12 09:00 supervdsm.log.5.xz I got a problem with SPM on 7 anuary and I correctly found in vdsm.log Thread-7000::INFO::2014-01-07 15:42:52,632::logUtils::44::dispatcher::(wrapper) Run and protect: disconnectStorageServer(domType=7, sp UUID='eb679feb-4da2-4fd0-a185-abbe459ffa70', conList=[{'port': '', 'connection': 'f18ovn01.mydomain:gvdata', 'iqn': '', 'portal' : '', 'user': '', 'vfs_type': 'glusterfs', 'password': '******', 'id': '9d01b8fa-853e-4720-990b-f86bdb7cfcbb'}], options=None) Thread-7001::INFO::2014-01-07 15:42:54,776::logUtils::44::dispatcher::(wrapper) Run and protect: getAllTasksStatuses(spUUID=None, opti ons=None) Thread-7001::ERROR::2014-01-07 15:42:54,777::task::850::TaskManager.Task::(_setError) Task=`2e948a29-fdaa-4049-ada4-421c6407b037`::Une xpected error Traceback (most recent call last): File "/usr/share/vdsm/storage/task.py", line 857, in _run return fn(*args, **kargs) File "/usr/share/vdsm/logUtils.py", line 45, in wrapper res = f(*args, **kwargs) File "/usr/share/vdsm/storage/hsm.py", line 2109, in getAllTasksStatuses raise se.SpmStatusError() SpmStatusError: Not SPM: () Thread-7001::INFO::2014-01-07 15:42:54,777::task::1151::TaskManager.Task::(prepare) Task=`2e948a29-fdaa-4049-ada4-421c6407b037`::abort ing: Task is aborted: 'Not SPM' - code 654 Thread-7001::ERROR::2014-01-07 15:42:54,778::dispatcher::67::Storage.Dispatcher.Protect::(run) {'status': {'message': 'Not SPM: ()', ' code': 654}} So I think it is good for me, otherwise I would have great difficulties identifying problems inside the big files produced Gianluca