How does the logging work?

Development
1

Hi,
I added a simple little ipmi fencing mechanism to /var/lib/one/remotes/hooks/ft/host_error.rb by executing the fence_ipmilan binary using functions out of /usr/lib/one/ruby/CommandManager.rb

I found out that stdout messages, eg. using “puts” land inside /var/log/one/oned.log and that errors produced by the CommandManager.rb functions also land their, which is fine.

However I do not exactely understand how this logging mechanism works.
Up to now this wasn’t a problem, but now I recognized the following behaviour: Errors and stdout stuff that is generated within a while-loop is only put to the oned.log file AFTER the while loop is finished! Why is that? Is there some kind of buffer that is only flushed after a loop is finished? How could I flush this buffer? Flushing STDOUT buffer did not help, tried that already.

Can you point me to the ruby module that is responsible for "receiving messages from other modules and writing to “oned.log”?

BTW I am not a programmer, just gave myself a ruby google crash course to implement the missing fencing mechanism :wink:

any help appreciated!
Jojo

2

Alright, I did some experiments and found out that I am probably misusing the logging. when I create a simple while loop with puts statements before, inside and after the loop, and let it iterate 4 times it looks like this:

Tue Apr 19 16:18:12 2016 [Z0][HKM][D]: Message received: EXECUTE SUCCESS 7 error: DEBUG: FIRST PUTS, BEFORE WHILE LOOP
Tue Apr 19 16:18:12 2016 [Z0][HKM][D]: Message received: DEBUG: BEFORE WHILE LOOP
Tue Apr 19 16:18:12 2016 [Z0][HKM][D]: Message received: DEBUG: INSIDE WHILE LOOP
Tue Apr 19 16:18:12 2016 [Z0][HKM][D]: Message received: DEBUG: INSIDE WHILE LOOP
Tue Apr 19 16:18:12 2016 [Z0][HKM][D]: Message received: DEBUG: INSIDE WHILE LOOP
Tue Apr 19 16:18:12 2016 [Z0][HKM][D]: Message received: DEBUG: INSIDE WHILE LOOP
Tue Apr 19 16:18:12 2016 [Z0][HKM][D]: Message received: DEBUG: AFTER WHILE LOOP

the first message tells me that the logging mechanism obviously receives my first “puts” statement as something undefined and classifies it as an error. all the other puts statement are probably only received because the error logging is already kind of “open for it”.

So my question still remains: How does the logging work?
How can I just log an informational message to the oned.log file. Sorry I am diggin in the code for hours and days already. It cannot be that difficult to just write something to the logfile without generating an error first.

any help appreciated!
thanks
Jojo

3

Hi Jojo,

For debug purposes I found that it is easier to log to syslog so all logging is going there. Here is my try to write on ruby:
https://github.com/OpenNebula/addon-storpool/blob/master/hooks/ft/sp_host_error.rb#L60

Hope it helps.

Kind Regards,
Anton Todorov

4

Hi Anton,
thanks for your answer! Logging to syslog is a great idea and defintely a very nice and actually quite clean workaround to my problems.

Still, I do not want to believe that there are no OpenNebula developers around here that could explain what should be the “official” way to log to oned.log. Can only be a few lines of code. Anyone?

Thanks
Jojo

5

Hi Anton,
unfortunately no OpenNebula coders lurking around in the OpenNebula dev forum :wink:
Just wanted to tell you that I now happily log everything to syslog using your little splog function :slight_smile:
Very handy!
Thanks again!

all the best
Jojo

6

Sorry for the delay. We are here but below a bunch of issues for 5.0. :anguished:

There are two helper libraries, one for shell script and another one for Ruby. They are found in /urs/lib/one/sh/scripts_common.sh and /usr/lib/one/ruby/scripts_common.rb

To use the ruby one you can do:

$: << '/var/lib/one/ruby'
require 'scripts_common'

OpenNebula.log_info 'info'
OpenNebula.log_debug 'debug'
OpenNebula.log_error 'error'

Concerning buffered output for messages, yes, they are buffered and not flushed until the command ends. It’s something I would like to address but still didn’t have the time to do it.

7

Hi Javi,
i understand! Good luck with 5.0!! Thanks a lot for your reply. I will give this a try when I find the time. For now I am satisfied with my result and logging to syslog.
If the problem with the buffered output for messages is also the case with the module you just mentioned, then I would consider it not optimal for debugging failover/fencing scenarios. Exact timestamps in the logs are critical when debugging why and when a cluster did something! Learned that through some years of ha-cluster/pacemaker/… experience.
Anyway, thank you!! I wish you MORE TIME :wink:
all the best
Jojo