SIPp: Generate CDR Log

 Jan 25, 2021

To get a csv file of call detail records, you can use log message command. The “log” action allows you to customize your traces. Messages are printed in the <scenario filename>_<pid>_logs.log file. Any keyword is expanded to reflect the value actually used.
Warning: Logs are generated only if -trace_logs option is set on the command line.

Lets start with an example where we want following fields in CDR csv file.
Call Start Time, From, To,  Call ID, Call Duration

Here is the full uac scenario

<?xml version="1.0" encoding="ISO-8859-1" ?> <!DOCTYPE scenario SYSTEM "sipp.dtd"> <!-- This program is free software; you can redistribute it and/or --> <!-- modify it under the terms of the GNU General Public License as --> <!-- published by the Free Software Foundation; either version 2 of the --> <!-- License, or (at your option) any later version. --> <!-- --> <!-- This program is distributed in the hope that it will be useful, --> <!-- but WITHOUT ANY WARRANTY; without even the implied warranty of --> <!-- MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the --> <!-- GNU General Public License for more details. --> <!-- --> <!-- You should have received a copy of the GNU General Public License --> <!-- along with this program; if not, write to the --> <!-- Free Software Foundation, Inc., --> <!-- 59 Temple Place, Suite 330, Boston, MA 02111-1307 USA --> <!-- --> <!-- Sipp 'uac' scenario with CDR and Pause --> <!-- ./sipp -i 10.108.60.155 -p 2500 -sf sh/pauseUac-cs1.xml -s 901 -m 1 10.108.60.128:2500 -trace_logs --> <!-- ./sipp -i 10.108.60.155 -p 2600 -sn uas --> <!-- --> <scenario name="Basic Sipstone UAC"> <!-- In client mode (sipp placing calls), the Call-ID MUST be --> <!-- generated by sipp. To do so, use [call_id] keyword. --> <!-- Content-Type: application/sdp --> <send retrans="500"> <![CDATA[ INVITE sip:[service]@[remote_ip]:[remote_port] SIP/2.0 Via: SIP/2.0/[transport] [local_ip]:[local_port];branch=[branch] From: "9876543210"<sip:9876543210@openplatform.xyz>;tag=[pid]9876543210Tag00[call_number] To: sut <sip:[service]@[remote_ip]:[remote_port]> Call-ID: [call_id] CSeq: 1 INVITE Contact: sip:9876543210@[local_ip]:[local_port] P-Asserted-Identity: <tel:9045470697> Max-Forwards: 70 Subject: Performance Test Content-Type: application/sdp Content-Length: [len] v=0 o=user1 53655765 2353687637 IN IP[local_ip_type] [local_ip] s=- c=IN IP[media_ip_type] [media_ip] t=0 0 m=audio [media_port] RTP/AVP 0 a=rtpmap:0 PCMU/8000 ]]> </send> <recv response="100" optional="true"> </recv> <recv response="180" optional="true"> </recv> <recv response="183" optional="true"> </recv> <!-- By adding rrs="true" (Record Route Sets), the route sets --> <!-- are saved and used for following messages sent. Useful to test --> <!-- against stateful SIP proxies/B2BUAs. --> <recv response="200" rtd="true"> </recv> <!-- Packet lost can be simulated in any send/recv message by --> <!-- by adding the 'lost = "10"'. Value can be [1-100] percent. --> <send> <![CDATA[ ACK sip:[service]@[remote_ip]:[remote_port] SIP/2.0 Via: SIP/2.0/[transport] [local_ip]:[local_port];branch=[branch] From: 9876543210 <sip:9876543210@[local_ip]:[local_port]>;tag=[pid]9876543210Tag00[call_number] To: sut <sip:[service]@[remote_ip]:[remote_port]>[peer_tag_param] Call-ID: [call_id] CSeq: 1 ACK Contact: sip:9876543210@[local_ip]:[local_port] Max-Forwards: 70 Subject: Performance Test Content-Length: 0 ]]> </send> <nop> <action> <assignstr assign_to="1" value="[timestamp]" /> <assignstr assign_to="2" value="[clock_tick]" /> <!-- Converts the string value in $2 to a double-precision value stored in $3. --> <todouble assign_to="3" variable="2" /> <!-- <log message="clock_tick on ACK is [$3]" /> --> </action> </nop> <!-- This delay can be customized by the -d command-line option --> <!-- or by adding a 'milliseconds = "value"' option here. --> <pause/> <!-- The 'crlf' option inserts a blank line in the statistics report. --> <send retrans="500"> <![CDATA[ BYE sip:[service]@[remote_ip]:[remote_port] SIP/2.0 Via: SIP/2.0/[transport] [local_ip]:[local_port];branch=[branch] From: 9876543210 <sip:9876543210@[local_ip]:[local_port]>;tag=[pid]9876543210Tag00[call_number] To: sut <sip:[service]@[remote_ip]:[remote_port]>[peer_tag_param] Call-ID: [call_id] CSeq: 2 BYE Contact: sip:9876543210@[local_ip]:[local_port] Max-Forwards: 70 Subject: Performance Test Content-Length: 0 ]]> </send> <recv response="200" crlf="true"> </recv> <nop> <action> <assignstr assign_to="4" value="[clock_tick]" /> <!-- <log message="clock_tick After BYE is [$4]" /> --> <!-- Converts the string value in $4 to a double-precision value stored in $5. --> <todouble assign_to="5" variable="4" /> <subtract assign_to="5" variable="3" /> <log message="StartTime is [$1],[last_From],[last_To],CallID is [call_id],CallDuration(ms) is [$5]" /> </action> </nop> <!-- definition of the response time repartition table (unit is ms) --> <ResponseTimeRepartition value="10, 20, 30, 40, 50, 100, 150, 200"/> <!-- definition of the call length repartition table (unit is ms) --> <CallLengthRepartition value="10, 50, 100, 500, 1000, 5000, 10000"/> </scenario>

