[pjsip] Accoustic echo cancelation

Alexandre Gonçalves alexandre at silvagoncalves.com
Fri Apr 22 11:50:49 EDT 2016


Hello,

I changed to Raspberry Pi 3, and the echo situation is the same; Echo not
cancelled!

Can find in the logs any clue why is this happening?


Thanks.




15:15:51.161 os_core_unix.c !pjlib 2.4.5 for POSIX initialized
15:15:51.164 sip_endpoint.c  .Creating endpoint instance...
15:15:51.165          pjlib  .select() I/O Queue created (0x15b8bf8)
15:15:51.166 sip_endpoint.c  .Module "mod-msg-print" registered
15:15:51.166 sip_transport.  .Transport manager created.
15:15:51.167   pjsua_core.c  .PJSUA state changed: NULL --> CREATED
15:15:51.167 sip_endpoint.c  .Module "mod-pjsua-log" registered
15:15:51.168 sip_endpoint.c  .Module "mod-tsx-layer" registered
15:15:51.168 sip_endpoint.c  .Module "mod-stateful-util" registered
15:15:51.169 sip_endpoint.c  .Module "mod-ua" registered
15:15:51.169 sip_endpoint.c  .Module "mod-100rel" registered
15:15:51.170 sip_endpoint.c  .Module "mod-pjsua" registered
15:15:51.170 sip_endpoint.c  .Module "mod-invite" registered
15:15:51.265     alsa_dev.c  ..Added sound device sysdefault:CARD=ALSA
15:15:51.270     alsa_dev.c  ..Added sound device dmix:CARD=ALSA,DEV=0
15:15:51.273     alsa_dev.c  ..Added sound device dmix:CARD=ALSA,DEV=1
15:15:51.278     alsa_dev.c  ..Added sound device hw:CARD=ALSA,DEV=0
15:15:51.279     alsa_dev.c  ..Added sound device hw:CARD=ALSA,DEV=1
15:15:51.279     alsa_dev.c  ..Added sound device plughw:CARD=ALSA,DEV=0
15:15:51.280     alsa_dev.c  ..Added sound device plughw:CARD=ALSA,DEV=1
15:15:51.289     alsa_dev.c  ..Added sound device sysdefault:CARD=Device
15:15:51.291     alsa_dev.c  ..Added sound device front:CARD=Device,DEV=0
15:15:51.292     alsa_dev.c  ..Added sound device
surround21:CARD=Device,DEV=0
15:15:51.294     alsa_dev.c  ..Added sound device
surround40:CARD=Device,DEV=0
15:15:51.296     alsa_dev.c  ..Added sound device
surround41:CARD=Device,DEV=0
15:15:51.298     alsa_dev.c  ..Added sound device
surround50:CARD=Device,DEV=0
15:15:51.300     alsa_dev.c  ..Added sound device
surround51:CARD=Device,DEV=0
15:15:51.301     alsa_dev.c  ..Added sound device
surround71:CARD=Device,DEV=0
15:15:51.304     alsa_dev.c  ..Added sound device iec958:CARD=Device,DEV=0
15:15:51.309     alsa_dev.c  ..Added sound device dmix:CARD=Device,DEV=0
15:15:51.313     alsa_dev.c  ..Added sound device dsnoop:CARD=Device,DEV=0
15:15:51.314     alsa_dev.c  ..Added sound device hw:CARD=Device,DEV=0
15:15:51.314     alsa_dev.c  ..Added sound device plughw:CARD=Device,DEV=0
15:15:51.315     alsa_dev.c  ..ALSA driver found 20 devices
15:15:51.315     alsa_dev.c  ..ALSA initialized
15:15:51.315          pjlib  ..select() I/O Queue created (0x15eed6c)
15:15:51.315   conference.c  ..Creating conference bridge with 254 ports
15:15:51.315   Master/sound  ..Using delay buffer with WSOLA.
15:15:51.329 sip_endpoint.c  .Module "mod-evsub" registered
15:15:51.329 sip_endpoint.c  .Module "mod-presence" registered
15:15:51.329        evsub.c  .Event pkg "presence" registered by
mod-presence
15:15:51.329 sip_endpoint.c  .Module "mod-mwi" registered
15:15:51.329        evsub.c  .Event pkg "message-summary" registered by
mod-mwi
15:15:51.330 sip_endpoint.c  .Module "mod-refer" registered
15:15:51.330        evsub.c  .Event pkg "refer" registered by mod-refer
15:15:51.330 sip_endpoint.c  .Module "mod-pjsua-pres" registered
15:15:51.330 sip_endpoint.c  .Module "mod-pjsua-im" registered
15:15:51.330 sip_endpoint.c  .Module "mod-pjsua-options" registered
15:15:51.330   pjsua_core.c  .1 SIP worker threads created
15:15:51.330   pjsua_core.c  .pjsua version 2.4.5 for
Linux-4.1.19/armv7l/glibc-2.19 initialized
15:15:51.330   pjsua_core.c  .PJSUA state changed: CREATED --> INIT
15:15:51.331   pjsua_core.c  SIP UDP socket reachable at 192.168.1.206:5060
15:15:51.331   udp0x15d9210  SIP UDP transport started, published address
is 192.168.1.206:5060
15:15:51.331   pjsua_core.c  PJSUA state changed: INIT --> STARTING
15:15:51.331 sip_endpoint.c  .Module "mod-unsolicited-mwi" registered
15:15:51.331   pjsua_core.c  .PJSUA state changed: STARTING --> RUNNING
15:15:51.331    pjsua_acc.c  Adding account: id=sip:511 at raspbx
15:15:51.331    pjsua_acc.c  .Account sip:511 at raspbx added with id 0
15:15:51.331    pjsua_acc.c  .Acc 0: setting registration..
15:15:51.331       endpoint  ..Request msg REGISTER/cseq=8445
(tdta0x15f7748) created.
15:15:51.331   tsx0x15f87b4  ...Transaction created for Request msg
REGISTER/cseq=8446 (tdta0x15f7748)
15:15:51.331   tsx0x15f87b4  ..Sending Request msg REGISTER/cseq=8446
(tdta0x15f7748) in state Null
15:15:51.331  sip_resolve.c  ...DNS resolver not available, target
'raspbx:0' type=Unspecified will be resolved with getaddrinfo()
15:15:51.335  sip_resolve.c  ...Target 'raspbx:0' type=Unspecified resolved
to '192.168.1.40:5060' type=UDP (UDP transport)
15:15:51.335   pjsua_core.c  ...TX 462 bytes Request msg REGISTER/cseq=8446
(tdta0x15f7748) to UDP 192.168.1.40:5060:
REGISTER sip:raspbx SIP/2.0
Via: SIP/2.0/UDP 192.168.1.206:5060
;rport;branch=z9hG4bKPjfsCydZd0rmC.rZym0JPeO1Udl8Y5BaG6
Max-Forwards: 70
From: <sip:511 at raspbx>;tag=JT0sL4JEZWqfHHd9YDnOOp1Tcbmneb.b
To: <sip:511 at raspbx>
Call-ID: 1qDB9TlQQxR-djUWVFjpQpJ7OlylITVQ
CSeq: 8446 REGISTER
Contact: <sip:511 at 192.168.1.206:5060;ob>
Expires: 300
Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, SUBSCRIBE, NOTIFY,
REFER, MESSAGE, OPTIONS
Content-Length:  0


--end msg--
15:15:51.335   tsx0x15f87b4  ...State changed from Null to Calling,
event=TX_MSG
15:15:51.336    pjsua_acc.c  ..Acc 0: Registration sent
15:15:51.336   pjsua_call.c  Making call with acc #0 to sip:501 at raspbx
15:15:51.336    pjsua_aud.c  .Set sound device: capture=-1, playback=-2
15:15:51.336    pjsua_aud.c  ..Opening sound device PCM at 16000/1/20ms
15:15:51.336     alsa_dev.c  ...open_playback: Open playback device
'sysdefault:CARD=Device'
15:15:51.340 sip_endpoint.c !Processing incoming message: Response msg
401/REGISTER/cseq=8446 (rdata0x15f4bf4)
15:15:51.340   pjsua_core.c  .RX 557 bytes Response msg
401/REGISTER/cseq=8446 (rdata0x15f4bf4) from UDP 192.168.1.40:5060:
SIP/2.0 401 Unauthorized
Via: SIP/2.0/UDP 192.168.1.206:5060
;branch=z9hG4bKPjfsCydZd0rmC.rZym0JPeO1Udl8Y5BaG6;received=192.168.1.206;rport=5060
From: <sip:511 at raspbx>;tag=JT0sL4JEZWqfHHd9YDnOOp1Tcbmneb.b
To: <sip:511 at raspbx>;tag=as530f6e44
Call-ID: 1qDB9TlQQxR-djUWVFjpQpJ7OlylITVQ
CSeq: 8446 REGISTER
Server: FPBX-13.0.105(11.22.0)
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO,
PUBLISH, MESSAGE
Supported: replaces, timer
WWW-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="49ee1c7e"
Content-Length: 0


