[LEDE-DEV] Bug when processing long lines

Message ID 173cfe61-4966-2870-ce78-677385a2602a@braiins.cz
State Superseded
Delegated to: John Crispin
Headers show
Series
  • [LEDE-DEV] Bug when processing long lines
Related show

Commit Message

Jakub Horák Jan. 11, 2018, 4:28 p.m.
Hello LEDE developers,

I found a bug in procd that gets triggered when long lines are printed
by services whose stdout/stderr are being logged. The bug itself is
explained in the attached patch.

However, when I was testing the fix, I found out that the bug is present
in other places, mostly those that call "ustream_get_read_buf" function.
Some examples:

- ubox/log/logread.c:logread_fb_data_cb() - when buffer passed on the
descriptor is larger than 4096, reception stops
- netifd/main.c:netifd_process_log_read_cb - this is a place that seems
to have this bug fixed, but still has incorrect handling of NUL bytes
- libubox/examples/ustream-example.c:client_read_cb - this is probably
the place that originated this broken bit of code
- uhttpd/relay.c:relay_process_headers - another place that seems broken

I've attached an init script (that goes to /etc/init.d/flood) and three
Lua programs (flood[123].lua) that trigger this behavior:
- flood1.lua writes long message to stdout, that triggers this behavior
in procd
- flood2.lua writes message that gets correctly processed by procd, but
triggers the bug in logread
- flood3.lua writes message with embedded zeros

I don't post patches to mailing lists very often, so I apologize if I'm
sending this in a wrong format or in a too broken english.

Best regards,
Jakub Horak
#!/bin/sh /etc/rc.common

START=99

USE_PROCD=1
PROG=/bin/flood1.lua

start_service()
{
	config_load cgminer

	procd_open_instance
	procd_set_param command "$PROG" 
	procd_set_param respawn ${respawn_threshold:-3600} ${respawn_timeout:-5} ${respawn_retry:-0}
	procd_set_param stdout 1
	procd_set_param stderr 1
	procd_close_instance
}

stop_service()
{
	echo stop
}

service_triggers()
{
	procd_add_reload_trigger "flood"
}

Comments

Alexandru Ardelean Jan. 11, 2018, 7:26 p.m. | #1
On Thu, Jan 11, 2018 at 6:28 PM, Jakub Horák <jakub.horak@braiins.cz> wrote:
> Hello LEDE developers,
>
> I found a bug in procd that gets triggered when long lines are printed
> by services whose stdout/stderr are being logged. The bug itself is
> explained in the attached patch.
>
> However, when I was testing the fix, I found out that the bug is present
> in other places, mostly those that call "ustream_get_read_buf" function.
> Some examples:
>
> - ubox/log/logread.c:logread_fb_data_cb() - when buffer passed on the
> descriptor is larger than 4096, reception stops
> - netifd/main.c:netifd_process_log_read_cb - this is a place that seems
> to have this bug fixed, but still has incorrect handling of NUL bytes
> - libubox/examples/ustream-example.c:client_read_cb - this is probably
> the place that originated this broken bit of code
> - uhttpd/relay.c:relay_process_headers - another place that seems broken
>
> I've attached an init script (that goes to /etc/init.d/flood) and three
> Lua programs (flood[123].lua) that trigger this behavior:
> - flood1.lua writes long message to stdout, that triggers this behavior
> in procd
> - flood2.lua writes message that gets correctly processed by procd, but
> triggers the bug in logread
> - flood3.lua writes message with embedded zeros
>
> I don't post patches to mailing lists very often, so I apologize if I'm
> sending this in a wrong format or in a too broken english.

Hey,

Patches usually are sent with git send-mail.
So  "git send-mail
0001-procd-Fix-behavior-when-parsing-long-lines.patch
--to=openwrt-devel@lists.openwrt.org"
[ FWIW: LEDE has merged back to OpenWrt :) ]

Now about the patch.

-       str = ustream_get_read_buf(s, NULL);
+       str = ustream_get_read_buf(s, &buflen);
        if (!str)
            break;

