Syslog messages sometimes not prefixed correctly

[gconnell]

Here's a sample of syslog messages from my /var/log/messages:

Mar  3 19:27:29 rockyduck.bld.corp.google.com stenographer[10202]: 2016-03-04T02:27:29.755193Z T:921fd7 [aio.cc:190] Opening packet file /tmp/stenographer551644138/PKT0/.1457058449627005: 4
2016-03-04T02:27:29.756744Z T:919fc7 [index.cc:269] Wrote all index files for /tmp/stenographer551644138/IDX0/.1457058388538817, moving to /tmp/stenographer551644138/IDX0/1457058388538817
Mar  3 19:27:50 rockyduck.bld.corp.google.com stenographer[10202]: 2016-03-04T02:27:50.795461Z T:921fd7 [stenotype.cc:499] Thread 0 stats: MB=2413 secs=15934.3 MBps=0.151434 packets=3425698 blocks=2413 polls=16248 drops=0 drop%=0
Mar  3 19:28:30 rockyduck.bld.corp.google.com stenographer[10202]: 2016-03-04T02:28:30.872843Z T:921fd7 [aio.cc:122] Closing /tmp/stenographer551644138/PKT0/.1457058449627005 (4), truncating to 7MB and moving to /tmp/stenographer551644138/PKT0/1457058449627005
Mar  3 19:28:30 rockyduck.bld.corp.google.com stenographer[10202]: 2016-03-04T02:28:30.872979Z T:921fd7 [aio.cc:190] Opening packet file /tmp/stenographer551644138/PKT0/.1457058510749942: 4
Mar  3 19:28:30 rockyduck.bld.corp.google.com stenographer[10202]: 2016-03-04T02:28:30.874880Z T:919fc7 [index.cc:269] Wrote all index files for /tmp/stenographer551644138/IDX0/.1457058449627005, moving to /tmp/stenographer551644138/IDX0/1457058449627005
Mar  3 19:27:29 rockyduck.bld.corp.google.com stenographer[10202]: 2016-03-04T02:27:29.749447Z T:921fd7 [aio.cc:122] Closing /tmp/stenographer551644138/PKT0/.1457058388538817 (4), truncating to 6MB and moving to /tmp/stenographer551644138/PKT0/1457058388538817
Mar  3 19:27:29 rockyduck.bld.corp.google.com stenographer[10202]: 2016-03-04T02:27:29.755193Z T:921fd7 [aio.cc:190] Opening packet file /tmp/stenographer551644138/PKT0/.1457058449627005: 4
2016-03-04T02:27:29.756744Z T:919fc7 [index.cc:269] Wrote all index files for /tmp/stenographer551644138/IDX0/.1457058388538817, moving to /tmp/stenographer551644138/IDX0/1457058388538817
Mar  3 19:27:50 rockyduck.bld.corp.google.com stenographer[10202]: 2016-03-04T02:27:50.795461Z T:921fd7 [stenotype.cc:499] Thread 0 stats: MB=2413 secs=15934.3 MBps=0.151434 packets=3425698 blocks=2413 polls=16248 drops=0 drop%=0
Mar  3 19:28:30 rockyduck.bld.corp.google.com stenographer[10202]: 2016-03-04T02:28:30.872843Z T:921fd7 [aio.cc:122] Closing /tmp/stenographer551644138/PKT0/.1457058449627005 (4), truncating to 7MB and moving to /tmp/stenographer551644138/PKT0/1457058449627005
Mar  3 19:28:30 rockyduck.bld.corp.google.com stenographer[10202]: 2016-03-04T02:28:30.872979Z T:921fd7 [aio.cc:190] Opening packet file /tmp/stenographer551644138/PKT0/.1457058510749942: 4
Mar  3 19:28:30 rockyduck.bld.corp.google.com stenographer[10202]: 2016-03-04T02:28:30.874880Z T:919fc7 [index.cc:269] Wrote all index files for /tmp/stenographer551644138/IDX0/.1457058449627005, moving to /tmp/stenographer551644138/IDX0/1457058449627005

Note the two lines that start with 2016, which are missing the normal "Month Day Time Host Daemon[PID]:" prefix.

[gconnell]

These all appear to be coming from stenotype, so my guess is it's because of the fact that we pass a syslog Logger into stenotype as STDOUT/STDERR. In stenographer.go:

logwriter, err := syslog.New(syslog.LOG_USER|syslog.LOG_INFO, "stenographer")
...
stenotypeOutput = logwriter // for stenotype
...
env.StenotypeOutput = stenotypeOutput

In env/env.go:

cmd.Stdout = d.StenotypeOutput
cmd.Stderr = d.StenotypeOutput

We've got C writing to stderr, and (correctly) flusing after each write using flush here in util.h:

~LogLine() {
  ss_ << "\n";
  std::cerr << ss_.str() << std::flush;

But that flushes into STDERR, which Go picks up and tries to pipe into the syslog logwriter. It uses an os.Pipe for this that it created with writerDescriptor. I expect it's this pipe that, in certain circumstances, buffers two lines together into a single Write call to the syslog writer.