Re: Accoustic echo cancelation

[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index]

 

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@raspbx
13:53:51.869    pjsua_acc.c  .Account sip:511@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@raspbx>;tag=s96E7GKkGb5ti9m603K6miDa9.i8Cow5
To: <sip:511@raspbx>
Call-ID: 9V1ox-mHiBZCYvDoVuu6ZDlSGCo7h9p1
CSeq: 47841 REGISTER
Contact: <sip:511@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@raspbx>;tag=s96E7GKkGb5ti9m603K6miDa9.i8Cow5
To: <sip:511@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@raspbx>;tag=s96E7GKkGb5ti9m603K6miDa9.i8Cow5
To: <sip:511@raspbx>
Call-ID: 9V1ox-mHiBZCYvDoVuu6ZDlSGCo7h9p1
CSeq: 47842 REGISTER
Contact: <sip:511@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@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@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@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@192.168.1.40>;tag=as0df0e1a8
To: <sip:511@192.168.1.120:5060;ob>
Contact: <sip:Unknown@192.168.1.40:5060>
Call-ID: 15c7a8267bbf71235fa859e4431f2326@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="">
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="">
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@raspbx SIP/2.0
Via: SIP/2.0/UDP 192.168.1.120:5060;rport;branch=z9hG4bKPjfvZU.XrhkVa5zrKBI0Wqx1ZJrzL5cf6R
Max-Forwards: 70
From: sip:511@raspbx;tag=Qn71ss84d4keesGybUw4EyodEcXtVwTz
To: sip:502@raspbx
Contact: <sip:511@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
From: "Unknown" <sip:Unknown@192.168.1.40>;tag=as0df0e1a8
To: <sip:511@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@raspbx>;tag=s96E7GKkGb5ti9m603K6miDa9.i8Cow5
To: <sip:511@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@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@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@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@192.168.1.40>;tag=as43b2ff19
To: <sip:511@192.168.1.120:5060;ob>
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@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
From: "Unknown" <sip:Unknown@192.168.1.40>;tag=as43b2ff19
To: <sip:511@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@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@192.168.1.40>;tag=as43b2ff19
To: <sip:511@192.168.1.120:5060;ob>
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@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
From: "Unknown" <sip:Unknown@192.168.1.40>;tag=as43b2ff19
To: <sip:511@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@raspbx;tag=Qn71ss84d4keesGybUw4EyodEcXtVwTz
To: sip:502@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@raspbx SIP/2.0
Via: SIP/2.0/UDP 192.168.1.120:5060;rport;branch=z9hG4bKPjfvZU.XrhkVa5zrKBI0Wqx1ZJrzL5cf6R
Max-Forwards: 70
From: sip:511@raspbx;tag=Qn71ss84d4keesGybUw4EyodEcXtVwTz
To: sip:502@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@raspbx SIP/2.0
Via: SIP/2.0/UDP 192.168.1.120:5060;rport;branch=z9hG4bKPjQGeYjC34n2OypR2mI9I8B7OQfe9n9xMb
Max-Forwards: 70
From: sip:511@raspbx;tag=Qn71ss84d4keesGybUw4EyodEcXtVwTz
To: sip:502@raspbx
Contact: <sip:511@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@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@raspbx;tag=Qn71ss84d4keesGybUw4EyodEcXtVwTz
To: sip:502@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
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@raspbx;tag=Qn71ss84d4keesGybUw4EyodEcXtVwTz
To: sip:502@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
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@raspbx;tag=Qn71ss84d4keesGybUw4EyodEcXtVwTz
To: sip:502@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
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@raspbx;tag=Qn71ss84d4keesGybUw4EyodEcXtVwTz
To: sip:502@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
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@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@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:
Via: SIP/2.0/UDP 192.168.1.120:5060;rport;branch=z9hG4bKPjxH-YvcJ.09t3v6k8dCfPxARll20ckMiG
Max-Forwards: 70
From: sip:511@raspbx;tag=Qn71ss84d4keesGybUw4EyodEcXtVwTz
To: sip:502@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:
Via: SIP/2.0/UDP 192.168.1.120:5060;rport;branch=z9hG4bKPjnM.jze3e2o2ebD2-GIkiCsPZlMAMLf1o
Max-Forwards: 70
From: sip:511@raspbx;tag=Qn71ss84d4keesGybUw4EyodEcXtVwTz
To: sip:502@raspbx;tag=as5b7281ba
Contact: <sip:511@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@raspbx;tag=Qn71ss84d4keesGybUw4EyodEcXtVwTz
To: sip:502@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
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@raspbx;tag=Qn71ss84d4keesGybUw4EyodEcXtVwTz
To: sip:502@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
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:
Via: SIP/2.0/UDP 192.168.1.120:5060;rport;branch=z9hG4bKPj6nr1w0IxJ1I9.U7d1MO6fFJqmhoKe6g1
Max-Forwards: 70
From: sip:511@raspbx;tag=Qn71ss84d4keesGybUw4EyodEcXtVwTz
To: sip:502@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@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@raspbx;tag=as5b7281ba
To: sip:511@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@raspbx>;tag=as5b7281ba
To: <sip:511@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@raspbx>;tag=0wL.b5MzXpIJdnAZRPSKiZj4zKyxUBjL
To: <sip:511@raspbx>
Call-ID: 9V1ox-mHiBZCYvDoVuu6ZDlSGCo7h9p1
CSeq: 47843 REGISTER
Contact: <sip:511@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@raspbx>;tag=0wL.b5MzXpIJdnAZRPSKiZj4zKyxUBjL
To: <sip:511@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@raspbx>;tag=0wL.b5MzXpIJdnAZRPSKiZj4zKyxUBjL
To: <sip:511@raspbx>
Call-ID: 9V1ox-mHiBZCYvDoVuu6ZDlSGCo7h9p1
CSeq: 47844 REGISTER
Contact: <sip:511@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@raspbx>;tag=0wL.b5MzXpIJdnAZRPSKiZj4zKyxUBjL
To: <sip:511@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@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

