Experimental Physics and
Industrial Control System

Michael Davidsaver via Core-talk <core-talk at aps.anl.gov> · Mon, 13 Apr 2020 21:52:57 -0700

Hi Freddie,

You put me on the path to a solution (really workaround).
And a lucky google search has given me a new favorite toy.

https://godbolt.org/

Compiling the following with MSVC demonstrates the problem with test1, and a workaround with test2.

> void _log_printf(unsigned lvl, const char* fmt, ...);
> 
> #define log_printf(LOGGER, LVL, FMT, ...) do{ \
>     _log_printf(unsigned(LVL), "%s " FMT, "blah", __VA_ARGS__); \
> }while(0)
> 
> #define log_info_printf1(LOGGER, ...)  log_printf(LOGGER, 5, __VA_ARGS__)
> #define log_info_printf2(LOGGER, FMT, ...)  log_printf(LOGGER, 5, FMT, __VA_ARGS__)
> 
> void expected() {
>     _log_printf(5, "%s test %d %d", "blah", 1, 2);
> }
> 
> void test1() {
>     log_info_printf1(foo, "test %d %d", 1, 2);
> }
> 
> void test2() {
>     log_info_printf2(foo, "test %d %d", 1, 2);
> }

On 4/13/20 11:53 AM, Freddie Akeroyd - UKRI STFC via Core-talk wrote:
> 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