Small subset of calls dropping with FreePBX 15.0.16.44 (16.9.0)

kmo12345 · April 28, 2020, 6:59am

I recently setup a FreePBX for a business wanting to allow some of their users to work remotely. I used a Grandstream GXW410X gateway and a virtualized FreePBX 15.0.16.44 (16.9.0)

All hardware phones are Grandstream GXP2170 and soft phones are MicroSIP.

95% of calls are working fine but the customer is reporting random call dropping to/from some of the soft phones. In order to access the business application, the remote users are connected via VPN.

Looking through the call logs, I can’t seem to find any problems other than MicroSIP reporting occasionally high jitter. There does not appear to be a correlation between high jitter and dropped calls. The customer has 300 down / 15 up and if I can prove the problem is bandwidth related would be willing to upgrade.

The user at 1103 called the hardphone at 106 which call forwarded to the softphone at 1106. Other than the jitter nothing appears out of the ordinary to me. I am using chan_sip cause I couldn’t get the PSTN gateway to work with pjsip (plus I’m just more comfortable with it).

Below is part of the MicroSIP log. I will have to split it into two posts.

13:43:34.054 sip_endpoint.c  Processing incoming message: Request msg INVITE/cseq=102 (rdata07D5AEEC)
13:43:34.054   pjsua_core.c  .RX 1058 bytes Request msg INVITE/cseq=102 (rdata07D5AEEC) from UDP 10.99.11.21:5160:
INVITE sip:[email protected]:55374;ob SIP/2.0
Via: SIP/2.0/UDP 10.99.11.21:5160;branch=z9hG4bK38147f45
Max-Forwards: 70
From: "Virtual Olfat" <sip:[email protected]:5160>;tag=as4ef92226
To: <sip:[email protected]:55374;ob>
Contact: <sip:[email protected]:5160>
Call-ID: [email protected]:5160
CSeq: 102 INVITE
User-Agent: FPBX-15.0.16.44(16.9.0)
Date: Mon, 27 Apr 2020 20:43:33 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
P-Asserted-Identity: "Virtual Olfat" <sip:[email protected]>
Diversion: <sip:[email protected]>;reason=unconditional
Content-Type: application/sdp
Content-Length: 351

v=0
o=root 1671105369 1671105369 IN IP4 10.99.11.21
s=Asterisk PBX 16.9.0
c=IN IP4 10.99.11.21
t=0 0
m=audio 19378 RTP/AVP 0 8 3 111 9 101
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:3 GSM/8000
a=rtpmap:111 G726-32/8000
a=rtpmap:9 G722/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=maxptime:150
a=sendrecv

--end msg--
13:43:34.054   pjsua_call.c  .Incoming Request msg INVITE/cseq=102 (rdata07D5AEEC)
13:43:34.054    tsx0732D9B4  ...Transaction created for Request msg INVITE/cseq=102 (rdata07D5AEEC)
13:43:34.054    tsx0732D9B4  ..Incoming Request msg INVITE/cseq=102 (rdata07D5AEEC) in state Null
13:43:34.055    tsx0732D9B4  ...State changed from Null to Trying, event=RX_MSG
13:43:34.055    dlg0733320C  ....Transaction tsx0732D9B4 state changed to Trying
13:43:34.055    dlg0733320C  ..UAS dialog created
13:43:34.055    dlg0733320C  ..Module mod-invite added as dialog usage, data=072D882C
13:43:34.055    dlg0733320C  ...Session count inc to 3 by mod-invite
13:43:34.055    inv0733320C  ..UAS invite session created for dialog dlg0733320C
13:43:34.055    dlg0733320C  ...Session count inc to 3 by mod-pjsua
13:43:34.055  pjsua_media.c  ..Call 3: initializing media..
13:43:34.074  pjsua_media.c  ...RTP socket reachable at 10.99.11.122:4000
13:43:34.074  pjsua_media.c  ...RTCP socket reachable at 10.99.11.122:4001
13:43:34.074   srtp07D6C348  ...SRTP keying SDES created
13:43:34.074  pjsua_media.c  ...Media index 0 selected for audio call 3
13:43:34.074  pjsua_media.c  ...Call 3: media transport initialization complete: Success
13:43:34.074    dlg0733320C  ...Session count dec to 3 by mod-pjsua
13:43:34.074   pjsua_call.c  ..Call 3: remote NAT type is 0 (Unknown)
13:43:34.074       endpoint  ...Response msg 100/INVITE/cseq=102 (tdta073429E4) created
13:43:34.074    dlg0733320C  ...Initial answer Response msg 100/INVITE/cseq=102 (tdta073429E4)
13:43:34.074    inv0733320C  ...Sending Response msg 100/INVITE/cseq=102 (tdta073429E4)
13:43:34.074    dlg0733320C  ....Sending Response msg 100/INVITE/cseq=102 (tdta073429E4)
13:43:34.074    tsx0732D9B4  ....Sending Response msg 100/INVITE/cseq=102 (tdta073429E4) in state Trying
13:43:34.074  sip_resolve.c  .....Target '10.99.11.21:5160' type=UDP resolved to '10.99.11.21:5160' type=UDP (UDP transport)
13:43:34.074   pjsua_core.c  .....TX 292 bytes Response msg 100/INVITE/cseq=102 (tdta073429E4) to UDP 10.99.11.21:5160:
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 10.99.11.21:5160;received=10.99.11.21;branch=z9hG4bK38147f45
Call-ID: [email protected]:5160
From: "Virtual Olfat" <sip:[email protected]>;tag=as4ef92226
To: <sip:[email protected];ob>
CSeq: 102 INVITE
Content-Length:  0


--end msg--
13:43:34.075    tsx0732D9B4  .....State changed from Trying to Proceeding, event=TX_MSG
13:43:34.075    dlg0733320C  ......Transaction tsx0732D9B4 state changed to Proceeding
13:43:34.075   pjsua_call.c  ..Answering call 3: code=180
13:43:34.075 sip_transport.  ....Tx data Response msg 100/INVITE/cseq=102 (tdta073419DC) cloned
13:43:34.075    inv0733320C  ....Sending Response msg 180/INVITE/cseq=102 (tdta073419DC)
13:43:34.075    dlg0733320C  .....Sending Response msg 180/INVITE/cseq=102 (tdta073419DC)
13:43:34.075    tsx0732D9B4  .....Sending Response msg 180/INVITE/cseq=102 (tdta073419DC) in state Proceeding
13:43:34.075   tdta073429E4  ......Destroying txdata Response msg 100/INVITE/cseq=102 (tdta073429E4)
13:43:34.075   pjsua_core.c  ......TX 478 bytes Response msg 180/INVITE/cseq=102 (tdta073419DC) to UDP 10.99.11.21:5160:
SIP/2.0 180 Ringing
Via: SIP/2.0/UDP 10.99.11.21:5160;received=10.99.11.21;branch=z9hG4bK38147f45
Call-ID: [email protected]:5160
From: "Virtual Olfat" <sip:[email protected]>;tag=as4ef92226
To: <sip:[email protected];ob>;tag=e7c5ac89fa494c88a3a1733820865020
CSeq: 102 INVITE
Contact: "Anna" <sip:[email protected]:55374;ob>
Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS
Content-Length:  0


