Changes:
[Pau Espin Pedrol] ms: Use osmo_use_count to track references
[Pau Espin Pedrol] ms: Make sure tbf!=NULL in ms_attach_{ul,dl}_tbf()
[Pau Espin Pedrol] ms: Make ms_{attach,detach}_tbf expectancies more robust
[Pau Espin Pedrol] ms: Log detaching tbf log line in proper place
[Pau Espin Pedrol] ms: Rewrite MS release lifecycle
[Pau Espin Pedrol] tbf: Store initial timestamp during constructor
------------------------------------------ [...truncated 142.99 KB...] 4: tbf FAILED (testsuite.at:28) 5: bitcomp ok 6: edge ok 7: types ok 8: ms ok 9: llc ok 10: llist ok 11: codel ok 12: fn ok 13: app_info ok 14: ulc ok
## ------------- ## ## Test results. ## ## ------------- ##
ERROR: All 14 tests were run, 1 failed unexpectedly. ## -------------------------- ## ## testsuite.log was created. ## ## -------------------------- ##
Please send `tests/testsuite.log' and all information you think might help:
To: osmocom-net-gprs@lists.osmocom.org Subject: [osmo-pcu 1.2.0.47-f978] testsuite: 4 failed
You may investigate any problem if you feel able to do so, in which case the test suite provides a good starting point. Its output may be found below `tests/testsuite.dir'.
make[4]: Leaving directory '/build/osmo-pcu-1.2.0.47-f978/_build/sub/tests' make[4]: *** [Makefile:1474: check-local] Error 1 make[3]: *** [Makefile:1232: check-am] Error 2 make[3]: Leaving directory '/build/osmo-pcu-1.2.0.47-f978/_build/sub/tests' make[2]: *** [Makefile:429: check-recursive] Error 1 make[2]: Leaving directory '/build/osmo-pcu-1.2.0.47-f978/_build/sub' make[1]: *** [Makefile:729: check] Error 2 make[1]: Leaving directory '/build/osmo-pcu-1.2.0.47-f978/_build/sub' make: *** [Makefile:649: distcheck] Error 1 + cat-testlogs.sh
======================== ./osmo-pcu-1.2.0.47-f978/_build/sub/tests/testsuite.dir/04/testsuite.log
# -*- compilation -*- 4. testsuite.at:25: testing tbf ... ../../../tests/testsuite.at:28: $OSMO_QEMU $abs_top_builddir/tests/tbf/TbfTest --- experr 2023-04-21 12:46:31.945618502 +0000 +++ /build/osmo-pcu-1.2.0.47-f978/_build/sub/tests/testsuite.dir/at-groups/4/stderr 2023-04-21 12:46:43.725381951 +0000 @@ -9853,138 +9853,52 @@ UL_TBF(UL:TFI-0-0--1:STATE-NEW:GPRS:TLLI-0xffeeddcc){ASSIGN}: Deallocated UL_ASS_TBF(UL:TFI-0-0--1:STATE-NEW:GPRS:TLLI-0xffeeddcc){NONE}: Deallocated DL_ASS_TBF(UL:TFI-0-0--1:STATE-NEW:GPRS:TLLI-0xffeeddcc){NONE}: Deallocated -=== end test_packet_access_rej_prr_no_other_tbfs === -=== start test_ms_merge_dl_tbf_different_trx === -PDCH(bts=0,trx=0,ts=1) PDCH state: disabled => enabled -PDCH(bts=0,trx=0,ts=1) PDCH state: enabled => disabled -PDCH(bts=0,trx=1,ts=4) PDCH state: disabled => enabled -PDCH(bts=0,trx=1,ts=5) PDCH state: disabled => enabled -PDCH(bts=0,trx=1,ts=6) PDCH state: disabled => enabled -Creating MS object -Modifying MS object, TLLI = 0xffffffff, IMSI '' -> '001001000000001' -The MS object cannot fully confirm an unexpected TLLI: 0xa3c2f953, partly confirmed -Modifying MS object, TLLI = 0xa3c2f953, MS class 0 -> 11 -MS(IMSI-001001000000001:TLLI-0xa3c2f953:TA-220:MSCLS-11-0) appending 19 bytes to DL LLC queue -MS(IMSI-001001000000001:TLLI-0xa3c2f953:TA-220:MSCLS-11-0) ********** DL-TBF starts here ********** -MS(IMSI-001001000000001:TLLI-0xa3c2f953:TA-220:MSCLS-11-0) Allocating DL TBF -UL_ASS_TBF{NONE}: Allocated -DL_ASS_TBF{NONE}: Allocated -DL_TBF{NEW}: Allocated -[DL] algo B <single> (suggested TRX: -1): Alloc start -Found first unallocated TRX=1 TFI=0 -Slot Allocation (Algorithm B) for class 11 -- Skipping TS 0, because not enabled -- Skipping TS 1, because not enabled -- Skipping TS 2, because not enabled -- Skipping TS 3, because not enabled -- Skipping TS 7, because not enabled -- Possible DL/UL slots: (TS=0)"....CCC."(TS=7) -Rx=4 Tx=3 Sum Rx+Tx=5, Tta=3 Ttb=1, Tra=2 Trb=1, Type=1 -- Skipping TS 6, because num TBFs 0 >= 0 -Selected DL slots: (TS=0)".ddd.D.."(TS=7), single -[DL] algo B <single> (suggested TRX: -1): using single slot at TS 5 -- Reserved DL/UL slots: (TS=0)"..D..CU."(TS=7) -- Assigning DL TS 5 -PDCH(bts=0,trx=1,ts=5) Attaching TBF(DL:TFI-0-1-0:STATE-NEW:GPRS:IMSI-001001000000001:TLLI-0xa3c2f953), 1 TBFs, USFs = 00, TFIs = 00000001. -TBF(DL:TFI-0-1-0:STATE-NEW:GPRS:IMSI-001001000000001:TLLI-0xa3c2f953) Setting Control TS PDCH(bts=0,trx=1,ts=5) -TBF(DL:TFI-0-1-0:STATE-NEW:GPRS:IMSI-001001000000001:TLLI-0xa3c2f953) Allocated: trx = 1, ul_slots = 20, dl_slots = 20 -MS(IMSI-001001000000001:TLLI-0xa3c2f953:TA-220:MSCLS-11-0) Attaching DL TBF: TBF(DL:TFI-0-1-0:STATE-NEW:GPRS:IMSI-001001000000001:TLLI-0xa3c2f953) -MS(IMSI-001001000000001:TLLI-0xa3c2f953:TA-220:MSCLS-11-0:DL): + tbf: now used by 1 (tbf) -TBF(DL:TFI-0-1-0:STATE-NEW:GPRS:IMSI-001001000000001:TLLI-0xa3c2f953) [DOWNLINK] START (PCH) -TBF(DL:TFI-0-1-0:STATE-NEW:GPRS:IMSI-001001000000001:TLLI-0xa3c2f953) Send downlink assignment on PCH, no TBF exist (IMSI=001001000000001) -DL_TBF(DL:TFI-0-1-0:STATE-NEW:GPRS:IMSI-001001000000001:TLLI-0xa3c2f953){NEW}: Received Event ASSIGN_ADD_CCCH -TBF(DL:TFI-0-1-0:STATE-NEW:GPRS:IMSI-001001000000001:TLLI-0xa3c2f953) set ass. type CCCH [prev CCCH:0, PACCH:0] -DL_TBF(DL:TFI-0-1-0:STATE-NEW:GPRS:IMSI-001001000000001:TLLI-0xa3c2f953){NEW}: state_chg to ASSIGN -TBF(DL:TFI-0-1-0:STATE-ASSIGN:GPRS:IMSI-001001000000001:TLLI-0xa3c2f953) TX: START Immediate Assignment Downlink (PCH) - - TRX=1 (0) TS=5 TA=220 -PDCH(bts=0,trx=0,ts=1) PDCH state: disabled => enabled -PDCH(bts=0,trx=0,ts=2) PDCH state: disabled => enabled -PDCH(bts=0,trx=0,ts=3) PDCH state: disabled => enabled -Creating MS object -Modifying MS object, UL TLLI: 0xffffffff -> 0xecc1f953, not yet confirmed -MS(TLLI-0xecc1f953:TA-220:MSCLS-0-0) ********** UL-TBF starts here ********** -MS(TLLI-0xecc1f953:TA-220:MSCLS-0-0) Allocating UL TBF -UL_ASS_TBF{NONE}: Allocated -DL_ASS_TBF{NONE}: Allocated -UL_TBF{NEW}: Allocated -UL_ACK_TBF{NONE}: Allocated -[UL] algo B <single> (suggested TRX: 0): Alloc start -Found first unallocated TRX=0 TFI=0 -- Skipping TS 0, because not enabled -- Skipping TS 4, because not enabled -- Skipping TS 5, because not enabled -- Skipping TS 6, because not enabled -- Skipping TS 7, because not enabled -- Possible DL/UL slots: (TS=0)".CCC...."(TS=7) -Rx=4 Tx=4 Sum Rx+Tx=5, Tta=2 Ttb=1, Tra=2 Trb=1, Type=1 -- Skipping TS 3, because num TBFs 0 >= 0 -Selected UL slots: (TS=0)"..U.uu.."(TS=7), single -[UL] algo B <single> (suggested TRX: 0): using single slot at TS 2 -- Reserved DL/UL slots: (TS=0)"..C.DDD."(TS=7) -- Assigning UL TS 2 -PDCH(bts=0,trx=0,ts=2) Attaching TBF(UL:TFI-0-0-0:STATE-NEW:GPRS:TLLI-0xecc1f953), 1 TBFs, USFs = 01, TFIs = 00000001. -TBF(UL:TFI-0-0-0:STATE-NEW:GPRS:TLLI-0xecc1f953) Setting Control TS PDCH(bts=0,trx=0,ts=2) -TBF(UL:TFI-0-0-0:STATE-NEW:GPRS:TLLI-0xecc1f953) Allocated: trx = 0, ul_slots = 04, dl_slots = 00 -MS(TLLI-0xecc1f953:TA-220:MSCLS-0-0) Attaching UL TBF: TBF(UL:TFI-0-0-0:STATE-NEW:GPRS:TLLI-0xecc1f953) -MS(TLLI-0xecc1f953:TA-220:MSCLS-0-0:UL): + tbf: now used by 1 (tbf) -There is a new MS object for the same MS: (0xa3c2f953, '001001000000001') -> (0xecc1f953, '') -MS(IMSI-001001000000001:TLLI-0xa3c2f953:TA-220:MSCLS-11-0:DL): + ms_merge_and_clear_ms: now used by 2 (tbf,ms_merge_and_clear_ms) -MS(TLLI-0xecc1f953:TA-220:MSCLS-0-0:UL) Merge MS: MS(IMSI-001001000000001:TLLI-0xa3c2f953:TA-220:MSCLS-11-0:DL) -Modifying MS object, TLLI = 0xecc1f953, MS class 0 -> 11 -MS(IMSI-001001000000001:TLLI-0xa3c2f953:TA-220:MSCLS-11-0:DL) Clearing MS object -TBF(DL:TFI-0-1-0:STATE-ASSIGN:GPRS:IMSI-001001000000001:TLLI-0xa3c2f953) free -PDCH(bts=0,trx=1,ts=5) Detaching TBF(DL:TFI-0-1-0:STATE-ASSIGN:GPRS:IMSI-001001000000001:TLLI-0xa3c2f953), 1 TBFs, USFs = 00, TFIs = 00000001. -MS(IMSI-001001000000001:TLLI-0xa3c2f953:TA-220:MSCLS-11-0:DL) Detaching TBF: TBF(DL:TFI-0-1-0:STATE-ASSIGN:GPRS:IMSI-001001000000001:TLLI-0xa3c2f953) -MS(IMSI-001001000000001:TLLI-0xa3c2f953:TA-220:MSCLS-11-0): - tbf: now used by 1 (ms_merge_and_clear_ms) -********** DL-TBF ends here ********** -DL_TBF(DL:TFI-0-1-0:STATE-NEW:GPRS:IMSI-001001000000001:TLLI-0xa3c2f953){ASSIGN}: Deallocated -UL_ASS_TBF(DL:TFI-0-1-0:STATE-NEW:GPRS:IMSI-001001000000001:TLLI-0xa3c2f953){NONE}: Deallocated -DL_ASS_TBF(DL:TFI-0-1-0:STATE-NEW:GPRS:IMSI-001001000000001:TLLI-0xa3c2f953){NONE}: Deallocated -MS(TA-220:MSCLS-11-0): - ms_merge_and_clear_ms: now used by 0 (-) -MS(TA-220:MSCLS-11-0) Destroying MS object -Modifying MS object, TLLI: 0xecc1f953 confirmed -MS(IMSI-001001000000001:TLLI-0xecc1f953:TA-220:MSCLS-11-0:UL) appending 19 bytes to DL LLC queue -MS(IMSI-001001000000001:TLLI-0xecc1f953:TA-220:MSCLS-11-0:UL) ********** DL-TBF starts here ********** -MS(IMSI-001001000000001:TLLI-0xecc1f953:TA-220:MSCLS-11-0:UL) Allocating DL TBF -UL_ASS_TBF{NONE}: Allocated -DL_ASS_TBF{NONE}: Allocated -DL_TBF{NEW}: Allocated -[DL] algo B <multi> (suggested TRX: 0): Alloc start -Found first unallocated TRX=0 TFI=0 -Selected DL slots: (TS=0)".DDDddd."(TS=7), multi -[DL] algo B <multi> (suggested TRX: 0): using 3 slots -- Assigning DL TS 1 -PDCH(bts=0,trx=0,ts=1) Attaching TBF(DL:TFI-0-0-0:STATE-NEW:GPRS:IMSI-001001000000001:TLLI-0xecc1f953), 1 TBFs, USFs = 00, TFIs = 00000001. -- Assigning DL TS 2 -PDCH(bts=0,trx=0,ts=2) Attaching TBF(DL:TFI-0-0-0:STATE-NEW:GPRS:IMSI-001001000000001:TLLI-0xecc1f953), 1 TBFs, USFs = 01, TFIs = 00000001. -- Assigning DL TS 3 -PDCH(bts=0,trx=0,ts=3) Attaching TBF(DL:TFI-0-0-0:STATE-NEW:GPRS:IMSI-001001000000001:TLLI-0xecc1f953), 1 TBFs, USFs = 00, TFIs = 00000001. -TBF(DL:TFI-0-0-0:STATE-NEW:GPRS:IMSI-001001000000001:TLLI-0xecc1f953) Setting Control TS PDCH(bts=0,trx=0,ts=2) -TBF(DL:TFI-0-0-0:STATE-NEW:GPRS:IMSI-001001000000001:TLLI-0xecc1f953) Allocated: trx = 0, ul_slots = 04, dl_slots = 0e -MS(IMSI-001001000000001:TLLI-0xecc1f953:TA-220:MSCLS-11-0:UL) Attaching DL TBF: TBF(DL:TFI-0-0-0:STATE-NEW:GPRS:IMSI-001001000000001:TLLI-0xecc1f953) -MS(IMSI-001001000000001:TLLI-0xecc1f953:TA-220:MSCLS-11-0:UL:DL): + tbf: now used by 2 (2*tbf) -TBF(DL:TFI-0-0-0:STATE-NEW:GPRS:IMSI-001001000000001:TLLI-0xecc1f953) [DOWNLINK] START (PACCH) -TBF(DL:TFI-0-0-0:STATE-NEW:GPRS:IMSI-001001000000001:TLLI-0xecc1f953) Send downlink assignment on PACCH, because TBF(UL:TFI-0-0-0:STATE-NEW:GPRS:IMSI-001001000000001:TLLI-0xecc1f953) exists -DL_ASS_TBF(UL:TFI-0-0-0:STATE-NEW:GPRS:IMSI-001001000000001:TLLI-0xecc1f953){NONE}: Received Event SCHED_ASS -DL_ASS_TBF(UL:TFI-0-0-0:STATE-NEW:GPRS:IMSI-001001000000001:TLLI-0xecc1f953){NONE}: state_chg to SEND_ASS -DL_TBF(DL:TFI-0-0-0:STATE-NEW:GPRS:IMSI-001001000000001:TLLI-0xecc1f953){NEW}: Received Event ASSIGN_ADD_PACCH -TBF(DL:TFI-0-0-0:STATE-NEW:GPRS:IMSI-001001000000001:TLLI-0xecc1f953) set ass. type PACCH [prev CCCH:0, PACCH:0] -DL_TBF(DL:TFI-0-0-0:STATE-NEW:GPRS:IMSI-001001000000001:TLLI-0xecc1f953){NEW}: state_chg to ASSIGN -TBF(DL:TFI-0-0-0:STATE-ASSIGN:GPRS:IMSI-001001000000001:TLLI-0xecc1f953) Starting timer X2001 [assignment (PACCH)] with 2 sec. 0 microsec -DL_TBF(DL:TFI-0-0-0:STATE-NEW:GPRS:IMSI-001001000000001:TLLI-0xecc1f953){ASSIGN}: Received Event ASSIGN_PCUIF_CNF -TBF(DL:TFI-0-0-0:STATE-ASSIGN:GPRS:IMSI-001001000000001:TLLI-0xecc1f953) Ignoring event ASSIGN_PCUIF_CNF from BTS (CCCH was not requested on current assignment) -DL_ASS_TBF(UL:TFI-0-0-0:STATE-NEW:GPRS:IMSI-001001000000001:TLLI-0xecc1f953){SEND_ASS}: Received Event CREATE_RLCMAC_MSG -PDCH(bts=0,trx=0,ts=2) POLL scheduled at FN 0 + 13 = 13 -TBF(UL:TFI-0-0-0:STATE-NEW:GPRS:IMSI-001001000000001:TLLI-0xecc1f953) start Packet Downlink Assignment (PACCH) for TBF(DL:TFI-0-0-0:STATE-ASSIGN:GPRS:IMSI-001001000000001:TLLI-0xecc1f953) -+++++++++++++++++++++++++ TX : Packet Downlink Assignment +++++++++++++++++++++++++ -------------------------- TX : Packet Downlink Assignment ------------------------- -PDCH(bts=0,trx=0,ts=2) Reserving FN 13 for type POLL -TBF(UL:TFI-0-0-0:STATE-NEW:GPRS:IMSI-001001000000001:TLLI-0xecc1f953) Scheduled DL Assignment polling on PACCH (FN=13, TS=2) -DL_ASS_TBF(UL:TFI-0-0-0:STATE-NEW:GPRS:IMSI-001001000000001:TLLI-0xecc1f953){SEND_ASS}: state_chg to WAIT_ACK -PDCH(bts=0,trx=0,ts=2) FN=0 Scheduling control message at RTS for TBF(UL:TFI-0-0-0:STATE-NEW:GPRS:IMSI-001001000000001:TLLI-0xecc1f953) -=== end test_ms_merge_dl_tbf_different_trx === -MS(IMSI-001001000000001:TLLI-0xecc1f953:TA-220:MSCLS-11-0:UL:DL) Destroying MS object -MS(IMSI-001001000000001:TLLI-0xecc1f953:TA-220:MSCLS-11-0:UL:DL) Detaching TBF: TBF(UL:TFI-0-0-0:STATE-NEW:GPRS:IMSI-001001000000001:TLLI-0xecc1f953) -MS(IMSI-001001000000001:TLLI-0xecc1f953:TA-220:MSCLS-11-0:DL): - tbf: now used by 1 (tbf) -MS(IMSI-001001000000001:TLLI-0xecc1f953:TA-220:MSCLS-11-0:DL) Detaching TBF: TBF(DL:TFI-0-0-0:STATE-ASSIGN:GPRS:IMSI-001001000000001:TLLI-0xecc1f953) -MS(IMSI-001001000000001:TLLI-0xecc1f953:TA-220:MSCLS-11-0): - tbf: now used by 0 (-) +================================================================= +==9645==ERROR: AddressSanitizer: heap-use-after-free on address 0xb2954d24 at pc 0x006153dd bp 0xbef931c0 sp 0xbef931c4 +READ of size 4 at 0xb2954d24 thread T0 + #0 0x6153da in gprs_rlcmac_tbf::name(bool) const (/build/osmo-pcu-1.2.0.47-f978/_build/sub/tests/tbf/TbfTest+0x1f53da) + #1 0x614454 in tbf_name (/build/osmo-pcu-1.2.0.47-f978/_build/sub/tests/tbf/TbfTest+0x1f4454) + #2 0x60796a in tbf_timeout_free(gprs_rlcmac_tbf*, tbf_timers, bool) (/build/osmo-pcu-1.2.0.47-f978/_build/sub/tests/tbf/TbfTest+0x1e796a) + #3 0x607ad4 in cb_T3191(void*) (/build/osmo-pcu-1.2.0.47-f978/_build/sub/tests/tbf/TbfTest+0x1e7ad4) + +0xb2954d24 is located 2852 bytes inside of 23728-byte region [0xb2954200,0xb2959eb0) +freed by thread T0 here: + #0 0xb6b0756e in __interceptor_free ../../../../src/libsanitizer/asan/asan_malloc_linux.cpp:123 + +previously allocated by thread T0 here: + #0 0xb6b07752 in __interceptor_malloc ../../../../src/libsanitizer/asan/asan_malloc_linux.cpp:145 + +SUMMARY: AddressSanitizer: heap-use-after-free (/build/osmo-pcu-1.2.0.47-f978/_build/sub/tests/tbf/TbfTest+0x1f53da) in gprs_rlcmac_tbf::name(bool) const +Shadow bytes around the buggy address: + 0x3652a950: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd + 0x3652a960: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd + 0x3652a970: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd + 0x3652a980: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd + 0x3652a990: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd +=>0x3652a9a0: fd fd fd fd[fd]fd fd fd fd fd fd fd fd fd fd fd + 0x3652a9b0: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd + 0x3652a9c0: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd + 0x3652a9d0: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd + 0x3652a9e0: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd + 0x3652a9f0: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd +Shadow byte legend (one shadow byte represents 8 application bytes): + Addressable: 00 + Partially addressable: 01 02 03 04 05 06 07 + Heap left redzone: fa + Freed heap region: fd + Stack left redzone: f1 + Stack mid redzone: f2 + Stack right redzone: f3 + Stack after return: f5 + Stack use after scope: f8 + Global redzone: f9 + Global init order: f6 + Poisoned by user: f7 + Container overflow: fc + Array cookie: ac + Intra object redzone: bb + ASan internal: fe + Left alloca redzone: ca + Right alloca redzone: cb + Shadow gap: cc +==9645==ABORTING stdout: ../../../tests/testsuite.at:28: exit code was 1, expected 0 4. testsuite.at:25: 4. tbf (testsuite.at:25): FAILED (testsuite.at:28) Build step 'Execute shell' marked build as failure $ ssh-agent -k unset SSH_AUTH_SOCK; unset SSH_AGENT_PID; echo Agent pid 9961 killed; [ssh-agent] Stopped. Archiving artifacts