Bug 1503052

Summary:	Log warnings not emitted even if they are int he code
Product:	Red Hat Satellite	Reporter:	Peter Vreman <peter.vreman>
Component:	Logging	Assignee:	satellite6-bugs <satellite6-bugs>
Status:	CLOSED ERRATA	QA Contact:	Sanket Jagtap <sjagtap>
Severity:	high	Docs Contact:
Priority:	high
Version:	6.2.12	CC:	bbuckingham, lzap, pcreech, sjagtap, sreber
Target Milestone:	6.4.0	Keywords:	Reopened, Triaged
Target Release:	Unused
Hardware:	x86_64
OS:	Linux
Whiteboard:
Fixed In Version:		Doc Type:	If docs needed, set a value
Doc Text:		Story Points:	---
Clone Of:		Environment:
Last Closed:	2018-10-16 19:29:13 UTC	Type:	Bug
Regression:	---	Mount Type:	---
Documentation:	---	CRM:
Verified Versions:		Category:	---
oVirt Team:	---	RHEL 7.3 requirements from Atomic Host:
Cloudforms Team:	---	Target Upstream Version:
Embargoed:
Bug Depends On:
Bug Blocks:	1122832

Description Peter Vreman 2017-10-17 09:27:04 UTC

Description of problem:
In some places the logger statements are not emitted to the log file. E.g. in the foreman model/host/base.rb the warning 'Saving bond0 NIC for host xxx.xxx failed, skipping because:' is never emitted although it the logger.warn code line is executed when the primary interface is a bond0 instead of a regular interface. I used this scenario as the reproducer.

Upstream foreman 1.16 has a refactoring of the logging, using applicationrecord as a base class instead of activerecord::base. the applicationrecord then provides the logger method. Upstream issue http://projects.theforeman.org/issues/13772

Version-Release number of selected component (if applicable):

How reproducible:

Steps to Reproduce:
1. create a host wiht a bond0 interface mode=0 with the ip address and add one slave (enough to test)
2. delete the host in foreman
3. run puppet to upload the facts, this should create through the puppet ENC the host in foreman
4. check the interfaces of the host, the bond0 is missing
5. check the log files, there is no warning

6. Now add the line 'delegate :logger, :to => :Rails' to the models/host/base.rb inside the class

7. delete the host in foreman
8. run puppet to upload the facts, this should create through the puppet ENC the host in foreman
9. check the interfaces of the host, the bond0 is still missing
10. check the log files, now the warnings 'Saving bond0 NIC for host xxx.xxx failed, skipping because:' and 'Identifier has already been taken' are emitted

Alternative enable logging level 'debug'
Restart the applciation and register some hosts and do other things
Grep for the logger.debug in the app and notice that many of those are not included in the log file even tough the code is executed

Actual results:
Missing log messages for at least warnings (and also for info, debug if loglevel is set as such)

Expected results:
All logger statements in the code are emitting there content when the loglevel matches

Additional info:

Comment 3 Lukas Zapletal 2017-10-19 13:48:25 UTC

Hello Peter,

as you figured out, this is long overdue issue in logging but we are unable to deliver this into 6.2 series because this introduced several regressions we had to fix upstream, the change also affects all database tables so this one is no go for backporting.

I can confirm this will be finally solved in 6.3. Please contact RH representative for dates, can't share that but we are close.

Moving to 6.3 bug, QA steps:

- enable debug level in Rails
- create a host
- check that orchestration is logged (e.g. creating DHCP records, comparing DHCP entries, DNS entry)

Comment 4 Peter Vreman 2017-10-23 16:58:01 UTC

Thanks for confirming that it will be fixed in Sat6.3. I understand that the required changes are significant for fixing this issue throughout the whole code base.

Comment 8 Satellite Program 2018-02-21 16:54:37 UTC

Since the problem described in this bug report should be resolved in a recent advisory, it has been closed with a resolution of ERRATA.
> > 
> > For information on the advisory, and where to find the updated files, follow the link below.
> > 
> > If the solution does not work for you, open a new bug report.
> > 
> > https://access.redhat.com/errata/RHSA-2018:0336

Comment 9 Peter Vreman 2018-05-09 10:04:36 UTC

It is not fixed in Sat6.3

I have enabled debug logging, but the log entries 'logger.debug "Saving #{name} NIC for host #{self.name}"' in models/host/base.rb is not emitted.

It is also confirmed in the inheritance of the model still on ActiveRecord::Base in stead of ApplicationRecord that is used in current github master.

Can you please recheck what is planned to improve this for 6.3.z and if not planned that the change to ApplicationRecord will be included in Sat6.4.

Comment 10 Lukas Zapletal 2018-05-10 09:47:32 UTC

