Deadlock in version 1.9.3 and a full test for reproducing the issue

[sillydong]

This is related to #1440

I got a simple test function to reproduce the scenario.

package playground_test

import (
	"fmt"
	"testing"
	"time"

	"github.com/sirupsen/logrus"
)

type XXX struct {
	X string `json:"x"`
}

func (x XXX) MarshalJSON() ([]byte, error) {
	fmt.Println("aaa")
	logrus.Info("second")
	return []byte(`{"x":"y"}`), nil
}

func TestLog(t *testing.T) {
	jsonFormatter := &logrus.JSONFormatter{TimestampFormat: time.RFC3339Nano}
	logrus.StandardLogger().SetFormatter(jsonFormatter)

	x := XXX{}

	logrus.WithFields(logrus.Fields{
		"a": "b",
		"c": x,
	}).Info("first")
}

This case is like when we want to log something, the fields contains a value which has its own function for marshaling, and in that marshal function, it logged again. It's like log in log.

From the test output, we can see aaa printed, and second will not be printed.

If we comment out line logging second, we can see both aaa and first in output

Internally, it is caused in the second time of calling log and it trying to acquire Logger.mu in Entry.log.

The lock is held by the first call, so here it will blocked.

Further more, it is caused by the change in write function

lock is moved from after format to before format. So when it's running the format function, logger is locked and that time when people want to log another content, it cannot get lock and do logging.

For a log lib, people may want to log anywhere they want. So such case is really a possible daily usage for people. We cannot stop people from call log function inside a log call. We cannot review every structure in log field to ensure it's marshaling function has no log call. So I think this worth be fixed.

[sillydong]

relate to this PR #1263

[github-actions]

This issue is stale because it has been open for 30 days with no activity.