gawk (3.1.2): fatal: grow_iop_buffer: iop->buf: can't allocate -2147483646 bytes of memory (Cannot allocate memory)

[James Troup]

Hi Aharon,

This bug report comes from the Debian bug tracking system.  You can
view the full log at:

  http://bugs.debian.org/186614

================================================================================

| Package: gawk
| Version: 1:3.1.2-1
| Severity: important
| 
| address@hidden:~/arch/dancer-1.1$ larch inventory --source --all --tags | 
gawk '{ if (seen[$2]) duplicates[$2] = yes } { seen[$2] = seen[$2] "\n" $1 } 
END { for (tag in duplicates) print seen[tag] "\n" }'
| gawk: cmd. line:1: (FILENAME=- FNR=6) fatal: grow_iop_buffer: iop->buf: can't 
allocate -2147483646 bytes of memory (Cannot allocate memory)
| 
| This is new as of the latest upload (1:3.1.2-1). Unfortunately it
| appears to be timing-sensitive; if I capture the input data to a file
| and pipe that in, gawk works fine.
| 
| The error message is partially a red herring. erealloc() passes a
| size_t to a %ld parameter (incorrectly), when it should have been
| %zu. It's really a very large positive number.
| 
| Throwing in some trivial debugging stuff to grow_iop_buffer() gets
| this, which shows the general problem more clearly:
| iop->size == 4098, iop->readsize == 4096
| newsize == 8194
| newsize == 8194
| iop->size == 8194, iop->readsize == 4096
| newsize == 16386
| newsize == 16386
| iop->size == 16386, iop->readsize == 4096
| newsize == 32770
| newsize == 32770
| iop->size == 32770, iop->readsize == 4096
| newsize == 65538
| newsize == 65538
| iop->size == 65538, iop->readsize == 4096
| newsize == 131074
| newsize == 131074
| iop->size == 131074, iop->readsize == 4096
| newsize == 262146
| newsize == 262146
| iop->size == 262146, iop->readsize == 4096
| newsize == 524290
| newsize == 524290
| iop->size == 524290, iop->readsize == 4096
| newsize == 1048578
| newsize == 1048578
| iop->size == 1048578, iop->readsize == 4096
| newsize == 2097154
| newsize == 2097154
| iop->size == 2097154, iop->readsize == 4096
| newsize == 4194306
| newsize == 4194306
| iop->size == 4194306, iop->readsize == 4096
| newsize == 8388610
| newsize == 8388610
| gawk: io.c:2416: grow_iop_buffer: Assertion `newsize < 5000000' failed.
| Aborted (core dumped)
| 
| #3  0x40061ae9 in __assert_fail () from /lib/libc.so.6
| #4  0x08066486 in grow_iop_buffer (iop=0x808e480) at io.c:2416
| #5  0x0806665a in rs1_get_a_record (out=0xbffff734, iop=0x808e480, grRS=10,=20
|     RSre=0x0, errcode=0x0) at io.c:2493
| #6  0x08061c9d in inrec (iop=0x808e480) at io.c:293
| #7  0x08061f80 in do_input () at io.c:405
| #8  0x080689a2 in main (argc=2, argv=0xbffff804) at main.c:558
| 
| The printfs and assertion I added (without them it would run up to
| ~4Gb and then fail in erealloc); line numbers still match. The input
| data is about 80k in size, so something is wrong in the allocation
| magic. In case it helps, here's the relevant IOBUF at this point:
| 
| $2 = {name = 0x8086162 "-", fd = 0, sbuf = {st_dev = 5, __pad1 = 0,=20
|     __st_ino = 8480698, st_mode = 4480, st_nlink = 1, st_uid = 1000,=20
|     st_gid = 1000, st_rdev = 0, __pad2 = 0, st_size = 0, st_blksize = 4096,=20
|     st_blocks = 0, st_atime = 1048863696, __unused1 = 0,=20
|     st_mtime = 1048863696, __unused2 = 0, st_ctime = 1048863696,=20
|     __unused3 = 0, st_ino = 8480698},=20
|   buf = 0x40151008 "./.arch-ids/address@hidden:34:57_BST_2002_16472.0\n\n",=20
|   off = 0x40151008 "./.arch-ids/address@hidden:34:57_BST_2002_16472.0\n\n",=20
|   dataend = 0x4015101f "address@hidden:34:57_BST_2002_16472.0\n\n", end = 
0x4055100a "", readsize = 4096, size = 4194306,=20
|   count = 1, total = 277, scanoff = 23, flag = 8}
| 
| I can reproduce this on one particular host if more data is needed,
| but have so far not been able to construct a test case that duplicates
| whatever oddity of timing is required to trigger this problem
| elsewhere.
| 
| -- System Information:
| Debian Release: testing/unstable
| Architecture: i386
| Kernel: Linux cyclone 2.4.21-pre4-ac4 #30 Wed Feb 12 21:40:14 GMT 2003 i686
| Locale: LANG=C, LC_CTYPE=C
| 
| Versions of packages gawk depends on:
| ii  libc6                         2.3.1-16   GNU C Library: Shared libraries 
an

================================================================================

| Package: gawk
| Version: 1:3.1.2-1
| Followup-For: Bug #186614
| 
| I've seen this bug, too.  My reproducible case is
| 
| echo | gawk '{for (i = 0; i < 80; i++) {
| printf "x";fflush("");
| system("sleep 1");
| }
| printf "\n";
| }' | ./gawk '/.i..libdvdcss2/ {print $3} '
| 
| 
| dpkg -l libdvdcss2 2>/dev/null | strace gawk '/.i..libdvdcss2/ {print $3} '
| 
| The strace is below.  But here's my analysis so far.  As you'll see
| below, the line is being read one character at a time.  In
| rs1_get_a_record, we grow the buffer if bp >= iop->dataend, and bp is
| set based on
| 
|   bp = iop->off + iop->scanoff;
| 
| after the read, not taking into account how much we actually read.  I
| think the code is implicitely assuming that read returns the entire
| amount read for purposes of keeping bp up to date, or
| something... I'm not completely sure yet, but hopefully this bit (and
| the test case I created after understanding this much) is helpful.
| 
| execve("/usr/bin/gawk", ["gawk", "/.i..libdvdcss2/ {print $3} "], [/* 45 vars 
*
| /]) = 0
| uname({sys="Linux", node="wesley.springies.com", ...}) = 0
| brk(0)                                  = 0x80835cc
| open("/etc/ld.so.preload", O_RDONLY)    = -1 ENOENT (No such file or 
directory)
| open("/etc/ld.so.cache", O_RDONLY)      = 3
| fstat64(3, {st_mode=S_IFREG|0644, st_size=30835, ...}) = 0
| old_mmap(NULL, 30835, PROT_READ, MAP_PRIVATE, 3, 0) = 0x40012000
| close(3)                                = 0
| open("/lib/libdl.so.2", O_RDONLY)       = 3
| read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0\3\0\1\0\0\0S\27\0\000"..., 1024) 
=
|  1024
| fstat64(3, {st_mode=S_IFREG|0644, st_size=7992, ...}) = 0
| old_mmap(NULL, 10924, PROT_READ|PROT_EXEC, MAP_PRIVATE, 3, 0) = 0x4001a000
| mprotect(0x4001c000, 2732, PROT_NONE)   = 0
| old_mmap(0x4001c000, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED, 3, 
0x10
| 00) = 0x4001c000
| close(3)                                = 0
| open("/lib/libm.so.6", O_RDONLY)        = 3
| read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0\3\0\1\0\0\0\2605\0"..., 1024) = 
10
| 24
| fstat64(3, {st_mode=S_IFREG|0644, st_size=131156, ...}) = 0
| old_mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) =
| 0x4001d000
| old_mmap(NULL, 133712, PROT_READ|PROT_EXEC, MAP_PRIVATE, 3, 0) = 0x4001e000
| mprotect(0x4003e000, 2640, PROT_NONE)   = 0
| old_mmap(0x4003e000, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED, 3, 
0x1f
| 000) = 0x4003e000
| close(3)                                = 0
| open("/lib/libc.so.6", O_RDONLY)        = 3
| read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0\3\0\1\0\0\0\275Z\1"..., 1024) = 
10
| 24
| fstat64(3, {st_mode=S_IFREG|0755, st_size=1104040, ...}) = 0
| old_mmap(NULL, 1113796, PROT_READ|PROT_EXEC, MAP_PRIVATE, 3, 0) = 0x4003f000
| mprotect(0x40147000, 32452, PROT_NONE)  = 0
| old_mmap(0x40147000, 24576, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED, 3, 
0x1
| 07000) = 0x40147000
| old_mmap(0x4014d000, 7876, PROT_READ|PROT_WRITE, 
MAP_PRIVATE|MAP_FIXED|MAP_ANON
| YMOUS, -1, 0) = 0x4014d000
| close(3)                                = 0
| munmap(0x40012000, 30835)               = 0
| open("/usr/lib/locale/locale-archive", O_RDONLY|O_LARGEFILE) = 3
| fstat64(3, {st_mode=S_IFREG|0644, st_size=1603488, ...}) = 0
| mmap2(NULL, 1603488, PROT_READ, MAP_PRIVATE, 3, 0) = 0x4014f000
| close(3)                                = 0
| brk(0)                                  = 0x80835cc
| brk(0x80845cc)                          = 0x80845cc
| brk(0)                                  = 0x80845cc
| brk(0x8085000)                          = 0x8085000
| rt_sigaction(SIGFPE, {0x806320c, [FPE], SA_RESTORER|SA_RESTART, 0x400659d8}, 
{S
| IG_DFL}, 8) = 0
| rt_sigaction(SIGSEGV, {0x806320c, [SEGV], SA_RESTORER|SA_RESTART, 0x400659d8},
| {SIG_DFL}, 8) = 0
| rt_sigaction(SIGBUS, {0x806320c, [BUS], SA_RESTORER|SA_RESTART, 0x400659d8}, 
{S
| IG_DFL}, 8) = 0
| fstat64(0, {st_mode=S_IFIFO|0600, st_size=0, ...}) = 0
| fstat64(1, {st_mode=S_IFCHR|0620, st_rdev=makedev(136, 1), ...}) = 0
| fstat64(2, {st_mode=S_IFREG|0644, st_size=2938, ...}) = 0
| getgroups32(0, 0)                       = 7
| getgroups32(0x7, 0x8083d78)             = 7
| ioctl(1, SNDCTL_TMR_TIMEBASE, {B38400 opost isig icanon echo ...}) = 0
| brk(0)                                  = 0x8085000
| brk(0x8086000)                          = 0x8086000
| fstat64(0, {st_mode=S_IFIFO|0600, st_size=0, ...}) = 0
| ioctl(0, SNDCTL_TMR_TIMEBASE, 0xbffff660) = -1 EINVAL (Invalid argument)
| fstat64(0, {st_mode=S_IFIFO|0600, st_size=0, ...}) = 0
| brk(0)                                  = 0x8086000
| brk(0x8087000)                          = 0x8087000
| read(0, "x", 4096)                      = 1
| brk(0)                                  = 0x8087000
| brk(0x8089000)                          = 0x8089000
| read(0, "x", 4096)                      = 1
| brk(0)                                  = 0x8089000
| brk(0x808c000)                          = 0x808c000
| read(0, "x", 12288)                     = 1
| brk(0)                                  = 0x808c000
| brk(0x8092000)                          = 0x8092000
| read(0, "x", 28672)                     = 1
| brk(0)                                  = 0x8092000
| brk(0x809e000)                          = 0x809e000
| read(0, "x", 61440)                     = 1
| old_mmap(NULL, 135168, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0)
| = 0x402d7000
| read(0, "x", 126976)                    = 1
| mremap(0x402d7000, 135168, 266240, MREMAP_MAYMOVE) = 0x402d7000
| read(0, "x", 258048)                    = 1
| mremap(0x402d7000, 266240, 528384, MREMAP_MAYMOVE) = 0x402d7000
| read(0, "x", 520192)                    = 1
| mremap(0x402d7000, 528384, 1052672, MREMAP_MAYMOVE) = 0x402d7000
| read(0, "x", 1044480)                   = 1
| mremap(0x402d7000, 1052672, 2101248, MREMAP_MAYMOVE) = 0x402d7000
| read(0, "x", 2093056)                   = 1
| mremap(0x402d7000, 2101248, 4198400, MREMAP_MAYMOVE) = 0x402d7000
| read(0, "x", 4190208)                   = 1
| mremap(0x402d7000, 4198400, 8392704, MREMAP_MAYMOVE) = 0x402d7000
| read(0, "x", 8384512)                   = 1
| mremap(0x402d7000, 8392704, 16781312, MREMAP_MAYMOVE) = 0x402d7000
| read(0, "x", 16773120)                  = 1
| mremap(0x402d7000, 16781312, 33558528, MREMAP_MAYMOVE) = 0x402d7000
| read(0, "x", 33550336)                  = 1
| mremap(0x402d7000, 33558528, 67112960, MREMAP_MAYMOVE) = 0x402d7000
| read(0, "x", 67104768)                  = 1
| mremap(0x402d7000, 67112960, 134221824, MREMAP_MAYMOVE) = 0x402d7000
| read(0, "x", 134213632)                 = 1
| mremap(0x402d7000, 134221824, 268439552, MREMAP_MAYMOVE) = 0x402d7000
| read(0, "x", 268431360)                 = 1
| mremap(0x402d7000, 268439552, 536875008, MREMAP_MAYMOVE) = 0x402d7000
| read(0, "x", 536866816)                 = 1
| mremap(0x402d7000, 536875008, 1073745920, MREMAP_MAYMOVE) = 0x402d7000
| read(0, "x", 1073737728)                = 1
| mremap(0x402d7000, 1073745920, 2147487744, MREMAP_MAYMOVE) = -1 ENOMEM (Cannot
| allocate memory)
| old_mmap(NULL, 2147487744, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, 
-1,
|  0) = -1 ENOMEM (Cannot allocate memory)
| brk(0)                                  = 0x809e000
| brk(0x88086000)                         = 0x809e000
| old_mmap(NULL, 2147487744, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, 
-1,
|  0) = -1 ENOMEM (Cannot allocate memory)
| old_mmap(NULL, 2097152, PROT_NONE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_NORESERVE, 
-1,
|  0) = 0x802d8000
| munmap(0x802d8000, 163840)              = 0
| munmap(0x80400000, 884736)              = 0
| mprotect(0x80300000, 32768, PROT_READ|PROT_WRITE) = 0
| old_mmap(NULL, 2147487744, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, 
-1,
|  0) = -1 ENOMEM (Cannot allocate memory)
| mprotect(0x80308000, 2147454976, PROT_READ|PROT_WRITE) = -1 EINVAL (Invalid 
arg
| ument)
| open("/usr/share/locale/locale.alias", O_RDONLY) = 3
| fstat64(3, {st_mode=S_IFREG|0644, st_size=2597, ...}) = 0
| old_mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) =
| 0x40012000
| read(3, "# Locale name alias data base.\n#"..., 4096) = 2597
| read(3, "", 4096)                       = 0
| close(3)                                = 0
| munmap(0x40012000, 4096)                = 0
| open("/usr/share/locale/en_US/LC_MESSAGES/libc.mo", O_RDONLY) = -1 ENOENT (No 
s
| uch file or directory)
| open("/usr/share/locale/en/LC_MESSAGES/libc.mo", O_RDONLY) = -1 ENOENT (No 
such
|  file or directory)
| open("/usr/share/locale/en_US/LC_MESSAGES/gawk.mo", O_RDONLY) = -1 ENOENT (No 
s
| uch file or directory)
| open("/usr/share/locale/en/LC_MESSAGES/gawk.mo", O_RDONLY) = -1 ENOENT (No 
such
|  file or directory)
| write(2, "gawk: ", 6gawk: )                   = 6
| write(2, "cmd. line:", 10cmd. line:)              = 10
| write(2, "2: ", 32: )                      = 3
| write(2, "fatal: ", 7fatal: )                  = 7
| write(2, "grow_iop_buffer: iop->buf: can\'t"..., 94grow_iop_buffer: iop->buf: 
c
| an't allocate -2147483646 bytes of memory (Cannot allocate memory)) = 94
| write(2, "\n", 1
| )                       = 1
| exit_group(2)                           = ?

================================================================================

-- 
James