............................................................................................................................


2016-04-12 14:42 GMT+01:00 Bill Gardner <billg@xxxxxxxxxxxx>:
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

............................................................................................................................


2016-04-11 20:14 GMT+01:00 Bill Gardner <billg@xxxxxxxxxxxx>:
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

............................................................................................................................


2016-04-11 16:09 GMT+01:00 Bill Gardner <billg@xxxxxxxxxxxx>:
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 = "">

        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

............................................................................................................................



_______________________________________________
Visit our blog: http://blog.pjsip.org

pjsip mailing list
pjsip@xxxxxxxxxxxxxxx
http://lists.pjsip.org/mailman/listinfo/pjsip_lists.pjsip.org


_______________________________________________
Visit our blog: http://blog.pjsip.org

pjsip mailing list
pjsip@xxxxxxxxxxxxxxx
http://lists.pjsip.org/mailman/listinfo/pjsip_lists.pjsip.org




_______________________________________________
Visit our blog: http://blog.pjsip.org

pjsip mailing list
pjsip@xxxxxxxxxxxxxxx
http://lists.pjsip.org/mailman/listinfo/pjsip_lists.pjsip.org


_______________________________________________
Visit our blog: http://blog.pjsip.org

pjsip mailing list
pjsip@xxxxxxxxxxxxxxx
http://lists.pjsip.org/mailman/listinfo/pjsip_lists.pjsip.org




_______________________________________________
Visit our blog: http://blog.pjsip.org

pjsip mailing list
pjsip@xxxxxxxxxxxxxxx
http://lists.pjsip.org/mailman/listinfo/pjsip_lists.pjsip.org


_______________________________________________
Visit our blog: http://blog.pjsip.org

pjsip mailing list
pjsip@xxxxxxxxxxxxxxx
http://lists.pjsip.org/mailman/listinfo/pjsip_lists.pjsip.org


_______________________________________________
Visit our blog: http://blog.pjsip.org

pjsip mailing list
pjsip@xxxxxxxxxxxxxxx
http://lists.pjsip.org/mailman/listinfo/pjsip_lists.pjsip.org
[Index of Archives]     [Asterisk Users]     [Asterisk App Development]     [Linux ARM Kernel]     [Linux ARM]     [Linux Omap]     [Fedora ARM]     [IETF Annouce]     [Security]     [Bugtraq]     [Linux]     [Linux OMAP]     [Linux MIPS]     [Linux API]
  Powered by Linux