tools/oxenstored: Render backtraces more nicely in Syslog

[PATCH] tools/oxenstored: Render backtraces more nicely in Syslog

Posted by Andrew Cooper 1 year, 4 months ago

fallback_exception_handler feeds a string with embedded newlines directly into
syslog().  While this is an improvement on getting nothing, syslogd escapes
all control characters it gets, and emits one (long) line into the log.

Fix the problem generally in the syslog stub.  As we already have a local copy
of the string, split it in place and emit one syslog() call per line.

Also tweak Logging.msg_of to avoid putting an extra newline on a string which
already ends with one.

Fixes: ee7815f49faf ("tools/oxenstored: Set uncaught exception handler")
Signed-off-by: Andrew Cooper <andrew.cooper3@citrix.com>
---
CC: Christian Lindig <christian.lindig@citrix.com>
CC: David Scott <dave@recoil.org>
CC: Edwin Torok <edvin.torok@citrix.com>
CC: Rob Hoes <Rob.Hoes@citrix.com>
---
 tools/ocaml/xenstored/logging.ml     |  2 +-
 tools/ocaml/xenstored/syslog_stubs.c | 26 +++++++++++++++++++++++---
 2 files changed, 24 insertions(+), 4 deletions(-)

diff --git a/tools/ocaml/xenstored/logging.ml b/tools/ocaml/xenstored/logging.ml
index 255051437d60..f233bc9a3956 100644
--- a/tools/ocaml/xenstored/logging.ml
+++ b/tools/ocaml/xenstored/logging.ml
@@ -344,7 +344,7 @@ let watch_not_fired ~con perms path =
 	access_logging ~tid:0 ~con ~data Watch_not_fired ~level:Info
 
 let msg_of exn bt =
-	Printf.sprintf "Fatal exception: %s\n%s\n" (Printexc.to_string exn)
+	Printf.sprintf "Fatal exception: %s\n%s" (Printexc.to_string exn)
 		(Printexc.raw_backtrace_to_string bt)
 
 let fallback_exception_handler exn bt =
