search

eggheads / eggdrop

The Eggdrop IRC Bot
GNU General Public License v2.0
509 stars 84 forks source link

Truncation (partial write) of output to foreground STDOUT #665

Closed michaelortmann closed 6 years ago

michaelortmann commented 6 years ago

If i type .help all or other commands resulting in long output, i see truncated output.

I see that behaviour with NetBSD Version 8.0, 7.1.2, 7.0.2 and 6.1.6 when ssh is involved.

Other versions not tested.

It could well happen under other systems also.

I don't see it with FreeBSD and OpenBSD.

And i only see it when sshing into the NetBSD system or out of the NetBSD system, or sshing to itself.

Direct login works fine.

I did ./eggdrop -nt

I can always reproduce the bug.

The truncated output looks like this:

.help all
[03:03:28] #-HQ# help all
###  core commands
   For all users:
      who          away         quit         whom
      me           page         match        motd
      bots         newpass      chat         handle
      whoami       echo         strip        su
      trace        fixcodes     bottree      vbottree
      botinfo      relay        -host
   For ops:
      addlog       console      match        whois
   For botnet masters:
      +bot         botattr      chhandle     chpass
      +host        -bot         link         chaddr
      boot         unlink       banner       dccstat
   For channel masters:
      chattr       save         backup       reload
      status       traffic      uptime
   For global masters:
      +user        +ignore      comment      binds
      ignores      -user        -ignore      dccstat
      debug        rehash       restart      module
   For owners:
      die          simul        loadmod      unloadmod
      language     set          tcl

(last line 1 trailing whitespace, no newline)

Additional information:

.whoami
You are -HQ@netbsd.
.whois -HQ
[03:10:14] #-HQ# whois -HQ
HANDLE                           PASS NOTES FLAGS           LAST
-HQ                              no       0 efjlmnoptuvx    03:03 (partyline)

The truncation happens after ~969 chars. The truncation also happens when i insert a long debug printf. It only happens for foreground chat, it doesnt when telnet to the bot. It only happens for ssh login to the system, it doesnt when direct login. The truncation happens from different terminals, even non-x terminal. It also happens, when i ssh from the netbsd machine to a freebsd machine. So the direction of ssh doesnt matter as long as any NetBSD system is involved.

When i tested eggdrop 1.8.2 instead of git version, i got the same truncated output, but also a coredump (this example is under NetBSD 7.1.2):

.help all
[23:32:24] #-HQ# help all
###  core commands
   For all users:
      who          away         quit         whom
      me           page         match        motd
      bots         newpass      chat         handle
      whoami       echo         strip        su
      trace        fixcodes     bottree      vbottree
      botinfo      relay        -host
   For ops:
      addlog       console      match        whois
   For botnet masters:
      +bot         botattr      chhandle     chpass
      +host        -bot         link         chaddr
      boot         unlink       banner       dccstat
   For channel masters:
      chattr       save         backup       reload
      status       traffic      uptime
   For global masters:
      +user        +ignore      comment      binds
      ignores      -user        -ignore      dccstat
      debug        rehash       restart      module
   For owners:
      die          simul        loadmod      unloadmod
      language     set          tcl [1]   Illegal instruction (core dumped) ./eggdrop -nt
