acme_client "got renewal info" (logger does not respect go-log config)

[lidel]

We properly set logger in client and in certmagic, but we also use acmez library which seems to have extra one here.

It seems to be produce periodic got renewal info entry in kubo log (info level logger even when go-log level set to error):

1.7308261718038344e+09	info	acme_client	got renewal info	{"names": ["*.peerid.libp2p.direct"], "window_start": 1735390961.3333333, "window_end": 1735563761.3333333, "selected_time": 1735465398, "recheck_after": 1730847771.803828, "explanation_url": ""}
1.730848371749988e+09	info	acme_client	got renewal info	{"names": ["*.peerid.libp2p.direct"], "window_start": 1735390961.3333333, "window_end": 1735563761.3333333, "selected_time": 1735484853, "recheck_after": 1730869971.74998, "explanation_url": ""}

Filling issue to track it down and set to logger we use in other places.

[lidel]

This should be taken care of by replacing defualt logger (above) with our custom go-log one (below):

p2p-forge/client/acme.go

Line 285 in d44723d

Logger: certCfg.Logger,

Tested latest code from #4 and it seems to log "got renewal info" with correct logger now:

2024-11-07T00:49:22.468+0100	INFO	autotls.acme_client	acme/ari.go:215	got renewal info	{"names": ["*.peerid.libp2p.direct"], "window_start": "2024-12-09T17:15:20.000Z", "window_end": "2024-12-11T17:15:20.000Z", "selected_time": "2024-12-09T17:51:39.000Z", "recheck_after": "2024-11-07T06:49:22.468+0100", "explanation_url": ""}
2024-11-07T00:49:22.470+0100	INFO	autotls	certmagic@v0.21.4/maintain.go:584	updated ACME renewal information	{"identifiers": ["*.peerid.libp2p.direct"], "cert_hash": "FOO", "ari_unique_id": "BAR", "cert_expiry": "2025-01-09T16:55:50.000Z", "selected_time": "2024-12-11T02:13:01.000Z", "next_update": "2024-11-07T06:49:22.468+0100", "explanation_url": ""}

Let's park this until Kubo 0.32.0-rc2 ships and runs for a while. If the log no longer appears (kubo defaults to ERROR), we will close this once 0.32.0 ships.

If it is still there in rc2, we have some other race condition than the one fixed in f599f48

[lidel]

ipfs/kubo@e18fdf2 helped identify the source of the log:

2024-11-08T00:15:44.453Z	INFO	autotls.default_acme_client_fixme.acme_client	acme/ari.go:215	got renewal info	{"names": ["*.peerid.libp2p.direct"], "window_start": "2024-12-28T13:02:41.333Z", "window_end": "2024-12-30T13:02:41.333Z", "selected_time": "2024-12-30T07:19:41.000Z", "recheck_after": "2024-11-08T06:15:44.453Z", "explanation_url": ""}

So we may need to refactor the way newCertmagicConfig and certCfg.Issuers = []certmagic.Issuer{myACME} interact.

If certmagic.Config.Issuers are not set when certmagic.New is called inside of newCertmagicConfig, then the default Issuer (certmagic.DefaultACME) with default client and default logger seems to be set somewhere inside of certmagic.

Does not look like a blocker, but def. a bug to fix once we tackle bigger problems.