Improved logging - work in progress

[Thomas Neumann]

To keep up with my promise:

I recently stumbled upon the Perl Log::Log4perl module and found it quite
awesome. It's a reimplementation of the well known Log4j Logging-Framework
for Perl. There are quite a number of advanced feature but the selling point to
me was:

Replace

print("Found partition flagged as 'bios_grub' with id $gptboot_partid\n");

with 

INFO("Found partition flagged as 'bios_grub' with id $gptboot_partid");

and you magically gain the ability to write this message to a logfile, to some
remote logserver and to the console all in one step. Did I mention that you can
even get colored output based on the criticality (fatal|error|warn|info|debug|trace)
of the message? (Very much like 'puppet agent --test'.)

You can even split up 'the' logfile into multiple logfiles where one may receive
just errors and warnings and a different one is intended for debug logging. It
even auto-rotates itself. (Doesn't sing and dance though.)

Still not everything: If you want to change the settings you don't even need
to touch the actual program or _even know which file is responsible_.

[I reimplemented the grub configuration hook from scratch due to some
local problems.]

Output in fai.log:
-----------------------------------------------------------
Calling hook: configure.GRUB2
Looking for required packages....
fcopy: copied /var/lib/fai/config/files/etc/default/grub/OS_TYPE-UBUNTU to /target/etc/default/grub
Installation finished. No error reported.
Generating grub.cfg ...
Found linux image: /boot/vmlinuz-3.2.0-38-generic
Found initrd image: /boot/initrd.img-3.2.0-38-generic
Found memtest86+ image: /boot/memtest86+.bin
done
configure.GRUB2      OK.
-----------------------------------------------------------

Output in log4perl-fai.log (custom logfile 1)
-----------------------------------------------------------
2013/03/05 22:19:38 - I:   DISK_LOCATION_MBR = /dev/sda
2013/03/05 22:19:38 - I:   BOOT_DEVICE = /dev/vg_system/root
2013/03/05 22:19:38 - I:   ROOT_PARTITION = /dev/vg_system/root
2013/03/05 22:19:38 - I:   SWAPLIST = /dev/sda2
2013/03/05 22:19:38 - I: Checking requirements
2013/03/05 22:19:38 - I:  - found required package 'grub-common'
2013/03/05 22:19:39 - I:  - found required package 'grub2-common'
2013/03/05 22:19:39 - I:  - found required package 'grub-pc'
2013/03/05 22:19:39 - I:  - found required package 'grub-pc-bin'
2013/03/05 22:19:39 - I: Found partition flagged as 'bios_grub' with id 1
2013/03/05 22:19:39 - I: Updating config file '/etc/default/grub'
2013/03/05 22:19:39 - I: Installing bootloader + bootmenu
2013/03/05 22:19:42 - I:  - looks good:   /target/boot/initrd.img-3.2.0-38-generic (14.1 MiB)
-----------------------------------------------------------

Output in log4perl-fai-debug.log (custom logfile 1)
-----------------------------------------------------------
2013/03/05 22:19:38 - [hooks/configure.GRUB2] [INFO]   DISK_LOCATION_MBR = /dev/sda
2013/03/05 22:19:38 - [hooks/configure.GRUB2] [INFO]   BOOT_DEVICE = /dev/vg_system/root
2013/03/05 22:19:38 - [hooks/configure.GRUB2] [INFO]   ROOT_PARTITION = /dev/vg_system/root
2013/03/05 22:19:38 - [hooks/configure.GRUB2] [INFO]   SWAPLIST = /dev/sda2
2013/03/05 22:19:38 - [hooks/configure.GRUB2] [INFO] Checking requirements
2013/03/05 22:19:38 - [hooks/configure.GRUB2] [INFO]  - found required package 'grub-common'
2013/03/05 22:19:39 - [hooks/configure.GRUB2] [INFO]  - found required package 'grub2-common'
2013/03/05 22:19:39 - [hooks/configure.GRUB2] [INFO]  - found required package 'grub-pc'
2013/03/05 22:19:39 - [hooks/configure.GRUB2] [INFO]  - found required package 'grub-pc-bin'
2013/03/05 22:19:39 - [hooks/configure.GRUB2] [INFO] Found partition flagged as 'bios_grub' with id 1
2013/03/05 22:19:39 - [hooks/configure.GRUB2] [INFO] Updating config file '/etc/default/grub'
2013/03/05 22:19:39 - [hooks/configure.GRUB2] [INFO] Installing bootloader + bootmenu
2013/03/05 22:19:42 - [hooks/configure.GRUB2] [INFO]  - looks good:   /target/boot/initrd.img-3.2.0-38-generic (14.1 MiB)
-----------------------------------------------------------

Notice how the debug log even tells you which file / programm generated
the message? It does this automatically if you tell it you want this info.
(the relevant setting is [%F{2}] in log4perl-fai.conf)

I put this stuff online, so whoever is interested in this can have a look at it. 

1) a log4perl'ed hook:

https://github.com/ThomasNeumann/Public/blob/master/fai-config/hooks/configure.GRUB2

(line 35, 36 & 39 initialize the logging framework, line 43 logs a message)

stripped down synthetic example:
https://github.com/ThomasNeumann/Public/blob/master/fai-config/hooks/configure.EXAMPLE

2) the logging configuration:

https://github.com/ThomasNeumann/Public/blob/master/fai-config/log4perl-fai.conf

3) a small convenience module to encapsulate the uninteresting stuff:

https://github.com/ThomasNeumann/Public/blob/master/fai-config/FAI_ENV.pm

(if you store this in /srv/fai/nfsroot/usr/local/lib/site_perl you
 can simply use this without worrying about Perl include path,
 and perl taint mode)


As I said before - the only downside (that I can see) is that this doesn't work
for bash scripts. Could be worse.


bye
thomas