--end msg--
13:43:34.075    tsx0732D9B4  ......State changed from Proceeding to Proceeding, event=TX_MSG
13:43:34.075    dlg0733320C  .......Transaction tsx0732D9B4 state changed to Proceeding
13:43:34.762    pjsua_aud.c !Creating file player: ringtone.wav..
13:43:34.770   wav_player.c  .File player 'ringtone.wav' created: samp.rate=8000, ch=1, bufsize=4KB, filesize=48KB
13:43:34.770    pjsua_aud.c  .Player created, id=0, slot=1
13:43:34.771    pjsua_aud.c  Conf connect: 1 --> 0
13:43:34.771    pjsua_aud.c  .Set sound device: capture=-1, playback=-2
13:43:34.771    pjsua_aud.c  ..Opening sound device (speaker + mic) PCM@8000/1/20ms
13:43:34.822     wmme_dev.c  ... WaveAPI Sound player "Wave mapper" initialized (format=PCM, clock_rate=8000, channel_count=1, samples_per_frame=160 (20ms))
13:43:34.835     wmme_dev.c  ... WaveAPI Sound recorder "Wave mapper" initialized (format=PCM, clock_rate=8000, channel_count=1, samples_per_frame=160 (20ms))
13:43:34.836     ec07D59840  ...Creating WebRTC AEC
13:43:34.837  echo_webrtc.c  ...WebRTC AEC successfully created with options 0
13:43:34.837     ec07D59840  ...Using delay buffer with WSOLA.
13:43:34.837     ec07D59840  ...WebRTC AEC created, clock_rate=8000, channel=1, samples per frame=160, tail length=200 ms, latency=100 ms
13:43:34.837     wmme_dev.c  ...WMME playback stream started
13:43:34.837     wmme_dev.c  ...WMME capture stream started
13:43:34.838   conference.c  .Port 1 (ringtone.wav) transmitting to port 0 (Wave mapper)
13:43:34.873     ec07D59840 !Prefetching..
13:43:34.893     ec07D59840  Prefetching..
13:43:34.914     ec07D59840  Prefetching..
13:43:34.933     ec07D59840  Prefetching..
13:43:34.953     ec07D59840  Prefetching..
13:43:34.973     ec07D59840  Prefetching..
13:43:34.975     ec07D59840  Latency bufferring complete
13:43:37.875   wav_player.c  File port ringtone.wav EOF
13:43:37.875   wav_player.c  File port ringtone.wav rewinding..
13:43:38.127    pjsua_acc.c !Sending 2 bytes keep-alive packet for acc 0 to 10.99.11.21:5160
13:43:38.127   tdta07346A04  Destroying txdata raw
13:43:40.875   wav_player.c !File port ringtone.wav EOF
13:43:40.875   wav_player.c  File port ringtone.wav rewinding..
13:43:43.875   wav_player.c  File port ringtone.wav EOF
13:43:43.875   wav_player.c  File port ringtone.wav rewinding..
13:43:46.874   wav_player.c  File port ringtone.wav EOF
13:43:46.874   wav_player.c  File port ringtone.wav rewinding..
13:43:47.824   pjsua_call.c !Answering call 3: code=200
13:43:47.824 sip_transport.  ..Tx data Response msg 180/INVITE/cseq=102 (tdta07346A04) cloned
13:43:47.824    inv0733320C  ..SDP negotiation done: Success
13:43:47.824   pjsua_call.c  ...Call 3: remote NAT type is 0 (Unknown)
13:43:47.824  pjsua_media.c  ...Call 3: updating media..
13:43:47.824  pjsua_media.c  .....Media stream call03:0 is destroyed
13:43:47.824    pjsua_aud.c  ....Audio channel update..
13:43:47.824          rtp.c  .....pjmedia_rtp_session_init: ses=0730E3DC, default_pt=0, ssrc=0x43654e38
13:43:47.824          rtp.c  .....pjmedia_rtp_session_init: ses=0730EA64, default_pt=0, ssrc=0x43654e38
13:43:47.824    udp0731A008  .....SO_RCVBUF set to 65536
13:43:47.824    udp0731A008  .....SO_SNDBUF set to 65536
13:43:47.824       stream.c  .....Stream strm0737E12C created
13:43:47.824   strm0737E12C  .....Encoder stream started
13:43:47.824   strm0737E12C  .....Decoder stream started
13:43:47.824  pjsua_media.c  ....Audio updated, stream #0: PCMU (sendrecv)
13:43:47.824    pjsua_aud.c  ...Conf connect: 2 --> 0
13:43:47.824   conference.c  ....Port 2 (sip:[email protected]:5160) transmitting to port 0 (Wave mapper)
13:43:47.825    pjsua_aud.c  ...Conf connect: 0 --> 2
13:43:47.825   conference.c  ....Port 0 (Wave mapper) transmitting to port 2 (sip:[email protected]:5160)
13:43:47.825    inv0733320C  ..Sending Response msg 200/INVITE/cseq=102 (tdta07346A04)
13:43:47.825    dlg0733320C  ...Sending Response msg 200/INVITE/cseq=102 (tdta07346A04)
13:43:47.825    tsx0732D9B4  ...Sending Response msg 200/INVITE/cseq=102 (tdta07346A04) in state Proceeding
13:43:47.825   tdta073419DC  ....Destroying txdata Response msg 180/INVITE/cseq=102 (tdta073419DC)
13:43:47.825   pjsua_core.c  ....TX 871 bytes Response msg 200/INVITE/cseq=102 (tdta07346A04) to UDP 10.99.11.21:5160:
SIP/2.0 200 OK
Via: SIP/2.0/UDP 10.99.11.21:5160;received=10.99.11.21;branch=z9hG4bK38147f45
Call-ID: [email protected]:5160
From: "Virtual Olfat" <sip:[email protected]>;tag=as4ef92226
To: <sip:[email protected];ob>;tag=e7c5ac89fa494c88a3a1733820865020
CSeq: 102 INVITE
Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS
Contact: "Anna" <sip:[email protected]:55374;ob>
Supported: replaces, 100rel, timer, norefersub
Content-Type: application/sdp
Content-Length:   316

v=0
o=- 3796983814 3796983815 IN IP4 10.99.11.122
s=pjmedia
b=AS:84
t=0 0
a=X-nat:0
m=audio 4000 RTP/AVP 0 101
c=IN IP4 10.99.11.122
b=TIAS:64000
a=rtcp:4001 IN IP4 10.99.11.122
a=sendrecv
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ssrc:1130712632 cname:456d7e0e06e30a6c