--end msg--
15:15:51.340   tsx0x15f87b4  .Incoming Response msg 401/REGISTER/cseq=8446
(rdata0x15f4bf4) in state Calling
15:15:51.340   tsx0x15f87b4  ..State changed from Calling to Completed,
event=RX_MSG
15:15:51.341     alsa_dev.c !...Opened device alsa(sysdefault:CARD=Device)
for playing, sample rate=16000, ch=1, bits=16, period size=320 frames,
latency=149 ms
15:15:51.341     alsa_dev.c  ...open_capture: Open capture device
'sysdefault:CARD=Device'
15:15:51.347     alsa_dev.c  ...Opened device alsa(sysdefault:CARD=Device)
for capture, sample rate=16000, ch=1, bits=16, period size=320 frames,
latency=106 ms
15:15:51.347    ec0x160f6b0  ...Creating AEC
15:15:51.348    ec0x160f6b0  ...AEC created, clock_rate=16000, channel=1,
samples per frame=320, tail length=200 ms, latency=0 ms
15:15:51.349          speex !warning: discarded first playback frame
15:15:51.349     alsa_dev.c !ca_thread_func(1784): Set thread priority for
audio capture thread.
15:15:51.349   dlg0x16392bc !.UAC dialog created
15:15:51.349          speex !warning: discarded first playback frame
15:15:51.349   dlg0x16392bc !..Session count inc to 2 by mod-pjsua
15:15:51.349  pjsua_media.c  .Call 0: initializing media..
15:15:51.349          speex !warning: discarded first playback frame
15:15:51.349          speex  warning: discarded first playback frame
15:15:51.349  pjsua_media.c !..RTP socket reachable at 192.168.1.206:4000
15:15:51.350  pjsua_media.c  ..RTCP socket reachable at 192.168.1.206:4001
15:15:51.350  pjsua_media.c  ..Media index 0 selected for audio call 0
15:15:51.350   dlg0x16392bc  ..Session count dec to 2 by mod-pjsua
15:15:51.350   dlg0x16392bc  .Module mod-invite added as dialog usage,
data=0x163e04c
15:15:51.350   dlg0x16392bc  ..Session count inc to 4 by mod-invite
15:15:51.350          speex !warning: discarded first playback frame
15:15:51.350   dlg0x16392bc !.Module mod-100rel added as dialog usage,
data=0x1639a40
15:15:51.350   dlg0x16392bc  .100rel module attached
15:15:51.350   inv0x16392bc  .UAC invite session created for dialog
dlg0x16392bc
15:15:51.350       endpoint  .Request msg INVITE/cseq=29025 (tdta0x163f278)
created.
15:15:51.350   inv0x16392bc  ..Sending Request msg INVITE/cseq=29025
(tdta0x163f278)
15:15:51.350   dlg0x16392bc  ...Sending Request msg INVITE/cseq=29025
(tdta0x163f278)
15:15:51.350   tsx0x164128c  ....Transaction created for Request msg
INVITE/cseq=29024 (tdta0x163f278)
15:15:51.350   tsx0x164128c  ...Sending Request msg INVITE/cseq=29024
(tdta0x163f278) in state Null
15:15:51.350  sip_resolve.c  ....DNS resolver not available, target
'raspbx:0' type=Unspecified will be resolved with getaddrinfo()
15:15:51.350          speex !warning: discarded first playback frame
15:15:51.350          speex  warning: discarded first playback frame
15:15:51.351          speex  warning: discarded first playback frame
15:15:51.353  sip_resolve.c !....Target 'raspbx:0' type=Unspecified
resolved to '192.168.1.40:5060' type=UDP (UDP transport)
15:15:51.353   pjsua_core.c  ....TX 1038 bytes Request msg
INVITE/cseq=29024 (tdta0x163f278) to UDP 192.168.1.40:5060:
INVITE sip:501 at raspbx SIP/2.0
Via: SIP/2.0/UDP 192.168.1.206:5060
;rport;branch=z9hG4bKPjo41IhhWHdzIpp4.RQWgPgFY8FZQZcuqT
Max-Forwards: 70
From: sip:511 at raspbx;tag=xMC7e5Vl1OklvvUsXswDdv0561uYcJ5b
To: sip:501 at raspbx
Contact: <sip:511 at 192.168.1.206:5060;ob>
Call-ID: Un2yyi.sLCyhioVAiMYvsHDk6MpgeFIU
CSeq: 29024 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:   476

v=0
o=- 3670326951 3670326951 IN IP4 192.168.1.206
s=pjmedia
b=AS:84
t=0 0
a=X-nat:0
m=audio 4000 RTP/AVP 98 97 99 104 3 0 8 9 96
c=IN IP4 192.168.1.206
b=TIAS:64000
a=rtcp:4001 IN IP4 192.168.1.206
a=sendrecv
a=rtpmap:98 speex/16000
a=rtpmap:97 speex/8000
a=rtpmap:99 speex/32000
a=rtpmap:104 iLBC/8000
a=fmtp:104 mode=30
a=rtpmap:3 GSM/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:9 G722/8000
a=rtpmap:96 telephone-event/8000
a=fmtp:96 0-16

--end msg--
15:15:51.354   tsx0x164128c  ....State changed from Null to Calling,
event=TX_MSG
15:15:51.354   dlg0x16392bc  .....Transaction tsx0x164128c state changed to
Calling
15:15:51.354            APP  .......Call 0 state=CALLING
15:15:51.354  tsx0x759004cc !....Transaction created for Request msg
REGISTER/cseq=8447 (tdta0x15f7748)
15:15:51.354  tsx0x759004cc  ...Sending Request msg REGISTER/cseq=8447
(tdta0x15f7748) in state Null
15:15:51.354       endpoint  ....Request msg REGISTER/cseq=8447
(tdta0x15f7748): skipping target resolution because address is already set
15:15:51.354   pjsua_core.c  ....TX 614 bytes Request msg
REGISTER/cseq=8447 (tdta0x15f7748) to UDP 192.168.1.40:5060:
REGISTER sip:raspbx SIP/2.0
Via: SIP/2.0/UDP 192.168.1.206:5060
;rport;branch=z9hG4bKPje3xDRkVFhCWHqmP51R0l0J5tm5xbEUV0
Max-Forwards: 70
From: <sip:511 at raspbx>;tag=JT0sL4JEZWqfHHd9YDnOOp1Tcbmneb.b
To: <sip:511 at raspbx>
Call-ID: 1qDB9TlQQxR-djUWVFjpQpJ7OlylITVQ
CSeq: 8447 REGISTER
Contact: <sip:511 at 192.168.1.206:5060;ob>
Expires: 300
Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, SUBSCRIBE, NOTIFY,
REFER, MESSAGE, OPTIONS
Authorization: Digest username="511", realm="asterisk", nonce="49ee1c7e",
uri="sip:raspbx", response="386f40db749e77f0b76493b32be1bec4", algorithm=MD5
Content-Length:  0


--end msg--
15:15:51.355  tsx0x759004cc  ....State changed from Null to Calling,
event=TX_MSG
15:15:51.356 sip_endpoint.c  Processing incoming message: Response msg
401/INVITE/cseq=29024 (rdata0x75900ea4)
15:15:51.356   pjsua_core.c  .RX 552 bytes Response msg
401/INVITE/cseq=29024 (rdata0x75900ea4) from UDP 192.168.1.40:5060:
SIP/2.0 401 Unauthorized
Via: SIP/2.0/UDP 192.168.1.206:5060
;branch=z9hG4bKPjo41IhhWHdzIpp4.RQWgPgFY8FZQZcuqT;received=192.168.1.206;rport=5060
From: sip:511 at raspbx;tag=xMC7e5Vl1OklvvUsXswDdv0561uYcJ5b
To: sip:501 at raspbx;tag=as394db5e7
Call-ID: Un2yyi.sLCyhioVAiMYvsHDk6MpgeFIU
CSeq: 29024 INVITE
Server: FPBX-13.0.105(11.22.0)
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO,
PUBLISH, MESSAGE
Supported: replaces, timer
WWW-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="797624bb"
Content-Length: 0


--end msg--
15:15:51.356   tsx0x164128c  .Incoming Response msg 401/INVITE/cseq=29024
(rdata0x75900ea4) in state Calling
15:15:51.356       endpoint  ..Request msg ACK/cseq=29024 (tdta0x75902dd8)
created.
15:15:51.356   pjsua_core.c  ..TX 314 bytes Request msg ACK/cseq=29024
(tdta0x75902dd8) to UDP 192.168.1.40:5060:
ACK sip:501 at raspbx SIP/2.0
Via: SIP/2.0/UDP 192.168.1.206:5060
;rport;branch=z9hG4bKPjo41IhhWHdzIpp4.RQWgPgFY8FZQZcuqT
Max-Forwards: 70
From: sip:511 at raspbx;tag=xMC7e5Vl1OklvvUsXswDdv0561uYcJ5b
To: sip:501 at raspbx;tag=as394db5e7
Call-ID: Un2yyi.sLCyhioVAiMYvsHDk6MpgeFIU
CSeq: 29024 ACK
Content-Length:  0


--end msg--
15:15:51.356   tsx0x164128c  ..State changed from Calling to Completed,
event=RX_MSG
15:15:51.356   dlg0x16392bc  ...Received Response msg 401/INVITE/cseq=29024
(rdata0x75900ea4)
15:15:51.356   dlg0x16392bc  ...Transaction tsx0x164128c state changed to
Completed
15:15:51.356   inv0x16392bc  .....Sending Request msg INVITE/cseq=29024
(tdta0x163f278)
15:15:51.356   dlg0x16392bc  ......Sending Request msg INVITE/cseq=29024
(tdta0x163f278)
15:15:51.357  tsx0x75905d8c  .......Transaction created for Request msg
INVITE/cseq=29025 (tdta0x163f278)
15:15:51.357  tsx0x75905d8c  ......Sending Request msg INVITE/cseq=29025
(tdta0x163f278) in state Null
15:15:51.357       endpoint  .......Request msg INVITE/cseq=29025
(tdta0x163f278): skipping target resolution because address is already set
15:15:51.357   pjsua_core.c  .......TX 1194 bytes Request msg
INVITE/cseq=29025 (tdta0x163f278) to UDP 192.168.1.40:5060:
INVITE sip:501 at raspbx SIP/2.0
Via: SIP/2.0/UDP 192.168.1.206:5060
;rport;branch=z9hG4bKPj25ndgyQYBLQeeXnFJzkwI.tkuqVIdLlT
Max-Forwards: 70
From: sip:511 at raspbx;tag=xMC7e5Vl1OklvvUsXswDdv0561uYcJ5b
To: sip:501 at raspbx
Contact: <sip:511 at 192.168.1.206:5060;ob>
Call-ID: Un2yyi.sLCyhioVAiMYvsHDk6MpgeFIU
CSeq: 29025 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="797624bb",
uri="sip:501 at raspbx", response="83914e6eeabdce07c48a30693069235a",
algorithm=MD5
Content-Type: application/sdp
Content-Length:   476