Apologies, this indeed missed the branching date and it is only present in 6.4 branch. Thus I am moving this to 6.4.

TRIAGE NOTES: I accidentally scheduled this into 6.3 but the patch is too big and it is part of 6.4. Please align into 6.4 release for QA.

QA NOTES: Please make sure this line is present when creating new host with debug level turned on:

Saving XXX NIC for host YYY

Comment 11 Sanket Jagtap 2018-08-31 09:44:32 UTC

Build: Satellite 6.4.0 snap19

I am unable get the exact phrase in the logs, Were there chnages made to it ?

I see a new block though 

20p8-08-3pT05:3p:p8 [D|app|p7472] creating VM with the following options: {"name"=>"ruben-sprinkel.domain", "first_boot_dev"=>"network", "quota"=>"5aaaaaO7-02a9-02Oe-0p85-00000000025f", "cluster"=>"5aaaaa4p-02db-027c-0p90-000000000pc8", "template"=>"", "instance_type"=>"", "cores"=>"p", "sockets"=>"p", "memory"=>"2p47483O48", "start"=>"p", "volumes_attributes"=>{"0"=>{"_delete"=>"", "size_gb"=>"O", "storage_domain"=>"c4fc24ba-O5pa-4dbO-ap37-c5ad8a4a92pf", "id"=>"", "preallocate"=>"0", "wipe_after_delete"=>"0", "interface"=>"virtio", "bootable"=>"true"}}, "provision_method"=>"build", "firmware_type"=>:bios, "interfaces_attributes"=>{"0"=>{"name"=>"nicp", "network"=>"73aO00a2-3b97-4423-8b7f-fcbec828578O", "ip"=>"0.0.2p5.p54", "ipO"=>""}}, "os"=>{"type"=>"rhel_7xO4"}}
20p8-08-3pT05:3p:p9 [I|app|] Started GET "/tasks/7d4f78pd-9dpa-4p95-b40d-O93b95f4f8eb" for O.O7.ppO.225 at 20p8-08-3p 05:3p:p9 -0400
20p8-08-3pT05:3p:p9 [I|app|47aO3] Processing by TasksController#show as */*
20p8-08-3pT05:3p:p9 [I|app|47aO3]   Parameters: {"id"=>"7d4f78pd-9dpa-4p95-b40d-O93b95f4f8eb"}
20p8-08-3pT05:3p:p9 [I|app|47aO3] Current user: admin (administrator)
20p8-08-3pT05:3p:p9 [D|app|47aO3] Setting current user thread-local variable to admin
20p8-08-3pT05:3p:p9 [I|app|47aO3]   Rendered tasks/_list.html.erb (p.2ms)
20p8-08-3pT05:3p:p9 [I|app|47aO3] Completed 200 OK in pOms (Views: 5.7ms | ActiveRecord: 2.0ms)
20p8-08-3pT05:3p:20 [D|app|p7472] Processing task 'Query instance details for ruben-sprinkel.domain' from 'Host::Managed Main'
20p8-08-3pT05:3p:20 [D|app|p7472] Orchestration::Compute: Trying to match network interfaces from fog   <Fog::Compute::Ovirt::Interfaces
    [
                  <Fog::Compute::Ovirt::Interface
        id="b5ba075f-22ab-4epa-bpe0-b7pbpd9f398f",
        name="nicp",
        network="73aO00a2-3b97-4423-8b7f-fcbec828578O",
        interface="virtio",
        mac="00:pa:4a:pO:0p:bf"
      >
    ]
  >
20p8-08-3pT05:3p:20 [D|app|p7472] Orchestration::Compute: nic #<Nic::Managed id: nil, mac: nil, ip: "0.0.2p5.p54", type: "Nic::Managed", name: "ruben-sprinkel.domain", host_id: nil, subnet_id: 2, domain_id: p, attrs: {}, created_at: nil, updated_at: nil, provider: nil, username: nil, password: nil, virtual: false, link: true, identifier: "", tag: "", attached_to: "", managed: true, mode: "balance-rr", attached_devices: "", bond_options: "", primary: true, provision: true, compute_attributes: {"name"=>"nicp", "network"=>"73aO00a2-3b97-4423-8b7f-fcbec828578O"}, execution: true, ipO: "", subnetO_id: nil> assigned to   <Fog::Compute::Ovirt::Interface
    id="b5ba075f-22ab-4epa-bpe0-b7pbpd9f398f",
    name="nicp",
    network="73aO00a2-3b97-4423-8b7f-fcbec828578O",
    interface="virtio",
    mac="00:pa:4a:pO:0p:bf"
  >
