New issue
Advanced search Search tips

Issue 771701 link

Starred by 2 users
Status: Fixed
Owner:
scottmg@chromium.org
Closed: Mar 2018
Cc:
pwnall@chromium.org
robliao@chromium.org
gab@chromium.org
fdoray@chromium.org
Components:
EstimatedDays: ----
NextAction: ----
OS: Linux , Android , Windows , Chrome , Mac , Fuchsia
Pri: 3
Type: Bug

Blocking:
issue 882906
issue 738275
issue 754861



Sign in to add a comment

IndexedDBFactoryTest.DataFormatVersion fails in content_unittests on Fuchsia

Project Member Reported by scottmg@chromium.org, Oct 4 2017 
This test is currently disabled since it was failing due to lack of file locking in sqlite ( https://crbug.com/758634 )

However, it failed 20/500 with this CHECK just now.

  [00008.228] 03553.03580> [3:776707479:1004/181916.942083:8184490:FATAL:scheduler_worker.cc(213)] Check failed: !join_called_for_testing_.IsSet().
  #00: base::debug::StackTrace::StackTrace(unsigned long) at ../../../../usr/local/google/work/cr/src/base/debug/stack_trace_fuchsia.cc:173
  #01: endl<char, std::__1::char_traits<char> > at ../../../../usr/local/google/work/cr/src/buildtools/third_party/libc++/trunk/include/ostream:1001
        (inlined by) operator<< at ../../../../usr/local/google/work/cr/src/buildtools/third_party/libc++/trunk/include/ostream:195
        (inlined by) ~LogMessage at ../../../../usr/local/google/work/cr/src/base/logging.cc:561
  #02: WakeUp at ../../../../usr/local/google/work/cr/src/base/task_scheduler/scheduler_worker.cc:216
  #03: WakeUpOneWorkerLockRequired at ../../../../usr/local/google/work/cr/src/base/task_scheduler/scheduler_worker_pool_impl.cc:668
  #04: ~AutoSchedulerLock at ../../../../usr/local/google/work/cr/src/base/task_scheduler/scheduler_lock.h:75
        (inlined by) WakeUpOneWorker at ../../../../usr/local/google/work/cr/src/base/task_scheduler/scheduler_worker_pool_impl.cc:679
        (inlined by) ScheduleSequence at ../../../../usr/local/google/work/cr/src/base/task_scheduler/scheduler_worker_pool_impl.cc:239
  #05: ~scoped_refptr at ../../../../usr/local/google/work/cr/src/base/memory/ref_counted.h:567
        (inlined by) PostTaskWithSequenceNow at ../../../../usr/local/google/work/cr/src/base/task_scheduler/scheduler_worker_pool.cc:213
  #06: ~scoped_refptr at ../../../../usr/local/google/work/cr/src/base/memory/ref_counted.h:567
        (inlined by) operator() at ../../../../usr/local/google/work/cr/src/base/task_scheduler/scheduler_worker_pool.cc:163
        (inlined by) Invoke<scoped_refptr<base::internal::Sequence>, base::internal::SchedulerWorkerPool *, std::__1::unique_ptr<base::internal::Task, std::__1::default_delete<base::internal::Task> > > at ../../../../usr/local/google/work/cr/src/base/bind_internal.h:136
        (inlined by) MakeItSo<(lambda at base/task_scheduler/scheduler_worker_pool.cc:161:13), scoped_refptr<base::internal::Sequence>, base::internal::SchedulerWorkerPool *, std::__1::unique_ptr<base::internal::Task, std::__1::default_delete<base::internal::Task> > > at ../../../../usr/local/google/work/cr/src/base/bind_internal.h:277
        (inlined by) RunImpl<(lambda at base/task_scheduler/scheduler_worker_pool.cc:161:13), std::__1::tuple<scoped_refptr<base::internal::Sequence>, base::internal::UnretainedWrapper<base::internal::SchedulerWorkerPool> >, 0, 1> at ../../../../usr/local/google/work/cr/src/base/bind_internal.h:349
        (inlined by) RunOnce at ../../../../usr/local/google/work/cr/src/base/bind_internal.h:318
  #07: Run at ../../../../usr/local/google/work/cr/src/base/callback.h:65
        (inlined by) Invoke<base::OnceCallback<void (std::__1::unique_ptr<base::internal::Task, std::__1::default_delete<base::internal::Task> >)>, std::__1::unique_ptr<base::internal::Task, std::__1::default_delete<base::internal::Task> > > at ../../../../usr/local/google/work/cr/src/base/bind_internal.h:238
  #08: reset at ../../../../usr/local/google/work/cr/src/buildtools/third_party/libc++/trunk/include/memory:2582
        (inlined by) ~unique_ptr at ../../../../usr/local/google/work/cr/src/buildtools/third_party/libc++/trunk/include/memory:2539
        (inlined by) RunImpl<base::OnceCallback<void (std::__1::unique_ptr<base::internal::Task, std::__1::default_delete<base::internal::Task> >)>, std::__1::tuple<base::internal::PassedWrapper<std::__1::unique_ptr<base::internal::Task, std::__1::default_delete<base::internal::Task> > > >, 0> at ../../../../usr/local/google/work/cr/src/base/bind_internal.h:349
        (inlined by) RunOnce at ../../../../usr/local/google/work/cr/src/base/bind_internal.h:318
  #09: Run at ../../../../usr/local/google/work/cr/src/base/callback.h:65
        (inlined by) RunTask at ../../../../usr/local/google/work/cr/src/base/debug/task_annotator.cc:57
  #10: RunTask at ../../../../usr/local/google/work/cr/src/base/message_loop/incoming_task_queue.cc:147
  #11: empty at ../../../../usr/local/google/work/cr/src/buildtools/third_party/libc++/trunk/include/vector:644
        (inlined by) begin at ../../../../usr/local/google/work/cr/src/base/observer_list.h:133
        (inlined by) RunTask at ../../../../usr/local/google/work/cr/src/base/message_loop/message_loop.cc:407
  #12: DeferOrRunPendingTask at ../../../../usr/local/google/work/cr/src/base/message_loop/message_loop.cc:417
        (inlined by) DoDelayedWork at ../../../../usr/local/google/work/cr/src/base/message_loop/message_loop.cc:564
  #13: Run at ../../../../usr/local/google/work/cr/src/base/message_loop/message_pump_fuchsia.cc:265
  #14: Run at ../../../../usr/local/google/work/cr/src/base/message_loop/message_loop.cc:346
  #15: Run at ../../../../usr/local/google/work/cr/src/base/run_loop.cc:121
  #16: Run at ../../../../usr/local/google/work/cr/src/base/threading/thread.cc:255
  #17: Acquire at ../../../../usr/local/google/work/cr/src/base/synchronization/lock.h:45
        (inlined by) AutoLock at ../../../../usr/local/google/work/cr/src/base/synchronization/lock.h:115
        (inlined by) ThreadMain at ../../../../usr/local/google/work/cr/src/base/threading/thread.cc:341
  #18: ThreadFunc at ../../../../usr/local/google/work/cr/src/base/threading/platform_thread_posix.cc:77
  #19: pc 0x54dc636b9226 (libc.so,0x19226)
  #20: pc 0x54dc6373099a (libc.so,0x9099a)
  [00008.234] 03553.03580>
  [00008.234] 03553.03580> [1/1] IndexedDBFactoryTest.DataFormatVersion (CRASHED)

Comment 1 by scottmg@chromium.org, Oct 4 2017 

This seems to be the close_timer OneShotTimer() that's scheduled in IndexedDBFactoryImpl::ReleaseBackingStore. Sometimes the timer is able post back a task after shutdown/flush are supposedly "complete". 

https://bugs.chromium.org/p/chromium/issues/detail?id=587199 pops up as potentially relevant, not sure.

Also, regrettably when I add some LOGs that change timing, I start experiencing this crash which looks unrelated :( So two different things to look at here.

 #01: get at ../../../../usr/local/google/work/cr/src/base/memory/ref_counted.h:571
        (inlined by) database at ../../../../usr/local/google/work/cr/src/content/browser/indexed_db/indexed_db_connection.h:48
        (inlined by) operator() at ../../../../usr/local/google/work/cr/src/content/browser/indexed_db/indexed_db_factory_unittest.cc:733
        (inlined by) Invoke<scoped_refptr<content::(anonymous namespace)::MockIDBFactory>, scoped_refptr<content::(anonymous namespace)::DataLossCallbacks>, url::Origin, long, blink::WebIDBDataLoss *> at ../../../../usr/local/google/work/cr/src/base/bind_internal.h:136
        (inlined by) MakeItSo<(lambda at content/browser/indexed_db/indexed_db_factory_unittest.cc:728:13), scoped_refptr<content::(anonymous namespace)::MockIDBFactory>, scoped_refptr<content::(anonymous namespace)::DataLossCallbacks>, url::Origin, long, blink::WebIDBDataLoss *> at ../../../../usr/local/google/work/cr/src/base/bind_internal.h:277
        (inlined by) RunImpl<(lambda at content/browser/indexed_db/indexed_db_factory_unittest.cc:728:13), std::__1::tuple<scoped_refptr<content::(anonymous namespace)::MockIDBFactory>, scoped_refptr<content::(anonymous namespace)::DataLossCallbacks>, url::Origin, long, base::internal::UnretainedWrapper<blink::WebIDBDataLoss> >, 0, 1, 2, 3, 4> at ../../../../usr/local/google/work/cr/src/base/bind_internal.h:349
        (inlined by) RunOnce at ../../../../usr/local/google/work/cr/src/base/bind_internal.h:318
  #02: Run at ../../../../usr/local/google/work/cr/src/base/callback.h:65
        (inlined by) RunTask at ../../../../usr/local/google/work/cr/src/base/debug/task_annotator.cc:57
  #03: RunOrSkipTask at ../../../../usr/local/google/work/cr/src/base/task_scheduler/task_tracker.cc:336
  #04: reset at ../../../../usr/local/google/work/cr/src/buildtools/third_party/libc++/trunk/include/memory:2582
        (inlined by) ~unique_ptr at ../../../../usr/local/google/work/cr/src/buildtools/third_party/libc++/trunk/include/memory:2539
        (inlined by) RunOrSkipTask at ../../../../usr/local/google/work/cr/src/base/task_scheduler/task_tracker_posix.cc:23
  #05: reset at ../../../../usr/local/google/work/cr/src/buildtools/third_party/libc++/trunk/include/memory:2582
        (inlined by) ~unique_ptr at ../../../../usr/local/google/work/cr/src/buildtools/third_party/libc++/trunk/include/memory:2539
        (inlined by) RunOrSkipTask at ../../../../usr/local/google/work/cr/src/base/test/scoped_task_environment.cc:239
  #06: reset at ../../../../usr/local/google/work/cr/src/buildtools/third_party/libc++/trunk/include/memory:2582
        (inlined by) ~unique_ptr at ../../../../usr/local/google/work/cr/src/buildtools/third_party/libc++/trunk/include/memory:2539
        (inlined by) RunNextTask at ../../../../usr/local/google/work/cr/src/base/task_scheduler/task_tracker.cc:250
  #07: ThreadMain at ../../../../usr/local/google/work/cr/src/base/task_scheduler/scheduler_worker.cc:73
  #08: ThreadFunc at ../../../../usr/local/google/work/cr/src/base/threading/platform_thread_posix.cc:77
  #09: pc 0x593174787226 sp 0x1952a70f5fe0 (libc.so,0x19226)
  #10: pc 0x5931747fe99a sp 0x1952a70f5ff0 (libc.so,0x9099a)
  #11: pc 0 sp 0x1952a70f6000
  [00007.598] 03544.03571> [ RUN      ] IndexedDBFactoryTest.DataFormatVersion

Comment 2 by scottmg@chromium.org, Oct 10 2017

Components: Internals>TaskScheduler
I've eventually tracked this down to an ordering problem in TaskSchedulerImpl::JoinForTesting(). If the DelayedTaskManager is used for deferred tasks (as it is in this test, which uses a OneShotTimer close_timer_), the service thread can have outstanding tasks on it, and so can post back to pool workers that have already set join_called_for_testing_, so they then CHECK.

Inserting sleep(5) before "service_thread_.Stop();" here 
https://cs.chromium.org/chromium/src/base/task_scheduler/task_scheduler_impl.cc?rcl=3708e4d8d448f2260fd0f5c1c24520e6fcf3b01d&l=179 causes this bug to repro on, e.g. Linux in a debug build with --gtest_filter=IndexedDBFactoryTest.DataFormatVersion.

Comment 3 by robliao@chromium.org, Oct 10 2017 

This sounds like a variant of http://crbug.com/698140 , except this occurs at Join time instead of shutdown time.

Comment 4 by scottmg@chromium.org, Oct 16 2017

Labels: OS-Android OS-Chrome OS-Linux OS-Mac OS-Windows
Project Member

Comment 5 by bugdroid1@chromium.org, Oct 17 2017 

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

commit adf845b5cb5e7d320c715256da11841ec43ed317
Author: Scott Graham <scottmg@chromium.org>
Date: Tue Oct 17 01:38:09 2017

Stop TaskScheduler service thread before joining workers

If the service thread is stopped after workers are joined, the service
thread can post a task after join_called_for_testing_ is set which
causes a CHECK. Instead stop the service thread before joining the pool
workers in TaskSchedulerImpl::JoinForTesting().

This bug showed up on Fuchsia, but is cross-platform.

Bug:  771701 , 698140
Change-Id: I4a25ede2bceb700eeea17ae47f7402211856bef6
Reviewed-on: https://chromium-review.googlesource.com/721570
Reviewed-by: Robert Liao <robliao@chromium.org>
Commit-Queue: Scott Graham <scottmg@chromium.org>
Cr-Commit-Position: refs/heads/master@{#509208}
[modify] https://crrev.com/adf845b5cb5e7d320c715256da11841ec43ed317/base/task_scheduler/task_scheduler_impl.cc
Project Member

Comment 6 by bugdroid1@chromium.org, Oct 17 2017 

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

commit c072e2c9ed75f34500bad931822c0fb12f8ffa2f
Author: Scott Graham <scottmg@chromium.org>
Date: Tue Oct 17 21:33:47 2017

Fix typo in TaskScheduler, enable associated test

Fix comment typo in
https://chromium-review.googlesource.com/c/chromium/src/+/721570/, and
also enable IndexedDBFactoryTest.DataFormatVersion which should now not
flake on Fuchsia.

Bug:  771701 
Change-Id: I7a67bf762cbf171965cb1f2810100945f685327e
Reviewed-on: https://chromium-review.googlesource.com/723562
Commit-Queue: Scott Graham <scottmg@chromium.org>
Commit-Queue: Gabriel Charette <gab@chromium.org>
Reviewed-by: Gabriel Charette <gab@chromium.org>
Cr-Commit-Position: refs/heads/master@{#509545}
[modify] https://crrev.com/c072e2c9ed75f34500bad931822c0fb12f8ffa2f/base/task_scheduler/task_scheduler_impl.cc
[modify] https://crrev.com/c072e2c9ed75f34500bad931822c0fb12f8ffa2f/testing/buildbot/filters/fuchsia.content_unittests.filter

Comment 7 by scottmg@chromium.org, Oct 17 2017

Status: Fixed (was: Started)

Comment 8 by scottmg@chromium.org, Oct 18 2017

Components: Blink>Storage>IndexedDB
Status: Assigned (was: Fixed)
Sigh, now that the TaskScheduler's not crashing, it seems to be flaking in a different way that's more IndexedDB-related.

[00157.121] 03585.03612> [ RUN      ] IndexedDBFactoryTest.DataFormatVersion
[00157.121] 03585.03612> [3:1099173773:1018/053611.910422:148645404:ERROR:indexed_db_backing_store.cc(933)] IndexedDB backing store had unknown schema, treating it as failure to open
[00157.121] 03585.03612> [3:1099173773:1018/053611.935362:148670352:ERROR:indexed_db_backing_store.cc(958)] IndexedDB backing store open failed, attempting cleanup
[00157.121] 03585.03612> [3:1099173773:1018/053612.230948:148965930:ERROR:indexed_db_backing_store.cc(968)] IndexedDB backing store cleanup succeeded, reopening
[00157.122] 03585.03612> [3:1099173773:1018/053613.369944:150104932:ERROR:indexed_db_backing_store.cc(933)] IndexedDB backing store had unknown schema, treating it as failure to open
[00157.122] 03585.03612> [3:1099173773:1018/053613.379899:150114885:ERROR:indexed_db_backing_store.cc(958)] IndexedDB backing store open failed, attempting cleanup
[00157.122] 03585.03612> [3:1099173773:1018/053613.646414:150381418:ERROR:indexed_db_backing_store.cc(968)] IndexedDB backing store cleanup succeeded, reopening
[00157.122] 03585.03612> [3:1099173773:1018/053615.593972:152328942:ERROR:indexed_db_backing_store.cc(933)] IndexedDB backing store had unknown schema, treating it as failure to open
[00157.123] 03585.03612> [3:1099173773:1018/053615.626180:152361165:ERROR:indexed_db_backing_store.cc(958)] IndexedDB backing store open failed, attempting cleanup
[00157.123] 03585.03612> [3:1099173773:1018/053615.900086:152635070:ERROR:indexed_db_backing_store.cc(968)] IndexedDB backing store cleanup succeeded, reopening
[00157.123] 03585.03612> [3:1099173773:1018/053617.225526:153960508:ERROR:indexed_db_backing_store.cc(933)] IndexedDB backing store had unknown schema, treating it as failure to open
[00157.124] 03585.03612> [3:1099173773:1018/053617.248682:153983658:ERROR:indexed_db_backing_store.cc(958)] IndexedDB backing store open failed, attempting cleanup
[00157.124] 03585.03612> [3:1099173773:1018/053617.500722:154235695:ERROR:indexed_db_backing_store.cc(968)] IndexedDB backing store cleanup succeeded, reopening
[00157.124] 03585.03612> [3:1099173773:1018/053619.152431:155887402:ERROR:indexed_db_backing_store.cc(933)] IndexedDB backing store had unknown schema, treating it as failure to open
[00157.124] 03585.03612> [3:1099173773:1018/053619.185393:155920361:ERROR:indexed_db_backing_store.cc(958)] IndexedDB backing store open failed, attempting cleanup
[00157.124] 03585.03612> [3:1099173773:1018/053619.225651:155960623:ERROR:indexed_db_backing_store.cc(968)] IndexedDB backing store cleanup succeeded, reopening
[00157.125] 03585.03612> [3:1099173773:1018/053619.652648:156387627:ERROR:indexed_db_backing_store.cc(750)] IndexedDB Consistency Error: SET_UP_METADATA
[00157.125] 03585.03612> ../../content/browser/indexed_db/indexed_db_factory_unittest.cc:666: Failure
[00157.125] 03585.03612> Failed
[00157.125] 03585.03612> Unexpected IDB error: Internal error opening backing store for indexedDB.open.
[00157.126] 03585.03612> ../../content/browser/indexed_db/indexed_db_factory_unittest.cc:727: Failure
[00157.126] 03585.03612> Value of: connection
[00157.126] 03585.03612>   Actual: false
[00157.126] 03585.03612> Expected: true
[00157.127] 03585.03612> [1116/4820] IndexedDBFactoryTest.DataFormatVersion (CRASHED)
Project Member

Comment 9 by bugdroid1@chromium.org, Oct 18 2017 

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

commit 380a395ab132d27e73b713475422299215dea1fc
Author: Scott Graham <scottmg@chromium.org>
Date: Wed Oct 18 20:44:15 2017

fuchsia: Re-disable IndexedDBFactoryTest.DataFormatVersion, failing in a new way

Bug:  771701 
Change-Id: Ia0d0be26d865b1d8d80b233a019b7819fc895f55
TBR: wez@chromium.org
Reviewed-on: https://chromium-review.googlesource.com/726360
Reviewed-by: Scott Graham <scottmg@chromium.org>
Reviewed-by: Wez <wez@chromium.org>
Commit-Queue: Scott Graham <scottmg@chromium.org>
Cr-Commit-Position: refs/heads/master@{#509862}
[modify] https://crrev.com/380a395ab132d27e73b713475422299215dea1fc/testing/buildbot/filters/fuchsia.content_unittests.filter
Project Member

Comment 10 by bugdroid1@chromium.org, Oct 18 2017 

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

commit 682f1b4ca0e94e1bee953e43a0010a7c182cad56
Author: Scott Graham <scottmg@chromium.org>
Date: Wed Oct 18 23:35:13 2017

fuchsia: Add --gtest_filter arg to run-swarmed.py

Useful to narrow down to a particular test fixture when flaking.

Bug:  771701 
Change-Id: Idcdb60739c55e759c7ad98a5597878d3753b39ca
Reviewed-on: https://chromium-review.googlesource.com/726276
Commit-Queue: Scott Graham <scottmg@chromium.org>
Reviewed-by: Wez <wez@chromium.org>
Cr-Commit-Position: refs/heads/master@{#509927}
[modify] https://crrev.com/682f1b4ca0e94e1bee953e43a0010a7c182cad56/tools/fuchsia/run-swarmed.py

Comment 11 by pwnall@chromium.org, Feb 6 2018

Cc: pwnall@chromium.org
In case it helps -- I'm reasonably sure that IndexedDB is built entirely on LevelDB, not on SQLite.

Comment 12 by scottmg@chromium.org, Mar 6 2018

Status: Fixed (was: Assigned)

Comment 13 by scottmg@chromium.org, Sep 11

Blocking: 882906
►

Sign in to add a comment