View Issue Details

Jump to NotesJump to History
IDProjectCategoryView StatusDate SubmittedLast Update
0004710GNUnetcadet servicepublic2016-10-09 23:042018-06-07 00:24
Reporterjah Assigned ToChristian Grothoff  
PrioritylowSeverityminorReproducibilityalways
Status closedResolutionfixed 
Platformx86_64OSTrisquelOS Version7.0, Belenos
Product VersionGit master 
Target Version0.11.0pre66Fixed in Version0.11.0pre66 
Summary0004710: Double free in GCC_send_prebuilt_message during testing and with DROP enabled
DescriptionA CadetConnectionQueue is new'd in GCC_send_prebuilt_message and freed twice when a retransmitted AX message was forcibly dropped. This is what I believe happens:

- GCC_send_prebuilt_message malloc's a CadetConnectionQueue (q) and calls GCP_send, passing the q as the closure for the continuation conn_message_sent
- GCP_send does new CadetPeerQueue and sets its cont and cont_cls with the conn_message_sent and q received as args
- GCP_send decides to drop the message and calls call_peer_cont, passing the CadetPeerQueue handle
- call_peer_cont calls the conn_message_sent continuation, passing our q as its closure arg
- conn_message_sent **frees q** and later returns to call_peer_cont and thence to GCP_send
- GCP_send returns NULL to GCC_send_prebuilt_message
- GCC_send_prebuilt_message **frees q** (again)
Steps To Reproducecd src/cadet; ./test_cadet_5_speed_reliable
Additional InformationOct 09 20:18:14-095284 cadet-con-29917 INFO --> { AX} ({retransmit} 0) on conn A00MQPQG (0x5624c27b8c70) FWD [ 144]
Oct 09 20:18:14-095292 cadet-con-29917 DEBUG Q_N+ 0x5624c27b8c78 1
Oct 09 20:18:14-095298 cadet-con-29917 DEBUG last pid sent 0
Oct 09 20:18:14-095303 cadet-con-29917 DEBUG ack recv 75
Oct 09 20:18:14-095310 cadet-con-29917 DEBUG C_P+ A00MQPQG 2
Oct 09 20:18:14-095320 cadet-con-29917 DEBUG get next hop A00MQPQG [3/5]
Oct 09 20:18:14-095327 cadet-con-29917 DEBUG ID: TY5J (2)
Oct 09 20:18:14-095341 cadet-p2p-29917 DEBUG que { AX} ({retransmit} 0) on conn A00MQPQG (0x5624c27b8c70) FWD towards TY5J (size 144)
Oct 09 20:18:14-095352 cadet-p2p-29917 WARNING DD { AX} ({retransmit} 0) on conn A00MQPQG FWD
Oct 09 20:18:14-095362 cadet-p2p-29917 DEBUG core mq just sent { AX}
Oct 09 20:18:14-095370 cadet-p2p-29917 DEBUG calling callback, time elapsed 21 µs
Oct 09 20:18:14-095376 cadet-con-29917 DEBUG connection message_sent
Oct 09 20:18:14-095384 cadet-con-29917 DEBUG CCC DEBUG CONNECTION A00MQPQG
Oct 09 20:18:14-095394 cadet-con-29917 DEBUG CCC path 6DEV 6YNB DK5W G3FK TY5J, own pos: 3
Oct 09 20:18:14-095402 cadet-con-29917 DEBUG CCC state: CADET_CONNECTION_READY, destroy: 0
Oct 09 20:18:14-095410 cadet-con-29917 DEBUG CCC pending messages: 3
Oct 09 20:18:14-095417 cadet-con-29917 DEBUG CCC FWD flow control:
Oct 09 20:18:14-095423 cadet-con-29917 DEBUG CCC queue: 2/3
Oct 09 20:18:14-095430 cadet-con-29917 DEBUG CCC last PID sent: 0, recv: 8
Oct 09 20:18:14-095437 cadet-con-29917 DEBUG CCC last ACK sent: 10, recv: 75
Oct 09 20:18:14-095443 cadet-con-29917 DEBUG CCC recv PID bitmap: 1FF
Oct 09 20:18:14-095454 cadet-con-29917 DEBUG CCC poll: task 0, msg (nil), msg_ack (nil))
Oct 09 20:18:14-095459 cadet-con-29917 DEBUG CCC BCK flow control:
Oct 09 20:18:14-095465 cadet-con-29917 DEBUG CCC queue: 0/3
Oct 09 20:18:14-095473 cadet-con-29917 DEBUG CCC last PID sent: 0, recv: 15
Oct 09 20:18:14-095479 cadet-con-29917 DEBUG CCC last ACK sent: 15, recv: 10
Oct 09 20:18:14-095487 cadet-con-29917 DEBUG CCC recv PID bitmap: FFFF
Oct 09 20:18:14-095492 cadet-con-29917 DEBUG CCC poll: task 0, msg (nil), msg_ack 0x5624c27ce8d0)
Oct 09 20:18:14-095498 cadet-con-29917 DEBUG CCC DEBUG CONNECTION END
Oct 09 20:18:14-095507 cadet-con-29917 DEBUG not sent FWD { AX} pid 3241210816
Oct 09 20:18:14-095515 cadet-con-29917 DEBUG C_P- 0x5624c27b8c70 3
Oct 09 20:18:14-095521 cadet-con-29917 DEBUG ! Q_N- 0x5624c27b8c78 2
Oct 09 20:18:14-095527 cadet-con-29917 DEBUG ! accounting pid 0
Oct 09 20:18:14-095534 cadet-con-29917 DEBUG ! message sent!
Oct 09 20:18:14-095541 cadet-con-29917 DEBUG dropping msg on A00MQPQG, NULL q

