Project

General

Profile

Actions

Bug #5265

closed

SIGSEGV pdch_ulc_release_tbf (ulc=0x0, tbf=tbf@entry=0x1bac98)

Added by keith about 2 months ago. Updated 17 days ago.

Status:
Resolved
Priority:
Normal
Assignee:
Target version:
-
Start date:
10/14/2021
Due date:
% Done:

100%

Spec Reference:

Description

Log leading up (not at level INFO, sorry. Will try to grab more next time we hit this one.)

<0002> ../../git/src/pdch_ul_controller.c:330 PDCH(bts=0,trx=0,ts=5) Timeout for registered POLL (FN=351069, reason=DL_ACK): TBF(TFI=4 TLLI=0xf8b95a7d DIR=DL STATE=FLOW EGPRS)             
<0008> ../../git/src/tbf.cpp:550 TBF(TFI=4 TLLI=0xf8b95a7d DIR=DL STATE=FLOW EGPRS) poll timeout for FN=351069, TS=5 (curr FN 351069)                                                       
<0008> ../../git/src/tbf.cpp:628 TBF(TFI=4 TLLI=0xf8b95a7d DIR=DL STATE=FLOW EGPRS) Timeout for polling PACKET DOWNLINK ACK: |Assignment was on PACCH|Downlink ACK was received|            
<0002> ../../git/src/pdch_ul_controller.c:330 PDCH(bts=0,trx=0,ts=5) Timeout for registered POLL (FN=351073, reason=DL_ACK): TBF(TFI=5 TLLI=0xd44ced11 DIR=DL STATE=FLOW EGPRS)             
<0008> ../../git/src/tbf.cpp:550 TBF(TFI=5 TLLI=0xd44ced11 DIR=DL STATE=FLOW EGPRS) poll timeout for FN=351073, TS=5 (curr FN 351073)                                                       
<0008> ../../git/src/tbf.cpp:628 TBF(TFI=5 TLLI=0xd44ced11 DIR=DL STATE=FLOW EGPRS) Timeout for polling PACKET DOWNLINK ACK: |Assignment was on PACCH|Downlink ACK was received|            
<0005> ../../git/src/pdch.cpp:1005 PDCH(bts=0,trx=0,ts=6) FN=351073 Rx UL DATA from unexpected TBF(TFI=0 TLLI=0x8e859ef4 DIR=UL STATE=ASSIGN EGPRS)                                         
<0005> ../../git/src/pdch.cpp:990 PDCH(bts=0,trx=0,ts=5) FN=351078 Rx UL DATA from unexpected TBF(TFI=6 TLLI=0x955aadcf DIR=UL STATE=RELEASING EGPRS) vs expected TBF(TFI=1 TLLI=0xd44ced11 
DIR=UL STATE=FLOW EGPRS)                                                                                                                                                                    
<0002> ../../git/src/pdch_ul_controller.c:330 PDCH(bts=0,trx=0,ts=7) Timeout for registered POLL (FN=351078, reason=UL_ASS): TBF(TFI=0 TLLI=0x8e859ef4 DIR=UL STATE=ASSIGN EGPRS)           
<0008> ../../git/src/tbf.cpp:550 TBF(TFI=0 TLLI=0x8e859ef4 DIR=UL STATE=ASSIGN EGPRS) poll timeout for FN=351078, TS=7 (curr FN 351078)                                                     
<0008> ../../git/src/tbf_ul_ass_fsm.c:224 TBF(TFI=0 TLLI=0x8e859ef4 DIR=UL STATE=ASSIGN EGPRS) Timeout for polling PACKET CONTROL ACK for PACKET UPLINK ASSIGNMENT: |Assignment was on PACCH
|Uplink data was received|                                                                                                                                                                  
<0002> ../../git/src/pdch_ul_controller.c:330 PDCH(bts=0,trx=0,ts=7) Timeout for registered POLL (FN=351082, reason=UL_ASS): TBF(TFI=6 TLLI=0xf1566875 DIR=DL STATE=FLOW EGPRS)             
<0008> ../../git/src/tbf.cpp:550 TBF(TFI=6 TLLI=0xf1566875 DIR=DL STATE=FLOW EGPRS) poll timeout for FN=351082, TS=7 (curr FN 351082)                                                       
<0008> ../../git/src/tbf_ul_ass_fsm.c:224 TBF(TFI=6 TLLI=0xf1566875 DIR=DL STATE=FLOW EGPRS) Timeout for polling PACKET CONTROL ACK for PACKET UPLINK ASSIGNMENT: |Assignment was on PACCH|D
ownlink ACK was received|
<0005> ../../git/src/pdch.cpp:1005 PDCH(bts=0,trx=0,ts=6) FN=351086 Rx UL DATA from unexpected TBF(TFI=9 TLLI=0xd323cdc1 DIR=UL STATE=RELEASING EGPRS)
<0002> ../../git/src/pdch_ul_controller.c:330 PDCH(bts=0,trx=0,ts=5) Timeout for registered POLL (FN=351095, reason=DL_ACK): TBF(TFI=4 TLLI=0xf8b95a7d DIR=DL STATE=FLOW EGPRS)
<0008> ../../git/src/tbf.cpp:550 TBF(TFI=4 TLLI=0xf8b95a7d DIR=DL STATE=FLOW EGPRS) poll timeout for FN=351095, TS=5 (curr FN 351095)
<0008> ../../git/src/tbf.cpp:628 TBF(TFI=4 TLLI=0xf8b95a7d DIR=DL STATE=FLOW EGPRS) Timeout for polling PACKET DOWNLINK ACK: |Assignment was on PACCH|Downlink ACK was received|
<0005> ../../git/src/pdch.cpp:995 PDCH(bts=0,trx=0,ts=6) FN=351095 Rx UL DATA from unexpected TBF(TFI=0 TLLI=0x8e859ef4 DIR=UL STATE=ASSIGN EGPRS) vs expected POLL TBF(TFI=7 TLLI=0xfe4e478
f DIR=DL STATE=FLOW EGPRS)
<0002> ../../git/src/pdch_ul_controller.c:330 PDCH(bts=0,trx=0,ts=6) Timeout for registered POLL (FN=351095, reason=DL_ACK): TBF(TFI=7 TLLI=0xfe4e478f DIR=DL STATE=FLOW EGPRS)
<0008> ../../git/src/tbf.cpp:550 TBF(TFI=7 TLLI=0xfe4e478f DIR=DL STATE=FLOW EGPRS) poll timeout for FN=351095, TS=6 (curr FN 351095)
<0008> ../../git/src/tbf.cpp:628 TBF(TFI=7 TLLI=0xfe4e478f DIR=DL STATE=FLOW EGPRS) Timeout for polling PACKET DOWNLINK ACK: |Assignment was on PACCH|No downlink ACK received yet|

