Bug 81628

Summary: journal: hang writing journal entry (v215)
Product: systemd Reporter: Brandon Philips <brandon>
Component: generalAssignee: systemd-bugs
Status: NEW --- QA Contact: systemd-bugs
Severity: normal    
Priority: medium CC: mike
Version: unspecified   
Hardware: Other   
OS: All   
Whiteboard:
i915 platform: i915 features:

Description Brandon Philips 2014-07-22 02:36:29 UTC
We have a service that writes to the systemd socket using github.com/coreos/go-systemd. With systemd 215 we have noticed that on some boots the process will hang trying to write to the socket. At around the same time that this process is starting journald is doing a compaction.

I will try and gather more details; it is a very easy thing to reproduce.

Jul 22 02:31:22 localhost systemd-journal[87]: Runtime journal is using 6.2M (max allowed 49.9M, trying to leave 74.8M free of 492.8M available → current limit 49.9M).
Jul 22 02:31:22 localhost systemd-journal[87]: Runtime journal is using 6.2M (max allowed 49.9M, trying to leave 74.8M free of 492.8M available → current limit 49.9M).
Jul 22 02:31:22 localhost systemd-journal[87]: Journal started
Jul 22 02:31:22 localhost systemd-journal[87]: Missed 73 kernel messages
Jul 22 02:31:22 localhost systemd-journal[87]: Missed 0 kernel messages
Jul 22 02:31:22 localhost systemd-journal[87]: Missed 5 kernel messages
Jul 22 02:31:22 localhost systemd-journal[87]: Missed 0 kernel messages
Jul 22 02:31:23 localhost systemd-journal[87]: Missed 0 kernel messages
Jul 22 02:31:23 localhost systemd-journal[87]: Missed 7 kernel messages
Jul 22 02:31:23 localhost systemd-journal[87]: Missed 1 kernel messages
Jul 22 02:31:23 localhost systemd-journal[87]: Missed 1 kernel messages
Jul 22 02:31:24 localhost systemd-journal[87]: Missed 11 kernel messages
Jul 22 02:31:24 core-03 systemd-journal[369]: Runtime journal is using 6.2M (max allowed 49.9M, trying to leave 74.8M free of 486.6M available → current limit 49.9M).
Jul 22 02:31:24 core-03 systemd-journal[369]: Runtime journal is using 6.2M (max allowed 49.9M, trying to leave 74.8M free of 486.6M available → current limit 49.9M).
Jul 22 02:31:24 core-03 systemd-journal[369]: Journal started
Jul 22 02:31:25 core-03 systemd-journal[369]: Permanent journal is using 24.0M (max allowed 1.6G, trying to leave 2.4G free of 15.7G available → current limit 1.6G).
Jul 22 02:31:25 core-03 systemd-journal[369]: Time spent on flushing to /var is 379.365ms for 820 entries.
Comment 1 Brandon Philips 2014-07-22 02:53:56 UTC
Hrm, it is pretty clearly hung writing to the systemd. I am going to try and write a C program to reproduce this using the systemd libraries.