(gdb) bt
#0  0x00007f7ff5ab8c36 in __vfprintf_unlocked_l () from /usr/lib/libc.so.12
#1  0x00007f7ff5aaeb9f in vsnprintf_l () from /usr/lib/libc.so.12
#2  0x00007f7ff5aaece2 in snprintf () from /usr/lib/libc.so.12
#3  0x00007f7ff5af7cd1 in ?? () from /usr/lib/libc.so.12
#4  0x00007f7ff5af7dd9 in _citrus_lookup_seq_open () from /usr/lib/libc.so.12
#5  0x00007f7ff5af7eda in _citrus_lookup_simple () from /usr/lib/libc.so.12
#6  0x00007f7ff5aaef3c in catopen_l () from /usr/lib/libc.so.12
#7  0x00007f7ff5aae9c5 in _strerror_lr () from /usr/lib/libc.so.12
#8  0x00007f7ff5af10dc in strerror_l () from /usr/lib/libc.so.12
#9  0x000000000042e3d2 in safe_write (fd=1, buf=<optimized out>, count=111) at net.c:802
#10 0x00000000004219f9 in dprintf_eggdrop (arg1=arg1@entry=1) at dccutil.c:203
#11 0x000000000042a2a1 in putlog (arg1=32) at misc.c:625
#12 0x00000000004219f9 in dprintf_eggdrop (arg1=arg1@entry=1) at dccutil.c:203
#13 0x000000000042a2a1 in putlog (arg1=32) at misc.c:625
#14 0x00000000004219f9 in dprintf_eggdrop (arg1=arg1@entry=1) at dccutil.c:203
#15 0x000000000042a2a1 in putlog (arg1=32) at misc.c:625
[...]

now its endlessly going on like this

(gdb) bt full
#0  0x00007f7ff5ab8c36 in __vfprintf_unlocked_l () from /usr/lib/libc.so.12
No symbol table info available.
#1  0x00007f7ff5aaeb9f in vsnprintf_l () from /usr/lib/libc.so.12
No symbol table info available.
#2  0x00007f7ff5aaece2 in snprintf () from /usr/lib/libc.so.12
No symbol table info available.
#3  0x00007f7ff5af7cd1 in ?? () from /usr/lib/libc.so.12
No symbol table info available.
#4  0x00007f7ff5af7dd9 in _citrus_lookup_seq_open () from /usr/lib/libc.so.12
No symbol table info available.
#5  0x00007f7ff5af7eda in _citrus_lookup_simple () from /usr/lib/libc.so.12
No symbol table info available.
#6  0x00007f7ff5aaef3c in catopen_l () from /usr/lib/libc.so.12
No symbol table info available.
#7  0x00007f7ff5aae9c5 in _strerror_lr () from /usr/lib/libc.so.12
No symbol table info available.
#8  0x00007f7ff5af10dc in strerror_l () from /usr/lib/libc.so.12
No symbol table info available.
#9  0x000000000042e3d2 in safe_write (fd=1, buf=<optimized out>, count=111) at net.c:802
        bytes = 0x7f7fffc01580 "[23:32:24] Unexpected write() failure on attempt to write 111 bytes to fd 1: Resource temporarily unavailable.\n"
        ret = -1
#10 0x00000000004219f9 in dprintf_eggdrop (arg1=arg1@entry=1) at dccutil.c:203
        buf = "[23:32:24] Unexpected write() failure on attempt to write 111 bytes to fd 1: Resource temporarily unavailable.\n\000\020ôr\367\177\177\000\000\000\000\000\000\000\000\000\000\324=\031\000\000\000\000\000\001\000\000\000\000\000\000\000\020t\367\177\177\000\000POy\367\177\177\000\000\020ôr\367\177\177\000\000\001", '\000' <repeats 15 times>, "\333\227\367\177\177\000\000\266-²õ\177\177\000\000"...
        format = <optimized out>
        idx = 1
        len = <optimized out>
        va = {{gp_offset = 24, fp_offset = 48, overflow_arg_area = 0x7f7fffc01a50, reg_save_area = 0x7f7fffc01980}}
