search

log2timeline / plaso

Super timeline all the things
https://plaso.readthedocs.io
Apache License 2.0
1.73k stars 348 forks source link

Performance issues on AWS with EBS #3156

Closed siftuser closed 4 years ago

siftuser commented 4 years ago

Description of problem:

continuation from #3151 ...

As suggested updated plaso to latest version. Initially I ran psteal on e01 image of a windows 10 disk (250gb) ... when it was showing 12-15% completion after 12 hours, killed the process & exited. Thought would instead run on a mounted volume. This time plaso auto exited midway after running for ~60 hours. Any suggestion ? Thanks

plaso 2020-07-08 at 9 06 02 AM

Command line and arguments:

psteal.py --source /mnt/windows_mount/ -o l2tcsv -w /data/plaso/l2t.txt

Plaso version:

plaso version 20200630

Operating system Plaso is running on:

ubuntu 18.04

Installation method:

sudo apt-get install python-plaso plaso-tools

joachimmetz commented 4 years ago

Can you provide the logs.

Also see: https://plaso.readthedocs.io/en/latest/sources/user/Troubleshooting.html

siftuser commented 4 years ago

@joachimmetz are you ref to this ? 

2020-07-09 15:41:40,232 [WARNING] (MainProcess) PID:4439 <windows> Unable to map: "@tzres.dll,-592" to time zone
2020-07-09 15:41:40,302 [INFO] (MainProcess) PID:4439 <engine> Preprocessing detected operating systems: Windows NT
2020-07-09 15:41:40,303 [INFO] (MainProcess) PID:4439 <extraction_tool> Parser filter expression set to: win7
2020-07-10 06:25:36,954 [WARNING] (MainProcess) PID:4439 <engine> Process: Worker_02 (PID: 4452) killed because it exceeded the memor
y limit: 2147483648.
2020-07-10 06:25:37,472 [ERROR] (MainProcess) PID:4439 <engine> Process Worker_02 (PID: 4452) is not functioning correctly. Status co
de: killed.
2020-07-10 06:25:37,472 [WARNING] (MainProcess) PID:4439 <engine> Terminating process: (PID: 4452).
2020-07-10 06:25:37,472 [INFO] (MainProcess) PID:4439 <engine> Attempt: 1 to start replacement worker process for Worker_02
2020-07-10 06:49:26,814 [WARNING] (MainProcess) PID:4439 <engine> Process: Worker_01 (PID: 4450) killed because it exceeded the memor
y limit: 2147483648.
2020-07-10 06:49:27,352 [ERROR] (MainProcess) PID:4439 <engine> Process Worker_01 (PID: 4450) is not functioning correctly. Status co
de: killed.
2020-07-10 06:49:27,353 [WARNING] (MainProcess) PID:4439 <engine> Terminating process: (PID: 4450).
2020-07-10 06:49:27,353 [INFO] (MainProcess) PID:4439 <engine> Attempt: 1 to start replacement worker process for Worker_01
2020-07-10 13:18:05,374 [WARNING] (MainProcess) PID:4439 <engine> Process: Worker_00 (PID: 4448) killed because it exceeded the memor
y limit: 2147483648.
2020-07-10 13:18:05,913 [ERROR] (MainProcess) PID:4439 <engine> Process Worker_00 (PID: 4448) is not functioning correctly. Status co
de: killed.
2020-07-10 13:18:05,913 [WARNING] (MainProcess) PID:4439 <engine> Terminating process: (PID: 4448).
2020-07-10 13:18:05,913 [INFO] (MainProcess) PID:4439 <engine> Attempt: 1 to start replacement worker process for Worker_00
2020-07-10 22:02:15,315 [WARNING] (MainProcess) PID:4439 <engine> Process: Worker_04 (PID: 8233) killed because it exceeded the memor
y limit: 2147483648.
2020-07-10 22:02:15,903 [WARNING] (MainProcess) PID:4439 <plaso_xmlrpc> Unable to make RPC call with error: [Errno 111] Connection re
fused
2020-07-10 22:02:15,904 [ERROR] (MainProcess) PID:4439 <engine> Process Worker_04 (PID: 8233) is not functioning correctly. Status co
de: killed.
2020-07-10 22:02:15,904 [WARNING] (MainProcess) PID:4439 <engine> Terminating process: (PID: 8233).
2020-07-10 22:02:15,904 [INFO] (MainProcess) PID:4439 <engine> Attempt: 1 to start replacement worker process for Worker_04
2020-07-10 23:55:46,812 [WARNING] (MainProcess) PID:4439 <engine> Process: Worker_03 (PID: 8079) killed because it exceeded the memor
y limit: 2147483648.
2020-07-10 23:55:47,335 [ERROR] (MainProcess) PID:4439 <engine> Process Worker_03 (PID: 8079) is not functioning correctly. Status co
de: killed.
2020-07-10 23:55:47,335 [WARNING] (MainProcess) PID:4439 <engine> Terminating process: (PID: 8079).
2020-07-10 23:55:47,335 [INFO] (MainProcess) PID:4439 <engine> Attempt: 1 to start replacement worker process for Worker_03
2020-07-11 07:19:03,678 [WARNING] (MainProcess) PID:4439 <engine> Process: Worker_05 (PID: 10435) killed because it exceeded the memo
ry limit: 2147483648.
2020-07-11 07:19:04,261 [WARNING] (MainProcess) PID:4439 <plaso_xmlrpc> Unable to make RPC call with error: [Errno 111] Connection re
fused
2020-07-11 07:19:04,261 [ERROR] (MainProcess) PID:4439 <engine> Process Worker_05 (PID: 10435) is not functioning correctly. Status c
ode: killed.
2020-07-11 07:19:04,262 [WARNING] (MainProcess) PID:4439 <engine> Terminating process: (PID: 10435).
2020-07-11 07:19:04,262 [INFO] (MainProcess) PID:4439 <engine> Attempt: 1 to start replacement worker process for Worker_05
2020-07-11 21:05:42,548 [WARNING] (MainProcess) PID:4439 <engine> Process: Worker_06 (PID: 11625) killed because it exceeded the memo
ry limit: 2147483648.
2020-07-11 21:05:43,059 [ERROR] (MainProcess) PID:4439 <engine> Process Worker_06 (PID: 11625) is not functioning correctly. Status c
ode: killed.
2020-07-11 21:05:43,059 [WARNING] (MainProcess) PID:4439 <engine> Terminating process: (PID: 11625).
2020-07-11 21:05:43,060 [INFO] (MainProcess) PID:4439 <engine> Attempt: 1 to start replacement worker process for Worker_06
2020-07-11 21:50:42,450 [WARNING] (MainProcess) PID:4439 <engine> Process: Worker_07 (PID: 11862) killed because it exceeded the memo
ry limit: 2147483648.
2020-07-11 21:50:42,957 [ERROR] (MainProcess) PID:4439 <engine> Process Worker_07 (PID: 11862) is not functioning correctly. Status c
ode: killed.
2020-07-11 21:50:42,957 [WARNING] (MainProcess) PID:4439 <engine> Terminating process: (PID: 11862).
2020-07-11 21:50:42,958 [INFO] (MainProcess) PID:4439 <engine> Attempt: 1 to start replacement worker process for Worker_07
2020-07-12 00:51:09,414 [WARNING] (MainProcess) PID:4439 <engine> Process: Worker_08 (PID: 14438) killed because it exceeded the memo
ry limit: 2147483648.
2020-07-12 00:51:10,179 [WARNING] (MainProcess) PID:4439 <plaso_xmlrpc> Unable to make RPC call with error: [Errno 111] Connection re
fused
2020-07-12 00:51:10,180 [ERROR] (MainProcess) PID:4439 <engine> Process Worker_08 (PID: 14438) is not functioning correctly. Status c
ode: killed.
2020-07-12 00:51:10,180 [WARNING] (MainProcess) PID:4439 <engine> Terminating process: (PID: 14438).
2020-07-12 00:51:10,181 [INFO] (MainProcess) PID:4439 <engine> Attempt: 1 to start replacement worker process for Worker_08
2020-07-12 11:52:56,073 [WARNING] (MainProcess) PID:4439 <engine> Process: Worker_10 (PID: 19218) killed because it exceeded the memo
ry limit: 2147483648.
2020-07-12 11:52:56,693 [WARNING] (MainProcess) PID:4439 <plaso_xmlrpc> Unable to make RPC call with error: [Errno 111] Connection re
fused
2020-07-12 11:52:56,694 [ERROR] (MainProcess) PID:4439 <engine> Process Worker_10 (PID: 19218) is not functioning correctly. Status c
ode: killed.
2020-07-12 11:52:56,694 [WARNING] (MainProcess) PID:4439 <engine> Terminating process: (PID: 19218).
2020-07-12 11:52:56,694 [INFO] (MainProcess) PID:4439 <engine> Attempt: 1 to start replacement worker process for Worker_10
2020-07-12 12:05:20,100 [WARNING] (MainProcess) PID:4439 <engine> Process: Worker_09 (PID: 19119) killed because it exceeded the memo
ry limit: 2147483648.
2020-07-12 12:05:20,608 [ERROR] (MainProcess) PID:4439 <engine> Process Worker_09 (PID: 19119) is not functioning correctly. Status c
ode: killed.
2020-07-12 12:05:20,608 [WARNING] (MainProcess) PID:4439 <engine> Terminating process: (PID: 19119).
2020-07-12 12:05:20,608 [INFO] (MainProcess) PID:4439 <engine> Attempt: 1 to start replacement worker process for Worker_09
2020-07-12 18:18:21,338 [WARNING] (MainProcess) PID:4439 <engine> Process: Worker_11 (PID: 19592) killed because it exceeded the memo
ry limit: 2147483648.
2020-07-12 18:18:22,026 [WARNING] (MainProcess) PID:4439 <plaso_xmlrpc> Unable to make RPC call with error: [Errno 111] Connection re
fused
2020-07-12 18:18:22,027 [ERROR] (MainProcess) PID:4439 <engine> Process Worker_11 (PID: 19592) is not functioning correctly. Status c
ode: killed.
2020-07-12 18:18:22,027 [WARNING] (MainProcess) PID:4439 <engine> Terminating process: (PID: 19592).
2020-07-12 18:18:22,027 [INFO] (MainProcess) PID:4439 <engine> Attempt: 1 to start replacement worker process for Worker_11
joachimmetz commented 4 years ago

@siftuser yes that is the logs of the main process

2020-07-10 06:25:36,954 [WARNING] (MainProcess) PID:4439 Process: Worker_02 (PID: 4452) killed because it exceeded the memory limit: 2147483648.

indicates a worker is consuming more memory than allowed

there should also be corresponding logs of the workers e.g. Worker_02*.log.gz

anything in those that indicates why the worker is requiring that much memory?

joachimmetz commented 4 years ago

@siftuser also anything at the end of the log of the main process that indicates why psteal exited?

siftuser commented 4 years ago

Thanks @joachimmetz ... this was from psteal-dateTtime.log.gz I dont see any files w/ worker logs as you indicated

siftuser commented 4 years ago

@siftuser also anything at the end of the log of the main process that indicates why psteal exited?

Nope ... I shared entire file

siftuser commented 4 years ago

I'm planning to run it again ... do you suggest to add any other flags/switches in the command line psteal.py --source /e01/file.e01 -o l2tcsv -w /data/plaso/l2t.txt

joachimmetz commented 4 years ago

I dont see any files w/ worker logs as you indicated

that's annoying they might not have been created then. I'll double check what the default behavior of psteal is regarding creating worker logs.

do you suggest to add any other flags/switches in the command line

Please add -d for debug output.

@siftuser also anything at the end of the log of the main process that indicates why psteal exited?

Nope ... I shared entire file

Anything in the system logs that might indicate the process was killed for some reason?

siftuser commented 4 years ago

Anything in the system logs that might indicate the process was killed for some reason?

sorry ... I dont see anything relevant

siftuser commented 4 years ago

@joachimmetz , restarted the process with -d. Seeing similar response, but this time it continues to run without exiting for past 2 days. Is there a way to force exit & retain data analyzed so far ? Please let me know, if you need more data. Thanks

hung plaso

zcat Worker_16_psteal-20200713T164651.log.gz | tail

2020-07-17 23:50:53,185 [DEBUG] (Worker_16 ) PID:31154 <extractors> winfirewall unable to parse file: NTFS:\Users\LocalAdmin\AppData\Local\SquirrelTemp\tempa\lib\net45\resources\app.asar.unpacked\node_modules\@slack\slack-calls-prebuilt\modules\@slack\slack-calls\build\Release\slack-calls.node.shasum with error: Not a text file or encoding not supported.
2020-07-17 23:50:53,185 [DEBUG] (Worker_16 ) PID:31154 <extractors> [ParseFileEntryWithParsers] parsing file: NTFS:\Users\LocalAdmin\AppData\Local\SquirrelTemp\tempa\lib\net45\resources\app.asar.unpacked\node_modules\@slack\slack-calls-prebuilt\modules\@slack\slack-calls\build\Release\slack-calls.node.shasum with parser: winjob
2020-07-17 23:50:53,186 [DEBUG] (Worker_16 ) PID:31154 <extractors> winjob unable to parse file: NTFS:\Users\LocalAdmin\AppData\Local\SquirrelTemp\tempa\lib\net45\resources\app.asar.unpacked\node_modules\@slack\slack-calls-prebuilt\modules\@slack\slack-calls\build\Release\slack-calls.node.shasum with error: Unsupported product version in: 0xbbef
2020-07-17 23:50:53,186 [DEBUG] (Worker_16 ) PID:31154 <worker> [ProcessFileEntry] done processing file entry: NTFS:\Users\LocalAdmin\AppData\Local\SquirrelTemp\tempa\lib\net45\resources\app.asar.unpacked\node_modules\@slack\slack-calls-prebuilt\modules\@slack\slack-calls\build\Release\slack-calls.node.shasum
2020-07-17 23:50:53,305 [DEBUG] (Worker_16 ) PID:31154 <worker_process> Completed processing task: b20e065aeab6459485d752d15371b9fa.
2020-07-17 23:50:53,306 [DEBUG] (Worker_16 ) PID:31154 <zeromq_queue> Pop on Worker_16 task queue queue, port 43917

zcat Worker_15_psteal-20200713T164651.log.gz | tail

