util/log: don't panic

[benesch]

Previously, log.outputLogEntry could panic while holding the log mutex.
This would deadlock any goroutine that logged while recovering from the
panic, which is approximately all of the recover routines. Most
annoyingly, the crash reporter would deadlock, swallowing the cause of
the panic.

Avoid panicking while holding the log mutex and use l.exit instead,
which exists for this very purpose. In the process, enforce the
invariant that l.mu is held when l.exit is called. (The previous
behavior was, in fact, incorrect, as l.flushAll should not be called
without holding l.mu.)

Also add a Tcl test to ensure this doesn't break in the future.

[cockroach-teamcity]

This change is 

[benesch]

Wait, this will also deadlock because the mutex is already held when l.exit() is called. Grr.

[knz]

I think this should be backported to 1.0.6 if we release one.

[tbg]

I think we'll release one, given the recent bugs that we fixed.

[tbg]

@benesch Imk when I can take a look.

[benesch]

@tschottdorf @knz mind taking another look today? Turns out this was more broken than I thought.

[benesch]

Specifically, @petermattis made l.exit acquire l.mu in 9fcfe5e, and @tschottdorf fixed the deadlock this caused in ed6a100 by unlocking l.mu before calling l.exit.

The fix I've applied here is to instead require that l.exit's caller acquire l.mu. This was both the original expectation when @tschottdorf imported clog in b0d884b and makes l.outputLogEntry much cleaner because it can defer the unlock of l.mu.

[knz]

This looks good, but I am a bit sad about introducing a defer in the logging hot path. We've tried hard to avoid that until now. Tobias what do you think?

---

Reviewed 1 of 2 files at r1.
Review status: 1 of 2 files reviewed at latest revision, all discussions resolved, some commit checks failed.

---

Comments from Reviewable

[benesch]

Ha, I had no idea defer was slow! I only added the defer to protect against someone adding a panic, since it's very confusing to panic while holding a lock unless you defer the unlock. But it's not strictly necessary now that I've removed all the panics from the code path.

---

Review status: 1 of 2 files reviewed at latest revision, all discussions resolved, some commit checks failed.

---

Comments from Reviewable

[petermattis]

Review status: 1 of 2 files reviewed at latest revision, 3 unresolved discussions, some commit checks failed.

---

pkg/util/log/clog.go, line 713 at r1 (raw file):

	// TODO(tschottdorf): this is a pretty horrible critical section.
	l.mu.Lock()
	defer l.mu.Unlock()

Rather than the defer, I think you should leave the explicit l.mu.Unlock on the two returns.

---

pkg/util/log/clog.go, line 803 at r1 (raw file):

	done := make(chan bool, 1)
	go func() {
		logging.flushAll()

This can get run without logging.mu being held. I'm not understanding this portion of the change given that timeoutFlush was only called from one place.

---

pkg/util/log/clog.go, line 841 at r1 (raw file):

// to stderr. It flushes the logs and exits the program; there's no point in
// hanging around. l.mu is held.
func (l *loggingT) exit(err error) {

Now that the lock is required, let's rename this exitLocked.

---

Comments from Reviewable

[tbg]

Afraid I can't right now, perhaps drum up someone else?

On Thu, Aug 31, 2017, 15:46 Nikhil Benesch ***@***.***> wrote: @tschottdorf <https://github.com/tschottdorf> @knz <https://github.com/knz> mind taking another look today? Turns out this was more broken than I thought. — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub <#17871 (comment)>, or mute the thread <https://github.com/notifications/unsubscribe-auth/AE135C-qDxhKWjHg-bHdEa4sq_Wyg8lqks5sdw2TgaJpZM4PAlkW> .

--

…

-- Tobias

[benesch]

@tschottdorf, ack. @petermattis @knz PTAL.

---

Review status: 1 of 2 files reviewed at latest revision, 3 unresolved discussions, some commit checks pending.

---

pkg/util/log/clog.go, line 713 at r1 (raw file):

Previously, petermattis (Peter Mattis) wrote…

Rather than the defer, I think you should leave the explicit l.mu.Unlock on the two returns.

Done.

---

pkg/util/log/clog.go, line 803 at r1 (raw file):

Previously, petermattis (Peter Mattis) wrote…

This can get run without logging.mu being held. I'm not understanding this portion of the change given that timeoutFlush was only called from one place.

It was changed to work with the defer l.mu.Unlock(); not necessary now. Reverted.

---

pkg/util/log/clog.go, line 841 at r1 (raw file):

Previously, petermattis (Peter Mattis) wrote…

Now that the lock is required, let's rename this exitLocked.

Done.

---

Comments from Reviewable

[petermattis]

---

Review status: 1 of 2 files reviewed at latest revision, all discussions resolved, some commit checks pending.

---

Comments from Reviewable