api: GetLogs: improve client example with 'Follow' #2747

alban · 2016-06-05T18:21:09Z

With this PR, the api client_example gets a new flag -follow to use the 'Follow' feature of GetLogs.

To test this, start with running a container:

sudo rkt run docker://busybox --exec sh -- -c 'while sleep 1 ; do date ; done'

In another terminal, start rkt's API service:

rkt api-service

In another terminal, start client_example with different options:

cd api/v1alpha
go build  client_example.go
./client_example
./client_example -follow

See also #2740

/cc @yifan-gu @euank @pskrzyns

Previously, client_example was only able to call GetLogs without the 'Follow' option. This patch updates client_example.go to show how to test calls to GetLogs both with and without the 'Follow' option.

pskrzyns · 2016-06-06T16:25:51Z

I think that getLogsWithoutFollow and getLogsWithFollow should be one function with additional param stream = true | false. And if its not stream we should break for loop after first iteration.

This doesn't work with kvm flavor. I get empty logs.

With coreos flavor:
If you run ./client_example twice in a row it's crashing

./client_example
Pod "dc9edd8e-d62e-4d3c-a84a-65ba9e7d537c" is running.
2016/06/06 18:19:35 transport: http2Client.notifyError got notified that the client transport was broken EOF.
rpc error: code = 13 desc = transport is closing

In api-service:

fatal error: unexpected signal during runtime execution
[signal 0xb code=0x2 addr=0x7fce0c767950 pc=0x7fce0c767950]

runtime stack:
runtime.throw(0xffc200, 0x2a)
        /usr/lib/go-1.6/src/runtime/panic.go:530 +0x90
runtime.sigpanic()
        /usr/lib/go-1.6/src/runtime/sigpanic_unix.go:12 +0x5a

goroutine 130 [syscall, locked to thread]:
runtime.cgocall(0xbecc10, 0xc8203936a8, 0x0)
        /usr/lib/go-1.6/src/runtime/cgocall.go:123 +0x11b fp=0xc820393658 sp=0xc820393628
github.com/coreos/go-systemd/sdjournal._Cfunc_my_sd_journal_open_directory(0x7fce0c767950, 0xc8201e5740, 0x7fcde4003160, 0x0, 0x0)
        github.com/coreos/go-systemd/sdjournal/_obj/_cgo_gotypes.go:269 +0x41 fp=0xc8203936a8 sp=0xc820393658
github.com/coreos/go-systemd/sdjournal.NewJournalFromDir(0xc8205942c0, 0xa5, 0xc8201e5740, 0x0, 0x0)
        /var/lib/jenkins/workspace/rkt_test_logs/src/github.com/coreos/rkt/build-rkt-1.7.0+git/gopath/src/github.com/coreos/rkt/Godeps/_workspace/src/github.com/coreos/go-systemd/sdjournal/journal.go:384 +0x448 fp=0xc820393790 sp=0xc8203936a8
github.com/coreos/go-systemd/sdjournal.NewJournalReader(0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0xc8205942c0, 0xa5, 0x18a956fa, ...)
        /var/lib/jenkins/workspace/rkt_test_logs/src/github.com/coreos/rkt/build-rkt-1.7.0+git/gopath/src/github.com/coreos/rkt/Godeps/_workspace/src/github.com/coreos/go-systemd/sdjournal/read.go:61 +0xa7 fp=0xc820393918 sp=0xc820393790
main.(*v1AlphaAPIServer).GetLogs(0xc82018a2f0, 0xc82039f640, 0x7fce1026db90, 0xc820501190, 0x0, 0x0)
        /var/lib/jenkins/workspace/rkt_test_logs/src/github.com/coreos/rkt/build-rkt-1.7.0+git/gopath/src/github.com/coreos/rkt/rkt/api_service.go:762 +0x692 fp=0xc820393c48 sp=0xc820393918
github.com/coreos/rkt/api/v1alpha._PublicAPI_GetLogs_Handler(0xe6cfe0, 0xc82018a2f0, 0x7fce1026daf8, 0xc820592300, 0x0, 0x0)
        /var/lib/jenkins/workspace/rkt_test_logs/src/github.com/coreos/rkt/build-rkt-1.7.0+git/gopath/src/github.com/coreos/rkt/api/v1alpha/api.pb.go:1088 +0x175 fp=0xc820393cd0 sp=0xc820393c48