2020-07-17 23:50:52,938 [DEBUG] (Worker_15 ) PID:28223 <extractors> winjob unable to parse file: NTFS:\Users\LocalAdmin\AppData\Local\SquirrelTemp\tempa\lib\net45\resources\app.asar.unpacked\node_modules\@slack\slack-calls-prebuilt\modules\@slack\slack-calls\build\Release\slack-calls.node.diff with error: Unsupported product version in: 0x4150
2020-07-17 23:50:52,939 [DEBUG] (Worker_15 ) PID:28223 <worker> [ProcessFileEntry] done processing file entry: NTFS:\Users\LocalAdmin\AppData\Local\SquirrelTemp\tempa\lib\net45\resources\app.asar.unpacked\node_modules\@slack\slack-calls-prebuilt\modules\@slack\slack-calls\build\Release\slack-calls.node.diff
2020-07-17 23:50:53,062 [DEBUG] (Worker_15 ) PID:28223 <worker_process> Completed processing task: 169e84477f124a2b8c9d444027642824.
2020-07-17 23:50:53,062 [DEBUG] (Worker_15 ) PID:28223 <zeromq_queue> Pop on Worker_15 task queue queue, port 43917
joachimmetz commented 4 years ago

@siftuser what are the last 15 log lines of the log file of one of the killed workers? e.g. Worker_00

siftuser commented 4 years ago

Thank you @joachimmetz ! please see couple of samples as follows ...

zcat Worker_02_psteal-20200713T164651.log.gz | tail -15

2020-07-14 13:35:18,656 [DEBUG] (Worker_02 ) PID:4388 <worker> [AnalyzeDataStream] completed analyzing file: NTFS:\Windows\WinSxS\wow64_microsoft-windows-errorreportingfaults_31bf3856ad364e35_10.0.19041.329_none_586daadecfe67780\Faultrep.dll
2020-07-14 13:35:18,656 [DEBUG] (Worker_02 ) PID:4388 <worker> [ExtractMetadataFromFileEntry] processing file entry: NTFS:\Windows\WinSxS\wow64_microsoft-windows-errorreportingfaults_31bf3856ad364e35_10.0.19041.329_none_586daadecfe67780\Faultrep.dll
2020-07-14 13:35:18,658 [DEBUG] (Worker_02 ) PID:4388 <extractors> [ParseFileEntryWithParsers] parsing file: NTFS:\Windows\WinSxS\wow64_microsoft-windows-errorreportingfaults_31bf3856ad364e35_10.0.19041.329_none_586daadecfe67780\Faultrep.dll with parser: pe
2020-07-14 13:35:18,788 [DEBUG] (Worker_02 ) PID:4388 <worker> [ProcessFileEntry] done processing file entry: NTFS:\Windows\WinSxS\wow64_microsoft-windows-errorreportingfaults_31bf3856ad364e35_10.0.19041.329_none_586daadecfe67780\Faultrep.dll
2020-07-14 13:35:18,916 [DEBUG] (Worker_02 ) PID:4388 <worker_process> Completed processing task: 9b6957dbdd374c80947dff3206be9d05.
2020-07-14 13:35:18,916 [DEBUG] (Worker_02 ) PID:4388 <zeromq_queue> Pop on Worker_02 task queue queue, port 43917
2020-07-14 13:35:18,917 [DEBUG] (Worker_02 ) PID:4388 <worker_process> Started processing task: 0e726741daaa4aa89082cb23bd6d9c9e.
2020-07-14 13:35:19,370 [DEBUG] (Worker_02 ) PID:4388 <worker> [ProcessFileEntry] processing file entry: NTFS:\Windows\WinSxS\wow64_microsoft-windows-errorreportingfaults_31bf3856ad364e35_10.0.19041.329_none_586daadecfe67780\WerFault.exe
2020-07-14 13:35:19,370 [DEBUG] (Worker_02 ) PID:4388 <worker> [ProcessFileEntryDataStream] processing data stream: "" of file entry: NTFS:\Windows\WinSxS\wow64_microsoft-windows-errorreportingfaults_31bf3856ad364e35_10.0.19041.329_none_586daadecfe67780\WerFault.exe
2020-07-14 13:35:19,370 [DEBUG] (Worker_02 ) PID:4388 <worker> [AnalyzeDataStream] analyzing file: NTFS:\Windows\WinSxS\wow64_microsoft-windows-errorreportingfaults_31bf3856ad364e35_10.0.19041.329_none_586daadecfe67780\WerFault.exe
2020-07-14 13:35:19,380 [DEBUG] (Worker_02 ) PID:4388 <hashing_analyzer> Processing results for hasher sha256
2020-07-14 13:35:19,381 [DEBUG] (Worker_02 ) PID:4388 <worker> [AnalyzeFileObject] attribute sha256_hash:23e2b8dc4b1327ed034ffcf7b04c6f52558271339a52b46d9968d7950dadc160 calculated for file: NTFS:\Windows\WinSxS\wow64_microsoft-windows-errorreportingfaults_31bf3856ad364e35_10.0.19041.329_none_586daadecfe67780\WerFault.exe.
2020-07-14 13:35:19,381 [DEBUG] (Worker_02 ) PID:4388 <worker> [AnalyzeDataStream] completed analyzing file: NTFS:\Windows\WinSxS\wow64_microsoft-windows-errorreportingfaults_31bf3856ad364e35_10.0.19041.329_none_586daadecfe67780\WerFault.exe
2020-07-14 13:35:19,381 [DEBUG] (Worker_02 ) PID:4388 <worker> [ExtractMetadataFromFileEntry] processing file entry: NTFS:\Windows\WinSxS\wow64_microsoft-windows-errorreportingfaults_31bf3856ad364e35_10.0.19041.329_none_586daadecfe67780\WerFault.exe
2020-07-14 13:35:19,383 [DEBUG] (Worker_02 ) PID:4388 <extractors> [ParseFileEntryWithParsers] parsing file: NTFS:\Windows\WinSxS\wow64_microsoft-windows-errorreportingfaults_31bf3856ad364e35_10.0.19041.329_none_586daadecfe67780\WerFault.exe with parser: pe

zcat Worker_12_psteal-20200713T164651.log.gz | tail -15

2020-07-17 05:54:06,661 [DEBUG] (Worker_12 ) PID:24459 <worker> [ProcessFileEntry] processing file entry: NTFS:\Windows.old\WINDOWS\SoftwareDistribution\Download\806e76e03f9c647629f4299158a902b6\amd64_Microsoft-Windows-EditionPack-Professional-Package~~amd64~~10.0.19041.1\amd64_microsoft-windows-s..isioningservice-wmi_31bf3856ad364e35_10.0.19041.1_none_a324694506479d47\mspsservice.dll
2020-07-17 05:54:06,661 [DEBUG] (Worker_12 ) PID:24459 <worker> [ProcessFileEntryDataStream] processing data stream: "" of file entry: NTFS:\Windows.old\WINDOWS\SoftwareDistribution\Download\806e76e03f9c647629f4299158a902b6\amd64_Microsoft-Windows-EditionPack-Professional-Package~~amd64~~10.0.19041.1\amd64_microsoft-windows-s..isioningservice-wmi_31bf3856ad364e35_10.0.19041.1_none_a324694506479d47\mspsservice.dll
2020-07-17 05:54:06,662 [DEBUG] (Worker_12 ) PID:24459 <worker> [AnalyzeDataStream] analyzing file: NTFS:\Windows.old\WINDOWS\SoftwareDistribution\Download\806e76e03f9c647629f4299158a902b6\amd64_Microsoft-Windows-EditionPack-Professional-Package~~amd64~~10.0.19041.1\amd64_microsoft-windows-s..isioningservice-wmi_31bf3856ad364e35_10.0.19041.1_none_a324694506479d47\mspsservice.dll
2020-07-17 05:54:06,686 [DEBUG] (Worker_12 ) PID:24459 <hashing_analyzer> Processing results for hasher sha256
2020-07-17 05:54:06,686 [DEBUG] (Worker_12 ) PID:24459 <worker> [AnalyzeFileObject] attribute sha256_hash:f9dd112f6758f2b56d5fc9f8915269fd945cb5acdd4eb9e8e9ecfce9d6ac9d02 calculated for file: NTFS:\Windows.old\WINDOWS\SoftwareDistribution\Download\806e76e03f9c647629f4299158a902b6\amd64_Microsoft-Windows-EditionPack-Professional-Package~~amd64~~10.0.19041.1\amd64_microsoft-windows-s..isioningservice-wmi_31bf3856ad364e35_10.0.19041.1_none_a324694506479d47\mspsservice.dll.
2020-07-17 05:54:06,686 [DEBUG] (Worker_12 ) PID:24459 <worker> [AnalyzeDataStream] completed analyzing file: NTFS:\Windows.old\WINDOWS\SoftwareDistribution\Download\806e76e03f9c647629f4299158a902b6\amd64_Microsoft-Windows-EditionPack-Professional-Package~~amd64~~10.0.19041.1\amd64_microsoft-windows-s..isioningservice-wmi_31bf3856ad364e35_10.0.19041.1_none_a324694506479d47\mspsservice.dll
2020-07-17 05:54:06,687 [DEBUG] (Worker_12 ) PID:24459 <worker> [ExtractMetadataFromFileEntry] processing file entry: NTFS:\Windows.old\WINDOWS\SoftwareDistribution\Download\806e76e03f9c647629f4299158a902b6\amd64_Microsoft-Windows-EditionPack-Professional-Package~~amd64~~10.0.19041.1\amd64_microsoft-windows-s..isioningservice-wmi_31bf3856ad364e35_10.0.19041.1_none_a324694506479d47\mspsservice.dll
2020-07-17 05:54:06,701 [DEBUG] (Worker_12 ) PID:24459 <extractors> [ParseFileEntryWithParsers] parsing file: NTFS:\Windows.old\WINDOWS\SoftwareDistribution\Download\806e76e03f9c647629f4299158a902b6\amd64_Microsoft-Windows-EditionPack-Professional-Package~~amd64~~10.0.19041.1\amd64_microsoft-windows-s..isioningservice-wmi_31bf3856ad364e35_10.0.19041.1_none_a324694506479d47\mspsservice.dll with parser: pe
2020-07-17 05:54:06,835 [DEBUG] (Worker_12 ) PID:24459 <worker> [ProcessFileEntry] done processing file entry: NTFS:\Windows.old\WINDOWS\SoftwareDistribution\Download\806e76e03f9c647629f4299158a902b6\amd64_Microsoft-Windows-EditionPack-Professional-Package~~amd64~~10.0.19041.1\amd64_microsoft-windows-s..isioningservice-wmi_31bf3856ad364e35_10.0.19041.1_none_a324694506479d47\mspsservice.dll
2020-07-17 05:54:07,300 [DEBUG] (Worker_12 ) PID:24459 <worker_process> Completed processing task: e464d7068e3f4b018f31d58c688c9a49.
2020-07-17 05:54:07,302 [DEBUG] (Worker_12 ) PID:24459 <zeromq_queue> Pop on Worker_12 task queue queue, port 43917
2020-07-17 05:54:07,321 [DEBUG] (Worker_12 ) PID:24459 <worker_process> Started processing task: 68e479a57e3547c8864e9ef42ce83ee0.
2020-07-17 05:54:09,032 [DEBUG] (Worker_12 ) PID:24459 <worker> [ProcessFileEntry] processing file entry: NTFS:\Windows.old\WINDOWS\SoftwareDistribution\Download\806e76e03f9c647629f4299158a902b6\amd64_Microsoft-Windows-EditionPack-Professional-Package~~amd64~~10.0.19041.1\amd64_microsoft-windows-s..isioningservice-wmi_31bf3856ad364e35_10.0.19041.1_none_a324694506479d47\mspsservice_uninstall.mof
2020-07-17 05:54:09,032 [DEBUG] (Worker_12 ) PID:24459 <worker> [ProcessFileEntryDataStream] processing data stream: "" of file entry: NTFS:\Windows.old\WINDOWS\SoftwareDistribution\Download\806e76e03f9c647629f4299158a902b6\amd64_Microsoft-Windows-EditionPack-Professional-Package~~amd64~~10.0.19041.1\amd64_microsoft-windows-s..isioningservice-wmi_31bf3856ad364e35_10.0.19041.1_none_a324694506479d47\mspsservice_uninstall.mof
2020-07-17 05:54:09,032 [DEBUG] (Worker_12 ) PID:24459 <worker> [AnalyzeDataStream] analyzing file: NTFS:\Windows.old\WINDOWS\SoftwareDistribution\Download\806e76e03f9c647629f4299158a902b6\amd64_Microsoft-Windows-EditionPack-Professional-Package~~amd64~~10.0.19041.1\amd64_microsoft-windows-s..isioningservice-wmi_31bf3856ad364e35_10.0.19041.1_none_a324694506479d47\mspsservice_uninstall.mof
joachimmetz commented 4 years ago

Based on: 2020-07-14 13:35:19,383 [DEBUG] (Worker_02 ) PID:4388 <extractors> [ParseFileEntryWithParsers] parsing file: NTFS:\Windows\WinSxS\wow64_microsoft-windows-errorreportingfaults_31bf3856ad364e35_10.0.19041.329_none_586daadecfe67780\WerFault.exe with parser: pe

And previous log messages of the main (foreman) process it would hint that the pe parser would be consuming too much memory.

@siftuser could you

siftuser commented 4 years ago
  • post the last 15 lines of the logs of the other killed workers as well

@joachimmetz these 2 are killed workers ... am I missing something ?

I shall share other data you suggested

siftuser commented 4 years ago
  • provide a copy of the output of log2timeline.py --troubles

$ log2timeline.py --troubles 2020-07-20 06:51:51,448 [INFO] (MainProcess) PID:6677 Determined data location: /usr/share/plaso Using Python version 3.6.9 (default, Apr 18 2020, 01:56:04) [GCC 8.4.0]

Path: /usr/bin/log2timeline.py

plaso - log2timeline version 20200630

