[pjsip] getting Underflow, buf_cnt=0, will generate 1 frame continuessly

suresh jaiswal itssuresh79 at yahoo.com
Mon Apr 27 11:05:51 EDT 2009


Hi ALL i'm new in PJSIP 
Sudenlly i'm getting strange problem with PJSUA to PJSUA call.. 
when i calling PJSUA to PJSUA (between three PJSUA clent using OPENIMS ) multiple times 
say 5-6 times after successfull tear down call we getting callee side PJSIU hang getting 
Underflow, buf_cnt=0, will generate 1 frame continuessly
 
i'm also attching log file alson this mail
can any tell me what is mean by VAD its seems to be problem is related to 
VAD not able to re-enalbe
 
 
 18:05:34.501 sip_endpoint.c Module "mod-pjsua-log" registered
18:05:34.517 sip_endpoint.c Module "mod-tsx-layer" registered
18:05:34.517 sip_endpoint.c Module "mod-stateful-util" registered
18:05:34.517 sip_endpoint.c Module "mod-ua" registered
18:05:34.517 sip_endpoint.c Module "mod-100rel" registered
18:05:34.517 sip_endpoint.c Module "mod-pjsua" registered
18:05:34.517 sip_endpoint.c Module "mod-invite" registered
18:05:34.548 pa_dev.c PA message: before paHostApiInitializers[0].
18:05:34.642 pa_dev.c PA message: Pa_GetDeviceInfo: Num input channels reported as 65535! Changed to 2.
18:05:34.642 pa_dev.c PA message: Pa_GetDeviceInfo: Num input channels reported as 65535! Changed to 2.
18:05:34.642 pa_dev.c PA message: Pa_GetDeviceInfo: Num output channels reported as 65535! Changed to 2.
18:05:34.642 pa_dev.c PA message: Pa_GetDeviceInfo: Num output channels reported as 65535! Changed to 2.
18:05:34.642 pa_dev.c PA message: after paHostApiInitializers[0].
18:05:34.642 pa_dev.c PA message: before paHostApiInitializers[1].
18:05:34.923 pa_dev.c PA message: after paHostApiInitializers[1].
18:05:34.923 pa_dev.c PA message: before paHostApiInitializers[2].
18:05:34.923 pa_dev.c PA message: after paHostApiInitializers[2].
18:05:34.923 pa_dev.c PortAudio sound library initialized, status=0
18:05:34.923 pa_dev.c PortAudio host api count=3
18:05:34.923 pa_dev.c Sound device count=12
18:05:34.923 wmme_dev.c WMME initialized, found 5 devices:
18:05:34.923 wmme_dev.c dev_id 0: Wave mapper (in=2, out=2)
18:05:34.923 wmme_dev.c dev_id 1: USB Device (in=2, out=0)
18:05:34.923 wmme_dev.c dev_id 2: Realtek AC97 Audio (in=2, out=0)
18:05:34.923 wmme_dev.c dev_id 3: USB Device (in=0, out=2)
18:05:34.923 wmme_dev.c dev_id 4: Realtek AC97 Audio (in=0, out=2)
18:05:34.939 pjlib select() I/O Queue created (00DD60AC)
18:05:34.939 conference.c Creating conference bridge with 254 ports
18:05:34.954 conference.c Sound device successfully created for port 0
18:05:34.954 sip_endpoint.c Module "mod-evsub" registered
18:05:34.954 sip_endpoint.c Module "mod-presence" registered
18:05:34.954 evsub.c Event pkg "presence" registered by mod-presence
18:05:34.954 sip_endpoint.c Module "mod-refer" registered
18:05:34.954 evsub.c Event pkg "refer" registered by mod-refer
18:05:34.954 sip_endpoint.c Module "mod-pjsua-pres" registered
18:05:34.954 sip_endpoint.c Module "mod-pjsua-im" registered
18:05:34.954 sip_endpoint.c Module "mod-pjsua-options" registered
18:05:34.954 pjsua_core.c 1 SIP worker threads created
18:05:34.954 pjsua_core.c pjsua version 1.1 for win32 initialized
18:05:34.954 sip_endpoint.c Module "mod-default-handler" registered
18:05:34.986 pjsua_core.c SIP UDP socket reachable at 172.18.2.74:5060
18:05:34.986 udp00DE60A8 SIP UDP transport started, published address is 172.18.2.74:5060
18:05:34.986 pjsua_acc.c Account <sip:172.18.2.74:5060> added with id 0
18:05:34.986 pjsua_acc.c Account sip:alice at voip3gppsrv2 added with id 1
18:05:34.986 endpoint Request msg REGISTER/cseq=16537 (tdta00DEA8F8) created.
18:05:34.986 tsx00DEB98C Transaction created for Request msg REGISTER/cseq=16538 (tdta00DEA8F8)
18:05:34.986 tsx00DEB98C Sending Request msg REGISTER/cseq=16538 (tdta00DEA8F8) in state Null
18:05:35.001 sip_resolve.c Target '172.18.1.218:4060' type=Unspecified resolved to '172.18.1.218:4060' type=UDP (UDP transport)
18:05:35.001 pjsua_core.c TX 569 bytes Request msg REGISTER/cseq=16538 (tdta00DEA8F8) to UDP 172.18.1.218:4060:
REGISTER sip:voip3gppsrv2 SIP/2.0
Via: SIP/2.0/UDP 172.18.2.74:5060;rport;branch=z9hG4bKPjc429fb3bcf2246949527e32b9e57b536
Route: <sip:172.18.1.218:4060;lr>
Max-Forwards: 70
From: <sip:alice at voip3gppsrv2>;tag=94aba484e1b54cc69a4f3967e1a951b3
To: <sip:alice at voip3gppsrv2>
Call-ID: de5488e94dbe4614bebd1aebecaa08d4
CSeq: 16538 REGISTER
Authorization: Digest username="alice at voip3gppsrv2", realm="voip3gppsrv2", nonce="", uri="sip:voip3gppsrv2", response=""
User-Agent: PJSUA v1.1/win32
Contact: <sip:alice at 172.18.2.74:5060>
Expires: 300
Content-Length: 0
 
--end msg--
18:05:35.017 tsx00DEB98C State changed from Null to Calling, event=TX_MSG
18:05:35.017 pjsua_acc.c Registration sent
18:05:35.033 pjsua_media.c RTP socket reachable at 172.18.2.74:4000
18:05:35.033 pjsua_media.c RTCP socket reachable at 172.18.2.74:4001
18:05:35.033 pjsua_media.c RTP socket reachable at 172.18.2.74:4002
18:05:35.033 pjsua_media.c RTCP socket reachable at 172.18.2.74:4003
18:05:35.033 pjsua_media.c RTP socket reachable at 172.18.2.74:4004
18:05:35.048 pjsua_media.c RTCP socket reachable at 172.18.2.74:4005
18:05:35.048 pjsua_media.c RTP socket reachable at 172.18.2.74:4006
18:05:35.048 pjsua_media.c RTCP socket reachable at 172.18.2.74:4007
18:05:35.095 sip_endpoint.c Processing incoming message: Response msg 401/REGISTER/cseq=16538 (rdata00DE754C)
18:05:35.095 pjsua_core.c RX 929 bytes Response msg 401/REGISTER/cseq=16538 (rdata00DE754C) from UDP 172.18.1.218:4060:
SIP/2.0 401 Unauthorized - Challenging the UE
Via: SIP/2.0/UDP 172.18.2.74:5060;rport=5060;branch=z9hG4bKPjc429fb3bcf2246949527e32b9e57b536
From: <sip:alice at voip3gppsrv2>;tag=94aba484e1b54cc69a4f3967e1a951b3
To: <sip:alice at voip3gppsrv2>;tag=f75735bb452c646ce340d959ac7ef7f2-7309
Call-ID: de5488e94dbe4614bebd1aebecaa08d4
CSeq: 16538 REGISTER
Path: <sip:term at pcscf.voip3gppsrv2:4060;lr>
Service-Route: <sip:orig at scscf.voip3gppsrv2:6060;lr>
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, MESSAGE, INFO
Server: Sip EXpress router (2.1.0-dev1 OpenIMSCore (i386/linux))
Content-Length: 0
Warning: 392 172.18.1.218:6060 "Noisy feedback tells: pid=5458 req_src_ip=172.18.1.218 req_src_port=5060 in_uri=sip:scscf.voip3gppsrv2:6060 out_uri=sip:scscf.voip3gppsrv2:6060 via_cnt==3"
WWW-Authenticate: Digest realm="voip3gppsrv2", nonce="W8Qrvi9uiMwtOAuJzLd/810z500IuAAALdQsY0WER6Q=", algorithm=AKAv1-MD5
 
--end msg--
18:05:35.126 tsx00DEB98C Incoming Response msg 401/REGISTER/cseq=16538 (rdata00DE754C) in state Calling
18:05:35.126 tsx00DEB98C State changed from Calling to Completed, event=RX_MSG
18:05:35.126 tsx00DF82BC Transaction created for Request msg REGISTER/cseq=16539 (tdta00DEA8F8)
18:05:35.126 tsx00DF82BC Sending Request msg REGISTER/cseq=16539 (tdta00DEA8F8) in state Null
18:05:35.126 sip_resolve.c Target '172.18.1.218:4060' type=Unspecified resolved to '172.18.1.218:4060' type=UDP (UDP transport)
18:05:35.126 pjsua_core.c TX 666 bytes Request msg REGISTER/cseq=16539 (tdta00DEA8F8) to UDP 172.18.1.218:4060:
REGISTER sip:voip3gppsrv2 SIP/2.0
Via: SIP/2.0/UDP 172.18.2.74:5060;rport;branch=z9hG4bKPj694ded0a6955423085df0f848f600e98
Route: <sip:172.18.1.218:4060;lr>
Max-Forwards: 70
From: <sip:alice at voip3gppsrv2>;tag=94aba484e1b54cc69a4f3967e1a951b3
To: <sip:alice at voip3gppsrv2>
Call-ID: de5488e94dbe4614bebd1aebecaa08d4
CSeq: 16539 REGISTER
User-Agent: PJSUA v1.1/win32
Contact: <sip:alice at 172.18.2.74:5060>
Expires: 300
Authorization: Digest username="alice at voip3gppsrv2", realm="voip3gppsrv2", nonce="W8Qrvi9uiMwtOAuJzLd/810z500IuAAALdQsY0WER6Q=", uri="sip:voip3gppsrv2", response="6fe922446c03b2792df1e8758edb9ece", algorithm=AKAv1-MD5
Content-Length: 0
 
--end msg--
18:05:35.158 tsx00DF82BC State changed from Null to Calling, event=TX_MSG
18:05:35.267 sip_endpoint.c Processing incoming message: Response msg 200/REGISTER/cseq=16539 (rdata00DE754C)
18:05:35.267 pjsua_core.c RX 959 bytes Response msg 200/REGISTER/cseq=16539 (rdata00DE754C) from UDP 172.18.1.218:4060:
SIP/2.0 200 OK - SAR succesful and registrar saved
Via: SIP/2.0/UDP 172.18.2.74:5060;rport=5060;branch=z9hG4bKPj694ded0a6955423085df0f848f600e98
From: <sip:alice at voip3gppsrv2>;tag=94aba484e1b54cc69a4f3967e1a951b3
To: <sip:alice at voip3gppsrv2>;tag=f75735bb452c646ce340d959ac7ef7f2-6158
Call-ID: de5488e94dbe4614bebd1aebecaa08d4
CSeq: 16539 REGISTER
P-Associated-URI: <sip:alice at voip3gppsrv2>
Contact: <sip:alice at 172.18.2.74:5060>;expires=300
Path: <sip:term at pcscf.voip3gppsrv2:4060;lr>
Service-Route: <sip:orig at scscf.voip3gppsrv2:6060;lr>
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, MESSAGE, INFO
P-Charging-Function-Addresses: ccf=pri_ccf_address
Server: Sip EXpress router (2.1.0-dev1 OpenIMSCore (i386/linux))
Content-Length: 0
Warning: 392 172.18.1.218:6060 "Noisy feedback tells: pid=5457 req_src_ip=172.18.1.218 req_src_port=5060 in_uri=sip:scscf.voip3gppsrv2:6060 out_uri=sip:scscf.voip3gppsrv2:6060 via_cnt==3"
 
--end msg--
18:05:35.283 tsx00DF82BC Incoming Response msg 200/REGISTER/cseq=16539 (rdata00DE754C) in state Calling
18:05:35.283 tsx00DF82BC State changed from Calling to Completed, event=RX_MSG
18:05:35.283 pjsua_acc.c Service-Route updated for acc 1 with 1 URI(s)
18:05:35.283 pjsua_acc.c sip:alice at voip3gppsrv2: registration success, status=200 (OK - SAR succesful and registrar saved), will re-register in 300 seconds
18:05:35.283 pjsua_acc.c Keep-alive timer started for acc 1, destination:172.18.1.218:4060, interval:15s
18:05:40.158 tsx00DEB98C Timeout timer event
18:05:40.158 tsx00DEB98C State changed from Completed to Terminated, event=TIMER
18:05:40.158 tsx00DEB98C Timeout timer event
18:05:40.158 tsx00DEB98C State changed from Terminated to Destroyed, event=TIMER
18:05:40.158 tsx00DEB98C Transaction destroyed!
18:05:40.283 tsx00DF82BC Timeout timer event
18:05:40.283 tsx00DF82BC State changed from Completed to Terminated, event=TIMER
18:05:40.283 tsx00DF82BC Timeout timer event
18:05:40.283 tsx00DF82BC State changed from Terminated to Destroyed, event=TIMER
18:05:40.283 tdta00DEA8F8 Destroying txdata Request msg REGISTER/cseq=16539 (tdta00DEA8F8)
18:05:40.283 tsx00DF82BC Transaction destroyed!
18:05:50.283 pjsua_acc.c Sending 2 bytes keep-alive packet for acc 1 to 172.18.1.218:4060
18:05:50.283 tdta00DEA8F8 Destroying txdata raw
18:06:05.284 pjsua_acc.c Sending 2 bytes keep-alive packet for acc 1 to 172.18.1.218:4060
18:06:05.284 tdta00DEA8F8 Destroying txdata raw
18:06:20.285 pjsua_acc.c Sending 2 bytes keep-alive packet for acc 1 to 172.18.1.218:4060
18:06:20.285 tdta00DEA8F8 Destroying txdata raw
18:06:35.286 pjsua_acc.c Sending 2 bytes keep-alive packet for acc 1 to 172.18.1.218:4060
18:06:35.286 tdta00DEA8F8 Destroying txdata raw
18:06:50.287 pjsua_acc.c Sending 2 bytes keep-alive packet for acc 1 to 172.18.1.218:4060
18:06:50.287 tdta00DEA8F8 Destroying txdata raw
18:07:05.288 pjsua_acc.c Sending 2 bytes keep-alive packet for acc 1 to 172.18.1.218:4060
18:07:05.288 tdta00DEA8F8 Destroying txdata raw
18:07:20.289 pjsua_acc.c Sending 2 bytes keep-alive packet for acc 1 to 172.18.1.218:4060
18:07:20.289 tdta00DEA8F8 Destroying txdata raw
18:07:35.290 pjsua_acc.c Sending 2 bytes keep-alive packet for acc 1 to 172.18.1.218:4060
18:07:35.290 tdta00DEA8F8 Destroying txdata raw
18:07:50.291 pjsua_acc.c Sending 2 bytes keep-alive packet for acc 1 to 172.18.1.218:4060
18:07:50.291 tdta00DEA8F8 Destroying txdata raw
18:08:04.011 endpoint Request msg REGISTER/cseq=16539 (tdta00DEA8F8) created.
18:08:04.011 tsx00DF82BC Transaction created for Request msg REGISTER/cseq=16540 (tdta00DEA8F8)
18:08:04.011 tsx00DF82BC Sending Request msg REGISTER/cseq=16540 (tdta00DEA8F8) in state Null
18:08:04.011 sip_resolve.c Target '172.18.1.218:4060' type=Unspecified resolved to '172.18.1.218:4060' type=UDP (UDP transport)
18:08:04.011 pjsua_core.c TX 567 bytes Request msg REGISTER/cseq=16540 (tdta00DEA8F8) to UDP 172.18.1.218:4060:
REGISTER sip:voip3gppsrv2 SIP/2.0
Via: SIP/2.0/UDP 172.18.2.74:5060;rport;branch=z9hG4bKPjcdb105a9aa11427097534838b6f9e146
Route: <sip:172.18.1.218:4060;lr>
Max-Forwards: 70
From: <sip:alice at voip3gppsrv2>;tag=17189584ace94648b77649b6524475f5
To: <sip:alice at voip3gppsrv2>
Call-ID: de5488e94dbe4614bebd1aebecaa08d4
CSeq: 16540 REGISTER
Authorization: Digest username="alice at voip3gppsrv2", realm="voip3gppsrv2", nonce="", uri="sip:voip3gppsrv2", response=""
User-Agent: PJSUA v1.1/win32
Contact: <sip:alice at 172.18.2.74:5060>
Expires: 0
Content-Length: 0
 
--end msg--
18:08:04.042 tsx00DF82BC State changed from Null to Calling, event=TX_MSG
18:08:04.042 pjsua_acc.c Unregistration sent
18:08:04.073 sip_endpoint.c Processing incoming message: Response msg 401/REGISTER/cseq=16540 (rdata00DE754C)
18:08:04.073 pjsua_core.c RX 929 bytes Response msg 401/REGISTER/cseq=16540 (rdata00DE754C) from UDP 172.18.1.218:4060:
SIP/2.0 401 Unauthorized - Challenging the UE
Via: SIP/2.0/UDP 172.18.2.74:5060;rport=5060;branch=z9hG4bKPjcdb105a9aa11427097534838b6f9e146
From: <sip:alice at voip3gppsrv2>;tag=17189584ace94648b77649b6524475f5
To: <sip:alice at voip3gppsrv2>;tag=f75735bb452c646ce340d959ac7ef7f2-8083
Call-ID: de5488e94dbe4614bebd1aebecaa08d4
CSeq: 16540 REGISTER
Path: <sip:term at pcscf.voip3gppsrv2:4060;lr>
Service-Route: <sip:orig at scscf.voip3gppsrv2:6060;lr>
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, MESSAGE, INFO
Server: Sip EXpress router (2.1.0-dev1 OpenIMSCore (i386/linux))
Content-Length: 0
Warning: 392 172.18.1.218:6060 "Noisy feedback tells: pid=5459 req_src_ip=172.18.1.218 req_src_port=5060 in_uri=sip:scscf.voip3gppsrv2:6060 out_uri=sip:scscf.voip3gppsrv2:6060 via_cnt==3"
WWW-Authenticate: Digest realm="voip3gppsrv2", nonce="ozvm+wuT1P9MzFE+9e08b3zexrGI7QAAKIZR2cW4Avg=", algorithm=AKAv1-MD5
 
--end msg--
18:08:04.105 tsx00DF82BC Incoming Response msg 401/REGISTER/cseq=16540 (rdata00DE754C) in state Calling
18:08:04.105 tsx00DF82BC State changed from Calling to Completed, event=RX_MSG
18:08:04.105 tsx00DED8FC Transaction created for Request msg REGISTER/cseq=16541 (tdta00DEA8F8)
18:08:04.105 tsx00DED8FC Sending Request msg REGISTER/cseq=16541 (tdta00DEA8F8) in state Null
18:08:04.105 sip_resolve.c Target '172.18.1.218:4060' type=Unspecified resolved to '172.18.1.218:4060' type=UDP (UDP transport)
18:08:04.105 pjsua_core.c TX 664 bytes Request msg REGISTER/cseq=16541 (tdta00DEA8F8) to UDP 172.18.1.218:4060:
REGISTER sip:voip3gppsrv2 SIP/2.0
Via: SIP/2.0/UDP 172.18.2.74:5060;rport;branch=z9hG4bKPjf8a49dd8e62344879d66639d70cd1e41
Route: <sip:172.18.1.218:4060;lr>
Max-Forwards: 70
From: <sip:alice at voip3gppsrv2>;tag=17189584ace94648b77649b6524475f5
To: <sip:alice at voip3gppsrv2>
Call-ID: de5488e94dbe4614bebd1aebecaa08d4
CSeq: 16541 REGISTER
User-Agent: PJSUA v1.1/win32
Contact: <sip:alice at 172.18.2.74:5060>
Expires: 0
Authorization: Digest username="alice at voip3gppsrv2", realm="voip3gppsrv2", nonce="ozvm+wuT1P9MzFE+9e08b3zexrGI7QAAKIZR2cW4Avg=", uri="sip:voip3gppsrv2", response="283d0a54f683e1d39d892e1ac61381d2", algorithm=AKAv1-MD5
Content-Length: 0
 
--end msg--
18:08:04.136 tsx00DED8FC State changed from Null to Calling, event=TX_MSG
18:08:04.183 sip_endpoint.c Processing incoming message: Response msg 200/REGISTER/cseq=16541 (rdata00DE754C)
18:08:04.183 pjsua_core.c RX 861 bytes Response msg 200/REGISTER/cseq=16541 (rdata00DE754C) from UDP 172.18.1.218:4060:
SIP/2.0 200 OK - SAR succesful and registrar saved
Via: SIP/2.0/UDP 172.18.2.74:5060;rport=5060;branch=z9hG4bKPjf8a49dd8e62344879d66639d70cd1e41
From: <sip:alice at voip3gppsrv2>;tag=17189584ace94648b77649b6524475f5
To: <sip:alice at voip3gppsrv2>;tag=f75735bb452c646ce340d959ac7ef7f2-c20b
Call-ID: de5488e94dbe4614bebd1aebecaa08d4
CSeq: 16541 REGISTER
Contact: <sip:alice at 172.18.2.74:5060>;expires=0
Path: <sip:term at pcscf.voip3gppsrv2:4060;lr>
Service-Route: <sip:orig at scscf.voip3gppsrv2:6060;lr>
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, MESSAGE, INFO
Server: Sip EXpress router (2.1.0-dev1 OpenIMSCore (i386/linux))
Content-Length: 0
Warning: 392 172.18.1.218:6060 "Noisy feedback tells: pid=5458 req_src_ip=172.18.1.218 req_src_port=5060 in_uri=sip:scscf.voip3gppsrv2:6060 out_uri=sip:scscf.voip3gppsrv2:6060 via_cnt==3"
 
--end msg--
18:08:04.214 tsx00DED8FC Incoming Response msg 200/REGISTER/cseq=16541 (rdata00DE754C) in state Calling
18:08:04.214 tsx00DED8FC State changed from Calling to Completed, event=RX_MSG
18:08:04.214 pjsua_acc.c sip:alice at voip3gppsrv2: unregistration success
18:08:06.261 endpoint Request msg REGISTER/cseq=21817 (tdta00DF8BB8) created.
18:08:06.261 tsx00DF9C4C Transaction created for Request msg REGISTER/cseq=21818 (tdta00DF8BB8)
18:08:06.261 tsx00DF9C4C Sending Request msg REGISTER/cseq=21818 (tdta00DF8BB8) in state Null
18:08:06.261 sip_resolve.c Target '172.18.1.218:4060' type=Unspecified resolved to '172.18.1.218:4060' type=UDP (UDP transport)
18:08:06.261 pjsua_core.c TX 615 bytes Request msg REGISTER/cseq=21818 (tdta00DF8BB8) to UDP 172.18.1.218:4060:
REGISTER sip:voip3gppsrv2 SIP/2.0
Via: SIP/2.0/UDP 172.18.2.74:5060;rport;branch=z9hG4bKPjaa93ed7bb9054801a656aa1ca192ef4e
Route: <sip:172.18.1.218:4060;lr>
Route: <sip:orig at scscf.voip3gppsrv2:6060;lr>
Max-Forwards: 70
From: <sip:alice at voip3gppsrv2>;tag=4300084482054a6692ea1f03821f4c36
To: <sip:alice at voip3gppsrv2>
Call-ID: d8f852bfe7cb4c758fafbaa8dbffed30
CSeq: 21818 REGISTER
Authorization: Digest username="alice at voip3gppsrv2", realm="voip3gppsrv2", nonce="", uri="sip:voip3gppsrv2", response=""
User-Agent: PJSUA v1.1/win32
Contact: <sip:alice at 172.18.2.74:5060>
Expires: 300
Content-Length: 0
 
--end msg--
18:08:06.292 tsx00DF9C4C State changed from Null to Calling, event=TX_MSG
18:08:06.292 pjsua_acc.c Registration sent
18:08:06.355 sip_endpoint.c Processing incoming message: Response msg 401/REGISTER/cseq=21818 (rdata00DE754C)
18:08:06.355 pjsua_core.c RX 929 bytes Response msg 401/REGISTER/cseq=21818 (rdata00DE754C) from UDP 172.18.1.218:4060:
SIP/2.0 401 Unauthorized - Challenging the UE
Via: SIP/2.0/UDP 172.18.2.74:5060;rport=5060;branch=z9hG4bKPjaa93ed7bb9054801a656aa1ca192ef4e
From: <sip:alice at voip3gppsrv2>;tag=4300084482054a6692ea1f03821f4c36
To: <sip:alice at voip3gppsrv2>;tag=f75735bb452c646ce340d959ac7ef7f2-7e85
Call-ID: d8f852bfe7cb4c758fafbaa8dbffed30
CSeq: 21818 REGISTER
Path: <sip:term at pcscf.voip3gppsrv2:4060;lr>
Service-Route: <sip:orig at scscf.voip3gppsrv2:6060;lr>
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, MESSAGE, INFO
Server: Sip EXpress router (2.1.0-dev1 OpenIMSCore (i386/linux))
Content-Length: 0
Warning: 392 172.18.1.218:6060 "Noisy feedback tells: pid=5456 req_src_ip=172.18.1.218 req_src_port=5060 in_uri=sip:scscf.voip3gppsrv2:6060 out_uri=sip:scscf.voip3gppsrv2:6060 via_cnt==3"
WWW-Authenticate: Digest realm="voip3gppsrv2", nonce="QMkAKwXNfHFTF7VRGe0TU8MqGconRQAAw4qvwNo+An8=", algorithm=AKAv1-MD5
 
