xmpp-certwatch

Add lots of logs rss
created pr with xmpp-certwatch/add-logging.1 on 2026-10-26T13:45:19Z · by 3c31bc8c
added xmpp-certwatch/add-logging.2 on 2026-10-26T13:54:49Z · by 3c31bc8c
1: 92fa143 ! 1: cfa444f Add lots of logs
commented on 2026-10-26T13:56:39Z · by 3c31bc8c
https://tangled.org/mrry.band/xmpp-certwatch add-logging
cmds
checkout latest patchset: 
ssh pr.pico.sh pull xmpp-certwatch:add-logging | git am -3
checkout specific patchset revision: 
ssh pr.pico.sh pull xmpp-certwatch:add-logging [rev] | git am -3
add changes to patch request: 
git format-patch main --stdout | ssh pr.pico.sh xmpp-certwatch:add-logging
add comment to patch request: 
ssh pr.pico.sh comment xmpp-certwatch:add-logging "lgtm!"

Patchset xmpp-certwatch/add-logging.1 on 2026-10-26T13:45:19Z · commit 92fa143

→ Add lots of logs
Eric Roberts 2026-10-26T13:41:20Z
+34 -6 cmd/cron/main.go #
......@@ -47,6 +47,8 @@ var xmppSession *xmpp.Session
4747 var pubsubService jid.JID
4848
4949 func publish(node string, title string) {
50+
51+ log.Printf("Publishing notification: node=%s", node)
5052 entryId := uuid.New().String()
5153 _, err := pubsub.PublishIQ(
5254 context.Background(),
......@@ -57,15 +59,20 @@ func publish(node string, title string) {
5759 atomEntry(entryId, title),
5860 )
5961 if err != nil {
60- log.Printf("Error publishing to %s", node, err)
62+ log.Printf("Error publishing to %s: %s", node, err)
63+ } else {
64+ log.Printf("Published notification: node=%s", node)
6165 }
6266 }
6367
6468 func main() {
69+
70+ log.Print("Cron started")
6571 opt, err := redis.ParseURL(os.Getenv("REDIS_URL"))
6672 if err != nil {
6773 log.Panic(err)
6874 }
75+ log.Print("Connecting XMPP session")
6976 xmppSession, err = DialXMPP(
7077 context.Background(),
7178 jid.MustParse(os.Args[1]),
......@@ -76,37 +83,58 @@ func main() {
7683 if err != nil {
7784 log.Panic(err)
7885 }
79- go func () {
86+ log.Print("XMPP session connected")
87+ go func() {
88+ log.Print("Serving XMPP session")
8089 err := xmppSession.Serve(nil)
8190 log.Printf("XMPP session error: %s\n", err)
8291 os.Exit(1)
8392 }()
8493 pubsubService = jid.MustParse(os.Args[3])
8594 rclient := redis.NewClient(opt)
95+ log.Print("Loading hosts from Redis")
8696 hosts := rclient.HGetAll(context.Background(), "mitm_monitor_hosts").Val()
97+ log.Printf("Loaded %d hosts from Redis", len(hosts))
98+ checked := 0
8799 for host, errCount := range hosts {
100+
101+ log.Printf("Checking host: host=%s progress=%d/%d", host, checked+1, len(hosts))
88102 result := CheckOne(host)
103+ log.Printf("Host check returned: host=%s", host)
89104 if result.Err != nil {
90105 log.Printf("Error checking %s: %s\n", host, result.Err)
91- errCount, _ := rclient.HIncrBy(context.Background(), "mitm_monitor_hosts", host, 1).Result()
106+ errCount := updateErrorCount(rclient, host, 1)
92107 if errCount > 1 {
93108 publish(host, fmt.Sprintf("Error checking %s: %s", host, result.Err))
94109 }
95110 } else if !result.Dnssec {
96111 log.Printf("No DNSSEC for %s\n", host)
97- rclient.HIncrBy(context.Background(), "mitm_monitor_hosts", host, 2)
112+ updateErrorCount(rclient, host, 2)
98113 publish(host, fmt.Sprintf("DNSSEC failed for %s", host))
99114 } else if !result.Daneok {
100115 log.Printf("DANE failed for %s\n", host)
101- rclient.HIncrBy(context.Background(), "mitm_monitor_hosts", host, 2)
116+ updateErrorCount(rclient, host, 2)
102117 publish(host, fmt.Sprintf("Certificate check failed for %s: possible MITM or you changed your public key", host))
103118 } else {
104119 log.Printf("Success for %s\n", host)
105- rclient.HSet(context.Background(), "mitm_monitor_hosts", host, 0)
120+ log.Printf("Resetting Redis error count: host=%s", host)
121+ err := rclient.HSet(context.Background(), "mitm_monitor_hosts", host, 0).Err()
122+ log.Printf("Redis error count reset returned: host=%s error=%v", host, err)
106123 errCountI, _ := strconv.Atoi(errCount)
107124 if errCountI > 1 {
108125 publish(host, fmt.Sprintf("Certificate checks passed for %s", host))
109126 }
110127 }
128+ checked++
129+ log.Printf("Finished host: host=%s progress=%d/%d", host, checked, len(hosts))
111130 }
131+ log.Printf("Cron completed: hosts=%d", checked)
132+}
133+
134+func updateErrorCount(client *redis.Client, host string, increment int64) int64 {
135+
136+ log.Printf("Updating Redis error count: host=%s increment=%d", host, increment)
137+ count, err := client.HIncrBy(context.Background(), "mitm_monitor_hosts", host, increment).Result()
138+ log.Printf("Redis error count update returned: host=%s count=%d error=%v", host, count, err)
139+ return count
112140 }
+17 -2 common/common.go #
......@@ -4,6 +4,7 @@ import (
44 "context"
55 "crypto/tls"
66 "fmt"
7+ "log"
78 "net"
89 "strings"
910 "time"
......@@ -73,6 +74,7 @@ func oneTarget(resolver *dane.Resolver, service string, selector string, target
7374 alpn = "xmpp-server"
7475 }
7576
77+ log.Printf("Resolving target addresses: service=%s selector=%s target=%s port=%d", service, selector, target, port)
7678 iplist, err := GetAddresses(resolver, target)
7779 if err != nil {
7880 return TargetResult{}, err
......@@ -83,8 +85,11 @@ func oneTarget(resolver *dane.Resolver, service string, selector string, target
8385 }
8486
8587 daneok := true
88+ log.Printf("Looking up TLSA: service=%s target=%s port=%d", service, target, port)
89+
8690 tlsa, err := dane.GetTLSA(resolver, target, int(port))
8791
92+ log.Printf("TLSA lookup returned: target=%s port=%d error=%v", target, port, err)
8893 if err != nil {
8994 return TargetResult{}, err
9095 }
......@@ -92,19 +97,25 @@ func oneTarget(resolver *dane.Resolver, service string, selector string, target
9297 infos := map[string]dane.TLSAinfo{}
9398 for _, ip := range iplist.IPs {
9499 // Ignore ygg targets for now
95- if strings.HasPrefix(fmt.Sprintf("%s", ip), "200:") { continue }
100+ if strings.HasPrefix(fmt.Sprintf("%s", ip), "200:") {
101+ log.Printf("Skipping Yggdrasil address: service=%s target=%s ip=%s port=%d", service, target, ip, port)
102+ continue
103+ }
96104 config := getDaneConfig(service, appname, alpn, service, ip, port)
97105 config.SetTLSA(tlsa)
98106
107+ log.Printf("Connecting target: service=%s selector=%s target=%s ip=%s port=%d starttls=%t", service, selector, target, ip, port, appname != "")
99108 if appname == "" {
100109 conn, err = dane.DialTLS(config)
101110 if err == nil {
111+ log.Printf("Starting TLS handshake: target=%s ip=%s port=%d", target, ip, port)
102112 err = conn.Handshake()
103113 }
104114 } else {
105115 conn, err = dane.DialStartTLS(config)
106116 }
107117
118+ log.Printf("Target connection returned: target=%s ip=%s port=%d error=%v", target, ip, port, err)
108119 if err != nil {
109120 return TargetResult{}, err
110121 }
......@@ -142,7 +153,9 @@ func oneTarget(resolver *dane.Resolver, service string, selector string, target
142153
143154 infos[fmt.Sprintf("%s:%d", ip, port)] = oneTlsa
144155
145- conn.Close()
156+ log.Printf("Closing target connection: target=%s ip=%s port=%d", target, ip, port)
157+ closeErr := conn.Close()
158+ log.Printf("Target connection close returned: target=%s ip=%s port=%d error=%v", target, ip, port, closeErr)
146159
147160 if config.DiagError != nil && config.DiagError.Error() != "DANE TLS authentication failed" {
148161 return TargetResult{}, config.DiagError
......@@ -168,6 +181,7 @@ type CheckResult struct {
168181
169182 func CheckOne(hostname string) CheckResult {
170183 finalResult := CheckResult{hostname, true, true, true, false, map[string]dane.TLSAinfo{}, nil}
184+ log.Printf("Initializing resolver: host=%s", hostname)
171185 resolver, err := dane.GetResolver("")
172186 if err != nil {
173187 finalResult.Err = err
......@@ -178,6 +192,7 @@ func CheckOne(hostname string) CheckResult {
178192 resolver.IPv6 = true
179193 resolver.IPv4 = true
180194
195+ log.Printf("Looking up SRV records: host=%s", hostname)
181196 allSrvs, err := GetSRV(resolver, hostname)
182197
183198 if err != nil {
+7 -0 common/dns.go #
......@@ -3,6 +3,7 @@ package common
33 import (
44 "errors"
55 "fmt"
6+ "log"
67 "net"
78 "strings"
89
......@@ -54,7 +55,10 @@ func sendQueryUDP(query *dane.Query, resolver *dane.Resolver) (*dns.Msg, error)
5455 retries := resolver.Retries
5556 for retries > 0 {
5657 for _, server := range resolver.Servers {
58+
59+ log.Printf("DNS query started: transport=udp name=%s type=%s server=%s attempt=%d", query.Name, dns.TypeToString[query.Type], server.Address(), resolver.Retries-retries+1)
5760 response, _, err = c.Exchange(m, server.Address())
61+ log.Printf("DNS query returned: transport=udp name=%s type=%s server=%s error=%v", query.Name, dns.TypeToString[query.Type], server.Address(), err)
5862 if err == nil {
5963 return response, err
6064 }
......@@ -81,7 +85,10 @@ func sendQueryTCP(query *dane.Query, resolver *dane.Resolver) (*dns.Msg, error)
8185 c.Timeout = resolver.Timeout
8286
8387 for _, server := range resolver.Servers {
88+
89+ log.Printf("DNS query started: transport=tcp name=%s type=%s server=%s", query.Name, dns.TypeToString[query.Type], server.Address())
8490 response, _, err = c.Exchange(m, server.Address())
91+ log.Printf("DNS query returned: transport=tcp name=%s type=%s server=%s error=%v", query.Name, dns.TypeToString[query.Type], server.Address(), err)
8592 if err == nil {
8693 return response, err
8794 }
Back to top