--end msg--
13:43:47.825    tsx0732D9B4  ....State changed from Proceeding to Completed, event=TX_MSG
13:43:47.825    dlg0733320C  .....Transaction tsx0732D9B4 state changed to Completed
13:43:47.825    pjsua_aud.c  Conf disconnect: 1 -x- 0
13:43:47.825   conference.c  .Port 1 (ringtone.wav) stop transmitting to port 0 (Wave mapper)
13:43:47.825    pjsua_aud.c  Destroying player 0..
13:43:47.834   strm0737E12C !Jitter buffer is bufferring (prefetch=0)
13:43:47.834   strm0737E12C  Start talksprut..
13:43:48.221   strm0737E12C !RTP status: badpt=0, badssrc=0, dup=0, outorder=0, probation=-1, restart=0
13:43:48.234   strm0737E12C !Jitter buffer starts returning normal frames (after 20 empty/lost)
13:43:48.324    tsx0732D9B4 !Retransmit timer event
13:43:48.324    tsx0732D9B4  .Retransmiting Response msg 200/INVITE/cseq=102 (tdta07346A04), count=0, restart?=1
13:43:48.324   pjsua_core.c  .TX 871 bytes Response msg 200/INVITE/cseq=102 (tdta07346A04) to UDP 10.99.11.21:5160:
SIP/2.0 200 OK
Via: SIP/2.0/UDP 10.99.11.21:5160;received=10.99.11.21;branch=z9hG4bK38147f45
Call-ID: [email protected]:5160
From: "Virtual Olfat" <sip:[email protected]>;tag=as4ef92226
To: <sip:[email protected];ob>;tag=e7c5ac89fa494c88a3a1733820865020
CSeq: 102 INVITE
Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS
Contact: "Anna" <sip:[email protected]:55374;ob>
Supported: replaces, 100rel, timer, norefersub
Content-Type: application/sdp
Content-Length:   316

v=0
o=- 3796983814 3796983815 IN IP4 10.99.11.122
s=pjmedia
b=AS:84
t=0 0
a=X-nat:0
m=audio 4000 RTP/AVP 0 101
c=IN IP4 10.99.11.122
b=TIAS:64000
a=rtcp:4001 IN IP4 10.99.11.122
a=sendrecv
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ssrc:1130712632 cname:456d7e0e06e30a6c

--end msg--
13:43:48.854   strm0737E12C !Frame lost, recovered!
13:43:48.855   strm0737E12C  Jitter buffer starts returning normal frames (after 1 empty/lost)
13:43:49.034   strm0737E12C  Frame lost, recovered!
13:43:49.055   strm0737E12C  Jitter buffer starts returning normal frames (after 1 empty/lost)
13:43:49.234   strm0737E12C  Frame lost, recovered!
13:43:49.234   strm0737E12C  Jitter buffer starts returning normal frames (after 1 empty/lost)
13:43:49.326    tsx0732D9B4 !Retransmit timer event
13:43:49.326    tsx0732D9B4  .Retransmiting Response msg 200/INVITE/cseq=102 (tdta07346A04), count=1, restart?=1
13:43:49.326   pjsua_core.c  .TX 871 bytes Response msg 200/INVITE/cseq=102 (tdta07346A04) to UDP 10.99.11.21:5160:
SIP/2.0 200 OK
Via: SIP/2.0/UDP 10.99.11.21:5160;received=10.99.11.21;branch=z9hG4bK38147f45
Call-ID: [email protected]:5160
From: "Virtual Olfat" <sip:[email protected]>;tag=as4ef92226
To: <sip:[email protected];ob>;tag=e7c5ac89fa494c88a3a1733820865020
CSeq: 102 INVITE
Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS
Contact: "Anna" <sip:[email protected]:55374;ob>
Supported: replaces, 100rel, timer, norefersub
Content-Type: application/sdp
Content-Length:   316

v=0
o=- 3796983814 3796983815 IN IP4 10.99.11.122
s=pjmedia
b=AS:84
t=0 0
a=X-nat:0
m=audio 4000 RTP/AVP 0 101
c=IN IP4 10.99.11.122
b=TIAS:64000
a=rtcp:4001 IN IP4 10.99.11.122
a=sendrecv
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ssrc:1130712632 cname:456d7e0e06e30a6c

--end msg--
13:43:49.415   strm0737E12C !Frame lost, recovered!
13:43:49.434   strm0737E12C  Jitter buffer starts returning normal frames (after 1 empty/lost)
13:43:49.615   strm0737E12C  Frame lost, recovered!
13:43:49.615   strm0737E12C  Jitter buffer starts returning normal frames (after 1 empty/lost)
13:43:49.795   strm0737E12C  Frame lost, recovered!
13:43:49.814   strm0737E12C  Jitter buffer starts returning normal frames (after 1 empty/lost)
13:43:49.995   strm0737E12C  Frame lost, recovered!
13:43:49.995   strm0737E12C  Jitter buffer starts returning normal frames (after 1 empty/lost)
13:43:50.174   strm0737E12C  Frame lost, recovered!
13:43:50.195   strm0737E12C  Jitter buffer starts returning normal frames (after 1 empty/lost)
13:43:50.375   strm0737E12C  Frame lost, recovered!
13:43:50.375   strm0737E12C  Jitter buffer starts returning normal frames (after 1 empty/lost)
13:43:50.555   strm0737E12C  Frame lost, recovered!
13:43:50.574   strm0737E12C  Jitter buffer starts returning normal frames (after 1 empty/lost)
13:43:50.754   strm0737E12C  Frame lost, recovered!
13:43:50.754   strm0737E12C  Jitter buffer starts returning normal frames (after 1 empty/lost)
13:43:50.935   strm0737E12C  Frame lost, recovered!
13:43:50.954   strm0737E12C  Jitter buffer starts returning normal frames (after 1 empty/lost)
13:43:51.134   strm0737E12C  Frame lost, recovered!
13:43:51.135   strm0737E12C  Jitter buffer starts returning normal frames (after 1 empty/lost)
13:43:51.314   strm0737E12C  Frame lost, recovered!
13:43:51.326    tsx0732D9B4 !Retransmit timer event
13:43:51.326    tsx0732D9B4  .Retransmiting Response msg 200/INVITE/cseq=102 (tdta07346A04), count=2, restart?=1
13:43:51.326   pjsua_core.c  .TX 871 bytes Response msg 200/INVITE/cseq=102 (tdta07346A04) to UDP 10.99.11.21:5160:
SIP/2.0 200 OK
Via: SIP/2.0/UDP 10.99.11.21:5160;received=10.99.11.21;branch=z9hG4bK38147f45
Call-ID: [email protected]:5160
From: "Virtual Olfat" <sip:[email protected]>;tag=as4ef92226
To: <sip:[email protected];ob>;tag=e7c5ac89fa494c88a3a1733820865020
CSeq: 102 INVITE
Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS
Contact: "Anna" <sip:[email protected]:55374;ob>
Supported: replaces, 100rel, timer, norefersub
Content-Type: application/sdp
Content-Length:   316

