[pjsip] Accoustic echo cancelation

Alexandre Gonçalves alexandre at silvagoncalves.com
Tue Apr 12 09:56:48 EDT 2016


Here it is:

13:53:51.440 os_core_unix.c !pjlib 2.4 for POSIX initialized
13:53:51.448 sip_endpoint.c  .Creating endpoint instance...
13:53:51.450          pjlib  .select() I/O Queue created (0xbbabd8)
13:53:51.452 sip_endpoint.c  .Module "mod-msg-print" registered
13:53:51.453 sip_transport.  .Transport manager created.
13:53:51.455   pjsua_core.c  .PJSUA state changed: NULL --> CREATED
13:53:51.456 sip_endpoint.c  .Module "mod-pjsua-log" registered
13:53:51.458 sip_endpoint.c  .Module "mod-tsx-layer" registered
13:53:51.459 sip_endpoint.c  .Module "mod-stateful-util" registered
13:53:51.459 sip_endpoint.c  .Module "mod-ua" registered
13:53:51.461 sip_endpoint.c  .Module "mod-100rel" registered
13:53:51.461 sip_endpoint.c  .Module "mod-pjsua" registered
13:53:51.462 sip_endpoint.c  .Module "mod-invite" registered
13:53:51.687     alsa_dev.c  ..Added sound device default:CARD=Device
13:53:51.716     alsa_dev.c  ..Added sound device sysdefault:CARD=Device
13:53:51.725     alsa_dev.c  ..Added sound device front:CARD=Device,DEV=0
13:53:51.735     alsa_dev.c  ..Added sound device
surround40:CARD=Device,DEV=0
13:53:51.744     alsa_dev.c  ..Added sound device
surround41:CARD=Device,DEV=0
13:53:51.753     alsa_dev.c  ..Added sound device
surround50:CARD=Device,DEV=0
13:53:51.762     alsa_dev.c  ..Added sound device
surround51:CARD=Device,DEV=0
13:53:51.770     alsa_dev.c  ..Added sound device
surround71:CARD=Device,DEV=0
13:53:51.781     alsa_dev.c  ..Added sound device iec958:CARD=Device,DEV=0
13:53:51.789     alsa_dev.c  ..Added sound device default:CARD=ALSA
13:53:51.796     alsa_dev.c  ..Added sound device sysdefault:CARD=ALSA
13:53:51.797     alsa_dev.c  ..ALSA driver found 11 devices
13:53:51.798     alsa_dev.c  ..ALSA initialized
13:53:51.800          pjlib  ..select() I/O Queue created (0xbe58c4)
13:53:51.803   conference.c  ..Creating conference bridge with 254 ports
13:53:51.805   Master/sound  ..Using delay buffer with WSOLA.
13:53:51.848 sip_endpoint.c  .Module "mod-evsub" registered
13:53:51.849 sip_endpoint.c  .Module "mod-presence" registered
13:53:51.851        evsub.c  .Event pkg "presence" registered by
mod-presence
13:53:51.853 sip_endpoint.c  .Module "mod-mwi" registered
13:53:51.854        evsub.c  .Event pkg "message-summary" registered by
mod-mwi
13:53:51.855 sip_endpoint.c  .Module "mod-refer" registered
13:53:51.856        evsub.c  .Event pkg "refer" registered by mod-refer
13:53:51.856 sip_endpoint.c  .Module "mod-pjsua-pres" registered
13:53:51.857 sip_endpoint.c  .Module "mod-pjsua-im" registered
13:53:51.857 sip_endpoint.c  .Module "mod-pjsua-options" registered
13:53:51.858   pjsua_core.c  .1 SIP worker threads created
13:53:51.859   pjsua_core.c  .pjsua version 2.4 for
Linux-3.18.7/armv6l/glibc-2.13 initialized
13:53:51.860   pjsua_core.c  .PJSUA state changed: CREATED --> INIT
13:53:51.862   pjsua_core.c  SIP UDP socket reachable at 192.168.1.120:5060
13:53:51.864    udp0xbefc38  SIP UDP transport started, published address
is 192.168.1.120:5060
13:53:51.866   pjsua_core.c  PJSUA state changed: INIT --> STARTING
13:53:51.867 sip_endpoint.c  .Module "mod-unsolicited-mwi" registered
13:53:51.868   pjsua_core.c  .PJSUA state changed: STARTING --> RUNNING
13:53:51.868    pjsua_acc.c  Adding account: id=sip:511 at raspbx
13:53:51.869    pjsua_acc.c  .Account sip:511 at raspbx added with id 0
13:53:51.870    pjsua_acc.c  .Acc 0: setting registration..
13:53:51.871       endpoint  ..Request msg REGISTER/cseq=47840
(tdta0xbf3dc0) created.
13:53:51.873    tsx0xbf4e2c  ...Transaction created for Request msg
REGISTER/cseq=47841 (tdta0xbf3dc0)
13:53:51.874    tsx0xbf4e2c  ..Sending Request msg REGISTER/cseq=47841
(tdta0xbf3dc0) in state Null
13:53:51.874  sip_resolve.c  ...DNS resolver not available, target
'raspbx:0' type=Unspecified will be resolved with getaddrinfo()
13:53:51.881  sip_resolve.c  ...Target 'raspbx:0' type=Unspecified resolved
to '192.168.1.40:5060' type=UDP (UDP transport)
13:53:51.882   pjsua_core.c  ...TX 463 bytes Request msg
REGISTER/cseq=47841 (tdta0xbf3dc0) to UDP 192.168.1.40:5060:
REGISTER sip:raspbx SIP/2.0
Via: SIP/2.0/UDP 192.168.1.120:5060
;rport;branch=z9hG4bKPjEGkMscGiSvt0O.KLo9dxJ4s03V7-1Kmw
Max-Forwards: 70
From: <sip:511 at raspbx>;tag=s96E7GKkGb5ti9m603K6miDa9.i8Cow5
To: <sip:511 at raspbx>
Call-ID: 9V1ox-mHiBZCYvDoVuu6ZDlSGCo7h9p1
CSeq: 47841 REGISTER
Contact: <sip:511 at 192.168.1.120:5060;ob>
Expires: 300
Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, SUBSCRIBE, NOTIFY,
REFER, MESSAGE, OPTIONS
Content-Length:  0


--end msg--
13:53:51.886    tsx0xbf4e2c  ...State changed from Null to Calling,
event=TX_MSG
13:53:51.888    pjsua_acc.c  ..Acc 0: Registration sent
13:53:51.889 sip_endpoint.c !Processing incoming message: Response msg
401/REGISTER/cseq=47841 (rdata0xbf126c)
13:53:51.891   pjsua_core.c  .RX 557 bytes Response msg
401/REGISTER/cseq=47841 (rdata0xbf126c) from UDP 192.168.1.40:5060:
SIP/2.0 401 Unauthorized
Via: SIP/2.0/UDP 192.168.1.120:5060
;branch=z9hG4bKPjEGkMscGiSvt0O.KLo9dxJ4s03V7-1Kmw;received=192.168.1.120;rport=5060
From: <sip:511 at raspbx>;tag=s96E7GKkGb5ti9m603K6miDa9.i8Cow5
To: <sip:511 at raspbx>;tag=as333960f3
Call-ID: 9V1ox-mHiBZCYvDoVuu6ZDlSGCo7h9p1
CSeq: 47841 REGISTER
Server: FPBX-13.0.98(11.21.0)
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO,
PUBLISH, MESSAGE
Supported: replaces, timer
WWW-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="729607f2"
Content-Length: 0


--end msg--
13:53:51.893    tsx0xbf4e2c  .Incoming Response msg 401/REGISTER/cseq=47841
(rdata0xbf126c) in state Calling
13:53:51.893    tsx0xbf4e2c  ..State changed from Calling to Completed,
event=RX_MSG
13:53:51.894    tsx0xbf7a6c  ....Transaction created for Request msg
REGISTER/cseq=47842 (tdta0xbf3dc0)
13:53:51.895    tsx0xbf7a6c  ...Sending Request msg REGISTER/cseq=47842
(tdta0xbf3dc0) in state Null
13:53:51.896       endpoint  ....Request msg REGISTER/cseq=47842
(tdta0xbf3dc0): skipping target resolution because address is already set
13:53:51.896   pjsua_core.c  ....TX 615 bytes Request msg
REGISTER/cseq=47842 (tdta0xbf3dc0) to UDP 192.168.1.40:5060:
REGISTER sip:raspbx SIP/2.0
Via: SIP/2.0/UDP 192.168.1.120:5060
;rport;branch=z9hG4bKPjP3YWUDS2G79cd9uSmZNxwOihH-vgIz7D
Max-Forwards: 70
From: <sip:511 at raspbx>;tag=s96E7GKkGb5ti9m603K6miDa9.i8Cow5
To: <sip:511 at raspbx>
Call-ID: 9V1ox-mHiBZCYvDoVuu6ZDlSGCo7h9p1
CSeq: 47842 REGISTER
Contact: <sip:511 at 192.168.1.120:5060;ob>
Expires: 300
Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, SUBSCRIBE, NOTIFY,
REFER, MESSAGE, OPTIONS
Authorization: Digest username="511", realm="asterisk", nonce="729607f2",
uri="sip:raspbx", response="2fff1075128c48f46ec28243fa1df69b", algorithm=MD5
Content-Length:  0


--end msg--
13:53:51.897    tsx0xbf7a6c  ....State changed from Null to Calling,
event=TX_MSG
13:53:51.898   pjsua_call.c !Making call with acc #0 to sip:502 at raspbx
13:53:51.899    pjsua_aud.c  .Set sound device: capture=-1, playback=-2
13:53:51.902    pjsua_aud.c !..Opening sound device PCM at 16000/1/20ms
13:53:51.902     alsa_dev.c  ...open_playback: Open playback device
'default:CARD=Device'
13:53:51.902 sip_endpoint.c !Processing incoming message: Request msg
OPTIONS/cseq=102 (rdata0xbf126c)
13:53:51.914   pjsua_core.c !.RX 555 bytes Request msg OPTIONS/cseq=102
(rdata0xbf126c) from UDP 192.168.1.40:5060:
OPTIONS sip:511 at 192.168.1.120:5060;ob SIP/2.0
Via: SIP/2.0/UDP 192.168.1.40:5060;branch=z9hG4bK1fb15846
Max-Forwards: 70
From: "Unknown" <sip:Unknown at 192.168.1.40>;tag=as0df0e1a8
To: <sip:511 at 192.168.1.120:5060;ob>
Contact: <sip:Unknown at 192.168.1.40:5060>
Call-ID: 15c7a8267bbf71235fa859e4431f2326 at 192.168.1.40:5060
CSeq: 102 OPTIONS
User-Agent: FPBX-13.0.98(11.21.0)
Date: Tue, 12 Apr 2016 13:53:51 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO,
PUBLISH, MESSAGE
Supported: replaces, timer
Content-Length: 0