--end msg--
18:08:06.370 tsx00DF9C4C Incoming Response msg 401/REGISTER/cseq=21818 (rdata00DE754C) in state Calling
18:08:06.370 tsx00DF9C4C State changed from Calling to Completed, event=RX_MSG
18:08:06.370 tsx00DFC3EC Transaction created for Request msg REGISTER/cseq=21819 (tdta00DF8BB8)
18:08:06.370 tsx00DFC3EC Sending Request msg REGISTER/cseq=21819 (tdta00DF8BB8) in state Null
18:08:06.370 sip_resolve.c Target '172.18.1.218:4060' type=Unspecified resolved to '172.18.1.218:4060' type=UDP (UDP transport)
18:08:06.370 pjsua_core.c TX 712 bytes Request msg REGISTER/cseq=21819 (tdta00DF8BB8) to UDP 172.18.1.218:4060:
REGISTER sip:voip3gppsrv2 SIP/2.0
Via: SIP/2.0/UDP 172.18.2.74:5060;rport;branch=z9hG4bKPj6a28b0354fdc46c28aaee2caf90888fa
Route: <sip:172.18.1.218:4060;lr>
Route: <sip:orig at scscf.voip3gppsrv2:6060;lr>
Max-Forwards: 70
From: <sip:alice at voip3gppsrv2>;tag=4300084482054a6692ea1f03821f4c36
To: <sip:alice at voip3gppsrv2>
Call-ID: d8f852bfe7cb4c758fafbaa8dbffed30
CSeq: 21819 REGISTER
User-Agent: PJSUA v1.1/win32
Contact: <sip:alice at 172.18.2.74:5060>
Expires: 300
Authorization: Digest username="alice at voip3gppsrv2", realm="voip3gppsrv2", nonce="QMkAKwXNfHFTF7VRGe0TU8MqGconRQAAw4qvwNo+An8=", uri="sip:voip3gppsrv2", response="06f555889f318639d98b428c80446e6e", algorithm=AKAv1-MD5
Content-Length: 0
 
--end msg--
18:08:06.402 tsx00DFC3EC State changed from Null to Calling, event=TX_MSG
18:08:06.495 sip_endpoint.c Processing incoming message: Response msg 200/REGISTER/cseq=21819 (rdata00DE754C)
18:08:06.495 pjsua_core.c RX 959 bytes Response msg 200/REGISTER/cseq=21819 (rdata00DE754C) from UDP 172.18.1.218:4060:
SIP/2.0 200 OK - SAR succesful and registrar saved
Via: SIP/2.0/UDP 172.18.2.74:5060;rport=5060;branch=z9hG4bKPj6a28b0354fdc46c28aaee2caf90888fa
From: <sip:alice at voip3gppsrv2>;tag=4300084482054a6692ea1f03821f4c36
To: <sip:alice at voip3gppsrv2>;tag=f75735bb452c646ce340d959ac7ef7f2-3712
Call-ID: d8f852bfe7cb4c758fafbaa8dbffed30
CSeq: 21819 REGISTER
P-Associated-URI: <sip:alice at voip3gppsrv2>
Contact: <sip:alice at 172.18.2.74:5060>;expires=300
Path: <sip:term at pcscf.voip3gppsrv2:4060;lr>
Service-Route: <sip:orig at scscf.voip3gppsrv2:6060;lr>
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, MESSAGE, INFO
P-Charging-Function-Addresses: ccf=pri_ccf_address
Server: Sip EXpress router (2.1.0-dev1 OpenIMSCore (i386/linux))
Content-Length: 0
Warning: 392 172.18.1.218:6060 "Noisy feedback tells: pid=5457 req_src_ip=172.18.1.218 req_src_port=5060 in_uri=sip:scscf.voip3gppsrv2:6060 out_uri=sip:scscf.voip3gppsrv2:6060 via_cnt==3"
 
--end msg--
18:08:06.511 tsx00DFC3EC Incoming Response msg 200/REGISTER/cseq=21819 (rdata00DE754C) in state Calling
18:08:06.511 tsx00DFC3EC State changed from Calling to Completed, event=RX_MSG
18:08:06.511 pjsua_acc.c Service-Route updated for acc 1 with 1 URI(s)
18:08:06.511 pjsua_acc.c sip:alice at voip3gppsrv2: registration success, status=200 (OK - SAR succesful and registrar saved), will re-register in 300 seconds
18:08:06.527 pjsua_acc.c Keep-alive timer started for acc 1, destination:172.18.1.218:4060, interval:15s
18:08:09.136 tsx00DF82BC Timeout timer event
18:08:09.136 tsx00DF82BC State changed from Completed to Terminated, event=TIMER
18:08:09.136 tsx00DF82BC Timeout timer event
18:08:09.136 tsx00DF82BC State changed from Terminated to Destroyed, event=TIMER
18:08:09.136 tsx00DF82BC Transaction destroyed!
18:08:09.214 tsx00DED8FC Timeout timer event
18:08:09.214 tsx00DED8FC State changed from Completed to Terminated, event=TIMER
18:08:09.214 tsx00DED8FC Timeout timer event
18:08:09.214 tsx00DED8FC State changed from Terminated to Destroyed, event=TIMER
18:08:09.214 tdta00DEA8F8 Destroying txdata Request msg REGISTER/cseq=16541 (tdta00DEA8F8)
18:08:09.214 tsx00DED8FC Transaction destroyed!
18:08:11.402 tsx00DF9C4C Timeout timer event
18:08:11.402 tsx00DF9C4C State changed from Completed to Terminated, event=TIMER
18:08:11.402 tsx00DF9C4C Timeout timer event
18:08:11.402 tsx00DF9C4C State changed from Terminated to Destroyed, event=TIMER
18:08:11.402 tsx00DF9C4C Transaction destroyed!
18:08:11.511 tsx00DFC3EC Timeout timer event
18:08:11.511 tsx00DFC3EC State changed from Completed to Terminated, event=TIMER
18:08:11.511 tsx00DFC3EC Timeout timer event
18:08:11.511 tsx00DFC3EC State changed from Terminated to Destroyed, event=TIMER
18:08:11.511 tdta00DF8BB8 Destroying txdata Request msg REGISTER/cseq=21819 (tdta00DF8BB8)
18:08:11.511 tsx00DFC3EC Transaction destroyed!
18:08:21.528 pjsua_acc.c Sending 2 bytes keep-alive packet for acc 1 to 172.18.1.218:4060
18:08:21.528 tdta00DEA8F8 Destroying txdata raw
18:08:25.122 sip_endpoint.c Processing incoming message: Request msg INVITE/cseq=5857 (rdata00DE754C)
18:08:25.122 pjsua_core.c <logging error: msg too long>
18:08:25.153 pjsua_media.c Media index 0 selected for call 0
18:08:25.153 tsx00DF907C Transaction created for Request msg INVITE/cseq=5857 (rdata00DE754C)
18:08:25.153 tsx00DF907C Incoming Request msg INVITE/cseq=5857 (rdata00DE754C) in state Null
18:08:25.153 tsx00DF907C State changed from Null to Trying, event=RX_MSG
18:08:25.153 dlg00DED8CC Transaction tsx00DF907C state changed to Trying
18:08:25.153 dlg00DED8CC UAS dialog created
18:08:25.153 dlg00DED8CC Module mod-invite added as dialog usage, data=00DF985C
18:08:25.153 dlg00DED8CC Session count inc to 2 by mod-invite
18:08:25.153 inv00DED8CC UAS invite session created for dialog dlg00DED8CC
18:08:25.153 pjsua_call.c Call 0: remote NAT type is 0 (Unknown)
18:08:25.153 endpoint Response msg 100/INVITE/cseq=5857 (tdta00DFB3F8) created
18:08:25.153 dlg00DED8CC Initial answer Response msg 100/INVITE/cseq=5857 (tdta00DFB3F8)
18:08:25.153 inv00DED8CC Sending Response msg 100/INVITE/cseq=5857 (tdta00DFB3F8)
18:08:25.153 dlg00DED8CC Sending Response msg 100/INVITE/cseq=5857 (tdta00DFB3F8)
18:08:25.153 tsx00DF907C Sending Response msg 100/INVITE/cseq=5857 (tdta00DFB3F8) in state Trying
18:08:25.153 sip_resolve.c Target '172.18.1.218:4060' type=UDP resolved to '172.18.1.218:4060' type=UDP (UDP transport)
18:08:25.153 pjsua_core.c TX 1144 bytes Response msg 100/INVITE/cseq=5857 (tdta00DFB3F8) to UDP 172.18.1.218:4060:
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 172.18.1.218:4060;received=172.18.1.218;branch=z9hG4bK1439.ce76d226.0
Via: SIP/2.0/UDP 172.18.1.218:6060;rport=6060;received=172.18.1.218;branch=z9hG4bK1439.f0db72b1.0
Via: SIP/2.0/UDP 172.18.1.218;branch=z9hG4bK1439.2f38d716.0
Via: SIP/2.0/UDP 172.18.1.218:6060;branch=z9hG4bK1439.e0db72b1.0
Via: SIP/2.0/UDP 172.18.1.218:5065;branch=z9hG4bK1439.e2dffd85.0
Via: SIP/2.0/UDP 172.18.1.218:6060;branch=z9hG4bK1439.d0db72b1.0
Via: SIP/2.0/UDP 172.18.1.218:4060;branch=z9hG4bK1439.be76d226.0
Via: SIP/2.0/UDP 172.18.1.222:5060;rport=5060;branch=z9hG4bKPj7af9a09c2e5a4c9599bbc5f74218db38
Record-Route: <sip:mt at pcscf.voip3gppsrv2:4060;lr>
Record-Route: <sip:mt at scscf.voip3gppsrv2:6060;lr>
Record-Route: <sip:mo at scscf.voip3gppsrv2:6060;lr>
Record-Route: <sip:172.18.1.218:5065;lr;ftag=062ce89b154844dfa30567ae5214c92a>
Record-Route: <sip:mo at scscf.voip3gppsrv2:6060;lr>
Record-Route: <sip:mo at pcscf.voip3gppsrv2:4060;lr>
Call-ID: fbef225ea1e145d7b409ef1b34b5f316
From: <sip:bob at voip3gppsrv2>;tag=062ce89b154844dfa30567ae5214c92a
To: <sip:alice at voip3gppsrv2>
CSeq: 5857 INVITE
Content-Length: 0
 
--end msg--
18:08:25.184 tsx00DF907C State changed from Trying to Proceeding, event=TX_MSG
18:08:25.184 dlg00DED8CC Transaction tsx00DF907C state changed to Proceeding
18:08:25.184 pjsua_media.c Opening sound device PCM at 16000/1/20ms
18:08:25.278 pa_dev.c Opened device Microsoft Sound Mapper - Input(MME)/Microsoft Sound Mapper - Output(MME) for recording and playback, sample rate=16000, ch=1, bits=16, 320 samples per frame, input latency=100 ms, output latency=100 ms
18:08:25.309 ec00DF88B8 Creating AEC
18:08:25.340 ec00DF88B8 AEC created, clock_rate=16000, channel=1, samples per frame=320, tail length=200 ms, latency=100 ms
18:08:25.340 pa_dev.c Starting Microsoft Sound Mapper - Input stream..
18:08:25.356 pa_dev.c PA message: Pa_StartStream: waveInStart returned = 0x0.
18:08:25.356 pa_dev.c Done, status=0
18:08:25.356 conference.c Port 2 (ring) transmitting to port 0 (Microsoft Sound Mapper - Input)
18:08:25.356 inv00DED8CC SDP negotiation done, status=0
18:08:25.356 pjsua_call.c Call 0: remote NAT type is 0 (Unknown)
18:08:25.356 strm00E3086C VAD temporarily disabled
18:08:25.356 rtp.c pjmedia_rtp_session_init: ses=00E31A40, default_pt=103, ssrc=0x294823
18:08:25.356 rtp.c pjmedia_rtp_session_init: ses=00E31EB4, default_pt=103, ssrc=0x294823
18:08:25.356 stream.c Stream strm00E3086C created
18:08:25.356 strm00E3086C Encoder stream started
18:08:25.356 strm00E3086C Decoder stream started
18:08:25.356 pjsua_media.c Media updates, stream #0: speex (sendrecv)
18:08:25.356 conference.c Port 2 (ring) stop transmitting to port 0 (Microsoft Sound Mapper - Input)
18:08:25.372 conference.c Port 3 (sip:bob at voip3gppsrv2) transmitting to port 0 (Microsoft Sound Mapper - Input)
18:08:25.372 conference.c Port 0 (Microsoft Sound Mapper - Input) transmitting to port 3 (sip:bob at voip3gppsrv2)
18:08:25.372 pjsua_app.c Media for call 0 is active
18:08:25.372 inv00DED8CC Sending Response msg 200/INVITE/cseq=5857 (tdta00DFB3F8)
18:08:25.372 dlg00DED8CC Sending Response msg 200/INVITE/cseq=5857 (tdta00DFB3F8)
18:08:25.372 tsx00DF907C Sending Response msg 200/INVITE/cseq=5857 (tdta00DFB3F8) in state Proceeding
18:08:25.372 pa_dev.c Recorder thread started
18:08:25.372 ec00DF88B8 Prefetching..
18:08:25.372 pjsua_core.c TX 1637 bytes Response msg 200/INVITE/cseq=5857 (tdta00DFB3F8) to UDP 172.18.1.218:4060:
SIP/2.0 200 OK
Via: SIP/2.0/UDP 172.18.1.218:4060;received=172.18.1.218;branch=z9hG4bK1439.ce76d226.0
Via: SIP/2.0/UDP 172.18.1.218:6060;rport=6060;received=172.18.1.218;branch=z9hG4bK1439.f0db72b1.0
Via: SIP/2.0/UDP 172.18.1.218;branch=z9hG4bK1439.2f38d716.0
Via: SIP/2.0/UDP 172.18.1.218:6060;branch=z9hG4bK1439.e0db72b1.0
Via: SIP/2.0/UDP 172.18.1.218:5065;branch=z9hG4bK1439.e2dffd85.0
Via: SIP/2.0/UDP 172.18.1.218:6060;branch=z9hG4bK1439.d0db72b1.0
Via: SIP/2.0/UDP 172.18.1.218:4060;branch=z9hG4bK1439.be76d226.0
Via: SIP/2.0/UDP 172.18.1.222:5060;rport=5060;branch=z9hG4bKPj7af9a09c2e5a4c9599bbc5f74218db38
Record-Route: <sip:mt at pcscf.voip3gppsrv2:4060;lr>
Record-Route: <sip:mt at scscf.voip3gppsrv2:6060;lr>
Record-Route: <sip:mo at scscf.voip3gppsrv2:6060;lr>
Record-Route: <sip:172.18.1.218:5065;lr;ftag=062ce89b154844dfa30567ae5214c92a>
Record-Route: <sip:mo at scscf.voip3gppsrv2:6060;lr>
Record-Route: <sip:mo at pcscf.voip3gppsrv2:4060;lr>
Call-ID: fbef225ea1e145d7b409ef1b34b5f316
From: <sip:bob at voip3gppsrv2>;tag=062ce89b154844dfa30567ae5214c92a
To: <sip:alice at voip3gppsrv2>;tag=eddd2b9b09f74cc0851e94a9043f996f
CSeq: 5857 INVITE
Contact: <sip:alice at 172.18.2.74:5060>
Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS
Supported: replaces, 100rel, norefersub
Content-Type: application/sdp
Content-Length: 254
v=0
o=- 3449844505 3449844506 IN IP4 172.18.2.74
s=pjmedia
c=IN IP4 172.18.2.74
t=0 0
a=X-nat:0
m=audio 4000 RTP/AVP 103 101
a=rtcp:4001 IN IP4 172.18.2.74
a=rtpmap:103 speex/16000
a=sendrecv
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
--end msg--
18:08:25.403 pa_dev.c Player thread started
18:08:25.403 strm00E3086C Jitter buffer empty (prefetch=0)
18:08:25.403 strm00E3086C Start talksprut..
18:08:25.403 ec00DF88B8 Prefetching..
18:08:25.434 Master/sound Underflow, buf_cnt=0, will generate 1 frame
18:08:25.434 ec00DF88B8 Prefetching..
18:08:25.450 ec00DF88B8 Prefetching..
18:08:25.450 tsx00DF907C State changed from Proceeding to Completed, event=TX_MSG
18:08:25.450 dlg00DED8CC Transaction tsx00DF907C state changed to Completed
18:08:25.450 pjsua_app.c Call 0 state changed to CONNECTING
18:08:25.465 ec00DF88B8 Prefetching..
18:08:25.481 ec00DF88B8 Prefetching..
18:08:25.481 sip_endpoint.c Processing incoming message: Request msg ACK/cseq=5857 (rdata00DE754C)
18:08:25.481 pjsua_core.c RX 771 bytes Request msg ACK/cseq=5857 (rdata00DE754C) from UDP 172.18.1.218:5065:
ACK sip:alice at 172.18.2.74:5060 SIP/2.0
Via: SIP/2.0/UDP 172.18.1.218:5065;branch=z9hG4bK1439.e2dffd85.2
Via: SIP/2.0/UDP 172.18.1.218:6060;branch=0
Via: SIP/2.0/UDP 172.18.1.218:4060;branch=0
Via: SIP/2.0/UDP 172.18.1.222:5060;rport=5060;branch=z9hG4bKPja95db9fe3dfc44968b29928e00927c66
Max-Forwards: 14
From: sip:bob at voip3gppsrv2;tag=062ce89b154844dfa30567ae5214c92a
To: sip:alice at voip3gppsrv2;tag=eddd2b9b09f74cc0851e94a9043f996f
Call-ID: fbef225ea1e145d7b409ef1b34b5f316
CSeq: 5857 ACK
Route: <sip:172.18.1.218:5065;lr;ftag=062ce89b154844dfa30567ae5214c92a>
Route: <sip:mo at scscf.voip3gppsrv2:6060;lr>
Route: <sip:mt at scscf.voip3gppsrv2:6060;lr>
Route: <sip:mt at pcscf.voip3gppsrv2:4060;lr>
Content-Length: 0
P-Asserted-Identity: <sip:bob at voip3gppsrv2>
 
