Accoustic echo cancelation
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@silvagoncalves.com
2016-04-14 15:12 GMT+01:00 Bill Gardner billg@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@silvagoncalves.comalexandre@silvagoncalves.com
2016-04-12 15:04 GMT+01:00 Bill Gardner billg@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@lists.pjsip.org
http://lists.pjsip.org/mailman/listinfo/pjsip_lists.pjsip.org
Visit our blog: http://blog.pjsip.org
pjsip mailing listpjsip@lists.pjsip.orghttp://lists.pjsip.org/mailman/listinfo/pjsip_lists.pjsip.org
Visit our blog: http://blog.pjsip.org
pjsip mailing list
pjsip@lists.pjsip.org
http://lists.pjsip.org/mailman/listinfo/pjsip_lists.pjsip.org
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@raspbx
15:15:51.331 pjsua_acc.c .Account sip:511@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@raspbx;tag=JT0sL4JEZWqfHHd9YDnOOp1Tcbmneb.b
To: sip:511@raspbx
Call-ID: 1qDB9TlQQxR-djUWVFjpQpJ7OlylITVQ
CSeq: 8446 REGISTER
Contact: sip:511@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@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@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@raspbx;tag=JT0sL4JEZWqfHHd9YDnOOp1Tcbmneb.b
To: sip:511@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@raspbx SIP/2.0
Via: SIP/2.0/UDP 192.168.1.206:5060
;rport;branch=z9hG4bKPjo41IhhWHdzIpp4.RQWgPgFY8FZQZcuqT
Max-Forwards: 70
From: sip:511@raspbx;tag=xMC7e5Vl1OklvvUsXswDdv0561uYcJ5b
To: sip:501@raspbx
Contact: sip:511@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@raspbx;tag=JT0sL4JEZWqfHHd9YDnOOp1Tcbmneb.b
To: sip:511@raspbx
Call-ID: 1qDB9TlQQxR-djUWVFjpQpJ7OlylITVQ
CSeq: 8447 REGISTER
Contact: sip:511@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@raspbx;tag=xMC7e5Vl1OklvvUsXswDdv0561uYcJ5b
To: sip:501@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@raspbx SIP/2.0
Via: SIP/2.0/UDP 192.168.1.206:5060
;rport;branch=z9hG4bKPjo41IhhWHdzIpp4.RQWgPgFY8FZQZcuqT
Max-Forwards: 70
From: sip:511@raspbx;tag=xMC7e5Vl1OklvvUsXswDdv0561uYcJ5b
To: sip:501@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@raspbx SIP/2.0
Via: SIP/2.0/UDP 192.168.1.206:5060
;rport;branch=z9hG4bKPj25ndgyQYBLQeeXnFJzkwI.tkuqVIdLlT
Max-Forwards: 70
From: sip:511@raspbx;tag=xMC7e5Vl1OklvvUsXswDdv0561uYcJ5b
To: sip:501@raspbx
Contact: sip:511@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@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@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@192.168.1.40;tag=as3da53871
To: sip:511@192.168.1.206:5060;ob
Contact: sip:Unknown@192.168.1.40:5060
Call-ID: 5d92cf1d2f3829ad7585f9f12d4d921d@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@192.168.1.40:5060
From: "Unknown" sip:Unknown@192.168.1.40;tag=as3da53871
To: sip:511@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@raspbx;tag=JT0sL4JEZWqfHHd9YDnOOp1Tcbmneb.b
To: sip:511@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@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@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@raspbx;tag=xMC7e5Vl1OklvvUsXswDdv0561uYcJ5b
To: sip:501@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@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@raspbx;tag=xMC7e5Vl1OklvvUsXswDdv0561uYcJ5b
To: sip:501@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@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@raspbx;tag=xMC7e5Vl1OklvvUsXswDdv0561uYcJ5b
To: sip:501@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@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@raspbx;tag=xMC7e5Vl1OklvvUsXswDdv0561uYcJ5b
To: sip:501@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@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@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@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@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@raspbx;tag=xMC7e5Vl1OklvvUsXswDdv0561uYcJ5b
To: sip:501@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@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@raspbx;tag=xMC7e5Vl1OklvvUsXswDdv0561uYcJ5b
To: sip:501@raspbx;tag=as542398d9
Contact: sip:511@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@raspbx;tag=xMC7e5Vl1OklvvUsXswDdv0561uYcJ5b
To: sip:501@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@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@raspbx;tag=xMC7e5Vl1OklvvUsXswDdv0561uYcJ5b
To: sip:501@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@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@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@raspbx;tag=xMC7e5Vl1OklvvUsXswDdv0561uYcJ5b
To: sip:501@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@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@192.168.1.40;tag=as03d7c32a
To: sip:511@192.168.1.206:5060;ob
Contact: sip:Unknown@192.168.1.40:5060
Call-ID: 50bbaec6532b5af73fd075f44bc78aaa@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@192.168.1.40:5060
From: "Unknown" sip:Unknown@192.168.1.40;tag=as03d7c32a
To: sip:511@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@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@raspbx;tag=as542398d9
To: sip:511@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@raspbx;tag=as542398d9
To: sip:511@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@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@192.168.1.40;tag=as2d99b8a5
To: sip:511@192.168.1.206:5060;ob
Contact: sip:Unknown@192.168.1.40:5060
Call-ID: 0ebcd15265d267c53c5967c275462c13@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@192.168.1.40:5060
From: "Unknown" sip:Unknown@192.168.1.40;tag=as2d99b8a5
To: sip:511@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@raspbx;tag=faxrODRGdph6M4sR8flQIdZv7GfYZC1U
To: sip:511@raspbx
Call-ID: 1qDB9TlQQxR-djUWVFjpQpJ7OlylITVQ
CSeq: 8448 REGISTER
Contact: sip:511@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@raspbx;tag=faxrODRGdph6M4sR8flQIdZv7GfYZC1U
To: sip:511@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@raspbx;tag=faxrODRGdph6M4sR8flQIdZv7GfYZC1U
To: sip:511@raspbx
Call-ID: 1qDB9TlQQxR-djUWVFjpQpJ7OlylITVQ
CSeq: 8449 REGISTER
Contact: sip:511@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@raspbx;tag=faxrODRGdph6M4sR8flQIdZv7GfYZC1U
To: sip:511@raspbx
Call-ID: 1qDB9TlQQxR-djUWVFjpQpJ7OlylITVQ
CSeq: 8449 REGISTER
Contact: sip:511@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@raspbx;tag=faxrODRGdph6M4sR8flQIdZv7GfYZC1U
To: sip:511@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@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@raspbx;tag=faxrODRGdph6M4sR8flQIdZv7GfYZC1U
To: sip:511@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@silvagoncalves.com
2016-04-14 15:28 GMT+01:00 Alexandre Gonçalves <alexandre@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@silvagoncalves.com
2016-04-14 15:12 GMT+01:00 Bill Gardner billg@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@silvagoncalves.comalexandre@silvagoncalves.com
2016-04-12 15:04 GMT+01:00 Bill Gardner billg@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@lists.pjsip.org
http://lists.pjsip.org/mailman/listinfo/pjsip_lists.pjsip.org
Visit our blog: http://blog.pjsip.org
pjsip mailing listpjsip@lists.pjsip.orghttp://lists.pjsip.org/mailman/listinfo/pjsip_lists.pjsip.org
Visit our blog: http://blog.pjsip.org
pjsip mailing list
pjsip@lists.pjsip.org
http://lists.pjsip.org/mailman/listinfo/pjsip_lists.pjsip.org