Checking availability and versions of dependencies. [OK] artifacts version: 20200515 [OK] bencode [OK] biplist [OK] certifi version: 2020.06.20 [OK] chardet version: 3.0.4 [OK] cryptography version: 2.9.2 [OK] dateutil version: 2.8.1 [OK] defusedxml version: 0.6.0 [OK] dfdatetime version: 20200613 [OK] dfvfs version: 20200625 [OK] dfwinreg version: 20200415 [OK] dtfabric version: 20200621 [OK] elasticsearch version: 7.8.0 [OK] future version: 0.18.2 [OK] idna version: 2.9 [OK] lz4 [OK] pefile version: 2019.4.18 [OK] psutil version: 5.7.0 [OK] pybde version: 20191221 [OK] pyesedb version: 20200418 [OK] pyevt version: 20200418 [OK] pyevtx version: 20200419 [OK] pyewf version: 20140808 [OK] pyfsapfs version: 20200416 [OK] pyfsntfs version: 20200627 [OK] pyfvde version: 20200101 [OK] pyfwnt version: 20200605 [OK] pyfwsi version: 20191221 [OK] pylnk version: 20191221 [OK] pyluksde version: 20200205 [OK] pymsiecf version: 20191221 [OK] pyolecf version: 20191221 [OK] pyparsing version: 2.4.7 [OK] pyqcow version: 20191221 [OK] pyregf version: 20200429 [OK] pyscca version: 20191222 [OK] pysigscan version: 20191221 [OK] pysmdev version: 20200210 [OK] pysmraw version: 20191221 [OK] pytsk3 version: 20200117 [OK] pytz [OK] pyvhdi version: 20191221 [OK] pyvmdk version: 20191221 [OK] pyvshadow version: 20191221 [OK] pyvslvm version: 20200102 [OK] redis version: 3.5.3 [OK] requests version: 2.24.0 [OK] six version: 1.15.0 [OK] urllib3 version: 1.25.9 [OK] xlsxwriter version: 1.2.9 [OK] yaml version: 3.12 [OK] yara version: 4.0.2 [OK] zmq version: 19.0.1

joachimmetz commented 4 years ago

I shall share other data you suggested

@siftuser thx

@joachimmetz these 2 are killed workers ... am I missing something ?

I mean the logs of the other killed workers Worker 00 , 01, 03 - 11 to see if pe is the last parser in more places

siftuser commented 4 years ago

@joachimmetz Please see addl data attached as suggested. FYI - I had to force exit this session. Now running another image, that too is exhibiting similar behaviour. Running for over 60 hours w/ 66% completion

It's running on aws t2.xlarge (4 vcpu, 16gb ram) Would you recommend specs for improving perf ? Thanks!

zcat Worker_00_psteal-20200713T164651.log.gz | tail -15

gzip: Worker_00_psteal-20200713T164651.log.gz: unexpected end of file
2020-07-14 13:44:46,990 [DEBUG] (Worker_00 ) PID:4384 <worker> [ProcessFileEntry] processing file entry: NTFS:\Windows\WinSxS\wow64_microsoft-windows-ie-htmlrendering_31bf3856ad364e35_11.0.19041.264_none_3f3171c3dee02d36\edgehtml.dll
2020-07-14 13:44:46,990 [DEBUG] (Worker_00 ) PID:4384 <worker> [ProcessFileEntryDataStream] processing data stream: "" of file entry: NTFS:\Windows\WinSxS\wow64_microsoft-windows-ie-htmlrendering_31bf3856ad364e35_11.0.19041.264_none_3f3171c3dee02d36\edgehtml.dll
2020-07-14 13:44:46,990 [DEBUG] (Worker_00 ) PID:4384 <worker> [AnalyzeDataStream] analyzing file: NTFS:\Windows\WinSxS\wow64_microsoft-windows-ie-htmlrendering_31bf3856ad364e35_11.0.19041.264_none_3f3171c3dee02d36\edgehtml.dll
2020-07-14 13:44:47,840 [DEBUG] (Worker_00 ) PID:4384 <hashing_analyzer> Processing results for hasher sha256
2020-07-14 13:44:47,840 [DEBUG] (Worker_00 ) PID:4384 <worker> [AnalyzeFileObject] attribute sha256_hash:bc05ee3d53ec271c10615a2946df58850c89ba02222bd04d688800d2bd34a545 calculated for file: NTFS:\Windows\WinSxS\wow64_microsoft-windows-ie-htmlrendering_31bf3856ad364e35_11.0.19041.264_none_3f3171c3dee02d36\edgehtml.dll.
2020-07-14 13:44:47,840 [DEBUG] (Worker_00 ) PID:4384 <worker> [AnalyzeDataStream] completed analyzing file: NTFS:\Windows\WinSxS\wow64_microsoft-windows-ie-htmlrendering_31bf3856ad364e35_11.0.19041.264_none_3f3171c3dee02d36\edgehtml.dll
2020-07-14 13:44:47,841 [DEBUG] (Worker_00 ) PID:4384 <worker> [ExtractMetadataFromFileEntry] processing file entry: NTFS:\Windows\WinSxS\wow64_microsoft-windows-ie-htmlrendering_31bf3856ad364e35_11.0.19041.264_none_3f3171c3dee02d36\edgehtml.dll
2020-07-14 13:44:47,859 [DEBUG] (Worker_00 ) PID:4384 <extractors> [ParseFileEntryWithParsers] parsing file: NTFS:\Windows\WinSxS\wow64_microsoft-windows-ie-htmlrendering_31bf3856ad364e35_11.0.19041.264_none_3f3171c3dee02d36\edgehtml.dll with parser: pe
2020-07-14 13:44:50,297 [DEBUG] (Worker_00 ) PID:4384 <worker> [ProcessFileEntry] done processing file entry: NTFS:\Windows\WinSxS\wow64_microsoft-windows-ie-htmlrendering_31bf3856ad364e35_11.0.19041.264_none_3f3171c3dee02d36\edgehtml.dll
2020-07-14 13:44:50,892 [DEBUG] (Worker_00 ) PID:4384 <worker_process> Completed processing task: 151172c6e7c149a3bb92e9b104735479.
2020-07-14 13:44:50,894 [DEBUG] (Worker_00 ) PID:4384 <zeromq_queue> Pop on Worker_00 task queue queue, port 43917
2020-07-14 13:44:50,923 [DEBUG] (Worker_00 ) PID:4384 <worker_process> Started processing task: 91ecf70ed4724a1981357123064a39d3.
2020-07-14 13:44:53,185 [DEBUG] (Worker_00 ) PID:4384 <worker> [ProcessFileEntry] processing file entry: NTFS:\Windows\WinSxS\wow64_microsoft-windows-ie-htmlrendering_31bf3856ad364e35_11.0.19041.329_none_3f61b4cbdebb394c\edgehtml.dll
2020-07-14 13:44:53,186 [DEBUG] (Worker_00 ) PID:4384 <worker> [ProcessFileEntryDataStream] processing data stream: "" of file entry: NTFS:\Windows\WinSxS\wow64_microsoft-windows-ie-htmlrendering_31bf3856ad364e35_11.0.19041.329_none_3f61b4cbdebb394c\edgehtml.dll
2020-07-14 13:44:53,186 [DEBUG] (Worker_00 ) PID:4384 <worker> [AnalyzeDataStream] analyzing file: NTFS:\Windows\WinSxS\wow64_microsoft-windows-ie-htmlrendering_31bf3856ad364e35_11.0.19041.329_none_3f61b4cbdebb394c\edgehtml.dll
zcat Worker_01_psteal-20200713T164651.log.gz | tail -15

gzip: Worker_01_psteal-20200713T164651.log.gz: unexpected end of file
2020-07-14 13:30:30,441 [DEBUG] (Worker_01 ) PID:4386 <worker> [ProcessFileEntry] processing file entry: NTFS:\Windows\WinSxS\wow64_microsoft-windows-d..s-sysprep.resources_31bf3856ad364e35_10.0.19041.1_en-us_5dd7b66aa6dfd9cb\SysprepProvider.dll.mui
2020-07-14 13:30:30,441 [DEBUG] (Worker_01 ) PID:4386 <worker> [ProcessFileEntryDataStream] processing data stream: "" of file entry: NTFS:\Windows\WinSxS\wow64_microsoft-windows-d..s-sysprep.resources_31bf3856ad364e35_10.0.19041.1_en-us_5dd7b66aa6dfd9cb\SysprepProvider.dll.mui
2020-07-14 13:30:30,442 [DEBUG] (Worker_01 ) PID:4386 <worker> [AnalyzeDataStream] analyzing file: NTFS:\Windows\WinSxS\wow64_microsoft-windows-d..s-sysprep.resources_31bf3856ad364e35_10.0.19041.1_en-us_5dd7b66aa6dfd9cb\SysprepProvider.dll.mui
2020-07-14 13:30:30,448 [DEBUG] (Worker_01 ) PID:4386 <hashing_analyzer> Processing results for hasher sha256
2020-07-14 13:30:30,448 [DEBUG] (Worker_01 ) PID:4386 <worker> [AnalyzeFileObject] attribute sha256_hash:4389362a9dc662aa3c7a1d830498472bc586e00f0d269a8541975a34b03a1aa4 calculated for file: NTFS:\Windows\WinSxS\wow64_microsoft-windows-d..s-sysprep.resources_31bf3856ad364e35_10.0.19041.1_en-us_5dd7b66aa6dfd9cb\SysprepProvider.dll.mui.
2020-07-14 13:30:30,448 [DEBUG] (Worker_01 ) PID:4386 <worker> [AnalyzeDataStream] completed analyzing file: NTFS:\Windows\WinSxS\wow64_microsoft-windows-d..s-sysprep.resources_31bf3856ad364e35_10.0.19041.1_en-us_5dd7b66aa6dfd9cb\SysprepProvider.dll.mui
2020-07-14 13:30:30,448 [DEBUG] (Worker_01 ) PID:4386 <worker> [ExtractMetadataFromFileEntry] processing file entry: NTFS:\Windows\WinSxS\wow64_microsoft-windows-d..s-sysprep.resources_31bf3856ad364e35_10.0.19041.1_en-us_5dd7b66aa6dfd9cb\SysprepProvider.dll.mui
2020-07-14 13:30:30,451 [DEBUG] (Worker_01 ) PID:4386 <extractors> [ParseFileEntryWithParsers] parsing file: NTFS:\Windows\WinSxS\wow64_microsoft-windows-d..s-sysprep.resources_31bf3856ad364e35_10.0.19041.1_en-us_5dd7b66aa6dfd9cb\SysprepProvider.dll.mui with parser: pe
2020-07-14 13:30:30,455 [DEBUG] (Worker_01 ) PID:4386 <worker> [ProcessFileEntry] done processing file entry: NTFS:\Windows\WinSxS\wow64_microsoft-windows-d..s-sysprep.resources_31bf3856ad364e35_10.0.19041.1_en-us_5dd7b66aa6dfd9cb\SysprepProvider.dll.mui
2020-07-14 13:30:30,585 [DEBUG] (Worker_01 ) PID:4386 <worker_process> Completed processing task: a76fe0a9e1694544bba30e0d81d5471a.
2020-07-14 13:30:30,586 [DEBUG] (Worker_01 ) PID:4386 <zeromq_queue> Pop on Worker_01 task queue queue, port 43917
2020-07-14 13:30:30,587 [DEBUG] (Worker_01 ) PID:4386 <worker_process> Started processing task: 179cf0d9c9524e9095548d720816caa7.
2020-07-14 13:30:31,070 [DEBUG] (Worker_01 ) PID:4386 <worker> [ProcessFileEntry] processing file entry: NTFS:\Windows\WinSxS\wow64_microsoft-windows-d..setupstatusprovider_31bf3856ad364e35_10.0.19041.1_none_457308751e7c5eb2\DeviceSetupStatusProvider.dll
2020-07-14 13:30:31,070 [DEBUG] (Worker_01 ) PID:4386 <worker> [ProcessFileEntryDataStream] processing data stream: "" of file entry: NTFS:\Windows\WinSxS\wow64_microsoft-windows-d..setupstatusprovider_31bf3856ad364e35_10.0.19041.1_none_457308751e7c5eb2\DeviceSetupStatusProvider.dll
2020-07-14 13:30:31,070 [DEBUG] (Worker_01 ) PID:4386 <worker> [AnalyzeDataStream] analyzing file: NTFS:\Windows\WinSxS\wow64_microsoft-windows-d..setupstatusprovider_31bf3856ad364e35_10.0.19041.1_none_457308751e7c5eb2\DeviceSetupStatusProvider.dll
zcat Worker_03_psteal-20200713T164651.log.gz | tail -15

