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

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

This is #196 rewritten with comments from @rn and @ijc integrated.

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

ijc · 2018-04-09T12:39:33Z

FYI you can force push to an existing branch with a PR and GH will do the right thing, you don't close the PR and carry just to do a rebase.

Anyway, this LGTM (once CI is green) if @rn is happy with the commit split.

ijc · 2018-04-09T12:42:01Z

src/lib/log.c

+}
+
+
+/* Send one character to the logger: wait for full lines before actually sending. */


There's a slight risk that hyperkit or the guest might crash with something useful still buffered.

There isn't much we can sensibly do if hyperkit has crashed, but a guest crash will look like a VM shutdown and be controlled from the hypervisor PoV -- perhaps (as a future improvement?) we should add a log_flush somewhere on the hyperkit exit path?

Sounds good.

ijc · 2018-04-09T12:43:05Z

src/lib/log.c

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


Do we care that \n\n\n\n will log a bunch of blank messages? A simple if (buf_idx == 0) return check at the top would fix that if we did.

Actually, that's what I wanted, to keep the current output.

Ah, yes, that's a good point.

BTW, would you happen to know why we have two whales? Maybe it's D4D specific, I have not checked yet, but I'm kinda worried by the backslashes having been processed.

There was some strangeness wrt how/where motd was handled in linuxkit but that was more than a year ago, I don't recall having seen anything like this recently.

Are you running the getty in a container or within the root? Or even both (which might explain things)?

I presume the console is functional (i.e. you can login and type normally)? If it isn't that might suggest you've got two getty processes somehow.

Only other thought I have is if you had configured two serial ports you would get a getty and motd on both of them, but the patches here would combine them into the logs without indicating which was which. If that were the case I'd expect them to be more mixed up though.

Before these patches, both whales were already in console-ring. I have not dug the issue yet, so I can't even answer to your questions now. It was just in case it rang a bell. Thanks for the hints, I'll use them when I focus on the twin-whale-issue.

Actually looks like I misremembered. In LinuxKit (modern ones at least) it is actually an initscript which cats /etc/issue (not motd) to any device with a console= on the kernel command line.

Looks like agetty (which LinuxKit uses) will also print /etc/issue but if it is in a container then that is a different /etc/issue, unless you bind it in or arrange to use a different getty container. LinuxKit demos don't have that bind but maybe you do? Or if you were running getty on the host you would see it.

ijc · 2018-04-09T12:44:30Z

Two things occurred to me right after I said "LGTM", but neither need to be blockers IMHO.

akimd · 2018-04-09T12:49:00Z

@ijc I will make more changes anyway, so let's log_flush this now :)

The failure is not mine I think, but I'm not allowed to restart.

ijc · 2018-04-09T12:52:30Z

I've kicked the CI to have another go.

ijc · 2018-04-09T13:17:37Z

Seems like either brew or the base image used by CircleCI is a bit fucked at the moment:

Error: The `brew link` step did not complete successfully
The formula built, but is not symlinked into /usr/local
Could not symlink bin/2to3-2
Target /usr/local/bin/2to3-2
is a symlink belonging to python. You can unlink it:
  brew unlink python

To force the link and overwrite all conflicting files:
  brew link --overwrite python@2

To list all files that would be deleted:
  brew link --overwrite --dry-run python@2

Not sure how to workaround that. I'm going to give it a day and see if things resolve themselves.

ijc · 2018-04-10T09:59:00Z

I've added a workaround for the CI breakage in #202 which has now been merged. Please rebase onto current master to pickup the change and force push the change to your branch here. Sorry for the inconvenience.

akimd · 2018-04-10T14:23:01Z

Different failure :)

ijc · 2018-04-10T14:25:10Z

Oh ffs, investigating now...

ijc · 2018-04-10T15:05:59Z

The fix in #207 is merged, please rebase again (sorry)

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

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>

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>

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

akimd · 2018-04-10T15:23:43Z

No worries!

I guess I guess what ffs means, and it never occurred to me that Franz Ferdinand and the Sparks could have been naughty...

ijc · 2018-04-10T15:50:36Z

Heh, I was not previously aware of their work!

Merging now while we have the chance, before CI gets picky again...

akimd · 2018-04-10T16:01:15Z

Yeah!

akimd mentioned this pull request Apr 9, 2018

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

Closed

ijc reviewed Apr 9, 2018

View reviewed changes

rn approved these changes Apr 9, 2018

View reviewed changes

akimd force-pushed the asl2 branch from 08cb466 to 41723cf Compare April 10, 2018 14:16

akimd added 6 commits April 10, 2018 17:22

doc: update link to freebsd uncrustify's config file

f0c4d94

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

Style: use tabs

0b65533

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

Go: factor and log the opening of the tty file

4327975

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>

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

06c3cf7

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

akimd force-pushed the asl2 branch from 41723cf to 06c3cf7 Compare April 10, 2018 15:22

ijc merged commit af56683 into moby:master Apr 10, 2018

akimd deleted the asl2 branch April 10, 2018 16:01

		}


		/* Send one character to the logger: wait for full lines before actually sending. */

Conversation

akimd commented Apr 9, 2018

Uh oh!

ijc commented Apr 9, 2018

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!

ijc commented Apr 9, 2018

Uh oh!

akimd commented Apr 9, 2018

Uh oh!

ijc commented Apr 9, 2018

Uh oh!

ijc commented Apr 9, 2018

Uh oh!

ijc commented Apr 10, 2018

Uh oh!

akimd commented Apr 10, 2018

Uh oh!

ijc commented Apr 10, 2018

Uh oh!

ijc commented Apr 10, 2018

Uh oh!

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

Uh oh!

Uh oh!

ijc commented Apr 10, 2018

Uh oh!

akimd commented Apr 10, 2018

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

3 participants

akimd commented Apr 10, 2018 •

edited

Loading