Bug 1540850 - ansible flow needs better logging
Summary: ansible flow needs better logging
Keywords:
Status: CLOSED CURRENTRELEASE
Alias: None
Product: ovirt-hosted-engine-setup
Classification: oVirt
Component: General
Version: 2.2.1
Hardware: Unspecified
OS: Unspecified
unspecified
unspecified
Target Milestone: ovirt-4.2.1
: 2.2.9
Assignee: Yedidyah Bar David
QA Contact: Nikolai Sednev
URL:
Whiteboard:
Depends On:
Blocks: 1458709
TreeView+ depends on / blocked
 
Reported: 2018-02-01 07:10 UTC by Yedidyah Bar David
Modified: 2018-05-04 10:46 UTC (History)
5 users (show)

Fixed In Version: ovirt-hosted-engine-setup-2.2.9
Clone Of:
Environment:
Last Closed: 2018-05-04 10:46:18 UTC
oVirt Team: Integration
Embargoed:
rule-engine: ovirt-4.2+


Attachments (Terms of Use)


Links
System ID Private Priority Status Summary Last Updated
Red Hat Bugzilla 1571117 0 urgent CLOSED HE-VM appliance and admin password saved in the setup log file as clear text executing from cockpit 2021-02-22 00:41:40 UTC
oVirt gerrit 86238 0 None MERGED 2_ovirt_logger.py: Log more data 2020-12-02 09:46:45 UTC
oVirt gerrit 86956 0 ovirt-hosted-engine-setup-2.2 MERGED 2_ovirt_logger.py: Log more data 2020-12-02 09:47:11 UTC
oVirt gerrit 87016 0 master MERGED ansible: Filter secret keys 2020-12-02 09:46:45 UTC
oVirt gerrit 87032 0 ovirt-hosted-engine-setup-2.2 MERGED ansible: Filter secret keys 2020-12-02 09:46:45 UTC

Internal Links: 1571117

Description Yedidyah Bar David 2018-02-01 07:10:31 UTC
Description of problem:

To help debug problems, we should have better logging, probably similarly to the otopi functionality. This includes to automatically log all variables changes without having to use 'debug' tasks, and ability to mark some variables as secret, so that their content is filtered out from the log.

Opening this bug after a patch was already merged to master branch, but not to the 2.2 branch yet.

Missing functionality in that patch is to filter existing vars. Without it, we log them clear-text. The ones I know of are: ADMIN_PASSWORD APPLIANCE_PASSWORD ISCSI_PASSWORD ISCSI_DISCOVER_PASSWORD.

I think I'll add also ROOTPWD although it's not used in ansible currently.

See e.g. [1]. Search there for ADMIN_PASSWORD, APPLIANCE_PASSWORD.

[1] http://jenkins.ovirt.org/view/oVirt%20system%20tests/job/ovirt-system-tests_manual/2105/artifact/exported-artifacts/test_logs/he-basic-ansible-suite-master/post-006_network_by_label.py/lago-he-basic-ansible-suite-master-host0/_var_log/ovirt-hosted-engine-setup/ovirt-hosted-engine-setup-ansible-create_target_vm-20180130100152-zvd20b.log

Comment 1 Nikolai Sednev 2018-04-08 07:33:20 UTC
Please provide reproduction steps for this bug.