--end msg--
18:08:25.512 ec00DF88B8 Prefetching..
18:08:25.512 strm00E3086C RTP status: badpt=0, badssrc=0, dup=0, outorder=0, probation=-1, restart=0
18:08:25.512 ec00DF88B8 Latency bufferring complete
18:08:25.512 strm00E3086C Jitter buffer empty (prefetch=0)
18:08:25.512 dlg00DED8CC Received Request msg ACK/cseq=5857 (rdata00DE754C)
18:08:25.512 tsx00DF907C Request to terminate transaction
18:08:25.512 tsx00DF907C State changed from Completed to Terminated, event=USER
18:08:25.512 dlg00DED8CC Transaction tsx00DF907C state changed to Terminated
18:08:25.528 pjsua_app.c Call 0 state changed to CONFIRMED
18:08:25.528 tsx00DF907C Timeout timer event
18:08:25.528 tsx00DF907C State changed from Terminated to Destroyed, event=TIMER
18:08:25.528 tdta00DFB3F8 Destroying txdata Response msg 200/INVITE/cseq=5857 (tdta00DFB3F8)
18:08:25.528 tsx00DF907C Transaction destroyed!
18:08:25.528 strm00E3086C jb updated(2), prefetch=1, size=1
18:08:25.528 strm00E3086C PUT prefetch_cnt=1/1
18:08:26.012 strm00E3086C VAD re-enabled
18:08:26.340 strm00E3086C Jitter buffer empty (prefetch=1)
18:08:26.481 strm00E3086C Starting silence
18:08:26.622 strm00E3086C Start talksprut..
18:08:26.653 strm00E3086C Starting silence
18:08:26.731 strm00E3086C PUT prefetch_cnt=21/1
18:08:26.762 strm00E3086C Jitter buffer empty (prefetch=1)
18:08:27.028 strm00E3086C Start talksprut..
18:08:27.028 strm00E3086C PUT prefetch_cnt=15/1
18:08:27.059 strm00E3086C Jitter buffer empty (prefetch=1)
18:08:27.090 strm00E3086C PUT prefetch_cnt=3/1
18:08:27.122 strm00E3086C Jitter buffer empty (prefetch=1)
18:08:27.340 strm00E3086C Starting silence
18:08:27.419 strm00E3086C Start talksprut..
18:08:27.450 strm00E3086C Starting silence
18:08:27.512 strm00E3086C PUT prefetch_cnt=21/1
18:08:27.544 strm00E3086C Jitter buffer empty (prefetch=1)
18:08:27.825 strm00E3086C PUT prefetch_cnt=16/1
18:08:27.840 strm00E3086C Start talksprut..
18:08:27.872 strm00E3086C Starting silence
18:08:27.887 strm00E3086C Jitter buffer empty (prefetch=1)
18:08:28.028 strm00E3086C PUT prefetch_cnt=9/1
18:08:28.262 strm00E3086C Start talksprut..
18:08:28.278 strm00E3086C Starting silence
18:08:28.340 strm00E3086C Jitter buffer empty (prefetch=1)
18:08:28.684 strm00E3086C Start talksprut..
18:08:28.700 strm00E3086C Starting silence
18:08:28.731 strm00E3086C PUT prefetch_cnt=21/1
18:08:28.762 strm00E3086C Jitter buffer empty (prefetch=1)
18:08:28.950 strm00E3086C Start talksprut..
18:08:28.981 strm00E3086C Starting silence
18:08:29.137 strm00E3086C PUT prefetch_cnt=20/1
18:08:29.153 strm00E3086C Start talksprut..
18:08:29.169 strm00E3086C Jitter buffer empty (prefetch=1)
18:08:29.325 strm00E3086C PUT prefetch_cnt=10/1
18:08:29.372 strm00E3086C Jitter buffer empty (prefetch=1)
18:08:29.747 strm00E3086C PUT prefetch_cnt=21/1
18:08:29.778 strm00E3086C Jitter buffer empty (prefetch=1)
18:08:29.825 strm00E3086C PUT prefetch_cnt=4/1
18:08:29.887 strm00E3086C Jitter buffer empty (prefetch=1)
18:08:30.216 strm00E3086C PUT prefetch_cnt=18/1
18:08:30.247 strm00E3086C Jitter buffer empty (prefetch=1)
18:08:30.247 strm00E3086C PUT prefetch_cnt=2/1
18:08:30.278 strm00E3086C Jitter buffer empty (prefetch=1)
18:08:30.309 strm00E3086C Starting silence
18:08:30.497 strm00E3086C PUT prefetch_cnt=12/1
18:08:30.528 strm00E3086C Jitter buffer empty (prefetch=1)
18:08:30.559 strm00E3086C PUT prefetch_cnt=3/1
18:08:30.591 strm00E3086C Jitter buffer empty (prefetch=1)
18:08:30.700 strm00E3086C Start talksprut..
18:08:30.731 strm00E3086C Starting silence
18:08:30.934 strm00E3086C PUT prefetch_cnt=19/1
18:08:31.044 strm00E3086C Start talksprut..
18:08:31.263 strm00E3086C Starting silence
18:08:31.403 strm00E3086C Jitter buffer empty (prefetch=1)
18:08:31.450 strm00E3086C PUT prefetch_cnt=4/1
18:08:31.466 strm00E3086C Start talksprut..
18:08:31.513 strm00E3086C Starting silence
18:08:31.528 strm00E3086C Start talksprut..
18:08:31.700 strm00E3086C Starting silence
18:08:31.778 strm00E3086C Start talksprut..
18:08:31.809 strm00E3086C Starting silence
18:08:31.981 strm00E3086C Jitter buffer empty (prefetch=1)
18:08:32.216 strm00E3086C Start talksprut..
18:08:32.216 strm00E3086C PUT prefetch_cnt=13/1
18:08:32.231 strm00E3086C Starting silence
18:08:32.466 strm00E3086C Jitter buffer empty (prefetch=1)
18:08:32.622 strm00E3086C Start talksprut..
18:08:32.638 strm00E3086C Starting silence
18:08:32.747 strm00E3086C PUT prefetch_cnt=16/1
18:08:32.810 strm00E3086C Jitter buffer empty (prefetch=1)
18:08:32.856 strm00E3086C PUT prefetch_cnt=4/1
18:08:32.888 strm00E3086C Jitter buffer empty (prefetch=1)
18:08:32.919 strm00E3086C PUT prefetch_cnt=3/1
18:08:33.044 strm00E3086C Start talksprut..
18:08:33.060 strm00E3086C Starting silence
18:08:33.091 strm00E3086C Jitter buffer empty (prefetch=1)
18:08:33.278 strm00E3086C PUT prefetch_cnt=11/1
18:08:33.325 strm00E3086C Start talksprut..
18:08:33.513 strm00E3086C Starting silence
18:08:33.544 strm00E3086C Jitter buffer empty (prefetch=1)
18:08:33.810 strm00E3086C Start talksprut..
18:08:33.935 strm00E3086C PUT prefetch_cnt=21/1
18:08:33.966 strm00E3086C Jitter buffer empty (prefetch=1)
18:08:34.013 strm00E3086C PUT prefetch_cnt=4/1
18:08:34.044 strm00E3086C Jitter buffer empty (prefetch=1)
18:08:34.060 strm00E3086C PUT prefetch_cnt=2/1
18:08:34.091 strm00E3086C Jitter buffer empty (prefetch=1)
18:08:34.231 strm00E3086C PUT prefetch_cnt=9/1
18:08:34.263 strm00E3086C Jitter buffer empty (prefetch=1)
18:08:34.513 strm00E3086C PUT prefetch_cnt=14/1
18:08:34.544 strm00E3086C Jitter buffer empty (prefetch=1)
18:08:34.638 strm00E3086C PUT prefetch_cnt=6/1
18:08:34.638 strm00E3086C Starting silence
18:08:34.685 strm00E3086C Start talksprut..
18:08:34.841 strm00E3086C Starting silence
18:08:34.888 strm00E3086C Start talksprut..
18:08:34.903 strm00E3086C Starting silence
18:08:34.997 strm00E3086C Jitter buffer empty (prefetch=1)
18:08:35.013 strm00E3086C PUT prefetch_cnt=2/1
18:08:35.232 strm00E3086C Jitter buffer empty (prefetch=1)
18:08:35.310 strm00E3086C Start talksprut..
18:08:35.607 strm00E3086C PUT prefetch_cnt=21/1
18:08:35.622 strm00E3086C Starting silence
18:08:35.638 strm00E3086C Jitter buffer empty (prefetch=1)
18:08:36.028 strm00E3086C Start talksprut..
18:08:36.028 strm00E3086C PUT prefetch_cnt=21/1
18:08:36.044 strm00E3086C Starting silence
18:08:36.060 strm00E3086C Jitter buffer empty (prefetch=1)
18:08:36.294 strm00E3086C Start talksprut..
18:08:36.372 strm00E3086C PUT prefetch_cnt=17/1
18:08:36.403 strm00E3086C Jitter buffer empty (prefetch=1)
18:08:36.528 pjsua_acc.c Sending 2 bytes keep-alive packet for acc 1 to 172.18.1.218:4060
18:08:36.528 tdta00DFB3F8 Destroying txdata raw
18:08:36.794 strm00E3086C PUT prefetch_cnt=21/1
18:08:36.825 strm00E3086C Jitter buffer empty (prefetch=1)
18:08:36.841 strm00E3086C Starting silence
18:08:36.919 strm00E3086C Start talksprut..
18:08:36.950 strm00E3086C Starting silence
18:08:36.966 strm00E3086C PUT prefetch_cnt=9/1
18:08:37.091 strm00E3086C Start talksprut..
18:08:37.310 strm00E3086C Jitter buffer empty (prefetch=1)
18:08:37.388 strm00E3086C Starting silence
18:08:37.404 strm00E3086C PUT prefetch_cnt=1/1
18:08:37.419 strm00E3086C jb updated(2), prefetch=7, size=7
18:08:37.419 strm00E3086C Start talksprut..
18:08:37.435 strm00E3086C PUT prefetch_cnt=2/7
18:08:37.450 strm00E3086C Starting silence
18:08:37.450 strm00E3086C PUT prefetch_cnt=3/7
18:08:37.482 strm00E3086C PUT prefetch_cnt=4/7
18:08:37.497 strm00E3086C PUT prefetch_cnt=5/7
18:08:37.513 strm00E3086C PUT prefetch_cnt=6/7
18:08:37.529 strm00E3086C PUT prefetch_cnt=7/7
18:08:37.560 strm00E3086C Start talksprut..
18:08:37.591 strm00E3086C Starting silence
18:08:37.669 strm00E3086C Start talksprut..
18:08:37.888 strm00E3086C Starting silence
18:08:37.966 strm00E3086C Start talksprut..
18:08:37.982 strm00E3086C Lost frame recovered
18:08:37.982 strm00E3086C Starting silence
18:08:37.997 strm00E3086C Lost frame recovered
18:08:38.029 strm00E3086C Lost frame recovered
18:08:38.029 strm00E3086C Start talksprut..
18:08:38.060 strm00E3086C Jitter buffer empty (prefetch=7)
18:08:38.091 strm00E3086C Starting silence
18:08:38.107 strm00E3086C Start talksprut..
18:08:38.247 strm00E3086C PUT prefetch_cnt=17/7
18:08:38.263 strm00E3086C Starting silence
18:08:38.279 strm00E3086C Jitter buffer empty (prefetch=7)
18:08:38.372 strm00E3086C PUT prefetch_cnt=6/7
18:08:38.404 strm00E3086C Jitter buffer empty (prefetch=7)
18:08:38.450 strm00E3086C PUT prefetch_cnt=4/7
18:08:38.482 strm00E3086C PUT prefetch_cnt=5/7
18:08:38.497 strm00E3086C PUT prefetch_cnt=6/7
18:08:38.497 strm00E3086C Start talksprut..
18:08:38.513 strm00E3086C PUT prefetch_cnt=7/7
18:08:38.544 strm00E3086C Starting silence
18:08:38.638 strm00E3086C Jitter buffer empty (prefetch=7)
18:08:38.841 strm00E3086C Start talksprut..
18:08:38.857 strm00E3086C Starting silence
18:08:39.029 strm00E3086C PUT prefetch_cnt=21/7
18:08:39.060 strm00E3086C Jitter buffer empty (prefetch=7)
18:08:39.263 strm00E3086C Start talksprut..
18:08:39.279 strm00E3086C Starting silence
18:08:39.451 strm00E3086C PUT prefetch_cnt=21/7
18:08:39.482 strm00E3086C Jitter buffer empty (prefetch=7)
18:08:39.685 strm00E3086C Start talksprut..
18:08:39.701 strm00E3086C Starting silence
18:08:39.872 strm00E3086C PUT prefetch_cnt=21/7
18:08:39.904 strm00E3086C Jitter buffer empty (prefetch=7)
18:08:39.919 strm00E3086C PUT prefetch_cnt=2/7
18:08:39.951 strm00E3086C Jitter buffer empty (prefetch=7)
18:08:39.951 strm00E3086C PUT prefetch_cnt=2/7
18:08:39.982 strm00E3086C Jitter buffer empty (prefetch=7)
18:08:40.107 strm00E3086C Start talksprut..
18:08:40.122 strm00E3086C Starting silence
18:08:40.372 strm00E3086C PUT prefetch_cnt=21/7
18:08:40.404 strm00E3086C Jitter buffer empty (prefetch=7)
18:08:40.529 strm00E3086C Start talksprut..
18:08:40.544 strm00E3086C Starting silence
18:08:40.669 strm00E3086C PUT prefetch_cnt=15/7
18:08:40.701 strm00E3086C Jitter buffer empty (prefetch=7)
18:08:40.951 strm00E3086C Start talksprut..
18:08:40.966 strm00E3086C Starting silence
18:08:41.091 strm00E3086C PUT prefetch_cnt=21/7
18:08:41.123 strm00E3086C Jitter buffer empty (prefetch=7)
18:08:41.357 strm00E3086C Start talksprut..
18:08:41.388 strm00E3086C Starting silence
18:08:41.513 strm00E3086C PUT prefetch_cnt=21/7
18:08:41.544 strm00E3086C Jitter buffer empty (prefetch=7)
18:08:41.779 strm00E3086C Start talksprut..
18:08:41.810 strm00E3086C Starting silence
18:08:41.935 strm00E3086C PUT prefetch_cnt=21/7
18:08:41.966 strm00E3086C Jitter buffer empty (prefetch=7)
18:08:42.201 strm00E3086C Start talksprut..
18:08:42.216 strm00E3086C Starting silence
18:08:42.357 strm00E3086C PUT prefetch_cnt=21/7
18:08:42.388 strm00E3086C Jitter buffer empty (prefetch=7)
18:08:42.623 strm00E3086C Start talksprut..
18:08:42.638 strm00E3086C Starting silence
18:08:42.779 strm00E3086C PUT prefetch_cnt=21/7
18:08:42.810 strm00E3086C Jitter buffer empty (prefetch=7)
18:08:43.045 strm00E3086C Start talksprut..
18:08:43.060 strm00E3086C Starting silence
18:08:43.201 strm00E3086C PUT prefetch_cnt=21/7
18:08:43.216 strm00E3086C Jitter buffer empty (prefetch=7)
18:08:43.295 strm00E3086C PUT prefetch_cnt=5/7
18:08:43.326 strm00E3086C Jitter buffer empty (prefetch=7)
18:08:43.357 strm00E3086C PUT prefetch_cnt=3/7
18:08:43.388 strm00E3086C Jitter buffer empty (prefetch=7)
18:08:43.466 strm00E3086C Start talksprut..
18:08:43.482 strm00E3086C Starting silence
18:08:43.779 strm00E3086C PUT prefetch_cnt=21/7
18:08:43.810 strm00E3086C Jitter buffer empty (prefetch=7)
18:08:43.857 strm00E3086C PUT prefetch_cnt=4/7
18:08:43.873 strm00E3086C PUT prefetch_cnt=5/7
18:08:43.888 strm00E3086C Start talksprut..
18:08:43.904 strm00E3086C PUT prefetch_cnt=6/7
18:08:43.904 strm00E3086C Starting silence
18:08:43.920 strm00E3086C PUT prefetch_cnt=7/7
18:08:43.966 strm00E3086C Jitter buffer empty (prefetch=7)
18:08:44.295 strm00E3086C PUT prefetch_cnt=18/7
18:08:44.310 strm00E3086C Start talksprut..
18:08:44.326 strm00E3086C Starting silence
18:08:44.420 strm00E3086C Jitter buffer empty (prefetch=7)
18:08:44.717 strm00E3086C Start talksprut..
18:08:44.748 strm00E3086C Starting silence
18:08:44.810 strm00E3086C PUT prefetch_cnt=21/7
18:08:44.842 strm00E3086C Jitter buffer empty (prefetch=7)
18:08:45.013 strm00E3086C PUT prefetch_cnt=10/7
18:08:45.045 strm00E3086C Jitter buffer empty (prefetch=7)
18:08:45.138 strm00E3086C Start talksprut..
18:08:45.170 strm00E3086C Starting silence
18:08:45.201 strm00E3086C PUT prefetch_cnt=9/7
18:08:45.420 strm00E3086C Jitter buffer empty (prefetch=7)
18:08:45.560 strm00E3086C Start talksprut..
18:08:45.576 strm00E3086C Starting silence
18:08:45.810 strm00E3086C PUT prefetch_cnt=21/7
18:08:45.842 strm00E3086C Jitter buffer empty (prefetch=7)
18:08:45.888 strm00E3086C Start talksprut..
18:08:46.060 strm00E3086C Starting silence
18:08:46.232 strm00E3086C PUT prefetch_cnt=21/7
18:08:46.263 strm00E3086C Jitter buffer empty (prefetch=7)
18:08:46.467 strm00E3086C Start talksprut..
18:08:46.482 strm00E3086C Starting silence
18:08:46.498 strm00E3086C PUT prefetch_cnt=13/7
18:08:46.607 strm00E3086C Jitter buffer empty (prefetch=7)
18:08:46.889 strm00E3086C Start talksprut..
18:08:46.904 strm00E3086C Starting silence
18:08:46.998 strm00E3086C PUT prefetch_cnt=21/7
18:08:47.029 strm00E3086C Jitter buffer empty (prefetch=7)
18:08:47.139 strm00E3086C PUT prefetch_cnt=7/7
18:08:47.310 strm00E3086C Start talksprut..
18:08:47.326 strm00E3086C Starting silence
18:08:47.529 strm00E3086C Jitter buffer empty (prefetch=7)
18:08:47.607 strm00E3086C Start talksprut..
18:08:47.607 strm00E3086C PUT prefetch_cnt=6/7
18:08:47.623 strm00E3086C jb updated(1), prefetch=6, size=1
18:08:47.623 strm00E3086C Starting silence
18:08:47.639 strm00E3086C Jitter buffer empty (prefetch=6)
18:08:47.717 strm00E3086C PUT prefetch_cnt=5/6
18:08:47.748 strm00E3086C Jitter buffer empty (prefetch=6)
18:08:47.826 strm00E3086C Start talksprut..
18:08:47.842 strm00E3086C Starting silence
18:08:47.920 strm00E3086C Start talksprut..
18:08:48.107 strm00E3086C Starting silence
18:08:48.139 strm00E3086C PUT prefetch_cnt=21/6
18:08:48.170 strm00E3086C Jitter buffer empty (prefetch=6)
18:08:48.498 strm00E3086C Start talksprut..
18:08:48.529 strm00E3086C Starting silence
18:08:48.561 strm00E3086C PUT prefetch_cnt=21/6
18:08:48.576 strm00E3086C Jitter buffer empty (prefetch=6)
18:08:48.920 strm00E3086C Start talksprut..
18:08:48.936 strm00E3086C Starting silence
18:08:48.967 strm00E3086C PUT prefetch_cnt=21/6
18:08:48.998 strm00E3086C Jitter buffer empty (prefetch=6)
18:08:49.342 strm00E3086C Start talksprut..
18:08:49.357 strm00E3086C Starting silence
18:08:49.389 strm00E3086C PUT prefetch_cnt=21/6
18:08:49.420 strm00E3086C Jitter buffer empty (prefetch=6)
18:08:49.764 strm00E3086C Start talksprut..
18:08:49.779 strm00E3086C Starting silence
18:08:49.811 strm00E3086C PUT prefetch_cnt=21/6
18:08:49.842 strm00E3086C Jitter buffer empty (prefetch=6)
18:08:49.920 strm00E3086C PUT prefetch_cnt=5/6
18:08:49.936 strm00E3086C Jitter buffer empty (prefetch=6)
18:08:50.186 strm00E3086C Start talksprut..
18:08:50.201 strm00E3086C Starting silence
18:08:50.326 strm00E3086C PUT prefetch_cnt=21/6
18:08:50.358 strm00E3086C Jitter buffer empty (prefetch=6)
18:08:50.420 strm00E3086C PUT prefetch_cnt=4/6
18:08:50.436 strm00E3086C PUT prefetch_cnt=5/6
18:08:50.451 strm00E3086C PUT prefetch_cnt=6/6
18:08:50.498 strm00E3086C Jitter buffer empty (prefetch=6)
18:08:50.514 strm00E3086C PUT prefetch_cnt=2/6
18:08:50.529 strm00E3086C PUT prefetch_cnt=3/6
18:08:50.545 strm00E3086C Start talksprut..
18:08:50.561 strm00E3086C Jitter buffer empty (prefetch=6)
18:08:50.561 strm00E3086C Starting silence
18:08:50.576 strm00E3086C Start talksprut..
18:08:50.623 strm00E3086C Starting silence
18:08:50.951 strm00E3086C PUT prefetch_cnt=21/6
18:08:50.983 strm00E3086C Jitter buffer empty (prefetch=6)
18:08:51.014 strm00E3086C PUT prefetch_cnt=3/6
18:08:51.029 strm00E3086C Start talksprut..
18:08:51.045 strm00E3086C Jitter buffer empty (prefetch=6)
18:08:51.045 strm00E3086C Starting silence
18:08:51.248 strm00E3086C PUT prefetch_cnt=12/6
18:08:51.279 strm00E3086C Jitter buffer empty (prefetch=6)
18:08:51.436 strm00E3086C Start talksprut..
18:08:51.467 strm00E3086C Starting silence
18:08:51.529 pjsua_acc.c Sending 2 bytes keep-alive packet for acc 1 to 172.18.1.218:4060
18:08:51.529 tdta00DFB3F8 Destroying txdata raw
18:08:51.654 strm00E3086C PUT prefetch_cnt=20/6
18:08:51.686 strm00E3086C Jitter buffer empty (prefetch=6)
18:08:51.717 strm00E3086C PUT prefetch_cnt=3/6
18:08:51.748 strm00E3086C Jitter buffer empty (prefetch=6)
18:08:51.858 strm00E3086C Start talksprut..
18:08:51.889 strm00E3086C Starting silence
18:08:52.014 strm00E3086C PUT prefetch_cnt=15/6
18:08:52.045 strm00E3086C Jitter buffer empty (prefetch=6)
18:08:52.280 strm00E3086C PUT prefetch_cnt=13/6
18:08:52.280 strm00E3086C Start talksprut..
18:08:52.295 strm00E3086C Jitter buffer empty (prefetch=6)
18:08:52.311 strm00E3086C Starting silence
18:08:52.436 strm00E3086C PUT prefetch_cnt=8/6
18:08:52.561 strm00E3086C Start talksprut..
18:08:52.576 strm00E3086C Starting silence
18:08:52.623 strm00E3086C Start talksprut..
18:08:52.639 strm00E3086C Starting silence
18:08:52.795 strm00E3086C Jitter buffer empty (prefetch=6)
18:08:53.045 strm00E3086C Start talksprut..
18:08:53.061 strm00E3086C Starting silence
18:08:53.201 strm00E3086C PUT prefetch_cnt=21/6
18:08:53.217 strm00E3086C Jitter buffer empty (prefetch=6)
18:08:53.420 strm00E3086C Start talksprut..
18:08:53.608 strm00E3086C Starting silence
18:08:53.608 strm00E3086C PUT prefetch_cnt=21/6
18:08:53.639 strm00E3086C Jitter buffer empty (prefetch=6)
18:08:53.748 strm00E3086C PUT prefetch_cnt=7/6
18:08:53.780 strm00E3086C Jitter buffer empty (prefetch=6)
18:08:53.920 strm00E3086C PUT prefetch_cnt=8/6
18:08:53.967 strm00E3086C Start talksprut..
18:08:54.076 strm00E3086C Jitter buffer empty (prefetch=6)
18:08:54.123 strm00E3086C Starting silence
18:08:54.467 strm00E3086C PUT prefetch_cnt=21/6
18:08:54.498 strm00E3086C Jitter buffer empty (prefetch=6)
18:08:54.530 strm00E3086C Start talksprut..
18:08:54.545 strm00E3086C Starting silence
18:08:54.889 strm00E3086C PUT prefetch_cnt=21/6
18:08:54.920 strm00E3086C Jitter buffer empty (prefetch=6)
18:08:54.936 strm00E3086C Start talksprut..
18:08:54.967 strm00E3086C Starting silence
18:08:54.998 strm00E3086C PUT prefetch_cnt=5/6
18:08:55.030 strm00E3086C Jitter buffer empty (prefetch=6)
18:08:55.092 strm00E3086C PUT prefetch_cnt=5/6
18:08:55.123 strm00E3086C Jitter buffer empty (prefetch=6)
18:08:55.358 strm00E3086C Start talksprut..
18:08:55.389 strm00E3086C Starting silence
18:08:55.514 strm00E3086C PUT prefetch_cnt=21/6
18:08:55.545 strm00E3086C Jitter buffer empty (prefetch=6)
18:08:55.655 strm00E3086C PUT prefetch_cnt=7/6
18:08:55.686 strm00E3086C Jitter buffer empty (prefetch=6)
18:08:55.780 strm00E3086C Start talksprut..
18:08:55.795 strm00E3086C Starting silence
18:08:55.998 strm00E3086C Start talksprut..
18:08:56.030 strm00E3086C Starting silence
18:08:56.077 strm00E3086C PUT prefetch_cnt=21/6
18:08:56.077 strm00E3086C Start talksprut..
18:08:56.108 strm00E3086C Jitter buffer empty (prefetch=6)
18:08:56.108 strm00E3086C Starting silence
18:08:56.233 strm00E3086C PUT prefetch_cnt=8/6
18:08:56.264 strm00E3086C Jitter buffer empty (prefetch=6)
18:08:56.295 strm00E3086C PUT prefetch_cnt=3/6
18:08:56.327 strm00E3086C Jitter buffer empty (prefetch=6)
18:08:56.374 strm00E3086C PUT prefetch_cnt=4/6
18:08:56.405 strm00E3086C Jitter buffer empty (prefetch=6)
18:08:56.420 strm00E3086C PUT prefetch_cnt=2/6
18:08:56.436 strm00E3086C PUT prefetch_cnt=3/6
18:08:56.452 strm00E3086C PUT prefetch_cnt=4/6
18:08:56.483 strm00E3086C Jitter buffer empty (prefetch=6)
18:08:56.499 strm00E3086C Start talksprut..
18:08:56.530 strm00E3086C Starting silence
18:08:56.874 strm00E3086C PUT prefetch_cnt=21/6
18:08:56.905 strm00E3086C Jitter buffer empty (prefetch=6)
18:08:56.920 strm00E3086C Start talksprut..
18:08:56.936 strm00E3086C Starting silence
18:08:57.077 strm00E3086C PUT prefetch_cnt=10/6
18:08:57.124 strm00E3086C Start talksprut..
18:08:57.420 strm00E3086C Starting silence
18:08:57.530 strm00E3086C Start talksprut..
18:08:57.702 strm00E3086C Starting silence
18:08:57.795 strm00E3086C jb updated(1), prefetch=5, size=1
18:08:57.905 strm00E3086C Jitter buffer empty (prefetch=5)
18:08:57.936 strm00E3086C PUT prefetch_cnt=3/5
18:08:57.936 strm00E3086C Start talksprut..
18:08:57.952 strm00E3086C PUT prefetch_cnt=4/5
18:08:57.967 strm00E3086C Starting silence
18:08:57.983 strm00E3086C PUT prefetch_cnt=5/5
18:08:57.999 strm00E3086C Jitter buffer empty (prefetch=5)
18:08:58.014 strm00E3086C PUT prefetch_cnt=2/5
18:08:58.030 strm00E3086C PUT prefetch_cnt=3/5
18:08:58.061 strm00E3086C PUT prefetch_cnt=4/5
18:08:58.077 strm00E3086C PUT prefetch_cnt=5/5
18:08:58.249 strm00E3086C Jitter buffer empty (prefetch=5)
18:08:58.280 strm00E3086C PUT prefetch_cnt=3/5
18:08:58.296 strm00E3086C PUT prefetch_cnt=4/5
18:08:58.311 strm00E3086C PUT prefetch_cnt=5/5
18:08:58.358 strm00E3086C Start talksprut..
18:08:58.389 strm00E3086C Starting silence
18:08:58.467 strm00E3086C Jitter buffer empty (prefetch=5)
18:08:58.530 strm00E3086C PUT prefetch_cnt=5/5
18:08:58.624 strm00E3086C Jitter buffer empty (prefetch=5)
18:08:58.639 strm00E3086C PUT prefetch_cnt=2/5
18:08:58.655 strm00E3086C PUT prefetch_cnt=3/5
18:08:58.671 strm00E3086C PUT prefetch_cnt=4/5
18:08:58.702 strm00E3086C PUT prefetch_cnt=5/5
18:08:58.717 strm00E3086C Jitter buffer empty (prefetch=5)
18:08:58.780 strm00E3086C Start talksprut..
18:08:58.796 strm00E3086C Starting silence
18:08:58.921 strm00E3086C PUT prefetch_cnt=11/5
18:08:58.936 strm00E3086C Jitter buffer empty (prefetch=5)
18:08:59.124 strm00E3086C PUT prefetch_cnt=10/5
18:08:59.202 strm00E3086C Start talksprut..
18:08:59.217 strm00E3086C Starting silence
18:08:59.327 strm00E3086C Jitter buffer empty (prefetch=5)
18:08:59.624 strm00E3086C Start talksprut..
18:08:59.639 strm00E3086C Starting silence
18:08:59.717 strm00E3086C PUT prefetch_cnt=21/5
18:08:59.749 strm00E3086C Jitter buffer empty (prefetch=5)
18:09:00.046 strm00E3086C Start talksprut..
18:09:00.061 strm00E3086C Starting silence
18:09:00.139 strm00E3086C PUT prefetch_cnt=21/5
18:09:00.155 strm00E3086C Jitter buffer empty (prefetch=5)
18:09:00.468 strm00E3086C Start talksprut..
18:09:00.483 strm00E3086C Starting silence
18:09:00.561 strm00E3086C PUT prefetch_cnt=21/5
18:09:00.577 strm00E3086C Jitter buffer empty (prefetch=5)
18:09:00.889 strm00E3086C Start talksprut..
18:09:00.905 strm00E3086C Starting silence
18:09:00.983 strm00E3086C PUT prefetch_cnt=21/5
18:09:00.999 strm00E3086C Jitter buffer empty (prefetch=5)
18:09:01.124 strm00E3086C PUT prefetch_cnt=7/5
18:09:01.280 strm00E3086C Jitter buffer empty (prefetch=5)
18:09:01.296 strm00E3086C Start talksprut..
18:09:01.327 strm00E3086C Starting silence
18:09:01.671 strm00E3086C PUT prefetch_cnt=21/5
18:09:01.702 strm00E3086C Jitter buffer empty (prefetch=5)
18:09:01.718 strm00E3086C Start talksprut..
18:09:01.749 strm00E3086C Starting silence
18:09:02.014 sip_endpoint.c Processing incoming message: Request msg INVITE/cseq=5867 (rdata00DE754C)
18:09:02.014 pjsua_core.c RX 1266 bytes Request msg INVITE/cseq=5867 (rdata00DE754C) from UDP 172.18.1.218:4060:
INVITE sip:alice at 172.18.2.74:5060 SIP/2.0
Record-Route: <sip:mt at pcscf.voip3gppsrv2:4060;lr>
Record-Route: <sip:mt at scscf.voip3gppsrv2:6060;lr>
Max-Forwards: 8
Via: SIP/2.0/UDP 172.18.1.218:4060;branch=z9hG4bK1a09.41feccf5.0
Via: SIP/2.0/UDP 172.18.1.218:6060;rport=6060;branch=z9hG4bK1a09.c6087fb5.0
Via: SIP/2.0/UDP 172.18.1.218;branch=z9hG4bK1a09.98bc3ec4.0
Via: SIP/2.0/UDP 172.18.1.218:5065;branch=z9hG4bK1a09.feb17ec1.0
To: sip:alice at voip3gppsrv2;tag=eddd2b9b09f74cc0851e94a9043f996f
From: sip:bob at voip3gppsrv2;tag=062ce89b154844dfa30567ae5214c92a
CSeq: 5867 INVITE
Call-ID: fbef225ea1e145d7b409ef1b34b5f316
Content-Length: 456
User-Agent: OpenSIPS (1.4.0-notls (i386/linux))
Contact: <sip:bob at 172.18.1.78:5060>
Content-Type: application/sdp
P-Called-Party-ID: <sip:alice at voip3gppsrv2>
v=0
o=- 3449844533 3449844533 IN IP4 172.18.1.78
s=pjmedia
c=IN IP4 172.18.1.78
t=0 0
a=X-nat:0
m=audio 4000 RTP/AVP 103 102 104 117 3 0 8 9 101
a=rtcp:4001 IN IP4 172.18.1.78
a=rtpmap:103 speex/16000
a=rtpmap:102 speex/8000
a=rtpmap:104 speex/32000
a=rtpmap:117 iLBC/8000
a=fmtp:117 mode=30
a=rtpmap:3 GSM/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:9 G722/8000
a=sendrecv
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
--end msg--
18:09:02.061 dlg00DED8CC Received Request msg INVITE/cseq=5867 (rdata00DE754C)
18:09:02.061 tsx00DF907C Transaction created for Request msg INVITE/cseq=5867 (rdata00DE754C)
18:09:02.061 tsx00DF907C Incoming Request msg INVITE/cseq=5867 (rdata00DE754C) in state Null
18:09:02.061 tsx00DF907C State changed from Null to Trying, event=RX_MSG
18:09:02.061 dlg00DED8CC Transaction tsx00DF907C state changed to Trying
18:09:02.061 inv00DED8CC Got SDP offer in Request msg INVITE/cseq=5867 (rdata00DE754C)
18:09:02.061 pjsua_call.c Call 0: received updated media offer
18:09:02.061 endpoint Response msg 200/INVITE/cseq=5867 (tdta00DEB8C8) created
18:09:02.061 inv00DED8CC SDP negotiation done, status=0
18:09:02.061 pjsua_call.c Call 0: remote NAT type is 0 (Unknown)
18:09:02.061 pjsua_media.c Media session for call 0 is destroyed
18:09:02.061 strm00E3086C VAD temporarily disabled
18:09:02.061 rtp.c pjmedia_rtp_session_init: ses=00E31A40, default_pt=103, ssrc=0x294823
18:09:02.061 rtp.c pjmedia_rtp_session_init: ses=00E31EB4, default_pt=103, ssrc=0x294823
18:09:02.061 stream.c Stream strm00E3086C created
18:09:02.061 strm00E3086C Encoder stream started
18:09:02.061 strm00E3086C Decoder stream started
18:09:02.061 pjsua_media.c Media updates, stream #0: speex (sendrecv)
18:09:02.061 conference.c Port 3 (sip:bob at voip3gppsrv2) transmitting to port 0 (Microsoft Sound Mapper - Input)
18:09:02.061 conference.c Port 0 (Microsoft Sound Mapper - Input) transmitting to port 3 (sip:bob at voip3gppsrv2)
18:09:02.061 pjsua_app.c Media for call 0 is active
18:09:02.077 inv00DED8CC Sending Response msg 200/INVITE/cseq=5867 (tdta00DEB8C8)
18:09:02.077 dlg00DED8CC Sending Response msg 200/INVITE/cseq=5867 (tdta00DEB8C8)
18:09:02.077 tsx00DF907C Sending Response msg 200/INVITE/cseq=5867 (tdta00DEB8C8) in state Trying
18:09:02.077 sip_resolve.c Target '172.18.1.218:4060' type=UDP resolved to '172.18.1.218:4060' type=UDP (UDP transport)
18:09:02.077 pjsua_core.c TX 1088 bytes Response msg 200/INVITE/cseq=5867 (tdta00DEB8C8) to UDP 172.18.1.218:4060:
SIP/2.0 200 OK
Via: SIP/2.0/UDP 172.18.1.218:4060;received=172.18.1.218;branch=z9hG4bK1a09.41feccf5.0
Via: SIP/2.0/UDP 172.18.1.218:6060;rport=6060;branch=z9hG4bK1a09.c6087fb5.0
Via: SIP/2.0/UDP 172.18.1.218;branch=z9hG4bK1a09.98bc3ec4.0
Via: SIP/2.0/UDP 172.18.1.218:5065;branch=z9hG4bK1a09.feb17ec1.0
Record-Route: <sip:mt at pcscf.voip3gppsrv2:4060;lr>
Record-Route: <sip:mt at scscf.voip3gppsrv2:6060;lr>
Call-ID: fbef225ea1e145d7b409ef1b34b5f316
From: <sip:bob at voip3gppsrv2>;tag=062ce89b154844dfa30567ae5214c92a
To: <sip:alice at voip3gppsrv2>;tag=eddd2b9b09f74cc0851e94a9043f996f
CSeq: 5867 INVITE
Contact: <sip:alice at 172.18.2.74:5060>
Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS
Supported: replaces, 100rel, norefersub
Content-Type: application/sdp
Content-Length: 254
v=0
o=- 3449844542 3449844507 IN IP4 172.18.2.74
s=pjmedia
c=IN IP4 172.18.2.74
t=0 0
a=X-nat:0
m=audio 4000 RTP/AVP 103 101
a=rtcp:4001 IN IP4 172.18.2.74
a=rtpmap:103 speex/16000
a=sendrecv
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
--end msg--
18:09:02.093 strm00E3086C Jitter buffer empty (prefetch=0)
18:09:02.108 strm00E3086C Start talksprut..
18:09:02.108 strm00E3086C RTP status: badpt=0, badssrc=0, dup=0, outorder=0, probation=-1, restart=0
18:09:02.124 tsx00DF907C State changed from Trying to Completed, event=TX_MSG
18:09:02.124 dlg00DED8CC Transaction tsx00DF907C state changed to Completed
18:09:02.124 sip_endpoint.c Processing incoming message: Request msg ACK/cseq=5867 (rdata00DE754C)
18:09:02.124 pjsua_core.c RX 554 bytes Request msg ACK/cseq=5867 (rdata00DE754C) from UDP 172.18.1.218:4060:
ACK sip:alice at 172.18.2.74:5060 SIP/2.0
Max-Forwards: 8
Via: SIP/2.0/UDP 172.18.1.218:4060;branch=0
Via: SIP/2.0/UDP 172.18.1.218:6060;rport=6060;branch=0
Via: SIP/2.0/UDP 172.18.1.218;branch=0
Via: SIP/2.0/UDP 172.18.1.218:5065;branch=z9hG4bK1a09.feb17ec1.0
From: sip:bob at voip3gppsrv2;tag=062ce89b154844dfa30567ae5214c92a
Call-ID: fbef225ea1e145d7b409ef1b34b5f316
To: <sip:alice at voip3gppsrv2>;tag=eddd2b9b09f74cc0851e94a9043f996f
CSeq: 5867 ACK
User-Agent: OpenSIPS (1.4.0-notls (i386/linux))
Content-Length: 0
P-hint: I-CSCF rr-enforced
 
