Log4cxx
  1. Log4cxx
  2. LOGCXX-126

std::cout stops working if log4cxx is first to output

    Details

    • Type: Bug Bug
    • Status: Resolved
    • Priority: Major Major
    • Resolution: Fixed
    • Affects Version/s: 0.10.0
    • Fix Version/s: 0.10.0
    • Component/s: Appender
    • Labels:
      None
    • Environment:
      Linux (RedHat FC4) x86_64, g++ 4.0.2 20051125 (Red Hat 4.0.2-8)

      Description

      If log4cxx is the first to write output via the ConsoleAppender, then std::cout (and stdout) doesn't work. If, on the other hand, std::cout is written to before log4cxx kicks in, then they both (std::cout and log4cxx) work. I will attach a small test program that illustrates the problem.

      1. output.cpp
        1 kB
        Andreas Fester
      2. triv.cpp
        0.4 kB
        Donovan Kolbly

        Activity

        Hide
        Donovan Kolbly added a comment -

        Trivial logging/std::cout program that illustrates the problem. As attached, the output after the LOG4CXX_DEBUG works, but if the first std::cout is removed, then the same outputs are lost.

        Show
        Donovan Kolbly added a comment - Trivial logging/std::cout program that illustrates the problem. As attached, the output after the LOG4CXX_DEBUG works, but if the first std::cout is removed, then the same outputs are lost.
        Hide
        Donovan Kolbly added a comment -

        This problem also manifests on gcc 3.4.4 / i686. Since this could be some kind of standard library interaction, I thought that worth mentioning.

        Show
        Donovan Kolbly added a comment - This problem also manifests on gcc 3.4.4 / i686. Since this could be some kind of standard library interaction, I thought that worth mentioning.
        Hide
        Donovan Kolbly added a comment -

        I notice a difference in the strace output of running the two variants of the test program. In the one where log4cxx is the first to print, there is an ioctl() and an lseek() call which is missing in the other:

        lseek(1, 0, SEEK_CUR) = -1 ESPIPE (Illegal seek)
        ioctl(1, SNDCTL_TMR_TIMEBASE or TCGETS,

        {B38400 opost isig icanon echo ...}

        ) = 0

        so it seems there is some stuff going on under the covers that is different.

        I did verify with gdb that SystemOutWriter::write() is being used, and it apparently just invokes std::cout on a std::string, so it is somewhat unclear why it shouldn't just work...

        Show
        Donovan Kolbly added a comment - I notice a difference in the strace output of running the two variants of the test program. In the one where log4cxx is the first to print, there is an ioctl() and an lseek() call which is missing in the other: lseek(1, 0, SEEK_CUR) = -1 ESPIPE (Illegal seek) ioctl(1, SNDCTL_TMR_TIMEBASE or TCGETS, {B38400 opost isig icanon echo ...} ) = 0 so it seems there is some stuff going on under the covers that is different. I did verify with gdb that SystemOutWriter::write() is being used, and it apparently just invokes std::cout on a std::string, so it is somewhat unclear why it shouldn't just work...
        Hide
        Andreas Fester added a comment -

        The problem is that intermixing output to wide and narrow streams is undefined behaviour. See for example http://nixdoc.net/files/forum/about50404.html:

        "Note that for unicode output, wide strings have portability
        issues. You can't mix wide and narrow streams (e.g. std::wcout and
        std::cout), which will cause problems if you use libraries which use
        the other stream width.

        The best solution is to use gettext() and narrow streams. This is
        both portable and flexible, and backward compatible with non-UTF-8
        locales (it recodes the strings on the fly to the locale codeset)."

        The ConsoleAppender uses wcout when log4cxx is compiled with WCHAR_T support.
        (I also found this issue while working on the InputStreamReader() when executing the regression tests: Some of the test cases perform output through cout, which conflicts with ConsoleAppender's wcout; but, the issue only occurs on AMD64 with current runtime libraries, while on i386 with older versions of the libraries it works).

        Show
        Andreas Fester added a comment - The problem is that intermixing output to wide and narrow streams is undefined behaviour. See for example http://nixdoc.net/files/forum/about50404.html: "Note that for unicode output, wide strings have portability issues. You can't mix wide and narrow streams (e.g. std::wcout and std::cout), which will cause problems if you use libraries which use the other stream width. The best solution is to use gettext() and narrow streams. This is both portable and flexible, and backward compatible with non-UTF-8 locales (it recodes the strings on the fly to the locale codeset)." The ConsoleAppender uses wcout when log4cxx is compiled with WCHAR_T support. (I also found this issue while working on the InputStreamReader() when executing the regression tests: Some of the test cases perform output through cout, which conflicts with ConsoleAppender's wcout; but, the issue only occurs on AMD64 with current runtime libraries, while on i386 with older versions of the libraries it works).
        Hide
        Curt Arnold added a comment -

        From Langer and Kreft, "Standard C++ IOStreams and Locales", pg 466:

        The relationship between global narrow-character streams and their wide-character counterparts is undefined, which means that you do not know what is going to happen if you use both in the same program.

        So it is more than just an weakness in one STL implementation and the source is more definitive without diving into the STL spec.

        pg 13 says that you can mix C stdio functions on stdout and cout and the order will be preserved.

        That suggests to me that the better approach would be to bypass STL in this case and go directly to the C stdio methods which should preserve the ability to use either std::cout or std::wcout in the calling programs.

        Show
        Curt Arnold added a comment - From Langer and Kreft, "Standard C++ IOStreams and Locales", pg 466: The relationship between global narrow-character streams and their wide-character counterparts is undefined, which means that you do not know what is going to happen if you use both in the same program. So it is more than just an weakness in one STL implementation and the source is more definitive without diving into the STL spec. pg 13 says that you can mix C stdio functions on stdout and cout and the order will be preserved. That suggests to me that the better approach would be to bypass STL in this case and go directly to the C stdio methods which should preserve the ability to use either std::cout or std::wcout in the calling programs.
        Hide
        Andreas Fester added a comment -

        This sounded like a real cool solution when I read it, but: mixing only applies to functions within the same class, i.e. you can mix C stdio and stl char functions, and C wide char and stl wide char functions, not C wide char and stl narrow functions or C narrow functions and stl wide functions. This is because the underlying streams are the same within each set of functions. See attached file output.cpp which checks some of the combinations.

        IMHO, the main issue is the calling application: we do not know in advance whether the calling application will use wide or narrow streams, so we probably have to provide even a runtime switch to choose between them. Otherwise we end up with two versions of the library, one compiled for wcerr/wcout and one compiled for cerr/cout.

        Show
        Andreas Fester added a comment - This sounded like a real cool solution when I read it, but: mixing only applies to functions within the same class, i.e. you can mix C stdio and stl char functions, and C wide char and stl wide char functions, not C wide char and stl narrow functions or C narrow functions and stl wide functions. This is because the underlying streams are the same within each set of functions. See attached file output.cpp which checks some of the combinations. IMHO, the main issue is the calling application: we do not know in advance whether the calling application will use wide or narrow streams, so we probably have to provide even a runtime switch to choose between them. Otherwise we end up with two versions of the library, one compiled for wcerr/wcout and one compiled for cerr/cout.
        Hide
        Curt Arnold added a comment -

        Added a simple console driver program to the examples directory which allows you to output "Hello" to the console by different methods in arbitrary order.

        With Visual Studio .NET 2003 under Windows XP, I could intermix any sequence of byte and wide C RTL, STL and log4cxx console output without any obvious problems. With gcc 3.3.5 on SuSE 9.3 x86, I could mix cout, wcout, log and puts without problems, but putws would stop anything but another putws to fail (including wcout) and would fail after any of the other methods. fwide(stdout, 1) had the same effect as fputws.

        Based on the SuSE x86 observations, I would suggest having the console appender do something like:

        if (fwide(stdout, -1) < 0)

        { ... fputs(..., stdout); }

        else

        { fputws(..., stdout); }

        Which should allow log statements to work after calls to fputws.

        I appreciate observations of from x86_64 or other platforms. I do have an AMD64 portable and have SuSE 10 x86_64 available, but not installed.

        Show
        Curt Arnold added a comment - Added a simple console driver program to the examples directory which allows you to output "Hello" to the console by different methods in arbitrary order. With Visual Studio .NET 2003 under Windows XP, I could intermix any sequence of byte and wide C RTL, STL and log4cxx console output without any obvious problems. With gcc 3.3.5 on SuSE 9.3 x86, I could mix cout, wcout, log and puts without problems, but putws would stop anything but another putws to fail (including wcout) and would fail after any of the other methods. fwide(stdout, 1) had the same effect as fputws. Based on the SuSE x86 observations, I would suggest having the console appender do something like: if (fwide(stdout, -1) < 0) { ... fputs(..., stdout); } else { fputws(..., stdout); } Which should allow log statements to work after calls to fputws. I appreciate observations of from x86_64 or other platforms. I do have an AMD64 portable and have SuSE 10 x86_64 available, but not installed.
        Hide
        Curt Arnold added a comment -

        SystemOutWriter and SystemErrWriter will use fputws() if LOG4CXX_FORCE_WIDE_CONSOLE is set or if console is already wide character oriented. Otherwise, will use encoding message to default encoding and output using fputs().

        LOG4CXX_FORCE_WIDE_CONSOLE is set for Windows, since the Microsoft compilers support interleaving fputws() and fputs() output to the console and using fputs() would result having to substitute for any characters that could not be represented in the current code page. When Borland and MinGW builds are refreshed, their behavior should be checked.

        Show
        Curt Arnold added a comment - SystemOutWriter and SystemErrWriter will use fputws() if LOG4CXX_FORCE_WIDE_CONSOLE is set or if console is already wide character oriented. Otherwise, will use encoding message to default encoding and output using fputs(). LOG4CXX_FORCE_WIDE_CONSOLE is set for Windows, since the Microsoft compilers support interleaving fputws() and fputs() output to the console and using fputs() would result having to substitute for any characters that could not be represented in the current code page. When Borland and MinGW builds are refreshed, their behavior should be checked.

          People

          • Assignee:
            Curt Arnold
            Reporter:
            Donovan Kolbly
          • Votes:
            0 Vote for this issue
            Watchers:
            1 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved:

              Development