View Issue Details

Jump to NotesJump to History
IDProjectCategoryView StatusDate SubmittedLast Update
0002672GNUnetpublic2012-11-28 20:312012-12-21 16:49
ReporterChristian Grothoff Assigned ToSree Harsha Totakura  
PrioritynormalSeveritycrashReproducibilitysometimes
Status closedResolutionfixed 
Product VersionGit master 
Target Version0.9.5Fixed in Version0.9.5 
Summary0002672: test_gnunet_service_fs_p2p_stream fails on some system with assertion failures in mesh/stream
DescriptionNov 28 20:20:04-662513 mesh-2539 WARNING External protocol violation detected at gnunet-service-mesh.c:5951.
Nov 28 20:20:04-662946 fs-2523 WARNING External protocol violation detected at stream_api.c:2903.
Nov 28 20:20:04-684922 fs-2523 WARNING Message `External protocol violation detected at stream_api.c:2903.' repeated 1 times in the last 22 ms
Nov 28 20:20:04-684922 mesh-api-2523 WARNING ACK on unknown tunnel B0000001
Nov 28 20:20:04-710123 fs-2523 WARNING External protocol violation detected at stream_api.c:2903.
Nov 28 20:20:04-710359 mesh-api-2523 WARNING ACK on unknown tunnel B0000002
Nov 28 20:20:04-742176 fs-2523 WARNING External protocol violation detected at stream_api.c:2903.
Nov 28 20:20:04-994304 fs-2523 WARNING Message `External protocol violation detected at stream_api.c:2903.' repeated 4 times in the last 252 ms
Nov 28 20:20:04-994304 mesh-api-2523 WARNING ACK on unknown tunnel B0000007
Nov 28 20:20:05-154431 fs-2523 WARNING External protocol violation detected at stream_api.c:2903.
Nov 28 20:20:05-154503 mesh-api-2523 WARNING ACK on unknown tunnel B0000008
Nov 28 20:20:05-448534 fs-2523 WARNING External protocol violation detected at stream_api.c:2903.
Nov 28 20:20:05-448613 mesh-api-2523 WARNING ACK on unknown tunnel B0000009
Nov 28 20:20:05-992417 fs-2523 WARNING External protocol violation detected at stream_api.c:2903.
Nov 28 20:20:05-992648 fs-2523 ERROR Assertion failed at mesh_api.c:2163.
Nov 28 20:20:07-045878 fs-2570 WARNING External protocol violation detected at stream_api.c:2903.
Nov 28 20:20:07-046042 mesh-api-2570 WARNING ACK on unknown tunnel B000000B
Nov 28 20:20:09-125206 fs-2570 WARNING External protocol violation detected at stream_api.c:2903.
Nov 28 20:20:09-125480 mesh-api-2570 WARNING ACK on unknown tunnel B000000C
Nov 28 20:20:13-251808 fs-2570 WARNING External protocol violation detected at stream_api.c:2903.
Nov 28 20:20:13-251883 mesh-api-2570 WARNING ACK on unknown tunnel B000000D
Nov 28 20:20:21-484115 fs-2570 WARNING External protocol violation detected at stream_api.c:2903.
Nov 28 20:20:21-484260 fs-2570 ERROR Assertion failed at mesh_api.c:2163.
Nov 28 20:20:37-913386 fs-2581 WARNING External protocol violation detected at stream_api.c:2903.
Nov 28 20:21:10-744122 fs-2581 WARNING Message `External protocol violation detected at stream_api.c:2903.' repeated 1 times in the last 32 s
Nov 28 20:21:10-744122 mesh-api-2581 WARNING ACK on unknown tunnel B0000010
Nov 28 20:22:16-381943 fs-2581 WARNING External protocol violation detected at stream_api.c:2903.
Nov 28 20:25:04-625382 test-gnunet-service-fs-p2p-2500 ERROR Timeout while trying to download file
FAIL: test_gnunet_service_fs_p2p_stream
TagsNo tags attached.

Activities

Bart Polot

2012-12-05 13:59

reporter   ~0006642

It looks like stream is the first to complain about something going on:

PASS: test_gnunet_service_fs_p2p
Dec 05 13:39:54-838582 mesh-26996 INFO Mesh for peer [FC74] starting
Dec 05 13:39:54-881000 mesh-27006 INFO Mesh for peer [KJI3] starting
Dec 05 13:39:56-199558 fs-26994 WARNING External protocol violation detected at stream_api.c:2903.
Dec 05 13:39:56-732739 mesh-26996 WARNING External protocol violation detected at gnunet-service-mesh.c:5951.
Dec 05 13:44:56-162163 test-gnunet-service-fs-p2p-26964 ERROR Timeout while trying to download file
Dec 05 13:44:56-163211 mesh-26996 WARNING Message `External protocol violation detected at gnunet-service-mesh.c:5951.' repeated 4 times in the last 299 s
Dec 05 13:44:56-163211 mesh-26996 INFO Mesh for peer [FC74] FWD ACKs 0, BCK ACKs 0
Dec 05 13:44:56-170325 fs-26994 WARNING Message `External protocol violation detected at stream_api.c:2903.' repeated 18 times in the last 299 s
Dec 05 13:44:56-170325 mesh-api-26994 INFO Sent 35 ACKs
Dec 05 13:44:56-171978 mesh-api-26994 INFO Recv 94 ACKs

Dec 05 13:44:56-172793 mesh-27006 INFO Mesh for peer [KJI3] FWD ACKs 0, BCK ACKs 0
FAIL: test_gnunet_service_fs_p2p_stream


On top of that I see planty of core files for:
[bart@ranger ~/g/src/fs]$ gdb --core core.27205 /tmp/gnunet/lib/gnunet/libexec/gnunet-service-fs
GNU gdb (GDB) 7.5
Copyright (C) 2012 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law. Type "show copying"
and "show warranty" for details.
This GDB was configured as "x86_64-unknown-linux-gnu".
For bug reporting instructions, please see:
<http://www.gnu.org/software/gdb/bugs/>...
Reading symbols from /tmp/gnunet/lib/gnunet/libexec/gnunet-service-fs...done.

warning: core file may not match specified executable file.
[New LWP 27205]

warning: Could not load shared library symbols for linux-vdso.so.1.
Do you need "set solib-search-path" or "set sysroot"?
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/usr/lib/libthread_db.so.1".
Core was generated by `/tmp/gnunet/lib/gnunet/libexec/gnunet-service-fs -c /tmp/testbedXAgNS1/1/config'.
Program terminated with signal 11, Segmentation fault.
#0 0x00007f699accf387 in handle_ack (socket=0xe7ce80, tunnel=0xe7d4d0,
    sender=0x7fff7f24b510, ack=0x7fff7f24b550, atsi=0x7fff7f24b3e0) at stream_api.c:2607