--end msg--
13:53:51.925     alsa_dev.c !...Opened device alsa(default:CARD=Device) for
playing, sample rate=16000, ch=1, bits=16, period size=320 frames,
latency=149 ms
13:53:51.927     alsa_dev.c  ...open_capture: Open capture device
'default:CARD=Device'
13:53:51.947     alsa_dev.c  ...Opened device alsa(default:CARD=Device) for
capture, sample rate=16000, ch=1, bits=16, period size=320 frames,
latency=106 ms
13:53:51.949     ec0xbd3f18  ...Creating AEC
13:53:51.954     ec0xbd3f18  ...AEC created, clock_rate=16000, channel=1,
samples per frame=320, tail length=200 ms, latency=0 ms
13:53:51.956    dlg0xc3773c  .UAC dialog created
13:53:51.958    dlg0xc3773c  ..Session count inc to 2 by mod-pjsua
13:53:51.960  pjsua_media.c  .Call 0: initializing media..
13:53:51.963     alsa_dev.c !ca_thread_func(2733): Set thread priority for
audio capture thread.
13:53:51.965     alsa_dev.c  Unable to increase thread priority, root
access needed.
13:53:51.968  pjsua_media.c !..RTP socket reachable at 192.168.1.120:4000
13:53:51.969  pjsua_media.c  ..RTCP socket reachable at 192.168.1.120:4001
13:53:51.966          speex !warning: discarded first playback frame
13:53:51.972          speex !warning: discarded first playback frame
13:53:51.975          speex  warning: discarded first playback frame
13:53:51.978          speex !warning: discarded first playback frame
13:53:51.977  pjsua_media.c !..Media index 0 selected for audio call 0
13:53:51.980    dlg0xc3773c !..Session count dec to 2 by mod-pjsua
13:53:51.984          speex !warning: discarded first playback frame
13:53:51.986          speex !warning: discarded first playback frame
13:53:51.985    dlg0xc3773c !.Module mod-invite added as dialog usage,
data=0xc08acc
13:53:51.993    dlg0xc3773c !..Session count inc to 4 by mod-invite
13:53:51.994    dlg0xc3773c  .Module mod-100rel added as dialog usage,
data=0xc08c18
13:53:51.997    dlg0xc3773c  .100rel module attached
13:53:51.998    inv0xc3773c  .UAC invite session created for dialog
dlg0xc3773c
13:53:52.003       endpoint !.Request msg INVITE/cseq=19591 (tdta0xc3d1e0)
created.
13:53:52.008    inv0xc3773c  ..Sending Request msg INVITE/cseq=19591
(tdta0xc3d1e0)
13:53:52.010    dlg0xc3773c  ...Sending Request msg INVITE/cseq=19591
(tdta0xc3d1e0)
13:53:52.012    tsx0xc3f1f4  ....Transaction created for Request msg
INVITE/cseq=19590 (tdta0xc3d1e0)
13:53:52.014    tsx0xc3f1f4  ...Sending Request msg INVITE/cseq=19590
(tdta0xc3d1e0) in state Null
13:53:52.016  sip_resolve.c  ....DNS resolver not available, target
'raspbx:0' type=Unspecified will be resolved with getaddrinfo()
13:53:52.001          speex !warning: Had to discard a playback frame (your
application is buggy and/or got xruns)
13:53:52.019          speex !warning: Had to discard a playback frame (your
application is buggy and/or got xruns)
13:53:52.025          speex  warning: Had to discard a playback frame (your
application is buggy and/or got xruns)
13:53:52.027  sip_resolve.c !....Target 'raspbx:0' type=Unspecified
resolved to '192.168.1.40:5060' type=UDP (UDP transport)
13:53:52.036   pjsua_core.c  ....TX 943 bytes Request msg INVITE/cseq=19590
(tdta0xc3d1e0) to UDP 192.168.1.40:5060:
INVITE sip:502 at raspbx SIP/2.0
Via: SIP/2.0/UDP 192.168.1.120:5060
;rport;branch=z9hG4bKPjfvZU.XrhkVa5zrKBI0Wqx1ZJrzL5cf6R
Max-Forwards: 70
From: sip:511 at raspbx;tag=Qn71ss84d4keesGybUw4EyodEcXtVwTz
To: sip:502 at raspbx
Contact: <sip:511 at 192.168.1.120:5060;ob>
Call-ID: qF3.50nrPaYalZJhk-h3463jTuv0Uuk0
CSeq: 19590 INVITE
Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, SUBSCRIBE, NOTIFY,
REFER, MESSAGE, OPTIONS
Supported: replaces, 100rel, timer, norefersub
Session-Expires: 1800
Min-SE: 90
Content-Type: application/sdp
Content-Length:   381

v=0
o=- 3669458031 3669458031 IN IP4 192.168.1.120
s=pjmedia
b=AS:84
t=0 0
a=X-nat:0
m=audio 4000 RTP/AVP 98 97 99 0 8 96
c=IN IP4 192.168.1.120
b=TIAS:64000
a=rtcp:4001 IN IP4 192.168.1.120
a=sendrecv
a=rtpmap:98 speex/16000
a=rtpmap:97 speex/8000
a=rtpmap:99 speex/32000
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:96 telephone-event/8000
a=fmtp:96 0-16

--end msg--
13:53:52.042    tsx0xc3f1f4  ....State changed from Null to Calling,
event=TX_MSG
13:53:52.043    dlg0xc3773c  .....Transaction tsx0xc3f1f4 state changed to
Calling
13:53:52.043            APP  .......Call 0 state=CALLING
13:53:52.044       endpoint !.Response msg 200/OPTIONS/cseq=102
(tdta0xc41ae8) created
13:53:52.046  sip_resolve.c  .Target '192.168.1.40:5060' type=UDP resolved
to '192.168.1.40:5060' type=UDP (UDP transport)
13:53:52.047   pjsua_core.c  .TX 683 bytes Response msg
200/OPTIONS/cseq=102 (tdta0xc41ae8) to UDP 192.168.1.40:5060:
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.1.40:5060
;received=192.168.1.40;branch=z9hG4bK1fb15846
Call-ID: 15c7a8267bbf71235fa859e4431f2326 at 192.168.1.40:5060
From: "Unknown" <sip:Unknown at 192.168.1.40>;tag=as0df0e1a8
To: <sip:511 at 192.168.1.120;ob>;tag=z9hG4bK1fb15846
CSeq: 102 OPTIONS
Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, SUBSCRIBE, NOTIFY,
REFER, MESSAGE, OPTIONS
Accept: application/sdp, application/pidf+xml, application/xpidf+xml,
application/simple-message-summary, message/sipfrag;version=2.0,
application/im-iscomposing+xml, text/plain
Supported: replaces, 100rel, timer, norefersub
Allow-Events: presence, message-summary, refer
Content-Length:  0


--end msg--
13:53:52.047   tdta0xc41ae8  .Destroying txdata Response msg
200/OPTIONS/cseq=102 (tdta0xc41ae8)
13:53:52.050 sip_endpoint.c  Processing incoming message: Response msg
200/REGISTER/cseq=47842 (rdata0xbf126c)
13:53:52.053   pjsua_core.c  .RX 576 bytes Response msg
200/REGISTER/cseq=47842 (rdata0xbf126c) from UDP 192.168.1.40:5060:
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.1.120:5060
;branch=z9hG4bKPjP3YWUDS2G79cd9uSmZNxwOihH-vgIz7D;received=192.168.1.120;rport=5060
From: <sip:511 at raspbx>;tag=s96E7GKkGb5ti9m603K6miDa9.i8Cow5
To: <sip:511 at raspbx>;tag=as333960f3
Call-ID: 9V1ox-mHiBZCYvDoVuu6ZDlSGCo7h9p1
CSeq: 47842 REGISTER
Server: FPBX-13.0.98(11.21.0)
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO,
PUBLISH, MESSAGE
Supported: replaces, timer
Expires: 300
Contact: <sip:511 at 192.168.1.120:5060;ob>;expires=300
Date: Tue, 12 Apr 2016 13:53:51 GMT
Content-Length: 0


--end msg--
13:53:52.055    tsx0xbf7a6c  .Incoming Response msg 200/REGISTER/cseq=47842
(rdata0xbf126c) in state Calling
13:53:52.056    tsx0xbf7a6c  ..State changed from Calling to Completed,
event=RX_MSG
13:53:52.057    pjsua_acc.c  ....SIP outbound status for acc 0 is not active
13:53:52.058    pjsua_acc.c  ....sip:511 at raspbx: registration success,
status=200 (OK), will re-register in 300 seconds
13:53:52.058    pjsua_acc.c  ....Keep-alive timer started for acc 0,
destination:192.168.1.40:5060, interval:15s
13:53:52.061 sip_endpoint.c  Processing incoming message: Request msg
NOTIFY/cseq=102 (rdata0xbf126c)
13:53:52.064   pjsua_core.c  .RX 558 bytes Request msg NOTIFY/cseq=102
(rdata0xbf126c) from UDP 192.168.1.40:5060:
NOTIFY sip:511 at 192.168.1.120:5060;ob SIP/2.0
Via: SIP/2.0/UDP 192.168.1.40:5060;branch=z9hG4bK7f31d868
Max-Forwards: 70
From: "Unknown" <sip:Unknown at 192.168.1.40>;tag=as43b2ff19
To: <sip:511 at 192.168.1.120:5060;ob>
Contact: <sip:Unknown at 192.168.1.40:5060>
Call-ID: 23fdfd4920b57317364ac36904b11312 at 192.168.1.40:5060
CSeq: 102 NOTIFY
User-Agent: FPBX-13.0.98(11.21.0)
Event: message-summary
Content-Type: application/simple-message-summary
Content-Length: 87

Messages-Waiting: no
Message-Account: sip:*97 at 192.168.1.40
Voice-Message: 0/0 (0/0)

--end msg--
13:53:52.066   pjsua_pres.c  .Got unsolicited NOTIFY from 192.168.1.40:5060
..
13:53:52.067       endpoint  ..Response msg 200/NOTIFY/cseq=102
(tdta0xc41ae8) created
13:53:52.075    tsx0xc42b54  ...Transaction created for Request msg
NOTIFY/cseq=102 (rdata0xbf126c)
13:53:52.077    tsx0xc42b54  ..Incoming Request msg NOTIFY/cseq=102
(rdata0xbf126c) in state Null
13:53:52.078    tsx0xc42b54  ...State changed from Null to Trying,
event=RX_MSG
13:53:52.080    tsx0xc42b54  ..Sending Response msg 200/NOTIFY/cseq=102
(tdta0xc41ae8) in state Trying
13:53:52.081  sip_resolve.c  ...Target '192.168.1.40:5060' type=UDP
resolved to '192.168.1.40:5060' type=UDP (UDP transport)
13:53:52.082   pjsua_core.c  ...TX 309 bytes Response msg
200/NOTIFY/cseq=102 (tdta0xc41ae8) to UDP 192.168.1.40:5060:
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.1.40:5060
;received=192.168.1.40;branch=z9hG4bK7f31d868
Call-ID: 23fdfd4920b57317364ac36904b11312 at 192.168.1.40:5060
From: "Unknown" <sip:Unknown at 192.168.1.40>;tag=as43b2ff19
To: <sip:511 at 192.168.1.120;ob>;tag=z9hG4bK7f31d868
CSeq: 102 NOTIFY
Content-Length:  0


--end msg--
13:53:52.084    tsx0xc42b54  ...State changed from Trying to Completed,
event=TX_MSG
13:53:52.085 sip_endpoint.c  Processing incoming message: Request msg
NOTIFY/cseq=102 (rdata0xbf126c)
13:53:52.086   pjsua_core.c  .RX 558 bytes Request msg NOTIFY/cseq=102
(rdata0xbf126c) from UDP 192.168.1.40:5060:
NOTIFY sip:511 at 192.168.1.120:5060;ob SIP/2.0
Via: SIP/2.0/UDP 192.168.1.40:5060;branch=z9hG4bK7f31d868
Max-Forwards: 70
From: "Unknown" <sip:Unknown at 192.168.1.40>;tag=as43b2ff19
To: <sip:511 at 192.168.1.120:5060;ob>
Contact: <sip:Unknown at 192.168.1.40:5060>
Call-ID: 23fdfd4920b57317364ac36904b11312 at 192.168.1.40:5060
CSeq: 102 NOTIFY
User-Agent: FPBX-13.0.98(11.21.0)
Event: message-summary
Content-Type: application/simple-message-summary
Content-Length: 87

