postfix/postqueue[5742]: panic: vbuf_print: output for \%s\ exceeds space 0

Previous Topic Next Topic
 
classic Classic list List threaded Threaded
13 messages Options
Reply | Threaded
Open this post in threaded view
|

postfix/postqueue[5742]: panic: vbuf_print: output for \%s\ exceeds space 0

A. Schulze

Hello,

I found the message in my logs. It turns they where triggered by a  
housekeeping script.

I did "qshape deferred" and used the first row (domainname) as  
argument to pfqgrep -r
For long domainnames qshape shorten the output and prefix the domain  
with a '+' character.
(described in man qshape, -w option)

Now my script called pfqgrep -r "+truncated-domain" which trigger the  
panic message sometimes

# pfqgrep -r '+12345678901'
Quantifier follows nothing in regex; marked by <-- HERE in m/+ <--  
HERE 12345678901/ at /usr/sbin/pfqgrep line 158, <MAILQ> chunk 1.
# pfqgrep -r '+123456789012'
Quantifier follows nothing in regex; marked by <-- HERE in m/+ <--  
HERE 123456789012/ at /usr/sbin/pfqgrep line 158, <MAILQ> chunk 1.
# pfqgrep -r '+1234567890123'
Quantifier follows nothing in regex; marked by <-- HERE in m/+ <--  
HERE 1234567890123/ at /usr/sbin/pfqgrep line 158, <MAILQ> chunk 1.
postqueue: panic: vbuf_print: output for '%s' exceeds space 0
# pfqgrep -r '+12345678901234'
Quantifier follows nothing in regex; marked by <-- HERE in m/+ <--  
HERE 12345678901234/ at /usr/sbin/pfqgrep line 158, <MAILQ> chunk 1.
# pfqgrep -r '+123456789012345'
Quantifier follows nothing in regex; marked by <-- HERE in m/+ <--  
HERE 123456789012345/ at /usr/sbin/pfqgrep line 158, <MAILQ> chunk 1.
postqueue: panic: vbuf_print: output for '%s' exceeds space 0
# pfqgrep -r '+1234567890123456'
Quantifier follows nothing in regex; marked by <-- HERE in m/+ <--  
HERE 1234567890123456/ at /usr/sbin/pfqgrep line 158, <MAILQ> chunk 1.
postqueue: panic: vbuf_print: output for '%s' exceeds space 0
# pfqgrep -r '+12345678901234567'
Quantifier follows nothing in regex; marked by <-- HERE in m/+ <--  
HERE 12345678901234567/ at /usr/sbin/pfqgrep line 158, <MAILQ> chunk 1.
# pfqgrep -r '+123456789012345678'
Quantifier follows nothing in regex; marked by <-- HERE in m/+ <--  
HERE 123456789012345678/ at /usr/sbin/pfqgrep line 158, <MAILQ> chunk 1.

I'm Unsure what's the really wrong part (beside input santisation in  
my script) but I guess, postqueue should not panic...

The messages went away after I changed my script to call "qshape -w  
100". This avoid domainname truncation for now.
Is there a safe way to avoid truncation completely?

postfix-3.2.0 is installed on the host.
pfqgrep is loaded from  
https://github.com/mikewaters/scripts/blob/master/mta/pfgrep.pl

Andreas


Reply | Threaded
Open this post in threaded view
|

Re: postfix/postqueue[5742]: panic: vbuf_print: output for \%s\ exceeds space 0

Wietse Venema
A. Schulze:
> I'm Unsure what's the really wrong part (beside input santisation in  
> my script) but I guess, postqueue should not panic...

To reduce the search space, it would help if you could provide
details of the postqueue command line. This gives some info about
what the program might be trying to do when it fails.

If you run the command as root, you can run postqueue by hand under
strace, which is even more helpful to find out what the program is
trying to do when it fails.

        Wietse
Reply | Threaded
Open this post in threaded view
|

Re: postfix/postqueue[5742]: panic: vbuf_print: output for \%s\ exceeds space 0

Wietse Venema
In reply to this post by A. Schulze
A. Schulze:
> postqueue: panic: vbuf_print: output for '%s' exceeds space 0

Unfortunately, there is no way that I can reproduce this in
postfix-3.2.0, given the preconditions in this code.  Does this
machine have ECC meory? Does it have a history of programs crashing?

        Wietse