v=0
o=- 3796983814 3796983815 IN IP4 10.99.11.122
s=pjmedia
b=AS:84
t=0 0
a=X-nat:0
m=audio 4000 RTP/AVP 0 101
c=IN IP4 10.99.11.122
b=TIAS:64000
a=rtcp:4001 IN IP4 10.99.11.122
a=sendrecv
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ssrc:1130712632 cname:456d7e0e06e30a6c

--end msg--
13:43:51.335   strm0737E12C !Jitter buffer starts returning normal frames (after 1 empty/lost)
13:43:51.515   strm0737E12C  Frame lost, recovered!
13:43:51.515   strm0737E12C  Jitter buffer starts returning normal frames (after 1 empty/lost)
13:43:51.695   strm0737E12C  Frame lost, recovered!
13:43:51.714   strm0737E12C  Jitter buffer starts returning normal frames (after 1 empty/lost)
13:43:51.895   strm0737E12C  Frame lost, recovered!
13:43:51.915   strm0737E12C  Jitter buffer starts returning normal frames (after 1 empty/lost)
13:43:52.095   strm0737E12C  Frame lost, recovered!
13:43:52.115   strm0737E12C  Jitter buffer starts returning normal frames (after 1 empty/lost)
13:43:52.295   strm0737E12C  Frame lost, recovered!
13:43:52.315   strm0737E12C  Jitter buffer starts returning normal frames (after 1 empty/lost)
13:43:52.494   strm0737E12C  Frame lost, recovered!
13:43:52.494   strm0737E12C  Jitter buffer starts returning normal frames (after 1 empty/lost)
13:43:52.694   strm0737E12C  Frame lost, recovered!
13:43:52.714   strm0737E12C  Jitter buffer starts returning normal frames (after 1 empty/lost)
13:43:53.034   strm0737E12C  Frame lost, recovered!
13:43:53.034   strm0737E12C  Jitter buffer starts returning normal frames (after 1 empty/lost)
13:43:53.128    pjsua_acc.c !Sending 2 bytes keep-alive packet for acc 0 to 10.99.11.21:5160
13:43:53.128   tdta07348A14  Destroying txdata raw
13:43:53.208 sip_endpoint.c  Processing incoming message: Request msg OPTIONS/cseq=102 (rdata07D5AEEC)
13:43:53.208   pjsua_core.c  .RX 560 bytes Request msg OPTIONS/cseq=102 (rdata07D5AEEC) from UDP 10.99.11.21:5160:
OPTIONS sip:[email protected]:55374;ob SIP/2.0
Via: SIP/2.0/UDP 10.99.11.21:5160;branch=z9hG4bK797f2066
Max-Forwards: 70
From: "Unknown" <sip:[email protected]:5160>;tag=as51fca75b
To: <sip:[email protected]:55374;ob>
Contact: <sip:[email protected]:5160>
Call-ID: [email protected]:5160
CSeq: 102 OPTIONS
User-Agent: FPBX-15.0.16.44(16.9.0)
Date: Mon, 27 Apr 2020 20:43:52 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Content-Length: 0


--end msg--
13:43:53.208       endpoint  .Response msg 200/OPTIONS/cseq=102 (tdta07348A14) created
13:43:53.208  sip_resolve.c  .Target '10.99.11.21:5160' type=UDP resolved to '10.99.11.21:5160' type=UDP (UDP transport)
13:43:53.208   pjsua_core.c  .TX 709 bytes Response msg 200/OPTIONS/cseq=102 (tdta07348A14) to UDP 10.99.11.21:5160:
SIP/2.0 200 OK
Via: SIP/2.0/UDP 10.99.11.21:5160;received=10.99.11.21;branch=z9hG4bK797f2066
Call-ID: [email protected]:5160
From: "Unknown" <sip:[email protected]>;tag=as51fca75b
To: <sip:[email protected];ob>;tag=z9hG4bK797f2066
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
User-Agent: MicroSIP/3.19.28
Content-Length:  0


--end msg--
13:43:53.208   tdta07348A14  .Destroying txdata Response msg 200/OPTIONS/cseq=102 (tdta07348A14)
13:43:53.355   strm0737E12C !Frame lost, recovered!
13:43:53.355   strm0737E12C  Jitter buffer starts returning normal frames (after 1 empty/lost)
13:43:54.195   strm0737E12C  Jitter buffer empty (prefetch=0), plc invoked
13:43:54.375   strm0737E12C  Jitter buffer starts returning normal frames (after 9 empty/lost)
13:43:54.414   strm0737E12C  Jitter buffer empty (prefetch=0), plc invoked
13:43:54.435   strm0737E12C  Jitter buffer starts returning normal frames (after 1 empty/lost)
13:43:54.755   strm0737E12C  Frame lost, recovered!

kmo12345 · April 28, 2020, 9:51am

Here is the rest of the MicroSIP log

13:43:54.755   strm0737E12C  Jitter buffer starts returning normal frames (after 1 empty/lost)
13:43:54.954   strm0737E12C  Frame lost, recovered!
13:43:54.975   strm0737E12C  Jitter buffer starts returning normal frames (after 1 empty/lost)
13:43:55.154   strm0737E12C  Frame lost, recovered!
13:43:55.154   strm0737E12C  Jitter buffer starts returning normal frames (after 1 empty/lost)
13:43:55.327    tsx0732D9B4 !Retransmit timer event
13:43:55.327    tsx0732D9B4  .Retransmiting Response msg 200/INVITE/cseq=102 (tdta07346A04), count=3, restart?=1
13:43:55.327   pjsua_core.c  .TX 871 bytes Response msg 200/INVITE/cseq=102 (tdta07346A04) to UDP 10.99.11.21:5160:
SIP/2.0 200 OK
Via: SIP/2.0/UDP 10.99.11.21:5160;received=10.99.11.21;branch=z9hG4bK38147f45
Call-ID: [email protected]:5160
From: "Virtual Olfat" <sip:[email protected]>;tag=as4ef92226
To: <sip:[email protected];ob>;tag=e7c5ac89fa494c88a3a1733820865020
CSeq: 102 INVITE
Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS
Contact: "Anna" <sip:[email protected]:55374;ob>
Supported: replaces, 100rel, timer, norefersub
Content-Type: application/sdp
Content-Length:   316

v=0
o=- 3796983814 3796983815 IN IP4 10.99.11.122
s=pjmedia
b=AS:84
t=0 0
a=X-nat:0
m=audio 4000 RTP/AVP 0 101
c=IN IP4 10.99.11.122
b=TIAS:64000
a=rtcp:4001 IN IP4 10.99.11.122
a=sendrecv
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ssrc:1130712632 cname:456d7e0e06e30a6c

