For quite some time, we had user requests (fate #100386) to provide the logging that would be readable to users (= not only YaST developers). Such logs should provide the information what certain YaST action is really doing to the system and exclude all the internal debug info our y2logs are full of.
Martin and Stano created some concept and added new logging functions y2usernote and y2useritem. These log to the new log file, /var/log/YaST2/y2changes (or $HOME/.y2changes).
The question which is still not resolved is how should we use these functions? Which events our modules produce should provide description as “note” and which should provide “items”? What level of complexity should be presented to user? Should we log the real actions, just like commands passed to system agent or rather the explanations of the actions taken? Or both?
Let’s go to the example. The changes are already in FACTORY version of yast2-users packages (yast2-perl-bindings needed as well), so you may even try yourself.
At first, I started logging actions done in Write function. I deleted one user and renamed another. See:
2009-02-05 15:15:55 <item> rivendell User and Group Management module started
2009-02-05 15:16:12 <note> rivendell File written: ‘/etc/group’
2009-02-05 15:16:12 <note> rivendell User pre-deletion script called: ‘/usr/sbin/userdel-pre.local cc 1003 100 /local/home/cc’
2009-02-05 15:16:12 <note> rivendell File written: ‘/etc/passwd’
2009-02-05 15:16:12 <note> rivendell User ‘aa’ renamed to ‘bb’
2009-02-05 15:16:12 <note> rivendell Home directory moved: ‘/bin/mv /local/home/aa /local/home/bb’
2009-02-05 15:16:12 <note> rivendell File written: ‘/etc/shadow’
2009-02-05 15:16:12 <note> rivendell nscd cache invalidated: ‘/usr/sbin/nscd -i passwd’
2009-02-05 15:16:12 <note> rivendell nscd cache invalidated: ‘/usr/sbin/nscd -i group’
2009-02-05 15:16:12 <note> rivendell Group ‘dialout’ modified
2009-02-05 15:16:12 <note> rivendell Group ‘video’ modified
2009-02-05 15:16:12 <note> rivendell Home directory removed: ‘/bin/rm -rf /local/home/cc’
2009-02-05 15:16:12 <note> rivendell User post-deletion script called: ‘/usr/sbin/userdel-post.local cc 1003 100 /local/home/cc’
2009-02-05 15:16:13 <item> rivendell User and Group Management module finished
Now, it is not bad, but the item “File written: ‘/etc/group'” doesn’t give much detailed info about what was done to that file. Stano proposed printing the diffs of the original and modified one, it could look this way:
2009-02-09 10:05:50 <item> rivendell User and Group Management module started
2009-02-09 11:05:49 <note> rivendell Backup created: ‘/bin/cp /etc/group /etc/group.YaST2save’
2009-02-09 11:05:49 <note> rivendell File written: ‘/etc/group’
2009-02-09 11:05:49 <note> rivendell Comparing original and new version:
— /etc/group.YaST2save 2009-02-09 11:05:49.000000000 +0100
+++ /etc/group 2009-02-09 11:05:49.000000000 +0100
@@ -8,3 +8,3 @@
daemon:x:2:
-dialout:x:16:bb,hh,linux,zz
+dialout:x:16:aa,hh,linux
disk:x:6:
@@ -45,3 +45,3 @@
vboxusers:!:113:jsuchome
-video:x:33:bb,hh,linux,zz
+video:x:33:aa,hh,linux
wheel:x:10:
`
2009-02-09 11:05:49 <note> rivendell User pre-deletion script called: ‘/usr/sbin/userdel-pre.local zz 1003 100 /local/home/zz’
2009-02-09 11:05:49 <note> rivendell Backup created: ‘/bin/cp /etc/passwd /etc/passwd.YaST2save’
2009-02-09 11:05:49 <note> rivendell File written: ‘/etc/passwd’
2009-02-09 11:05:49 <note> rivendell Comparing original and new version:
— /etc/passwd.YaST2save 2009-02-09 11:05:49.000000000 +0100
+++ /etc/passwd 2009-02-09 11:05:49.000000000 +0100
@@ -28,6 +28,5 @@
wwwrun:x:30:8:WWW daemon apache:/var/lib/wwwrun:/bin/false
-bb:x:1002:100:AAA:/local/home/bb:/bin/bash
+aa:x:1002:100:AAA:/local/home/aa:/bin/bash
hh:x:1000:100:hhh:/local/home/hh:/bin/bash
linux:x:1001:100:linux:/local/home/linux:/bin/bash
-zz:x:1003:100:zz:/local/home/zz:/bin/bash
+::::::
`
2009-02-09 11:05:49 <note> rivendell User ‘bb’ renamed to ‘aa’
2009-02-09 11:05:49 <note> rivendell Home directory moved: ‘/bin/mv /local/home/bb /local/home/aa’
2009-02-09 11:05:49 <note> rivendell Backup created: ‘/bin/cp /etc/shadow /etc/shadow.YaST2save’
2009-02-09 11:05:49 <note> rivendell File written: ‘/etc/shadow’
2009-02-09 11:05:49 <note> rivendell nscd cache invalidated: ‘/usr/sbin/nscd -i passwd’
2009-02-09 11:05:49 <note> rivendell nscd cache invalidated: ‘/usr/sbin/nscd -i group’
2009-02-09 11:05:49 <note> rivendell Group ‘dialout’ modified
2009-02-09 11:05:49 <note> rivendell Group ‘video’ modified
2009-02-09 11:05:49 <note> rivendell Home directory removed: ‘/bin/rm -rf /local/home/zz’
2009-02-09 11:05:49 <note> rivendell User post-deletion script called: ‘/usr/sbin/userdel-post.local zz 1003 100 /local/home/zz’
2009-02-09 11:05:50 <item> rivendell User and Group Management module finished
Here, the user knows more about the real changes, but the log file is getting a bit less readable again… still I think I’d prefer it.
You could see on examples that I don’t really use the advantage of having 2 logging functions. AFAIK Martin’s original proposal was to use items to tell what actions are we going to perform and notes to log the details of such action. This is hardly achievable in yast2-users module (may be better with
others), since at the time of writing we don’t know the “user actions” taken, this is the info which is known when user is clicking in the UI (*). So another idea is to log directly when users is using UI and not at the time of write. See the last example (this is not a full log this time, just part of it):
2009-02-06 15:54:02 <item> rivendell User and Group Management module started
2009-02-06 15:54:11 <note> rivendell (UI info) User ‘bb’ removed from group ‘dialout’
2009-02-06 15:54:11 <note> rivendell (UI info) User ‘aa’ added to group ‘dialout’
2009-02-06 15:54:11 <note> rivendell (UI info) User ‘bb’ removed from group ‘video’
2009-02-06 15:54:11 <note> rivendell (UI info) User ‘aa’ added to group ‘video’
2009-02-06 15:54:11 <note> rivendell (UI info) User ‘bb’ renamed to ‘aa’
2009-02-06 15:54:11 <item> rivendell (UI info) User modified: ‘aa’
2009-02-06 16:03:10 <item> rivendell User and Group Management module finished
I think the last method is getting more talkative and actually is not more helpful.
So – comments? Proposals?
(*) Actually it would need to be cached during the UI-clicking and logged at the time of writing only if user doesn’t cancel the actions.
Both comments and pings are currently closed.
“I think the last method is getting more talkative and actually is not more helpful.”
I agree but I would like to see the command mentioned, the user has used to do the stuff.
Like
2009-02-06 15:54:11 rivendell (UI info) User ‘bb’ renamed to ‘aa’ (mv ‘bb’ ‘aa’)
Just to have the chance to learn more about the commandline.
> I agree but I would like to see the command mentioned, the user has used to do the stuff.
This is what you can see in the second variant (with the diffs):
2009-02-09 11:05:49 rivendell Home directory moved: ‘/bin/mv /local/home/bb /local/home/aa’
I wanted to write that the last option (with “UI info”) is not really usable
Whoops, I must have been blind 😉
Then I vote for the second variant.
Speaking as a user the third version is definitely the most readable and understandable. I do agree with the comment from Andre that adding the actual command that deoes the action would be valuable. And certainly a great learning tool. Version 2 is getting very technical again and becomong difficult to follow. Remember the whole idea here is for a standard user to be able to read and understand the log.
Great work so far. Keep it up.
You may want to consider enclosing commands (system calls) in square brackets, to distinguish them from file I/O operations and to prevent issues with command lines that may already contain quotes and parenthesis. Example:
2009-02-09 11:05:49 rivendell File Written: ‘/tmp/pre-install.sh’
2009-02-09 11:05:49 rivendell Executing: [ /tmp/pre-install.sh ]
It makes finding the commands in a sea of log file lines a bit easier – especially for scripts that scan those files. The added pre and post spaces are just make it a bit easier to ‘cut-n-paste’ those commands, if needed.
IMHO the most important part is to show the exact commands used (exact as in copying the commands from the log and executing them in a console has to lead to the same result) since that’s pretty much what that logging is good for (otherwise the normal log is good enough).
This way people can easily learn how to do something manually in a console by simply monitoring the log while doing stuff in Yast.
There are some contradicting wishes in the comments above, IMHO:
– 3rd version is understandable, while 2nd version is too much technical
– let’s log exact commands in the log (which is closer to 2nd version)
So, what exactly you don’t like in that 2nd version (which is logging the commands)? Do you think the diffs make it too technical?