Messages-Waiting: no
Message-Account: sip:*97 at 192.168.1.40
Voice-Message: 0/0 (0/0)

--end msg--
13:53:52.087    tsx0xc42b54  .Incoming Request msg NOTIFY/cseq=102
(rdata0xbf126c) in state Completed
13:53:52.087    tsx0xc42b54  ..Retransmiting Response msg
200/NOTIFY/cseq=102 (tdta0xc41ae8), count=0, restart?=0
13:53:52.087   pjsua_core.c  ..TX 309 bytes Response msg
200/NOTIFY/cseq=102 (tdta0xc41ae8) to UDP 192.168.1.40:5060:
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.1.40:5060
;received=192.168.1.40;branch=z9hG4bK7f31d868
Call-ID: 23fdfd4920b57317364ac36904b11312 at 192.168.1.40:5060
From: "Unknown" <sip:Unknown at 192.168.1.40>;tag=as43b2ff19
To: <sip:511 at 192.168.1.120;ob>;tag=z9hG4bK7f31d868
CSeq: 102 NOTIFY
Content-Length:  0


--end msg--
13:53:52.090 sip_endpoint.c  Processing incoming message: Response msg
401/INVITE/cseq=19590 (rdata0xbf126c)
13:53:52.095          speex !warning: Had to discard a playback frame (your
application is buggy and/or got xruns)
13:53:52.096   pjsua_core.c !.RX 551 bytes Response msg
401/INVITE/cseq=19590 (rdata0xbf126c) from UDP 192.168.1.40:5060:
SIP/2.0 401 Unauthorized
Via: SIP/2.0/UDP 192.168.1.120:5060
;branch=z9hG4bKPjfvZU.XrhkVa5zrKBI0Wqx1ZJrzL5cf6R;received=192.168.1.120;rport=5060
From: sip:511 at raspbx;tag=Qn71ss84d4keesGybUw4EyodEcXtVwTz
To: sip:502 at raspbx;tag=as60484cbf
Call-ID: qF3.50nrPaYalZJhk-h3463jTuv0Uuk0
CSeq: 19590 INVITE
Server: FPBX-13.0.98(11.21.0)
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO,
PUBLISH, MESSAGE
Supported: replaces, timer
WWW-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="0b35fab6"
Content-Length: 0


--end msg--
13:53:52.100    tsx0xc3f1f4  .Incoming Response msg 401/INVITE/cseq=19590
(rdata0xbf126c) in state Calling
13:53:52.101       endpoint  ..Request msg ACK/cseq=19590 (tdta0xc45240)
created.
13:53:52.101   pjsua_core.c  ..TX 314 bytes Request msg ACK/cseq=19590
(tdta0xc45240) to UDP 192.168.1.40:5060:
ACK sip:502 at raspbx SIP/2.0
Via: SIP/2.0/UDP 192.168.1.120:5060
;rport;branch=z9hG4bKPjfvZU.XrhkVa5zrKBI0Wqx1ZJrzL5cf6R
Max-Forwards: 70
From: sip:511 at raspbx;tag=Qn71ss84d4keesGybUw4EyodEcXtVwTz
To: sip:502 at raspbx;tag=as60484cbf
Call-ID: qF3.50nrPaYalZJhk-h3463jTuv0Uuk0
CSeq: 19590 ACK
Content-Length:  0


--end msg--
13:53:52.102    tsx0xc3f1f4  ..State changed from Calling to Completed,
event=RX_MSG
13:53:52.104    dlg0xc3773c  ...Received Response msg 401/INVITE/cseq=19590
(rdata0xbf126c)
13:53:52.116    dlg0xc3773c  ...Transaction tsx0xc3f1f4 state changed to
Completed
13:53:52.117    inv0xc3773c  .....Sending Request msg INVITE/cseq=19590
(tdta0xc3d1e0)
13:53:52.119    dlg0xc3773c  ......Sending Request msg INVITE/cseq=19590
(tdta0xc3d1e0)
13:53:52.121    tsx0xc481f4  .......Transaction created for Request msg
INVITE/cseq=19591 (tdta0xc3d1e0)
13:53:52.124    tsx0xc481f4  ......Sending Request msg INVITE/cseq=19591
(tdta0xc3d1e0) in state Null
13:53:52.124       endpoint  .......Request msg INVITE/cseq=19591
(tdta0xc3d1e0): skipping target resolution because address is already set
13:53:52.126   pjsua_core.c  .......TX 1099 bytes Request msg
INVITE/cseq=19591 (tdta0xc3d1e0) to UDP 192.168.1.40:5060:
INVITE sip:502 at raspbx SIP/2.0
Via: SIP/2.0/UDP 192.168.1.120:5060
;rport;branch=z9hG4bKPjQGeYjC34n2OypR2mI9I8B7OQfe9n9xMb
Max-Forwards: 70
From: sip:511 at raspbx;tag=Qn71ss84d4keesGybUw4EyodEcXtVwTz
To: sip:502 at raspbx
Contact: <sip:511 at 192.168.1.120:5060;ob>
Call-ID: qF3.50nrPaYalZJhk-h3463jTuv0Uuk0
CSeq: 19591 INVITE
Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, SUBSCRIBE, NOTIFY,
REFER, MESSAGE, OPTIONS
Supported: replaces, 100rel, timer, norefersub
Session-Expires: 1800
Min-SE: 90
Authorization: Digest username="511", realm="asterisk", nonce="0b35fab6",
uri="sip:502 at raspbx", response="9646ac31cd32c3f8aa8e925e6977060e",
algorithm=MD5
Content-Type: application/sdp
Content-Length:   381

v=0
o=- 3669458031 3669458031 IN IP4 192.168.1.120
s=pjmedia
b=AS:84
t=0 0
a=X-nat:0
m=audio 4000 RTP/AVP 98 97 99 0 8 96
c=IN IP4 192.168.1.120
b=TIAS:64000
a=rtcp:4001 IN IP4 192.168.1.120
a=sendrecv
a=rtpmap:98 speex/16000
a=rtpmap:97 speex/8000
a=rtpmap:99 speex/32000
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:96 telephone-event/8000
a=fmtp:96 0-16

--end msg--
13:53:52.128    tsx0xc481f4  .......State changed from Null to Calling,
event=TX_MSG
13:53:52.130    dlg0xc3773c  ........Transaction tsx0xc481f4 state changed
to Calling
13:53:52.135 sip_endpoint.c  Processing incoming message: Response msg
100/INVITE/cseq=19591 (rdata0xbf126c)
13:53:52.136   pjsua_core.c  .RX 529 bytes Response msg
100/INVITE/cseq=19591 (rdata0xbf126c) from UDP 192.168.1.40:5060:
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 192.168.1.120:5060
;branch=z9hG4bKPjQGeYjC34n2OypR2mI9I8B7OQfe9n9xMb;received=192.168.1.120;rport=5060
From: sip:511 at raspbx;tag=Qn71ss84d4keesGybUw4EyodEcXtVwTz
To: sip:502 at raspbx
Call-ID: qF3.50nrPaYalZJhk-h3463jTuv0Uuk0
CSeq: 19591 INVITE
Server: FPBX-13.0.98(11.21.0)
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO,
PUBLISH, MESSAGE
Supported: replaces, timer
Session-Expires: 1800;refresher=uas
Contact: <sip:502 at 192.168.1.40:5060>
Content-Length: 0


--end msg--
13:53:52.139    tsx0xc481f4  .Incoming Response msg 100/INVITE/cseq=19591
(rdata0xbf126c) in state Calling
13:53:52.141    tsx0xc481f4  ..State changed from Calling to Proceeding,
event=RX_MSG
13:53:52.142    dlg0xc3773c  ...Received Response msg 100/INVITE/cseq=19591
(rdata0xbf126c)
13:53:52.142    dlg0xc3773c  ...Transaction tsx0xc481f4 state changed to
Proceeding
13:53:52.179          speex !warning: Auto-filling the buffer (your
application is buggy and/or got xruns)
13:53:52.188 sip_endpoint.c !Processing incoming message: Response msg
180/INVITE/cseq=19591 (rdata0xbf126c)
13:53:52.190   pjsua_core.c  .RX 545 bytes Response msg
180/INVITE/cseq=19591 (rdata0xbf126c) from UDP 192.168.1.40:5060:
SIP/2.0 180 Ringing
Via: SIP/2.0/UDP 192.168.1.120:5060
;branch=z9hG4bKPjQGeYjC34n2OypR2mI9I8B7OQfe9n9xMb;received=192.168.1.120;rport=5060
From: sip:511 at raspbx;tag=Qn71ss84d4keesGybUw4EyodEcXtVwTz
To: sip:502 at raspbx;tag=as5b7281ba
Call-ID: qF3.50nrPaYalZJhk-h3463jTuv0Uuk0
CSeq: 19591 INVITE
Server: FPBX-13.0.98(11.21.0)
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO,
PUBLISH, MESSAGE
Supported: replaces, timer
Session-Expires: 1800;refresher=uas
Contact: <sip:502 at 192.168.1.40:5060>
Content-Length: 0


--end msg--
13:53:52.192    tsx0xc481f4  .Incoming Response msg 180/INVITE/cseq=19591
(rdata0xbf126c) in state Proceeding
13:53:52.193    tsx0xc481f4  ..State changed from Proceeding to Proceeding,
event=RX_MSG
13:53:52.195    dlg0xc3773c  ...Received Response msg 180/INVITE/cseq=19591
(rdata0xbf126c)
13:53:52.196    dlg0xc3773c  ....Route-set updated
13:53:52.197    dlg0xc3773c  ...Transaction tsx0xc481f4 state changed to
Proceeding
13:53:52.203            APP  .....Call 0 state=EARLY
13:53:52.222          speex !warning: Had to discard a playback frame (your
application is buggy and/or got xruns)
13:53:52.227 sip_endpoint.c !Processing incoming message: Response msg
180/INVITE/cseq=19591 (rdata0xbf126c)
13:53:52.234   pjsua_core.c  .RX 545 bytes Response msg
180/INVITE/cseq=19591 (rdata0xbf126c) from UDP 192.168.1.40:5060:
SIP/2.0 180 Ringing
Via: SIP/2.0/UDP 192.168.1.120:5060
;branch=z9hG4bKPjQGeYjC34n2OypR2mI9I8B7OQfe9n9xMb;received=192.168.1.120;rport=5060
From: sip:511 at raspbx;tag=Qn71ss84d4keesGybUw4EyodEcXtVwTz
To: sip:502 at raspbx;tag=as5b7281ba
Call-ID: qF3.50nrPaYalZJhk-h3463jTuv0Uuk0
CSeq: 19591 INVITE
Server: FPBX-13.0.98(11.21.0)
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO,
PUBLISH, MESSAGE
Supported: replaces, timer
Session-Expires: 1800;refresher=uas
Contact: <sip:502 at 192.168.1.40:5060>
Content-Length: 0


