tracing: Add OpenTracing support by jodh-intel · Pull Request #415 · kata-containers/agent

jodh-intel · 2018-11-16T14:10:34Z

Add OpenTracing [1] support using Jaeger [2]. Full details are provided
in TRACING.md.

Fixes #322.

[1] - https://opentracing.io
[2] - https://jaegertracing.io

Signed-off-by: James O. D. Hunt james.o.hunt@intel.com

jodh-intel · 2018-11-16T14:11:25Z

Related: #328.

jodh-intel · 2018-11-16T14:21:55Z

I should point out that this PR removes the original grpcTracer() function (which logged gRPC calls) as this now seems superfluous given this PR provides real tracing. Additionally, retaining it is going to be awkward since although it will be trivial to work it into the "isolated" trace mode, it will be less easy to deal with "collated" mode (see TRACING.md for details of trace modes).

jodh-intel · 2018-11-16T14:28:37Z

Hi @klynnrif - ptal.

klynnrif

Scrubbed for grammar, structure, and flow. Here's to hoping I didn't change meanings :) Thanks!

klynnrif · 2018-11-16T19:17:28Z

README.md

+
+## Developer mode
+
+Adding `agent.devmode` to the guest kernel command line will enable [debug mode](#debug-mode) and also allow the agent process to coredump (disabled by default).


Suggested rewrite: Add agent.devmode to the guest kernel command line to enable debug mode and allow the agent process to coredump (disabled by default).

klynnrif · 2018-11-16T19:20:42Z

TRACING.md

+
+# OpenTracing summary
+
+An OpenTracing enabled application creates trace "spans". A span must contain


Adding hyphen: An OpenTracing-enabled application ....

klynnrif · 2018-11-16T19:21:50Z

TRACING.md

+An OpenTracing enabled application creates trace "spans". A span must contain
+the following attributes:
+
+- A name.


Lines 31 - 33 suggest removing the periods at the end of each bullet since they are not complete sentences.

klynnrif · 2018-11-16T19:24:06Z

TRACING.md

+[golang client package](https://github.com/jaegertracing/jaeger-client-go/).
+
+The Jaeger architecture means that the Jaeger client code running in the
+application reports all span information to a Jaeger agent. This agent then


Suggest removing "then": This agent forwards the information on to...

klynnrif · 2018-11-16T19:25:10Z

TRACING.md

+is not desirable to run a `jaeger-agent` process inside the VM:
+
+- Adding extra binaries and an extra service to run the Jaeger agent inside
+  the VM would increase the size of the guest OS image used to


Suggested rewrite to stay active: the VM increases the size of the guest OS image used to

klynnrif · 2018-11-16T19:59:30Z

TRACING.md

+- The image configured in the `kata-runtime` `configuration.toml` file must
+  be specified using `image=` (`initrd=` is not supported).
+
+  This is due to having to run additional systemd services inside the VM


Suggested rewrite: This is because, currently, additional systemd services have to run inside the VM in order to proxy the Jaeger trace flows...

klynnrif · 2018-11-16T20:02:45Z

TRACING.md

+  [Guest to Host communication using VSOCK](#guest-to-host-communication-using-vsock)
+  section for further details.
+
+- Tracing is only finalised when the workload has exited


finalised => finalized

I've gone for "completed" here instead:

for consistency with that is already written.

to remove the contention ;)

klynnrif · 2018-11-16T20:03:34Z

TRACING.md

+
+- Tracing is only finalised when the workload has exited
+
+  Although trace *can* be inspected before the workload exits, it will be


Suggested rewrite to stay active: Although trace can be inspected before the workload exits, it is incomplete.

klynnrif · 2018-11-16T20:05:33Z

TRACING.md

+
+# Appendix: Setting up a tracing development environment
+
+If you wish to debug, further develop or test tracing, follow the steps below


Add series comma, wish=>want, and below=>following:

If you want to debug, further develop, or test tracing, use the following steps...

klynnrif · 2018-11-16T20:10:13Z

TRACING.md

+## Guest journal redirector
+
+Since agent tracing requires VSOCK, and enabling VSOCK in `configuration.toml`
+disables the `kata-proxy` (since it is not required), the Kata Container has


Lines 291-294 suggested rewrite: disables the 'kata-proxy' (not required), the Kata Container has no way to display the guest OS journal messages, which are normally redirected through the proxy. This makes debugging difficult. To overcome this issue, create another pair of ...

sboeuf · 2018-11-16T20:28:06Z

@jodh-intel oh nice you finally got the PR ready!!! Yay!
How many days do I need to plan to review this properly :p

devimc · 2018-11-16T21:38:58Z

agent.go


-func (s *sandbox) setContainer(id string, ctr *container) {
+func (s *sandbox) setContainer(ctx context.Context, id string, ctr *container) {
+	span, _ := trace(ctx, "sandbox", "setContainer")


other functions use s.trace, why don't use it here?

devimc · 2018-11-16T21:42:30Z

agent.go


+func (s *sandbox) trace(name string) (opentracing.Span, context.Context) {
+	if s.ctx == nil {
+		agentLog.WithField("type", "bug").Error("trace called before context set")


might be this function should be a singleton, hence log an error is not needed

I added this for consistency with the approach used in the runtime. If you look at agent.go, you'll see that there is a "gap" between creating the sandbox and having s.ctx set. That is unfortunately required since:

the context can only be set after tracing has been setup.

the sandbox needs to be created before tracing has been setup.

We could use a new context when creating the sandbox and then reset it to the correct context containing the trace metadata but this approach is simpler I think.

devimc · 2018-11-16T21:45:04Z

nice job James! 😄

jshachm · 2018-11-19T09:01:13Z

Nice job @jodh-intel

Beyond this, will we have a chance to support this in initrd model

jodh-intel · 2018-11-19T09:37:29Z

Thanks @klynnrif, @devimc - branch updated.

@sboeuf - hahaaa! It's not as bad as it might appear in terms of LOC. But it is a little subtle in places, hence the big TRACING.md.

jodh-intel · 2018-11-19T15:27:39Z

I recommend testing this PR using:

rootfs: Support agent tracing osbuilder#200

jodh-intel · 2018-11-19T18:06:35Z

Note that the horrid hex strings in the scripts and Jaeger systemd services are going to be architecture-dependent. That's not a problem today but probably will be once os390x support lands. It's unclear how best to handle this. A reliable mechanism would be to provide a C program to generate the output as @mcastelino does on https://gist.github.com/mcastelino/9a57d00ccf245b98de2129f0efe39857#using-specific-ports, but the ideal would be to not require users to build and run a C program simply to get tracing working on big endian systems.

klynnrif

lgtm - thanks!

sboeuf

@jodh-intel I didn't finish the review because I realized that you were explaining the way a container exit was working and I didn't agree with it. But this led me to try to reproduce the behavior that you were seeing on my machine and I understand now why you thought DestroySandbox() is not called in case of simple container process termination.
Please refer to moby/moby#38233 and kata-containers/runtime#926
I think the problem comes from your environment running docker 18.09 with the wrong version of containerd.
This generates some errors in the cleanup path, and the delete never gets called, which means we never end up calling into DestroySandbox().

But if you can confirm that this behavior is fixed by updating containerd and making sure the containerd service runs the right binary, I think the whole part of the documentation where you say that you cannot stop the tracing in DestroySandbox() could be avoided and your code could be modified accordingly.

Please try to confirm the behavior here, I'd really like to make sure we're all on the same page with the code flow.

Makefile

sboeuf · 2018-11-20T18:07:12Z

Makefile

 endif

+# If "yes", install additional services to redirect guest OS journal messages
+# to the host using VHOST.


s/VHOST/VSOCK/

sboeuf · 2018-11-20T18:10:28Z

Gopkg.toml

+
+[[constraint]]
+  name = "github.com/uber/jaeger-client-go"
+  version = "2.15.0"


Please add this constraint after the last constraint that is already in this file. This way it remains clear that we have constraint first, then the override, and at the end the special prune case.

That was auto-added by dep, but I agree it makes sense so fixed.

sboeuf · 2018-11-20T18:14:57Z

TRACING.md

+- A pair of timestamps (recording the start time and end time of some operation)
+- A reference to the span's parent span
+
+All spans need to be "finished", or completed, to allow the OpenTracing


Don't you want to use italic for finished and completed words here?

Good point - fixed.

TRACING.md

sboeuf · 2018-11-20T18:20:40Z

TRACING.md

+
+# VM shutdown
+
+Assume a user has run the following to create a Kata Container:


I would say Kata Containers container or Kata container.

Agreed - fixed.

sboeuf · 2018-11-20T18:23:17Z

TRACING.md

+  The user exits the primary workload shell by typing `exit`.
+
+  This results in the `kata-agent` process detecting that the primary workload
+  process has exited, and then exits itself. This, in turn, causes the VM to shut down.


I thought we changed the kata-agent service so that it won't shutdown the VM when terminating. The reason was to make sure the shutdown of the VM was coming only from the runtime, preventing from any conflict with a VM that would have been already shutdown because the agent exited.

Similarly to the case you describe as container manager requested, because the container representing the sandbox terminates, the shim will terminate and the container manager will issue a container delete, leading to the gRPC call destroySandbox.

I did indeed do this in testing but due I suspect to the containerd issue, that change wasn't required.

This will no doubt need updating as you suggest but let me go and look at the containerd version...

Picking this up again...

We don't want to stop the kata agent service stopping the VM - it's the other way around for tracing scenarios:

If the user types exit:

The workload shell exits

The agent detects this and stops tracing itself.

The agent exits.

The agent service detects this and performs a controlled VM shutdown.

If the user types docker stop, the same thing has to happen - the VM needs to shut itself down and the runtime should not call the QMP QUIT command as that will kill the VM before the agent has finished stopping tracing itself.

That does mean I'll have to tweak the runtime "somehow" to stop it calling QUIT. I can't see currently how to make that change "clean" - currently, you enable agent trace by modifying hypervisor.qemu.kernel_params directly. The best I can think of right now is to add a runtime.enable_agent_tracing which will:

Disable the QUIT.

Add the trace arguments to hypervisor.qemu.kernel_params (yuck).

Any other ideas?

I don't get what's wrong with the gRPC call DestroySandbox(). This function is always called in every situation (now that we fixed Docker 18.09), meaning the agent is always around, even when the container workload exited.
In both cases (container workload exit, and forced kill), the runtime will at some point communicate with the agent the need to terminate through agent.stopSandbox() which will send the gRPC call DestroySandbox().

Yes - DestroySandbox() is always called, but it doesn't appear to be possible to shut down the gRPC server by triggering the server to end from DestroySandbox(). I need to debug further but I think this is the same problem I hit a while back with gRPC internal locks and waitgroups. It's sounding like you cannot shut down the server on the same goroutine that's it's running in. However, if you try to stop the server in WaitProcess(), all works as expected.

sboeuf · 2018-11-20T18:28:07Z

TRACING.md

+
+  - The `kata-agent` `DestroySandbox` gRPC API is called.
+  - The runtime sends a [QMP](https://wiki.qemu.org/Documentation/QMP) `quit`
+    command to the VM to ensure it is stopped.


Not to ensure, but to shut it down.

sboeuf · 2018-11-20T18:56:59Z

TRACING.md

+The crucial difference between the two shutdown methods explained in the [VM
+shutdown](#vm-shutdown) section is that the user-initiated shutdown does not
+explicitly destroy the sandbox using the `DestroySandbox` gRPC API: the
+sandbox is "destroyed" by the agent shutting down the VM.


It's not explicitly done the same way, but when the management layer realizes the shim is not there anymore, it sends a kata-runtime delete and eventually this calls into DestroySandbox.

Again, this relates to the issue I seem to have been having with containerd so I'll come back to this one...

grahamwhaley · 2018-11-26T16:18:28Z

@sboeuf - this probably needs your re-review now when you find a slot.

grahamwhaley

A few doc notes... nothing major, but a couple of fixes required.

grahamwhaley · 2018-11-26T16:22:51Z

TRACING.md

+  * [Host environment](#host-environment)
+  * [Guest environment](#guest-environment)
+* [Limitations](#limitations)
+* [Appendix: Setting up a tracing development environment](#appendix:-setting-up-a-tracing-development-environment)


The appendix link does not hot-render. I think it needs the ref modding to (that is, drop the stray :) :

#appendix-setting-up-a-tracing-development-environment

grahamwhaley · 2018-11-26T16:37:03Z

TRACING.md

+following:
+
+| Trace type | Trace setting | Description | Use-case | Notes |
+|-|-|-|-|


This table is not rendering for me - I suspect you are missing one set of | - | in the second line.

Weirdly it rendered for me in both github and atom. What are you using ooi?

I was just looking in the 'view file' on the github PR - so, dunno why that was different from your github view...

TRACING.md

grahamwhaley · 2018-11-26T16:40:09Z

TRACING.md

+1. Build a custom non-initrd image using
+   [osbuilder](https://github.com/kata-containers/osbuilder).
+
+   - The image **must** include:


How does one achieve this? I think you added the ability to osbuilder to do this for you?, in which case we can note the method (TRACE=true or somesuch) here?

See kata-containers/osbuilder#200 :)

It's a bit circular. Once the osbuilder PR has landed, this can be simplified.

I did toy with the idea of creating a small .md doc here and having osbuilder execute it, but discarded the idea since that script needs to know things like $ROOTFS directories and those are a purely osbuilder concern so it would have been "the wrong way round".

TRACING.md

jodh-intel · 2019-03-12T11:20:53Z

@sboeuf - I think we just need you ack to allow us break out the champagne... 😄

jodh-intel · 2019-03-12T11:48:11Z

Gah - I'm starting to go off this browser with it's aggressive caching and page unloading - I'd missed @sboeuf's ack.

/me looks at test carnage...

jodh-intel · 2019-03-12T13:42:59Z

/retest

jodh-intel · 2019-03-12T14:04:30Z

16.04 metrics CI timed out @grahamwhaley:

Build timed out (after 10 minutes). Marking the build as aborted.
14:01:43 density/docker_memory_usage.sh: line 190: 29584 Terminated              docker rm -f ${containers[@]}

grahamwhaley · 2019-03-12T14:09:59Z

@jodh-intel - that metrics CI timeout looks like docker/kata got stuck trying to delete the containers after the test had been run. It looks like @amshinde also saw a 'failed to delete container' on another CI before on this PR? That makes me wonder if we have some inherent rm/delete hangup hiding in here somewhere?
I'll re-trigger the CI (and I've tried to adjust the bounds, so the metrics CI has a chance of passing...)

jodh-intel · 2019-03-12T14:13:16Z

Nooo - I've already re-triggered :)

Yes, there may be an issue but I was hoping to get a fresh set of CI logs as cannot recreate locally.

This commit attempts to close cleanly the gRPC server so that tracing will be ended properly. Fixes kata-containers#445 Signed-off-by: Sebastien Boeuf <sebastien.boeuf@intel.com>

The semantic around the agent is that it should be a passive component, hence it should not implicitly shut down the VM. Instead, we expect the kata-runtime to be responsible for this, using the appropriate VM interface to stop it. Fixes kata-containers#449 Depends-on: github.com/kata-containers/tests#1101 Signed-off-by: Sebastien Boeuf <sebastien.boeuf@intel.com> Signed-off-by: James O. D. Hunt <james.o.hunt@intel.com>

Tabs should only be used in rules. Signed-off-by: James O. D. Hunt <james.o.hunt@intel.com>

Reformat an `ifeq` test for clarity. Signed-off-by: James O. D. Hunt <james.o.hunt@intel.com>

Detected by the CI's static analysis: ``` api.go:38:2:warning: unused variable or constant exitSuccess (varcheck) api.go:39:2:warning: unused variable or constant exitFailure (varcheck) api.go:38:2:warning: const exitSuccess is unused (U1000) (unused) api.go:39:2:warning: const exitFailure is unused (U1000) (unused) ``` Signed-off-by: James O. D. Hunt <james.o.hunt@intel.com>

This seems to be an erroneous / outdated entry as it's hiding files below `vendor/`! Signed-off-by: James O. D. Hunt <james.o.hunt@intel.com>

Firm up the language used in the README. Signed-off-by: James O. D. Hunt <james.o.hunt@intel.com>

Explain how to enable debug. Signed-off-by: James O. D. Hunt <james.o.hunt@intel.com>

Update the README to show how to enable developer mode. Signed-off-by: James O. D. Hunt <james.o.hunt@intel.com>

jodh-intel · 2019-03-13T15:43:33Z

/retest

Add OpenTracing [1] support using Jaeger [2]. Introduces two new gRPC API calls to enable and disable tracing dynamically: `StartTracing()` and `StopTracing()`. Full details of this feature are provided in `TRACING.md`. Updated vendoring for github.com/mdlayher/vsock to resolve hangs using a vsock socket with `grpcServer.Serve()`. Changes: 498f144 Handle return result in Accept test fda437e Fix unblocking after closing listener 4b12813 Add go.mod ce2ff06 vsock: factor out newConn function on Linux d8b0f13 vsock: adjust listener test for nonblocking 7a158c6 vsock: enable timeouts also on listener connections f68ad55 vsock: allow timeouts with Go 1.11 d0067a6 vsock/conn: don't use struct embedding Note: the agent **must** be built with golang 1.11* or newer to ensure correct behaviour. Fixes kata-containers#322. [1] - https://opentracing.io [2] - https://jaegertracing.io Signed-off-by: James O. D. Hunt <james.o.hunt@intel.com>

jodh-intel · 2019-03-13T16:13:00Z

/retest

jodh-intel · 2019-03-13T16:51:37Z

@nitkon - It looks like the ppc64 CI isn't actually running tests for PRs?:

Building remotely on Power8_slave01 (power8-ubuntu-1604 power8_node) in workspace /home/jenkins/workspace/kata-containers-agent-Power8-ubuntu-16-04-PR-initrd
[WS-CLEANUP] Deleting project workspace...

jodh-intel · 2019-03-13T17:48:58Z

Branch updated.

@mcastelino - ftr, I removed the unused gRPC stream interceptor function.

sboeuf · 2019-03-13T22:57:17Z

@mcastelino if you agree, let's merge this PR :)

mcastelino · 2019-03-14T00:51:02Z

LGTM @sboeuf please merge this so that we can switch to a custom exporter quickly

sboeuf · 2019-03-14T14:57:48Z

@jodh-intel that's it you're done, you can go to the beach for a year now 🌴 🌞

jodh-intel force-pushed the support-opentracing branch from 252e133 to f8cd0bd Compare November 16, 2018 14:28

jodh-intel force-pushed the support-opentracing branch 3 times, most recently from 90091c8 to dd40de0 Compare November 16, 2018 15:34

klynnrif suggested changes Nov 16, 2018

View reviewed changes

devimc reviewed Nov 16, 2018

View reviewed changes

jodh-intel force-pushed the support-opentracing branch from dd40de0 to 7860e8d Compare November 19, 2018 09:26

jodh-intel force-pushed the support-opentracing branch from 7860e8d to b054354 Compare November 19, 2018 11:42

This was referenced Nov 19, 2018

Support agent tracing kata-containers/osbuilder#199

Closed

rootfs: Support agent tracing kata-containers/osbuilder#200

Closed

jodh-intel added do-not-merge and removed do-not-merge labels Nov 19, 2018

klynnrif approved these changes Nov 20, 2018

View reviewed changes

sboeuf suggested changes Nov 20, 2018

View reviewed changes

jodh-intel force-pushed the support-opentracing branch 2 times, most recently from 6a1761c to f8eae56 Compare November 22, 2018 15:21

grahamwhaley reviewed Nov 26, 2018

View reviewed changes

jodh-intel force-pushed the support-opentracing branch 2 times, most recently from e38e2f0 to 8524e85 Compare November 26, 2018 17:02

Sebastien Boeuf and others added 9 commits March 13, 2019 14:50

agent: Properly stop the gRPC server

bbe06a4

This commit attempts to close cleanly the gRPC server so that tracing will be ended properly. Fixes kata-containers#445 Signed-off-by: Sebastien Boeuf <sebastien.boeuf@intel.com>

build: Remove tabs

46ec60a

Tabs should only be used in rules. Signed-off-by: James O. D. Hunt <james.o.hunt@intel.com>

build: Indent ifeq test

30d98fe

Reformat an `ifeq` test for clarity. Signed-off-by: James O. D. Hunt <james.o.hunt@intel.com>

git: Don't ignore "agent"

4383dbf

This seems to be an erroneous / outdated entry as it's hiding files below `vendor/`! Signed-off-by: James O. D. Hunt <james.o.hunt@intel.com>

docs: Update README

5cc1df7

Firm up the language used in the README. Signed-off-by: James O. D. Hunt <james.o.hunt@intel.com>

docs: Add debug options to README

0b7cae1

Explain how to enable debug. Signed-off-by: James O. D. Hunt <james.o.hunt@intel.com>

docs: Explain developer mode

cbd0aae

Update the README to show how to enable developer mode. Signed-off-by: James O. D. Hunt <james.o.hunt@intel.com>

jodh-intel force-pushed the support-opentracing branch from 429ebd9 to e6dc82b Compare March 13, 2019 15:42

jodh-intel force-pushed the support-opentracing branch from e6dc82b to 00cf907 Compare March 13, 2019 16:12

sboeuf merged commit 13347ed into kata-containers:master Mar 14, 2019

sboeuf mentioned this pull request Mar 14, 2019

Fail to stop kata container kata-containers/runtime#1368

Closed

This was referenced Mar 14, 2019

Add agent tracing support kata-containers/runtime#1369

Closed

Hide trace message unless tracing is really enabled #482

Closed

Remove kata-redirect-agent-output-to-journal.conf #484

Closed


		## Developer mode

		Adding `agent.devmode` to the guest kernel command line will enable [debug mode](#debug-mode) and also allow the agent process to coredump (disabled by default).


		# OpenTracing summary

		An OpenTracing enabled application creates trace "spans". A span must contain


		- Tracing is only finalised when the workload has exited

		Although trace can be inspected before the workload exits, it will be


		# Appendix: Setting up a tracing development environment

		If you wish to debug, further develop or test tracing, follow the steps below


		# VM shutdown

		Assume a user has run the following to create a Kata Container:

Conversation

jodh-intel commented Nov 16, 2018

Uh oh!

jodh-intel commented Nov 16, 2018

Uh oh!

jodh-intel commented Nov 16, 2018

Uh oh!

jodh-intel commented Nov 16, 2018

Uh oh!

klynnrif left a comment

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!

sboeuf commented Nov 16, 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!

devimc commented Nov 16, 2018

Uh oh!

jshachm commented Nov 19, 2018

Uh oh!

jodh-intel commented Nov 19, 2018

Uh oh!

jodh-intel commented Nov 19, 2018

Uh oh!

jodh-intel commented Nov 19, 2018

Uh oh!

klynnrif left a comment

Choose a reason for hiding this comment

Uh oh!

sboeuf left a comment

Choose a reason for hiding this comment

Uh oh!

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!

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!