google.golang.org/grpc.(*Server).processStreamingRPC(0xc8200a29c0, 0x7fce1026d0d8, 0xc820590120, 0xc8202cea80, 0xc820341b80, 0x158d520, 0xc82033fdd0, 0x0, 0x0)
        /var/lib/jenkins/workspace/rkt_test_logs/src/github.com/coreos/rkt/build-rkt-1.7.0+git/gopath/src/github.com/coreos/rkt/Godeps/_workspace/src/google.golang.org/grpc/server.go:421 +0x2dc fp=0xc820393de8 sp=0xc820393cd0
google.golang.org/grpc.(*Server).handleStream(0xc8200a29c0, 0x7fce1026d0d8, 0xc820590120, 0xc8202cea80, 0xc82033fdd0)
        /var/lib/jenkins/workspace/rkt_test_logs/src/github.com/coreos/rkt/build-rkt-1.7.0+git/gopath/src/github.com/coreos/rkt/Godeps/_workspace/src/google.golang.org/grpc/server.go:493 +0x114e fp=0xc820393f40 sp=0xc820393de8
google.golang.org/grpc.(*Server).Serve.func2.1.1(0xc8200a29c0, 0x7fce1026d0d8, 0xc820590120, 0xc8202cea80, 0xc82033fdd0, 0xc82043c110)
        /var/lib/jenkins/workspace/rkt_test_logs/src/github.com/coreos/rkt/build-rkt-1.7.0+git/gopath/src/github.com/coreos/rkt/Godeps/_workspace/src/google.golang.org/grpc/server.go:278 +0x49 fp=0xc820393f70 sp=0xc820393f40
runtime.goexit()
        /usr/lib/go-1.6/src/runtime/asm_amd64.s:1998 +0x1 fp=0xc820393f78 sp=0xc820393f70
created by google.golang.org/grpc.(*Server).Serve.func2.1
        /var/lib/jenkins/workspace/rkt_test_logs/src/github.com/coreos/rkt/build-rkt-1.7.0+git/gopath/src/github.com/coreos/rkt/Godeps/_workspace/src/google.golang.org/grpc/server.go:280 +0x5ac

goroutine 1 [chan receive, locked to thread]:
main.runAPIService(0x158f960, 0x15edbf8, 0x0, 0x0, 0x0)
        /var/lib/jenkins/workspace/rkt_test_logs/src/github.com/coreos/rkt/build-rkt-1.7.0+git/gopath/src/github.com/coreos/rkt/rkt/api_service.go:818 +0x5ac
main.runWrapper.func1(0x158f960, 0x15edbf8, 0x0, 0x0)
        /var/lib/jenkins/workspace/rkt_test_logs/src/github.com/coreos/rkt/build-rkt-1.7.0+git/gopath/src/github.com/coreos/rkt/rkt/rkt.go:197 +0x43
github.com/spf13/cobra.(*Command).execute(0x158f960, 0x15edbf8, 0x0, 0x0, 0x0, 0x0)
        /var/lib/jenkins/workspace/rkt_test_logs/src/github.com/coreos/rkt/build-rkt-1.7.0+git/gopath/src/github.com/coreos/rkt/Godeps/_workspace/src/github.com/spf13/cobra/command.go:572 +0x85a
github.com/spf13/cobra.(*Command).ExecuteC(0x158f760, 0x158f960, 0x0, 0x0)
        /var/lib/jenkins/workspace/rkt_test_logs/src/github.com/coreos/rkt/build-rkt-1.7.0+git/gopath/src/github.com/coreos/rkt/Godeps/_workspace/src/github.com/spf13/cobra/command.go:662 +0x53f
github.com/spf13/cobra.(*Command).Execute(0x158f760, 0x0, 0x0)
        /var/lib/jenkins/workspace/rkt_test_logs/src/github.com/coreos/rkt/build-rkt-1.7.0+git/gopath/src/github.com/coreos/rkt/Godeps/_workspace/src/github.com/spf13/cobra/command.go:618 +0x2d
main.main()
        /var/lib/jenkins/workspace/rkt_test_logs/src/github.com/coreos/rkt/build-rkt-1.7.0+git/gopath/src/github.com/coreos/rkt/rkt/main.go:32 +0x98

goroutine 17 [syscall, locked to thread]:
runtime.goexit()
        /usr/lib/go-1.6/src/runtime/asm_amd64.s:1998 +0x1

