OSError while collecting path leads to EOF

[OlafHaalstra]

When collecting a VM I get the following output:

Collected with: acquire --profile full /path/to/VM.vmx

...
timestamp [INFO ] - Collecting file /var/lib/rpm/Packages to: fs/$rootfs$/var/lib/rpm/Packages
timestamp [ERROR] - OSError while collecting path /var/lib/rpm/Packages (while collecting /var/lib/rpm/Packages)
...
    failure: path:/var/lib/rpm/Packages

There are no more occurrences for the failed path in the .log file.

Subsequently when running the target-* tools over the .tar file I get:

> target-shell hostname_timestamp.tar
...
  File "/usr/lib/python3.9/tarfile.py", line 2321, in next
      raise ReadError("unexpected end of data")
tarfile.ReadError: unexpted end of data
...

Raised from calling dissect/target/target.py via open_all -> _load

Also when running tar tvf or 7z l the file listing stops after listing fs/$rootfs$/var/lib/rpm/Packages.

> tar tvf hostname_timestamp.tar
tar: Unexpected EOF in archive
tar: Error is not recoverable: exiting now

> 7z t hostname_timestamp.tar
...
ERROR: Data Error : fs/$rootfs$/var/lib/rpm/Packages
...

Expected behavior
I would expect a OSError to not cause the archive to get corrupted, acquire actually finishes successfully and even collected many extra files after the error.

[Miauwkeru]

Hello @OlafHaalstra this is certainly an unexpected issue and we will look into it.

This is just me spitballing why the issue occurred, but did you try to acquire a live system? And it was accidentally trying to update its packages right at that moment? cause I can imagine that it trying to acquire a file/folder that "existed" in that path at one point, but doesn't exist anymore could result in an issue.

[Schamper]

@OlafHaalstra can you provide a full stacktrace (ideally from the log file since it includes debug logging) from acquire?

[OlafHaalstra]

This is the part of the logs where the error occurs:

[2025-02-12 17:24:02,612] [DEBUG] <Target /path/to/VM.vmx>: <RootFilesystemEntry '/var/lib/rpm/.dbenv.lock'>::is_symlink()
[2025-02-12 17:24:02,612] [DEBUG] <Target /path/to/VM.vmx>: <RootFilesystemEntry '/var/lib/rpm/.dbenv.lock'>::lstat()
[2025-02-12 17:24:02,613] [INFO ] - Collecting file /var/lib/rpm/.dbenv.lock succeeded
[2025-02-12 17:24:02,613] [DEBUG] - Collecting path /var/lib/rpm/.dbenv.lock succeeded
[2025-02-12 17:24:02,613] [DEBUG] - Collecting path /var/lib/rpm/Packages
[2025-02-12 17:24:02,613] [DEBUG] <Target /path/to/VM.vmx>: <RootFilesystem>::get('/var')
[2025-02-12 17:24:02,614] [DEBUG] <Target /path/to/VM.vmx>: <RootFilesystemEntry '/var'>::readlink()
[2025-02-12 17:24:02,614] [DEBUG] <Target /path/to/VM.vmx>: <RootFilesystemEntry '/var'>::is_symlink()
[2025-02-12 17:24:02,614] [DEBUG] <Target /path/to/VM.vmx>: <RootFilesystem>::get('/var/lib')
[2025-02-12 17:24:02,615] [DEBUG] <Target /path/to/VM.vmx>: <RootFilesystemEntry '/var/lib'>::readlink()
[2025-02-12 17:24:02,616] [DEBUG] <Target /path/to/VM.vmx>: <RootFilesystemEntry '/var/lib'>::is_symlink()
[2025-02-12 17:24:02,616] [DEBUG] <Target /path/to/VM.vmx>: <RootFilesystem>::get('/var/lib/rpm')
[2025-02-12 17:24:02,617] [DEBUG] <Target /path/to/VM.vmx>: <RootFilesystemEntry '/var/lib/rpm'>::readlink()
[2025-02-12 17:24:02,617] [DEBUG] <Target /path/to/VM.vmx>: <RootFilesystemEntry '/var/lib/rpm'>::is_symlink()
[2025-02-12 17:24:02,617] [DEBUG] <Target /path/to/VM.vmx>: <RootFilesystem>::get('/var/lib/rpm/Packages')
[2025-02-12 17:24:02,619] [DEBUG] <Target /path/to/VM.vmx>: <RootFilesystemEntry '/var/lib/rpm/Packages'>::is_dir()
[2025-02-12 17:24:02,619] [DEBUG] <Target /path/to/VM.vmx>: <RootFilesystemEntry '/var/lib/rpm/Packages'>::is_symlink()
[2025-02-12 17:24:02,619] [DEBUG] <Target /path/to/VM.vmx>: <RootFilesystemEntry '/var/lib/rpm/Packages'>::is_file()
[2025-02-12 17:24:02,619] [DEBUG] <Target /path/to/VM.vmx>: <RootFilesystemEntry '/var/lib/rpm/Packages'>::is_symlink()
[2025-02-12 17:24:02,619] [DEBUG] <Target /path/to/VM.vmx>: <RootFilesystemEntry '/var/lib/rpm/Packages'>::is_symlink()
[2025-02-12 17:24:02,619] [DEBUG] <Target /path/to/VM.vmx>: <RootFilesystem>::get('/')
[2025-02-12 17:24:02,619] [DEBUG] <Target /path/to/VM.vmx>: <RootFilesystemEntry '/'>::is_symlink()
[2025-02-12 17:24:02,622] [DEBUG] <Target /path/to/VM.vmx>: <RootFilesystem>::get('/var')
[2025-02-12 17:24:02,623] [DEBUG] <Target /path/to/VM.vmx>: <RootFilesystemEntry '/var'>::is_symlink()
[2025-02-12 17:24:02,623] [DEBUG] <Target /path/to/VM.vmx>: <RootFilesystem>::get('/var/lib')
[2025-02-12 17:24:02,624] [DEBUG] <Target /path/to/VM.vmx>: <RootFilesystemEntry '/var/lib'>::is_symlink()
[2025-02-12 17:24:02,624] [DEBUG] <Target /path/to/VM.vmx>: <RootFilesystem>::get('/var/lib/rpm')
[2025-02-12 17:24:02,625] [DEBUG] <Target /path/to/VM.vmx>: <RootFilesystemEntry '/var/lib/rpm'>::is_symlink()
[2025-02-12 17:24:02,625] [INFO ] - Collecting file /var/lib/rpm/Packages to: fs/$rootfs$/var/lib/rpm/Packages
[2025-02-12 17:24:02,625] [DEBUG] <Target /path/to/VM.vmx>: <RootFilesystemEntry '/var/lib/rpm/Packages'>::is_dir()
[2025-02-12 17:24:02,625] [DEBUG] <Target /path/to/VM.vmx>: <RootFilesystemEntry '/var/lib/rpm/Packages'>::is_symlink()
[2025-02-12 17:24:02,625] [DEBUG] <Target /path/to/VM.vmx>: <RootFilesystemEntry '/var/lib/rpm/Packages'>::is_symlink()
[2025-02-12 17:24:02,625] [DEBUG] <Target /path/to/VM.vmx>: <RootFilesystemEntry '/var/lib/rpm/Packages'>::open()
[2025-02-12 17:24:02,625] [DEBUG] <Target /path/to/VM.vmx>: <RootFilesystemEntry '/var/lib/rpm/Packages'>::is_symlink()
[2025-02-12 17:24:02,668] [DEBUG] <Target /path/to/VM.vmx>: <RootFilesystemEntry '/var/lib/rpm/Packages'>::is_symlink()
[2025-02-12 17:24:02,668] [DEBUG] <Target /path/to/VM.vmx>: <RootFilesystemEntry '/var/lib/rpm/Packages'>::is_dir()
[2025-02-12 17:24:02,668] [DEBUG] <Target /path/to/VM.vmx>: <RootFilesystemEntry '/var/lib/rpm/Packages'>::is_symlink()
[2025-02-12 17:24:02,668] [DEBUG] <Target /path/to/VM.vmx>: <RootFilesystemEntry '/var/lib/rpm/Packages'>::lstat()
[2025-02-12 17:24:19,548] [ERROR] - OSError while collecting path /var/lib/rpm/Packages (while collecting /var/lib/rpm/Packages)
[2025-02-12 17:24:19,548] [DEBUG] - Collecting path /var/lib/rpm/Name
[2025-02-12 17:24:19,548] [DEBUG] <Target /path/to/VM.vmx>: <RootFilesystem>::get('/var')
[2025-02-12 17:24:19,549] [DEBUG] <Target /path/to/VM.vmx>: <RootFilesystemEntry '/var'>::readlink()
[2025-02-12 17:24:19,549] [DEBUG] <Target /path/to/VM.vmx>: <RootFilesystemEntry '/var'>::is_symlink()
[2025-02-12 17:24:19,549] [DEBUG] <Target /path/to/VM.vmx>: <RootFilesystem>::get('/var/lib')

[Schamper]

It's likely something related to #203 that we missed with that PR. What version of acquire did you encounter this with, the latest I assume?

[OlafHaalstra]

I'm using version 3.16, let me upgrade and check again

[OlafHaalstra]

I just upgraded to 3.17 and can confirm that the issue still persists

[OlafHaalstra]

Hello @OlafHaalstra this is certainly an unexpected issue and we will look into it.

This is just me spitballing why the issue occurred, but did you try to acquire a live system? And it was accidentally trying to update its packages right at that moment? cause I can imagine that it trying to acquire a file/folder that "existed" in that path at one point, but doesn't exist anymore could result in an issue.

It is not an acquisition from a live system. Also the behavior is consistent across multiple tries (minutes, hours and even days apart)