search

ipshipyard / p2p-forge

An Authoritative DNS server for distributing DNS subdomains to libp2p peers
1 stars 0 forks source link

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

Open lidel opened 1 day ago

lidel commented 1 day ago

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 commented 16 hours ago

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

https://github.com/ipshipyard/p2p-forge/blob/d44723dbe7865df18a1d294dc4984b6c7903ebf2/client/acme.go#L285

Tested latest code from https://github.com/ipshipyard/p2p-forge/pull/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 https://github.com/ipshipyard/p2p-forge/commit/f599f4803109aeaeae1c80756580759889a92e16