MAAS

Lots of duplicate event log entries for PXE booting

Bug #1402109 reported by Jason Hobbs
22
This bug affects 3 people
Affects Status Importance Assigned to Milestone
MAAS
Fix Released
High
Newell Jensen
MAAS 1.8.0
1.7
Won't Fix
High
Newell Jensen

Bug Description

This is with MAAS 1.7.1~rc1+bzr3313-0

Here's the event log so far for one boot of a node in my MAAS cluster. There shouldn't be this many entries logged.

DEBUG Sat, 13 Dec. 2014 00:12:43 TFTP Request — ubuntu/amd64/generic/trusty/daily/boot-initrd
INFO Sat, 13 Dec. 2014 00:12:41 PXE Request — commissioning
INFO Sat, 13 Dec. 2014 00:12:41 PXE Request — commissioning
INFO Sat, 13 Dec. 2014 00:12:41 PXE Request — commissioning
INFO Sat, 13 Dec. 2014 00:12:41 PXE Request — commissioning
INFO Sat, 13 Dec. 2014 00:12:40 PXE Request — commissioning
INFO Sat, 13 Dec. 2014 00:12:40 PXE Request — commissioning
INFO Sat, 13 Dec. 2014 00:12:40 PXE Request — commissioning
INFO Sat, 13 Dec. 2014 00:12:40 PXE Request — commissioning
INFO Sat, 13 Dec. 2014 00:12:40 PXE Request — commissioning
INFO Sat, 13 Dec. 2014 00:12:39 PXE Request — commissioning
INFO Sat, 13 Dec. 2014 00:12:39 PXE Request — commissioning
INFO Sat, 13 Dec. 2014 00:12:39 PXE Request — commissioning
INFO Sat, 13 Dec. 2014 00:12:39 PXE Request — commissioning
INFO Sat, 13 Dec. 2014 00:12:39 PXE Request — commissioning
DEBUG Sat, 13 Dec. 2014 00:12:38 TFTP Request — ubuntu/amd64/generic/trusty/daily/boot-kernel
DEBUG Sat, 13 Dec. 2014 00:12:38 TFTP Request — ifcpu64.c32
INFO Sat, 13 Dec. 2014 00:12:38 PXE Request — commissioning
DEBUG Sat, 13 Dec. 2014 00:12:38 TFTP Request — pxelinux.cfg/01-9c-b6-54-0a-40-fa
DEBUG Sat, 13 Dec. 2014 00:12:37 TFTP Request — pxelinux.cfg/01-9c-b6-54-0a-40-fa
DEBUG Sat, 13 Dec. 2014 00:12:36 TFTP Request — pxelinux.cfg/01-9c-b6-54-0a-40-fa
DEBUG Sat, 13 Dec. 2014 00:12:35 TFTP Request — pxelinux.cfg/01-9c-b6-54-0a-40-fa
DEBUG Sat, 13 Dec. 2014 00:12:35 TFTP Request — pxelinux.cfg/01-9c-b6-54-0a-40-fa
DEBUG Sat, 13 Dec. 2014 00:12:34 TFTP Request — pxelinux.cfg/01-9c-b6-54-0a-40-fa
DEBUG Sat, 13 Dec. 2014 00:12:33 TFTP Request — pxelinux.cfg/01-9c-b6-54-0a-40-fa
DEBUG Sat, 13 Dec. 2014 00:12:33 TFTP Request — pxelinux.cfg/01-9c-b6-54-0a-40-fa
DEBUG Sat, 13 Dec. 2014 00:12:32 TFTP Request — pxelinux.cfg/01-9c-b6-54-0a-40-fa
DEBUG Sat, 13 Dec. 2014 00:12:32 TFTP Request — pxelinux.cfg/01-9c-b6-54-0a-40-fa
DEBUG Sat, 13 Dec. 2014 00:12:32 TFTP Request — pxelinux.cfg/01-9c-b6-54-0a-40-fa
DEBUG Sat, 13 Dec. 2014 00:12:31 TFTP Request — pxelinux.cfg/01-9c-b6-54-0a-40-fa
DEBUG Sat, 13 Dec. 2014 00:12:31 TFTP Request — pxelinux.cfg/01-9c-b6-54-0a-40-fa
DEBUG Sat, 13 Dec. 2014 00:12:30 TFTP Request — pxelinux.cfg/01-9c-b6-54-0a-40-fa
DEBUG Sat, 13 Dec. 2014 00:12:30 TFTP Request — pxelinux.cfg/36393837-3233-5553-4534-313456594c34
DEBUG Sat, 13 Dec. 2014 00:12:30 TFTP Request — pxelinux.cfg/01-9c-b6-54-0a-40-fa
DEBUG Sat, 13 Dec. 2014 00:12:30 TFTP Request — pxelinux.0
DEBUG Sat, 13 Dec. 2014 00:12:30 TFTP Request — pxelinux.0
DEBUG Sat, 13 Dec. 2014 00:12:30 TFTP Request — pxelinux.0
DEBUG Sat, 13 Dec. 2014 00:12:30 TFTP Request — pxelinux.0
INFO Sat, 13 Dec. 2014 00:09:55 Node powered on

Tags: oil
Jason Hobbs (jason-hobbs)
tags: added: oil
Blake Rouse (blake-rouse)
Changed in maas:
status: New → Triaged
importance: Undecided → Critical
assignee: nobody → Newell Jensen (newell-jensen)
milestone: none → next
Revision history for this message
Raphaël Badin (rvb) wrote :

Partially a duplicate of bug 1376489.

Changed in maas:
importance: Critical → High
Revision history for this message
Newell Jensen (newell-jensen) wrote :

Also possibly related to bug 1399825

We weren't seeing this kinda of duplication until just recently. Wonder if something changed somewhere else to possibly introduce this?

Revision history for this message
Jason Hobbs (jason-hobbs) wrote :

It happens sometimes and sometimes it doesn't. I think it was a side effect of a bottlenecked network - the client is resending packets many times.

Revision history for this message
Christian Reis (kiko) wrote :

I have concerns about this patch that I discussed with Jason and Newell today. Fundamentally, I don't think we should be doing any de-duplication (or folding) of events being written to the database; the issue this bug presents is a display issue, not a performance issue.

We can fold on the output side; by this I mean either doing:

  - syslog-style (timestamp N identical messages suppressed)
  - client-side (with an expander next to a cluster of identical messages)

Note that syslog-style allows one to understand the length of time over which repeated messages arrived, which for a long process that is running is a non-trivial aid to debugging.

Folding of the very last log line is an interesting problem, as the entry displayed will actually change as repeated messages come up. Consider:

  timestamp A: message 1

Later:

  timestamp B: N identical messages supressed
  timestamp A: message 1

Later:

  timestamp C: N+M identical messages suppressed
  timestamp A: message 1

Even if there are performance issues being caused by large log entries, these are a) likely bugs, i.e. bug 1402237 and b) fixable through optional trucation of old entries, which seems sane to me.

Revision history for this message
Christian Reis (kiko) wrote :

Punting from 1.7.2.

Andres Rodriguez (andreserl)
Changed in maas:
status: Triaged → Fix Released
milestone: next → 1.8.0
status: Fix Released → Fix Committed
Andres Rodriguez (andreserl)
Changed in maas:
status: Fix Committed → Fix Released
To post a comment you must log in.
This report contains Public information  
Everyone can see this information.

Duplicates of this bug

Subscribing...

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.