20p8-08-3pT05:3p:20 [D|app|p7472] Processing task 'Create DHCP Settings for ruben-sprinkel.domain' from 'Host::Managed Main'
20p8-08-3pT05:3p:20 [I|app|p7472] Create DHCP reservation ruben-sprinkel.domain for ruben-sprinkel.domain-00:pa:4a:pO:0p:bf/0.0.2p5.p54
20p8-08-3pT05:3p:20 [D|app|p7472] DHCP reservation on net 0.0.2p5.0 with attrs: {:hostname=>"ruben-sprinkel.domain", :mac=>"00:pa:4a:pO:0p:bf", :ip=>"0.0.2p5.p54", :network=>"0.0.2p5.0", :nextServer=>"0.0.2p5.p", :filename=>"pxelinux.0", :name=>"ruben-sprinkel.domain", :related_macs=>[]}
20p8-08-3pT05:3p:2p [D|app|p7472] Processing task 'Create IPv4 DNS record for ruben-sprinkel.domain' from 'Host::Managed Main'
20p8-08-3pT05:3p:2p [I|app|p7472] Add DNS A record for ruben-sprinkel.domain/0.0.2p5.p54
20p8-08-3pT05:3p:2p [D|app|p7472] Processing task 'Create Reverse IPv4 DNS record for ruben-sprinkel.domain' from 'Host::Managed Main'
20p8-08-3pT05:3p:2p [I|app|p7472] Add DNS PTR record for 0.0.2p5.p54/ruben-sprinkel.domain
20p8-08-3pT05:3p:2p [D|app|p7472] Processing task 'Deploy TFTP PXELinux config for ruben-sprinkel.domain' from 'Host::Managed Main'
20p8-08-3pT05:3p:2p [D|app|p7472] Setting current organization thread-local variable to Default Organization
20p8-08-3pT05:3p:2p [D|app|p7472] Setting current location thread-local variable to Default Location
20p8-08-3pT05:3p:2p [D|app|p7472] Setting current location thread-local variable to none
20p8-08-3pT05:3p:2p [D|app|p7472] Setting current organization thread-local variable to Default Organization
20p8-08-3pT05:3p:2p [I|tem|p7472] Rendering template 'Kickstart default PXELinux'

Comment 12 Lukas Zapletal 2018-09-03 06:51:27 UTC

Hello, all our orchestration messages (e.g. "Processing task") were previously only in SQL logger, now they are properly set in APP loger.

Comment 13 Sanket Jagtap 2018-09-03 10:46:54 UTC

Build:Satellite 6.4.0 snap20

1. Create a host with interfaces
2. Host is provisioned and puppet is run 


Logs:
Interface eth0 facts: {"ipaddress6"=>"2620:52:0:86f:21a:4aff:fe16:1cf", "ipaddress"=>"0.0.0.6", "macaddress"=>"00:1a:4a:16:01:cf", "mtu"=>1500, "netmask6"=>"ffff:ffff:ffff:ffff::", "netmask"=>"255.255.255.0", "network6"=>"2620:52:0:86f::", "network"=>"0.0.0.0"}
2018-09-03T05:21:03 [D|app|32887] Interface eth1 facts: {"macaddress"=>"00:1a:4a:16:01:d1", "mtu"=>1500}
2018-09-03T05:21:03 [D|app|32887] Saving eth0 NIC for host kerry-beger.sat-domain
2018-09-03T05:21:03 [D|app|32887] Enqueued task 'Remove IPv4 DNS record for kerry-beger.sat-domain' to 'Host::Managed Main' queue
2018-09-03T05:21:03 [D|app|32887] Enqueued task 'Remove Reverse IPv4 DNS record for kerry-beger.sat-domain' to 'Host::Managed Main' queue
2018-09-03T05:21:03 [D|app|32887] Scheduling new DNS entries
2018-09-03T05:21:03 [D|app|32887] Enqueued task 'Create IPv4 DNS record for kerry-beger.sat-domain' to 'Host::Managed Main' queue
2018-09-03T05:21:03 [D|app|32887] Enqueued task 'Create IPv6 DNS record for kerry-beger.sat-domain' to 'Host::Managed Main' queue
2018-09-03T05:21:03 [D|app|32887] Enqueued task 'Create Reverse IPv4 DNS record for kerry-beger.sat-domain' to 'Host::Managed Main' queue
2018-09-03T05:21:03 [I|aud|32887] update event for Nic::Managed with id 3
2018-09-03T05:21:03 [D|app|32887] Saving eth1 NIC for host kerry-beger.sat-domain
2018-09-03T05:21:03 [I|aud|32887] update event for Nic::Managed with id 4
2018-09-03T05:21:03 [I|aud|32887] update event for Host::Base with id 3

Comment 14 Bryan Kearney 2018-10-16 19:29:13 UTC

Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory, and where to find the updated
files, follow the link below.

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

https://access.redhat.com/errata/RHSA-2018:2927