Comment 2 Yedidyah Bar David 2018-04-09 06:55:33 UTC
(In reply to Nikolai Sednev from comment #1)
> Please provide reproduction steps for this bug.

Run: hosted-engine --deploy --ansible

Check the resulting log files.

They should include a line per every variable change - host var, group var, fact, etc.

Secret data (including, but not limited to variable content, including in above item) should be filtered out.

If you want more information in the logs, unless it's critical/urgent, please open other bugs. Some things mentioned in the past, not done yet (nor had a bug open for them):
- Perhaps log somehow the module name of each task.
- Remove useless information, including doc strings and the vars 'hostvars' and 'vars'.

Comment 3 Nikolai Sednev 2018-04-09 09:14:35 UTC
Do we have proper documentation for all types of variables for the testing and for the feature?

Comment 4 Yedidyah Bar David 2018-04-09 10:20:01 UTC
(In reply to Nikolai Sednev from comment #3)
> Do we have proper documentation for all types of variables for the testing
> and for the feature?

You can find something in ansible documentation, e.g.:

http://docs.ansible.com/ansible/latest/user_guide/playbooks_variables.html#variable-precedence-where-should-i-put-a-variable

Comment 5 Nikolai Sednev 2018-04-09 10:38:16 UTC
(In reply to Yedidyah Bar David from comment #4)
> (In reply to Nikolai Sednev from comment #3)
> > Do we have proper documentation for all types of variables for the testing
> > and for the feature?
> 
> You can find something in ansible documentation, e.g.:
> 
> http://docs.ansible.com/ansible/latest/user_guide/playbooks_variables.
> html#variable-precedence-where-should-i-put-a-variable

Don't we have an official Red Hat documentation for this?

Comment 6 Yedidyah Bar David 2018-04-10 05:29:23 UTC
(In reply to Nikolai Sednev from comment #5)
> (In reply to Yedidyah Bar David from comment #4)
> > (In reply to Nikolai Sednev from comment #3)
> > > Do we have proper documentation for all types of variables for the testing
> > > and for the feature?
> > 
> > You can find something in ansible documentation, e.g.:
> > 
> > http://docs.ansible.com/ansible/latest/user_guide/playbooks_variables.
> > html#variable-precedence-where-should-i-put-a-variable
> 
> Don't we have an official Red Hat documentation for this?

I am not aware of any.

Note that this link, and this bug, is not a directly-user-facing issue - it's about our own hosted-engine code. So even if there was such official doc, it would have applied to us (developers) and not to users. The only way users are directly affected is if we have a bug and secrets can leak to the log files.

Comment 7 Nikolai Sednev 2018-04-10 10:00:21 UTC
(In reply to Yedidyah Bar David from comment #6)
> (In reply to Nikolai Sednev from comment #5)
> > (In reply to Yedidyah Bar David from comment #4)
> > > (In reply to Nikolai Sednev from comment #3)
> > > > Do we have proper documentation for all types of variables for the testing
> > > > and for the feature?
> > > 
> > > You can find something in ansible documentation, e.g.:
> > > 
> > > http://docs.ansible.com/ansible/latest/user_guide/playbooks_variables.
> > > html#variable-precedence-where-should-i-put-a-variable
> > 
> > Don't we have an official Red Hat documentation for this?
> 
> I am not aware of any.
> 
> Note that this link, and this bug, is not a directly-user-facing issue -
> it's about our own hosted-engine code. So even if there was such official
> doc, it would have applied to us (developers) and not to users. The only way
> users are directly affected is if we have a bug and secrets can leak to the
> log files.

If we don't have any official documentation, I'm afraid that I won't be able to provide proper test coverage as I have no idea of what and how I supposed to test here.

Comment 8 Yedidyah Bar David 2018-04-10 10:24:03 UTC
For now, it's enough if you verify that we do not leak secrets.

Once we get more experience with the hosted-engine ansible flow, we might come up with more logging changes/additions.

If/when you do run into problems, try to see if the logs are detailed enough to help find the root cause of the failure.

Comment 9 Nikolai Sednev 2018-04-10 11:04:29 UTC
(In reply to Yedidyah Bar David from comment #8)
> For now, it's enough if you verify that we do not leak secrets.
> 
> Once we get more experience with the hosted-engine ansible flow, we might
> come up with more logging changes/additions.
> 
> If/when you do run into problems, try to see if the logs are detailed enough
> to help find the root cause of the failure.

1.Which log should I test exactly? 
2.Where is it placed?

Comment 10 Yedidyah Bar David 2018-04-11 05:27:33 UTC
(In reply to Nikolai Sednev from comment #9)
> 1.Which log should I test exactly? 
> 2.Where is it placed?

All of /var/log/ovirt-hosted-engine-setup/* .

Per each run of 'hosted-engine --deploy --ansible', You will find there one log of the main process, called (as before) ovirt-hosted-engine-setup-$TIMESTAMP-$RAND.log , and one log per playbook it ran, called ovirt-hosted-engine-setup-ansible-$PLAYBOOKNAME-$TIMESTAMP-$RAND.log .

Comment 11 Nikolai Sednev 2018-05-02 09:54:51 UTC
In /var/log/ovirt-hosted-engine-setup/ovirt-hosted-engine-setup-20180501153954-4bh9ka.log I see logs like this, I would not say its clear logging.

2018-05-01 16:33:29,626+0300 DEBUG otopi.ovirt_hosted_engine_setup.ansible_utils ansible_utils.run:156 ansible-playbook: env: {'HE_ANSIBLE_LOG_PATH': '/var/log/ovirt-hosted-engine-setup/ovirt-hosted-engine-setup-ansible-final_clean-20180501163329-4jypfv.log', 'LESSOPEN': '||/usr/bin/lesspipe.sh %s', 'SSH_CLIENT': '10.35.4.36 47604 22', 'SELINUX_USE_CURRENT_RANGE': '', 'LOGNAME': 'root', 'USER': 'root', 'PATH': '/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/root/bin', 'HOME': '/root', 'GUESTFISH_RESTORE': '\\e[0m', 'GUESTFISH_INIT': '\\e[1;34m', 'LANG': 'en_US.UTF-8', 'TERM': 'xterm-256color', 'SHELL': '/bin/bash', 'LANGUAGE': '', 'SHLVL': '1', 'HISTSIZE': '1000', 'OTOPI_CALLBACK_OF': '/tmp/tmp11iXGj', 'XMODIFIERS': '@im=none', 'XDG_RUNTIME_DIR': '/run/user/0', 'GUESTFISH_PS1': '\\[\\e[1;32m\\]><fs>\\[\\e[0;31m\\] ', 'ANSIBLE_STDOUT_CALLBACK': '1_otopi_json', 'PYTHONPATH': '/usr/share/ovirt-hosted-engine-setup/scripts/..:', 'SELINUX_ROLE_REQUESTED': '', 'MAIL': '/var/spool/mail/root', 'ANSIBLE_CALLBACK_WHITELIST': '1_otopi_json,2_ovirt_logger', 'XDG_SESSION_ID': '5', 'LS_COLORS': 'rs=0:di=38;5;27:ln=38;5;51:mh=44;38;5;15:pi=40;38;5;11:so=38;5;13:do=38;5;5:bd=48;5;232;38;5;11:cd=48;5;232;38;5;3:or=48;5;232;38;5;9:mi=05;48;5;232;38;5;15:su=48;5;196;38;5;15:sg=48;5;11;38;5;16:ca=48;5;196;38;5;226:tw=48;5;10;38;5;16:ow=48;5;10;38;5;21:st=48;5;21;38;5;15:ex=38;5;34:*.tar=38;5;9:*.tgz=38;5;9:*.arc=38;5;9:*.arj=38;5;9:*.taz=38;5;9:*.lha=38;5;9:*.lz4=38;5;9:*.lzh=38;5;9:*.lzma=38;5;9:*.tlz=38;5;9:*.txz=38;5;9:*.tzo=38;5;9:*.t7z=38;5;9:*.zip=38;5;9:*.z=38;5;9:*.Z=38;5;9:*.dz=38;5;9:*.gz=38;5;9:*.lrz=38;5;9:*.lz=38;5;9:*.lzo=38;5;9:*.xz=38;5;9:*.bz2=38;5;9:*.bz=38;5;9:*.tbz=38;5;9:*.tbz2=38;5;9:*.tz=38;5;9:*.deb=38;5;9:*.rpm=38;5;9:*.jar=38;5;9:*.war=38;5;9:*.ear=38;5;9:*.sar=38;5;9:*.rar=38;5;9:*.alz=38;5;9:*.ace=38;5;9:*.zoo=38;5;9:*.cpio=38;5;9:*.7z=38;5;9:*.rz=38;5;9:*.cab=38;5;9:*.jpg=38;5;13:*.jpeg=38;5;13:*.gif=38;5;13:*.bmp=38;5;13:*.pbm=38;5;13:*.pgm=38;5;13:*.ppm=38;5;13:*.tga=38;5;13:*.xbm=38;5;13:*.xpm=38;5;13:*.tif=38;5;13:*.tiff=38;5;13:*.png=38;5;13:*.svg=38;5;13:*.svgz=38;5;13:*.mng=38;5;13:*.pcx=38;5;13:*.mov=38;5;13:*.mpg=38;5;13:*.mpeg=38;5;13:*.m2v=38;5;13:*.mkv=38;5;13:*.webm=38;5;13:*.ogm=38;5;13:*.mp4=38;5;13:*.m4v=38;5;13:*.mp4v=38;5;13:*.vob=38;5;13:*.qt=38;5;13:*.nuv=38;5;13:*.wmv=38;5;13:*.asf=38;5;13:*.rm=38;5;13:*.rmvb=38;5;13:*.flc=38;5;13:*.avi=38;5;13:*.fli=38;5;13:*.flv=38;5;13:*.gl=38;5;13:*.dl=38;5;13:*.xcf=38;5;13:*.xwd=38;5;13:*.yuv=38;5;13:*.cgm=38;5;13:*.emf=38;5;13:*.axv=38;5;13:*.anx=38;5;13:*.ogv=38;5;13:*.ogx=38;5;13:*.aac=38;5;45:*.au=38;5;45:*.flac=38;5;45:*.mid=38;5;45:*.midi=38;5;45:*.mka=38;5;45:*.mp3=38;5;45:*.mpc=38;5;45:*.ogg=38;5;45:*.ra=38;5;45:*.wav=38;5;45:*.axa=38;5;45:*.oga=38;5;45:*.spx=38;5;45:*.xspf=38;5;45:', 'GUESTFISH_OUTPUT': '\\e[0m', 'SSH_TTY': '/dev/pts/0', 'HOSTNAME': 'alma04.qa.lab.tlv.redhat.com', 'SELINUX_LEVEL_REQUESTED': '', 'HISTCONTROL': 'ignoredups', 'PWD': '/root', 'OTOPI_LOGFILE': '/var/log/ovirt-hosted-engine-setup/ovirt-hosted-engine-setup-20180501153954-4bh9ka.log', 'SSH_CONNECTION': '10.35.4.36 47604 10.35.92.4 22', 'OTOPI_EXECDIR': '/root'}


Or this one from cat /var/log/ovirt-hosted-engine-setup/ovirt-hosted-engine-setup-ansible-iscsi_getdevices-20180501155335-btt3wr.log
{u'otopi_iscsi_devices': {'failed': False, u'changed': False, u'ansible_facts': {u'ovirt_host_storag.__doc__: "dict() -> new empty dictionary\ndict(mapping) -> new dictionary initialized from a mapping object's\n    (key, value) pairs\ndict(iterable) -> new dictionary initialized as if via:\n    d = {}\n    for k, v in iterable:\n        d[k] = v\ndict(**kwargs) -> new dictionary initialized with the name=value pairs\n    in the keyword argument list.  For example:  dict(one=1, two=2)"
{u'otopi_iscsi_devices': {'failed': False, u'changed': False, u'ansible_facts': {u'ovirt_host_storag.__hash__: None
2018-05-01 15:53:52,913+0300 DEBUG ansible on_any args <ansible.executor.task_result.TaskResult object at 0x7ffaae84c310> kwargs 
2018-05-01 15:53:52,917+0300 INFO ansible stats {'status': 'OK', 'ansible_playbook_duration': 16.340226, 'ansible_result': u'type: <type \'dict\'>\nstr: {u\'localhost\': {\'unreachable\': 0, \'skipped\': 0, \'ok\': 6, \'changed\': 1, \'failures\': 0}}\nrepr: {u\'localhost\': {\'unreachable\': 0, \'skipped\': 0, \'ok\': 6, \'changed\': 1, \'failures\': 0}}\ndir: [\'__class__\', \'__cmp__\', \'__contains__\', \'__delattr__\', \'__delitem__\', \'__doc__\', \'__eq__\', \'__format__\', \'__ge__\', \'__getattribute__\', \'__getitem__\', \'__gt__\', \'__hash__\', \'__init__\', \'__iter__\', \'__le__\', \'__len__\', \'__lt__\', \'__ne__\', \'__new__\', \'__reduce__\', \'__reduce_ex__\', \'__repr__\', \'__setattr__\', \'__setitem__\', \'__sizeof__\', \'__str__\', \'__subclasshook__\', \'clear\', \'copy\', \'fromkeys\', \'get\', \'has_key\', \'items\', \'iteritems\', \'iterkeys\', \'itervalues\', \'keys\', \'pop\', \'popitem\', \'setdefault\', \'update\', \'values\', \'viewitems\', \'viewkeys\', \'viewvalues\']\npprint: {u\'localhost\': {\'changed\': 1,\n                \'failures\': 0,\n                \'ok\': 6,\n                \'skipped\': 0,\n                \'unreachable\': 0}}\n{u\'localhost\': {\'unreachable\': 0, \'skipped\': 0, \'ok\': 6, \'changed\': 1, \'failures\': 0}}.__doc__: "dict() -> new empty dictionary\\ndict(mapping) -> new dictionary initialized from a mapping object\'s\\n    (key, value) pairs\\ndict(iterable) -> new dictionary initialized as if via:\\n    d = {}\\n    for k, v in iterable:\\n        d[k] = v\\ndict(**kwargs) -> new dictionary initialized with the name=value pairs\\n    in the keyword argument list.  For example:  dict(one=1, two=2)"\n{u\'localhost\': {\'unreachable\': 0, \'skipped\': 0, \'ok\': 6, \'changed\': 1, \'failures\': 0}}.__hash__: None', 'ansible_playbook': u'/usr/share/ovirt-hosted-engine-setup/ansible/iscsi_getdevices.yml', 'ansible_type': 'finish'}
2018-05-01 15:53:52,917+0300 DEBUG ansible on_any args <ansible.executor.stats.AggregateStats object at 0x7ffaaf914b90> kwargs

All these loggings are not clear enough for regular customer ans IMHO should not be even logged there. 

IMHO, logs should be short, informative and clear.

Comment 13 Yedidyah Bar David 2018-05-03 06:04:14 UTC
(In reply to Nikolai Sednev from comment #11)
> In
> /var/log/ovirt-hosted-engine-setup/ovirt-hosted-engine-setup-20180501153954-
> 4bh9ka.log I see logs like this, I would not say its clear logging.

This log is otopi's, not ansible's. I do not mind considering improvements there as well, but not in current bug. Please open one if needed, with concrete suggestions.

That said, not sure what's unclear here:

> 
> 2018-05-01 16:33:29,626+0300 DEBUG
> otopi.ovirt_hosted_engine_setup.ansible_utils ansible_utils.run:156

That's the standard prefix of otopi logs:

Timestamp Log-level File/Function:Line

> ansible-playbook: env:

This is just a text string, see here:

https://github.com/oVirt/ovirt-hosted-engine-setup/blob/master/src/ovirt_hosted_engine_setup/ansible_utils.py#L156

I'd say it's pretty clear ("we are going to run 'ansible-playbook', and this is the environment we are going to supply"), but suggestions are welcome.

> {'HE_ANSIBLE_LOG_PATH':
> '/var/log/ovirt-hosted-engine-setup/ovirt-hosted-engine-setup-ansible-
> final_clean-20180501163329-4jypfv.log', 'LESSOPEN': '||/usr/bin/lesspipe.sh
> %s', 'SSH_CLIENT': '10.35.4.36 47604 22', 'SELINUX_USE_CURRENT_RANGE': '',
> 'LOGNAME': 'root', 'USER': 'root', 'PATH':
> '/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/root/bin', 'HOME':
> '/root', 'GUESTFISH_RESTORE': '\\e[0m', 'GUESTFISH_INIT': '\\e[1;34m',
> 'LANG': 'en_US.UTF-8', 'TERM': 'xterm-256color', 'SHELL': '/bin/bash',
> 'LANGUAGE': '', 'SHLVL': '1', 'HISTSIZE': '1000', 'OTOPI_CALLBACK_OF':
> '/tmp/tmp11iXGj', 'XMODIFIERS': '@im=none', 'XDG_RUNTIME_DIR':
> '/run/user/0', 'GUESTFISH_PS1': '\\[\\e[1;32m\\]><fs>\\[\\e[0;31m\\] ',
> 'ANSIBLE_STDOUT_CALLBACK': '1_otopi_json', 'PYTHONPATH':
> '/usr/share/ovirt-hosted-engine-setup/scripts/..:',
> 'SELINUX_ROLE_REQUESTED': '', 'MAIL': '/var/spool/mail/root',
> 'ANSIBLE_CALLBACK_WHITELIST': '1_otopi_json,2_ovirt_logger',
> 'XDG_SESSION_ID': '5', 'LS_COLORS':
> 'rs=0:di=38;5;27:ln=38;5;51:mh=44;38;5;15:pi=40;38;5;11:so=38;5;13:do=38;5;5:
> bd=48;5;232;38;5;11:cd=48;5;232;38;5;3:or=48;5;232;38;5;9:mi=05;48;5;232;38;
> 5;15:su=48;5;196;38;5;15:sg=48;5;11;38;5;16:ca=48;5;196;38;5;226:tw=48;5;10;
> 38;5;16:ow=48;5;10;38;5;21:st=48;5;21;38;5;15:ex=38;5;34:*.tar=38;5;9:*.
> tgz=38;5;9:*.arc=38;5;9:*.arj=38;5;9:*.taz=38;5;9:*.lha=38;5;9:*.lz4=38;5;9:
> *.lzh=38;5;9:*.lzma=38;5;9:*.tlz=38;5;9:*.txz=38;5;9:*.tzo=38;5;9:*.t7z=38;5;
> 9:*.zip=38;5;9:*.z=38;5;9:*.Z=38;5;9:*.dz=38;5;9:*.gz=38;5;9:*.lrz=38;5;9:*.
> lz=38;5;9:*.lzo=38;5;9:*.xz=38;5;9:*.bz2=38;5;9:*.bz=38;5;9:*.tbz=38;5;9:*.
> tbz2=38;5;9:*.tz=38;5;9:*.deb=38;5;9:*.rpm=38;5;9:*.jar=38;5;9:*.war=38;5;9:
> *.ear=38;5;9:*.sar=38;5;9:*.rar=38;5;9:*.alz=38;5;9:*.ace=38;5;9:*.zoo=38;5;
> 9:*.cpio=38;5;9:*.7z=38;5;9:*.rz=38;5;9:*.cab=38;5;9:*.jpg=38;5;13:*.jpeg=38;
> 5;13:*.gif=38;5;13:*.bmp=38;5;13:*.pbm=38;5;13:*.pgm=38;5;13:*.ppm=38;5;13:*.
> tga=38;5;13:*.xbm=38;5;13:*.xpm=38;5;13:*.tif=38;5;13:*.tiff=38;5;13:*.
> png=38;5;13:*.svg=38;5;13:*.svgz=38;5;13:*.mng=38;5;13:*.pcx=38;5;13:*.
> mov=38;5;13:*.mpg=38;5;13:*.mpeg=38;5;13:*.m2v=38;5;13:*.mkv=38;5;13:*.
> webm=38;5;13:*.ogm=38;5;13:*.mp4=38;5;13:*.m4v=38;5;13:*.mp4v=38;5;13:*.
> vob=38;5;13:*.qt=38;5;13:*.nuv=38;5;13:*.wmv=38;5;13:*.asf=38;5;13:*.rm=38;5;
> 13:*.rmvb=38;5;13:*.flc=38;5;13:*.avi=38;5;13:*.fli=38;5;13:*.flv=38;5;13:*.
> gl=38;5;13:*.dl=38;5;13:*.xcf=38;5;13:*.xwd=38;5;13:*.yuv=38;5;13:*.cgm=38;5;
> 13:*.emf=38;5;13:*.axv=38;5;13:*.anx=38;5;13:*.ogv=38;5;13:*.ogx=38;5;13:*.
> aac=38;5;45:*.au=38;5;45:*.flac=38;5;45:*.mid=38;5;45:*.midi=38;5;45:*.
> mka=38;5;45:*.mp3=38;5;45:*.mpc=38;5;45:*.ogg=38;5;45:*.ra=38;5;45:*.wav=38;
> 5;45:*.axa=38;5;45:*.oga=38;5;45:*.spx=38;5;45:*.xspf=38;5;45:',
> 'GUESTFISH_OUTPUT': '\\e[0m', 'SSH_TTY': '/dev/pts/0', 'HOSTNAME':
> 'alma04.qa.lab.tlv.redhat.com', 'SELINUX_LEVEL_REQUESTED': '',
> 'HISTCONTROL': 'ignoredups', 'PWD': '/root', 'OTOPI_LOGFILE':
> '/var/log/ovirt-hosted-engine-setup/ovirt-hosted-engine-setup-20180501153954-
> 4bh9ka.log', 'SSH_CONNECTION': '10.35.4.36 47604 10.35.92.4 22',
> 'OTOPI_EXECDIR': '/root'}

This is the actual environment, as a python dict.

I have mixed feelings about its format, myself. Having it in one line is definitely shorter, and good enough for most needs. If we decide to log each var in its own line, we definitely want at least some prefix (e.g. "ansible-playbook: env:"), or it will be very hard to grep. If we also add a timestamp and function name as in the above single line, it will make the log considerably larger. Suggestions are welcome :-)

> 
> 
> Or this one from cat
> /var/log/ovirt-hosted-engine-setup/ovirt-hosted-engine-setup-ansible-
> iscsi_getdevices-20180501155335-btt3wr.log

The following line has no prefix, which is the exact problem I noted above.

If you look at the code:

https://github.com/oVirt/ovirt-hosted-engine-setup/blob/master/src/ansible/callback_plugins/2_ovirt_logger.py#L300

https://github.com/oVirt/ovirt-hosted-engine-setup/blob/master/src/ansible/callback_plugins/2_ovirt_logger.py#L417

I think it makes more sense: A few lines before that, you see 'ansible ok', which is unique enough to allow easily finding it in the code, and then the result of dump_obj, which I agree is not yet refined wrt to what I wrote above (about the tension between splitting to different lines and adding prefixes).

Again, concrete suggestions are welcome.

I now opened bug 1574336, feel free to comment there, and/or open a new bug and make bug 1574336 depend on it.

> {u'otopi_iscsi_devices': {'failed': False, u'changed': False,
> u'ansible_facts': {u'ovirt_host_storag.__doc__: "dict() -> new empty
> dictionary\ndict(mapping) -> new dictionary initialized from a mapping
> object's\n    (key, value) pairs\ndict(iterable) -> new dictionary
> initialized as if via:\n    d = {}\n    for k, v in iterable:\n        d[k]
> = v\ndict(**kwargs) -> new dictionary initialized with the name=value
> pairs\n    in the keyword argument list.  For example:  dict(one=1, two=2)"
> {u'otopi_iscsi_devices': {'failed': False, u'changed': False,
> u'ansible_facts': {u'ovirt_host_storag.__hash__: None
> 2018-05-01 15:53:52,913+0300 DEBUG ansible on_any args
> <ansible.executor.task_result.TaskResult object at 0x7ffaae84c310> kwargs 
> 2018-05-01 15:53:52,917+0300 INFO ansible stats {'status': 'OK',
> 'ansible_playbook_duration': 16.340226, 'ansible_result': u'type: <type
> \'dict\'>\nstr: {u\'localhost\': {\'unreachable\': 0, \'skipped\': 0,
> \'ok\': 6, \'changed\': 1, \'failures\': 0}}\nrepr: {u\'localhost\':
> {\'unreachable\': 0, \'skipped\': 0, \'ok\': 6, \'changed\': 1,
> \'failures\': 0}}\ndir: [\'__class__\', \'__cmp__\', \'__contains__\',
> \'__delattr__\', \'__delitem__\', \'__doc__\', \'__eq__\', \'__format__\',
> \'__ge__\', \'__getattribute__\', \'__getitem__\', \'__gt__\', \'__hash__\',
> \'__init__\', \'__iter__\', \'__le__\', \'__len__\', \'__lt__\', \'__ne__\',
> \'__new__\', \'__reduce__\', \'__reduce_ex__\', \'__repr__\',
> \'__setattr__\', \'__setitem__\', \'__sizeof__\', \'__str__\',
> \'__subclasshook__\', \'clear\', \'copy\', \'fromkeys\', \'get\',
> \'has_key\', \'items\', \'iteritems\', \'iterkeys\', \'itervalues\',
> \'keys\', \'pop\', \'popitem\', \'setdefault\', \'update\', \'values\',
> \'viewitems\', \'viewkeys\', \'viewvalues\']\npprint: {u\'localhost\':
> {\'changed\': 1,\n                \'failures\': 0,\n                \'ok\':
> 6,\n                \'skipped\': 0,\n                \'unreachable\':
> 0}}\n{u\'localhost\': {\'unreachable\': 0, \'skipped\': 0, \'ok\': 6,
> \'changed\': 1, \'failures\': 0}}.__doc__: "dict() -> new empty
> dictionary\\ndict(mapping) -> new dictionary initialized from a mapping
> object\'s\\n    (key, value) pairs\\ndict(iterable) -> new dictionary
> initialized as if via:\\n    d = {}\\n    for k, v in iterable:\\n       
> d[k] = v\\ndict(**kwargs) -> new dictionary initialized with the name=value
> pairs\\n    in the keyword argument list.  For example:  dict(one=1,
> two=2)"\n{u\'localhost\': {\'unreachable\': 0, \'skipped\': 0, \'ok\': 6,
> \'changed\': 1, \'failures\': 0}}.__hash__: None', 'ansible_playbook':
> u'/usr/share/ovirt-hosted-engine-setup/ansible/iscsi_getdevices.yml',
> 'ansible_type': 'finish'}
> 2018-05-01 15:53:52,917+0300 DEBUG ansible on_any args
> <ansible.executor.stats.AggregateStats object at 0x7ffaaf914b90> kwargs
> 
> All these loggings are not clear enough for regular customer

Agreed.

I do not think any of our logs are clear enough for regular customers.

I do not think I, as a user, always understand every log line of every program I have to sometimes debug.

> ans IMHO should
> not be even logged there. 
> 
> IMHO, logs should be short, informative and clear.

Current logs are a result of:

1. Wanting as much relevant information as possible logged, so that if/when we run into failures, we have enough to work with to analyze them.

2. Not revealing sensitive information.

3. Not wanting the logs to be so large that they become impractical to use (backup/archive, share in a file sharing service, upload to bugzilla, grep, etc.). (And, believe me, during development I did, at some points, create logs that were really too large, in this sense).

4. Due to lack of time, only slightly trying to reduce noise.

If you claim they are so bad that it's a blocker, feel free to move current bug to assigned and mark "blocker". Otherwise, please open new bugs or add comments to bug 1574336. Thanks.

Comment 15 Nikolai Sednev 2018-05-03 09:39:31 UTC
I did not found any leaks within the logs that were created during deployment on puma18 over Gluster, using node 0 over CLI:
2.4M -rw-r--r--.  1 root root 2.4M May  1 16:12 ovirt-hosted-engine-setup-ansible-bootstrap_local_vm-20180501160142-ewlc26.log
2.0M -rw-r--r--.  1 root root 2.0M May  1 16:14 ovirt-hosted-engine-setup-ansible-create_storage_domain-20180501161246-dy47c0.log
5.6M -rw-r--r--.  1 root root 5.6M May  1 16:26 ovirt-hosted-engine-setup-ansible-create_target_vm-20180501161418-n4nmd3.log
304K -rw-r--r--.  1 root root 300K May  1 16:26 ovirt-hosted-engine-setup-ansible-final_clean-20180501162645-5ppuuo.log
424K -rw-r--r--.  1 root root 417K May  1 16:00 ovirt-hosted-engine-setup-ansible-get_network_interfaces-20180501160025-al13bz.log
248K -rw-r--r--.  1 root root 242K May  1 16:01 ovirt-hosted-engine-setup-ansible-initial_clean-20180501160120-ron813.log

Moving to verified.

Please reopen if it does not work for you.

Works for me on these components:
ovirt-engine-4.2.3.3-0.1.el7.noarch
rhvm-appliance-4.2-20180427.0.el7.noarch
ovirt-hosted-engine-setup-2.2.19-1.el7ev.noarch
ovirt-hosted-engine-ha-2.2.11-1.el7ev.noarch
Linux 3.10.0-862.el7.x86_64 #1 SMP Wed Mar 21 18:14:51 EDT 2018 x86_64 x86_64 x86_64 GNU/Linux
Red Hat Enterprise Linux Server release 7.5 (Maipo)

Comment 16 Sandro Bonazzola 2018-05-04 10:46:18 UTC
This bugzilla is included in oVirt 4.2.1 release, published on Feb 12th 2018.

Since the problem described in this bug report should be
resolved in oVirt 4.2.1 release, it has been closed with a resolution of CURRENT RELEASE.

If the solution does not work for you, please open a new bug report.


Note You need to log in before you can comment on or make changes to this bug.