Repeated LevelDB recovery failures (from IndexedDB open) on Linux / btrfs on chrome startup after computer crash
Reported by
mer...@gmail.com,
Jul 4 2017
|
|||||||
Issue descriptionUserAgent: Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/58.0.3029.110 Safari/537.36 Steps to reproduce the problem: 1) use btrfs as filesystem 2) crash the system/unclear shutdown 3) restart chrome What is the expected behavior? tabs restore What went wrong? sometimes tabs restore, sometimes they don't. Often chrome starts, opens a window and hangs there without even giving me the option to restore tabs. The only way out is ^C. Restarting chrome then usually restarts it clean with all my tabs lost (not being asked to restore them). sometimes I get a chrome warning that my profile is corrupted and submit an automated-ish bugreport from that some other times, after that is all fixed, I get never ending sqlite and other read/write errors on the console Did this work before? No Chrome version: 58.0.3029.110 Channel: beta OS Version: debian/testing Flash Version: Usually if my tabs are lost, I rsync a btrfs snapshot over my chrome config dir, and that pretty reliably gives me a back a working profile with my saved tabs. Problems to fix: 1) there is no good reason for chrome to give me never ending errors about sqlite problems. It should wipe the damaged file and restart fresh (possibly after asking me whether it's ok to do so) 2) I'm reasonably sure that btrfs does write consistent data on disk as per the filesystem semantics, even when the system crashes. If it's in the middle of writing data, it uses COW and only atomically repoints block pointers to the new COW blocks after they've been fully ritten. Btrfs also has per block checksums and does not get corrupted data without complaining loudly in syslog. I have not gotten any such warnings. Maybe chrome is missing some fsync statements in places, or sqlite is just buggy when it doesn't get to write all its data like it wished it had been able to.
,
Jul 4 2017
After the above, chrome seems to start correctly after some extra complaining on the console. However the complaining eventually stops. Sadly, this is business as usual for google-chrome on my laptop (all versions, been true for at least 3 years) [15828:15861:0703/233619.588274:ERROR:service_manager.cc(425)] InterfaceProviderSpec prevented connection from: content_utility to: content_browser [15828:15861:0703/233619.734462:ERROR:service_manager.cc(425)] InterfaceProviderSpec prevented connection from: content_utility to: content_browser [15828:15861:0703/233710.346837:ERROR:service_manager.cc(425)] InterfaceProviderSpec prevented connection from: content_utility to: content_browser [15828:15862:0703/233713.287063:ERROR:leveldb_database.cc(317)] Failed to open LevelDB database from /var/change/merlin-change/.config/google-chrome-dir/google-chrome-beta/Default/IndexedDB/https_docs.google.com_0.indexeddb.leveldb,IO error: /var/change/merlin-change/.config/google-chrome-dir/google-chrome-beta/Default/IndexedDB/https_docs.google.com_0.indexeddb.leveldb/MANIFEST-010814: Unable to create sequential file (ChromeMethodBFE: 7::NewSequentialFile::4) [15828:15862:0703/233713.287236:ERROR:indexed_db_backing_store.cc(1406)] Unable to open backing store, not trying to recover - IO error: /var/change/merlin-change/.config/google-chrome-dir/google-chrome-beta/Default/IndexedDB/https_docs.google.com_0.indexeddb.leveldb/MANIFEST-010814: Unable to create sequential file (ChromeMethodBFE: 7::NewSequentialFile::4) [15828:15862:0703/233713.347559:ERROR:leveldb_database.cc(317)] Failed to open LevelDB database from /var/change/merlin-change/.config/google-chrome-dir/google-chrome-beta/Default/IndexedDB/https_docs.google.com_0.indexeddb.leveldb,IO error: /var/change/merlin-change/.config/google-chrome-dir/google-chrome-beta/Default/IndexedDB/https_docs.google.com_0.indexeddb.leveldb/MANIFEST-010814: Unable to create sequential file (ChromeMethodBFE: 7::NewSequentialFile::4) [15828:15862:0703/233713.347920:ERROR:indexed_db_backing_store.cc(1406)] Unable to open backing store, not trying to recover - IO error: /var/change/merlin-change/.config/google-chrome-dir/google-chrome-beta/Default/IndexedDB/https_docs.google.com_0.indexeddb.leveldb/MANIFEST-010814: Unable to create sequential file (ChromeMethodBFE: 7::NewSequentialFile::4) [15828:15954:0703/233756.667114:ERROR:cert_verify_proc_nss.cc(923)] CERT_PKIXVerifyCert for home.merlins.org failed err=-8172 [15828:15862:0703/233758.748365:ERROR:leveldb_database.cc(317)] Failed to open LevelDB database from /var/change/merlin-change/.config/google-chrome-dir/google-chrome-beta/Default/IndexedDB/https_docs.google.com_0.indexeddb.leveldb,IO error: /var/change/merlin-change/.config/google-chrome-dir/google-chrome-beta/Default/IndexedDB/https_docs.google.com_0.indexeddb.leveldb/MANIFEST-010814: Unable to create sequential file (ChromeMethodBFE: 7::NewSequentialFile::4) [15828:15862:0703/233758.748633:ERROR:indexed_db_backing_store.cc(1406)] Unable to open backing store, not trying to recover - IO error: /var/change/merlin-change/.config/google-chrome-dir/google-chrome-beta/Default/IndexedDB/https_docs.google.com_0.indexeddb.leveldb/MANIFEST-010814: Unable to create sequential file (ChromeMethodBFE: 7::NewSequentialFile::4) [15828:15828:0703/233800.056332:ERROR:background_mode_manager_aura.cc(18)] Not implemented reached in virtual void BackgroundModeManager::DisplayClientInstalledNotification(const base::string16 &) [15828:15888:0703/233800.388241:ERROR:object_proxy.cc(583)] Failed to call method: org.freedesktop.NetworkManager.GetDevices: object_path= /org/freedesktop/NetworkManager: org.freedesktop.DBus.Error.ServiceUnknown: The name org.freedesktop.NetworkManager was not provided by any .service files
,
Jul 4 2017
+pwnall, leveldb and sqlite owner. merlin@, thanks for filing the bug with all the logs. What you says makes sense. Just a clarification, you repeatedly mention "sqlite" in your bug, however the log files in #1 #2 don't mention sqlite but indexeddb (which is backed by leveldb). Can I just ask where sqlite came from? Is there a log missing here? > 1) there is no good reason for chrome to give me never ending errors about sqlite problems. It should wipe the damaged file and restart fresh (possibly after asking me whether it's ok to do so) Not an owner of the area, but the request seems reasonable. We shouldn't just choke. > 2) I'm reasonably sure that btrfs does write consistent data on disk as per the filesystem semantics, even when the system crashes. Fun, I've been a btrfs aficionados since the early days :). It is possible that we (chrome) are implicitly making some assumption that holds only on ext4 or other FS but not btrfs. As regards the actual crashes, they seem to be GL related. Forked Issue 739095 for the actual crash problem. Let's keep this bug to discuss the indexeddb corruption. Slightly unrelated, I see from the crash logs that you could be affected by the Skylake bug*. Did you get a microcode update? Not sure if that is related here but that could explain some of the instability. * https://lists.debian.org/debian-devel/2017/06/msg00308.html
,
Jul 5 2017
IMPORTANT ASIDE: The current _stable_ version is Chrome 59. Running an older version is a security hazard. The package repository that you are using is fairly out of date, and you should get Chrome from a better source. This is entirely LevelDB / IndexedDB. SQLite is not involved here at all. I think that the problem is that the LevelDB CURRENT file points to a log file (MANIFEST-010814) that doesn't exist. Reporter: If you still see this issue, can you please open a shell and tell us the result of the command below: cat /var/change/merlin-change/.config/google-chrome-dir/google-chrome-beta/Default/IndexedDB/https_docs.google.com_0.indexeddb.leveldb/CURRENT This is based on the directory in the following log line: [15828:15862:0703/233713.347920:ERROR:indexed_db_backing_store.cc(1406)] Unable to open backing store, not trying to recover - IO error: /var/change/merlin-change/.config/google-chrome-dir/google-chrome-beta/Default/IndexedDB/https_docs.google.com_0.indexeddb.leveldb/MANIFEST-010814: Unable to create sequential file (ChromeMethodBFE: 7::NewSequentialFile::4) If your log lines show a different path, please try replacing MANIFEST-* with CURRENT in that path, and please report the log line and the contents of the CURRENT file. The file should consist of a single line that says "MANIFEST-010814" -- the digits might differ. Details: The IndexedDB log line seems to be coming from here: https://cs.chromium.org/chromium/src/content/browser/indexed_db/indexed_db_backing_store.cc?type=cs&q=file:indexed_db_backing_store.cc+not+trying+to+recover&l=1411 The LevelDB log line is most likely: https://cs.chromium.org/chromium/src/content/browser/indexed_db/leveldb/leveldb_database.cc?type=cs&q=file:leveldb_database.cc+failed+to+open+LevelDB+database+from&l=317 The "Unable to create sequential file" bit comes from either https://cs.chromium.org/chromium/src/components/leveldb/env_mojo.cc?q=NewSequentialFile+%22Unable+to+create+sequential+file%22&l=334&dr=C or https://cs.chromium.org/chromium/src/third_party/leveldatabase/env_chromium.cc?q=NewSequentialFile+%22Unable+to+create+sequential+file%22&l=857&dr=C The ChromeMethodBFE error detail seems to come from: https://cs.chromium.org/chromium/src/third_party/leveldatabase/env_chromium.cc?q=(ChromeMethodBFE:+%25d::%25s::%25d)&l=426 The ::4 bit at the end is FILE_NOT_FOUND: https://cs.chromium.org/chromium/src/base/files/file.h?type=cs&q=file:base/files/file.h+%22-4%22&l=105 I think the NewSequentialFile call is coming from leveldb::DB::Open -> leveldb::DBImpl::Recover -> leveldb::VersionSet::Recover at https://cs.chromium.org/chromium/src/third_party/leveldatabase/src/db/version_set.cc?gsn=Recover&l=926
,
Jul 6 2017
@primiano:thanks for having a look. I thought I saw sqlite earlier before, but you are correct that my report had data on leveldb, not sqlite. Thanks for the pointer on skylake, no I don't think I got the microcode update and my laptop has been hanging a bit too often since I upgraded from 4.4 kernel to 4.11.6. I will look into installing that, very much appreciated. @pwnall: I have google-chrome-beta 59.0.3071.61-1 google-chrome-stable 58.0.3029.110-1 yes, I'm one rev behind, I know I need to upgrade, will do soon. saruman:~$ cat /var/change/merlin-change/.config/google-chrome-dir/google-chrome-beta/Default/IndexedDB/https_docs.google.com_0.indexeddb.leveldb/CURRENT MANIFEST-010814 I just had my computer crash and I'm recovering right now. Both google-chrome-stable and google-chrome-beta failed to recover. One of the two just sent 2 different reports while loading up. I'll attach the logs of each.
,
Jul 6 2017
Thank you for providing more feedback. Adding requester "pwnall@chromium.org" to the cc list and removing "Needs-Feedback" label. For more details visit https://www.chromium.org/issue-tracking/autotriage - Your friendly Sheriffbot
,
Jul 6 2017
google-chrome-beta complained quite a bit on restart, but to its credit, managed to restore all my tabs without crashing (yes, I've just upgraded beta from 59 to 60 now): saruman:~# ulimit -n 120000; su - merlin -c '/usr/bin/google-chrome-beta' & [1] 11796 saruman:~# [1:1:0705/211648.994732:ERROR:chrome_content_client.cc(372)] Failed to locate and load the component updated flash plugin. [11804:11804:0705/211649.079990:ERROR:chrome_content_client.cc(372)] Failed to locate and load the component updated flash plugin. [11804:11804:0705/211649.322109:ERROR:desktop_window_tree_host_x11.cc(1148)] Not implemented reached in virtual void views::DesktopWindowTreeHostX11::InitModalType(ui::ModalType) [11804:11804:0705/211649.736448:ERROR:background_mode_manager_aura.cc(13)] Not implemented reached in virtual void BackgroundModeManager::EnableLaunchOnStartup(bool) [11804:11902:0705/211649.803074:ERROR:simple_index_file_posix.cc(49)] Could not get file info for /var/change/merlin-change/.config/google-chrome-dir/google-chrome-beta/Default/Cache/496f1894c1926f8a_0 --2017-07-05 21:16:49-- https://clients2.google.com/cr/report Resolving clients2.google.com (clients2.google.com)... 2607:f8b0:4005:80a::200e, 172.217.6.78 Connecting to clients2.google.com (clients2.google.com)|2607:f8b0:4005:80a::200e|:443... connected. HTTP request sent, awaiting response... 200 OK Length: unspecified [text/html] Saving to: ‘/dev/fd/4’ 0K 984K=0s 2017-07-05 21:16:50 (984 KB/s) - ‘/dev/fd/4’ saved [16] Crash dump id: 065b4a3d08000000 --2017-07-05 21:16:50-- https://clients2.google.com/cr/report Resolving clients2.google.com (clients2.google.com)... 2607:f8b0:4005:80a::200e, 172.217.6.78 Connecting to clients2.google.com (clients2.google.com)|2607:f8b0:4005:80a::200e|:443... connected. HTTP request sent, awaiting response... [11804:11867:0705/211650.706460:ERROR:object_proxy.cc(583)] Failed to call method: org.freedesktop.NetworkManager.GetDevices: object_path= /org/freedesktop/NetworkManager: org.freedesktop.DBus.Error.ServiceUnknown: The name org.freedesktop.NetworkManager was not provided by any .service files [11804:11867:0705/211650.706481:ERROR:networking_private_linux.cc(720)] Failed to enumerate network devices [11804:11837:0705/211650.947292:ERROR:service_manager.cc(425)] InterfaceProviderSpec prevented connection from: content_utility to: content_browser [11804:11837:0705/211651.084777:ERROR:service_manager.cc(425)] InterfaceProviderSpec prevented connection from: content_utility to: content_browser 200 OK Length: unspecified [text/html] Saving to: ‘/dev/fd/4’ 0K Crash dump id: 5fd759fc68000000 904K=0s 2017-07-05 21:16:51 (904 KB/s) - ‘/dev/fd/4’ saved [16] [11804:11837:0705/211651.143557:ERROR:browser_gpu_channel_host_factory.cc(103)] Failed to launch GPU process. [11804:11837:0705/211651.146618:ERROR:browser_gpu_channel_host_factory.cc(103)] Failed to launch GPU process. [11804:11837:0705/211651.147913:ERROR:browser_gpu_channel_host_factory.cc(103)] Failed to launch GPU process. [11804:11837:0705/211651.150692:ERROR:browser_gpu_channel_host_factory.cc(103)] Failed to launch GPU process. --2017-07-05 21:16:51-- https://clients2.google.com/cr/report Resolving clients2.google.com (clients2.google.com)... 2607:f8b0:4005:80a::200e, 172.217.6.78 Connecting to clients2.google.com (clients2.google.com)|2607:f8b0:4005:80a::200e|:443... connected. HTTP request sent, awaiting response... 200 OK Length: unspecified [text/html] Saving to: ‘/dev/fd/4’ 0K Crash dump id: 249f59fc68000000 849K=0s 2017-07-05 21:16:51 (849 KB/s) - ‘/dev/fd/4’ saved [16] --2017-07-05 21:16:51-- https://clients2.google.com/cr/report Resolving clients2.google.com (clients2.google.com)... 2607:f8b0:4005:80a::200e, 172.217.6.78 Connecting to clients2.google.com (clients2.google.com)|2607:f8b0:4005:80a::200e|:443... connected. HTTP request sent, awaiting response... 200 OK Length: unspecified [text/html] Saving to: ‘/dev/fd/4’ 0K 1.50M=0s 2017-07-05 21:16:52 (1.50 MB/s) - ‘/dev/fd/4’ saved [16] Crash dump id: d6c45fde40000000 --2017-07-05 21:16:52-- https://clients2.google.com/cr/report Resolving clients2.google.com (clients2.google.com)... 2607:f8b0:4005:80a::200e, 172.217.6.78 Connecting to clients2.google.com (clients2.google.com)|2607:f8b0:4005:80a::200e|:443... connected. HTTP request sent, awaiting response... 200 OK Length: unspecified [text/html] Saving to: ‘/dev/fd/4’ 0K Crash dump id: 1580d9fc68000000 507K=0s 2017-07-05 21:16:52 (507 KB/s) - ‘/dev/fd/4’ saved [16] --2017-07-05 21:16:52-- https://clients2.google.com/cr/report Resolving clients2.google.com (clients2.google.com)... 2607:f8b0:4005:80a::200e, 172.217.6.78 Connecting to clients2.google.com (clients2.google.com)|2607:f8b0:4005:80a::200e|:443... connected. HTTP request sent, awaiting response... 200 OK Length: unspecified [text/html] Saving to: ‘/dev/fd/4’ 0KCrash dump id: 9d205fde40000000 498K--2017-07-05 21:16:53-- https://clients2.google.com/cr/report Resolving clients2.google.com (clients2.google.com)... 2607:f8b0:4005:80a::200e, 172.217.6.78 Connecting to clients2.google.com (clients2.google.com)|2607:f8b0:4005:80a::200e|:443... connected. HTTP request sent, awaiting response... 200 OK Length: unspecified [text/html] Saving to: ‘/dev/fd/4’ 0K Crash dump id: 193f9fde40000000 650K=0s 2017-07-05 21:16:53 (650 KB/s) - ‘/dev/fd/4’ saved [16] [11804:11837:0705/211745.222455:ERROR:socket_stream.cc(210)] Closing stream with result -101 [11804:11837:0705/211749.220528:ERROR:service_manager.cc(425)] InterfaceProviderSpec prevented connection from: content_utility to: content_browser [11804:11837:0705/211850.744677:ERROR:socket_stream.cc(210)] Closing stream with result -101 [11804:11837:0705/212010.621313:ERROR:socket_stream.cc(210)] Closing stream with result -101 [11804:11837:0705/212130.256259:ERROR:service_manager.cc(425)] InterfaceProviderSpec prevented connection from: content_utility to: content_browser [11804:11837:0705/212130.392062:ERROR:service_manager.cc(425)] InterfaceProviderSpec prevented connection from: content_utility to: content_browser [11804:11837:0705/212130.535583:ERROR:socket_stream.cc(210)] Closing stream with result -101
,
Jul 6 2017
google-chrome (58) did the semi usual thing of starting and hanging during start without displaying anything. Semi usual meaning it's done this will all versions of chrome for the last 3 years (yes, I realize it may be a different bug, if so, feel free to fork this). saruman:~# ulimit -n 65000; su - merlin -c '/usr/bin/google-chrome' & [1] 12132 saruman:~# [12140:12140:0705/211704.257766:ERROR:background_mode_manager_aura.cc(13)] Not implemented reached in virtual void BackgroundModeManager::EnableLaunchOnStartup(bool) [12140:12140:0705/211704.300921:ERROR:desktop_window_tree_host_x11.cc(1147)] Not implemented reached in virtual void views::DesktopWindowTreeHostX11::InitModalType(ui::ModalType) --2017-07-05 21:17:04-- https://clients2.google.com/cr/report Resolving clients2.google.com (clients2.google.com)... 2607:f8b0:4005:80a::200e, 172.217.6.78 Connecting to clients2.google.com (clients2.google.com)|2607:f8b0:4005:80a::200e|:443... connected. HTTP request sent, awaiting response... [12140:12170:0705/211704.845991:ERROR:form_field_data.cc(333)] Unknown FormFieldData pickle version 41 [12140:12170:0705/211704.847034:ERROR:form_field_data.cc(333)] Unknown FormFieldData pickle version 8 [12140:12170:0705/211704.848456:ERROR:form_field_data.cc(250)] Could not deserialize FormFieldData from pickle [12140:12170:0705/211704.852271:ERROR:form_field_data.cc(250)] Could not deserialize FormFieldData from pickle [12140:12170:0705/211704.854709:ERROR:form_field_data.cc(333)] Unknown FormFieldData pickle version 8 [12140:12170:0705/211704.854958:ERROR:form_field_data.cc(250)] Could not deserialize FormFieldData from pickle [12140:12170:0705/211704.855706:ERROR:form_field_data.cc(312)] Could not deserialize FormFieldData from pickle 200 OK Length: unspecified [text/html] Saving to: ‘/dev/fd/4’ 0K Crash dump id: 82576bdf38000000 672K=0s 2017-07-05 21:17:05 (672 KB/s) - ‘/dev/fd/4’ saved [16] --2017-07-05 21:17:05-- https://clients2.google.com/cr/report Resolving clients2.google.com (clients2.google.com)... 2607:f8b0:4005:80a::200e, 172.217.6.78 Connecting to clients2.google.com (clients2.google.com)|2607:f8b0:4005:80a::200e|:443... connected. HTTP request sent, awaiting response... [12140:12175:0705/211705.402083:ERROR:browser_gpu_channel_host_factory.cc(113)] Failed to launch GPU process. [12140:12175:0705/211705.442769:ERROR:browser_gpu_channel_host_factory.cc(113)] Failed to launch GPU process. [12140:12175:0705/211705.471943:ERROR:browser_gpu_channel_host_factory.cc(113)] Failed to launch GPU process. [12140:12174:0705/211705.512931:ERROR:simple_version_upgrade.cc(164)] File structure does not match the disk cache backend. [12140:12174:0705/211705.512953:ERROR:simple_backend_impl.cc(621)] Simple Cache Backend: wrong file structure on disk: /home/merlin/.config/google-chrome/Default/Service Worker/CacheStorage/4b3c19c3f2722f26e3232756cd5969a07cd830d1/773af946-b5b4-48c8-8608-02becb8f4ea3 [12140:12174:0705/211705.513229:ERROR:simple_version_upgrade.cc(164)] File structure does not match the disk cache backend. [12140:12175:0705/211705.513266:ERROR:disk_cache.cc(132)] Unable to create cache [12140:12174:0705/211705.513244:ERROR:simple_backend_impl.cc(621)] Simple Cache Backend: wrong file structure on disk: /home/merlin/.config/google-chrome/Default/Service Worker/CacheStorage/3a540d1e37ee145760ae0664f65701da31f9ea56/028239fc-97eb-4e4b-b230-fb1016ed8f64 [12140:12175:0705/211705.513574:ERROR:disk_cache.cc(132)] Unable to create cache [12140:12174:0705/211705.514581:ERROR:simple_version_upgrade.cc(164)] File structure does not match the disk cache backend. [12140:12174:0705/211705.514607:ERROR:simple_backend_impl.cc(621)] Simple Cache Backend: wrong file structure on disk: /home/merlin/.config/google-chrome/Default/Service Worker/CacheStorage/783e7ccd1569e6f0af8b16953519e77950ae84e4/485649e7-c1d1-4032-b717-0f66e82c84a1 [12140:12175:0705/211705.514879:ERROR:disk_cache.cc(132)] Unable to create cache [12140:12174:0705/211705.518923:ERROR:simple_version_upgrade.cc(164)] File structure does not match the disk cache backend. [12140:12174:0705/211705.518988:ERROR:simple_backend_impl.cc(621)] Simple Cache Backend: wrong file structure on disk: /home/merlin/.config/google-chrome/Default/Service Worker/CacheStorage/28da9c56fde4021055a681112c092453f74d8dd8/2bc8b9da-1a4b-4377-a32b-1a6cf7088030 [12140:12175:0705/211705.522767:ERROR:disk_cache.cc(132)] Unable to create cache [12140:12174:0705/211705.526213:ERROR:simple_version_upgrade.cc(164)] File structure does not match the disk cache backend. [12140:12174:0705/211705.526241:ERROR:simple_backend_impl.cc(621)] Simple Cache Backend: wrong file structure on disk: /home/merlin/.config/google-chrome/Default/Service Worker/CacheStorage/bf537d81268177ef05a3e3a1617232fce0d7767b/e1bf22a8-4169-4d2f-b1c4-205f293c5bb6 [12140:12175:0705/211705.526895:ERROR:disk_cache.cc(132)] Unable to create cache 200 OK Length: unspecified [text/html] Saving to: ‘/dev/fd/4’ 0KCrash dump id: 16420a3d08000000 1.29M=0s --2017-07-05 21:17:05-- https://clients2.google.com/cr/report Resolving clients2.google.com (clients2.google.com)... 2607:f8b0:4005:80a::200e, 172.217.6.78 Connecting to clients2.google.com (clients2.google.com)|2607:f8b0:4005:80a::200e|:443... connected. HTTP request sent, awaiting response... 200 OK Length: unspecified [text/html] Saving to: ‘/dev/fd/4’ 0K Crash dump id: 5040d9fc68000000 1.67M=0s [12140:12170:0705/211706.660344:ERROR:form_field_data.cc(333)] Unknown FormFieldData pickle version 41 [12140:12170:0705/211706.660856:ERROR:form_field_data.cc(333)] Unknown FormFieldData pickle version 8 [12140:12170:0705/211706.661358:ERROR:form_field_data.cc(250)] Could not deserialize FormFieldData from pickle [12140:12170:0705/211706.663242:ERROR:form_field_data.cc(250)] Could not deserialize FormFieldData from pickle [12140:12170:0705/211706.664300:ERROR:form_field_data.cc(333)] Unknown FormFieldData pickle version 8 [12140:12170:0705/211706.664587:ERROR:form_field_data.cc(250)] Could not deserialize FormFieldData from pickle [12140:12170:0705/211706.665402:ERROR:form_field_data.cc(312)] Could not deserialize FormFieldData from pickle [12140:12140:0705/211706.680463:ERROR:sessions_sync_manager.cc(252)] No windows present, see crbug.com/639009 [12140:12170:0705/211714.622199:ERROR:form_field_data.cc(333)] Unknown FormFieldData pickle version 41 [12140:12170:0705/211714.623374:ERROR:form_field_data.cc(333)] Unknown FormFieldData pickle version 8 [12140:12170:0705/211714.624592:ERROR:form_field_data.cc(250)] Could not deserialize FormFieldData from pickle [12140:12170:0705/211714.629696:ERROR:form_field_data.cc(250)] Could not deserialize FormFieldData from pickle [12140:12170:0705/211714.632023:ERROR:form_field_data.cc(333)] Unknown FormFieldData pickle version 8 [12140:12170:0705/211714.632613:ERROR:form_field_data.cc(250)] Could not deserialize FormFieldData from pickle [12140:12170:0705/211714.634818:ERROR:form_field_data.cc(312)] Could not deserialize FormFieldData from pickle [12140:12174:0705/211720.789235:ERROR:simple_version_upgrade.cc(164)] File structure does not match the disk cache backend. [12140:12174:0705/211720.789266:ERROR:simple_backend_impl.cc(621)] Simple Cache Backend: wrong file structure on disk: /home/merlin/.config/google-chrome/Default/Service Worker/CacheStorage/28da9c56fde4021055a681112c092453f74d8dd8/2bc8b9da-1a4b-4377-a32b-1a6cf7088030 [12140:12175:0705/211720.789346:ERROR:disk_cache.cc(132)] Unable to create cache [12140:12174:0705/211720.856730:ERROR:simple_version_upgrade.cc(164)] File structure does not match the disk cache backend. [12140:12174:0705/211720.856754:ERROR:simple_backend_impl.cc(621)] Simple Cache Backend: wrong file structure on disk: /home/merlin/.config/google-chrome/Default/Service Worker/CacheStorage/28da9c56fde4021055a681112c092453f74d8dd8/2bc8b9da-1a4b-4377-a32b-1a6cf7088030 [12140:12175:0705/211720.856867:ERROR:disk_cache.cc(132)] Unable to create cache I killed it and restarted it and all my tabs got lost after being told that my profile could not be read: saruman:~# ulimit -n 65000; su - merlin -c '/usr/bin/google-chrome' & [1] 26812 saruman:~# [26820:26820:0705/214038.123481:ERROR:desktop_window_tree_host_x11.cc(1148)] Not implemented reached in virtual void views::DesktopWindowTreeHostX11::InitModalType(ui::ModalType) [26820:26820:0705/214038.407699:ERROR:background_mode_manager_aura.cc(13)] Not implemented reached in virtual void BackgroundModeManager::EnableLaunchOnStartup(bool) --2017-07-05 21:40:38-- https://clients2.google.com/cr/report Resolving clients2.google.com (clients2.google.com)... 2607:f8b0:4005:80a::200e, 172.217.6.78 Connecting to clients2.google.com (clients2.google.com)|2607:f8b0:4005:80a::200e|:443... connected. HTTP request sent, awaiting response... [26820:26820:0705/214039.025433:ERROR:display_info_provider_aura.cc(31)] Not implemented reached in virtual void extensions::DisplayInfoProviderAura::UpdateDisplayUnitInfoForPlatform(const display::Display &, extensions::api::system_display::DisplayUnitInfo *) 200 OK Length: unspecified [text/html] Saving to: ‘/dev/fd/4’ 0K Crash dump id: 5877ce3d08000000 1.11M=0s 2017-07-05 21:40:39 (1.11 MB/s) - ‘/dev/fd/4’ saved [16] --2017-07-05 21:40:39-- https://clients2.google.com/cr/report Resolving clients2.google.com (clients2.google.com)... 2607:f8b0:4005:80a::200e, 172.217.6.78 Connecting to clients2.google.com (clients2.google.com)|2607:f8b0:4005:80a::200e|:443... connected. [26820:26879:0705/214039.155244:ERROR:object_proxy.cc(583)] Failed to call method: org.freedesktop.NetworkManager.GetDevices: object_path= /org/freedesktop/NetworkManager: org.freedesktop.DBus.Error.ServiceUnknown: The name org.freedesktop.NetworkManager was not provided by any .service files [26820:26879:0705/214039.155259:ERROR:networking_private_linux.cc(720)] Failed to enumerate network devices HTTP request sent, awaiting response... 200 OK Length: unspecified [text/html] Saving to: ‘/dev/fd/4’ 0K Crash dump id: 8343d9fc68000000 577K=0s 2017-07-05 21:40:39 (577 KB/s) - ‘/dev/fd/4’ saved [16] --2017-07-05 21:40:39-- https://clients2.google.com/cr/report Resolving clients2.google.com (clients2.google.com)... 2607:f8b0:4005:80a::200e, 172.217.6.78 Connecting to clients2.google.com (clients2.google.com)|2607:f8b0:4005:80a::200e|:443... connected. HTTP request sent, awaiting response... 200 OK Length: unspecified [text/html] Saving to: ‘/dev/fd/4’ 0KCrash dump id: 3477ce3d08000000 515K saruman:~# [26820:26852:0705/214115.843109:ERROR:simple_version_upgrade.cc(164)] File structure does not match the disk cache backend. [26820:26852:0705/214115.843156:ERROR:simple_backend_impl.cc(630)] Simple Cache Backend: wrong file structure on disk: /home/merlin/.config/google-chrome/Default/Service Worker/CacheStorage/28da9c56fde4021055a681112c092453f74d8dd8/2bc8b9da-1a4b-4377-a32b-1a6cf7088030 [26820:26853:0705/214115.843257:ERROR:disk_cache.cc(132)] Unable to create cache [26820:26853:0705/214131.391412:ERROR:socket_stream.cc(210)] Closing stream with result -101 [26820:26879:0705/214132.015138:ERROR:object_proxy.cc(583)] Failed to call method: org.freedesktop.NetworkManager.GetDevices: object_path= /org/freedesktop/NetworkManager: org.freedesktop.DBus.Error.ServiceUnknown: The name org.freedesktop.NetworkManager was not provided by any .service files [26820:26879:0705/214132.015155:ERROR:networking_private_linux.cc(720)] Failed to enumerate network devices
,
Jul 6 2017
Both google-chrome stable and beta started up without major problems after I rsynced an old snapshot of my config (and upgraded both chromes to the latest versions). Now I'm only seeing this: [12202:12237:0705/215957.952551:ERROR:leveldb_database.cc(317)] Failed to open LevelDB database from /var/change/merlin-change/.config/google-chrome-dir/google-chrome-beta/Default/IndexedDB/https_docs.google.com_0.indexeddb.leveldb,IO error: /var/change/merlin-change/.config/google-chrome-dir/google-chrome-beta/Default/IndexedDB/https_docs.google.com_0.indexeddb.leveldb/MANIFEST-010814: Unable to create sequential file (ChromeMethodBFE: 7::NewSequentialFile::4) [12202:12237:0705/215957.953023:ERROR:indexed_db_backing_store.cc(1411)] Unable to open backing store, not trying to recover - IO error: /var/change/merlin-change/.config/google-chrome-dir/google-chrome-beta/Default/IndexedDB/https_docs.google.com_0.indexeddb.leveldb/MANIFEST-010814: Unable to create sequential file (ChromeMethodBFE: 7::NewSequentialFile::4) Sure enough, the value of "CURRENT" doesn't exist as you said: saruman:/var/change/merlin-change/.config/google-chrome-dir/google-chrome-beta/Default/IndexedDB/https_docs.google.com_0.indexeddb.leveldb$ l total 30932 drwx------ 1 merlin merlin 402 Jul 5 22:31 ./ drwx------ 1 merlin merlin 18950 Jun 24 18:23 ../ -rw------- 1 merlin merlin 4229 Jul 3 08:31 000003.log -rw------- 1 merlin merlin 3756884 May 12 17:36 022749.log -rw------- 1 merlin merlin 2155322 May 12 14:56 022753.ldb -rw------- 1 merlin merlin 2192607 May 12 14:56 022754.ldb -rw------- 1 merlin merlin 2108647 May 12 14:56 022755.ldb -rw------- 1 merlin merlin 2136078 May 12 14:56 022756.ldb -rw------- 1 merlin merlin 2129077 May 12 14:56 022757.ldb -rw------- 1 merlin merlin 2113558 May 12 14:56 022758.ldb -rw------- 1 merlin merlin 3008418 May 12 14:56 022759.ldb -rw------- 1 merlin merlin 2577827 May 12 14:56 022760.ldb -rw------- 1 merlin merlin 2474728 May 12 14:56 022761.ldb -rw------- 1 merlin merlin 2538930 May 12 14:56 022762.ldb -rw------- 1 merlin merlin 2233975 May 12 17:36 022763.ldb -rw------- 1 merlin merlin 2129588 May 12 17:36 022764.ldb -rw------- 1 merlin merlin 58698 May 12 17:36 022765.ldb -rw------- 1 merlin merlin 16 Oct 4 2016 CURRENT -rw------- 1 merlin merlin 0 Apr 9 2016 LOCK -rw------- 1 merlin merlin 0 Jul 5 22:31 LOG -rw------- 1 merlin merlin 0 Jul 5 22:31 LOG.old -rw------- 1 merlin merlin 23 Jul 3 08:31 MANIFEST-000001 -rw------- 1 merlin merlin 8639 May 12 17:36 MANIFEST-022745 saruman:/var/change/merlin-change/.config/google-chrome-dir/google-chrome-beta/Default/IndexedDB/https_docs.google.com_0.indexeddb.leveldb$ cat CURRENT MANIFEST-010814 Looks like the workaround is this? echo MANIFEST-022745 > CURRENT
,
Jul 6 2017
Two questions: 1) How does rsync resolve conflicts when a file exists on both sides? Is it possible that you ended up with an older CURRENT and a newer set of MANIFEST files, or the other way around? 2) You mentioned earlier that btrfs has some consistency guarantees. Do you happen to know where I can read about them? I'm most interested in whether it guarantees that a sequence of writes to different files are committed in order, or whether its integrity guarantees are per-file.
,
Jul 6 2017
Reproduction steps: 1) Download the attached file and open it using an http server or via a file: URL (I use xdg-open). On my computer, the URL looks like below. file:///Users/pwnall/Desktop/ bug738961 .html 2) Open the console and wait for the "Database opened" message to show up. 3) Go to chrome://indexeddb-internals and search for bug738916 to find the path to IndexedDB's leveldb directory. On my computer, the path looks like below. /Users/pwnall/Library/Application Support/Chromium/Default/IndexedDB/file__0.indexeddb.leveldb 4) Confirm that the directory looks like a leveldb database. The path below will need adjusting. 4a) ls "/Users/pwnall/Library/Application Support/Chromium/Default/IndexedDB/file__0.indexeddb.leveldb" 000003.log CURRENT LOCK LOG MANIFEST-000001 4b) cat "/Users/pwnall/Library/Application Support/Chromium/Default/IndexedDB/file__0.indexeddb.leveldb/CURRENT" MANIFEST-000001 5) Close Chrome. 6) Replace CURRENT with an invalid MANIFEST. The below will need adjusting. echo MANIFEST-000002 > "/Users/pwnall/Library/Application Support/Chromium/Default/IndexedDB/file__0.indexeddb.leveldb/CURRENT" 7) Start Chrome and navigate to the same URL as before. The log should contain output like the following. [35887:32259:0706/011534.889548:ERROR:leveldb_database.cc(317)] Failed to open LevelDB database from /Users/pwnall/Library/Application Support/Chromium/Default/IndexedDB/file__0.indexeddb.leveldb,IO error: /Users/pwnall/Library/Application Support/Chromium/Default/IndexedDB/file__0.indexeddb.leveldb/MANIFEST-000002: Unable to create sequential file (ChromeMethodBFE: 7::NewSequentialFile::4) [35887:32259:0706/011534.890437:ERROR:indexed_db_backing_store.cc(1411)] Unable to open backing store, not trying to recover - IO error: /Users/pwnall/Library/Application Support/Chromium/Default/IndexedDB/file__0.indexeddb.leveldb/MANIFEST-000002: Unable to create sequential file (ChromeMethodBFE: 7::NewSequentialFile::4) [35887:775:0706/011534.991303:INFO:CONSOLE(42)] "Failed to open database", source: file:///Users/pwnall/Desktop/ bug738961 .html (42) [35887:775:0706/011534.992193:INFO:CONSOLE(43)] "[object DOMException]", source: file:///Users/pwnall/Desktop/ bug738961 .html (43) The easiest way out of the weird state is to go to the Application tab in Developer Tools and use the Clear Storage option. Only the IndexedDB checkbox needs to be ticked. The repeated log entries in the original bug report are probably due to the fact that Google Docs retries to open the IndexedDB database forever. Using the workaround described above in a tab with Google Docs open should get the profile unstuck. The fix is non-trivial due to the many bits that need to be modified. 1) On the Chromium side, MakeIOError should return a Status::NotFound when the error is base::File::Error::FILE_ERROR_NOT_FOUND. This change should be applied in both https://cs.chromium.org/chromium/src/components/leveldb/env_mojo.cc and https://cs.chromium.org/chromium/src/third_party/leveldatabase/env_chromium.cc. 2) On the LevelDB side, leveldb::VersionSet::Recover needs to return Status::Corruption if NewSequentialFile() returns Status::NotFound instead of simply passing the status up, at https://cs.chromium.org/chromium/src/third_party/leveldatabase/src/db/version_set.cc Alternatively, we could just nuke the database and restart if an I/O error occurs. Setting the priority back to P2, because this seems like a reasonable corruption case that we get stuck in.
,
Jul 6 2017
1) How does rsync resolve conflicts when a file exists on both sides? I use rsync -av -SH -P --fuzzy --delete --delete-after --force This effectively takes the source dir and re-applies it to the destination dir, solving all conflicts so that they are identical at the end. 2) You mentioned earlier that btrfs has some consistency guarantees. => that is a very good question. I'm not sure that this is published outside of reading the source, but I will ask on the mailing list for you and report back (this may take a few days). It is very possible that its guarantees are so that files are always in some consistent state, but not necessarily all written at the same time, or not at all.
,
Jul 6 2017
Are these yet another problem by the way? [12140:12170:0705/211714.632613:ERROR:form_field_data.cc(250)] Could not deserialize FormFieldData from pickle [12140:12170:0705/211714.634818:ERROR:form_field_data.cc(312)] Could not deserialize FormFieldData from pickle [12140:12174:0705/211720.789235:ERROR:simple_version_upgrade.cc(164)] File structure does not match the disk cache backend. [12140:12174:0705/211720.789266:ERROR:simple_backend_impl.cc(621)] Simple Cache Backend: wrong file structure on disk: /home/merlin/.config/google-chrome/Default/Service Worker/CacheStorage/28da9c56fde4021055a681112c092453f74d8dd8/2bc8b9da-1a4b-4377-a32b-1a6cf7088030 [12140:12175:0705/211720.789346:ERROR:disk_cache.cc(132)] Unable to create cache [12140:12174:0705/211720.856730:ERROR:simple_version_upgrade.cc(164)] File structure does not match the disk cache backend. [12140:12174:0705/211720.856754:ERROR:simple_backend_impl.cc(621)] Simple Cache Backend: wrong file structure on disk: /home/merlin/.config/google-chrome/Default/Service Worker/CacheStorage/28da9c56fde4021055a681112c092453f74d8dd8/2bc8b9da-1a4b-4377-a32b-1a6cf7088030 [12140:12175:0705/211720.856867:ERROR:disk_cache.cc(132)] Unable to create cache
,
Jul 6 2017
I've Cc'ed you to the message to the btrfs list (which allows anyone to post without subscribing) so that you can clarify the sequence of events in a leveldb record update (I totally guessed and I may be wrong) Thanks again for looking at all this.
,
Jul 6 2017
I just realized that I did have sqlite issues at another start a few days ago, and pasted them in the mailing list, but not this bug. I've opened a separate bug for those logs. Can you help make sure it gets into the right queue? https://bugs.chromium.org/p/chromium/issues/detail?id=739819
,
Jul 6 2017
This seems related to what I'm seeing: https://github.com/google/leveldb/issues/195
,
Jul 6 2017
Btrfs dev here, I replied to Marc's email on the mailing list but also asking for more details here. From what I can see, LevelDB numbers filenames sequentially, so MANIFEST-010814 and MANIFEST-022745 should be very far apart in time, right? And since MANIFEST only gets updated on every open, that's a lot of Chrome restarts...
,
Jul 7 2017
As discussed on the list, I think I may have ended up with that old CURRENT file after a previous rsync after my chrome profile was one more time non functional after a crash/reboot. Sadly this also means that I don't have an exact sequence of events of how I got into that state, but I'm happy to pay closer attention next time it happens and give better info.
,
Jul 7 2017
I am working on the LevelDB-side fix described in #11. If that fix is accepted, I'll put together the Chromium-side fix as well.
,
Jul 12 2017
The following revision refers to this bug: https://chromium.googlesource.com/chromium/src.git/+/c3cf672fff16e8546056e3da9181097d76c91746 commit c3cf672fff16e8546056e3da9181097d76c91746 Author: Victor Costan <pwnall@chromium.org> Date: Wed Jul 12 01:34:05 2017 DEPS: Roll src/third_party/leveldatabase/src/ a53934a3a..8415f00ee (2 commits) The LevelDB update includes better handling for a database corruption case that can impact IndexedDB. https://chromium.googlesource.com/external/leveldb.git/+log/a53934a3ae12..8415f00eeedd $ git log a53934a3a..8415f00ee --date=short --no-merges --format='%ad %ae %s' 2017-07-10 costan leveldb: Report missing CURRENT manifest file as database corruption. 2017-05-23 costan LevelDB: Add WriteBatch::ApproximateSize(). This CL also modifies Chromium's LevelDB environment so file operations return Status::NotFound when appropriate. This change is needed to pass a new test case in leveldb_env_test, and for the new corruption handling to work. BUG= 738961 TESTED=leveldb_env_test Change-Id: I20550877383c34ece318dd1d35024fcd40dc9c15 Reviewed-on: https://chromium-review.googlesource.com/563652 Reviewed-by: Marijn Kruisselbrink <mek@chromium.org> Commit-Queue: Victor Costan <pwnall@chromium.org> Cr-Commit-Position: refs/heads/master@{#485775} [modify] https://crrev.com/c3cf672fff16e8546056e3da9181097d76c91746/DEPS [modify] https://crrev.com/c3cf672fff16e8546056e3da9181097d76c91746/components/leveldb/env_mojo.cc [modify] https://crrev.com/c3cf672fff16e8546056e3da9181097d76c91746/third_party/leveldatabase/env_chromium.cc
,
Jul 12 2017
The CL above should take care of this issue. Thank you very much for the thorough information in the bug report! |
|||||||
►
Sign in to add a comment |
|||||||
Comment 1 by mer...@gmail.com
, Jul 4 2017