2607 (socket->write_handle->messages[packet]->sequence_number)
(gdb) bt
#0 0x00007f699accf387 in handle_ack (socket=0xe7ce80, tunnel=0xe7d4d0,
    sender=0x7fff7f24b510, ack=0x7fff7f24b550, atsi=0x7fff7f24b3e0) at stream_api.c:2607
#1 0x00007f699accf608 in client_handle_ack (cls=0xe7ce80, tunnel=0xe7d4d0,
    tunnel_ctx=0xe7d518, sender=0x7fff7f24b510, message=0x7fff7f24b550,
    atsi=0x7fff7f24b3e0) at stream_api.c:2677
#2 0x00007f699aabf149 in process_incoming_data (h=0xe7d0c0, message=0x7fff7f24b4c0)
    at mesh_api.c:1212
#3 0x00007f699aabffdb in msg_received (cls=0xe7d0c0, msg=0x7fff7f24b4c0)
    at mesh_api.c:1424
#4 0x00007f699a23e2c4 in receive_task (cls=0xe7d2f0, tc=0x7fff7f24b610) at client.c:597
#5 0x00007f699a277a8d in run_ready (rs=0xe453c0, ws=0xe45450) at scheduler.c:597
#6 0x00007f699a278259 in GNUNET_SCHEDULER_run (task=0x7f699a284ef0 <service_task>,
    task_cls=0x7fff7f24b9b0) at scheduler.c:785
