Assertion failure in dgram

[clowwindy]

node 0.10.15, Debian 6

This assertion failure happened once after running half a day with about 2k QPS.

node: ../deps/uv/src/unix/udp.c:267: uv__udp_sendmsg: Assertion `!(&handle->write_queue == (&handle->write_queue)->prev) || !(&handle->write_completed_queue == (&handle->write_completed_queue)->prev)' failed.

The only place in my app using UDP is statsd, which is a simple module that only does UDP socket.send().

[ronkorving]

I'm getting this problem too on v0.10.17, have not been able to find the cause yet. It does however seem to be related to my worker processes. Without cluster, this doesn't seem to happen.

Apparently my app is doing lots of udp listening, because my workers emit that they're listening on address:

{
    "address": "0.0.0.0",
    "port": 51916,
    "addressType": "udp4",
    "fd": -1
  }

The error:

../deps/uv/src/unix/udp.c:267: uv__udp_sendmsg: Assertion `!(&handle->write_queue == (&handle->write_queue)->prev) || !(&handle->write_completed_queue == (&handle->write_completed_queue)->prev)' failed.

For me, it's caused by the graylog module.

[bnoordhuis]

Can one of you get me a backtrace full from gdb, either from a live instance or a core dump? In particular, I'd like to know what print *handle prints when you execute it in the uv__udp_sendmsg frame (which should be the stack frame that's right before libc's assert code.) Maybe run set print pretty and set pagination off first. :-)

[ronkorving]

(gdb) backtrace full
#0  0x00000034da030285 in raise () from /lib64/libc.so.6
No symbol table info available.
#1  0x00000034da031d30 in abort () from /lib64/libc.so.6
No symbol table info available.
#2  0x00000034da029706 in __assert_fail () from /lib64/libc.so.6
No symbol table info available.
#3  0x00000000006e740f in uv__udp_sendmsg (loop=0xe25140, w=0x2aaaac0018a0, revents=<value optimized out>) at ../deps/uv/src/unix/udp.c:266
        handle = 0x2aaaac001850
