Too rapid geth.log file growth

[osmaczko]

Problem

The general problem is that the geth.log file grows too rapidly, especially when the debug log level is enabled. The default geth.log rotation strategy in status-desktop is to maintain a single geth.log file with a size limit of 100MB, then overwrite it when the next output file reaches the same limit:

$ ll geth*
100M Sep 28 10:42 geth-2024-09-28T08-42-56.771.log
40M Sep 28 10:45 geth.log

For my main Status account with the debug log level enabled, it takes approximately 6 minutes for the rotation, which is far too quick.

status-go version: 74ae41154

Future Steps

• identify extensive and excessive logs
• consider disabling go-waku logs
• consider moving some debug level logs to trace level
• consider logging categories which can be configured at runtime

[osmaczko]

$ grep "github.com/waku-org/go-waku" geth-2024-09-28T08-42-56.771.log | wc -c | awk '{print $1 / (1024 * 1024) " MB"}'     
1.79132 MB

$ grep "github.com/status-im/status-go/wakuv2" geth-2024-09-28T08-42-56.771.log | wc -c | awk '{print $1 / (1024 * 1024) " MB"}'
48.1634 MB

$ grep "protocol/messenger_mailserver.go" geth-2024-09-28T08-42-56.771.log | wc -c | awk '{print $1 / (1024 * 1024) " MB"}'     
45.0911 MB

Most of the log size is coming from github.com/status-im/status-go/wakuv2 and protocol/messenger_mailserver.go, where the later is being fixed.

CC: @richard-ramos

[osmaczko]

I've done more grepping, the results:

Code location	Size [MB]
github.com/status-im/status-go/wakuv2/waku.go	28.44
github.com/status-im/status-go/wakuv2/waku.go:1310	7.88
github.com/status-im/status-go/wakuv2/waku.go:1543	6.69
github.com/status-im/status-go/wakuv2/waku.go:1438	6.53
github.com/status-im/status-go/wakuv2/waku.go:1584	4.26
github.com/status-im/status-go/wakuv2/tracer.go	19

github.com/status-im/status-go/wakuv2/tracer.go seems to be fixed already status-im/status-go#5740

[richard-ramos]

:1310 - Seems useful for debugging

		logger.Info("received waku2 store message",
			zap.Stringer("envelopeHash", envelope.Hash()),
			zap.String("pubsubTopic", query.PubsubTopic),
			zap.Int64p("timestamp", envelope.Message().Timestamp),

:1543 - This seems useful for debugging too

	logger := w.logger.With(
		zap.Any("messageType", msgType),
		zap.Stringer("envelopeHash", envelope.Hash()),
		zap.String("contentTopic", envelope.Message().ContentTopic),
		zap.Int64("timestamp", envelope.Message().GetTimestamp()),
	)

	logger.Debug("received new envelope")

:1438 - We can probably eliminate this one, as it is not really useful to log that

	w.logger.Debug("peer stats",
		zap.Int("peersCount", len(latestConnStatus.Peers)),
		zap.Any("stats", latestConnStatus))

:1584 - These can be probably eliminated (they're all part of waku.add)

		logger := w.logger.With(zap.String("envelopeHash", recvMessage.Hash().Hex()))
...
		logger.Debug("w envelope already cached")
...
		logger.Debug("cached w envelope")
...
		logger.Debug("immediately processing envelope")
...
		logger.Debug("posting event")

I think we can get rid of some of these bugs, but the first two are kind of useful when debugging whether a message is received or not. I wonder if we can add some other level like TRACE to the logs?

[richard-ramos]

Seems like it should be possible?
uber-go/zap#680 (comment)

Wdyt, @osmaczko @igor-sirotin

[igor-sirotin]

uber-go/zap#680 (comment)

I like the idea of Trace level in general 👍 (but we should be careful even with that one)

[osmaczko]

Seems like it should be possible? uber-go/zap#680 (comment)

Wdyt, @osmaczko @igor-sirotin

We discussed the trace level in one of the meetings. The conclusion was that with the trace level, we could end up having the same problem, so it is better to implement categorized logging configurable at runtime. Examples of potential categories include "wallet," "waku," "messenger," "communities," etc. I believe it would be best to combine both, to be honest.

[osmaczko]

Note to myself: historical reasons of why we use zap.Logger and geth.Logger and how they were merged together: status-im/status-go#1534

[osmaczko]

Waiting for status-im/status-mobile#21758 to merge the last missing piece status-im/status-go#6164.