And let's break it down ...

Call Duration timer starts when sipp receives 200 OK and sends ACK. Following code snippet is taken from above scenario just after sipp sends ACK.

It just puts timestamp and clock_tick in variables. Also clock_tick is converted from string to float as we intend to do subtraction later.

<nop>
<action>
<assignstr assign_to="1" value="[timestamp]" />
<assignstr assign_to="2" value="[clock_tick]" />
<!-- Converts the string value in $2 to a double-precision value stored in $3. -->
<todouble assign_to="3" variable="2" />
</action>
</nop>

Call Duration timer stops when sipp sends BYE and receives 200 OK. Following code snippet is taken from scenario just after sipp receives 200 OK to BYE sent.

Here we store present clock_tick in other variable and subtract previous clock_tick (ACK sent) from it, to get call duration in milli seconds.
Call Duration = clock_tick (BYE) - clock_tick (ACK)

<nop>
<action>
<assignstr assign_to="4" value="[clock_tick]" />
<!-- Converts the string value in $4 to a double-precision value stored in $5. -->
<todouble assign_to="5" variable="4" />
<subtract assign_to="5" variable="3" />
<log message="StartTime is [$1],[last_From],[last_To],CallID is [call_id],CallDuration(ms) is [$5]" />
</action>
</nop>

To demonstrate I have logged Start Time, From, To, Call ID and Duration. You can add more fields, customize and format it.

Note: Apparently <NOP> before <RECV> doesn't work.

To run this scenario I used following commands

UAS
./sipp -i 10.108.60.128 -p 2500 -sn uas

UAC
./sipp -i 10.108.60.155 -p 2500 -sf uac-cdr.xml -s 901 -d 5000 -m 10 10.108.60.128:2500 -trace_logs

And below is a cdr files thus generated for 10 calls (1 line for each call, total 10 lines)

StartTime is 2021-01-25 11:41:09.048866 1611574869.048866,From: 9876543210 <sip:9876543210@10.108.60.155:2500>;tag=303639876543210Tag001,To: sut <sip:901@10.108.60.128:2500>;tag=9299937628566694693,CallID is 1-30363@10.108.60.155,CallDuration(ms) is 5003.000000 StartTime is 2021-01-25 11:41:09.144762 1611574869.144762,From: 9876543210 <sip:9876543210@10.108.60.155:2500>;tag=303639876543210Tag002,To: sut <sip:901@10.108.60.128:2500>;tag=9299937628566694696,CallID is 2-30363@10.108.60.155,CallDuration(ms) is 5005.000000 StartTime is 2021-01-25 11:41:09.244567 1611574869.244567,From: 9876543210 <sip:9876543210@10.108.60.155:2500>;tag=303639876543210Tag003,To: sut <sip:901@10.108.60.128:2500>;tag=9299937628566694699,CallID is 3-30363@10.108.60.155,CallDuration(ms) is 5005.000000 StartTime is 2021-01-25 11:41:09.345286 1611574869.345286,From: 9876543210 <sip:9876543210@10.108.60.155:2500>;tag=303639876543210Tag004,To: sut <sip:901@10.108.60.128:2500>;tag=9299937628566694702,CallID is 4-30363@10.108.60.155,CallDuration(ms) is 5004.000000 StartTime is 2021-01-25 11:41:09.444799 1611574869.444799,From: 9876543210 <sip:9876543210@10.108.60.155:2500>;tag=303639876543210Tag005,To: sut <sip:901@10.108.60.128:2500>;tag=9299937628566694705,CallID is 5-30363@10.108.60.155,CallDuration(ms) is 5004.000000 StartTime is 2021-01-25 11:41:09.544520 1611574869.544520,From: 9876543210 <sip:9876543210@10.108.60.155:2500>;tag=303639876543210Tag006,To: sut <sip:901@10.108.60.128:2500>;tag=9299937628566694708,CallID is 6-30363@10.108.60.155,CallDuration(ms) is 5004.000000 StartTime is 2021-01-25 11:41:09.644505 1611574869.644505,From: 9876543210 <sip:9876543210@10.108.60.155:2500>;tag=303639876543210Tag007,To: sut <sip:901@10.108.60.128:2500>;tag=9299937628566694711,CallID is 7-30363@10.108.60.155,CallDuration(ms) is 5004.000000 StartTime is 2021-01-25 11:41:09.744447 1611574869.744447,From: 9876543210 <sip:9876543210@10.108.60.155:2500>;tag=303639876543210Tag008,To: sut <sip:901@10.108.60.128:2500>;tag=9299937628566694714,CallID is 8-30363@10.108.60.155,CallDuration(ms) is 5003.000000 StartTime is 2021-01-25 11:41:09.846787 1611574869.846787,From: 9876543210 <sip:9876543210@10.108.60.155:2500>;tag=303639876543210Tag009,To: sut <sip:901@10.108.60.128:2500>;tag=9299937628566694717,CallID is 9-30363@10.108.60.155,CallDuration(ms) is 5005.000000 StartTime is 2021-01-25 11:41:09.946421 1611574869.946421,From: 9876543210 <sip:9876543210@10.108.60.155:2500>;tag=303639876543210Tag0010,To: sut <sip:901@10.108.60.128:2500>;tag=9299937628566694720,CallID is 10-30363@10.108.60.155,CallDuration(ms) is 5003.000000

 

Next, how to generate calls of different call-durations.