This is merely a historical archive of years 2008-2021, before the migration to mailman3.
A maintained and still updated list archive can be found at https://lists.osmocom.org/hyperkitty/list/OpenBSC@lists.osmocom.org/.
Harald Welte laforge at gnumonks.orgHi all,
T200 is the LAPDm re-transmission timer, after which the sender assumes
a L2 frame transmitted was lost and starts with recovery.
Until recently, OsmoBTS ignored the T200 values that the BSC specified
via OML, always falling back to the (relatively long) T200 values that
exist in libosmocore (1s for the main channel, 2s for the associated
channel).
As you know, OsmoBTS is used in production in this configuration and we
never recevied any associated bug reports.
Recently, in e9f12acbeb5a369282719f8e0deecc88034a5488 I started to use
the T200 values as communicated from the BSC via OML. This is what
proprietary BTSs like the BS-11, nanoBTS etc. (supposedly) have been
using all the time anyway, so I thought of it as a bug fix.
However, as it turns out, it breaks our LAPDm implementation in many
ways. The LAPDm performance gets that bad that you cannot even transmit
a single SMS anymore, and even LU only occasionally work anymore.
You can see the erroneous behavior in the attached PCAP file showing
OsmoBTS-generated GSMTAP and RSL. Also attached are log file outputs of
LAPDm logging for mo-sms and mt-sms. In them you can find troubling
lines like 'S frame response with F=1 error' which should never
happen...
I suspect two issues related to this:
1) Our lapdm.c code uses regular osmo_timer_* functions to determine
once T200 expires, rather than a GSM frame number time-base.
This wouldn't be a problem in a synchronous real-time environemnt.
However, in OsmoBTS (as in OsmocomBB), there is a relatively long and
queue / delay between the point where a frame is pulled out of the
bottom end of LAPDm and actual transmission on the radio interface.
However, LAPDm T200 starts ticking from the point the frame was
pulled out, rather than from the point transmission started.
In order to change this, I suggest that we either change LAPDm timers
to work on frame numbers passed up from L1 via every L1SAP primitive
(comparing RTS.ind for downlink vs. DATA.ind for uplink), or simply
keeping a per-PHY/per-TRX measurement of that 'round trip time
between the actual radio and the L2'. We can then compensate for
this by adding it to T200.
I briefly tried this here, where one given hardware indicated about
56ms round-trip-time (13 frames difference between RTS.ind and
DATA.ind). However, it didn't help. Even compensating by 120ms was
not sufficient. This needs to be revisited.
2) I think libosmogsm LAPDm implementation is actually buggy,
specifically in situations where T200 expires. We don't see that
often, as the 1s/2s is so long that in reality it rarely happens.
Once the T200 value is reduced, the probability of running into T200
expiration increases, and so does the probability of seeing related
problems.
Our existing lapdm unit tests don't seem to cover timing related
behavior, so that definitely is something tha appears to need
improvement.
Any help on those issues is appreciated.
Meanwhile, I decided to revert back to the libosmogsm T200 defaults by
the means of commit 3ca59512d2f4eb1f87699e8fada67f33674918b4
Regards,
Harald
--
- Harald Welte <laforge at gnumonks.org> http://laforge.gnumonks.org/
============================================================================
"Privacy in residential applications is a desirable marketing option."
(ETSI EN 300 175-7 Ch. A6)
-------------- next part --------------
A non-text attachment was scrubbed...
Name: 20160125-osmobts-t200-gsmtap-rsl.pcap
Type: application/vnd.tcpdump.pcap
Size: 9597 bytes
Desc: not available
URL: <http://lists.osmocom.org/pipermail/openbsc/attachments/20160125/7a053485/attachment.bin>
-------------- next part --------------
<0010> lapd_core.c:2180 Message DL-DATA-REQUEST received in state LAPD_STATE_MF_EST
<0010> lapd_core.c:1756 writing message to send-queue: l3len: 2
<0010> lapd_core.c:1779 lapd_send_i() called from line 1762
<0010> lapd_core.c:1819 get message from send-queue
<0010> lapd_core.c:1831 msg-len 2 sent 0 left 2 N201 20 length 2 first byte 05
<0010> lapd_core.c:1840 send I frame V(S)=0
<0010> lapd_core.c:196 start T200
<0010> lapd_core.c:1802 k frames outstanding, not sending more (k=1 V(S)=1 V(A)=0)
<0010> lapdm.c:550 fmt=B
<0010> lapd_core.c:992 UI received
<0000> rsl.c:1734 (bts=0,trx=1,ts=0,ss=0) Handing RLL msg UNIT_DATA_IND from LAPDm to MEAS REP
<0010> lapd_core.c:545 Timeout T200 (0xb6a4a49c) state=7
<0010> lapd_core.c:227 new state LAPD_STATE_MF_EST -> LAPD_STATE_TIMER_RECOV
<0010> lapd_core.c:614 retransmit last frame V(S)=0
<0010> lapd_core.c:196 start T200
<0010> lapdm.c:561 fmt=B
<0010> lapd_core.c:1459 I received in state LAPD_STATE_TIMER_RECOV on SAPI(0)
<0010> lapd_core.c:1542 incrementing V(R) to 1
<0010> lapd_core.c:1551 message in single I frame
<0000> rsl.c:1741 (bts=0,trx=1,ts=0,ss=0) Fwd RLL msg DATA_IND from LAPDm to A-bis
<0010> lapd_core.c:1779 lapd_send_i() called from line 1609
<0010> lapd_core.c:1789 timer recovery, not sending
<0010> lapd_core.c:545 Timeout T200 (0xb6a4a49c) state=8
<0010> lapd_core.c:614 retransmit last frame V(S)=0
<0010> lapd_core.c:196 start T200
<0010> lapdm.c:561 fmt=B
<0010> lapd_core.c:1252 RR received in state LAPD_STATE_TIMER_RECOV
<0010> lapd_core.c:721 ack frame 0
<0010> lapd_core.c:1779 lapd_send_i() called from line 1290
<0010> lapd_core.c:1789 timer recovery, not sending
<0010> lapd_core.c:545 Timeout T200 (0xb6a4a49c) state=8
<0010> lapd_core.c:196 start T200
<0010> lapdm.c:550 fmt=B
<0010> lapd_core.c:992 UI received
<0000> rsl.c:1734 (bts=0,trx=1,ts=0,ss=0) Handing RLL msg UNIT_DATA_IND from LAPDm to MEAS REP
<0010> lapd_core.c:545 Timeout T200 (0xb6a4a49c) state=8
<0010> lapd_core.c:196 start T200
<0010> lapdm.c:561 fmt=B
<0010> lapd_core.c:1252 RR received in state LAPD_STATE_TIMER_RECOV
<0010> lapd_core.c:1281 RR response with F==1, and we are in timer recovery state, so we leave that state
<0010> lapd_core.c:212 stop T200
<0010> lapd_core.c:227 new state LAPD_STATE_TIMER_RECOV -> LAPD_STATE_MF_EST
<0010> lapd_core.c:1779 lapd_send_i() called from line 1290
<0010> lapd_core.c:1831 msg-len 2 sent 2 left 0 N201 20 length 0 first byte 05
<0010> lapdm.c:561 fmt=B
<0010> lapd_core.c:1232 S frame response with F=1 error
<0010> lapd_core.c:378 sending MDL-ERROR-IND cause 6
<0010> lapdm.c:386 sending MDL-ERROR-IND 6
<0000> rsl.c:1741 (bts=0,trx=1,ts=0,ss=0) Fwd RLL msg ERROR_IND from LAPDm to A-bis
<0010> lapd_core.c:1252 RR received in state LAPD_STATE_MF_EST
<0010> lapd_core.c:1779 lapd_send_i() called from line 1290
<0010> lapdm.c:550 fmt=B
<0010> lapd_core.c:992 UI received
<0000> rsl.c:1734 (bts=0,trx=1,ts=0,ss=0) Handing RLL msg UNIT_DATA_IND from LAPDm to MEAS REP
<0010> lapdm.c:561 fmt=B
<0010> lapd_core.c:1232 S frame response with F=1 error
<0010> lapd_core.c:378 sending MDL-ERROR-IND cause 6
<0010> lapdm.c:386 sending MDL-ERROR-IND 6
<0000> rsl.c:1741 (bts=0,trx=1,ts=0,ss=0) Fwd RLL msg ERROR_IND from LAPDm to A-bis
<0010> lapd_core.c:1252 RR received in state LAPD_STATE_MF_EST
<0010> lapd_core.c:1779 lapd_send_i() called from line 1290
<0010> lapdm.c:561 fmt=B
<0010> lapd_core.c:1232 S frame response with F=1 error
<0010> lapd_core.c:378 sending MDL-ERROR-IND cause 6
<0010> lapdm.c:386 sending MDL-ERROR-IND 6
<0000> rsl.c:1741 (bts=0,trx=1,ts=0,ss=0) Fwd RLL msg ERROR_IND from LAPDm to A-bis
<0010> lapd_core.c:1252 RR received in state LAPD_STATE_MF_EST
<0010> lapd_core.c:1779 lapd_send_i() called from line 1290
<0010> lapdm.c:550 fmt=B
<0010> lapd_core.c:992 UI received
<0000> rsl.c:1734 (bts=0,trx=1,ts=0,ss=0) Handing RLL msg UNIT_DATA_IND from LAPDm to MEAS REP
<0010> lapdm.c:561 fmt=B
<0010> lapd_core.c:789 SABM(E) received in state LAPD_STATE_IDLE
<0010> lapd_core.c:227 new state LAPD_STATE_IDLE -> LAPD_STATE_MF_EST
<0000> rsl.c:1741 (bts=0,trx=1,ts=0,ss=0) Fwd RLL msg EST_IND from LAPDm to A-bis
<0010> lapdm.c:561 fmt=B
<0010> lapd_core.c:1459 I received in state LAPD_STATE_MF_EST on SAPI(3)
<0010> lapd_core.c:1542 incrementing V(R) to 1
<0010> lapd_core.c:1560 message in multiple I frames (first message)
<0010> lapd_core.c:1583 message in multiple I frames (next message)
<0010> lapd_core.c:1779 lapd_send_i() called from line 1609
<0010> lapd_core.c:1618 we are not busy and have no pending data, send RR
<0010> lapdm.c:550 fmt=B
<0010> lapd_core.c:992 UI received
<0000> rsl.c:1734 (bts=0,trx=1,ts=0,ss=0) Handing RLL msg UNIT_DATA_IND from LAPDm to MEAS REP
<0010> lapdm.c:561 fmt=B
<0010> lapd_core.c:1459 I received in state LAPD_STATE_MF_EST on SAPI(3)
<0010> lapd_core.c:1542 incrementing V(R) to 2
<0010> lapd_core.c:1576 message in multiple I frames (last message)
<0000> rsl.c:1741 (bts=0,trx=1,ts=0,ss=0) Fwd RLL msg DATA_IND from LAPDm to A-bis
<0010> lapd_core.c:1779 lapd_send_i() called from line 1609
<0010> lapd_core.c:1618 we are not busy and have no pending data, send RR
<0010> lapd_core.c:2180 Message DL-DATA-REQUEST received in state LAPD_STATE_MF_EST
<0010> lapd_core.c:1756 writing message to send-queue: l3len: 2
<0010> lapd_core.c:1779 lapd_send_i() called from line 1762
<0010> lapd_core.c:1819 get message from send-queue
<0010> lapd_core.c:1831 msg-len 2 sent 0 left 2 N201 20 length 2 first byte 89
<0010> lapd_core.c:1840 send I frame V(S)=0
<0010> lapd_core.c:196 start T200
<0010> lapd_core.c:1802 k frames outstanding, not sending more (k=1 V(S)=1 V(A)=0)
<0010> lapd_core.c:2180 Message DL-DATA-REQUEST received in state LAPD_STATE_MF_EST
<0010> lapd_core.c:1756 writing message to send-queue: l3len: 5
<0010> lapd_core.c:1779 lapd_send_i() called from line 1762
<0010> lapd_core.c:1802 k frames outstanding, not sending more (k=1 V(S)=1 V(A)=0)
<0010> lapd_core.c:545 Timeout T200 (0xb6a4a590) state=7
<0010> lapd_core.c:227 new state LAPD_STATE_MF_EST -> LAPD_STATE_TIMER_RECOV
<0010> lapd_core.c:614 retransmit last frame V(S)=0
<0010> lapd_core.c:196 start T200
<0010> lapdm.c:561 fmt=B
<0010> lapd_core.c:992 UI received
<0010> lapd_core.c:1019 length=0 (discarding)
<0010> lapd_core.c:545 Timeout T200 (0xb6a4a590) state=8
<0010> lapd_core.c:614 retransmit last frame V(S)=0
<0010> lapd_core.c:196 start T200
<0010> lapdm.c:550 fmt=B
<0010> lapd_core.c:992 UI received
<0000> rsl.c:1734 (bts=0,trx=1,ts=0,ss=0) Handing RLL msg UNIT_DATA_IND from LAPDm to MEAS REP
<0010> lapdm.c:561 fmt=B
<0010> lapd_core.c:1252 RR received in state LAPD_STATE_TIMER_RECOV
<0010> lapd_core.c:721 ack frame 0
<0010> lapd_core.c:1779 lapd_send_i() called from line 1290
<0010> lapd_core.c:1789 timer recovery, not sending
<0010> lapd_core.c:545 Timeout T200 (0xb6a4a590) state=8
<0010> lapd_core.c:196 start T200
<0010> lapd_core.c:545 Timeout T200 (0xb6a4a590) state=8
<0010> lapd_core.c:196 start T200
<0010> lapdm.c:561 fmt=B
<0010> lapd_core.c:1252 RR received in state LAPD_STATE_TIMER_RECOV
<0010> lapd_core.c:1281 RR response with F==1, and we are in timer recovery state, so we leave that state
<0010> lapd_core.c:212 stop T200
<0010> lapd_core.c:227 new state LAPD_STATE_TIMER_RECOV -> LAPD_STATE_MF_EST
<0010> lapd_core.c:1779 lapd_send_i() called from line 1290
<0010> lapd_core.c:1831 msg-len 2 sent 2 left 0 N201 20 length 0 first byte 89
<0010> lapd_core.c:1819 get message from send-queue
<0010> lapd_core.c:1831 msg-len 5 sent 0 left 5 N201 20 length 5 first byte 89
<0010> lapd_core.c:1840 send I frame V(S)=1
<0010> lapd_core.c:196 start T200
<0010> lapd_core.c:1802 k frames outstanding, not sending more (k=1 V(S)=2 V(A)=1)
<0010> lapdm.c:550 fmt=B
<0010> lapd_core.c:992 UI received
<0000> rsl.c:1734 (bts=0,trx=1,ts=0,ss=0) Handing RLL msg UNIT_DATA_IND from LAPDm to MEAS REP
<0010> lapd_core.c:1252 RR received in state LAPD_STATE_TIMER_RECOV
<0010> lapd_core.c:1281 RR response with F==1, and we are in timer recovery state, so we leave that state
<0010> lapd_core.c:212 stop T200
<0010> lapd_core.c:227 new state LAPD_STATE_TIMER_RECOV -> LAPD_STATE_MF_EST
<0010> lapd_core.c:1779 lapd_send_i() called from line 1290
<0010> lapd_core.c:1873 resend I frame from tx buffer V(S)=1
<0010> lapd_core.c:196 start T200
<0010> lapd_core.c:1802 k frames outstanding, not sending more (k=1 V(S)=2 V(A)=1)
<0010> lapd_core.c:545 Timeout T200 (0xb6a4a590) state=7
<0010> lapd_core.c:227 new state LAPD_STATE_MF_EST -> LAPD_STATE_TIMER_RECOV
<0010> lapd_core.c:614 retransmit last frame V(S)=1
<0010> lapd_core.c:196 start T200
<0010> lapdm.c:561 fmt=B
<0010> lapd_core.c:1252 RR received in state LAPD_STATE_TIMER_RECOV
<0010> lapd_core.c:1281 RR response with F==1, and we are in timer recovery state, so we leave that state
<0010> lapd_core.c:212 stop T200
<0010> lapd_core.c:227 new state LAPD_STATE_TIMER_RECOV -> LAPD_STATE_MF_EST
<0010> lapd_core.c:1779 lapd_send_i() called from line 1290
<0010> lapd_core.c:1873 resend I frame from tx buffer V(S)=1
<0010> lapd_core.c:196 start T200
<0010> lapd_core.c:1802 k frames outstanding, not sending more (k=1 V(S)=2 V(A)=1)
<0010> lapdm.c:550 fmt=B
<0010> lapd_core.c:992 UI received
<0000> rsl.c:1734 (bts=0,trx=1,ts=0,ss=0) Handing RLL msg UNIT_DATA_IND from LAPDm to MEAS REP
<0010> lapd_core.c:545 Timeout T200 (0xb6a4a590) state=7
<0010> lapd_core.c:227 new state LAPD_STATE_MF_EST -> LAPD_STATE_TIMER_RECOV
<0010> lapd_core.c:614 retransmit last frame V(S)=1
<0010> lapd_core.c:196 start T200
<0010> lapdm.c:561 fmt=B
<0010> lapd_core.c:1252 RR received in state LAPD_STATE_TIMER_RECOV
<0010> lapd_core.c:1281 RR response with F==1, and we are in timer recovery state, so we leave that state
<0010> lapd_core.c:212 stop T200
<0010> lapd_core.c:227 new state LAPD_STATE_TIMER_RECOV -> LAPD_STATE_MF_EST
<0010> lapd_core.c:1779 lapd_send_i() called from line 1290
<0010> lapd_core.c:1873 resend I frame from tx buffer V(S)=1
<0010> lapd_core.c:196 start T200
<0010> lapd_core.c:1802 k frames outstanding, not sending more (k=1 V(S)=2 V(A)=1)
<0010> lapd_core.c:545 Timeout T200 (0xb6a4a590) state=7
<0010> lapd_core.c:227 new state LAPD_STATE_MF_EST -> LAPD_STATE_TIMER_RECOV
<0010> lapd_core.c:614 retransmit last frame V(S)=1
<0010> lapd_core.c:196 start T200
<0010> lapdm.c:561 fmt=B
<0010> lapd_core.c:1459 I received in state LAPD_STATE_TIMER_RECOV on SAPI(3)
<0010> lapd_core.c:1542 incrementing V(R) to 3
<0010> lapd_core.c:721 ack frame 1
<0010> lapd_core.c:1551 message in single I frame
<0000> rsl.c:1741 (bts=0,trx=1,ts=0,ss=0) Fwd RLL msg DATA_IND from LAPDm to A-bis
<0010> lapd_core.c:1779 lapd_send_i() called from line 1609
<0010> lapd_core.c:1789 timer recovery, not sending
<0010> lapd_core.c:2180 Message DL-RELEASE-REQUEST received in state LAPD_STATE_TIMER_RECOV
<0010> lapd_core.c:2021 perform local release
<0010> lapd_core.c:212 stop T200
<0010> lapd_core.c:227 new state LAPD_STATE_TIMER_RECOV -> LAPD_STATE_IDLE
<0000> rsl.c:1741 (bts=0,trx=1,ts=0,ss=0) Fwd RLL msg REL_CONF from LAPDm to A-bis
<0010> lapd_core.c:2180 Message DL-DATA-REQUEST received in state LAPD_STATE_MF_EST
<0010> lapd_core.c:1756 writing message to send-queue: l3len: 3
<0010> lapd_core.c:1779 lapd_send_i() called from line 1762
<0010> lapd_core.c:1819 get message from send-queue
<0010> lapd_core.c:1831 msg-len 3 sent 0 left 3 N201 20 length 3 first byte 06
<0010> lapd_core.c:1840 send I frame V(S)=1
<0010> lapd_core.c:196 start T200
<0010> lapd_core.c:1802 k frames outstanding, not sending more (k=1 V(S)=2 V(A)=1)
<0000> rsl.c:1822 (bts=0,trx=1,ts=0,ss=0) Rx RSL DEACTIVATE_SACCH
<0006> oml.c:1432 (bts=0,trx=1,ts=0,ss=0) MPH-DEACTIVATE.req (SACCH TxDL)
<0006> oml.c:1372 (bts=0,trx=1,ts=0,ss=0) MPH-DEACTIVATE.conf (SACCH TxDL)
<0006> oml.c:1432 (bts=0,trx=1,ts=0,ss=0) MPH-DEACTIVATE.req (SACCH RxUL)
<0006> oml.c:1372 (bts=0,trx=1,ts=0,ss=0) MPH-DEACTIVATE.conf (SACCH RxUL)
<0006> oml.c:660 (bts=0,trx=1,ts=0,ss=0) End of queue encountered. Now empty? 1
<0010> lapd_core.c:545 Timeout T200 (0xb6a4a49c) state=7
<0010> lapd_core.c:227 new state LAPD_STATE_MF_EST -> LAPD_STATE_TIMER_RECOV
<0010> lapd_core.c:614 retransmit last frame V(S)=1
<0010> lapd_core.c:196 start T200
<0010> lapdm.c:561 fmt=B
<0010> lapd_core.c:1032 DISC received in state LAPD_STATE_TIMER_RECOV
<0010> lapd_core.c:1076 DISC in est state
<0010> lapd_core.c:212 stop T200
<0010> lapd_core.c:227 new state LAPD_STATE_TIMER_RECOV -> LAPD_STATE_IDLE
<0000> rsl.c:1741 (bts=0,trx=1,ts=0,ss=0) Fwd RLL msg REL_IND from LAPDm to A-bis
<0000> rsl.c:1822 (bts=0,trx=1,ts=0,ss=0) Rx RSL RF_CHAN_REL
<0006> oml.c:1432 (bts=0,trx=1,ts=0,ss=0) MPH-DEACTIVATE.req (SDCCH RxUL)
<0006> oml.c:1372 (bts=0,trx=1,ts=0,ss=0) MPH-DEACTIVATE.conf (SDCCH RxUL)
<0006> oml.c:1432 (bts=0,trx=1,ts=0,ss=0) MPH-DEACTIVATE.req (SDCCH TxDL)
<0006> oml.c:1372 (bts=0,trx=1,ts=0,ss=0) MPH-DEACTIVATE.conf (SDCCH TxDL)
<0000> rsl.c:528 (bts=0,trx=1,ts=0,ss=0) Tx RF CHAN REL ACK
<0006> oml.c:660 (bts=0,trx=1,ts=0,ss=0) End of queue encountered. Now empty? 1
-------------- next part --------------
<0010> lapdm.c:561 fmt=B
<0010> lapd_core.c:789 SABM(E) received in state LAPD_STATE_IDLE
<0010> lapd_core.c:227 new state LAPD_STATE_IDLE -> LAPD_STATE_MF_EST
<0010> lapd_core.c:896 Store content res.
<0000> rsl.c:1741 (bts=0,trx=1,ts=0,ss=0) Fwd RLL msg EST_IND from LAPDm to A-bis
<0010> lapdm.c:1137 ((nil)) RLL Message 'EST_REQ' received. (sapi 3)
<0010> lapd_core.c:2180 Message DL-ESTABLISH-REQUEST received in state LAPD_STATE_IDLE
<0010> lapd_core.c:1694 perform normal establishm. (SABM)
<0010> lapd_core.c:227 new state LAPD_STATE_IDLE -> LAPD_STATE_SABM_SENT
<0010> lapd_core.c:196 start T200
<0010> lapdm.c:550 fmt=B
<0010> lapd_core.c:992 UI received
<0000> rsl.c:1734 (bts=0,trx=1,ts=0,ss=0) Handing RLL msg UNIT_DATA_IND from LAPDm to MEAS REP
<0010> lapd_core.c:545 Timeout T200 (0xb6a26590) state=5
<0010> lapd_core.c:196 start T200
<0010> lapdm.c:561 fmt=B
<0010> lapd_core.c:789 SABM(E) received in state LAPD_STATE_MF_EST
<0010> lapd_core.c:815 SABM command, multiple frame established state
<0010> lapd_core.c:545 Timeout T200 (0xb6a26590) state=5
<0010> lapd_core.c:196 start T200
<0010> lapdm.c:561 fmt=B
<0010> lapd_core.c:1459 I received in state LAPD_STATE_MF_EST on SAPI(0)
<0010> lapd_core.c:1542 incrementing V(R) to 1
<0010> lapd_core.c:1551 message in single I frame
<0000> rsl.c:1741 (bts=0,trx=1,ts=0,ss=0) Fwd RLL msg DATA_IND from LAPDm to A-bis
<0010> lapd_core.c:1779 lapd_send_i() called from line 1609
<0010> lapd_core.c:1618 we are not busy and have no pending data, send RR
<0010> lapd_core.c:545 Timeout T200 (0xb6a26590) state=5
<0010> lapd_core.c:196 start T200
<0005> paging.c:512 Removed paging record, queue_len=0
<0010> lapdm.c:550 fmt=B
<0010> lapd_core.c:992 UI received
<0000> rsl.c:1734 (bts=0,trx=1,ts=0,ss=0) Handing RLL msg UNIT_DATA_IND from LAPDm to MEAS REP
<0010> lapd_core.c:545 Timeout T200 (0xb6a26590) state=5
<0010> lapd_core.c:196 start T200
<0010> lapdm.c:561 fmt=B
<0010> lapd_core.c:1459 I received in state LAPD_STATE_MF_EST on SAPI(0)
<0010> lapd_core.c:1508 N(S) sequence error: N(S)=0, V(R)=1
<0010> lapd_core.c:1779 lapd_send_i() called from line 1534
<0010> lapd_core.c:545 Timeout T200 (0xb6a26590) state=5
<0010> lapd_core.c:196 start T200
<0010> lapdm.c:561 fmt=B
<0010> lapd_core.c:1459 I received in state LAPD_STATE_MF_EST on SAPI(0)
<0010> lapd_core.c:1508 N(S) sequence error: N(S)=0, V(R)=1
<0010> lapd_core.c:1779 lapd_send_i() called from line 1534
<0010> lapd_core.c:545 Timeout T200 (0xb6a26590) state=5
<0000> rsl.c:1741 (bts=0,trx=1,ts=0,ss=0) Fwd RLL msg REL_IND from LAPDm to A-bis
<0010> lapd_core.c:378 sending MDL-ERROR-IND cause 1
<0010> lapdm.c:386 sending MDL-ERROR-IND 1
<0000> rsl.c:1741 (bts=0,trx=1,ts=0,ss=0) Fwd RLL msg ERROR_IND from LAPDm to A-bis
<0010> lapd_core.c:227 new state LAPD_STATE_SABM_SENT -> LAPD_STATE_IDLE
<0000> rsl.c:1822 (bts=0,trx=1,ts=0,ss=0) Rx RSL DEACTIVATE_SACCH
<0006> oml.c:1432 (bts=0,trx=1,ts=0,ss=0) MPH-DEACTIVATE.req (SACCH TxDL)
<0010> lapd_core.c:2180 Message DL-RELEASE-REQUEST received in state LAPD_STATE_MF_EST
<0010> lapd_core.c:2021 perform local release
<0010> lapd_core.c:227 new state LAPD_STATE_MF_EST -> LAPD_STATE_IDLE