Message-ID: <[hidden email]>
postfix 3.2.0
postqueue: panic: vbuf_print: output for '%s' exceeds space 0

This msg_panic() call is made from VBUF_SNPRINTF():
#define VBUF_SNPRINTF(bp, sz, fmt, arg) do { \
        ssize_t _ret; \
        VBUF_SPACE((bp), (sz)); \
        _ret = snprintf((char *) (bp)->ptr, (bp)->cnt, (fmt), (arg)); \
        if (_ret < 0) \
            msg_panic("%s: output error for '%s'", myname, (fmt)); \
        if (_ret >= (bp)->cnt) \
            msg_panic("%s: output for '%s' exceeds space %ld", \
                      myname, fmt, (long) (bp)->cnt); \

According to the panic message, (bp)->cnt is zero, meaning the
output buffer has no free space, which can't happen because
VBUF_SNPRINTF() is called with sz > 0, as will be argued below.
Therefore, VBUF_SPACE() is called with a value sz > 0, and the
output buffer must have free space.

The panic message says "%s" therefore this VBUF_SNPRINTF() call is
made while formatting a string with an fmt value of "%s".

This VBUF_SNPRINTF() call is made from vbuf_print():
                s = va_arg(ap, char *);
                if (prec >= 0 || (width > 0 && width > strlen(s))) {
                    VBUF_SNPRINTF(bp, (width > prec ? width : prec) + INT_SPACE,
                                  vstring_str(fmt), s);
                } else {
                    VBUF_STRCAT(bp, s); /* noop for empty string */
                }

This is the only VBUF_SNPRINTF() call with an fmt value of "%<whatever>s".

Note that this VBUF_SNPRINTF() call happens only when prec >= 0
(VBUF_SNPRINTF called with sz >= INT_SPACE) or when width > 0
(VBUF_SNPRINTF called with sz > INT_SPACE).

The fmt argument for VBUF_SNPRINTF() contains "%s". Therefore:

    There was no '-' for left-adjusted field. This info is copied literally.

    There was no '+' for signed field. This info is copied literally.

    There was no '0' for numeric left-padding. This info is copied literally.

    There was no '*' for dynamic field width. This info is converted to
    decimal string and added to the format string.

    There was no hard-coded field width. This info is copied literally.

Therefore width == 0 (see vbuf_print source code).

There was no '.' for precision. This info is copied literally.

    Therefore there was no '*' for dynamic precision.

    Therefore there was no hard-coded precision.

Therefore prec == -1 (see vbuf_print source code).

In order to invoke VBUF_SNPRINTF() for %s, at least one of the
following predicates must be true:

    prec >= 0, falsified by the above analysis.

    width > 0 && width > strlen(s), falsified by the above analysis.

If VBUF_SNPRINTF() is invoked anyway, then some memory was corrupted
either dynamically during program execution, or some bit got flipped
in the file system page cache with some part of the executable file
or Postfix library, so that a constant or instruction was clobbered.

There is no point speculating which memory might be affected, without
making this panic independently reproducible.
Reply | Threaded
Open this post in threaded view
|

Re: postfix/postqueue[5742]: panic: vbuf_print: output for \%s\ exceeds space 0

Larry Kuenning
In reply to this post by A. Schulze
Pardon an amateur for jumping in here, but I think I see something:

On 8/26/2017 6:24 AM, A. Schulze wrote:

> Now my script called pfqgrep -r "+truncated-domain" which trigger the
> panic message sometimes
>
> # pfqgrep -r '+12345678901'
> Quantifier follows nothing in regex; marked by <-- HERE in m/+ <-- HERE
> 12345678901/ at /usr/sbin/pfqgrep line 158, <MAILQ> chunk 1.

Doesn't that error message "Quantifier follows nothing" mean that the
regexp parser pfqgrep is choking on a quoted expression because it
begins with a "+" sign?  It seems to expect the "+" to mean "one or more
of what precedes" and finds nothing to apply this to.

Since A. Schulze is trying to find a literal "+" sign, isn't "\+" the
way to represent it?

--
Larry Kuenning
[hidden email]

Reply | Threaded
Open this post in threaded view
|

Re: postfix/postqueue[5742]: panic: vbuf_print: output for \%s exceeds space 0

