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
>
>