gzip: Worker_03_psteal-20200713T164651.log.gz: unexpected end of file
2020-07-15 07:12:10,684 [DEBUG] (Worker_03 ) PID:9147 <worker> [ProcessFileEntry] processing file entry: NTFS:\Windows.old\WINDOWS\WinSxS\wow64_microsoft-windows-x..achviewer.resources_31bf3856ad364e35_10.0.18362.1_he-il_48bebf5c78ad5c6f\xpsrchvw.exe.mui
2020-07-15 07:12:10,685 [DEBUG] (Worker_03 ) PID:9147 <worker> [ProcessFileEntryDataStream] processing data stream: "" of file entry: NTFS:\Windows.old\WINDOWS\WinSxS\wow64_microsoft-windows-x..achviewer.resources_31bf3856ad364e35_10.0.18362.1_he-il_48bebf5c78ad5c6f\xpsrchvw.exe.mui
2020-07-15 07:12:10,685 [DEBUG] (Worker_03 ) PID:9147 <worker> [AnalyzeDataStream] analyzing file: NTFS:\Windows.old\WINDOWS\WinSxS\wow64_microsoft-windows-x..achviewer.resources_31bf3856ad364e35_10.0.18362.1_he-il_48bebf5c78ad5c6f\xpsrchvw.exe.mui
2020-07-15 07:12:10,707 [DEBUG] (Worker_03 ) PID:9147 <hashing_analyzer> Processing results for hasher sha256
2020-07-15 07:12:10,707 [DEBUG] (Worker_03 ) PID:9147 <worker> [AnalyzeFileObject] attribute sha256_hash:6908ff1cae844e9b40b0fc47b433613eef35c5ce988b3d738f0ae331624b8415 calculated for file: NTFS:\Windows.old\WINDOWS\WinSxS\wow64_microsoft-windows-x..achviewer.resources_31bf3856ad364e35_10.0.18362.1_he-il_48bebf5c78ad5c6f\xpsrchvw.exe.mui.
2020-07-15 07:12:10,707 [DEBUG] (Worker_03 ) PID:9147 <worker> [AnalyzeDataStream] completed analyzing file: NTFS:\Windows.old\WINDOWS\WinSxS\wow64_microsoft-windows-x..achviewer.resources_31bf3856ad364e35_10.0.18362.1_he-il_48bebf5c78ad5c6f\xpsrchvw.exe.mui
2020-07-15 07:12:10,708 [DEBUG] (Worker_03 ) PID:9147 <worker> [ExtractMetadataFromFileEntry] processing file entry: NTFS:\Windows.old\WINDOWS\WinSxS\wow64_microsoft-windows-x..achviewer.resources_31bf3856ad364e35_10.0.18362.1_he-il_48bebf5c78ad5c6f\xpsrchvw.exe.mui
2020-07-15 07:12:10,722 [DEBUG] (Worker_03 ) PID:9147 <extractors> [ParseFileEntryWithParsers] parsing file: NTFS:\Windows.old\WINDOWS\WinSxS\wow64_microsoft-windows-x..achviewer.resources_31bf3856ad364e35_10.0.18362.1_he-il_48bebf5c78ad5c6f\xpsrchvw.exe.mui with parser: pe
2020-07-15 07:12:10,888 [DEBUG] (Worker_03 ) PID:9147 <worker> [ProcessFileEntry] done processing file entry: NTFS:\Windows.old\WINDOWS\WinSxS\wow64_microsoft-windows-x..achviewer.resources_31bf3856ad364e35_10.0.18362.1_he-il_48bebf5c78ad5c6f\xpsrchvw.exe.mui
2020-07-15 07:12:11,506 [DEBUG] (Worker_03 ) PID:9147 <worker_process> Completed processing task: 03279ea8a02c4aba88365e56ba9bbf85.
2020-07-15 07:12:11,520 [DEBUG] (Worker_03 ) PID:9147 <zeromq_queue> Pop on Worker_03 task queue queue, port 43917
2020-07-15 07:12:11,529 [DEBUG] (Worker_03 ) PID:9147 <worker_process> Started processing task: 7f16094c9e944223975e471e89cc630c.
2020-07-15 07:12:13,798 [DEBUG] (Worker_03 ) PID:9147 <worker> [ProcessFileEntry] processing file entry: NTFS:\Windows.old\WINDOWS\WinSxS\wow64_microsoft-windows-x..achviewer.resources_31bf3856ad364e35_10.0.18362.1_it-it_eec70e01697040ff\xpsrchvw.exe.mui
2020-07-15 07:12:13,798 [DEBUG] (Worker_03 ) PID:9147 <worker> [ProcessFileEntryDataStream] processing data stream: "" of file entry: NTFS:\Windows.old\WINDOWS\WinSxS\wow64_microsoft-windows-x..achviewer.resources_31bf3856ad364e35_10.0.18362.1_it-it_eec70e01697040ff\xpsrchvw.exe.mui
2020-07-15 07:12:13,798 [DEBUG] (Worker_03 ) PID:9147 <worker> [AnalyzeDataStream] analyzing file: NTFS:\Windows.old\WINDOWS\WinSxS\wow64_microsoft-windows-x..achviewer.resources_31bf3856ad364e35_10.0.18362.1_it-it_eec70e01697040ff\xpsrchvw.exe.mui
zcat Worker_04_psteal-20200713T164651.log.gz | tail -15

gzip: Worker_04_psteal-20200713T164651.log.gz: unexpected end of file
2020-07-15 07:11:43,954 [DEBUG] (Worker_04 ) PID:9225 <worker> [ProcessFileEntry] processing file entry: NTFS:\Windows.old\WINDOWS\WinSxS\wow64_microsoft-windows-wsp-replication_31bf3856ad364e35_10.0.18362.1_none_3a1876a7c37ecc14\wsp_sr.dll
2020-07-15 07:11:43,954 [DEBUG] (Worker_04 ) PID:9225 <worker> [ProcessFileEntryDataStream] processing data stream: "" of file entry: NTFS:\Windows.old\WINDOWS\WinSxS\wow64_microsoft-windows-wsp-replication_31bf3856ad364e35_10.0.18362.1_none_3a1876a7c37ecc14\wsp_sr.dll
2020-07-15 07:11:43,954 [DEBUG] (Worker_04 ) PID:9225 <worker> [AnalyzeDataStream] analyzing file: NTFS:\Windows.old\WINDOWS\WinSxS\wow64_microsoft-windows-wsp-replication_31bf3856ad364e35_10.0.18362.1_none_3a1876a7c37ecc14\wsp_sr.dll
2020-07-15 07:11:44,037 [DEBUG] (Worker_04 ) PID:9225 <hashing_analyzer> Processing results for hasher sha256
2020-07-15 07:11:44,037 [DEBUG] (Worker_04 ) PID:9225 <worker> [AnalyzeFileObject] attribute sha256_hash:44bb7697e4dd89e542ede1a904f06b3dc7853f4d185aa4a460e67319a9aa5093 calculated for file: NTFS:\Windows.old\WINDOWS\WinSxS\wow64_microsoft-windows-wsp-replication_31bf3856ad364e35_10.0.18362.1_none_3a1876a7c37ecc14\wsp_sr.dll.
2020-07-15 07:11:44,037 [DEBUG] (Worker_04 ) PID:9225 <worker> [AnalyzeDataStream] completed analyzing file: NTFS:\Windows.old\WINDOWS\WinSxS\wow64_microsoft-windows-wsp-replication_31bf3856ad364e35_10.0.18362.1_none_3a1876a7c37ecc14\wsp_sr.dll
2020-07-15 07:11:44,037 [DEBUG] (Worker_04 ) PID:9225 <worker> [ExtractMetadataFromFileEntry] processing file entry: NTFS:\Windows.old\WINDOWS\WinSxS\wow64_microsoft-windows-wsp-replication_31bf3856ad364e35_10.0.18362.1_none_3a1876a7c37ecc14\wsp_sr.dll
2020-07-15 07:11:44,039 [DEBUG] (Worker_04 ) PID:9225 <extractors> [ParseFileEntryWithParsers] parsing file: NTFS:\Windows.old\WINDOWS\WinSxS\wow64_microsoft-windows-wsp-replication_31bf3856ad364e35_10.0.18362.1_none_3a1876a7c37ecc14\wsp_sr.dll with parser: pe
2020-07-15 07:11:44,241 [DEBUG] (Worker_04 ) PID:9225 <worker> [ProcessFileEntry] done processing file entry: NTFS:\Windows.old\WINDOWS\WinSxS\wow64_microsoft-windows-wsp-replication_31bf3856ad364e35_10.0.18362.1_none_3a1876a7c37ecc14\wsp_sr.dll
2020-07-15 07:11:44,859 [DEBUG] (Worker_04 ) PID:9225 <worker_process> Completed processing task: 668dcd0ad51e4570aad18949d67f65cb.
2020-07-15 07:11:44,859 [DEBUG] (Worker_04 ) PID:9225 <zeromq_queue> Pop on Worker_04 task queue queue, port 43917
2020-07-15 07:11:44,880 [DEBUG] (Worker_04 ) PID:9225 <worker_process> Started processing task: 51545479d5344190b6bc91d43d5a20a1.
2020-07-15 07:11:47,103 [DEBUG] (Worker_04 ) PID:9225 <worker> [ProcessFileEntry] processing file entry: NTFS:\Windows.old\WINDOWS\WinSxS\wow64_microsoft-windows-wsp-spaces_31bf3856ad364e35_10.0.18362.1_none_42eb1c7f5f241877\mispace.dll
2020-07-15 07:11:47,103 [DEBUG] (Worker_04 ) PID:9225 <worker> [ProcessFileEntryDataStream] processing data stream: "" of file entry: NTFS:\Windows.old\WINDOWS\WinSxS\wow64_microsoft-windows-wsp-spaces_31bf3856ad364e35_10.0.18362.1_none_42eb1c7f5f241877\mispace.dll
2020-07-15 07:11:47,103 [DEBUG] (Worker_04 ) PID:9225 <worker> [AnalyzeDataStream] analyzing file: NTFS:\Windows.old\WINDOWS\WinSxS\wow64_microsoft-windows-wsp-spaces_31bf3856ad364e35_10.0.18362.1_none_42eb1c7f5f241877\mispace.dll
zcat Worker_05_psteal-20200713T164651.log.gz | tail -15

gzip: Worker_05_psteal-20200713T164651.log.gz: unexpected end of file
2020-07-15 06:09:25,783 [DEBUG] (Worker_05 ) PID:9250 <worker> [ProcessFileEntry] processing file entry: NTFS:\Windows.old\WINDOWS\WinSxS\wow64_microsoft-windows-dusm.resources_31bf3856ad364e35_10.0.18362.1_en-us_4442e9825f53e265\dusmsvc.dll.mui
2020-07-15 06:09:25,783 [DEBUG] (Worker_05 ) PID:9250 <worker> [ProcessFileEntryDataStream] processing data stream: "" of file entry: NTFS:\Windows.old\WINDOWS\WinSxS\wow64_microsoft-windows-dusm.resources_31bf3856ad364e35_10.0.18362.1_en-us_4442e9825f53e265\dusmsvc.dll.mui
2020-07-15 06:09:25,784 [DEBUG] (Worker_05 ) PID:9250 <worker> [AnalyzeDataStream] analyzing file: NTFS:\Windows.old\WINDOWS\WinSxS\wow64_microsoft-windows-dusm.resources_31bf3856ad364e35_10.0.18362.1_en-us_4442e9825f53e265\dusmsvc.dll.mui
2020-07-15 06:09:25,805 [DEBUG] (Worker_05 ) PID:9250 <hashing_analyzer> Processing results for hasher sha256
2020-07-15 06:09:25,805 [DEBUG] (Worker_05 ) PID:9250 <worker> [AnalyzeFileObject] attribute sha256_hash:b4fc3774a5a5ec1b95a6a36f42ab2f5542ec52edba46b6f54d9ccfada9b7be30 calculated for file: NTFS:\Windows.old\WINDOWS\WinSxS\wow64_microsoft-windows-dusm.resources_31bf3856ad364e35_10.0.18362.1_en-us_4442e9825f53e265\dusmsvc.dll.mui.
2020-07-15 06:09:25,806 [DEBUG] (Worker_05 ) PID:9250 <worker> [AnalyzeDataStream] completed analyzing file: NTFS:\Windows.old\WINDOWS\WinSxS\wow64_microsoft-windows-dusm.resources_31bf3856ad364e35_10.0.18362.1_en-us_4442e9825f53e265\dusmsvc.dll.mui
2020-07-15 06:09:25,806 [DEBUG] (Worker_05 ) PID:9250 <worker> [ExtractMetadataFromFileEntry] processing file entry: NTFS:\Windows.old\WINDOWS\WinSxS\wow64_microsoft-windows-dusm.resources_31bf3856ad364e35_10.0.18362.1_en-us_4442e9825f53e265\dusmsvc.dll.mui
2020-07-15 06:09:25,820 [DEBUG] (Worker_05 ) PID:9250 <extractors> [ParseFileEntryWithParsers] parsing file: NTFS:\Windows.old\WINDOWS\WinSxS\wow64_microsoft-windows-dusm.resources_31bf3856ad364e35_10.0.18362.1_en-us_4442e9825f53e265\dusmsvc.dll.mui with parser: pe
2020-07-15 06:09:25,842 [DEBUG] (Worker_05 ) PID:9250 <worker> [ProcessFileEntry] done processing file entry: NTFS:\Windows.old\WINDOWS\WinSxS\wow64_microsoft-windows-dusm.resources_31bf3856ad364e35_10.0.18362.1_en-us_4442e9825f53e265\dusmsvc.dll.mui
2020-07-15 06:09:26,436 [DEBUG] (Worker_05 ) PID:9250 <worker_process> Completed processing task: a11b93621ca1402182bfcdce413f0770.
2020-07-15 06:09:26,436 [DEBUG] (Worker_05 ) PID:9250 <zeromq_queue> Pop on Worker_05 task queue queue, port 43917
2020-07-15 06:09:26,449 [DEBUG] (Worker_05 ) PID:9250 <worker_process> Started processing task: 95e523b6ced548e6be2c358b39eed47e.
2020-07-15 06:09:28,697 [DEBUG] (Worker_05 ) PID:9250 <worker> [ProcessFileEntry] processing file entry: NTFS:\Windows.old\WINDOWS\WinSxS\wow64_microsoft-windows-dxptasks-sync_31bf3856ad364e35_10.0.18362.1_none_6b5c184a5f39d401\DxpTaskSync.dll
2020-07-15 06:09:28,698 [DEBUG] (Worker_05 ) PID:9250 <worker> [ProcessFileEntryDataStream] processing data stream: "" of file entry: NTFS:\Windows.old\WINDOWS\WinSxS\wow64_microsoft-windows-dxptasks-sync_31bf3856ad364e35_10.0.18362.1_none_6b5c184a5f39d401\DxpTaskSync.dll
2020-07-15 06:09:28,698 [DEBUG] (Worker_05 ) PID:9250 <worker> [AnalyzeDataStream] analyzing file: NTFS:\Windows.old\WINDOWS\WinSxS\wow64_microsoft-windows-dxptasks-sync_31bf3856ad364e35_10.0.18362.1_none_6b5c184a5f39d401\DxpTaskSync.dll
zcat Worker_06_psteal-20200713T164651.log.gz | tail -15

