Opened 7 years ago

Closed 6 years ago

#3000 closed defect (complete)

reproduce mixed log issues

Reported by: jinmei Owned by: UnAssigned
Priority: medium Milestone: bind10-1.2-release-freeze
Component: logging Version:
Keywords: Cc:
CVSS Scoring: Parent Tickets:
Sensitive: no Defect Severity: N/A
Sub-Project: Core Feature Depending on Ticket:
Estimated Difficulty: 5 Add Hours to Ticket: 0
Total Hours: 0 Internal?: no

Description

This is a subtask of #2900 and focuses on the specific suggestion
at https://bind10.isc.org/ticket/2900#comment:5

So what to do is:

  • try to reproduce the issue in a simpler scenario, like writing a simple multi-process Python program dumping logs and running it multiple times. We know this happens on macmini.lab.isc.org, so if we are lucky we should be able to reproduce it on that machine.

Then, not to spend too much time for this focused task:

  • if we can reproduce it and can easily identify and fix the cause, do it within this ticket.
  • if we can reproduce it but can't easily identify and/or fix the cause, stop at that point, defer it to a separate ticket (create it), and close this one
  • if we can't even easily reproduce it, stop at that point, close this ticket, add the fact as a comment for #2900

Subtickets

Change History (5)

comment:1 Changed 7 years ago by muks

  • Milestone changed from Next-Sprint-Proposed to Sprint-20130625

comment:2 Changed 7 years ago by muks

  • Estimated Difficulty changed from 0 to 5

comment:3 Changed 7 years ago by vorner

  • Owner set to vorner
  • Status changed from new to accepted

comment:4 Changed 7 years ago by vorner

  • Owner changed from vorner to UnAssigned
  • Status changed from accepted to reviewing

Hello

I added a src/bin/mixes script. It's python that forks 8 processes and each runs in 8 threads, all of them just logging.

There's a configuration at the top for the logging. What I noticed is, if flush is true, no mixing happens to me, if it's false, it produces mixed messages. Do you know what the logging configuration is on the mentioned machine? To see if it happens with this program too?

There's a shellscript, check-file-log, that greps and finds messages that don't look correctly.

Sometimes, it produced only few mixed messages. They were all at the top of the file. I don't know if it might be related to the configuration of the logger (like that the disturbance happens only when it is newly configured) or something.

comment:5 Changed 6 years ago by stephen

  • Resolution set to complete
  • Status changed from reviewing to closed

Reviewed commit b3b16651cfdaf35aae6f2bfa367b8531622bbb8d

Running on Ubuntu 12.04, I can reproduce the behaviour described by vorner:

a) If flush is true, no mixing happens, if it's false, it produces mixed messages.

b) If mixed messages occur, they tend to be at the head of the file (and rare): in a 640,008-line file, three runs of the b10-mixer each produced seven mixed messages, all within the first 4,000 lines. (I speculate that each mixed message is the result of the first write by a new process.)

c) Not mentioned by vorner, towards the end of the file (all after line 600,000) in each run were seven blank lines. (I speculate that each is caused by a process terminating.)

It is not clear what is happening and so, as per the ticket description, this ticket is being closed. Ticket #2900 is left open as the development task for fixing the problem.

Branch trac3000 (that contains the code reproducing the issue) is not being merged to master. A note that this branch contains such code is being added to the notes in #2900.

Note: See TracTickets for help on using tickets.