goroutine 19 [syscall]:
os/signal.signal_recv(0x0)
        /usr/lib/go-1.6/src/runtime/sigqueue.go:116 +0x132
os/signal.loop()
        /usr/lib/go-1.6/src/os/signal/signal_unix.go:22 +0x18
created by os/signal.init.1
        /usr/lib/go-1.6/src/os/signal/signal_unix.go:28 +0x37

goroutine 22 [select, locked to thread]:
runtime.gopark(0x108b918, 0xc820057728, 0xee20a0, 0x6, 0xc82035b318, 0x2)
        /usr/lib/go-1.6/src/runtime/proc.go:262 +0x163
runtime.selectgoImpl(0xc820057728, 0x0, 0x18)
        /usr/lib/go-1.6/src/runtime/select.go:392 +0xa67
runtime.selectgo(0xc820057728)
        /usr/lib/go-1.6/src/runtime/select.go:215 +0x12
runtime.ensureSigM.func1()
        /usr/lib/go-1.6/src/runtime/signal1_unix.go:279 +0x358
runtime.goexit()
        /usr/lib/go-1.6/src/runtime/asm_amd64.s:1998 +0x1

goroutine 8 [IO wait]:
net.runtime_pollWait(0x7fce1026ada0, 0x72, 0x0)
        /usr/lib/go-1.6/src/runtime/netpoll.go:160 +0x60
net.(*pollDesc).Wait(0xc820106a70, 0x72, 0x0, 0x0)
        /usr/lib/go-1.6/src/net/fd_poll_runtime.go:73 +0x3a
net.(*pollDesc).WaitRead(0xc820106a70, 0x0, 0x0)
        /usr/lib/go-1.6/src/net/fd_poll_runtime.go:78 +0x36
net.(*netFD).accept(0xc820106a10, 0x0, 0x7fce102a41c0, 0xc8205280a0)
        /usr/lib/go-1.6/src/net/fd_unix.go:426 +0x27c
net.(*TCPListener).AcceptTCP(0xc8200c8218, 0xc82006de58, 0x0, 0x0)
        /usr/lib/go-1.6/src/net/tcpsock_posix.go:254 +0x4d
net.(*TCPListener).Accept(0xc8200c8218, 0x0, 0x0, 0x0, 0x0)
        /usr/lib/go-1.6/src/net/tcpsock_posix.go:264 +0x3d
google.golang.org/grpc.(*Server).Serve(0xc8200a29c0, 0x7fce1026aef8, 0xc8200c8218, 0x0, 0x0)
        /var/lib/jenkins/workspace/rkt_test_logs/src/github.com/coreos/rkt/build-rkt-1.7.0+git/gopath/src/github.com/coreos/rkt/Godeps/_workspace/src/google.golang.org/grpc/server.go:224 +0x1c1
created by main.runAPIService
        /var/lib/jenkins/workspace/rkt_test_logs/src/github.com/coreos/rkt/build-rkt-1.7.0+git/gopath/src/github.com/coreos/rkt/rkt/api_service.go:814 +0x498

goroutine 92 [select]:
google.golang.org/grpc/transport.(*http2Server).controller(0xc820590120)
        /var/lib/jenkins/workspace/rkt_test_logs/src/github.com/coreos/rkt/build-rkt-1.7.0+git/gopath/src/github.com/coreos/rkt/Godeps/_workspace/src/google.golang.org/grpc/transport/http2_server.go:618 +0x5da
created by google.golang.org/grpc/transport.newHTTP2Server
        /var/lib/jenkins/workspace/rkt_test_logs/src/github.com/coreos/rkt/build-rkt-1.7.0+git/gopath/src/github.com/coreos/rkt/Godeps/_workspace/src/google.golang.org/grpc/transport/http2_server.go:134 +0x853

goroutine 93 [IO wait]:
net.runtime_pollWait(0x7fce1026ace0, 0x72, 0xc8205900b4)
        /usr/lib/go-1.6/src/runtime/netpoll.go:160 +0x60
net.(*pollDesc).Wait(0xc820386060, 0x72, 0x0, 0x0)
        /usr/lib/go-1.6/src/net/fd_poll_runtime.go:73 +0x3a
net.(*pollDesc).WaitRead(0xc820386060, 0x0, 0x0)
        /usr/lib/go-1.6/src/net/fd_poll_runtime.go:78 +0x36