A. Schulze
In reply to this post by Wietse Venema

wietse:

> A. Schulze:
>> postqueue: panic: vbuf_print: output for '%s' exceeds space 0
>

this is pfqgrep:

   $mailq = "/usr/sbin/postqueue -p |"; # added 'strace -f' here
   open(MAILQ, $mailq) or die;
   while (<MAILQ>) {
     # read from STDIN
   }

execve("/usr/sbin/postqueue", ["/usr/sbin/postqueue", "-p"], [/* 52  
vars */]) = 0
...
chdir("/var/spool/postfix")             = 0
rt_sigaction(SIGPIPE, {0x1, [PIPE], SA_RESTORER|SA_RESTART,  
0x7f4c8e917910}, {SIG_DFL, [], 0}, 8) = 0
getuid()                                = 0
socket(PF_FILE, SOCK_STREAM, 0)         = 4
fcntl(4, F_GETFL)                       = 0x2 (flags O_RDWR)
fcntl(4, F_SETFL, O_RDWR)               = 0
connect(4, {sa_family=AF_FILE, path="public/showq"}, 110) = 0
poll([{fd=4, events=POLLIN}], 1, 3600000) = 1 ([{fd=4, revents=POLLIN}])
read(4, "queue_name\0active\0queue_id\0003xdsD"..., 4096) = 149
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2335, ...}) = 0
write(1, "----Queue ID----- --Size-- ---Ar"..., 218) = 218
poll([{fd=4, events=POLLIN}], 1, 3600000) = 1 ([{fd=4, revents=POLLIN}])
read(4, "queue_name\0active\0queue_id\0003xgg0"..., 4096) = 1453
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2335, ...}) = 0
write(1, "\n3xgg0L0F7Lz4FLj*     30013 Mon "..., 257) = 257
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2335, ...}) = 0
Quantifier follows nothing in regex; marked by <-- HERE in m/+ <--  
HERE 1234567890123/ at /usr/sbin/pfqgrep line 158, <MAILQ> chunk 1.
write(1, "\n3xgfY21WScz4FLZ*     32602 Mon "..., 241) = 241
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2335, ...}) = 0
write(1, "\n3xgWSk0qGbz4FKf*     42628 Mon "..., 257) = 257
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2335, ...}) = 0
write(1, "\n3xgh1z1cT1z4FLr*     76609 Mon "..., 184) = -1 EPIPE (Broken pipe)
--- SIGPIPE (Broken pipe) @ 0 (0) ---
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2335, ...}) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2335, ...}) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2335, ...}) = 0
poll([{fd=4, events=POLLIN}], 1, 3600000) = 1 ([{fd=4, revents=POLLIN}])
read(4, "queue_name\0active\0queue_id\0003xgKR"..., 4096) = 4096
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2335, ...}) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2335, ...}) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2335, ...}) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2335, ...}) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2335, ...}) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2335, ...}) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2335, ...}) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2335, ...}) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2335, ...}) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2335, ...}) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2335, ...}) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2335, ...}) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2335, ...}) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2335, ...}) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2335, ...}) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2335, ...}) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2335, ...}) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2335, ...}) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2335, ...}) = 0
poll([{fd=4, events=POLLIN}], 1, 3600000) = 1 ([{fd=4, revents=POLLIN}])
read(4, "3xdqXK4q4lz4FLK\0time\0001503639089\0"..., 4096) = 4096
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2335, ...}) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2335, ...}) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2335, ...}) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2335, ...}) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2335, ...}) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2335, ...}) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2335, ...}) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2335, ...}) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2335, ...}) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2335, ...}) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2335, ...}) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2335, ...}) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2335, ...}) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2335, ...}) = 0
write(2, "postqueue: panic: vbuf_print: ou"..., 62postqueue: panic:  
vbuf_print: output for '%s' exceeds space 0
) = 62
sendto(3, "<18>Aug 28 08:09:02 postfix/post"..., 95, MSG_NOSIGNAL,  
NULL, 0) = 95
rt_sigprocmask(SIG_BLOCK, [CHLD], [], 8) = 0
rt_sigaction(SIGCHLD, NULL, {SIG_DFL, [], 0}, 8) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
nanosleep({1, 0}, {1, 0})               = 0
rt_sigprocmask(SIG_UNBLOCK, [ABRT], NULL, 8) = 0
tgkill(1753, 1753, SIGABRT)             = 0
--- SIGABRT (Aborted) @ 0 (0) ---
+++ killed by SIGABRT +++