--end msg--
13:53:52.238    tsx0xc481f4  .Incoming Response msg 180/INVITE/cseq=19591
(rdata0xbf126c) in state Proceeding
13:53:52.239    tsx0xc481f4  ..State changed from Proceeding to Proceeding,
event=RX_MSG
13:53:52.240    dlg0xc3773c  ...Received Response msg 180/INVITE/cseq=19591
(rdata0xbf126c)
13:53:52.240    dlg0xc3773c  ...Transaction tsx0xc481f4 state changed to
Proceeding
13:53:52.242            APP  .....Call 0 state=EARLY
13:53:52.350          speex !warning: Auto-filling the buffer (your
application is buggy and/or got xruns)
13:53:52.606          speex  warning: Had to discard a playback frame (your
application is buggy and/or got xruns)
13:53:52.670          speex  warning: Auto-filling the buffer (your
application is buggy and/or got xruns)
13:53:53.908          speex  warning: Had to discard a playback frame (your
application is buggy and/or got xruns)
13:53:53.951          speex  warning: Auto-filling the buffer (your
application is buggy and/or got xruns)
13:53:54.126          speex  warning: Had to discard a playback frame (your
application is buggy and/or got xruns)
13:53:54.171          speex  warning: Auto-filling the buffer (your
application is buggy and/or got xruns)
13:53:54.271          speex  warning: Had to discard a playback frame (your
application is buggy and/or got xruns)
13:53:54.292          speex  warning: Auto-filling the buffer (your
application is buggy and/or got xruns)
13:53:54.446          speex  warning: Had to discard a playback frame (your
application is buggy and/or got xruns)
13:53:54.496          speex  warning: Auto-filling the buffer (your
application is buggy and/or got xruns)
13:53:54.530          speex  warning: Had to discard a playback frame (your
application is buggy and/or got xruns)
13:53:54.591          speex  warning: Auto-filling the buffer (your
application is buggy and/or got xruns)
13:53:54.822 sip_endpoint.c !Processing incoming message: Response msg
200/INVITE/cseq=19591 (rdata0xbf126c)
13:53:54.823   pjsua_core.c  .RX 846 bytes Response msg
200/INVITE/cseq=19591 (rdata0xbf126c) from UDP 192.168.1.40:5060:
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.1.120:5060
;branch=z9hG4bKPjQGeYjC34n2OypR2mI9I8B7OQfe9n9xMb;received=192.168.1.120;rport=5060
From: sip:511 at raspbx;tag=Qn71ss84d4keesGybUw4EyodEcXtVwTz
To: sip:502 at raspbx;tag=as5b7281ba
Call-ID: qF3.50nrPaYalZJhk-h3463jTuv0Uuk0
CSeq: 19591 INVITE
Server: FPBX-13.0.98(11.21.0)
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO,
PUBLISH, MESSAGE
Supported: replaces, timer
Session-Expires: 1800;refresher=uas
Contact: <sip:502 at 192.168.1.40:5060>
Content-Type: application/sdp
Require: timer
Content-Length: 257

v=0
o=root 1874987630 1874987630 IN IP4 192.168.1.40
s=Asterisk PBX 11.21.0
c=IN IP4 192.168.1.40
t=0 0
m=audio 12164 RTP/AVP 0 8 96
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:96 telephone-event/8000
a=fmtp:96 0-16
a=ptime:20
a=sendrecv

--end msg--
13:53:54.828    tsx0xc481f4  .Incoming Response msg 200/INVITE/cseq=19591
(rdata0xbf126c) in state Proceeding
13:53:54.828    tsx0xc481f4  ..State changed from Proceeding to Terminated,
event=RX_MSG
13:53:54.829    dlg0xc3773c  ...Received Response msg 200/INVITE/cseq=19591
(rdata0xbf126c)
13:53:54.829    dlg0xc3773c  ....Route-set updated
13:53:54.829    dlg0xc3773c  ....Route-set frozen
13:53:54.830    dlg0xc3773c  ...Transaction tsx0xc481f4 state changed to
Terminated
13:53:54.830            APP  .....Call 0 state=CONNECTING
13:53:54.833    inv0xc3773c  ....Got SDP answer in Response msg
200/INVITE/cseq=19591 (rdata0xbf126c)
13:53:54.842    inv0xc3773c  ....SDP negotiation done, status=0
13:53:54.844   pjsua_call.c  .....Call 0: remote NAT type is 0 (Unknown)
13:53:54.845  pjsua_media.c  .....Call 0: updating media..
13:53:54.847    pjsua_aud.c  ......Audio channel update..
13:53:54.853   strm0xc49be4  .......VAD temporarily disabled
13:53:54.854          rtp.c  .......pjmedia_rtp_session_init: ses=0xc4b6a8,
default_pt=0, ssrc=0x68577511
13:53:54.856          rtp.c  .......pjmedia_rtp_session_init: ses=0xc4bd30,
default_pt=0, ssrc=0x68577511
13:53:54.858       stream.c  .......Stream strm0xc49be4 created
13:53:54.859   strm0xc49be4  .......Encoder stream started
13:53:54.862   strm0xc49be4  .......Decoder stream started
13:53:54.864     resample.c  .......resample created: high qualiy, large
filter, in/out rate=8000/16000
13:53:54.865     resample.c  .......resample created: high qualiy, large
filter, in/out rate=16000/8000
13:53:54.874  pjsua_media.c  ......Audio updated, stream #0: PCMU (sendrecv)
13:53:54.877    pjsua_aud.c !.....Conf connect: 1 --> 0
13:53:54.876   strm0xc49be4 !Start talksprut..
13:53:54.881   strm0xc49be4 !RTP status: badpt=0, badssrc=0, dup=0,
outorder=0, probation=-1, restart=0
13:53:54.882   conference.c !......Port 1 (sip:502 at raspbx) transmitting to
port 0 (default:CARD=Device)
13:53:54.885    pjsua_aud.c  .....Conf connect: 0 --> 1
13:53:54.887   conference.c  ......Port 0 (default:CARD=Device)
transmitting to port 1 (sip:502 at raspbx)
13:53:54.888    inv0xc3773c  ....Received Response msg
200/INVITE/cseq=19591 (rdata0xbf126c), sending ACK
13:53:54.890       endpoint  ....Request msg ACK/cseq=19591 (tdta0xc4db10)
created.
13:53:54.890    dlg0xc3773c !.....Sending Request msg ACK/cseq=19591
(tdta0xc4db10)
13:53:54.891  sip_resolve.c  .....Target '192.168.1.40:5060'
type=Unspecified resolved to '192.168.1.40:5060' type=UDP (UDP transport)
13:53:54.891   pjsua_core.c  .....TX 325 bytes Request msg ACK/cseq=19591
(tdta0xc4db10) to UDP 192.168.1.40:5060:
ACK sip:502 at 192.168.1.40:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.1.120:5060
;rport;branch=z9hG4bKPjxH-YvcJ.09t3v6k8dCfPxARll20ckMiG
Max-Forwards: 70
From: sip:511 at raspbx;tag=Qn71ss84d4keesGybUw4EyodEcXtVwTz
To: sip:502 at raspbx;tag=as5b7281ba
Call-ID: qF3.50nrPaYalZJhk-h3463jTuv0Uuk0
CSeq: 19591 ACK
Content-Length:  0


--end msg--
13:53:54.890   Master/sound !Underflow, buf_cnt=0, will generate 1 frame
13:53:54.902            APP  .....Call 0 state=CONFIRMED
13:53:54.904   pjsua_call.c  .Call 0 sending re-INVITE for updating media
session to use only one codec
13:53:54.906       endpoint  ..Request msg INVITE/cseq=19593 (tdta0xc51ca8)
created.
13:53:54.907    inv0xc3773c  ..Sending Request msg INVITE/cseq=19593
(tdta0xc51ca8)
13:53:54.913    dlg0xc3773c  ...Sending Request msg INVITE/cseq=19593
(tdta0xc51ca8)
13:53:54.914    tsx0xc53cbc  ....Transaction created for Request msg
INVITE/cseq=19592 (tdta0xc51ca8)
13:53:54.917    tsx0xc53cbc  ...Sending Request msg INVITE/cseq=19592
(tdta0xc51ca8) in state Null
13:53:54.918  sip_resolve.c  ....Target '192.168.1.40:5060'
type=Unspecified resolved to '192.168.1.40:5060' type=UDP (UDP transport)
13:53:54.921   pjsua_core.c  ....TX 876 bytes Request msg INVITE/cseq=19592
(tdta0xc51ca8) to UDP 192.168.1.40:5060:
INVITE sip:502 at 192.168.1.40:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.1.120:5060
;rport;branch=z9hG4bKPjnM.jze3e2o2ebD2-GIkiCsPZlMAMLf1o
Max-Forwards: 70
From: sip:511 at raspbx;tag=Qn71ss84d4keesGybUw4EyodEcXtVwTz
To: sip:502 at raspbx;tag=as5b7281ba
Contact: <sip:511 at 192.168.1.120:5060;ob>
Call-ID: qF3.50nrPaYalZJhk-h3463jTuv0Uuk0
CSeq: 19592 INVITE
Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, SUBSCRIBE, NOTIFY,
REFER, MESSAGE, OPTIONS
Supported: replaces, 100rel, timer, norefersub
Session-Expires: 1800;refresher=uas
Min-SE: 90
Content-Type: application/sdp
Content-Length:   274

v=0
o=- 3669458031 3669458032 IN IP4 192.168.1.120
s=pjmedia
b=AS:84
t=0 0
a=X-nat:0
m=audio 4000 RTP/AVP 0 96
c=IN IP4 192.168.1.120
b=TIAS:64000
a=rtcp:4001 IN IP4 192.168.1.120
a=rtpmap:0 PCMU/8000
a=rtpmap:96 telephone-event/8000
a=fmtp:96 0-16
a=sendrecv

--end msg--
13:53:54.926    tsx0xc53cbc !....State changed from Null to Calling,
event=TX_MSG
13:53:54.928    dlg0xc3773c  .....Transaction tsx0xc53cbc state changed to
Calling
13:53:54.929    tsx0xc481f4  Timeout timer event
13:53:54.932    tsx0xc481f4  .State changed from Terminated to Destroyed,
event=TIMER
13:53:54.934    tsx0xc481f4  Transaction destroyed!
13:53:54.935 sip_endpoint.c  Processing incoming message: Response msg
100/INVITE/cseq=19592 (rdata0xbf126c)
13:53:54.937   pjsua_core.c  .RX 544 bytes Response msg
100/INVITE/cseq=19592 (rdata0xbf126c) from UDP 192.168.1.40:5060:
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 192.168.1.120:5060
;branch=z9hG4bKPjnM.jze3e2o2ebD2-GIkiCsPZlMAMLf1o;received=192.168.1.120;rport=5060
From: sip:511 at raspbx;tag=Qn71ss84d4keesGybUw4EyodEcXtVwTz
To: sip:502 at raspbx;tag=as5b7281ba
Call-ID: qF3.50nrPaYalZJhk-h3463jTuv0Uuk0
CSeq: 19592 INVITE
Server: FPBX-13.0.98(11.21.0)
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO,
PUBLISH, MESSAGE
Supported: replaces, timer
Session-Expires: 1800;refresher=uas
Contact: <sip:502 at 192.168.1.40:5060>
Content-Length: 0