-       newline = strchr(str, '\n');
-       if (!newline)
-           break;
-
-       *newline = 0;
+       /* search for '\n', take into account NUL bytes */
+       newline = memchr(str, '\n', buflen);
+       if (!newline) {
+           /* is there a room in buffer? */
+           if (buflen < s->r.buffer_len) {
+               /* yes - bailout, newline may still come */
+               break;
+           } else {
+               /* no - force newline */
+               len = buflen;

It's weird that this would happen here, since there should be a
ustream_reserve() call that would guarantee that there is sufficient
buffer size.
I could be wrong, or it could be a bug somewhere; who knows ?

In any case, if this is a correct approach, I think you should also
add  *(str + len) = 0  ; to make sure the string is null-terminated.

+           }
+       } else {
+           *newline = 0;
+           len = newline + 1 - str;
+       }
+       /* "str" is NUL terminated by ustream_get_read_buf */
        ulog(prio, "%s\n", str);
-
-       len = newline + 1 - str;
        ustream_consume(s, len);


Alex

>
> Best regards,
> Jakub Horak
>
> _______________________________________________
> Lede-dev mailing list
> Lede-dev@lists.infradead.org
> http://lists.infradead.org/mailman/listinfo/lede-dev
>
Jakub Horák Jan. 12, 2018, 10:13 a.m. | #2
Hello,

On 01/11/2018 08:26 PM, Alexandru Ardelean wrote:
>> I don't post patches to mailing lists very often, so I apologize if I'm
>> sending this in a wrong format or in a too broken english.
> 
> Hey,
> 
> Patches usually are sent with git send-mail.
> So  "git send-mail
> 0001-procd-Fix-behavior-when-parsing-long-lines.patch
> --to=openwrt-devel@lists.openwrt.org"
> [ FWIW: LEDE has merged back to OpenWrt :) ]

So... should I resend it there?

> Now about the patch.
> 
> -       str = ustream_get_read_buf(s, NULL);
> +       str = ustream_get_read_buf(s, &buflen);
>         if (!str)
>             break;
> 
> -       newline = strchr(str, '\n');
> -       if (!newline)
> -           break;
> -
> -       *newline = 0;
> +       /* search for '\n', take into account NUL bytes */
> +       newline = memchr(str, '\n', buflen);
> +       if (!newline) {
> +           /* is there a room in buffer? */
> +           if (buflen < s->r.buffer_len) {
> +               /* yes - bailout, newline may still come */
> +               break;
> +           } else {
> +               /* no - force newline */
> +               len = buflen;
> 
> It's weird that this would happen here, since there should be a
> ustream_reserve() call that would guarantee that there is sufficient
> buffer size.
> I could be wrong, or it could be a bug somewhere; who knows ?

The buffer might be full at this point and that's OK - we are checking
just after we read data into it. However if the buffer is full and it
doesn't contain a newline - then it will never contain a new-line -
because its full.
> 
> In any case, if this is a correct approach, I think you should also
> add  *(str + len) = 0  ; to make sure the string is null-terminated.

The string is guaranteed to be null terminated, see the comment six
lines bellow:

> +           }
> +       } else {
> +           *newline = 0;
> +           len = newline + 1 - str;
> +       }
> +       /* "str" is NUL terminated by ustream_get_read_buf */
>         ulog(prio, "%s\n", str);
> -
> -       len = newline + 1 - str;
>         ustream_consume(s, len);
> 
> 
> Alex

Best regards,
Jakub


> 
>>
>> Best regards,
>> Jakub Horak
>>
>> _______________________________________________
>> Lede-dev mailing list
>> Lede-dev@lists.infradead.org
>> http://lists.infradead.org/mailman/listinfo/lede-dev
>>
John Crispin Feb. 13, 2018, 4:01 p.m. | #3
On 11/01/18 17:28, Jakub Horák wrote:
> Hello LEDE developers,
>
> I found a bug in procd that gets triggered when long lines are printed
> by services whose stdout/stderr are being logged. The bug itself is
> explained in the attached patch.
>
> However, when I was testing the fix, I found out that the bug is present
> in other places, mostly those that call "ustream_get_read_buf" function.
> Some examples:
>
> - ubox/log/logread.c:logread_fb_data_cb() - when buffer passed on the
> descriptor is larger than 4096, reception stops
> - netifd/main.c:netifd_process_log_read_cb - this is a place that seems
> to have this bug fixed, but still has incorrect handling of NUL bytes
> - libubox/examples/ustream-example.c:client_read_cb - this is probably
> the place that originated this broken bit of code
> - uhttpd/relay.c:relay_process_headers - another place that seems broken
>
> I've attached an init script (that goes to /etc/init.d/flood) and three
> Lua programs (flood[123].lua) that trigger this behavior:
> - flood1.lua writes long message to stdout, that triggers this behavior
> in procd
> - flood2.lua writes message that gets correctly processed by procd, but
> triggers the bug in logread
> - flood3.lua writes message with embedded zeros
>
> I don't post patches to mailing lists very often, so I apologize if I'm
> sending this in a wrong format or in a too broken english.
>
> Best regards,
> Jakub Horak