#11 0x000000000042a2a1 in putlog (arg1=32) at misc.c:625
        inhere = 0
        i = 1
        type = 32
        tsl = <optimized out>
        format = <optimized out>
        chname = 0x449004 "*"
        s = "[23:32:24] Unexpected write() failure on attempt to write 111 bytes to fd 1: Resource temporarily unavailable.\n", '\000' <repeats 50 times>, "\061\061\061", '\000' <repeats 52 times>...
        s1 = "\000\000\000\000\000\000\000\000\036\223\261õ\177\177\000\000/usr/share/nls/C/libc.cat", '\000' <repeats 15 times>, "\033\223\261õ\177\177\000\000\033\000\000\000\377\377\377\377", '\000' <repeats 16 times>, "\003\000\063\063\000\000\000\000è&À\377\177\177", '\000' <repeats 22 times>, "\177\177\000\000\000\000\000\000\000\000\000\000\005\000UU\000\177\000\000\000\000\000\000\000\000\000\000°\033À\377\177\177\000\000\000\000\000\000\000\000\000\000\034\347°õ\177\177\000\000 \035À\377\177\177\000\000q@\367\177\177\000\000@\036À\377\177\177\000\000"...
        out = <optimized out>
        ct = "\003", '\000' <repeats 39 times>, "P\034À\377\177\177\000\000P$À\377\177\177\000\000\003\000\000\000\000\000\000\000\003\000\000\000\000\000\000\000P$À\377\177\177\000\000è"
        s2 = <optimized out>
        stamp = "[23:32:24] \000\177\177\000\000\035¯D\000\000\000\000\000\001\000\000\000\000\000\000\000\000h"
        va = {{gp_offset = 48, fp_offset = 48, overflow_arg_area = 0x7f7fffc02010, reg_save_area = 0x7f7fffc01f20}}
        now2 = 1538523144
        t = <optimized out>
#12 0x00000000004219f9 in dprintf_eggdrop (arg1=arg1@entry=1) at dccutil.c:203
        buf = "[23:32:24] Unexpected write() failure on attempt to write 111 bytes to fd 1: Resource temporarily unavailable.\n\000\020ôr\367\177\177\000\000\000\000\000\000\000\000\000\000\324=\031\000\000\000\000\000\001\000\000\000\000\000\000\000\020t\367\177\177\000\000°\033v\367\177\177\000\000\020ôr\367\177\177\000\000\001", '\000' <repeats 15 times>, "\333\227\367\177\177\000\000\266-²õ\177\177\000\000"...
        format = <optimized out>
        idx = 1
        len = <optimized out>
        va = {{gp_offset = 24, fp_offset = 48, overflow_arg_area = 0x7f7fffc02500, reg_save_area = 0x7f7fffc02430}}
#13 0x000000000042a2a1 in putlog (arg1=32) at misc.c:625
        inhere = 0
        i = 1
        type = 32
        tsl = <optimized out>
        format = <optimized out>
        chname = 0x449004 "*"
        s = "[23:32:24] Unexpected write() failure on attempt to write 111 bytes to fd 1: Resource temporarily unavailable.\n", '\000' <repeats 50 times>, "\061\061\061", '\000' <repeats 52 times>...
        s1 = "\000\000\000\000\000\000\000\000\036\223\261õ\177\177\000\000/usr/share/nls/C/libc.cat", '\000' <repeats 15 times>, "\033\223\261õ\177\177\000\000\033\000\000\000\377\377\377\377", '\000' <repeats 16 times>, "\003\000\063\063\000\000\000\000\230\061À\377\177\177", '\000' <repeats 22 times>, "\177\177\000\000\000\000\000\000\000\000\000\000\005\000UU\000\177\000\000\000\000\000\000\000\000\000\000`&À\377\177\177\000\000\000\000\000\000\000\000\000\000\034\347°õ\177\177\000\000\320'À\377\177\177\000\000q@\367\177\177\000\000\360(À\377\177\177\000\000"...
        out = <optimized out>
        ct = "\003", '\000' <repeats 40 times>, "'À\377\177\177\000\000\000/À\377\177\177\000\000\003\000\000\000\000\000\000\000\003\000\000\000\000\000\000\000\000/À\377\177\177\000\000è"
        s2 = <optimized out>
        stamp = "[23:32:24] \000\177\177\000\000\035¯D\000\000\000\000\000\001\000\000\000\000\000\000\000\000h"
        va = {{gp_offset = 48, fp_offset = 48, overflow_arg_area = 0x7f7fffc02ac0, reg_save_area = 0x7f7fffc029d0}}
        now2 = 1538523144
        t = <optimized out>