--end msg--
13:43:55.335   strm0737E12C !Frame lost, recovered!
13:43:55.355   strm0737E12C  Jitter buffer starts returning normal frames (after 1 empty/lost)
13:43:55.536   strm0737E12C  Frame lost, recovered!
13:43:55.536   strm0737E12C  Jitter buffer starts returning normal frames (after 1 empty/lost)
13:43:55.715   strm0737E12C  Frame lost, recovered!
13:43:55.734   strm0737E12C  Jitter buffer starts returning normal frames (after 1 empty/lost)
13:43:55.914   strm0737E12C  Frame lost, recovered!
13:43:55.914   strm0737E12C  Jitter buffer starts returning normal frames (after 1 empty/lost)
13:43:56.094   strm0737E12C  Frame lost, recovered!
13:43:56.114   strm0737E12C  Jitter buffer starts returning normal frames (after 1 empty/lost)
13:43:56.294   strm0737E12C  Frame lost, recovered!
13:43:56.294   strm0737E12C  Jitter buffer starts returning normal frames (after 1 empty/lost)
13:43:56.474   strm0737E12C  Frame lost, recovered!
13:43:56.494   strm0737E12C  Jitter buffer starts returning normal frames (after 1 empty/lost)
13:43:56.674   strm0737E12C  Frame lost, recovered!
13:43:56.674   strm0737E12C  Jitter buffer starts returning normal frames (after 1 empty/lost)
13:43:56.855   strm0737E12C  Frame lost, recovered!
13:43:56.874   strm0737E12C  Jitter buffer starts returning normal frames (after 1 empty/lost)
13:43:57.054   strm0737E12C  Frame lost, recovered!
13:43:57.054   strm0737E12C  Jitter buffer starts returning normal frames (after 1 empty/lost)
13:43:57.235   strm0737E12C  Frame lost, recovered!
13:43:57.255   strm0737E12C  Jitter buffer starts returning normal frames (after 1 empty/lost)
13:43:57.554   strm0737E12C  Frame lost, recovered!
13:43:57.554   strm0737E12C  Jitter buffer starts returning normal frames (after 1 empty/lost)
13:43:57.855   strm0737E12C  Frame lost, recovered!
13:43:57.855   strm0737E12C  Jitter buffer starts returning normal frames (after 1 empty/lost)
13:43:58.195   strm0737E12C  Frame lost, recovered!
13:43:58.195   strm0737E12C  Jitter buffer starts returning normal frames (after 1 empty/lost)
13:43:58.515   strm0737E12C  Frame lost, recovered!
13:43:58.535   strm0737E12C  Jitter buffer starts returning normal frames (after 1 empty/lost)
13:43:58.835   strm0737E12C  Frame lost, recovered!
13:43:58.854   strm0737E12C  Jitter buffer starts returning normal frames (after 1 empty/lost)
13:43:59.155   strm0737E12C  Frame lost, recovered!
13:43:59.155   strm0737E12C  Jitter buffer starts returning normal frames (after 1 empty/lost)
13:43:59.327    tsx0732D9B4 !Retransmit timer event
13:43:59.327    tsx0732D9B4  .Retransmiting Response msg 200/INVITE/cseq=102 (tdta07346A04), count=4, restart?=1
13:43:59.327   pjsua_core.c  .TX 871 bytes Response msg 200/INVITE/cseq=102 (tdta07346A04) to UDP 10.99.11.21:5160:
SIP/2.0 200 OK
Via: SIP/2.0/UDP 10.99.11.21:5160;received=10.99.11.21;branch=z9hG4bK38147f45
Call-ID: [email protected]:5160
From: "Virtual Olfat" <sip:[email protected]>;tag=as4ef92226
To: <sip:[email protected];ob>;tag=e7c5ac89fa494c88a3a1733820865020
CSeq: 102 INVITE
Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS
Contact: "Anna" <sip:[email protected]:55374;ob>
Supported: replaces, 100rel, timer, norefersub
Content-Type: application/sdp
Content-Length:   316

v=0
o=- 3796983814 3796983815 IN IP4 10.99.11.122
s=pjmedia
b=AS:84
t=0 0
a=X-nat:0
m=audio 4000 RTP/AVP 0 101
c=IN IP4 10.99.11.122
b=TIAS:64000
a=rtcp:4001 IN IP4 10.99.11.122
a=sendrecv
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ssrc:1130712632 cname:456d7e0e06e30a6c

--end msg--
13:43:59.515   strm0737E12C !Frame lost, recovered!
13:43:59.515   strm0737E12C  Jitter buffer starts returning normal frames (after 1 empty/lost)
13:44:00.855   strm0737E12C  Frame lost, recovered!
13:44:00.855   strm0737E12C  Jitter buffer starts returning normal frames (after 1 empty/lost)
13:44:01.174   strm0737E12C  Jitter buffer empty (prefetch=0), plc invoked
13:44:01.255   strm0737E12C  Jitter buffer starts returning normal frames (after 4 empty/lost)
13:44:01.294   strm0737E12C  Jitter buffer empty (prefetch=0), plc invoked
13:44:01.415   strm0737E12C  Jitter buffer starts returning normal frames (after 6 empty/lost)
13:44:02.154   strm0737E12C  Frame lost, recovered!
13:44:02.174   strm0737E12C  Jitter buffer starts returning normal frames (after 1 empty/lost)
13:44:02.894   strm0737E12C  Frame lost, recovered!
13:44:02.915   strm0737E12C  Jitter buffer starts returning normal frames (after 1 empty/lost)
13:44:03.134   strm0737E12C  Frame lost, recovered!
13:44:03.134   strm0737E12C  Jitter buffer starts returning normal frames (after 1 empty/lost)
13:44:03.329    tsx0732D9B4 !Retransmit timer event
13:44:03.329    tsx0732D9B4  .Retransmiting Response msg 200/INVITE/cseq=102 (tdta07346A04), count=5, restart?=1
13:44:03.329   pjsua_core.c  .TX 871 bytes Response msg 200/INVITE/cseq=102 (tdta07346A04) to UDP 10.99.11.21:5160:
SIP/2.0 200 OK
Via: SIP/2.0/UDP 10.99.11.21:5160;received=10.99.11.21;branch=z9hG4bK38147f45
Call-ID: [email protected]:5160
From: "Virtual Olfat" <sip:[email protected]>;tag=as4ef92226
To: <sip:[email protected];ob>;tag=e7c5ac89fa494c88a3a1733820865020
CSeq: 102 INVITE
Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS
Contact: "Anna" <sip:[email protected]:55374;ob>
Supported: replaces, 100rel, timer, norefersub
Content-Type: application/sdp
Content-Length:   316

v=0
o=- 3796983814 3796983815 IN IP4 10.99.11.122
s=pjmedia
b=AS:84
t=0 0
a=X-nat:0
m=audio 4000 RTP/AVP 0 101
c=IN IP4 10.99.11.122
b=TIAS:64000
a=rtcp:4001 IN IP4 10.99.11.122
a=sendrecv
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ssrc:1130712632 cname:456d7e0e06e30a6c