--end msg--
18:09:02.140 strm00E3086C Jitter buffer empty (prefetch=0)
18:09:02.155 udp00DE9D38 Remote RTCP address switched to 172.18.1.222:4001
18:09:02.155 udp00DE9D38 Remote RTCP address switched to 172.18.1.78:4001
18:09:02.155 dlg00DED8CC Received Request msg ACK/cseq=5867 (rdata00DE754C)
18:09:02.155 tsx00DF907C Request to terminate transaction
18:09:02.155 tsx00DF907C State changed from Completed to Terminated, event=USER
18:09:02.155 dlg00DED8CC Transaction tsx00DF907C state changed to Terminated
18:09:02.155 tsx00DF907C Timeout timer event
18:09:02.155 tsx00DF907C State changed from Terminated to Destroyed, event=TIMER
18:09:02.155 tdta00DEB8C8 Destroying txdata Response msg 200/INVITE/cseq=5867 (tdta00DEB8C8)
18:09:02.155 tsx00DF907C Transaction destroyed!
18:09:02.155 strm00E3086C RTP status: badpt=0, badssrc=0, dup=0, outorder=-1, probation=-1, restart=0
18:09:02.186 strm00E3086C jb updated(2), prefetch=1, size=0
18:09:02.702 strm00E3086C VAD re-enabled
18:09:02.874 strm00E3086C Starting silence
18:09:03.280 strm00E3086C Start talksprut..
18:09:03.296 strm00E3086C Starting silence
18:09:03.436 strm00E3086C Start talksprut..
18:09:03.686 strm00E3086C Starting silence
18:09:04.077 strm00E3086C Start talksprut..
18:09:04.108 strm00E3086C Starting silence
18:09:04.499 strm00E3086C Start talksprut..
18:09:04.515 strm00E3086C Starting silence
18:09:04.765 strm00E3086C Start talksprut..
18:09:05.202 strm00E3086C Starting silence
18:09:05.265 strm00E3086C Start talksprut..
18:09:05.280 strm00E3086C Starting silence
18:09:05.687 strm00E3086C Start talksprut..
18:09:05.702 strm00E3086C Starting silence
18:09:06.109 strm00E3086C Start talksprut..
18:09:06.124 strm00E3086C Starting silence
18:09:06.515 strm00E3086C Start talksprut..
18:09:06.530 pjsua_acc.c Sending 2 bytes keep-alive packet for acc 1 to 172.18.1.218:4060
18:09:06.530 tdta00DEB8C8 Destroying txdata raw
18:09:06.546 strm00E3086C Starting silence
18:09:06.702 sound_port.c EC suspended because of inactivity
18:09:06.780 strm00E3086C Start talksprut..
18:09:09.015 strm00E3086C Starting silence
18:09:09.421 strm00E3086C Start talksprut..
18:09:09.437 strm00E3086C Starting silence
18:09:09.843 strm00E3086C Start talksprut..
18:09:09.859 strm00E3086C Starting silence
18:09:10.265 strm00E3086C Start talksprut..
18:09:10.281 strm00E3086C Starting silence
18:09:10.656 strm00E3086C Start talksprut..
18:09:11.093 strm00E3086C Starting silence
18:09:11.499 strm00E3086C Start talksprut..
18:09:11.515 strm00E3086C Starting silence
18:09:11.921 strm00E3086C Start talksprut..
18:09:11.937 strm00E3086C Starting silence
18:09:12.343 strm00E3086C Start talksprut..
18:09:12.359 strm00E3086C Starting silence
18:09:12.437 strm00E3086C Start talksprut..
18:09:12.468 strm00E3086C Starting silence
18:09:12.562 strm00E3086C Start talksprut..
18:09:12.578 strm00E3086C Starting silence
18:09:12.984 strm00E3086C Start talksprut..
18:09:13.000 strm00E3086C Starting silence
18:09:13.406 strm00E3086C Start talksprut..
18:09:13.421 strm00E3086C Starting silence
18:09:13.828 strm00E3086C Start talksprut..
18:09:13.843 strm00E3086C Starting silence
18:09:14.234 strm00E3086C Start talksprut..
18:09:14.265 strm00E3086C Starting silence
18:09:14.656 strm00E3086C Start talksprut..
18:09:14.687 strm00E3086C Starting silence
18:09:14.687 endpoint Request msg BYE/cseq=9210 (tdta00DEB8C8) created.
18:09:14.687 inv00DED8CC Sending Request msg BYE/cseq=9210 (tdta00DEB8C8)
18:09:14.687 dlg00DED8CC Sending Request msg BYE/cseq=9210 (tdta00DEB8C8)
18:09:14.687 tsx00DF907C Transaction created for Request msg BYE/cseq=9209 (tdta00DEB8C8)
18:09:14.687 tsx00DF907C Sending Request msg BYE/cseq=9209 (tdta00DEB8C8) in state Null
18:09:14.687 sip_resolve.c DNS resolver not available, target 'pcscf.voip3gppsrv2:4060' type=Unspecified will be resolved with gethostbyname()
18:09:14.687 sip_resolve.c Target 'pcscf.voip3gppsrv2:4060' type=Unspecified resolved to '172.18.1.218:4060' type=UDP (UDP transport)
18:09:14.687 pjsua_core.c TX 814 bytes Request msg BYE/cseq=9209 (tdta00DEB8C8) to UDP 172.18.1.218:4060:
BYE sip:bob at 172.18.1.78:5060 SIP/2.0
Via: SIP/2.0/UDP 172.18.2.74:5060;rport;branch=z9hG4bKPj34a8526d58ab4f5885575012224fac43
Max-Forwards: 70
From: <sip:alice at voip3gppsrv2>;tag=eddd2b9b09f74cc0851e94a9043f996f
To: <sip:bob at voip3gppsrv2>;tag=062ce89b154844dfa30567ae5214c92a
Call-ID: fbef225ea1e145d7b409ef1b34b5f316
CSeq: 9209 BYE
Route: <sip:mt at pcscf.voip3gppsrv2:4060;lr>
Route: <sip:mt at scscf.voip3gppsrv2:6060;lr>
Route: <sip:mo at scscf.voip3gppsrv2:6060;lr>
Route: <sip:172.18.1.218:5065;lr;ftag=062ce89b154844dfa30567ae5214c92a>
Route: <sip:mo at scscf.voip3gppsrv2:6060;lr>
Route: <sip:mo at pcscf.voip3gppsrv2:4060;lr>
Authorization: Digest username="alice at voip3gppsrv2", realm="voip3gppsrv2", nonce="", uri="sip:bob at 172.18.1.78:5060", response=""
User-Agent: PJSUA v1.1/win32
Content-Length: 0
 
--end msg--
18:09:14.703 tsx00DF907C State changed from Null to Calling, event=TX_MSG
18:09:14.703 dlg00DED8CC Transaction tsx00DF907C state changed to Calling
18:09:14.718 sip_endpoint.c Processing incoming message: Response msg 400/BYE/cseq=9209 (rdata00DE754C)
18:09:14.718 pjsua_core.c RX 623 bytes Response msg 400/BYE/cseq=9209 (rdata00DE754C) from UDP 172.18.1.218:4060:
SIP/2.0 400 Bad Request - Not following indicated dialog routes
Via: SIP/2.0/UDP 172.18.2.74:5060;rport=5060;branch=z9hG4bKPj34a8526d58ab4f5885575012224fac43
From: <sip:alice at voip3gppsrv2>;tag=eddd2b9b09f74cc0851e94a9043f996f
To: <sip:bob at voip3gppsrv2>;tag=062ce89b154844dfa30567ae5214c92a
Call-ID: fbef225ea1e145d7b409ef1b34b5f316
CSeq: 9209 BYE
Server: Sip EXpress router (2.1.0-dev1 OpenIMSCore (i386/linux))
Content-Length: 0
Warning: 392 172.18.1.218:4060 "Noisy feedback tells: pid=5328 req_src_ip=172.18.2.74 req_src_port=5060 in_uri=sip:bob at 172.18.1.78:5060 out_uri=sip:bob at 172.18.1.78:5060 via_cnt==1"
 
--end msg--
18:09:14.734 tsx00DF907C Incoming Response msg 400/BYE/cseq=9209 (rdata00DE754C) in state Calling
18:09:14.734 tsx00DF907C State changed from Calling to Completed, event=RX_MSG
18:09:14.734 dlg00DED8CC Received Response msg 400/BYE/cseq=9209 (rdata00DE754C)
18:09:14.734 dlg00DED8CC Transaction tsx00DF907C state changed to Completed
18:09:14.734 pjsua_app.c Call 0 is DISCONNECTED [reason=200 (Normal call clearing)]
18:09:14.734 pjsua_app.c Call 0 disconnected, dumping media stats..
18:09:14.734 pjsua_app.c 
[DISCONNCTD] To: <sip:bob at voip3gppsrv2>;tag=062ce89b154844dfa30567ae5214c92a
Call time: 00h:00m:49s, 1st res in 234 ms, conn in 406ms
SRTP status: Not active Crypto-suite: (null)
#0 speex @16KHz, sendrecv, peer=172.18.1.78:4000
RX pt=103, stat last update: 00h:00m:02.609s ago
total 171pkt 9.4KB (16.2KB +IP hdr) @avg=5.9Kbps/10.2Kbps
pkt loss=0 (0.0%), discrd=1 (0.6%), dup=0 (0.0%), reord=0 (0.0%)
(msec) min avg max last dev
loss period: 0.000 0.000 0.000 0.000 0.000
jitter : 0.000 0.503 11.437 0.062 1.416
TX pt=103, ptime=20ms, stat last update: 00h:00m:02.500s ago
total 228pkt 14.4KB (23.5KB +IP hdr) @avg 9.1Kbps/14.8Kbps
pkt loss=0 (0.0%), dup=0 (0.0%), reorder=0 (0.0%)
(msec) min avg max last dev 
loss period: 0.000 0.000 0.000 0.000 0.000
jitter : 0.000 0.187 0.312 0.312 0.134
RTT msec : 0.991 1.014 1.037 0.991 0.023
18:09:14.765 pjsua_media.c Media session for call 0 is destroyed
18:09:14.765 dlg00DED8CC Session count dec to 1 by mod-invite
18:09:15.765 pjsua_media.c Closing sound device after idle for 1 seconds
18:09:15.765 pjsua_media.c Closing Microsoft Sound Mapper - Output sound playback device and Microsoft Sound Mapper - Input sound capture device
18:09:15.781 pa_dev.c Stopping stream..
18:09:15.781 pa_dev.c PA message: WinMME StopStream: waiting for background thread.
18:09:15.859 pa_dev.c PA message: WinMME StopStream: waiting for background thread.
18:09:15.875 pa_dev.c Done, status=0
18:09:15.875 pa_dev.c Closing Microsoft Sound Mapper - Input: 0 underflow, 0 overflow
18:09:19.766 tsx00DF907C Timeout timer event
18:09:19.766 tsx00DF907C State changed from Completed to Terminated, event=TIMER
18:09:19.766 dlg00DED8CC Transaction tsx00DF907C state changed to Terminated
18:09:19.766 dlg00DED8CC Dialog destroyed
18:09:19.766 tsx00DF907C Timeout timer event
18:09:19.766 tsx00DF907C State changed from Terminated to Destroyed, event=TIMER
18:09:19.766 tdta00DEB8C8 Destroying txdata Request msg BYE/cseq=9209 (tdta00DEB8C8)
18:09:19.766 tsx00DF907C Transaction destroyed!
18:09:21.531 pjsua_acc.c Sending 2 bytes keep-alive packet for acc 1 to 172.18.1.218:4060
18:09:21.531 tdta00DF8BB8 Destroying txdata raw
18:09:36.532 pjsua_acc.c Sending 2 bytes keep-alive packet for acc 1 to 172.18.1.218:4060
18:09:36.532 tdta00DF8BB8 Destroying txdata raw
18:09:51.533 pjsua_acc.c Sending 2 bytes keep-alive packet for acc 1 to 172.18.1.218:4060
18:09:51.533 tdta00DF8BB8 Destroying txdata raw
18:10:00.925 sip_endpoint.c Processing incoming message: Request msg BYE/cseq=5869 (rdata00DE754C)
18:10:00.925 pjsua_core.c RX 563 bytes Request msg BYE/cseq=5869 (rdata00DE754C) from UDP 172.18.1.218:4060:
BYE sip:alice at 172.18.2.74:5060 SIP/2.0
Max-Forwards: 9
Via: SIP/2.0/UDP 172.18.1.218:4060;branch=z9hG4bKea09.262408f4.0
Via: SIP/2.0/UDP 172.18.1.218:6060;rport=6060;branch=z9hG4bKea09.46a96585.0
Via: SIP/2.0/UDP 172.18.1.218:5065;branch=z9hG4bKea09.1ae24474.0
To: sip:alice at voip3gppsrv2;tag=eddd2b9b09f74cc0851e94a9043f996f
From: sip:bob at voip3gppsrv2;tag=062ce89b154844dfa30567ae5214c92a
CSeq: 5869 BYE
Call-ID: fbef225ea1e145d7b409ef1b34b5f316
Content-Length: 0
User-Agent: OpenSIPS (1.4.0-notls (i386/linux))
Contact: <sip:bob at 172.18.1.78:5060>
 
--end msg--
18:10:00.940 sip_ua_layer.c Unable to find dialogset for Request msg BYE/cseq=5869 (rdata00DE754C), answering with 481
18:10:00.940 endpoint Response msg 481/BYE/cseq=5869 (tdta00DF8BB8) created
18:10:00.940 sip_resolve.c Target '172.18.1.218:4060' type=UDP resolved to '172.18.1.218:4060' type=UDP (UDP transport)
18:10:00.940 pjsua_core.c TX 491 bytes Response msg 481/BYE/cseq=5869 (tdta00DF8BB8) to UDP 172.18.1.218:4060:
SIP/2.0 481 Call/Transaction Does Not Exist
Via: SIP/2.0/UDP 172.18.1.218:4060;received=172.18.1.218;branch=z9hG4bKea09.262408f4.0
Via: SIP/2.0/UDP 172.18.1.218:6060;rport=6060;branch=z9hG4bKea09.46a96585.0
Via: SIP/2.0/UDP 172.18.1.218:5065;branch=z9hG4bKea09.1ae24474.0
Call-ID: fbef225ea1e145d7b409ef1b34b5f316
From: <sip:bob at voip3gppsrv2>;tag=062ce89b154844dfa30567ae5214c92a
To: <sip:alice at voip3gppsrv2>;tag=eddd2b9b09f74cc0851e94a9043f996f
CSeq: 5869 BYE
Content-Length: 0
 
--end msg--
18:10:00.971 tdta00DF8BB8 Destroying txdata Response msg 481/BYE/cseq=5869 (tdta00DF8BB8)
18:10:06.534 pjsua_acc.c Sending 2 bytes keep-alive packet for acc 1 to 172.18.1.218:4060
18:10:06.534 tdta00DF8BB8 Destroying txdata raw
18:10:17.519 sip_endpoint.c Processing incoming message: Request msg INVITE/cseq=21779 (rdata00DE754C)
18:10:17.519 pjsua_core.c <logging error: msg too long>
18:10:17.519 pjsua_media.c Media index 0 selected for call 1
18:10:17.519 tsx00DEA95C Transaction created for Request msg INVITE/cseq=21779 (rdata00DE754C)
18:10:17.519 tsx00DEA95C Incoming Request msg INVITE/cseq=21779 (rdata00DE754C) in state Null
18:10:17.519 tsx00DEA95C State changed from Null to Trying, event=RX_MSG
18:10:17.519 dlg00DFC08C Transaction tsx00DEA95C state changed to Trying
18:10:17.519 dlg00DFC08C UAS dialog created
18:10:17.519 dlg00DFC08C Module mod-invite added as dialog usage, data=00DF9DCC
18:10:17.519 dlg00DFC08C Session count inc to 2 by mod-invite
18:10:17.519 inv00DFC08C UAS invite session created for dialog dlg00DFC08C
18:10:17.535 pjsua_call.c Call 1: remote NAT type is 0 (Unknown)
18:10:17.535 endpoint Response msg 100/INVITE/cseq=21779 (tdta00DEC448) created
18:10:17.535 dlg00DFC08C Initial answer Response msg 100/INVITE/cseq=21779 (tdta00DEC448)
18:10:17.535 inv00DFC08C Sending Response msg 100/INVITE/cseq=21779 (tdta00DEC448)
18:10:17.535 dlg00DFC08C Sending Response msg 100/INVITE/cseq=21779 (tdta00DEC448)
18:10:17.535 tsx00DEA95C Sending Response msg 100/INVITE/cseq=21779 (tdta00DEC448) in state Trying
18:10:17.535 sip_resolve.c Target '172.18.1.218:4060' type=UDP resolved to '172.18.1.218:4060' type=UDP (UDP transport)
18:10:17.535 pjsua_core.c TX 1142 bytes Response msg 100/INVITE/cseq=21779 (tdta00DEC448) to UDP 172.18.1.218:4060:
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 172.18.1.218:4060;received=172.18.1.218;branch=z9hG4bKb42f.fb5c6986.0
Via: SIP/2.0/UDP 172.18.1.218:6060;rport=6060;received=172.18.1.218;branch=z9hG4bKb42f.c6065a34.0
Via: SIP/2.0/UDP 172.18.1.218;branch=z9hG4bKb42f.09075161.0
Via: SIP/2.0/UDP 172.18.1.218:6060;branch=z9hG4bKb42f.b6065a34.0
Via: SIP/2.0/UDP 172.18.1.218:5065;branch=z9hG4bKb42f.97e4e9.0
Via: SIP/2.0/UDP 172.18.1.218:6060;branch=z9hG4bKb42f.a6065a34.0
Via: SIP/2.0/UDP 172.18.1.218:4060;branch=z9hG4bKb42f.eb5c6986.0
Via: SIP/2.0/UDP 172.18.1.78:5060;rport=5060;branch=z9hG4bKPj860d814952d8408a9b8e0dbeff7bdb90
Record-Route: <sip:mt at pcscf.voip3gppsrv2:4060;lr>
Record-Route: <sip:mt at scscf.voip3gppsrv2:6060;lr>
Record-Route: <sip:mo at scscf.voip3gppsrv2:6060;lr>
Record-Route: <sip:172.18.1.218:5065;lr;ftag=d1668b6ac642456cbfbd4f2c1a301227>
Record-Route: <sip:mo at scscf.voip3gppsrv2:6060;lr>
Record-Route: <sip:mo at pcscf.voip3gppsrv2:4060;lr>
Call-ID: 0f23cac12e744ad1866cd555948b4b6e
From: <sip:bob at voip3gppsrv2>;tag=d1668b6ac642456cbfbd4f2c1a301227
To: <sip:alice at voip3gppsrv2>
CSeq: 21779 INVITE
Content-Length: 0
 
