Misuse of LOG(ERROR) causes undefined behavior |
|
Issue descriptionI was debugging a browser_test problem by adding some log statements. Working close to top of tree: 83013584d091473d3a5fee6a823bc63b223a472c After some heading scratching, I realize that calling ``` LOG(ERROR) << "cat0: " << (const char*)nullptr; ``` causes a CHECK to be hit deep within mojo::edk. I expect either the LOG(ERROR) to fail with an error, or this to succeed. I definitely don't expect a CHECK with mojo that shared very little stack trace with my original call to LOG(ERROR), which was from web_contents_view_mac.mm. It looks like strlen() can't be called on nullptrs. Fix incoming. [83515:16915:0309/181811:FATAL:message_pump_libevent.cc(140)] Check failed: fd >= 0 (-1 vs. 0) 0 libbase.dylib 0x000000011885948f _ZN4base5debug10StackTraceC2Ev + 47 1 libbase.dylib 0x0000000118859633 _ZN4base5debug10StackTraceC1Ev + 35 2 libbase.dylib 0x00000001188e5550 _ZN7logging10LogMessageD2Ev + 80 3 libbase.dylib 0x00000001188e2e83 _ZN7logging10LogMessageD1Ev + 35 4 libbase.dylib 0x00000001187fd505 _ZN4base19MessagePumpLibevent19WatchFileDescriptorEibiPNS0_21FileDescriptorWatcherEPNS0_7WatcherE + 229 5 libbase.dylib 0x0000000118931d16 _ZN4base16MessageLoopForIO19WatchFileDescriptorEibNS0_4ModeEPNS_19MessagePumpLibevent21FileDescriptorWatcherEPNS2_7WatcherE + 102 6 libmojo_system_impl.dylib 0x000000012872cfda _ZN4mojo3edk12_GLOBAL__N_112ChannelPosix15StartOnIOThreadEv + 698 7 libmojo_system_impl.dylib 0x000000012872b7a8 _ZN4mojo3edk12_GLOBAL__N_112ChannelPosix5StartEv + 88 8 libmojo_system_impl.dylib 0x000000012876f153 _ZN4mojo3edk11NodeChannel5StartEv + 323 9 libmojo_system_impl.dylib 0x0000000128777619 _ZN4mojo3edk14NodeController25ConnectToParentOnIOThreadENS0_20ScopedPlatformHandleE + 729 10 libmojo_system_impl.dylib 0x000000012878808c _ZN4base8internal15RunnableAdapterIMN4mojo3edk14NodeControllerEFvNS3_20ScopedPlatformHandleEEE3RunIJS5_EEEvPS4_DpOT_ + 156 11 libmojo_system_impl.dylib 0x0000000128787fcd _ZN4base8internal12InvokeHelperILb0EvNS0_15RunnableAdapterIMN4mojo3edk14NodeControllerEFvNS4_20ScopedPlatformHandleEEEEE8MakeItSoIJPS5_S6_EEEvS9_DpOT_ + 77 12 libmojo_system_impl.dylib 0x0000000128787f4c _ZN4base8internal7InvokerINS_13IndexSequenceIJLm0ELm1EEEENS0_9BindStateINS0_15RunnableAdapterIMN4mojo3edk14NodeControllerEFvNS7_20ScopedPlatformHandleEEEEFvPS8_S9_EJNS0_17UnretainedWrapperIS8_EENS0_13PassedWrapperIS9_EEEEENS0_12InvokeHelperILb0EvSC_EEFvvEE3RunEPNS0_13BindStateBaseE + 156 13 libbase.dylib 0x00000001188300df _ZNK4base8CallbackIFvvEE3RunEv + 63 14 libbase.dylib 0x000000011885b1fe _ZN4base5debug13TaskAnnotator7RunTaskEPKcRKNS_11PendingTaskE + 654 15 libbase.dylib 0x0000000118930220 _ZN4base11MessageLoop7RunTaskERKNS_11PendingTaskE + 848 16 libbase.dylib 0x0000000118930856 _ZN4base11MessageLoop21DeferOrRunPendingTaskERKNS_11PendingTaskE + 86 17 libbase.dylib 0x0000000118930ede _ZN4base11MessageLoop6DoWorkEv + 526 18 libbase.dylib 0x00000001187feffb _ZN4base19MessagePumpLibevent3RunEPNS_11MessagePump8DelegateE + 139 19 libbase.dylib 0x000000011892fa63 _ZN4base11MessageLoop10RunHandlerEv + 275 20 libbase.dylib 0x00000001189c24a5 _ZN4base7RunLoop3RunEv + 85 21 libbase.dylib 0x000000011892d59d _ZN4base11MessageLoop3RunEv + 269 22 libbase.dylib 0x0000000118a79b87 _ZN4base6Thread3RunEPNS_11MessageLoopE + 39 23 libbase.dylib 0x0000000118a7a365 _ZN4base6Thread10ThreadMainEv + 1445 24 libbase.dylib 0x0000000118a59263 _ZN4base12_GLOBAL__N_110ThreadFuncEPv + 195 25 libsystem_pthread.dylib 0x00007fff88767c13 _pthread_body + 131 26 libsystem_pthread.dylib 0x00007fff88767b90 _pthread_body + 0 27 libsystem_pthread.dylib 0x00007fff88765375 thread_start + 13
,
Mar 10 2016
mark: Do you think it's reasonable to make a ostringstream subclass that overrides operator<< (const char*) to prevent undefined behavior? A lot of logging code isn't tested, because it only gets called in exceptional circumstances. I'd much rather see graceful failure, then the type of UB that I saw in the opening post.
,
Mar 10 2016
Yes. In fact, I’d rather have an ostringstream subclass and provide operator<<(Subclass&, const char*) and operator<<(Subclass&, const wchar_t*) than our weirdo current behavior that defines operator<<(std::ostream&, const wchar_t*).
,
Mar 10 2016
This is probably reasonably straight forward, but I wasn't able to figure out all the details, and I can't justify spending too much more time on this right now.
Here's what I have:
Make a subclass of ostringstream that forwards the relevant calls to ostringstream.
"""
BASE_EXPORT class SafeOStringStream : public std::ostringstream {
public:
SafeOStringStream() {}
SafeOStringStream& operator<<(const char* str);
SafeOStringStream& operator<<(const wchar_t* wstr);
template<typename T>
SafeOStringStream& operator<<(const T& t);
};
"""
Use this shell script to convert all the ostream overrides.
"""
git grep -l 'std::ostream& operator<<(std::ostream&' | xargs sed -i '' -e 's/std::ostream& operator<<(std::ostream&/SafeOStringStream\& operator<<(SafeOStringStream\&/g'
"""
Find a way to override std::endl to have the right behavior.
Note: There are 322 overrides for operator<<.
https://code.google.com/p/chromium/codesearch#search/&q=%22std::ostream&%20operator%3C%3C(std::ostream&%22&sq=package:chromium&type=cs
,
Mar 11 2016
The following revision refers to this bug: https://chromium.googlesource.com/chromium/src.git/+/0c9fe71dfa3a702e9357835f5f144eb46314bf27 commit 0c9fe71dfa3a702e9357835f5f144eb46314bf27 Author: erikchen <erikchen@chromium.org> Date: Fri Mar 11 22:07:49 2016 base: Add nullptr checks to logging.cc. Avoid calling wstrlen() or strlen() on nullptrs, as that causes undefined behavior. BUG=593561 Review URL: https://codereview.chromium.org/1778083003 Cr-Commit-Position: refs/heads/master@{#380747} [modify] https://crrev.com/0c9fe71dfa3a702e9357835f5f144eb46314bf27/base/logging.cc |
|
►
Sign in to add a comment |
|
Comment 1 by erikc...@chromium.org
, Mar 10 2016