--end msg--
13:44:03.374   strm0737E12C !Frame lost, recovered!
13:44:03.394   strm0737E12C  Jitter buffer starts returning normal frames (after 1 empty/lost)
13:44:03.634   strm0737E12C  Frame lost, recovered!
13:44:03.635   strm0737E12C  Jitter buffer starts returning normal frames (after 1 empty/lost)
13:44:03.875   strm0737E12C  Frame lost, recovered!
13:44:03.894   strm0737E12C  Jitter buffer starts returning normal frames (after 1 empty/lost)
13:44:04.095   strm0737E12C  Frame lost, recovered!
13:44:04.095   strm0737E12C  Jitter buffer starts returning normal frames (after 1 empty/lost)
13:44:04.295   strm0737E12C  Frame lost, recovered!
13:44:04.314   strm0737E12C  Jitter buffer starts returning normal frames (after 1 empty/lost)
13:44:04.535   strm0737E12C  Frame lost, recovered!
13:44:04.535   strm0737E12C  Jitter buffer starts returning normal frames (after 1 empty/lost)
13:44:04.714   strm0737E12C  Frame lost, recovered!
13:44:04.735   strm0737E12C  Jitter buffer starts returning normal frames (after 1 empty/lost)
13:44:04.934   strm0737E12C  Frame lost, recovered!
13:44:04.934   strm0737E12C  Jitter buffer starts returning normal frames (after 1 empty/lost)
13:44:05.135   strm0737E12C  Frame lost, recovered!
13:44:05.135   strm0737E12C  Jitter buffer starts returning normal frames (after 1 empty/lost)
13:44:05.355   strm0737E12C  Frame lost, recovered!
13:44:05.376   strm0737E12C  Jitter buffer starts returning normal frames (after 1 empty/lost)
13:44:05.615   strm0737E12C  Frame lost, recovered!
13:44:05.615   strm0737E12C  Jitter buffer starts returning normal frames (after 1 empty/lost)
13:44:05.894   strm0737E12C  Frame lost, recovered!
13:44:05.914   strm0737E12C  Jitter buffer starts returning normal frames (after 1 empty/lost)
13:44:06.174   strm0737E12C  Frame lost, recovered!
13:44:06.195   strm0737E12C  Jitter buffer starts returning normal frames (after 1 empty/lost)
13:44:06.274   strm0737E12C  Jitter buffer empty (prefetch=0), plc invoked
13:44:06.314   strm0737E12C  Jitter buffer starts returning normal frames (after 2 empty/lost)
13:44:07.330    tsx0732D9B4 !Retransmit timer event
13:44:07.330    tsx0732D9B4  .Retransmiting Response msg 200/INVITE/cseq=102 (tdta07346A04), count=6, restart?=1
13:44:07.330   pjsua_core.c  .TX 871 bytes Response msg 200/INVITE/cseq=102 (tdta07346A04) to UDP 10.99.11.21:5160:
SIP/2.0 200 OK
Via: SIP/2.0/UDP 10.99.11.21:5160;received=10.99.11.21;branch=z9hG4bK38147f45
Call-ID: [email protected]:5160
From: "Virtual Olfat" <sip:[email protected]>;tag=as4ef92226
To: <sip:[email protected];ob>;tag=e7c5ac89fa494c88a3a1733820865020
CSeq: 102 INVITE
Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS
Contact: "Anna" <sip:[email protected]:55374;ob>
Supported: replaces, 100rel, timer, norefersub
Content-Type: application/sdp
Content-Length:   316

v=0
o=- 3796983814 3796983815 IN IP4 10.99.11.122
s=pjmedia
b=AS:84
t=0 0
a=X-nat:0
m=audio 4000 RTP/AVP 0 101
c=IN IP4 10.99.11.122
b=TIAS:64000
a=rtcp:4001 IN IP4 10.99.11.122
a=sendrecv
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ssrc:1130712632 cname:456d7e0e06e30a6c

--end msg--
13:44:07.714   strm0737E12C !Frame lost, recovered!
13:44:07.714   strm0737E12C  Jitter buffer starts returning normal frames (after 1 empty/lost)
13:44:08.054   strm0737E12C  Frame lost, recovered!
13:44:08.074   strm0737E12C  Jitter buffer starts returning normal frames (after 1 empty/lost)
13:44:08.128    pjsua_acc.c !Sending 2 bytes keep-alive packet for acc 0 to 10.99.11.21:5160
13:44:08.128   tdta073419DC  Destroying txdata raw
13:44:08.394   strm0737E12C !Frame lost, recovered!
13:44:08.415   strm0737E12C  Jitter buffer starts returning normal frames (after 1 empty/lost)
13:44:08.735   strm0737E12C  Frame lost, recovered!
13:44:08.735   strm0737E12C  Jitter buffer starts returning normal frames (after 1 empty/lost)
13:44:09.114   strm0737E12C  Frame lost, recovered!
13:44:09.135   strm0737E12C  Jitter buffer starts returning normal frames (after 1 empty/lost)
13:44:09.594   strm0737E12C  Frame lost, recovered!
13:44:09.594   strm0737E12C  Jitter buffer starts returning normal frames (after 1 empty/lost)
13:44:10.034   strm0737E12C  Frame lost, recovered!
13:44:10.055   strm0737E12C  Jitter buffer starts returning normal frames (after 1 empty/lost)
13:44:11.214   strm0737E12C  Frame lost, recovered!
13:44:11.214   strm0737E12C  Jitter buffer starts returning normal frames (after 1 empty/lost)
13:44:11.330    tsx0732D9B4 !Retransmit timer event
13:44:11.330    tsx0732D9B4  .Retransmiting Response msg 200/INVITE/cseq=102 (tdta07346A04), count=7, restart?=1
13:44:11.330   pjsua_core.c  .TX 871 bytes Response msg 200/INVITE/cseq=102 (tdta07346A04) to UDP 10.99.11.21:5160:
SIP/2.0 200 OK
Via: SIP/2.0/UDP 10.99.11.21:5160;received=10.99.11.21;branch=z9hG4bK38147f45
Call-ID: [email protected]:5160
From: "Virtual Olfat" <sip:[email protected]>;tag=as4ef92226
To: <sip:[email protected];ob>;tag=e7c5ac89fa494c88a3a1733820865020
CSeq: 102 INVITE
Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS
Contact: "Anna" <sip:[email protected]:55374;ob>
Supported: replaces, 100rel, timer, norefersub
Content-Type: application/sdp
Content-Length:   316

v=0
o=- 3796983814 3796983815 IN IP4 10.99.11.122
s=pjmedia
b=AS:84
t=0 0
a=X-nat:0
m=audio 4000 RTP/AVP 0 101
c=IN IP4 10.99.11.122
b=TIAS:64000
a=rtcp:4001 IN IP4 10.99.11.122
a=sendrecv
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ssrc:1130712632 cname:456d7e0e06e30a6c