Maybe perl open not only read from th process but write also
I've an older version of perl (5.10.0)
maybe perl open is already changed in newer versions.

> Unfortunately, there is no way that I can reproduce this in
> postfix-3.2.0, given the preconditions in this code.  Does this
> machine have ECC memory? Does it have a history of programs crashing?
no ecc issue. no other crashes. panic starts with reading qshape, take  
row #1 as argv to pfqgrep.

unrelated by interesting: why does strace show so many  
'stat("/etc/localtime" ...' calls?

Andreas

Reply | Threaded
Open this post in threaded view
|

Re: postfix/postqueue[5742]: panic: vbuf_print: output for \%s\ exceeds space 0

Wietse Venema
A. Schulze:
>
> wietse:
>
> > A. Schulze:
> >> postqueue: panic: vbuf_print: output for '%s' exceeds space 0

OK, now please (install and) use ltrace. This provides more details
what happens in postqueue itself (strace gives insight into system
calls, i.e.  the postqueue-kernel interface).

        Wietse

>
> this is pfqgrep:
>
>    $mailq = "/usr/sbin/postqueue -p |"; # added 'strace -f' here
>    open(MAILQ, $mailq) or die;
>    while (<MAILQ>) {
>      # read from STDIN
>    }
>
> execve("/usr/sbin/postqueue", ["/usr/sbin/postqueue", "-p"], [/* 52  
> vars */]) = 0
> ...
> chdir("/var/spool/postfix")             = 0
> rt_sigaction(SIGPIPE, {0x1, [PIPE], SA_RESTORER|SA_RESTART,  
> 0x7f4c8e917910}, {SIG_DFL, [], 0}, 8) = 0
> getuid()                                = 0
> socket(PF_FILE, SOCK_STREAM, 0)         = 4
> fcntl(4, F_GETFL)                       = 0x2 (flags O_RDWR)
> fcntl(4, F_SETFL, O_RDWR)               = 0
> connect(4, {sa_family=AF_FILE, path="public/showq"}, 110) = 0
> poll([{fd=4, events=POLLIN}], 1, 3600000) = 1 ([{fd=4, revents=POLLIN}])
> read(4, "queue_name\0active\0queue_id\0003xdsD"..., 4096) = 149
> stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2335, ...}) = 0
> write(1, "----Queue ID----- --Size-- ---Ar"..., 218) = 218
> poll([{fd=4, events=POLLIN}], 1, 3600000) = 1 ([{fd=4, revents=POLLIN}])
> read(4, "queue_name\0active\0queue_id\0003xgg0"..., 4096) = 1453
> stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2335, ...}) = 0
> write(1, "\n3xgg0L0F7Lz4FLj*     30013 Mon "..., 257) = 257
> stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2335, ...}) = 0
> Quantifier follows nothing in regex; marked by <-- HERE in m/+ <--  
> HERE 1234567890123/ at /usr/sbin/pfqgrep line 158, <MAILQ> chunk 1.
> write(1, "\n3xgfY21WScz4FLZ*     32602 Mon "..., 241) = 241
> stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2335, ...}) = 0
> write(1, "\n3xgWSk0qGbz4FKf*     42628 Mon "..., 257) = 257
> stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2335, ...}) = 0
> write(1, "\n3xgh1z1cT1z4FLr*     76609 Mon "..., 184) = -1 EPIPE (Broken pipe)
> --- SIGPIPE (Broken pipe) @ 0 (0) ---
> stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2335, ...}) = 0
> stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2335, ...}) = 0
> stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2335, ...}) = 0
> poll([{fd=4, events=POLLIN}], 1, 3600000) = 1 ([{fd=4, revents=POLLIN}])
> read(4, "queue_name\0active\0queue_id\0003xgKR"..., 4096) = 4096
> stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2335, ...}) = 0
> stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2335, ...}) = 0
> stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2335, ...}) = 0
> stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2335, ...}) = 0
> stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2335, ...}) = 0
> stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2335, ...}) = 0
> stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2335, ...}) = 0
> stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2335, ...}) = 0
> stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2335, ...}) = 0
> stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2335, ...}) = 0
> stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2335, ...}) = 0
> stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2335, ...}) = 0
> stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2335, ...}) = 0
> stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2335, ...}) = 0
> stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2335, ...}) = 0
> stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2335, ...}) = 0
> stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2335, ...}) = 0
> stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2335, ...}) = 0
> stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2335, ...}) = 0
> poll([{fd=4, events=POLLIN}], 1, 3600000) = 1 ([{fd=4, revents=POLLIN}])
> read(4, "3xdqXK4q4lz4FLK\0time\0001503639089\0"..., 4096) = 4096
> stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2335, ...}) = 0
> stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2335, ...}) = 0
> stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2335, ...}) = 0
> stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2335, ...}) = 0
> stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2335, ...}) = 0
> stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2335, ...}) = 0
> stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2335, ...}) = 0
> stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2335, ...}) = 0
> stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2335, ...}) = 0
> stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2335, ...}) = 0
> stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2335, ...}) = 0
> stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2335, ...}) = 0
> stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2335, ...}) = 0
> stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2335, ...}) = 0
> write(2, "postqueue: panic: vbuf_print: ou"..., 62postqueue: panic:  
> vbuf_print: output for '%s' exceeds space 0
> ) = 62
> sendto(3, "<18>Aug 28 08:09:02 postfix/post"..., 95, MSG_NOSIGNAL,  
> NULL, 0) = 95
> rt_sigprocmask(SIG_BLOCK, [CHLD], [], 8) = 0
> rt_sigaction(SIGCHLD, NULL, {SIG_DFL, [], 0}, 8) = 0
> rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
> nanosleep({1, 0}, {1, 0})               = 0
> rt_sigprocmask(SIG_UNBLOCK, [ABRT], NULL, 8) = 0
> tgkill(1753, 1753, SIGABRT)             = 0
> --- SIGABRT (Aborted) @ 0 (0) ---
> +++ killed by SIGABRT +++
>
>
> Maybe perl open not only read from th process but write also
> I've an older version of perl (5.10.0)
> maybe perl open is already changed in newer versions.
>
> > Unfortunately, there is no way that I can reproduce this in
> > postfix-3.2.0, given the preconditions in this code.  Does this
> > machine have ECC memory? Does it have a history of programs crashing?
> no ecc issue. no other crashes. panic starts with reading qshape, take  
> row #1 as argv to pfqgrep.
>
> unrelated by interesting: why does strace show so many  
> 'stat("/etc/localtime" ...' calls?
>
> Andreas
>
>
Reply | Threaded
Open this post in threaded view
|

