printf disables lib$signal stack dump on stdout?

[Claus Olesen]

We run a number of daemon type processes on our OpenVMS/IA64 systems. They are started by a master program using $creprc and config files but in principle like this
$ run prog /out=prog.out
The problem we're having with this is that we need to stop the process in order to view the log file.

But if we ignore stdout and instead open a log file directly in the program for shared access then another problem for us is that stdout is not automatically flushed (whereas stderr is). Finally, sometimes we would like stack dumps in the stdout file mingled with other output.

The following program is an attempt on testing for a solution to these issues

#include
#include
#include
#include
#include

/* printf with flush */
int printff(const char *template, ...)
{
int sts;
va_list ap;

va_start(ap,template);
sts=vfprintf(stdout,template,ap);
va_end(ap);
fflush(stdout);
fsync(fileno(stdout));
return sts;
}

int main()
{
freopen("std.out","a+",stdout,"shr=get"); //reopen for shared access
printff("before\n"); //log some text with flush
lib$signal(0); //log dump of call stack
printff("after\n"); //log more text with flush

sys$hiber(); //to allow test of shared access before exit
return 1;
}

I used lib$signal (on a non-fatal code) because it dumps stack and is readily available (whereas TBK$I64_SYMBOLIZE looks like it may take some time to apply. TBK$IA64_TRACEBACK I think is really what we are looking for but is not documented?)

I had the problem with the above that the stack dump by lib$signal(0) does not show up in stdout if also printf's are present. As in this excerpt

#include
#include
int main()
{
printf("before\n");
lib$signal(0);
printf("after\n");
return 1;
}

If I comment out the printf's or instead assigna file to sys$output from the commandline rather than using the /out qualifier of the run command then the stack dump does show up in the stdout file.
Is that to be expected?

[Ian Miller.]

I vaguely recall having to do something with stdout or stderr in a condition handler then resignaling the error so that stack dumps appeared correctly. It was due to the interaction between what the CRTL does with stdout and code that write to SYS$OUTPUT directly.

[Hoff · Accepted solution]

The sequence for creating and maintaining a shareable log file is discussed in the OpenVMS FAQ. I assume this is what you are using when you manage your own (shareable) log file.

On older OpenVMS releases, the process rundown doesn't necessarily completely flush the I/O channels. You can try a SET FILE/END on the log file, and potentially get a little more data at the end of the file. Basically, flushing the data that can be lurking between the EOF and the end of the file. (I'd assume that the OpenVMS I64 release in use here would have this rundown-related change. That change was at V7.3-1, IIRC.)

The somewhat sneaky (and fully documented, and long-standing) mechanism for getting a log file is to signal SS$_DEBUG, and to pass in debugger commands that way. The first is an output log file declaration, then a series of show call and show stack commands, etc. (An example of this is in the FAQ.)

lib$signal(0)? That's not a valid condition code. There are signal handlers which output data from the signal frames, if that's the direction you are headed here. That's an approach I would consider here. I've certainly displayed a whole lot in the signal handler itself.

I tend to go in one of two directions here, either toward generating a process dump, or toward integrating the debugging into the application. The OpenVMS signal display stuff is certainly useful, but -- save for hard failures like ACCVIOs -- the displayed stackdump almost never has what I need in the dump. Having an application-specific log is often best, and having a dump file is second. In some cases, I use both.

C itself adds a layer onto this problem, and another layer of caching. I tend to aim this outout stuff into a local routine that fields all of this, including capabilities for passing in a variable-length argument list. At the lowest level, it can be printf, but when working with the stack frames and such (and inherently non-portable), I tend to use lib$put_output or sys$putmsg.

And rather than issuing a process deletion, a $forcex or the associated STOP command would be appropriate. See the /EXIT qualifier on recent STOP commands. This flushes logs and the output in the RMS caches.

[Claus Olesen]

Thank you for your replies.

I just tested a little more on a file abc.c containing this

#include
#include
#include
#include
int main()
{
//printf("stdout\n");
//fprintf(stderr,"stderr\n");
lib$signal(SS$_NOSUCHFILE);

/* verify that process does not exit because of the above signal */
//sys$hiber();
return 1;
}