--end msg--
13:44:11.814   strm0737E12C !Frame lost, recovered!
13:44:11.834   strm0737E12C  Jitter buffer starts returning normal frames (after 1 empty/lost)
13:44:12.234   strm0737E12C  Jitter buffer empty (prefetch=0), plc invoked
13:44:12.254   strm0737E12C  Jitter buffer starts returning normal frames (after 1 empty/lost)
13:44:15.215   strm0737E12C  Jitter buffer empty (prefetch=0), plc invoked
13:44:15.234   strm0737E12C  Jitter buffer starts returning normal frames (after 1 empty/lost)
13:44:15.331    tsx0732D9B4 !Retransmit timer event
13:44:15.331    tsx0732D9B4  .Retransmiting Response msg 200/INVITE/cseq=102 (tdta07346A04), count=8, restart?=1
13:44:15.331   pjsua_core.c  .TX 871 bytes Response msg 200/INVITE/cseq=102 (tdta07346A04) to UDP 10.99.11.21:5160:
SIP/2.0 200 OK
Via: SIP/2.0/UDP 10.99.11.21:5160;received=10.99.11.21;branch=z9hG4bK38147f45
Call-ID: [email protected]:5160
From: "Virtual Olfat" <sip:[email protected]>;tag=as4ef92226
To: <sip:[email protected];ob>;tag=e7c5ac89fa494c88a3a1733820865020
CSeq: 102 INVITE
Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS
Contact: "Anna" <sip:[email protected]:55374;ob>
Supported: replaces, 100rel, timer, norefersub
Content-Type: application/sdp
Content-Length:   316

v=0
o=- 3796983814 3796983815 IN IP4 10.99.11.122
s=pjmedia
b=AS:84
t=0 0
a=X-nat:0
m=audio 4000 RTP/AVP 0 101
c=IN IP4 10.99.11.122
b=TIAS:64000
a=rtcp:4001 IN IP4 10.99.11.122
a=sendrecv
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ssrc:1130712632 cname:456d7e0e06e30a6c

--end msg--
13:44:16.434   strm0737E12C !Frame lost, recovered!
13:44:16.454   strm0737E12C  Jitter buffer starts returning normal frames (after 1 empty/lost)
13:44:16.694   strm0737E12C  Jitter buffer empty (prefetch=0), plc invoked
13:44:16.734   strm0737E12C  Jitter buffer starts returning normal frames (after 2 empty/lost)
13:44:18.755   strm0737E12C  Frame lost, recovered!
13:44:18.755   strm0737E12C  Jitter buffer starts returning normal frames (after 1 empty/lost)
13:44:19.215   strm0737E12C  Frame lost, recovered!
13:44:19.234   strm0737E12C  Jitter buffer starts returning normal frames (after 1 empty/lost)
13:44:19.331    tsx0732D9B4 !Retransmit timer event
13:44:19.331    tsx0732D9B4  .Retransmiting Response msg 200/INVITE/cseq=102 (tdta07346A04), count=9, restart?=1
13:44:19.331   pjsua_core.c  .TX 871 bytes Response msg 200/INVITE/cseq=102 (tdta07346A04) to UDP 10.99.11.21:5160:
SIP/2.0 200 OK
Via: SIP/2.0/UDP 10.99.11.21:5160;received=10.99.11.21;branch=z9hG4bK38147f45
Call-ID: [email protected]:5160
From: "Virtual Olfat" <sip:[email protected]>;tag=as4ef92226
To: <sip:[email protected];ob>;tag=e7c5ac89fa494c88a3a1733820865020
CSeq: 102 INVITE
Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS
Contact: "Anna" <sip:[email protected]:55374;ob>
Supported: replaces, 100rel, timer, norefersub
Content-Type: application/sdp
Content-Length:   316

v=0
o=- 3796983814 3796983815 IN IP4 10.99.11.122
s=pjmedia
b=AS:84
t=0 0
a=X-nat:0
m=audio 4000 RTP/AVP 0 101
c=IN IP4 10.99.11.122
b=TIAS:64000
a=rtcp:4001 IN IP4 10.99.11.122
a=sendrecv
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ssrc:1130712632 cname:456d7e0e06e30a6c

--end msg--
13:44:19.675   strm0737E12C !Frame lost, recovered!
13:44:19.675   strm0737E12C  Jitter buffer starts returning normal frames (after 1 empty/lost)
13:44:19.826    tsx0732D9B4 !Timeout timer event
13:44:19.826    tsx0732D9B4  .State changed from Completed to Terminated, event=TIMER
13:44:19.826    dlg0733320C  ..Transaction tsx0732D9B4 state changed to Terminated
13:44:19.826       endpoint  ...Request msg BYE/cseq=13986 (tdta073419DC) created.
13:44:19.826    inv0733320C  ....Sending Request msg BYE/cseq=13986 (tdta073419DC)
13:44:19.826    dlg0733320C  .....Sending Request msg BYE/cseq=13986 (tdta073419DC)
13:44:19.826    tsx0732C19C  ......Transaction created for Request msg BYE/cseq=13985 (tdta073419DC)
13:44:19.826    tsx0732C19C  .....Sending Request msg BYE/cseq=13985 (tdta073419DC) in state Null
13:44:19.826  sip_resolve.c  ......Target '10.99.11.21:5160' type=Unspecified resolved to '10.99.11.21:5160' type=UDP (UDP transport)
13:44:19.826   pjsua_core.c  ......TX 378 bytes Request msg BYE/cseq=13985 (tdta073419DC) to UDP 10.99.11.21:5160:
BYE sip:[email protected]:5160 SIP/2.0
Via: SIP/2.0/UDP 10.99.11.122:55374;rport;branch=z9hG4bKPj81a7d804590f48b589b2c13ea3677182
Max-Forwards: 70
From: <sip:[email protected];ob>;tag=e7c5ac89fa494c88a3a1733820865020
To: "Virtual Olfat" <sip:[email protected]>;tag=as4ef92226
Call-ID: [email protected]:5160
CSeq: 13985 BYE
Content-Length:  0


--end msg--
13:44:19.826    tsx0732C19C  ......State changed from Null to Calling, event=TX_MSG
13:44:19.826    dlg0733320C  .......Transaction tsx0732C19C state changed to Calling
13:44:19.826    tsx0732D9B4  Timeout timer event
13:44:19.826    tsx0732D9B4  .State changed from Terminated to Destroyed, event=TIMER
13:44:19.826   tdta07346A04  ..Destroying txdata Response msg 200/INVITE/cseq=102 (tdta07346A04)
13:44:19.826    tsx0732D9B4  Transaction destroyed!
13:44:19.859 sip_endpoint.c  Processing incoming message: Response msg 200/BYE/cseq=13985 (rdata07D5AEEC)
13:44:19.859   pjsua_core.c  .RX 517 bytes Response msg 200/BYE/cseq=13985 (rdata07D5AEEC) from UDP 10.99.11.21:5160:
SIP/2.0 200 OK
Via: SIP/2.0/UDP 10.99.11.122:55374;branch=z9hG4bKPj81a7d804590f48b589b2c13ea3677182;received=10.99.11.122;rport=55374
From: <sip:[email protected];ob>;tag=e7c5ac89fa494c88a3a1733820865020
To: "Virtual Olfat" <sip:[email protected]>;tag=as4ef92226
Call-ID: [email protected]:5160
CSeq: 13985 BYE
Server: FPBX-15.0.16.44(16.9.0)
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Content-Length: 0


