Calling fclose() on a NULL filehandle on win32 causes an assertion to fail

[geoffbeier]

No description provided.

[JenkinsForOpenSC]

Can one of the admins verify this patch?

[LudovicRousseau]

How can you get a NULL ctx->debug_file at the fclose()?

A few lines before (line 120) we have https://github.com/OpenSC/OpenSC/blob/master/src/libopensc/log.c#L120

    outf = ctx->debug_file;
    if (outf == NULL)
        return;

[geoffbeier]

That is a very good question. I do not know how ctx->debug_file became NULL between the check and the fclose(). But it did, very consistently, as soon as I changed my opensc configuration to a higher log level.

Our application is a GUI tool that starts a background thread to access the card. Most of the time that background thread blocks on a call like
sc_wait_for_event(ctx, mask, &reader, &event, -1, NULL);
When the main thread requests that the blocking be cancelled, sc_cancel(ctx); is called from the main thread.

Could the file write be taking long enough that the call by the other thread is causing ctx->debug_file to be set to NULL between the check and the call to fclose()?

[LudovicRousseau]

We have a different problem:

• the return value of sc_ctx_log_to_file() is not checked
• the file handle should not be closed at https://github.com/OpenSC/OpenSC/blob/master/src/libopensc/log.c#L132 since it may be stdout or stderr. The close is done in sc_ctx_log_to_file()
• the function sc_do_log_va() is not be thread safe

[geoffbeier]

Doesn't sc_ctx_log_to_file() always open a new one after closing any existing one?
https://github.com/OpenSC/OpenSC/blob/master/src/libopensc/ctx.c#L211

So it sounds like the right fix is to:

• check the return value of sc_ctx_log_to_file() and have sc_do_log_va() return if it's anything other than SC_SUCCESS.
• Inside sc_ctx_log_to_file() make sure to set ctx->debug_file to NULL whenever it does call fclose() on it.
• Inside sc_do_log_va() where it currently calls fclose() check
  if(ctx->debug_file && ctx->debug_file != stdout &&ctx->debug_file != stderr)

Obviously, none of that will take care of the thread safety. Can (or should) sc_do_log_va() be fixed to be thread safe? Or should I just not be calling sc_cancel() to force a blocking sc_wait_for_event() to return? If that's the case, could you suggest a better way?

[LudovicRousseau]

Maybe the solution is to never close the handle and open it only once (if needed).

Untested:

--- /var/folders/x0/49d2r2j93qscjp625r74zjwc0000gn/T//jQcXh7_ctx.c  2013-07-03 13:24:24.000000000 +0200
+++ src/libopensc/ctx.c 2013-07-03 13:24:11.000000000 +0200
@@ -198,9 +198,9 @@ static void set_defaults(sc_context_t *c
  */
 int sc_ctx_log_to_file(sc_context_t *ctx, const char* filename)
 {
-   /* Close any existing handles */
-   if (ctx->debug_file && (ctx->debug_file != stderr && ctx->debug_file != stdout))
-       fclose(ctx->debug_file);
+   /* Nothing to do if already set */
+   if (ctx->debug_file)
+       return SC_SUCCESS;

    /* Handle special names */
    if (!strcmp(filename, "stdout"))
--- /var/folders/x0/49d2r2j93qscjp625r74zjwc0000gn/T//ZfNrEX_log.c  2013-07-03 13:24:25.000000000 +0200
+++ src/libopensc/log.c 2013-07-03 13:22:44.000000000 +0200
@@ -127,14 +127,6 @@ static void sc_do_log_va(sc_context_t *c
        fprintf(outf, "\n");
    fflush(outf);

-#ifdef _WIN32
-   if (ctx->debug_filename)   {
-       fclose(ctx->debug_file);
-       ctx->debug_file = NULL;
-   }
-#endif
-
-
    return;
 }

[viktorTarasov]

It's possible "to never close handle and to open it only once"
with configuration option reopen_debug_file set to false.

By default, the debug file is opened before every log message and closed immediately after.

[viktorTarasov]

@geoffbeier
applied in f053070 your suggestions from comments #171 (comment)

"fopen - fclose" frame for debug messages was introduced as a configuration option with the regards to OpenSC minidriver, that is accessed in a multi-thread mode, and the difficulties to share handle of debug file handle between these threads.