FC: extract error info from firecracker built-in log and metrics scheme #2073

Pennyzct · 2019-09-19T06:37:35Z

Which feature do you think can be improved?
Hi~ I've recently been working on enabling firecracker on kata containers.
If Firecracker exits abnormally after InstantStart request, the error output you could get is only timeout related, nothing useful.

docker: Error response from daemon: OCI runtime create failed: Failed to check if grpc server is working: context deadline exceeded: unknown.

Firecracker has its own logging scheme, involving two fifo files. For better debugging, we should
extract those error info and re-play them in kata-runtime log.

Pennyzct · 2019-09-19T06:38:40Z

@jodh-intel @devimc plz review. ;)

amshinde · 2019-09-19T20:21:16Z

virtcontainers/fc.go

+		for scanner.Scan() {
+			fc.Logger().WithFields(logrus.Fields{
+				"level":    "log",
+				"contents": scanner.Text()}).Error("firecracker failed")


@Pennyzct Why are you logging these as errors? Are these generic log messages or errors?

Hi @amshinde Since it's the error info extracted from firecracker built-in logging scheme. It will only have outputs when firecracker failed setting up vmm. I have already set the logging level as Error here.

fcLogLevel := "Error"

amshinde · 2019-09-19T20:21:52Z

virtcontainers/fc.go

+		for scanner.Scan() {
+			fc.Logger().WithFields(logrus.Fields{
+				"level":    "metrics",
+				"contents": scanner.Text()}).Error("firecracker failed")


Same question as above. Why are metrics logged as errors as well.

yep, metrics data will be more about performance, but it also has data structure like drive_fails, machine_cfg_fails, ... etc for users to spot root cause of failure. And Like I said last comment, I have set the level as Error, it will only output when firecracker fail.

thanks @Pennyzct for the explanation.

devimc

thanks @Pennyzct

devimc · 2019-09-19T20:44:21Z

virtcontainers/fc.go

+		if err := fc.metricsFifo.Close(); err != nil {
+			fc.Logger().WithError(err).Error("Failed closing firecracker metrics fifo file")
+		}
+	}()


I think you can factorize a lot of code here, how about creating a new function to open and read the pipe and call it with different parameters depending on the pipe type

Hi @devimc I have already used the API from containerd/fifo to open, read,..., close pipe files.
And you're right, reading from logs.fifo and metrics.fifo share a lot same logic and I should create one new function to summarize. ;)

devimc · 2019-09-20T14:17:49Z

/test

codecov · 2019-09-20T14:56:39Z

Codecov Report

Merging #2073 into master will decrease coverage by 0.14%.
The diff coverage is 0%.

@@            Coverage Diff             @@
##           master    #2073      +/-   ##
==========================================
- Coverage   50.98%   50.84%   -0.15%     
==========================================
  Files         110      110              
  Lines       15224    15266      +42     
==========================================
  Hits         7762     7762              
- Misses       6506     6548      +42     
  Partials      956      956

Pennyzct · 2019-09-26T02:02:16Z

re-base and /test

jcvenegas · 2019-10-02T16:50:27Z

/test

jcvenegas · 2019-10-04T15:01:10Z

@Pennyzct sorry a re-re-rebase is required here , btw some test were failing

jodh-intel

lgtm

jodh-intel · 2019-10-07T10:01:05Z

virtcontainers/fc.go

@@ -579,6 +584,68 @@ func (fc *firecracker) fcSetVMBaseConfig(mem int64, vcpus int64, htEnabled bool)
 	return err
 }

+func (fc *firecracker) fcSetLogger() error {


I don't like the fc prefix as it's redundant but I see there is already precedent for this in the codebase.

Pennyzct · 2019-10-08T02:43:22Z

Hi @amshinde
So sorry for the delayed response, just got back from our national holiday. ;)
I will re-re-base asap. For the failing part, with arm CI, it's because the missing aarch64 entry in the latest image centos:latest. I have addressed specific details in kata-contains/ci:#222.
And for the other failing part, I will track down and try to find out how it's related. 😁