gzip: Worker_06_psteal-20200713T164651.log.gz: unexpected end of file
2020-07-16 02:10:38,523 [DEBUG] (Worker_06 ) PID:14384 <extractors> [ParseFileEntryWithParsers] parsing file: NTFS:\Windows.old\WINDOWS\SoftwareDistribution\Download\806e76e03f9c647629f4299158a902b6\Windows10.0-KB4556803-x64.cab with parser: sccm
2020-07-16 02:10:38,523 [DEBUG] (Worker_06 ) PID:14384 <extractors> sccm unable to parse file: NTFS:\Windows.old\WINDOWS\SoftwareDistribution\Download\806e76e03f9c647629f4299158a902b6\Windows10.0-KB4556803-x64.cab with error: Not a text file, with error: 'utf-8' codec can't decode byte 0xb0 in position 28: invalid start byte
2020-07-16 02:10:38,523 [DEBUG] (Worker_06 ) PID:14384 <extractors> [ParseFileEntryWithParsers] parsing file: NTFS:\Windows.old\WINDOWS\SoftwareDistribution\Download\806e76e03f9c647629f4299158a902b6\Windows10.0-KB4556803-x64.cab with parser: setupapi
2020-07-16 02:10:38,523 [DEBUG] (Worker_06 ) PID:14384 <extractors> setupapi unable to parse file: NTFS:\Windows.old\WINDOWS\SoftwareDistribution\Download\806e76e03f9c647629f4299158a902b6\Windows10.0-KB4556803-x64.cab with error: Not a text file or encoding not supported.
2020-07-16 02:10:38,523 [DEBUG] (Worker_06 ) PID:14384 <extractors> [ParseFileEntryWithParsers] parsing file: NTFS:\Windows.old\WINDOWS\SoftwareDistribution\Download\806e76e03f9c647629f4299158a902b6\Windows10.0-KB4556803-x64.cab with parser: skydrive_log
2020-07-16 02:10:38,523 [DEBUG] (Worker_06 ) PID:14384 <extractors> skydrive_log unable to parse file: NTFS:\Windows.old\WINDOWS\SoftwareDistribution\Download\806e76e03f9c647629f4299158a902b6\Windows10.0-KB4556803-x64.cab with error: Not a text file, with error: 'utf-8' codec can't decode byte 0xb0 in position 28: invalid start byte
2020-07-16 02:10:38,523 [DEBUG] (Worker_06 ) PID:14384 <extractors> [ParseFileEntryWithParsers] parsing file: NTFS:\Windows.old\WINDOWS\SoftwareDistribution\Download\806e76e03f9c647629f4299158a902b6\Windows10.0-KB4556803-x64.cab with parser: skydrive_log_old
2020-07-16 02:10:38,524 [DEBUG] (Worker_06 ) PID:14384 <extractors> skydrive_log_old unable to parse file: NTFS:\Windows.old\WINDOWS\SoftwareDistribution\Download\806e76e03f9c647629f4299158a902b6\Windows10.0-KB4556803-x64.cab with error: Not a text file or encoding not supported.
2020-07-16 02:10:38,524 [DEBUG] (Worker_06 ) PID:14384 <extractors> [ParseFileEntryWithParsers] parsing file: NTFS:\Windows.old\WINDOWS\SoftwareDistribution\Download\806e76e03f9c647629f4299158a902b6\Windows10.0-KB4556803-x64.cab with parser: symantec_scanlog
2020-07-16 02:10:38,571 [DEBUG] (Worker_06 ) PID:14384 <extractors> symantec_scanlog unable to parse file: NTFS:\Windows.old\WINDOWS\SoftwareDistribution\Download\806e76e03f9c647629f4299158a902b6\Windows10.0-KB4556803-x64.cab with error: [symantec_scanlog] Unable to parse DSV file: NTFS:\Windows.old\WINDOWS\SoftwareDistribution\Download\806e76e03f9c647629f4299158a902b6\Windows10.0-KB4556803-x64.cab with error: 'charmap' codec can't decode byte 0x81 in position 122: character maps to <undefined>.
2020-07-16 02:10:38,573 [DEBUG] (Worker_06 ) PID:14384 <extractors> [ParseFileEntryWithParsers] parsing file: NTFS:\Windows.old\WINDOWS\SoftwareDistribution\Download\806e76e03f9c647629f4299158a902b6\Windows10.0-KB4556803-x64.cab with parser: winfirewall
2020-07-16 02:10:38,573 [DEBUG] (Worker_06 ) PID:14384 <extractors> winfirewall unable to parse file: NTFS:\Windows.old\WINDOWS\SoftwareDistribution\Download\806e76e03f9c647629f4299158a902b6\Windows10.0-KB4556803-x64.cab with error: Not a text file or encoding not supported.
2020-07-16 02:10:38,573 [DEBUG] (Worker_06 ) PID:14384 <extractors> [ParseFileEntryWithParsers] parsing file: NTFS:\Windows.old\WINDOWS\SoftwareDistribution\Download\806e76e03f9c647629f4299158a902b6\Windows10.0-KB4556803-x64.cab with parser: winjob
2020-07-16 02:10:38,573 [DEBUG] (Worker_06 ) PID:14384 <extractors> winjob unable to parse file: NTFS:\Windows.old\WINDOWS\SoftwareDistribution\Download\806e76e03f9c647629f4299158a902b6\Windows10.0-KB4556803-x64.cab with error: Unsupported product version in: 0x534d
2020-07-16 02:10:38,574 [DEBUG] (Worker_06 ) PID:14384 <worker> [ProcessFileEntry] done processing file entry: NTFS:\Windows.old\WINDOWS\SoftwareDistribution\Download\806e76e03f9c647629f4299158a902b6\Windows10.0-KB4556803-x64.cab
zcat Worker_07_psteal-20200713T164651.log.gz | tail -15

gzip: Worker_07_psteal-20200713T164651.log.gz: unexpected end of file
2020-07-16 03:29:17,670 [DEBUG] (Worker_07 ) PID:14948 <extractors> recycle_bin unable to parse file: NTFS:\Windows.old\WINDOWS\System32\LogFiles\Firewall\publicfw.log.old with error: Filename must start with $I.
2020-07-16 03:29:17,670 [DEBUG] (Worker_07 ) PID:14948 <extractors> [ParseFileEntryWithParsers] parsing file: NTFS:\Windows.old\WINDOWS\System32\LogFiles\Firewall\publicfw.log.old with parser: sccm
2020-07-16 03:29:17,672 [DEBUG] (Worker_07 ) PID:14948 <extractors> sccm unable to parse file: NTFS:\Windows.old\WINDOWS\System32\LogFiles\Firewall\publicfw.log.old with error: Wrong file structure.
2020-07-16 03:29:17,672 [DEBUG] (Worker_07 ) PID:14948 <extractors> [ParseFileEntryWithParsers] parsing file: NTFS:\Windows.old\WINDOWS\System32\LogFiles\Firewall\publicfw.log.old with parser: setupapi
2020-07-16 03:29:17,672 [DEBUG] (Worker_07 ) PID:14948 <setupapi> Not a Windows Setupapi log file: Expected "[Device Install Log]", found '#'  (at char 0), (line:1, col:1)
2020-07-16 03:29:17,672 [DEBUG] (Worker_07 ) PID:14948 <extractors> setupapi unable to parse file: NTFS:\Windows.old\WINDOWS\System32\LogFiles\Firewall\publicfw.log.old with error: Wrong file structure.
2020-07-16 03:29:17,672 [DEBUG] (Worker_07 ) PID:14948 <extractors> [ParseFileEntryWithParsers] parsing file: NTFS:\Windows.old\WINDOWS\System32\LogFiles\Firewall\publicfw.log.old with parser: skydrive_log
2020-07-16 03:29:17,673 [DEBUG] (Worker_07 ) PID:14948 <skydrivelog> Not a SkyDrive log file
2020-07-16 03:29:17,690 [DEBUG] (Worker_07 ) PID:14948 <extractors> skydrive_log unable to parse file: NTFS:\Windows.old\WINDOWS\System32\LogFiles\Firewall\publicfw.log.old with error: Wrong file structure.
2020-07-16 03:29:17,690 [DEBUG] (Worker_07 ) PID:14948 <extractors> [ParseFileEntryWithParsers] parsing file: NTFS:\Windows.old\WINDOWS\System32\LogFiles\Firewall\publicfw.log.old with parser: skydrive_log_old
2020-07-16 03:29:17,690 [DEBUG] (Worker_07 ) PID:14948 <skydrivelog> Not a SkyDrive old log file
2020-07-16 03:29:17,691 [DEBUG] (Worker_07 ) PID:14948 <extractors> skydrive_log_old unable to parse file: NTFS:\Windows.old\WINDOWS\System32\LogFiles\Firewall\publicfw.log.old with error: Wrong file structure.
2020-07-16 03:29:17,691 [DEBUG] (Worker_07 ) PID:14948 <extractors> [ParseFileEntryWithParsers] parsing file: NTFS:\Windows.old\WINDOWS\System32\LogFiles\Firewall\publicfw.log.old with parser: symantec_scanlog
2020-07-16 03:29:18,744 [DEBUG] (Worker_07 ) PID:14948 <extractors> symantec_scanlog unable to parse file: NTFS:\Windows.old\WINDOWS\System32\LogFiles\Firewall\publicfw.log.old with error: [symantec_scanlog] Unable to parse DSV file: NTFS:\Windows.old\WINDOWS\System32\LogFiles\Firewall\publicfw.log.old. Signature mismatch.
2020-07-16 03:29:18,781 [DEBUG] (Worker_07 ) PID:14948 <extractors> [ParseFileEntryWithParsers] parsing file: NTFS:\Windows.old\WINDOWS\System32\LogFiles\Firewall\publicfw.log.old with parser: winfirewall
zcat Worker_08_psteal-20200713T164651.log.gz | tail -15

gzip: Worker_08_psteal-20200713T164651.log.gz: unexpected end of file
2020-07-15 23:36:50,504 [DEBUG] (Worker_08 ) PID:14953 <worker_process> Started processing task: 2b1d0cf3b6374d509d5a43ac511237bb.
2020-07-15 23:36:52,768 [DEBUG] (Worker_08 ) PID:14953 <worker> [ProcessFileEntry] processing file entry: NTFS:\Windows.old\WINDOWS\servicing\LCU\Package_for_RollupFix~31bf3856ad364e35~amd64~~18362.778.1.9\amd64_microsoft-windows-icm-base_31bf3856ad364e35_10.0.18362.267_none_788c4a381b0b71b3\r
2020-07-15 23:36:52,785 [DEBUG] (Worker_08 ) PID:14953 <worker> [ProcessFileEntryDataStream] processing data stream: "" of file entry: NTFS:\Windows.old\WINDOWS\servicing\LCU\Package_for_RollupFix~31bf3856ad364e35~amd64~~18362.778.1.9\amd64_microsoft-windows-icm-base_31bf3856ad364e35_10.0.18362.267_none_788c4a381b0b71b3\r
2020-07-15 23:36:52,785 [DEBUG] (Worker_08 ) PID:14953 <worker> [ExtractMetadataFromFileEntry] processing file entry: NTFS:\Windows.old\WINDOWS\servicing\LCU\Package_for_RollupFix~31bf3856ad364e35~amd64~~18362.778.1.9\amd64_microsoft-windows-icm-base_31bf3856ad364e35_10.0.18362.267_none_788c4a381b0b71b3\r
2020-07-15 23:36:52,786 [DEBUG] (Worker_08 ) PID:14953 <worker> [ProcessFileEntry] done processing file entry: NTFS:\Windows.old\WINDOWS\servicing\LCU\Package_for_RollupFix~31bf3856ad364e35~amd64~~18362.778.1.9\amd64_microsoft-windows-icm-base_31bf3856ad364e35_10.0.18362.267_none_788c4a381b0b71b3\r
2020-07-15 23:36:53,352 [DEBUG] (Worker_08 ) PID:14953 <worker_process> Completed processing task: 2b1d0cf3b6374d509d5a43ac511237bb.
2020-07-15 23:36:53,364 [DEBUG] (Worker_08 ) PID:14953 <zeromq_queue> Pop on Worker_08 task queue queue, port 43917
2020-07-15 23:36:53,389 [DEBUG] (Worker_08 ) PID:14953 <worker_process> Started processing task: f98b0ef56423493c90ccfe1a05f200e5.
2020-07-15 23:36:55,667 [DEBUG] (Worker_08 ) PID:14953 <worker> [ProcessFileEntry] processing file entry: NTFS:\Windows.old\WINDOWS\servicing\LCU\Package_for_RollupFix~31bf3856ad364e35~amd64~~18362.778.1.9\amd64_microsoft-windows-ie-feeds-platform_31bf3856ad364e35_11.0.18362.628_none_f98f45b4f571d324\f
2020-07-15 23:36:55,667 [DEBUG] (Worker_08 ) PID:14953 <worker> [ProcessFileEntryDataStream] processing data stream: "" of file entry: NTFS:\Windows.old\WINDOWS\servicing\LCU\Package_for_RollupFix~31bf3856ad364e35~amd64~~18362.778.1.9\amd64_microsoft-windows-ie-feeds-platform_31bf3856ad364e35_11.0.18362.628_none_f98f45b4f571d324\f
2020-07-15 23:36:55,667 [DEBUG] (Worker_08 ) PID:14953 <worker> [ExtractMetadataFromFileEntry] processing file entry: NTFS:\Windows.old\WINDOWS\servicing\LCU\Package_for_RollupFix~31bf3856ad364e35~amd64~~18362.778.1.9\amd64_microsoft-windows-ie-feeds-platform_31bf3856ad364e35_11.0.18362.628_none_f98f45b4f571d324\f
2020-07-15 23:36:55,668 [DEBUG] (Worker_08 ) PID:14953 <worker> [ProcessFileEntry] done processing file entry: NTFS:\Windows.old\WINDOWS\servicing\LCU\Package_for_RollupFix~31bf3856ad364e35~amd64~~18362.778.1.9\amd64_microsoft-windows-ie-feeds-platform_31bf3856ad364e35_11.0.18362.628_none_f98f45b4f571d324\f
2020-07-15 23:36:56,249 [DEBUG] (Worker_08 ) PID:14953 <worker_process> Completed processing task: f98b0ef56423493c90ccfe1a05f200e5.
2020-07-15 23:36:56,249 [DEBUG] (Worker_08 ) PID:14953 <zeromq_queue> Pop on Worker_08 task queue queue, port 43917
2020-07-15 23:36:56,267 [DEBUG] (Worker_08 ) PID:14953 <worker_process> Started processing task: b1a1774e73d043e89fdf3f8428f2afb0.
zcat Worker_10_psteal-20200713T164651.log.gz | tail -15

