See
<https://jenkins.osmocom.org/jenkins/job/master-osmo-pcu/FIRMWARE_VERSION=master,WITH_MANUALS=0,label=rpi4-raspbian11,with_dsp=none,with_vty=False/5719/display/redirect?page=changes>
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(a)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