[Openbts-discuss] No voice on incoming calls

[Omar R. <om...@en...>]

Hi,

I am facing no voice issues on mobile terminated calls. I am running a 
RAD1 using OpenBTS release 4.0TRUNK+GPRS on a Ubuntu 14.04.1 LTS 
VirtualBox VM.

Outbound calls work completely fine, and the strange deal is that the 
voice issues on incoming calls are not the one sided voice problems you 
have when behind a NAT, but there is no audio at all.

There are other people who seem to have come across the same issue (I 
just joined this listserv, sorry for not being able to respond to the 
original thread): 
http://sourceforge.net/p/openbts/mailman/message/33424257/

So doing a little bit of debugging, the problem seems to be that on 
incoming calls, the SIP state never reaches the "Active" state needed 
for the flow of RTP traffic. This seems to be caused by a race condition 
in 
[SipMTInviteServerTransactionLayer::MTCSendOK](https://github.com/RangeNetworks/openbts/blob/4.0/SIP/SIPBase.cpp#L1382)
Let's take a look at the sequence of SIP states that you would normally 
encounter for a normal incoming call:

```
Feb 25 00:37:40 endaga openbts: INFO 18894:18910 2015-02-25T00:37:40.5 
SIPBase.cpp:154:setSipState: Changing SIP State: NullState->Proceeding
Feb 25 00:37:41 endaga openbts: INFO 18894:18928 2015-02-25T00:37:41.1 
SIPBase.cpp:154:setSipState: Changing SIP State: Proceeding->Proceeding
Feb 25 00:37:43 endaga openbts: INFO 18894:18952 2015-02-25T00:37:43.8 
SIPBase.cpp:154:setSipState: Changing SIP State: Proceeding->Proceeding
Feb 25 00:37:47 endaga openbts: INFO 18894:18952 2015-02-25T00:37:47.9 
SIPBase.cpp:154:setSipState: Changing SIP State: Proceeding->Connecting
Feb 25 00:37:47 endaga openbts: INFO 18894:18910 2015-02-25T00:37:47.9 
SIPBase.cpp:154:setSipState: Changing SIP State: Connecting->Active
Feb 25 00:38:02 endaga openbts: INFO 18894:18910 2015-02-25T00:38:02.7 
SIPBase.cpp:154:setSipState: Changing SIP State: Active->MTDClearing
Feb 25 00:38:02 endaga openbts: INFO 18894:18910 2015-02-25T00:38:02.7 
SIPBase.cpp:154:setSipState: Changing SIP State: 
MTDClearing->MTDClearing
```

So how I understand this works is that the transition from Proceeding to 
Connecting happens when the radio recieves the Connect request from L3 
that is triggered when the subscriber picks up the call. The next thing 
that happens is that MTCSendOK is called which readies the RTP ports and 
sends a 200 OK to the PBX. The SIP state is now in the Connecting state. 
After we recieve the ACK to the OK, 
[SipMTInviteServerTransactionLayer::MTWriteHighSide](https://github.com/RangeNetworks/openbts/blob/4.0/SIP/SIPBase.cpp#L1441) 
transitions us into the Active state. At this point, the two endpoints 
are connected and RTP traffic flows begin and you can transmit voice.


Now let's take a look at the set of states I encounter when I have calls 
that have no voice:

```
Feb 20 04:33:45 vagrant-ubuntu-trusty-32 openbts: INFO 19047:19055 
2015-02-20T04:33:45.8 SIPBase.cpp:154:setSipState: Changing SIP State: 
NullState->Proceeding
Feb 20 04:33:46 vagrant-ubuntu-trusty-32 openbts: INFO 19047:19068 
2015-02-20T04:33:46.6 SIPBase.cpp:154:setSipState: Changing SIP State: 
Proceeding->Proceeding
Feb 20 04:33:48 vagrant-ubuntu-trusty-32 openbts: INFO 19047:19092 
2015-02-20T04:33:48.6 SIPBase.cpp:154:setSipState: Changing SIP State: 
Proceeding->Proceeding
Feb 20 04:33:55 vagrant-ubuntu-trusty-32 openbts: INFO 19047:19055 
2015-02-20T04:33:55.0 SIPBase.cpp:154:setSipState: Changing SIP State: 
Proceeding->Active
Feb 20 04:33:55 vagrant-ubuntu-trusty-32 openbts: INFO 19047:19092 
2015-02-20T04:33:55.0 SIPBase.cpp:154:setSipState: Changing SIP State: 
Active->Connecting
Feb 20 04:34:27 vagrant-ubuntu-trusty-32 openbts: INFO 19047:19056 
2015-02-20T04:34:27.2 SIPBase.cpp:154:setSipState: Changing SIP State: 
Connecting->SSFail
```

This has race condition written all over it. This is all happening in 
the SipMTInviteServerTransactionLayer::MTCSendOK method. In the 
Proceeding state, we get the Connect request from L3 and send the OK 
packet as usual. But the problem that happens is that if we get the ACK 
back too quickly, we process it in another thread and set the SIP state 
to Active before MTCSendOK finishes evaluating. At the end of MTCSendOK 
we set the SIP state to Connecting, so we go from Active back to the 
Connecting state. Since we only process RTP packets when SIP state is 
Active, we have no voice on incoming calls.

So what I tried to do to fix this issue is move the 
setSipState(Connecting) to happen BEFORE we send the OK in MTCSendOK. 
That way, no matter when the ACK comes in for the OK, we know that we 
won't clobber the Active state with a Connecting.

Great, so this seems like this should solve the problem, and looking at 
the SIP state flow with this change, things line up. We initialize the 
RTP ports, and everything looks like it will work as it should, but it 
doesn't. What happens is that OpenBTS starts transmitting and receiving 
RTP data for a few iterations lasting a second (still no sound) and then 
it crashes.


```
Feb 25 17:01:09 vagrant-ubuntu-trusty-32 openbts: INFO 2573:2581 
2015-02-25T17:01:09.8 ./SIPBase.h:132:setSipState: Changing SIP State: 
Connecting->Active
Feb 25 17:01:09 vagrant-ubuntu-trusty-32 openbts: DEBUG 2573:2581 
2015-02-25T17:01:09.8 SIPDialog.cpp:485:dialogPushState: We are now 
active.
Feb 25 17:01:09 vagrant-ubuntu-trusty-32 openbts: DEBUG 2573:2581 
2015-02-25T17:01:09.8 SIPDialog.cpp:489:dialogPushState:  
oldSipState=Connecting newSipState=Active getSipState()=Active 
mPrevDialogState=0 oldDialogState=2 nextDialogState=4 SipDialog( 
TranId=100 state=4 PrevDialogState=0 SipBase( 
localUsername=IMSI901550000000040 remoteUsername=_REDACTED_ 
InviteViaBranch= DialogStateVars=( 
CallId=b7cb58ab-37b2-1233-4fa8-080027b42128 LocalHeader.value()= 
<sip:IMSI901550000000040@127.0.0.1:5062>;tag=OBTSicdvymrjprpsomfa 
RemoteHeader.value()="_REDACTED_" <sip: 
_REDACTED_@127.0.0.1>;tag=vgj30ayrX83tQ LocalCSeq=56402 RouteSet= proxy= 
ipName=127.0.0.1 ipIP=127.0.0.1 ipPort=5060) TxTime=0 RxTime=0 
mRTPPort=16512 Codec= GSM_FR dtmf=0 DTMFDuration=0 DTMFStartTime=0 
SipState=Active DialogType=4) Timers: G=(active=0) H=(active=0) 
J=(active=0))
Feb 25 17:01:09 vagrant-ubuntu-trusty-32 openbts: DEBUG 2573:2581 
2015-02-25T17:01:09.8 SIPDialog.cpp:457:dialogQueueMessage: sending 
DialogMessage to L3  dmsg=DialogMessage( MsgState=Active StatusCode=0)
Feb 25 17:01:09 vagrant-ubuntu-trusty-32 openbts: DEBUG 2573:2618 
2015-02-25T17:01:09.8 L3StateMachine.cpp:856:l3CallTrafficLoop: C0T1 
TCH/F state=Established main loop nextDelay=0 found tran:1
Feb 25 17:01:09 vagrant-ubuntu-trusty-32 openbts: DEBUG 2573:2618 
2015-02-25T17:01:09.8 L3StateMachine.cpp:903:l3CallTrafficLoop: C0T1 
TCH/F state=Established after checkem Messages
Feb 25 17:01:09 vagrant-ubuntu-trusty-32 openbts: DEBUG 2573:2618 
2015-02-25T17:01:09.8 L3StateMachine.cpp:710:newUpdateCallTraffic: GSM 
State: connect-indication
Feb 25 17:01:09 vagrant-ubuntu-trusty-32 openbts: DEBUG 2573:2618 
2015-02-25T17:01:09.8 L3StateMachine.cpp:938:l3CallTrafficLoop: C0T1 
TCH/F state=Established end of loop
Feb 25 17:01:09 vagrant-ubuntu-trusty-32 openbts: DEBUG 2573:2618 
2015-02-25T17:01:09.8 L3StateMachine.cpp:856:l3CallTrafficLoop: C0T1 
TCH/F state=Established main loop nextDelay=20 found tran:1
Feb 25 17:01:09 vagrant-ubuntu-trusty-32 openbts: DEBUG 2573:2618 
2015-02-25T17:01:09.8 L3StateMachine.cpp:759:checkemMessages:  dcch=C0T1 
TCH/F state=Established delay=20
Feb 25 17:01:09 vagrant-ubuntu-trusty-32 openbts: INFO 2573:2670 
2015-02-25T17:01:09.8 PARPCClient.cpp:106:pa_on: PA On from client
Feb 25 17:01:09 vagrant-ubuntu-trusty-32 openbts: INFO 2573:2586 
2015-02-25T17:01:09.8 GSML1FEC.cpp:488:countGoodFrame: obj: 0xa053f68 
C0T1 TCH/FL1Decoder FER=0.000975337
Feb 25 17:01:09 vagrant-ubuntu-trusty-32 openbts: INFO 2573:2621 
2015-02-25T17:01:09.8 GSML3Message.cpp:192:parseL3: L3 recv RR 
Measurement Report BA_USED=0 DTX_USED=0 MEAS_VALID=0 
RXLEV_FULL_SERVING_CELL=58 RXLEV_SUB_SERVING_CELL=59 
RXQUAL_FULL_SERVING_CELL=2 RXQUAL_SUB_SERVING_CELL=0 NO_NCELL=1 
RXLEV_NCELL1=59 BCCH_FREQ_NCELL1=0 BSIC_NCELL1=2
Feb 25 17:01:09 vagrant-ubuntu-trusty-32 openbts: INFO 2573:2621 
2015-02-25T17:01:09.8 ../GSM/GSMLogicalChannel.h:201:l2sendf: 
typeAndOffset=TCH/F TN=1 TSC=2 ARFCN=51 SAPI=SAPI0 chtype()=SACCH 
L3Frame(primitive=UNIT_DATA PD=Radio Resource MTI=0x1d(System 
Information Type 5) TI=0 raw=(061d8e198000000000000000000000000000))
Feb 25 17:01:09 vagrant-ubuntu-trusty-32 openbts: INFO 2573:2621 
2015-02-25T17:01:09.8 GSML2LAPDm.cpp:963:sendUFrameUI: obj:  LAPDm(C0T1 
TCH/F-SACCH(0xa05bc28) SAPI=SAPI0 State=LinkReleased C=1 R=0 VS=0 VA=0 
VR=0 RC=0 EstablishmentInProgress=0 L1In.size()=0 L3Out.size()=0) 
payload=L3Frame(primitive=UNIT_DATA PD=Radio Resource MTI=0x1d(System 
Information Type 5) TI=0 raw=(061d8e198000000000000000000000000000))
Feb 25 17:01:09 vagrant-ubuntu-trusty-32 openbts: INFO 2573:2621 
2015-02-25T17:01:09.8 GSML1FEC.cpp:2558:sendFrame: obj: 0xa058f48 
SACCHL1Encoder  primitive=DATA SAPI=0 
raw=(031349061d8e1980000000000000000000000000002b2b)
Feb 25 17:01:09 vagrant-ubuntu-trusty-32 openbts: INFO 2573:2621 
2015-02-25T17:01:09.8 GSML1FEC.cpp:2600:sendFrame: obj: 0xa058f48 
SACCHL1Encoder orders pow=5 TA=0.585184 with header 0001001100000001
Feb 25 17:01:09 vagrant-ubuntu-trusty-32 openbts: DEBUG 2573:2618 
2015-02-25T17:01:09.8 L3StateMachine.cpp:352:machineRunState1:  
state=0x1004 frame=(null L3Frame) l3msg=null sipmsg=DialogMessage( 
MsgState=Active StatusCode=0)
Feb 25 17:01:09 vagrant-ubuntu-trusty-32 openbts: DEBUG 2573:2618 
2015-02-25T17:01:09.8 L3StateMachine.cpp:358:machineRunState1: calling 
machineRunState  state=0x1004 Machine=(MTCMachine tid=100 C0T1 TCH/F 
CCState=connect-indication PopState=1) l3msg=null
Feb 25 17:01:09 vagrant-ubuntu-trusty-32 openbts: DEBUG 2573:2618 
2015-02-25T17:01:09.8 L3CallControl.cpp:843:machineRunState:  
state=0x1004 Machine=(MTCMachine tid=100 C0T1 TCH/F 
CCState=connect-indication PopState=1)  state=4100 l3msg=null 
sipmsg=DialogMessage( MsgState=Active StatusCode=0) imsi= 
Imsi=901550000000040 Tmsi=(no tmsi) Imei=""
Feb 25 17:01:09 vagrant-ubuntu-trusty-32 openbts: DEBUG 2573:2618 
2015-02-25T17:01:09.8 SIPBase.cpp:944:initRTP1:  d_ip_addr=127.0.0.1 
d_port=32024 SipBase( localUsername=IMSI901550000000040 remoteUsername= 
_REDACTED_ InviteViaBranch= DialogStateVars=( 
CallId=b7cb58ab-37b2-1233-4fa8-080027b42128 LocalHeader.value()= 
<sip:IMSI901550000000040@127.0.0.1:5062>;tag=OBTSicdvymrjprpsomfa 
RemoteHeader.value()="_REDACTED_" 
<sip:_REDACTED_@127.0.0.1>;tag=vgj30ayrX83tQ LocalCSeq=56402 RouteSet= 
proxy= ipName=127.0.0.1 ipIP=127.0.0.1 ipPort=5060) TxTime=0 RxTime=0 
mRTPPort=16512 Codec= GSM_FR dtmf=0 DTMFDuration=0 DTMFStartTime=0 
SipState=Active DialogType=4)
Feb 25 17:01:09 vagrant-ubuntu-trusty-32 openbts: DEBUG 2573:2618 
2015-02-25T17:01:09.8 SIPBase.cpp:990:initRTP1: *** initRTP local=16512 
remote=127.0.0.1 32024
Feb 25 17:01:09 vagrant-ubuntu-trusty-32 openbts: DEBUG 2573:2618 
2015-02-25T17:01:09.8 SIPBase.cpp:1008:initRTP1:  jump_limit=5000
Feb 25 17:01:09 vagrant-ubuntu-trusty-32 openbts: INFO 2573:2618 
2015-02-25T17:01:09.8 L3LogicalChannel.cpp:87:l3sendm: l3sendm prim=DATA 
SAPI=SAPI0 msg=(CC Connect Acknowledge TI=2 ) C0T1 TCH/F 
state=Established
Feb 25 17:01:09 vagrant-ubuntu-trusty-32 openbts: INFO 2573:2618 
2015-02-25T17:01:09.8 GSMLogicalChannel.cpp:86:l2sendm: obj: C0T1 TCH/F 
L3 SAPI=SAPI0 sending CC Connect Acknowledge TI=2
Feb 25 17:01:09 vagrant-ubuntu-trusty-32 openbts: INFO 2573:2618 
2015-02-25T17:01:09.8 ../GSM/GSMLogicalChannel.h:201:l2sendf: 
typeAndOffset=TCH/F TN=1 TSC=2 ARFCN=51 SAPI=SAPI0 chtype()=FACCH 
L3Frame(primitive=DATA PD=Call Control MTI=0xf(Connect Acknowledge) TI=2 
raw=(230f))
Feb 25 17:01:09 vagrant-ubuntu-trusty-32 openbts: INFO 2573:2618 
2015-02-25T17:01:09.8 GSML2LAPDm.cpp:986:sendMultiframeData: obj:  
LAPDm(C0T1 TCH/F(0xa0585b0) SAPI=SAPI0 State=LinkEstablished C=1 R=0 
VS=0 VA=0 VR=3 RC=0 EstablishmentInProgress=0 L1In.size()=0 
L3Out.size()=0) payload=L3Frame(primitive=DATA PD=Call Control 
MTI=0xf(Connect Acknowledge) TI=2 raw=(230f))
Feb 25 17:01:09 vagrant-ubuntu-trusty-32 openbts: INFO 2573:2618 
2015-02-25T17:01:09.8 GSML2LAPDm.cpp:1041:sendIFrame: obj:  LAPDm(C0T1 
TCH/F(0xa0585b0) SAPI=SAPI0 State=LinkEstablished C=1 R=0 VS=0 VA=0 VR=3 
RC=0 EstablishmentInProgress=0 L1In.size()=0 L3Out.size()=0) M=0 VS=0 
payload=0010001100001111
Feb 25 17:01:09 vagrant-ubuntu-trusty-32 openbts: DEBUG 2573:2618 
2015-02-25T17:01:09.8 L3StateMachine.cpp:183:callMachStart: start 
Procedure: Machine=(InCallMachine tid=100 C0T1 TCH/F CCState=active 
PopState=0)
Feb 25 17:01:09 vagrant-ubuntu-trusty-32 openbts: DEBUG 2573:2618 
2015-02-25T17:01:09.8 L3StateMachine.cpp:352:machineRunState1:  
state=0x0 frame=(null L3Frame) l3msg=null sipmsg=(null DialogMessage)
Feb 25 17:01:09 vagrant-ubuntu-trusty-32 openbts: DEBUG 2573:2618 
2015-02-25T17:01:09.8 L3StateMachine.cpp:358:machineRunState1: calling 
machineRunState  state=0x0 Machine=(InCallMachine tid=100 C0T1 TCH/F 
CCState=active PopState=0) l3msg=null
Feb 25 17:01:09 vagrant-ubuntu-trusty-32 openbts: DEBUG 2573:2618 
2015-02-25T17:01:09.8 L3CallControl.cpp:1116:machineRunState:  state=0x0 
Machine=(InCallMachine tid=100 C0T1 TCH/F CCState=active PopState=0)  
l3msg=null sipmsg=(null DialogMessage) imsi= Imsi=901550000000040 
Tmsi=(no tmsi) Imei=""
Feb 25 17:01:09 vagrant-ubuntu-trusty-32 openbts: INFO 2573:2618 
2015-02-25T17:01:09.8 L3MMLayer.cpp:960:mmAttachByImsi: attachMMC 
imsi=901550000000040 chan=C0T1 TCH/F state=Established
Feb 25 17:01:09 vagrant-ubuntu-trusty-32 openbts: DEBUG 2573:2618 
2015-02-25T17:01:09.8 L3CallControl.cpp:1124:machineRunState:  
Machine=(InCallMachine tid=100 C0T1 TCH/F CCState=active 
PopState=0)setting voice tran= TranEntry( tid=100 GSMState=active 
chan=(C0T1 TCH/F state=Established) Subscriber= Imsi=901550000000040 
Tmsi=(no tmsi) Imei="" L3TI=2 Service=MTC from=_REDACTED_ stateAge=(0 
sec) stack=( Machine=(InCallMachine tid=100 C0T1 TCH/F CCState=active 
PopState=0)))
Feb 25 17:01:09 vagrant-ubuntu-trusty-32 openbts: DEBUG 2573:2618 
2015-02-25T17:01:09.8 L3StateMachine.cpp:801:checkemMessages: C0T1 TCH/F 
state=Established Sip message processed
Feb 25 17:01:09 vagrant-ubuntu-trusty-32 openbts: DEBUG 2573:2618 
2015-02-25T17:01:09.8 L3StateMachine.cpp:856:l3CallTrafficLoop: C0T1 
TCH/F state=Established main loop nextDelay=0 found tran:1
Feb 25 17:01:09 vagrant-ubuntu-trusty-32 openbts: DEBUG 2573:2618 
2015-02-25T17:01:09.8 L3StateMachine.cpp:903:l3CallTrafficLoop: C0T1 
TCH/F state=Established after checkem Messages
Feb 25 17:01:09 vagrant-ubuntu-trusty-32 openbts: DEBUG 2573:2618 
2015-02-25T17:01:09.8 L3StateMachine.cpp:710:newUpdateCallTraffic: GSM 
State: active
Feb 25 17:01:09 vagrant-ubuntu-trusty-32 openbts: DEBUG 2573:2618 
2015-02-25T17:01:09.8 L3StateMachine.cpp:729:newUpdateCallTraffic: C0T1 
TCH/F ulFrame flushed 534 in 0 msecs
Feb 25 17:01:09 vagrant-ubuntu-trusty-32 openbts: DEBUG 2573:2618 
2015-02-25T17:01:09.8 L3StateMachine.cpp:734:newUpdateCallTraffic: C0T1 
TCH/F *ulFrame=ByteVector(size=33 data: da a7 aa a5 1a 50 20 38 e4 6d c9 
1b 50 20 38 e4 6d c9 1b 50 20 38 e4 6d c9 1b 50 20 38 e4 6d c9 1b)
Feb 25 17:01:09 vagrant-ubuntu-trusty-32 openbts: DEBUG 2573:2618 
2015-02-25T17:01:09.8 SIPBase.cpp:1168:txFrame:  mTxTime=85600 result=45
Feb 25 17:01:09 vagrant-ubuntu-trusty-32 openbts: DEBUG 2573:2618 
2015-02-25T17:01:09.8 SIPBase.cpp:1267:rxFrame:  getSipState()=Active 
mRxTime=160 ret=0
Feb 25 17:01:09 vagrant-ubuntu-trusty-32 openbts: DEBUG 2573:2618 
2015-02-25T17:01:09.8 L3StateMachine.cpp:751:newUpdateCallTraffic:  
activity=33
Feb 25 17:01:09 vagrant-ubuntu-trusty-32 openbts: DEBUG 2573:2618 
2015-02-25T17:01:09.8 L3StateMachine.cpp:915:l3CallTrafficLoop: C0T1 
TCH/F state=Established call traffic bytes=33 tran= TranEntry( tid=100 
GSMState=active chan=(C0T1 TCH/F state=Established) Subscriber= 
Imsi=901550000000040 Tmsi=(no tmsi) Imei="" L3TI=2 Service=MTC 
from=_REDACTED_ stateAge=(0 sec) stack=( Machine=(InCallMachine tid=100 
C0T1 TCH/F CCState=active PopState=0)))
Feb 25 17:01:09 vagrant-ubuntu-trusty-32 openbts: DEBUG 2573:2618 
2015-02-25T17:01:09.8 L3StateMachine.cpp:856:l3CallTrafficLoop: C0T1 
TCH/F state=Established main loop nextDelay=0 found tran:1
Feb 25 17:01:09 vagrant-ubuntu-trusty-32 openbts: DEBUG 2573:2618 
2015-02-25T17:01:09.8 L3StateMachine.cpp:759:checkemMessages:  dcch=C0T1 
TCH/F state=Established delay=0
Feb 25 17:01:09 vagrant-ubuntu-trusty-32 openbts: DEBUG 2573:2618 
2015-02-25T17:01:09.8 L3StateMachine.cpp:816:checkemMessages: C0T1 TCH/F 
state=Established returning, nothing to do
Feb 25 17:01:09 vagrant-ubuntu-trusty-32 openbts: DEBUG 2573:2618 
2015-02-25T17:01:09.8 L3StateMachine.cpp:903:l3CallTrafficLoop: C0T1 
TCH/F state=Established after checkem Messages
Feb 25 17:01:09 vagrant-ubuntu-trusty-32 openbts: DEBUG 2573:2618 
2015-02-25T17:01:09.8 L3StateMachine.cpp:710:newUpdateCallTraffic: GSM 
State: active
Feb 25 17:01:09 vagrant-ubuntu-trusty-32 openbts: DEBUG 2573:2618 
2015-02-25T17:01:09.8 L3StateMachine.cpp:734:newUpdateCallTraffic: C0T1 
TCH/F *ulFrame=ByteVector(size=33 data: d8 20 a2 e1 5a 50 00 49 24 92 49 
24 50 00 49 24 92 49 24 50 00 49 24 92 49 24 50 00 49 24 92 49 24)
Feb 25 17:01:09 vagrant-ubuntu-trusty-32 openbts: INFO 2573:2586 
2015-02-25T17:01:09.9 GSML1FEC.cpp:488:countGoodFrame: obj: 0xa053f68 
C0T1 TCH/FL1Decoder FER=0.000970648
Feb 25 17:01:09 vagrant-ubuntu-trusty-32 openbts: INFO 2573:2670 
2015-02-25T17:01:09.9 PARPCClient.cpp:106:pa_on: PA On from client
Feb 25 17:01:09 vagrant-ubuntu-trusty-32 openbts: INFO 2573:2586 
2015-02-25T17:01:09.9 GSML1FEC.cpp:947:processPhysInfo: obj: 0xa059e0c 
SACCHL1Decoder  RSSI=-45.7011 burst.RSSI=-43 timestamp=1.42488e+09 
timingError=-0.210938 RSSICount=60
Feb 25 17:01:09 vagrant-ubuntu-trusty-32 openbts: INFO 2573:2586 
2015-02-25T17:01:09.9 GSML1FEC.cpp:488:countGoodFrame: obj: 0xa059d00 
C0T1 TCH/F-SACCHL1Decoder FER=0.00449402
Feb 25 17:01:09 vagrant-ubuntu-trusty-32 openbts: INFO 2573:2586 
2015-02-25T17:01:09.9 GSML1FEC.cpp:972:handleGoodFrame: obj: 0xa059d00 
SACCHL1Decoder actuals pow=5 TA=1
Feb 25 17:01:09 vagrant-ubuntu-trusty-32 openbts: INFO 2573:2619 
2015-02-25T17:01:09.9 GSML2LAPDm.cpp:733:receiveUFrameUI: obj:  
LAPDm(C0T1 TCH/F-SACCH(0xa05bc28) SAPI=SAPI0 State=LinkReleased C=1 R=0 
VS=0 VA=0 VR=0 RC=0 EstablishmentInProgress=0 L1In.size()=0 
L3Out.size()=0)  primitive=DATA SAPI=0 
raw=(01034906153a3b207b0040000000000000000000002b2b)
Feb 25 17:01:09 vagrant-ubuntu-trusty-32 openbts: DEBUG 2573:2618 
2015-02-25T17:01:09.9 SIPBase.cpp:1168:txFrame:  mTxTime=85760 result=45
Feb 25 17:01:09 vagrant-ubuntu-trusty-32 openbts: DEBUG 2573:2618 
2015-02-25T17:01:09.9 SIPBase.cpp:1267:rxFrame:  getSipState()=Active 
mRxTime=320 ret=0
Feb 25 17:01:09 vagrant-ubuntu-trusty-32 openbts: DEBUG 2573:2618 
2015-02-25T17:01:09.9 L3StateMachine.cpp:751:newUpdateCallTraffic:  
activity=33
Feb 25 17:01:09 vagrant-ubuntu-trusty-32 openbts: DEBUG 2573:2618 
2015-02-25T17:01:09.9 L3StateMachine.cpp:915:l3CallTrafficLoop: C0T1 
TCH/F state=Established call traffic bytes=66 tran= TranEntry( tid=100 
GSMState=active chan=(C0T1 TCH/F state=Established) Subscriber= 
Imsi=901550000000040 Tmsi=(no tmsi) Imei="" L3TI=2 Service=MTC 
from=_REDACTED_ stateAge=(0 sec) stack=( Machine=(InCallMachine tid=100 
C0T1 TCH/F CCState=active PopState=0)))
Feb 25 17:01:09 vagrant-ubuntu-trusty-32 openbts: DEBUG 2573:2618 
2015-02-25T17:01:09.9 L3StateMachine.cpp:856:l3CallTrafficLoop: C0T1 
TCH/F state=Established main loop nextDelay=0 found tran:1
Feb 25 17:01:09 vagrant-ubuntu-trusty-32 openbts: DEBUG 2573:2618 
2015-02-25T17:01:09.9 L3StateMachine.cpp:903:l3CallTrafficLoop: C0T1 
TCH/F state=Established after checkem Messages
Feb 25 17:01:09 vagrant-ubuntu-trusty-32 openbts: DEBUG 2573:2618 
2015-02-25T17:01:09.9 L3StateMachine.cpp:710:newUpdateCallTraffic: GSM 
State: active
Feb 25 17:01:09 vagrant-ubuntu-trusty-32 openbts: DEBUG 2573:2618 
2015-02-25T17:01:09.9 L3StateMachine.cpp:734:newUpdateCallTraffic: C0T1 
TCH/F *ulFrame=ByteVector(size=33 data: d8 20 a2 e1 5a 50 00 49 24 92 49 
24 50 00 49 24 92 49 24 50 00 49 24 92 49 24 50 00 49 24 92 49 24)

         ------------------- TX/RX loop repeats a bunch of times, but no 
audio ---------------

Feb 25 17:01:09 vagrant-ubuntu-trusty-32 openbts: INFO 2573:2670 
2015-02-25T17:01:09.9 PARPCClient.cpp:106:pa_on: PA On from client
Feb 25 17:01:09 vagrant-ubuntu-trusty-32 transceiver: INFO 1980:2115 
2015-02-25T17:01:09.9 Transceiver.cpp:836:driveTransmitFIFO: reduced 
latency: 3:3
Feb 25 17:01:09 vagrant-ubuntu-trusty-32 openbts: INFO 2573:2586 
2015-02-25T17:01:09.9 GSML1FEC.cpp:488:countGoodFrame: obj: 0xa053f68 
C0T1 TCH/FL1Decoder FER=0.000961337
Feb 25 17:01:09 vagrant-ubuntu-trusty-32 openbts: DEBUG 2573:2618 
2015-02-25T17:01:09.9 SIPBase.cpp:1168:txFrame:  mTxTime=86080 result=45
Feb 25 17:01:09 vagrant-ubuntu-trusty-32 openbts: DEBUG 2573:2618 
2015-02-25T17:01:09.9 SIPBase.cpp:1267:rxFrame:  getSipState()=Active 
mRxTime=640 ret=0
Feb 25 17:01:09 vagrant-ubuntu-trusty-32 openbts: DEBUG 2573:2618 
2015-02-25T17:01:09.9 L3StateMachine.cpp:751:newUpdateCallTraffic:  
activity=33
Feb 25 17:01:09 vagrant-ubuntu-trusty-32 openbts: DEBUG 2573:2618 
2015-02-25T17:01:09.9 L3StateMachine.cpp:915:l3CallTrafficLoop: C0T1 
TCH/F state=Established call traffic bytes=132 tran= TranEntry( tid=100 
GSMState=active chan=(C0T1 TCH/F state=Established) Subscriber= 
Imsi=901550000000040 Tmsi=(no tmsi) Imei="" L3TI=2 Service=MTC 
from=_REDACTED_ stateAge=(0 sec) stack=( Machine=(InCallMachine tid=100 
C0T1 TCH/F CCState=active PopState=0)))
Feb 25 17:01:09 vagrant-ubuntu-trusty-32 openbts: DEBUG 2573:2618 
2015-02-25T17:01:09.9 L3StateMachine.cpp:856:l3CallTrafficLoop: C0T1 
TCH/F state=Established main loop nextDelay=0 found tran:1
Feb 25 17:01:09 vagrant-ubuntu-trusty-32 openbts: DEBUG 2573:2618 
2015-02-25T17:01:09.9 L3StateMachine.cpp:903:l3CallTrafficLoop: C0T1 
TCH/F state=Established after checkem Messages
Feb 25 17:01:09 vagrant-ubuntu-trusty-32 openbts: DEBUG 2573:2618 
2015-02-25T17:01:09.9 L3StateMachine.cpp:710:newUpdateCallTraffic: GSM 
State: active
Feb 25 17:01:09 vagrant-ubuntu-trusty-32 openbts: DEBUG 2573:2618 
2015-02-25T17:01:09.9 L3StateMachine.cpp:734:newUpdateCallTraffic: C0T1 
TCH/F *ulFrame=ByteVector(size=33 data: d8 20 a2 e1 5a 50 00 49 24 92 49 
24 50 00 49 24 92 49 24 50 00 49 24 92 49 24 50 00 49 24 92 49 24)

         ------------------- TX/RX loop repeats a bunch of times, but no 
audio ---------------


eb 25 17:01:10 vagrant-ubuntu-trusty-32 openbts: DEBUG 2573:2618 
2015-02-25T17:01:10.4 SIPBase.cpp:1168:txFrame:  mTxTime=90240 result=45
Feb 25 17:01:10 vagrant-ubuntu-trusty-32 openbts: INFO 2573:2586 
2015-02-25T17:01:10.4 GSML1FEC.cpp:488:countGoodFrame: obj: 0xa053f68 
C0T1 TCH/FL1Decoder FER=0.000852218
Feb 25 17:01:10 vagrant-ubuntu-trusty-32 openbts: INFO 2573:2670 
2015-02-25T17:01:10.4 PARPCClient.cpp:106:pa_on: PA On from client
Feb 25 17:01:10 vagrant-ubuntu-trusty-32 openbts: INFO 2573:2586 
2015-02-25T17:01:10.4 GSML1FEC.cpp:488:countGoodFrame: obj: 0xa053f68 
C0T1 TCH/FL1Decoder FER=0.000848121
Feb 25 17:01:10 vagrant-ubuntu-trusty-32 openbts: DEBUG 2573:2618 
2015-02-25T17:01:10.4 SIPBase.cpp:1267:rxFrame:  getSipState()=Active 
mRxTime=4960 ret=33
Feb 25 17:01:10 vagrant-ubuntu-trusty-32 openbts: DEBUG 2573:2618 
2015-02-25T17:01:10.4 L3StateMachine.cpp:746:newUpdateCallTraffic: C0T1 
TCH/F *dlFrame=ByteVector(size=33 data: d9 e8 cb a5 e2 64 00 37 23 8d c7 
1b e8 a0 46 db 6d c8 dc d0 60 49 1b 6d b9 1c 90 20 49 24 8e 36 db)
Feb 25 17:01:10 vagrant-ubuntu-trusty-32 openbts: DEBUG 2573:2618 
2015-02-25T17:01:10.4 L3StateMachine.cpp:751:newUpdateCallTraffic:  
activity=66
Feb 25 17:01:10 vagrant-ubuntu-trusty-32 openbts: DEBUG 2573:2618 
2015-02-25T17:01:10.4 L3StateMachine.cpp:915:l3CallTrafficLoop: C0T1 
TCH/F state=Established call traffic bytes=1089 tran= TranEntry( tid=100 
GSMState=active chan=(C0T1 TCH/F state=Established) Subscriber= 
Imsi=901550000000040 Tmsi=(no tmsi) Imei="" L3TI=2 Service=MTC 
from=_REDACTED_ stateAge=(1 sec) stack=( Machine=(InCallMachine tid=100 
C0T1 TCH/F CCState=active PopState=0)))
Feb 25 17:01:10 vagrant-ubuntu-trusty-32 openbts: DEBUG 2573:2618 
2015-02-25T17:01:10.4 L3StateMachine.cpp:856:l3CallTrafficLoop: C0T1 
TCH/F state=Established main loop nextDelay=0 found tran:1
Feb 25 17:01:10 vagrant-ubuntu-trusty-32 openbts: DEBUG 2573:2618 
2015-02-25T17:01:10.4 L3StateMachine.cpp:759:checkemMessages:  dcch=C0T1 
TCH/F state=Established delay=0
Feb 25 17:01:10 vagrant-ubuntu-trusty-32 openbts: DEBUG 2573:2618 
2015-02-25T17:01:10.4 L3StateMachine.cpp:816:checkemMessages: C0T1 TCH/F 
state=Established returning, nothing to do
Feb 25 17:01:10 vagrant-ubuntu-trusty-32 openbts: DEBUG 2573:2618 
2015-02-25T17:01:10.4 L3StateMachine.cpp:903:l3CallTrafficLoop: C0T1 
TCH/F state=Established after checkem Messages
Feb 25 17:01:10 vagrant-ubuntu-trusty-32 openbts: DEBUG 2573:2618 
2015-02-25T17:01:10.4 L3StateMachine.cpp:710:newUpdateCallTraffic: GSM 
State: active
Feb 25 17:01:10 vagrant-ubuntu-trusty-32 openbts: DEBUG 2573:2618 
2015-02-25T17:01:10.4 L3StateMachine.cpp:734:newUpdateCallTraffic: C0T1 
TCH/F *ulFrame=ByteVector(size=33 data: d8 20 a2 e1 5a 50 00 49 24 92 49 
24 50 00 49 24 92 49 24 50 00 49 24 92 49 24 50 00 49 24 92 49 24)
Feb 25 17:01:10 vagrant-ubuntu-trusty-32 openbts: DEBUG 2573:2618 
2015-02-25T17:01:10.4 L3StateMachine.cpp:915:l3CallTrafficLoop: C0T1 
TCH/F state=Established call traffic bytes=1089 tran= TranEntry( tid=100 
GSMState=active chan=(C0T1 TCH/F state=Established) Subscriber= 
Imsi=901550000000040 Tmsi=(no tmsi) Imei="" L3TI=2 Service=MTC 
from=_REDACTED_ stateAge=(1 sec) stack=( Machine=(InCallMachine tid=100 
C0T1 TCH/F CCState=active PopState=0)))
Feb 25 17:01:10 vagrant-ubuntu-trusty-32 openbts: DEBUG 2573:2618 
2015-02-25T17:01:10.4 L3StateMachine.cpp:856:l3CallTrafficLoop: C0T1 
TCH/F state=Established main loop nextDelay=0 found tran:1
Feb 25 17:01:10 vagrant-ubuntu-trusty-32 openbts: DEBUG 2573:2618 
2015-02-25T17:01:10.4 L3StateMachine.cpp:759:checkemMessages:  dcch=C0T1 
TCH/F state=Established delay=0
Feb 25 17:01:10 vagrant-ubuntu-trusty-32 openbts: DEBUG 2573:2618 
2015-02-25T17:01:10.4 L3StateMachine.cpp:816:checkemMessages: C0T1 TCH/F 
state=Established returning, nothing to do
Feb 25 17:01:10 vagrant-ubuntu-trusty-32 openbts: DEBUG 2573:2618 
2015-02-25T17:01:10.4 L3StateMachine.cpp:903:l3CallTrafficLoop: C0T1 
TCH/F state=Established after checkem Messages
Feb 25 17:01:10 vagrant-ubuntu-trusty-32 openbts: DEBUG 2573:2618 
2015-02-25T17:01:10.4 L3StateMachine.cpp:710:newUpdateCallTraffic: GSM 
State: active
Feb 25 17:01:10 vagrant-ubuntu-trusty-32 openbts: DEBUG 2573:2618 
2015-02-25T17:01:10.4 L3StateMachine.cpp:734:newUpdateCallTraffic: C0T1 
TCH/F *ulFrame=ByteVector(size=33 data: d8 20 a2 e1 5a 50 00 49 24 92 49 
24 50 00 49 24 92 49 24 50 00 49 24 92 49 24 50 00 49 24 92 49 24)
Feb 25 17:01:10 vagrant-ubuntu-trusty-32 openbts: DEBUG 2573:2618 
2015-02-25T17:01:10.4 SIPBase.cpp:1168:txFrame:  mTxTime=90400 result=45
Feb 25 17:01:10 vagrant-ubuntu-trusty-32 transceiver: INFO 1980:2115 
2015-02-25T17:01:10.9 Transceiver.cpp:836:driveTransmitFIFO: reduced 
latency: 2:3
Feb 25 17:01:11 vagrant-ubuntu-trusty-32 openbts: INFO 3081:3081 
2015-02-25T17:01:11.6 PowerManager.cpp:90:PowerManager: setting initial 
power to -10 dB
Feb 25 17:01:11 vagrant-ubuntu-trusty-32 openbts: ALERT 3081:3081 
2015-02-25T17:01:11.6 OpenBTS.cpp:425:main: OpenBTS (re)starting, ver 
4.0TRUNK build date Feb 25 2015
Feb 25 17:01:11 vagrant-ubuntu-trusty-32 openbts: ALERT 3081:3081 
2015-02-25T17:01:11.6 OpenBTS.cpp:426:main: OpenBTS reading config file 
/etc/OpenBTS/OpenBTS.db

```

Looking at wireshark data, I can confirm that OpenBTS did transmit and 
receive RTP packets before it crashes. Even though OpenBTS restarts, the 
call continues, but of course now we have lost state so outbound RTP 
data flow stops. The call originator gives up soon after and sends a 
BYE.

I've been trying to debug this for some time now, and I don't understand 
why OpenBTS restarts silently after one second of RTP data flow. Perhaps 
the fix for race condition isn't valid? Is there a particular reason as 
to why we set the sip state to Connecting after sending the OK? Is the 
restart an unrelated issue perhaps VM/usb related? Has anyone 
experienced similar problems when not running on a VM?

Thanks!