Pennyzct · 2019-10-08T03:08:06Z

/test

Pennyzct · 2019-10-10T08:35:27Z

Hi guys.
I really need some help here. 😭
The error docker: Error response from daemon: OCI runtime create failed: Put http://localhost/logger: EOF: unknown. really frustrated me. Have you guys ever encounter the similar error or have any clue where this comes from?
@devimc @amshinde @jcvenegas @jodh-intel @bergwolf

bergwolf · 2019-10-10T08:44:58Z

virtcontainers/fc.go

+		MetricsFifo: &jailedMetricsFifo,
+	}
+	param.SetBody(cfg)
+	_, err = fc.client().Operations.PutLogger(param)


I guess this can only be be called after fc is started?

I'm afraid not, it should belong to the configuration part, and should before the InstanceStart command.
And if you are using curl to reproduce, it works well. 😂

curl --unix-socket api.socket -i \ -X PUT "http://localhost/logger" \ -H "accept: application/json" \ -H "Content-Type: application/json" \ -d "{ \"log_fifo\": \"/root/firecracker/log.fifo\", \"metrics_fifo\": \"/root/firecracker/metrics.fifo\", \"level\": \"Info\" }"

Pennyzct · 2019-10-10T09:26:36Z

I have tried a few "plausible" reason:

The connection has already been closed. But when client initiates another request before it actually
detects the close, and the EOF that it reads get interpreted as an error for this new request rather
than a close that occurred prior to the request.

Given that, I've given sleeping time between requests to give it time to detect the close, but, still,
the error occured.

devimc · 2019-10-10T13:41:36Z

virtcontainers/fc.go

+
+func (fc *firecracker) fcListenToFifo(fifoName string) (string, error) {
+	fcFifoPath := filepath.Join(fc.vmPath, fifoName)
+	fcFifo, err := fifo.OpenFifo(context.Background(), fcFifoPath, syscall.O_CREAT|syscall.O_RDONLY|syscall.O_NONBLOCK, 0)


@Pennyzct have you tried with a blocking io?

lifupan · 2019-11-08T06:51:42Z

Hi @Pennyzct

I spend some time investigating on this issue, and found that the root cause located in firecracker, which would be crashed when setting logger with options as null.
I had opened a defect to firecracker: firecracker-microvm/firecracker#1375 .

I think you can workaround this issue in kata side by applying the following diff to your commits:

diff --git a/virtcontainers/fc.go b/virtcontainers/fc.go
index 1d8e9f39..b3acdf56 100644
--- a/virtcontainers/fc.go
+++ b/virtcontainers/fc.go
@@ -630,6 +630,7 @@ func (fc *firecracker) fcSetLogger() error {
                Level:       &fcLogLevel,
                LogFifo:     &jailedLogFifo,
                MetricsFifo: &jailedMetricsFifo,
+               Options: []string{},
        }
        param.SetBody(cfg)
        _, err = fc.client().Operations.PutLogger(param)

Pennyzct · 2019-11-08T07:52:45Z

Hi @lifupan
Thanks three thousand times!!!! update asap. ;).

Pennyzct · 2019-11-12T08:38:40Z

/test

Firecracker have its own logging scheme, providing two fifo files with log and metrics info. We should extract error info for better debugging. Fixes: kata-containers#2072 Signed-off-by: Penny Zheng <[email protected]> Signed-off-by: Haibo Xu <[email protected]>

Pennyzct · 2019-11-13T01:23:25Z

/test

raravena80 · 2019-11-15T19:56:21Z

/test

amshinde reviewed Sep 19, 2019

View reviewed changes

devimc reviewed Sep 19, 2019

View reviewed changes

Pennyzct force-pushed the firecracker_fifo_log branch 3 times, most recently from 9966589 to f258d79 Compare September 20, 2019 09:54

