Cellular Network Infrastructure » Core Network (CN) » OsmoBSCNAT

I can easily reproduce it running latest master of all osmocom related projects.

During investigation, I already submited several patches that I think are not directly related but were catched during code reading:
https://gerrit.osmocom.org/#/c/7746
https://gerrit.osmocom.org/#/c/7749

The code running during the backtrace below has the following extra changes built-in:

diff --git a/openbsc/src/osmo-bsc_nat/bsc_nat_ctrl.c b/openbsc/src/osmo-bsc_nat/bsc_nat_ctrl.c
index 738ac87..f454185 100644
--- a/openbsc/src/osmo-bsc_nat/bsc_nat_ctrl.c
+++ b/openbsc/src/osmo-bsc_nat/bsc_nat_ctrl.c
@@ -142,6 +142,7 @@ int bsc_nat_handle_ctrlif_msg(struct bsc_connection *bsc, struct msgb *msg)
                /* Find the pending command */
                pending = bsc_get_pending(bsc, cmd->id);
                if (pending) {
+                       LOGP(DNAT, LOGL_ERROR, "CTRL cmd pending found, patching\n");
                        osmo_talloc_replace_string(cmd, &cmd->id, pending->cmd->id);
                        if (!cmd->id) {
                                cmd->type = CTRL_TYPE_ERROR;
@@ -161,6 +162,8 @@ int bsc_nat_handle_ctrlif_msg(struct bsc_connection *bsc, struct msgb *msg)
                                goto err;
                        }
                }
+       } else {
+               LOGP(DNAT, LOGL_ERROR, "CTRL: list empty? bsc->cfg=%p\n", bsc->cfg);
        }
        talloc_free(cmd);
        return 0;

As a result, the message printed can be seen before the crash, and bsc_nat_ctrl.c:168 points to the talloc_free immediately before the "err" goto tag.
During investigation I at least once saw the execution of the code with the output "CTRL: list empty? bsc->cfg=(nil)", which didn't crash. Also receival of TRAP messages doesn't crash. So the bug seems to be related to the pending struct that is bsc-nat related.

talloc aborts with a clear "Bad talloc magic value - access after free" message.

<0015> /home/data/pespin/git/openbsc/openbsc/src/osmo-bsc_nat/bsc_nat.c:1328 MSG from BSC: 00 6a ee 00 54 52 41 50 20 30 20 62 74 73 2e 30 2e 6c 6f 63 61 74 69 6f 6e 2d 73 74 61 74 65 20 31 35 32 33 34 34 36 37 33 38 2c 69 6e 76 61 6c 69 64 2c 30 2e 30 30 30 30 30 30 2c 30 2e 30 30 30 30 30 30 2c 30 2e 30 30 30 30 30 30 2c 6f 70 65 72 61 74 69 6f 6e 61 6c 2c 75 6e 6c 6f 63 6b 65 64 2c 6f 66 66 2c 32 37 34 2c 30 38  proto: 0
<0025> /home/data/pespin/git/libosmocore/src/ctrl/control_cmd.c:439 Command: TRAP bts.0.location-state: 1523446738,invalid,0.000000,0.000000,0.000000,operational,unlocked,off,274,08
<0025> /home/data/pespin/git/libosmocore/src/ctrl/control_cmd.c:411 Command: SET net.0.bsc_cfg.0.no-access-list-name = "1" 
<0025> /home/data/pespin/git/libosmocore/src/ctrl/control_cmd.c:411 Command: SET net.0.bsc.0.mcc-mnc-apply = "274,08" 
<0025> /home/data/pespin/git/libosmocore/src/ctrl/control_cmd.c:411 Command: SET net.0.bsc.0.rf_locked = "1" 
<0015> /home/data/pespin/git/openbsc/openbsc/src/osmo-bsc_nat/bsc_nat.c:1328 MSG from BSC: 00 2a ee 00 53 45 54 5f 52 45 50 4c 59 20 31 20 6d 63 63 2d 6d 6e 63 2d 61 70 70 6c 79 20 4e 6f 74 68 69 6e 67 20 63 68 61 6e 67 65 64  proto: 0
<0025> /home/data/pespin/git/libosmocore/src/ctrl/control_cmd.c:438 Command: SET REPLY mcc-mnc-apply: Nothing changed
<0015> /home/data/pespin/git/openbsc/openbsc/src/osmo-bsc_nat/bsc_nat_ctrl.c:145 CTRL cmd pending found, patching