gzip: Worker_10_psteal-20200713T164651.log.gz: unexpected end of file
2020-07-16 23:35:11,761 [DEBUG] (Worker_10 ) PID:20632 <extractors> [ParseFileEntryWithParsers] parsing file: NTFS:\Windows.old\WINDOWS\servicing\LCU\Package_for_RollupFix~31bf3856ad364e35~amd64~~18362.778.1.9\amd64_microsoft-windows-n..oller-wmiv2provider_31bf3856ad364e35_10.0.18362.657_none_3f76fd1508b004b8\f\ncserverpsprovider.dll with parser: skydrive_log_old
2020-07-16 23:35:11,761 [DEBUG] (Worker_10 ) PID:20632 <extractors> skydrive_log_old unable to parse file: NTFS:\Windows.old\WINDOWS\servicing\LCU\Package_for_RollupFix~31bf3856ad364e35~amd64~~18362.778.1.9\amd64_microsoft-windows-n..oller-wmiv2provider_31bf3856ad364e35_10.0.18362.657_none_3f76fd1508b004b8\f\ncserverpsprovider.dll with error: Not a text file or encoding not supported.
2020-07-16 23:35:11,761 [DEBUG] (Worker_10 ) PID:20632 <extractors> [ParseFileEntryWithParsers] parsing file: NTFS:\Windows.old\WINDOWS\servicing\LCU\Package_for_RollupFix~31bf3856ad364e35~amd64~~18362.778.1.9\amd64_microsoft-windows-n..oller-wmiv2provider_31bf3856ad364e35_10.0.18362.657_none_3f76fd1508b004b8\f\ncserverpsprovider.dll with parser: symantec_scanlog
2020-07-16 23:35:11,761 [DEBUG] (Worker_10 ) PID:20632 <extractors> symantec_scanlog unable to parse file: NTFS:\Windows.old\WINDOWS\servicing\LCU\Package_for_RollupFix~31bf3856ad364e35~amd64~~18362.778.1.9\amd64_microsoft-windows-n..oller-wmiv2provider_31bf3856ad364e35_10.0.18362.657_none_3f76fd1508b004b8\f\ncserverpsprovider.dll with error: [symantec_scanlog] Unable to parse DSV file: NTFS:\Windows.old\WINDOWS\servicing\LCU\Package_for_RollupFix~31bf3856ad364e35~amd64~~18362.778.1.9\amd64_microsoft-windows-n..oller-wmiv2provider_31bf3856ad364e35_10.0.18362.657_none_3f76fd1508b004b8\f\ncserverpsprovider.dll with error: 'charmap' codec can't decode byte 0x81 in position 8: character maps to <undefined>.
2020-07-16 23:35:11,761 [DEBUG] (Worker_10 ) PID:20632 <extractors> [ParseFileEntryWithParsers] parsing file: NTFS:\Windows.old\WINDOWS\servicing\LCU\Package_for_RollupFix~31bf3856ad364e35~amd64~~18362.778.1.9\amd64_microsoft-windows-n..oller-wmiv2provider_31bf3856ad364e35_10.0.18362.657_none_3f76fd1508b004b8\f\ncserverpsprovider.dll with parser: winfirewall
2020-07-16 23:35:11,761 [DEBUG] (Worker_10 ) PID:20632 <extractors> winfirewall unable to parse file: NTFS:\Windows.old\WINDOWS\servicing\LCU\Package_for_RollupFix~31bf3856ad364e35~amd64~~18362.778.1.9\amd64_microsoft-windows-n..oller-wmiv2provider_31bf3856ad364e35_10.0.18362.657_none_3f76fd1508b004b8\f\ncserverpsprovider.dll with error: Not a text file or encoding not supported.
2020-07-16 23:35:11,762 [DEBUG] (Worker_10 ) PID:20632 <extractors> [ParseFileEntryWithParsers] parsing file: NTFS:\Windows.old\WINDOWS\servicing\LCU\Package_for_RollupFix~31bf3856ad364e35~amd64~~18362.778.1.9\amd64_microsoft-windows-n..oller-wmiv2provider_31bf3856ad364e35_10.0.18362.657_none_3f76fd1508b004b8\f\ncserverpsprovider.dll with parser: winjob
2020-07-16 23:35:11,762 [DEBUG] (Worker_10 ) PID:20632 <extractors> winjob unable to parse file: NTFS:\Windows.old\WINDOWS\servicing\LCU\Package_for_RollupFix~31bf3856ad364e35~amd64~~18362.778.1.9\amd64_microsoft-windows-n..oller-wmiv2provider_31bf3856ad364e35_10.0.18362.657_none_3f76fd1508b004b8\f\ncserverpsprovider.dll with error: Unsupported product version in: 0x4562
2020-07-16 23:35:11,762 [DEBUG] (Worker_10 ) PID:20632 <worker> [ProcessFileEntry] done processing file entry: NTFS:\Windows.old\WINDOWS\servicing\LCU\Package_for_RollupFix~31bf3856ad364e35~amd64~~18362.778.1.9\amd64_microsoft-windows-n..oller-wmiv2provider_31bf3856ad364e35_10.0.18362.657_none_3f76fd1508b004b8\f\ncserverpsprovider.dll
2020-07-16 23:35:11,887 [DEBUG] (Worker_10 ) PID:20632 <worker_process> Completed processing task: f26aed929d48436595d3a920119c96cd.
2020-07-16 23:35:11,888 [DEBUG] (Worker_10 ) PID:20632 <zeromq_queue> Pop on Worker_10 task queue queue, port 43917
2020-07-16 23:35:11,889 [DEBUG] (Worker_10 ) PID:20632 <worker_process> Started processing task: 0c08e857d7d14ed5bbbe7cde42d6c9e3.
2020-07-16 23:35:12,372 [DEBUG] (Worker_10 ) PID:20632 <worker> [ProcessFileEntry] processing file entry: NTFS:\Windows.old\WINDOWS\servicing\LCU\Package_for_RollupFix~31bf3856ad364e35~amd64~~18362.778.1.9\amd64_microsoft-windows-n..ork-setup-servicing_31bf3856ad364e35_10.0.18362.628_none_dc39344c9fac9094\f\netsetupapi.dll
2020-07-16 23:35:12,373 [DEBUG] (Worker_10 ) PID:20632 <worker> [ProcessFileEntryDataStream] processing data stream: "" of file entry: NTFS:\Windows.old\WINDOWS\servicing\LCU\Package_for_RollupFix~31bf3856ad364e35~amd64~~18362.778.1.9\amd64_microsoft-windows-n..ork-setup-servicing_31bf3856ad364e35_10.0.18362.628_none_dc39344c9fac9094\f\netsetupapi.dll
2020-07-16 23:35:12,373 [DEBUG] (Worker_10 ) PID:20632 <worker> [AnalyzeDataStream] analyzing file: NTFS:\Windows.old\WINDOWS\servicing\LCU\Package_for_RollupFix~31bf3856ad364e35~amd64~~18362.778.1.9\amd64_microsoft-windows-n..ork-setup-servicing_31bf3856ad364e35_10.0.18362.628_none_dc39344c9fac9094\f\netsetupapi.dll
zcat Worker_11_psteal-20200713T164651.log.gz | tail -15

gzip: Worker_11_psteal-20200713T164651.log.gz: unexpected end of file
2020-07-16 18:15:20,335 [DEBUG] (Worker_11 ) PID:20872 <extractors> [ParseFileEntryWithParsers] parsing file: NTFS:\Users\user1\AppData\Local\Google\Drive\user_default\sync_log.log with parser: amcache
2020-07-16 18:15:20,335 [DEBUG] (Worker_11 ) PID:20872 <extractors> [ParseFileEntryWithParsers] parsing file: NTFS:\Users\user1\AppData\Local\Google\Drive\user_default\sync_log.log with parser: bencode
2020-07-16 18:15:20,335 [DEBUG] (Worker_11 ) PID:20872 <extractors> bencode unable to parse file: NTFS:\Users\user1\AppData\Local\Google\Drive\user_default\sync_log.log with error: Not a valid Bencoded file.
2020-07-16 18:15:20,335 [DEBUG] (Worker_11 ) PID:20872 <extractors> [ParseFileEntryWithParsers] parsing file: NTFS:\Users\user1\AppData\Local\Google\Drive\user_default\sync_log.log with parser: chrome_cache
2020-07-16 18:15:20,362 [DEBUG] (Worker_11 ) PID:20872 <extractors> chrome_cache unable to parse file: NTFS:\Users\user1\AppData\Local\Google\Drive\user_default\sync_log.log with error: [chrome_cache] unable to parse index file NTFS:\Users\user1\AppData\Local\Google\Drive\user_default\sync_log.log with error: Unable to parse index file header with error: Unable to parse index file header with error: Unable to map chrome_cache_index_file_header data at offset: 0x00000000 with error: Value: 808595506 not in supported values: 3238251203
2020-07-16 18:15:20,363 [DEBUG] (Worker_11 ) PID:20872 <extractors> [ParseFileEntryWithParsers] parsing file: NTFS:\Users\user1\AppData\Local\Google\Drive\user_default\sync_log.log with parser: chrome_preferences
2020-07-16 18:15:20,363 [DEBUG] (Worker_11 ) PID:20872 <extractors> chrome_preferences unable to parse file: NTFS:\Users\user1\AppData\Local\Google\Drive\user_default\sync_log.log with error: [chrome_preferences] NTFS:\Users\user1\AppData\Local\Google\Drive\user_default\sync_log.log is not a valid Preference file, missing opening brace.
2020-07-16 18:15:20,363 [DEBUG] (Worker_11 ) PID:20872 <extractors> [ParseFileEntryWithParsers] parsing file: NTFS:\Users\user1\AppData\Local\Google\Drive\user_default\sync_log.log with parser: czip
2020-07-16 18:15:20,363 [DEBUG] (Worker_11 ) PID:20872 <extractors> czip unable to parse file: NTFS:\Users\user1\AppData\Local\Google\Drive\user_default\sync_log.log with error: [czip] unable to parse file: NTFS:\Users\user1\AppData\Local\Google\Drive\user_default\sync_log.log with error: Not a Zip file.
2020-07-16 18:15:20,364 [DEBUG] (Worker_11 ) PID:20872 <extractors> [ParseFileEntryWithParsers] parsing file: NTFS:\Users\user1\AppData\Local\Google\Drive\user_default\sync_log.log with parser: firefox_cache
2020-07-16 18:15:20,364 [DEBUG] (Worker_11 ) PID:20872 <extractors> firefox_cache unable to parse file: NTFS:\Users\suser1\AppData\Local\Google\Drive\user_default\sync_log.log with error: Not a Firefox cache1 file.
2020-07-16 18:15:20,364 [DEBUG] (Worker_11 ) PID:20872 <extractors> [ParseFileEntryWithParsers] parsing file: NTFS:\Users\user1\AppData\Local\Google\Drive\user_default\sync_log.log with parser: gdrive_synclog
2020-07-16 18:31:50,800 [DEBUG] (Worker_11 ) PID:20872 <extractors> [ParseFileEntryWithParsers] parsing file: NTFS:\Users\user1\AppData\Local\Google\Drive\user_default\sync_log.log with parser: java_idx
2020-07-16 18:31:50,801 [DEBUG] (Worker_11 ) PID:20872 <extractors> java_idx unable to parse file: NTFS:\Users\user1\AppData\Local\Google\Drive\user_default\sync_log.log with error: Unsupported format version.
2020-07-16 18:31:50,801 [DEBUG] (Worker_11 ) PID:20872 <extractors> [ParseFileEntryWithParsers] parsing file: NTFS:\Users\user1\AppData\Local\Google\Drive\user_default\sync_log.log with parser: mcafee_protection
zcat Worker_14_psteal-20200713T164651.log.gz | tail -15

gzip: Worker_14_psteal-20200713T164651.log.gz: unexpected end of file
2020-07-17 14:37:40,545 [DEBUG] (Worker_14 ) PID:27444 <skydrivelog> Not a SkyDrive old log file
2020-07-17 14:37:40,545 [DEBUG] (Worker_14 ) PID:27444 <extractors> skydrive_log_old unable to parse file: NTFS:\Program Files (x86)\Adobe\Acrobat Reader DC\Reader\WebResources\Resource0\static\images\themes\dark\s_reminders_18.svg with error: Wrong file structure.
2020-07-17 14:37:40,545 [DEBUG] (Worker_14 ) PID:27444 <extractors> [ParseFileEntryWithParsers] parsing file: NTFS:\Program Files (x86)\Adobe\Acrobat Reader DC\Reader\WebResources\Resource0\static\images\themes\dark\s_reminders_18.svg with parser: symantec_scanlog
2020-07-17 14:37:40,545 [DEBUG] (Worker_14 ) PID:27444 <extractors> symantec_scanlog unable to parse file: NTFS:\Program Files (x86)\Adobe\Acrobat Reader DC\Reader\WebResources\Resource0\static\images\themes\dark\s_reminders_18.svg with error: [symantec_scanlog] Unable to parse DSV file: NTFS:\Program Files (x86)\Adobe\Acrobat Reader DC\Reader\WebResources\Resource0\static\images\themes\dark\s_reminders_18.svg. Signature mismatch.
2020-07-17 14:37:40,546 [DEBUG] (Worker_14 ) PID:27444 <extractors> [ParseFileEntryWithParsers] parsing file: NTFS:\Program Files (x86)\Adobe\Acrobat Reader DC\Reader\WebResources\Resource0\static\images\themes\dark\s_reminders_18.svg with parser: winfirewall
2020-07-17 14:37:40,546 [DEBUG] (Worker_14 ) PID:27444 <extractors> winfirewall unable to parse file: NTFS:\Program Files (x86)\Adobe\Acrobat Reader DC\Reader\WebResources\Resource0\static\images\themes\dark\s_reminders_18.svg with error: Wrong file structure.
2020-07-17 14:37:40,546 [DEBUG] (Worker_14 ) PID:27444 <extractors> [ParseFileEntryWithParsers] parsing file: NTFS:\Program Files (x86)\Adobe\Acrobat Reader DC\Reader\WebResources\Resource0\static\images\themes\dark\s_reminders_18.svg with parser: winjob
2020-07-17 14:37:40,546 [DEBUG] (Worker_14 ) PID:27444 <extractors> winjob unable to parse file: NTFS:\Program Files (x86)\Adobe\Acrobat Reader DC\Reader\WebResources\Resource0\static\images\themes\dark\s_reminders_18.svg with error: Unsupported product version in: 0x733c
2020-07-17 14:37:40,546 [DEBUG] (Worker_14 ) PID:27444 <worker> [ProcessFileEntry] done processing file entry: NTFS:\Program Files (x86)\Adobe\Acrobat Reader DC\Reader\WebResources\Resource0\static\images\themes\dark\s_reminders_18.svg
2020-07-17 14:37:41,001 [DEBUG] (Worker_14 ) PID:27444 <worker_process> Completed processing task: 5909fa5c5e474856a73f8c20f0a9a2ac.
2020-07-17 14:37:41,002 [DEBUG] (Worker_14 ) PID:27444 <zeromq_queue> Pop on Worker_14 task queue queue, port 43917
2020-07-17 14:37:41,021 [DEBUG] (Worker_14 ) PID:27444 <worker_process> Started processing task: 8c6edb6e90d74dd397865b31afdf5b5b.
2020-07-17 14:37:42,730 [DEBUG] (Worker_14 ) PID:27444 <worker> [ProcessFileEntry] processing file entry: NTFS:\Program Files (x86)\Adobe\Acrobat Reader DC\Reader\WebResources\Resource0\static\images\themes\dark\s_remove_18.svg
2020-07-17 14:37:42,730 [DEBUG] (Worker_14 ) PID:27444 <worker> [ProcessFileEntryDataStream] processing data stream: "" of file entry: NTFS:\Program Files (x86)\Adobe\Acrobat Reader DC\Reader\WebResources\Resource0\static\images\themes\dark\s_remove_18.svg
2020-07-17 14:37:42,730 [DEBUG] (Worker_14 ) PID:27444 <worker> [AnalyzeDataStream] analyzing file: NTFS:\Program Files (x86)\Adobe\Acrobat Reader DC\Reader\WebResources\Resource0\static\images\themes\dark\s_remove_18.svg
zcat Worker_15_psteal-20200713T164651.log.gz | tail -15