#7 0x00007f699a2869fe in GNUNET_SERVICE_run (argc=3, argv=0x7fff7f24bc18,
    service_name=0x41a74b "fs", options=GNUNET_SERVICE_OPTION_NONE,
    task=0x40545e <run>, task_cls=0x0) at service.c:1813
#8 0x00000000004056c6 in main (argc=3, argv=0x7fff7f24bc18) at gnunet-service-fs.c:709

I'll keep looking into it, anyway, the mesh warning means "ACK received on unknown tunnel" so it might be mesh's fault still...

Bart Polot

2012-12-06 13:20

reporter   ~0006646

All the core files are created for the fs service crashing in "handle_ack" in the stream library, therefore I think Sree Harsha should look into it...

Bart Polot

2012-12-10 13:38

reporter   ~0006663

Last edited: 2012-12-10 13:39

 ./perf_gnunet_service_fs_p2p_dht 2>&1 | tee log
Dec 10 13:32:04-275503 fs-11545 WARNING External protocol violation detected at stream_api.c:2903.
Dec 10 13:32:04-305965 fs-11545 WARNING Message `External protocol violation detected at stream_api.c:2903.' repeated 1 times in the last 30 ms
Dec 10 13:32:04-305965 fs-11545 ERROR Assertion failed at mesh_api.c:2225.
Peer 0: fs/ # replies received and matched = 323
Peer 0: fs/ # replies received for local clients = 323
Peer 0: core/ # bytes decrypted = 10778130
Peer 0: core/ # bytes encrypted = 154268
Peer 0: transport/ # bytes received via TCP = 10804102
Peer 0: transport/ # bytes transmitted via TCP = 158204
Peer 0: datacache/ # bytes stored = 136
Peer 1: fs/ # replies received and matched = 335
Peer 1: core/ # bytes decrypted = 154268
Peer 1: core/ # bytes encrypted = 10778130
Peer 1: transport/ # bytes received via TCP = 158068
Peer 1: transport/ # bytes transmitted via TCP = 10804238
Peer 1: datacache/ # bytes stored = 136
Download speed was 16 MiB/s
[bart@saturn ~/g/src/fs]$

mesh_api.c:2225 (first check of GNUNET_MESH_notify_transmit_ready(tunnel, ...)) reads:
  GNUNET_assert (NULL != tunnel);

So stream is calling mesh transmit ready with a NULL tunnel. This is not good...

Bart Polot

2012-12-10 14:18

reporter   ~0006665

Last edited: 2012-12-10 14:18

 More logs for this are available in description/notes of bug 2660.

Sree Harsha Totakura

2012-12-10 14:34

updater   ~0006666

I cannot reproduce 'Assertion failed at mesh_api.c:2225'. Do you still get it on your system?

Bart Polot

2012-12-10 14:38

reporter   ~0006667

(gdb) bt full
#0 0x00007fa7811f1fd5 in raise () from /usr/lib/libc.so.6
No symbol table info available.
#1 0x00007fa7811f3458 in abort () from /usr/lib/libc.so.6
No symbol table info available.
#2 0x00007fa78262f494 in GNUNET_abort () at common_logging.c:293
No locals.
#3 0x00007fa782eb17f1 in GNUNET_MESH_notify_transmit_ready (tunnel=0x0, cork=0, maxdelay=..., target=0x19e88a8,
    notify_size=32804, notify=0x7fa7830b6df0 <send_message_notify>, notify_cls=0x19e8840) at mesh_api.c:2225
        th = 0x2af00419b2f
        overhead = 140357423786100
        __FUNCTION__ = "GNUNET_MESH_notify_transmit_ready"
#4 0x00007fa7830b7a4c in queue_message (socket=0x19e8840, message=0x1a2dac0, finish_cb=0x0, finish_cb_cls=0x0, urgent=0)
    at stream_api.c:709
        queue_entity = 0x1a79630
        __FUNCTION__ = "queue_message"
#5 0x00007fa7830b7adb in copy_and_queue_message (socket=0x19e8840, message=0x1a25a90, finish_cb=0x0, finish_cb_cls=0x0)
    at stream_api.c:741
        msg_copy = 0x1a2dac0
        size = 32804
#6 0x00007fa7830b82b2 in write_data (socket=0x19e8840) at stream_api.c:928
        io_handle = 0x1a7c5d0
        packet = 0
        __FUNCTION__ = "write_data"
#7 0x00007fa7830c062e in GNUNET_STREAM_write (socket=0x19e8840, data=0x7fffb79594a0, size=32784, timeout=...,
    write_cont=0x4199c1 <write_continuation>, write_cont_cls=0x1a7d2d0) at stream_api.c:3548
        io_handle = 0x1a7c5d0
        data_msg = 0x1a25a90
        sweep = 0x7fffb79614b0
        ack_deadline = {rel_value = 5000}
        num_needed_packets = 1
        packet = 1
        packet_size = 32804
        payload_size = 32784
        max_data_packet_size = 64020
        __FUNCTION__ = "GNUNET_STREAM_write"
#8 0x0000000000419df4 in handle_datastore_reply (cls=0x1a7d2d0, key=0x7fffb7961680, size=32768, data=0x7fffb79616c0,
    type=GNUNET_BLOCK_TYPE_FS_DBLOCK, priority=42, anonymity=0, expiration=..., uid=148)
    at gnunet-service-fs_stream.c:1158
        sc = 0x1a7d2d0
        msize = 32784
        buf = 0x7fffb79594a0 "\200\020"
        srm = 0x7fffb79594a0
        __FUNCTION__ = "handle_datastore_reply"
#9 0x00007fa783b1a489 in process_result_message (cls=0x19abfe0, msg=0x7fffb7961650) at datastore_api.c:1232
        h = 0x19abfe0
        qe = 0x19e3250
        rc = {proc = 0x419b2f <handle_datastore_reply>, proc_cls = 0x1a7d2d0}
        dm = 0x7fffb7961650
        was_transmitted = 1101127724
        __FUNCTION__ = "process_result_message"
#10 0x00007fa783b17c72 in receive_cb (cls=0x19abfe0, msg=0x7fffb7961650) at datastore_api.c:582
        h = 0x19abfe0
        qe = 0x19e3250
        __FUNCTION__ = "receive_cb"
#11 0x00007fa78262c3b4 in receive_task (cls=0x1999bc0, tc=0x7fffb7969760) at client.c:597
        client = 0x1999bc0
        handler = 0x7fa783b17acd <receive_cb>
        cmsg = 0x19d0410
        handler_cls = 0x19abfe0
        msize = 32880
        mbuf = 0x7fffb7961650 "\200p"
        msg = 0x7fffb7961650
        __FUNCTION__ = "receive_task"
#12 0x00007fa782665c29 in run_ready (rs=0x19993a0, ws=0x1999430) at scheduler.c:597
        p = GNUNET_SCHEDULER_PRIORITY_DEFAULT
        pos = 0x1a6d500
        tc = {reason = GNUNET_SCHEDULER_REASON_TIMEOUT, read_ready = 0x19993a0, write_ready = 0x1999430}
        __FUNCTION__ = "run_ready"
#13 0x00007fa7826663f5 in GNUNET_SCHEDULER_run (task=0x7fa78267308c <service_task>, task_cls=0x7fffb7969b00)
    at scheduler.c:785
        rs = 0x19993a0
        ws = 0x1999430
        timeout = {rel_value = 0}
        ret = 0
---Type <return> to continue, or q <return> to quit---
        shc_int = 0x19994c0
        shc_term = 0x1999570
        shc_quit = 0x19996d0
        shc_hup = 0x1999780
        shc_pipe = 0x1999620
        last_tr = 2509
        busy_wait_warning = 0
        pr = 0x1999370
        c = 0 '\000'
        __FUNCTION__ = "GNUNET_SCHEDULER_run"
#14 0x00007fa782674b9a in GNUNET_SERVICE_run (argc=3, argv=0x7fffb7969d68, service_name=0x41a74b "fs",
    options=GNUNET_SERVICE_OPTION_NONE, task=0x40545e <run>, task_cls=0x0) at service.c:1813
        err = 0
        ret = 3
        cfg_fn = 0x1997260 "/tmp/testbedJVab8l/0/config"
        loglev = 0x0
        logfile = 0x0
        do_daemonize = 0
        i = 4215902
        skew_offset = 140357452435824
        skew_variance = 1
        clock_offset = 3
        sctx = {cfg = 0x1997000, server = 0x1999890, addrs = 0x0, service_name = 0x41a74b "fs", task = 0x40545e <run>,
          task_cls = 0x0, v4_denied = 0x0, v6_denied = 0x0, v4_allowed = 0x1999330, v6_allowed = 0x19a23c0,
          my_handlers = 0x19a6280, addrlens = 0x0, lsocks = 0x19992b0, shutdown_task = 4, timeout = {
            rel_value = 18446744073709551615}, ret = 1, ready_confirm_fd = -1, require_found = 1, match_uid = 0,
          match_gid = 1, options = GNUNET_SERVICE_OPTION_NONE}
        cfg = 0x1997000
        service_options = {{shortName = 99 'c', name = 0x7fa782680505 "config",
            argumentHelp = 0x7fa78268050c "FILENAME", description = 0x7fa782680518 "use configuration file FILENAME",
            require_argument = 1, processor = 0x7fa782655687 <GNUNET_GETOPT_set_string>, scls = 0x7fffb7969bb8}, {
            shortName = 100 'd', name = 0x7fa782680538 "daemonize", argumentHelp = 0x0,
            description = 0x7fa782680548 "do daemonize (detach from terminal)", require_argument = 0,
            processor = 0x7fa78265565a <GNUNET_GETOPT_set_one>, scls = 0x7fffb7969ba4}, {shortName = 104 'h',
            name = 0x7fa78268056c "help", argumentHelp = 0x0, description = 0x7fa782680571 "print this help",
            require_argument = 0, processor = 0x7fa78265511a <GNUNET_GETOPT_format_help_>, scls = 0x0}, {
            shortName = 76 'L', name = 0x7fa782680581 "log", argumentHelp = 0x7fa782680585 "LOGLEVEL",
            description = 0x7fa782680590 "configure logging to use LOGLEVEL", require_argument = 1,
            processor = 0x7fa782655687 <GNUNET_GETOPT_set_string>, scls = 0x7fffb7969bb0}, {shortName = 108 'l',
            name = 0x7fa7826805b2 "logfile", argumentHelp = 0x7fa7826805ba "LOGFILE",
            description = 0x7fa7826805c8 "configure logging to write logs to LOGFILE", require_argument = 1,
            processor = 0x7fa782655687 <GNUNET_GETOPT_set_string>, scls = 0x7fffb7969ba8}, {shortName = 118 'v',
            name = 0x7fa7826805f3 "version", argumentHelp = 0x0,
            description = 0x7fa7826805fb "print the version number", require_argument = 0,
            processor = 0x7fa7826550d4 <GNUNET_GETOPT_print_version_>, scls = 0x7fa782680614}, {shortName = 0 '\000',
            name = 0x0, argumentHelp = 0x0, description = 0x0, require_argument = 0, processor = 0x0, scls = 0x0}}
        __FUNCTION__ = "GNUNET_SERVICE_run"
#15 0x00000000004056c6 in main (argc=3, argv=0x7fffb7969d68) at gnunet-service-fs.c:709
No locals.

Sree Harsha Totakura

2012-12-10 15:12

updater   ~0006668

I believe this is fixed in SVN 25357. Please confirm

Bart Polot

2012-12-10 15:15

reporter   ~0006669

I get this:

Dec 10 15:10:14-233322 fs-10164 ERROR Assertion failed at stream_api.c:3462.
Dec 10 15:10:14-233344 stream-api-10164 WARNING Closing STREAM socket when a write handle is pending

But no core dumps anymore and the test seems to pass.

Sree Harsha Totakura

2012-12-10 15:32

updater   ~0006670

Christian is hacking FS to resolve it.

Sree Harsha Totakura

2012-12-11 11:57

updater   ~0006671

This should be fixed in SVN 25387. Please confirm.

Christian Grothoff

2012-12-11 16:57

manager   ~0006673

I now get:

Dec 11 16:50:20-131753 test-gnunet-service-fs-p2p-25723 ERROR Assertion failed at testbed_api_testbed.c:929.
/bin/bash: line 5: 25723 Aborted ${dir}$tst
FAIL: test_gnunet_service_fs_p2p

I believe you should allow a NULL argument here, and just not invoke any callback if you were given NULL.

Sree Harsha Totakura

2012-12-11 22:26

updater   ~0006674

ok, fixed it now in SVN 25400.

Christian Grothoff

2012-12-11 22:54

manager   ~0006675

Ok, I confirm it all works now on my systems.

Issue History

Date Modified Username Field Change
2012-11-28 20:31 Christian Grothoff New Issue
2012-11-28 20:31 Christian Grothoff Status new => assigned
2012-11-28 20:31 Christian Grothoff Assigned To => Bart Polot
2012-12-05 13:59 Bart Polot Note Added: 0006642
2012-12-06 13:19 Bart Polot Assigned To Bart Polot => Sree Harsha Totakura
2012-12-06 13:20 Bart Polot Category mesh service => stream library
2012-12-06 13:20 Bart Polot Note Added: 0006646
2012-12-09 17:11 Christian Grothoff Target Version => 0.9.5
2012-12-10 13:38 Bart Polot Note Added: 0006663
2012-12-10 13:39 Bart Polot Note Edited: 0006663
2012-12-10 14:18 Bart Polot Note Added: 0006665
2012-12-10 14:18 Bart Polot Note Edited: 0006665
2012-12-10 14:34 Sree Harsha Totakura Note Added: 0006666
2012-12-10 14:38 Bart Polot Note Added: 0006667
2012-12-10 15:12 Sree Harsha Totakura Note Added: 0006668
2012-12-10 15:12 Sree Harsha Totakura Status assigned => feedback
2012-12-10 15:15 Bart Polot Note Added: 0006669
2012-12-10 15:32 Sree Harsha Totakura Note Added: 0006670
2012-12-11 11:57 Sree Harsha Totakura Note Added: 0006671
2012-12-11 16:57 Christian Grothoff Note Added: 0006673
2012-12-11 16:57 Christian Grothoff Status feedback => assigned
2012-12-11 22:26 Sree Harsha Totakura Note Added: 0006674
2012-12-11 22:54 Christian Grothoff Note Added: 0006675
2012-12-11 22:54 Christian Grothoff Status assigned => resolved
2012-12-11 22:54 Christian Grothoff Fixed in Version => 0.9.5
2012-12-11 22:54 Christian Grothoff Resolution open => fixed
2012-12-21 16:49 Christian Grothoff Status resolved => closed
2014-12-15 19:13 Christian Grothoff Category stream library => (No Category)