Console errors from file compression?

Hi,

Under 10.7.4 Time Machine hangs and I get these in my console log:

5/30/12 9:51:11.000 AM kernel: /SourceCache/AppleFSCompression/AppleFSCompression-37/Compressors/Dataless/compressorType5Kext.c:532: Error: post_request error for /Volumes/T3/Backups.backupdb/jbenniMac/2012-05-30-084212.inProgress/1C6092BC-1544-4B25-97EC-CAF382604372/Macintosh HD/.DocumentRevisions-V100-bad-1/PerUID/501/118/com.apple.documentVersions/08669C22-C5AD-4414-BE6D-D77C54D398CF.m: 35

5/30/12 9:51:11.000 AM kernel: decmpfs.c:1309:decmpfs_read_compressed: decmpfs_fetch_uncompressed_data err -35

The destination disk (direct attach, FW) is new. Both the source and dest disks verify under Disk Utils. TM hangs with X bytes written. (The time to complete estimate continues to rise indefinitely.) The above messages repeat on console every 15 secs.

How can I find the cause?

Thanks!
John

Erased dest volume - same problem reocurred

Thanks for responding.

I used Disk Utils and erased the backup disk partition, then restarted TM. It recognized the volume as a new one, recomputed space then started file backup. At the same progress point, it began to get the same errors:

5/30/12 4:07:54.000 PM kernel: /SourceCache/AppleFSCompression/AppleFSCompression-37/Compressors/Dataless/compressorType5Kext.c:532: Error: post_request error for /.DocumentRevisions-V100-bad-1/PerUID/501/118/com.apple.documentVersions/10AFD71C-1C15-426A-8156-DD957ADD2A45.m: 35
5/30/12 4:07:54.000 PM kernel: decmpfs.c:1309:decmpfs_read_compressed: decmpfs_fetch_uncompressed_data err -35

Looks identical to me. Could it be a bad file on the source disk (which Verifies as clean)? If so, how to identify what file so I can skip it?

I appreciate any help with this one!

More console detail, will submit as bug

Thanks Mr. Retrofire,

I double checked that the drive partition is HFS+ (OS X extended, case-sensitive, journaled). It is.

I confirmed volume ownership with the terminal command. That worked.

I restarted TM and get the same problem at the same point.

There is some other chatter on the console that I had assumed wasn't related, but it may be. So in the interest of more complete disclosure, here are some other messages. The timestamps are preserved, so you can see the sequence:
5/30/12 4:56:23.370 PM com.apple.backupd: Starting standard backup
5/30/12 4:56:23.475 PM com.apple.backupd: Backing up to: /Volumes/T3/Backups.backupdb
5/30/12 4:58:03.044 PM com.apple.backupd: Backup content size: 455.3 GB excluded items size: 88.3 GB for volume Macintosh HD
5/30/12 4:58:03.318 PM com.apple.backupd: 440.35 GB required (including padding), 2.61 TB available
5/30/12 4:58:03.330 PM com.apple.backupd: Waiting for index to be ready (101)
5/30/12 4:58:15.056 PM com.apple.revisiond: [ERROR] genstore_chunk_interface.m:GSChunkedFilesSatisfyReadRequest:423 no chunk store for fsid 234881030 fileid 209 offset 0 size 65536
5/30/12 4:58:30.057 PM com.apple.revisiond: [ERROR] genstore_chunk_interface.m:GSChunkedFilesSatisfyReadRequest:423 no chunk store for fsid 234881030 fileid 209 offset 65536 size 62045
5/30/12 4:58:30.000 PM kernel: /SourceCache/AppleFSCompression/AppleFSCompression-37/Compressors/Dataless/compressorType5Kext.c:532: Error: post_request error for /Volumes/T3/Backups.backupdb/jbenniMac/2012-05-30-160241.inProgress/85CE1122-6471-4A46-AA6E-A279496FC595/Macintosh HD/.DocumentRevisions-V100-bad-1/PerUID/501/1/com.apple.documentVersions/A6B83243-607F-49F8-B959-0DDE4EA2EAFC.pdf: 35
5/30/12 4:58:30.000 PM kernel: decmpfs.c:1309:decmpfs_read_compressed: decmpfs_fetch_uncompressed_data err -35

... repetitions of similar messages at frequent intervals ...
When I canceled TM (clicked "stop backup" in the progress bar) I got more logging:

5/30/12 5:00:30.128 PM revisiond: send response: Invalid argument
5/30/12 5:00:30.128 PM com.apple.revisiond: [ERROR] 181f1dcb21be [12/05/30 17:00:30.127] 72. _CSChunkRefsForToken:2425 _CSChunkRefsForToken sqlite3_step returned: 101 unknown error, for listToken: 5572
5/30/12 5:00:30.128 PM com.apple.revisiond: [ERROR] genstore_chunk_interface.m:-[GSChunkedFilesEntry updateEntry:]:305 CSCopyChunkIDsForToken failed for 5572
5/30/12 5:00:30.128 PM com.apple.revisiond: [ERROR] genstore_chunk_interface.m:-[GSChunkedFilesEntry _initWithPath:chunkStore:]:326 updateEntry for new entry /.DocumentRevisions-V100-bad-1/PerUID/501/118/com.apple.documentVersions/245A73B8-715A-41C8-AC92-14D37FB20C47.m failed
5/30/12 5:00:30.128 PM com.apple.revisiond: [ERROR] genstore_chunk_interface.m:assembleInfoForOffset:376 no entry for '/.DocumentRevisions-V100-bad-1/PerUID/501/118/com.apple.documentVersions/245A73B8-715A-41C8-AC92-14D37FB20C47.m'
5/30/12 5:00:30.128 PM com.apple.revisiond: [ERROR] genstore_chunk_interface.m:GSChunkedFilesSatisfyReadRequest:439 failed assembleInfoForOffset for fsid 234881026 fileid 118644920 offset 0 size 3391 (path /.DocumentRevisions-V100-bad-1/PerUID/501/118/com.apple.documentVersions/245A73B8-715A-41C8-AC92-14D37FB20C47.m)
5/30/12 5:00:30.129 PM com.apple.backupd: Copied 26 files (147.0 MB) from volume Macintosh HD.
5/30/12 5:00:30.130 PM mds: (Error) Volume: Could not find requested backup type:2 for volume
5/30/12 5:00:30.660 PM com.apple.backupd: Backup canceled.

I assumed the revisiond messages were unrelated, but I'd hate to omit important context.

At this point, I'm stumped and the experts don't seem to recognize anything obviously wrong. So I'd still welcome any and all suggestions, but unless someone sees something soon I'll report it to Apple as a bug and see if they accept it.

Thanks for your response!

Thank you!

wrldwzrd89,

Yes, that appears to work. I hadn't realized that the destination path name included the source path that TM was choking on. I've also learned that it is safe to exclude from TM the entire directory:
/.DocumentRevisions-V100-bad-1/

Apparently if the Document Revisions database becomes corrupt for some unspecified reason, OSX renames it to /.DocumentRevisions-V100-bad (adding a suffix to ensure a unique name).

So my backup is now running, and well past the point where it formerly hung.

Thank you so much!

Resolved - Thank you!

After excluding the offending hidden directory, everything worked just fine.

I completed a backup and will now delete the offending directory (since it's invalid anyway!).

I very much appreciate the astute advice - especially from wrldwzrd89.

Thank you!!