Duplicate log messages in /var/log/maas/*.log

[Newell Jensen]

There are many duplicate log messages in /var/log/maas/*.log

Example of tailing /var/log/maas/*.log:

2014-12-08 09:31:28-0800 [HTTPPageGetter,client] RemoteOriginReadSession starting on 44463
2014-12-08 09:31:28-0800 [HTTPPageGetter,client] Starting protocol <tftp.bootstrap.RemoteOriginReadSession instance at 0x7f00d2872440>
2014-12-08 09:31:28-0800 [HTTPPageGetter,client] Starting protocol <tftp.bootstrap.RemoteOriginReadSession instance at 0x7f00d2872440>
2014-12-08 09:31:28-0800 [RemoteOriginReadSession (UDP)] Final ACK received, transfer successful
2014-12-08 09:31:28-0800 [RemoteOriginReadSession (UDP)] Final ACK received, transfer successful
2014-12-08 09:31:28-0800 [-] (UDP Port 44463 Closed)
2014-12-08 09:31:28-0800 [-] (UDP Port 44463 Closed)
2014-12-08 09:31:28-0800 [-] Stopping protocol <tftp.bootstrap.RemoteOriginReadSession instance at 0x7f00d2872440>
2014-12-08 09:31:28-0800 [-] Stopping protocol <tftp.bootstrap.RemoteOriginReadSession instance at 0x7f00d2872440>
2014-12-08 09:31:28-0800 [TFTP (UDP)] Datagram received from ('192.168.122.101', 49163): <RRQDatagram(filename=ifcpu64.c32, mode=octet, options={'tsize': '0', 'blksize': '1408'})>
2014-12-08 09:31:28-0800 [TFTP (UDP)] Datagram received from ('192.168.122.101', 49163): <RRQDatagram(filename=ifcpu64.c32, mode=octet, options={'tsize': '0', 'blksize': '1408'})>
2014-12-08 09:31:28-0800 [-] RemoteOriginReadSession starting on 56028
2014-12-08 09:31:28-0800 [-] RemoteOriginReadSession starting on 56028
2014-12-08 09:31:28-0800 [-] Starting protocol <tftp.bootstrap.RemoteOriginReadSession instance at 0x7f00cdb65b48>
2014-12-08 09:31:28-0800 [-] Starting protocol <tftp.bootstrap.RemoteOriginReadSession instance at 0x7f00cdb65b48>
2014-12-08 09:31:29-0800 [RemoteOriginReadSession (UDP)] Final ACK received, transfer successful
2014-12-08 09:31:29-0800 [RemoteOriginReadSession (UDP)] Final ACK received, transfer successful
2014-12-08 09:31:29-0800 [-] (UDP Port 56028 Closed)
2014-12-08 09:31:29-0800 [-] (UDP Port 56028 Closed)
2014-12-08 09:31:29-0800 [-] Stopping protocol <tftp.bootstrap.RemoteOriginReadSession instance at 0x7f00cdb65b48>
2014-12-08 09:31:29-0800 [-] Stopping protocol <tftp.bootstrap.RemoteOriginReadSession instance at 0x7f00cdb65b48>
2014-12-08 09:31:29-0800 [TFTP (UDP)] Datagram received from ('192.168.122.101', 49164): <RRQDatagram(filename=ubuntu/amd64/generic/trusty/release/boot-kernel, mode=octet, options={'tsize': '0', 'blksize': '1408'})>
2014-12-08 09:31:29-0800 [TFTP (UDP)] Datagram received from ('192.168.122.101', 49164): <RRQDatagram(filename=ubuntu/amd64/generic/trusty/release/boot-kernel, mode=octet, options={'tsize': '0', 'blksize': '1408'})>
2014-12-08 09:31:29-0800 [-] RemoteOriginReadSession starting on 51722
2014-12-08 09:31:29-0800 [-] RemoteOriginReadSession starting on 51722
2014-12-08 09:31:29-0800 [-] Starting protocol <tftp.bootstrap.RemoteOriginReadSession instance at 0x7f00cdae3098>
2014-12-08 09:31:29-0800 [-] Starting protocol <tftp.bootstrap.RemoteOriginReadSession instance at 0x7f00cdae3098>
2014-12-08 09:31:29-0800 [RemoteOriginReadSession (UDP)] Final ACK received, transfer successful
2014-12-08 09:31:29-0800 [RemoteOriginReadSession (UDP)] Final ACK received, transfer successful
2014-12-08 09:31:29-0800 [-] (UDP Port 51722 Closed)
2014-12-08 09:31:29-0800 [-] (UDP Port 51722 Closed)
2014-12-08 09:31:29-0800 [-] Stopping protocol <tftp.bootstrap.RemoteOriginReadSession instance at 0x7f00cdae3098>
2014-12-08 09:31:29-0800 [-] Stopping protocol <tftp.bootstrap.RemoteOriginReadSession instance at 0x7f00cdae3098>
2014-12-08 09:31:29-0800 [TFTP (UDP)] Datagram received from ('192.168.122.101', 49165): <RRQDatagram(filename=ubuntu/amd64/generic/trusty/release/boot-initrd, mode=octet, options={'tsize': '0', 'blksize': '1408'})>
2014-12-08 09:31:29-0800 [TFTP (UDP)] Datagram received from ('192.168.122.101', 49165): <RRQDatagram(filename=ubuntu/amd64/generic/trusty/release/boot-initrd, mode=octet, options={'tsize': '0', 'blksize': '1408'})>
2014-12-08 09:31:29-0800 [-] RemoteOriginReadSession starting on 59673
2014-12-08 09:31:29-0800 [-] RemoteOriginReadSession starting on 59673
2014-12-08 09:31:29-0800 [-] Starting protocol <tftp.bootstrap.RemoteOriginReadSession instance at 0x7f00cdb1e050>
2014-12-08 09:31:29-0800 [-] Starting protocol <tftp.bootstrap.RemoteOriginReadSession instance at 0x7f00cdb1e050>
2014-12-08 09:31:32-0800 [RemoteOriginReadSession (UDP)] Final ACK received, transfer successful
2014-12-08 09:31:32-0800 [RemoteOriginReadSession (UDP)] Final ACK received, transfer successful
2014-12-08 09:31:32-0800 [-] (UDP Port 59673 Closed)
2014-12-08 09:31:32-0800 [-] (UDP Port 59673 Closed)
2014-12-08 09:31:32-0800 [-] Stopping protocol <tftp.bootstrap.RemoteOriginReadSession instance at 0x7f00cdb1e050>
2014-12-08 09:31:32-0800 [-] Stopping protocol <tftp.bootstrap.RemoteOriginReadSession instance at 0x7f00cdb1e050>

==> /var/log/maas/maas.log <==
Dec 8 09:32:06 mc1 maas.lease_upload_service: [INFO] Uploading 1 DHCP leases to region controller.
Dec 8 09:32:21 mc1 maas.dns: [INFO] Generating new DNS zone file for maas
Dec 8 09:32:21 mc1 maas.calls: [INFO] Starting task 'write_dns_zone_config' with args: () {'zones': [<provisioningserver.dns.zoneconfig.DNSForwardZoneConfig object at 0x7fca42df3950>], 'callback': provisioningserver.tasks.rndc_command([u'reload', u'maas'])}
Dec 8 09:32:21 mc1 maas.calls: [INFO] Starting task 'rndc_command' with args: ([u'reload', u'maas'],) {}
Dec 8 09:32:21 mc1 maas.calls: [INFO] Finished task 'rndc_command' with args: ([u'reload', u'maas'],) {}

This is redundant and takes up space.

ubuntu@mc1:~$ dpkg -l '*maas*'|cat
Desired=Unknown/Install/Remove/Purge/Hold
| Status=Not/Inst/Conf-files/Unpacked/halF-conf/Half-inst/trig-aWait/Trig-pend
|/ Err?=(none)/Reinst-required (Status,Err: uppercase=bad)
||/ Name Version Architecture Description
+++-=================================-===================================-============-===============================================================================
ii maas 1.8.0~beta1+bzr3398-0ubuntu1 all MAAS server all-in-one metapackage
ii maas-cli 1.8.0~beta1+bzr3398-0ubuntu1 all MAAS command line API tool
ii maas-cluster-controller 1.8.0~beta1+bzr3398-0ubuntu1 all MAAS server cluster controller
ii maas-common 1.8.0~beta1+bzr3398-0ubuntu1 all MAAS server common files
ii maas-dhcp 1.8.0~beta1+bzr3398-0ubuntu1 all MAAS DHCP server
ii maas-dns 1.8.0~beta1+bzr3398-0ubuntu1 all MAAS DNS server
ii maas-proxy 1.8.0~beta1+bzr3398-0ubuntu1 all MAAS Caching Proxy
ii maas-region-controller 1.8.0~beta1+bzr3398-0ubuntu1 all MAAS server complete region controller
ii maas-region-controller-min 1.8.0~beta1+bzr3398-0ubuntu1 all MAAS Server minimum region controller
ii python-django-maas 1.8.0~beta1+bzr3398-0ubuntu1 all MAAS server Django web framework
ii python-maas-client 1.8.0~beta1+bzr3398-0ubuntu1 all MAAS python API client
ii python-maas-provisioningserver 1.8.0~beta1+bzr3398-0ubuntu1 all MAAS server provisioning libraries

[Blake Rouse (blake-rouse)]

Can you specifically call out which are duplicates?

[Newell Jensen (newell-jensen)]

I see all kinds of duplication happening. From the exert that I have above here are a few:

2014-12-08 09:31:29-0800 [-] RemoteOriginReadSession starting on 59673
2014-12-08 09:31:29-0800 [-] RemoteOriginReadSession starting on 59673
2014-12-08 09:31:29-0800 [-] Starting protocol <tftp.bootstrap.RemoteOriginReadSession instance at 0x7f00cdb1e050>
2014-12-08 09:31:29-0800 [-] Starting protocol <tftp.bootstrap.RemoteOriginReadSession instance at 0x7f00cdb1e050>
2014-12-08 09:31:32-0800 [RemoteOriginReadSession (UDP)] Final ACK received, transfer successful
2014-12-08 09:31:32-0800 [RemoteOriginReadSession (UDP)] Final ACK received, transfer successful

Additionally, I have also been seeing ones that look like this:

Dec 8 09:44:41 mc1 maas.node: message repeated 4 times: [ [INFO] evil-bait.local: Stopping transition monitor: node-9753cc3c-7f01-11e4-b03f-00163e9395d5]
Dec 8 09:45:04 mc1 maas.node: [INFO] worried-grain.local: Stopping transition monitor: node-9702efc4-7f01-11e4-91d3-00163e9395d5
Dec 8 09:44:41 mc1 maas.node: message repeated 5 times: [ [INFO] evil-bait.local: Stopping transition monitor: node-9753cc3c-7f01-11e4-b03f-00163e9395d5]
Dec 8 09:45:05 mc1 maas.node: [INFO] worried-grain.local: Stopping transition monitor: node-9702efc4-7f01-11e4-91d3-00163e9395d5
Dec 8 09:45:09 mc1 maas.node: message repeated 4 times: [ [INFO] worried-grain.local: Stopping transition monitor: node-9702efc4-7f01-11e4-91d3-00163e9395d5]

These say that they are repeated four or five times. So there is something going on here.