syslog messages truncated to 256 chars during debian-installer run

[Mike Harris]

[Impact]
Users relying on busybox within their environment and attempting to do any sort of debugging of logs.

[Test Case]
Run the installer, parse logs from syslogd packaged within busybox.

[Regression]
Minimal, only doubling buffer size for syslogd within busybox.

We're seeing syslog messages during installers runs truncated to 256 chars. This is annoying.

Digging into the debian-installer source, its calling /sbin/syslogd from the initrd - this is a busybox binary. In the busybox source, there's a config variable CONFIG_FEATURE_SYSLOGD_READ_BUFFER_SIZE that defaults to 256. From the code, that looks to be the problem.

Can we either -
1. fix busybox to use a dynamic buffer, or
2. bump the config variable up to 1024 or so?

I'm perfectly happy with solution 2 :)

[Mike Harris (mwharris-h)]

Reproduction instructions, using the binary itself.
# Extract syslogd from the Precise netboot:
wget http://archive.ubuntu.com/ubuntu/dists/precise/main/installer-amd64/current/images/netboot/netboot.tar.gz
tar xzf /home/mwharris/Downloads/netboot.tar.gz ./ubuntu-installer/amd64/initrd.gz
mkdir sbin
gzip -dc ubuntu-installer/amd64/initrd.gz | cpio -i sbin/syslogd

# Run the new syslogd.
sudo stop rsyslog # to free the port
sudo ./sbin/syslogd -n

# Now the busybox syslogd is running.
# Send a long line to syslogd
logger "watch runs command repeatedly, displaying its output and errors (the first screenfull). This allows you to watch the program output change over time. By default, the program is run every 2 seconds; use -n or --interval to specify a different interval. Normally, this interval is interpreted as the amout of time between the completion of one run of command and the beginning of the next run. However, with the -p or --precise option, you can make watch attempt to run command every interval seconds. Try it with ntptime and notice how the fractional seconds stays (nearly) the same, as opposed to normal mode where they continuously increase."

Check /var/log/messages for truncated output.

Another option to reproduce would be to look for a long line generated during install time, but I don't know of one off-hand. We're running puppet during install and it generates some long lines when it errors.

[Ubuntu Foundations Team Bug Bot (crichton)]

Thank you for taking the time to report this bug and helping to make Ubuntu better. It seems that your bug report is not filed about a specific source package though, rather it is just filed against Ubuntu in general. It is important that bug reports be filed about source packages so that people interested in the package can find the bugs about it. You can find some hints about determining what package your bug might be about at https://wiki.ubuntu.com/Bugs/FindRightPackage. You might also ask for help in the #ubuntu-bugs irc channel on Freenode.

To change the source package that this bug is filed about visit https://bugs.launchpad.net/ubuntu/+bug/1040900/+editstatus and add the package name in the text box next to the word Package.

[This is an automated message. I apologize if it reached you inappropriately; please just reply to this message indicating so.]

[Scott Kitterman (kitterman)]

Has it always been this way or is this some kind of regression.

[Dimitri John Ledkov (xnox)]

On 28 September 2012 21:49, Scott Kitterman <email address hidden> wrote:
> Has it always been this way or is this some kind of regression.
>

The setting (hardcoded to 256) first appeared in 1.10.2 release in
~2008-06-11, later there was interface introduced to modify that.

I can't quite see how'd it's been limited before 1.10.2 release,
something like there was a file limit 200*1024 bytes, after which it
was rotated =/

[Scott Kitterman (kitterman)]

If we've lived with it for 4 years, I think we can live with it another 6
months. Let's defer this to "R" and not monkey with core code for non-
critical things right before release.

[Colin Watson (cjwatson)]

The raring patch is fine, thanks, but I changed the version from ...ubuntu2.1 to ...ubuntu3, since this is the development release.

[Colin Watson (cjwatson)]

I've uploaded all these changes now, so unsubscribing ~ubuntu-sponsors to take this bug off the sponsorship list.

[Launchpad Janitor (janitor)]

This bug was fixed in the package busybox - 1:1.20.0-7ubuntu3