net.(*netFD).Read(0xc820386000, 0xc8205900b4, 0x9, 0x9, 0x0, 0x7fce10261028, 0xc8200a60b0)
        /usr/lib/go-1.6/src/net/fd_unix.go:250 +0x23a
net.(*conn).Read(0xc82056a008, 0xc8205900b4, 0x9, 0x9, 0x0, 0x0, 0x0)
        /usr/lib/go-1.6/src/net/net.go:172 +0xe4
io.ReadAtLeast(0x7fce1026d088, 0xc82056a008, 0xc8205900b4, 0x9, 0x9, 0x9, 0x0, 0x0, 0x0)
        /usr/lib/go-1.6/src/io/io.go:297 +0xe6
io.ReadFull(0x7fce1026d088, 0xc82056a008, 0xc8205900b4, 0x9, 0x9, 0x0, 0x0, 0x0)
        /usr/lib/go-1.6/src/io/io.go:315 +0x62
golang.org/x/net/http2.readFrameHeader(0xc8205900b4, 0x9, 0x9, 0x7fce1026d088, 0xc82056a008, 0x10000000, 0xc800000000, 0x0, 0x0)
        /var/lib/jenkins/workspace/rkt_test_logs/src/github.com/coreos/rkt/build-rkt-1.7.0+git/gopath/src/github.com/coreos/rkt/Godeps/_workspace/src/golang.org/x/net/http2/frame.go:228 +0xa5
golang.org/x/net/http2.(*Framer).ReadFrame(0xc820590090, 0x0, 0x0, 0x0, 0x0)
        /var/lib/jenkins/workspace/rkt_test_log
8000
s/src/github.com/coreos/rkt/build-rkt-1.7.0+git/gopath/src/github.com/coreos/rkt/Godeps/_workspace/src/golang.org/x/net/http2/frame.go:373 +0xe6
google.golang.org/grpc/transport.(*framer).readFrame(0xc820406060, 0x0, 0x0, 0x0, 0x0)
        /var/lib/jenkins/workspace/rkt_test_logs/src/github.com/coreos/rkt/build-rkt-1.7.0+git/gopath/src/github.com/coreos/rkt/Godeps/_workspace/src/google.golang.org/grpc/transport/http_util.go:450 +0x3d
google.golang.org/grpc/transport.(*http2Server).HandleStreams(0xc820590120, 0xc8204060f0)
        /var/lib/jenkins/workspace/rkt_test_logs/src/github.com/coreos/rkt/build-rkt-1.7.0+git/gopath/src/github.com/coreos/rkt/Godeps/_workspace/src/google.golang.org/grpc/transport/http2_server.go:247 +0x663
google.golang.org/grpc.(*Server).Serve.func2(0x7fce1026d0d8, 0xc820590120, 0xc8200a29c0)
        /var/lib/jenkins/workspace/rkt_test_logs/src/github.com/coreos/rkt/build-rkt-1.7.0+git/gopath/src/github.com/coreos/rkt/Godeps/_workspace/src/google.golang.org/grpc/server.go:281 +0xcd
created by google.golang.org/grpc.(*Server).Serve
        /var/lib/jenkins/workspace/rkt_test_logs/src/github.com/coreos/rkt/build-rkt-1.7.0+git/gopath/src/github.com/coreos/rkt/Godeps/_workspace/src/google.golang.org/grpc/server.go:286 +0xc78

cc @jellonek @jjlakis

alban · 2016-06-06T16:42:07Z

@pskrzyns I got the same crash with the same stack (with _Cfunc_my_sd_journal_open_directory) when I was trying coreos/go-systemd#166. Did your test include changes in go-systemd?

pskrzyns · 2016-06-06T16:55:30Z

@alban : no i didn't include those changes, I will try again with them

@iaguis : should api-service GetLogs work with kvm flavor ? or the changes were made only for coreos flavor ? cause at this moment I'm getting empty logs

alban · 2016-06-06T16:59:59Z

@pskrzyns I think my changes in go-systemd were wrong, as explained by @lucab there. So I was not suggested that you that, I was wondering if the crash were caused by them. But since you are not testing my go-systemd changes, the crash is not related. For some unknown reasons, that crash with that stack does not happen for me anymore. I don't know why. I thought it was because I dropped my patch on go-systemd.

yifan-gu · 2016-06-07T01:58:57Z

LGTM on this PR, this PR doesn't seem to related with the panic.

iaguis · 2016-06-07T14:01:13Z

