Offer a means to send the tty to the Apple log system by akimd · Pull Request #196 · moby/hyperkit

akimd · 2018-03-29T12:36:42Z

On Docker for Windows, all the logs are aggregated: GUI, LinuxKit, etc. Currently debugging on Docker for Mac is less easy, in particular because LinuxKit's log are sent to the consolefile rings of fixed sized buffers. As a result, it's hard to find the interleaving of actions between Docker for Mac and LinuxKit, the console files are fragmented and full of '\0', etc.

It is possible to have hyperkit redirect the tty's output to its stderr/stdout, and then its caller (Docker for Mac's driver) could redirect these streams to the logger. Unfortunately on recent macOS releases, asl is replaced by os_log which uses exclusively the path of the executable as source (changing argv[0] is useless). As a result, hyperkit's logs are "credited" to the driver.

The most elegant approach is to embrace asl/os_log.

Currently Docker for Mac still targets 10.11, and os_log appeared in macOS 10.12, so we cannot use directly os_log's API, we use it through the asl shim.

add a new device configuration, asl, that sends the tty's output to asl
in Go, add a new ConsoleLog enum to enum it.

Since some of the logs use escapes for the terminal, escapes appear in the logs. But that's another issue.

2018-03-30 10:09:04.784291 +0200	par défaut	75122	com.docker.hyperkit	\^[[34mINFO\^[[0m[0000] starting containerd                           \^[[34mmodule\^[[0m=containerd \^[[34mrevision\^[[0m=9b55aab90508bd389d7654c4baf173a981477d55 \^[[34mversion\^[[0m=v1.0.1
2018-03-30 10:09:04.785597 +0200	par défaut	75122	com.docker.hyperkit	\^[[34mINFO\^[[0m[0000] loading plugin "io.containerd.content.v1.content"...  \^[[34mmodule\^[[0m=containerd \^[[34mtype\^[[0m=io.containerd.content.v1
2018-03-30 10:09:04.786756 +0200	par défaut	75122	com.docker.hyperkit	\^[[34mINFO\^[[0m[0000] loading plugin "io.containerd.snapshotter.v1.btrfs"...  \^[[34mmodule\^[[0m=containerd \^[[34mtype\^[[0m=io.containerd.snapshotter.v1
2018-03-30 10:09:04.788161 +0200	par défaut	75122	com.docker.hyperkit	\^[[33mWARN\^[[0m[0000] failed to load plugin io.containerd.snapshotter.v1.btrfs  \^[[33merror\^[[0m="path /var/lib/containerd/io.containerd.snapshotter.v1.btrfs must be a btrfs filesystem to be used with the btrfs snapshotter" \^[[33mmodule\^[[0m=containerd

rn · 2018-03-29T19:10:05Z

Couple of generic comments:

for C code please follow CODINGSTYLE.md
there is a bunch of conditional code for apple/darwin. HyperKit is specifically for Darwin so there is no need for that unless the source is shared with bhyve

Signed-off-by: Akim Demaille <akim.demaille@docker.com>

In some earlier experiment this function was called several times. Since it made the code slightly easier to understand, I left it. Signed-off-by: Akim Demaille <akim.demaille@docker.com>

Hyperkit.check verifies that if `h.Console == ConsoleStdio`, then either `isTerminal(os.Stdout)` or `h.StateDir != ""`. In the next commit, the device configuration becomes more complex, and simplifying this conditional by eliminating impossible situations makes this next commit clearer. Signed-off-by: Akim Demaille <akim.demaille@docker.com>

akimd · 2018-03-30T08:51:07Z

Hi @rn. Thanks for the tips!

I have reached a point where this is really nice to use from Docker for Mac.

ijc · 2018-04-03T11:18:27Z

src/lib/asl.c

+		buf = malloc(buf_capacity);
+	} else {
+		buf_capacity *= 2;
+		buf = realloc(buf, buf_capacity);


Both malloc and realloc can fail so you need to check here. Take extra care with realloc not to leak the original buffer -- although given there isn't much error handling you can do without a lot of reworking perhaps an xhyve_abort would be a reasonable choice and then leaks are somewhat immaterial.

You could also simplify using the fact that realloc(NULL, N) is equivalent to malloc(N).

I did not check that allocation succeeded, because there are many places where this is not done, starting with that very file

hyperkit/src/lib/uart_emul.c

Line 650 in b2a7a6a

sc = calloc(1, sizeof(struct uart_softc));

What would you recommend? perror + exit?

ijc · 2018-04-03T11:18:51Z

src/lib/uart_emul.c


 	struct ttyfd tty;
 	struct log log;
+        bool	asl;		/* Output to Apple logger. */


GH's rendering suggests a tabs vs spaces issue here

ijc · 2018-04-03T11:19:27Z

src/lib/uart_emul.c

+		} else if (strcmp("asl", backend) == 0) {
+                        sc->asl = true;
+                        asl_init();
+			retval = 0;


More tab/space issues?

ijc · 2018-04-03T11:23:22Z

go/hyperkit.go

 }

+// openTty opens the tty files for reading, and returns it.
+func (h *HyperKit) openTty() *os.File {


TTY is an abbreviation so either openTTY or opentty throughout would be preferable.

Signed-off-by: Akim Demaille <akim.demaille@docker.com>

akimd · 2018-04-03T11:39:31Z

I uploaded a version that should address your concerns. Thanks!

rn

c725002 should be split up into two commits, one which changes the hyperkit code and one which updates the go code.

rn · 2018-04-03T12:18:21Z

src/lib/asl.c

+/* Grow buf/buf_capacity. */
+static void buf_grow(void)
+{
+	buf_capacity = buf_capacity ? 2 * buf_capacity : 1024;


Why not initialise the buffer capacity to 1024 in asl_init() and then just grow from there? Also, we should probably add an upper bound unconditionally flush if it is reached. Or more generally, is there a reason you just don't allocate a fixed buffer of, say 4k and flush it when it's full (or on \n). Seem's much simpler.

I hesitated, but the code was so simple to make it dynamic, that I chose the safest path.

rn · 2018-04-03T12:25:01Z

src/lib/asl.c

+static aslmsg log_msg = NULL;
+
+static unsigned char *buf = NULL;
+static size_t buf_size = 0;


buf_size seems misnamed, as it is not the size of the buffer, but rather the index into the buffer where to write.

That would depend on what you call size. Size is the size of the contents of the buffer (0 when it's empty). Capacity is the "available size".

In pretty much all the code I know which handles buffers in C, size/sz etc refers to the size of a buffer (not the size of the contents). IMHO, something like buf_idx is much clearer

rn · 2018-04-03T12:26:31Z

src/lib/uart_emul.c

 			ttywrite(&sc->tty, value);
 			if (sc->log.ring)
 				ringwrite(&sc->log, value);
+			if (sc->asl)


below it looks like the asl and log are exclusive, as a else if is used while here it seems as if they can be used together.

I don't see that they are exclusive. What do you mean?

sorry, I misread the snippet of code from below. This is fine.

ijc · 2018-04-03T12:25:56Z

src/lib/asl.c

+	if (!buf) {
+		perror("buf_grow");
+		exit(1);
+	}


I'd have used xhyve_abort but this is ok too I guess.

There were several exit(1) already. I don't know which coding style to follow, there are too many.

I think it depends on whether the code was originally kernel, library or application code in the FreeBSD bhyve stack. Looks like xhyve_abort is only in "kernel" code so that was a bad suggestion, sorry. In src/lib abort and exit are basically even so lets stick with exit.

ijc · 2018-04-03T12:35:37Z

src/lib/asl.c

+	if (buf_size + 1 >= buf_capacity) {
+		buf_grow();
+	}
+	if (c == '\n') {


I'm slightly concerned about what happens if the console is e.g. running some sort of curses app or something where \n might conceivably be quite rare, it could end up building up quite a large buffer.

Perhaps add an upper bound on the buffer and flush then even if no \n is observed?

Also don't you need to handle \0 specially here? Without such handling the buffer passed to asl_log will be truncated at any NUL in the stream. Perhaps just treat \0 as equivalent to \n?

I have no idea what can be sent to tty here, whatever you suggest, I'll buy! I'm fine with your \0 = \n approach, or \0 = \\0 to make it visible, etc.

If you are aware of a tty2text approach, I'll take it too.

I think what can be sent to the console here is effectively arbitrary bytes, could be anything, from raw binary to utf-16 encoded text, there's probably no good universal answer. Most frequently it'll be ASCII or UTF-8 though plus some escape codes, I expect.

How about:

Put an upper limit of 4K on the buffer. If we reach this limit then flush unconditionally (could also make it a static 4K buffer if you like since the dynamism is no longer that important with a static limit in place).

Treat \n and \0 the same: do not inject them in the log stream, instead flush the current buffer.

For \ insert it as \\ (i.e. escape it, to distinguish from the result of the next rule)

If !isprint(c) then escape it as hex \xx

otherwise simply insert c as is.

This should preserve all of the useful text in the common case without injecting control characters or anything too weird into ASL (which I don't expect to handle anything especially crazy). It's not quite reversible since we've lost the distinction between \n and \0 but I think it'll do, including the \n would make things pretty unreadable in the common case.

The escaping makes the buffer size check a little more complicated, since it's no longer 1:1. I suggest just growing when you reach capacity - 3 rather than being too fancy.

If we put an upper limit of 4k on the buffer, why not just statically allocate it?

I don't like the escaping of !isprint. In my pet project I did exactly that, and as a result, every single UTF-8 non-ascii character was broken. I think we should not try to be too smart here.

Looking at http://www.manpagez.com/man/3/asl_log/ I'm half wondering if perhaps ASL is already setup to deal with such things correctly. There's a bunch of ASL_ENCODING_* which look to only be used with asl_add_output_file but there seems to be a general implication that the internal DB treats things as NUL terminated strings ("All keys and values are NUL-character terminated C language strings. UTF-8 encoding may be used for non-ASCII characters.") and it understands escaping in the presentation layer to some extent.

So, while I'm a bit wary that we're going to bring things crashing down around us lets try just flushing on a) 4K limit and b) on \n or \0 and hope for the best.

On Docker for Windows, all the logs are aggregated: GUI, LinuxKit, etc. Currently debugging on Docker for Mac is less easy, in particular because LinuxKit's log are sent to the consolefile rings of fixed sized buffers. As a result, it's hard to find the interleaving of actions between Docker for Mac and LinuxKit, the console files are fragmented and full of '\0', etc. It is possible to have hyperkit redirect the tty's output to its stderr/stdout, and then its caller (Docker for Mac's driver) could redirect these streams to the logger. Unfortunately on recent macOS releases, asl is replaced by os_log which uses exclusively the path of the executable as source (changing `argv[0]` is useless). As a result, hyperkit's logs are "credited" to the driver. The most elegant approach is to embrace asl/os_log. Currently Docker for Mac still targets 10.11, and os_log appeared in macOS 10.12, so we cannot use directly os_log's API, we use it through the asl shim. Add a new device configuration, asl, that sends the tty's output to asl. Signed-off-by: Akim Demaille <akim.demaille@docker.com>

Signed-off-by: Akim Demaille <akim.demaille@docker.com>

Suggested by Rolf Neugebauer. Signed-off-by: Akim Demaille <akim.demaille@docker.com>

Suggested by Ian Campbell. Signed-off-by: Akim Demaille <akim.demaille@docker.com>

Suggested by Rolf Neugebauer. Signed-off-by: Akim Demaille <akim.demaille@docker.com>

ijc · 2018-04-03T15:53:52Z

src/lib/asl.c

+		asl_log(asl, log_msg, ASL_LEVEL_NOTICE, "%s", buf);
+		buf_idx = 0;
+	} else {
+		if (buf_idx + 2 >= sizeof buf) {


Please use sizeof(buf). If it were me I would also prefer to write buf_idx + 1 > sizeof(buf) but each to his own.

I also prefer strict comparisons. And as a matter of fact, I also prefer stick to < and <= only, and never > or >= (lesson taught from Paul Eggert, a mentor of mine). But many people object to this style, and I wish to go forward, not open new debates.

Here, what I mean is if (! (buf_idx + 2 < sizeof buf)), so >= expresses more naturally the constraint.

Suggested by Ian Campbell.

rn

After the code looks ok, the commit need to be re-arranged. There should be:

One commit adding ASL support to hyperkit
One commit for whitespace clean up
One commit to fix the link
One commit for the changes to the go bindings

rn · 2018-04-04T09:20:28Z

src/lib/asl.c

+		buf_idx = 0;
+	} else {
+		if (buf_idx + 2 >= sizeof(buf)) {
+			/* Running out of space, flush.  */


How does this flush the buffer? I would also expect this to reset the buf_idx. Actually the size check should be in the first conditional, something like:
if \n or \0 or if buffer is full, flush it otherwise add character to buffer.

Well, asl_put('\n') flushes. Where should I start to help us see it?

but then you start writing over the end of the buffer...

It took me a moment to grok that too. How about adding asl_flush() with the contents of the \n case and calling that from both?

@ijc Ok, good idea. @rn sorry, I don't understand what you mean.

@rn I think buf_idx + 2 >= sizeof(buf) ensures there is enough space for the \0 which would be added for flushing. I'm not quite sure why it is +2 rather than +1 though, with the use of >= it seems like it would flush a byte too soon (but, meh).

@ijc just pointed out the "subtle" recursive call to asl_put(). This is just plain crazy! don't do that.

I suppose intruding on the asl_* namespace also used by the OS provided functions is moderately confusing. Perhaps our wrappers should all be xhyve_asl_* to avoid that?

Suggested by Ian Campbell. Signed-off-by: Akim Demaille <akim.demaille@docker.com>

rn · 2018-04-05T07:32:24Z

src/lib/log.c

+static void log_flush(void)
+{
+	buf[buf_idx] = 0;
+	asl_log(log_client, log_msg, ASL_LEVEL_NOTICE, "%s", buf);


If I read the code which calls this function correctly in neither case where this function is called do you null terminate buf. So, how does asl_log() know how long buf is?

Hi @rn. Again, I'm sorry, but I don't know what you mean. It seems to me that you missed line 32, or I misunderstand your sentence.

sorry, my bad. shouldn't review code without having coffee before

rn · 2018-04-05T09:27:18Z

src/lib/log.c

+	if ((c == '\n') || (c == 0)) {
+		log_flush();
+	} else {
+		if (buf_idx + 2 >= sizeof(buf)) {


this now seems to waste one byte.

But more in general maybe have something like:

if (buf_idx + 2 >= sizeof(buf)) { buf[buf_idx++] = c; c = 0; } if ((c == '\n') || (c == 0)) { buf[buf_idx] = 0; asl_log(log_client, log_msg, ASL_LEVEL_NOTICE, "%s", buf); buf_idx = 0; } else { buf[buf_idx++] = c; }

This would keep everything in one function, but it's a matter of taste, i guess

Yes, I guess. I dislike assignments such as c=0 (I try to stick to some SSA form), and side-effects in expressions such as buf[buf_idx++]. Besides, in some situations you are now adding a \n (and 0) in the buffer.

akimd · 2018-04-09T12:28:39Z

Superseded by #199.

akimd force-pushed the asl branch 5 times, most recently from f7f7584 to 888ac48 Compare March 29, 2018 15:12

akimd force-pushed the asl branch from 888ac48 to 97afe4e Compare March 30, 2018 06:14

akimd added 3 commits March 30, 2018 08:53

doc: update link to freebsd uncrustify's config file

5083e30

Signed-off-by: Akim Demaille <akim.demaille@docker.com>

Go: factor and log the opening of the tty file

f107b67

In some earlier experiment this function was called several times. Since it made the code slightly easier to understand, I left it. Signed-off-by: Akim Demaille <akim.demaille@docker.com>

akimd force-pushed the asl branch 2 times, most recently from 7179ee9 to cba5521 Compare March 30, 2018 07:08

akimd changed the title ~~[wip] Asl~~ Offer a means to send the tty to the logs Mar 30, 2018

akimd force-pushed the asl branch 2 times, most recently from 50794bf to d72b731 Compare March 30, 2018 08:19

akimd mentioned this pull request Mar 30, 2018

[wip] Improve logs for Docker for Mac #195

Closed

akimd changed the title ~~Offer a means to send the tty to the logs~~ Offer a means to send the tty to the Apple log system Mar 30, 2018

ijc reviewed Apr 3, 2018

View reviewed changes

src/lib/uart_emul.c

} else if (strcmp("asl", backend) == 0) {

sc->asl = true;

asl_init();

retval = 0;

Copy link

Collaborator

ijc Apr 3, 2018

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

More tab/space issues?

ijc reviewed Apr 3, 2018

View reviewed changes

Style: use tabs

9a66ade

Signed-off-by: Akim Demaille <akim.demaille@docker.com>

akimd force-pushed the asl branch from d72b731 to c725002 Compare April 3, 2018 11:38

rn reviewed Apr 3, 2018

View reviewed changes

ijc reviewed Apr 3, 2018

View reviewed changes

akimd added 3 commits April 3, 2018 17:03

Go: add ConsoleLog to redirect the tty to the Apple logs

8f07383

Signed-off-by: Akim Demaille <akim.demaille@docker.com>

Asl: prefer a static buffer

336fbb8

Suggested by Rolf Neugebauer. Signed-off-by: Akim Demaille <akim.demaille@docker.com>

Asl: treat \0 like \n

27aa572

Suggested by Ian Campbell. Signed-off-by: Akim Demaille <akim.demaille@docker.com>

akimd force-pushed the asl branch from c725002 to 27aa572 Compare April 3, 2018 15:24

Asl: use index instead of size to denote the number of stored bytes

e2af04b

Suggested by Rolf Neugebauer. Signed-off-by: Akim Demaille <akim.demaille@docker.com>

ijc reviewed Apr 3, 2018

View reviewed changes

Asl: prefer sizeof() to sizeof, even for a variable

bf1404f

Suggested by Ian Campbell.

rn requested changes Apr 4, 2018

View reviewed changes

akimd added 2 commits April 5, 2018 08:09

Asl: stay away from the asl prefix

5b93edd

Suggested by Ian Campbell. Signed-off-by: Akim Demaille <akim.demaille@docker.com>

Log: a function to flush

679700d

Suggested by Ian Campbell. Signed-off-by: Akim Demaille <akim.demaille@docker.com>

akimd force-pushed the asl branch from df6547b to 679700d Compare April 5, 2018 06:11

rn reviewed Apr 5, 2018

View reviewed changes

akimd mentioned this pull request Apr 9, 2018

Offer a means to send the tty to the Apple log system #199

Merged

akimd closed this Apr 9, 2018

Conversation

akimd commented Mar 29, 2018 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

rn commented Mar 29, 2018

Uh oh!

akimd commented Mar 30, 2018

Uh oh!

Choose a reason for hiding this comment

Uh oh!

akimd Apr 3, 2018 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

akimd commented Apr 3, 2018

Uh oh!

rn left a comment

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

akimd Apr 3, 2018 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

rn left a comment

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

akimd Apr 4, 2018 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

akimd commented Mar 29, 2018 •

edited

Loading

akimd Apr 3, 2018 •

edited

Loading

akimd Apr 3, 2018 •

edited

Loading

akimd Apr 4, 2018 •

edited

Loading

rn Apr 5, 2018 •

edited

Loading

akimd Apr 5, 2018 •

edited

Loading