--end msg--
13:53:54.925   Master/sound !Underflow, buf_cnt=0, will generate 1 frame
13:53:54.953    tsx0xc53cbc  .Incoming Response msg 100/INVITE/cseq=19592
(rdata0xbf126c) in state Calling
13:53:54.954    tsx0xc53cbc  ..State changed from Calling to Proceeding,
event=RX_MSG
13:53:54.956    dlg0xc3773c  ...Received Response msg 100/INVITE/cseq=19592
(rdata0xbf126c)
13:53:54.957    dlg0xc3773c  ...Transaction tsx0xc53cbc state changed to
Proceeding
13:53:54.961 sip_endpoint.c  Processing incoming message: Response msg
200/INVITE/cseq=19592 (rdata0xbf126c)
13:53:54.962   pjsua_core.c  .RX 822 bytes Response msg
200/INVITE/cseq=19592 (rdata0xbf126c) from UDP 192.168.1.40:5060:
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.1.120:5060
;branch=z9hG4bKPjnM.jze3e2o2ebD2-GIkiCsPZlMAMLf1o;received=192.168.1.120;rport=5060
From: sip:511 at raspbx;tag=Qn71ss84d4keesGybUw4EyodEcXtVwTz
To: sip:502 at raspbx;tag=as5b7281ba
Call-ID: qF3.50nrPaYalZJhk-h3463jTuv0Uuk0
CSeq: 19592 INVITE
Server: FPBX-13.0.98(11.21.0)
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO,
PUBLISH, MESSAGE
Supported: replaces, timer
Session-Expires: 1800;refresher=uas
Contact: <sip:502 at 192.168.1.40:5060>
Content-Type: application/sdp
Require: timer
Content-Length: 233

v=0
o=root 1874987630 1874987631 IN IP4 192.168.1.40
s=Asterisk PBX 11.21.0
c=IN IP4 192.168.1.40
t=0 0
m=audio 12164 RTP/AVP 0 96
a=rtpmap:0 PCMU/8000
a=rtpmap:96 telephone-event/8000
a=fmtp:96 0-16
a=ptime:20
a=sendrecv

--end msg--
13:53:54.974    tsx0xc53cbc  .Incoming Response msg 200/INVITE/cseq=19592
(rdata0xbf126c) in state Proceeding
13:53:54.977    tsx0xc53cbc  ..State changed from Proceeding to Terminated,
event=RX_MSG
13:53:54.978    dlg0xc3773c  ...Received Response msg 200/INVITE/cseq=19592
(rdata0xbf126c)
13:53:54.979    dlg0xc3773c  ...Transaction tsx0xc53cbc state changed to
Terminated
13:53:54.979    inv0xc3773c  ....Got SDP answer in Response msg
200/INVITE/cseq=19592 (rdata0xbf126c)
13:53:54.982    inv0xc3773c  ....SDP negotiation done, status=0
13:53:54.982   pjsua_call.c  .....Call 0: remote NAT type is 0 (Unknown)
13:53:54.982  pjsua_media.c  .....Call 0: updating media..
13:53:54.984  pjsua_media.c  ......Call 0: stream #0 (audio) unchanged.
13:53:54.984  pjsua_media.c  ......Audio updated, stream #0: PCMU (sendrecv)
13:53:54.987    pjsua_aud.c  .....Conf connect: 1 --> 0
13:53:54.997    pjsua_aud.c  .....Conf connect: 0 --> 1
13:53:54.998    inv0xc3773c  ....Received Response msg
200/INVITE/cseq=19592 (rdata0xbf126c), sending ACK
13:53:55.000   tdta0xc4db10  ....Destroying txdata Request msg
ACK/cseq=19591 (tdta0xc4db10)
13:53:55.002       endpoint  ....Request msg ACK/cseq=19592 (tdta0xc4db10)
created.
13:53:55.004    dlg0xc3773c  .....Sending Request msg ACK/cseq=19592
(tdta0xc4db10)
13:53:55.005  sip_resolve.c  .....Target '192.168.1.40:5060'
type=Unspecified resolved to '192.168.1.40:5060' type=UDP (UDP transport)
13:53:55.007   pjsua_core.c  .....TX 325 bytes Request msg ACK/cseq=19592
(tdta0xc4db10) to UDP 192.168.1.40:5060:
ACK sip:502 at 192.168.1.40:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.1.120:5060
;rport;branch=z9hG4bKPj6nr1w0IxJ1I9.U7d1MO6fFJqmhoKe6g1
Max-Forwards: 70
From: sip:511 at raspbx;tag=Qn71ss84d4keesGybUw4EyodEcXtVwTz
To: sip:502 at raspbx;tag=as5b7281ba
Call-ID: qF3.50nrPaYalZJhk-h3463jTuv0Uuk0
CSeq: 19592 ACK
Content-Length:  0


--end msg--
13:53:55.008    tsx0xc53cbc  Timeout timer event
13:53:55.013    tsx0xc53cbc  .State changed from Terminated to Destroyed,
event=TIMER
13:53:55.014   tdta0xc51ca8  ..Destroying txdata Request msg
INVITE/cseq=19592 (tdta0xc51ca8)
13:53:55.022    tsx0xc53cbc  Transaction destroyed!
13:53:55.172          speex !warning: No playback frame available (your
application is buggy and/or got xruns)
13:53:55.174          speex !warning: Auto-filling the buffer (your
application is buggy and/or got xruns)
13:53:55.181          speex !warning: internal playback buffer corruption?
13:53:55.184          speex  warning: No playback frame available (your
application is buggy and/or got xruns)
13:53:55.189          speex  warning: No playback frame available (your
application is buggy and/or got xruns)
13:53:55.193          speex !warning: internal playback buffer corruption?
13:53:55.193          speex !warning: Auto-filling the buffer (your
application is buggy and/or got xruns)
13:53:55.222          speex !warning: Had to discard a playback frame (your
application is buggy and/or got xruns)
13:53:55.234          speex  warning: Had to discard a playback frame (your
application is buggy and/or got xruns)
13:53:55.240   strm0xc49be4  Jitter buffer empty (prefetch=0), plc invoked
13:53:55.260   strm0xc49be4  Jitter buffer starts returning normal frames
(after 1 empty/lost)
13:53:55.400          speex  warning: Auto-filling the buffer (your
application is buggy and/or got xruns)
13:53:55.435          speex  warning: Had to discard a playback frame (your
application is buggy and/or got xruns)
13:53:55.486   strm0xc49be4  VAD re-enabled
13:53:55.487   strm0xc49be4  Starting silence
13:53:55.739          speex  warning: Auto-filling the buffer (your
application is buggy and/or got xruns)
13:53:55.776          speex  warning: Had to discard a playback frame (your
application is buggy and/or got xruns)
13:53:55.948          speex  warning: Auto-filling the buffer (your
application is buggy and/or got xruns)
13:53:55.987          speex  warning: Had to discard a playback frame (your
application is buggy and/or got xruns)
13:53:56.075          speex  warning: Auto-filling the buffer (your
application is buggy and/or got xruns)
13:53:56.096          speex  warning: Had to discard a playback frame (your
application is buggy and/or got xruns)
13:53:56.292          speex  warning: Auto-filling the buffer (your
application is buggy and/or got xruns)
13:53:56.325   silencedet.c  Starting talk burst (level=1321 threshold=1000)
13:53:56.327   strm0xc49be4  Start talksprut..
13:53:56.416          speex  warning: Had to discard a playback frame (your
application is buggy and/or got xruns)
13:53:56.648          speex  warning: Auto-filling the buffer (your
application is buggy and/or got xruns)
13:53:56.737          speex  warning: Had to discard a playback frame (your
application is buggy and/or got xruns)
13:53:56.899    tsx0xbf4e2c !Timeout timer event
13:53:56.900    tsx0xbf4e2c  .State changed from Completed to Terminated,
event=TIMER
13:53:56.906    tsx0xbf4e2c  Timeout timer event
13:53:56.907    tsx0xbf4e2c  .State changed from Terminated to Destroyed,
event=TIMER
13:53:56.908    tsx0xbf4e2c  Transaction destroyed!
13:53:57.056    tsx0xbf7a6c  Timeout timer event
13:53:57.057    tsx0xbf7a6c  .State changed from Completed to Terminated,
event=TIMER
13:53:57.062    tsx0xbf7a6c  Timeout timer event
13:53:57.063    tsx0xbf7a6c  .State changed from Terminated to Destroyed,
event=TIMER
13:53:57.065   tdta0xbf3dc0  ..Destroying txdata Request msg
REGISTER/cseq=47842 (tdta0xbf3dc0)
13:53:57.066    tsx0xbf7a6c  Transaction destroyed!
13:53:57.160          speex !warning: Had to discard a playback frame (your
application is buggy and/or got xruns)
13:53:57.187          speex !warning: No playback frame available (your
application is buggy and/or got xruns)
13:53:57.189          speex !warning: Auto-filling the buffer (your
application is buggy and/or got xruns)
13:53:57.193          speex !warning: internal playback buffer corruption?
13:53:57.203          speex  warning: No playback frame available (your
application is buggy and/or got xruns)
13:53:57.217          speex !warning: Auto-filling the buffer (your
application is buggy and/or got xruns)
13:53:57.256          speex  warning: Auto-filling the buffer (your
application is buggy and/or got xruns)
13:53:57.311          speex  warning: Had to discard a playback frame (your
application is buggy and/or got xruns)
13:53:57.336          speex  warning: Auto-filling the buffer (your
application is buggy and/or got xruns)
13:53:57.355   silencedet.c  Starting silence (level=105 threshold=338)
13:53:57.356   strm0xc49be4  Starting silence
13:53:57.358          speex  warning: Had to discard a playback frame (your
application is buggy and/or got xruns)
13:53:57.480          speex  warning: Had to discard a playback frame (your
application is buggy and/or got xruns)
13:53:57.551          speex !warning: No playback frame available (your
application is buggy and/or got xruns)
13:53:57.555          speex !warning: Auto-filling the buffer (your
application is buggy and/or got xruns)
13:53:57.565          speex !warning: internal playback buffer corruption?
13:53:57.569          speex  warning: No playback frame available (your
application is buggy and/or got xruns)
13:53:57.573          speex !warning: Auto-filling the buffer (your
application is buggy and/or got xruns)
13:53:57.702   silencedet.c  Starting talk burst (level=403 threshold=338)
13:53:57.703   strm0xc49be4  Start talksprut..
13:53:57.739          speex  warning: Had to discard a playback frame (your
application is buggy and/or got xruns)
13:53:57.909          speex  warning: Auto-filling the buffer (your
application is buggy and/or got xruns)
13:53:58.059          speex  warning: Had to discard a playback frame (your
application is buggy and/or got xruns)
13:53:58.337          speex  warning: Auto-filling the buffer (your
application is buggy and/or got xruns)
13:53:58.358          speex  warning: Had to discard a playback frame (your
application is buggy and/or got xruns)
13:53:58.739          speex  warning: Had to discard a playback frame (your
application is buggy and/or got xruns)
13:53:58.828          speex  warning: Auto-filling the buffer (your
application is buggy and/or got xruns)
13:53:58.866   silencedet.c  Starting silence (level=95 threshold=218)
13:53:58.867   strm0xc49be4  Starting silence
13:53:58.898          speex  warning: Auto-filling the buffer (your
application is buggy and/or got xruns)
13:53:59.029          speex  warning: Had to discard a playback frame (your
application is buggy and/or got xruns)
13:53:59.230          speex  warning: Auto-filling the buffer (your
application is buggy and/or got xruns)
13:53:59.398          speex  warning: Had to discard a playback frame (your
application is buggy and/or got xruns)
13:53:59.516          speex  warning: Auto-filling the buffer (your
application is buggy and/or got xruns)
13:53:59.718          speex  warning: Had to discard a playback frame (your
application is buggy and/or got xruns)
13:53:59.740          speex  warning: Had to discard a playback frame (your
application is buggy and/or got xruns)
13:53:59.812          speex !warning: No playback frame available (your
application is buggy and/or got xruns)
13:53:59.817          speex !warning: Auto-filling the buffer (your
application is buggy and/or got xruns)
13:53:59.825          speex !warning: internal playback buffer corruption?
13:53:59.829          speex  warning: No playback frame available (your
application is buggy and/or got xruns)
13:53:59.834          speex !warning: Auto-filling the buffer (your
application is buggy and/or got xruns)
13:53:59.962   silencedet.c  Starting talk burst (level=378 threshold=218)
13:53:59.970   strm0xc49be4  Start talksprut..
13:54:00.038          speex  warning: Had to discard a playback frame (your
application is buggy and/or got xruns)
13:54:00.158          speex  warning: Auto-filling the buffer (your
application is buggy and/or got xruns)
13:54:00.211          speex  warning: Had to discard a playback frame (your
application is buggy and/or got xruns)
13:54:00.238          speex  warning: Auto-filling the buffer (your
application is buggy and/or got xruns)
13:54:00.302          speex  warning: Had to discard a playback frame (your
application is buggy and/or got xruns)
13:54:00.334          speex  warning: Auto-filling the buffer (your
application is buggy and/or got xruns)
13:54:00.380          speex  warning: Had to discard a playback frame (your
application is buggy and/or got xruns)
13:54:00.555          speex  warning: Auto-filling the buffer (your
application is buggy and/or got xruns)
13:54:00.642          speex  warning: Had to discard a playback frame (your
application is buggy and/or got xruns)
13:54:00.776          speex  warning: Auto-filling the buffer (your
application is buggy and/or got xruns)
13:54:00.963          speex  warning: Had to discard a playback frame (your
application is buggy and/or got xruns)
13:54:01.200          speex  warning: Auto-filling the buffer (your
application is buggy and/or got xruns)
13:54:01.270          speex  warning: Had to discard a playback frame (your
application is buggy and/or got xruns)
13:54:01.437          speex  warning: Auto-filling the buffer (your
application is buggy and/or got xruns)
13:54:01.511          speex  warning: Had to discard a playback frame (your
application is buggy and/or got xruns)
13:54:01.537          speex  warning: Auto-filling the buffer (your
application is buggy and/or got xruns)
13:54:01.613          speex  warning: Auto-filling the buffer (your
application is buggy and/or got xruns)
13:54:01.631          speex  warning: Had to discard a playback frame (your
application is buggy and/or got xruns)
13:54:01.644          speex  warning: Had to discard a playback frame (your
application is buggy and/or got xruns)
13:54:01.768          speex  warning: Had to discard a playback frame (your
application is buggy and/or got xruns)
13:54:01.799          speex !warning: No playback frame available (your
application is buggy and/or got xruns)
13:54:01.810          speex !warning: Auto-filling the buffer (your
application is buggy and/or got xruns)
13:54:01.861   strm0xc49be4  Jitter buffer empty (prefetch=0), plc invoked
13:54:01.867 sip_endpoint.c !Processing incoming message: Request msg
BYE/cseq=102 (rdata0xbf126c)
13:54:01.869   pjsua_core.c  .RX 565 bytes Request msg BYE/cseq=102
(rdata0xbf126c) from UDP 192.168.1.40:5060:
BYE sip:511 at 192.168.1.120:5060;ob SIP/2.0
Via: SIP/2.0/UDP 192.168.1.40:5060;branch=z9hG4bK09a0ac5a;rport
Max-Forwards: 70
From: sip:502 at raspbx;tag=as5b7281ba
To: sip:511 at raspbx;tag=Qn71ss84d4keesGybUw4EyodEcXtVwTz
Call-ID: qF3.50nrPaYalZJhk-h3463jTuv0Uuk0
CSeq: 102 BYE
User-Agent: FPBX-13.0.98(11.21.0)
Proxy-Authorization: Digest username="511", realm="asterisk",
algorithm=MD5, uri="sip:raspbx", nonce="0b35fab6",
response="a0afa939a199cdfdda39b0b9f57fa58b"
X-Asterisk-HangupCause: Normal Clearing
X-Asterisk-HangupCauseCode: 16
Content-Length: 0