#14 0x00000000004219f9 in dprintf_eggdrop (arg1=arg1@entry=1) at dccutil.c:203
        buf = "[23:32:24] Unexpected write() failure on attempt to write 111 bytes to fd 1: Resource temporarily unavailable.\n\000\020ôr\367\177\177\000\000\000\000\000\000\000\000\000\000\324=\031\000\000\000\000\000\001\000\000\000\000\000\000\000\020t\367\177\177\000\000POy\367\177\177\000\000\020ôr\367\177\177\000\000\001", '\000' <repeats 15 times>, "\333\227\367\177\177\000\000\266-²õ\177\177\000\000"...
        format = <optimized out>
        idx = 1
        len = <optimized out>
        va = {{gp_offset = 24, fp_offset = 48, overflow_arg_area = 0x7f7fffc02fb0, reg_save_area = 0x7f7fffc02ee0}}
#15 0x000000000042a2a1 in putlog (arg1=32) at misc.c:625
        inhere = 0
        i = 1
        type = 32
        tsl = <optimized out>
        format = <optimized out>
        chname = 0x449004 "*"
        s = "[23:32:24] Unexpected write() failure on attempt to write 111 bytes to fd 1: Resource temporarily unavailable.\n", '\000' <repeats 50 times>, "\061\061\061", '\000' <repeats 52 times>...
        s1 = "\000\000\000\000\000\000\000\000\036\223\261õ\177\177\000\000/usr/share/nls/C/libc.cat", '\000' <repeats 15 times>, "\033\223\261õ\177\177\000\000\033\000\000\000\377\377\377\377", '\000' <repeats 16 times>, "\003\000\063\063\000\000\000\000H<À\377\177\177", '\000' <repeats 22 times>, "\177\177\000\000\000\000\000\000\000\000\000\000\005\000UU\000\177\000\000\000\000\000\000\000\000\000\000\020\061À\377\177\177\000\000\000\000\000\000\000\000\000\000\034\347°õ\177\177\000\0002À\377\177\177\000\000q@\367\177\177\000\000\240\063À\377\177\177\000\000"...
        out = <optimized out>
        ct = "\003", '\000' <repeats 39 times>, "°1À\377\177\177\000\000°9À\377\177\177\000\000\003\000\000\000\000\000\000\000\003\000\000\000\000\000\000\000°9À\377\177\177\000\000è"
        s2 = <optimized out>
        stamp = "[23:32:24] \000\177\177\000\000\035¯D\000\000\000\000\000\001\000\000\000\000\000\000\000\000h"
        va = {{gp_offset = 48, fp_offset = 48, overflow_arg_area = 0x7f7fffc03570, reg_save_area = 0x7f7fffc03480}}
        now2 = 1538523144
        t = <optimized out>
[...]

So, in safe_write() we try to write to fd and get: EAGAIN == Resource temporarily unavailable

eggdrop 1.8.2 crashes, because in case it couldn't write it tries to write an error message on top.

This was fixed with commit https://github.com/eggheads/eggdrop/commit/affc49eef90560eff6dedcd6464b35f4b36116b4

safe_write is quite new, see the following 2 commits: https://github.com/eggheads/eggdrop/commit/9bd9d1bd34bcdcf0f69ef59f549bc4cec8c22371 https://github.com/eggheads/eggdrop/commit/6bc613a54effac9ac260277d0b3dbc2aca6ba8fa

Analyzation result:

safe_write() isn't handling EAGAIN properly.

vanosg commented 6 years ago

Works fine on Ubuntu as well

vanosg commented 6 years ago

For completeness' sake, there is no truncation in NetBSD 7.1 either