threeplanetssoftware / apple_cloud_notes_parser

Parser for Apple Notes data stored on the Cloud as seen on Apple handsets
MIT License
410 stars 26 forks source link

SQLite3::CorruptException / Zlib::DataError #108

Open forthrin opened 7 months ago

forthrin commented 7 months ago

Describe the bug

What more information (short of the files) can be provided to resolve the issues?

EXCEPTION 1 (No call stack)
SQLite3::CorruptException encountered while trying to write plaintext to database, this may be a result of a Notes migration, try opening the application and saving it again.

EXCEPTION 2
Guessed Notes Version: 16
./apple_cloud_notes_parser/lib/AppleNote.rb:332:in `inflate': invalid stored block lengths (Zlib::DataError)

EXCEPTION 3
Guessed Notes Version: 17
/opt/homebrew/lib/ruby/gems/3.3.0/gems/sqlite3-1.7.3-arm64-darwin/lib/sqlite3/resultset.rb:162:in `step': database disk image is malformed (SQLite3::CorruptException)
from ./apple_cloud_notes_parser/lib/AppleNoteStore.rb:678:in `rip_notes'

EXCEPTION 4 (Same as 2, but different notes version)
Guessed Notes Version: 17
./apple_cloud_notes_parser/lib/AppleNote.rb:332:in `inflate': incorrect data check (Zlib::DataError)

Expected behavior No crashes, obviously.

Desktop (please complete the following information):

Command used ruby notes_cloud_parser.rb -f NoteStore.sqlite

Please confirm the following

Additional context Workaround:

diff --git a/lib/AppleNote.rb b/lib/AppleNote.rb
index 051616b..c318e97 100644
--- a/lib/AppleNote.rb
+++ b/lib/AppleNote.rb
@@ -332 +332,5 @@ class AppleNote < AppleCloudKitRecord
-      @decompressed_data = zlib_inflater.inflate(@compressed_data)
+      begin
+        @decompressed_data = zlib_inflater.inflate(@compressed_data)
+      rescue StandardError => e
+        warn "\033[101m#{e}\033[m"
+      end
diff --git a/lib/AppleNoteStore.rb b/lib/AppleNoteStore.rb
index ff17399..eb54919 100644
--- a/lib/AppleNoteStore.rb
+++ b/lib/AppleNoteStore.rb
@@ -678,3 +678,7 @@ class AppleNoteStore
-      @database.execute(tmp_query, range_start_core, range_end_core) do |row|
-        self.rip_note(row["ZNOTE"])
-      end
+        @database.execute(tmp_query, range_start_core, range_end_core) do |row|
+          begin
+            self.rip_note(row["ZNOTE"])
+          rescue StandardError => e
+            warn "\033[101m#{e}\033[m"
+          end
+        end
threeplanetssoftware commented 7 months ago

Good morning and thanks for reporting this issue!

I would normally blame deleted notes for something like this, but the SQLite errors seem to point more towards something happening to your database files since all 4 are throwing errors and they're at the level of the SQLite file being corrupt.

I appreciate the patch for adding in the rescue statements, I certainly don't have enough of those. The section you're looking at had been an issue in the past, but I haven't come across any data that both checked out as gzipped data and was truncated after adding Zlib::MAX_WBITS + 16.

The first thing I'd recommend is making sure that the files look correct. Do they open in a tool like sqlite3 or sqlitebrowser? Do you see data that looks order of magnitude like what you're expecting (i.e. if you have 800 notes and the file shows a handful of entries in each table, this would fail)?

As evidenced by the first error message you listed, I've seen issues where the database wasn't in a great state when the OS updated. So I would also recommend open Notes, then closing it explicitly, and maybe wait a breath or two before doing your backups again. However, because all four are failing I suspect there's something wrong inside of them. Are all four of these notes from the same account? There might be something that got corrupted that is being shared across them which you need to delete.