#0  0xb6ebd674 in rb_first () from /usr/lib/libosmocore.so.17
#1  0x0003d418 in pdch_ulc_release_tbf (ulc=0x0, tbf=tbf@entry=0x1bac98)
    at /usr/src/debug/osmo-pcu/0.9.0+gitAUTOINC+b9fede74ef-r0.18/git/src/pdch_ul_controller.c:273
#2  0x00039bf8 in gprs_rlcmac_pdch::detach_tbf (this=0x1380b4, tbf=tbf@entry=0x1bac98)
    at /usr/src/debug/osmo-pcu/0.9.0+gitAUTOINC+b9fede74ef-r0.18/git/src/pdch.cpp:1148
#3  0x0002b7d4 in tbf_unlink_pdch (tbf=tbf@entry=0x1bac98)
    at /usr/src/debug/osmo-pcu/0.9.0+gitAUTOINC+b9fede74ef-r0.18/git/src/tbf.cpp:260
#4  0x0002ba50 in tbf_free (tbf=0x1bac98)
    at /usr/src/debug/osmo-pcu/0.9.0+gitAUTOINC+b9fede74ef-r0.18/git/src/tbf.cpp:293
#5  0x00020ab4 in pcu_rx_susp_req (susp_req=0xbefff3b4, bts=0x137b20)
    at /usr/src/debug/osmo-pcu/0.9.0+gitAUTOINC+b9fede74ef-r0.18/git/src/pcu_l1_if.cpp:974
