implement debug log

[mnalis]

I'd like to have debug log, e.g. when using DoH I'd like to seetimestamps and detailed steps by step raw information

[mnalis]

Ideally, similar to what curl -v does, e.g.:

Oct 13 09:08:13.000603 *   Trying 1.1.1.1:443...
Oct 13 09:08:13.005656 * Connected to 1.1.1.1 (1.1.1.1) port 443 (#0)
Oct 13 09:08:13.006905 * ALPN: offers h2,http/1.1
Oct 13 09:08:13.007127 } [5 bytes data]
Oct 13 09:08:13.007150 * TLSv1.3 (OUT), TLS handshake, Client hello (1):
Oct 13 09:08:13.007157 } [512 bytes data]
Oct 13 09:08:13.027921 *  CAfile: /etc/ssl/certs/ca-certificates.crt
Oct 13 09:08:13.027944 *  CApath: /etc/ssl/certs
Oct 13 09:08:13.027951 { [5 bytes data]
Oct 13 09:08:13.027957 * TLSv1.3 (IN), TLS handshake, Server hello (2):
Oct 13 09:08:13.027965 { [122 bytes data]
Oct 13 09:08:13.028051 * TLSv1.3 (IN), TLS handshake, Encrypted Extensions (8):
Oct 13 09:08:13.028075 { [15 bytes data]
Oct 13 09:08:13.028085 * TLSv1.3 (IN), TLS handshake, Certificate (11):
Oct 13 09:08:13.028091 { [2993 bytes data]
Oct 13 09:08:13.028532 * TLSv1.3 (IN), TLS handshake, CERT verify (15):
Oct 13 09:08:13.028551 { [79 bytes data]
Oct 13 09:08:13.028557 * TLSv1.3 (IN), TLS handshake, Finished (20):
Oct 13 09:08:13.028562 { [52 bytes data]
Oct 13 09:08:13.028654 * TLSv1.3 (OUT), TLS change cipher, Change cipher spec (1):
Oct 13 09:08:13.028674 } [1 bytes data]
Oct 13 09:08:13.028681 * TLSv1.3 (OUT), TLS handshake, Finished (20):
Oct 13 09:08:13.028688 } [52 bytes data]
Oct 13 09:08:13.028695 * SSL connection using TLSv1.3 / TLS_AES_256_GCM_SHA384
Oct 13 09:08:13.028700 * ALPN: server accepted h2
Oct 13 09:08:13.028706 * Server certificate:
Oct 13 09:08:13.028712 *  subject: C=US; ST=California; L=San Francisco; O=Cloudflare, Inc.; CN=cloudflare-dns.com
Oct 13 09:08:13.028723 *  start date: Jul 30 00:00:00 2024 GMT
Oct 13 09:08:13.028729 *  expire date: Jan 21 23:59:59 2025 GMT
Oct 13 09:08:13.028734 *  subjectAltName: host "1.1.1.1" matched cert's IP address!
Oct 13 09:08:13.028739 *  issuer: C=US; O=DigiCert Inc; CN=DigiCert Global G2 TLS RSA SHA256 2020 CA1
Oct 13 09:08:13.028745 *  SSL certificate verify ok.
Oct 13 09:08:13.028756 } [5 bytes data]
Oct 13 09:08:13.028765 * using HTTP/2
Oct 13 09:08:13.028869 * h2h3 [:method: GET]
Oct 13 09:08:13.028892 * h2h3 [:path: /dns-query?name=cloudflare.com]
Oct 13 09:08:13.028898 * h2h3 [:scheme: https]
Oct 13 09:08:13.028903 * h2h3 [:authority: 1.1.1.1]
Oct 13 09:08:13.028908 * h2h3 [user-agent: curl/7.88.1]
Oct 13 09:08:13.028913 * h2h3 [accept: application/dns-json]
Oct 13 09:08:13.028917 * Using Stream ID: 1 (easy handle 0x55f41c105ce0)
Oct 13 09:08:13.028922 } [5 bytes data]
Oct 13 09:08:13.028927 > GET /dns-query?name=cloudflare.com HTTP/2
Oct 13 09:08:13.028931 > Host: 1.1.1.1
Oct 13 09:08:13.028936 > user-agent: curl/7.88.1
Oct 13 09:08:13.028940 > accept: application/dns-json
Oct 13 09:08:13.028945 > 
Oct 13 09:08:13.037014 { [5 bytes data]
Oct 13 09:08:13.037036 * TLSv1.3 (IN), TLS handshake, Newsession Ticket (4):
Oct 13 09:08:13.037043 { [230 bytes data]
Oct 13 09:08:13.037049 * TLSv1.3 (IN), TLS handshake, Newsession Ticket (4):
Oct 13 09:08:13.037057 { [230 bytes data]
Oct 13 09:08:13.037062 * old SSL session ID is stale, removing
Oct 13 09:08:13.037069 { [5 bytes data]
Oct 13 09:08:13.043912 < HTTP/2 200 
Oct 13 09:08:13.043972 < server: cloudflare
Oct 13 09:08:13.043983 < date: Sun, 13 Oct 2024 07:08:13 GMT
Oct 13 09:08:13.043993 < content-type: application/dns-json
Oct 13 09:08:13.044003 < access-control-allow-origin: *
Oct 13 09:08:13.044011 < content-length: 261
Oct 13 09:08:13.044017 < cf-ray: 8d1d7f457e63c205-ZAG
Oct 13 09:08:13.044023 < alt-svc: h3=":443"; ma=86400
Oct 13 09:08:13.044029 < 
Oct 13 09:08:13.044133 { [5 bytes data]
Oct 13 09:08:13.044158 * Connection #0 to host 1.1.1.1 left intact
Oct 13 09:08:13.044255 {"Status":0,"TC":false,"RD":true,"RA":true,"AD":true,"CD":false,"Question":[{"name":"cloudflare.com","type":1}],"Answer":[{"name":"cloudflare.com","type":1,"TTL":167,"data":"104.16.133.229"},{"name":"cloudflare.com","type":1,"TTL":167,"data":"104.16.132.229"}]}* Found bundle for host: 0x55f41c0ff980 [can multiplex]
Oct 13 09:08:13.044280 * Hostname 1.1.1.1 was found in DNS cache
Oct 13 09:08:13.044288 *   Trying 1.1.1.1:443...
Oct 13 09:08:13.055376 * Connected to 1.1.1.1 (1.1.1.1) port 443 (#1)
Oct 13 09:08:13.055817 * ALPN: offers http/1.1
Oct 13 09:08:13.055858 * SSL re-using session ID
Oct 13 09:08:13.056080 } [5 bytes data]
Oct 13 09:08:13.056127 * TLSv1.3 (OUT), TLS handshake, Client hello (1):
Oct 13 09:08:13.056140 } [578 bytes data]
Oct 13 09:08:13.079881 *  CAfile: /etc/ssl/certs/ca-certificates.crt
Oct 13 09:08:13.079900 *  CApath: /etc/ssl/certs
Oct 13 09:08:13.079906 { [5 bytes data]
Oct 13 09:08:13.079911 * TLSv1.3 (IN), TLS handshake, Server hello (2):
Oct 13 09:08:13.079915 { [128 bytes data]
Oct 13 09:08:13.079922 * TLSv1.3 (IN), TLS handshake, Encrypted Extensions (8):
Oct 13 09:08:13.079940 { [21 bytes data]
Oct 13 09:08:13.079945 * TLSv1.3 (IN), TLS handshake, Finished (20):
Oct 13 09:08:13.079950 { [52 bytes data]
Oct 13 09:08:13.079955 * TLSv1.3 (OUT), TLS change cipher, Change cipher spec (1):
Oct 13 09:08:13.079960 } [1 bytes data]
Oct 13 09:08:13.079965 * TLSv1.3 (OUT), TLS handshake, Finished (20):
Oct 13 09:08:13.079971 } [52 bytes data]
Oct 13 09:08:13.080056 * SSL connection using TLSv1.3 / TLS_AES_256_GCM_SHA384
Oct 13 09:08:13.080075 * ALPN: server accepted http/1.1
Oct 13 09:08:13.080081 * Server certificate:
Oct 13 09:08:13.080085 *  subject: C=US; ST=California; L=San Francisco; O=Cloudflare, Inc.; CN=cloudflare-dns.com
Oct 13 09:08:13.080091 *  start date: Jul 30 00:00:00 2024 GMT
Oct 13 09:08:13.080097 *  expire date: Jan 21 23:59:59 2025 GMT
Oct 13 09:08:13.080102 *  subjectAltName: host "1.1.1.1" matched cert's IP address!
Oct 13 09:08:13.080107 *  issuer: C=US; O=DigiCert Inc; CN=DigiCert Global G2 TLS RSA SHA256 2020 CA1
Oct 13 09:08:13.080112 *  SSL certificate verify ok.
Oct 13 09:08:13.080117 * using HTTP/1.1
Oct 13 09:08:13.080125 } [5 bytes data]
Oct 13 09:08:13.080132 > GET /dns-query?name=example.com HTTP/1.1
Oct 13 09:08:13.080136 > Host: 1.1.1.1
Oct 13 09:08:13.080141 > User-Agent: curl/7.88.1
Oct 13 09:08:13.080146 > accept: application/dns-json
Oct 13 09:08:13.080151 > 
Oct 13 09:08:13.096134 { [5 bytes data]
Oct 13 09:08:13.096205 * TLSv1.3 (IN), TLS handshake, Newsession Ticket (4):
Oct 13 09:08:13.096215 { [230 bytes data]
Oct 13 09:08:13.096223 * old SSL session ID is stale, removing
Oct 13 09:08:13.096230 * TLSv1.3 (IN), TLS handshake, Newsession Ticket (4):
Oct 13 09:08:13.096239 { [230 bytes data]
Oct 13 09:08:13.096246 * old SSL session ID is stale, removing
Oct 13 09:08:13.096253 { [5 bytes data]
Oct 13 09:08:13.096261 < HTTP/1.1 200 OK
Oct 13 09:08:13.096269 < Server: cloudflare
Oct 13 09:08:13.096276 < Date: Sun, 13 Oct 2024 07:08:13 GMT
Oct 13 09:08:13.096283 < Content-Type: application/dns-json
Oct 13 09:08:13.096291 < Connection: keep-alive
Oct 13 09:08:13.096298 < Access-Control-Allow-Origin: *
Oct 13 09:08:13.096306 < Content-Length: 186
Oct 13 09:08:13.096314 < CF-RAY: 8d1d7f45c906247e-ZAG
Oct 13 09:08:13.096323 < 
Oct 13 09:08:13.096331 { [186 bytes data]
Oct 13 09:08:13.096339 * Connection #1 to host 1.1.1.1 left intact
Oct 13 09:08:13.098771 {"Status":0,"TC":false,"RD":true,"RA":true,"AD":true,"CD":false,"Question":[{"name":"example.com","type":1}],"Answer":[{"name":"example.com","type":1,"TTL":1380,"data":"93.184.215.14"}]}

or at least basic timestamps with IP and port being connected to, and raw data being sent/received

[gryphius]

I like the idea. Not sure how much debugging details can be grabbed from the rather high leven function calls we use but timestamps and some more info would certainly be feasible.

That being said: I'm not actively developing AndroDNS currently. Sometimes I apply some dependency updates, but thats about it. So unless some wants to dig in my rather horrible code and provide a pull request this will likely hang around for quite a while, like many other good feature requests.