+Vadimsh@, is this related to swarming?

It is something in the recipes that generate "WidgetTest.WindowMouseModalityTest" log.

Swarming logs and general stdout log on buildbot both are correct, it is only 'WidgetTest.WindowMouseModalityTest' failure log that is broken.

+ Pawel

This is due to this line: https://chromium.googlesource.com/chromium/tools/build/+blame/master/scripts/common/gtest_utils.py#656

>>> x = "(e:\\b\\swarm_slave\\w\\iri9tjvs\\out\\Release\\views_unittests.exe+0xf5063b)\n    #3 0x1640051"
>>> x
'(e:\\b\\swarm_slave\\w\\iri9tjvs\\out\\Release\\views_unittests.exe+0xf5063b)\n    #3 0x1640051'
>>> x1 = x.encode('ascii', errors='replace')
>>> x1
'(e:\\b\\swarm_slave\\w\\iri9tjvs\\out\\Release\\views_unittests.exe+0xf5063b)\n    #3 0x1640051'
>>> x1.decode('string_escape', errors='replace')
'(e:\x08\\swarm_slave\\w\\iri9tjvs\\out\\Release\x0biews_unittests.exe+0xf5063b)\n    #3 0x1640051'

I'm not sure what it does and why.

Is this something we can revert to fix?

This is still an issue, and it is making it harder to understand this true positive ASan report:
https://build.chromium.org/p/chromium.fyi/builders/CrWinAsan%20tester/builds/1225/steps/content_unittests%20on%20Windows-7-SP1/logs/BrowserAccessibilityManagerTest.TestFatalError

This stack trace would be significantly more beautiful with some \b's, \t's, and \a's:

    #0 0x67775a7 in content::BrowserAccessibilityManager::GetParentNodeFromParentTree C:\c\CrWinAsan\src\contentrowserccessibilityrowser_accessibility_manager.cc:297
    #1 0x6777716 in content::BrowserAccessibilityManager::GetRootManager C:\c\CrWinAsan\src\contentrowserccessibilityrowser_accessibility_manager.cc:1047
    #2 0x6778ce7 in content::BrowserAccessibilityManager::GetDelegateFromRootManager C:\c\CrWinAsan\src\contentrowserccessibilityrowser_accessibility_manager.cc:1056
    #3 0x678b202 in content::BrowserAccessibilityManagerWin::CanFireEvents C:\c\CrWinAsan\src\contentrowserccessibilityrowser_accessibility_manager_win.cc:227
    #4 0x678aad5 in content::BrowserAccessibilityManagerWin::NotifyAccessibilityEvent C:\c\CrWinAsan\src\contentrowserccessibilityrowser_accessibility_manager_win.cc:114
    #5 0x676eb75 in content::BrowserAccessibility::Destroy C:\c\CrWinAsan\src\contentrowserccessibilityrowser_accessibility.cc:768
    #6 0x677dc86 in content::BrowserAccessibilityManager::OnNodeWillBeDeleted C:\c\CrWinAsan\src\contentrowserccessibilityrowser_accessibility_manager.cc:967
    #7 0x92993db in ui::AXTree::DestroyNodeAndSubtree C:\c\CrWinAsan\src\uiccessibilityx_tree.cc:297
    #8 0x929c648 in ui::AXTree::UpdateNode C:\c\CrWinAsan\src\uiccessibilityx_tree.cc:251
    #9 0x929a3db in ui::AXTree::Unserialize C:\c\CrWinAsan\src\uiccessibilityx_tree.cc:142
    #10 0x67763e0 in content::BrowserAccessibilityManager::Initialize C:\c\CrWinAsan\src\contentrowserccessibilityrowser_accessibility_manager.cc:165
    #11 0x678a40a in content::BrowserAccessibilityManagerWin::BrowserAccessibilityManagerWin C:\c\CrWinAsan\src\contentrowserccessibilityrowser_accessibility_manager_win.cc:45
    #12 0x678a357 in content::BrowserAccessibilityManager::Create C:\c\CrWinAsan\src\contentrowserccessibilityrowser_accessibility_manager_win.cc:29
    #13 0x319c7 in content::BrowserAccessibilityManagerTest_TestFatalError_Test::TestBody+0x493 (e:\swarm_slave\w\irwykngw\out\Release\content_unittests.exe+0x4219c7)
    #14 0x911e257 in testing::internal::HandleExceptionsInMethodIfSupported<testing::Test,void>+0xea (e:\swarm_slave\w\irwykngw\out\Release\content_unittests.exe+0x950e257)
    #15 0x911de3f in testing::Test::Run C:\c\CrWinAsan\src	esting\gtest\src\gtest.cc:2474
    #16 0x91207e3 in testing::TestInfo::Run C:\c\CrWinAsan\src	esting\gtest\src\gtest.cc:2656
    #17 0x9121a6d in testing::TestCase::Run C:\c\CrWinAsan\src	esting\gtest\src\gtest.cc:2774
    #18 0x913852e in testing::internal::UnitTestImpl::RunAllTests C:\c\CrWinAsan\src	esting\gtest\src\gtest.cc:4647
    #19 0x9137d26 in testing::internal::HandleExceptionsInMethodIfSupported<testing::internal::UnitTestImpl,bool> C:\c\CrWinAsan\src	esting\gtest\src\gtest.cc:2458
    #20 0x9137a2e in testing::UnitTest::Run C:\c\CrWinAsan\src	esting\gtest\src\gtest.cc:4255
    #21 0x7b92bd6 in base::TestSuite::Run C:\c\CrWinAsan\srcase	est	est_suite.cc:241
    #22 0x7b86089 in base::`anonymous namespace'::LaunchUnitTestsInternal C:\c\CrWinAsan\srcase	est\launcher\unit_test_launcher.cc:204
    #23 0x7b85d9c in base::LaunchUnitTests C:\c\CrWinAsan\srcase	est\launcher\unit_test_launcher.cc:445
    #25 0x10a5d445 in __scrt_common_main_seh f:\ddctools\crtcstartup\src\startup\exe_common.inl:253

