I would like to examine the response just before it's dispatched to the client. Primarily, I'm interested in the ;; ANSWER SECTION:.
What had looked like a trivial modification of logDnsMsg function turned out to be a dounting task of browsing reply_info, rrset_ref and ub_packed_rrset_key structures in pursuit of the desired ;; ANSWER SECTION: bytes.
The reason is the logDnsMsg function does not work as expected for A queries ;; ANSWER SECTION:, while it suprisingly operates as expected for ;; AUTHORITY SECTION: on AAAA queries.
Lemme demonstrate a comparison between the Python implemented logDnsMsg function and a native log_dns_msg function; with the former displaying a gibberish and the latter performing exactly as expected. Both functions are called from within the Python module context as follows:
+++
def operate(id, event, qstate, qdata):
log_info("pythonmod: operate called, id: %d, event:%s" % (id, strmodulevent(event)))
if (qstate.return_msg):
logDnsMsg(qstate)
log_dns_msg("blackpie KARMMMMMM XXXXXXX", qstate.return_msg.qinfo, qstate.return_msg.rep)
+++
Note that I altered the original logDnsMsg so as it uses the logging framework in favour of print. The output was the same for print but for being scattered across the logfile at buffer's discretion.
dig output:
karm@localhost:~$ dig seznam.cz @127.0.0.1 -p53535
; <<>> DiG 9.9.4-P2-RedHat-9.9.4-18.P2.fc20 <<>> seznam.cz @127.0.0.1 -p53535
;; global options: +cmd
;; Got answer:
;; ->>HEADER<<- opcode: QUERY, status: NOERROR, id: 38630
;; flags: qr rd ra; QUERY: 1, ANSWER: 1, AUTHORITY: 0, ADDITIONAL: 1
;; OPT PSEUDOSECTION:
; EDNS: version: 0, flags:; udp: 4096
;; QUESTION SECTION:
;seznam.cz. IN A
;; ANSWER SECTION:
seznam.cz. 300 IN A 77.75.76.3
;; Query time: 656 msec
;; SERVER: 127.0.0.1#53535(127.0.0.1)
;; WHEN: Sat Apr 25 16:04:32 CEST 2015
;; MSG SIZE rcvd: 54
Output for AAAA query, ;; AUTHORITY SECTION: looks decent enough from both logDnsMsg and log_dns_msg:
[1429970672] unbound[14053:0] info: pythonmod: operate called, id: 1, event:module_event_moddone
[1429970672] unbound[14053:0] info: ------------------------------------------------------------------------------------------
[1429970672] unbound[14053:0] info: Query: e.root-servers.net., type: AAAA (28), class: IN (1)
[1429970672] unbound[14053:0] info: ------------------------------------------------------------------------------------------
[1429970672] unbound[14053:0] info: Return reply :: flags: 8080, QDcount: 1, Security:0, TTL=86400
[1429970672] unbound[14053:0] info: qinfo :: qname: ['e', 'root-servers', 'net', ''] e.root-servers.net., qtype: AAAA, qclass: IN
[1429970672] unbound[14053:0] info: Reply:
[1429970672] unbound[14053:0] info: 0:['root-servers', 'net', ''] root-servers.net. flags: 0004
[1429970672] unbound[14053:0] info: type:SOA (6) class:IN (1)
[1429970672] unbound[14053:0] info: 0:TTL=3600000
[1429970672] unbound[14053:0] info:
[1429970672] unbound[14053:0] info: 0x00 | 00 40 01 61 0C 72 6F 6F 74 2D 73 65 72 76 65 72 73 | . @ . a . r o o t - s e r v e r s
0x10 | 73 03 6E 65 74 00 05 6E 73 74 6C 64 0C 76 65 72 69 | s . n e t . . n s t l d . v e r i
0x20 | 69 73 69 67 6E 2D 67 72 73 03 63 6F 6D 00 78 0C E3 | i s i g n - g r s . c o m . x . .
0x30 | E3 24 00 00 38 40 00 00 1C 20 00 12 75 00 00 36 EE | . $ . . 8 @ . . . . . u . . 6 .
0x40 | EE 80 | . .
[1429970672] unbound[14053:0] info: ------------------------------------------------------------------------------------------
[1429970672] unbound[14053:0] info: blackpie KARMMMMMM XXXXXXX ;; ->>HEADER<<- opcode: QUERY, rcode: NOERROR, id: 0
;; flags: qr ra ; QUERY: 1, ANSWER: 0, AUTHORITY: 1, ADDITIONAL: 0
;; QUESTION SECTION:
e.root-servers.net. IN AAAA
;; ANSWER SECTION:
;; AUTHORITY SECTION:
root-servers.net. 3600000 IN SOA a.root-servers.net. nstld.verisign-grs.com. 2014110500 14400 7200 1209600 3600000
;; ADDITIONAL SECTION:
;; MSG SIZE rcvd: 96
[1429970672] unbound[14053:0] debug: mesh_run: python module exit state is module_finished
On the contrary, for A query, ;; ANSWER SECTION: is completely useless as far as logDnsMsg goes:
[1429970672] unbound[14053:0] info: pythonmod: operate called, id: 1, event:module_event_moddone
[1429970672] unbound[14053:0] info: ------------------------------------------------------------------------------------------
[1429970672] unbound[14053:0] info: Query: seznam.cz., type: A (1), class: IN (1)
[1429970672] unbound[14053:0] info: ------------------------------------------------------------------------------------------
[1429970672] unbound[14053:0] info: Return reply :: flags: 8080, QDcount: 1, Security:0, TTL=300
[1429970672] unbound[14053:0] info: qinfo :: qname: ['seznam', 'cz', ''] seznam.cz., qtype: A, qclass: IN
[1429970672] unbound[14053:0] info: Reply:
[1429970672] unbound[14053:0] info: 0:['seznam', 'cz', ''] seznam.cz. flags: 0000
[1429970672] unbound[14053:0] info: type:A (1) class:IN (1)
[1429970672] unbound[14053:0] info: 0:TTL=300
[1429970672] unbound[14053:0] info:
[1429970672] unbound[14053:0] info: 0x00 | 00 04 4D 4B 4C 03 | . . M K L .
[1429970672] unbound[14053:0] info: ------------------------------------------------------------------------------------------
[1429970672] unbound[14053:0] info: blackpie KARMMMMMM XXXXXXX ;; ->>HEADER<<- opcode: QUERY, rcode: NOERROR, id: 0
;; flags: qr ra ; QUERY: 1, ANSWER: 1, AUTHORITY: 0, ADDITIONAL: 0
;; QUESTION SECTION:
seznam.cz. IN A
;; ANSWER SECTION:
seznam.cz. 300 IN A 77.75.76.3
;; AUTHORITY SECTION:
;; ADDITIONAL SECTION:
;; MSG SIZE rcvd: 43
[1429970672] unbound[14053:0] debug: mesh_run: python module exit state is module_finished
Note the 00 04 4D 4B 4C 03 bytes that are erroneously interpreted as ASCII.
Where in the struct ub_packed_rrset_key** rrsets; one finds the desired ;; ANSWER SECTION: data? (If it is indeed the right place to look.)
I've been fiddling with it for quite some time without any luck. I examined the sldns_wire2str_pkt_scan function that is used internally for unpacking the wire binary data, but I am none the wiser.