gzip: Worker_15_psteal-20200713T164651.log.gz: unexpected end of file
2020-07-17 23:50:52,937 [DEBUG] (Worker_15 ) PID:28223 <extractors> [ParseFileEntryWithParsers] parsing file: NTFS:\Users\LocalAdmin\AppData\Local\SquirrelTemp\tempa\lib\net45\resources\app.asar.unpacked\node_modules\@slack\slack-calls-prebuilt\modules\@slack\slack-calls\build\Release\slack-calls.node.diff with parser: setupapi
2020-07-17 23:50:52,937 [DEBUG] (Worker_15 ) PID:28223 <extractors> setupapi unable to parse file: NTFS:\Users\LocalAdmin\AppData\Local\SquirrelTemp\tempa\lib\net45\resources\app.asar.unpacked\node_modules\@slack\slack-calls-prebuilt\modules\@slack\slack-calls\build\Release\slack-calls.node.diff with error: Not a text file or encoding not supported.
2020-07-17 23:50:52,937 [DEBUG] (Worker_15 ) PID:28223 <extractors> [ParseFileEntryWithParsers] parsing file: NTFS:\Users\LocalAdmin\AppData\Local\SquirrelTemp\tempa\lib\net45\resources\app.asar.unpacked\node_modules\@slack\slack-calls-prebuilt\modules\@slack\slack-calls\build\Release\slack-calls.node.diff with parser: skydrive_log
2020-07-17 23:50:52,937 [DEBUG] (Worker_15 ) PID:28223 <extractors> skydrive_log unable to parse file: NTFS:\Users\LocalAdmin\AppData\Local\SquirrelTemp\tempa\lib\net45\resources\app.asar.unpacked\node_modules\@slack\slack-calls-prebuilt\modules\@slack\slack-calls\build\Release\slack-calls.node.diff with error: Not a text file, with error: 'utf-8' codec can't decode byte 0xa1 in position 4: invalid start byte
2020-07-17 23:50:52,937 [DEBUG] (Worker_15 ) PID:28223 <extractors> [ParseFileEntryWithParsers] parsing file: NTFS:\Users\LocalAdmin\AppData\Local\SquirrelTemp\tempa\lib\net45\resources\app.asar.unpacked\node_modules\@slack\slack-calls-prebuilt\modules\@slack\slack-calls\build\Release\slack-calls.node.diff with parser: skydrive_log_old
2020-07-17 23:50:52,937 [DEBUG] (Worker_15 ) PID:28223 <extractors> skydrive_log_old unable to parse file: NTFS:\Users\LocalAdmin\AppData\Local\SquirrelTemp\tempa\lib\net45\resources\app.asar.unpacked\node_modules\@slack\slack-calls-prebuilt\modules\@slack\slack-calls\build\Release\slack-calls.node.diff with error: Not a text file or encoding not supported.
2020-07-17 23:50:52,938 [DEBUG] (Worker_15 ) PID:28223 <extractors> [ParseFileEntryWithParsers] parsing file: NTFS:\Users\LocalAdmin\AppData\Local\SquirrelTemp\tempa\lib\net45\resources\app.asar.unpacked\node_modules\@slack\slack-calls-prebuilt\modules\@slack\slack-calls\build\Release\slack-calls.node.diff with parser: symantec_scanlog
2020-07-17 23:50:52,938 [DEBUG] (Worker_15 ) PID:28223 <extractors> symantec_scanlog unable to parse file: NTFS:\Users\LocalAdmin\AppData\Local\SquirrelTemp\tempa\lib\net45\resources\app.asar.unpacked\node_modules\@slack\slack-calls-prebuilt\modules\@slack\slack-calls\build\Release\slack-calls.node.diff with error: [symantec_scanlog] Unable to parse DSV file: NTFS:\Users\LocalAdmin\AppData\Local\SquirrelTemp\tempa\lib\net45\resources\app.asar.unpacked\node_modules\@slack\slack-calls-prebuilt\modules\@slack\slack-calls\build\Release\slack-calls.node.diff with error: 'charmap' codec can't decode byte 0x8f in position 18: character maps to <undefined>.
2020-07-17 23:50:52,938 [DEBUG] (Worker_15 ) PID:28223 <extractors> [ParseFileEntryWithParsers] parsing file: NTFS:\Users\LocalAdmin\AppData\Local\SquirrelTemp\tempa\lib\net45\resources\app.asar.unpacked\node_modules\@slack\slack-calls-prebuilt\modules\@slack\slack-calls\build\Release\slack-calls.node.diff with parser: winfirewall
2020-07-17 23:50:52,938 [DEBUG] (Worker_15 ) PID:28223 <extractors> winfirewall unable to parse file: NTFS:\Users\LocalAdmin\AppData\Local\SquirrelTemp\tempa\lib\net45\resources\app.asar.unpacked\node_modules\@slack\slack-calls-prebuilt\modules\@slack\slack-calls\build\Release\slack-calls.node.diff with error: Not a text file or encoding not supported.
2020-07-17 23:50:52,938 [DEBUG] (Worker_15 ) PID:28223 <extractors> [ParseFileEntryWithParsers] parsing file: NTFS:\Users\LocalAdmin\AppData\Local\SquirrelTemp\tempa\lib\net45\resources\app.asar.unpacked\node_modules\@slack\slack-calls-prebuilt\modules\@slack\slack-calls\build\Release\slack-calls.node.diff with parser: winjob
2020-07-17 23:50:52,938 [DEBUG] (Worker_15 ) PID:28223 <extractors> winjob unable to parse file: NTFS:\Users\LocalAdmin\AppData\Local\SquirrelTemp\tempa\lib\net45\resources\app.asar.unpacked\node_modules\@slack\slack-calls-prebuilt\modules\@slack\slack-calls\build\Release\slack-calls.node.diff with error: Unsupported product version in: 0x4150
2020-07-17 23:50:52,939 [DEBUG] (Worker_15 ) PID:28223 <worker> [ProcessFileEntry] done processing file entry: NTFS:\Users\LocalAdmin\AppData\Local\SquirrelTemp\tempa\lib\net45\resources\app.asar.unpacked\node_modules\@slack\slack-calls-prebuilt\modules\@slack\slack-calls\build\Release\slack-calls.node.diff
2020-07-17 23:50:53,062 [DEBUG] (Worker_15 ) PID:28223 <worker_process> Completed processing task: 169e84477f124a2b8c9d444027642824.
2020-07-17 23:50:53,062 [DEBUG] (Worker_15 ) PID:28223 <zeromq_queue> Pop on Worker_15 task queue queue, port 43917
zcat Worker_16_psteal-20200713T164651.log.gz | tail -15

gzip: Worker_16_psteal-20200713T164651.log.gz: unexpected end of file
2020-07-17 23:50:53,184 [DEBUG] (Worker_16 ) PID:31154 <extractors> [ParseFileEntryWithParsers] parsing file: NTFS:\Users\LocalAdmin\AppData\Local\SquirrelTemp\tempa\lib\net45\resources\app.asar.unpacked\node_modules\@slack\slack-calls-prebuilt\modules\@slack\slack-calls\build\Release\slack-calls.node.shasum with parser: skydrive_log
2020-07-17 23:50:53,184 [DEBUG] (Worker_16 ) PID:31154 <skydrivelog> Not a SkyDrive log file
2020-07-17 23:50:53,184 [DEBUG] (Worker_16 ) PID:31154 <extractors> skydrive_log unable to parse file: NTFS:\Users\LocalAdmin\AppData\Local\SquirrelTemp\tempa\lib\net45\resources\app.asar.unpacked\node_modules\@slack\slack-calls-prebuilt\modules\@slack\slack-calls\build\Release\slack-calls.node.shasum with error: Wrong file structure.
2020-07-17 23:50:53,184 [DEBUG] (Worker_16 ) PID:31154 <extractors> [ParseFileEntryWithParsers] parsing file: NTFS:\Users\LocalAdmin\AppData\Local\SquirrelTemp\tempa\lib\net45\resources\app.asar.unpacked\node_modules\@slack\slack-calls-prebuilt\modules\@slack\slack-calls\build\Release\slack-calls.node.shasum with parser: skydrive_log_old
2020-07-17 23:50:53,184 [DEBUG] (Worker_16 ) PID:31154 <skydrivelog> Not a SkyDrive old log file
2020-07-17 23:50:53,185 [DEBUG] (Worker_16 ) PID:31154 <extractors> skydrive_log_old unable to parse file: NTFS:\Users\LocalAdmin\AppData\Local\SquirrelTemp\tempa\lib\net45\resources\app.asar.unpacked\node_modules\@slack\slack-calls-prebuilt\modules\@slack\slack-calls\build\Release\slack-calls.node.shasum with error: Wrong file structure.
2020-07-17 23:50:53,185 [DEBUG] (Worker_16 ) PID:31154 <extractors> [ParseFileEntryWithParsers] parsing file: NTFS:\Users\LocalAdmin\AppData\Local\SquirrelTemp\tempa\lib\net45\resources\app.asar.unpacked\node_modules\@slack\slack-calls-prebuilt\modules\@slack\slack-calls\build\Release\slack-calls.node.shasum with parser: symantec_scanlog
2020-07-17 23:50:53,185 [DEBUG] (Worker_16 ) PID:31154 <extractors> symantec_scanlog unable to parse file: NTFS:\Users\LocalAdmin\AppData\Local\SquirrelTemp\tempa\lib\net45\resources\app.asar.unpacked\node_modules\@slack\slack-calls-prebuilt\modules\@slack\slack-calls\build\Release\slack-calls.node.shasum with error: [symantec_scanlog] Unable to parse DSV file: NTFS:\Users\LocalAdmin\AppData\Local\SquirrelTemp\tempa\lib\net45\resources\app.asar.unpacked\node_modules\@slack\slack-calls-prebuilt\modules\@slack\slack-calls\build\Release\slack-calls.node.shasum. Signature mismatch.
2020-07-17 23:50:53,185 [DEBUG] (Worker_16 ) PID:31154 <extractors> [ParseFileEntryWithParsers] parsing file: NTFS:\Users\LocalAdmin\AppData\Local\SquirrelTemp\tempa\lib\net45\resources\app.asar.unpacked\node_modules\@slack\slack-calls-prebuilt\modules\@slack\slack-calls\build\Release\slack-calls.node.shasum with parser: winfirewall
2020-07-17 23:50:53,185 [DEBUG] (Worker_16 ) PID:31154 <extractors> winfirewall unable to parse file: NTFS:\Users\LocalAdmin\AppData\Local\SquirrelTemp\tempa\lib\net45\resources\app.asar.unpacked\node_modules\@slack\slack-calls-prebuilt\modules\@slack\slack-calls\build\Release\slack-calls.node.shasum with error: Not a text file or encoding not supported.
2020-07-17 23:50:53,185 [DEBUG] (Worker_16 ) PID:31154 <extractors> [ParseFileEntryWithParsers] parsing file: NTFS:\Users\LocalAdmin\AppData\Local\SquirrelTemp\tempa\lib\net45\resources\app.asar.unpacked\node_modules\@slack\slack-calls-prebuilt\modules\@slack\slack-calls\build\Release\slack-calls.node.shasum with parser: winjob
2020-07-17 23:50:53,186 [DEBUG] (Worker_16 ) PID:31154 <extractors> winjob unable to parse file: NTFS:\Users\LocalAdmin\AppData\Local\SquirrelTemp\tempa\lib\net45\resources\app.asar.unpacked\node_modules\@slack\slack-calls-prebuilt\modules\@slack\slack-calls\build\Release\slack-calls.node.shasum with error: Unsupported product version in: 0xbbef
2020-07-17 23:50:53,186 [DEBUG] (Worker_16 ) PID:31154 <worker> [ProcessFileEntry] done processing file entry: NTFS:\Users\LocalAdmin\AppData\Local\SquirrelTemp\tempa\lib\net45\resources\app.asar.unpacked\node_modules\@slack\slack-calls-prebuilt\modules\@slack\slack-calls\build\Release\slack-calls.node.shasum
2020-07-17 23:50:53,305 [DEBUG] (Worker_16 ) PID:31154 <worker_process> Completed processing task: b20e065aeab6459485d752d15371b9fa.
2020-07-17 23:50:53,306 [DEBUG] (Worker_16 ) PID:31154 <zeromq_queue> Pop on Worker_16 task queue queue, port 43917
joachimmetz commented 4 years ago

@siftuser thx for all the data, much appreciated

joachimmetz commented 4 years ago

Would you recommend specs for improving perf ?

Not in this case, you are running into some edge case that causes the workers to get killed because of high memory consumption. Worker memory usage is limited by default to 4G, which for most parsers and workloads should be more than enough.

I see a lot of PE/COFF files as the last being parsed the workers that were killed. A couple of hypotheses:

  1. something in pe parser causing high memory consumption, as mentioned before memory profiling data could tell us more here or running with the pe parser disabled
  2. something in the volume/file system system handing causing high memory consumption, one option you could try is running psteal with --vfs-back-end tsk and see if the issue persists
siftuser commented 4 years ago

@joachimmetz running it again ... how do I exclude just pe parser & include all others ? it's also hogging the cpu

plaso 2020-07-21 at 11 39 42 AM

joachimmetz commented 4 years ago

@joachimmetz running it again ... how do I exclude just pe parser & include all others ?

Either remove it from the preset or disable it with ! (make sure to escape the exclamation mark on shells like bash)

it's also hogging the cpu

Working as intended, Plaso will utilize the CPU as much as possible by default, you can limit the number of workers if want less CPU utilization

siftuser commented 4 years ago

is this what you meant ?

log2timeline.py -z UTC --profilers=memory --profiling-directory=/volume2/profile --vfs-back-end tsk /volume2/case_1.plaso /volume1/case/case_1.E01 -d --no_vss --parsers -pe

joachimmetz commented 4 years ago

Nope, you need to use exclamation (!) mark not dash (-). You can find a more detailed explanation in the help psteal.py --help

Instead try: --parsers 'win7,!pe'

joachimmetz commented 4 years ago

