How to make a trace file self documenting
There are two ways to benchmark the network footprint of an application. First you can collect lots of little traces; starting a trace, then running the application function, and then stopping the trace and saving it to a file with a descriptive name. The second method is to have one large trace file with a record of frame numbers for when each application function was started and completed. I prefer the second method but these approaches only work if you can see and have control of the analyzer.
In cases where I am not located next to the analyzer I've used all sorts of tricks to try to delineate which frames in a trace go with which application functions. I've kept very careful track of the time that I execute application functions, I've sent a fixed number of pings to a specific IP address which show up in the trace. I've even pinged a non-existent IP address and used the broadcast ARP packet in the trace as my delimiter. These methods all worked to some extent but I still needed to create a separate "what did I do" record.
It finally dawned on me that the appropriate place for the "what did I do" record is the trace file itself. To that end I wrote a simple perl script that allows me to send a UDP packet containing a message. The message can identify what function I am about to execute and another message can identify when the function completes. Between those messages is the application function's network footprint. Adding time stamps to the messages makes the trace file completely self documenting.
Usage
perl addTraceLabel.pl -ip DESTINATION-IP-ADDRESS [ip DESTINATION-IP-ADDRESS]*
-port PORT-NUMBER -message MESSAGE
-ip | -i
The script can accept multiple IP addresses, each prefixed with "-ip ". An address can be a broadcast (255.255.255.255 or 172.16.1.255) or directed at a specific host. The number of addresses is limited by your version of Perl but is probably much greater than any number of IP addresses you will find useful. Host names will work as well as IP addresses.
-port | -p
This is the port number than the message packet will be directed to. Any value between 1 and 65535 can be used. Values in the dynamic range (49152-65535) will probably not be in use so you will not run the risk of crashing an application with unexpected data, I like 49876.
-message | -m
The message. If it contains spaces it needs to be in quotes.
-repeat | -r
The number of times to repeat the message. Multiple messages in a "block" will make them easier to spot as you scroll through the trace file. The default is 5.
Examples
Figure 1 shows two sets of begin/end messages directed to a specific IP address, I've highlighted the messages in the command line. Trace 1 shows the corresponding packets; I have included the hex dump for the UDP message packets so I could highlight the message. Note the date-time stamp that precedes the message text entered on the command line. I've included summary lines for some of the application related messages more for context than anything else. I have edited those summary lines to reduce their length.
C:\>perl addTraceLabel.pl -ip 172.16.1.44 -port 49876 -message "begin remote des ktop connection" -repeat 1 C:\>mstsc C:\>perl addTraceLabel.pl -ip 172.16.1.44 -port 49876 -message "end remote deskt op connection" -repeat 1 C:\>perl addTraceLabel.pl -ip 172.16.1.44 -port 49876 -message "begin send passw ord" -repeat 1 C:\>perl addTraceLabel.pl -ip 172.16.1.44 -port 49876 -message "end send passwor d - logged in" -repeat 1 |
No. Time Source Destination Protocol Info
315 16:32:26.306231 164.152.77.50 172.16.1.44 UDP Source port: winshadow-hd Destination port: 49876
0000 00 00 ef 04 d0 10 00 23 54 52 18 6e 08 00 45 00 .......#TR.n..E.
0010 00 56 0d b1 00 00 80 11 8d df a4 98 4d 32 ac 10 .V..........M2..
0020 01 2c 0f 15 C2 D4 00 42 ec 18 46 72 69 20 4d 61 .,..09.B..Fri Ma
0030 79 20 20 37 20 31 36 3a 33 32 3a 32 36 20 32 30 y 7 16:32:26 20
0040 31 30 20 3a 20 62 65 67 69 6e 20 72 65 6d 6f 74 10 : begin remot
0050 65 20 64 65 73 6b 74 6f 70 20 63 6f 6e 6e 65 63 e desktop connec
0060 74 69 6f 6e tion
316 16:32:26.320259 172.16.1.44 164.152.77.50 ICMP Destination unreachable (Port unreachable)
448 16:32:33.931712 164.152.77.50 172.16.1.44 TCP giga-pocket > ms-wbt-server [SYN] ....
449 16:32:33.932448 172.16.1.44 164.152.77.50 TCP ms-wbt-server > giga-pocket [SYN, ....
450 16:32:33.932487 164.152.77.50 172.16.1.44 TCP giga-pocket > ms-wbt-server [ACK] ....
451 16:32:33.932763 164.152.77.50 172.16.1.44 X.224 Connection Request (0xe0)
452 16:32:33.934269 172.16.1.44 164.152.77.50 X.224 Connection Confirm (0xd0)
. . . .
603 16:32:35.469895 164.152.77.50 172.16.1.44 TCP asap-tcp > ms-wbt-server [ACK] Seq=2358....
604 16:32:35.573543 172.16.1.44 164.152.77.50 TPKT Continuation
609 16:32:35.711175 164.152.77.50 172.16.1.44 TCP asap-tcp > ms-wbt-server [ACK] Seq=2358....
765 16:32:45.841971 164.152.77.50 172.16.1.44 UDP Source port: 3864 Destination port: 49876
0000 00 00 ef 04 d0 10 00 23 54 52 18 6e 08 00 45 00 .......#TR.n..E.
0010 00 54 0d ef 00 00 80 11 8d a3 a4 98 4d 32 ac 10 .T..........M2..
0020 01 2c 0f 18 C2 D4 00 40 4d 86 46 72 69 20 4d 61 .,..09.@M.Fri Ma
0030 79 20 20 37 20 31 36 3a 33 32 3a 34 35 20 32 30 y 7 16:32:45 20
0040 31 30 20 3a 20 65 6e 64 20 72 65 6d 6f 74 65 20 10 : end remote
0050 64 65 73 6b 74 6f 70 20 63 6f 6e 6e 65 63 74 69 desktop connecti
0060 6f 6e on
766 16:32:45.842853 172.16.1.44 164.152.77.50 ICMP Destination unreachable (Port unreachable)
. . . .
1245 16:33:08.375633 164.152.77.50 172.16.1.44 UDP Source port: xpl Destination port: 49876
0000 00 00 ef 04 d0 10 00 23 54 52 18 6e 08 00 45 00 .......#TR.n..E.
0010 00 4a 0d f3 00 00 80 11 8d a9 a4 98 4d 32 ac 10 .J..........M2..
0020 01 2c 0f 19 C2 D4 00 36 64 71 46 72 69 20 4d 61 .,..09.6dqFri Ma
0030 79 20 20 37 20 31 36 3a 33 33 3a 30 38 20 32 30 y 7 16:33:08 20
0040 31 30 20 3a 20 62 65 67 69 6e 20 73 65 6e 64 20 10 : begin send
0050 70 61 73 73 77 6f 72 64 password
1246 16:33:08.376700 172.16.1.44 164.152.77.50 ICMP Destination unreachable (Port unreachable)
1340 16:33:12.484470 164.152.77.50 172.16.1.44 TPKT Continuation
1341 16:33:12.492610 172.16.1.44 164.152.77.50 TPKT Continuation
1343 16:33:12.670581 164.152.77.50 172.16.1.44 TPKT Continuation
1345 16:33:12.766465 164.152.77.50 172.16.1.44 TPKT Continuation
. . . . .
1864 16:33:30.788792 172.16.1.44 164.152.77.50 TPKT Continuation
1867 16:33:30.899455 172.16.1.44 164.152.77.50 TPKT Continuation
1868 16:33:30.899482 164.152.77.50 172.16.1.44 TCP asap-tcp > ms-wbt-server [ACK] Seq=24879....
1885 16:33:32.050555 164.152.77.50 172.16.1.44 UDP Source port: dzdaemon Destination port: 49876
0000 00 00 ef 04 d0 10 00 23 54 52 18 6e 08 00 45 00 .......#TR.n..E.
0010 00 54 0e 3f 00 00 80 11 8d 53 a4 98 4d 32 ac 10 .T.?.....S..M2..
0020 01 2c 0f 1a D2 D4 00 40 e5 d2 46 72 69 20 4d 61 .,..09.@..Fri Ma
0030 79 20 20 37 20 31 36 3a 33 33 3a 33 32 20 32 30 y 7 16:33:32 20
0040 31 30 20 3a 20 65 6e 64 20 73 65 6e 64 20 70 61 10 : end send pa
0050 73 73 77 6f 72 64 20 2d 20 6c 6f 67 67 65 64 20 ssword - logged
0060 69 6e in
1886 16:33:32.051375 172.16.1.44 164.152.77.50 ICMP Destination unreachable (Port unreachable)
|
Figure 2 shows the first set of messages but without the repeat argument. The result shown in trace 2 shows the message repeated the default 5 times.
F:\projects\Perl Projects\trace lables>perl addTraceLabel.pl -ip 164.152.77.255 -port 49876 -m "begin remote desktop connection" F:\projects\Perl Projects\trace lables>perl addTraceLabel.pl -ip 164.152.77.255 -port 49876 -m "connection completed" |
No. Time Source Destination TTL Protocol Window size Info
77 13:35:31.004354 164.152.77.50 164.152.77.255 128 Source port: 3228 Destination port: 49876
78 13:35:31.004394 164.152.77.50 164.152.77.255 128 Source port: 3228 Destination port: 49876
79 13:35:31.004424 164.152.77.50 164.152.77.255 128 Source port: 3228 Destination port: 49876
80 13:35:31.004449 164.152.77.50 164.152.77.255 128 Source port: 3228 Destination port: 49876
81 13:35:31.004474 164.152.77.50 164.152.77.255 128 Source port: 3228 Destination port: 49876
419 13:35:47.184710 164.152.77.50 172.16.1.44 128 3232 > 3389 [SYN] Seq=0 Win=65535 Len=0 MSS=1460 SACK_PERM=1
420 13:35:47.185619 172.16.1.44 164.152.77.50 127 3389 > 3232 [SYN, ACK] Seq=0 Ack=1 Win=16384 Len=0 MSS=1460 SACK_PERM=1
421 13:35:47.185635 164.152.77.50 172.16.1.44 128 3232 > 3389 [ACK] Seq=1 Ack=1 Win=65535 [TCP CHECKSUM INCORRECT] Len=0
423 13:35:47.198059 164.152.77.50 172.16.1.44 128 Connection Request (0xe0)
. . . .
570 13:35:48.486344 164.152.77.50 172.16.1.44 128 3233 > 3389 [ACK] Seq=23580 Ack=20432 Win=65535 [TCP CHECKSUM INCORRECT] Len=0
571 13:35:48.486708 172.16.1.44 164.152.77.50 127 Continuation
572 13:35:48.487044 172.16.1.44 164.152.77.50 127 Continuation
573 13:35:48.487065 164.152.77.50 172.16.1.44 128 3233 > 3389 [ACK] Seq=23580 Ack=22102 Win=65535 [TCP CHECKSUM INCORRECT] Len=0
577 13:35:48.590773 172.16.1.44 164.152.77.50 127 Continuation
580 13:35:48.717800 164.152.77.50 172.16.1.44 128 3233 > 3389 [ACK] Seq=23580 Ack=22950 Win=64687 [TCP CHECKSUM INCORRECT] Len=0
885 13:36:04.360086 164.152.77.50 164.152.77.255 128 Source port: 3234 Destination port: 49876
886 13:36:04.360123 164.152.77.50 164.152.77.255 128 Source port: 3234 Destination port: 49876
887 13:36:04.360147 164.152.77.50 164.152.77.255 128 Source port: 3234 Destination port: 49876
888 13:36:04.360178 164.152.77.50 164.152.77.255 128 Source port: 3234 Destination port: 49876
889 13:36:04.360208 164.152.77.50 164.152.77.255 128 Source port: 3234 Destination port: 49876
|
The message can be addressed to the broadcast address (limited or unlimited), a multicast address or a specific IP address. What address to use will depend of where the analyzer is in relation to the host sending the trace label message. Broadcasts have the advantage of going everywhere in the network but have the disadvantage of being broadcasts. A specific IP address has the advantage of not being a broadcast but chances are that the target will respond with an ICMP destination unreachable message, see frames 316, 766, 1246 and 1886 in trace 1. Also a specific address will probably not work if you are tracing two different links, for example, between client and server and between server and back end database server.
A compromise is to use a pseudo broadcast. Pick an IP address that doesn't exist and set a bogus MAC address with the arp command, see figure 3, I like 0-1-2-3-4-5. Since this MAC address does not exist all switches will flood the packet out all ports BUT since it is not a broadcast it isn't processed by all the other hosts on the network; only a host with an adapter running in promiscuous mode (like an analyzer) will process the packet. If you don't have an unused IP address, pick an IP address that the host sending the trace label messages doesn't need to communicate with. Even when the packet reaches the target host it is ignored because the destination MAC address in the Ethernet frame doesn't match. Of course, this only works if the analyzer is in the same IP subnet as the host sending the labels.
C:\>arp 164.152.77.3 -s 0-1-2-3-4-5 C:\>perl addTraceLabel.pl -ip 164.152.77.3 -port 49876 -message "begin remote de sktop connection" C;\>mstsc C:\>perl addTraceLabel.pl -ip 164.152.77.3 -port 49876 -message "end remote desk top connection" |
In a multi-tiered system, for example, client to remote desktop server to domain controller spanning multiple subnets you may need multiple analyzers but you can send multiple trace label messages, each to a different subnet, with one command (figure 4).
C:\>perl addTraceLabel.pl -ip 172.16.1.44 -ip 192.168.1.25 -port 49876 -message "begin remote desktop connection login" |
The script is simple enough that I suspect it will work on any system with a Perl interpreter and the IO::Socket and Getopt::Long modules. However, I have tested the script with
# addTraceLabel.pl begins here
#
# Version 1.00 10-05-04
# Version 1.10 10-06-02 Added the repeat argument
# Version 1.20 10-12-26 Added disclaimer
# Version 1.30 13-12-10 Added Broadcast flag when creating the socket
# needed for RHEL 6.5
#
# noah@noahdavids.org
#
# See http://noahdavids.org/self_published/addTraceLabel.html for documentation
#
# This software is provided on an "AS IS" basis, WITHOUT ANY WARRANTY OR ANY
# SUPPORT OF ANY KIND. The AUTHOR SPECIFICALLY DISCLAIMS ANY IMPLIED WARRANTIES
# OF MERCHANTABILITY OR FITNESS FOR ANY PARTICULAR PURPOSE. This disclaimer
# applies, despite any verbal representations of any kind provided by the
# author or anyone else.
#
use IO::Socket;
use Getopt::Long;
use strict;
my ($result);
my (@destIP, $destPort, $message, $repeat, $i, $j);
$result = GetOptions ('ip=s' => \@destIP,
'port=s' => \$destPort,
'message=s' => \$message,
'repeat=s' => \$repeat);
if (($result != 1) ||
!((@destIP > 0) && defined($destPort) && defined ($message)))
{
print "\n\nUsage:\n";
print "\tperl addTraceLabel.pl -ip DESTINATION-IP-ADDRESS [-ip DEST-IP-ADDR]* ";
print "-port DESTINATION-PORT-NUMBER -message \"MESSAGE [-repeat NUMBER]\"\n\n";
exit;
}
if (!defined($repeat)) {$repeat = 5};
$message = localtime () . " : " . $message;
for ($i = 0; $i < @destIP; $i++)
{
my $sock = IO::Socket::INET->new(
Proto => 'udp',
PeerPort => $destPort,
PeerAddr => $destIP[$i],
Broadcast => 1,
) or die "Could not create socket for destination $destIP[$i]: $!\n";
for ($j = 0; $j < $repeat; $j++)
{
$sock->send($message) or die "Send error: $!\n";
}
}
#
# addTraceLabel.pl ends here
|
Send comments and suggestions