v=0
o=- 3670326951 3670326951 IN IP4 192.168.1.206
s=pjmedia
b=AS:84
t=0 0
a=X-nat:0
m=audio 4000 RTP/AVP 98 97 99 104 3 0 8 9 96
c=IN IP4 192.168.1.206
b=TIAS:64000
a=rtcp:4001 IN IP4 192.168.1.206
a=sendrecv
a=rtpmap:98 speex/16000
a=rtpmap:97 speex/8000
a=rtpmap:99 speex/32000
a=rtpmap:104 iLBC/8000
a=fmtp:104 mode=30
a=rtpmap:3 GSM/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:9 G722/8000
a=rtpmap:96 telephone-event/8000
a=fmtp:96 0-16

--end msg--
15:15:51.357  tsx0x75905d8c  .......State changed from Null to Calling,
event=TX_MSG
15:15:51.357   dlg0x16392bc  ........Transaction tsx0x75905d8c state
changed to Calling
15:15:51.358 sip_endpoint.c  Processing incoming message: Request msg
OPTIONS/cseq=102 (rdata0x75900ea4)
15:15:51.358   pjsua_core.c  .RX 556 bytes Request msg OPTIONS/cseq=102
(rdata0x75900ea4) from UDP 192.168.1.40:5060:
OPTIONS sip:511 at 192.168.1.206:5060;ob SIP/2.0
Via: SIP/2.0/UDP 192.168.1.40:5060;branch=z9hG4bK0adbcd60
Max-Forwards: 70
From: "Unknown" <sip:Unknown at 192.168.1.40>;tag=as3da53871
To: <sip:511 at 192.168.1.206:5060;ob>
Contact: <sip:Unknown at 192.168.1.40:5060>
Call-ID: 5d92cf1d2f3829ad7585f9f12d4d921d at 192.168.1.40:5060
CSeq: 102 OPTIONS
User-Agent: FPBX-13.0.105(11.22.0)
Date: Fri, 22 Apr 2016 15:15:51 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO,
PUBLISH, MESSAGE
Supported: replaces, timer
Content-Length: 0