--end msg--
18:10:17.551 tsx00DEA95C State changed from Trying to Proceeding, event=TX_MSG
18:10:17.551 dlg00DFC08C Transaction tsx00DEA95C state changed to Proceeding
18:10:17.551 pjsua_media.c Opening sound device PCM at 16000/1/20ms
18:10:17.582 pa_dev.c Opened device Microsoft Sound Mapper - Input(MME)/Microsoft Sound Mapper - Output(MME) for recording and playback, sample rate=16000, ch=1, bits=16, 320 samples per frame, input latency=100 ms, output latency=100 ms
18:10:17.582 ec00DFCA88 Creating AEC
18:10:17.582 ec00DFCA88 AEC created, clock_rate=16000, channel=1, samples per frame=320, tail length=200 ms, latency=100 ms
18:10:17.582 pa_dev.c Starting Microsoft Sound Mapper - Input stream..
18:10:17.597 pa_dev.c PA message: Pa_StartStream: waveInStart returned = 0x0.
18:10:17.597 pa_dev.c Done, status=0
18:10:17.597 conference.c Port 2 (ring) transmitting to port 0 (Microsoft Sound Mapper - Input)
18:10:17.597 inv00DFC08C SDP negotiation done, status=0
18:10:17.597 pjsua_call.c Call 1: remote NAT type is 0 (Unknown)
18:10:17.597 strm00E2A164 VAD temporarily disabled
18:10:17.597 rtp.c pjmedia_rtp_session_init: ses=00E2B338, default_pt=103, ssrc=0x6d5c2c8f
18:10:17.597 rtp.c pjmedia_rtp_session_init: ses=00E2B7AC, default_pt=103, ssrc=0x6d5c2c8f
18:10:17.597 stream.c Stream strm00E2A164 created
18:10:17.597 strm00E2A164 Encoder stream started
18:10:17.597 strm00E2A164 Decoder stream started
18:10:17.597 pjsua_media.c Media updates, stream #0: speex (sendrecv)
18:10:17.597 conference.c Port 2 (ring) stop transmitting to port 0 (Microsoft Sound Mapper - Input)
18:10:17.597 conference.c Port 3 (sip:bob at voip3gppsrv2) transmitting to port 0 (Microsoft Sound Mapper - Input)
18:10:17.597 conference.c Port 0 (Microsoft Sound Mapper - Input) transmitting to port 3 (sip:bob at voip3gppsrv2)
18:10:17.597 pjsua_app.c Media for call 1 is active
18:10:17.597 inv00DFC08C Sending Response msg 200/INVITE/cseq=21779 (tdta00DEC448)
18:10:17.597 dlg00DFC08C Sending Response msg 200/INVITE/cseq=21779 (tdta00DEC448)
18:10:17.597 tsx00DEA95C Sending Response msg 200/INVITE/cseq=21779 (tdta00DEC448) in state Proceeding
18:10:17.597 pjsua_core.c TX 1635 bytes Response msg 200/INVITE/cseq=21779 (tdta00DEC448) to UDP 172.18.1.218:4060:
SIP/2.0 200 OK
Via: SIP/2.0/UDP 172.18.1.218:4060;received=172.18.1.218;branch=z9hG4bKb42f.fb5c6986.0
Via: SIP/2.0/UDP 172.18.1.218:6060;rport=6060;received=172.18.1.218;branch=z9hG4bKb42f.c6065a34.0
Via: SIP/2.0/UDP 172.18.1.218;branch=z9hG4bKb42f.09075161.0
Via: SIP/2.0/UDP 172.18.1.218:6060;branch=z9hG4bKb42f.b6065a34.0
Via: SIP/2.0/UDP 172.18.1.218:5065;branch=z9hG4bKb42f.97e4e9.0
Via: SIP/2.0/UDP 172.18.1.218:6060;branch=z9hG4bKb42f.a6065a34.0
Via: SIP/2.0/UDP 172.18.1.218:4060;branch=z9hG4bKb42f.eb5c6986.0
Via: SIP/2.0/UDP 172.18.1.78:5060;rport=5060;branch=z9hG4bKPj860d814952d8408a9b8e0dbeff7bdb90
Record-Route: <sip:mt at pcscf.voip3gppsrv2:4060;lr>
Record-Route: <sip:mt at scscf.voip3gppsrv2:6060;lr>
Record-Route: <sip:mo at scscf.voip3gppsrv2:6060;lr>
Record-Route: <sip:172.18.1.218:5065;lr;ftag=d1668b6ac642456cbfbd4f2c1a301227>
Record-Route: <sip:mo at scscf.voip3gppsrv2:6060;lr>
Record-Route: <sip:mo at pcscf.voip3gppsrv2:4060;lr>
Call-ID: 0f23cac12e744ad1866cd555948b4b6e
From: <sip:bob at voip3gppsrv2>;tag=d1668b6ac642456cbfbd4f2c1a301227
To: <sip:alice at voip3gppsrv2>;tag=bc27d41fb5ea4706839220367a190b5e
CSeq: 21779 INVITE
Contact: <sip:alice at 172.18.2.74:5060>
Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS
Supported: replaces, 100rel, norefersub
Content-Type: application/sdp
Content-Length: 254
v=0
o=- 3449844617 3449844618 IN IP4 172.18.2.74
s=pjmedia
c=IN IP4 172.18.2.74
t=0 0
a=X-nat:0
m=audio 4002 RTP/AVP 103 101
a=rtcp:4003 IN IP4 172.18.2.74
a=rtpmap:103 speex/16000
a=sendrecv
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
--end msg--
18:10:17.629 pa_dev.c Player thread started
18:10:17.629 strm00E2A164 Jitter buffer empty (prefetch=0)
18:10:17.629 strm00E2A164 Start talksprut..
18:10:17.629 pa_dev.c Recorder thread started
18:10:17.629 ec00DFCA88 Prefetching..
18:10:17.660 ec00DFCA88 Prefetching..
18:10:17.660 ec00DFCA88 Prefetching..
18:10:17.676 tsx00DEA95C State changed from Proceeding to Completed, event=TX_MSG
18:10:17.676 dlg00DFC08C Transaction tsx00DEA95C state changed to Completed
18:10:17.676 pjsua_app.c Call 1 state changed to CONNECTING
18:10:17.676 ec00DFCA88 Prefetching..
18:10:17.676 Master/sound 333 samples reduced, buf_cnt=627
18:10:17.676 Master/sound Buffer size adjusted from 960 to 627 (eff_cnt=376)
18:10:17.691 ec00DFCA88 Prefetching..
18:10:17.707 strm00E2A164 RTP status: badpt=0, badssrc=0, dup=0, outorder=0, probation=-1, restart=0
18:10:17.722 ec00DFCA88 Prefetching..
18:10:17.722 sip_endpoint.c Processing incoming message: Request msg ACK/cseq=21779 (rdata00DE754C)
18:10:17.722 pjsua_core.c RX 769 bytes Request msg ACK/cseq=21779 (rdata00DE754C) from UDP 172.18.1.218:5065:
ACK sip:alice at 172.18.2.74:5060 SIP/2.0
Via: SIP/2.0/UDP 172.18.1.218:5065;branch=z9hG4bKb42f.97e4e9.2
Via: SIP/2.0/UDP 172.18.1.218:6060;branch=0
Via: SIP/2.0/UDP 172.18.1.218:4060;branch=0
Via: SIP/2.0/UDP 172.18.1.78:5060;rport=5060;branch=z9hG4bKPjd0298f60fd814d3b9b20f3fe1cecf20c
Max-Forwards: 14
From: sip:bob at voip3gppsrv2;tag=d1668b6ac642456cbfbd4f2c1a301227
To: sip:alice at voip3gppsrv2;tag=bc27d41fb5ea4706839220367a190b5e
Call-ID: 0f23cac12e744ad1866cd555948b4b6e
CSeq: 21779 ACK
Route: <sip:172.18.1.218:5065;lr;ftag=d1668b6ac642456cbfbd4f2c1a301227>
Route: <sip:mo at scscf.voip3gppsrv2:6060;lr>
Route: <sip:mt at scscf.voip3gppsrv2:6060;lr>
Route: <sip:mt at pcscf.voip3gppsrv2:4060;lr>
Content-Length: 0
P-Asserted-Identity: <sip:bob at voip3gppsrv2>
 
--end msg--
18:10:17.738 ec00DFCA88 Prefetching..
18:10:17.738 strm00E2A164 jb updated(2), prefetch=1, size=2
18:10:17.754 ec00DFCA88 Latency bufferring complete
18:10:17.754 dlg00DFC08C Received Request msg ACK/cseq=21779 (rdata00DE754C)
18:10:17.754 tsx00DEA95C Request to terminate transaction
18:10:17.754 tsx00DEA95C State changed from Completed to Terminated, event=USER
18:10:17.754 dlg00DFC08C Transaction tsx00DEA95C state changed to Terminated
18:10:17.754 pjsua_app.c Call 1 state changed to CONFIRMED
18:10:17.754 tsx00DEA95C Timeout timer event
18:10:17.754 tsx00DEA95C State changed from Terminated to Destroyed, event=TIMER
18:10:17.754 tdta00DEC448 Destroying txdata Response msg 200/INVITE/cseq=21779 (tdta00DEC448)
18:10:17.754 tsx00DEA95C Transaction destroyed!
18:10:17.754 strm00E2A164 PUT prefetch_cnt=1/1
18:10:18.238 strm00E2A164 VAD re-enabled
18:10:18.723 strm00E2A164 Starting silence
18:10:19.004 strm00E2A164 Start talksprut..
18:10:19.019 strm00E2A164 Starting silence
18:10:19.269 strm00E2A164 Jitter buffer empty (prefetch=1)
18:10:19.316 strm00E2A164 PUT prefetch_cnt=4/1
18:10:19.363 strm00E2A164 Jitter buffer empty (prefetch=1)
18:10:19.379 strm00E2A164 Start talksprut..
18:10:19.394 strm00E2A164 PUT prefetch_cnt=3/1
18:10:19.410 strm00E2A164 Starting silence
18:10:19.426 strm00E2A164 Jitter buffer empty (prefetch=1)
18:10:19.426 strm00E2A164 PUT prefetch_cnt=2/1
18:10:19.457 strm00E2A164 Jitter buffer empty (prefetch=1)
18:10:19.488 strm00E2A164 PUT prefetch_cnt=3/1
18:10:19.519 strm00E2A164 Jitter buffer empty (prefetch=1)
18:10:19.754 strm00E2A164 PUT prefetch_cnt=13/1
18:10:19.785 strm00E2A164 Jitter buffer empty (prefetch=1)
18:10:19.801 strm00E2A164 Start talksprut..
18:10:19.832 strm00E2A164 Starting silence
18:10:20.113 strm00E2A164 PUT prefetch_cnt=18/1
18:10:20.144 strm00E2A164 Jitter buffer empty (prefetch=1)
18:10:20.144 strm00E2A164 PUT prefetch_cnt=2/1
18:10:20.191 strm00E2A164 Jitter buffer empty (prefetch=1)
18:10:20.223 strm00E2A164 Start talksprut..
18:10:20.238 strm00E2A164 Starting silence
18:10:20.566 strm00E2A164 PUT prefetch_cnt=21/1
18:10:20.582 strm00E2A164 Start talksprut..
18:10:20.598 strm00E2A164 Jitter buffer empty (prefetch=1)
18:10:20.598 strm00E2A164 Starting silence
18:10:20.988 strm00E2A164 PUT prefetch_cnt=21/1
18:10:21.004 strm00E2A164 Start talksprut..
18:10:21.020 strm00E2A164 Jitter buffer empty (prefetch=1)
18:10:21.020 strm00E2A164 Starting silence
18:10:21.098 strm00E2A164 PUT prefetch_cnt=5/1
18:10:21.129 strm00E2A164 Jitter buffer empty (prefetch=1)
18:10:21.145 strm00E2A164 PUT prefetch_cnt=3/1
18:10:21.426 strm00E2A164 Start talksprut..
18:10:21.441 strm00E2A164 Starting silence
18:10:21.535 pjsua_acc.c Sending 2 bytes keep-alive packet for acc 1 to 172.18.1.218:4060
18:10:21.535 tdta00DEC448 Destroying txdata raw
18:10:21.801 strm00E2A164 Jitter buffer empty (prefetch=1)
18:10:21.848 strm00E2A164 Start talksprut..
18:10:21.863 strm00E2A164 Starting silence
18:10:21.926 strm00E2A164 PUT prefetch_cnt=8/1
18:10:21.957 strm00E2A164 Jitter buffer empty (prefetch=1)
18:10:21.973 strm00E2A164 PUT prefetch_cnt=2/1
18:10:22.020 strm00E2A164 Jitter buffer empty (prefetch=1)
18:10:22.145 strm00E2A164 PUT prefetch_cnt=8/1
18:10:22.192 strm00E2A164 Jitter buffer empty (prefetch=1)
18:10:22.270 strm00E2A164 Start talksprut..
18:10:22.285 strm00E2A164 Starting silence
18:10:22.426 strm00E2A164 PUT prefetch_cnt=14/1
18:10:22.457 strm00E2A164 Jitter buffer empty (prefetch=1)
18:10:22.504 strm00E2A164 PUT prefetch_cnt=4/1
18:10:22.551 strm00E2A164 Jitter buffer empty (prefetch=1)
18:10:22.676 strm00E2A164 PUT prefetch_cnt=8/1
18:10:22.692 strm00E2A164 Start talksprut..
18:10:22.707 strm00E2A164 Jitter buffer empty (prefetch=1)
18:10:22.707 strm00E2A164 Starting silence
18:10:22.848 strm00E2A164 PUT prefetch_cnt=9/1
18:10:22.879 strm00E2A164 Jitter buffer empty (prefetch=1)
18:10:23.004 strm00E2A164 PUT prefetch_cnt=8/1
18:10:23.051 strm00E2A164 Jitter buffer empty (prefetch=1)
18:10:23.098 strm00E2A164 Start talksprut..
18:10:23.129 strm00E2A164 Starting silence
18:10:23.176 strm00E2A164 PUT prefetch_cnt=8/1
18:10:23.207 strm00E2A164 Jitter buffer empty (prefetch=1)
18:10:23.223 strm00E2A164 Start talksprut..
18:10:23.238 strm00E2A164 Starting silence
18:10:23.254 strm00E2A164 PUT prefetch_cnt=4/1
18:10:23.301 strm00E2A164 Jitter buffer empty (prefetch=1)
18:10:23.317 strm00E2A164 PUT prefetch_cnt=2/1
18:10:23.348 strm00E2A164 Jitter buffer empty (prefetch=1)
18:10:23.426 strm00E2A164 PUT prefetch_cnt=6/1
18:10:23.457 strm00E2A164 Jitter buffer empty (prefetch=1)
18:10:23.473 strm00E2A164 PUT prefetch_cnt=2/1
18:10:23.504 strm00E2A164 Jitter buffer empty (prefetch=1)
18:10:23.504 strm00E2A164 PUT prefetch_cnt=2/1
18:10:23.520 strm00E2A164 Start talksprut..
18:10:23.551 strm00E2A164 Jitter buffer empty (prefetch=1)
18:10:23.551 strm00E2A164 Starting silence
18:10:23.551 strm00E2A164 PUT prefetch_cnt=2/1
18:10:23.582 strm00E2A164 Jitter buffer empty (prefetch=1)
18:10:23.645 strm00E2A164 Start talksprut..
18:10:23.660 strm00E2A164 Starting silence
18:10:23.738 strm00E2A164 PUT prefetch_cnt=9/1
18:10:23.770 strm00E2A164 Jitter buffer empty (prefetch=1)
18:10:23.848 strm00E2A164 PUT prefetch_cnt=6/1
18:10:23.879 strm00E2A164 Jitter buffer empty (prefetch=1)
18:10:23.988 strm00E2A164 PUT prefetch_cnt=7/1
18:10:24.051 strm00E2A164 Jitter buffer empty (prefetch=1)
18:10:24.067 strm00E2A164 Start talksprut..
18:10:24.082 strm00E2A164 Starting silence
18:10:24.145 strm00E2A164 PUT prefetch_cnt=7/1
18:10:24.160 strm00E2A164 Start talksprut..
18:10:24.176 strm00E2A164 Jitter buffer empty (prefetch=1)
18:10:24.192 strm00E2A164 Starting silence
18:10:24.207 strm00E2A164 PUT prefetch_cnt=3/1
18:10:24.239 strm00E2A164 Jitter buffer empty (prefetch=1)
18:10:24.317 strm00E2A164 PUT prefetch_cnt=5/1
18:10:24.317 strm00E2A164 Start talksprut..
18:10:24.348 strm00E2A164 Jitter buffer empty (prefetch=1)
18:10:24.348 strm00E2A164 Starting silence
18:10:24.489 strm00E2A164 PUT prefetch_cnt=9/1
18:10:24.551 strm00E2A164 Jitter buffer empty (prefetch=1)
18:10:24.739 strm00E2A164 Start talksprut..
18:10:24.770 strm00E2A164 Starting silence
18:10:24.926 strm00E2A164 PUT prefetch_cnt=21/1
18:10:24.957 strm00E2A164 Jitter buffer empty (prefetch=1)
18:10:25.160 strm00E2A164 Start talksprut..
18:10:25.176 strm00E2A164 Starting silence
18:10:25.348 strm00E2A164 PUT prefetch_cnt=21/1
18:10:25.379 strm00E2A164 Jitter buffer empty (prefetch=1)
18:10:25.582 strm00E2A164 Start talksprut..
18:10:25.598 strm00E2A164 Starting silence
18:10:25.692 strm00E2A164 PUT prefetch_cnt=17/1
18:10:25.739 strm00E2A164 Jitter buffer empty (prefetch=1)
18:10:25.754 strm00E2A164 PUT prefetch_cnt=2/1
18:10:25.770 strm00E2A164 Start talksprut..
18:10:25.785 strm00E2A164 Jitter buffer empty (prefetch=1)
18:10:25.785 strm00E2A164 Starting silence
18:10:25.817 strm00E2A164 Start talksprut..
18:10:25.848 strm00E2A164 Starting silence
18:10:25.864 strm00E2A164 PUT prefetch_cnt=6/1
18:10:25.910 strm00E2A164 Jitter buffer empty (prefetch=1)
18:10:26.036 strm00E2A164 PUT prefetch_cnt=8/1
18:10:26.129 strm00E2A164 Jitter buffer empty (prefetch=1)
18:10:26.239 strm00E2A164 Start talksprut..
18:10:26.270 strm00E2A164 Starting silence
18:10:26.504 strm00E2A164 PUT prefetch_cnt=21/1
18:10:26.551 strm00E2A164 Jitter buffer empty (prefetch=1)
18:10:26.661 strm00E2A164 Start talksprut..
18:10:26.676 strm00E2A164 Starting silence
18:10:26.926 strm00E2A164 PUT prefetch_cnt=21/1
18:10:26.957 strm00E2A164 Jitter buffer empty (prefetch=1)
18:10:26.989 strm00E2A164 PUT prefetch_cnt=3/1
18:10:27.020 strm00E2A164 Jitter buffer empty (prefetch=1)
18:10:27.082 strm00E2A164 Start talksprut..
18:10:27.098 strm00E2A164 Starting silence
18:10:27.411 strm00E2A164 PUT prefetch_cnt=21/1
18:10:27.442 strm00E2A164 Jitter buffer empty (prefetch=1)
18:10:27.504 strm00E2A164 Start talksprut..
18:10:27.520 strm00E2A164 Starting silence
18:10:27.598 strm00E2A164 PUT prefetch_cnt=9/1
18:10:27.926 strm00E2A164 Start talksprut..
18:10:27.942 strm00E2A164 Jitter buffer empty (prefetch=1)
18:10:27.942 strm00E2A164 Starting silence
18:10:28.333 strm00E2A164 PUT prefetch_cnt=21/1
18:10:28.348 strm00E2A164 Start talksprut..
18:10:28.364 strm00E2A164 Jitter buffer empty (prefetch=1)
18:10:28.364 strm00E2A164 Starting silence
18:10:28.754 strm00E2A164 PUT prefetch_cnt=21/1
18:10:28.770 strm00E2A164 Start talksprut..
18:10:28.786 strm00E2A164 Jitter buffer empty (prefetch=1)
18:10:28.786 strm00E2A164 Starting silence
18:10:28.926 strm00E2A164 PUT prefetch_cnt=9/1
18:10:28.958 strm00E2A164 Jitter buffer empty (prefetch=1)
18:10:28.973 strm00E2A164 PUT prefetch_cnt=2/1
18:10:29.004 strm00E2A164 Jitter buffer empty (prefetch=1)
18:10:29.114 strm00E2A164 PUT prefetch_cnt=7/1
18:10:29.145 strm00E2A164 Jitter buffer empty (prefetch=1)
18:10:29.176 strm00E2A164 Start talksprut..
18:10:29.208 strm00E2A164 Starting silence
18:10:29.395 strm00E2A164 PUT prefetch_cnt=14/1
18:10:29.442 strm00E2A164 Jitter buffer empty (prefetch=1)
18:10:29.598 strm00E2A164 Start talksprut..
18:10:29.629 strm00E2A164 Starting silence
18:10:29.833 strm00E2A164 PUT prefetch_cnt=21/1
18:10:29.864 strm00E2A164 Jitter buffer empty (prefetch=1)
18:10:30.020 strm00E2A164 Start talksprut..
18:10:30.036 strm00E2A164 Starting silence
18:10:30.255 strm00E2A164 PUT prefetch_cnt=21/1
18:10:30.286 strm00E2A164 Jitter buffer empty (prefetch=1)
18:10:30.442 strm00E2A164 Start talksprut..
18:10:30.458 strm00E2A164 Starting silence
18:10:30.676 strm00E2A164 PUT prefetch_cnt=21/1
18:10:30.708 strm00E2A164 Jitter buffer empty (prefetch=1)
18:10:30.864 strm00E2A164 Start talksprut..
18:10:30.880 strm00E2A164 Starting silence
18:10:31.098 strm00E2A164 PUT prefetch_cnt=21/1
18:10:31.270 strm00E2A164 Jitter buffer empty (prefetch=1)
18:10:31.286 strm00E2A164 Start talksprut..
18:10:31.301 strm00E2A164 Starting silence
18:10:31.645 strm00E2A164 PUT prefetch_cnt=21/1
18:10:31.676 strm00E2A164 Jitter buffer empty (prefetch=1)
18:10:31.708 strm00E2A164 Start talksprut..
18:10:31.723 strm00E2A164 Starting silence
18:10:32.067 strm00E2A164 PUT prefetch_cnt=21/1
18:10:32.130 strm00E2A164 Start talksprut..
18:10:32.145 strm00E2A164 Starting silence
18:10:32.223 strm00E2A164 Jitter buffer empty (prefetch=1)
18:10:32.458 strm00E2A164 PUT prefetch_cnt=13/1
18:10:32.489 strm00E2A164 Jitter buffer empty (prefetch=1)
18:10:32.536 strm00E2A164 PUT prefetch_cnt=4/1
18:10:32.536 strm00E2A164 Start talksprut..
18:10:32.567 strm00E2A164 Jitter buffer empty (prefetch=1)
18:10:32.567 strm00E2A164 Starting silence
18:10:32.958 strm00E2A164 PUT prefetch_cnt=21/1
18:10:32.958 strm00E2A164 Start talksprut..
18:10:32.989 strm00E2A164 Jitter buffer empty (prefetch=1)
18:10:32.989 strm00E2A164 Starting silence
18:10:33.255 strm00E2A164 PUT prefetch_cnt=15/1
18:10:33.286 strm00E2A164 Jitter buffer empty (prefetch=1)
18:10:33.333 strm00E2A164 PUT prefetch_cnt=4/1
18:10:33.364 strm00E2A164 Jitter buffer empty (prefetch=1)
18:10:33.380 strm00E2A164 Start talksprut..
18:10:33.395 strm00E2A164 Starting silence
18:10:33.723 sip_endpoint.c Processing incoming message: Request msg INVITE/cseq=21789 (rdata00DE754C)
18:10:33.723 pjsua_core.c RX 1220 bytes Request msg INVITE/cseq=21789 (rdata00DE754C) from UDP 172.18.1.218:4060:
INVITE sip:alice at 172.18.2.74:5060 SIP/2.0
Record-Route: <sip:mt at scscf.voip3gppsrv2:6060;lr>
Max-Forwards: 8
Via: SIP/2.0/UDP 172.18.1.218:4060;branch=z9hG4bK952f.9f77fb01.0
Via: SIP/2.0/UDP 172.18.1.218:6060;rport=6060;branch=z9hG4bK952f.8b570035.0
Via: SIP/2.0/UDP 172.18.1.218;branch=z9hG4bK952f.7a9c97d1.0
Via: SIP/2.0/UDP 172.18.1.218:5065;branch=z9hG4bK952f.e5f69b87.0
To: sip:alice at voip3gppsrv2;tag=bc27d41fb5ea4706839220367a190b5e
From: sip:bob at voip3gppsrv2;tag=d1668b6ac642456cbfbd4f2c1a301227
CSeq: 21789 INVITE
Call-ID: 0f23cac12e744ad1866cd555948b4b6e
Content-Length: 459
User-Agent: OpenSIPS (1.4.0-notls (i386/linux))
Contact: <sip:bob at 172.18.1.222:5060>
Content-Type: application/sdp
P-Called-Party-ID: <sip:alice at voip3gppsrv2>
v=0
o=- 3449844628 3449844628 IN IP4 172.18.1.222
s=pjmedia
c=IN IP4 172.18.1.222
t=0 0
a=X-nat:0
m=audio 4002 RTP/AVP 103 102 104 117 3 0 8 9 101
a=rtcp:4003 IN IP4 172.18.1.222
a=rtpmap:103 speex/16000
a=rtpmap:102 speex/8000
a=rtpmap:104 speex/32000
a=rtpmap:117 iLBC/8000
a=fmtp:117 mode=30
a=rtpmap:3 GSM/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:9 G722/8000
a=sendrecv
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
--end msg--
18:10:33.770 strm00E2A164 PUT prefetch_cnt=21/1
18:10:33.770 dlg00DFC08C Received Request msg INVITE/cseq=21789 (rdata00DE754C)
18:10:33.770 tsx00DEA95C Transaction created for Request msg INVITE/cseq=21789 (rdata00DE754C)
18:10:33.770 tsx00DEA95C Incoming Request msg INVITE/cseq=21789 (rdata00DE754C) in state Null
18:10:33.770 tsx00DEA95C State changed from Null to Trying, event=RX_MSG
18:10:33.770 dlg00DFC08C Transaction tsx00DEA95C state changed to Trying
18:10:33.770 inv00DFC08C Got SDP offer in Request msg INVITE/cseq=21789 (rdata00DE754C)
18:10:33.770 pjsua_call.c Call 1: received updated media offer
18:10:33.770 endpoint Response msg 200/INVITE/cseq=21789 (tdta00E37898) created
18:10:33.770 inv00DFC08C SDP negotiation done, status=0
18:10:33.770 pjsua_call.c Call 1: remote NAT type is 0 (Unknown)
18:10:33.770 pjsua_media.c Media session for call 1 is destroyed
18:10:33.770 strm00E2A164 VAD temporarily disabled
18:10:33.770 rtp.c pjmedia_rtp_session_init: ses=00E2B338, default_pt=103, ssrc=0x6d5c2c8f
18:10:33.770 rtp.c pjmedia_rtp_session_init: ses=00E2B7AC, default_pt=103, ssrc=0x6d5c2c8f
18:10:33.770 stream.c Stream strm00E2A164 created
18:10:33.770 strm00E2A164 Encoder stream started
18:10:33.770 strm00E2A164 Decoder stream started
18:10:33.770 pjsua_media.c Media updates, stream #0: speex (sendrecv)
18:10:33.770 conference.c Port 3 (sip:bob at voip3gppsrv2) transmitting to port 0 (Microsoft Sound Mapper - Input)
18:10:33.770 conference.c Port 0 (Microsoft Sound Mapper - Input) transmitting to port 3 (sip:bob at voip3gppsrv2)
18:10:33.786 pjsua_app.c Media for call 1 is active
18:10:33.786 inv00DFC08C Sending Response msg 200/INVITE/cseq=21789 (tdta00E37898)
18:10:33.786 dlg00DFC08C Sending Response msg 200/INVITE/cseq=21789 (tdta00E37898)
18:10:33.786 tsx00DEA95C Sending Response msg 200/INVITE/cseq=21789 (tdta00E37898) in state Trying
18:10:33.786 sip_resolve.c Target '172.18.1.218:4060' type=UDP resolved to '172.18.1.218:4060' type=UDP (UDP transport)
18:10:33.786 pjsua_core.c TX 1038 bytes Response msg 200/INVITE/cseq=21789 (tdta00E37898) to UDP 172.18.1.218:4060:
SIP/2.0 200 OK
Via: SIP/2.0/UDP 172.18.1.218:4060;received=172.18.1.218;branch=z9hG4bK952f.9f77fb01.0
Via: SIP/2.0/UDP 172.18.1.218:6060;rport=6060;branch=z9hG4bK952f.8b570035.0
Via: SIP/2.0/UDP 172.18.1.218;branch=z9hG4bK952f.7a9c97d1.0
Via: SIP/2.0/UDP 172.18.1.218:5065;branch=z9hG4bK952f.e5f69b87.0
Record-Route: <sip:mt at scscf.voip3gppsrv2:6060;lr>
Call-ID: 0f23cac12e744ad1866cd555948b4b6e
From: <sip:bob at voip3gppsrv2>;tag=d1668b6ac642456cbfbd4f2c1a301227
To: <sip:alice at voip3gppsrv2>;tag=bc27d41fb5ea4706839220367a190b5e
CSeq: 21789 INVITE
Contact: <sip:alice at 172.18.2.74:5060>
Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS
Supported: replaces, 100rel, norefersub
Content-Type: application/sdp
Content-Length: 254
v=0
o=- 3449844633 3449844619 IN IP4 172.18.2.74
s=pjmedia
c=IN IP4 172.18.2.74
t=0 0
a=X-nat:0
m=audio 4002 RTP/AVP 103 101
a=rtcp:4003 IN IP4 172.18.2.74
a=rtpmap:103 speex/16000
a=sendrecv
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
--end msg--
18:10:33.817 strm00E2A164 Jitter buffer empty (prefetch=0)
18:10:33.817 strm00E2A164 Start talksprut..
18:10:33.817 Master/sound Underflow, buf_cnt=307, will generate 1 frame
18:10:33.833 tsx00DEA95C State changed from Trying to Completed, event=TX_MSG
18:10:33.833 dlg00DFC08C Transaction tsx00DEA95C state changed to Completed
18:10:33.833 sip_endpoint.c Processing incoming message: Request msg ACK/cseq=21789 (rdata00DE754C)
18:10:33.833 pjsua_core.c RX 499 bytes Request msg ACK/cseq=21789 (rdata00DE754C) from UDP 172.18.1.218:6060:
ACK sip:alice at 172.18.2.74:5060 SIP/2.0
Max-Forwards: 9
Via: SIP/2.0/UDP 172.18.1.218:6060;branch=0
Via: SIP/2.0/UDP 172.18.1.218;branch=0
Via: SIP/2.0/UDP 172.18.1.218:5065;branch=z9hG4bK952f.e5f69b87.0
From: sip:bob at voip3gppsrv2;tag=d1668b6ac642456cbfbd4f2c1a301227
Call-ID: 0f23cac12e744ad1866cd555948b4b6e
To: <sip:alice at voip3gppsrv2>;tag=bc27d41fb5ea4706839220367a190b5e
CSeq: 21789 ACK
User-Agent: OpenSIPS (1.4.0-notls (i386/linux))
Content-Length: 0
P-hint: I-CSCF rr-enforced
 
