Logging change crashes on OSX

[annatisch]

It seems one of the latest logging changes crashes in connection.c log_outgoing_frame (probably incoming frame too, but the code doesn't get that far).

By reverting these changes:

• Removing the extra "%s" argument here:
  https://github.com/Azure/azure-uamqp-c/blob/master/src/connection.c#L250

• And removing the "if (0) " statement here:
  https://github.com/Azure/azure-c-shared-utility/blob/master/inc/azure_c_shared_utility/xlogging.h#L113

Then it runs without issues.

[dcristoloveanu]

Hi @annatisch

Very interesting. I need to look at this in closer detail tomorrow. I don't understand yet why it would crash. The only explanation would be VA_ARGS gets expanded to something else and and basically the printf under LOG() attempts to print a string from a pointer that is not pointing to a string.

The problem with removing the extra %s is that a warning is spewed I believe by clang that a spring is directly used in printf as format (which is a potential for security issues usually - because if the string unintentionally contains a %s or some other format specifier then unspecified things will happen including segfaults).

So the correct way to handle this is to use %s, but the problem seems to be the VA_ARGS expansion.
I'll look at it more tomorrow.

Cheers,
/Dan

[dcristoloveanu]

@annatisch I was looking a bit more into this today.
One thing to mention is that the %s formatting is there to avoid the warning on clang when building for OsX:

/Users/jenkins/build/workspace/c-osx-xcode-native/src/connection.c:225:30: error: format string is not a string literal (potentially insecure) [-Werror,-Wformat-security]
LOG(AZ_LOG_TRACE, 0, get_frame_type_as_string(descriptor));
^~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
In file included from /Users/jenkins/build/workspace/c-osx-xcode-native/src/connection.c:10:
/Users/jenkins/build/workspace/c-osx-xcode-native/deps/azure-c-shared-utility/inc/azure_c_shared_utility/xlogging.h:113:77: note: expanded from macro 'LOG'
#define LOG(log_category, log_options, format, ...) { if (0) { (void)printf(format, ##VA_ARGS); } { LOGGER_LOG l = xlogging_get_log_function(); if (l != NULL) l(log_category, FILE, FUNC_NAME, LINE, log_options, format, ##VA_ARGS); } }
^~~~~~
/Users/jenkins/build/workspace/c-osx-xcode-native/src/connection.c:225:30: note: treat the string as an argument to avoid this
LOG(AZ_LOG_TRACE, 0, get_frame_type_as_string(descriptor));
^
"%s",

I think the clang compiler is right generally, there should always be a string literal used as format. Otherwise it is easier to introduce a mistake and provide a format string that might contain a format specifier in it and then a bug ensues.

Which compiler are you using? clang or gcc?
I am asking because I'd like to try and repro the failure.

Cheers,
/Dan

[dcristoloveanu]

Hi @annatisch,

Whenever you have some extra time can you update me on the compiler used so I can try a repro?

Cheers,
/Dan

[annatisch]

So sorry for dropping the ball here!
My full build log is as follows:

2018-12-06T20:44:19.7407280Z Building with generator: Unix Makefiles
2018-12-06T20:44:19.7408090Z calling cmake /Users/vsts/agent/2.142.1/work/1/s/src/vendor/azure-uamqp-c/ -G "Unix Makefiles" -Duse_openssl:bool=ON -Duse_default_uuid:bool=ON  -Duse_builtin_httpapi:bool=ON  -Dskip_samples:bool=ON -DCMAKE_POSITION_INDEPENDENT_CODE=TRUE -DCMAKE_BUILD_TYPE=Release
2018-12-06T20:44:20.3000250Z -- The C compiler identification is AppleClang 9.1.0.9020039
2018-12-06T20:44:20.4233070Z -- The CXX compiler identification is AppleClang 9.1.0.9020039
2018-12-06T20:44:20.4581610Z -- Check for working C compiler: /Applications/Xcode_9.4.1.app/Contents/Developer/Toolchains/XcodeDefault.xctoolchain/usr/bin/cc
2018-12-06T20:44:21.2717030Z -- Check for working C compiler: /Applications/Xcode_9.4.1.app/Contents/Developer/Toolchains/XcodeDefault.xctoolchain/usr/bin/cc -- works
2018-12-06T20:44:21.2752260Z -- Detecting C compiler ABI info
2018-12-06T20:44:21.5093270Z -- Detecting C compiler ABI info - done
2018-12-06T20:44:21.5317440Z -- Detecting C compile features
2018-12-06T20:44:22.2476470Z -- Detecting C compile features - done
2018-12-06T20:44:22.2623730Z -- Check for working CXX compiler: /Applications/Xcode_9.4.1.app/Contents/Developer/Toolchains/XcodeDefault.xctoolchain/usr/bin/c++
2018-12-06T20:44:22.4964920Z -- Check for working CXX compiler: /Applications/Xcode_9.4.1.app/Contents/Developer/Toolchains/XcodeDefault.xctoolchain/usr/bin/c++ -- works
2018-12-06T20:44:22.5148200Z -- Detecting CXX compiler ABI info
2018-12-06T20:44:22.7475200Z -- Detecting CXX compiler ABI info - done
2018-12-06T20:44:22.7747220Z -- Detecting CXX compile features
2018-12-06T20:44:24.0646000Z -- Detecting CXX compile features - done
2018-12-06T20:44:24.1086120Z -- Looking for include file stdint.h
2018-12-06T20:44:24.3478260Z -- Looking for include file stdint.h - found
2018-12-06T20:44:24.3556480Z -- Looking for include file stdbool.h
2018-12-06T20:44:24.5657940Z -- Looking for include file stdbool.h - found
2018-12-06T20:44:24.9024420Z -- target architecture: GENERIC
2018-12-06T20:44:24.9112810Z -- Performing Test CXX_FLAG_CXX11
2018-12-06T20:44:25.0581750Z -- Performing Test CXX_FLAG_CXX11 - Failed
2018-12-06T20:44:27.3844400Z -- Found OpenSSL: /Users/vsts/agent/2.142.1/work/_temp/openssl/lib/libcrypto.a (found version "1.0.2q")  
2018-12-06T20:44:27.4137130Z -- target architecture: GENERIC
2018-12-06T20:44:27.4243250Z -- Configuring done
2018-12-06T20:44:27.5288130Z -- Generating done
2018-12-06T20:44:27.5470200Z -- Build files have been written to: /Users/vsts/agent/2.142.1/work/1/s/build/temp.macosx-10.6-intel-3.6/cmake
2018-12-06T20:44:27.5525050Z calling cmake --build . --config Release
2018-12-06T20:44:27.7295850Z Scanning dependencies of target aziotsharedutil
2018-12-06T20:44:27.7562710Z [  1%] Building C object deps/azure-c-shared-utility/CMakeFiles/aziotsharedutil.dir/src/base32.c.o
2018-12-06T20:44:28.1616510Z [  2%] Building C object deps/azure-c-shared-utility/CMakeFiles/aziotsharedutil.dir/src/base64.c.o
2018-12-06T20:44:28.5334990Z [  3%] Building C object deps/azure-c-shared-utility/CMakeFiles/aziotsharedutil.dir/src/buffer.c.o
2018-12-06T20:44:28.8075710Z [  5%] Building C object deps/azure-c-shared-utility/CMakeFiles/aziotsharedutil.dir/src/connection_string_parser.c.o
2018-12-06T20:44:29.0514160Z [  6%] Building C object deps/azure-c-shared-utility/CMakeFiles/aziotsharedutil.dir/src/constbuffer.c.o
2018-12-06T20:44:29.2686140Z [  7%] Building C object deps/azure-c-shared-utility/CMakeFiles/aziotsharedutil.dir/src/consolelogger.c.o
2018-12-06T20:44:29.4182500Z [  8%] Building C object deps/azure-c-shared-utility/CMakeFiles/aziotsharedutil.dir/src/crt_abstractions.c.o
2018-12-06T20:44:29.7403950Z [ 10%] Building C object deps/azure-c-shared-utility/CMakeFiles/aziotsharedutil.dir/src/constmap.c.o
2018-12-06T20:44:30.0238960Z [ 11%] Building C object deps/azure-c-shared-utility/CMakeFiles/aziotsharedutil.dir/src/doublylinkedlist.c.o
2018-12-06T20:44:30.1674260Z [ 12%] Building C object deps/azure-c-shared-utility/CMakeFiles/aziotsharedutil.dir/src/gballoc.c.o
2018-12-06T20:44:30.4041540Z [ 13%] Building C object deps/azure-c-shared-utility/CMakeFiles/aziotsharedutil.dir/src/gbnetwork.c.o
2018-12-06T20:44:30.6277180Z [ 15%] Building C object deps/azure-c-shared-utility/CMakeFiles/aziotsharedutil.dir/src/gb_stdio.c.o
2018-12-06T20:44:30.6798350Z [ 16%] Building C object deps/azure-c-shared-utility/CMakeFiles/aziotsharedutil.dir/src/gb_time.c.o
2018-12-06T20:44:30.7316200Z [ 17%] Building C object deps/azure-c-shared-utility/CMakeFiles/aziotsharedutil.dir/src/gb_rand.c.o
2018-12-06T20:44:30.8737930Z [ 18%] Building C object deps/azure-c-shared-utility/CMakeFiles/aziotsharedutil.dir/src/hmac.c.o
2018-12-06T20:44:30.9879850Z [ 20%] Building C object deps/azure-c-shared-utility/CMakeFiles/aziotsharedutil.dir/src/hmacsha256.c.o
2018-12-06T20:44:31.1562890Z [ 21%] Building C object deps/azure-c-shared-utility/CMakeFiles/aziotsharedutil.dir/src/xio.c.o
2018-12-06T20:44:31.4017130Z [ 22%] Building C object deps/azure-c-shared-utility/CMakeFiles/aziotsharedutil.dir/src/singlylinkedlist.c.o
2018-12-06T20:44:31.6313600Z [ 23%] Building C object deps/azure-c-shared-utility/CMakeFiles/aziotsharedutil.dir/src/map.c.o
2018-12-06T20:44:32.0051390Z [ 25%] Building C object deps/azure-c-shared-utility/CMakeFiles/aziotsharedutil.dir/src/sastoken.c.o
2018-12-06T20:44:32.3242930Z [ 26%] Building C object deps/azure-c-shared-utility/CMakeFiles/aziotsharedutil.dir/src/sha1.c.o
2018-12-06T20:44:32.6112540Z [ 27%] Building C object deps/azure-c-shared-utility/CMakeFiles/aziotsharedutil.dir/src/sha224.c.o
2018-12-06T20:44:32.8716900Z [ 28%] Building C object deps/azure-c-shared-utility/CMakeFiles/aziotsharedutil.dir/src/sha384-512.c.o
2018-12-06T20:44:33.1402800Z [ 30%] Building C object deps/azure-c-shared-utility/CMakeFiles/aziotsharedutil.dir/src/strings.c.o
2018-12-06T20:44:33.4602390Z [ 31%] Building C object deps/azure-c-shared-utility/CMakeFiles/aziotsharedutil.dir/src/string_token.c.o
2018-12-06T20:44:33.7435080Z [ 32%] Building C object deps/azure-c-shared-utility/CMakeFiles/aziotsharedutil.dir/src/string_tokenizer.c.o
2018-12-06T20:44:33.9712720Z [ 33%] Building C object deps/azure-c-shared-utility/CMakeFiles/aziotsharedutil.dir/src/uuid.c.o
2018-12-06T20:44:34.1867440Z [ 35%] Building C object deps/azure-c-shared-utility/CMakeFiles/aziotsharedutil.dir/src/urlencode.c.o
2018-12-06T20:44:34.4561590Z [ 36%] Building C object deps/azure-c-shared-utility/CMakeFiles/aziotsharedutil.dir/src/usha.c.o
2018-12-06T20:44:34.5529270Z [ 37%] Building C object deps/azure-c-shared-utility/CMakeFiles/aziotsharedutil.dir/src/vector.c.o
2018-12-06T20:44:34.8121300Z [ 38%] Building C object deps/azure-c-shared-utility/CMakeFiles/aziotsharedutil.dir/src/xlogging.c.o
2018-12-06T20:44:34.9844890Z [ 40%] Building C object deps/azure-c-shared-utility/CMakeFiles/aziotsharedutil.dir/src/optionhandler.c.o
2018-12-06T20:44:35.2405620Z [ 41%] Building C object deps/azure-c-shared-utility/CMakeFiles/aziotsharedutil.dir/adapters/agenttime.c.o
2018-12-06T20:44:35.4033460Z [ 42%] Building C object deps/azure-c-shared-utility/CMakeFiles/aziotsharedutil.dir/adapters/condition_pthreads.c.o
2018-12-06T20:44:35.6506270Z [ 43%] Building C object deps/azure-c-shared-utility/CMakeFiles/aziotsharedutil.dir/adapters/lock_pthreads.c.o
2018-12-06T20:44:35.8523950Z [ 45%] Building C object deps/azure-c-shared-utility/CMakeFiles/aziotsharedutil.dir/adapters/platform_linux.c.o
2018-12-06T20:44:36.1000260Z [ 46%] Building C object deps/azure-c-shared-utility/CMakeFiles/aziotsharedutil.dir/adapters/socketio_berkeley.c.o
2018-12-06T20:44:36.5532200Z [ 47%] Building C object deps/azure-c-shared-utility/CMakeFiles/aziotsharedutil.dir/adapters/tickcounter_linux.c.o
2018-12-06T20:44:36.7540140Z [ 48%] Building C object deps/azure-c-shared-utility/CMakeFiles/aziotsharedutil.dir/adapters/threadapi_pthreads.c.o
2018-12-06T20:44:36.9825410Z [ 50%] Building C object deps/azure-c-shared-utility/CMakeFiles/aziotsharedutil.dir/adapters/uniqueid_stub.c.o
2018-12-06T20:44:37.1828770Z [ 51%] Building C object deps/azure-c-shared-utility/CMakeFiles/aziotsharedutil.dir/adapters/envvariable.c.o
2018-12-06T20:44:37.3411270Z [ 52%] Building C object deps/azure-c-shared-utility/CMakeFiles/aziotsharedutil.dir/adapters/linux_time.c.o
2018-12-06T20:44:37.6370380Z [ 53%] Building C object deps/azure-c-shared-utility/CMakeFiles/aziotsharedutil.dir/src/httpapiex.c.o
2018-12-06T20:44:38.0139220Z [ 55%] Building C object deps/azure-c-shared-utility/CMakeFiles/aziotsharedutil.dir/src/httpapiexsas.c.o
2018-12-06T20:44:38.3297120Z [ 56%] Building C object deps/azure-c-shared-utility/CMakeFiles/aziotsharedutil.dir/src/httpheaders.c.o
2018-12-06T20:44:38.6348560Z [ 57%] Building C object deps/azure-c-shared-utility/CMakeFiles/aziotsharedutil.dir/adapters/httpapi_compact.c.o
2018-12-06T20:44:39.2561310Z [ 58%] Building C object deps/azure-c-shared-utility/CMakeFiles/aziotsharedutil.dir/src/http_proxy_io.c.o
2018-12-06T20:44:39.6726050Z [ 60%] Building C object deps/azure-c-shared-utility/CMakeFiles/aziotsharedutil.dir/adapters/tlsio_openssl.c.o
2018-12-06T20:44:40.2978970Z [ 61%] Building C object deps/azure-c-shared-utility/CMakeFiles/aziotsharedutil.dir/adapters/x509_openssl.c.o
2018-12-06T20:44:40.6146920Z [ 62%] Building C object deps/azure-c-shared-utility/CMakeFiles/aziotsharedutil.dir/src/wsio.c.o
2018-12-06T20:44:40.9813710Z [ 63%] Building C object deps/azure-c-shared-utility/CMakeFiles/aziotsharedutil.dir/src/uws_client.c.o
2018-12-06T20:44:41.7018440Z [ 65%] Building C object deps/azure-c-shared-utility/CMakeFiles/aziotsharedutil.dir/src/uws_frame_encoder.c.o
2018-12-06T20:44:41.9568230Z [ 66%] Building C object deps/azure-c-shared-utility/CMakeFiles/aziotsharedutil.dir/src/utf8_checker.c.o
2018-12-06T20:44:42.1244410Z [ 67%] Building C object deps/azure-c-shared-utility/CMakeFiles/aziotsharedutil.dir/src/ws_url.c.o
2018-12-06T20:44:42.3923000Z [ 68%] Linking C static library libaziotsharedutil.a
2018-12-06T20:44:42.4419110Z /Applications/Xcode_9.4.1.app/Contents/Developer/Toolchains/XcodeDefault.xctoolchain/usr/bin/ranlib: for architecture: i386 file: libaziotsharedutil.a(gb_stdio.c.o) has no symbols
2018-12-06T20:44:42.4419570Z /Applications/Xcode_9.4.1.app/Contents/Developer/Toolchains/XcodeDefault.xctoolchain/usr/bin/ranlib: for architecture: i386 file: libaziotsharedutil.a(gb_time.c.o) has no symbols
2018-12-06T20:44:42.4420010Z /Applications/Xcode_9.4.1.app/Contents/Developer/Toolchains/XcodeDefault.xctoolchain/usr/bin/ranlib: for architecture: x86_64 file: libaziotsharedutil.a(gb_stdio.c.o) has no symbols
2018-12-06T20:44:42.4420720Z /Applications/Xcode_9.4.1.app/Contents/Developer/Toolchains/XcodeDefault.xctoolchain/usr/bin/ranlib: for architecture: x86_64 file: libaziotsharedutil.a(gb_time.c.o) has no symbols
2018-12-06T20:44:42.4855580Z [ 68%] Built target aziotsharedutil
2018-12-06T20:44:42.5905610Z Scanning dependencies of target uamqp
2018-12-06T20:44:42.6153960Z [ 70%] Building C object CMakeFiles/uamqp.dir/src/amqp_definitions.c.o
2018-12-06T20:44:45.3992000Z [ 71%] Building C object CMakeFiles/uamqp.dir/src/amqp_frame_codec.c.o
2018-12-06T20:44:45.7053030Z [ 72%] Building C object CMakeFiles/uamqp.dir/src/amqp_management.c.o
2018-12-06T20:44:46.9122410Z [ 73%] Building C object CMakeFiles/uamqp.dir/src/amqpvalue.c.o
2018-12-06T20:44:48.5115210Z [ 75%] Building C object CMakeFiles/uamqp.dir/src/amqpvalue_to_string.c.o
2018-12-06T20:44:48.9592310Z [ 76%] Building C object CMakeFiles/uamqp.dir/src/async_operation.c.o
2018-12-06T20:44:49.1398130Z [ 77%] Building C object CMakeFiles/uamqp.dir/src/cbs.c.o
2018-12-06T20:44:49.8573370Z [ 78%] Building C object CMakeFiles/uamqp.dir/src/connection.c.o
2018-12-06T20:44:51.2080240Z [ 80%] Building C object CMakeFiles/uamqp.dir/src/frame_codec.c.o
2018-12-06T20:44:51.5552870Z [ 81%] Building C object CMakeFiles/uamqp.dir/src/header_detect_io.c.o
2018-12-06T20:44:51.9593920Z [ 82%] Building C object CMakeFiles/uamqp.dir/src/link.c.o
2018-12-06T20:44:53.2020470Z [ 83%] Building C object CMakeFiles/uamqp.dir/src/message.c.o
2018-12-06T20:44:54.2297960Z [ 85%] Building C object CMakeFiles/uamqp.dir/src/message_receiver.c.o
2018-12-06T20:44:55.3247350Z [ 86%] Building C object CMakeFiles/uamqp.dir/src/message_sender.c.o
2018-12-06T20:44:56.5465310Z [ 87%] Building C object CMakeFiles/uamqp.dir/src/messaging.c.o
2018-12-06T20:44:57.3975650Z [ 88%] Building C object CMakeFiles/uamqp.dir/src/sasl_anonymous.c.o
2018-12-06T20:44:57.5964740Z [ 90%] Building C object CMakeFiles/uamqp.dir/src/sasl_frame_codec.c.o
2018-12-06T20:44:58.4692410Z [ 91%] Building C object CMakeFiles/uamqp.dir/src/sasl_mechanism.c.o
2018-12-06T20:44:58.6695140Z [ 92%] Building C object CMakeFiles/uamqp.dir/src/sasl_server_mechanism.c.o
2018-12-06T20:44:58.8815850Z [ 93%] Building C object CMakeFiles/uamqp.dir/src/sasl_mssbcbs.c.o
2018-12-06T20:44:59.0750850Z [ 95%] Building C object CMakeFiles/uamqp.dir/src/sasl_plain.c.o
2018-12-06T20:44:59.2903310Z [ 96%] Building C object CMakeFiles/uamqp.dir/src/saslclientio.c.o
2018-12-06T20:45:00.4845170Z [ 97%] Building C object CMakeFiles/uamqp.dir/src/session.c.o
2018-12-06T20:45:01.7074120Z [ 98%] Building C object CMakeFiles/uamqp.dir/src/socket_listener_berkeley.c.o
2018-12-06T20:45:01.9893530Z [100%] Linking C static library libuamqp.a
2018-12-06T20:45:02.0659670Z [100%] Built target uamqp

However it looks like the Python extension is being build with gcc?

2018-12-06T20:45:02.1321250Z building 'uamqp.c_uamqp' extension
2018-12-06T20:45:02.1321890Z creating build/temp.macosx-10.6-intel-3.6/uamqp
2018-12-06T20:45:02.1323390Z gcc -DNDEBUG -g -fwrapv -O3 -Wall -mmacosx-version-min=10.6 -I/Users/vsts/agent/2.142.1/work/_temp/openssl/include -I/Users/vsts/agent/2.142.1/work/1/s/src/vendor/inc -I./src/vendor/azure-uamqp-c/deps/azure-c-shared-utility/pal/inc -I./src/vendor/azure-uamqp-c/deps/azure-c-shared-utility/inc -I./src/vendor/azure-uamqp-c/inc -I./src/vendor/azure-uamqp-c/deps/azure-c-shared-utility/pal/linux -I/Library/Frameworks/Python.framework/Versions/3.6/include/python3.6m -c uamqp/c_uamqp.c -o build/temp.macosx-10.6-intel-3.6/uamqp/c_uamqp.o -g -O0 -std=gnu99 -fPIC
2018-12-06T20:45:06.3303300Z gcc -bundle -undefined dynamic_lookup -arch i386 -arch x86_64 -g -mmacosx-version-min=10.6 -L/Users/vsts/agent/2.142.1/work/_temp/openssl/lib -mmacosx-version-min=10.6 -I/Users/vsts/agent/2.142.1/work/_temp/openssl/include build/temp.macosx-10.6-intel-3.6/uamqp/c_uamqp.o -Lbuild/temp.macosx-10.6-intel-3.6/cmake -Lbuild/temp.macosx-10.6-intel-3.6/cmake/deps/azure-c-shared-utility/ -Lbuild/temp.macosx-10.6-intel-3.6/cmake/Debug/ -Lbuild/temp.macosx-10.6-intel-3.6/cmake/Release/ -Lbuild/temp.macosx-10.6-intel-3.6/cmake/deps/azure-c-shared-utility/Debug/ -Lbuild/temp.macosx-10.6-intel-3.6/cmake/deps/azure-c-shared-utility/Release/ -luamqp -laziotsharedutil -lazssl -lazcrypto -o build/lib.macosx-10.6-intel-3.6/uamqp/c_uamqp.cpython-36m-darwin.so

[bsiegel]

On Mac, gcc is an alias for clang, you can verify with gcc --help.