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.
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.