Opened 13 years ago

Closed 10 years ago

#156 closed bug (fixed)

syslog is corrupted

Reported by: marcusoverhagen Owned by: axeld
Priority: high Milestone: R1
Component: System/Kernel Version: R1/pre-alpha1
Keywords: Cc: diver, adek336@…
Blocked By: Blocking: #2732
Has a Patch: no Platform: All

Description (last modified by axeld)

Syslog doesn't properly log all dprintf messages.

initializing the /Haiku partition again didn't fix it.

examples:

(somwhere before the "KERN: em-alloc" a lot of messages are missing) KERN: con_init: trying module console/frame_buffer/v1 KERN: loaded driver /boot/beos/system/add-ons/kernel/drivers/dev/console KERN: loaded driver /boot/beos/system/add-ons/kernel/drivers/dev/dprintf KERN: loaded driver /boot/beos/system/add-ons/kernel/drivers/dev/keyboard KERN: loaded driver /boot/beos/system/add-ons/kernel/drivers/dev/null KERN: loaded driver /boot/beos/system/add-ons/kernel/drivers/dev/random KERN: loaded driver /boot/beos/system/add-ons/kernel/drivers/dev/tty KERN: loaded driver /boot/beos/system/add-ons/kernel/drivers/dev/zero KERN: loaded driver /boot/beos/systeloaded driver /boot/beos/system/add-ons/kernel/driveloaded driver /boot/beos/system/add-ons/kernel/drivers/dev/zeroloaded driver /boot/beos/system/add-ons/kernel/drivloaded driver /boot/beos/system/add-ons/kernel/driverloaded driver /boot/beos/system/add-ons/kernel/drivers/dev/zero KERN: em_alloc: size=8192, tag=0x00000000 KERN: Graphics Driver - mem_alloc: block_id=1, offset=0 KERN: Radeon - initRingBuffer: CP buffer address=1fffa000 KERN: Radeon - initRingBuffer: CP buffer size mask=10

or this one: KERN: ps2: ps2_dev_command cmd 0xf4, out 0, in 0, dev input/mouse/ps2/3 KERN: ps2: ps2_dev_command wait for ack res 0x00000000, wait-time 2446 KERN: ps2: ps2_dev_command got ACK KERN: ps2: ps2_dev_command result 0x00000000 KERN: ps2: mouse_open input/mouse/ps2/3 success KERN: ps2: mouse_open input/mouse/ps2KERN: ps2: KB_SET_KEY_REPEAT_RATE 300 KERN: ps2: set_typematic rate 300, delay 500000 KERN: ps2: ps2_dev_command cmd 0xf3, out 1, in 0, dev input/keyboard/at/0 KERN: ps2: ps2_dev_command out 0x20 KERN: ps2: ps2_dev_command wait for ack res 0x00000000, wait-time 6349

Attachments (1)

syslog (6.5 KB) - added by Adek336 10 years ago.
syslog buffer too small

Download all attachments as: .zip

Change History (9)

comment:1 Changed 13 years ago by diver

Cc: diver added

comment:2 Changed 12 years ago by axeld

Component: GeneralSystem/Kernel
Description: modified (diff)
Platform: All

comment:3 Changed 10 years ago by Adek336

Cc: adek336@… added

Changed 10 years ago by Adek336

Attachment: syslog added

syslog buffer too small

comment:4 Changed 10 years ago by Adek336

In the attachment it is like

KERN: {QW<syslog_write call count>}{QE<dprint_args call count>, <free space in buff>} message

We see it discards a thousand messages because of a too small buffer and doesn't emit any <TRUNC>s or <DROP>s.

comment:5 Changed 10 years ago by Adek336

- 74    #define SYSLOG_BUFFER_SIZE 65536
+ 74    #define SYSLOG_BUFFER_SIZE 131072

With 128 kb of buffer space, even with the additional message-number and free-space-in-buffer data stored in the buffer, the peak usage is around 100 kb. So by increasing the buffer space by 64 kb we ensure that the ~1000 messages previously dropped aren't anymore. Each of these messages is sent to the log because a programmer thought it was an important message, so loosing a thousand of them is very unfortunate and I think preserving them is worth the 64 kbs.

Perhaps SYSLOG_BUFFER_SIZE could be specified at build time in UserBuildConfig - so that if one day there is even more messages to be logged and they get dropped, one may fix the problem by tuning the build config; on the other hand, if the default buffer size was set to huge, somebody who wants to conserve memory can set it low.

        length = ring_buffer_readable(sSyslogBuffer);
        if (length > (int32)SYSLOG_MAX_MESSAGE_LENGTH)
             length = SYSLOG_MAX_MESSAGE_LENGTH;

        length = ring_buffer_read(sSyslogBuffer, 
            (uint8 *)sSyslogMessage->message, length);
  932   if (sSyslogDropped) {
  933   // add drop marker
- 934      if (length < (int32)SYSLOG_MAX_MESSAGE_LENGTH - 6)
- 935             strlcat(sSyslogMessage->message, "<DROP>", SYSLOG_MAX_MESSAGE_LENGTH);
- 936      else if (length > 7)
- 937           strcpy(sSyslogMessage->message + length - 7, "<DROP>");
+ 934      ring_buffer_write(sSyslogBuffer, (uint8 *) "<DROP>", 6);

        sSyslogDropped = false;
}

This fixes a problem with the <DROP> message being emitted in the wrong place. In the old code, if the buffer is full, sSyslogDropped is set and then, after sending approx MIN(SYSLOG_MAX_MESSAGE_LENGTH, SYSLOG_BUFFER_SIZE) the <DROP> message is emitted. SYSLOG_MAX_MESSAGE_LENGTH = approx 8192 so this is erroneus.

The proposed fix helps: <DROP> are emitted in the place, where a message has been indeed dropped.

comment:6 Changed 10 years ago by axeld

I think that the syslog size could indeed be moved to build/config_headers, although it's probably simpler to just add a kernel setting for it.

The second patch makes definitely sense, thanks, I will apply it in a minute!

comment:7 Changed 10 years ago by axeld

Blocking: 2732 added

(In #2732) Thanks for the note :-)

comment:8 Changed 10 years ago by axeld

Resolution: fixed
Status: newclosed
Version: R1 development

I guess this one can be closed.

Note: See TracTickets for help on using tickets.