[Openbts-discuss] SMS delivery problem between clients

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

-----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] SMS delivery problem between clients

GSM L1-L3 stack with SIP network interfaces

[Openbts-discuss] SMS delivery problem between clients