--end msg--
15:15:51.358       endpoint  .Response msg 200/OPTIONS/cseq=102
(tdta0x75906738) created
15:15:51.358  sip_resolve.c  .Target '192.168.1.40:5060' type=UDP resolved
to '192.168.1.40:5060' type=UDP (UDP transport)
15:15:51.358   pjsua_core.c  .TX 683 bytes Response msg
200/OPTIONS/cseq=102 (tdta0x75906738) 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=z9hG4bK0adbcd60
Call-ID: 5d92cf1d2f3829ad7585f9f12d4d921d at 192.168.1.40:5060
From: "Unknown" <sip:Unknown at 192.168.1.40>;tag=as3da53871
To: <sip:511 at 192.168.1.206;ob>;tag=z9hG4bK0adbcd60
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--
15:15:51.359 tdta0x75906738  .Destroying txdata Response msg
200/OPTIONS/cseq=102 (tdta0x75906738)
15:15:51.359 sip_endpoint.c  Processing incoming message: Response msg
200/REGISTER/cseq=8447 (rdata0x75900ea4)
15:15:51.359   pjsua_core.c  .RX 576 bytes Response msg
200/REGISTER/cseq=8447 (rdata0x75900ea4) from UDP 192.168.1.40:5060:
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.1.206:5060
;branch=z9hG4bKPje3xDRkVFhCWHqmP51R0l0J5tm5xbEUV0;received=192.168.1.206;rport=5060
From: <sip:511 at raspbx>;tag=JT0sL4JEZWqfHHd9YDnOOp1Tcbmneb.b
To: <sip:511 at raspbx>;tag=as530f6e44
Call-ID: 1qDB9TlQQxR-djUWVFjpQpJ7OlylITVQ
CSeq: 8447 REGISTER
Server: FPBX-13.0.105(11.22.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.206:5060;ob>;expires=300
Date: Fri, 22 Apr 2016 15:15:51 GMT
Content-Length: 0


--end msg--
15:15:51.359  tsx0x759004cc  .Incoming Response msg 200/REGISTER/cseq=8447
(rdata0x75900ea4) in state Calling
15:15:51.359  tsx0x759004cc  ..State changed from Calling to Completed,
event=RX_MSG
15:15:51.359    pjsua_acc.c  ....SIP outbound status for acc 0 is not active
15:15:51.359    pjsua_acc.c  ....sip:511 at raspbx: registration success,
status=200 (OK), will re-register in 300 seconds
15:15:51.359    pjsua_acc.c  ....Keep-alive timer started for acc 0,
destination:192.168.1.40:5060, interval:15s
15:15:51.362 sip_endpoint.c  Processing incoming message: Response msg
100/INVITE/cseq=29025 (rdata0x75900ea4)
15:15:51.363   pjsua_core.c  .RX 530 bytes Response msg
100/INVITE/cseq=29025 (rdata0x75900ea4) from UDP 192.168.1.40:5060:
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 192.168.1.206:5060
;branch=z9hG4bKPj25ndgyQYBLQeeXnFJzkwI.tkuqVIdLlT;received=192.168.1.206;rport=5060
From: sip:511 at raspbx;tag=xMC7e5Vl1OklvvUsXswDdv0561uYcJ5b
To: sip:501 at raspbx
Call-ID: Un2yyi.sLCyhioVAiMYvsHDk6MpgeFIU
CSeq: 29025 INVITE
Server: FPBX-13.0.105(11.22.0)
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO,
PUBLISH, MESSAGE
Supported: replaces, timer
Session-Expires: 1800;refresher=uas
Contact: <sip:501 at 192.168.1.40:5060>
Content-Length: 0


--end msg--
15:15:51.363  tsx0x75905d8c  .Incoming Response msg 100/INVITE/cseq=29025
(rdata0x75900ea4) in state Calling
15:15:51.363  tsx0x75905d8c  ..State changed from Calling to Proceeding,
event=RX_MSG
15:15:51.363   dlg0x16392bc  ...Received Response msg 100/INVITE/cseq=29025
(rdata0x75900ea4)
15:15:51.363   dlg0x16392bc  ...Transaction tsx0x75905d8c state changed to
Proceeding
15:15:51.621          speex !warning: Had to discard a playback frame (your
application is buggy and/or got xruns)
15:15:51.958 sip_endpoint.c !Processing incoming message: Response msg
180/INVITE/cseq=29025 (rdata0x75900ea4)
15:15:51.958   pjsua_core.c  .RX 546 bytes Response msg
180/INVITE/cseq=29025 (rdata0x75900ea4) from UDP 192.168.1.40:5060:
SIP/2.0 180 Ringing
Via: SIP/2.0/UDP 192.168.1.206:5060
;branch=z9hG4bKPj25ndgyQYBLQeeXnFJzkwI.tkuqVIdLlT;received=192.168.1.206;rport=5060
From: sip:511 at raspbx;tag=xMC7e5Vl1OklvvUsXswDdv0561uYcJ5b
To: sip:501 at raspbx;tag=as542398d9
Call-ID: Un2yyi.sLCyhioVAiMYvsHDk6MpgeFIU
CSeq: 29025 INVITE
Server: FPBX-13.0.105(11.22.0)
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO,
PUBLISH, MESSAGE
Supported: replaces, timer
Session-Expires: 1800;refresher=uas
Contact: <sip:501 at 192.168.1.40:5060>
Content-Length: 0


--end msg--
15:15:51.958  tsx0x75905d8c  .Incoming Response msg 180/INVITE/cseq=29025
(rdata0x75900ea4) in state Proceeding
15:15:51.958  tsx0x75905d8c  ..State changed from Proceeding to Proceeding,
event=RX_MSG
15:15:51.958   dlg0x16392bc  ...Received Response msg 180/INVITE/cseq=29025
(rdata0x75900ea4)
15:15:51.958   dlg0x16392bc  ....Route-set updated
15:15:51.958   dlg0x16392bc  ...Transaction tsx0x75905d8c state changed to
Proceeding
15:15:51.958            APP  .....Call 0 state=EARLY
15:15:51.975 sip_endpoint.c  Processing incoming message: Response msg
180/INVITE/cseq=29025 (rdata0x75900ea4)
15:15:51.975   pjsua_core.c  .RX 546 bytes Response msg
180/INVITE/cseq=29025 (rdata0x75900ea4) from UDP 192.168.1.40:5060:
SIP/2.0 180 Ringing
Via: SIP/2.0/UDP 192.168.1.206:5060
;branch=z9hG4bKPj25ndgyQYBLQeeXnFJzkwI.tkuqVIdLlT;received=192.168.1.206;rport=5060
From: sip:511 at raspbx;tag=xMC7e5Vl1OklvvUsXswDdv0561uYcJ5b
To: sip:501 at raspbx;tag=as542398d9
Call-ID: Un2yyi.sLCyhioVAiMYvsHDk6MpgeFIU
CSeq: 29025 INVITE
Server: FPBX-13.0.105(11.22.0)
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO,
PUBLISH, MESSAGE
Supported: replaces, timer
Session-Expires: 1800;refresher=uas
Contact: <sip:501 at 192.168.1.40:5060>
Content-Length: 0


--end msg--
15:15:51.975  tsx0x75905d8c  .Incoming Response msg 180/INVITE/cseq=29025
(rdata0x75900ea4) in state Proceeding
15:15:51.975  tsx0x75905d8c  ..State changed from Proceeding to Proceeding,
event=RX_MSG
15:15:51.975   dlg0x16392bc  ...Received Response msg 180/INVITE/cseq=29025
(rdata0x75900ea4)
15:15:51.975   dlg0x16392bc  ...Transaction tsx0x75905d8c state changed to
Proceeding
15:15:51.975            APP  .....Call 0 state=EARLY
15:15:56.208   sound_port.c !EC suspended because of inactivity
15:15:56.355   tsx0x15f87b4 !Timeout timer event
15:15:56.355   tsx0x15f87b4  .State changed from Completed to Terminated,
event=TIMER
15:15:56.355   tsx0x15f87b4  Timeout timer event
15:15:56.355   tsx0x15f87b4  .State changed from Terminated to Destroyed,
event=TIMER
15:15:56.355   tsx0x15f87b4  Transaction destroyed!
15:15:56.359  tsx0x759004cc  Timeout timer event
15:15:56.359  tsx0x759004cc  .State changed from Completed to Terminated,
event=TIMER
15:15:56.359  tsx0x759004cc  Timeout timer event
15:15:56.359  tsx0x759004cc  .State changed from Terminated to Destroyed,
event=TIMER
15:15:56.360  tdta0x15f7748  ..Destroying txdata Request msg
REGISTER/cseq=8447 (tdta0x15f7748)
15:15:56.360  tsx0x759004cc  Transaction destroyed!
15:15:56.821 sip_endpoint.c  Processing incoming message: Response msg
200/INVITE/cseq=29025 (rdata0x75900ea4)
15:15:56.821   pjsua_core.c  .RX 868 bytes Response msg
200/INVITE/cseq=29025 (rdata0x75900ea4) from UDP 192.168.1.40:5060:
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.1.206:5060
;branch=z9hG4bKPj25ndgyQYBLQeeXnFJzkwI.tkuqVIdLlT;received=192.168.1.206;rport=5060
From: sip:511 at raspbx;tag=xMC7e5Vl1OklvvUsXswDdv0561uYcJ5b
To: sip:501 at raspbx;tag=as542398d9
Call-ID: Un2yyi.sLCyhioVAiMYvsHDk6MpgeFIU
CSeq: 29025 INVITE
Server: FPBX-13.0.105(11.22.0)
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO,
PUBLISH, MESSAGE
Supported: replaces, timer
Session-Expires: 1800;refresher=uas
Contact: <sip:501 at 192.168.1.40:5060>
Content-Type: application/sdp
Require: timer
Content-Length: 278

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

--end msg--
15:15:56.822  tsx0x75905d8c  .Incoming Response msg 200/INVITE/cseq=29025
(rdata0x75900ea4) in state Proceeding
15:15:56.822  tsx0x75905d8c  ..State changed from Proceeding to Terminated,
event=RX_MSG
15:15:56.822   dlg0x16392bc  ...Received Response msg 200/INVITE/cseq=29025
(rdata0x75900ea4)
15:15:56.822   dlg0x16392bc  ....Route-set updated
15:15:56.822   dlg0x16392bc  ....Route-set frozen
15:15:56.822   dlg0x16392bc  ...Transaction tsx0x75905d8c state changed to
Terminated
15:15:56.822            APP  .....Call 0 state=CONNECTING
15:15:56.822   inv0x16392bc  ....Got SDP answer in Response msg
200/INVITE/cseq=29025 (rdata0x75900ea4)
15:15:56.822   inv0x16392bc  ....SDP negotiation done, status=0
15:15:56.822   pjsua_call.c  .....Call 0: remote NAT type is 0 (Unknown)
15:15:56.822  pjsua_media.c  .....Call 0: updating media..
15:15:56.822    pjsua_aud.c  ......Audio channel update..
15:15:56.823 strm0x75906f64  .......VAD temporarily disabled
15:15:56.823          rtp.c  .......pjmedia_rtp_session_init:
ses=0x75908e10, default_pt=0, ssrc=0xab2fd6c
15:15:56.823          rtp.c  .......pjmedia_rtp_session_init:
ses=0x75909498, default_pt=0, ssrc=0xab2fd6c
15:15:56.823       stream.c  .......Stream strm0x75906f64 created
15:15:56.823 strm0x75906f64  .......Encoder stream started
15:15:56.823 strm0x75906f64  .......Decoder stream started
15:15:56.823     resample.c  .......resample created: high qualiy, large
filter, in/out rate=8000/16000
15:15:56.823     resample.c  .......resample created: high qualiy, large
filter, in/out rate=16000/8000
15:15:56.823  pjsua_media.c  ......Audio updated, stream #0: PCMU (sendrecv)
15:15:56.823    pjsua_aud.c  .....Conf connect: 1 --> 0
15:15:56.823   conference.c  ......Port 1 (sip:501 at raspbx) transmitting to
port 0 (sysdefault:CARD=Device)
15:15:56.823    pjsua_aud.c  .....Conf connect: 0 --> 1
15:15:56.823   conference.c  ......Port 0 (sysdefault:CARD=Device)
transmitting to port 1 (sip:501 at raspbx)
15:15:56.823   inv0x16392bc  ....Received Response msg
200/INVITE/cseq=29025 (rdata0x75900ea4), sending ACK
15:15:56.823       endpoint  ....Request msg ACK/cseq=29025
(tdta0x7590b278) created.
15:15:56.823   dlg0x16392bc  .....Sending Request msg ACK/cseq=29025
(tdta0x7590b278)
15:15:56.824  sip_resolve.c  .....Target '192.168.1.40:5060'
type=Unspecified resolved to '192.168.1.40:5060' type=UDP (UDP transport)
15:15:56.824   pjsua_core.c  .....TX 325 bytes Request msg ACK/cseq=29025
(tdta0x7590b278) to UDP 192.168.1.40:5060:
ACK sip:501 at 192.168.1.40:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.1.206:5060
;rport;branch=z9hG4bKPjYOGWeWMsizsLN90zENMCIHvD7CX9OhHd
Max-Forwards: 70
From: sip:511 at raspbx;tag=xMC7e5Vl1OklvvUsXswDdv0561uYcJ5b
To: sip:501 at raspbx;tag=as542398d9
Call-ID: Un2yyi.sLCyhioVAiMYvsHDk6MpgeFIU
CSeq: 29025 ACK
Content-Length:  0


--end msg--
15:15:56.824            APP  .....Call 0 state=CONFIRMED
15:15:56.824   pjsua_call.c  .Call 0 sending re-INVITE for updating media
session to use only one codec
15:15:56.824       endpoint  ..Request msg INVITE/cseq=29027
(tdta0x7590f410) created.
15:15:56.824   inv0x16392bc  ..Sending Request msg INVITE/cseq=29027
(tdta0x7590f410)
15:15:56.824   dlg0x16392bc  ...Sending Request msg INVITE/cseq=29027
(tdta0x7590f410)
15:15:56.824  tsx0x75911424  ....Transaction created for Request msg
INVITE/cseq=29026 (tdta0x7590f410)
15:15:56.824  tsx0x75911424  ...Sending Request msg INVITE/cseq=29026
(tdta0x7590f410) in state Null
15:15:56.825  sip_resolve.c  ....Target '192.168.1.40:5060'
type=Unspecified resolved to '192.168.1.40:5060' type=UDP (UDP transport)
15:15:56.825   pjsua_core.c  ....TX 876 bytes Request msg INVITE/cseq=29026
(tdta0x7590f410) to UDP 192.168.1.40:5060:
INVITE sip:501 at 192.168.1.40:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.1.206:5060
;rport;branch=z9hG4bKPjJkhmkaN5vX4mSGZxY64zCXV0L2uEApnR
Max-Forwards: 70
From: sip:511 at raspbx;tag=xMC7e5Vl1OklvvUsXswDdv0561uYcJ5b
To: sip:501 at raspbx;tag=as542398d9
Contact: <sip:511 at 192.168.1.206:5060;ob>
Call-ID: Un2yyi.sLCyhioVAiMYvsHDk6MpgeFIU
CSeq: 29026 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=- 3670326951 3670326952 IN IP4 192.168.1.206
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.206
b=TIAS:64000
a=rtcp:4001 IN IP4 192.168.1.206
a=rtpmap:0 PCMU/8000
a=rtpmap:96 telephone-event/8000
a=fmtp:96 0-16
a=sendrecv

--end msg--
15:15:56.825  tsx0x75911424  ....State changed from Null to Calling,
event=TX_MSG
15:15:56.825   dlg0x16392bc  .....Transaction tsx0x75911424 state changed
to Calling
15:15:56.825  tsx0x75905d8c  Timeout timer event
15:15:56.825  tsx0x75905d8c  .State changed from Terminated to Destroyed,
event=TIMER
15:15:56.825  tsx0x75905d8c  Transaction destroyed!
15:15:56.827   Master/sound !Underflow, buf_cnt=0, will generate 1 frame
15:15:56.827 sip_endpoint.c !Processing incoming message: Response msg
100/INVITE/cseq=29026 (rdata0x75900ea4)
15:15:56.827   pjsua_core.c  .RX 545 bytes Response msg
100/INVITE/cseq=29026 (rdata0x75900ea4) from UDP 192.168.1.40:5060:
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 192.168.1.206:5060
;branch=z9hG4bKPjJkhmkaN5vX4mSGZxY64zCXV0L2uEApnR;received=192.168.1.206;rport=5060
From: sip:511 at raspbx;tag=xMC7e5Vl1OklvvUsXswDdv0561uYcJ5b
To: sip:501 at raspbx;tag=as542398d9
Call-ID: Un2yyi.sLCyhioVAiMYvsHDk6MpgeFIU
CSeq: 29026 INVITE
Server: FPBX-13.0.105(11.22.0)
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO,
PUBLISH, MESSAGE
Supported: replaces, timer
Session-Expires: 1800;refresher=uas
Contact: <sip:501 at 192.168.1.40:5060>
Content-Length: 0


--end msg--
15:15:56.828  tsx0x75911424  .Incoming Response msg 100/INVITE/cseq=29026
(rdata0x75900ea4) in state Calling
15:15:56.828  tsx0x75911424  ..State changed from Calling to Proceeding,
event=RX_MSG
15:15:56.828   dlg0x16392bc  ...Received Response msg 100/INVITE/cseq=29026
(rdata0x75900ea4)
15:15:56.828   dlg0x16392bc  ...Transaction tsx0x75911424 state changed to
Proceeding
15:15:56.828 sip_endpoint.c  Processing incoming message: Response msg
200/INVITE/cseq=29026 (rdata0x75900ea4)
15:15:56.828   pjsua_core.c  .RX 821 bytes Response msg
200/INVITE/cseq=29026 (rdata0x75900ea4) from UDP 192.168.1.40:5060:
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.1.206:5060
;branch=z9hG4bKPjJkhmkaN5vX4mSGZxY64zCXV0L2uEApnR;received=192.168.1.206;rport=5060
From: sip:511 at raspbx;tag=xMC7e5Vl1OklvvUsXswDdv0561uYcJ5b
To: sip:501 at raspbx;tag=as542398d9
Call-ID: Un2yyi.sLCyhioVAiMYvsHDk6MpgeFIU
CSeq: 29026 INVITE
Server: FPBX-13.0.105(11.22.0)
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO,
PUBLISH, MESSAGE
Supported: replaces, timer
Session-Expires: 1800;refresher=uas
Contact: <sip:501 at 192.168.1.40:5060>
Content-Type: application/sdp
Require: timer
Content-Length: 231

v=0
o=root 535804958 535804959 IN IP4 192.168.1.40
s=Asterisk PBX 11.22.0
c=IN IP4 192.168.1.40
t=0 0
m=audio 11492 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--
15:15:56.828  tsx0x75911424  .Incoming Response msg 200/INVITE/cseq=29026
(rdata0x75900ea4) in state Proceeding
15:15:56.828  tsx0x75911424  ..State changed from Proceeding to Terminated,
event=RX_MSG
15:15:56.828   dlg0x16392bc  ...Received Response msg 200/INVITE/cseq=29026
(rdata0x75900ea4)
15:15:56.828   dlg0x16392bc  ...Transaction tsx0x75911424 state changed to
Terminated
15:15:56.828   inv0x16392bc  ....Got SDP answer in Response msg
200/INVITE/cseq=29026 (rdata0x75900ea4)
15:15:56.829   inv0x16392bc  ....SDP negotiation done, status=0
15:15:56.829   pjsua_call.c  .....Call 0: remote NAT type is 0 (Unknown)
15:15:56.829  pjsua_media.c  .....Call 0: updating media..
15:15:56.829  pjsua_media.c  ......Call 0: stream #0 (audio) unchanged.
15:15:56.829  pjsua_media.c  ......Audio updated, stream #0: PCMU (sendrecv)
15:15:56.829    pjsua_aud.c  .....Conf connect: 1 --> 0
15:15:56.830 strm0x75906f64 !Jitter buffer is bufferring (prefetch=0), plc
invoked
15:15:56.831 strm0x75906f64  Start talksprut..
15:15:56.831    pjsua_aud.c !.....Conf connect: 0 --> 1
15:15:56.831   inv0x16392bc  ....Received Response msg
200/INVITE/cseq=29026 (rdata0x75900ea4), sending ACK
15:15:56.831 tdta0x7590b278  ....Destroying txdata Request msg
ACK/cseq=29025 (tdta0x7590b278)
15:15:56.832       endpoint  ....Request msg ACK/cseq=29026
(tdta0x7590b278) created.
15:15:56.832   dlg0x16392bc  .....Sending Request msg ACK/cseq=29026
(tdta0x7590b278)
15:15:56.832  sip_resolve.c  .....Target '192.168.1.40:5060'
type=Unspecified resolved to '192.168.1.40:5060' type=UDP (UDP transport)
15:15:56.832   pjsua_core.c  .....TX 325 bytes Request msg ACK/cseq=29026
(tdta0x7590b278) to UDP 192.168.1.40:5060:
ACK sip:501 at 192.168.1.40:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.1.206:5060
;rport;branch=z9hG4bKPjVYL7VSyqEDEdWcmHoiX-FMI5Kon7SJSQ
Max-Forwards: 70
From: sip:511 at raspbx;tag=xMC7e5Vl1OklvvUsXswDdv0561uYcJ5b
To: sip:501 at raspbx;tag=as542398d9
Call-ID: Un2yyi.sLCyhioVAiMYvsHDk6MpgeFIU
CSeq: 29026 ACK
Content-Length:  0


--end msg--
15:15:56.832  tsx0x75911424  Timeout timer event
15:15:56.832  tsx0x75911424  .State changed from Terminated to Destroyed,
event=TIMER
15:15:56.832 tdta0x7590f410  ..Destroying txdata Request msg
INVITE/cseq=29026 (tdta0x7590f410)
15:15:56.832  tsx0x75911424  Transaction destroyed!
15:15:56.843 strm0x75906f64 !RTP status: badpt=0, badssrc=0, dup=0,
outorder=0, probation=-1, restart=0
15:15:56.848 strm0x75906f64 !Jitter buffer starts returning normal frames
(after 1 empty/lost)
15:15:56.849   sound_port.c  EC activated
15:15:56.850          speex  warning: Had to discard a playback frame (your
application is buggy and/or got xruns)
15:15:57.468 strm0x75906f64  VAD re-enabled
15:15:57.470 strm0x75906f64  Starting silence
15:16:01.437   silencedet.c  Re-adjust threshold (in silence)to 0
15:16:02.461 strm0x75906f64  Start talksprut..
15:16:02.482 strm0x75906f64  Starting silence
15:16:02.824          speex  warning: Auto-filling the buffer (your
application is buggy and/or got xruns)
15:16:03.037          speex  warning: Had to discard a playback frame (your
application is buggy and/or got xruns)
15:16:03.144          speex  warning: Auto-filling the buffer (your
application is buggy and/or got xruns)
15:16:03.357          speex  warning: Had to discard a playback frame (your
application is buggy and/or got xruns)
15:16:03.464          speex  warning: Auto-filling the buffer (your
application is buggy and/or got xruns)
15:16:03.677          speex  warning: Had to discard a playback frame (your
application is buggy and/or got xruns)
15:16:03.784          speex  warning: Auto-filling the buffer (your
application is buggy and/or got xruns)
15:16:03.997          speex  warning: Had to discard a playback frame (your
application is buggy and/or got xruns)
15:16:04.104          speex  warning: Auto-filling the buffer (your
application is buggy and/or got xruns)
15:16:04.317          speex  warning: Had to discard a playback frame (your
application is buggy and/or got xruns)
15:16:04.424          speex  warning: Auto-filling the buffer (your
application is buggy and/or got xruns)
15:16:04.637          speex  warning: Had to discard a playback frame (your
application is buggy and/or got xruns)
15:16:04.745          speex  warning: Auto-filling the buffer (your
application is buggy and/or got xruns)
15:16:05.298          speex  warning: Had to discard a playback frame (your
application is buggy and/or got xruns)
15:16:05.385          speex  warning: Auto-filling the buffer (your
application is buggy and/or got xruns)
15:16:05.448   silencedet.c  Re-adjust threshold (in silence)to 0
15:16:05.618          speex  warning: Had to discard a playback frame (your
application is buggy and/or got xruns)
15:16:05.705          speex  warning: Auto-filling the buffer (your
application is buggy and/or got xruns)
15:16:05.938          speex  warning: Had to discard a playback frame (your
application is buggy and/or got xruns)
15:16:06.003          speex  warning: Auto-filling the buffer (your
application is buggy and/or got xruns)
15:16:06.359    pjsua_acc.c !Sending 2 bytes keep-alive packet for acc 0 to
192.168.1.40:5060
15:16:06.360 tdta0x7590f410  Destroying txdata raw
15:16:07.474 strm0x75906f64 !Start talksprut..
15:16:07.496 strm0x75906f64  Starting silence
15:16:09.459   silencedet.c  Re-adjust threshold (in silence)to 0
15:16:10.398   silencedet.c  Starting talk burst (level=25 threshold=0)
15:16:10.398 strm0x75906f64  Start talksprut..
15:16:11.230   silencedet.c  Starting silence (level=0 threshold=0)
15:16:11.231 strm0x75906f64  Starting silence
15:16:11.614   silencedet.c  Starting talk burst (level=1021 threshold=0)
15:16:11.614 strm0x75906f64  Start talksprut..
15:16:12.787   silencedet.c  Starting silence (level=0 threshold=0)
15:16:12.787 strm0x75906f64  Starting silence
15:16:13.022   silencedet.c  Starting talk burst (level=1 threshold=0)
15:16:13.022 strm0x75906f64  Start talksprut..
15:16:21.024   silencedet.c  Re-adjust threshold (in talk burst)to 60
15:16:21.360    pjsua_acc.c !Sending 2 bytes keep-alive packet for acc 0 to
192.168.1.40:5060
15:16:21.360 tdta0x7590f410  Destroying txdata raw
15:16:23.357   tsx0x164128c  Timeout timer event
15:16:23.357   tsx0x164128c  .State changed from Completed to Terminated,
event=TIMER
15:16:23.357   dlg0x16392bc  ..Transaction tsx0x164128c state changed to
Terminated
15:16:23.357   tsx0x164128c  Timeout timer event
15:16:23.357   tsx0x164128c  .State changed from Terminated to Destroyed,
event=TIMER
15:16:23.357 tdta0x75902dd8  ..Destroying txdata Request msg ACK/cseq=29024
(tdta0x75902dd8)
15:16:23.357   tsx0x164128c  Transaction destroyed!
15:16:27.189   silencedet.c !Starting silence (level=9 threshold=24)
15:16:27.190 strm0x75906f64  Starting silence
15:16:27.232   silencedet.c  Starting talk burst (level=59 threshold=24)
15:16:27.233 strm0x75906f64  Start talksprut..
15:16:28.532 strm0x75906f64  Frame lost, recovered!
15:16:28.532 strm0x75906f64  Jitter buffer starts returning normal frames
(after 1 empty/lost)
15:16:29.215 strm0x75906f64  Frame lost, recovered!
15:16:29.215 strm0x75906f64  Jitter buffer starts returning normal frames
(after 1 empty/lost)
15:16:31.201   silencedet.c  Starting silence (level=13 threshold=22)
15:16:31.201 strm0x75906f64  Starting silence
15:16:32.204   silencedet.c  Starting talk burst (level=44 threshold=22)
15:16:32.204 strm0x75906f64  Start talksprut..
15:16:36.361    pjsua_acc.c !Sending 2 bytes keep-alive packet for acc 0 to
192.168.1.40:5060
15:16:36.361 tdta0x75902dd8  Destroying txdata raw
15:16:47.670 strm0x75906f64 !Frame lost, recovered!
15:16:47.692 strm0x75906f64  Jitter buffer starts returning normal frames
(after 1 empty/lost)
15:16:47.694          speex  warning: Auto-filling the buffer (your
application is buggy and/or got xruns)
15:16:47.907          speex  warning: Had to discard a playback frame (your
application is buggy and/or got xruns)
15:16:47.928   silencedet.c  Re-adjust threshold (in talk burst)to 131
15:16:47.950          speex  warning: Auto-filling the buffer (your
application is buggy and/or got xruns)
15:16:48.204 strm0x75906f64  Frame lost, recovered!
15:16:48.204 strm0x75906f64  Jitter buffer starts returning normal frames
(after 1 empty/lost)
15:16:48.227          speex  warning: Had to discard a playback frame (your
application is buggy and/or got xruns)
15:16:48.270          speex  warning: Auto-filling the buffer (your
application is buggy and/or got xruns)
15:16:48.547          speex  warning: Had to discard a playback frame (your
application is buggy and/or got xruns)
15:16:49.401          speex  warning: Auto-filling the buffer (your
application is buggy and/or got xruns)
15:16:49.550   silencedet.c  Starting silence (level=70 threshold=150)
15:16:49.551 strm0x75906f64  Starting silence
15:16:49.742   silencedet.c  Starting talk burst (level=183 threshold=150)
15:16:49.742 strm0x75906f64  Start talksprut..
15:16:50.488          speex  warning: Had to discard a playback frame (your
application is buggy and/or got xruns)
15:16:50.531          speex  warning: Auto-filling the buffer (your
application is buggy and/or got xruns)
15:16:50.808          speex  warning: Had to discard a playback frame (your
application is buggy and/or got xruns)
15:16:50.830   silencedet.c  Starting silence (level=102 threshold=136)
15:16:50.830 strm0x75906f64  Starting silence
15:16:50.851   silencedet.c  Starting talk burst (level=383 threshold=136)
15:16:50.851 strm0x75906f64  Start talksprut..
15:16:50.852          speex  warning: Auto-filling the buffer (your
application is buggy and/or got xruns)
15:16:51.361    pjsua_acc.c !Sending 2 bytes keep-alive packet for acc 0 to
192.168.1.40:5060
15:16:51.362 tdta0x75902dd8  Destroying txdata raw
15:16:51.364 sip_endpoint.c  Processing incoming message: Request msg
OPTIONS/cseq=102 (rdata0x75900ea4)
15:16:51.364   pjsua_core.c  .RX 556 bytes Request msg OPTIONS/cseq=102
(rdata0x75900ea4) from UDP 192.168.1.40:5060:
OPTIONS sip:511 at 192.168.1.206:5060;ob SIP/2.0
Via: SIP/2.0/UDP 192.168.1.40:5060;branch=z9hG4bK23a8c463
Max-Forwards: 70
From: "Unknown" <sip:Unknown at 192.168.1.40>;tag=as03d7c32a
To: <sip:511 at 192.168.1.206:5060;ob>
Contact: <sip:Unknown at 192.168.1.40:5060>
Call-ID: 50bbaec6532b5af73fd075f44bc78aaa at 192.168.1.40:5060
CSeq: 102 OPTIONS
User-Agent: FPBX-13.0.105(11.22.0)
Date: Fri, 22 Apr 2016 15:16:51 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO,
PUBLISH, MESSAGE
Supported: replaces, timer
Content-Length: 0


--end msg--
15:16:51.364       endpoint  .Response msg 200/OPTIONS/cseq=102
(tdta0x75902dd8) created
15:16:51.365  sip_resolve.c  .Target '192.168.1.40:5060' type=UDP resolved
to '192.168.1.40:5060' type=UDP (UDP transport)
15:16:51.365   pjsua_core.c  .TX 683 bytes Response msg
200/OPTIONS/cseq=102 (tdta0x75902dd8) 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=z9hG4bK23a8c463
Call-ID: 50bbaec6532b5af73fd075f44bc78aaa at 192.168.1.40:5060
From: "Unknown" <sip:Unknown at 192.168.1.40>;tag=as03d7c32a
To: <sip:511 at 192.168.1.206;ob>;tag=z9hG4bK23a8c463
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--
15:16:51.366 tdta0x75902dd8  .Destroying txdata Response msg
200/OPTIONS/cseq=102 (tdta0x75902dd8)
15:16:54.307   silencedet.c !Starting silence (level=11 threshold=52)
15:16:54.307 strm0x75906f64  Starting silence
15:16:54.693   silencedet.c  Starting talk burst (level=57 threshold=52)
15:16:54.693 strm0x75906f64  Start talksprut..
15:16:55.672   silencedet.c  Starting silence (level=12 threshold=22)
15:16:55.672 strm0x75906f64  Starting silence
15:16:55.971   silencedet.c  Starting talk burst (level=311 threshold=22)
15:16:55.971 strm0x75906f64  Start talksprut..
15:16:57.828   silencedet.c  Starting silence (level=6 threshold=16)
15:16:57.828 strm0x75906f64  Starting silence
15:16:58.383   silencedet.c  Starting talk burst (level=24 threshold=16)
15:16:58.383 strm0x75906f64  Start talksprut..
15:16:59.535   silencedet.c  Starting silence (level=8 threshold=16)
15:16:59.535 strm0x75906f64  Starting silence
15:17:01.241   silencedet.c  Starting talk burst (level=23 threshold=16)
15:17:01.241 strm0x75906f64  Start talksprut..
15:17:02.929 sip_endpoint.c !Processing incoming message: Request msg
BYE/cseq=102 (rdata0x75900ea4)
15:17:02.929   pjsua_core.c  .RX 566 bytes Request msg BYE/cseq=102
(rdata0x75900ea4) from UDP 192.168.1.40:5060:
BYE sip:511 at 192.168.1.206:5060;ob SIP/2.0
Via: SIP/2.0/UDP 192.168.1.40:5060;branch=z9hG4bK0a6a8a66;rport
Max-Forwards: 70
From: sip:501 at raspbx;tag=as542398d9
To: sip:511 at raspbx;tag=xMC7e5Vl1OklvvUsXswDdv0561uYcJ5b
Call-ID: Un2yyi.sLCyhioVAiMYvsHDk6MpgeFIU
CSeq: 102 BYE
User-Agent: FPBX-13.0.105(11.22.0)
Proxy-Authorization: Digest username="511", realm="asterisk",
algorithm=MD5, uri="sip:raspbx", nonce="797624bb",
response="e04670429476a52beb51a5e711d6ecc2"
X-Asterisk-HangupCause: Normal Clearing
X-Asterisk-HangupCauseCode: 16
Content-Length: 0


--end msg--
15:17:02.930   dlg0x16392bc  .Received Request msg BYE/cseq=102
(rdata0x75900ea4)
15:17:02.930  tsx0x759004cc  ...Transaction created for Request msg
BYE/cseq=102 (rdata0x75900ea4)
15:17:02.930  tsx0x759004cc  ..Incoming Request msg BYE/cseq=102
(rdata0x75900ea4) in state Null
15:17:02.930  tsx0x759004cc  ...State changed from Null to Trying,
event=RX_MSG
15:17:02.930   dlg0x16392bc  ....Transaction tsx0x759004cc state changed to
Trying
15:17:02.930       endpoint  .....Response msg 200/BYE/cseq=102
(tdta0x75902dd8) created
15:17:02.930   dlg0x16392bc  ......Sending Response msg 200/BYE/cseq=102
(tdta0x75902dd8)
15:17:02.930  tsx0x759004cc  ......Sending Response msg 200/BYE/cseq=102
(tdta0x75902dd8) in state Trying
15:17:02.930   pjsua_core.c  .......TX 286 bytes Response msg
200/BYE/cseq=102 (tdta0x75902dd8) 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=z9hG4bK0a6a8a66
Call-ID: Un2yyi.sLCyhioVAiMYvsHDk6MpgeFIU
From: <sip:501 at raspbx>;tag=as542398d9
To: <sip:511 at raspbx>;tag=xMC7e5Vl1OklvvUsXswDdv0561uYcJ5b
CSeq: 102 BYE
Content-Length:  0


--end msg--
15:17:02.930  tsx0x759004cc  .......State changed from Trying to Completed,
event=TX_MSG
15:17:02.930   dlg0x16392bc  ........Transaction tsx0x759004cc state
changed to Completed
15:17:02.930            APP  ......Call 0 state=DISCONNCTD
15:17:02.930  pjsua_media.c  ......Call 0: deinitializing media..
15:17:02.930 strm0x75906f64  ........JB summary:
  size=0/eff=0 prefetch=0 level=4
  delay (min/max/avg/dev)=20/60/46/12 ms
  burst (min/max/avg/dev)=2/4/2/0 frames
  lost=4 discard=0 empty=1
15:17:02.931  pjsua_media.c  ........Media stream call00:0 is destroyed
15:17:02.931 tdta0x7590b278  .....Destroying txdata Request msg
ACK/cseq=29026 (tdta0x7590b278)
15:17:02.931  tdta0x163f278  .....Destroying txdata Request msg
INVITE/cseq=29025 (tdta0x163f278)
15:17:02.931   dlg0x16392bc  ......Session count dec to 3 by mod-invite
15:17:03.930    pjsua_aud.c  Closing sound device after idle for 1 second(s)
15:17:03.930    pjsua_aud.c  .Closing sysdefault:CARD=Device sound playback
device and sysdefault:CARD=Device sound capture device
15:17:06.362    pjsua_acc.c  Sending 2 bytes keep-alive packet for acc 0 to
192.168.1.40:5060
15:17:06.363 tdta0x75906b48  Destroying txdata raw
15:17:21.363    pjsua_acc.c  Sending 2 bytes keep-alive packet for acc 0 to
192.168.1.40:5060
15:17:21.364 tdta0x75906b48  Destroying txdata raw
15:17:34.930  tsx0x759004cc  Timeout timer event
15:17:34.931  tsx0x759004cc  .State changed from Completed to Terminated,
event=TIMER
15:17:34.931   dlg0x16392bc  ..Transaction tsx0x759004cc state changed to
Terminated
15:17:34.932   dlg0x16392bc  ...Dialog destroyed
15:17:34.935  tsx0x759004cc  Timeout timer event
15:17:34.935  tsx0x759004cc  .State changed from Terminated to Destroyed,
event=TIMER
15:17:34.935 tdta0x75902dd8  ..Destroying txdata Response msg
200/BYE/cseq=102 (tdta0x75902dd8)
15:17:34.936  tsx0x759004cc  Transaction destroyed!
15:17:36.364    pjsua_acc.c  Sending 2 bytes keep-alive packet for acc 0 to
192.168.1.40:5060
15:17:36.365 tdta0x75902dd8  Destroying txdata raw
15:17:51.365    pjsua_acc.c  Sending 2 bytes keep-alive packet for acc 0 to
192.168.1.40:5060
15:17:51.366 tdta0x75902dd8  Destroying txdata raw
15:17:51.368 sip_endpoint.c  Processing incoming message: Request msg
OPTIONS/cseq=102 (rdata0x75900ea4)
15:17:51.368   pjsua_core.c  .RX 556 bytes Request msg OPTIONS/cseq=102
(rdata0x75900ea4) from UDP 192.168.1.40:5060:
OPTIONS sip:511 at 192.168.1.206:5060;ob SIP/2.0
Via: SIP/2.0/UDP 192.168.1.40:5060;branch=z9hG4bK29b1e896
Max-Forwards: 70
From: "Unknown" <sip:Unknown at 192.168.1.40>;tag=as2d99b8a5
To: <sip:511 at 192.168.1.206:5060;ob>
Contact: <sip:Unknown at 192.168.1.40:5060>
Call-ID: 0ebcd15265d267c53c5967c275462c13 at 192.168.1.40:5060
CSeq: 102 OPTIONS
User-Agent: FPBX-13.0.105(11.22.0)
Date: Fri, 22 Apr 2016 15:17:51 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO,
PUBLISH, MESSAGE
Supported: replaces, timer
Content-Length: 0


--end msg--
15:17:51.368       endpoint  .Response msg 200/OPTIONS/cseq=102
(tdta0x75902dd8) created
15:17:51.368  sip_resolve.c  .Target '192.168.1.40:5060' type=UDP resolved
to '192.168.1.40:5060' type=UDP (UDP transport)
15:17:51.368   pjsua_core.c  .TX 683 bytes Response msg
200/OPTIONS/cseq=102 (tdta0x75902dd8) 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=z9hG4bK29b1e896
Call-ID: 0ebcd15265d267c53c5967c275462c13 at 192.168.1.40:5060
From: "Unknown" <sip:Unknown at 192.168.1.40>;tag=as2d99b8a5
To: <sip:511 at 192.168.1.206;ob>;tag=z9hG4bK29b1e896
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--
15:17:51.368 tdta0x75902dd8  .Destroying txdata Response msg
200/OPTIONS/cseq=102 (tdta0x75902dd8)
q
15:17:55.938   pjsua_core.c !Shutting down, flags=0...
15:17:55.939   pjsua_core.c  PJSUA state changed: RUNNING --> CLOSING
15:17:55.946   pjsua_call.c  .Hangup all calls..
15:17:55.947  pjsua_media.c  .Call 0: deinitializing media..
15:17:55.947   pjsua_pres.c  .Shutting down presence..
15:17:55.948    pjsua_acc.c  .Acc 0: setting unregistration..
15:17:55.949       endpoint  ..Request msg REGISTER/cseq=8447
(tdta0x15f7748) created.
15:17:55.949   tsx0x15f87b4  ...Transaction created for Request msg
REGISTER/cseq=8448 (tdta0x15f7748)
15:17:55.949   tsx0x15f87b4  ..Sending Request msg REGISTER/cseq=8448
(tdta0x15f7748) in state Null
15:17:55.950  sip_resolve.c  ...DNS resolver not available, target
'raspbx:0' type=Unspecified will be resolved with getaddrinfo()
15:17:55.954  sip_resolve.c  ...Target 'raspbx:0' type=Unspecified resolved
to '192.168.1.40:5060' type=UDP (UDP transport)
15:17:55.954   pjsua_core.c  ...TX 362 bytes Request msg REGISTER/cseq=8448
(tdta0x15f7748) to UDP 192.168.1.40:5060:
REGISTER sip:raspbx SIP/2.0
Via: SIP/2.0/UDP 192.168.1.206:5060
;rport;branch=z9hG4bKPjD0xKIpOAvkMbWiuktb3DE58fOxm9h.1v
Max-Forwards: 70
From: <sip:511 at raspbx>;tag=faxrODRGdph6M4sR8flQIdZv7GfYZC1U
To: <sip:511 at raspbx>
Call-ID: 1qDB9TlQQxR-djUWVFjpQpJ7OlylITVQ
CSeq: 8448 REGISTER
Contact: <sip:511 at 192.168.1.206:5060;ob>
Expires: 0
Content-Length:  0


--end msg--
15:17:55.960   tsx0x15f87b4  ...State changed from Null to Calling,
event=TX_MSG
15:17:55.960    pjsua_acc.c  ..Acc 0: Unregistration sent
15:17:55.961 sip_endpoint.c  .Processing incoming message: Response msg
401/REGISTER/cseq=8448 (rdata0x75900ea4)
15:17:55.961   pjsua_core.c  ..RX 557 bytes Response msg
401/REGISTER/cseq=8448 (rdata0x75900ea4) from UDP 192.168.1.40:5060:
SIP/2.0 401 Unauthorized
Via: SIP/2.0/UDP 192.168.1.206:5060
;branch=z9hG4bKPjD0xKIpOAvkMbWiuktb3DE58fOxm9h.1v;received=192.168.1.206;rport=5060
From: <sip:511 at raspbx>;tag=faxrODRGdph6M4sR8flQIdZv7GfYZC1U
To: <sip:511 at raspbx>;tag=as29d71240
Call-ID: 1qDB9TlQQxR-djUWVFjpQpJ7OlylITVQ
CSeq: 8448 REGISTER
Server: FPBX-13.0.105(11.22.0)
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO,
PUBLISH, MESSAGE
Supported: replaces, timer
WWW-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="568148a3"
Content-Length: 0


--end msg--
15:17:55.962   tsx0x15f87b4  ..Incoming Response msg 401/REGISTER/cseq=8448
(rdata0x75900ea4) in state Calling
15:17:55.963   tsx0x15f87b4  ...State changed from Calling to Completed,
event=RX_MSG
15:17:55.963   tsx0x15f9744  .....Transaction created for Request msg
REGISTER/cseq=8449 (tdta0x15f7748)
15:17:55.963   tsx0x15f9744  ....Sending Request msg REGISTER/cseq=8449
(tdta0x15f7748) in state Null
15:17:55.963       endpoint  .....Request msg REGISTER/cseq=8449
(tdta0x15f7748): skipping target resolution because address is already set
15:17:55.963   pjsua_core.c  .....TX 514 bytes Request msg
REGISTER/cseq=8449 (tdta0x15f7748) to UDP 192.168.1.40:5060:
REGISTER sip:raspbx SIP/2.0
Via: SIP/2.0/UDP 192.168.1.206:5060
;rport;branch=z9hG4bKPj28sWaDKbpFKzgM2UtgEgUEfzzWXkthw1
Max-Forwards: 70
From: <sip:511 at raspbx>;tag=faxrODRGdph6M4sR8flQIdZv7GfYZC1U
To: <sip:511 at raspbx>
Call-ID: 1qDB9TlQQxR-djUWVFjpQpJ7OlylITVQ
CSeq: 8449 REGISTER
Contact: <sip:511 at 192.168.1.206:5060;ob>
Expires: 0
Authorization: Digest username="511", realm="asterisk", nonce="568148a3",
uri="sip:raspbx", response="ce31a0154031b709fd332ceaed3ff8ba", algorithm=MD5
Content-Length:  0


--end msg--
15:17:55.964   tsx0x15f9744  .....State changed from Null to Calling,
event=TX_MSG
15:17:56.465   tsx0x15f9744  .Retransmit timer event
15:17:56.465   tsx0x15f9744  ..Retransmiting Request msg REGISTER/cseq=8449
(tdta0x15f7748), count=0, restart?=1
15:17:56.466   pjsua_core.c  ..TX 514 bytes Request msg REGISTER/cseq=8449
(tdta0x15f7748) to UDP 192.168.1.40:5060:
REGISTER sip:raspbx SIP/2.0
Via: SIP/2.0/UDP 192.168.1.206:5060
;rport;branch=z9hG4bKPj28sWaDKbpFKzgM2UtgEgUEfzzWXkthw1
Max-Forwards: 70
From: <sip:511 at raspbx>;tag=faxrODRGdph6M4sR8flQIdZv7GfYZC1U
To: <sip:511 at raspbx>
Call-ID: 1qDB9TlQQxR-djUWVFjpQpJ7OlylITVQ
CSeq: 8449 REGISTER
Contact: <sip:511 at 192.168.1.206:5060;ob>
Expires: 0
Authorization: Digest username="511", realm="asterisk", nonce="568148a3",
uri="sip:raspbx", response="ce31a0154031b709fd332ceaed3ff8ba", algorithm=MD5
Content-Length:  0


--end msg--
15:17:56.568 sip_endpoint.c  .Processing incoming message: Response msg
200/REGISTER/cseq=8449 (rdata0x15fa104)
15:17:56.568   pjsua_core.c  ..RX 520 bytes Response msg
200/REGISTER/cseq=8449 (rdata0x15fa104) from UDP 192.168.1.40:5060:
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.1.206:5060
;branch=z9hG4bKPj28sWaDKbpFKzgM2UtgEgUEfzzWXkthw1;received=192.168.1.206;rport=5060
From: <sip:511 at raspbx>;tag=faxrODRGdph6M4sR8flQIdZv7GfYZC1U
To: <sip:511 at raspbx>;tag=as29d71240
Call-ID: 1qDB9TlQQxR-djUWVFjpQpJ7OlylITVQ
CSeq: 8449 REGISTER
Server: FPBX-13.0.105(11.22.0)
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO,
PUBLISH, MESSAGE
Supported: replaces, timer
Expires: 0
Date: Fri, 22 Apr 2016 15:17:56 GMT
Content-Length: 0


--end msg--
15:17:56.569   tsx0x15f9744  ..Incoming Response msg 200/REGISTER/cseq=8449
(rdata0x15fa104) in state Calling
15:17:56.569   tsx0x15f9744  ...State changed from Calling to Completed,
event=RX_MSG
15:17:56.569    pjsua_acc.c  .....sip:511 at raspbx: unregistration success
15:17:56.570 sip_endpoint.c  .Processing incoming message: Response msg
200/REGISTER/cseq=8449 (rdata0x15fa104)
15:17:56.570   pjsua_core.c  ..RX 520 bytes Response msg
200/REGISTER/cseq=8449 (rdata0x15fa104) from UDP 192.168.1.40:5060:
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.1.206:5060
;branch=z9hG4bKPj28sWaDKbpFKzgM2UtgEgUEfzzWXkthw1;received=192.168.1.206;rport=5060
From: <sip:511 at raspbx>;tag=faxrODRGdph6M4sR8flQIdZv7GfYZC1U
To: <sip:511 at raspbx>;tag=as29d71240
Call-ID: 1qDB9TlQQxR-djUWVFjpQpJ7OlylITVQ
CSeq: 8449 REGISTER
Server: FPBX-13.0.105(11.22.0)
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO,
PUBLISH, MESSAGE
Supported: replaces, timer
Expires: 0
Date: Fri, 22 Apr 2016 15:17:56 GMT
Content-Length: 0


--end msg--
15:17:56.571   tsx0x15f9744  ..Incoming Response msg 200/REGISTER/cseq=8449
(rdata0x15fa104) in state Completed
15:17:56.994   pjsua_core.c  .Destroying...
15:17:56.995  pjsua_media.c  .Shutting down media..
15:17:57.392 sip_endpoint.c  .Destroying endpoing instance..
15:17:57.392 sip_transactio  .Stopping transaction layer module
15:17:57.393   tsx0x15f87b4  .Request to terminate transaction
15:17:57.393   tsx0x15f87b4  ..State changed from Completed to Terminated,
event=USER
15:17:57.393   tsx0x15f87b4  .Transaction destroyed!
15:17:57.394   tsx0x15f9744  .Request to terminate transaction
15:17:57.394   tsx0x15f9744  ..State changed from Completed to Terminated,
event=USER
15:17:57.394  tdta0x15f7748  .Destroying txdata Request msg
REGISTER/cseq=8449 (tdta0x15f7748)
15:17:57.394   tsx0x15f9744  .Transaction destroyed!
15:17:57.394 sip_transactio  .Stopped transaction layer module
15:17:57.394 sip_endpoint.c  .Module "mod-unsolicited-mwi" unregistered
15:17:57.394 sip_endpoint.c  .Module "mod-pjsua-options" unregistered
15:17:57.394 sip_endpoint.c  .Module "mod-pjsua-im" unregistered
15:17:57.394 sip_endpoint.c  .Module "mod-pjsua-pres" unregistered
15:17:57.395 sip_endpoint.c  .Module "mod-pjsua" unregistered
15:17:57.395 sip_endpoint.c  .Module "mod-stateful-util" unregistered
15:17:57.395 sip_endpoint.c  .Module "mod-refer" unregistered
15:17:57.395 sip_endpoint.c  .Module "mod-mwi" unregistered
15:17:57.395 sip_endpoint.c  .Module "mod-presence" unregistered
15:17:57.395 sip_endpoint.c  .Module "mod-evsub" unregistered
15:17:57.395 sip_endpoint.c  .Module "mod-invite" unregistered
15:17:57.395 sip_endpoint.c  .Module "mod-100rel" unregistered
15:17:57.395 sip_endpoint.c  .Module "mod-ua" unregistered
15:17:57.396 sip_transactio  .Transaction layer module destroyed
15:17:57.396 sip_endpoint.c  .Module "mod-tsx-layer" unregistered
15:17:57.396 sip_endpoint.c  .Module "mod-msg-print" unregistered
15:17:57.396 sip_endpoint.c  .Module "mod-pjsua-log" unregistered
15:17:57.396 sip_transport.  .Destroying transport manager
15:17:57.397   udp0x15d9210  .SIP UDP transport destroyed
15:17:57.398 sip_endpoint.c  .Endpoint 0x15b0d4c destroyed
15:17:57.398   pjsua_core.c  .PJSUA state changed: CLOSING --> NULL
15:17:57.398   pjsua_core.c  .PJSUA destroyed...




*Alexandre Gonçalves*

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

2016-04-14 15:28 GMT+01:00 Alexandre Gonçalves <alexandre at silvagoncalves.com
>:

> Indeed I'm using a Raspberry (model 1). I've also a model 3, and I'm going
> to try.
>
> Later I post the results.
>
> Thanks.
>
>
> *Alexandre Gonçalves*
>
>
> ............................................................................................................................
> Email: alexandre at silvagoncalves.com
>
> 2016-04-14 15:12 GMT+01:00 Bill Gardner <billg at wavearts.com>:
>
>> Other raspberry users have encountered this issue. I think it's either a
>> buffer issue with ALSA device, or you're running out of CPU. In my
>> experience with PJSIP, one of the most useful debugging statistics is to
>> see a count of audio recording and playback callbacks. That will tell you
>> if media is flowing in both directions to from device, and also if PJSIP is
>> keeping up or running out of CPU. But it is not built-in. - Bill
>>
>>
>>
>> On 4/12/2016 10:32 AM, Alexandre Gonçalves wrote:
>>
>> Running with root privilegies, the warning went away:
>>
>> 14:18:12.516     alsa_dev.c !ca_thread_func(2765): Set thread priority
>> for audio capture thread.
>> 14:18:12.517          speex !warning: discarded first playback frame
>> 14:18:12.521          speex  warning: discarded first playback frame
>> 14:18:12.524          speex  warning: discarded first playback frame
>> 14:18:12.526          speex !warning: discarded first playback frame
>>
>>
>> But the speex warning continues.
>>
>> In my code, I have this callback function defined:
>>
>> 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);
>>     }
>> }
>>
>>
>> The connection with pjsua_conf_connect, shouldn't be with the frames
>> after being processed by the aec?
>>
>>
>> Thanks.
>>
>> *Alexandre Gonçalves*
>>
>>
>> ............................................................................................................................
>> Email:  <alexandre at silvagoncalves.com>alexandre at silvagoncalves.com
>>
>> 2016-04-12 15:04 GMT+01:00 Bill Gardner <billg at wavearts.com>:
>>
>>> Oh, ALSA dev. I don't have much of any experience with this, but it is a
>>> frequent topic on the list. You might want to browse through the archives.
>>> I note the following in the log:
>>>
>>> On 4/12/2016 9:56 AM, Alexandre Gonçalves wrote:
>>>
>>>> 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.
>>>>
>>>
>>> If the audio thread priority isn't high enough, you could get underruns
>>> which would cause the speex warnings you see.
>>>
>>> Bill
>>>
>>>
>>> _______________________________________________
>>> 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/20160422/7a180556/attachment-0002.html>


More information about the pjsip mailing list