diff --git a/tools/ocaml/xenstored/syslog_stubs.c b/tools/ocaml/xenstored/syslog_stubs.c
index e16c3a9491d0..760e78ff73dc 100644
--- a/tools/ocaml/xenstored/syslog_stubs.c
+++ b/tools/ocaml/xenstored/syslog_stubs.c
@@ -37,14 +37,34 @@ value stub_syslog(value facility, value level, value msg)
 {
 	CAMLparam3(facility, level, msg);
 	char *c_msg = strdup(String_val(msg));
+	char *s = c_msg, *ss;
 	int c_facility = __syslog_facility_table[Int_val(facility)]
 	               | __syslog_level_table[Int_val(level)];
 
 	if ( !c_msg )
 		caml_raise_out_of_memory();
-	caml_enter_blocking_section();
-	syslog(c_facility, "%s", c_msg);
-	caml_leave_blocking_section();
+
+	/*
+	 * syslog() doesn't like embedded newlines, and c_msg generally
+	 * contains them.
+	 *
+	 * Split the message in place by converting \n to \0, and issue one
+	 * syslog() call per line, skipping the final iteration if c_msg ends
+	 * with a newline anyway.
+	 */
+	do {
+		ss = strchr(s, '\n');
+		if ( ss )
+			*ss = '\0';
+		else if ( *s == '\0' )
+			break;
+
+		caml_enter_blocking_section();
+		syslog(c_facility, "%s", s);
+		caml_leave_blocking_section();
+
+		s = ss + 1;
+	} while ( ss );
 
 	free(c_msg);
 	CAMLreturn(Val_unit);
-- 
2.11.0

Re: [PATCH] tools/oxenstored: Render backtraces more nicely in Syslog

Posted by Christian Lindig 1 year, 4 months ago


> On 1 Dec 2022, at 21:19, Andrew Cooper <andrew.cooper3@citrix.com> wrote:
> 
> fallback_exception_handler feeds a string with embedded newlines directly into
> syslog().  While this is an improvement on getting nothing, syslogd escapes
> all control characters it gets, and emits one (long) line into the log.
> 
> Fix the problem generally in the syslog stub.  As we already have a local copy
> of the string, split it in place and emit one syslog() call per line.
> 
> Also tweak Logging.msg_of to avoid putting an extra newline on a string which
> already ends with one.
> 
> Fixes: ee7815f49faf ("tools/oxenstored: Set uncaught exception handler")
> Signed-off-by: Andrew Cooper <andrew.cooper3@citrix.com>
> ---
> CC: Christian Lindig <christian.lindig@citrix.com>
> CC: David Scott <dave@recoil.org>
> CC: Edwin Torok <edvin.torok@citrix.com>
> CC: Rob Hoes <Rob.Hoes@citrix.com>

Acked-by: Christian Lindig <christian.lindig@citrix.com>

> ---
> tools/ocaml/xenstored/logging.ml     |  2 +-
> tools/ocaml/xenstored/syslog_stubs.c | 26 +++++++++++++++++++++++---
> 2 files changed, 24 insertions(+), 4 deletions(-)
> 
> diff --git a/tools/ocaml/xenstored/logging.ml b/tools/ocaml/xenstored/logging.ml
> index 255051437d60..f233bc9a3956 100644
> --- a/tools/ocaml/xenstored/logging.ml
> +++ b/tools/ocaml/xenstored/logging.ml
> @@ -344,7 +344,7 @@ let watch_not_fired ~con perms path =
> 	access_logging ~tid:0 ~con ~data Watch_not_fired ~level:Info
> 
> let msg_of exn bt =
> -	Printf.sprintf "Fatal exception: %s\n%s\n" (Printexc.to_string exn)
> +	Printf.sprintf "Fatal exception: %s\n%s" (Printexc.to_string exn)
> 		(Printexc.raw_backtrace_to_string bt)
> 
> let fallback_exception_handler exn bt =
> diff --git a/tools/ocaml/xenstored/syslog_stubs.c b/tools/ocaml/xenstored/syslog_stubs.c
> index e16c3a9491d0..760e78ff73dc 100644
> --- a/tools/ocaml/xenstored/syslog_stubs.c
> +++ b/tools/ocaml/xenstored/syslog_stubs.c
> @@ -37,14 +37,34 @@ value stub_syslog(value facility, value level, value msg)
> {
> 	CAMLparam3(facility, level, msg);
> 	char *c_msg = strdup(String_val(msg));

Is this working as expected? An OCaml string may contain embedded null bytes.

> +	char *s = c_msg, *ss;
> 	int c_facility = __syslog_facility_table[Int_val(facility)]
> 	               | __syslog_level_table[Int_val(level)];
> 
> 	if ( !c_msg )
> 		caml_raise_out_of_memory();
> -	caml_enter_blocking_section();
> -	syslog(c_facility, "%s", c_msg);
> -	caml_leave_blocking_section();
> +
> +	/*
> +	 * syslog() doesn't like embedded newlines, and c_msg generally
> +	 * contains them.
> +	 *
> +	 * Split the message in place by converting \n to \0, and issue one
> +	 * syslog() call per line, skipping the final iteration if c_msg ends
> +	 * with a newline anyway.
> +	 */
> +	do {
> +		ss = strchr(s, '\n');
> +		if ( ss )
> +			*ss = '\0';
> +		else if ( *s == '\0' )
> +			break;
> +
> +		caml_enter_blocking_section();
> +		syslog(c_facility, "%s", s);
> +		caml_leave_blocking_section();
> +
> +		s = ss + 1;
> +	} while ( ss );
> 
> 	free(c_msg);
> 	CAMLreturn(Val_unit);
> -- 
> 2.11.0
>

Re: [PATCH] tools/oxenstored: Render backtraces more nicely in Syslog

Posted by Andrew Cooper 1 year, 4 months ago

On 02/12/2022 09:14, Christian Lindig wrote:
>> On 1 Dec 2022, at 21:19, Andrew Cooper <andrew.cooper3@citrix.com> wrote:
>>
>> fallback_exception_handler feeds a string with embedded newlines directly into
>> syslog().  While this is an improvement on getting nothing, syslogd escapes
>> all control characters it gets, and emits one (long) line into the log.
>>
>> Fix the problem generally in the syslog stub.  As we already have a local copy
>> of the string, split it in place and emit one syslog() call per line.
>>
>> Also tweak Logging.msg_of to avoid putting an extra newline on a string which
>> already ends with one.
>>
>> Fixes: ee7815f49faf ("tools/oxenstored: Set uncaught exception handler")
>> Signed-off-by: Andrew Cooper <andrew.cooper3@citrix.com>
>> ---
>> CC: Christian Lindig <christian.lindig@citrix.com>
>> CC: David Scott <dave@recoil.org>
>> CC: Edwin Torok <edvin.torok@citrix.com>
>> CC: Rob Hoes <Rob.Hoes@citrix.com>
> Acked-by: Christian Lindig <christian.lindig@citrix.com>

Thanks.

>
>> ---
>> tools/ocaml/xenstored/logging.ml     |  2 +-
>> tools/ocaml/xenstored/syslog_stubs.c | 26 +++++++++++++++++++++++---
>> 2 files changed, 24 insertions(+), 4 deletions(-)
>>
>> diff --git a/tools/ocaml/xenstored/logging.ml b/tools/ocaml/xenstored/logging.ml
>> index 255051437d60..f233bc9a3956 100644
>> --- a/tools/ocaml/xenstored/logging.ml
>> +++ b/tools/ocaml/xenstored/logging.ml
>> @@ -344,7 +344,7 @@ let watch_not_fired ~con perms path =
>> 	access_logging ~tid:0 ~con ~data Watch_not_fired ~level:Info
>>
>> let msg_of exn bt =
>> -	Printf.sprintf "Fatal exception: %s\n%s\n" (Printexc.to_string exn)
>> +	Printf.sprintf "Fatal exception: %s\n%s" (Printexc.to_string exn)
>> 		(Printexc.raw_backtrace_to_string bt)
>>
>> let fallback_exception_handler exn bt =
>> diff --git a/tools/ocaml/xenstored/syslog_stubs.c b/tools/ocaml/xenstored/syslog_stubs.c
>> index e16c3a9491d0..760e78ff73dc 100644
>> --- a/tools/ocaml/xenstored/syslog_stubs.c
>> +++ b/tools/ocaml/xenstored/syslog_stubs.c
>> @@ -37,14 +37,34 @@ value stub_syslog(value facility, value level, value msg)
>> {
>> 	CAMLparam3(facility, level, msg);
>> 	char *c_msg = strdup(String_val(msg));
> Is this working as expected? An OCaml string may contain embedded null bytes.

I wondered the same, but there's really nothing sane to be done.

This is for handling human readable strings, and attempting to force
NULs out via syslog() can't be done (because of syslog()'s API).

~Andrew