devimc approved these changes Sep 20, 2019

View reviewed changes

amshinde approved these changes Sep 20, 2019

View reviewed changes

Pennyzct force-pushed the firecracker_fifo_log branch from f258d79 to 6bec9d3 Compare September 26, 2019 02:01

jodh-intel approved these changes Oct 7, 2019

View reviewed changes

Pennyzct force-pushed the firecracker_fifo_log branch from 6bec9d3 to 11c4026 Compare October 8, 2019 03:07

bergwolf reviewed Oct 10, 2019

View reviewed changes

devimc reviewed Oct 10, 2019

View reviewed changes

Pennyzct force-pushed the firecracker_fifo_log branch from 11c4026 to bd633e1 Compare November 12, 2019 08:38

Pennyzct force-pushed the firecracker_fifo_log branch from bd633e1 to daae1db Compare November 13, 2019 01:22

lifupan approved these changes Nov 14, 2019

View reviewed changes

teawater merged commit 562d9fd into kata-containers:master Nov 25, 2019

teawater mentioned this pull request Nov 25, 2019

fc.go: Open firecracker log if hypervisor.enable_debug is true #2259

Closed

This was referenced Dec 27, 2019

FC: Update Firecracker to v0.20.0 #2378

Closed

FC: Update Firecracker to v0.20.0 #2379

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

FC: extract error info from firecracker built-in log and metrics scheme #2073

FC: extract error info from firecracker built-in log and metrics scheme #2073

Pennyzct commented Sep 19, 2019

Pennyzct commented Sep 19, 2019

amshinde Sep 19, 2019

Pennyzct Sep 20, 2019

amshinde Sep 19, 2019

Pennyzct Sep 20, 2019

amshinde Sep 20, 2019

devimc left a comment

devimc Sep 19, 2019

Pennyzct Sep 20, 2019 •

edited

Loading

devimc commented Sep 20, 2019

codecov bot commented Sep 20, 2019 •

edited

Loading

Pennyzct commented Sep 26, 2019

jcvenegas commented Oct 2, 2019

jcvenegas commented Oct 4, 2019

jodh-intel left a comment

jodh-intel Oct 7, 2019

Pennyzct commented Oct 8, 2019

Pennyzct commented Oct 8, 2019

Pennyzct commented Oct 10, 2019 •

edited

Loading

bergwolf Oct 10, 2019

Pennyzct Oct 10, 2019

Pennyzct commented Oct 10, 2019

devimc Oct 10, 2019

lifupan commented Nov 8, 2019

Pennyzct commented Nov 8, 2019

Pennyzct commented Nov 12, 2019

Pennyzct commented Nov 13, 2019

raravena80 commented Nov 15, 2019

FC: extract error info from firecracker built-in log and metrics scheme #2073

FC: extract error info from firecracker built-in log and metrics scheme #2073

Conversation

Pennyzct commented Sep 19, 2019

Pennyzct commented Sep 19, 2019

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

devimc left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Pennyzct Sep 20, 2019 • edited Loading

Choose a reason for hiding this comment

devimc commented Sep 20, 2019

codecov bot commented Sep 20, 2019 • edited Loading

Codecov Report

Pennyzct commented Sep 26, 2019

jcvenegas commented Oct 2, 2019

jcvenegas commented Oct 4, 2019

jodh-intel left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Pennyzct commented Oct 8, 2019

Pennyzct commented Oct 8, 2019

Pennyzct commented Oct 10, 2019 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Pennyzct commented Oct 10, 2019

Choose a reason for hiding this comment

lifupan commented Nov 8, 2019

Pennyzct commented Nov 8, 2019

Pennyzct commented Nov 12, 2019

Pennyzct commented Nov 13, 2019

raravena80 commented Nov 15, 2019

Pennyzct Sep 20, 2019 •

edited

Loading

codecov bot commented Sep 20, 2019 •

edited

Loading

Pennyzct commented Oct 10, 2019 •

edited

Loading