logging: Redirect yamux warnings/errors to logger by jodh-intel · Pull Request #89 · kata-containers/proxy

jodh-intel · 2018-07-03T11:09:50Z

Capture yamux messages to the logger.

Fixes #88.

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

jodh-intel · 2018-07-03T11:09:58Z

opendev-zuul · 2018-07-03T11:57:40Z

Build failed (third-party-check pipeline) integration testing with
OpenStack. For information on how to proceed, see
http://docs.openstack.org/infra/manual/developers.html#automated-testing

kata-runsh : FAILURE in 42m 03s
kata-runsh-fedora-28 : RETRY_LIMIT in 8m 02s

grahamwhaley · 2018-07-03T12:07:36Z

Nice fix (I'd not twigged we could link the yamux with a writer to the log), but CI is not happy:

Goroutine 12 (finished) created at:
  github.com/kata-containers/proxy/vendor/github.com/hashicorp/yamux.newSession()
      /tmp/jenkins/workspace/kata-containers-proxy-ubuntu-16-04-PR/go/src/github.com/kata-containers/proxy/vendor/github.com/hashicorp/yamux/session.go:109 +0x72a
  github.com/kata-containers/proxy/vendor/github.com/hashicorp/yamux.Client()
      /tmp/jenkins/workspace/kata-containers-proxy-ubuntu-16-04-PR/go/src/github.com/kata-containers/proxy/vendor/github.com/hashicorp/yamux/mux.go:86 +0xb6
  github.com/kata-containers/proxy.serve()
      /tmp/jenkins/workspace/kata-containers-proxy-ubuntu-16-04-PR/go/src/github.com/kata-containers/proxy/proxy.go:70 +0x1c5
  github.com/kata-containers/proxy.TestProxy()
      /tmp/jenkins/workspace/kata-containers-proxy-ubuntu-16-04-PR/go/src/github.com/kata-containers/proxy/proxy_test.go:196 +0x297
  testing.tRunner()
      /usr/local/go/src/testing/testing.go:777 +0x16d
==================
--- FAIL: TestSignalBacktrace (0.14s)
	testing.go:730: race detected during execution of test

jodh-intel · 2018-07-03T12:30:15Z

ugh - that's going to be fun to debug ;)

jodh-intel · 2018-07-03T13:17:27Z

Fixed it!

@bergwolf - ptal.

opendev-zuul · 2018-07-03T14:52:08Z

Build failed (third-party-check pipeline) integration testing with
OpenStack. For information on how to proceed, see
http://docs.openstack.org/infra/manual/developers.html#automated-testing

kata-runsh : FAILURE in 40m 55s
kata-runsh-fedora-28 : RETRY_LIMIT in 7m 42s

codecov · 2018-07-05T12:37:00Z

Codecov Report

Merging #89 into master will decrease coverage by 0.48%.
The diff coverage is 16.66%.

@@            Coverage Diff             @@
##           master      #89      +/-   ##
==========================================
- Coverage   37.74%   37.26%   -0.49%     
==========================================
  Files           2        2              
  Lines         257      263       +6     
==========================================
+ Hits           97       98       +1     
- Misses        149      154       +5     
  Partials       11       11

jodh-intel · 2018-07-05T12:41:09Z

That's distressing - go test -race seems to be racy when running these tests - fine locally and under Jenkins, but unreliable under Travis.

opendev-zuul · 2018-07-05T13:55:23Z

Build failed (third-party-check pipeline) integration testing with
OpenStack. For information on how to proceed, see
http://docs.openstack.org/infra/manual/developers.html#automated-testing

kata-runsh : FAILURE in 44m 08s
kata-runsh-fedora-28 : TIMED_OUT in 1h 17m 51s

jodh-intel · 2018-07-05T16:10:56Z

Effectively blocked on #90 (as that contains a fix for the Travis OSX bash failure).

opendev-zuul · 2018-07-05T18:15:19Z

Build failed (third-party-check pipeline) integration testing with
OpenStack. For information on how to proceed, see
http://docs.openstack.org/infra/manual/developers.html#automated-testing

kata-runsh : FAILURE in 43m 17s
kata-runsh-fedora-28 : TIMED_OUT in 1h 17m 25s

sboeuf · 2018-07-05T19:21:08Z

@jodh-intel #90 has been merged, please rebase this one !

jodh-intel · 2018-07-06T06:56:48Z

Hi @sboeuf - branch updated.

opendev-zuul · 2018-07-06T08:14:53Z

Build failed (third-party-check pipeline) integration testing with
OpenStack. For information on how to proceed, see
http://docs.openstack.org/infra/manual/developers.html#automated-testing

kata-runsh : FAILURE in 45m 11s
kata-runsh-fedora-28 : TIMED_OUT in 1h 17m 45s

egernst · 2018-07-23T13:59:57Z

/retest <--i wish this worked?

grahamwhaley · 2018-07-23T14:18:43Z

@egernst - you wish we had a 'trigger phrase' for Jenkins we could use in comments.... well, that is a feature supported in the github plugins we use in Jenkins afaik - we would just have to define it, configure it, and turn it on...

jodh-intel · 2018-07-25T16:46:17Z

Well, there does appear to be a test race here. I can force it on go 1.8 and 1.10 but it's easier to see on go 1.8.

I'm still digging as the main code fires off go routines... that fire off go routines (in multiple parts of the code). And those go routines are unstoppable fwics as they are doing I/O copy.

I'll take another look tomorrow but might need to get @sboeuf / @bergwolf to take a look, being the original authors of the go routine code.

jodh-intel · 2018-07-30T10:18:21Z

Branch updated. The test race still exists though.

@sboeuf, @bergwolf - ptal to see if you can work out how we can solve this one. I don't think you can interrupt I/O copies so we might need to get creative here :)

opendev-zuul · 2018-07-30T10:22:10Z

Build failed (third-party-check pipeline) integration testing with
OpenStack. For information on how to proceed, see
http://docs.openstack.org/infra/manual/developers.html#automated-testing

kata-runsh : NODE_FAILURE
kata-runsh-fedora-28 : NODE_FAILURE

bergwolf · 2018-08-01T03:32:07Z

@jodh-intel Could you give a pointer to the logs of the race somewhere?

jodh-intel · 2018-08-02T09:00:20Z

Hi @bergwolf - yep, if you look at the travis log...

=== RUN   TestHandleSigtermSignalNilConnectionsSuccess
--- PASS: TestHandleSigtermSignalNilConnectionsSuccess (0.00s)
=== RUN   TestLogger
==================
WARNING: DATA RACE
Write at 0x00c42001cbe0 by goroutine 32:
  github.com/kata-containers/proxy.TestLogger()
      /home/travis/gopath/src/github.com/kata-containers/proxy/proxy_test.go:287 +0x15c
  testing.tRunner()
      /home/travis/.gimme/versions/go1.8.linux.amd64/src/testing/testing.go:657 +0x107

Previous read at 0x00c42001cbe0 by goroutine 13:
  github.com/kata-containers/proxy/vendor/github.com/sirupsen/logrus.Entry.log()
      /home/travis/gopath/src/github.com/kata-containers/proxy/vendor/github.com/sirupsen/logrus/entry.go:117 +0x59e
  github.com/kata-containers/proxy/vendor/github.com/sirupsen/logrus.(*Entry).Warn()
      /home/travis/gopath/src/github.com/kata-containers/proxy/vendor/github.com/sirupsen/logrus/entry.go:150 +0x116
  github.com/kata-containers/proxy.yamuxWriter.Write()
      github.com/kata-containers/proxy/_test/_obj_test/proxy.go:56 +0x1c6
  github.com/kata-containers/proxy.(*yamuxWriter).Write()
      <autogenerated>:1 +0x8d
  log.(*Logger).Output()
      /home/travis/.gimme/versions/go1.8.linux.amd64/src/log/log.go:168 +0x39d
  log.(*Logger).Printf()
      /home/travis/.gimme/versions/go1.8.linux.amd64/src/log/log.go:175 +0x8f
  github.com/kata-containers/proxy/vendor/github.com/hashicorp/yamux.(*Session).send()
      /home/travis/gopath/src/github.com/kata-containers/proxy/vendor/github.com/hashicorp/yamux/session.go:376 +0x2e1

Goroutine 32 (running) created at:
  testing.(*T).Run()
      /home/travis/.gimme/versions/go1.8.linux.amd64/src/testing/testing.go:697 +0x543
  testing.runTests.func1()
      /home/travis/.gimme/versions/go1.8.linux.amd64/src/testing/testing.go:882 +0xaa
  testing.tRunner()
      /home/travis/.gimme/versions/go1.8.linux.amd64/src/testing/testing.go:657 +0x107
  testing.runTests()
      /home/travis/.gimme/versions/go1.8.linux.amd64/src/testing/testing.go:888 +0x4e0
  testing.(*M).Run()
      /home/travis/.gimme/versions/go1.8.linux.amd64/src/testing/testing.go:822 +0x1c3
  main.main()
      github.com/kata-containers/proxy/_test/_testmain.go:118 +0x33d

Goroutine 13 (finished) created at:
  github.com/kata-containers/proxy/vendor/github.com/hashicorp/yamux.newSession()
      /home/travis/gopath/src/github.com/kata-containers/proxy/vendor/github.com/hashicorp/yamux/session.go:109 +0x7d2
  github.com/kata-containers/proxy/vendor/github.com/hashicorp/yamux.Client()
      /home/travis/gopath/src/github.com/kata-containers/proxy/vendor/github.com/hashicorp/yamux/mux.go:86 +0xb6
  github.com/kata-containers/proxy.serve()
      github.com/kata-containers/proxy/_test/_obj_test/proxy.go:92 +0x20d
  github.com/kata-containers/proxy.TestProxy()
      /home/travis/gopath/src/github.com/kata-containers/proxy/proxy_test.go:199 +0x2c8
  testing.tRunner()
      /home/travis/.gimme/versions/go1.8.linux.amd64/src/testing/testing.go:657 +0x107
==================
--- FAIL: TestLogger (0.00s)
	<autogenerated>:12: 
                          
	Error Trace:	proxy_test.go:294
		
	Error:      	Should be true
		
	Test:       	TestLogger
	<autogenerated>:12: 
                          
	Error Trace:	proxy_test.go:295
		
	Error:      	Should be true
		
	Test:       	TestLogger
	<autogenerated>:12: 
                          
	Error Trace:	proxy_test.go:296
		
	Error:      	Should be true
		
	Test:       	TestLogger
	<autogenerated>:12: 
                          
	Error Trace:	proxy_test.go:300
		
	Error:      	Expected value not to be nil.
		
	Test:       	TestLogger
	testing.go:610: race detected during execution of test

opendev-zuul · 2018-08-02T09:30:24Z

Build failed (third-party-check pipeline) integration testing with
OpenStack. For information on how to proceed, see
http://docs.openstack.org/infra/manual/developers.html#automated-testing

kata-runsh : TIMED_OUT in 1h 01m 09s
kata-runsh-fedora-28 : RETRY_LIMIT in 20m 19s

bergwolf · 2018-08-02T09:57:42Z

@jodh-intel I think the problem is that the yamux session is not closed properly. Please see if #94 fixes the race.

jodh-intel · 2018-08-02T14:41:42Z

Blocked on #94 (I also need to remove the first commit).

sboeuf · 2018-08-03T07:17:53Z

@jodh-intel please rebase now that #94 has been merged :)

Capture yamux messages to the logger. Fixes kata-containers#88. Signed-off-by: James O. D. Hunt <james.o.hunt@intel.com>

jodh-intel · 2018-08-03T07:41:39Z

Reworked now that #94 has landed.

Ping @kata-containers/proxy.

grahamwhaley · 2018-08-03T09:12:39Z

OK, I think we are in the same 'the CIs that failed do not matter' situation here:

travis, failed the yq on OSX, but passed the others
codecov - @jodh-intel , are you bothered about the -0.49% diff?
ARM CI is not functional yet

None of the failing CIs is 'required', so I can press the big GREY button if we agree....

opendev-zuul · 2018-08-03T18:14:59Z

Build failed (third-party-check pipeline) integration testing with
OpenStack. For information on how to proceed, see
http://docs.openstack.org/infra/manual/developers.html#automated-testing

kata-runsh : SUCCESS in 59m 52s
kata-runsh-fedora-28 : NODE_FAILURE

sboeuf · 2018-08-06T16:09:28Z

@grahamwhaley yes I agree this can be merged.

jodh-intel mentioned this pull request Jul 3, 2018

logging: Redirect yamux warnings/errors to logger kata-containers/agent#289

Merged

jodh-intel force-pushed the add-yamux-logging branch from 466d8c2 to 6cbfedd Compare July 3, 2018 13:16

jodh-intel force-pushed the add-yamux-logging branch from 6cbfedd to 921f4f2 Compare July 5, 2018 12:36

jodh-intel force-pushed the add-yamux-logging branch from 921f4f2 to db780f4 Compare July 5, 2018 16:10

sboeuf approved these changes Jul 5, 2018

View reviewed changes

jodh-intel force-pushed the add-yamux-logging branch from db780f4 to b476458 Compare July 6, 2018 06:56

grahamwhaley mentioned this pull request Jul 6, 2018

yamux: keepalive failed: i/o deadline reached for proxybuiltin kata-containers/agent#294

Closed

egernst approved these changes Jul 23, 2018

View reviewed changes

jodh-intel force-pushed the add-yamux-logging branch from b476458 to 54eab20 Compare July 30, 2018 10:17

jodh-intel force-pushed the add-yamux-logging branch from 54eab20 to 0569fc2 Compare August 2, 2018 08:17

jodh-intel mentioned this pull request Aug 2, 2018

proxy: close yamux session properly #94

Merged

jodh-intel added the do-not-merge label Aug 2, 2018

logging: Redirect yamux warnings/errors to logger

ec252d8

Capture yamux messages to the logger. Fixes kata-containers#88. Signed-off-by: James O. D. Hunt <james.o.hunt@intel.com>

jodh-intel force-pushed the add-yamux-logging branch from 0569fc2 to ec252d8 Compare August 3, 2018 07:41

jodh-intel removed the do-not-merge label Aug 3, 2018

sboeuf merged commit ab48d7a into kata-containers:master Aug 6, 2018

Conversation

jodh-intel commented Jul 3, 2018

Uh oh!

jodh-intel commented Jul 3, 2018

Uh oh!

opendev-zuul bot commented Jul 3, 2018

Uh oh!

grahamwhaley commented Jul 3, 2018

Uh oh!

jodh-intel commented Jul 3, 2018

Uh oh!

jodh-intel commented Jul 3, 2018

Uh oh!

opendev-zuul bot commented Jul 3, 2018

Uh oh!

codecov bot commented Jul 5, 2018 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Codecov Report

Uh oh!

jodh-intel commented Jul 5, 2018

Uh oh!

opendev-zuul bot commented Jul 5, 2018

Uh oh!

jodh-intel commented Jul 5, 2018

Uh oh!

opendev-zuul bot commented Jul 5, 2018

Uh oh!

sboeuf commented Jul 5, 2018

Uh oh!

jodh-intel commented Jul 6, 2018

Uh oh!

opendev-zuul bot commented Jul 6, 2018

Uh oh!

egernst commented Jul 23, 2018

Uh oh!

grahamwhaley commented Jul 23, 2018

Uh oh!

jodh-intel commented Jul 25, 2018

Uh oh!

jodh-intel commented Jul 30, 2018

Uh oh!

opendev-zuul bot commented Jul 30, 2018

Uh oh!

bergwolf commented Aug 1, 2018

Uh oh!

jodh-intel commented Aug 2, 2018

Uh oh!

opendev-zuul bot commented Aug 2, 2018

Uh oh!

bergwolf commented Aug 2, 2018

Uh oh!

jodh-intel commented Aug 2, 2018

Uh oh!

sboeuf commented Aug 3, 2018

Uh oh!

jodh-intel commented Aug 3, 2018

Uh oh!

grahamwhaley commented Aug 3, 2018

Uh oh!

opendev-zuul bot commented Aug 3, 2018

Uh oh!

sboeuf commented Aug 6, 2018

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

5 participants

codecov bot commented Jul 5, 2018 •

edited

Loading