Leftover logfile is close()d … unpredictably?

[FGasper]

#include <stdio.h>
#include <unbound.h>

int main(void)
{
    FILE *tfh = tmpfile();
    setvbuf( tfh, NULL, _IONBF, 0 );

    struct ub_ctx* ctx;

    for (int i=0; i<2; i++) {
        ctx = ub_ctx_create();

        ub_ctx_debuglevel(ctx, 5);
        ub_ctx_debugout( ctx, tfh );

        ub_ctx_delete(ctx);

        if (-1 == fseek(tfh, 0, 0)) {
            perror("fseek()");
        }
    }
}

The above code illustrates a problem where a 2nd context creation will clobber a leftover logfile from a former context.

It seems like the ideal fix would be to put the log state variables into the context struct rather than having them be globals?

(I haven’t tested it, but it looks like, given the globals, it would be problematic, for example, to have two concurrent Unbound objects in the same process with different log outputs?)

Failing that change … is there any way to fix this, short of removing that fclose() in log.c (and potentially breaking behavior that implementations may have been expecting now for over 10 years)?

Regardless, it seems like this issue should at least be documented? The existing libunbound(3) documentation for ub_ctx_debugout() gives the impression that log state is contained entirely within the log object, which of course isn’t the case.

The workaround seems to be to set the log handle to stderr before deleting the context … does that seem reasonable?

Thank you!

[wcawijngaards]

Have you tried _IOLBF ? The line buffer should correspond nicely to the line-at-a-time log entries, when you use two contexts at the same time.
This is a fix to switch to stderr when there is an override, in ctx_delete. It works, and if I add fclose(tfh) to the end of the example to free that, it is error free.

diff --git a/libunbound/libunbound.c b/libunbound/libunbound.c
index 5f5a8a10..9dd7d6db 100644
--- a/libunbound/libunbound.c
+++ b/libunbound/libunbound.c
@@ -328,6 +328,8 @@ ub_ctx_delete(struct ub_ctx* ctx)
        ub_randfree(ctx->seed_rnd);
        alloc_clear(&ctx->superalloc);
        traverse_postorder(&ctx->queries, delq, NULL);
+       if(ctx->logfile_override)
+               log_file(NULL);
        free(ctx);
 #ifdef USE_WINSOCK
        WSACleanup();

[FGasper]

This is the workaround that I have in place in my calling code. It seems to fix this particular issue, yes. :)

There seems to be a related problem, where anything that depends on the global logfile will break if there are concurrent contexts:

struct ub_ctx* ctx1 = ub_ctx_create();
struct ub_ctx* ctx2 = ub_ctx_create();

ub_ctx_debugout( ctx1, fh1 );    // sets global `logfile` variable in log.c

ub_ctx_debugout( ctx2, fh2 );    // sets global `logfile` … clobbers previous setting?

I’ve not analyzed the code enough to determine if this causes “real” breakage.

[wcawijngaards]

Not really "real" breakage, apart from a global variable. At least I think that is what happens.

[wcawijngaards]

Thanks for the report, the fix is for the unpredictable close, and does not address the global variable use. That is for debug.

[FGasper]

Thank you!