The debug log should give you some relevant information. The best place to start for a failing pass is simply looking at the very last lines. That should help you bound which note is failing (or would prior to your patch above. I've added in an error statement to the log in ea799e052736edf795a3d91a2f16040a1786cf68, so now you can look at those lines rather than the last line). You can then look for that specific note in the ZICNOTEDATA table to make sure it looks decent.

I hope this helps for initial troubleshooting. Thank you again for the rescue code, I'm sure it will help others as well!

threeplanetssoftware commented 7 months ago

One other thought, just because you're getting these errors part of the way through a run. I would highly recommend making sure you're not running it while something else has the database open. I copy my backups elsewhere before running this script to avoid the file being locked. Make sure Notes is closed and copy the files to another location and try running it there.

forthrin commented 7 months ago

Thanks for your friendly feedback.

The following moronic workaround salvages as much binary data as possible. There is probably a way to make Ruby's gzip library similarily decompress a stream and/or return stubs of incomplete data. I assume this is as good as it gets.

diff --git a/lib/AppleNote.rb b/lib/AppleNote.rb
index 051616b..5a54fe1 100644
--- a/lib/AppleNote.rb
+++ b/lib/AppleNote.rb
@@ -331,3 +331,10 @@ class AppleNote < AppleCloudKitRecord
       zlib_inflater = Zlib::Inflate.new(Zlib::MAX_WBITS + 16)
-      @decompressed_data = zlib_inflater.inflate(@compressed_data)
+      begin
+        @decompressed_data = zlib_inflater.inflate(@compressed_data)
+      rescue StandardError => e
+        File.write('/tmp/foo', @compressed_data)
+        `gunzip < /tmp/foo > /tmp/bar`
+        @uncompressed_data = File.read('/tmp/bar')
+        warn "\033[101m#{e.class} - #{e.message} (managed to uncompress #{@uncompressed_data.length} bytes of #{@compressed_data.length} compressed bytes before encountering corrupt data)\033[m"
+      end
     else

The types of integrity checks reported were:

Error: stepping, database disk image is malformed (###)
Freelist: freelist leaf count too big on page ###
Freelist: invalid page number ###
Page ###: never used
Tree ### page ### cell ###: ###nd reference to page ###
Tree ### page ### cell ###: Bad ptr map entry key=### expected=(###,###) got=(###,###)
Tree ### page ### cell ###: Failed to read ptrmap key=###
Tree ### page ### cell ###: invalid page number ###
Tree ### page ### right child: ###nd reference to page ###
Tree ### page ### right child: Bad ptr map entry key=### expected=(###,###) got=(###,###)
Tree ### page ### right child: Failed to read ptrmap key=###
Tree ### page ### right child: invalid page number ###
row ### missing from index Z_TRANSACTION_TransactionAuthorIndex
wrong # of entries in index ATRANSACTION_ZAUTHORTS_INDEX
wrong # of entries in index ATRANSACTION_ZBUNDLEIDTS_INDEX
wrong # of entries in index ATRANSACTION_ZCONTEXTNAMETS_INDEX
wrong # of entries in index ATRANSACTION_ZPROCESSIDTS_INDEX
wrong # of entries in index Z_TRANSACTION_TransactionAuthorIndex
wrong # of entries in index Z_TRANSACTION_TransactionTimestampIndex

To save yourself unnecessary exception handling and bug reports, pre-pass with SQLite's built-ins before parsing.

Anything more information that would be useful to you?

threeplanetssoftware commented 7 months ago

Thanks for the detailed feedback, I'm going to look this over and ponder the best way to move forward.

May I ask if you were expecting these to be corrupted databases? Having 50 databases, with 14 corrupted, makes me think this is more of a data recovery situation and not actual backups of a healthy system. I would be somewhat interested in knowing how they got corrupted to try to recreate that for test data.

forthrin commented 7 months ago

Well, the "transaction" things could be be because those tables are trimmed before backing up, as they were taking up an enormous amount of space (much more than the content itself), as revealed by sqlite3_analyzer.

delete from atransaction where unixepoch() - 978307200 - ztimestamp > 86400*7;
delete from achange where ztransactionid not in (select rowid from atransaction);
pragma wal_checkpoint(full);
vacuum;

Regardless, if the database is well defined, deleting items should trigger necessary cleanup. Furthermore, running this manually on the resident database, pragma integrity_check returned OK afterwards, so seems harmless.

What are they used for anyway? Full undo history? Excessive safety measure for rollbacks to prevent content loss?

Assume the other errors are unrelated to the transaction things, and general corruption of backup data can also be excluded, as this has not happened a single time for any other files within the same backup system.

Happy to provide more tests or information be it useful.

threeplanetssoftware commented 7 months ago

That's fascinating, thanks. So you have 50 NoteStore files, and you ran something akin to the above SQLite command to better manage the size. After doing that 14 of the 50 threw SQLite errors. This is certainly a unique use case.

I think I lean towards running those integrity checks after such errors are caught (maybe in a rescue, or maybe as an explicit switch someone can run intentionally) rather than on every database. This code started as a forensic tool and I currently try to keep everything read only, other than adding the plaintext note contents back into the NoteStore for readability. I wouldn't want to truncate or alter it other than that if the user is not expecting it.

I'm still interested in the corrupted gzipped blobs, I don't know how removing the transactions and changes would affect that. I am not very keen to trying to parse as much as possible from potentially bad objects for a similar reason as above. Because the protobuf order is not strictly specified (a lot of fields are optional, as is the order for repeated fields), I'd be concerned at displaying something that isn't quite right with no obvious way to know it was only partially done. I like the idea of writing out the bad blobs, but would probably again gate that behind a switch to make sure the user wanted them dumped to disk.

Taking this back to the thread genesis, do you feel the addition of these rescue statements (thank you for them, again!) satisfies the immediate need of this issue? It should allow the program to keep running whether a blob is corrupted or not.

forthrin commented 7 months ago

The files come from a temporal backup routine.

If you know gzip on a detailed binary level, you could try to look at the data to see if the corruption is noticeable. Post here if there are tools that already do this. Initial guess(!) is that a single changed/added/removed bit can make gunzip bail.

If you can find out how many bytes/percent of the compressed data is read before failing, you can add a output notification saying, "Only 42% of the compressed data of the note "Dinner" in the folder "Food" could be decompressed. Some of your content may be missing. Open the note in macOS Notes and see if more content is available there."

The rescue statements were minute quick fixes, not intended for production, but use and modify them as you please. As mentioned, try to do as mentioned earlier, but if it doesn't, and doing a dirty system call works, why not.

... make Ruby's gzip library similarily decompress a stream and/or return stubs of incomplete data.