Jul 22 02:41:05 core-03 etcd[562]: net.(*conn).Write(0xc2100001c8, 0xc210099400, 0x158, 0x1dd, 0xeffe28, ...)
Jul 22 02:41:05 core-03 etcd[562]: /usr/lib/go/src/pkg/net/net.go:130 +0xc5
Jul 22 02:41:05 core-03 etcd[562]: bytes.(*Buffer).WriteTo(0xc21004acb0, 0x7f46407c34f0, 0xc2100001c8, 0x0, 0x0, ...)
Jul 22 02:41:05 core-03 etcd[562]: /usr/lib/go/src/pkg/bytes/buffer.go:202 +0xc5
Jul 22 02:41:05 core-03 systemd[1]: etcd.service: main process exited, code=exited, status=2/INVALIDARGUMENT
Jul 22 02:41:05 core-03 systemd[1]: Unit etcd.service entered failed state.
Jul 22 02:41:05 core-03 etcd[562]: io.Copy(0x7f46407c34f0, 0xc2100001c8, 0x7f46407c34c8, 0xc21004acb0, 0x0, ...)
Jul 22 02:41:05 core-03 etcd[562]: /usr/lib/go/src/pkg/io/io.go:344 +0xa5
Jul 22 02:41:05 core-03 etcd[562]: github.com/coreos/etcd/third_party/github.com/coreos/go-systemd/journal.Send(0xc2100389c0, 0x50, 0x6, 0xc2100a2060, 0xc2100007a8, ...)
Jul 22 02:41:05 core-03 etcd[562]: /build/amd64-usr/var/tmp/portage/dev-db/etcd-0.4.5/work/etcd-0.4.5/gopath/src/github.com/coreos/etcd/third_party/github.com/coreos/go-systemd/journal/send.go:66 +0x2d0
Jul 22 02:41:05 core-03 etcd[562]: github.com/coreos/etcd/third_party/github.com/coreos/go-log/log.(*journalSink).Log(0xf09f08, 0xc2100a2030)
Jul 22 02:41:05 core-03 etcd[562]: /build/amd64-usr/var/tmp/portage/dev-db/etcd-0.4.5/work/etcd-0.4.5/gopath/src/github.com/coreos/etcd/third_party/github.com/coreos/go-log/log/sinks_unix.go:41 +0x228
Jul 22 02:41:05 core-03 etcd[562]: github.com/coreos/etcd/third_party/github.com/coreos/go-log/log.(*combinedSink).Log(0xc210048560, 0xc2100a2030)
Jul 22 02:41:05 core-03 etcd[562]: /build/amd64-usr/var/tmp/portage/dev-db/etcd-0.4.5/work/etcd-0.4.5/gopath/src/github.com/coreos/etcd/third_party/github.com/coreos/go-log/log/sinks.go:76 +0x67
Jul 22 02:41:05 core-03 etcd[562]: github.com/coreos/etcd/third_party/github.com/coreos/go-log/log.(*Logger).Log(0xc210038120, 0x6, 0x7f4640620ae0, 0x1, 0x1)
Jul 22 02:41:05 core-03 etcd[562]: /build/amd64-usr/var/tmp/portage/dev-db/etcd-0.4.5/work/etcd-0.4.5/gopath/src/github.com/coreos/etcd/third_party/github.com/coreos/go-log/log/commands.go:37 +0x14e
Jul 22 02:41:05 core-03 etcd[562]: github.com/coreos/etcd/third_party/github.com/coreos/go-log/log.(*Logger).Infof(0xc210038120, 0x8a5910, 0x14, 0x7f4640620be0, 0x2, ...)
Jul 22 02:41:05 core-03 etcd[562]: /build/amd64-usr/var/tmp/portage/dev-db/etcd-0.4.5/work/etcd-0.4.5/gopath/src/github.com/coreos/etcd/third_party/github.com/coreos/go-log/log/commands.go:92 +0xfc
Jul 22 02:41:05 core-03 etcd[562]: github.com/coreos/etcd/log.Infof(0x8a5910, 0x14, 0x7f4640620be0, 0x2, 0x2)
Jul 22 02:41:05 core-03 etcd[562]: /build/amd64-usr/var/tmp/portage/dev-db/etcd-0.4.5/work/etcd-0.4.5/gopath/src/github.com/coreos/etcd/log/log.go:16 +0x5c
Jul 22 02:41:05 core-03 etcd[562]: github.com/coreos/etcd/server.(*PeerServer).raftEventLogger(0xc21009d000, 0x7f46407c3268, 0xc21009aa40)
Jul 22 02:41:05 core-03 etcd[562]: /build/amd64-usr/var/tmp/portage/dev-db/etcd-0.4.5/work/etcd-0.4.5/gopath/src/github.com/coreos/etcd/server/peer_server.go:699 +0x2a5
Jul 22 02:41:05 core-03 etcd[562]: github.com/coreos/etcd/server.*PeerServer.(github.com/coreos/etcd/server.raftEventLogger)<C2><B7>fm(0x7f46407c3268, 0xc21009aa40)
Jul 22 02:41:05 core-03 etcd[562]: /build/amd64-usr/var/tmp/portage/dev-db/etcd-0.4.5/work/etcd-0.4.5/gopath/src/github.com/coreos/etcd/server/peer_server.go:128 +0x3a
Jul 22 02:41:05 core-03 etcd[562]: github.com/coreos/etcd/third_party/github.com/goraft/raft.(*eventDispatcher).DispatchEvent(0xc210098810, 0x7f46407c3268, 0xc21009aa40)
Jul 22 02:41:05 core-03 etcd[562]: /build/amd64-usr/var/tmp/portage/dev-db/etcd-0.4.5/work/etcd-0.4.5/gopath/src/github.com/coreos/etcd/third_party/github.com/goraft/raft/event_dispatcher.go:66 +0x151
Jul 22 02:41:05 core-03 etcd[562]: github.com/coreos/etcd/third_party/github.com/goraft/raft.(*server).AddPeer(0xc210052d80, 0xc210098cc0, 0x20, 0x863890, 0x0, ...)
Jul 22 02:41:05 core-03 etcd[562]: /build/amd64-usr/var/tmp/portage/dev-db/etcd-0.4.5/work/etcd-0.4.5/gopath/src/github.com/coreos/etcd/third_party/github.com/goraft/raft/server.go:1135 +0x4a0
Jul 22 02:41:05 core-03 etcd[562]: github.com/coreos/etcd/server.applyJoin(0xc21009a2c0, 0x7f46407c32d0, 0xc210098cf0, 0x7f46407b8000, 0x200872170, ...)
Jul 22 02:41:05 core-03 etcd[562]: /build/amd64-usr/var/tmp/portage/dev-db/etcd-0.4.5/work/etcd-0.4.5/gopath/src/github.com/coreos/etcd/server/join_command.go:91 +0xb1a
Jul 22 02:41:05 core-03 etcd[562]: github.com/coreos/etcd/server.(*JoinCommand).Apply(0xc21009a2c0, 0x7f46407c32d0, 0xc210098cf0, 0x7f46407c32d0, 0xc21009a2c0, ...)
Jul 22 02:41:05 core-03 etcd[562]: /build/amd64-usr/var/tmp/portage/dev-db/etcd-0.4.5/work/etcd-0.4.5/gopath/src/github.com/coreos/etcd/server/join_command.go:32 +0x40
Jul 22 02:41:05 core-03 etcd[562]: github.com/coreos/etcd/third_party/github.com/goraft/raft.func<C2><B7>006(0xc210048c80, 0x7f46407c2920, 0xc21009a2c0, 0x94, 0x94, ...)
Jul 22 02:41:05 core-03 etcd[562]: /build/amd64-usr/var/tmp/portage/dev-db/etcd-0.4.5/work/etcd-0.4.5/gopath/src/github.com/coreos/etcd/third_party/github.com/goraft/raft/server.go:205 +0x23b
Jul 22 02:41:05 core-03 etcd[562]: github.com/coreos/etcd/third_party/github.com/goraft/raft.(*Log).open(0xc21004a850, 0xc210048c40, 0x11, 0x7f46407c2a40, 0xc2100988d0)
Jul 22 02:41:05 core-03 etcd[562]: /build/amd64-usr/var/tmp/portage/dev-db/etcd-0.4.5/work/etcd-0.4.5/gopath/src/github.com/coreos/etcd/third_party/github.com/goraft/raft/log.go:186 +0xa47
Jul 22 02:41:05 core-03 etcd[562]: github.com/coreos/etcd/third_party/github.com/goraft/raft.(*server).Init(0xc210052d80, 0x19, 0x7f46406213d0)
Jul 22 02:41:05 core-03 etcd[562]: /build/amd64-usr/var/tmp/portage/dev-db/etcd-0.4.5/work/etcd-0.4.5/gopath/src/github.com/coreos/etcd/third_party/github.com/goraft/raft/server.go:506 +0x714
Jul 22 02:41:05 core-03 etcd[562]: github.com/coreos/etcd/server.(*PeerServer).SetRaftServer(0xc21009d000, 0x7f46407c2ed0, 0xc210052d80, 0x1)
Jul 22 02:41:05 core-03 etcd[562]: /build/amd64-usr/var/tmp/portage/dev-db/etcd-0.4.5/work/etcd-0.4.5/gopath/src/github.com/coreos/etcd/server/peer_server.go:154 +0x4cc
Jul 22 02:41:05 core-03 etcd[562]: github.com/coreos/etcd/etcd.(*Etcd).Run(0xc210058700)
Jul 22 02:41:05 core-03 etcd[562]: /build/amd64-usr/var/tmp/portage/dev-db/etcd-0.4.5/work/etcd-0.4.5/gopath/src/github.com/coreos/etcd/etcd/etcd.go:215 +0x1bfd
Jul 22 02:41:05 core-03 etcd[562]: main.main()
Jul 22 02:41:05 core-03 etcd[562]: /build/amd64-usr/var/tmp/portage/dev-db/etcd-0.4.5/work/etcd-0.4.5/gopath/src/github.com/coreos/etcd/main.go:43 +0x2b2
Jul 22 02:41:05 core-03 etcd[562]: rax     0xca
Jul 22 02:41:05 core-03 etcd[562]: rbx     0xc2100290e8
Jul 22 02:41:05 core-03 etcd[562]: rcx     0xffffffffffffffff
Jul 22 02:41:05 core-03 etcd[562]: rdx     0x0
Jul 22 02:41:05 core-03 etcd[562]: rdi     0xf00c20
Jul 22 02:41:05 core-03 etcd[562]: rsi     0x0
Jul 22 02:41:05 core-03 etcd[562]: rbp     0xc21000b0a0
Jul 22 02:41:05 core-03 etcd[562]: rsp     0x7f464063beb0
Jul 22 02:41:05 core-03 etcd[562]: r8      0x0
Jul 22 02:41:05 core-03 etcd[562]: r9      0x0
Jul 22 02:41:05 core-03 etcd[562]: r10     0x0
Jul 22 02:41:05 core-03 etcd[562]: r11     0x286
Jul 22 02:41:05 core-03 etcd[562]: r12     0x84c200
Jul 22 02:41:05 core-03 etcd[562]: r13     0x0
Jul 22 02:41:05 core-03 etcd[562]: r14     0x232
Jul 22 02:41:05 core-03 etcd[562]: r15     0x10
Jul 22 02:41:05 core-03 etcd[562]: rip     0x427f71
Jul 22 02:41:05 core-03 etcd[562]: rflags  0x286
Jul 22 02:41:05 core-03 etcd[562]: cs      0x33
Jul 22 02:41:05 core-03 etcd[562]: fs      0x0
Jul 22 02:41:05 core-03 etcd[562]: gs      0x0

Use of freedesktop.org services, including Bugzilla, is subject to our Code of Conduct. How we collect and use information is described in our Privacy Policy.