touch-packages team mailing list archive

[Roger Lehmann <roger.lehmann@xxxxxxxxxxxx>]

Public bug reported:

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.

** Affects: rsyslog (Ubuntu)
     Importance: Undecided
         Status: New


** Tags: mixed order repeatedmsgreduction

-- 
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:
  New

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