Program received signal SIGABRT, Aborted.
0x00007ffff6950067 in __GI_raise (sig=sig@entry=6) at ../nptl/sysdeps/unix/sysv/linux/raise.c:56
56      ../nptl/sysdeps/unix/sysv/linux/raise.c: No such file or directory.
(gdb) bt
#0  0x00007ffff6950067 in __GI_raise (sig=sig@entry=6) at ../nptl/sysdeps/unix/sysv/linux/raise.c:56
#1  0x00007ffff6951448 in __GI_abort () at abort.c:89
#2  0x00007ffff79a769c in talloc_abort (reason=0x7ffff79b4248 "Bad talloc magic value - access after free") at ../talloc.c:340
#3  0x00007ffff79a6a37 in talloc_abort_access_after_free () at ../talloc.c:359
#4  talloc_chunk_from_ptr (ptr=0x7f59b0) at ../talloc.c:380
#5  _talloc_free (ptr=0x7f59b0, location=0x45cea0 "/home/data/pespin/git/openbsc/openbsc/src/osmo-bsc_nat/bsc_nat_ctrl.c:168") at ../talloc.c:1572
#6  0x00000000004163d4 in bsc_nat_handle_ctrlif_msg (bsc=0x77bf60, msg=0x7d9440)
    at /home/data/pespin/git/openbsc/openbsc/src/osmo-bsc_nat/bsc_nat_ctrl.c:168
#7  0x000000000040d385 in ipaccess_bsc_read_cb (bfd=0x77bf88) at /home/data/pespin/git/openbsc/openbsc/src/osmo-bsc_nat/bsc_nat.c:1353
#8  0x00007ffff73127e3 in osmo_wqueue_bfd_cb (fd=0x77bf88, what=1) at /home/data/pespin/git/libosmocore/src/write_queue.c:51
#9  0x00007ffff730c634 in osmo_fd_disp_fds (_rset=0x7fffffffe9b0, _wset=0x7fffffffe930, _eset=0x7fffffffe8b0)
    at /home/data/pespin/git/libosmocore/src/select.c:216
#10 0x00007ffff730c7a4 in osmo_select_main (polling=0) at /home/data/pespin/git/libosmocore/src/select.c:256
#11 0x000000000040e17e in main (argc=3, argv=0x7fffffffeb78) at /home/data/pespin/git/openbsc/openbsc/src/osmo-bsc_nat/bsc_nat.c:1713

(gdb) frame 6
#6  0x00000000004163d4 in bsc_nat_handle_ctrlif_msg (bsc=0x77bf60, msg=0x7d9440)
    at /home/data/pespin/git/openbsc/openbsc/src/osmo-bsc_nat/bsc_nat_ctrl.c:168
168             talloc_free(cmd);
(gdb) print *cmd
$1 = {ccon = 0x0, type = CTRL_TYPE_SET_REPLY, id = 0x7bef50 "1", node = 0x0, variable = 0x7f5b60 "net.0.bsc.0.mcc-mnc-apply", value = 0x0,
  reply = 0x7f5ae0 "Nothing changed", defer = 0x0}
(gdb) print *pending
$2 = {list_entry = {next = 0x100100, prev = 0x200200}, timeout = {node = {rb_parent_color = 8347520, rb_right = 0x0, rb_left = 0x0}, list = {
      next = 0x7f70a8, prev = 0x7f70a8}, timeout = {tv_sec = 1523446757, tv_usec = 988566}, active = 0, cb = 0x41640a <pending_timeout_cb>,
    data = 0x7f7080}, nat_id = 1, ccon = 0x77c1a0, cmd = 0x1110}