When it comes to troubleshooting a web service and logs don’t help, it is time to use Tcpdump.
The Problem
Just the other day, we were implementing a web service in Go that was experiencing a glitch for a functionality under development. The functionality pertained to querying another web service – let us call it Key Web Service (KWS) – parsing the JSON result, extracting a key, and doing further processing using the key.
KWS was written quickly in Python and was to be a test replacement for the actual service that would be provided by a customer in production. We looked at the URL constructed by our web service, printed it, and gave the same to curl. It worked perfectly!
Sample command-line:
curl http://127.0.0.1:8000/kws/api/v2/query?requestor=KWSUser'&'lastSyncTime=1555401815
Basically, the query contained two parameters, requestor and lastSyncTime. Yet, when our web server was to query KWS, it looked as if KWS did not honour the lastSyncTime parameter. Confused, we ran curl again. It worked fine, again!
Tcpdump Primer
It was time to bring in tcpdump, we thought. For those not familiar with tcpdump, it is a packet analyzer that prints out a description of packets being transmitted or received over a network interface. We sought to capture the network traffic generated by our web service and directed towards KWS, which was listening on port 8000. Both were running on the local host. Therefore, we launched tcpdump as:
tcpdump -i eth0 -w capture.pcap tcp and port 8000
Where:
- -i <interface>is the network interface that is used to capture network traffic. The list of interfaces on a GNU/Linux system can be known by means of commands for example, ifconfig and ip.
- -w <file> is the file to which the captured packets are written. In our case, this was going to be helpful in allowing us to view packets as many times as we wanted and feel assure of the results.
- Expression is the last portion of the command-line that serves as a powerful filter that can be used to select only those packets that match the specified conditions. In our case, we were happy to just capture TCP traffic over port 8000.
We then used tcpdump to print the captured traffic. It was run as:
tcpdump -n -r capture.pcap -A
- -n: By default tcpdump prints hostnames and port numbers in name format. That is, for the IP address 127.0.0.1, the name localhost and the name for port 8000 as per the /etc/services file. While debugging, it is frequently preferable to avoid using names and focus on the numbers.
- -r <file>: This option instructs tcpdump to read from the specified file. It is the same file that we used when writing.
- -A: This is the option that does the magic. It tells tcpdump to dump every printable character in a packet in ASCII format. A non-printable character is shown by single dot.
The HTTP GET request that was made by our web service to KWS was shown by the following line in tcpdump output:
11:59:35.518806 IP 127.0.0.1.54374 > 127.0.0.1.8000: Flags [P.],
seq 1:204, ack 1, win 342, options [nop,nop,TS val 2047574 ecr 2047574],
length 203 E....b@.@.b..........f.@,).7I......V.......
..>V..>VGET /kws/api/v2/query?requestor=KWSUser'&'lastSyncTime=1555402115HTTP/1.1
Bug Spotting
Look at the line once again:
GET /kws/api/v2/query?requestor=KWSUser'&'lastSyncTime=1555402115
Can you spot the bug? For those of you who could, you have a keen eye that spotted that bug caused by single quotes. For those looking for answers, the issue was with our initial version of the code, surrounding the parameter separator, ampersand (&) with single quotes.
As per the man page of Bash, which was our shell:
If a command is terminated by the control operator &, the shell executes the command in the background in a subshell.
Quoting is a pervasive issue on the command-line and in shell programming. Everything inside single quotes becomes a literal string. When using curl on the command-line, this behaviour is desired so that Bash does not interpret the ampersand character in the usual manner – as an instruction to run a command in the background. The quotes themselves don’t reach the command, which in our case happens to be curl.
The initial version of our Go function looked as follows:
func makeURL(baseURL string, syncTime int64) string {
if syncTime != 0 {
return baseURL + "'&'lastSyncTime=" + strconv.FormatInt(syncTime, 10)
} else {
return baseURL
}
}
This made KWS see the the parameter requestor assigned the value KWSUser’ and the parameter ‘lastSyncTime assigned the value 1555402115, respectively. KWS was expecting lastSyncTime and not ‘lastSyncTime. The unexpected parameter was ignored.
Conclusion
The resolution was to change our URL construction function to not add the quote characters:
func makeURL(baseURL string, syncTime int64) string {
if syncTime != 0 {
return baseURL + "&lastSyncTime=" + strconv.FormatInt(syncTime, 10)
} else {
return baseURL
}
}
A powerful fallback in debugging network applications is actually seeing the packets. After all, the wire never lies!
References
Image attribution: Shutterstock