--end msg--
13:44:19.859    tsx0732C19C  .Incoming Response msg 200/BYE/cseq=13985 (rdata07D5AEEC) in state Calling
13:44:19.860    tsx0732C19C  ..State changed from Calling to Completed, event=RX_MSG
13:44:19.860    dlg0733320C  ...Received Response msg 200/BYE/cseq=13985 (rdata07D5AEEC)
13:44:19.860    dlg0733320C  ...Transaction tsx0732C19C state changed to Completed
13:44:19.860  pjsua_media.c  .....Call 3: deinitializing media..
13:44:19.860   strm0737E12C  .......JB summary:
  size=7/eff=7 prefetch=0 level=5
  delay (min/max/avg/dev)=20/340/150/69 ms
  burst (min/max/avg/dev)=2/22/2/1 frames
  lost=74 discard=0 empty=46
13:44:19.860  pjsua_media.c  .......Media stream call03:0 is destroyed
13:44:19.860    dlg0733320C  .....Session count dec to 1 by mod-invite
13:44:20.860    pjsua_aud.c  Closing sound device after idle for 1 second(s)
13:44:20.861    pjsua_aud.c  .Closing Wave mapper sound playback device and Wave mapper sound capture device
13:44:20.866     wmme_dev.c  .Stopped WMME playback stream
13:44:20.874     wmme_dev.c  .Stopped WMME capture stream
13:44:20.874     wmme_dev.c  .Stopped WMME playback stream
13:44:20.875     wmme_dev.c  .Stopped WMME capture stream
13:44:20.875     wmme_dev.c !WMME: thread stopping..
13:44:20.875           wmme  Thread stack max usage=9477 by ..\src\pj\string.c:450
13:44:23.130    pjsua_acc.c !Sending 2 bytes keep-alive packet for acc 0 to 10.99.11.21:5160
13:44:23.130   tdta0733E9C4  Destroying txdata raw
13:44:24.860    tsx0732C19C  Timeout timer event
13:44:24.860    tsx0732C19C  .State changed from Completed to Terminated, event=TIMER
13:44:24.860    dlg0733320C  ..Transaction tsx0732C19C state changed to Terminated
13:44:24.860    dlg0733320C  ...Dialog destroyed!
13:44:24.861    tsx0732C19C  Timeout timer event
13:44:24.861    tsx0732C19C  .State changed from Terminated to Destroyed, event=TIMER
13:44:24.861   tdta073419DC  ..Destroying txdata Request msg BYE/cseq=13985 (tdta073419DC)
13:44:24.861    tsx0732C19C  Transaction destroyed!

wmoon · April 28, 2020, 8:58pm

Have you noticed any patterns with the dropped calls? For example, do they all end around the same time, like 30min? I noticed you have some SIP tracing in your logs. If you were monitoring any calls that were reported to be dropped, is there any consistency with where the BYE/hangup is coming from? Have calls ever dropped on an extension to extension call where the Grandstream was not involved?

kmo12345 · April 29, 2020, 5:57am

Because the large majority of calls are not dropping and I can’t distinguish between dropped and regular calls in the CDR report, I am having a very difficult time discerning any meaningful trends in call duration. I was asking about this as well as I believe 30 seconds could indicate an RTP issue. I will reply with more info as soon as I can get it.

The SIP trace I posted above is likely from one of the calls which dropped. I have enabled SIP tracing on a number of the MicroSIP clients and have Packet Capturing turned on for a few of the Grandstreams. I might be missing something but I can’t seem to distinguish any difference between a normal hangup and this “drop” hangup.

From talking with the end users, I can say three things:

Grandstream to Grandstream calls do not appear to be dropping.
Grandstream to MicroSIP calls are dropping.
MicroSIP to MicroSIP calls are dropping although it is possible that the MicroSIP users have been dialing the Grandstream extensions and then being forwarded to a MicroSIP extension.

cynjut · April 29, 2020, 1:50pm

If that is, in fact, one of the symptoms, I’d start with Codec mismatches and work from there. If the MicroSIP end is not happy with the codec choice or there is no translation path, the call will drop.

kmo12345 · May 2, 2020, 5:42am

Hi all,

Finally managed to track down this problem. The issue was that some users were launching the MicroSIP application before turning on their VPN. The MicroSIP was storing the local 192.168.1.xxx address and partway through the call this address would be used and the FreePBX and/or Grandstream phones were unable to reach it. Therefore the call would drop…

I think there are probably a few ways to solve the problem but the easiest for me seemed to be send out a mass email to the users reminding them that they MUST connect to the VPN before launching the softphone. Once this was done, the softphone used the correct IP address in the same subnet as the FreePBX and the Grandstream phones and the calls stopped dropping partway through the call.

Although the problem is fixed, I would still like to know if anyone has any idea why this was happening? Reinvite behaviour was set to No in the SIP settings so I don’t understand how the MicroSIP was able to ask the Grandstream and/or FreePBX to start routing data to the incorrect address?

cynjut · May 4, 2020, 1:42pm

If it worked any other way, it would violate the rule of least astonishment. Once you’re client side address is fixed (even in a VPN or NAT environment) there’s no common way to reassess the address without restart the application.

The problem wasn’t a FreePBX problem. I don’t know of any SIP Clients that reassess their network connection once it’s established. I’m not ever sure I can think of a way to provide code the client end to ask it to do such a thing.

kmo12345 · May 6, 2020, 6:36am

I understand what you’re saying, it makes sense that the SIP client wouldn’t reassess what its IP address is once it has been started.

My question is rather, why were the calls working at all if the softphone had the wrong IP address the entire time. It seems strange to me that the users reported the calls were always working for some period of time (with 2-way audio) before suddenly dropping.

What event was happening partway through the call that was causing the wrong IP address to start being used? As mentioned before, I set Reinvite to No so I don’t understand why the clients were trying to change the call routing partway through the call?

jcolp · May 6, 2020, 9:21am

When a call is answered a SIP response is sent to say so. This includes the IP address and port that the acknowledgement of reception should be sent to. If no acknowledgement is received this SIP response gets retransmitted for a period of time (thus why it could work for a period of time) until finally without getting acknowledgement the call is terminated, since to the client it appeared as though the other side did not get the answer.

kmo12345 · May 8, 2020, 5:16am

Makes sense. Thanks Joshua!

system · May 15, 2020, 5:16am

This topic was automatically closed 7 days after the last reply. New replies are no longer allowed.