Re: postfix/postqueue[5742]: panic: vbuf_print: output for \%s\ exceeds space 0

Wietse Venema
In reply to this post by A. Schulze
A. Schulze:

>
> wietse:
>
> > A. Schulze:
> >> postqueue: panic: vbuf_print: output for '%s' exceeds space 0
> >
>
> this is pfqgrep:
>
>    $mailq = "/usr/sbin/postqueue -p |"; # added 'strace -f' here
>    open(MAILQ, $mailq) or die;
>    while (<MAILQ>) {
>      # read from STDIN
>    }
>
> execve("/usr/sbin/postqueue", ["/usr/sbin/postqueue", "-p"], [/* 52  
> vars */]) = 0
> ...
> chdir("/var/spool/postfix")             = 0
> rt_sigaction(SIGPIPE, {0x1, [PIPE], SA_RESTORER|SA_RESTART,  
> 0x7f4c8e917910}, {SIG_DFL, [], 0}, 8) = 0
> getuid()                                = 0
> socket(PF_FILE, SOCK_STREAM, 0)         = 4
> fcntl(4, F_GETFL)                       = 0x2 (flags O_RDWR)
> fcntl(4, F_SETFL, O_RDWR)               = 0
> connect(4, {sa_family=AF_FILE, path="public/showq"}, 110) = 0
> poll([{fd=4, events=POLLIN}], 1, 3600000) = 1 ([{fd=4, revents=POLLIN}])
> read(4, "queue_name\0active\0queue_id\0003xdsD"..., 4096) = 149
> stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2335, ...}) = 0
> write(1, "----Queue ID----- --Size-- ---Ar"..., 218) = 218
> poll([{fd=4, events=POLLIN}], 1, 3600000) = 1 ([{fd=4, revents=POLLIN}])
> read(4, "queue_name\0active\0queue_id\0003xgg0"..., 4096) = 1453
> stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2335, ...}) = 0
> write(1, "\n3xgg0L0F7Lz4FLj*     30013 Mon "..., 257) = 257
> stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2335, ...}) = 0
> Quantifier follows nothing in regex; marked by <-- HERE in m/+ <--  
> HERE 1234567890123/ at /usr/sbin/pfqgrep line 158, <MAILQ> chunk 1.
> write(1, "\n3xgfY21WScz4FLZ*     32602 Mon "..., 241) = 241
> stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2335, ...}) = 0
> write(1, "\n3xgWSk0qGbz4FKf*     42628 Mon "..., 257) = 257
> stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2335, ...}) = 0
> write(1, "\n3xgh1z1cT1z4FLr*     76609 Mon "..., 184) = -1 EPIPE (Broken pipe)