Hi Jakub,

i've just posted and alternative solution. could you help test it please ?

     John


>
>
> _______________________________________________
> Lede-dev mailing list
> Lede-dev@lists.infradead.org
> http://lists.infradead.org/mailman/listinfo/lede-dev
Jakub Horák Feb. 14, 2018, 11:11 a.m. | #4
On 02/13/2018 05:01 PM, John Crispin wrote:
>> I found a bug in procd that gets triggered when long lines are printed
>> by services whose stdout/stderr are being logged. The bug itself is
>> explained in the attached patch.
[SNIP]
> 
> Hi Jakub,
> 
> i've just posted and alternative solution. could you help test it please ?
> 
>     John

Hello John,
I currently do not have time to test it. But I've attached script to
trigger this bug in my previous e-mail, so I should be fairly easy to
run the test.

Best regards,
Jakub Horak

Patch

From c4ea27994bfa81e38dff9ccf9a92a33b5c612407 Mon Sep 17 00:00:00 2001
From: Jakub Horak <jakub.horak@braiins.cz>
Date: Thu, 11 Jan 2018 16:47:50 +0100
Subject: [PATCH] procd: Fix behavior when parsing long lines

Processing of service stdout/stderr is silently stopped when long lines (>4096 bytes)
are encountered. Moreover, when NUL byte (0) is received on input, the
processing is stopped as well.

When reading long lines procd waits until a newline character is received
even though receive buffer is full. At that moment the file-descriptor is
removed from epoll and communication stopson that descriptor stops. Similar
thing happens with NUL byte, only that the newline is not found because "NUL"
stops strchr() from processing further down the string.

This patch corrects the behavior: long lines are broken into smaller ones with
forced newline and NUL bytes are skipped when searching for a newline.

Signed-off-by: Jakub Horak <jakub.horak@braiins.cz>
---
 service/instance.c | 26 ++++++++++++++++++--------
 1 file changed, 18 insertions(+), 8 deletions(-)

diff --git a/service/instance.c b/service/instance.c
index a968a0b..0293099 100644
--- a/service/instance.c
+++ b/service/instance.c
@@ -461,24 +461,34 @@  instance_stdio(struct ustream *s, int prio, struct service_instance *in)
 {
 	char *newline, *str, *arg0, ident[32];
 	int len;
+	int buflen;
 
 	arg0 = basename(blobmsg_data(blobmsg_data(in->command)));
 	snprintf(ident, sizeof(ident), "%s[%d]", arg0, in->proc.pid);
 	ulog_open(ULOG_SYSLOG, LOG_DAEMON, ident);
 
 	do {
-		str = ustream_get_read_buf(s, NULL);
+		str = ustream_get_read_buf(s, &buflen);
 		if (!str)
 			break;
 
-		newline = strchr(str, '\n');
-		if (!newline)
-			break;
-
-		*newline = 0;
+		/* search for '\n', take into account NUL bytes */
+		newline = memchr(str, '\n', buflen);
+		if (!newline) {
+			/* is there a room in buffer? */
+			if (buflen < s->r.buffer_len) {
+				/* yes - bailout, newline may still come */
+				break;
+			} else {
+				/* no - force newline */
+				len = buflen;
+			}
+		} else {
+			*newline = 0;
+			len = newline + 1 - str;
+		}
+		/* "str" is NUL terminated by ustream_get_read_buf */
 		ulog(prio, "%s\n", str);
-
-		len = newline + 1 - str;
 		ustream_consume(s, len);
 	} while (1);
 
-- 
2.7.4