---------------
busybox (1:1.20.0-7ubuntu3) raring; urgency=low

  [ Timo Juhani Lindfors ]
  * increase the maximum supported log line length from 256 to 512
    bytes. (Closes: #519356, LP: #1040900)
 -- Adam Stokes <email address hidden> Mon, 05 Nov 2012 12:57:13 -0500

[Brian Murray (brian-murray)]

Hello Mike, or anyone else affected,

Accepted busybox into quantal-proposed. The package will build now and be available at http://launchpad.net/ubuntu/+source/busybox/1:1.19.3-7ubuntu1.1 in a few hours, and then in the -proposed repository.

Please help us by testing this new package. See https://wiki.ubuntu.com/Testing/EnableProposed for documentation how to enable and use -proposed. Your feedback will aid us getting this update out to other Ubuntu users.

If this package fixes the bug for you, please change the bug tag from verification-needed to verification-done. If it does not, change the tag to verification-failed. In either case, details of your testing will help us make a better decision.

Further information regarding the verification process can be found at https://wiki.ubuntu.com/QATeam/PerformingSRUVerification . Thank you in advance!

[Brian Murray (brian-murray)]

Hello Mike, or anyone else affected,

Accepted busybox into precise-proposed. The package will build now and be available at http://launchpad.net/ubuntu/+source/busybox/1:1.18.5-1ubuntu4.1 in a few hours, and then in the -proposed repository.

Please help us by testing this new package. See https://wiki.ubuntu.com/Testing/EnableProposed for documentation how to enable and use -proposed. Your feedback will aid us getting this update out to other Ubuntu users.

If this package fixes the bug for you, please change the bug tag from verification-needed to verification-done. If it does not, change the tag to verification-failed. In either case, details of your testing will help us make a better decision.

Further information regarding the verification process can be found at https://wiki.ubuntu.com/QATeam/PerformingSRUVerification . Thank you in advance!

[Javier López (javier-lopez)]

I've tested both versions of the package, precise & quantal and it works as expected:

$ cat /etc/issue
Ubuntu 12.04.1 LTS \n \l

Nov 21 01:50:00 precise syslog.info syslogd started: BusyBox v1.18.5
Nov 21 01:50:09 precise user.notice chilicuil: watch runs command repeatedly, displaying its output and errors (the first screenfull). This allows you to watch the program output change over time. By default, the program is run every 2 seconds; use -n or --interval to sp

$ apt-cache policy busybox
busybox:
  Installed: 1:1.18.5-1ubuntu4.1
  Candidate: 1:1.18.5-1ubuntu4.1
  Version table:
 *** 1:1.18.5-1ubuntu4.1 0
        500 http://us.archive.ubuntu.com/ubuntu/ precise-proposed/universe i386 Packages
        100 /var/lib/dpkg/status
     1:1.18.5-1ubuntu4 0
        500 http://us.archive.ubuntu.com/ubuntu/ precise/universe i386 Packages

$ sudo stop rsyslog

$ sudo busybox syslogd -n

$ logger "watch runs command repeatedly, displaying its output and errors (the first screenfull). This allows you to watch the program output change over time. By default, the program is run every 2 seconds; use -n or --interval to specify a different interval. Normally, this interval is interpreted as the amout of time between the completion of one run of command and the beginning of the next run. However, with the -p or --precise option, you can make watch attempt to run command every interval seconds. Try it with ntptime and notice how the fractional seconds stays (nearly) the same, as opposed to normal mode where they continuously increase."

$ vim /var/log/messages

-- With busybox ubuntu4
Nov 21 01:50:00 precise syslog.info syslogd started: BusyBox v1.18.5
Nov 21 01:50:09 precise user.notice chilicuil: watch runs command repeatedly, displaying its output and errors (the first screenfull). This allows you to watch the program output change over time. By default, the program is run every 2 seconds; use -n or --interval to sp

-- With busybox ubuntu4.1 (this patch)
Nov 21 01:45:18 precise syslog.info syslogd started: BusyBox v1.18.5
Nov 21 01:46:07 precise user.notice chilicuil: watch runs command repeatedly, displaying its output and errors (the first screenfull). This allows you to watch the program output change over time. By default, the program is run every 2 seconds; use -n or --interval to specify a different interval. Normally, this interval is interpreted as the amout of time between the completion of one run of command and the beginning of the next run. However, with the -p or --precise option, you can make watch attempt to run command ever

It doubles the capacity to hold number of characters in a line, the same behavior is for Quantal, I didn't provide the outputs for it, however they're the same (except for the versions involved), however if it's needed I'd be happy to add them.

I'm modifying the tag to verification-done

Greetings.

--------------------------
Ubuntu Bug Squad volunteer triager
http://wiki.ubuntu.com/BugSquad

[Launchpad Janitor (janitor)]

This bug was fixed in the package busybox - 1:1.18.5-1ubuntu4.1

---------------
busybox (1:1.18.5-1ubuntu4.1) precise-proposed; urgency=low

  [ Timo Juhani Lindfors ]
  * increase the maximum supported log line length from 256 to 512
    bytes. (Closes: #519356, LP: #1040900)
 -- Adam Stokes <email address hidden> Fri, 28 Sep 2012 16:11:14 -0400

[Scott Kitterman (kitterman)]

The verification of this Stable Release Update has completed successfully and the package has now been released to -updates. Subsequently, the Ubuntu Stable Release Updates Team is being unsubscribed and will not receive messages about this bug report. In the event that you encounter a regression using the package from -updates please report a new bug using ubuntu-bug and tag the bug report regression-update so we can easily find any regresssions.

[Launchpad Janitor (janitor)]

This bug was fixed in the package busybox - 1:1.19.3-7ubuntu1.1

---------------
busybox (1:1.19.3-7ubuntu1.1) quantal-proposed; urgency=low

  [ Timo Juhani Lindfors ]
  * increase the maximum supported log line length from 256 to 512
    bytes. (Closes: #519356, LP: #1040900)
 -- Adam Stokes <email address hidden> Fri, 28 Sep 2012 16:11:14 -0400