--end msg--
13:54:01.872    dlg0xc3773c  .Received Request msg BYE/cseq=102
(rdata0xbf126c)
13:54:01.874    tsx0xc49014  ...Transaction created for Request msg
BYE/cseq=102 (rdata0xbf126c)
13:54:01.875    tsx0xc49014  ..Incoming Request msg BYE/cseq=102
(rdata0xbf126c) in state Null
13:54:01.876    tsx0xc49014  ...State changed from Null to Trying,
event=RX_MSG
13:54:01.876    dlg0xc3773c  ....Transaction tsx0xc49014 state changed to
Trying
13:54:01.877       endpoint  .....Response msg 200/BYE/cseq=102
(tdta0xbf3dc0) created
13:54:01.884    dlg0xc3773c  ......Sending Response msg 200/BYE/cseq=102
(tdta0xbf3dc0)
13:54:01.886    tsx0xc49014  ......Sending Response msg 200/BYE/cseq=102
(tdta0xbf3dc0) in state Trying
13:54:01.887   pjsua_core.c  .......TX 286 bytes Response msg
200/BYE/cseq=102 (tdta0xbf3dc0) to UDP 192.168.1.40:5060:
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.1.40:5060
;rport=5060;received=192.168.1.40;branch=z9hG4bK09a0ac5a
Call-ID: qF3.50nrPaYalZJhk-h3463jTuv0Uuk0
From: <sip:502 at raspbx>;tag=as5b7281ba
To: <sip:511 at raspbx>;tag=Qn71ss84d4keesGybUw4EyodEcXtVwTz
CSeq: 102 BYE
Content-Length:  0


--end msg--
13:54:01.891    tsx0xc49014  .......State changed from Trying to Completed,
event=TX_MSG
13:54:01.892    dlg0xc3773c  ........Transaction tsx0xc49014 state changed
to Completed
13:54:01.904            APP  ......Call 0 state=DISCONNCTD
13:54:01.906  pjsua_media.c  ......Call 0: deinitializing media..
13:54:01.909   strm0xc49be4  ........JB summary:
  size=0/eff=0 prefetch=0 level=4
  delay (min/max/avg/dev)=20/80/30/12 ms
  burst (min/max/avg/dev)=2/4/2/0 frames
  lost=0 discard=0 empty=2
13:54:01.912  pjsua_media.c  ........Media stream call00:0 is destroyed
13:54:01.914   tdta0xc4db10  .....Destroying txdata Request msg
ACK/cseq=19592 (tdta0xc4db10)
13:54:01.916   tdta0xc3d1e0 !.....Destroying txdata Request msg
INVITE/cseq=19591 (tdta0xc3d1e0)
13:54:01.917    dlg0xc3773c  ......Session count dec to 3 by mod-invite
13:54:01.915          speex !warning: Auto-filling the buffer (your
application is buggy and/or got xruns)
13:54:01.921          speex !warning: Had to discard a playback frame (your
application is buggy and/or got xruns)
13:54:01.922          speex  warning: Had to discard a playback frame (your
application is buggy and/or got xruns)
13:54:01.936          speex  warning: Had to discard a playback frame (your
application is buggy and/or got xruns)
13:54:01.979          speex  warning: Auto-filling the buffer (your
application is buggy and/or got xruns)
13:54:02.037          speex  warning: Had to discard a playback frame (your
application is buggy and/or got xruns)
13:54:02.059          speex  warning: Auto-filling the buffer (your
application is buggy and/or got xruns)
13:54:02.358          speex  warning: Had to discard a playback frame (your
application is buggy and/or got xruns)
13:54:02.400          speex  warning: Auto-filling the buffer (your
application is buggy and/or got xruns)
13:54:02.635          speex  warning: Had to discard a playback frame (your
application is buggy and/or got xruns)
13:54:02.716          speex !warning: No playback frame available (your
application is buggy and/or got xruns)
13:54:02.720          speex !warning: Auto-filling the buffer (your
application is buggy and/or got xruns)
13:54:02.908    pjsua_aud.c !Closing sound device after idle for 1 second(s)
13:54:02.910    pjsua_aud.c  .Closing default:CARD=Device sound playback
device and default:CARD=Device sound capture device
q
13:54:04.568   pjsua_core.c !Shutting down, flags=0...
13:54:04.569   pjsua_core.c  PJSUA state changed: RUNNING --> CLOSING
13:54:04.574   pjsua_call.c  .Hangup all calls..
13:54:04.575  pjsua_media.c  .Call 0: deinitializing media..
13:54:04.577   pjsua_pres.c  .Shutting down presence..
13:54:04.578    pjsua_acc.c  .Acc 0: setting unregistration..
13:54:04.579       endpoint  ..Request msg REGISTER/cseq=47842
(tdta0xbf1258) created.
13:54:04.580    tsx0xbf4e2c  ...Transaction created for Request msg
REGISTER/cseq=47843 (tdta0xbf1258)
13:54:04.582    tsx0xbf4e2c  ..Sending Request msg REGISTER/cseq=47843
(tdta0xbf1258) in state Null
13:54:04.582  sip_resolve.c  ...DNS resolver not available, target
'raspbx:0' type=Unspecified will be resolved with getaddrinfo()
13:54:04.586  sip_resolve.c  ...Target 'raspbx:0' type=Unspecified resolved
to '192.168.1.40:5060' type=UDP (UDP transport)
13:54:04.587   pjsua_core.c  ...TX 363 bytes Request msg
REGISTER/cseq=47843 (tdta0xbf1258) to UDP 192.168.1.40:5060:
REGISTER sip:raspbx SIP/2.0
Via: SIP/2.0/UDP 192.168.1.120:5060
;rport;branch=z9hG4bKPjdZxzHLF2U1nuelK2RwUrFHaDnOw3Lqc2
Max-Forwards: 70
From: <sip:511 at raspbx>;tag=0wL.b5MzXpIJdnAZRPSKiZj4zKyxUBjL
To: <sip:511 at raspbx>
Call-ID: 9V1ox-mHiBZCYvDoVuu6ZDlSGCo7h9p1
CSeq: 47843 REGISTER
Contact: <sip:511 at 192.168.1.120:5060;ob>
Expires: 0
Content-Length:  0


--end msg--
13:54:04.589    tsx0xbf4e2c  ...State changed from Null to Calling,
event=TX_MSG
13:54:04.589    pjsua_acc.c  ..Acc 0: Unregistration sent
13:54:04.591 sip_endpoint.c  .Processing incoming message: Response msg
401/REGISTER/cseq=47843 (rdata0xc3fbb4)
13:54:04.591   pjsua_core.c  ..RX 557 bytes Response msg
401/REGISTER/cseq=47843 (rdata0xc3fbb4) from UDP 192.168.1.40:5060:
SIP/2.0 401 Unauthorized
Via: SIP/2.0/UDP 192.168.1.120:5060
;branch=z9hG4bKPjdZxzHLF2U1nuelK2RwUrFHaDnOw3Lqc2;received=192.168.1.120;rport=5060
From: <sip:511 at raspbx>;tag=0wL.b5MzXpIJdnAZRPSKiZj4zKyxUBjL
To: <sip:511 at raspbx>;tag=as333960f3
Call-ID: 9V1ox-mHiBZCYvDoVuu6ZDlSGCo7h9p1
CSeq: 47843 REGISTER
Server: FPBX-13.0.98(11.21.0)
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO,
PUBLISH, MESSAGE
Supported: replaces, timer
WWW-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="400ad4b5"
Content-Length: 0