@siftuser any luck with determining what is eating up the memory? did excluding the pe parser do the trick? or changing to tsk backend?

siftuser commented 4 years ago

Thanks @joachimmetz for follow up. Yes, I did try & running for 7+ days (about 65% complete) as follows with one change win7,!pe. Is this performance usual for a 250gb image running on t2.xlarge/4 vcore cpu, 16GB RAM ? would beefing-up the hardware help ?

log2timeline.py -z UTC --profilers=memory --profiling-directory=/volume2/profile --vfs-back-end tsk /volume2/image.plaso /volume1/image.E01 -d --no_vss --parsers 'win7_slow,!pe'

plaso2

joachimmetz commented 4 years ago

Is this performance usual for a 250gb image running on t2.xlarge/4 vcore cpu, 16GB RAM ?

Nope, the long processing time is due to something misbehaving.

Since running with both tsk and fsntfs seem to have the issue, with and without the pe parser, maybe something elsewhere?

which version of libewf/pyewf are you using?

log2timeline.py --troubles

siftuser commented 4 years ago

output of log2timeline.py --troubles

plaso - log2timeline version 20200717

Checking availability and versions of dependencies.
[OK]        artifacts version: 20200515
[OK]        bencode
[OK]        biplist
[OK]        certifi version: 2020.06.20
[OK]        chardet version: 3.0.4
[OK]        cryptography version: 2.9.2
[OK]        dateutil version: 2.8.1
[OK]        defusedxml version: 0.6.0
[OK]        dfdatetime version: 20200613
[OK]        dfvfs version: 20200625
[OK]        dfwinreg version: 20200415
[OK]        dtfabric version: 20200621
[OK]        elasticsearch version: 7.8.0
[OK]        future version: 0.18.2
[OK]        idna version: 2.9
[OK]        lz4
[OK]        pefile version: 2019.4.18
[OK]        psutil version: 5.7.0
[OK]        pybde version: 20191221
[OK]        pyesedb version: 20200418
[OK]        pyevt version: 20200418
[OK]        pyevtx version: 20200419
[OK]        pyewf version: 20140808
[OK]        pyfsapfs version: 20200416
[OK]        pyfsntfs version: 20200627
[OK]        pyfvde version: 20200101
[OK]        pyfwnt version: 20200605
[OK]        pyfwsi version: 20191221
[OK]        pylnk version: 20191221
[OK]        pyluksde version: 20200205
[OK]        pymsiecf version: 20191221
[OK]        pyolecf version: 20191221
[OK]        pyparsing version: 2.4.7
[OK]        pyqcow version: 20191221
[OK]        pyregf version: 20200429
[OK]        pyscca version: 20191222
[OK]        pysigscan version: 20191221
[OK]        pysmdev version: 20200210
[OK]        pysmraw version: 20191221
[OK]        pytsk3 version: 20200117
[OK]        pytz
[OK]        pyvhdi version: 20191221
[OK]        pyvmdk version: 20191221
[OK]        pyvshadow version: 20191221
[OK]        pyvslvm version: 20200102
[OK]        redis version: 3.5.3
[OK]        requests version: 2.24.0
[OK]        six version: 1.15.0
[OK]        urllib3 version: 1.25.9
[OK]        xlsxwriter version: 1.2.9
[OK]        yaml version: 3.12
[OK]        yara version: 4.0.2
[OK]        zmq version: 19.0.1
joachimmetz commented 4 years ago

thx, I see I had asked this earlier. I'll try see if I can set up a comparable environment. Something is misbehaving but unclear what.

Initially I ran psteal on e01 image of a windows 10 disk (250gb) ..

What version of Window 10? 2004? anything else characteristic about the data on the image?

siftuser commented 4 years ago

Image is from a Windows 10 Enterprise (1909) Build 18363 related to data exfil

No malware suspected

joachimmetz commented 4 years ago

a dependency that stands out, since this is newer than the current release https://github.com/libyal/libfvde/releases

[OK]        pyfvde version: 20200101

This should not have direct impact on the issue you are seeing but does make me wonder about the installation. Since this version is not provided by the GIFT PPA. https://travis-ci.com/github/log2timeline/l2tbinaries/jobs/366988666#L865

@siftuser any idea why your version of pyfvde is newer than the official release/version provided by the GIFT PPA? Any secondary installations of packages on your system that could cause issues?

joachimmetz commented 4 years ago

@siftuser a couple of more questions about the source data:

I'm currently running log2timeline on the Desktop image of https://www.hecfblog.com/2018/08/daily-blog-451-defcon-dfir-ctf-2018.html?m=1. Which seems per system configuration somewhat in the direction of the source data you described.

joachimmetz commented 4 years ago

Ran log2timeline on all 3 images with the default parser preset. All complete under 30 mins with fsntfs. A couple of things we could try:

Also can you confirm which parser preset you've been using? I see you using the the default, which is likely win7 for your configuration, and win7_slow at a later point. It is important that to test consistently with same parameters so we can pinpoint the issue.

siftuser commented 4 years ago
  • how many EWF segment files? (E01, E02, ...)
  • how large is the set of EWF files? I assume the original disk is 250GB based on your earlier info

2gb x 120 segments

siftuser commented 4 years ago

@siftuser any idea why your version of pyfvde is newer than the official release/version provided by the GIFT PPA? Any secondary installations of packages on your system that could cause issues?

possible because of libfsntfs ? fsntfsmount 20200627

joachimmetz commented 4 years ago

possible because of libfsntfs ? fsntfsmount 20200627

unlikely, libfvde and libfsntfs are 2 separate dependencies

2gb x 120 segments

was compression used? otherwise it sounds like there is vast amount of data on the image, which could hint at the default log2timeline/psteal memory limits maybe being too small. You could try enlarging --process_memory_limit and/or --process_memory_limit

siftuser commented 4 years ago

was compression used?

Nope

joachimmetz commented 4 years ago

was compression used?

ack, in that case it could be vast amount of unallocated space as well and my previous remark about the limits might not apply.

siftuser commented 4 years ago

fyi - iotop shows 

Total DISK READ :       0.00 B/s | Total DISK WRITE :      22.78 K/s
 0.00 BDISK READ:       0.00 B/s | Actual DISK WRITE:      13.21 K/s

sounds like there is vast amount of data on the image

shows 9,749,719 events after ~68% of processed data

Now trying to install docker version & restart using following options (win7 instead of win7_slow)

Any suggestions ?

log2timeline.py -z UTC --profilers=memory --profiling-directory=/volume2/profile --vfs-back-end tsk /volume2/image.plaso /volume1/image.E01 -d --no_vss --parsers 'win7,!pe'

joachimmetz commented 4 years ago

Now trying to install docker version & restart using following options (win7 instead of win7_slow)

I tested the 3 images mentioned previously with both, but let's stick with win7 for now.

shows 9,749,719 events after ~68% of processed data

3M - 10M events is not uncommon for a current Windows image

Any suggestions ?

Do you have the profiling files from the previous run still in /volume2/profile ? I would be interested in the contents of the profile/memory-Worker_*-parsers.csv.gz files

siftuser commented 4 years ago

Do you have the profiling files from the previous run still in /volume2/profile ? I would be interested in the contents of the profile/memory-Worker_*-parsers.csv.gz files

Yes I do. Please let me know, which portion do you want to be shared

joachimmetz commented 4 years ago

The full files if you can. There should be no other data in there than many lines of a timestamp, memory usage and name of parser. Make sure to double check.

siftuser commented 4 years ago

@joachimmetz is there a storage I can upload the memory profile csv files ?

joachimmetz commented 4 years ago

how large are they approximate? you could mail them if they are not too large, otherwise Google Drive or some other online file sharing service?

siftuser commented 4 years ago

Running again via docker, but the plaso file size is not changing. Any clue @joachimmetz ?

nohup docker run -t -v /volume2/:/volume2 -v /volume1/:/volume1 log2timeline.py -z UTC --profilers=memory --profiling-directory=/volume2/profile --vfs-back-end tsk /volume2/image.plaso /volume1/image.E01 -d --no_vss --parsers 'win7,!pe' $

-rw-r--r-- 1 root root 61440 Aug 1 14:21 image_docker.plaso

btw, I can see from nohup.out it's running as expected

joachimmetz commented 4 years ago

Running again via docker, but the plaso file size is not changing. Any clue @joachimmetz ?

Could it be waiting for user input? there is an --unattended flag that will cause log2timeline.py to error out when input is needed

thx for sharing some of the memory-Worker_*.csv.gz files though I need the profile/memory-Worker_*-parsers.csv.gz files to determine which parser is increasing the memory consumption. The memory-Worker_*.csv.gz files confirm that something causes the memory usage to steadily grow: Figure_1

siftuser commented 4 years ago

Thank you @joachimmetz. Sorry I don't see profile/memory-Worker_*-parsers.csv.gz

It only has profile/memory-Worker_*.csv.gz & a profile/memory-Main.csv.gz

siftuser commented 4 years ago

Could it be waiting for user input? there is an --unattended flag that will cause log2timeline.py to error out when input is needed

Tried, no change. tail -f on image.plaso shows as follows with no updates, whereas nohup.out shows event count increasing 

tablesystem_configurationsystem_configurationCREATE TABLE system_configuration (_identifier INTEGER PRIMARY KEY''�7tablesession_startsession_startCREATE TABLE session_start (_identifier INTEGER PRIMARY KEY AUTOINCREMENT,_data BLOB)�
                                                                                                                         77�GtablesesCREATE TABLE session_configuration (_identifier INTEGER PRIMARY KEY AUTOINCREMENT,_data BLOB)�

                                                                                              11�Atablesession_completionsession_completion
      CREATE TABLE session_completion (_identifier INTEGER PRIMARY KEY AUTOINCREMENT,_data BLOB)p
�/tableevent_tagevent_tag
                         CREATE TABLE event_tag (_identifier INTEGER PRIMARY KEY AUTOINCREMENT,_data BLOB)y %%�5tableevent_sourceevent_source
CREATE TABLE event_source (_identifier INTEGER PRIMARY KEY AUTOINCREMENT,_data BLOB//�?tableevent_data_streamevent_data_stream  CREATE TABLE event_data_stream (_identifier INTEGER PRIMARY KEY AUTOINCREMENT,_data BLOB)s!!�1tableevent_dataevent_datCREATE TABLE event_data (_identifier INTEGER PRIMARY KEY AUTOINCREMENT,_data BLOB)v�KtableeventeventCREATE TABLE event (_identifier INTEGER PRIMARY KEY AUTOINCREMENT,_timestamp BIGINT,_data BLOB)�
                                           11�Atableextraction_warningextraction_warningCREATE TABLE extraction_warning (_identifier INTEGER PRIMARY KEY AUTOINCREMENT,_data BLOB)�--�=tableextraction_errorextraction_errorCREATE TABLE extraction_error (_identifier INTEGER PRIMARY KEY AUTOINCREMENT,_data BLOB)P++Ytablesqlite_sequencesqlite_sequenceCREATE TABLE sqlite_sequence(name,seq)�++�;tableanalysis_reportanalysis_reportCREATE TABLE analysis_report (_identifier INTEGER PRIMARY KEY AUTOINCREMENT,_data BLOB)Hetablemetadatametad
joachimmetz commented 4 years ago

Tried, no change. tail -f on image.plaso shows as follows with no updates, whereas nohup.out shows event count increasing

The workers use separate database files that are merged. So this behavior could be normal if no merging is happening. Also the database will likely grow in increments (pre-allocating blocks of data). There is likely also a WAL file. I opt to give a bit of time.

It only has profile/memory-Worker_*.csv.gz & a profile/memory-Main.csv.gz

That is unfortunate, that means I cannot tell if and/or which parser is causing the issue.

siftuser commented 4 years ago

That is unfortunate, that means I cannot tell if and/or which parser is causing the issue.

Any clue or things I would have missed to capture parser logs ?

FYI - still not very encouraging results (with docker l2t) ....

plaso 3

docker log2timeline --troubles

plaso - log2timeline version 20200717

Checking availability and versions of dependencies.
[OK]        artifacts version: 20200515
[OK]        bencode
[OK]        biplist
[OK]        certifi version: 2020.06.20
[OK]        chardet version: 3.0.4
[OK]        cryptography version: 2.9.2
[OK]        dateutil version: 2.8.1
[OK]        defusedxml version: 0.6.0
[OK]        dfdatetime version: 20200613
[OK]        dfvfs version: 20200625
[OK]        dfwinreg version: 20200415
[OK]        dtfabric version: 20200621
[OK]        elasticsearch version: 7.8.0
[OK]        future version: 0.18.2
[OK]        idna version: 2.9
[OK]        lz4
[OK]        pefile version: 2019.4.18
[OK]        psutil version: 5.7.2
[OK]        pybde version: 20191221
[OK]        pyesedb version: 20200418
[OK]        pyevt version: 20200715
[OK]        pyevtx version: 20200709
[OK]        pyewf version: 20140808
[OK]        pyfsapfs version: 20200416
[OK]        pyfsntfs version: 20200627
[OK]        pyfvde version: 20191221
[OK]        pyfwnt version: 20200605
[OK]        pyfwsi version: 20191221
[OK]        pylnk version: 20200709
[OK]        pyluksde version: 20200205
[OK]        pymsiecf version: 20200710
[OK]        pyolecf version: 20191221
[OK]        pyparsing version: 2.4.7
[OK]        pyqcow version: 20191221
[OK]        pyregf version: 20200429
[OK]        pyscca version: 20191222
[OK]        pysigscan version: 20191221
[OK]        pysmdev version: 20200210
[OK]        pysmraw version: 20191221
[OK]        pytsk3 version: 20200117
[OK]        pytz
[OK]        pyvhdi version: 20191221
[OK]        pyvmdk version: 20191221
[OK]        pyvshadow version: 20191221
[OK]        pyvslvm version: 20200102
[OK]        redis version: 3.5.3
[OK]        requests version: 2.24.0
[OK]        six version: 1.15.0
[OK]        urllib3 version: 1.25.9
[OK]        xlsxwriter version: 1.2.9
[OK]        yaml version: 3.12
[OK]        yara version: 4.0.2
[OK]        zmq version: 19.0.1
joachimmetz commented 4 years ago

FYI - still not very encouraging results (with docker l2t) ....

So far I do not see workers being killed, that is a good sign.

You might need to tune the resources available to your Docker configuration. https://docs.docker.com/config/containers/resource_constraints/

Any clue or things I would have missed to capture parser logs ?

Try --profilers=memory,parsers