--end msg--
18:10:33.864 strm00E2A164 RTP status: badpt=0, badssrc=0, dup=0, outorder=0, probation=-1, restart=0
18:10:33.864 dlg00DFC08C Received Request msg ACK/cseq=21789 (rdata00DE754C)
18:10:33.864 tsx00DEA95C Request to terminate transaction
18:10:33.864 tsx00DEA95C State changed from Completed to Terminated, event=USER
18:10:33.864 dlg00DFC08C Transaction tsx00DEA95C state changed to Terminated
18:10:33.864 tsx00DEA95C Timeout timer event
18:10:33.864 tsx00DEA95C State changed from Terminated to Destroyed, event=TIMER
18:10:33.864 tdta00E37898 Destroying txdata Response msg 200/INVITE/cseq=21789 (tdta00E37898)
18:10:33.864 tsx00DEA95C Transaction destroyed!
18:10:33.864 udp00DF06F8 Remote RTCP address switched to 172.18.1.78:4003
18:10:33.880 strm00E2A164 jb updated(2), prefetch=1, size=1
18:10:33.880 strm00E2A164 PUT prefetch_cnt=1/1
18:10:34.020 udp00DF06F8 Remote RTCP address switched to 172.18.1.222:4003
18:10:34.395 strm00E2A164 VAD re-enabled
18:10:34.536 strm00E2A164 Starting silence
18:10:34.567 strm00E2A164 jb updated(2), prefetch=2, size=2
18:10:34.599 strm00E2A164 Jitter buffer empty (prefetch=2)
18:10:34.599 strm00E2A164 PUT prefetch_cnt=2/2
18:10:34.661 strm00E2A164 Jitter buffer empty (prefetch=2)
18:10:34.786 strm00E2A164 PUT prefetch_cnt=8/2
18:10:34.942 strm00E2A164 Start talksprut..
18:10:34.958 strm00E2A164 Starting silence
18:10:35.364 strm00E2A164 Start talksprut..
18:10:35.520 strm00E2A164 Starting silence
18:10:35.599 strm00E2A164 Jitter buffer empty (prefetch=2)
18:10:35.739 strm00E2A164 PUT prefetch_cnt=9/2
18:10:35.755 strm00E2A164 Jitter buffer empty (prefetch=2)
18:10:35.770 strm00E2A164 PUT prefetch_cnt=1/2
18:10:35.786 strm00E2A164 PUT prefetch_cnt=2/2
18:10:35.927 strm00E2A164 Start talksprut..
18:10:35.942 strm00E2A164 Starting silence
18:10:36.099 strm00E2A164 Jitter buffer empty (prefetch=2)
18:10:36.161 strm00E2A164 PUT prefetch_cnt=5/2
18:10:36.317 strm00E2A164 Start talksprut..
18:10:36.349 strm00E2A164 Starting silence
18:10:36.489 strm00E2A164 Start talksprut..
18:10:36.505 strm00E2A164 Starting silence
18:10:36.536 pjsua_acc.c Sending 2 bytes keep-alive packet for acc 1 to 172.18.1.218:4060
18:10:36.536 tdta00E37898 Destroying txdata raw
18:10:36.536 strm00E2A164 Jitter buffer empty (prefetch=2)
18:10:36.802 strm00E2A164 PUT prefetch_cnt=15/2
18:10:36.864 strm00E2A164 Start talksprut..
18:10:36.880 strm00E2A164 Starting silence
18:10:36.989 strm00E2A164 Jitter buffer empty (prefetch=2)
18:10:37.161 strm00E2A164 Start talksprut..
18:10:37.161 strm00E2A164 PUT prefetch_cnt=11/2
18:10:37.177 strm00E2A164 Starting silence
18:10:37.567 strm00E2A164 Jitter buffer empty (prefetch=2)
18:10:37.583 strm00E2A164 Start talksprut..
18:10:37.599 strm00E2A164 Starting silence
18:10:37.739 strm00E2A164 PUT prefetch_cnt=11/2
18:10:38.005 strm00E2A164 Start talksprut..
18:10:38.021 strm00E2A164 Starting silence
18:10:38.068 strm00E2A164 Jitter buffer empty (prefetch=2)
18:10:38.099 strm00E2A164 PUT prefetch_cnt=4/2
18:10:38.146 strm00E2A164 Jitter buffer empty (prefetch=2)
18:10:38.161 strm00E2A164 PUT prefetch_cnt=2/2
18:10:38.177 strm00E2A164 Jitter buffer empty (prefetch=2)
18:10:38.177 strm00E2A164 Start talksprut..
18:10:38.177 strm00E2A164 PUT prefetch_cnt=1/2
18:10:38.208 strm00E2A164 Starting silence
18:10:38.208 strm00E2A164 PUT prefetch_cnt=2/2
18:10:38.239 strm00E2A164 Start talksprut..
18:10:38.255 strm00E2A164 Starting silence
18:10:38.489 strm00E2A164 Jitter buffer empty (prefetch=2)
18:10:38.599 strm00E2A164 PUT prefetch_cnt=8/2
18:10:38.614 strm00E2A164 Jitter buffer empty (prefetch=2)
18:10:38.661 strm00E2A164 Start talksprut..
18:10:38.677 strm00E2A164 Starting silence
18:10:39.021 strm00E2A164 PUT prefetch_cnt=21/2
18:10:39.036 strm00E2A164 Jitter buffer empty (prefetch=2)
18:10:39.083 strm00E2A164 Start talksprut..
18:10:39.099 strm00E2A164 Starting silence
18:10:39.177 strm00E2A164 PUT prefetch_cnt=8/2
18:10:39.505 strm00E2A164 Start talksprut..
18:10:39.521 strm00E2A164 Starting silence
18:10:39.583 strm00E2A164 Jitter buffer empty (prefetch=2)
18:10:39.927 strm00E2A164 Start talksprut..
18:10:39.943 strm00E2A164 Starting silence
18:10:39.958 strm00E2A164 PUT prefetch_cnt=21/2
18:10:39.990 strm00E2A164 Jitter buffer empty (prefetch=2)
18:10:40.208 strm00E2A164 PUT prefetch_cnt=12/2
18:10:40.349 strm00E2A164 Start talksprut..
18:10:40.365 strm00E2A164 Starting silence
18:10:40.755 strm00E2A164 Start talksprut..
18:10:40.786 strm00E2A164 Starting silence
18:10:40.880 strm00E2A164 Start talksprut..
18:10:40.896 strm00E2A164 Starting silence
18:10:40.958 strm00E2A164 Start talksprut..
18:10:40.990 strm00E2A164 Starting silence
18:10:41.130 strm00E2A164 Start talksprut..
18:10:41.146 strm00E2A164 Starting silence
18:10:41.161 strm00E2A164 Start talksprut..
18:10:41.177 strm00E2A164 Jitter buffer empty (prefetch=2)
18:10:41.177 strm00E2A164 Starting silence
18:10:41.208 strm00E2A164 Start talksprut..
18:10:41.208 strm00E2A164 PUT prefetch_cnt=3/2
18:10:41.302 strm00E2A164 Jitter buffer empty (prefetch=2)
18:10:41.380 strm00E2A164 PUT prefetch_cnt=6/2
18:10:41.396 strm00E2A164 Starting silence
18:10:41.427 strm00E2A164 Start talksprut..
18:10:41.568 strm00E2A164 Jitter buffer empty (prefetch=2)
18:10:41.740 strm00E2A164 PUT prefetch_cnt=11/2
18:10:41.755 strm00E2A164 Starting silence
18:10:41.927 strm00E2A164 Start talksprut..
18:10:41.958 strm00E2A164 Starting silence
18:10:42.208 strm00E2A164 Jitter buffer empty (prefetch=2)
18:10:42.208 strm00E2A164 Start talksprut..
18:10:42.318 strm00E2A164 PUT prefetch_cnt=8/2
18:10:42.365 strm00E2A164 Jitter buffer empty (prefetch=2)
18:10:42.380 strm00E2A164 PUT prefetch_cnt=3/2
18:10:42.427 strm00E2A164 Jitter buffer empty (prefetch=2)
18:10:42.427 strm00E2A164 Starting silence
18:10:42.490 strm00E2A164 Start talksprut..
18:10:42.583 strm00E2A164 PUT prefetch_cnt=10/2
18:10:42.615 strm00E2A164 Jitter buffer empty (prefetch=2)
18:10:42.615 strm00E2A164 Starting silence
18:10:42.771 strm00E2A164 Start talksprut..
18:10:43.005 strm00E2A164 PUT prefetch_cnt=21/2
18:10:43.037 strm00E2A164 Jitter buffer empty (prefetch=2)
18:10:43.099 strm00E2A164 PUT prefetch_cnt=5/2
18:10:43.146 strm00E2A164 Jitter buffer empty (prefetch=2)
18:10:43.162 strm00E2A164 Starting silence
18:10:43.208 strm00E2A164 Start talksprut..
18:10:43.240 strm00E2A164 Starting silence
18:10:43.255 strm00E2A164 PUT prefetch_cnt=8/2
18:10:43.302 strm00E2A164 Start talksprut..
18:10:43.396 strm00E2A164 Starting silence
18:10:43.458 strm00E2A164 Jitter buffer empty (prefetch=2)
18:10:43.505 strm00E2A164 PUT prefetch_cnt=4/2
18:10:43.537 strm00E2A164 Jitter buffer empty (prefetch=2)
18:10:43.599 strm00E2A164 PUT prefetch_cnt=5/2
18:10:43.646 strm00E2A164 Jitter buffer empty (prefetch=2)
18:10:43.709 strm00E2A164 Start talksprut..
18:10:43.724 strm00E2A164 Starting silence
18:10:43.787 strm00E2A164 PUT prefetch_cnt=9/2
18:10:43.849 strm00E2A164 Start talksprut..
18:10:43.865 strm00E2A164 Starting silence
18:10:43.896 strm00E2A164 Start talksprut..
18:10:43.927 strm00E2A164 Starting silence
18:10:43.974 strm00E2A164 Jitter buffer empty (prefetch=2)
18:10:44.224 strm00E2A164 Start talksprut..
18:10:44.240 strm00E2A164 Starting silence
18:10:44.318 strm00E2A164 PUT prefetch_cnt=19/2
18:10:44.646 strm00E2A164 Start talksprut..
18:10:44.662 strm00E2A164 Starting silence
18:10:44.740 strm00E2A164 Jitter buffer empty (prefetch=2)
18:10:45.068 strm00E2A164 Start talksprut..
18:10:45.084 strm00E2A164 Starting silence
18:10:45.115 strm00E2A164 PUT prefetch_cnt=21/2
18:10:45.162 strm00E2A164 Jitter buffer empty (prefetch=2)
18:10:45.396 strm00E2A164 PUT prefetch_cnt=14/2
18:10:45.443 strm00E2A164 Jitter buffer empty (prefetch=2)
18:10:45.443 strm00E2A164 PUT prefetch_cnt=2/2
18:10:45.490 strm00E2A164 Start talksprut..
18:10:45.505 strm00E2A164 Starting silence
18:10:45.787 strm00E2A164 Start talksprut..
18:10:45.802 strm00E2A164 Starting silence
18:10:45.865 strm00E2A164 Start talksprut..
18:10:45.881 strm00E2A164 Starting silence
18:10:46.021 strm00E2A164 Jitter buffer empty (prefetch=2)
18:10:46.287 strm00E2A164 Start talksprut..
18:10:46.302 strm00E2A164 Starting silence
18:10:46.318 strm00E2A164 PUT prefetch_cnt=17/2
18:10:46.459 strm00E2A164 Jitter buffer empty (prefetch=2)
18:10:46.709 strm00E2A164 Start talksprut..
18:10:46.724 strm00E2A164 Starting silence
18:10:46.849 strm00E2A164 PUT prefetch_cnt=21/2
18:10:46.881 strm00E2A164 Jitter buffer empty (prefetch=2)
18:10:47.115 strm00E2A164 Start talksprut..
18:10:47.146 strm00E2A164 Starting silence
18:10:47.209 strm00E2A164 PUT prefetch_cnt=18/2
18:10:47.224 sip_endpoint.c Processing incoming message: Request msg BYE/cseq=21791 (rdata00DE754C)
18:10:47.224 pjsua_core.c RX 565 bytes Request msg BYE/cseq=21791 (rdata00DE754C) from UDP 172.18.1.218:4060:
BYE sip:alice at 172.18.2.74:5060 SIP/2.0
Max-Forwards: 9
Via: SIP/2.0/UDP 172.18.1.218:4060;branch=z9hG4bK152f.b7653005.0
Via: SIP/2.0/UDP 172.18.1.218:6060;rport=6060;branch=z9hG4bK152f.1d926fd5.0
Via: SIP/2.0/UDP 172.18.1.218:5065;branch=z9hG4bK152f.12a22fd5.0
To: sip:alice at voip3gppsrv2;tag=bc27d41fb5ea4706839220367a190b5e
From: sip:bob at voip3gppsrv2;tag=d1668b6ac642456cbfbd4f2c1a301227
CSeq: 21791 BYE
Call-ID: 0f23cac12e744ad1866cd555948b4b6e
Content-Length: 0
User-Agent: OpenSIPS (1.4.0-notls (i386/linux))
Contact: <sip:bob at 172.18.1.222:5060>
 
--end msg--
18:10:47.240 dlg00DFC08C Received Request msg BYE/cseq=21791 (rdata00DE754C)
18:10:47.240 tsx00DEA95C Transaction created for Request msg BYE/cseq=21791 (rdata00DE754C)
18:10:47.240 tsx00DEA95C Incoming Request msg BYE/cseq=21791 (rdata00DE754C) in state Null
18:10:47.240 tsx00DEA95C State changed from Null to Trying, event=RX_MSG
18:10:47.240 dlg00DFC08C Transaction tsx00DEA95C state changed to Trying
18:10:47.240 endpoint Response msg 200/BYE/cseq=21791 (tdta00E37898) created
18:10:47.240 dlg00DFC08C Sending Response msg 200/BYE/cseq=21791 (tdta00E37898)
18:10:47.240 tsx00DEA95C Sending Response msg 200/BYE/cseq=21791 (tdta00E37898) in state Trying
18:10:47.240 sip_resolve.c Target '172.18.1.218:4060' type=UDP resolved to '172.18.1.218:4060' type=UDP (UDP transport)
18:10:47.240 pjsua_core.c TX 463 bytes Response msg 200/BYE/cseq=21791 (tdta00E37898) to UDP 172.18.1.218:4060:
SIP/2.0 200 OK
Via: SIP/2.0/UDP 172.18.1.218:4060;received=172.18.1.218;branch=z9hG4bK152f.b7653005.0
Via: SIP/2.0/UDP 172.18.1.218:6060;rport=6060;branch=z9hG4bK152f.1d926fd5.0
Via: SIP/2.0/UDP 172.18.1.218:5065;branch=z9hG4bK152f.12a22fd5.0
Call-ID: 0f23cac12e744ad1866cd555948b4b6e
From: <sip:bob at voip3gppsrv2>;tag=d1668b6ac642456cbfbd4f2c1a301227
To: <sip:alice at voip3gppsrv2>;tag=bc27d41fb5ea4706839220367a190b5e
CSeq: 21791 BYE
Content-Length: 0
 