-- No more output from pid 29917 --

gdb lib/gnunet/libexec/gnunet-service-cadet core-gnunet-service--29917-1476040694

#0 0x00007f054164bc37 in __GI_raise (sig=sig@entry=6)
    at ../nptl/sysdeps/unix/sysv/linux/raise.c:56
        resultvar = 0
        pid = 29917
        selftid = 29917
#1 0x00007f054164f028 in __GI_abort () at abort.c:89
        save_stage = 2
        act = {__sigaction_handler = {sa_handler = 0x7ffc1a38ce30,
            sa_sigaction = 0x7ffc1a38ce30}, sa_mask = {__val = {140720748416864, 0,
              139660549197281, 18446744073709551615, 139660567776752, 0, 0,
              140720748416928, 140720748417312, 139660552389056, 139660548910738, 0,
              139660567428991, 140720748416928, 140720748417288, 140720748417264}},
          sa_flags = -1074013952, sa_restorer = 0x7ffc1a38d030}
        sigs = {__val = {32, 0 <repeats 15 times>}}
#2 0x00007f05416882a4 in __libc_message (do_abort=do_abort@entry=1,
    fmt=fmt@entry=0x7f05417966b0 "*** Error in `%s': %s: 0x%s ***\n")
    at ../sysdeps/posix/libc_fatal.c:175
        ap = {{gp_offset = 40, fp_offset = 0, overflow_arg_area = 0x7ffc1a38d200,
            reg_save_area = 0x7ffc1a38d190}}
        fd = 15
        on_2 = <optimised out>
        list = <optimised out>
        nlist = <optimised out>
        cp = <optimised out>
        written = <optimised out>
#3 0x00007f054169455e in malloc_printerr (ptr=<optimised out>,
    str=0x7f0541796878 "double free or corruption (fasttop)", action=1) at malloc.c:4996
        buf = "00005624c27cef40"
        cp = <optimised out>
#4 _int_free (av=<optimised out>, p=<optimised out>, have_lock=0) at malloc.c:3840
        size = <optimised out>
        fb = <optimised out>
        nextchunk = <optimised out>
        nextsize = <optimised out>
        nextinuse = <optimised out>
        prevsize = <optimised out>
        bck = <optimised out>
        fwd = <optimised out>
        errstr = <optimised out>
        locked = <optimised out>