--end msg--
13:54:04.592    tsx0xbf4e2c  ..Incoming Response msg
401/REGISTER/cseq=47843 (rdata0xc3fbb4) in state Calling
13:54:04.592    tsx0xbf4e2c  ...State changed from Calling to Completed,
event=RX_MSG
13:54:04.592    tsx0xc481f4  .....Transaction created for Request msg
REGISTER/cseq=47844 (tdta0xbf1258)
13:54:04.593    tsx0xc481f4  ....Sending Request msg REGISTER/cseq=47844
(tdta0xbf1258) in state Null
13:54:04.595       endpoint  .....Request msg REGISTER/cseq=47844
(tdta0xbf1258): skipping target resolution because address is already set
13:54:04.596   pjsua_core.c  .....TX 515 bytes Request msg
REGISTER/cseq=47844 (tdta0xbf1258) to UDP 192.168.1.40:5060:
REGISTER sip:raspbx SIP/2.0
Via: SIP/2.0/UDP 192.168.1.120:5060
;rport;branch=z9hG4bKPjYfrGNCf3X2QKgM-48bH19v6Xo1sTQec2
Max-Forwards: 70
From: <sip:511 at raspbx>;tag=0wL.b5MzXpIJdnAZRPSKiZj4zKyxUBjL
To: <sip:511 at raspbx>
Call-ID: 9V1ox-mHiBZCYvDoVuu6ZDlSGCo7h9p1
CSeq: 47844 REGISTER
Contact: <sip:511 at 192.168.1.120:5060;ob>
Expires: 0
Authorization: Digest username="511", realm="asterisk", nonce="400ad4b5",
uri="sip:raspbx", response="e4eef128c83d7c5640951aa90c31d30d", algorithm=MD5
Content-Length:  0


--end msg--
13:54:04.596    tsx0xc481f4  .....State changed from Null to Calling,
event=TX_MSG
13:54:04.599 sip_endpoint.c  .Processing incoming message: Response msg
200/REGISTER/cseq=47844 (rdata0xc3fbb4)
13:54:04.599   pjsua_core.c  ..RX 520 bytes Response msg
200/REGISTER/cseq=47844 (rdata0xc3fbb4) from UDP 192.168.1.40:5060:
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.1.120:5060
;branch=z9hG4bKPjYfrGNCf3X2QKgM-48bH19v6Xo1sTQec2;received=192.168.1.120;rport=5060
From: <sip:511 at raspbx>;tag=0wL.b5MzXpIJdnAZRPSKiZj4zKyxUBjL
To: <sip:511 at raspbx>;tag=as333960f3
Call-ID: 9V1ox-mHiBZCYvDoVuu6ZDlSGCo7h9p1
CSeq: 47844 REGISTER
Server: FPBX-13.0.98(11.21.0)
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO,
PUBLISH, MESSAGE
Supported: replaces, timer
Expires: 0
Date: Tue, 12 Apr 2016 13:54:04 GMT
Content-Length: 0


--end msg--
13:54:04.600    tsx0xc481f4  ..Incoming Response msg
200/REGISTER/cseq=47844 (rdata0xc3fbb4) in state Calling
13:54:04.600    tsx0xc481f4  ...State changed from Calling to Completed,
event=RX_MSG
13:54:04.600    pjsua_acc.c  .....sip:511 at raspbx: unregistration success
13:54:05.595   pjsua_core.c  .Destroying...
13:54:05.596  pjsua_media.c  .Shutting down media..
13:54:05.823 sip_endpoint.c  .Destroying endpoing instance..
13:54:05.824 sip_transactio  .Stopping transaction layer module
13:54:05.825    tsx0xbf4e2c  .Request to terminate transaction
13:54:05.827    tsx0xbf4e2c  ..State changed from Completed to Terminated,
event=USER
13:54:05.828    tsx0xbf4e2c  .Transaction destroyed!
13:54:05.829    tsx0xc49014  .Request to terminate transaction
13:54:05.829    tsx0xc49014  ..State changed from Completed to Terminated,
event=USER
13:54:05.829    dlg0xc3773c  ...Transaction tsx0xc49014 state changed to
Terminated
13:54:05.830   tdta0xbf3dc0  .Destroying txdata Response msg
200/BYE/cseq=102 (tdta0xbf3dc0)
13:54:05.831    tsx0xc49014  .Transaction destroyed!
13:54:05.831    tsx0xc3f1f4  .Request to terminate transaction
13:54:05.831    tsx0xc3f1f4  ..State changed from Completed to Terminated,
event=USER
13:54:05.832    dlg0xc3773c  ...Transaction tsx0xc3f1f4 state changed to
Terminated
13:54:05.833    dlg0xc3773c  ....Dialog destroyed
13:54:05.833   tdta0xc45240  .Destroying txdata Request msg ACK/cseq=19590
(tdta0xc45240)
13:54:05.833    tsx0xc3f1f4  .Transaction destroyed!
13:54:05.835    tsx0xc42b54  .Request to terminate transaction
13:54:05.835    tsx0xc42b54  ..State changed from Completed to Terminated,
event=USER
13:54:05.835   tdta0xc41ae8  .Destroying txdata Response msg
200/NOTIFY/cseq=102 (tdta0xc41ae8)
13:54:05.836    tsx0xc42b54  .Transaction destroyed!
13:54:05.836    tsx0xc481f4  .Request to terminate transaction
13:54:05.836    tsx0xc481f4  ..State changed from Completed to Terminated,
event=USER
13:54:05.836   tdta0xbf1258  .Destroying txdata Request msg
REGISTER/cseq=47844 (tdta0xbf1258)
13:54:05.839    tsx0xc481f4  .Transaction destroyed!
13:54:05.840 sip_transactio  .Stopped transaction layer module
13:54:05.840 sip_endpoint.c  .Module "mod-unsolicited-mwi" unregistered
13:54:05.840 sip_endpoint.c  .Module "mod-pjsua-options" unregistered
13:54:05.840 sip_endpoint.c  .Module "mod-pjsua-im" unregistered
13:54:05.840 sip_endpoint.c  .Module "mod-pjsua-pres" unregistered
13:54:05.840 sip_endpoint.c  .Module "mod-pjsua" unregistered
13:54:05.840 sip_endpoint.c  .Module "mod-stateful-util" unregistered
13:54:05.840 sip_endpoint.c  .Module "mod-refer" unregistered
13:54:05.841 sip_endpoint.c  .Module "mod-mwi" unregistered
13:54:05.841 sip_endpoint.c  .Module "mod-presence" unregistered
13:54:05.841 sip_endpoint.c  .Module "mod-evsub" unregistered
13:54:05.841 sip_endpoint.c  .Module "mod-invite" unregistered
13:54:05.841 sip_endpoint.c  .Module "mod-100rel" unregistered
13:54:05.841 sip_endpoint.c  .Module "mod-ua" unregistered
13:54:05.842 sip_transactio  .Transaction layer module destroyed
13:54:05.842 sip_endpoint.c  .Module "mod-tsx-layer" unregistered
13:54:05.842 sip_endpoint.c  .Module "mod-msg-print" unregistered
13:54:05.842 sip_endpoint.c  .Module "mod-pjsua-log" unregistered
13:54:05.842 sip_transport.  .Destroying transport manager
13:54:05.844    udp0xbefc38  .SIP UDP transport destroyed
13:54:05.844 sip_endpoint.c  .Endpoint 0xbb2d2c destroyed
13:54:05.844   pjsua_core.c  .PJSUA state changed: CLOSING --> NULL
13:54:05.845   pjsua_core.c  .PJSUA destroyed...


*Alexandre Gonçalves*

............................................................................................................................
Email: alexandre at silvagoncalves.com

2016-04-12 14:42 GMT+01:00 Bill Gardner <billg at wavearts.com>:

