Experimental Physics and
Industrial Control System

Freddie Akeroyd - UKRI STFC via Core-talk <core-talk at aps.anl.gov> · Mon, 13 Apr 2020 18:53:32 +0000

Hi Michael,

I ran your code through the visual studio pre-processor to see what it generated and it was:

    do{ if((logerr).test(::pvxs::Level::Info)) ::pvxs::detail:: _log_printf(unsigned(::pvxs::Level::Info), "%s " "Enter loop worker for %p\n", base.get(), ""  ); }while(0);

So the "" argument is being moved to the end. I removed the string concatenation and the problem was still there. I moved the "" argument to before the FMT   i.e.

    _log_printf(unsigned(LVL), "", "%s " FMT, __VA_ARGS__)

And then it seemed to pre-process correctly, so I think you may have discovered an interesting "feature" of the pre-processor

Regards,

Freddie

-----Original Message-----
From: Core-talk <core-talk-bounces at aps.anl.gov> On Behalf Of Michael Davidsaver via Core-talk
Sent: 13 April 2020 08:29
To: EPICS core-talk <core-talk at aps.anl.gov>
Subject: MSVC printf/vararg weirdness

All,

I've run up against a strange behavior with MSVC.  I've reduced the problem somewhat, but which I'm not sure how to proceed.  This might have something to do with the MSVC pre-processor, implicit concatenation of string constants, or maybe vararg functions.

It has to do with how I'm trying to do logging.  At core I have a function:

> void _log_printf(unsigned lvl, const char* fmt, ...);

which internally calls errlogVprintf()

I'm calling it through two levels of macro.  eg.

> #define log_info_printf(LOGGER, ...)  log_printf(LOGGER, 
> ::pvxs::Level::Info, __VA_ARGS__)

> #define log_printf(LOGGER, LVL, FMT, ...) do{ \
>     if((LOGGER).test(LVL)) \
>        ::pvxs::detail:: _log_printf(unsigned(LVL), "%s " FMT, "", 
> __VA_ARGS__); \
> }while(0)

called like:

> log_info_printf(logerr, "Enter loop worker for %p\n", base.get());

The reason for the second level of macro is that I'd like to prefix each log line with some extra information, including a timestamp, in a way which can't be split.
(as could happen if I called errlogPrintf() twice)

The above is already a reduced case.  The empty string constant "" after FMT will be replaced with a char* returned by a function (a thread local buffer).  However, I can't get that far.

The above, with the empty string constant, is somehow corrupting output and crashing.
eg.

> `b"l  Enter loop worker for 00007FFA6C34DCC0 `b"l  Enter loop worker 
> for 00007FFA6C34DCC0

If I change the log_printf macro as follows, then everything is fine (sans timestamp).

> #define log_printf(LOGGER, LVL, FMT, ...) do{ \
>     if((LOGGER).test(LVL)) \
>        ::pvxs::detail:: _log_printf(unsigned(LVL), FMT, __VA_ARGS__); 
> \
> }while(0)

Does anyone have an idea of what is going on here?

I don't think I'm depending on any GCC-isms here.  (eg.  __VA_ARGS__ always has at least one argument)  And '"%s " FMT' should be taking advantage of automatic concatenation of string constants.

I'm seeing this on appveyor with the MSVC 2019, 2017, and 2015.
mingw builds work fine.

https://ci.appveyor.com/project/mdavidsaver/pvxs

the full version I'm starting from (and would like to end with).

https://github.com/mdavidsaver/pvxs/blob/e2a7e5e451a06e3865b8684e747dfaa6026a6e15/src/pvxs/log.h#L77-L80

Experimental Physics and Industrial Control System

Experimental Physics and
Industrial Control System