Would it be possible to provide a copy of file 3xgh1z1cT1z4FLr (off-list
email, please) so that I can examine this in detail? If not, output from
"postcat -oeq 3xgh1z1cT1z4FLr" will do.

        Wietse
Reply | Threaded
Open this post in threaded view
|

Re: postfix/postqueue[5742]: panic: vbuf_print: output for \%s exceeds space 0

A. Schulze
In reply to this post by Wietse Venema

wietse:

> OK, now please (install and) use ltrace. This provides more details
> what happens in postqueue itself (strace gives insight into system
> calls, i.e.  the postqueue-kernel interface).

off-list...

I installed ltrace.
I modified pfqgrep: $mailq = "/usr/bin/ltrace /usr/sbin/postqueue -p |";

# pfqgrep -r '+123456789012' > /tmp/ltrace.txt 2>&1
available at https://postmaster.datev.de/tmp/ltrace.txt

There are two strings looking like a queueid in this trace:
3xhXFj2Wt7z4FL3* and 3xhXDS3PqBz4FK9*

that are two messages in the active queue just in the moment I run the  
command above.
postfix delivered both messages as usual...

Btw: as I said, I fixed the initial problem by calling "qshape -w 100"
Is 100 safe? Or even 1000?

I'm fine if you say "Oh ... Andreas run old perl ..." without further  
investigation.
Otherwise I'm willing to support you wherever possible :-)

Andreas

Reply | Threaded
Open this post in threaded view
|

Re: postfix/postqueue[5742]: panic: vbuf_print: output for \%s exceeds space 0

A. Schulze

A. Schulze:

> off-list...
ok not "off list", my fault :-)


Reply | Threaded
Open this post in threaded view
|

Re: postfix/postqueue[5742]: panic: vbuf_print: output for \%s\ exceeds space 0

Wietse Venema
In reply to this post by A. Schulze
A. Schulze:
> There are two strings looking like a queueid in this trace:
> 3xhXFj2Wt7z4FL3* and 3xhXDS3PqBz4FK9*
>
> that are two messages in the active queue just in the moment I run the  
> command above.
> postfix delivered both messages as usual...

To clarify, this panic call happens with arbitrary messages in the
mail queue, not just one message?  In that case I suspect a
site-specific problem, like, a bad build of some kind.

I'm a little surprised that ltrace does not show calls into the
Postfix library. Is this Postfix from a distribution or a custom
build? If it is the latter that would open up the ppssibility of a
site-specific problem.

        Wiete
Reply | Threaded
Open this post in threaded view
|

Re: postfix/postqueue[5742]: panic: vbuf_print: output for \%s\ exceeds space 0

Wietse Venema
In reply to this post by Wietse Venema
Wietse Venema:

> A. Schulze:
> > postqueue: panic: vbuf_print: output for '%s' exceeds space 0
>
> Unfortunately, there is no way that I can reproduce this in
> postfix-3.2.0, given the preconditions in this code.  Does this
> machine have ECC meory? Does it have a history of programs crashing?
>
> Wietse
>
> Message-ID: <[hidden email]>
> postfix 3.2.0
> postqueue: panic: vbuf_print: output for '%s' exceeds space 0
>
> This msg_panic() call is made from VBUF_SNPRINTF():
> #define VBUF_SNPRINTF(bp, sz, fmt, arg) do { \
>         ssize_t _ret; \
>         VBUF_SPACE((bp), (sz)); \
>         _ret = snprintf((char *) (bp)->ptr, (bp)->cnt, (fmt), (arg)); \
>         if (_ret < 0) \
>             msg_panic("%s: output error for '%s'", myname, (fmt)); \
>         if (_ret >= (bp)->cnt) \
>             msg_panic("%s: output for '%s' exceeds space %ld", \
>                       myname, fmt, (long) (bp)->cnt); \
>
> According to the panic message, (bp)->cnt is zero, meaning the
> output buffer has no free space, which can't happen because
> VBUF_SNPRINTF() is called with sz > 0, as will be argued below.
> Therefore, VBUF_SPACE() is called with a value sz > 0, and the
> output buffer must have free space.
>
> The panic message says "%s" therefore this VBUF_SNPRINTF() call is
> made while formatting a string with an fmt value of "%s".

Unfortunately, the panic call overwrites the format string that was
involved with the error, so the analysis for width and precision
is wrong.

        Wietse
Reply | Threaded
Open this post in threaded view
|

Re: postfix/postqueue[5742]: panic: vbuf_print: output for \%s\ exceeds space 0

Wietse Venema
Wietse Venema:
> > The panic message says "%s" therefore this VBUF_SNPRINTF() call is
> > made while formatting a string with an fmt value of "%s".
>
> Unfortunately, the panic call overwrites the format string that was
> involved with the error, so the analysis for width and precision
> is wrong.

If you built Postfix from source, applying this will save the
format string during panic, and may make problem diagnosis
possible.

        Wietse

--- src/util/vbuf_print.c- 2017-01-01 10:58:50.000000000 -0500
+++ src/util/vbuf_print.c 2017-08-30 07:09:17.000000000 -0400
@@ -109,10 +109,10 @@
  VBUF_SPACE((bp), (sz)); \
  _ret = snprintf((char *) (bp)->ptr, (bp)->cnt, (fmt), (arg)); \
  if (_ret < 0) \
-    msg_panic("%s: output error for '%s'", myname, (fmt)); \
+    msg_panic("%s: output error for '%s'", myname, mystrdup(fmt)); \
  if (_ret >= (bp)->cnt) \
     msg_panic("%s: output for '%s' exceeds space %ld", \
-      myname, fmt, (long) (bp)->cnt); \
+      myname, mystrdup(fmt), (long) (bp)->cnt); \
  VBUF_SKIP(bp); \
     } while (0)
 #else
Reply | Threaded
Open this post in threaded view
|

Re: postfix/postqueue[5742]: panic: vbuf_print: output for \%s\ exceeds space 0

Wietse Venema
Wietse Venema:

> Wietse Venema:
> > > The panic message says "%s" therefore this VBUF_SNPRINTF() call is
> > > made while formatting a string with an fmt value of "%s".
> >
> > Unfortunately, the panic call overwrites the format string that was
> > involved with the error, so the analysis for width and precision
> > is wrong.
>
> If you built Postfix from source, applying this will save the
> format string during panic, and may make problem diagnosis
> possible.

Sorry, you also have to add a ``#include "mymalloc.h"'' line.

        Wietse

--- /var/tmp/postfix-3.3-20170730/src/util/vbuf_print.c 2017-01-01 10:58:50.000000000 -0500
+++ src/util/vbuf_print.c 2017-08-30 19:47:51.000000000 -0400
@@ -64,6 +64,7 @@
 /* Application-specific. */
 
 #include "msg.h"
+#include "mymalloc.h"
 #include "vbuf.h"
 #include "vstring.h"
 #include "vbuf_print.h"
@@ -109,10 +110,10 @@
  VBUF_SPACE((bp), (sz)); \
  _ret = snprintf((char *) (bp)->ptr, (bp)->cnt, (fmt), (arg)); \
  if (_ret < 0) \
-    msg_panic("%s: output error for '%s'", myname, (fmt)); \
+    msg_panic("%s: output error for '%s'", myname, mystrdup(fmt)); \
  if (_ret >= (bp)->cnt) \
     msg_panic("%s: output for '%s' exceeds space %ld", \
-      myname, fmt, (long) (bp)->cnt); \
+      myname, mystrdup(fmt), (long) (bp)->cnt); \
  VBUF_SKIP(bp); \
     } while (0)
 #else