Re: [Openbts-discuss] SMS delivery problem between clients

SourceForge Headquarters 1320 Columbia Street Suite 310 San Diego, CA 92101 +1 (858) 422-6466

Hi Phil,

Thanks for reporting the problem. We took a look and it's a bonafide bug when dealing with certain devices. They seem to be sending bogus requests to disconnect L2 SABM. Even though this is out-of-spec, they're now handled gracefully.

The fix has been pushed to master. The actual changeset is visible here:
 - https://github.com/RangeNetworks/openbts/commit/e9bac710e383fbe3b99bd3dd6889468c16317315

Commercial customers will receive this fix as version 6.0.4 of the RangeSDMN basestation firmware to be released on Monday, December 21st.

Regards,
-Michael

> On 18 Dec 2015, at 15:24, Phil Knüfer <phi...@ru...> wrote:
> 
> -----BEGIN PGP SIGNED MESSAGE-----
> Hash: SHA512
> 
> Dear list,
> 
> I am currently working on my master's thesis, a security analysis of a
> telematic
> device used for car tracking. The device can be equipped with a SIM
> card and is
> then accessible over a GSM interface, i.e., it can be queried by SMS
> and will
> respond accordingly.
> In order to intercept and modify messages I set up OpenBTS as
> described in the
> "Getting Started with OpenBTS" eBook. The device's SIM card is
> self-burned and
> has the IMSI 001020000000001. For basic communication testing in the
> network I also
> connect my private smart phone, using the SIM card of my provider.
> When sending SMS over my network I encounter several problems.
> 
> First, I tried to directly message the telematic device via the
> 'sendsms' command
> from OpenBTSCLI. As the device is only a passive dongle without any
> user interface,
> I can only get very basic feedback from it. However, there is a message
> "led123456 [[on|off]" which will result in the device toggling it's
> status LED.
> Somehow I have to send each request two times before the device reacts.
> After the first time issuing 'sendsms' the following logfile output is
> created:
> 
> 
>    Dec 18 12:50:51 phl-openBTSBox openbts: INFO 7009:7009
> 2015-12-18T12:50:51.4 L3TranEntry.cpp:869:ttAdd: new transaction
> TranEntry( tid=204 GSMState=null chan=none Subscriber=(
> Imsi=001020000000001 Tmsi=(no tmsi) Imei="") L3TI=16 Service=MTSMS
> from=6055551234 stateAge=(0 sec) message="led123456 off ")
>    Dec 18 12:50:53 phl-openBTSBox openbts: INFO 7009:7041
> 2015-12-18T12:50:53.7 L3MMLayer.cpp:1278:mmPageReceived: paging
> reponse for  MMUser( state=0 imsi=001020000000001 tmsi=(no tmsi)
> channel:C0T0 SDCCH/4-0 state=Established queued transactions: SMS:204)
>    Dec 18 12:50:53 phl-openBTSBox openbts: INFO 7009:7041
> 2015-12-18T12:50:53.8 L3MMLayer.cpp:73:startSMSTran: new MTSMS tran=
> TranEntry( tid=204 GSMState=null chan=none Subscriber=(
> Imsi=001020000000001 Tmsi=(no tmsi) Imei="") L3TI=16 Service=MTSMS
> from=6055551234 stateAge=(2 sec) message="led123456 off ") chan=
> MMContext(C0T0 SDCCH/4-0 state=Established mmcChannelUseCnt=1
> duration=0 mmcMMU= MMUser( state=0 imsi=001020000000001 tmsi=(no tmsi)
> channel:C0T0 SDCCH/4-0 state=Established queued transactions:))
>    Dec 18 12:50:53 phl-openBTSBox openbts: ERR 7009:7041
> 2015-12-18T12:50:53.9 L3StateMachine.cpp:558:checkPrimitive: Layer3
> received ERROR from layer2 on channel C0T0 SDCCH/4-0 state=Established
> sapi=3
>    Dec 18 12:50:54 phl-openBTSBox openbts: NOTICE 7009:7048
> 2015-12-18T12:50:54.2 GSML2LAPDm.cpp:277:unexpectedMessage: obj:
> LAPDm(C0T0 SDCCH/4-0(0x8a63ae0) SAPI=SAPI3 State=LinkReleased C=1 R=0
> VS=0 VA=0 VR=0 RC=0 EstablishmentInProgress=0 L1In.size()=0
> master.State=AwaitingRelease)  from:5
> 
> I believe that lines 4 and 5 indicate the problem. When issuing the
> same 'sendsms'
> command again, these lines are missing and the device correctly turns
> off its LED:
> 
>    Dec 18 12:51:02 phl-openBTSBox openbts: INFO 7009:7009
> 2015-12-18T12:51:02.8 L3TranEntry.cpp:869:ttAdd: new transaction
> TranEntry( tid=205 GSMState=null chan=none Subscriber=(
> Imsi=001020000000001 Tmsi=(no tmsi) Imei="") L3TI=16 Service=MTSMS
> from=6055551234 stateAge=(0 sec) message="led123456 off ")
>    Dec 18 12:51:04 phl-openBTSBox openbts: INFO 7009:7041
> 2015-12-18T12:51:04.1 L3MMLayer.cpp:1278:mmPageReceived: paging
> reponse for  MMUser( state=0 imsi=001020000000001 tmsi=(no tmsi)
> channel:C0T0 SDCCH/4-0 state=Established queued transactions: SMS:205)
>    Dec 18 12:51:04 phl-openBTSBox openbts: INFO 7009:7041
> 2015-12-18T12:51:04.2 L3MMLayer.cpp:73:startSMSTran: new MTSMS tran=
> TranEntry( tid=205 GSMState=null chan=none Subscriber=(
> Imsi=001020000000001 Tmsi=(no tmsi) Imei="") L3TI=16 Service=MTSMS
> from=6055551234 stateAge=(1 sec) message="led123456 off ") chan=
> MMContext(C0T0 SDCCH/4-0 state=Established mmcChannelUseCnt=1
> duration=0 mmcMMU= MMUser( state=0 imsi=001020000000001 tmsi=(no tmsi)
> channel:C0T0 SDCCH/4-0 state=Established queued transactions:))
> 
> 
> I then went away from the simple 'sendsms' CLI command and tried
> messaging the
> telematic device from my mobile phone. Results are the same, each
> message has to
> be sent twice until a reaction is visible.
> I also wanted to test the backchannel from the device to my mobile phone.
> Therefore, I used the message 'imei123456', which the device should
> answer with
> its IMEI. No matter how often I send the message, I do not receive a
> response
> from the device. During the process, the following log messages are
> generated
> (the censored IMSI starting with 26202 is the one of my mobile phone):
> 
>    Dec 18 12:52:44 phl-openBTSBox openbts: INFO 7009:7049
> 2015-12-18T12:52:44.7 L3TranEntry.cpp:869:ttAdd: new transaction
> TranEntry( tid=209 GSMState=null chan=(C0T0 SDCCH/4-1
> state=Established) Subscriber=( Imsi="" Tmsi=(no tmsi) Imei="")
> L3TI=16 Service=SMS stateAge=(0 sec))
>    Dec 18 12:52:44 phl-openBTSBox openbts: NOTICE 7009:7049
> 2015-12-18T12:52:44.7 L3MobilityManagement.cpp:215:machineRunState:
> Machine=(L3IdentifyMachine tid=209 C0T0 SDCCH/4-1 CCState=null
> PopState=0)No IMSI or valid TMSI.  Reqesting IMSI.
>    Dec 18 12:52:46 phl-openBTSBox smqueue: NOTICE 1403:1499
> 2015-12-18T12:52:46.7 smqueue.cpp:2455:main_loop: Got SMS rqst qtag
> '995814--OBTSwhcajfnkkkphnhkh' from IMSI26202XXXXXXXXXX for smsc
>    Dec 18 12:52:46 phl-openBTSBox smqueue: NOTICE 1403:1500
> 2015-12-18T12:52:46.7 smqueue.h:505:get_text: Decoded text: imei123456
>    Dec 18 12:52:46 phl-openBTSBox openbts: INFO 7009:7049
> 2015-12-18T12:52:46.8 L3MMLayer.cpp:1067:mmAttachByImsi: attachMMC
> imsi=26202XXXXXXXXXX chan=C0T0 SDCCH/4-1 state=Established
>    Dec 18 12:52:46 phl-openBTSBox openbts: INFO 7009:7049
> 2015-12-18T12:52:46.8 L3TranEntry.cpp:1571:teRemove: SIP term info
> dialogCancel called in teRemove cancel cause:
> l3cause=782=0x30e(SMS_Success) SipCode=0()
>    Dec 18 12:52:47 phl-openBTSBox smqueue: NOTICE 1403:1500
> 2015-12-18T12:52:47.7 smqueue.h:505:get_text: Decoded text: imei123456
>    Dec 18 12:52:47 phl-openBTSBox openbts: INFO 7009:7027
> 2015-12-18T12:52:47.7 L3TranEntry.cpp:869:ttAdd: new transaction
> TranEntry( tid=210 GSMState=null chan=none Subscriber=(
> Imsi=001020000000001 Tmsi=(no tmsi) Imei="") L3TI=16 Service=MTSMS
> from=6055551234 stateAge=(0 sec)
> message="01f903a10000001b040aa106555521430000512181212574400ae976391d93cd68351b")
>    Dec 18 12:52:47 phl-openBTSBox openbts: INFO 7009:7049
> 2015-12-18T12:52:47.9 L3MMLayer.cpp:498:findTran: No transaction found
> to handle frame with PD=0x9 TI=6 MTI=4
>    Dec 18 12:52:49 phl-openBTSBox openbts: INFO 7009:7057
> 2015-12-18T12:52:49.6 L3TranEntry.cpp:869:ttAdd: new transaction
> TranEntry( tid=211 GSMState=null chan=(C0T0 SDCCH/4-2
> state=Established) Subscriber=( Imsi="" Tmsi=(no tmsi) Imei="")
> L3TI=16 Service=LUR stateAge=(0 sec))
>    Dec 18 12:52:51 phl-openBTSBox sipauthserve: NOTICE 1401:1401
> 2015-12-18T12:52:51.7 sipauthserve.cpp:198:processBuffer: imsi unknown
>    Dec 18 12:52:51 phl-openBTSBox openbts: INFO 7009:7057
> 2015-12-18T12:52:51.9 L3TranEntry.cpp:1571:teRemove: SIP term info
> dialogCancel called in teRemove cancel cause:
> l3cause=4=0x4(<unrecognized Call Control Cause>) SipCode=0()
>    Dec 18 12:52:51 phl-openBTSBox openbts: INFO 7009:7065
> 2015-12-18T12:52:51.9 L3MMLayer.cpp:1278:mmPageReceived: paging
> reponse for  MMUser( state=0 imsi=001020000000001 tmsi=(no tmsi)
> channel:C0T0 SDCCH/4-3 state=Established queued transactions: SMS:210)
>    Dec 18 12:52:52 phl-openBTSBox openbts: INFO 7009:7065
> 2015-12-18T12:52:52.0 L3MMLayer.cpp:73:startSMSTran: new MTSMS tran=
> TranEntry( tid=210 GSMState=null chan=none Subscriber=(
> Imsi=001020000000001 Tmsi=(no tmsi) Imei="") L3TI=16 Service=MTSMS
> from=6055551234 stateAge=(4 sec)
> message="01f903a10000001b040aa106555521430000512181212574400ae976391d93cd68351b")
> chan= MMContext(C0T0 SDCCH/4-3 state=Established mmcChannelUseCnt=1
> duration=1 mmcMMU= MMUser( state=0 imsi=001020000000001 tmsi=(no tmsi)
> channel:C0T0 SDCCH/4-3 state=Established queued transactions:))
>    Dec 18 12:52:53 phl-openBTSBox openbts: INFO 7009:7049
> 2015-12-18T12:52:53.6 L3TranEntry.cpp:869:ttAdd: new transaction
> TranEntry( tid=213 GSMState=null chan=(C0T0 SDCCH/4-1
> state=Established) Subscriber=( Imsi="" Tmsi=(no tmsi) Imei="")
> L3TI=16 Service=LUR stateAge=(0 sec))
>    Dec 18 12:52:53 phl-openBTSBox smqueue: NOTICE 1403:1500
> 2015-12-18T12:52:53.8 smqueue.cpp:318:handle_response: Got 200
> response for sent msg '995814--OBTSwhcajfnkkkphnhkh' in state 12
>    Dec 18 12:52:53 phl-openBTSBox openbts: INFO 7009:7065
> 2015-12-18T12:52:53.8 L3TranEntry.cpp:1571:teRemove: SIP term info
> dialogCancel called in teRemove cancel cause:
> l3cause=782=0x30e(SMS_Success) SipCode=0()
>    Dec 18 12:52:54 phl-openBTSBox sipauthserve: NOTICE 1401:1401
> 2015-12-18T12:52:54.9 sipauthserve.cpp:198:processBuffer: imsi unknown
>    Dec 18 12:52:55 phl-openBTSBox openbts: INFO 7009:7049
> 2015-12-18T12:52:55.1 L3TranEntry.cpp:1571:teRemove: SIP term info
> dialogCancel called in teRemove cancel cause:
> l3cause=4=0x4(<unrecognized Call Control Cause>) SipCode=0()
>    Dec 18 12:53:19 phl-openBTSBox openbts: INFO 7009:7041
> 2015-12-18T12:53:19.6 L3TranEntry.cpp:869:ttAdd: new transaction
> TranEntry( tid=214 GSMState=null chan=(C0T0 SDCCH/4-0
> state=Established) Subscriber=( Imsi="" Tmsi=(no tmsi) Imei="")
> L3TI=16 Service=LUR stateAge=(0 sec))
>    Dec 18 12:53:20 phl-openBTSBox sipauthserve: NOTICE 1401:1401
> 2015-12-18T12:53:20.1 sipauthserve.cpp:198:processBuffer: imsi unknown
>    Dec 18 12:53:20 phl-openBTSBox openbts: INFO 7009:7041
> 2015-12-18T12:53:20.2 L3TranEntry.cpp:1571:teRemove: SIP term info
> dialogCancel called in teRemove cancel cause:
> l3cause=4=0x4(<unrecognized Call Control Cause>) SipCode=0()
>    Dec 18 12:53:20 phl-openBTSBox openbts: INFO 7009:7041
> 2015-12-18T12:53:20.3 L3MMLayer.cpp:498:findTran: No transaction found
> to handle frame with PD=Radio Resource TI=0 MTI=52
>    Dec 18 12:53:26 phl-openBTSBox openbts: INFO 7009:7027
> 2015-12-18T12:53:26.2 L3TranEntry.cpp:869:ttAdd: new transaction
> TranEntry( tid=215 GSMState=null chan=none Subscriber=(
> Imsi=001020000000001 Tmsi=(no tmsi) Imei="") L3TI=16 Service=MTSMS
> from=6055551234 stateAge=(0 sec)
> message="01fc03a10000001b040aa106555521430000512181212511400ae976391d93cd68351b")
>    Dec 18 12:53:27 phl-openBTSBox openbts: INFO 7009:7049
> 2015-12-18T12:53:27.9 L3MMLayer.cpp:1278:mmPageReceived: paging
> reponse for  MMUser( state=0 imsi=001020000000001 tmsi=(no tmsi)
> channel:C0T0 SDCCH/4-1 state=Established queued transactions: SMS:215)
>    Dec 18 12:53:28 phl-openBTSBox openbts: INFO 7009:7049
> 2015-12-18T12:53:28.0 L3MMLayer.cpp:73:startSMSTran: new MTSMS tran=
> TranEntry( tid=215 GSMState=null chan=none Subscriber=(
> Imsi=001020000000001 Tmsi=(no tmsi) Imei="") L3TI=16 Service=MTSMS
> from=6055551234 stateAge=(2 sec)
> message="01fc03a10000001b040aa106555521430000512181212511400ae976391d93cd68351b")
> chan= MMContext(C0T0 SDCCH/4-1 state=Established mmcChannelUseCnt=1
> duration=1 mmcMMU= MMUser( state=0 imsi=001020000000001 tmsi=(no tmsi)
> channel:C0T0 SDCCH/4-1 state=Established queued transactions:))
>    Dec 18 12:53:28 phl-openBTSBox openbts: ERR 7009:7049
> 2015-12-18T12:53:28.1 L3StateMachine.cpp:558:checkPrimitive: Layer3
> received ERROR from layer2 on channel C0T0 SDCCH/4-1 state=Established
> sapi=3
>    Dec 18 12:53:28 phl-openBTSBox openbts: INFO 7009:7049
> 2015-12-18T12:53:28.1 L3TranEntry.cpp:1571:teRemove: SIP term info
> dialogCancel called in teRemove cancel cause:
> l3cause=778=0x30a(No_Transaction_Expected) SipCode=0()
>    Dec 18 12:53:28 phl-openBTSBox openbts: NOTICE 7009:7056
> 2015-12-18T12:53:28.4 GSML2LAPDm.cpp:277:unexpectedMessage: obj:
> LAPDm(C0T0 SDCCH/4-1(0x8a6c4b8) SAPI=SAPI3 State=LinkReleased C=1 R=0
> VS=0 VA=0 VR=0 RC=0 EstablishmentInProgress=0 L1In.size()=0
> master.State=AwaitingRelease)  from:5
>    Dec 18 12:54:27 phl-openBTSBox openbts: INFO 7009:7041
> 2015-12-18T12:54:27.2 L3TranEntry.cpp:869:ttAdd: new transaction
> TranEntry( tid=216 GSMState=null chan=(C0T0 SDCCH/4-0
> state=Established) Subscriber=( Imsi="" Tmsi=(no tmsi) Imei="")
> L3TI=16 Service=LUR stateAge=(0 sec))
>    Dec 18 12:54:29 phl-openBTSBox sipauthserve: NOTICE 1401:1401
> 2015-12-18T12:54:29.3 sipauthserve.cpp:198:processBuffer: imsi unknown
>    Dec 18 12:54:29 phl-openBTSBox openbts: INFO 7009:7041
> 2015-12-18T12:54:29.4 L3TranEntry.cpp:1571:teRemove: SIP term info
> dialogCancel called in teRemove cancel cause:
> l3cause=4=0x4(<unrecognized Call Control Cause>) SipCode=0()
>    Dec 18 12:54:41 phl-openBTSBox openbts: INFO 7009:7027
> 2015-12-18T12:54:41.3 L3TranEntry.cpp:869:ttAdd: new transaction
> TranEntry( tid=217 GSMState=null chan=none Subscriber=(
> Imsi=001020000000001 Tmsi=(no tmsi) Imei="") L3TI=16 Service=MTSMS
> from=6055551234 stateAge=(0 sec)
> message="01fc03a10000001b040aa106555521430000512181212511400ae976391d93cd68351b")
>    Dec 18 12:54:44 phl-openBTSBox openbts: INFO 7009:7041
> 2015-12-18T12:54:44.4 L3MMLayer.cpp:1278:mmPageReceived: paging
> reponse for  MMUser( state=0 imsi=001020000000001 tmsi=(no tmsi)
> channel:C0T0 SDCCH/4-0 state=Established queued transactions: SMS:217)
>    Dec 18 12:54:44 phl-openBTSBox openbts: INFO 7009:7041
> 2015-12-18T12:54:44.5 L3MMLayer.cpp:73:startSMSTran: new MTSMS tran=
> TranEntry( tid=217 GSMState=null chan=none Subscriber=(
> Imsi=001020000000001 Tmsi=(no tmsi) Imei="") L3TI=16 Service=MTSMS
> from=6055551234 stateAge=(3 sec)
> message="01fc03a10000001b040aa106555521430000512181212511400ae976391d93cd68351b")
> chan= MMContext(C0T0 SDCCH/4-0 state=Established mmcChannelUseCnt=1
> duration=0 mmcMMU= MMUser( state=0 imsi=001020000000001 tmsi=(no tmsi)
> channel:C0T0 SDCCH/4-0 state=Established queued transactions:))
>    Dec 18 12:54:46 phl-openBTSBox smqueue: NOTICE 1403:1500
> 2015-12-18T12:54:46.3 smqueue.cpp:318:handle_response: Got 200
> response for sent msg '995812--OBTSdyivtbajpjlcfnvc' in state 12
>    Dec 18 12:54:46 phl-openBTSBox openbts: INFO 7009:7041
> 2015-12-18T12:54:46.3 L3TranEntry.cpp:1571:teRemove: SIP term info
> dialogCancel called in teRemove cancel cause:
> l3cause=782=0x30e(SMS_Success) SipCode=0()
>    Dec 18 12:54:49 phl-openBTSBox openbts: INFO 7009:7049
> 2015-12-18T12:54:49.4 L3TranEntry.cpp:869:ttAdd: new transaction
> TranEntry( tid=218 GSMState=null chan=(C0T0 SDCCH/4-1
> state=Established) Subscriber=( Imsi="" Tmsi=(no tmsi) Imei="")
> L3TI=16 Service=LUR stateAge=(0 sec))
>    Dec 18 12:54:50 phl-openBTSBox sipauthserve: NOTICE 1401:1401
> 2015-12-18T12:54:50.5 sipauthserve.cpp:198:processBuffer: imsi unknown
>    Dec 18 12:54:50 phl-openBTSBox openbts: INFO 7009:7049
> 2015-12-18T12:54:50.6 L3TranEntry.cpp:1571:teRemove: SIP term info
> dialogCancel called in teRemove cancel cause:
> l3cause=4=0x4(<unrecognized Call Control Cause>) SipCode=0()
>    Dec 18 12:55:11 phl-openBTSBox openbts: INFO 7009:7041
> 2015-12-18T12:55:11.9 L3TranEntry.cpp:869:ttAdd: new transaction
> TranEntry( tid=219 GSMState=null chan=(C0T0 SDCCH/4-0
> state=Established) Subscriber=( Imsi="" Tmsi=(no tmsi) Imei="")
> L3TI=16 Service=LUR stateAge=(0 sec))
>    Dec 18 12:55:12 phl-openBTSBox sipauthserve: NOTICE 1401:1401
> 2015-12-18T12:55:12.9 sipauthserve.cpp:198:processBuffer: imsi unknown
>    Dec 18 12:55:13 phl-openBTSBox openbts: INFO 7009:7041
> 2015-12-18T12:55:13.0 L3TranEntry.cpp:1571:teRemove: SIP term info
> dialogCancel called in teRemove cancel cause:
> l3cause=4=0x4(<unrecognized Call Control Cause>) SipCode=0()
> 
> 
> I have to admit that I am helplessly drowning in the sheer amount of
> log output.
> I read multiple lines of "imsi unknown" and somewhere in the middle I
> see the
> same error as in my first test from the command line.
> I hope that someone on this mailing list is more knowledgeable in
> interpreting
> the logs! As the LED does indeed switch off the second time sending a
> message,
> I suppose that the sending of messages from the device back to my mobile
> phone somehow does not work.
> 
> 
> The TL;DR version of this message (sorry for the wall of text):
> 1. Messages are only delivered after sending them twice.
> 2. Responses from my telematic device are not delivered at all.
> 3. Please help :)
> 
> 
> 
> 
> Finally, once I have sorted out the above problems I want to eliminate
> the mobile
> phone from the setup. Any help with setting up an SMS sending /
> receiving party
> directly on the computer where OpenBTS is running would be much
> appreciated!
> I believe that I would need to register a sipclient with my network
> but I have no
> idea how to do that (and how to address messages afterwards).
> 
> 
> Thanks for any help!
> 
> Phil
> -----BEGIN PGP SIGNATURE-----
> Version: GnuPG/MacGPG2 v2
> Comment: GPGTools - https://gpgtools.org
> 
> iF4EAREKAAYFAlZ0FygACgkQdPqg1tDfnS97EgD/YQB7gkeuQWNwk1Gc2UUNK5zX
> yGWAP1Ei1bnmVqNGPD4A/ifQBqvKF4EvImI8/4L9d3yLEy93I5a95rveDGV2q1Th
> =vQ1q
> -----END PGP SIGNATURE-----
> 
> ------------------------------------------------------------------------------
> _______________________________________________
> Openbts-discuss mailing list
> Ope...@li...
> https://lists.sourceforge.net/lists/listinfo/openbts-discuss

Re: [Openbts-discuss] SMS delivery problem between clients

GSM L1-L3 stack with SIP network interfaces

Re: [Openbts-discuss] SMS delivery problem between clients