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:
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)
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.
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
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.
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
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'
Hello, all our orchestration messages (e.g. "Processing task") were previously only in SQL logger, now they are properly set in APP loger.
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
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