touch-packages team mailing list archive

[Kobus <1392317@xxxxxxxxxxxxxxxxxx>]

I'm experiencing the same on several 14.04 servers.

Here are some links showing that it is a general problem and some details regarding the bug:
http://serverfault.com/questions/608690/weird-syslog-order
http://bugzilla.adiscon.com/show_bug.cgi?id=527

** Bug watch added: bugzilla.adiscon.com/ #527
   http://bugzilla.adiscon.com/show_bug.cgi?id=527

** Changed in: rsyslog (Ubuntu)
       Status: New => Confirmed

-- 
You received this bug notification because you are a member of Ubuntu
Touch seeded packages, which is subscribed to rsyslog in Ubuntu.
https://bugs.launchpad.net/bugs/1392317

Title:
  Incorrect order of messages with RepeatedMsgReduction on

Status in rsyslog package in Ubuntu:
  Confirmed

Bug description:
  In rsyslog Version 7.4.4-1ubuntu2.3 there is a bug which mixes up the order of some messages when $RepeatedMsgReduction is enabled.
  This can sometimes result in a message missing in the current syslog and being printed even days later.
  Using Ubuntu 14.04.1 LTS.
  […]
  Nov 12 16:32:01 ws-api3 CRON[5572]: pam_unix(cron:session): session closed for user www-data
  Nov 12 16:33:01 ws-api3 CRON[5582]: pam_unix(cron:session): session opened for user www-data by (uid=0)
  Nov 10 11:56:01 ws-api3 CRON[5583]: (www-data) CMD (nice -n10 php /var/www/api/scripts/import/php/import.php all^I>> $CL/import.log 2>> $PL/api_cli_er
  rlog)
  Nov 12 16:33:01 ws-api3 CRON[5583]: (www-data) CMD (nice -n10 php /var/www/api/scripts/import/php/import.php all^I>> $CL/dev_import.log 2>> $PL/dev_ap
  i_cli_errlog)
  Nov 12 16:33:01 ws-api3 CRON[5582]: pam_unix(cron:session): session closed for user www-data
  […]

  
  To reproduce this error, turn on $RepeatedMsgReduction in the rsyslog.conf and generate a whole bunch of syslog message, e.g. with the following php script:
  <?php
  for($k=0;$k<10;$k++){
       echo "** $k **\n";
       for($i=0;$i<32768;$i++){
           exec("logger --id 'log > $k'");
       }
  }

  Result will be (after a short while):
  Nov 12 11:17:08 syslogTest vm[21410]: log > 0
  Nov 12 11:18:05 syslogTest vm[21410]: log > 1
  Nov 12 11:17:08 syslogTest vm[21412]: log > 0
  Nov 12 11:18:05 syslogTest vm[21412]: log > 1
  Nov 12 11:17:08 syslogTest vm[21414]: log > 0
  Nov 12 11:18:05 syslogTest vm[21414]: log > 1

  What's pretty suspicious is that after the pool of process IDs is exhausted and resettet, old messages are from the same process ID but from the previous iteration.
  Is RepeatedMsgReduction somehow grouping by process ID? In the first example is a cron process using the same process ID like one before, therefore printing the old message from Nov, 10. The old message was not at the position inside the syslog where it should have been.

To manage notifications about this bug go to:
https://bugs.launchpad.net/ubuntu/+source/rsyslog/+bug/1392317/+subscriptions