#5 0x00005624c10e5ecb in GCC_send_prebuilt_message (
    message=message@entry=0x7ffc1a38d3b4, payload_type=payload_type@entry=0,
    payload_id=payload_id@entry=0, c=c@entry=0x5624c27b8c70, fwd=fwd@entry=1,
    force=force@entry=0, cont=cont@entry=0x0, cont_cls=cont_cls@entry=0x0)
    at gnunet-service-cadet_connection.c:3347
        axmsg = <optimised out>
        amsg = <optimised out>
        pmsg = <optimised out>
        bmsg = <optimised out>
        fc = 0x5624c27b8c78
        q = 0x5624c27cef40
        copy = 0x5624c27ceea0
        size = <optimised out>
        type = <optimised out>
        droppable = <optimised out>
        __FUNCTION__ = "GCC_send_prebuilt_message"
#6 0x00005624c10ebf00 in GCC_handle_encrypted (peer=0x5624c27b80e0, msg=0x7ffc1a38d3b4)
    at gnunet-service-cadet_connection.c:2659
        cid = 0x7ffc1a38d3bc
        c = 0x5624c27b8c70
        fwd = 1
        __FUNCTION__ = "GCC_handle_encrypted"
#7 0x00007f0542827977 in receive_task (cls=0x5624c27bc3a0) at client.c:610
        client = 0x5624c27bc3a0
        handler = 0x7f0542854ab0 <handle_client_message>
        cmsg = 0x5624c27ccff0
        handler_cls = 0x5624c27bc440
        msize = 180
        mbuf = 0x7ffc1a38d390 ""
        msg = 0x7ffc1a38d390
        __FUNCTION__ = "receive_task"
#8 0x00007f0542866048 in run_ready (ws=0x5624c27b9a40, rs=0x5624c27b99b0)
    at scheduler.c:620
        p = GNUNET_SCHEDULER_PRIORITY_DEFAULT
        pos = 0x5624c27ced60
#9 GNUNET_SCHEDULER_run (task=task@entry=0x7f054286db90 <service_task>,
    task_cls=task_cls@entry=0x7ffc1a38d610) at scheduler.c:887
        rs = 0x5624c27b99b0
        ws = 0x5624c27b9a40
        timeout = <optimised out>
        ret = <optimised out>
        shc_int = 0x5624c27b9af0
        shc_term = 0x5624c27b9bb0
        shc_quit = 0x5624c27b9d30
        shc_hup = 0x5624c27b9df0
        shc_pipe = 0x5624c27b9c70
        last_tr = 608
        busy_wait_warning = 0
        pr = 0x5624c27bcae0
        c = 0 '\000'
        __FUNCTION__ = "GNUNET_SCHEDULER_run"