--end msg--
18:10:47.256 strm00E2A164 Jitter buffer empty (prefetch=2)
18:10:47.256 tsx00DEA95C State changed from Trying to Completed, event=TX_MSG
18:10:47.256 dlg00DFC08C Transaction tsx00DEA95C state changed to Completed
18:10:47.256 pjsua_app.c Call 1 is DISCONNECTED [reason=200 (Normal call clearing)]
18:10:47.256 pjsua_app.c Call 1 disconnected, dumping media stats..
18:10:47.256 pjsua_app.c 
[DISCONNCTD] To: <sip:bob at voip3gppsrv2>;tag=d1668b6ac642456cbfbd4f2c1a301227
Call time: 00h:00m:29s, 1st res in 78 ms, conn in 235ms
SRTP status: Not active Crypto-suite: (null)
#0 speex @16KHz, sendrecv, peer=172.18.1.222:4002
RX pt=103, stat last update: 00h:00m:03.798s ago
total 360pkt 22.3KB (36.7KB +IP hdr) @avg=13.2Kbps/21.8Kbps
pkt loss=0 (0.0%), discrd=0 (0.0%), dup=0 (0.0%), reord=0 (0.0%)
(msec) min avg max last dev
loss period: 0.000 0.000 0.000 0.000 0.000
jitter : 0.000 0.612 4.000 0.062 0.916
TX pt=103, ptime=20ms, stat last update: 00h:00m:03.016s ago
total 152pkt 7.8KB (13.9KB +IP hdr) @avg 4.6Kbps/8.2Kbps
pkt loss=0 (0.0%), dup=0 (0.0%), reorder=0 (0.0%)
(msec) min avg max last dev 
loss period: 0.000 0.000 0.000 0.000 0.000
jitter : 0.000 0.333 0.750 0.750 0.311
RTT msec : 1.327 1.403 1.480 1.327 0.076
Start talksprut.. 18:10:47.287 pjsua_media.c Media session for call 1 is destroyed
18:10:47.287 dlg00DFC08C Session count dec to 3 by mod-invite
18:10:48.287 pjsua_media.c Closing sound device after idle for 1 seconds
18:10:48.287 pjsua_media.c Closing Microsoft Sound Mapper - Output sound playback device and Microsoft Sound Mapper - Input sound capture device
18:10:48.365 pa_dev.c Stopping stream..
18:10:48.365 pa_dev.c PA message: WinMME StopStream: waiting for background thread.
18:10:48.459 pa_dev.c PA message: WinMME StopStream: waiting for background thread.
18:10:48.459 pa_dev.c Done, status=0
18:10:48.459 pa_dev.c Closing Microsoft Sound Mapper - Input: 0 underflow, 0 overflow
18:10:51.537 pjsua_acc.c Sending 2 bytes keep-alive packet for acc 1 to 172.18.1.218:4060
18:10:51.537 tdta00E19028 Destroying txdata raw
18:10:59.522 sip_endpoint.c Processing incoming message: Request msg INVITE/cseq=6884 (rdata00DE754C)
18:10:59.522 pjsua_core.c <logging error: msg too long>
18:10:59.522 pjsua_media.c Media index 0 selected for call 2
18:10:59.522 tsx00DED7CC Transaction created for Request msg INVITE/cseq=6884 (rdata00DE754C)
18:10:59.522 tsx00DED7CC Incoming Request msg INVITE/cseq=6884 (rdata00DE754C) in state Null
18:10:59.522 tsx00DED7CC State changed from Null to Trying, event=RX_MSG
18:10:59.522 dlg00E2808C Transaction tsx00DED7CC state changed to Trying
18:10:59.522 dlg00E2808C UAS dialog created
18:10:59.522 dlg00E2808C Module mod-invite added as dialog usage, data=00DF9FFC
18:10:59.522 dlg00E2808C Session count inc to 2 by mod-invite
18:10:59.522 inv00E2808C UAS invite session created for dialog dlg00E2808C
18:10:59.522 pjsua_call.c Call 2: remote NAT type is 0 (Unknown)
18:10:59.522 endpoint Response msg 100/INVITE/cseq=6884 (tdta00E2D650) created
18:10:59.522 dlg00E2808C Initial answer Response msg 100/INVITE/cseq=6884 (tdta00E2D650)
18:10:59.522 inv00E2808C Sending Response msg 100/INVITE/cseq=6884 (tdta00E2D650)
18:10:59.522 dlg00E2808C Sending Response msg 100/INVITE/cseq=6884 (tdta00E2D650)
18:10:59.522 tsx00DED7CC Sending Response msg 100/INVITE/cseq=6884 (tdta00E2D650) in state Trying
18:10:59.522 sip_resolve.c Target '172.18.1.218:4060' type=UDP resolved to '172.18.1.218:4060' type=UDP (UDP transport)
18:10:59.522 pjsua_core.c TX 1137 bytes Response msg 100/INVITE/cseq=6884 (tdta00E2D650) to UDP 172.18.1.218:4060:
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 172.18.1.218:4060;received=172.18.1.218;branch=z9hG4bK67a2.48fe566.0
Via: SIP/2.0/UDP 172.18.1.218:6060;rport=6060;received=172.18.1.218;branch=z9hG4bK67a2.0e84f71.0
Via: SIP/2.0/UDP 172.18.1.218;branch=z9hG4bK67a2.628ecfe.0
Via: SIP/2.0/UDP 172.18.1.218:6060;branch=z9hG4bK67a2.fd84f71.0
Via: SIP/2.0/UDP 172.18.1.218:5065;branch=z9hG4bK67a2.e2eb58c.0
Via: SIP/2.0/UDP 172.18.1.218:6060;branch=z9hG4bK67a2.ed84f71.0
Via: SIP/2.0/UDP 172.18.1.218:4060;branch=z9hG4bK67a2.38fe566.0
Via: SIP/2.0/UDP 172.18.1.222:5060;rport=5060;branch=z9hG4bKPjde466559097f4883b24e1f88a13e463f
Record-Route: <sip:mt at pcscf.voip3gppsrv2:4060;lr>
Record-Route: <sip:mt at scscf.voip3gppsrv2:6060;lr>
Record-Route: <sip:mo at scscf.voip3gppsrv2:6060;lr>
Record-Route: <sip:172.18.1.218:5065;lr;ftag=15a28719e9eb4442a1d20d24ca897b37>
Record-Route: <sip:mo at scscf.voip3gppsrv2:6060;lr>
Record-Route: <sip:mo at pcscf.voip3gppsrv2:4060;lr>
Call-ID: af199956066e448d851bdb067a6ced46
From: <sip:bob at voip3gppsrv2>;tag=15a28719e9eb4442a1d20d24ca897b37
To: <sip:alice at voip3gppsrv2>
CSeq: 6884 INVITE
Content-Length: 0
 
--end msg--
18:10:59.553 tsx00DED7CC State changed from Trying to Proceeding, event=TX_MSG
18:10:59.553 dlg00E2808C Transaction tsx00DED7CC state changed to Proceeding
18:10:59.553 pjsua_media.c Opening sound device PCM at 16000/1/20ms
18:10:59.585 pa_dev.c Opened device Microsoft Sound Mapper - Input(MME)/Microsoft Sound Mapper - Output(MME) for recording and playback, sample rate=16000, ch=1, bits=16, 320 samples per frame, input latency=100 ms, output latency=100 ms
18:10:59.585 ec00DEDF98 Creating AEC
18:10:59.585 ec00DEDF98 AEC created, clock_rate=16000, channel=1, samples per frame=320, tail length=200 ms, latency=100 ms
18:10:59.585 pa_dev.c Starting Microsoft Sound Mapper - Input stream..
18:10:59.600 pa_dev.c PA message: Pa_StartStream: waveInStart returned = 0x0.
18:10:59.600 pa_dev.c Done, status=0
18:10:59.600 conference.c Port 2 (ring) transmitting to port 0 (Microsoft Sound Mapper - Input)
18:10:59.600 inv00E2808C SDP negotiation done, status=0
18:10:59.600 pjsua_call.c Call 2: remote NAT type is 0 (Unknown)
18:10:59.600 strm00E3D4FC VAD temporarily disabled
18:10:59.600 rtp.c pjmedia_rtp_session_init: ses=00E3E6D0, default_pt=103, ssrc=0x3a284172
18:10:59.600 rtp.c pjmedia_rtp_session_init: ses=00E3EB44, default_pt=103, ssrc=0x3a284172
18:10:59.600 stream.c Stream strm00E3D4FC created
18:10:59.600 strm00E3D4FC Encoder stream started
18:10:59.600 strm00E3D4FC Decoder stream started
18:10:59.600 pjsua_media.c Media updates, stream #0: speex (sendrecv)
18:10:59.600 conference.c Port 2 (ring) stop transmitting to port 0 (Microsoft Sound Mapper - Input)
18:10:59.600 conference.c Port 3 (sip:bob at voip3gppsrv2) transmitting to port 0 (Microsoft Sound Mapper - Input)
18:10:59.616 conference.c Port 0 (Microsoft Sound Mapper - Input) transmitting to port 3 (sip:bob at voip3gppsrv2)
18:10:59.616 pjsua_app.c Media for call 2 is active
18:10:59.616 inv00E2808C Sending Response msg 200/INVITE/cseq=6884 (tdta00E2D650)
18:10:59.616 dlg00E2808C Sending Response msg 200/INVITE/cseq=6884 (tdta00E2D650)
18:10:59.616 tsx00DED7CC Sending Response msg 200/INVITE/cseq=6884 (tdta00E2D650) in state Proceeding
18:10:59.616 pjsua_core.c TX 1630 bytes Response msg 200/INVITE/cseq=6884 (tdta00E2D650) to UDP 172.18.1.218:4060:
SIP/2.0 200 OK
Via: SIP/2.0/UDP 172.18.1.218:4060;received=172.18.1.218;branch=z9hG4bK67a2.48fe566.0
Via: SIP/2.0/UDP 172.18.1.218:6060;rport=6060;received=172.18.1.218;branch=z9hG4bK67a2.0e84f71.0
Via: SIP/2.0/UDP 172.18.1.218;branch=z9hG4bK67a2.628ecfe.0
Via: SIP/2.0/UDP 172.18.1.218:6060;branch=z9hG4bK67a2.fd84f71.0
Via: SIP/2.0/UDP 172.18.1.218:5065;branch=z9hG4bK67a2.e2eb58c.0
Via: SIP/2.0/UDP 172.18.1.218:6060;branch=z9hG4bK67a2.ed84f71.0
Via: SIP/2.0/UDP 172.18.1.218:4060;branch=z9hG4bK67a2.38fe566.0
Via: SIP/2.0/UDP 172.18.1.222:5060;rport=5060;branch=z9hG4bKPjde466559097f4883b24e1f88a13e463f
Record-Route: <sip:mt at pcscf.voip3gppsrv2:4060;lr>
Record-Route: <sip:mt at scscf.voip3gppsrv2:6060;lr>
Record-Route: <sip:mo at scscf.voip3gppsrv2:6060;lr>
Record-Route: <sip:172.18.1.218:5065;lr;ftag=15a28719e9eb4442a1d20d24ca897b37>
Record-Route: <sip:mo at scscf.voip3gppsrv2:6060;lr>
Record-Route: <sip:mo at pcscf.voip3gppsrv2:4060;lr>
Call-ID: af199956066e448d851bdb067a6ced46
From: <sip:bob at voip3gppsrv2>;tag=15a28719e9eb4442a1d20d24ca897b37
To: <sip:alice at voip3gppsrv2>;tag=d77e8361ab1d4cc5894928a47ca53aa6
CSeq: 6884 INVITE
Contact: <sip:alice at 172.18.2.74:5060>
Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS
Supported: replaces, 100rel, norefersub
Content-Type: application/sdp
Content-Length: 254
v=0
o=- 3449844659 3449844660 IN IP4 172.18.2.74
s=pjmedia
c=IN IP4 172.18.2.74
t=0 0
a=X-nat:0
m=audio 4004 RTP/AVP 103 101
a=rtcp:4005 IN IP4 172.18.2.74
a=rtpmap:103 speex/16000
a=sendrecv
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
--end msg--
18:10:59.631 pa_dev.c Player thread started
18:10:59.631 strm00E3D4FC Jitter buffer empty (prefetch=0)
18:10:59.631 strm00E3D4FC Start talksprut..
18:10:59.631 pa_dev.c Recorder thread started
18:10:59.631 ec00DEDF98 Prefetching..
18:10:59.678 ec00DEDF98 Prefetching..
18:10:59.678 ec00DEDF98 Prefetching..
18:10:59.678 tsx00DED7CC State changed from Proceeding to Completed, event=TX_MSG
18:10:59.678 dlg00E2808C Transaction tsx00DED7CC state changed to Completed
18:10:59.678 pjsua_app.c Call 2 state changed to CONNECTING
18:10:59.678 ec00DEDF98 Prefetching..
18:10:59.694 sip_endpoint.c Processing incoming message: Request msg ACK/cseq=6884 (rdata00DE754C)
18:10:59.694 pjsua_core.c RX 770 bytes Request msg ACK/cseq=6884 (rdata00DE754C) from UDP 172.18.1.218:5065:
ACK sip:alice at 172.18.2.74:5060 SIP/2.0
Via: SIP/2.0/UDP 172.18.1.218:5065;branch=z9hG4bK67a2.e2eb58c.2
Via: SIP/2.0/UDP 172.18.1.218:6060;branch=0
Via: SIP/2.0/UDP 172.18.1.218:4060;branch=0
Via: SIP/2.0/UDP 172.18.1.222:5060;rport=5060;branch=z9hG4bKPj489a067215e44ca0a0034154e8ef0fef
Max-Forwards: 14
From: sip:bob at voip3gppsrv2;tag=15a28719e9eb4442a1d20d24ca897b37
To: sip:alice at voip3gppsrv2;tag=d77e8361ab1d4cc5894928a47ca53aa6
Call-ID: af199956066e448d851bdb067a6ced46
CSeq: 6884 ACK
Route: <sip:172.18.1.218:5065;lr;ftag=15a28719e9eb4442a1d20d24ca897b37>
Route: <sip:mo at scscf.voip3gppsrv2:6060;lr>
Route: <sip:mt at scscf.voip3gppsrv2:6060;lr>
Route: <sip:mt at pcscf.voip3gppsrv2:4060;lr>
Content-Length: 0
P-Asserted-Identity: <sip:bob at voip3gppsrv2>
 
