osmo-pcu always "T3193 timeout expired, freeing TBF" when osmo-sgsn send GPRS ATTACH ACCEPT
28 Apr
2021
28 Apr
'21
3:24 a.m.
Hi All,
Here is the issue when use egprs with osmo-bts-trx,osmo-pcu and osmo-sgsn.
osmo-pcu debugging info as below:
<000c> gprs_bssgp_pcu.cpp:168 LLC [SGSN -> PCU] = TLLI: 0xaf8ce1ff IMSI:
460000323182742 len: 26
<0008> tbf.cpp:1068 Allocating DL TBF: MS_CLASS=12/12
<0008> tbf.cpp:541 TBF(TFI=0 TLLI=0x00000000 DIR=DL STATE=NULL) Setting Control
TS 6
<0008> tbf.cpp:945 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=NULL) Allocated: trx =
0, ul_slots = 40, dl_slots = 40
<0008> bts.cpp:898 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=ASSIGN) TX: START
Immediate Assignment Downlink (PCH)
<0008> tbf_dl.cpp:520 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=ASSIGN) set ass.
type PACCH [prev CCCH:0, PACCH:0]
<0008> tbf.cpp:1270 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=ASSIGN) start Packet
Downlink Assignment (PACCH)
<0009> tbf.cpp:788 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=ASSIGN) Scheduled DL
Assignment polling on PACCH (FN=2402222, TS=6)
<0009> tbf_dl.cpp:880 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Scheduled
Ack/Nack polling on FN=2402270, TS=6
<0009> tbf_dl.cpp:880 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Scheduled
Ack/Nack polling on FN=2402322, TS=6
<0008> tbf.cpp:808 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) poll timeout for
FN=2402322, TS=6 (curr FN 2402387)
<0008> tbf.cpp:879 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Timeout for
polling PACKET DOWNLINK ACK.
<0008> tbf.cpp:1184 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Assignment was
on PACCH
<0008> tbf.cpp:1190 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Downlink ACK
was received
<0009> tbf_dl.cpp:880 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Scheduled
Ack/Nack polling on FN=2402426, TS=6
<0008> tbf.cpp:989 Allocating UL TBF: MS_CLASS=12/12
<0008> tbf.cpp:541 TBF(TFI=0 TLLI=0x00000000 DIR=UL STATE=NULL) Setting Control
TS 6
<0008> tbf.cpp:945 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=UL STATE=NULL) Allocated: trx =
0, ul_slots = 40, dl_slots = 00
<0008> tbf.cpp:1359 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=UL STATE=ASSIGN) start Packet
Uplink Assignment (PACCH)
<0009> tbf.cpp:782 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Scheduled UL
Assignment polling on PACCH (FN=2402478, TS=6)
<0007> gprs_rlcmac_meas.cpp:184 DL Bandwitdh of IMSI=460000323182742 /
TLLI=0xaf8ce1ff: 66 KBits/s
<0009> tbf_dl.cpp:880 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Scheduled
Ack/Nack polling on FN=2402525, TS=6
<000c> tbf_ul.cpp:404 LLC [PCU -> SGSN] TBF(TFI=0 TLLI=0xaf8ce1ff DIR=UL
STATE=FLOW) len=97
<000c> gprs_bssgp_pcu.cpp:168 LLC [SGSN -> PCU] = TLLI: 0xaf8ce1ff IMSI:
460000323182742 len: 9
<0008> tbf.cpp:808 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) poll timeout for
FN=2402525, TS=6 (curr FN 2402586)
<0008> tbf.cpp:879 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Timeout for
polling PACKET DOWNLINK ACK.
<0008> tbf.cpp:1184 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Assignment was
on PACCH
<0008> tbf.cpp:1190 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Downlink ACK
was received
<0009> tbf_dl.cpp:880 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Scheduled
Ack/Nack polling on FN=2402625, TS=6
<0007> gprs_rlcmac_meas.cpp:106 UL RSSI of TLLI=0xaf8ce1ff: -31 dBm
<0008> tbf.cpp:486 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=UL STATE=FINISHED) free
<0008> tbf.cpp:989 Allocating UL TBF: MS_CLASS=12/12
<0008> tbf.cpp:541 TBF(TFI=0 TLLI=0x00000000 DIR=UL STATE=NULL) Setting Control
TS 6
<0008> tbf.cpp:945 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=UL STATE=NULL) Allocated: trx =
0, ul_slots = 40, dl_slots = 00
<0008> tbf.cpp:1359 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=UL STATE=ASSIGN) start Packet
Uplink Assignment (PACCH)
<0009> tbf.cpp:782 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Scheduled UL
Assignment polling on PACCH (FN=2402673, TS=6)
<0009> tbf_dl.cpp:880 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Scheduled
Ack/Nack polling on FN=2402720, TS=6
<000c> tbf_ul.cpp:404 LLC [PCU -> SGSN] TBF(TFI=0 TLLI=0xaf8ce1ff DIR=UL
STATE=FLOW) len=17
<000c> gprs_bssgp_pcu.cpp:168 LLC [SGSN -> PCU] = TLLI: 0xaf8ce1ff IMSI:
460000323182742 len: 26
<0007> gprs_rlcmac_meas.cpp:184 DL Bandwitdh of IMSI=460000323182742 /
TLLI=0xaf8ce1ff: 86 KBits/s
<0009> tbf_dl.cpp:880 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Scheduled
Ack/Nack polling on FN=2402768, TS=6
<0007> gprs_rlcmac_meas.cpp:106 UL RSSI of TLLI=0xaf8ce1ff: -31 dBm
<0008> tbf.cpp:486 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=UL STATE=FINISHED) free
<0009> tbf_dl.cpp:880 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Scheduled
Ack/Nack polling on FN=2402816, TS=6
<0009> tbf_dl.cpp:880 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Scheduled
Ack/Nack polling on FN=2402863, TS=6
<0009> tbf_dl.cpp:880 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Scheduled
Ack/Nack polling on FN=2402911, TS=6
<0009> tbf_dl.cpp:880 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Scheduled
Ack/Nack polling on FN=2402959, TS=6
<0007> gprs_rlcmac_meas.cpp:184 DL Bandwitdh of IMSI=460000323182742 /
TLLI=0xaf8ce1ff: 240 KBits/s
<0009> tbf_dl.cpp:880 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Scheduled
Ack/Nack polling on FN=2403006, TS=6
<0009> tbf_dl.cpp:880 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Scheduled
Ack/Nack polling on FN=2403054, TS=6
<0009> tbf_dl.cpp:880 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Scheduled
Ack/Nack polling on FN=2403102, TS=6
<0009> tbf_dl.cpp:880 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Scheduled
Ack/Nack polling on FN=2403149, TS=6
<0009> tbf_dl.cpp:880 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FINISHED) Scheduled
Ack/Nack polling on FN=2403197, TS=6
<0008> tbf.cpp:650 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=WAIT RELEASE) T3193
timeout expired, freeing TBF
<0008> tbf.cpp:486 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=RELEASING) free
<000c> gprs_bssgp_pcu.cpp:168 LLC [SGSN -> PCU] = TLLI: 0xaf8ce1ff IMSI:
460000323182742 len: 26
<0008> tbf.cpp:1068 Allocating DL TBF: MS_CLASS=12/12
<0008> tbf.cpp:541 TBF(TFI=0 TLLI=0x00000000 DIR=DL STATE=NULL) Setting Control
TS 6
<0008> tbf.cpp:945 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=NULL) Allocated: trx =
0, ul_slots = 40, dl_slots = 40
<0008> bts.cpp:898 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=ASSIGN) TX: START
Immediate Assignment Downlink (PCH)
<0008> tbf_dl.cpp:520 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=ASSIGN) set ass.
type PACCH [prev CCCH:0, PACCH:0]
<0008> tbf.cpp:1270 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=ASSIGN) start Packet
Downlink Assignment (PACCH)
<0009> tbf.cpp:788 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=ASSIGN) Scheduled DL
Assignment polling on PACCH (FN=2404263, TS=6)
<0007> gprs_rlcmac_meas.cpp:184 DL Bandwitdh of IMSI=460000323182742 /
TLLI=0xaf8ce1ff: 22 KBits/s
<0009> tbf_dl.cpp:880 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Scheduled
Ack/Nack polling on FN=2404311, TS=6
<0009> tbf_dl.cpp:880 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Scheduled
Ack/Nack polling on FN=2404358, TS=6
<0009> tbf_dl.cpp:880 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Scheduled
Ack/Nack polling on FN=2404406, TS=6
<0009> tbf_dl.cpp:880 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Scheduled
Ack/Nack polling on FN=2404454, TS=6
<0008> tbf.cpp:808 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) poll timeout for
FN=2404454, TS=6 (curr FN 2404519)
<0008> tbf.cpp:879 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Timeout for
polling PACKET DOWNLINK ACK.
<0008> tbf.cpp:1184 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Assignment was
on PACCH
<0008> tbf.cpp:1190 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Downlink ACK
was received
<0009> tbf_dl.cpp:880 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Scheduled
Ack/Nack polling on FN=2404558, TS=6
<0007> gprs_rlcmac_meas.cpp:184 DL Bandwitdh of IMSI=460000323182742 /
TLLI=0xaf8ce1ff: 163 KBits/s
<0009> tbf_dl.cpp:880 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Scheduled
Ack/Nack polling on FN=2404605, TS=6
<0009> tbf_dl.cpp:880 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Scheduled
Ack/Nack polling on FN=2404653, TS=6
<0009> tbf_dl.cpp:880 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Scheduled
Ack/Nack polling on FN=2404701, TS=6
<0009> tbf_dl.cpp:880 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FINISHED) Scheduled
Ack/Nack polling on FN=2404748, TS=6
<0008> tbf.cpp:650 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=WAIT RELEASE) T3193
timeout expired, freeing TBF
<0008> tbf.cpp:486 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=RELEASING) free
<000c> gprs_bssgp_pcu.cpp:168 LLC [SGSN -> PCU] = TLLI: 0xaf8ce1ff IMSI:
460000323182742 len: 26
<0008> tbf.cpp:1068 Allocating DL TBF: MS_CLASS=12/12
<0008> tbf.cpp:541 TBF(TFI=0 TLLI=0x00000000 DIR=DL STATE=NULL) Setting Control
TS 6
<0008> tbf.cpp:945 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=NULL) Allocated: trx =
0, ul_slots = 40, dl_slots = 40
<0008> bts.cpp:898 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=ASSIGN) TX: START
Immediate Assignment Downlink (PCH)
<0008> tbf_dl.cpp:520 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=ASSIGN) set ass.
type PACCH [prev CCCH:0, PACCH:0]
<0008> tbf.cpp:1270 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=ASSIGN) start Packet
Downlink Assignment (PACCH)
<0009> tbf.cpp:788 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=ASSIGN) Scheduled DL
Assignment polling on PACCH (FN=2405537, TS=6)
<0007> gprs_rlcmac_meas.cpp:184 DL Bandwitdh of IMSI=460000323182742 /
TLLI=0xaf8ce1ff: 25 KBits/s
<0009> tbf_dl.cpp:880 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Scheduled
Ack/Nack polling on FN=2405585, TS=6
<0009> tbf_dl.cpp:880 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Scheduled
Ack/Nack polling on FN=2405632, TS=6
<0009> tbf_dl.cpp:880 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Scheduled
Ack/Nack polling on FN=2405680, TS=6
<0008> tbf.cpp:808 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) poll timeout for
FN=2405680, TS=6 (curr FN 2405741)
<0008> tbf.cpp:879 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Timeout for
polling PACKET DOWNLINK ACK.
osmo-sgsn debugging info:
<0011> gprs_llc_parse.c:78 LLC SAPI=1 C U GEA0
IOV-UI=0x000000 FCS=0xa3ad04 CMD=UI DATA
<0002> gprs_gmm.c:1118 MM(---/ffffffff) -> GMM ATTACH REQUEST
MI(4018987519) type="GPRS attach"
<0002> fsm.c:461 GMM(gmm_fsm)[0xaaaaf63e5b50]{Deregistered}: Allocated
<0002> fsm.c:461 GMM_ATTACH_REQ_FSM(gb_gmm_req)[0xaaaaf63e5c80]{Init}:
Allocated
<0002> fsm.c:461 MM_STATE_Gb[0xaaaaf63e5e50]{Idle}: Allocated
<0002> gprs_sgsn.c:299 MM(/00000000) Allocated with GEA0 cipher.
<0002> gprs_gmm.c:1100 GMM(gmm_fsm)[0xaaaaf63e5b50]{Deregistered}: Received
Event E_GMM_COMMON_PROC_INIT_REQ
<0002> gprs_gmm_fsm.c:25 GMM(gmm_fsm)[0xaaaaf63e5b50]{Deregistered}: state_chg
to CommonProcedureInitiated
<0011> gprs_llc.c:1056 LLME(ffffffff/af8ce1ff){UNASSIGNED} LLGM Assign pre
(af8ce1ff => cf0ebf06)
<0011> gprs_llc.c:1102 LLME(af8ce1ff/cf0ebf06){ASSIGNED} LLGM Assign post
(af8ce1ff => cf0ebf06)
<0002> gprs_gmm.c:1271 GMM_ATTACH_REQ_FSM(gb_gmm_req)[0xaaaaf63e5c80]{Init}:
Received Event E_ATTACH_REQ_RECV
<0002> gprs_gmm_attach.c:50
GMM_ATTACH_REQ_FSM(gb_gmm_req)[0xaaaaf63e5c80]{Init}: state_chg to CheckIdentity
<0002> gprs_gmm.c:409 MM(/cf0ebf06) <- GPRS IDENTITY REQUEST: mi_type=IMEI
<0010> gprs_bssgp.c:423 BSSGP TLLI=0xaf8ce1ff Rx UPLINK-UNITDATA
<0011> gprs_llc_parse.c:78 LLC SAPI=1 C U GEA0
IOV-UI=0x000000 FCS=0x8c64cd CMD=UI DATA
<0002> gprs_gb.c:40 MM_STATE_Gb(2945245695)[0xaaaaf63e5e50]{Idle}: Received
Event E_MM_PDU_RECEPTION
<0002> gprs_gmm.c:1040 MM(/cf0ebf06) -> GMM IDENTITY RESPONSE:
MI(IMEI)=866089038960590
<0002> gprs_gmm.c:113 MM(/cf0ebf06) Stopping MM timer 3370 but 0 is running
<0002> gprs_gmm.c:1084
GMM_ATTACH_REQ_FSM(gb_gmm_req)[0xaaaaf63e5c80]{CheckIdentity}: Received Event
E_IDEN_RESP_RECV
<0002> gprs_gmm_attach.c:111
GMM_ATTACH_REQ_FSM(gb_gmm_req)[0xaaaaf63e5c80]{CheckIdentity}: state_chg to
CheckIdentity
<0002> gprs_gmm.c:409 MM(/cf0ebf06) <- GPRS IDENTITY REQUEST: mi_type=IMSI
<0010> gprs_bssgp.c:423 BSSGP TLLI=0xaf8ce1ff Rx UPLINK-UNITDATA
<0011> gprs_llc_parse.c:78 LLC SAPI=1 C U GEA0
IOV-UI=0x000000 FCS=0xb71895 CMD=UI DATA
<0002> gprs_gb.c:40 MM_STATE_Gb(2945245695)[0xaaaaf63e5e50]{Idle}: Received
Event E_MM_PDU_RECEPTION
<0002> gprs_gmm.c:1040 MM(/cf0ebf06) -> GMM IDENTITY RESPONSE:
MI(IMSI)=460000323182742
<0002> gprs_gmm.c:113 MM(/cf0ebf06) Stopping MM timer 3370 but 0 is running
<0002> gprs_gmm.c:1084
GMM_ATTACH_REQ_FSM(gb_gmm_req)[0xaaaaf63e5c80]{CheckIdentity}: Received Event
E_IDEN_RESP_RECV
<0002> gprs_gmm_attach.c:113
GMM_ATTACH_REQ_FSM(gb_gmm_req)[0xaaaaf63e5c80]{CheckIdentity}: state_chg to Authenticate
<0002> gprs_gmm_attach.c:148
GMM_ATTACH_REQ_FSM(gb_gmm_req)[0xaaaaf63e5c80]{Authenticate}: state_chg to
WaitAttachComplete
<0002> gprs_gmm.c:289 MM(460000323182742/cf0ebf06) <- GPRS ATTACH ACCEPT (new
P-TMSI=0xcf0ebf06)
<0002> gprs_gmm.c:305 MM(460000323182742/cf0ebf06) <- GPRS ATTACH ACCEPT
(ra_id=0x020xf20x50 lac:2f11 rac:2)
<000e> gprs_sgsn.c:1012 Checking for inactive LLMEs, time = 1652
<000f> gprs_ns.c:779 NSEI=1234 Timer expired in mode tns-test (30 seconds)
<000f> gprs_ns.c:712 NSEI=1234 Tx NS ALIVE (NSVCI=1234)
<000f> gprs_ns.c:751 NSEI=1234 Starting timer in mode tns-alive (3 seconds)
<000f> gprs_ns.c:725 NSEI=1234 Tx NS ALIVE_ACK (NSVCI=1234)
<000f> gprs_ns.c:1763 NSEI 1234 (NS-VCI=1234) setting state
[ALIVE,UNBLOCKED,UNRESET] -> [ALIVE,UNBLOCKED,UNRESET]
<000f> gprs_ns.c:751 NSEI=1234 Starting timer in mode tns-test (30 seconds)
<0010> gprs_bssgp.c:839 BSSGP BVCI=1234 Rx Flow Control BVC
<0002> fsm.c:322
GMM_ATTACH_REQ_FSM(gb_gmm_req)[0xaaaaf63e5c80]{WaitAttachComplete}: Timeout of T3350
<0002> gprs_gmm.c:289 MM(460000323182742/cf0ebf06) <- GPRS ATTACH ACCEPT (new
P-TMSI=0xcf0ebf06)
<0002> gprs_gmm.c:305 MM(460000323182742/cf0ebf06) <- GPRS ATTACH ACCEPT
(ra_id=0x020xf20x50 lac:2f11 rac:2)
<0002> fsm.c:322
GMM_ATTACH_REQ_FSM(gb_gmm_req)[0xaaaaf63e5c80]{WaitAttachComplete}: Timeout of T3350
<0002> gprs_gmm.c:289 MM(460000323182742/cf0ebf06) <- GPRS ATTACH ACCEPT (new
P-TMSI=0xcf0ebf06)
<0002> gprs_gmm.c:305 MM(460000323182742/cf0ebf06) <- GPRS ATTACH ACCEPT
(ra_id=0x020xf20x50 lac:2f11 rac:2)
<0010> gprs_bssgp.c:423 BSSGP TLLI=0xaf8ce1ff Rx UPLINK-UNITDATA
<0011> gprs_llc_parse.c:78 LLC SAPI=1 C U GEA0
IOV-UI=0x000000 FCS=0x0d0447 CMD=UI DATA
<0002> gprs_gb.c:40 MM_STATE_Gb(2945245695)[0xaaaaf63e5e50]{Idle}: Received
Event E_MM_PDU_RECEPTION
<0002> gprs_gmm.c:1118 MM(460000323182742/cf0ebf06) -> GMM ATTACH REQUEST
MI(4018987519) type="GPRS attach"
<0002> gprs_gmm.c:1100 GMM(gmm_fsm)[0xaaaaf63e5b50]{CommonProcedureInitiated}:
Received Event E_GMM_COMMON_PROC_INIT_REQ
<0002> gprs_gmm.c:1100 GMM(gmm_fsm)[0xaaaaf63e5b50]{CommonProcedureInitiated}:
Event E_GMM_COMMON_PROC_INIT_REQ not permitted
<0011> gprs_llc.c:1056 LLME(af8ce1ff/cf0ebf06){ASSIGNED} LLGM Assign pre
(af8ce1ff => cf0ebf06)
<0011> gprs_llc.c:1102 LLME(af8ce1ff/cf0ebf06){ASSIGNED} LLGM Assign post
(af8ce1ff => cf0ebf06)
<0002> gprs_gmm.c:1271
GMM_ATTACH_REQ_FSM(gb_gmm_req)[0xaaaaf63e5c80]{WaitAttachComplete}: Received Event
E_ATTACH_REQ_RECV
<0002> gprs_gmm_attach.c:360
GMM_ATTACH_REQ_FSM(gb_gmm_req)[0xaaaaf63e5c80]{WaitAttachComplete}: state_chg to Init
<0002> gprs_gmm_attach.c:50
GMM_ATTACH_REQ_FSM(gb_gmm_req)[0xaaaaf63e5c80]{Init}: state_chg to CheckIdentity
<0002> gprs_gmm.c:409 MM(460000323182742/cf0ebf06) <- GPRS IDENTITY REQUEST:
mi_type=IMEI
<0010> gprs_bssgp.c:839 BSSGP BVCI=1234 Rx Flow Control BVC
<0010> gprs_bssgp.c:423 BSSGP TLLI=0xaf8ce1ff Rx UPLINK-UNITDATA
<0011> gprs_llc_parse.c:78 LLC SAPI=1 C U GEA0
IOV-UI=0x000000 FCS=0xea5c4f CMD=UI DATA
<0002> gprs_gb.c:40 MM_STATE_Gb(2945245695)[0xaaaaf63e5e50]{Idle}: Received
Event E_MM_PDU_RECEPTION
<0002> gprs_gmm.c:1040 MM(460000323182742/cf0ebf06) -> GMM IDENTITY
RESPONSE: MI(IMEI)=866089038960590
<0002> gprs_gmm.c:113 MM(460000323182742/cf0ebf06) Stopping MM timer 3370 but 0
is running
<0002> gprs_gmm.c:1084
GMM_ATTACH_REQ_FSM(gb_gmm_req)[0xaaaaf63e5c80]{CheckIdentity}: Received Event
E_IDEN_RESP_RECV
<0002> gprs_gmm_attach.c:113
GMM_ATTACH_REQ_FSM(gb_gmm_req)[0xaaaaf63e5c80]{CheckIdentity}: state_chg to Authenticate
<0002> gprs_gmm_attach.c:148
GMM_ATTACH_REQ_FSM(gb_gmm_req)[0xaaaaf63e5c80]{Authenticate}: state_chg to
WaitAttachComplete
<0002> gprs_gmm.c:289 MM(460000323182742/cf0ebf06) <- GPRS ATTACH ACCEPT (new
P-TMSI=0xcf0ebf06)
<0002> gprs_gmm.c:305 MM(460000323182742/cf0ebf06) <- GPRS ATTACH ACCEPT
(ra_id=0x020xf20x50 lac:2f11 rac:2)
<0002> fsm.c:322
GMM_ATTACH_REQ_FSM(gb_gmm_req)[0xaaaaf63e5c80]{WaitAttachComplete}: Timeout of T3350
<0002> gprs_gmm.c:289 MM(460000323182742/cf0ebf06) <- GPRS ATTACH ACCEPT (new
P-TMSI=0xcf0ebf06)
<0002> gprs_gmm.c:305 MM(460000323182742/cf0ebf06) <- GPRS ATTACH ACCEPT
(ra_id=0x020xf20x50 lac:2f11 rac:2)
Configure information：
gprs mode egprs
gprs routing area 2
gprs cell bvci 1234
gprs nsei 1234
gprs nsvc 0 nsvci 1234
gprs nsvc 0 local udp port 23001
gprs nsvc 0 remote udp port 23000
。。。
timeslot 6
phys_chan_config PDCH
hopping enabled 0
timeslot 7
phys_chan_config PDCH
hopping enabled 0
pcu
flow-control-interval 10
cs 2
cs max 4
cs threshold 10 33
cs downgrade-threshold 200
cs link-quality-ranges cs1 6 cs2 5 8 cs3 7 13 cs4 12
mcs link-quality-ranges mcs1 6 mcs2 5 8 mcs3 7 13 mcs4 12 15 mcs5 14 17 mcs6 16
18 mcs7 17 20 mcs8 19 24 mcs9 23
mcs max 9
window-size 64 0
queue idle-ack-delay 10
queue codel
alloc-algorithm dynamic
alpha 0
gamma 0
dl-tbf-idle-time 2000
sgsn
gtp local-ip 127.0.0.1
ggsn 0 remote-ip 127.0.0.6
ggsn 0 gtp-version 1
auth-policy accept-all
ns
timer tns-block 3
timer tns-block-retries 3
timer tns-reset 3
timer tns-reset-retries 3
timer tns-test 30
timer tns-alive 3
timer tns-alive-retries 10
encapsulation udp local-ip 127.0.0.1
encapsulation udp local-port 23000
encapsulation framerelay-gre enabled 0
Version information:
OsmoPCU version 0.8.0
OsmoSGSN version 1.6.2
I tried to debug this issue but the no any progress for this issue.The root cause is
confifure or something else?
I need help.
Thanks a lot.
Br,
Perter
29 Apr
29 Apr
5:27 p.m.
Hi,
can you please record and send a pcap file while trying to attach?
Make sure you are using osmo-bts-trx and osmo-pcu master (please provide
output wyou get with "--version").
Also make sure to enable GSMTAP in both osmo-pcu and osmo-bts-trx.
Also please enable "gsmtap log" with "logging level set-all info" for
osmo-pcu, so that everything end sup in the pcap file.
Regards,
Pau Espin Pedrol
Missatge de 海鱼 <86731050(a)qq.com> del dia dc., 28 d’abr. 2021 a les 3:32:
Hi All,
Here is the issue when use egprs with osmo-bts-trx,osmo-pcu and osmo-sgsn.
osmo-pcu debugging info as below:
<000c> gprs_bssgp_pcu.cpp:168 LLC [SGSN -> PCU] = TLLI: 0xaf8ce1ff IMSI:
460000323182742 len: 26
<0008> tbf.cpp:1068 Allocating DL TBF: MS_CLASS=12/12
<0008> tbf.cpp:541 TBF(TFI=0 TLLI=0x00000000 DIR=DL STATE=NULL) Setting
Control TS 6
<0008> tbf.cpp:945 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=NULL) Allocated:
trx = 0, ul_slots = 40, dl_slots = 40
<0008> bts.cpp:898 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=ASSIGN) TX:
START Immediate Assignment Downlink (PCH)
<0008> tbf_dl.cpp:520 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=ASSIGN) set
ass. type PACCH [prev CCCH:0, PACCH:0]
<0008> tbf.cpp:1270 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=ASSIGN) start
Packet Downlink Assignment (PACCH)
<0009> tbf.cpp:788 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=ASSIGN)
Scheduled DL Assignment polling on PACCH (FN=2402222, TS=6)
<0009> tbf_dl.cpp:880 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW)
Scheduled Ack/Nack polling on FN=2402270, TS=6
<0009> tbf_dl.cpp:880 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW)
Scheduled Ack/Nack polling on FN=2402322, TS=6
<0008> tbf.cpp:808 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) poll
timeout for FN=2402322, TS=6 (curr FN 2402387)
<0008> tbf.cpp:879 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Timeout
for polling PACKET DOWNLINK ACK.
<0008> tbf.cpp:1184 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW)
Assignment was on PACCH
<0008> tbf.cpp:1190 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Downlink
ACK was received
<0009> tbf_dl.cpp:880 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW)
Scheduled Ack/Nack polling on FN=2402426, TS=6
<0008> tbf.cpp:989 Allocating UL TBF: MS_CLASS=12/12
<0008> tbf.cpp:541 TBF(TFI=0 TLLI=0x00000000 DIR=UL STATE=NULL) Setting
Control TS 6
<0008> tbf.cpp:945 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=UL STATE=NULL) Allocated:
trx = 0, ul_slots = 40, dl_slots = 00
<0008> tbf.cpp:1359 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=UL STATE=ASSIGN) start
Packet Uplink Assignment (PACCH)
<0009> tbf.cpp:782 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Scheduled
UL Assignment polling on PACCH (FN=2402478, TS=6)
<0007> gprs_rlcmac_meas.cpp:184 DL Bandwitdh of IMSI=460000323182742 /
TLLI=0xaf8ce1ff: 66 KBits/s
<0009> tbf_dl.cpp:880 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW)
Scheduled Ack/Nack polling on FN=2402525, TS=6
<000c> tbf_ul.cpp:404 LLC [PCU -> SGSN] TBF(TFI=0 TLLI=0xaf8ce1ff DIR=UL
STATE=FLOW) len=97
<000c> gprs_bssgp_pcu.cpp:168 LLC [SGSN -> PCU] = TLLI: 0xaf8ce1ff IMSI:
460000323182742 len: 9
<0008> tbf.cpp:808 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) poll
timeout for FN=2402525, TS=6 (curr FN 2402586)
<0008> tbf.cpp:879 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Timeout
for polling PACKET DOWNLINK ACK.
<0008> tbf.cpp:1184 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW)
Assignment was on PACCH
<0008> tbf.cpp:1190 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Downlink
ACK was received
<0009> tbf_dl.cpp:880 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW)
Scheduled Ack/Nack polling on FN=2402625, TS=6
<0007> gprs_rlcmac_meas.cpp:106 UL RSSI of TLLI=0xaf8ce1ff: -31 dBm
<0008> tbf.cpp:486 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=UL STATE=FINISHED) free
<0008> tbf.cpp:989 Allocating UL TBF: MS_CLASS=12/12
<0008> tbf.cpp:541 TBF(TFI=0 TLLI=0x00000000 DIR=UL STATE=NULL) Setting
Control TS 6
<0008> tbf.cpp:945 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=UL STATE=NULL) Allocated:
trx = 0, ul_slots = 40, dl_slots = 00
<0008> tbf.cpp:1359 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=UL STATE=ASSIGN) start
Packet Uplink Assignment (PACCH)
<0009> tbf.cpp:782 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Scheduled
UL Assignment polling on PACCH (FN=2402673, TS=6)
<0009> tbf_dl.cpp:880 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW)
Scheduled Ack/Nack polling on FN=2402720, TS=6
<000c> tbf_ul.cpp:404 LLC [PCU -> SGSN] TBF(TFI=0 TLLI=0xaf8ce1ff DIR=UL
STATE=FLOW) len=17
<000c> gprs_bssgp_pcu.cpp:168 LLC [SGSN -> PCU] = TLLI: 0xaf8ce1ff IMSI:
460000323182742 len: 26
<0007> gprs_rlcmac_meas.cpp:184 DL Bandwitdh of IMSI=460000323182742 /
TLLI=0xaf8ce1ff: 86 KBits/s
<0009> tbf_dl.cpp:880 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW)
Scheduled Ack/Nack polling on FN=2402768, TS=6
<0007> gprs_rlcmac_meas.cpp:106 UL RSSI of TLLI=0xaf8ce1ff: -31 dBm
<0008> tbf.cpp:486 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=UL STATE=FINISHED) free
<0009> tbf_dl.cpp:880 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW)
Scheduled Ack/Nack polling on FN=2402816, TS=6
<0009> tbf_dl.cpp:880 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW)
Scheduled Ack/Nack polling on FN=2402863, TS=6
<0009> tbf_dl.cpp:880 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW)
Scheduled Ack/Nack polling on FN=2402911, TS=6
<0009> tbf_dl.cpp:880 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW)
Scheduled Ack/Nack polling on FN=2402959, TS=6
<0007> gprs_rlcmac_meas.cpp:184 DL Bandwitdh of IMSI=460000323182742 /
TLLI=0xaf8ce1ff: 240 KBits/s
<0009> tbf_dl.cpp:880 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW)
Scheduled Ack/Nack polling on FN=2403006, TS=6
<0009> tbf_dl.cpp:880 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW)
Scheduled Ack/Nack polling on FN=2403054, TS=6
<0009> tbf_dl.cpp:880 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW)
Scheduled Ack/Nack polling on FN=2403102, TS=6
<0009> tbf_dl.cpp:880 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW)
Scheduled Ack/Nack polling on FN=2403149, TS=6
<0009> tbf_dl.cpp:880 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FINISHED)
Scheduled Ack/Nack polling on FN=2403197, TS=6
<0008> tbf.cpp:650 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=WAIT RELEASE)
T3193 timeout expired, freeing TBF
<0008> tbf.cpp:486 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=RELEASING) free
<000c> gprs_bssgp_pcu.cpp:168 LLC [SGSN -> PCU] = TLLI: 0xaf8ce1ff IMSI:
460000323182742 len: 26
<0008> tbf.cpp:1068 Allocating DL TBF: MS_CLASS=12/12
<0008> tbf.cpp:541 TBF(TFI=0 TLLI=0x00000000 DIR=DL STATE=NULL) Setting
Control TS 6
<0008> tbf.cpp:945 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=NULL) Allocated:
trx = 0, ul_slots = 40, dl_slots = 40
<0008> bts.cpp:898 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=ASSIGN) TX:
START Immediate Assignment Downlink (PCH)
<0008> tbf_dl.cpp:520 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=ASSIGN) set
ass. type PACCH [prev CCCH:0, PACCH:0]
<0008> tbf.cpp:1270 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=ASSIGN) start
Packet Downlink Assignment (PACCH)
<0009> tbf.cpp:788 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=ASSIGN)
Scheduled DL Assignment polling on PACCH (FN=2404263, TS=6)
<0007> gprs_rlcmac_meas.cpp:184 DL Bandwitdh of IMSI=460000323182742 /
TLLI=0xaf8ce1ff: 22 KBits/s
<0009> tbf_dl.cpp:880 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW)
Scheduled Ack/Nack polling on FN=2404311, TS=6
<0009> tbf_dl.cpp:880 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW)
Scheduled Ack/Nack polling on FN=2404358, TS=6
<0009> tbf_dl.cpp:880 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW)
Scheduled Ack/Nack polling on FN=2404406, TS=6
<0009> tbf_dl.cpp:880 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW)
Scheduled Ack/Nack polling on FN=2404454, TS=6
<0008> tbf.cpp:808 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) poll
timeout for FN=2404454, TS=6 (curr FN 2404519)
<0008> tbf.cpp:879 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Timeout
for polling PACKET DOWNLINK ACK.
<0008> tbf.cpp:1184 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW)
Assignment was on PACCH
<0008> tbf.cpp:1190 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Downlink
ACK was received
<0009> tbf_dl.cpp:880 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW)
Scheduled Ack/Nack polling on FN=2404558, TS=6
<0007> gprs_rlcmac_meas.cpp:184 DL Bandwitdh of IMSI=460000323182742 /
TLLI=0xaf8ce1ff: 163 KBits/s
<0009> tbf_dl.cpp:880 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW)
Scheduled Ack/Nack polling on FN=2404605, TS=6
<0009> tbf_dl.cpp:880 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW)
Scheduled Ack/Nack polling on FN=2404653, TS=6
<0009> tbf_dl.cpp:880 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW)
Scheduled Ack/Nack polling on FN=2404701, TS=6
<0009> tbf_dl.cpp:880 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FINISHED)
Scheduled Ack/Nack polling on FN=2404748, TS=6
<0008> tbf.cpp:650 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=WAIT RELEASE)
T3193 timeout expired, freeing TBF
<0008> tbf.cpp:486 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=RELEASING) free
<000c> gprs_bssgp_pcu.cpp:168 LLC [SGSN -> PCU] = TLLI: 0xaf8ce1ff IMSI:
460000323182742 len: 26
<0008> tbf.cpp:1068 Allocating DL TBF: MS_CLASS=12/12
<0008> tbf.cpp:541 TBF(TFI=0 TLLI=0x00000000 DIR=DL STATE=NULL) Setting
Control TS 6
<0008> tbf.cpp:945 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=NULL) Allocated:
trx = 0, ul_slots = 40, dl_slots = 40
<0008> bts.cpp:898 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=ASSIGN) TX:
START Immediate Assignment Downlink (PCH)
<0008> tbf_dl.cpp:520 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=ASSIGN) set
ass. type PACCH [prev CCCH:0, PACCH:0]
<0008> tbf.cpp:1270 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=ASSIGN) start
Packet Downlink Assignment (PACCH)
<0009> tbf.cpp:788 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=ASSIGN)
Scheduled DL Assignment polling on PACCH (FN=2405537, TS=6)
<0007> gprs_rlcmac_meas.cpp:184 DL Bandwitdh of IMSI=460000323182742 /
TLLI=0xaf8ce1ff: 25 KBits/s
<0009> tbf_dl.cpp:880 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW)
Scheduled Ack/Nack polling on FN=2405585, TS=6
<0009> tbf_dl.cpp:880 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW)
Scheduled Ack/Nack polling on FN=2405632, TS=6
<0009> tbf_dl.cpp:880 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW)
Scheduled Ack/Nack polling on FN=2405680, TS=6
<0008> tbf.cpp:808 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) poll
timeout for FN=2405680, TS=6 (curr FN 2405741)
<0008> tbf.cpp:879 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Timeout
for polling PACKET DOWNLINK ACK.
osmo-sgsn debugging info:
<0011> gprs_llc_parse.c:78 LLC SAPI=1 C U GEA0 IOV-UI=0x000000
FCS=0xa3ad04 CMD=UI DATA
<0002> gprs_gmm.c:1118 MM(---/ffffffff) -> GMM ATTACH REQUEST
MI(4018987519) type="GPRS attach"
<0002> fsm.c:461 GMM(gmm_fsm)[0xaaaaf63e5b50]{Deregistered}: Allocated
<0002> fsm.c:461 GMM_ATTACH_REQ_FSM(gb_gmm_req)[0xaaaaf63e5c80]{Init}:
Allocated
<0002> fsm.c:461 MM_STATE_Gb[0xaaaaf63e5e50]{Idle}: Allocated
<0002> gprs_sgsn.c:299 MM(/00000000) Allocated with GEA0 cipher.
<0002> gprs_gmm.c:1100 GMM(gmm_fsm)[0xaaaaf63e5b50]{Deregistered}:
Received Event E_GMM_COMMON_PROC_INIT_REQ
<0002> gprs_gmm_fsm.c:25 GMM(gmm_fsm)[0xaaaaf63e5b50]{Deregistered}:
state_chg to CommonProcedureInitiated
<0011> gprs_llc.c:1056 LLME(ffffffff/af8ce1ff){UNASSIGNED} LLGM Assign pre
(af8ce1ff => cf0ebf06)
<0011> gprs_llc.c:1102 LLME(af8ce1ff/cf0ebf06){ASSIGNED} LLGM Assign post
(af8ce1ff => cf0ebf06)
<0002> gprs_gmm.c:1271
GMM_ATTACH_REQ_FSM(gb_gmm_req)[0xaaaaf63e5c80]{Init}: Received Event
E_ATTACH_REQ_RECV
<0002> gprs_gmm_attach.c:50
GMM_ATTACH_REQ_FSM(gb_gmm_req)[0xaaaaf63e5c80]{Init}: state_chg to
CheckIdentity
<0002> gprs_gmm.c:409 MM(/cf0ebf06) <- GPRS IDENTITY REQUEST: mi_type=IMEI
<0010> gprs_bssgp.c:423 BSSGP TLLI=0xaf8ce1ff Rx UPLINK-UNITDATA
<0011> gprs_llc_parse.c:78 LLC SAPI=1 C U GEA0 IOV-UI=0x000000
FCS=0x8c64cd CMD=UI DATA
<0002> gprs_gb.c:40 MM_STATE_Gb(2945245695)[0xaaaaf63e5e50]{Idle}:
Received Event E_MM_PDU_RECEPTION
<0002> gprs_gmm.c:1040 MM(/cf0ebf06) -> GMM IDENTITY RESPONSE:
MI(IMEI)=866089038960590
<0002> gprs_gmm.c:113 MM(/cf0ebf06) Stopping MM timer 3370 but 0 is running
<0002> gprs_gmm.c:1084
GMM_ATTACH_REQ_FSM(gb_gmm_req)[0xaaaaf63e5c80]{CheckIdentity}: Received
Event E_IDEN_RESP_RECV
<0002> gprs_gmm_attach.c:111
GMM_ATTACH_REQ_FSM(gb_gmm_req)[0xaaaaf63e5c80]{CheckIdentity}: state_chg to
CheckIdentity
<0002> gprs_gmm.c:409 MM(/cf0ebf06) <- GPRS IDENTITY REQUEST: mi_type=IMSI
<0010> gprs_bssgp.c:423 BSSGP TLLI=0xaf8ce1ff Rx UPLINK-UNITDATA
<0011> gprs_llc_parse.c:78 LLC SAPI=1 C U GEA0 IOV-UI=0x000000
FCS=0xb71895 CMD=UI DATA
<0002> gprs_gb.c:40 MM_STATE_Gb(2945245695)[0xaaaaf63e5e50]{Idle}:
Received Event E_MM_PDU_RECEPTION
<0002> gprs_gmm.c:1040 MM(/cf0ebf06) -> GMM IDENTITY RESPONSE:
MI(IMSI)=460000323182742
<0002> gprs_gmm.c:113 MM(/cf0ebf06) Stopping MM timer 3370 but 0 is running
<0002> gprs_gmm.c:1084
GMM_ATTACH_REQ_FSM(gb_gmm_req)[0xaaaaf63e5c80]{CheckIdentity}: Received
Event E_IDEN_RESP_RECV
<0002> gprs_gmm_attach.c:113
GMM_ATTACH_REQ_FSM(gb_gmm_req)[0xaaaaf63e5c80]{CheckIdentity}: state_chg to
Authenticate
<0002> gprs_gmm_attach.c:148
GMM_ATTACH_REQ_FSM(gb_gmm_req)[0xaaaaf63e5c80]{Authenticate}: state_chg to
WaitAttachComplete
<0002> gprs_gmm.c:289 MM(460000323182742/cf0ebf06) <- GPRS ATTACH ACCEPT
(new P-TMSI=0xcf0ebf06)
<0002> gprs_gmm.c:305 MM(460000323182742/cf0ebf06) <- GPRS ATTACH ACCEPT
(ra_id=0x020xf20x50 lac:2f11 rac:2)
<000e> gprs_sgsn.c:1012 Checking for inactive LLMEs, time = 1652
<000f> gprs_ns.c:779 NSEI=1234 Timer expired in mode tns-test (30 seconds)
<000f> gprs_ns.c:712 NSEI=1234 Tx NS ALIVE (NSVCI=1234)
<000f> gprs_ns.c:751 NSEI=1234 Starting timer in mode tns-alive (3 seconds)
<000f> gprs_ns.c:725 NSEI=1234 Tx NS ALIVE_ACK (NSVCI=1234)
<000f> gprs_ns.c:1763 NSEI 1234 (NS-VCI=1234) setting state
[ALIVE,UNBLOCKED,UNRESET] -> [ALIVE,UNBLOCKED,UNRESET]
<000f> gprs_ns.c:751 NSEI=1234 Starting timer in mode tns-test (30 seconds)
<0010> gprs_bssgp.c:839 BSSGP BVCI=1234 Rx Flow Control BVC
<0002> fsm.c:322
GMM_ATTACH_REQ_FSM(gb_gmm_req)[0xaaaaf63e5c80]{WaitAttachComplete}: Timeout
of T3350
<0002> gprs_gmm.c:289 MM(460000323182742/cf0ebf06) <- GPRS ATTACH ACCEPT
(new P-TMSI=0xcf0ebf06)
<0002> gprs_gmm.c:305 MM(460000323182742/cf0ebf06) <- GPRS ATTACH ACCEPT
(ra_id=0x020xf20x50 lac:2f11 rac:2)
<0002> fsm.c:322
GMM_ATTACH_REQ_FSM(gb_gmm_req)[0xaaaaf63e5c80]{WaitAttachComplete}: Timeout
of T3350
<0002> gprs_gmm.c:289 MM(460000323182742/cf0ebf06) <- GPRS ATTACH ACCEPT
(new P-TMSI=0xcf0ebf06)
<0002> gprs_gmm.c:305 MM(460000323182742/cf0ebf06) <- GPRS ATTACH ACCEPT
(ra_id=0x020xf20x50 lac:2f11 rac:2)
<0010> gprs_bssgp.c:423 BSSGP TLLI=0xaf8ce1ff Rx UPLINK-UNITDATA
<0011> gprs_llc_parse.c:78 LLC SAPI=1 C U GEA0 IOV-UI=0x000000
FCS=0x0d0447 CMD=UI DATA
<0002> gprs_gb.c:40 MM_STATE_Gb(2945245695)[0xaaaaf63e5e50]{Idle}:
Received Event E_MM_PDU_RECEPTION
<0002> gprs_gmm.c:1118 MM(460000323182742/cf0ebf06) -> GMM ATTACH REQUEST
MI(4018987519) type="GPRS attach"
<0002> gprs_gmm.c:1100
GMM(gmm_fsm)[0xaaaaf63e5b50]{CommonProcedureInitiated}: Received Event
E_GMM_COMMON_PROC_INIT_REQ
<0002> gprs_gmm.c:1100
GMM(gmm_fsm)[0xaaaaf63e5b50]{CommonProcedureInitiated}: Event
E_GMM_COMMON_PROC_INIT_REQ not permitted
<0011> gprs_llc.c:1056 LLME(af8ce1ff/cf0ebf06){ASSIGNED} LLGM Assign pre
(af8ce1ff => cf0ebf06)
<0011> gprs_llc.c:1102 LLME(af8ce1ff/cf0ebf06){ASSIGNED} LLGM Assign post
(af8ce1ff => cf0ebf06)
<0002> gprs_gmm.c:1271
GMM_ATTACH_REQ_FSM(gb_gmm_req)[0xaaaaf63e5c80]{WaitAttachComplete}:
Received Event E_ATTACH_REQ_RECV
<0002> gprs_gmm_attach.c:360
GMM_ATTACH_REQ_FSM(gb_gmm_req)[0xaaaaf63e5c80]{WaitAttachComplete}:
state_chg to Init
<0002> gprs_gmm_attach.c:50
GMM_ATTACH_REQ_FSM(gb_gmm_req)[0xaaaaf63e5c80]{Init}: state_chg to
CheckIdentity
<0002> gprs_gmm.c:409 MM(460000323182742/cf0ebf06) <- GPRS IDENTITY
REQUEST: mi_type=IMEI
<0010> gprs_bssgp.c:839 BSSGP BVCI=1234 Rx Flow Control BVC
<0010> gprs_bssgp.c:423 BSSGP TLLI=0xaf8ce1ff Rx UPLINK-UNITDATA
<0011> gprs_llc_parse.c:78 LLC SAPI=1 C U GEA0 IOV-UI=0x000000
FCS=0xea5c4f CMD=UI DATA
<0002> gprs_gb.c:40 MM_STATE_Gb(2945245695)[0xaaaaf63e5e50]{Idle}:
Received Event E_MM_PDU_RECEPTION
<0002> gprs_gmm.c:1040 MM(460000323182742/cf0ebf06) -> GMM IDENTITY
RESPONSE: MI(IMEI)=866089038960590
<0002> gprs_gmm.c:113 MM(460000323182742/cf0ebf06) Stopping MM timer 3370
but 0 is running
<0002> gprs_gmm.c:1084
GMM_ATTACH_REQ_FSM(gb_gmm_req)[0xaaaaf63e5c80]{CheckIdentity}: Received
Event E_IDEN_RESP_RECV
<0002> gprs_gmm_attach.c:113
GMM_ATTACH_REQ_FSM(gb_gmm_req)[0xaaaaf63e5c80]{CheckIdentity}: state_chg to
Authenticate
<0002> gprs_gmm_attach.c:148
GMM_ATTACH_REQ_FSM(gb_gmm_req)[0xaaaaf63e5c80]{Authenticate}: state_chg to
WaitAttachComplete
<0002> gprs_gmm.c:289 MM(460000323182742/cf0ebf06) <- GPRS ATTACH ACCEPT
(new P-TMSI=0xcf0ebf06)
<0002> gprs_gmm.c:305 MM(460000323182742/cf0ebf06) <- GPRS ATTACH ACCEPT
(ra_id=0x020xf20x50 lac:2f11 rac:2)
<0002> fsm.c:322
GMM_ATTACH_REQ_FSM(gb_gmm_req)[0xaaaaf63e5c80]{WaitAttachComplete}: Timeout
of T3350
<0002> gprs_gmm.c:289 MM(460000323182742/cf0ebf06) <- GPRS ATTACH ACCEPT
(new P-TMSI=0xcf0ebf06)
<0002> gprs_gmm.c:305 MM(460000323182742/cf0ebf06) <- GPRS ATTACH ACCEPT
(ra_id=0x020xf20x50 lac:2f11 rac:2)
Configure information：
gprs mode egprs
gprs routing area 2
gprs cell bvci 1234
gprs nsei 1234
gprs nsvc 0 nsvci 1234
gprs nsvc 0 local udp port 23001
gprs nsvc 0 remote udp port 23000
。。。
timeslot 6
phys_chan_config PDCH
hopping enabled 0
timeslot 7
phys_chan_config PDCH
hopping enabled 0
pcu
flow-control-interval 10
cs 2
cs max 4
cs threshold 10 33
cs downgrade-threshold 200
cs link-quality-ranges cs1 6 cs2 5 8 cs3 7 13 cs4 12
mcs link-quality-ranges mcs1 6 mcs2 5 8 mcs3 7 13 mcs4 12 15 mcs5 14 17
mcs6 16 18 mcs7 17 20 mcs8 19 24 mcs9 23
mcs max 9
window-size 64 0
queue idle-ack-delay 10
queue codel
alloc-algorithm dynamic
alpha 0
gamma 0
dl-tbf-idle-time 2000
sgsn
gtp local-ip 127.0.0.1
ggsn 0 remote-ip 127.0.0.6
ggsn 0 gtp-version 1
auth-policy accept-all
ns
timer tns-block 3
timer tns-block-retries 3
timer tns-reset 3
timer tns-reset-retries 3
timer tns-test 30
timer tns-alive 3
timer tns-alive-retries 10
encapsulation udp local-ip 127.0.0.1
encapsulation udp local-port 23000
encapsulation framerelay-gre enabled 0
Version information:
OsmoPCU version 0.8.0
OsmoSGSN version 1.6.2
I tried to debug this issue but the no any progress for this issue.The
root cause is confifure or something else?
I need help.
Thanks a lot.
Br,
Perter
11 May
11 May
1 p.m.
New subject: 回复： osmo-pcu always "T3193 timeout expired, freeing TBF" when osmo-sgsn send GPRS ATTACH ACCEPT
Hi Pedrol,
One more additonal infor. The system is ubuntu 20.04 on raspberry 4b.
uname -a
Linux ubuntu 5.8.0-1021-raspi #24-Ubuntu SMP PREEMPT Tue Apr 13 11:00:57 UTC 2021 aarch64
aarch64 aarch64 GNU/Linux
Br,
Peter
------------------ 原始邮件 ------------------
发件人:
"Pau Espin Pedrol"
<pespin.shar(a)gmail.com&gt;om>;
发送时间: 2021年4月29日(星期四) 晚上11:27
收件人: "海鱼"<86731050@qq.com>;
抄送: "osmocom-net-gprs"<osmocom-net-gprs@lists.osmocom.org>;
主题: Re: osmo-pcu always "T3193 timeout expired, freeing TBF" when
osmo-sgsn send GPRS ATTACH ACCEPT
Hi,
can you please record and send a pcap file while trying to attach?
Make sure you are using osmo-bts-trx and osmo-pcu master (please provide output wyou get
with "--version").
Also make sure to enable GSMTAP in both osmo-pcu and osmo-bts-trx.
Also please enable "gsmtap log" with "logging level set-all info" for
osmo-pcu, so that everything end sup in the pcap file.
Regards,
Pau Espin Pedrol
Missatge de 海鱼 <86731050(a)qq.com&gt; del dia dc., 28 d’abr. 2021 a les 3:32:
Hi All,
Here is the issue when use egprs with osmo-bts-trx,osmo-pcu and osmo-sgsn.
osmo-pcu debugging info as below:
<000c> gprs_bssgp_pcu.cpp:168 LLC [SGSN -> PCU] = TLLI: 0xaf8ce1ff IMSI:
460000323182742 len: 26
<0008> tbf.cpp:1068 Allocating DL TBF: MS_CLASS=12/12
<0008> tbf.cpp:541 TBF(TFI=0 TLLI=0x00000000 DIR=DL STATE=NULL) Setting Control
TS 6
<0008> tbf.cpp:945 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=NULL) Allocated: trx =
0, ul_slots = 40, dl_slots = 40
<0008> bts.cpp:898 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=ASSIGN) TX: START
Immediate Assignment Downlink (PCH)
<0008> tbf_dl.cpp:520 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=ASSIGN) set ass.
type PACCH [prev CCCH:0, PACCH:0]
<0008> tbf.cpp:1270 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=ASSIGN) start Packet
Downlink Assignment (PACCH)
<0009> tbf.cpp:788 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=ASSIGN) Scheduled DL
Assignment polling on PACCH (FN=2402222, TS=6)
<0009> tbf_dl.cpp:880 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Scheduled
Ack/Nack polling on FN=2402270, TS=6
<0009> tbf_dl.cpp:880 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Scheduled
Ack/Nack polling on FN=2402322, TS=6
<0008> tbf.cpp:808 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) poll timeout for
FN=2402322, TS=6 (curr FN 2402387)
<0008> tbf.cpp:879 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Timeout for
polling PACKET DOWNLINK ACK.
<0008> tbf.cpp:1184 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Assignment was
on PACCH
<0008> tbf.cpp:1190 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Downlink ACK
was received
<0009> tbf_dl.cpp:880 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Scheduled
Ack/Nack polling on FN=2402426, TS=6
<0008> tbf.cpp:989 Allocating UL TBF: MS_CLASS=12/12
<0008> tbf.cpp:541 TBF(TFI=0 TLLI=0x00000000 DIR=UL STATE=NULL) Setting Control
TS 6
<0008> tbf.cpp:945 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=UL STATE=NULL) Allocated: trx =
0, ul_slots = 40, dl_slots = 00
<0008> tbf.cpp:1359 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=UL STATE=ASSIGN) start Packet
Uplink Assignment (PACCH)
<0009> tbf.cpp:782 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Scheduled UL
Assignment polling on PACCH (FN=2402478, TS=6)
<0007> gprs_rlcmac_meas.cpp:184 DL Bandwitdh of IMSI=460000323182742 /
TLLI=0xaf8ce1ff: 66 KBits/s
<0009> tbf_dl.cpp:880 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Scheduled
Ack/Nack polling on FN=2402525, TS=6
<000c> tbf_ul.cpp:404 LLC [PCU -> SGSN] TBF(TFI=0 TLLI=0xaf8ce1ff DIR=UL
STATE=FLOW) len=97
<000c> gprs_bssgp_pcu.cpp:168 LLC [SGSN -> PCU] = TLLI: 0xaf8ce1ff IMSI:
460000323182742 len: 9
<0008> tbf.cpp:808 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) poll timeout for
FN=2402525, TS=6 (curr FN 2402586)
<0008> tbf.cpp:879 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Timeout for
polling PACKET DOWNLINK ACK.
<0008> tbf.cpp:1184 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Assignment was
on PACCH
<0008> tbf.cpp:1190 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Downlink ACK
was received
<0009> tbf_dl.cpp:880 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Scheduled
Ack/Nack polling on FN=2402625, TS=6
<0007> gprs_rlcmac_meas.cpp:106 UL RSSI of TLLI=0xaf8ce1ff: -31 dBm
<0008> tbf.cpp:486 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=UL STATE=FINISHED) free
<0008> tbf.cpp:989 Allocating UL TBF: MS_CLASS=12/12
<0008> tbf.cpp:541 TBF(TFI=0 TLLI=0x00000000 DIR=UL STATE=NULL) Setting Control
TS 6
<0008> tbf.cpp:945 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=UL STATE=NULL) Allocated: trx =
0, ul_slots = 40, dl_slots = 00
<0008> tbf.cpp:1359 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=UL STATE=ASSIGN) start Packet
Uplink Assignment (PACCH)
<0009> tbf.cpp:782 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Scheduled UL
Assignment polling on PACCH (FN=2402673, TS=6)
<0009> tbf_dl.cpp:880 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Scheduled
Ack/Nack polling on FN=2402720, TS=6
<000c> tbf_ul.cpp:404 LLC [PCU -> SGSN] TBF(TFI=0 TLLI=0xaf8ce1ff DIR=UL
STATE=FLOW) len=17
<000c> gprs_bssgp_pcu.cpp:168 LLC [SGSN -> PCU] = TLLI: 0xaf8ce1ff IMSI:
460000323182742 len: 26
<0007> gprs_rlcmac_meas.cpp:184 DL Bandwitdh of IMSI=460000323182742 /
TLLI=0xaf8ce1ff: 86 KBits/s
<0009> tbf_dl.cpp:880 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Scheduled
Ack/Nack polling on FN=2402768, TS=6
<0007> gprs_rlcmac_meas.cpp:106 UL RSSI of TLLI=0xaf8ce1ff: -31 dBm
<0008> tbf.cpp:486 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=UL STATE=FINISHED) free
<0009> tbf_dl.cpp:880 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Scheduled
Ack/Nack polling on FN=2402816, TS=6
<0009> tbf_dl.cpp:880 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Scheduled
Ack/Nack polling on FN=2402863, TS=6
<0009> tbf_dl.cpp:880 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Scheduled
Ack/Nack polling on FN=2402911, TS=6
<0009> tbf_dl.cpp:880 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Scheduled
Ack/Nack polling on FN=2402959, TS=6
<0007> gprs_rlcmac_meas.cpp:184 DL Bandwitdh of IMSI=460000323182742 /
TLLI=0xaf8ce1ff: 240 KBits/s
<0009> tbf_dl.cpp:880 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Scheduled
Ack/Nack polling on FN=2403006, TS=6
<0009> tbf_dl.cpp:880 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Scheduled
Ack/Nack polling on FN=2403054, TS=6
<0009> tbf_dl.cpp:880 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Scheduled
Ack/Nack polling on FN=2403102, TS=6
<0009> tbf_dl.cpp:880 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Scheduled
Ack/Nack polling on FN=2403149, TS=6
<0009> tbf_dl.cpp:880 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FINISHED) Scheduled
Ack/Nack polling on FN=2403197, TS=6
<0008> tbf.cpp:650 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=WAIT RELEASE) T3193
timeout expired, freeing TBF
<0008> tbf.cpp:486 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=RELEASING) free
<000c> gprs_bssgp_pcu.cpp:168 LLC [SGSN -> PCU] = TLLI: 0xaf8ce1ff IMSI:
460000323182742 len: 26
<0008> tbf.cpp:1068 Allocating DL TBF: MS_CLASS=12/12
<0008> tbf.cpp:541 TBF(TFI=0 TLLI=0x00000000 DIR=DL STATE=NULL) Setting Control
TS 6
<0008> tbf.cpp:945 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=NULL) Allocated: trx =
0, ul_slots = 40, dl_slots = 40
<0008> bts.cpp:898 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=ASSIGN) TX: START
Immediate Assignment Downlink (PCH)
<0008> tbf_dl.cpp:520 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=ASSIGN) set ass.
type PACCH [prev CCCH:0, PACCH:0]
<0008> tbf.cpp:1270 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=ASSIGN) start Packet
Downlink Assignment (PACCH)
<0009> tbf.cpp:788 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=ASSIGN) Scheduled DL
Assignment polling on PACCH (FN=2404263, TS=6)
<0007> gprs_rlcmac_meas.cpp:184 DL Bandwitdh of IMSI=460000323182742 /
TLLI=0xaf8ce1ff: 22 KBits/s
<0009> tbf_dl.cpp:880 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Scheduled
Ack/Nack polling on FN=2404311, TS=6
<0009> tbf_dl.cpp:880 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Scheduled
Ack/Nack polling on FN=2404358, TS=6
<0009> tbf_dl.cpp:880 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Scheduled
Ack/Nack polling on FN=2404406, TS=6
<0009> tbf_dl.cpp:880 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Scheduled
Ack/Nack polling on FN=2404454, TS=6
<0008> tbf.cpp:808 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) poll timeout for
FN=2404454, TS=6 (curr FN 2404519)
<0008> tbf.cpp:879 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Timeout for
polling PACKET DOWNLINK ACK.
<0008> tbf.cpp:1184 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Assignment was
on PACCH
<0008> tbf.cpp:1190 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Downlink ACK
was received
<0009> tbf_dl.cpp:880 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Scheduled
Ack/Nack polling on FN=2404558, TS=6
<0007> gprs_rlcmac_meas.cpp:184 DL Bandwitdh of IMSI=460000323182742 /
TLLI=0xaf8ce1ff: 163 KBits/s
<0009> tbf_dl.cpp:880 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Scheduled
Ack/Nack polling on FN=2404605, TS=6
<0009> tbf_dl.cpp:880 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Scheduled
Ack/Nack polling on FN=2404653, TS=6
<0009> tbf_dl.cpp:880 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Scheduled
Ack/Nack polling on FN=2404701, TS=6
<0009> tbf_dl.cpp:880 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FINISHED) Scheduled
Ack/Nack polling on FN=2404748, TS=6
<0008> tbf.cpp:650 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=WAIT RELEASE) T3193
timeout expired, freeing TBF
<0008> tbf.cpp:486 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=RELEASING) free
<000c> gprs_bssgp_pcu.cpp:168 LLC [SGSN -> PCU] = TLLI: 0xaf8ce1ff IMSI:
460000323182742 len: 26
<0008> tbf.cpp:1068 Allocating DL TBF: MS_CLASS=12/12
<0008> tbf.cpp:541 TBF(TFI=0 TLLI=0x00000000 DIR=DL STATE=NULL) Setting Control
TS 6
<0008> tbf.cpp:945 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=NULL) Allocated: trx =
0, ul_slots = 40, dl_slots = 40
<0008> bts.cpp:898 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=ASSIGN) TX: START
Immediate Assignment Downlink (PCH)
<0008> tbf_dl.cpp:520 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=ASSIGN) set ass.
type PACCH [prev CCCH:0, PACCH:0]
<0008> tbf.cpp:1270 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=ASSIGN) start Packet
Downlink Assignment (PACCH)
<0009> tbf.cpp:788 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=ASSIGN) Scheduled DL
Assignment polling on PACCH (FN=2405537, TS=6)
<0007> gprs_rlcmac_meas.cpp:184 DL Bandwitdh of IMSI=460000323182742 /
TLLI=0xaf8ce1ff: 25 KBits/s
<0009> tbf_dl.cpp:880 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Scheduled
Ack/Nack polling on FN=2405585, TS=6
<0009> tbf_dl.cpp:880 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Scheduled
Ack/Nack polling on FN=2405632, TS=6
<0009> tbf_dl.cpp:880 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Scheduled
Ack/Nack polling on FN=2405680, TS=6
<0008> tbf.cpp:808 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) poll timeout for
FN=2405680, TS=6 (curr FN 2405741)
<0008> tbf.cpp:879 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Timeout for
polling PACKET DOWNLINK ACK.
osmo-sgsn debugging info:
<0011> gprs_llc_parse.c:78 LLC SAPI=1 C U GEA0
IOV-UI=0x000000 FCS=0xa3ad04 CMD=UI DATA
<0002> gprs_gmm.c:1118 MM(---/ffffffff) -> GMM ATTACH REQUEST
MI(4018987519) type="GPRS attach"
<0002> fsm.c:461 GMM(gmm_fsm)[0xaaaaf63e5b50]{Deregistered}: Allocated
<0002> fsm.c:461 GMM_ATTACH_REQ_FSM(gb_gmm_req)[0xaaaaf63e5c80]{Init}:
Allocated
<0002> fsm.c:461 MM_STATE_Gb[0xaaaaf63e5e50]{Idle}: Allocated
<0002> gprs_sgsn.c:299 MM(/00000000) Allocated with GEA0 cipher.
<0002> gprs_gmm.c:1100 GMM(gmm_fsm)[0xaaaaf63e5b50]{Deregistered}: Received
Event E_GMM_COMMON_PROC_INIT_REQ
<0002> gprs_gmm_fsm.c:25 GMM(gmm_fsm)[0xaaaaf63e5b50]{Deregistered}: state_chg
to CommonProcedureInitiated
<0011> gprs_llc.c:1056 LLME(ffffffff/af8ce1ff){UNASSIGNED} LLGM Assign pre
(af8ce1ff => cf0ebf06)
<0011> gprs_llc.c:1102 LLME(af8ce1ff/cf0ebf06){ASSIGNED} LLGM Assign post
(af8ce1ff => cf0ebf06)
<0002> gprs_gmm.c:1271 GMM_ATTACH_REQ_FSM(gb_gmm_req)[0xaaaaf63e5c80]{Init}:
Received Event E_ATTACH_REQ_RECV
<0002> gprs_gmm_attach.c:50
GMM_ATTACH_REQ_FSM(gb_gmm_req)[0xaaaaf63e5c80]{Init}: state_chg to CheckIdentity
<0002> gprs_gmm.c:409 MM(/cf0ebf06) <- GPRS IDENTITY REQUEST: mi_type=IMEI
<0010> gprs_bssgp.c:423 BSSGP TLLI=0xaf8ce1ff Rx UPLINK-UNITDATA
<0011> gprs_llc_parse.c:78 LLC SAPI=1 C U GEA0
IOV-UI=0x000000 FCS=0x8c64cd CMD=UI DATA
<0002> gprs_gb.c:40 MM_STATE_Gb(2945245695)[0xaaaaf63e5e50]{Idle}: Received
Event E_MM_PDU_RECEPTION
<0002> gprs_gmm.c:1040 MM(/cf0ebf06) -> GMM IDENTITY RESPONSE:
MI(IMEI)=866089038960590
<0002> gprs_gmm.c:113 MM(/cf0ebf06) Stopping MM timer 3370 but 0 is running
<0002> gprs_gmm.c:1084
GMM_ATTACH_REQ_FSM(gb_gmm_req)[0xaaaaf63e5c80]{CheckIdentity}: Received Event
E_IDEN_RESP_RECV
<0002> gprs_gmm_attach.c:111
GMM_ATTACH_REQ_FSM(gb_gmm_req)[0xaaaaf63e5c80]{CheckIdentity}: state_chg to
CheckIdentity
<0002> gprs_gmm.c:409 MM(/cf0ebf06) <- GPRS IDENTITY REQUEST: mi_type=IMSI
<0010> gprs_bssgp.c:423 BSSGP TLLI=0xaf8ce1ff Rx UPLINK-UNITDATA
<0011> gprs_llc_parse.c:78 LLC SAPI=1 C U GEA0
IOV-UI=0x000000 FCS=0xb71895 CMD=UI DATA
<0002> gprs_gb.c:40 MM_STATE_Gb(2945245695)[0xaaaaf63e5e50]{Idle}: Received
Event E_MM_PDU_RECEPTION
<0002> gprs_gmm.c:1040 MM(/cf0ebf06) -> GMM IDENTITY RESPONSE:
MI(IMSI)=460000323182742
<0002> gprs_gmm.c:113 MM(/cf0ebf06) Stopping MM timer 3370 but 0 is running
<0002> gprs_gmm.c:1084
GMM_ATTACH_REQ_FSM(gb_gmm_req)[0xaaaaf63e5c80]{CheckIdentity}: Received Event
E_IDEN_RESP_RECV
<0002> gprs_gmm_attach.c:113
GMM_ATTACH_REQ_FSM(gb_gmm_req)[0xaaaaf63e5c80]{CheckIdentity}: state_chg to Authenticate
<0002> gprs_gmm_attach.c:148
GMM_ATTACH_REQ_FSM(gb_gmm_req)[0xaaaaf63e5c80]{Authenticate}: state_chg to
WaitAttachComplete
<0002> gprs_gmm.c:289 MM(460000323182742/cf0ebf06) <- GPRS ATTACH ACCEPT (new
P-TMSI=0xcf0ebf06)
<0002> gprs_gmm.c:305 MM(460000323182742/cf0ebf06) <- GPRS ATTACH ACCEPT
(ra_id=0x020xf20x50 lac:2f11 rac:2)
<000e> gprs_sgsn.c:1012 Checking for inactive LLMEs, time = 1652
<000f> gprs_ns.c:779 NSEI=1234 Timer expired in mode tns-test (30 seconds)
<000f> gprs_ns.c:712 NSEI=1234 Tx NS ALIVE (NSVCI=1234)
<000f> gprs_ns.c:751 NSEI=1234 Starting timer in mode tns-alive (3 seconds)
<000f> gprs_ns.c:725 NSEI=1234 Tx NS ALIVE_ACK (NSVCI=1234)
<000f> gprs_ns.c:1763 NSEI 1234 (NS-VCI=1234) setting state
[ALIVE,UNBLOCKED,UNRESET] -> [ALIVE,UNBLOCKED,UNRESET]
<000f> gprs_ns.c:751 NSEI=1234 Starting timer in mode tns-test (30 seconds)
<0010> gprs_bssgp.c:839 BSSGP BVCI=1234 Rx Flow Control BVC
<0002> fsm.c:322
GMM_ATTACH_REQ_FSM(gb_gmm_req)[0xaaaaf63e5c80]{WaitAttachComplete}: Timeout of T3350
<0002> gprs_gmm.c:289 MM(460000323182742/cf0ebf06) <- GPRS ATTACH ACCEPT (new
P-TMSI=0xcf0ebf06)
<0002> gprs_gmm.c:305 MM(460000323182742/cf0ebf06) <- GPRS ATTACH ACCEPT
(ra_id=0x020xf20x50 lac:2f11 rac:2)
<0002> fsm.c:322
GMM_ATTACH_REQ_FSM(gb_gmm_req)[0xaaaaf63e5c80]{WaitAttachComplete}: Timeout of T3350
<0002> gprs_gmm.c:289 MM(460000323182742/cf0ebf06) <- GPRS ATTACH ACCEPT (new
P-TMSI=0xcf0ebf06)
<0002> gprs_gmm.c:305 MM(460000323182742/cf0ebf06) <- GPRS ATTACH ACCEPT
(ra_id=0x020xf20x50 lac:2f11 rac:2)
<0010> gprs_bssgp.c:423 BSSGP TLLI=0xaf8ce1ff Rx UPLINK-UNITDATA
<0011> gprs_llc_parse.c:78 LLC SAPI=1 C U GEA0
IOV-UI=0x000000 FCS=0x0d0447 CMD=UI DATA
<0002> gprs_gb.c:40 MM_STATE_Gb(2945245695)[0xaaaaf63e5e50]{Idle}: Received
Event E_MM_PDU_RECEPTION
<0002> gprs_gmm.c:1118 MM(460000323182742/cf0ebf06) -> GMM ATTACH REQUEST
MI(4018987519) type="GPRS attach"
<0002> gprs_gmm.c:1100 GMM(gmm_fsm)[0xaaaaf63e5b50]{CommonProcedureInitiated}:
Received Event E_GMM_COMMON_PROC_INIT_REQ
<0002> gprs_gmm.c:1100 GMM(gmm_fsm)[0xaaaaf63e5b50]{CommonProcedureInitiated}:
Event E_GMM_COMMON_PROC_INIT_REQ not permitted
<0011> gprs_llc.c:1056 LLME(af8ce1ff/cf0ebf06){ASSIGNED} LLGM Assign pre
(af8ce1ff => cf0ebf06)
<0011> gprs_llc.c:1102 LLME(af8ce1ff/cf0ebf06){ASSIGNED} LLGM Assign post
(af8ce1ff => cf0ebf06)
<0002> gprs_gmm.c:1271
GMM_ATTACH_REQ_FSM(gb_gmm_req)[0xaaaaf63e5c80]{WaitAttachComplete}: Received Event
E_ATTACH_REQ_RECV
<0002> gprs_gmm_attach.c:360
GMM_ATTACH_REQ_FSM(gb_gmm_req)[0xaaaaf63e5c80]{WaitAttachComplete}: state_chg to Init
<0002> gprs_gmm_attach.c:50
GMM_ATTACH_REQ_FSM(gb_gmm_req)[0xaaaaf63e5c80]{Init}: state_chg to CheckIdentity
<0002> gprs_gmm.c:409 MM(460000323182742/cf0ebf06) <- GPRS IDENTITY REQUEST:
mi_type=IMEI
<0010> gprs_bssgp.c:839 BSSGP BVCI=1234 Rx Flow Control BVC
<0010> gprs_bssgp.c:423 BSSGP TLLI=0xaf8ce1ff Rx UPLINK-UNITDATA
<0011> gprs_llc_parse.c:78 LLC SAPI=1 C U GEA0
IOV-UI=0x000000 FCS=0xea5c4f CMD=UI DATA
<0002> gprs_gb.c:40 MM_STATE_Gb(2945245695)[0xaaaaf63e5e50]{Idle}: Received
Event E_MM_PDU_RECEPTION
<0002> gprs_gmm.c:1040 MM(460000323182742/cf0ebf06) -> GMM IDENTITY
RESPONSE: MI(IMEI)=866089038960590
<0002> gprs_gmm.c:113 MM(460000323182742/cf0ebf06) Stopping MM timer 3370 but 0
is running
<0002> gprs_gmm.c:1084
GMM_ATTACH_REQ_FSM(gb_gmm_req)[0xaaaaf63e5c80]{CheckIdentity}: Received Event
E_IDEN_RESP_RECV
<0002> gprs_gmm_attach.c:113
GMM_ATTACH_REQ_FSM(gb_gmm_req)[0xaaaaf63e5c80]{CheckIdentity}: state_chg to Authenticate
<0002> gprs_gmm_attach.c:148
GMM_ATTACH_REQ_FSM(gb_gmm_req)[0xaaaaf63e5c80]{Authenticate}: state_chg to
WaitAttachComplete
<0002> gprs_gmm.c:289 MM(460000323182742/cf0ebf06) <- GPRS ATTACH ACCEPT (new
P-TMSI=0xcf0ebf06)
<0002> gprs_gmm.c:305 MM(460000323182742/cf0ebf06) <- GPRS ATTACH ACCEPT
(ra_id=0x020xf20x50 lac:2f11 rac:2)
<0002> fsm.c:322
GMM_ATTACH_REQ_FSM(gb_gmm_req)[0xaaaaf63e5c80]{WaitAttachComplete}: Timeout of T3350
<0002> gprs_gmm.c:289 MM(460000323182742/cf0ebf06) <- GPRS ATTACH ACCEPT (new
P-TMSI=0xcf0ebf06)
<0002> gprs_gmm.c:305 MM(460000323182742/cf0ebf06) <- GPRS ATTACH ACCEPT
(ra_id=0x020xf20x50 lac:2f11 rac:2)
Configure information：
gprs mode egprs
gprs routing area 2
gprs cell bvci 1234
gprs nsei 1234
gprs nsvc 0 nsvci 1234
gprs nsvc 0 local udp port 23001
gprs nsvc 0 remote udp port 23000
。。。
timeslot 6
phys_chan_config PDCH
hopping enabled 0
timeslot 7
phys_chan_config PDCH
hopping enabled 0
pcu
flow-control-interval 10
cs 2
cs max 4
cs threshold 10 33
cs downgrade-threshold 200
cs link-quality-ranges cs1 6 cs2 5 8 cs3 7 13 cs4 12
mcs link-quality-ranges mcs1 6 mcs2 5 8 mcs3 7 13 mcs4 12 15 mcs5 14 17 mcs6 16
18 mcs7 17 20 mcs8 19 24 mcs9 23
mcs max 9
window-size 64 0
queue idle-ack-delay 10
queue codel
alloc-algorithm dynamic
alpha 0
gamma 0
dl-tbf-idle-time 2000
sgsn
gtp local-ip 127.0.0.1
ggsn 0 remote-ip 127.0.0.6
ggsn 0 gtp-version 1
auth-policy accept-all
ns
timer tns-block 3
timer tns-block-retries 3
timer tns-reset 3
timer tns-reset-retries 3
timer tns-test 30
timer tns-alive 3
timer tns-alive-retries 10
encapsulation udp local-ip 127.0.0.1
encapsulation udp local-port 23000
encapsulation framerelay-gre enabled 0
Version information:
OsmoPCU version 0.8.0
OsmoSGSN version 1.6.2
I tried to debug this issue but the no any progress for this issue.The root cause is
confifure or something else?
I need help.
Thanks a lot.
Br,
Perter
12:54 p.m.
New subject: 回复： osmo-pcu always "T3193 timeout expired, freeing TBF" when osmo-sgsn send GPRS ATTACH ACCEPT
Hi Pedrol,
Sorry for answer late. I was in holiday these days.
Version info as below:
sudo ./osmo-pcu --version
OsmoPCU version 0.8.0
Copyright (C) 2012 by Ivan Kluchnikov <kluchnikovi(a)gmail.com&gt; and
Andreas Eversberg <jolly(a)eversberg.eu&gt;
License GNU GPL version 2 or later
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law.
sudo osmo-bts-trx --version
((*))
|
/ \ OsmoBTS
OsmoBTS version 1.2.2
Copyright (C) 2010, 2011 by Harald Welte, Andreas Eversberg and On-Waves
License AGPLv3+: GNU AGPL version 3 or later
<http://gnu.org/licenses/agpl-3.0.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law.
pcap file attached.
BTW:
I had a test for this issue.If modify gsm48_gmm_sendmsg(, 0, , true) to
gsm48_gmm_sendmsg(, 1, , false) in gsm48_tx_gmm_att_ack in the gprs_gmm.c. The attach
process can be successful.
Thanks a lot.
Peter
------------------ 原始邮件 ------------------
发件人:
"Pau Espin Pedrol"
<pespin.shar(a)gmail.com&gt;om>;
发送时间: 2021年4月29日(星期四) 晚上11:27
收件人: "海鱼"<86731050@qq.com>;
抄送: "osmocom-net-gprs"<osmocom-net-gprs@lists.osmocom.org>;
主题: Re: osmo-pcu always "T3193 timeout expired, freeing TBF" when
osmo-sgsn send GPRS ATTACH ACCEPT
Hi,
can you please record and send a pcap file while trying to attach?
Make sure you are using osmo-bts-trx and osmo-pcu master (please provide output wyou get
with "--version").
Also make sure to enable GSMTAP in both osmo-pcu and osmo-bts-trx.
Also please enable "gsmtap log" with "logging level set-all info" for
osmo-pcu, so that everything end sup in the pcap file.
Regards,
Pau Espin Pedrol
Missatge de 海鱼 <86731050(a)qq.com&gt; del dia dc., 28 d’abr. 2021 a les 3:32:
Hi All,
Here is the issue when use egprs with osmo-bts-trx,osmo-pcu and osmo-sgsn.
osmo-pcu debugging info as below:
<000c> gprs_bssgp_pcu.cpp:168 LLC [SGSN -> PCU] = TLLI: 0xaf8ce1ff IMSI:
460000323182742 len: 26
<0008> tbf.cpp:1068 Allocating DL TBF: MS_CLASS=12/12
<0008> tbf.cpp:541 TBF(TFI=0 TLLI=0x00000000 DIR=DL STATE=NULL) Setting Control
TS 6
<0008> tbf.cpp:945 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=NULL) Allocated: trx =
0, ul_slots = 40, dl_slots = 40
<0008> bts.cpp:898 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=ASSIGN) TX: START
Immediate Assignment Downlink (PCH)
<0008> tbf_dl.cpp:520 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=ASSIGN) set ass.
type PACCH [prev CCCH:0, PACCH:0]
<0008> tbf.cpp:1270 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=ASSIGN) start Packet
Downlink Assignment (PACCH)
<0009> tbf.cpp:788 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=ASSIGN) Scheduled DL
Assignment polling on PACCH (FN=2402222, TS=6)
<0009> tbf_dl.cpp:880 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Scheduled
Ack/Nack polling on FN=2402270, TS=6
<0009> tbf_dl.cpp:880 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Scheduled
Ack/Nack polling on FN=2402322, TS=6
<0008> tbf.cpp:808 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) poll timeout for
FN=2402322, TS=6 (curr FN 2402387)
<0008> tbf.cpp:879 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Timeout for
polling PACKET DOWNLINK ACK.
<0008> tbf.cpp:1184 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Assignment was
on PACCH
<0008> tbf.cpp:1190 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Downlink ACK
was received
<0009> tbf_dl.cpp:880 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Scheduled
Ack/Nack polling on FN=2402426, TS=6
<0008> tbf.cpp:989 Allocating UL TBF: MS_CLASS=12/12
<0008> tbf.cpp:541 TBF(TFI=0 TLLI=0x00000000 DIR=UL STATE=NULL) Setting Control
TS 6
<0008> tbf.cpp:945 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=UL STATE=NULL) Allocated: trx =
0, ul_slots = 40, dl_slots = 00
<0008> tbf.cpp:1359 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=UL STATE=ASSIGN) start Packet
Uplink Assignment (PACCH)
<0009> tbf.cpp:782 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Scheduled UL
Assignment polling on PACCH (FN=2402478, TS=6)
<0007> gprs_rlcmac_meas.cpp:184 DL Bandwitdh of IMSI=460000323182742 /
TLLI=0xaf8ce1ff: 66 KBits/s
<0009> tbf_dl.cpp:880 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Scheduled
Ack/Nack polling on FN=2402525, TS=6
<000c> tbf_ul.cpp:404 LLC [PCU -> SGSN] TBF(TFI=0 TLLI=0xaf8ce1ff DIR=UL
STATE=FLOW) len=97
<000c> gprs_bssgp_pcu.cpp:168 LLC [SGSN -> PCU] = TLLI: 0xaf8ce1ff IMSI:
460000323182742 len: 9
<0008> tbf.cpp:808 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) poll timeout for
FN=2402525, TS=6 (curr FN 2402586)
<0008> tbf.cpp:879 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Timeout for
polling PACKET DOWNLINK ACK.
<0008> tbf.cpp:1184 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Assignment was
on PACCH
<0008> tbf.cpp:1190 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Downlink ACK
was received
<0009> tbf_dl.cpp:880 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Scheduled
Ack/Nack polling on FN=2402625, TS=6
<0007> gprs_rlcmac_meas.cpp:106 UL RSSI of TLLI=0xaf8ce1ff: -31 dBm
<0008> tbf.cpp:486 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=UL STATE=FINISHED) free
<0008> tbf.cpp:989 Allocating UL TBF: MS_CLASS=12/12
<0008> tbf.cpp:541 TBF(TFI=0 TLLI=0x00000000 DIR=UL STATE=NULL) Setting Control
TS 6
<0008> tbf.cpp:945 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=UL STATE=NULL) Allocated: trx =
0, ul_slots = 40, dl_slots = 00
<0008> tbf.cpp:1359 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=UL STATE=ASSIGN) start Packet
Uplink Assignment (PACCH)
<0009> tbf.cpp:782 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Scheduled UL
Assignment polling on PACCH (FN=2402673, TS=6)
<0009> tbf_dl.cpp:880 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Scheduled
Ack/Nack polling on FN=2402720, TS=6
<000c> tbf_ul.cpp:404 LLC [PCU -> SGSN] TBF(TFI=0 TLLI=0xaf8ce1ff DIR=UL
STATE=FLOW) len=17
<000c> gprs_bssgp_pcu.cpp:168 LLC [SGSN -> PCU] = TLLI: 0xaf8ce1ff IMSI:
460000323182742 len: 26
<0007> gprs_rlcmac_meas.cpp:184 DL Bandwitdh of IMSI=460000323182742 /
TLLI=0xaf8ce1ff: 86 KBits/s
<0009> tbf_dl.cpp:880 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Scheduled
Ack/Nack polling on FN=2402768, TS=6
<0007> gprs_rlcmac_meas.cpp:106 UL RSSI of TLLI=0xaf8ce1ff: -31 dBm
<0008> tbf.cpp:486 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=UL STATE=FINISHED) free
<0009> tbf_dl.cpp:880 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Scheduled
Ack/Nack polling on FN=2402816, TS=6
<0009> tbf_dl.cpp:880 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Scheduled
Ack/Nack polling on FN=2402863, TS=6
<0009> tbf_dl.cpp:880 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Scheduled
Ack/Nack polling on FN=2402911, TS=6
<0009> tbf_dl.cpp:880 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Scheduled
Ack/Nack polling on FN=2402959, TS=6
<0007> gprs_rlcmac_meas.cpp:184 DL Bandwitdh of IMSI=460000323182742 /
TLLI=0xaf8ce1ff: 240 KBits/s
<0009> tbf_dl.cpp:880 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Scheduled
Ack/Nack polling on FN=2403006, TS=6
<0009> tbf_dl.cpp:880 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Scheduled
Ack/Nack polling on FN=2403054, TS=6
<0009> tbf_dl.cpp:880 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Scheduled
Ack/Nack polling on FN=2403102, TS=6
<0009> tbf_dl.cpp:880 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Scheduled
Ack/Nack polling on FN=2403149, TS=6
<0009> tbf_dl.cpp:880 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FINISHED) Scheduled
Ack/Nack polling on FN=2403197, TS=6
<0008> tbf.cpp:650 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=WAIT RELEASE) T3193
timeout expired, freeing TBF
<0008> tbf.cpp:486 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=RELEASING) free
<000c> gprs_bssgp_pcu.cpp:168 LLC [SGSN -> PCU] = TLLI: 0xaf8ce1ff IMSI:
460000323182742 len: 26
<0008> tbf.cpp:1068 Allocating DL TBF: MS_CLASS=12/12
<0008> tbf.cpp:541 TBF(TFI=0 TLLI=0x00000000 DIR=DL STATE=NULL) Setting Control
TS 6
<0008> tbf.cpp:945 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=NULL) Allocated: trx =
0, ul_slots = 40, dl_slots = 40
<0008> bts.cpp:898 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=ASSIGN) TX: START
Immediate Assignment Downlink (PCH)
<0008> tbf_dl.cpp:520 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=ASSIGN) set ass.
type PACCH [prev CCCH:0, PACCH:0]
<0008> tbf.cpp:1270 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=ASSIGN) start Packet
Downlink Assignment (PACCH)
<0009> tbf.cpp:788 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=ASSIGN) Scheduled DL
Assignment polling on PACCH (FN=2404263, TS=6)
<0007> gprs_rlcmac_meas.cpp:184 DL Bandwitdh of IMSI=460000323182742 /
TLLI=0xaf8ce1ff: 22 KBits/s
<0009> tbf_dl.cpp:880 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Scheduled
Ack/Nack polling on FN=2404311, TS=6
<0009> tbf_dl.cpp:880 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Scheduled
Ack/Nack polling on FN=2404358, TS=6
<0009> tbf_dl.cpp:880 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Scheduled
Ack/Nack polling on FN=2404406, TS=6
<0009> tbf_dl.cpp:880 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Scheduled
Ack/Nack polling on FN=2404454, TS=6
<0008> tbf.cpp:808 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) poll timeout for
FN=2404454, TS=6 (curr FN 2404519)
<0008> tbf.cpp:879 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Timeout for
polling PACKET DOWNLINK ACK.
<0008> tbf.cpp:1184 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Assignment was
on PACCH
<0008> tbf.cpp:1190 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Downlink ACK
was received
<0009> tbf_dl.cpp:880 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Scheduled
Ack/Nack polling on FN=2404558, TS=6
<0007> gprs_rlcmac_meas.cpp:184 DL Bandwitdh of IMSI=460000323182742 /
TLLI=0xaf8ce1ff: 163 KBits/s
<0009> tbf_dl.cpp:880 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Scheduled
Ack/Nack polling on FN=2404605, TS=6
<0009> tbf_dl.cpp:880 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Scheduled
Ack/Nack polling on FN=2404653, TS=6
<0009> tbf_dl.cpp:880 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Scheduled
Ack/Nack polling on FN=2404701, TS=6
<0009> tbf_dl.cpp:880 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FINISHED) Scheduled
Ack/Nack polling on FN=2404748, TS=6
<0008> tbf.cpp:650 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=WAIT RELEASE) T3193
timeout expired, freeing TBF
<0008> tbf.cpp:486 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=RELEASING) free
<000c> gprs_bssgp_pcu.cpp:168 LLC [SGSN -> PCU] = TLLI: 0xaf8ce1ff IMSI:
460000323182742 len: 26
<0008> tbf.cpp:1068 Allocating DL TBF: MS_CLASS=12/12
<0008> tbf.cpp:541 TBF(TFI=0 TLLI=0x00000000 DIR=DL STATE=NULL) Setting Control
TS 6
<0008> tbf.cpp:945 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=NULL) Allocated: trx =
0, ul_slots = 40, dl_slots = 40
<0008> bts.cpp:898 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=ASSIGN) TX: START
Immediate Assignment Downlink (PCH)
<0008> tbf_dl.cpp:520 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=ASSIGN) set ass.
type PACCH [prev CCCH:0, PACCH:0]
<0008> tbf.cpp:1270 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=ASSIGN) start Packet
Downlink Assignment (PACCH)
<0009> tbf.cpp:788 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=ASSIGN) Scheduled DL
Assignment polling on PACCH (FN=2405537, TS=6)
<0007> gprs_rlcmac_meas.cpp:184 DL Bandwitdh of IMSI=460000323182742 /
TLLI=0xaf8ce1ff: 25 KBits/s
<0009> tbf_dl.cpp:880 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Scheduled
Ack/Nack polling on FN=2405585, TS=6
<0009> tbf_dl.cpp:880 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Scheduled
Ack/Nack polling on FN=2405632, TS=6
<0009> tbf_dl.cpp:880 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Scheduled
Ack/Nack polling on FN=2405680, TS=6
<0008> tbf.cpp:808 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) poll timeout for
FN=2405680, TS=6 (curr FN 2405741)
<0008> tbf.cpp:879 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Timeout for
polling PACKET DOWNLINK ACK.
osmo-sgsn debugging info:
<0011> gprs_llc_parse.c:78 LLC SAPI=1 C U GEA0
IOV-UI=0x000000 FCS=0xa3ad04 CMD=UI DATA
<0002> gprs_gmm.c:1118 MM(---/ffffffff) -> GMM ATTACH REQUEST
MI(4018987519) type="GPRS attach"
<0002> fsm.c:461 GMM(gmm_fsm)[0xaaaaf63e5b50]{Deregistered}: Allocated
<0002> fsm.c:461 GMM_ATTACH_REQ_FSM(gb_gmm_req)[0xaaaaf63e5c80]{Init}:
Allocated
<0002> fsm.c:461 MM_STATE_Gb[0xaaaaf63e5e50]{Idle}: Allocated
<0002> gprs_sgsn.c:299 MM(/00000000) Allocated with GEA0 cipher.
<0002> gprs_gmm.c:1100 GMM(gmm_fsm)[0xaaaaf63e5b50]{Deregistered}: Received
Event E_GMM_COMMON_PROC_INIT_REQ
<0002> gprs_gmm_fsm.c:25 GMM(gmm_fsm)[0xaaaaf63e5b50]{Deregistered}: state_chg
to CommonProcedureInitiated
<0011> gprs_llc.c:1056 LLME(ffffffff/af8ce1ff){UNASSIGNED} LLGM Assign pre
(af8ce1ff => cf0ebf06)
<0011> gprs_llc.c:1102 LLME(af8ce1ff/cf0ebf06){ASSIGNED} LLGM Assign post
(af8ce1ff => cf0ebf06)
<0002> gprs_gmm.c:1271 GMM_ATTACH_REQ_FSM(gb_gmm_req)[0xaaaaf63e5c80]{Init}:
Received Event E_ATTACH_REQ_RECV
<0002> gprs_gmm_attach.c:50
GMM_ATTACH_REQ_FSM(gb_gmm_req)[0xaaaaf63e5c80]{Init}: state_chg to CheckIdentity
<0002> gprs_gmm.c:409 MM(/cf0ebf06) <- GPRS IDENTITY REQUEST: mi_type=IMEI
<0010> gprs_bssgp.c:423 BSSGP TLLI=0xaf8ce1ff Rx UPLINK-UNITDATA
<0011> gprs_llc_parse.c:78 LLC SAPI=1 C U GEA0
IOV-UI=0x000000 FCS=0x8c64cd CMD=UI DATA
<0002> gprs_gb.c:40 MM_STATE_Gb(2945245695)[0xaaaaf63e5e50]{Idle}: Received
Event E_MM_PDU_RECEPTION
<0002> gprs_gmm.c:1040 MM(/cf0ebf06) -> GMM IDENTITY RESPONSE:
MI(IMEI)=866089038960590
<0002> gprs_gmm.c:113 MM(/cf0ebf06) Stopping MM timer 3370 but 0 is running
<0002> gprs_gmm.c:1084
GMM_ATTACH_REQ_FSM(gb_gmm_req)[0xaaaaf63e5c80]{CheckIdentity}: Received Event
E_IDEN_RESP_RECV
<0002> gprs_gmm_attach.c:111
GMM_ATTACH_REQ_FSM(gb_gmm_req)[0xaaaaf63e5c80]{CheckIdentity}: state_chg to
CheckIdentity
<0002> gprs_gmm.c:409 MM(/cf0ebf06) <- GPRS IDENTITY REQUEST: mi_type=IMSI
<0010> gprs_bssgp.c:423 BSSGP TLLI=0xaf8ce1ff Rx UPLINK-UNITDATA
<0011> gprs_llc_parse.c:78 LLC SAPI=1 C U GEA0
IOV-UI=0x000000 FCS=0xb71895 CMD=UI DATA
<0002> gprs_gb.c:40 MM_STATE_Gb(2945245695)[0xaaaaf63e5e50]{Idle}: Received
Event E_MM_PDU_RECEPTION
<0002> gprs_gmm.c:1040 MM(/cf0ebf06) -> GMM IDENTITY RESPONSE:
MI(IMSI)=460000323182742
<0002> gprs_gmm.c:113 MM(/cf0ebf06) Stopping MM timer 3370 but 0 is running
<0002> gprs_gmm.c:1084
GMM_ATTACH_REQ_FSM(gb_gmm_req)[0xaaaaf63e5c80]{CheckIdentity}: Received Event
E_IDEN_RESP_RECV
<0002> gprs_gmm_attach.c:113
GMM_ATTACH_REQ_FSM(gb_gmm_req)[0xaaaaf63e5c80]{CheckIdentity}: state_chg to Authenticate
<0002> gprs_gmm_attach.c:148
GMM_ATTACH_REQ_FSM(gb_gmm_req)[0xaaaaf63e5c80]{Authenticate}: state_chg to
WaitAttachComplete
<0002> gprs_gmm.c:289 MM(460000323182742/cf0ebf06) <- GPRS ATTACH ACCEPT (new
P-TMSI=0xcf0ebf06)
<0002> gprs_gmm.c:305 MM(460000323182742/cf0ebf06) <- GPRS ATTACH ACCEPT
(ra_id=0x020xf20x50 lac:2f11 rac:2)
<000e> gprs_sgsn.c:1012 Checking for inactive LLMEs, time = 1652
<000f> gprs_ns.c:779 NSEI=1234 Timer expired in mode tns-test (30 seconds)
<000f> gprs_ns.c:712 NSEI=1234 Tx NS ALIVE (NSVCI=1234)
<000f> gprs_ns.c:751 NSEI=1234 Starting timer in mode tns-alive (3 seconds)
<000f> gprs_ns.c:725 NSEI=1234 Tx NS ALIVE_ACK (NSVCI=1234)
<000f> gprs_ns.c:1763 NSEI 1234 (NS-VCI=1234) setting state
[ALIVE,UNBLOCKED,UNRESET] -> [ALIVE,UNBLOCKED,UNRESET]
<000f> gprs_ns.c:751 NSEI=1234 Starting timer in mode tns-test (30 seconds)
<0010> gprs_bssgp.c:839 BSSGP BVCI=1234 Rx Flow Control BVC
<0002> fsm.c:322
GMM_ATTACH_REQ_FSM(gb_gmm_req)[0xaaaaf63e5c80]{WaitAttachComplete}: Timeout of T3350
<0002> gprs_gmm.c:289 MM(460000323182742/cf0ebf06) <- GPRS ATTACH ACCEPT (new
P-TMSI=0xcf0ebf06)
<0002> gprs_gmm.c:305 MM(460000323182742/cf0ebf06) <- GPRS ATTACH ACCEPT
(ra_id=0x020xf20x50 lac:2f11 rac:2)
<0002> fsm.c:322
GMM_ATTACH_REQ_FSM(gb_gmm_req)[0xaaaaf63e5c80]{WaitAttachComplete}: Timeout of T3350
<0002> gprs_gmm.c:289 MM(460000323182742/cf0ebf06) <- GPRS ATTACH ACCEPT (new
P-TMSI=0xcf0ebf06)
<0002> gprs_gmm.c:305 MM(460000323182742/cf0ebf06) <- GPRS ATTACH ACCEPT
(ra_id=0x020xf20x50 lac:2f11 rac:2)
<0010> gprs_bssgp.c:423 BSSGP TLLI=0xaf8ce1ff Rx UPLINK-UNITDATA
<0011> gprs_llc_parse.c:78 LLC SAPI=1 C U GEA0
IOV-UI=0x000000 FCS=0x0d0447 CMD=UI DATA
<0002> gprs_gb.c:40 MM_STATE_Gb(2945245695)[0xaaaaf63e5e50]{Idle}: Received
Event E_MM_PDU_RECEPTION
<0002> gprs_gmm.c:1118 MM(460000323182742/cf0ebf06) -> GMM ATTACH REQUEST
MI(4018987519) type="GPRS attach"
<0002> gprs_gmm.c:1100 GMM(gmm_fsm)[0xaaaaf63e5b50]{CommonProcedureInitiated}:
Received Event E_GMM_COMMON_PROC_INIT_REQ
<0002> gprs_gmm.c:1100 GMM(gmm_fsm)[0xaaaaf63e5b50]{CommonProcedureInitiated}:
Event E_GMM_COMMON_PROC_INIT_REQ not permitted
<0011> gprs_llc.c:1056 LLME(af8ce1ff/cf0ebf06){ASSIGNED} LLGM Assign pre
(af8ce1ff => cf0ebf06)
<0011> gprs_llc.c:1102 LLME(af8ce1ff/cf0ebf06){ASSIGNED} LLGM Assign post
(af8ce1ff => cf0ebf06)
<0002> gprs_gmm.c:1271
GMM_ATTACH_REQ_FSM(gb_gmm_req)[0xaaaaf63e5c80]{WaitAttachComplete}: Received Event
E_ATTACH_REQ_RECV
<0002> gprs_gmm_attach.c:360
GMM_ATTACH_REQ_FSM(gb_gmm_req)[0xaaaaf63e5c80]{WaitAttachComplete}: state_chg to Init
<0002> gprs_gmm_attach.c:50
GMM_ATTACH_REQ_FSM(gb_gmm_req)[0xaaaaf63e5c80]{Init}: state_chg to CheckIdentity
<0002> gprs_gmm.c:409 MM(460000323182742/cf0ebf06) <- GPRS IDENTITY REQUEST:
mi_type=IMEI
<0010> gprs_bssgp.c:839 BSSGP BVCI=1234 Rx Flow Control BVC
<0010> gprs_bssgp.c:423 BSSGP TLLI=0xaf8ce1ff Rx UPLINK-UNITDATA
<0011> gprs_llc_parse.c:78 LLC SAPI=1 C U GEA0
IOV-UI=0x000000 FCS=0xea5c4f CMD=UI DATA
<0002> gprs_gb.c:40 MM_STATE_Gb(2945245695)[0xaaaaf63e5e50]{Idle}: Received
Event E_MM_PDU_RECEPTION
<0002> gprs_gmm.c:1040 MM(460000323182742/cf0ebf06) -> GMM IDENTITY
RESPONSE: MI(IMEI)=866089038960590
<0002> gprs_gmm.c:113 MM(460000323182742/cf0ebf06) Stopping MM timer 3370 but 0
is running
<0002> gprs_gmm.c:1084
GMM_ATTACH_REQ_FSM(gb_gmm_req)[0xaaaaf63e5c80]{CheckIdentity}: Received Event
E_IDEN_RESP_RECV
<0002> gprs_gmm_attach.c:113
GMM_ATTACH_REQ_FSM(gb_gmm_req)[0xaaaaf63e5c80]{CheckIdentity}: state_chg to Authenticate
<0002> gprs_gmm_attach.c:148
GMM_ATTACH_REQ_FSM(gb_gmm_req)[0xaaaaf63e5c80]{Authenticate}: state_chg to
WaitAttachComplete
<0002> gprs_gmm.c:289 MM(460000323182742/cf0ebf06) <- GPRS ATTACH ACCEPT (new
P-TMSI=0xcf0ebf06)
<0002> gprs_gmm.c:305 MM(460000323182742/cf0ebf06) <- GPRS ATTACH ACCEPT
(ra_id=0x020xf20x50 lac:2f11 rac:2)
<0002> fsm.c:322
GMM_ATTACH_REQ_FSM(gb_gmm_req)[0xaaaaf63e5c80]{WaitAttachComplete}: Timeout of T3350
<0002> gprs_gmm.c:289 MM(460000323182742/cf0ebf06) <- GPRS ATTACH ACCEPT (new
P-TMSI=0xcf0ebf06)
<0002> gprs_gmm.c:305 MM(460000323182742/cf0ebf06) <- GPRS ATTACH ACCEPT
(ra_id=0x020xf20x50 lac:2f11 rac:2)
Configure information：
gprs mode egprs
gprs routing area 2
gprs cell bvci 1234
gprs nsei 1234
gprs nsvc 0 nsvci 1234
gprs nsvc 0 local udp port 23001
gprs nsvc 0 remote udp port 23000
。。。
timeslot 6
phys_chan_config PDCH
hopping enabled 0
timeslot 7
phys_chan_config PDCH
hopping enabled 0
pcu
flow-control-interval 10
cs 2
cs max 4
cs threshold 10 33
cs downgrade-threshold 200
cs link-quality-ranges cs1 6 cs2 5 8 cs3 7 13 cs4 12
mcs link-quality-ranges mcs1 6 mcs2 5 8 mcs3 7 13 mcs4 12 15 mcs5 14 17 mcs6 16
18 mcs7 17 20 mcs8 19 24 mcs9 23
mcs max 9
window-size 64 0
queue idle-ack-delay 10
queue codel
alloc-algorithm dynamic
alpha 0
gamma 0
dl-tbf-idle-time 2000
sgsn
gtp local-ip 127.0.0.1
ggsn 0 remote-ip 127.0.0.6
ggsn 0 gtp-version 1
auth-policy accept-all
ns
timer tns-block 3
timer tns-block-retries 3
timer tns-reset 3
timer tns-reset-retries 3
timer tns-test 30
timer tns-alive 3
timer tns-alive-retries 10
encapsulation udp local-ip 127.0.0.1
encapsulation udp local-port 23000
encapsulation framerelay-gre enabled 0
Version information:
OsmoPCU version 0.8.0
OsmoSGSN version 1.6.2
I tried to debug this issue but the no any progress for this issue.The root cause is
confifure or something else?
I need help.
Thanks a lot.
Br,
Perter
6:54 p.m.
New subject: 回复： osmo-pcu always "T3193 timeout expired, freeing TBF" when osmo-sgsn send GPRS ATTACH ACCEPT
Hi,
I would say the RLCMAC side looks fine. It looks like the SGSN is
rejecting the ATTACH REQUEST. You may have a misconfiguration in the
encryption config of osmo-sgsn?
Unfortuantely, your pcap doesn't contain the contents of the Gb
interface ("gprs-ns" filter in wireshark), so it's difficult to say
what's going on.
Please share a pcap containing gprs-ns (PCU<->SGSN) and gtp
(SGSN<->GGSN) packets in order to find out what's going on. Share also a
log file of osmo-sgsn (or use gsmtap log) with debug enabled to find out
why is the SGSN rejecting it.
Regards,
Pau
--
- Pau Espin Pedrol <pespin(a)sysmocom.de> http://www.sysmocom.de/
=======================================================================
* sysmocom - systems for mobile communications GmbH
* Alt-Moabit 93
* 10559 Berlin, Germany
* Sitz / Registered office: Berlin, HRB 134158 B
* Geschaeftsfuehrer / Managing Director: Harald Welte
1:12 p.m.
New subject: 回复： osmo-pcu always "T3193 timeout expired, freeing TBF" when osmo-sgsn send GPRS ATTACH ACCEPT
Hi Pedrol,
Sorry for answer late. I was in holiday these days.
Version info as below:
sudo ./osmo-pcu --version
OsmoPCU version 0.8.0
Copyright (C) 2012 by Ivan Kluchnikov <kluchnikovi(a)gmail.com&gt; and
Andreas Eversberg <jolly(a)eversberg.eu&gt;
License GNU GPL version 2 or later
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law.
sudo osmo-bts-trx --version
((*))
|
/ \ OsmoBTS
OsmoBTS version 1.2.2
Copyright (C) 2010, 2011 by Harald Welte, Andreas Eversberg and On-Waves
License AGPLv3+: GNU AGPL version 3 or later
<http://gnu.org/licenses/agpl-3.0.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law.
pcap file attached.
BTW:
I had a test for this issue.If modify gsm48_gmm_sendmsg(, 0, , true) to
gsm48_gmm_sendmsg(, 1, , false) in gsm48_tx_gmm_att_ack in the gprs_gmm.c. The attach
process can be successful.
Thanks a lot.
Peter
------------------ 原始邮件 ------------------
发件人:
"Pau Espin Pedrol"
<pespin.shar(a)gmail.com&gt;om>;
发送时间: 2021年4月29日(星期四) 晚上11:27
收件人: "海鱼"<86731050@qq.com>;
抄送: "osmocom-net-gprs"<osmocom-net-gprs@lists.osmocom.org>;
主题: Re: osmo-pcu always "T3193 timeout expired, freeing TBF" when
osmo-sgsn send GPRS ATTACH ACCEPT
Hi,
can you please record and send a pcap file while trying to attach?
Make sure you are using osmo-bts-trx and osmo-pcu master (please provide output wyou get
with "--version").
Also make sure to enable GSMTAP in both osmo-pcu and osmo-bts-trx.
Also please enable "gsmtap log" with "logging level set-all info" for
osmo-pcu, so that everything end sup in the pcap file.
Regards,
Pau Espin Pedrol
Missatge de 海鱼 <86731050(a)qq.com&gt; del dia dc., 28 d’abr. 2021 a les 3:32:
Hi All,
Here is the issue when use egprs with osmo-bts-trx,osmo-pcu and osmo-sgsn.
osmo-pcu debugging info as below:
<000c> gprs_bssgp_pcu.cpp:168 LLC [SGSN -> PCU] = TLLI: 0xaf8ce1ff IMSI:
460000323182742 len: 26
<0008> tbf.cpp:1068 Allocating DL TBF: MS_CLASS=12/12
<0008> tbf.cpp:541 TBF(TFI=0 TLLI=0x00000000 DIR=DL STATE=NULL) Setting Control
TS 6
<0008> tbf.cpp:945 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=NULL) Allocated: trx =
0, ul_slots = 40, dl_slots = 40
<0008> bts.cpp:898 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=ASSIGN) TX: START
Immediate Assignment Downlink (PCH)
<0008> tbf_dl.cpp:520 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=ASSIGN) set ass.
type PACCH [prev CCCH:0, PACCH:0]
<0008> tbf.cpp:1270 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=ASSIGN) start Packet
Downlink Assignment (PACCH)
<0009> tbf.cpp:788 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=ASSIGN) Scheduled DL
Assignment polling on PACCH (FN=2402222, TS=6)
<0009> tbf_dl.cpp:880 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Scheduled
Ack/Nack polling on FN=2402270, TS=6
<0009> tbf_dl.cpp:880 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Scheduled
Ack/Nack polling on FN=2402322, TS=6
<0008> tbf.cpp:808 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) poll timeout for
FN=2402322, TS=6 (curr FN 2402387)
<0008> tbf.cpp:879 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Timeout for
polling PACKET DOWNLINK ACK.
<0008> tbf.cpp:1184 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Assignment was
on PACCH
<0008> tbf.cpp:1190 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Downlink ACK
was received
<0009> tbf_dl.cpp:880 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Scheduled
Ack/Nack polling on FN=2402426, TS=6
<0008> tbf.cpp:989 Allocating UL TBF: MS_CLASS=12/12
<0008> tbf.cpp:541 TBF(TFI=0 TLLI=0x00000000 DIR=UL STATE=NULL) Setting Control
TS 6
<0008> tbf.cpp:945 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=UL STATE=NULL) Allocated: trx =
0, ul_slots = 40, dl_slots = 00
<0008> tbf.cpp:1359 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=UL STATE=ASSIGN) start Packet
Uplink Assignment (PACCH)
<0009> tbf.cpp:782 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Scheduled UL
Assignment polling on PACCH (FN=2402478, TS=6)
<0007> gprs_rlcmac_meas.cpp:184 DL Bandwitdh of IMSI=460000323182742 /
TLLI=0xaf8ce1ff: 66 KBits/s
<0009> tbf_dl.cpp:880 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Scheduled
Ack/Nack polling on FN=2402525, TS=6
<000c> tbf_ul.cpp:404 LLC [PCU -> SGSN] TBF(TFI=0 TLLI=0xaf8ce1ff DIR=UL
STATE=FLOW) len=97
<000c> gprs_bssgp_pcu.cpp:168 LLC [SGSN -> PCU] = TLLI: 0xaf8ce1ff IMSI:
460000323182742 len: 9
<0008> tbf.cpp:808 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) poll timeout for
FN=2402525, TS=6 (curr FN 2402586)
<0008> tbf.cpp:879 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Timeout for
polling PACKET DOWNLINK ACK.
<0008> tbf.cpp:1184 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Assignment was
on PACCH
<0008> tbf.cpp:1190 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Downlink ACK
was received
<0009> tbf_dl.cpp:880 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Scheduled
Ack/Nack polling on FN=2402625, TS=6
<0007> gprs_rlcmac_meas.cpp:106 UL RSSI of TLLI=0xaf8ce1ff: -31 dBm
<0008> tbf.cpp:486 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=UL STATE=FINISHED) free
<0008> tbf.cpp:989 Allocating UL TBF: MS_CLASS=12/12
<0008> tbf.cpp:541 TBF(TFI=0 TLLI=0x00000000 DIR=UL STATE=NULL) Setting Control
TS 6
<0008> tbf.cpp:945 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=UL STATE=NULL) Allocated: trx =
0, ul_slots = 40, dl_slots = 00
<0008> tbf.cpp:1359 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=UL STATE=ASSIGN) start Packet
Uplink Assignment (PACCH)
<0009> tbf.cpp:782 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Scheduled UL
Assignment polling on PACCH (FN=2402673, TS=6)
<0009> tbf_dl.cpp:880 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Scheduled
Ack/Nack polling on FN=2402720, TS=6
<000c> tbf_ul.cpp:404 LLC [PCU -> SGSN] TBF(TFI=0 TLLI=0xaf8ce1ff DIR=UL
STATE=FLOW) len=17
<000c> gprs_bssgp_pcu.cpp:168 LLC [SGSN -> PCU] = TLLI: 0xaf8ce1ff IMSI:
460000323182742 len: 26
<0007> gprs_rlcmac_meas.cpp:184 DL Bandwitdh of IMSI=460000323182742 /
TLLI=0xaf8ce1ff: 86 KBits/s
<0009> tbf_dl.cpp:880 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Scheduled
Ack/Nack polling on FN=2402768, TS=6
<0007> gprs_rlcmac_meas.cpp:106 UL RSSI of TLLI=0xaf8ce1ff: -31 dBm
<0008> tbf.cpp:486 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=UL STATE=FINISHED) free
<0009> tbf_dl.cpp:880 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Scheduled
Ack/Nack polling on FN=2402816, TS=6
<0009> tbf_dl.cpp:880 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Scheduled
Ack/Nack polling on FN=2402863, TS=6
<0009> tbf_dl.cpp:880 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Scheduled
Ack/Nack polling on FN=2402911, TS=6
<0009> tbf_dl.cpp:880 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Scheduled
Ack/Nack polling on FN=2402959, TS=6
<0007> gprs_rlcmac_meas.cpp:184 DL Bandwitdh of IMSI=460000323182742 /
TLLI=0xaf8ce1ff: 240 KBits/s
<0009> tbf_dl.cpp:880 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Scheduled
Ack/Nack polling on FN=2403006, TS=6
<0009> tbf_dl.cpp:880 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Scheduled
Ack/Nack polling on FN=2403054, TS=6
<0009> tbf_dl.cpp:880 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Scheduled
Ack/Nack polling on FN=2403102, TS=6
<0009> tbf_dl.cpp:880 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Scheduled
Ack/Nack polling on FN=2403149, TS=6
<0009> tbf_dl.cpp:880 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FINISHED) Scheduled
Ack/Nack polling on FN=2403197, TS=6
<0008> tbf.cpp:650 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=WAIT RELEASE) T3193
timeout expired, freeing TBF
<0008> tbf.cpp:486 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=RELEASING) free
<000c> gprs_bssgp_pcu.cpp:168 LLC [SGSN -> PCU] = TLLI: 0xaf8ce1ff IMSI:
460000323182742 len: 26
<0008> tbf.cpp:1068 Allocating DL TBF: MS_CLASS=12/12
<0008> tbf.cpp:541 TBF(TFI=0 TLLI=0x00000000 DIR=DL STATE=NULL) Setting Control
TS 6
<0008> tbf.cpp:945 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=NULL) Allocated: trx =
0, ul_slots = 40, dl_slots = 40
<0008> bts.cpp:898 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=ASSIGN) TX: START
Immediate Assignment Downlink (PCH)
<0008> tbf_dl.cpp:520 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=ASSIGN) set ass.
type PACCH [prev CCCH:0, PACCH:0]
<0008> tbf.cpp:1270 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=ASSIGN) start Packet
Downlink Assignment (PACCH)
<0009> tbf.cpp:788 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=ASSIGN) Scheduled DL
Assignment polling on PACCH (FN=2404263, TS=6)
<0007> gprs_rlcmac_meas.cpp:184 DL Bandwitdh of IMSI=460000323182742 /
TLLI=0xaf8ce1ff: 22 KBits/s
<0009> tbf_dl.cpp:880 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Scheduled
Ack/Nack polling on FN=2404311, TS=6
<0009> tbf_dl.cpp:880 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Scheduled
Ack/Nack polling on FN=2404358, TS=6
<0009> tbf_dl.cpp:880 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Scheduled
Ack/Nack polling on FN=2404406, TS=6
<0009> tbf_dl.cpp:880 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Scheduled
Ack/Nack polling on FN=2404454, TS=6
<0008> tbf.cpp:808 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) poll timeout for
FN=2404454, TS=6 (curr FN 2404519)
<0008> tbf.cpp:879 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Timeout for
polling PACKET DOWNLINK ACK.
<0008> tbf.cpp:1184 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Assignment was
on PACCH
<0008> tbf.cpp:1190 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Downlink ACK
was received
<0009> tbf_dl.cpp:880 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Scheduled
Ack/Nack polling on FN=2404558, TS=6
<0007> gprs_rlcmac_meas.cpp:184 DL Bandwitdh of IMSI=460000323182742 /
TLLI=0xaf8ce1ff: 163 KBits/s
<0009> tbf_dl.cpp:880 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Scheduled
Ack/Nack polling on FN=2404605, TS=6
<0009> tbf_dl.cpp:880 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Scheduled
Ack/Nack polling on FN=2404653, TS=6
<0009> tbf_dl.cpp:880 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Scheduled
Ack/Nack polling on FN=2404701, TS=6
<0009> tbf_dl.cpp:880 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FINISHED) Scheduled
Ack/Nack polling on FN=2404748, TS=6
<0008> tbf.cpp:650 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=WAIT RELEASE) T3193
timeout expired, freeing TBF
<0008> tbf.cpp:486 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=RELEASING) free
<000c> gprs_bssgp_pcu.cpp:168 LLC [SGSN -> PCU] = TLLI: 0xaf8ce1ff IMSI:
460000323182742 len: 26
<0008> tbf.cpp:1068 Allocating DL TBF: MS_CLASS=12/12
<0008> tbf.cpp:541 TBF(TFI=0 TLLI=0x00000000 DIR=DL STATE=NULL) Setting Control
TS 6
<0008> tbf.cpp:945 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=NULL) Allocated: trx =
0, ul_slots = 40, dl_slots = 40
<0008> bts.cpp:898 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=ASSIGN) TX: START
Immediate Assignment Downlink (PCH)
<0008> tbf_dl.cpp:520 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=ASSIGN) set ass.
type PACCH [prev CCCH:0, PACCH:0]
<0008> tbf.cpp:1270 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=ASSIGN) start Packet
Downlink Assignment (PACCH)
<0009> tbf.cpp:788 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=ASSIGN) Scheduled DL
Assignment polling on PACCH (FN=2405537, TS=6)
<0007> gprs_rlcmac_meas.cpp:184 DL Bandwitdh of IMSI=460000323182742 /
TLLI=0xaf8ce1ff: 25 KBits/s
<0009> tbf_dl.cpp:880 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Scheduled
Ack/Nack polling on FN=2405585, TS=6
<0009> tbf_dl.cpp:880 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Scheduled
Ack/Nack polling on FN=2405632, TS=6
<0009> tbf_dl.cpp:880 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Scheduled
Ack/Nack polling on FN=2405680, TS=6
<0008> tbf.cpp:808 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) poll timeout for
FN=2405680, TS=6 (curr FN 2405741)
<0008> tbf.cpp:879 TBF(TFI=0 TLLI=0xaf8ce1ff DIR=DL STATE=FLOW) Timeout for
polling PACKET DOWNLINK ACK.
osmo-sgsn debugging info:
<0011> gprs_llc_parse.c:78 LLC SAPI=1 C U GEA0 IOV-UI=0x000000
FCS=0xa3ad04 CMD=UI DATA
<0002> gprs_gmm.c:1118 MM(---/ffffffff) -> GMM ATTACH REQUEST
MI(4018987519) type="GPRS attach"
<0002> fsm.c:461 GMM(gmm_fsm)[0xaaaaf63e5b50]{Deregistered}: Allocated
<0002> fsm.c:461 GMM_ATTACH_REQ_FSM(gb_gmm_req)[0xaaaaf63e5c80]{Init}:
Allocated
<0002> fsm.c:461 MM_STATE_Gb[0xaaaaf63e5e50]{Idle}: Allocated
<0002> gprs_sgsn.c:299 MM(/00000000) Allocated with GEA0 cipher.
<0002> gprs_gmm.c:1100 GMM(gmm_fsm)[0xaaaaf63e5b50]{Deregistered}: Received
Event E_GMM_COMMON_PROC_INIT_REQ
<0002> gprs_gmm_fsm.c:25 GMM(gmm_fsm)[0xaaaaf63e5b50]{Deregistered}: state_chg
to CommonProcedureInitiated
<0011> gprs_llc.c:1056 LLME(ffffffff/af8ce1ff){UNASSIGNED} LLGM Assign pre
(af8ce1ff => cf0ebf06)
<0011> gprs_llc.c:1102 LLME(af8ce1ff/cf0ebf06){ASSIGNED} LLGM Assign post
(af8ce1ff => cf0ebf06)
<0002> gprs_gmm.c:1271 GMM_ATTACH_REQ_FSM(gb_gmm_req)[0xaaaaf63e5c80]{Init}:
Received Event E_ATTACH_REQ_RECV
<0002> gprs_gmm_attach.c:50
GMM_ATTACH_REQ_FSM(gb_gmm_req)[0xaaaaf63e5c80]{Init}: state_chg to CheckIdentity
<0002> gprs_gmm.c:409 MM(/cf0ebf06) <- GPRS IDENTITY REQUEST: mi_type=IMEI
<0010> gprs_bssgp.c:423 BSSGP TLLI=0xaf8ce1ff Rx UPLINK-UNITDATA
<0011> gprs_llc_parse.c:78 LLC SAPI=1 C U GEA0 IOV-UI=0x000000
FCS=0x8c64cd CMD=UI DATA
<0002> gprs_gb.c:40 MM_STATE_Gb(2945245695)[0xaaaaf63e5e50]{Idle}: Received
Event E_MM_PDU_RECEPTION
<0002> gprs_gmm.c:1040 MM(/cf0ebf06) -> GMM IDENTITY RESPONSE:
MI(IMEI)=866089038960590
<0002> gprs_gmm.c:113 MM(/cf0ebf06) Stopping MM timer 3370 but 0 is running
<0002> gprs_gmm.c:1084
GMM_ATTACH_REQ_FSM(gb_gmm_req)[0xaaaaf63e5c80]{CheckIdentity}: Received Event
E_IDEN_RESP_RECV
<0002> gprs_gmm_attach.c:111
GMM_ATTACH_REQ_FSM(gb_gmm_req)[0xaaaaf63e5c80]{CheckIdentity}: state_chg to
CheckIdentity
<0002> gprs_gmm.c:409 MM(/cf0ebf06) <- GPRS IDENTITY REQUEST: mi_type=IMSI
<0010> gprs_bssgp.c:423 BSSGP TLLI=0xaf8ce1ff Rx UPLINK-UNITDATA
<0011> gprs_llc_parse.c:78 LLC SAPI=1 C U GEA0 IOV-UI=0x000000
FCS=0xb71895 CMD=UI DATA
<0002> gprs_gb.c:40 MM_STATE_Gb(2945245695)[0xaaaaf63e5e50]{Idle}: Received
Event E_MM_PDU_RECEPTION
<0002> gprs_gmm.c:1040 MM(/cf0ebf06) -> GMM IDENTITY RESPONSE:
MI(IMSI)=460000323182742
<0002> gprs_gmm.c:113 MM(/cf0ebf06) Stopping MM timer 3370 but 0 is running
<0002> gprs_gmm.c:1084
GMM_ATTACH_REQ_FSM(gb_gmm_req)[0xaaaaf63e5c80]{CheckIdentity}: Received Event
E_IDEN_RESP_RECV
<0002> gprs_gmm_attach.c:113
GMM_ATTACH_REQ_FSM(gb_gmm_req)[0xaaaaf63e5c80]{CheckIdentity}: state_chg to Authenticate
<0002> gprs_gmm_attach.c:148
GMM_ATTACH_REQ_FSM(gb_gmm_req)[0xaaaaf63e5c80]{Authenticate}: state_chg to
WaitAttachComplete
<0002> gprs_gmm.c:289 MM(460000323182742/cf0ebf06) <- GPRS ATTACH ACCEPT (new
P-TMSI=0xcf0ebf06)
<0002> gprs_gmm.c:305 MM(460000323182742/cf0ebf06) <- GPRS ATTACH ACCEPT
(ra_id=0x020xf20x50 lac:2f11 rac:2)
<000e> gprs_sgsn.c:1012 Checking for inactive LLMEs, time = 1652
<000f> gprs_ns.c:779 NSEI=1234 Timer expired in mode tns-test (30 seconds)
<000f> gprs_ns.c:712 NSEI=1234 Tx NS ALIVE (NSVCI=1234)
<000f> gprs_ns.c:751 NSEI=1234 Starting timer in mode tns-alive (3 seconds)
<000f> gprs_ns.c:725 NSEI=1234 Tx NS ALIVE_ACK (NSVCI=1234)
<000f> gprs_ns.c:1763 NSEI 1234 (NS-VCI=1234) setting state
[ALIVE,UNBLOCKED,UNRESET] -> [ALIVE,UNBLOCKED,UNRESET]
<000f> gprs_ns.c:751 NSEI=1234 Starting timer in mode tns-test (30 seconds)
<0010> gprs_bssgp.c:839 BSSGP BVCI=1234 Rx Flow Control BVC
<0002> fsm.c:322
GMM_ATTACH_REQ_FSM(gb_gmm_req)[0xaaaaf63e5c80]{WaitAttachComplete}: Timeout of T3350
<0002> gprs_gmm.c:289 MM(460000323182742/cf0ebf06) <- GPRS ATTACH ACCEPT (new
P-TMSI=0xcf0ebf06)
<0002> gprs_gmm.c:305 MM(460000323182742/cf0ebf06) <- GPRS ATTACH ACCEPT
(ra_id=0x020xf20x50 lac:2f11 rac:2)
<0002> fsm.c:322
GMM_ATTACH_REQ_FSM(gb_gmm_req)[0xaaaaf63e5c80]{WaitAttachComplete}: Timeout of T3350
<0002> gprs_gmm.c:289 MM(460000323182742/cf0ebf06) <- GPRS ATTACH ACCEPT (new
P-TMSI=0xcf0ebf06)
<0002> gprs_gmm.c:305 MM(460000323182742/cf0ebf06) <- GPRS ATTACH ACCEPT
(ra_id=0x020xf20x50 lac:2f11 rac:2)
<0010> gprs_bssgp.c:423 BSSGP TLLI=0xaf8ce1ff Rx UPLINK-UNITDATA
<0011> gprs_llc_parse.c:78 LLC SAPI=1 C U GEA0 IOV-UI=0x000000
FCS=0x0d0447 CMD=UI DATA
<0002> gprs_gb.c:40 MM_STATE_Gb(2945245695)[0xaaaaf63e5e50]{Idle}: Received
Event E_MM_PDU_RECEPTION
<0002> gprs_gmm.c:1118 MM(460000323182742/cf0ebf06) -> GMM ATTACH REQUEST
MI(4018987519) type="GPRS attach"
<0002> gprs_gmm.c:1100 GMM(gmm_fsm)[0xaaaaf63e5b50]{CommonProcedureInitiated}:
Received Event E_GMM_COMMON_PROC_INIT_REQ
<0002> gprs_gmm.c:1100 GMM(gmm_fsm)[0xaaaaf63e5b50]{CommonProcedureInitiated}:
Event E_GMM_COMMON_PROC_INIT_REQ not permitted
<0011> gprs_llc.c:1056 LLME(af8ce1ff/cf0ebf06){ASSIGNED} LLGM Assign pre
(af8ce1ff => cf0ebf06)
<0011> gprs_llc.c:1102 LLME(af8ce1ff/cf0ebf06){ASSIGNED} LLGM Assign post
(af8ce1ff => cf0ebf06)
<0002> gprs_gmm.c:1271
GMM_ATTACH_REQ_FSM(gb_gmm_req)[0xaaaaf63e5c80]{WaitAttachComplete}: Received Event
E_ATTACH_REQ_RECV
<0002> gprs_gmm_attach.c:360
GMM_ATTACH_REQ_FSM(gb_gmm_req)[0xaaaaf63e5c80]{WaitAttachComplete}: state_chg to Init
<0002> gprs_gmm_attach.c:50
GMM_ATTACH_REQ_FSM(gb_gmm_req)[0xaaaaf63e5c80]{Init}: state_chg to CheckIdentity
<0002> gprs_gmm.c:409 MM(460000323182742/cf0ebf06) <- GPRS IDENTITY REQUEST:
mi_type=IMEI
<0010> gprs_bssgp.c:839 BSSGP BVCI=1234 Rx Flow Control BVC
<0010> gprs_bssgp.c:423 BSSGP TLLI=0xaf8ce1ff Rx UPLINK-UNITDATA
<0011> gprs_llc_parse.c:78 LLC SAPI=1 C U GEA0 IOV-UI=0x000000
FCS=0xea5c4f CMD=UI DATA
<0002> gprs_gb.c:40 MM_STATE_Gb(2945245695)[0xaaaaf63e5e50]{Idle}: Received
Event E_MM_PDU_RECEPTION
<0002> gprs_gmm.c:1040 MM(460000323182742/cf0ebf06) -> GMM IDENTITY
RESPONSE: MI(IMEI)=866089038960590
<0002> gprs_gmm.c:113 MM(460000323182742/cf0ebf06) Stopping MM timer 3370 but 0
is running
<0002> gprs_gmm.c:1084
GMM_ATTACH_REQ_FSM(gb_gmm_req)[0xaaaaf63e5c80]{CheckIdentity}: Received Event
E_IDEN_RESP_RECV
<0002> gprs_gmm_attach.c:113
GMM_ATTACH_REQ_FSM(gb_gmm_req)[0xaaaaf63e5c80]{CheckIdentity}: state_chg to Authenticate
<0002> gprs_gmm_attach.c:148
GMM_ATTACH_REQ_FSM(gb_gmm_req)[0xaaaaf63e5c80]{Authenticate}: state_chg to
WaitAttachComplete
<0002> gprs_gmm.c:289 MM(460000323182742/cf0ebf06) <- GPRS ATTACH ACCEPT (new
P-TMSI=0xcf0ebf06)
<0002> gprs_gmm.c:305 MM(460000323182742/cf0ebf06) <- GPRS ATTACH ACCEPT
(ra_id=0x020xf20x50 lac:2f11 rac:2)
<0002> fsm.c:322
GMM_ATTACH_REQ_FSM(gb_gmm_req)[0xaaaaf63e5c80]{WaitAttachComplete}: Timeout of T3350
<0002> gprs_gmm.c:289 MM(460000323182742/cf0ebf06) <- GPRS ATTACH ACCEPT (new
P-TMSI=0xcf0ebf06)
<0002> gprs_gmm.c:305 MM(460000323182742/cf0ebf06) <- GPRS ATTACH ACCEPT
(ra_id=0x020xf20x50 lac:2f11 rac:2)
Configure information：
gprs mode egprs
gprs routing area 2
gprs cell bvci 1234
gprs nsei 1234
gprs nsvc 0 nsvci 1234
gprs nsvc 0 local udp port 23001
gprs nsvc 0 remote udp port 23000
。。。
timeslot 6
phys_chan_config PDCH
hopping enabled 0
timeslot 7
phys_chan_config PDCH
hopping enabled 0
pcu
flow-control-interval 10
cs 2
cs max 4
cs threshold 10 33
cs downgrade-threshold 200
cs link-quality-ranges cs1 6 cs2 5 8 cs3 7 13 cs4 12
mcs link-quality-ranges mcs1 6 mcs2 5 8 mcs3 7 13 mcs4 12 15 mcs5 14 17 mcs6 16
18 mcs7 17 20 mcs8 19 24 mcs9 23
mcs max 9
window-size 64 0
queue idle-ack-delay 10
queue codel
alloc-algorithm dynamic
alpha 0
gamma 0
dl-tbf-idle-time 2000
sgsn
gtp local-ip 127.0.0.1
ggsn 0 remote-ip 127.0.0.6
ggsn 0 gtp-version 1
auth-policy accept-all
ns
timer tns-block 3
timer tns-block-retries 3
timer tns-reset 3
timer tns-reset-retries 3
timer tns-test 30
timer tns-alive 3
timer tns-alive-retries 10
encapsulation udp local-ip 127.0.0.1
encapsulation udp local-port 23000
encapsulation framerelay-gre enabled 0
Version information:
OsmoPCU version 0.8.0
OsmoSGSN version 1.6.2
I tried to debug this issue but the no any progress for this issue.The root cause is
confifure or something else?
I need help.
Thanks a lot.
Br,
Perter
1087
days inactive
1100
days old
osmocom-net-gprs@lists.osmocom.org
5 comments
3 participants
participants (3)
-
Pau Espin Pedrol -
Pau Espin Pedrol -
海鱼