#10 0x00007f054287133f in GNUNET_SERVICE_run (argc=<optimised out>,
    argv=<optimised out>, service_name=0x5624c1107e4b "cadet", options=<optimised out>,
    task=<optimised out>, task_cls=<optimised out>) at service.c:1497
        err = 0
        ret = <optimised out>
        cfg_fn = 0x5624c27b3700 "~/.config/gnunet.conf"
        opt_cfg_fn = 0x5624c27b3850 "/tmp/testbed9lC2L9/3/config"
        loglev = 0x0
        logfile = 0x0
        do_daemonize = 0
        i = <optimised out>
        skew_offset = 0
        skew_variance = 0
        clock_offset = <optimised out>
        sctx = {cfg = 0x5624c27b3720, server = 0x5624c27ba240, addrs = 0x0,
          service_name = 0x5624c1107e4b "cadet", task = 0x5624c1102750 <run>,
          task_cls = 0x0, v4_denied = 0x0, v6_denied = 0x0, v4_allowed = 0x5624c27b4820,
          v6_allowed = 0x5624c27cb7a0, my_handlers = 0x5624c27c3fd0, addrlens = 0x0,
          lsocks = 0x5624c27be0a0, shutdown_task = 0x5624c27ba2d0, timeout = {
            rel_value_us = 18446744073709551615}, ret = 1, ready_confirm_fd = -1,
          require_found = 1, match_uid = 1, match_gid = 1,
          options = GNUNET_SERVICE_OPTION_NONE}
        cfg = 0x5624c27b3720
        xdg = <optimised out>
        service_options = {{shortName = 99 'c', name = 0x7f0542885183 "config",
            argumentHelp = 0x7f054288518a "FILENAME",
            description = 0x7f0542885238 "use configuration file FILENAME",
            require_argument = 1, processor = 0x7f0542851040 <GNUNET_GETOPT_set_string>,
            scls = 0x7ffc1a38d5b0}, {shortName = 100 'd',
            name = 0x7f0542886a7b "daemonize", argumentHelp = 0x0,
            description = 0x7f0542886dd8 "do daemonize (detach from terminal)",
            require_argument = 0, processor = 0x7f0542851000 <GNUNET_GETOPT_set_one>,
            scls = 0x7ffc1a38d5a4}, {shortName = 104 'h', name = 0x7f054288519e "help",
            argumentHelp = 0x0, description = 0x7f0542885193 "print this help",
            require_argument = 0,
            processor = 0x7f0542850c10 <GNUNET_GETOPT_format_help_>, scls = 0x0}, {
            shortName = 76 'L', name = 0x7f05428851a3 "log",
            argumentHelp = 0x7f05428851a7 "LOGLEVEL",
            description = 0x7f0542885258 "configure logging to use LOGLEVEL",
            require_argument = 1, processor = 0x7f0542851040 <GNUNET_GETOPT_set_string>,
            scls = 0x7ffc1a38d5b8}, {shortName = 108 'l',
            name = 0x7f05428851b0 "logfile", argumentHelp = 0x7f0542880e91 "LOGFILE",
            description = 0x7f0542885280 "configure logging to write logs to LOGFILE",
            require_argument = 1, processor = 0x7f0542851040 <GNUNET_GETOPT_set_string>,
            scls = 0x7ffc1a38d5c0}, {shortName = 118 'v',
            name = 0x7f05428851b8 "version", argumentHelp = 0x0,
            description = 0x7f05428851c0 "print the version number",
            require_argument = 0,
            processor = 0x7f0542850bc0 <GNUNET_GETOPT_print_version_>,
            scls = 0x7f05428851d9}, {shortName = 0 '\000', name = 0x0,
            argumentHelp = 0x0, description = 0x0, require_argument = 0,
            processor = 0x0, scls = 0x0}}
        __FUNCTION__ = "GNUNET_SERVICE_run"
#11 0x00005624c10d595a in main (argc=<optimised out>, argv=<optimised out>)
    at gnunet-service-cadet.c:173
        r = <optimised out>

And to illustrate that the CadetConnectionQueue was previously freed (and poisoned):-

(gdb) f 5
#5 0x00005624c10e5ecb in GCC_send_prebuilt_message (
    message=message@entry=0x7ffc1a38d3b4, payload_type=payload_type@entry=0,
    payload_id=payload_id@entry=0, c=c@entry=0x5624c27b8c70, fwd=fwd@entry=1,
    force=force@entry=0, cont=cont@entry=0x0, cont_cls=cont_cls@entry=0x0)
    at gnunet-service-cadet_connection.c:3347
3347 GNUNET_free (q);

(gdb) x/4xg q
0x5624c27cef40: 0x0df0adba0df0adba 0x0df0adba0df0adba
0x5624c27cef50: 0x0df0adba0df0adba 0x0df0adba0df0adba

(gdb) p q->peer_q
$1 = (struct CadetPeerQueue *) 0xdf0adba0df0adba

(gdb) p q->cont
$2 = (GCC_sent) 0xdf0adba0df0adba

(gdb) p q->cont_cls
$3 = (void *) 0xdf0adba0df0adba

(gdb) p q->forced
$4 = 233876922 (0x0DF0ADBA)
TagsNo tags attached.

Activities

Christian Grothoff

2017-02-21 18:24

manager   ~0011805

No longer relevant after CADET rewrite.

Issue History

Date Modified Username Field Change
2016-10-09 23:04 jah New Issue
2016-10-09 23:04 jah Status new => assigned
2016-10-09 23:04 jah Assigned To => Bart Polot
2017-02-21 18:24 Christian Grothoff Assigned To Bart Polot => Christian Grothoff
2017-02-21 18:24 Christian Grothoff Status assigned => resolved
2017-02-21 18:24 Christian Grothoff Resolution open => fixed
2017-02-21 18:24 Christian Grothoff Fixed in Version => 0.11.0pre66
2017-02-21 18:24 Christian Grothoff Note Added: 0011805
2017-02-21 18:24 Christian Grothoff Target Version => 0.11.0pre66
2018-06-07 00:24 Christian Grothoff Status resolved => closed