> Please attach a complete log. - Bill
>
> On 4/11/2016 9:31 PM, Alexandre Gonçalves wrote:
>
> I followed your suggestion, and indeed the EC is created:
>
> 00:14:30.374    ec0x16adf18  ...Creating AEC
> 00:14:30.382    ec0x16adf18  ...AEC created, clock_rate=16000, channel=1,
> samples per frame=320, tail length=200 ms, latency=0 ms
>
>
> However the logs about speex are still appearing:
>
> 01:23:25.435   tsx0x171eca4  .Incoming Response msg 401/REGISTER/cseq=762
> (rdata0x16cb26c) in state Completed
> 01:23:25.454          speex !warning: Had to discard a playback frame
> (your application is buggy and/or got xruns)
> 01:23:25.501          speex  warning: Auto-filling the buffer (your
> application is buggy and/or got xruns)
> 01:23:25.517          speex  warning: Had to discard a playback frame
> (your application is buggy and/or got xruns)
> 01:23:25.771          speex !warning: No playback frame available (your
> application is buggy and/or got xruns)
> 01:23:25.774          speex !warning: internal playback buffer corruption?
> 01:23:25.774          speex !warning: Auto-filling the buffer (your
> application is buggy and/or got xruns)
> 01:23:26.380          speex !warning: Auto-filling the buffer (your
> application is buggy and/or got xruns)
> 01:23:26.444          speex  warning: Had to discard a playback frame
> (your application is buggy and/or got xruns)
> 01:23:27.799          speex  warning: Auto-filling the buffer (your
> application is buggy and/or got xruns)
> 01:23:27.851          speex  warning: Had to discard a playback frame
> (your application is buggy and/or got xruns)
> 01:23:28.181   tsx0x16ce62c !Timeout timer event
> 01:23:28.185   tsx0x16ce62c  .State changed from Completed to Terminated,
> event=TIMER
> 01:23:28.191   tsx0x16ce62c  Timeout timer event
> 01:23:28.193   tsx0x16ce62c  .State changed from Terminated to Destroyed,
> event=TIMER
> 01:23:28.194   tsx0x16ce62c  Transaction destroyed!
> 01:23:28.206          speex !warning: Auto-filling the buffer (your
> application is buggy and/or got xruns)
> 01:23:28.287          speex  warning: Had to discard a playback frame
> (your application is buggy and/or got xruns)
> 01:23:28.583          speex  warning: Had to discard a playback frame
> (your application is buggy and/or got xruns)
> 01:23:28.616          speex  warning: Auto-filling the buffer (your
> application is buggy and/or got xruns)
> 01:23:28.807          speex  warning: Had to discard a playback frame
> (your application is buggy and/or got xruns)
> 01:23:29.739          speex  warning: Auto-filling the buffer (your
> application is buggy and/or got xruns)
> 01:23:29.827          speex  warning: Had to discard a playback frame
> (your application is buggy and/or got xruns)
> 01:23:30.378   tsx0x171eca4 !Timeout timer event
> 01:23:30.380   tsx0x171eca4  .State changed from Completed to Terminated,
> event=TIMER
> 01:23:30.385   tsx0x171eca4  Timeout timer event
> 01:23:30.386   tsx0x171eca4  .State changed from Terminated to Destroyed,
> event=TIMER
> 01:23:30.388  tdta0x16d74a0  ..Destroying txdata Request msg
> REGISTER/cseq=762 (tdta0x16d74a0)
> 01:23:30.398   tsx0x171eca4  Transaction destroyed!
> 01:23:31.944          speex !warning: Auto-filling the buffer (your
> application is buggy and/or got xruns)
> 01:23:32.134          speex  warning: Had to discard a playback frame
> (your application is buggy and/or got xruns)
> 01:23:32.280          speex  warning: Auto-filling the buffer (your
> application is buggy and/or got xruns)
> 01:23:32.312          speex  warning: Had to discard a playback frame
> (your application is buggy and/or got xruns)
> 01:23:32.517   silencedet.c  Starting silence (level=9 threshold=22)
>
>
> There is still echo, in other words on the remote party I hear my own
> voice.
>
> Regards.
>
>
> *Alexandre Gonçalves*
>
>
> ............................................................................................................................
> Email:  <alexandre at silvagoncalves.com>alexandre at silvagoncalves.com
>
> 2016-04-11 20:14 GMT+01:00 Bill Gardner <billg at wavearts.com>:
>
>> Try removing your code that creates the EC, then run again and see if the
>> log shows that an EC was created. - Bill
>>
>>
>> On 4/11/2016 11:16 AM, Alexandre Gonçalves wrote:
>>
>> Yes it does. The device is handsfree.
>>
>> Thanks.
>>
>> *Alexandre Gonçalves*
>>
>>
>> ............................................................................................................................
>> Email:  <alexandre at silvagoncalves.com>alexandre at silvagoncalves.com
>>
>> 2016-04-11 16:09 GMT+01:00 Bill Gardner < <billg at wavearts.com>
>> billg at wavearts.com>:
>>
>>> Hi Alexandre,
>>>
>>> I don't know what the problem is, but you shouldn't need to create a
>>> separate EC object. pjsua_init will create an echo canceller and connect it
>>> to the sound port.
>>>
>>> Does the call work without EC?
>>>
>>> Regards,
>>>
>>> Bill
>>>
>>> On 4/11/2016 10:33 AM, Alexandre Gonçalves wrote:
>>>
>>> Hello,
>>>
>>> I've made a small C application to run on a linux machine, based on
>>> "Simple PJSUA" example.
>>>
>>> What I need to add is echo cancellation, and I tryed to do it like the
>>> code attached:
>>>
>>> But according to the logs I get it seems that something is missing. I
>>> suspect it's the manipulation of the capture and playback frames, but I
>>> have no idea how to do it!
>>>
>>>
>>> #include <pjsua-lib/pjsua.h>
>>> #define THIS_FILE "APP"
>>>
>>> #define SIP_DOMAIN "raspbx"
>>> #define SIP_USER "511"
>>> #define SIP_PASSWD "aaa511"
>>> #define SIP_REALM "asterisk"
>>> #define SIP_SCHEME "digest"
>>>
>>>
>>>
>>> pjmedia_echo_state *ec;
>>> pjmedia_frame play_frame, rec_frame;
>>>
>>> /* Callback called by the library upon receiving incoming call */
>>> static void on_incoming_call(pjsua_acc_id acc_id, pjsua_call_id call_id,
>>>         pjsip_rx_data *rdata) {
>>>     pjsua_call_info ci;
>>>
>>>     PJ_UNUSED_ARG(acc_id);
>>>     PJ_UNUSED_ARG(rdata);
>>>
>>>     pjsua_call_get_info(call_id, &ci);
>>>
>>>     PJ_LOG(2, (THIS_FILE, "Incoming call from %.*s!!",
>>>             (int) ci.remote_info.slen,
>>>             ci.remote_info.ptr));
>>>
>>>     /* Automatically answer incoming calls with 200/OK */
>>>     pjsua_call_answer(call_id, 200, NULL, NULL);
>>> }
>>>
>>> /* Callback called by the library when call's state has changed */
>>> static void on_call_state(pjsua_call_id call_id, pjsip_event *e) {
>>>     pjsua_call_info ci;
>>>
>>>     PJ_UNUSED_ARG(e);
>>>
>>>     pjsua_call_get_info(call_id, &ci);
>>>     PJ_LOG(2, (THIS_FILE, "Call %d state=%.*s", call_id,
>>>             (int) ci.state_text.slen,
>>>             ci.state_text.ptr));
>>>
>>> }
>>>
>>> /* Callback called by the library when call's media state has changed */
>>> static void on_call_media_state(pjsua_call_id call_id) {
>>>     pjsua_call_info ci;
>>>
>>>     pjsua_call_get_info(call_id, &ci);
>>>
>>>     if (ci.media_status == PJSUA_CALL_MEDIA_ACTIVE) {
>>>         // When media is active, connect call to sound device.
>>>         pjsua_conf_connect(ci.conf_slot, 0);
>>>         pjsua_conf_connect(0, ci.conf_slot);
>>>     }
>>> }
>>>
>>> /* Display error and exit application */
>>> static void error_exit(const char *title, pj_status_t status) {
>>>     pjsua_perror(THIS_FILE, title, status);
>>>     pjsua_destroy();
>>>     exit(1);
>>> }
>>>
>>> /*
>>>  * main()
>>>  *
>>>  * argv[1] may contain URL to call.
>>>  */
>>> int main(int argc, char *argv[]) {
>>>     pjsua_acc_id acc_id;
>>>     pj_status_t status;
>>>
>>>
>>>
>>>     /* Create pjsua first! */
>>>     status = pjsua_create();
>>>     if (status != PJ_SUCCESS) error_exit("Error in pjsua_create()",
>>> status);
>>>
>>>
>>>     /* Init pjsua */
>>>     {
>>>         pjsua_config cfg;
>>>         pjsua_logging_config log_cfg;
>>>         pjsua_media_config media_cfg;
>>>
>>>         pjsua_config_default(&cfg);
>>>         cfg.cb.on_incoming_call = &on_incoming_call;
>>>         cfg.cb.on_call_media_state = &on_call_media_state;
>>>         cfg.cb.on_call_state = &on_call_state;
>>>         cfg.max_calls = 1;
>>>
>>>         pjsua_logging_config_default(&log_cfg);
>>>         log_cfg.console_level = 6;
>>>
>>>         pjsua_media_config_default(&media_cfg);
>>>         media_cfg.ec_options = PJMEDIA_ECHO_DEFAULT;
>>>         media_cfg.ec_tail_len = 250;
>>>
>>>
>>>         status = pjsua_init(&cfg, &log_cfg, &media_cfg);
>>>         // status = pjsua_init(&cfg, &log_cfg, NULL);
>>>
>>>         if (status != PJ_SUCCESS) error_exit("Error in pjsua_init()",
>>> status);
>>>
>>>         pj_pool_t *pool = pjsua_pool_create("my_echo", 1000, 1000);
>>>         status = pjmedia_echo_create(pool, 16000, 320, 500, 500,
>>> PJMEDIA_ECHO_DEFAULT, &ec);
>>>         play_frame.buf = pj_pool_alloc(pool, 320);
>>>         rec_frame.buf = pj_pool_alloc(pool, 320);
>>>
>>>     }
>>>
>>>     /* Add UDP transport. */
>>>     {
>>>         pjsua_transport_config cfg;
>>>
>>>         pjsua_transport_config_default(&cfg);
>>>         cfg.port = 5060;
>>>         status = pjsua_transport_create(PJSIP_TRANSPORT_UDP, &cfg, NULL);
>>>         if (status != PJ_SUCCESS) error_exit("Error creating transport",
>>> status);
>>>     }
>>>
>>>     /* Initialization is done, now start pjsua */
>>>     status = pjsua_start();
>>>     if (status != PJ_SUCCESS) error_exit("Error starting pjsua", status);
>>>
>>>     /* Register to SIP server by creating SIP account. */
>>>     {
>>>         pjsua_acc_config cfg;
>>>
>>>         pjsua_acc_config_default(&cfg);
>>>         cfg.id = pj_str("sip:" SIP_USER "@" SIP_DOMAIN);
>>>         cfg.reg_uri = pj_str("sip:" SIP_DOMAIN);
>>>         cfg.cred_count = 1;
>>>         cfg.cred_info[0].realm = pj_str(SIP_REALM);
>>>         cfg.cred_info[0].scheme = pj_str(SIP_SCHEME);
>>>         cfg.cred_info[0].username = pj_str(SIP_USER);
>>>         cfg.cred_info[0].data_type = PJSIP_CRED_DATA_PLAIN_PASSWD;
>>>         cfg.cred_info[0].data = pj_str(SIP_PASSWD);
>>>
>>>         status = pjsua_acc_add(&cfg, PJ_TRUE, &acc_id);
>>>         if (status != PJ_SUCCESS) error_exit("Error adding account",
>>> status);
>>>     }
>>>
>>>     if (argc > 1) {
>>>         pj_str_t uri = pj_str(argv[1]);
>>>         status = pjsua_call_make_call(acc_id, &uri, 0, NULL, NULL, NULL);
>>>         if (status != PJ_SUCCESS) error_exit("Error making call",
>>> status);
>>>     }
>>>
>>>
>>>     char option[10];
>>>     while (1) {
>>>
>>>         if (fgets(option, sizeof (option), stdin) == NULL) {
>>>             puts("EOF while reading stdin, will quit now..");
>>>             break;
>>>         }
>>>
>>>         if (option[0] == 'q')
>>>             break;
>>>
>>>     }
>>>
>>>     /* Destroy pjsua */
>>>     pjsua_destroy();
>>>
>>>     return 0;
>>> }
>>>
>>>
>>> The logs:
>>>
>>> 16:10:45.203          speex !warning: No playback frame available (your
>>> application is buggy and/or got xruns)
>>> 16:10:45.207          speex !warning: Auto-filling the buffer (your
>>> application is buggy and/or got xruns)
>>> 16:10:45.216          speex !warning: internal playback buffer
>>> corruption?
>>> 16:10:45.221          speex !warning: Auto-filling the buffer (your
>>> application is buggy and/or got xruns)
>>> 16:10:45.279          speex  warning: Had to discard a playback frame
>>> (your application is buggy and/or got xruns)
>>> 16:10:45.393          speex  warning: Auto-filling the buffer (your
>>> application is buggy and/or got xruns)
>>> 16:10:45.462          speex  warning: Had to discard a playback frame
>>> (your application is buggy and/or got xruns)
>>> 16:10:45.522          speex  warning: Auto-filling the buffer (your
>>> application is buggy and/or got xruns)
>>> 16:10:45.562          speex  warning: Had to discard a playback frame
>>> (your application is buggy and/or got xruns)
>>>
>>>
>>> Pjsip version: 2.4
>>>
>>>
>>> Can anyone help out?
>>>
>>>
>>> Thanks.
>>>
>>>
>>>
>>>
>>> *Alexandre Gonçalves*
>>>
>>>
>>> ............................................................................................................................
>>> Email:  <alexandre at silvagoncalves.com>alexandre at silvagoncalves.com
>>>
>>>
>>> _______________________________________________
>>> Visit our blog: http://blog.pjsip.org
>>>
>>> pjsip mailing listpjsip at lists.pjsip.orghttp://lists.pjsip.org/mailman/listinfo/pjsip_lists.pjsip.org
>>>
>>>
>>>
>>> _______________________________________________
>>> Visit our blog: http://blog.pjsip.org
>>>
>>> pjsip mailing list
>>> pjsip at lists.pjsip.org
>>> http://lists.pjsip.org/mailman/listinfo/pjsip_lists.pjsip.org
>>>
>>>
>>
>>
>> _______________________________________________
>> Visit our blog: http://blog.pjsip.org
>>
>> pjsip mailing listpjsip at lists.pjsip.orghttp://lists.pjsip.org/mailman/listinfo/pjsip_lists.pjsip.org
>>
>>
>>
>> _______________________________________________
>> Visit our blog: http://blog.pjsip.org
>>
>> pjsip mailing list
>> pjsip at lists.pjsip.org
>> http://lists.pjsip.org/mailman/listinfo/pjsip_lists.pjsip.org
>>
>>
>
>
> _______________________________________________
> Visit our blog: http://blog.pjsip.org
>
> pjsip mailing listpjsip at lists.pjsip.orghttp://lists.pjsip.org/mailman/listinfo/pjsip_lists.pjsip.org
>
>
>
> _______________________________________________
> Visit our blog: http://blog.pjsip.org
>
> pjsip mailing list
> pjsip at lists.pjsip.org
> http://lists.pjsip.org/mailman/listinfo/pjsip_lists.pjsip.org
>
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.pjsip.org/pipermail/pjsip_lists.pjsip.org/attachments/20160412/9548e88f/attachment-0002.html>


More information about the pjsip mailing list