#6  pcu_rx (pcu_prim=pcu_prim@entry=0xbefff3b0, pcu_prim_length=pcu_prim_length@entry=1006)
    at /usr/src/debug/osmo-pcu/0.9.0+gitAUTOINC+b9fede74ef-r0.18/git/src/pcu_l1_if.cpp:1135
#7  0x00044584 in pcu_sock_read (bfd=<optimized out>)
    at /usr/src/debug/osmo-pcu/0.9.0+gitAUTOINC+b9fede74ef-r0.18/git/src/osmobts_sock.c:156
#8  0x0004476c in pcu_sock_cb (bfd=0x8ddfc <pcu_sock_state>, flags=1)
    at /usr/src/debug/osmo-pcu/0.9.0+gitAUTOINC+b9fede74ef-r0.18/git/src/osmobts_sock.c:211
#9  0xb6eadddc in ?? () from /usr/lib/libosmocore.so.17
Backtrace stopped: previous frame identical to this frame (corrupt stack?)

Actions #1

Updated by pespin about 2 months ago

  • Status changed from New to Feedback
  • Assignee set to keith

I believe this should be fixed in current osmo-pcu.git master b0aba591433c7c22298035453713724172d1cfbc

Please keith see if you can still reproduce.

Actions #2

Updated by keith about 2 months ago

Hi, I still see a crash here with last nights build.

Slightly different code path:

Program received signal SIGSEGV, Segmentation fault.
0xb6de1704 in rb_first () from /usr/lib/libosmocore.so.17
(gdb) bt
#0  0xb6de1704 in rb_first () from /usr/lib/libosmocore.so.17
#1  0x0003d500 in pdch_ulc_release_tbf (ulc=0x0, tbf=tbf@entry=0x270970)
    at /usr/src/debug/osmo-pcu/0.9.0+gitAUTOINC+b0aba59143-r0.18/git/src/pdch_ul_controller.c:273
#2  0x00039ce0 in gprs_rlcmac_pdch::detach_tbf (this=0x138d04, tbf=tbf@entry=0x270970)
    at /usr/src/debug/osmo-pcu/0.9.0+gitAUTOINC+b0aba59143-r0.18/git/src/pdch.cpp:1148
#3  0x0002a28c in tbf_unlink_pdch (tbf=tbf@entry=0x270970)
    at /usr/src/debug/osmo-pcu/0.9.0+gitAUTOINC+b0aba59143-r0.18/git/src/tbf.cpp:261
#4  0x0002ba48 in tbf_free (tbf=0x270970)
    at /usr/src/debug/osmo-pcu/0.9.0+gitAUTOINC+b0aba59143-r0.18/git/src/tbf.cpp:294
#5  0x0002cbe8 in tbf_fsm_timer_cb (fi=<optimized out>)
    at /usr/src/debug/osmo-pcu/0.9.0+gitAUTOINC+b0aba59143-r0.18/git/src/tbf_fsm.c:393
#6  0xb6dd7184 in ?? () from /usr/lib/libosmocore.so.17

Actions #3

Updated by pespin about 2 months ago

So PDCH uplink controller (ULC) is NULL, which probably means the pdch TS was somehow disabled while still some TBFs kept attached to it, which of course should not happen. I'd really appreciate more verbose and longer loggings to understand better the list of events.

Actions #4

Updated by pespin about 2 months ago

Also print with gdb the tbf and pdch objects, etc. Maybe send me privately a core file + osmo-pcu binary file.

Actions #5

Updated by keith about 1 month ago

Dunno if this is of any use to you. https://www.rhizomatica.org/files/bin+core.zip

EDIT: Apologies, This core is actually related to "Assert failed pdch != NULL encoding.cpp:561" but well it serves to let us know if this type of feedback helps.

Actions #7

Updated by keith about 1 month ago

With current master (ef8a730):