#4  uv__udp_io (loop=0xe25140, w=0x2aaaac0018a0, revents=<value optimized out>) at ../deps/uv/src/unix/udp.c:182
No locals.
#5  0x00000000006e8602 in uv__io_poll (loop=0xe25140, timeout=801) at ../deps/uv/src/unix/linux-core.c:211
        events = {{events = 1, data = 3}, {events = 4, data = 66}, {events = 4, data = 80}, {events = 4, data = 70}, {events = 4, data = 59}, {events = 4, data = 71}, {events = 1, data = 78}, {events = 4, data = 59}, {events = 4, data = 71}, {events = 1, data = 78}, {events = 8708536, data = 720664382345838592}, {events = 0, data = 140734512364208}, {events = 167792752, data = 723651136963215360}, {events = 0, data = 140734512362687}, {events = 1318976176, data = 5664959540123172863}, {events = 32767, data = 140734512362687}, {events = 0, data = 37352329845932032}, {events = 0, data = 140734512364248}, {events = 8699240, data = 5718945393543217152}, {events = 14490, data = 168457280}, {events = 1318976216, data = 36310602708189183}, {events = 0, data = 168488080}, {events = 1, data = 723518508373117479}, {events = 0, data = 2}, {events = 1331545760, data = 5664959540123154586}, {events = 32767, data = 140734512362687}, {events = 1318974655, data = 5664936072421867519}, {events = 32767, data = 140734512362687}, {events = 0, data = 37361456651436032}, {events = 0, data = 1}, {events = 1318970176, data = 60266981130239}, {events = 0, data = 8617926}, {events = 1318976176, data = 5664953007477915647}, {events = 16383, data = 54235859272625}, {events = 168456944, data = 49898930044928}, {events = 0, data = 8454221}, {events = 0, data = 5664959540123140096}, {events = 32767, data = 140734512362687}, {events = 1318974655, data = 5664936072421867519}, {events = 32767, data = 140734512362687}, {events = 0, data = 37367967821856768}, {events = 0, data = 8642759777752973317}, {events = 167792752, data = 5664959540123140096}, {events = 32767, data = 140734512362687}, {events = 1, data = 5664936072421834752}, {events = 32767, data = 140734512362687}, {events = 8700986, data = 14204834192344219648}, {events = 12627, data = 70364456995370}, {events = 168457280, data = 7274229467482947584}, {events = 1507, data = 140734512358384}, {events = 1318970424, data = 723621072192176127}, {events = 0, data = 140734512358720}, {events = 1318974655, data = 5664959540123172863}, {events = 32767, data = 1}, {events = 1318970712, data = 5664953007477915647}, {events = 32767, data = 8702452}, {events = 168481160, data = 36454286544076800}, {events = 0, data = 168456944}, {events = 5, data = 48737433449136128}, {events = 0, data = 168456944}, {events = 5, data = 4087779216102260736}, {events = 965117150, data = 0}, {events = 1, data = 723517065280880640}, {events = 0, data = 17179869189}, {events = 1318976216, data = 14204426896300605439}, {events = 12627, data = 167792752}, {events = 1318974655, data = 5664959540123172863}, {events = 32767, data = 1}, {events = 1318970712, data = 4295000063}, {events = 0, data = 0}, {events = 8706588, data = 720939466411212800}, {events = 0, data = 9109176}, {events = 0, data = 37262315921342464}, {events = 0, data = 167792752}, {events = 1318976176, data = 5664959540123172863}, {events = 32767, data = 140734512362687}, {events = 1318970712, data = 4295000063}, {events = 0, data = 0}, {events = 8707042, data = 0}, {events = 0, data = 9110391}, {events = 1318976176, data = 5664959540123172863}, {events = 32767, data = 2}, {events = 8669953, data = 720664382345838592}, {events = 0, data = 140734512362687}, {events = 1318976176, data = 5664953007477915647}, {events = 32767, data = 168481288}, {events = 8708536, data = 720664382345838592}, {events = 0, data = 140734512359800}, {events = 1318974607, data = 723622068624588799}, {events = 0, data = 2594}, {events = 1318976176, data = 723621381429821439}, {events = 0, data = 140734512362687}, {events = 1318970832, data = 5664936656537419775}, {events = 32767, data = 140734512364248}, {events = 8699240, data = 5664936862695817216}, {events = 32767, data = 140734512359000}, {events = 0, data = 723622274782986240}, {events = 0, data = 168481288}, {events = 8487258, data = 14204848490290351627}, {events = 12627, data = 168457280}, {events = 3307324017, data = 723517065264116051}, {events = 0, data = 2514}, {events = 1318976176, data = 5664953007477915647}, {events = 32767, data = 140734512362687}, {events = 0, data = 5664953007477882880}, {events = 32767, data = 3591}, {events = 8700408, data = 14204848490290348032}, {events = 12627, data = 168456944}, {events = 1318976176, data = 5664953007477915647}, {events = 32767, data = 1}, {events = 0, data = 5664953007477882880}, {events = 32767, data = 8700986}, {events = 3307324040, data = 34359750995}, {events = 32767, data = 140733193388033}, {events = 8629365, data = 34359738368}, {events = 186098212, data = 167792752}, {events = 1693663529, data = 10797547783651}, {events = 0, data = 140734512362687}, {events = 1318976176, data = 4295000063}, {events = 0, data = 0}, {events = 1318974655, data = 37376746735042559}, {events = 0, data = 54235859439345}, {events = 1693663529, data = 5664938305804830179}, {events = 32767, data = 140734512359336}, {events = 1318972552, data = 5664952801319485439}, {events = 32767, data = 0}, {events = 8487258, data = 5664940607907299328}, {events = 32767, data = 72057594037927937}, {events = 167792768, data = 5664952801319452672}, {events = 4, data = 140734512360584}, {events = 8487675, data = 723517065264103424}, {events = 0, data = 140734512362687}, {events = 1318976176, data = 4295000063}, {events = 0, data = 0}, {events = 1, data = 15423227559936}, {events = 0, data = 8706588}, {events = 1318976216, data = 4295000063}, {events = 1507, data = 140734512359440}, {events = 3307324017, data = 14204881784876839251}, {events = 12627, data = 46912518504080}, {events = 14902, data = 36310602708156416}, {events = 0, data = 0}, {events = 1, data = 12393974962719817728}, {events = 10922, data = 4}, {events = 3307331792, data = 17179881811}, {events = 32767, data = 54232552046593}, {events = 8629365, data = 17179869184}, {events = 93097645, data = 167792752}, {events = 1693663529, data = 64003602646499}, {events = 0, data = 2}, {events = 1318971616, data = 64003602677759}, {events = 0, data = 8617926}, {events = 3591, data = 39128831398772736}, {events = 16383, data = 54235859425553}, {events = 2885697168, data = 17295833311914}, {events = 0, data = 8454221}, {events = 0, data = 5664970737102880768}, {events = 32767, data = 46912518504080}, {events = 9, data = 14205084571757707264}, {events = 12627, data = 9}, {events = 1, data = 37062840460247040}, {events = 0, data = 7731835297746386953}, {events = 167792752, data = 7274229467482947584}, {events = 1507, data = 4027}, {events = 2, data = 5664940710986514432}, {events = 32767, data = 4027}, {events = 8617926, data = 720664451065315328}, {events = 0, data = 70364456995370}, {events = 2885697168, data = 7274229467482958506}, {events = 1507, data = 140734512359824}, {events = 1318971864, data = 12394278771526500351}, {events = 10922, data = 140734512360160}, {events = 1318972144, data = 36452495542747135}, {events = 0, data = 46912518504080}, {events = 167792768, data = 720664451065315328}, {events = 0, data = 0}, {events = 2885767904, data = 36454286544087722}, {events = 0, data = 46912518504080}, {events = 9, data = 48737433449136128}, {events = 0, data = 46912518504080}, {events = 9, data = 13124965863784448000}, {events = 965117150, data = 0}, {events = 7785002, data = 12393974962719817728}, {events = 10922, data = 9}, {events = 1318980344, data = 14205084472973492223}, {events = 12627, data = 167792752}, {events = 7647979, data = 21474836480}, {events = 0, data = 140734512368376}, {events = 2885697168, data = 38654716586}, {events = 150994944, data = 1}, {events = 111, data = 5664977269748137984}, {events = 32767, data = 140734512366815}, {events = 0, data = 37262315921342464}, {events = 0, data = 167792752}, {events = 4294967295, data = 12393974962719817728}, {events = 10922, data = 46912518558848}, {events = 167997928, data = 0}, {events = 0, data = 46912518574888}, {events = 9901438, data = 721545606555762688}, {events = 0, data = 1}...}
        pe = <value optimized out>
        e = {events = 0, data = 15710545457400774656}
        q = <value optimized out>
        w = <value optimized out>
        base = 14294200163
        diff = <value optimized out>
        nevents = <value optimized out>
        count = 48
        nfds = 6
        fd = <value optimized out>
        op = <value optimized out>
        i = <value optimized out>
        __PRETTY_FUNCTION__ = "uv__io_poll"
#6  0x00000000006dc3a0 in uv_run (loop=0xe25140, mode=<value optimized out>) at ../deps/uv/src/unix/core.c:317
        timeout = <value optimized out>
        r = <value optimized out>
#7  0x000000000059d41d in node::Start(int, char**) ()
No symbol table info available.
#8  0x00000034da01d994 in __libc_start_main () from /lib64/libc.so.6
No symbol table info available.
#9  0x0000000000594069 in _start ()
No symbol table info available.

[ronkorving]

That looks like a very unhealthy situation. I'm guessing the problem arises from every single log message creating a fresh new udp4 socket (I have no idea why it was designed like that).

[ronkorving]

If you need more output, like when you asked for "In particular, I'd like to know what print *handle prints when you execute it in the uv__udp_sendmsg frame", could you give me some pointers as to how I can get there? I don't use gdb a lot (or ever).

[wcummings]

Seeing this on v0.10.15 (w/ the lynx statsd client)

[indutny]

I believe the fix will be released soon: joyent/libuv@29fdb34

[indutny]

Fixed in joyent/libuv@29fdb34, fix will be included in next v0.10 release.