@iaguis : should api-service GetLogs work with kvm flavor ? or the changes were made only for coreos flavor ? cause at this moment I'm getting empty logs

For some reason, journal integration doesn't work with the kvm flavor. Running journalctl -m doesn't show kvm pods' logs. I'll have a look.

jellonek · 2016-06-07T15:40:59Z

AFAIR kvm flavor does not register correctly in systemd-machined but still these logs could be readed with journalctl (without -m parameter, using some other option).

@pskrzyns could you elaborate a bit about this?

iaguis · 2016-06-07T15:46:23Z

AFAIR kvm flavor does not register correctly in systemd-machined but still these logs could be readed with journalctl (without -m parameter, using some other option).

If we register with systemd-machined, then -M works. Without doing that, it should still work with -m but it doesn't (just tested it). Not sure what happens.

iaguis · 2016-06-07T16:03:17Z

It seems persistent journaling is not enabled in the kvm stage1.

iaguis · 2016-06-07T17:01:01Z

I figured out why the journal is not persistent.

I started a kvm pod, changed root to stage1, copied a static strace program there and ran strace -s 512 -f /usr/lib/systemd/systemd-journald and saw the following snippet:

mkdir("/var/log/journal/c0adece08abd4c7f835bafdf59ed2b9a", 0755) = -1 EEXIST (File exists)
open("/var/log/journal/c0adece08abd4c7f835bafdf59ed2b9a/system.journal", O_RDWR|O_CREAT|O_CLOEXEC, 0640) = 14
fstat(14, {st_mode=S_IFREG|0640, st_size=240, ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_SHARED, 14, 0) = -1 EINVAL (Invalid argument)
close(14)                               = 0
writev(2, [{"Failed to open system journal: I"..., 47}, {"\n", 1}], 2Failed to open system journal: Invalid argument
) = 48

So apparently, the journal doesn't go to /var/log/journal because systemd attempts to mmap the system.journal file as MAP_SHARED and that's probably not supported by 9p (got the idea from http://stackoverflow.com/questions/18420473/invalid-argument-for-read-write-mmap/18421071#18421071).

iaguis · 2016-06-07T17:09:25Z

After mounting a tmpfs on /var/log/journal and restarting systemd-journald, I can see the journal running journalctl -D /var/log/journal/${machine-id} on stage1, which wasn't working before.

jellonek · 2016-06-07T17:47:50Z

Ough, very detailed info.
@jjlakis could you follow this?

jjlakis · 2016-06-13T14:29:18Z

As @xelatex mentioned, this LKVM patch solves the problem. But we apply this patch for LKVM. After removing it, I can see logs.
Maybe we can prevent situations described in commit message by adding sync after stopping the pod (after merging rkt stop)? So we can leave cache=loose.
@iaguis @jellonek @pskrzyns @lukasredynk

jjlakis · 2016-06-14T10:07:57Z

See #2795

jellonek · 2016-06-14T11:40:26Z

IMO sync should be done on kernel side just before reboot in patch, which turns halt into reboot.
I don't have resources to check this.

alban added 2 commits June 5, 2016 20:14

api: client_example: GetLogs with follow

741d9df

Previously, client_example was only able to call GetLogs without the 'Follow' option. This patch updates client_example.go to show how to test calls to GetLogs both with and without the 'Follow' option.

api: GetLogs: remove empty lines

fcd4ee0

alban added the area/api label Jun 5, 2016

This was referenced Jun 5, 2016

api_service: GetLogs() panic when setting follow == true #2740

Closed

sdjournal: fix error mgmt in NewJournalFromDir coreos/go-systemd#166

Closed

yifan-gu added the required-by/rktnetes label Jun 7, 2016

yifan-gu added priority/P0 area/api reviewed/lgtm and removed area/api labels Jun 7, 2016

alban added this to the v1.8.0 milestone Jun 7, 2016

alban merged commit 8721527 into rkt:master Jun 7, 2016

lucab mentioned this pull request Jun 9, 2016

apt-get update failed in kvm-flavor stage1 #1917

Closed

iaguis mentioned this pull request Jun 10, 2016

kvm: pod is not registered in machined #2664

Open

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Uh oh!

api: GetLogs: improve client example with 'Follow' #2747

api: GetLogs: improve client example with 'Follow' #2747

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

api: GetLogs: improve client example with 'Follow' #2747

api: GetLogs: improve client example with 'Follow' #2747

Uh oh!

Conversation

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!