Program received signal SIGSEGV, Segmentation fault.
0xb6ebb704 in rb_first () from /usr/lib/libosmocore.so.17
(gdb) bt
#0  0xb6ebb704 in rb_first () from /usr/lib/libosmocore.so.17
#1  0x00058644 in pdch_ulc_release_tbf (ulc=0x0, tbf=0x192860) at pdch_ul_controller.c:273
#2  0x000573a0 in gprs_rlcmac_pdch::detach_tbf (this=0x163c6c, tbf=0x192860) at pdch.cpp:1152
#3  0x000399e4 in tbf_unlink_pdch (tbf=0x192860) at tbf.cpp:262
#4  0x00039bac in tbf_free (tbf=0x192860) at tbf.cpp:295
#5  0x0003ebc0 in tbf_fsm_timer_cb (fi=0x16d690) at tbf_fsm.c:396
#6  0xb6eb1184 in ?? () from /usr/lib/libosmocore.so.17
Backtrace stopped: previous frame identical to this frame (corrupt stack?)

Complete LOG, Core and Binary: https://www.rhizomatica.org/files/log_core_bin-OS5265-1.zip

Actions #8

Updated by keith 30 days ago

(gdb) bt
#0  0xb6ebb704 in rb_first () from /usr/lib/libosmocore.so.17
#1  0x00058644 in pdch_ulc_release_tbf (ulc=0x0, tbf=0x3feec0) at pdch_ul_controller.c:273
#2  0x000573a0 in gprs_rlcmac_pdch::detach_tbf (this=0x163b14, tbf=0x3feec0) at pdch.cpp:1152
#3  0x000399e4 in tbf_unlink_pdch (tbf=0x3feec0) at tbf.cpp:262
#4  0x00039bac in tbf_free (tbf=0x3feec0) at tbf.cpp:295
#5  0x000536d8 in gprs_rlcmac_pdch::rcv_control_ack (this=0x163dc4, packet=0x1701f0, fn=877851) at pdch.cpp:415
#6  0x00055af4 in gprs_rlcmac_pdch::rcv_control_block (this=0x163dc4, data=0x173922 "@\a(\367'\273", '+' <repeats 17 times>, data_len=23 '\027', fn=877851, meas=0xbefffaf0, cs=CS1)
    at pdch.cpp:865
#7  0x0005692c in gprs_rlcmac_pdch::rcv_block_gprs (this=0x163dc4, data=0x173922 "@\a(\367'\273", '+' <repeats 17 times>, data_len=23 '\027', fn=877851, meas=0xbefffaf0, cs=CS1)
    at pdch.cpp:1029
#8  0x00055eec in gprs_rlcmac_pdch::rcv_block (this=0x163dc4, data=0x173922 "@\a(\367'\273", '+' <repeats 17 times>, len=23 '\027', fn=877851, meas=0xbefffaf0) at pdch.cpp:923
#9  0x00027db8 in pcu_rx_data_ind_pdtch (bts=0x163580, pdch=0x163dc4, data=0x173922 "@\a(\367'\273", '+' <repeats 17 times>, len=23 '\027', fn=877851, meas=0xbefffaf0)
    at pcu_l1_if.cpp:350
#10 0x00016368 in handle_ph_data_ind (fl1h=0x16b740, data_ind=0x173900, l1p_msg=0x173838) at osmo-bts-sysmo/sysmo_l1_if.c:214
#11 0x00016788 in l1if_handle_l1prim (wq=3, fl1h=0x16b740, msg=0x173838) at osmo-bts-sysmo/sysmo_l1_if.c:290
#12 0x00016f60 in l1if_fd_cb (ofd=0x16b7f0, what=1) at osmo-bts-sysmo/sysmo_l1_hw.c:118
#13 0xb6eabe10 in ?? () from /usr/lib/libosmocore.so.17

I this case I lost the lead up log due to disk filling long before the bug was triggered.
ulc was valid in rcv_control_ack() but by the time we get to detach_tbf() it is 0x0

Actions #9

Updated by pespin 29 days ago

I found in log_core_bin-OS5265-1.zip what I think is the issue:

[First, we recieve a DL paylod to send, we create a new DL TBF and we assign only 1 TS to it, because that's the most we can assign over CCCH:]
Mon Nov  8 19:51:30 2021 DLNSDATA INFO ../../../git/src/gb/gprs_ns2.c:1311 NSE(00103)-NSVC(00103) Rx NS-UNITDATA
Mon Nov  8 19:51:30 2021 DLNSDATA INFO ../../../git/src/gb/gprs_ns2_vc_fsm.c:671 NSE(00103)-NSVC(00103) Rx NS-UNITDATA
Mon Nov  8 19:51:30 2021 DCSN1 INFO gsm_rlcmac.c:6171 csnStreamDecoder (RAcap):
Mon Nov  8 19:51:30 2021 DLBSSGP INFO gprs_bssgp_pcu.c:183 LLC [SGSN -> PCU] = TLLI: 0xfbadc80b IMSI: 334020215191321 len: 278
Mon Nov  8 19:51:30 2021 DTBF INFO tbf_dl.cpp:133 MS(TLLI=0xfbadc80b, IMSI=334020215191321, TA=4, 12/0,) Allocating DL TBF
Mon Nov  8 19:51:30 2021 DTBF INFO ../../git/src/fsm.c:461 TBF[0x16d690]{NEW}: Allocated
Mon Nov  8 19:51:30 2021 DTBF INFO ../../git/src/fsm.c:461 UL_ASS_TBF[0x16d7d0]{NONE}: Allocated
Mon Nov  8 19:51:30 2021 DTBF INFO ../../git/src/fsm.c:461 DL_ASS_TBF[0x2e7ff8]{NONE}: Allocated
Mon Nov  8 19:51:30 2021 DRLCMAC INFO gprs_rlcmac_ts_alloc.cpp:944 [DL] algo B <single> (suggested TRX: -1): using single slot at TS 6
Mon Nov  8 19:51:30 2021 DRLCMAC INFO pdch.cpp:1131 PDCH(bts=0,trx=0,ts=6) Attaching TBF(TFI=1 TLLI=0xfbadc80b DIR=DL STATE=NEW), 1 TBFs, USFs = 38, TFIs = 00000002.
Mon Nov  8 19:51:30 2021 DTBF INFO tbf.cpp:345 TBF(TFI=1 TLLI=0xfbadc80b DIR=DL STATE=NEW) Setting Control TS 6
Mon Nov  8 19:51:30 2021 DTBF INFO tbf.cpp:680 TBF(TFI=1 TLLI=0xfbadc80b DIR=DL STATE=NEW) Allocated: trx = 0, ul_slots = 40, dl_slots = 40
Mon Nov  8 19:51:30 2021 DRLCMAC INFO gprs_ms.c:321 MS(TLLI=0xfbadc80b, IMSI=334020215191321, TA=4, 12/0,) Attaching DL TBF: TBF(TFI=1 TLLI=0xfbadc80b DIR=DL STATE=NEW)
Mon Nov  8 19:51:30 2021 DTBF INFO tbf_dl.cpp:618 TBF(DL-TFI_1)[0x16d690]{NEW}: Received Event ASSIGN_ADD_CCCH
Mon Nov  8 19:51:30 2021 DTBF INFO tbf_fsm.c:89 TBF(TFI=1 TLLI=0xfbadc80b DIR=DL STATE=NEW) set ass. type CCCH [prev CCCH:0, PACCH:0]
Mon Nov  8 19:51:30 2021 DTBF INFO tbf_fsm.c:107 TBF(DL-TFI_1)[0x16d690]{NEW}: state_chg to ASSIGN
Mon Nov  8 19:51:30 2021 DTBF INFO bts.cpp:1046 TBF(TFI=1 TLLI=0xfbadc80b DIR=DL STATE=ASSIGN) TX: START Immediate Assignment Downlink (PCH)
...
[Meanwhile, a PDCH is disabled (ddiferent than the one we assigned for the DL TBF, so it won't be destroyed, that's correct.]
Mon Nov  8 19:51:30 2021 DL1IF INFO pcu_l1_if.cpp:743 BTS available
Mon Nov  8 19:51:30 2021 DL1IF INFO pcu_l1_if.cpp:176 PDCH(bts=0,trx=0,ts=5) Sending deactivate request
... [TS5 is never enabled again and crash occurs below] ...
Mon Nov  8 19:51:31 2021 DL1IF INFO pcu_l1_if.cpp:346 PDCH(bts=0,trx=0,ts=5) Received DATA.ind (PDTCH) on disabled TS
Mon Nov  8 19:51:31 2021 DCSN1 INFO gsm_rlcmac.c:5394 csnStreamDecoder (type: Pkt UL Dummy Ctrl Block (3)):
Mon Nov  8 19:51:31 2021 DRLCMAC NOTICE pdch_ul_controller.c:330 PDCH(bts=0,trx=0,ts=6) Timeout for registered POLL (FN=437627, reason=DL_ASS): TBF(TFI=0 TLLI=0xb487de52 DIR=UL STATE=FINISHED EGPRS)
Mon Nov  8 19:51:31 2021 DTBF NOTICE tbf.cpp:552 TBF(TFI=0 TLLI=0xb487de52 DIR=UL STATE=FINISHED EGPRS) poll timeout for FN=437627, TS=6 (curr FN 437627)
Mon Nov  8 19:51:31 2021 DTBF INFO tbf.cpp:610 DL_ASS_TBF(UL-TFI_0)[0x1f6e98]{WAIT_ACK}: Received Event ASS_POLL_TIMEOUT
Mon Nov  8 19:51:31 2021 DTBF NOTICE tbf_dl_ass_fsm.c:175 TBF(TFI=0 TLLI=0xb487de52 DIR=UL STATE=FINISHED EGPRS) Timeout for polling PACKET CONTROL ACK for PACKET DOWNLINK ASSIGNMENT: |Assignment was on PACCH|Uplink data was r
eceived|
Mon Nov  8 19:51:31 2021 DTBF INFO tbf_dl_ass_fsm.c:177 DL_ASS_TBF(UL-TFI_0)[0x1f6e98]{WAIT_ACK}: state_chg to SEND_ASS
Mon Nov  8 19:51:31 2021 DTBF INFO ../../git/src/fsm.c:322 TBF(DL-TFI_1)[0x16d690]{ASSIGN}: Timeout of X2002
Mon Nov  8 19:51:31 2021 DRLCMAC INFO pdch.cpp:1157 PDCH(bts=0,trx=0,ts=6) Detaching TBF(TFI=1 TLLI=0xfbadc80b DIR=DL STATE=ASSIGN), 2 TBFs, USFs = 23, TFIs = 0000000c.
Mon Nov  8 19:51:31 2021 DRLCMAC INFO gprs_rlcmac_ts_alloc.cpp:947 [DL] algo B <multi> (suggested TRX: -1): using 3 slots
Mon Nov  8 19:51:31 2021 DRLCMAC INFO pdch.cpp:1131 PDCH(bts=0,trx=0,ts=5) Attaching TBF(TFI=1 TLLI=0xfbadc80b DIR=DL STATE=ASSIGN), 1 TBFs, USFs = 00, TFIs = 00000002.  <!--- HERE alloc_algo is allocating TS5 despite it it disabled!
Mon Nov  8 19:51:31 2021 DRLCMAC INFO pdch.cpp:1131 PDCH(bts=0,trx=0,ts=6) Attaching TBF(TFI=1 TLLI=0xfbadc80b DIR=DL STATE=ASSIGN), 3 TBFs, USFs = 23, TFIs = 0000000e.
Mon Nov  8 19:51:31 2021 DRLCMAC INFO pdch.cpp:1131 PDCH(bts=0,trx=0,ts=7) Attaching TBF(TFI=1 TLLI=0xfbadc80b DIR=DL STATE=ASSIGN), 4 TBFs, USFs = 0b, TFIs = 0000001b.
Mon Nov  8 19:51:31 2021 DTBF INFO tbf_dl.cpp:609 DL_ASS_TBF(DL-TFI_1)[0x2e7ff8]{NONE}: Received Event SCHED_ASS
Mon Nov  8 19:51:31 2021 DTBF INFO tbf_dl_ass_fsm.c:139 DL_ASS_TBF(DL-TFI_1)[0x2e7ff8]{NONE}: state_chg to SEND_ASS
Mon Nov  8 19:51:31 2021 DTBF INFO tbf_dl.cpp:612 TBF(DL-TFI_1)[0x16d690]{ASSIGN}: Received Event ASSIGN_ADD_PACCH
Mon Nov  8 19:51:31 2021 DTBF INFO tbf_fsm.c:89 TBF(TFI=1 TLLI=0xfbadc80b DIR=DL STATE=ASSIGN) set ass. type PACCH [prev CCCH:0, PACCH:0]
Mon Nov  8 19:51:31 2021 DRLCMACSCHED INFO gprs_rlcmac_sched.cpp:425 PDCH(bts=0,trx=0,ts=5) Received RTS on disabled TS
Mon Nov  8 19:51:31 2021 DTBF INFO tbf_dl_ass_fsm.c:249 DL_ASS_TBF(DL-TFI_1)[0x2e7ff8]{SEND_ASS}: Received Event CREATE_RLCMAC_MSG
Mon Nov  8 19:51:31 2021 DTBF INFO tbf_dl_ass_fsm.c:102 TBF(TFI=1 TLLI=0xfbadc80b DIR=DL STATE=ASSIGN) start Packet Downlink Assignment (PACCH)
Mon Nov  8 19:51:31 2021 DCSN1 INFO gsm_rlcmac.c:5878 csnStreamEncoder (type: Pkt DL ASS (2)):

Actions #10

Updated by pespin 29 days ago

And finally when the TBF finishes, we can see it crashing because it tries to unlink itself from a pdch which is disabled and hence ulc is null:

Mon Nov  8 19:51:35 2021 DTBF INFO tbf_dl.cpp:758 TBF(DL-TFI_1)[0x16d690]{FLOW}: Received Event LAST_DL_DATA_SENT
Mon Nov  8 19:51:35 2021 DTBF INFO tbf_fsm.c:231 TBF(DL-TFI_1)[0x16d690]{FLOW}: state_chg to FINISHED
Mon Nov  8 19:51:35 2021 DTBFDL INFO tbf_dl.cpp:983 TBF(TFI=1 TLLI=0xfbadc80b DIR=DL STATE=FINISHED) Scheduled Ack/Nack polling on FN=438568, TS=6
...
Mon Nov  8 19:51:35 2021 DCSN1 INFO gsm_rlcmac.c:5394 csnStreamDecoder (type: Pkt DL ACK/NACK (2)):
Mon Nov  8 19:51:35 2021 DTBF INFO tbf_dl.cpp:1146 TBF(DL-TFI_1)[0x16d690]{FINISHED}: Received Event FINAL_ACK_RECVD
Mon Nov  8 19:51:35 2021 DTBF INFO tbf_fsm.c:262 TBF(DL-TFI_1)[0x16d690]{FINISHED}: state_chg to WAIT_RELEASE
...
Mon Nov  8 19:51:37 2021 DTBF INFO tbf.cpp:292 TBF(TFI=1 TLLI=0xfbadc80b DIR=DL STATE=WAIT_RELEASE) free

Actions #11

Updated by pespin 29 days ago

  • % Done changed from 0 to 50

I hope this should be fixed by:
https://gerrit.osmocom.org/c/osmo-pcu/+/26183 pdch: Update ms_reserved_slots in GprsMS when TS becomes disabled

Actions #12

Updated by keith 29 days ago

  • % Done changed from 50 to 70

Great! It ran for 1 hour 46 minutes before hitting #5293
Looking good here.

Actions #13

Updated by keith 19 days ago

  • Assignee changed from keith to pespin

pespin I think you mentioned something on IRC related to this - a very rare crash maybe?

Please close if not directly related to this ticket.

Actions #14

Updated by pespin 17 days ago

  • Status changed from Feedback to Resolved
  • % Done changed from 70 to 100
Actions

Also available in: Atom PDF

Add picture from clipboard (Maximum size: 48.8 MB)