|
From: Omar R. <om...@en...> - 2015-02-26 08:21:41
|
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! |