+ clang people, since it affects our bot

The decode call has been there in some form for a while, since the initial revision (https://codereview.chromium.org/109223007). phajdan (author) or stip (reviewer), is the bug that the json producer doesn't escape enough, or that the recipe unescapes too much?

This is still happening:
https://build.chromium.org/p/chromium.fyi/builders/CrWinAsan%28dll%29%20tester/builds/1866/steps/browser_tests%20on%20Windows-7-SP1/logs/ECKEncryptedMediaTest.CDMExpectedCrash
(C:\c\CrWinAsan_dll_\srcase	hreading	hread_local_storage_win.cc:30)

Why is gtest_util.py doing .decode("string_escape")? That's what's interpreting the backslashes.
https://chromium.googlesource.com/chromium/tools/build/+blame/master/scripts/common/gtest_utils.py#656

There is an owner on this bug, but the status was not "Assigned" or "Started". Fixing. If you do not own this bug, please remove yourself as the owner and make the status "Available".

This is still happening:
https://luci-logdog.appspot.com/v/?s=chromium%2Fbb%2Fchromium.fyi%2FCrWinAsan_tester%2F1671%2F%2B%2Frecipes%2Fsteps%2Fbrowser_tests%2F0%2Flogs%2FPrintPreviewDestinationSearchTest.Select%2F0
  _CxxThrowException [0x16BEDC3E+101] (f:\ddctools\crtcruntime\src\eh	hrow.cpp:131)

Can somebody suggest a good owner for this bug?

dnj: Can you help finding an owner for this?

does logdog team own this now?

I'm not sure what you want here. The raw log output can be seen here: https://luci-logdog.appspot.com/rpcexplorer/services/logdog.Logs/Get?request={%20%20%20%20%22project%22:%20%22chromium%22,%20%20%20%20%22path%22:%20%22bb/chromium.fyi/CrWinAsan_tester/1671/+/recipes/steps/browser_tests/0/logs/PrintPreviewDestinationSearchTest.Select/0%22}

e.g.,: "value": "\t_CxxThrowException [0x16BEDC3E+101] (f:\\dd\u000bctools\\crt\u000bcruntime\\src\\eh\throw.cpp:131)",

This is the unmodified, raw UTF-8 output from the script, which includes lots of "\u000b" escape characters. Those are being properly rendered by both BuildBot and LogDog. If you don't want those characters there, you need to not emit them to LogDog/BuildBot.

By "you" here, I mean something upstream from the actual log collection/dissemination system. Maybe that's "recipe engine", maybe that's the runner script.

We want paths to show up as paths. We don't know where information gets lost. Looks like you just determined it's upstream of logdog. Who can own tracking down where exactly that happens, and fixing it?

I did just determine it's upstream of BuildBot/LogDog, but that's important, since this bug and all preceding comments actually (erroneously) attribute the failure to BuildBot/LogDog rendering.

For analysis, a persistent example:

Build: https://luci-milo.appspot.com/buildbot/chromium.fyi/CrWinAsan%28dll%29%20tester/2090
Log: https://luci-logdog.appspot.com/v/?s=chromium%2Fbb%2Fchromium.fyi%2FCrWinAsan_dll__tester%2F2090%2F%2B%2Frecipes%2Fsteps%2Fbrowser_tests%2F0%2Flogs%2FPrintPreviewDestinationSearchTest.Select%2F0
Command: 'E:\b\depot_tools\python276_bin\python.exe' -u 'E:\b\rr\tmpbfhlfp\rw\checkout\scripts\tools\runit.py' --show-path -- python 'E:\b\rr\tmpbfhlfp\rw\checkout\scripts/slave\recipe_modules\swarming\resources\collect_gtest_task.py' --swarming-client-dir 'E:\b\c\b\CrWinAsan_dll__tester\src\tools\swarming_client' --temp-root-dir 'c:\users\chrome~2\appdata\local\temp' --merged-test-output 'c:\users\chrome~2\appdata\local\temp\tmp3db4wb.json' -- collect --swarming https://chromium-swarm.appspot.com --decorate --print-status-updates --json 'c:\users\chrome~2\appdata\local\temp\tmpfogmfh.json'

The stack looks to be including:
- Swarming Task: https://chromium-swarm.appspot.com/task?id=34f4cac074eff810&refresh=10&show_raw=1
- Swarming Task Output API: https://apis-explorer.appspot.com/apis-explorer/?base=https://chromium-swarm.appspot.com/_ah/api#p/swarming/v1/swarming.task.stdout?task_id=34f4cac074eff810&_h=1&
- "collect_gtest_task.py"
- "runit.py" (probably not the culprit, since it's just an execve)
- The "chromium" Recipe
- Recipe Engine (which emits the logs)

The Swarming task looks sensible, and its output API looks to be escaped. I guess find someone familiar with "collect_gtest_task.py" and look at the code that is pulling Swarming task data and emitting it as annotation logs. After that, pass to a "chromium" recipe owner. After that, we'll make this a recipe engine bug.

vadimsh: Can you check if collect_gtest_task gets this right?

As I've already said in #3, broken escaping pops up due to 'string_escape ' here: https://chromium.googlesource.com/chromium/tools/build/+/c5785fd4e2714cae309ce96418450635207b4d69/scripts/common/gtest_utils.py#658 :

>>> "(e:\\b\\swarm_slave\\w\\iri9tjvs\\out\\Release\\views_unittests.exe+0xf5063b)\n    #3 0x1640051".decode('string_escape')
'(e:\x08\\swarm_slave\\w\\iri9tjvs\\out\\Release\x0biews_unittests.exe+0xf5063b)\n    #3 0x1640051'

(notice how it converted 'Release\\views' into 'Release\x0biews').

gtest_utils.py is used by collect_gtest_task internally to parse snippets of output/

I don't know what 'string_escape' is, or why exactly it was added there by phajdan.jr@ in https://chromium.googlesource.com/chromium/tools/build/+/f54e3551f6ee617e425361524bd39ac3ac50a98b (I tried bringing this bug to Pawel's attention, but no luck).

We can try removing it. It will probably break something else. Or, if we are lucky, this something else is not used anymore and nothing will break.

Correction: looks like string_escape was introduced here - https://chromium.googlesource.com/chromium/tools/build/+/c4a86d8ccd53fefd2f72ef987691be80e2ee7ba9 

I don't know why it's needed. I'm removing it: https://chromium-review.googlesource.com/c/457147/

The following revision refers to this bug:
  https://chromium.googlesource.com/chromium/tools/build/+/fd4a367a08d86233224a15427031b503f01faf0e

commit fd4a367a08d86233224a15427031b503f01faf0e
Author: Vadim Shtayura <vadimsh@chromium.org>
Date: Thu Mar 23 18:43:11 2017

Remove mysterious 'string_escape'.

It is not clear why it is needed, yet it actively breaks ASAN stack trace
dumps.

R=phajdan.jr@chromium.org
BUG= 632047 

Change-Id: I083f43e631f30e1fd30de5d9d6515836d464425e
Reviewed-on: https://chromium-review.googlesource.com/457147
Reviewed-by: Paweł Hajdan Jr. <phajdan.jr@chromium.org>
Commit-Queue: Vadim Shtayura <vadimsh@chromium.org>

[modify] https://crrev.com/fd4a367a08d86233224a15427031b503f01faf0e/scripts/common/gtest_utils.py
[modify] https://crrev.com/fd4a367a08d86233224a15427031b503f01faf0e/scripts/common/unittests/gtest_utils_test.py

So https://luci-logdog.appspot.com/v/?s=chromium%2Fbb%2Fchromium.memory.full%2FLinux_MSan_Tests%2F7097%2F%2B%2Frecipes%2Fsteps%2Fcc_unittests%2F0%2Flogs%2FGpuImageDecodeCacheTest.GetTaskForImageLargerScaleNoReuse%2F0 now prints:

[ RUN      ] GpuImageDecodeCacheTest.GetTaskForImageLargerScaleNoReuse\n==4464==WARNING: MemorySanitizer: use-of-uninitialized-value\n    #0 0x52cbdb4 in downsample_2_2_srgb(void*, void const*, unsigned long, int) third_party/skia/src/core/SkMipMap.cpp:320:26\n    #1 0x52cde5f in SkMipMap::Build(SkPixmap const&, SkDestinationSurfaceColorMode, SkDiscardableMemory* (*)(unsigned long)) third_party/skia/src/core/SkMipMap.cpp:564:13\n    #2 0x52ee5a8 in SkMipMap::Build(SkBitmap const&, SkDestinationSurfaceColorMode, SkDiscardableMemory* (*)(unsigned long)) third_party/skia/src/core/SkMipMap.cpp:693:12\n    #3 0x51834ae in SkMipMapCache::AddAndRef(SkBitmap const&, SkDestinationSurfaceColorMode, SkResourceCache*) third_party/skia/src/core/SkBitmapCache.cpp:250:24\n    #4 0x5186149 in SkDefaultBitmapControllerState::processMediumRequest(SkBitmapProvider const&) third_party/skia/src/core/SkBitmapController.cpp:187:28\n    #5 0x5186784 in SkDefaultBitmapControllerState::SkDefaultBitmapControllerState(SkBitmapProvider const&, SkMatrix const&, SkFilterQuality, bool) third_party/skia/src/core/SkBitmapController.cpp:223:64\n    #6 0x5186afb in SkInPlaceNewCheck\u003CSkDefaultBitmapControllerState, SkBitmapProvider, SkMatrix, SkFilterQuality, bool> third_party/skia/include/private/SkTemplates.h:445:72\n    #7 0x5186afb in SkDefaultBitmapController::onRequestBitmap(SkBitmapProvider const&, SkMatrix const&, SkFilterQuality, void*, unsigned long) third_party/skia/src/core/SkBitmapController.cpp:244:0\n    #8 0x5183f48 in SkBitmapController::requestBitmap(SkBitmapProvider const&, SkMatrix const&, SkFilterQuality, void*, unsigned long) third_party/skia/src/core/SkBitmapController.cpp:24:26\n    #9 0x4b2caf1 in requestBitmap third_party/skia/src/core/SkBitmapController.h:46:22\n    #10 0x4b2caf1 in SkImageShader::onAppendStages(SkRasterPipeline*, SkColorSpace*, SkArenaAlloc*, SkMatrix const&, SkPaint const&, SkMatrix const*) const third_party/skia/src/image/SkImageShader.cpp:229:0\n    #11 0x4acb161 in SkShader::appendStages(SkRasterPipeline*, SkColorSpace*, SkArenaAlloc*, SkMatrix const&, SkPaint const&) const third_party/skia/src/core/SkShader.cpp:260:18\n    #12 0x532f09e in SkRasterPipelineBlitter::Create(SkPixmap const&, SkPaint const&, SkMatrix const&, SkArenaAlloc*) third_party/skia/src/core/SkRasterPipelineBlitter.cpp:114:22\n    #13 0x51a4104 in SkBlitter::Choose(SkPixmap const&, SkMatrix const&, SkPaint const&, SkArenaAlloc*, bool) third_party/skia/src/core/SkBlitter.cpp:850:30\n    #14 0x48b7657 in SkAutoBlitterChoose third_party/skia/src/core/SkDraw.cpp:60:20\n    #15 0x48b7657 in SkDraw::drawRect(SkRect const&, SkPaint const&, SkMatrix const*, SkRect const*) const third_party/skia/src/core/SkDraw.cpp:835:0\n    #16 0x48bdb0b in SkDraw::drawBitmap(SkBitmap const&, SkMatrix const&, SkRect const*, SkPaint const&) const third_party/skia/src/core/SkDraw.h:0:15\n    #17 0x518b777 in SkBitmapDevice::drawBitmapRect(SkBitmap const&, SkRect const*, SkRect const&, SkPaint const&, SkCanvas::SrcRectConstraint) third_party/skia/src/core/SkBitmapDevice.cpp:336:26\n    #18 0x46d88a0 in SkCanvas::internalDrawBitmapRect(SkBitmap const&, SkRect const*, SkRect const&, SkPaint const*, SkCanvas::SrcRectConstraint) third_party/skia/src/core/SkCanvas.cpp:2387:23\n    #19 0x46d9211 in SkCanvas::onDrawBitmapRect(SkBitmap const&, SkRect const*, SkRect const&, SkPaint const*, SkCanvas::SrcRectConstraint) third_party/skia/src/core/SkCanvas.cpp:2397:11\n    #20 0x46c501a in drawBitmapRect third_party/skia/src/core/SkCanvas.cpp:1889:11\n    #21 0x46c501a in SkCanvas::drawBitmapRect(SkBitmap const&, SkRect const&, SkPaint const*, SkCanvas::SrcRectConstraint) third_party/skia/src/core/SkCanvas.cpp:1899:0\n    #22 0x4a13e7f in SkPixmap::scalePixels(SkPixmap const&, SkFilterQuality) const third_party/skia/src/core/SkPixmap.cpp:259:27\n    #23 0x4b17a08 in SkImage::scalePixels(SkPixmap const&, SkFilterQuality, SkImage::CachingHint) const third_party/skia/src/image/SkImage.cpp:76:45\n    #24 0x506294e in SkImage::getDeferredTextureImageData(GrContextThreadSafeProxy const&, SkImage::DeferredTextureImageUsageParams const*, int, void*, SkColorSpace*) const third_party/skia/src/image/SkImage_Gpu.cpp:641:28\n    #25 0x3c46fa5 in cc::GpuImageDecodeCache::DecodeImageIfNecessary(cc::DrawImage const&, cc::GpuImageDecodeCache::ImageData*) cc/tiles/gpu_image_decode_cache.cc:1120:34\n    #26 0x3c4dded in cc::GpuImageDecodeCache::DecodeImage(cc::DrawImage const&) cc/tiles/gpu_image_decode_cache.cc:702:3\n    #27 0x3c53355 in cc::ImageDecodeTaskImpl::RunOnWorkerThread() cc/tiles/gpu_image_decode_cache.cc:177:13\n    #28 0x3fa7dc3 in RunTask cc/test/test_tile_task_runner.cc:30:9\n    #29 0x3fa7dc3 in cc::TestTileTaskRunner::ProcessTask(cc::TileTask*) cc/test/test_tile_task_runner.cc:13:0\n    #30 0x2103ee6 in cc::(anonymous namespace)::GpuImageDecodeCacheTest_GetTaskForImageLargerScaleNoReuse_Test::TestBody() cc/tiles/gpu_image_decode_cache_unittest.cc:282:3\n    #31 0x423fe0c in HandleExceptionsInMethodIfSupported\u003Ctesting::Test, void> testing/gtest/src/gtest.cc:2458:12\n    #32 0x423fe0c in testing::Test::Run() testing/gtest/src/gtest.cc:2474:0\n    #33 0x4242b7b in testing::TestInfo::Run() testing/gtest/src/gtest.cc:2656:11\n    #34 0x4244119 in testing::TestCase::Run() testing/gtest/src/gtest.cc:2774:28\n    #35 0x4263dbd in testing::internal::UnitTestImpl::RunAllTests() testing/gtest/src/gtest.cc:4647:43\n    #36 0x4262c4e in HandleExceptionsInMethodIfSupported\u003Ctesting::internal::UnitTestImpl, bool> testing/gtest/src/gtest.cc:2458:12\n    #37 0x4262c4e in testing::UnitTest::Run() testing/gtest/src/gtest.cc:4255:0\n    #38 0x3fc7620 in RUN_ALL_TESTS testing/gtest/include/gtest/gtest.h:2237:46\n    #39 0x3fc7620 in base::TestSuite::Run() base/test/test_suite.cc:271:0\n    #40 0x3fcc69c in Run base/callback.h:80:12\n    #41 0x3fcc69c in base::(anonymous namespace)::LaunchUnitTestsInternal(base::Callback\u003Cint (), (base::internal::CopyMode)1, (base::internal::RepeatMode)1> const&, int, int, bool, base::Callback\u003Cvoid (), (base::internal::CopyMode)1, (base::internal::RepeatMode)1> const&) base/test/launcher/unit_test_launcher.cc:211:0\n    #42 0x3fcbec6 in base::LaunchUnitTests(int, char**, base::Callback\u003Cint (), (base::internal::CopyMode)1, (base::internal::RepeatMode)1> const&) base/test/launcher/unit_test_launcher.cc:453:10\n    #43 0x37283d7 in main cc/test/run_all_unittests.cc:15:10\n    #44 0x7fe64ab08f44 in __libc_start_main /build/eglibc-MjiXCM/eglibc-2.19/csu/libc-start.c:287:0\n    #45 0x616d77 in _start ??:0:0\n\n  Uninitialized value was stored to memory at\n    #0 0x6377eb in __msan_memcpy ??:0:0\n    #1 0x48a488a in SkData::PrivateNewWithCopy(void const*, unsigned long) third_party/skia/src/core/SkData.cpp:75:9\n    #2 0x48a4eed in SkData::MakeWithCopy(void const*, unsigned long) third_party/skia/src/core/SkData.cpp:103:12\n    #3 0x4b22dbb in SkImage::MakeRasterCopy(SkPixmap const&) third_party/skia/src/image/SkImage_Raster.cpp:277:24\n    #4 0x4b24a04 in SkMakeImageFromRasterBitmap(SkBitmap const&, SkCopyPixelsMode) third_party/skia/src/image/SkImage_Raster.cpp:327:20\n    #5 0x4b19bb1 in SkImage::MakeFromBitmap(SkBitmap const&) third_party/skia/src/image/SkImage.cpp:229:12\n    #6 0x20f4d33 in cc::(anonymous namespace)::CreateImage(int, int) cc/tiles/gpu_image_decode_cache_unittest.cc:35:10\n    #7 0x2101ce6 in cc::(anonymous namespace)::GpuImageDecodeCacheTest_GetTaskForImageLargerScaleNoReuse_Test::TestBody() cc/tiles/gpu_image_decode_cache_unittest.cc:250:32\n    #8 0x423fe0c in HandleExceptionsInMethodIfSupported\u003Ctesting::Test, void> testing/gtest/src/gtest.cc:2458:12\n    #9 0x423fe0c in testing::Test::Run() testing/gtest/src/gtest.cc:2474:0\n    #10 0x4242b7b in testing::TestInfo::Run() testing/gtest/src/gtest.cc:2656:11\n    #11 0x4244119 in testing::TestCase::Run() testing/gtest/src/gtest.cc:2774:28\n    #12 0x4263dbd in testing::internal::UnitTestImpl::RunAllTests() testing/gtest/src/gtest.cc:4647:43\n    #13 0x4262c4e in HandleExceptionsInMethodIfSupported\u003Ctesting::internal::UnitTestImpl, bool> testing/gtest/src/gtest.cc:2458:12\n    #14 0x4262c4e in testing::UnitTest::Run() testing/gtest/src/gtest.cc:4255:0\n    #15 0x3fc7620 in RUN_ALL_TESTS testing/gtest/include/gtest/gtest.h:2237:46\n    #16 0x3fc7620 in base::TestSuite::Run() base/test/test_suite.cc:271:0\n    #17 0x3fcc69c in Run base/callback.h:80:12\n    #18 0x3fcc69c in base::(anonymous namespace)::LaunchUnitTestsInternal(base::Callback\u003Cint (), (base::internal::CopyMode)1, (base::internal::RepeatMode)1> const&, int, int, bool, base::Callback\u003Cvoid (), (base::internal::CopyMode)1, (base::internal::RepeatMode)1> const&) base/test/launcher/unit_test_launcher.cc:211:0\n    #19 0x3fcbec6 in base::LaunchUnitTests(int, char**, base::Callback\u003Cint (), (base::internal::CopyMode)1, (base::internal::RepeatMode)1> const&) base/test/launcher/unit_test_launcher.cc:453:10\n    #20 0x37283d7 in main cc/test/run_all_unittests.cc:15:10\n    #21 0x7fe64ab08f44 in __libc_start_main /build/eglibc-MjiXCM/eglibc-2.19/csu/libc-start.c:287:0\n\n  Uninitialized value was created by a heap allocation\n    #0 0x63e93d in __interceptor_malloc ??:0:0\n    #1 0x44d71f9 in base::UncheckedMalloc(unsigned long, void**) base/process/memory_linux.cc:203:13\n    #2 0x46520d6 in sk_malloc_nothrow skia/ext/SkMemory_new_handler.cpp:75:19\n    #3 0x46520d6 in sk_malloc_flags(unsigned long, unsigned int) skia/ext/SkMemory_new_handler.cpp:87:0\n    #4 0x4900abd in operator() third_party/skia/src/core/SkMallocPixelRef.cpp:95:55\n    #5 0x4900abd in __invoke third_party/skia/src/core/SkMallocPixelRef.cpp:95:0\n    #6 0x4900abd in MakeUsing third_party/skia/src/core/SkMallocPixelRef.cpp:83:0\n    #7 0x4900abd in SkMallocPixelRef::MakeAllocate(SkImageInfo const&, unsigned long, sk_sp\u003CSkColorTable>) third_party/skia/src/core/SkMallocPixelRef.cpp:96:0\n    #8 0x4664976 in SkBitmap::tryAllocPixels(SkImageInfo const&, unsigned long) third_party/skia/src/core/SkBitmap.cpp:325:28\n    #9 0x20f4b39 in allocPixels third_party/skia/include/core/SkBitmap.h:269:20\n    #10 0x20f4b39 in allocPixels third_party/skia/include/core/SkBitmap.h:279:0\n    #11 0x20f4b39 in cc::(anonymous namespace)::CreateImage(int, int) cc/tiles/gpu_image_decode_cache_unittest.cc:33:0\n    #12 0x2101ce6 in cc::(anonymous namespace)::GpuImageDecodeCacheTest_GetTaskForImageLargerScaleNoReuse_Test::TestBody() cc/tiles/gpu_image_decode_cache_unittest.cc:250:32\n    #13 0x423fe0c in HandleExceptionsInMethodIfSupported\u003Ctesting::Test, void> testing/gtest/src/gtest.cc:2458:12\n    #14 0x423fe0c in testing::Test::Run() testing/gtest/src/gtest.cc:2474:0\n    #15 0x4242b7b in testing::TestInfo::Run() testing/gtest/src/gtest.cc:2656:11\n    #16 0x4244119 in testing::TestCase::Run() testing/gtest/src/gtest.cc:2774:28\n    #17 0x4263dbd in testing::internal::UnitTestImpl::RunAllTests() testing/gtest/src/gtest.cc:4647:43\n    #18 0x4262c4e in HandleExceptionsInMethodIfSupported\u003Ctesting::internal::UnitTestImpl, bool> testing/gtest/src/gtest.cc:2458:12\n    #19 0x4262c4e in testing::UnitTest::Run() testing/gtest/src/gtest.cc:4255:0\n    #20 0x3fc7620 in RUN_ALL_TESTS testing/gtest/include/gtest/gtest.h:2237:46\n    #21 0x3fc7620 in base::TestSuite::Run() base/test/test_suite.cc:271:0\n    #22 0x3fcc69c in Run base/callback.h:80:12\n    #23 0x3fcc69c in base::(anonymous namespace)::LaunchUnitTestsInternal(base::Callback\u003Cint (), (base::internal::CopyMode)1, (base::internal::RepeatMode)1> const&, int, int, bool, base::Callback\u003Cvoid (), (base::internal::CopyMode)1, (base::internal::RepeatMode)1> const&) base/test/launcher/unit_test_launcher.cc:211:0\n    #24 0x3fcbec6 in base::LaunchUnitTests(int, char**, base::Callback\u003Cint (), (base::internal::CopyMode)1, (base::internal::RepeatMode)1> const&) base/test/launcher/unit_test_launcher.cc:453:10\n    #25 0x37283d7 in main cc/test/run_all_unittests.cc:15:10\n    #26 0x7fe64ab08f44 in __libc_start_main /build/eglibc-MjiXCM/eglibc-2.19/csu/libc-start.c:287:0\n\nSUMMARY: MemorySanitizer: use-of-uninitialized-value (/b/s/w/ir/out/Release/cc_unittests+0x52cbdb4)\nExiting\n


So I guess whatever produces that output used to rely on this behavior -- but the producer of that output is what's wrong, not interpreting these is right I feel. Does anyone know what prints those lines?

:( 

Looks like Test Launcher is producing strings with literal "\n" instead of newlines:

Here's a chunk of test results JSON: 

"output_snippet": "[ RUN      ] GpuImageDecodeCacheTest.GetTaskForImageLargerScaleNoReuse\\n==4464==WARNING: MemorySanitizer: use-of-uninitialized-value\\n    #0 0x52cbdb4 in downsample_2_2_srgb(void*, void const*, unsigned long, int) third_party/skia/src/core/SkMipMap.cpp:320:26\\n
..."

Notice double '\\' there. It's escaped '\' in JSON.

This file is generated here: https://cs.chromium.org/chromium/src/base/test/launcher/test_results_tracker.cc?dr=C&l=304

---
To get this JSON file: 
1. Open Buildbot build page: https://uberchromegw.corp.google.com/i/chromium.memory.full/builders/Linux%20MSan%20Tests/builds/7097
2. Find failing step, "cc_unittests" in this case.
3. Click "shard #0 isolated out". Then "output.json".

Actually, looking deeper, it is not test launcher's fault.

I've noticed the JSON also has "original_output_snippet" field which is correct:

"original_output_snippet": "[ RUN      ] GpuImageDecodeCacheTest.GetTaskForImageLargerScaleNoReuse\n==4464==WARNING: MemorySanitizer: use-of-uninitialized-value\n    #0 0x52cbdb4  (/b/s/w/ir/out/Release/cc_unittests+0x52cbdb4)\n  
....
"

(single '\')

Code search for 'original_output_snippet' gives only one hit: https://cs.chromium.org/chromium/src/tools/valgrind/asan/asan_symbolize.py?q=original_output_snippet+package:%5Echromium$&l=204

So asan_symbolize.py takes a good snippet, transforms it (introducing '\\n') and writes it back into 'output_snipped'.

So the bug is there. And looks like it was done intentionally? See comments for StringEncoder:

# We want our output to match base::EscapeJSONString(), which produces
# doubly-escaped strings. The first escaping pass is handled by this class. The
# second pass happens when JSON data is dumped to file.
class StringEncoder(json.JSONEncoder):
...

Maybe it was a counter-measure for bad parsing fixed in #23? :)

Nice digging! I agree that sounds like what could be the bug. I'll try to change that, thanks.

The following revision refers to this bug:
  https://chromium.googlesource.com/chromium/src.git/+/3abe8396ac16185a59b420564d80c1f802ce1f3b

commit 3abe8396ac16185a59b420564d80c1f802ce1f3b
Author: thakis <thakis@chromium.org>
Date: Thu Apr 13 19:45:04 2017

Don't double-JSON-escape crash stacks in asan symbolizer.

gtest_utils.py used to double-unescape test JSON.  Now that that's fixed,
there's no need to escape twice here.

BUG= 632047 

Review-Url: https://codereview.chromium.org/2818653003
Cr-Commit-Position: refs/heads/master@{#464511}

[modify] https://crrev.com/3abe8396ac16185a59b420564d80c1f802ce1f3b/tools/valgrind/asan/asan_symbolize.py

Someone graciously broke the msan bots again, which enables us to check that the change in comment 28 works -- looks like it does: https://luci-logdog.appspot.com/v/?s=chromium%2Fbb%2Ftryserver.chromium.linux%2Flinux_chromium_msan_rel_ng%2F611%2F%2B%2Frecipes%2Fsteps%2Fcc_unittests__with_patch_%2F0%2Flogs%2FGpuImageDecodeCacheTest.ShouldAggressivelyFreeResources%2F0

So I think this is all done now. Thanks, vadimsh!

https://luci-logdog.appspot.com/v/?s=chromium%2Fbb%2Fchromium.memory%2FLinux_MSan_Tests%2F41%2F%2B%2Frecipes%2Fsteps%2Fcomponents_unittests%2F0%2Fstdout

Traceback (most recent call last):
  File "/b/s/w/ir/tools/valgrind/asan/asan_symbolize.py", line 245, in <module>
    main()
  File "/b/s/w/ir/tools/valgrind/asan/asan_symbolize.py", line 238, in main
    symbolize_snippets_in_json(args.test_summary_json_file, loop)
  File "/b/s/w/ir/tools/valgrind/asan/asan_symbolize.py", line 204, in symbolize_snippets_in_json
    json.dump(json_data, f, indent=3, sort_keys=True)
  File "/usr/lib/python2.7/json/__init__.py", line 189, in dump
    for chunk in iterable:
  File "/usr/lib/python2.7/json/encoder.py", line 434, in _iterencode
    for chunk in _iterencode_dict(o, _current_indent_level):
  File "/usr/lib/python2.7/json/encoder.py", line 408, in _iterencode_dict
    for chunk in chunks:
  File "/usr/lib/python2.7/json/encoder.py", line 332, in _iterencode_list
    for chunk in chunks:
  File "/usr/lib/python2.7/json/encoder.py", line 408, in _iterencode_dict
    for chunk in chunks:
  File "/usr/lib/python2.7/json/encoder.py", line 332, in _iterencode_list
    for chunk in chunks:
  File "/usr/lib/python2.7/json/encoder.py", line 390, in _iterencode_dict
    yield _encoder(value)
UnicodeDecodeError: 'utf8' codec can't decode byte 0xda in position 176: invalid continuation byte

Traceback (most recent call last):
  File "../../testing/xvfb.py", line 101, in <module>
    sys.exit(main())
  File "../../testing/xvfb.py", line 97, in main
    return run_executable(sys.argv[1:], os.environ.copy())
  File "../../testing/xvfb.py", line 64, in run_executable
    return test_env.run_executable(cmd, env)
  File "/b/s/w/ir/testing/test_env.py", line 229, in run_executable
    symbolize_snippets_in_json(cmd, env)
  File "/b/s/w/ir/testing/test_env.py", line 165, in symbolize_snippets_in_json
    raise subprocess.CalledProcessError(p.returncode, symbolize_command)
subprocess.CalledProcessError: Command '['/usr/bin/python', '/b/s/w/ir/tools/valgrind/asan/asan_symbolize.py', '--test-summary-json-file=/b/s/w/ioOO436H/output.json', '--executable-path=./components_unittests']' returned non-zero exit status 1


Sigh.

The following revision refers to this bug:
  https://chromium.googlesource.com/chromium/src.git/+/9d47da2334d77bd084aef8e0d5765a47967d449a

commit 9d47da2334d77bd084aef8e0d5765a47967d449a
Author: thakis <thakis@chromium.org>
Date: Fri Apr 14 15:46:06 2017

asan symbolize: Restore invalid utf-8 ignorance.

This was removed in
https://codereview.chromium.org/2818653003/diff/1/tools/valgrind/asan/asan_symbolize.py
but apparently tests do write invalid UTF-8 (maybe on Windows they write output in
the native codepage by default?).  Having stacks seems more important atm.

BUG= 632047 
TBR=vadimsh@chromium.org

Review-Url: https://codereview.chromium.org/2823563003
Cr-Commit-Position: refs/heads/master@{#464730}

[modify] https://crrev.com/9d47da2334d77bd084aef8e0d5765a47967d449a/tools/valgrind/asan/asan_symbolize.py

Looks better now.