Hoff wrote that condition code "0" is not valid so I picked SS$_NOSUCHFILE instead hoping it is harmless aside from resulting in the desired stack dump without exit from also being a non-success non-severe code.

I built and ran using this
cc abc.c
link abc.c
run abc /out=abc.out/err=abc.err/proc=abc


What I observed is that

1) if I leave the program as above then both the stdout and stderr file shows a stack dump (and only that) e.g.
%SYSTEM-W-NOSUCHFILE, no such file
%TRACE-W-TRACEBACK, symbolic stack dump follows
image module routine line rel PC abs PC
ABC ABC main 23783 0000000000000120 0000000000010120
ABC ABC __main 23776 00000000000000C0 00000000000100C0
0 FFFFFFFF80B23210 FFFFFFFF80B23210
0 FFFFFFFF8055C9A0 FFFFFFFF8055C9A0
%TRACE-I-END, end of TRACE stack dump

2) if I uncomment the printf then stdout shows "stdout" and no longer the stack dump whereas stderr still shows (only) the stack dump.

3) if I instead uncomment the fprintf then stdout again shows (only) the stack dump whereas stderr shows "stderr" and the following instead of the stack dump
"TRACEBACK Error: failure on output lineTRACEBACK Error: failure on output lineTRACEBACK Error: failure on output lineTRACEBACK Error: failure on output lineTRACEBACK Error: failure on output line"

4) if I uncomment both the printf and the fprintf then the result is the union of 2) and 3). E.g. stdout again shows only "stdout" e.g. no stack dump whereas stderr shows "stderr" and the following instead of the stack dump
"TRACEBACK Error: failure on output lineTRACEBACK Error: failure on output lineTRACEBACK Error: failure on output lineTRACEBACK Error: failure on output lineTRACEBACK Error: failure on output line".

To me it looks like a bug.
Firstly, I question if inclusion of the printf should result in the stack dump no longer being included in stdout. Another question is perhaps if the stack dump should show on stdout at all in the first place.
Secondly, I question the "TRACEBACK Error: failure on output line" on stderr when explicitly writing to stderr. But perhaps it is illegal to explicitly write to stderr?

Hoff mentioned the new "stop/exit". Thank you. I tried it. I uncommented the above sys$hiber and used "stop/exit" to stop/exit the program. And observed that "stop/exit" does not flush printf buffers to the stdout file before exit/delete of the process whereas "stop/image" (alias sys$forcex) does. To me it looks like stop/exit is intended specifically only for custom exit handlers. Just an observation.

We are currently using OpenVMS 8.2-1 on IA64.

[Claus Olesen]

I tested also on an AXP OpenVMS 7.2-1 using the above abc.c program. Besides from providing a proper traceback rather than the multiple "TRACEBACK Error: ..." produced by the IA64 then the result is the same e.g. use of printf in a C program somehow disables print of stack traces to stdout - not only staged stack traces as in the above but also stack traces from real exceptions such as for example a real ACCVIO. fprintf(stderr,...) shows the exact same behavior. A little scary. I guess the morale is to never C print to both stdout and stderr if a stack trace is desired in case the program should crash.

Thank you for the info on LIB$PUT_OUTPUT and SYS$PUTMSG. I tried LIB$PUT_OUTPUT but unfortunately got the exact same behavior as with printf. Does this mean that the problem is not with CRTL but perhaps with RMS?

I tried using this on IA64

#include
#include
#include
#include
#include
#include
int main()
{
struct dsc$descriptor strdsc = {6,DSC$K_DTYPE_T,DSC$K_CLASS_S,"stdout"};

// lib$put_output(&strdsc);
lib$signal(SS$_NOSUCHFILE);
lib$put_output(&strdsc);
lib$signal(SS$_NOSUCHFILE);
lib$put_output(&strdsc);

return 1;
}

I also tried with the first call uncommented. It showed that whoever is called first wins.

If lib$put_output is called first then no stack trace is produced on stdout. If lib$signal is called first then no "stdout" message is produced.