--end msg--
18:10:59.725 ec00DEDF98 Prefetching..
18:10:59.725 ec00DEDF98 Prefetching..
18:10:59.725 strm00E3D4FC RTP status: badpt=0, badssrc=0, dup=0, outorder=0, probation=-1, restart=0
18:10:59.725 dlg00E2808C Received Request msg ACK/cseq=6884 (rdata00DE754C)
18:10:59.725 tsx00DED7CC Request to terminate transaction
18:10:59.725 tsx00DED7CC State changed from Completed to Terminated, event=USER
18:10:59.725 dlg00E2808C Transaction tsx00DED7CC state changed to Terminated
18:10:59.725 pjsua_app.c Call 2 state changed to CONFIRMED
18:10:59.725 tsx00DED7CC Timeout timer event
18:10:59.725 tsx00DED7CC State changed from Terminated to Destroyed, event=TIMER
18:10:59.725 tdta00E2D650 Destroying txdata Response msg 200/INVITE/cseq=6884 (tdta00E2D650)
18:10:59.725 tsx00DED7CC Transaction destroyed!
18:10:59.725 strm00E3D4FC jb updated(2), prefetch=1, size=2
18:10:59.725 ec00DEDF98 Latency bufferring complete
18:10:59.741 strm00E3D4FC PUT prefetch_cnt=1/1
18:11:00.241 strm00E3D4FC VAD re-enabled
18:11:00.725 strm00E3D4FC Starting silence
18:11:00.772 strm00E3D4FC Jitter buffer empty (prefetch=1)
18:11:00.803 strm00E3D4FC PUT prefetch_cnt=4/1
18:11:00.928 strm00E3D4FC Start talksprut..
18:11:00.944 strm00E3D4FC Starting silence
18:11:00.991 strm00E3D4FC Jitter buffer empty (prefetch=1)
18:11:00.991 strm00E3D4FC PUT prefetch_cnt=2/1
18:11:01.194 strm00E3D4FC Jitter buffer empty (prefetch=1)
18:11:01.303 strm00E3D4FC Start talksprut..
18:11:01.475 strm00E3D4FC Starting silence
18:11:01.569 strm00E3D4FC PUT prefetch_cnt=21/1
18:11:01.600 strm00E3D4FC Jitter buffer empty (prefetch=1)
18:11:01.866 strm00E3D4FC Start talksprut..
18:11:01.882 strm00E3D4FC Starting silence
18:11:01.991 strm00E3D4FC PUT prefetch_cnt=21/1
18:11:02.022 strm00E3D4FC Jitter buffer empty (prefetch=1)
18:11:02.100 strm00E3D4FC PUT prefetch_cnt=5/1
18:11:02.116 strm00E3D4FC Start talksprut..
18:11:02.132 strm00E3D4FC Starting silence
18:11:02.522 strm00E3D4FC Jitter buffer empty (prefetch=1)
18:11:02.522 strm00E3D4FC Start talksprut..
18:11:02.553 strm00E3D4FC Starting silence
18:11:02.600 strm00E3D4FC PUT prefetch_cnt=5/1
18:11:02.647 strm00E3D4FC Jitter buffer empty (prefetch=1)
18:11:02.678 strm00E3D4FC PUT prefetch_cnt=3/1
18:11:02.710 strm00E3D4FC Jitter buffer empty (prefetch=1)
18:11:02.710 strm00E3D4FC PUT prefetch_cnt=2/1
18:11:02.741 strm00E3D4FC Jitter buffer empty (prefetch=1)
18:11:02.757 strm00E3D4FC PUT prefetch_cnt=2/1
18:11:02.788 strm00E3D4FC Jitter buffer empty (prefetch=1)
18:11:02.803 strm00E3D4FC PUT prefetch_cnt=2/1
18:11:02.835 strm00E3D4FC Jitter buffer empty (prefetch=1)
18:11:02.835 strm00E3D4FC PUT prefetch_cnt=2/1
18:11:02.913 strm00E3D4FC Jitter buffer empty (prefetch=1)
18:11:02.944 strm00E3D4FC Start talksprut..
18:11:02.975 strm00E3D4FC Starting silence
18:11:02.991 strm00E3D4FC PUT prefetch_cnt=6/1
18:11:03.022 strm00E3D4FC Jitter buffer empty (prefetch=1)
18:11:03.038 strm00E3D4FC PUT prefetch_cnt=2/1
18:11:03.053 strm00E3D4FC Start talksprut..
18:11:03.069 strm00E3D4FC Jitter buffer empty (prefetch=1)
18:11:03.085 strm00E3D4FC Starting silence
18:11:03.100 strm00E3D4FC PUT prefetch_cnt=3/1
18:11:03.132 strm00E3D4FC Jitter buffer empty (prefetch=1)
18:11:03.163 strm00E3D4FC PUT prefetch_cnt=3/1
18:11:03.210 strm00E3D4FC Jitter buffer empty (prefetch=1)
18:11:03.210 strm00E3D4FC Start talksprut..
18:11:03.225 strm00E3D4FC Starting silence
18:11:03.600 strm00E3D4FC PUT prefetch_cnt=21/1
18:11:03.632 strm00E3D4FC Jitter buffer empty (prefetch=1)
18:11:03.632 strm00E3D4FC Start talksprut..
18:11:03.647 strm00E3D4FC Starting silence
18:11:04.022 strm00E3D4FC PUT prefetch_cnt=21/1
18:11:04.054 strm00E3D4FC Start talksprut..
18:11:04.069 strm00E3D4FC Starting silence
18:11:04.085 strm00E3D4FC Jitter buffer empty (prefetch=1)
18:11:04.100 strm00E3D4FC PUT prefetch_cnt=2/1
18:11:04.132 strm00E3D4FC Jitter buffer empty (prefetch=1)
18:11:04.132 strm00E3D4FC PUT prefetch_cnt=2/1
18:11:04.163 strm00E3D4FC Jitter buffer empty (prefetch=1)
18:11:04.194 strm00E3D4FC PUT prefetch_cnt=3/1
18:11:04.272 strm00E3D4FC Start talksprut..
18:11:04.444 strm00E3D4FC Starting silence
18:11:04.491 strm00E3D4FC Jitter buffer empty (prefetch=1)
18:11:04.600 strm00E3D4FC PUT prefetch_cnt=7/1
18:11:04.850 strm00E3D4FC Start talksprut..
18:11:04.866 strm00E3D4FC Starting silence
18:11:04.882 strm00E3D4FC Jitter buffer empty (prefetch=1)
18:11:05.226 strm00E3D4FC PUT prefetch_cnt=18/1
18:11:05.272 strm00E3D4FC Start talksprut..
18:11:05.288 strm00E3D4FC Starting silence
18:11:05.491 strm00E3D4FC Jitter buffer empty (prefetch=1)
18:11:05.601 strm00E3D4FC PUT prefetch_cnt=7/1
18:11:05.663 strm00E3D4FC Start talksprut..
18:11:05.694 strm00E3D4FC Jitter buffer empty (prefetch=1)
18:11:05.694 strm00E3D4FC Starting silence
18:11:05.694 strm00E3D4FC PUT prefetch_cnt=2/1
18:11:05.882 strm00E3D4FC Jitter buffer empty (prefetch=1)
18:11:06.022 strm00E3D4FC Start talksprut..
18:11:06.054 strm00E3D4FC Starting silence
18:11:06.147 strm00E3D4FC PUT prefetch_cnt=14/1
18:11:06.163 strm00E3D4FC Start talksprut..
18:11:06.366 strm00E3D4FC Starting silence
18:11:06.538 pjsua_acc.c Sending 2 bytes keep-alive packet for acc 1 to 172.18.1.218:4060
18:11:06.538 tdta00E32F98 Destroying txdata raw
18:11:06.772 strm00E3D4FC Start talksprut..
18:11:06.788 strm00E3D4FC Starting silence
18:11:06.929 strm00E3D4FC Jitter buffer empty (prefetch=1)
18:11:07.194 strm00E3D4FC Start talksprut..
18:11:07.210 strm00E3D4FC Starting silence
18:11:07.241 strm00E3D4FC PUT prefetch_cnt=17/1
18:11:07.366 strm00E3D4FC Jitter buffer empty (prefetch=1)
18:11:07.523 strm00E3D4FC PUT prefetch_cnt=9/1
18:11:07.601 strm00E3D4FC Start talksprut..
18:11:07.632 strm00E3D4FC Starting silence
18:11:07.788 strm00E3D4FC Start talksprut..
18:11:07.882 strm00E3D4FC Jitter buffer empty (prefetch=1)
18:11:08.101 strm00E3D4FC Starting silence
18:11:08.273 strm00E3D4FC PUT prefetch_cnt=21/1
18:11:08.507 strm00E3D4FC Start talksprut..
18:11:08.523 strm00E3D4FC Starting silence
18:11:08.710 strm00E3D4FC Jitter buffer empty (prefetch=1)
18:11:08.929 strm00E3D4FC Start talksprut..
18:11:08.944 strm00E3D4FC Starting silence
18:11:09.101 strm00E3D4FC PUT prefetch_cnt=21/1
18:11:09.132 strm00E3D4FC Jitter buffer empty (prefetch=1)
18:11:09.351 strm00E3D4FC Start talksprut..
18:11:09.366 strm00E3D4FC Starting silence
18:11:09.523 strm00E3D4FC PUT prefetch_cnt=21/1
18:11:09.554 strm00E3D4FC Jitter buffer empty (prefetch=1)
18:11:09.773 strm00E3D4FC Start talksprut..
18:11:09.788 strm00E3D4FC Starting silence
18:11:09.945 strm00E3D4FC PUT prefetch_cnt=21/1
18:11:09.960 strm00E3D4FC Jitter buffer empty (prefetch=1)
18:11:10.195 strm00E3D4FC Start talksprut..
18:11:10.210 strm00E3D4FC Starting silence
18:11:10.351 strm00E3D4FC Start talksprut..
18:11:10.366 strm00E3D4FC PUT prefetch_cnt=21/1
18:11:10.382 strm00E3D4FC Jitter buffer empty (prefetch=1)
18:11:10.445 strm00E3D4FC PUT prefetch_cnt=4/1
18:11:10.460 strm00E3D4FC Jitter buffer empty (prefetch=1)
18:11:10.523 strm00E3D4FC PUT prefetch_cnt=4/1
18:11:10.554 strm00E3D4FC Jitter buffer empty (prefetch=1)
18:11:10.648 strm00E3D4FC Starting silence
18:11:10.945 strm00E3D4FC PUT prefetch_cnt=21/1
18:11:10.960 strm00E3D4FC Jitter buffer empty (prefetch=1)
18:11:11.054 strm00E3D4FC Start talksprut..
18:11:11.070 strm00E3D4FC Starting silence
18:11:11.367 strm00E3D4FC PUT prefetch_cnt=21/1
18:11:11.382 strm00E3D4FC Jitter buffer empty (prefetch=1)
18:11:11.460 strm00E3D4FC Start talksprut..
18:11:11.492 strm00E3D4FC Starting silence
18:11:11.773 strm00E3D4FC PUT prefetch_cnt=21/1
18:11:11.804 strm00E3D4FC Jitter buffer empty (prefetch=1)
18:11:11.867 strm00E3D4FC PUT prefetch_cnt=4/1
18:11:11.882 strm00E3D4FC Start talksprut..
18:11:11.913 strm00E3D4FC Jitter buffer empty (prefetch=1)
18:11:11.913 strm00E3D4FC Starting silence
18:11:11.945 strm00E3D4FC PUT prefetch_cnt=3/1
18:11:11.960 strm00E3D4FC Jitter buffer empty (prefetch=1)
18:11:12.304 strm00E3D4FC Start talksprut..
18:11:12.320 strm00E3D4FC Starting silence
18:11:12.367 strm00E3D4FC PUT prefetch_cnt=21/1
18:11:12.382 strm00E3D4FC Jitter buffer empty (prefetch=1)
18:11:12.445 strm00E3D4FC PUT prefetch_cnt=4/1
18:11:12.460 strm00E3D4FC Jitter buffer empty (prefetch=1)
18:11:12.601 strm00E3D4FC PUT prefetch_cnt=8/1
18:11:12.726 strm00E3D4FC Start talksprut..
18:11:12.742 strm00E3D4FC Starting silence
18:11:13.148 strm00E3D4FC Start talksprut..
18:11:13.164 strm00E3D4FC Starting silence
18:11:13.320 strm00E3D4FC Jitter buffer empty (prefetch=1)
18:11:13.382 strm00E3D4FC PUT prefetch_cnt=4/1
18:11:13.414 strm00E3D4FC Jitter buffer empty (prefetch=1)
18:11:13.554 strm00E3D4FC Start talksprut..
18:11:13.570 strm00E3D4FC Starting silence
18:11:13.695 strm00E3D4FC PUT prefetch_cnt=16/1
18:11:13.882 strm00E3D4FC Jitter buffer empty (prefetch=1)
18:11:13.960 strm00E3D4FC Start talksprut..
18:11:13.976 strm00E3D4FC PUT prefetch_cnt=6/1
18:11:13.992 strm00E3D4FC Starting silence
18:11:14.304 strm00E3D4FC Jitter buffer empty (prefetch=1)
18:11:14.382 strm00E3D4FC Start talksprut..
18:11:14.414 strm00E3D4FC Starting silence
18:11:14.539 strm00E3D4FC PUT prefetch_cnt=13/1
18:11:14.804 strm00E3D4FC Start talksprut..
18:11:14.820 strm00E3D4FC Starting silence
18:11:14.882 strm00E3D4FC Jitter buffer empty (prefetch=1)
18:11:14.898 strm00E3D4FC PUT prefetch_cnt=2/1
18:11:15.070 strm00E3D4FC Start talksprut..
18:11:15.086 strm00E3D4FC Starting silence
18:11:15.289 strm00E3D4FC Jitter buffer empty (prefetch=1)
18:11:15.289 strm00E3D4FC Start talksprut..
18:11:15.304 strm00E3D4FC Starting silence
18:11:15.445 strm00E3D4FC PUT prefetch_cnt=9/1
18:11:15.461 strm00E3D4FC Jitter buffer empty (prefetch=1)
18:11:15.539 strm00E3D4FC PUT prefetch_cnt=5/1
18:11:15.570 strm00E3D4FC Jitter buffer empty (prefetch=1)
18:11:15.711 strm00E3D4FC Start talksprut..
18:11:15.726 strm00E3D4FC Starting silence
18:11:15.773 strm00E3D4FC PUT prefetch_cnt=12/1
18:11:15.804 strm00E3D4FC Jitter buffer empty (prefetch=1)
18:11:15.914 strm00E3D4FC PUT prefetch_cnt=7/1
18:11:16.132 strm00E3D4FC Start talksprut..
18:11:16.148 strm00E3D4FC Starting silence
18:11:16.179 strm00E3D4FC Jitter buffer empty (prefetch=1)
18:11:16.195 strm00E3D4FC PUT prefetch_cnt=2/1
18:11:16.242 strm00E3D4FC Jitter buffer empty (prefetch=1)
18:11:16.461 strm00E3D4FC PUT prefetch_cnt=12/1
18:11:16.554 strm00E3D4FC Start talksprut..
18:11:16.570 strm00E3D4FC Starting silence
18:11:16.726 strm00E3D4FC Start talksprut..
18:11:16.742 strm00E3D4FC Starting silence
18:11:17.148 strm00E3D4FC Start talksprut..
18:11:17.164 strm00E3D4FC Jitter buffer empty (prefetch=1)
18:11:17.164 strm00E3D4FC Starting silence
18:11:17.367 strm00E3D4FC Start talksprut..
18:11:17.414 strm00E3D4FC Starting silence
18:11:17.461 strm00E3D4FC Start talksprut..
18:11:17.492 strm00E3D4FC Starting silence
18:11:17.508 strm00E3D4FC Start talksprut..
18:11:17.523 strm00E3D4FC Starting silence
18:11:17.554 strm00E3D4FC PUT prefetch_cnt=21/1
18:11:17.664 strm00E3D4FC Start talksprut..
18:11:17.679 strm00E3D4FC Starting silence
18:11:17.711 strm00E3D4FC Start talksprut..
18:11:17.742 strm00E3D4FC Starting silence
18:11:17.820 strm00E3D4FC Start talksprut..
18:11:17.929 strm00E3D4FC Jitter buffer empty (prefetch=1)
18:11:18.179 strm00E3D4FC Starting silence
18:11:18.226 strm00E3D4FC Start talksprut..
18:11:18.258 strm00E3D4FC PUT prefetch_cnt=18/1
18:11:18.679 strm00E3D4FC Jitter buffer empty (prefetch=1)
18:11:18.726 strm00E3D4FC Starting silence
18:11:18.851 strm00E3D4FC PUT prefetch_cnt=10/1
18:11:18.867 strm00E3D4FC Start talksprut..
18:11:18.883 strm00E3D4FC Starting silence
18:11:18.930 strm00E3D4FC Start talksprut..
18:11:19.180 strm00E3D4FC Jitter buffer empty (prefetch=1)
18:11:19.211 strm00E3D4FC Starting silence
18:11:19.258 tsx00DEA95C Timeout timer event
18:11:19.258 tsx00DEA95C State changed from Completed to Terminated, event=TIMER
18:11:19.258 dlg00DFC08C Transaction tsx00DEA95C state changed to Terminated
18:11:19.258 dlg00DFC08C Dialog destroyed
18:11:19.258 tsx00DEA95C Timeout timer event
18:11:19.258 tsx00DEA95C State changed from Terminated to Destroyed, event=TIMER
18:11:19.258 tdta00E37898 Destroying txdata Response msg 200/BYE/cseq=21791 (tdta00E37898)
18:11:19.258 tsx00DEA95C Transaction destroyed!
18:11:19.273 strm00E3D4FC Start talksprut..
18:11:19.305 strm00E3D4FC Starting silence
18:11:19.398 strm00E3D4FC PUT prefetch_cnt=12/1
18:11:19.430 strm00E3D4FC Jitter buffer empty (prefetch=1)
18:11:19.430 strm00E3D4FC Start talksprut..
18:11:19.445 strm00E3D4FC Starting silence
18:11:19.476 strm00E3D4FC PUT prefetch_cnt=4/1
18:11:19.508 strm00E3D4FC Jitter buffer empty (prefetch=1)
18:11:19.523 strm00E3D4FC PUT prefetch_cnt=2/1
18:11:19.523 strm00E3D4FC Start talksprut..
18:11:19.539 strm00E3D4FC Starting silence
18:11:19.586 strm00E3D4FC Start talksprut..
18:11:19.601 strm00E3D4FC Starting silence
18:11:19.664 strm00E3D4FC Start talksprut..
18:11:19.711 strm00E3D4FC Starting silence
18:11:19.726 strm00E3D4FC Start talksprut..
18:11:19.742 strm00E3D4FC Starting silence
18:11:19.789 strm00E3D4FC Start talksprut..
18:11:19.805 strm00E3D4FC Starting silence
18:11:19.805 sip_endpoint.c Processing incoming message: Request msg INVITE/cseq=6894 (rdata00DE754C)
18:11:19.805 pjsua_core.c RX 1215 bytes Request msg INVITE/cseq=6894 (rdata00DE754C) from UDP 172.18.1.218:4060:
INVITE sip:alice at 172.18.2.74:5060 SIP/2.0
Record-Route: <sip:mt at scscf.voip3gppsrv2:6060;lr>
Max-Forwards: 8
Via: SIP/2.0/UDP 172.18.1.218:4060;branch=z9hG4bK6592.1b4cd5b5.0
Via: SIP/2.0/UDP 172.18.1.218:6060;rport=6060;branch=z9hG4bK6592.dde817e2.0
Via: SIP/2.0/UDP 172.18.1.218;branch=z9hG4bK6592.91140fa5.0
Via: SIP/2.0/UDP 172.18.1.218:5065;branch=z9hG4bK6592.39f44924.0
To: sip:alice at voip3gppsrv2;tag=d77e8361ab1d4cc5894928a47ca53aa6
From: sip:bob at voip3gppsrv2;tag=15a28719e9eb4442a1d20d24ca897b37
CSeq: 6894 INVITE
Call-ID: af199956066e448d851bdb067a6ced46
Content-Length: 456
User-Agent: OpenSIPS (1.4.0-notls (i386/linux))
Contact: <sip:bob at 172.18.1.78:5060>
Content-Type: application/sdp
P-Called-Party-ID: <sip:alice at voip3gppsrv2>
v=0
o=- 3449844671 3449844671 IN IP4 172.18.1.78
s=pjmedia
c=IN IP4 172.18.1.78
t=0 0
a=X-nat:0
m=audio 4004 RTP/AVP 103 102 104 117 3 0 8 9 101
a=rtcp:4005 IN IP4 172.18.1.78
a=rtpmap:103 speex/16000
a=rtpmap:102 speex/8000
a=rtpmap:104 speex/32000
a=rtpmap:117 iLBC/8000
a=fmtp:117 mode=30
a=rtpmap:3 GSM/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:9 G722/8000
a=sendrecv
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
--end msg--
18:11:19.836 strm00E3D4FC Jitter buffer empty (prefetch=1)
18:11:19.836 strm00E3D4FC PUT prefetch_cnt=1/1
18:11:19.851 dlg00E2808C Received Request msg INVITE/cseq=6894 (rdata00DE754C)
18:11:19.851 tsx00DED7CC Transaction created for Request msg INVITE/cseq=6894 (rdata00DE754C)
18:11:19.851 tsx00DED7CC Incoming Request msg INVITE/cseq=6894 (rdata00DE754C) in state Null
18:11:19.851 tsx00DED7CC State changed from Null to Trying, event=RX_MSG
18:11:19.851 dlg00E2808C Transaction tsx00DED7CC state changed to Trying
18:11:19.851 inv00E2808C Got SDP offer in Request msg INVITE/cseq=6894 (rdata00DE754C)
18:11:19.851 pjsua_call.c Call 2: received updated media offer
18:11:19.851 endpoint Response msg 200/INVITE/cseq=6894 (tdta00E19028) created
18:11:19.851 inv00E2808C SDP negotiation done, status=0
18:11:19.851 pjsua_call.c Call 2: remote NAT type is 0 (Unknown)
18:11:19.867 pjsua_media.c Media session for call 2 is destroyed
18:11:19.867 strm00E3197C VAD temporarily disabled
18:11:19.867 rtp.c pjmedia_rtp_session_init: ses=00E32B50, default_pt=103, ssrc=0x3a284172
18:11:19.867 rtp.c pjmedia_rtp_session_init: ses=00E32FC4, default_pt=103, ssrc=0x3a284172
18:11:19.867 stream.c Stream strm00E3197C created
18:11:19.867 strm00E3197C Encoder stream started
18:11:19.867 strm00E3197C Decoder stream started
18:11:19.867 pjsua_media.c Media updates, stream #0: speex (sendrecv)
18:11:19.867 conference.c Port 3 (sip:bob at voip3gppsrv2) transmitting to port 0 (Microsoft Sound Mapper - Input)
18:11:19.867 strm00E3197C Jitter buffer empty (prefetch=0)
18:11:19.867 strm00E3197C Start talksprut..
18:11:19.867 conference.c Port 0 (Microsoft Sound Mapper - Input) transmitting to port 3 (sip:bob at voip3gppsrv2)
18:11:19.867 pjsua_app.c Media for call 2 is active
18:11:19.867 inv00E2808C Sending Response msg 200/INVITE/cseq=6894 (tdta00E19028)
18:11:19.867 dlg00E2808C Sending Response msg 200/INVITE/cseq=6894 (tdta00E19028)
18:11:19.867 tsx00DED7CC Sending Response msg 200/INVITE/cseq=6894 (tdta00E19028) in state Trying
18:11:19.867 sip_resolve.c Target '172.18.1.218:4060' type=UDP resolved to '172.18.1.218:4060' type=UDP (UDP transport)
18:11:19.867 pjsua_core.c TX 1037 bytes Response msg 200/INVITE/cseq=6894 (tdta00E19028) to UDP 172.18.1.218:4060:
SIP/2.0 200 OK
Via: SIP/2.0/UDP 172.18.1.218:4060;received=172.18.1.218;branch=z9hG4bK6592.1b4cd5b5.0
Via: SIP/2.0/UDP 172.18.1.218:6060;rport=6060;branch=z9hG4bK6592.dde817e2.0
Via: SIP/2.0/UDP 172.18.1.218;branch=z9hG4bK6592.91140fa5.0
Via: SIP/2.0/UDP 172.18.1.218:5065;branch=z9hG4bK6592.39f44924.0
Record-Route: <sip:mt at scscf.voip3gppsrv2:6060;lr>
Call-ID: af199956066e448d851bdb067a6ced46
From: <sip:bob at voip3gppsrv2>;tag=15a28719e9eb4442a1d20d24ca897b37
To: <sip:alice at voip3gppsrv2>;tag=d77e8361ab1d4cc5894928a47ca53aa6
CSeq: 6894 INVITE
Contact: <sip:alice at 172.18.2.74:5060>
Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS
Supported: replaces, 100rel, norefersub
Content-Type: application/sdp
Content-Length: 254
v=0
o=- 3449844679 3449844661 IN IP4 172.18.2.74
s=pjmedia
c=IN IP4 172.18.2.74
t=0 0
a=X-nat:0
m=audio 4004 RTP/AVP 103 101
a=rtcp:4005 IN IP4 172.18.2.74
a=rtpmap:103 speex/16000
a=sendrecv
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
--end msg--
18:11:19.914 strm00E3197C RTP status: badpt=0, badssrc=0, dup=0, outorder=0, probation=-1, restart=0
18:11:19.930 Master/sound 345 samples reduced, buf_cnt=602
18:11:19.930 Master/sound Buffer size adjusted from 947 to 602 (eff_cnt=341)
18:11:19.930 tsx00DED7CC State changed from Trying to Completed, event=TX_MSG
18:11:19.930 dlg00E2808C Transaction tsx00DED7CC state changed to Completed
18:11:19.930 sip_endpoint.c Processing incoming message: Request msg ACK/cseq=6894 (rdata00DE754C)
18:11:19.930 pjsua_core.c RX 498 bytes Request msg ACK/cseq=6894 (rdata00DE754C) from UDP 172.18.1.218:6060:
ACK sip:alice at 172.18.2.74:5060 SIP/2.0
Max-Forwards: 9
Via: SIP/2.0/UDP 172.18.1.218:6060;branch=0
Via: SIP/2.0/UDP 172.18.1.218;branch=0
Via: SIP/2.0/UDP 172.18.1.218:5065;branch=z9hG4bK6592.39f44924.0
From: sip:bob at voip3gppsrv2;tag=15a28719e9eb4442a1d20d24ca897b37
Call-ID: af199956066e448d851bdb067a6ced46
To: <sip:alice at voip3gppsrv2>;tag=d77e8361ab1d4cc5894928a47ca53aa6
CSeq: 6894 ACK
User-Agent: OpenSIPS (1.4.0-notls (i386/linux))
Content-Length: 0
P-hint: I-CSCF rr-enforced
 
--end msg--
18:11:19.945 strm00E3197C Jitter buffer empty (prefetch=0)
18:11:19.961 dlg00E2808C Received Request msg ACK/cseq=6894 (rdata00DE754C)
18:11:19.961 tsx00DED7CC Request to terminate transaction
18:11:19.961 tsx00DED7CC State changed from Completed to Terminated, event=USER
18:11:19.961 dlg00E2808C Transaction tsx00DED7CC state changed to Terminated
18:11:19.961 tsx00DED7CC Timeout timer event
18:11:19.961 tsx00DED7CC State changed from Terminated to Destroyed, event=TIMER
18:11:19.961 tdta00E19028 Destroying txdata Response msg 200/INVITE/cseq=6894 (tdta00E19028)
18:11:19.961 tsx00DED7CC Transaction destroyed!
18:11:19.961 udp00DF2F58 Remote RTCP address switched to 172.18.1.222:4005
18:11:19.961 udp00DF2F58 Remote RTCP address switched to 172.18.1.78:4005
18:11:19.961 strm00E3197C RTP status: badpt=0, badssrc=0, dup=0, outorder=-1, probation=0, restart=0
18:11:19.961 strm00E3197C jb updated(2), prefetch=1, size=1
18:11:19.976 strm00E3197C RTP status: badpt=0, badssrc=0, dup=0, outorder=0, probation=-1, restart=-1
18:11:19.976 strm00E3197C Jitter buffer reset
18:11:19.992 strm00E3197C Jitter buffer empty (prefetch=1)
18:11:20.023 ec00DEDF98 Underflow, buf_cnt=0, will generate 1 frame
18:11:20.039 ec00DEDF98 Underflow, buf_cnt=0, will generate 1 frame
18:11:20.055 ec00DEDF98 Underflow, buf_cnt=0, will generate 1 frame
18:11:20.070 ec00DEDF98 Underflow, buf_cnt=0, will generate 1 frame
18:11:20.101 ec00DEDF98 Underflow, buf_cnt=0, will generate 1 frame
18:11:20.101 Master/sound 527 samples reduced, buf_cnt=1355
18:11:20.117 ec00DEDF98 Underflow, buf_cnt=0, will generate 1 frame
18:11:20.117 Master/sound 182 samples reduced, buf_cnt=1493
18:11:20.133 ec00DEDF98 Underflow, buf_cnt=0, will generate 1 frame
18:11:20.133 Master/sound 370 samples reduced, buf_cnt=1443
18:11:20.164 ec00DEDF98 Underflow, buf_cnt=0, will generate 1 frame
18:11:20.164 Master/sound 478 samples reduced, buf_cnt=1285
18:11:37.728 Master/sound 350 samples reduced, buf_cnt=1289
18:11:37.743 ec00DEDF98 Underflow, buf_cnt=0, will generate 1 frame
18:11:37.743 Master/sound 9 samples reduced, buf_cnt=1600
18:11:37.759 ec00DEDF98 Underflow, buf_cnt=0, will generate 1 frame
18:11:37.759 Master/sound 358 samples reduced, buf_cnt=1562
18:11:37.774 ec00DEDF98 Underflow, buf_cnt=0, will generate 1 frame
18:11:37.774 Master/sound 377 samples reduced, buf_cnt=1505
18:11:37.806 ec00DEDF98 Underflow, buf_cnt=0, will generate 1 frame
18:11:37.806 Master/sound 376 samples reduced, buf_cnt=1449
18:11:37.806 endpoint Request msg BYE/cseq=13714 (tdta00E19018) created.
18:11:37.806 inv00E2808C Sending Request msg BYE/cseq=13714 (tdta00E19018)
18:11:37.806 dlg00E2808C Sending Request msg BYE/cseq=13714 (tdta00E19018)
18:11:37.806 tsx00DED7CC Transaction created for Request msg BYE/cseq=13713 (tdta00E19018)
18:11:37.806 tsx00DED7CC Sending Request msg BYE/cseq=13713 (tdta00E19018) in state Null
18:11:37.806 sip_resolve.c DNS resolver not available, target 'pcscf.voip3gppsrv2:4060' type=Unspecified will be resolved with gethostbyname()
18:11:37.806 sip_resolve.c Target 'pcscf.voip3gppsrv2:4060' type=Unspecified resolved to '172.18.1.218:4060' type=UDP (UDP transport)
18:11:37.821 ec00DEDF98 Underflow, buf_cnt=0, will generate 1 frame
18:11:37.821 Master/sound 371 samples reduced, buf_cnt=1398
18:11:37.837 ec00DEDF98 Underflow, buf_cnt=0, will generate 1 frame
18:11:37.837 Master/sound 186 samples reduced, buf_cnt=1532
18:11:37.853 pjsua_core.c TX 815 bytes Request msg BYE/cseq=13713 (tdta00E19018) to UDP 172.18.1.218:4060:
BYE sip:bob at 172.18.1.78:5060 SIP/2.0
Via: SIP/2.0/UDP 172.18.2.74:5060;rport;branch=z9hG4bKPje3a80a89760443039b093984823ae0bc
Max-Forwards: 70
From: <sip:alice at voip3gppsrv2>;tag=d77e8361ab1d4cc5894928a47ca53aa6
To: <sip:bob at voip3gppsrv2>;tag=15a28719e9eb4442a1d20d24ca897b37
Call-ID: af199956066e448d851bdb067a6ced46
CSeq: 13713 BYE
Route: <sip:mt at pcscf.voip3gppsrv2:4060;lr>
Route: <sip:mt at scscf.voip3gppsrv2:6060;lr>
Route: <sip:mo at scscf.voip3gppsrv2:6060;lr>
Route: <sip:172.18.1.218:5065;lr;ftag=15a28719e9eb4442a1d20d24ca897b37>
Route: <sip:mo at scscf.voip3gppsrv2:6060;lr>
Route: <sip:mo at pcscf.voip3gppsrv2:4060;lr>
Authorization: Digest username="alice at voip3gppsrv2", realm="voip3gppsrv2", nonce="", uri="sip:bob at 172.18.1.78:5060", response=""
User-Agent: PJSUA v1.1/win32
Content-Length: 0
 
--end msg--
18:11:37.884 ec00DEDF98 Underflow, buf_cnt=0, will generate 1 frame
18:11:37.884 Master/sound 370 samples reduced, buf_cnt=1482
18:11:37.884 ec00DEDF98 Underflow, buf_cnt=0, will generate 1 frame
18:11:37.884 Master/sound 210 samples reduced, buf_cnt=1592
18:11:37.884 tsx00DED7CC State changed from Null to Calling, event=TX_MSG
18:11:37.884 dlg00E2808C Transaction tsx00DED7CC state changed to Calling
18:11:37.899 sip_endpoint.c Processing incoming message: Response msg 200/BYE/cseq=13713 (rdata00DE754C)
18:11:37.899 pjsua_core.c RX 379 bytes Response msg 200/BYE/cseq=13713 (rdata00DE754C) from UDP 172.18.1.218:4060:
SIP/2.0 200 OK From AS
Via: SIP/2.0/UDP 172.18.2.74:5060;rport=5060;branch=z9hG4bKPje3a80a89760443039b093984823ae0bc
From: <sip:alice at voip3gppsrv2>;tag=d77e8361ab1d4cc5894928a47ca53aa6
To: <sip:bob at voip3gppsrv2>;tag=15a28719e9eb4442a1d20d24ca897b37
Call-ID: af199956066e448d851bdb067a6ced46
CSeq: 13713 BYE
Server: OpenSIPS (1.4.0-notls (i386/linux))
Content-Length: 0
 
--end msg--
18:11:37.915 ec00DEDF98 Underflow, buf_cnt=0, will generate 1 frame
18:11:37.915 Master/sound 534 samples reduced, buf_cnt=1378
18:11:37.915 tsx00DED7CC Incoming Response msg 200/BYE/cseq=13713 (rdata00DE754C) in state Calling
18:11:37.915 tsx00DED7CC State changed from Calling to Completed, event=RX_MSG
18:11:37.915 dlg00E2808C Received Response msg 200/BYE/cseq=13713 (rdata00DE754C)
18:11:37.915 dlg00E2808C Transaction tsx00DED7CC state changed to Completed
18:11:37.915 pjsua_app.c Call 2 is DISCONNECTED [reason=200 (Normal call clearing)]
18:11:37.915 pjsua_app.c Call 2 disconnected, dumping media stats..
18:11:37.915 pjsua_app.c 
[DISCONNCTD] To: <sip:bob at voip3gppsrv2>;tag=15a28719e9eb4442a1d20d24ca897b37
Call time: 00h:00m:38s, 1st res in 78 ms, conn in 203ms
SRTP status: Not active Crypto-suite: (null)
#0 speex @16KHz, sendrecv, peer=172.18.1.78:4004
RX pt=103, stat last update: never
total 4pkt 160B (320B +IP hdr) @avg=70bps/141bps
pkt loss=0 (0.0%), discrd=1 (25.0%), dup=0 (0.0%), reord=1 (25.0%)
(msec) min avg max last dev
loss period: 0.000 0.000 0.000 0.000 0.000
jitter : -0.001 0.000 0.000 0.000 0.000
TX pt=103, ptime=20ms, stat last update: never
total 7pkt 490B (770B +IP hdr) @avg 217bps/341bps
pkt loss=0 (0.0%), dup=0 (0.0%), reorder=0 (0.0%)
(msec) min avg max last dev 
loss period: 0.000 0.000 0.000 0.000 0.000
jitter : 0.000 0.000 0.000 0.000 0.000
RTT msec : 0.000 0.000 0.000 0.000 0.000
Underflow, buf_cnt=0, will generate 1 frame186 samples reduced, buf_cnt=1512 18:11:37.946 ec00DEDF98 Underflow, buf_cnt=0, will generate 1 frame
18:11:37.946 Master/sound 377 samples reduced, buf_cnt=1455
18:11:37.962 ec00DEDF98 Underflow, buf_cnt=0, will generate 1 frame
18:11:37.962 Master/sound 197 samples reduced, buf_cnt=1578
18:11:37.978 ec00DEDF98 Underflow, buf_cnt=0, will generate 1 frame
18:11:37.978 Master/sound 364 samples reduced, buf_cnt=1534
18:11:37.993 ec00DEDF98 Underflow, buf_cnt=0, will generate 1 frame
18:11:37.993 Master/sound 552 samples reduced, buf_cnt=1302
18:11:38.024 ec00DEDF98 Underflow, buf_cnt=0, will generate 1 frame
18:11:38.024 Master/sound 211 samples reduced, buf_cnt=1411


      Own a website.Get an unlimited package.Pay next to nothing.*Go to http://in.business.yahoo.com/
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.pjsip.org/pipermail/pjsip_lists.pjsip.org/attachments/20090427/2eba8698/attachment-0001.html>


More information about the pjsip mailing list