search

CERT-Polska / drakvuf-sandbox

DRAKVUF Sandbox - automated hypervisor-level malware analysis system
https://drakvuf-sandbox.readthedocs.io/
Other
1.03k stars 143 forks source link

Error in drak-postprocess and ProcDOT #520

Open Alex1under opened 3 years ago

Alex1under commented 3 years ago

I found already mentioned problem with #378 and #380. But it's not clear for me, is it fixed in new version or not. My problem: I installed ProcDOT according to the documentation, but still get this. image With journalctl -e -u drak-postprocess@1 see next log:

Apr 21 09:30:16 alex-virtual-machine drak-postprocess[866]: line_obj = json.loads(line) Apr 21 09:30:16 alex-virtual-machine drak-postprocess[866]: File "/usr/lib/python3.8/json/init.py", line 357, in loads Apr 21 09:30:16 alex-virtual-machine drak-postprocess[866]: return _default_decoder.decode(s) Apr 21 09:30:16 alex-virtual-machine drak-postprocess[866]: File "/usr/lib/python3.8/json/decoder.py", line 337, in decode Apr 21 09:30:16 alex-virtual-machine drak-postprocess[866]: obj, end = self.raw_decode(s, idx=_w(s, 0).end()) Apr 21 09:30:16 alex-virtual-machine drak-postprocess[866]: File "/usr/lib/python3.8/json/decoder.py", line 353, in raw_decode Apr 21 09:30:16 alex-virtual-machine drak-postprocess[866]: obj, end = self.scan_once(s, idx) Apr 21 09:30:16 alex-virtual-machine drak-postprocess[866]: json.decoder.JSONDecodeError: Invalid control character at: line 1 column 326 (char 325) Apr 21 09:30:16 alex-virtual-machine drak-postprocess[866]: procmon2dot (Build 48u) Apr 21 09:30:16 alex-virtual-machine drak-postprocess[866]: Loading ignore-file "procmon2dot_fileignores.dat" ... MD5: Apr 21 09:30:16 alex-virtual-machine procmon2dot[7148]: Warning: ReadFile(#PB_Any, 'procmon2dot_fileignores.dat') failed! (Callstack: ) Apr 21 09:30:16 alex-virtual-machine drak-postprocess[866]: Loading ignore-file "procmon2dot_registrykeyignores.dat" ... MD5: Apr 21 09:30:16 alex-virtual-machine procmon2dot[7149]: Warning: ReadFile(#PB_Any, 'procmon2dot_registrykeyignores.dat') failed! (Callstack: ) Apr 21 09:30:16 alex-virtual-machine drak-postprocess[866]: Loading ignore-file "procmon2dot_serverignores.dat" ... MD5: Apr 21 09:30:16 alex-virtual-machine procmon2dot[7150]: Warning: ReadFile(#PB_Any, 'procmon2dot_serverignores.dat') failed! (Callstack: ) Apr 21 09:30:16 alex-virtual-machine drak-postprocess[866]: Collecting Procmon data ... Apr 21 09:30:16 alex-virtual-machine drak-postprocess[866]: 117 lines Apr 21 09:30:16 alex-virtual-machine drak-postprocess[866]: 23 processes Apr 21 09:30:16 alex-virtual-machine drak-postprocess[866]: 90 threads Apr 21 09:30:16 alex-virtual-machine drak-postprocess[866]: 0 files Apr 21 09:30:16 alex-virtual-machine drak-postprocess[866]: 0 registry keys Apr 21 09:30:16 alex-virtual-machine drak-postprocess[866]: 0 servers Apr 21 09:30:16 alex-virtual-machine drak-postprocess[866]: 0 connections Apr 21 09:30:16 alex-virtual-machine drak-postprocess[866]: Done. Apr 21 09:30:16 alex-virtual-machine drak-postprocess[866]: Managing launcher ... Apr 21 09:30:16 alex-virtual-machine drak-postprocess[866]: Launcher found: PID 2192-n2 Apr 21 09:30:16 alex-virtual-machine drak-postprocess[866]: Done. Apr 21 09:30:16 alex-virtual-machine drak-postprocess[866]: Collecting network data ... Apr 21 09:30:16 alex-virtual-machine drak-postprocess[866]: No file provided! Apr 21 09:30:16 alex-virtual-machine drak-postprocess[866]: Done. Apr 21 09:30:16 alex-virtual-machine drak-postprocess[866]: Analyzing data ... Apr 21 09:30:16 alex-virtual-machine drak-postprocess[866]: Done. Apr 21 09:30:16 alex-virtual-machine drak-postprocess[866]: Writing files ... Apr 21 09:30:16 alex-virtual-machine drak-postprocess[866]: Done. Apr 21 09:30:16 alex-virtual-machine drak-postprocess[866]: End. Apr 21 09:30:16 alex-virtual-machine drak-postprocess[866]: [2021-04-21 09:30:16,742][ERROR] Postprocess failed Apr 21 09:30:16 alex-virtual-machine drak-postprocess[866]: Traceback (most recent call last): Apr 21 09:30:16 alex-virtual-machine drak-postprocess[866]: File "/opt/venvs/drakcore/lib/python3.8/site-packages/drakcore/process.py", line 88, in process Apr 21 09:30:16 alex-virtual-machine drak-postprocess[866]: outputs = plugin.handler(self.current_task, task_resources, self.backend.minio) Apr 21 09:30:16 alex-virtual-machine drak-postprocess[866]: File "/opt/venvs/drakcore/lib/python3.8/site-packages/drakcore/postprocess/generate_graphs.py", line 31, in generate_graphs Apr 21 09:30:16 alex-virtual-machine drak-postprocess[866]: minio.fput_object("drakrun", f"{analysis_uid}/graph.dot", os.path.join(output_dir, 'graph.dot')) Apr 21 09:30:16 alex-virtual-machine drak-postprocess[866]: File "/opt/venvs/drakcore/lib/python3.8/site-packages/minio/api.py", line 628, in fput_object Apr 21 09:30:16 alex-virtual-machine drak-postprocess[866]: with open(file_path, 'rb') as file_data: Apr 21 09:30:16 alex-virtual-machine drak-postprocess[866]: FileNotFoundError: [Errno 2] No such file or directory: '/tmp/tmpa60t04kq/graph.dot' Apr 21 09:30:16 alex-virtual-machine drak-postprocess[866]: ERROR:karton.drakrun.processor:Postprocess failed Apr 21 09:30:16 alex-virtual-machine drak-postprocess[866]: Traceback (most recent call last): Apr 21 09:30:16 alex-virtual-machine drak-postprocess[866]: File "/opt/venvs/drakcore/lib/python3.8/site-packages/drakcore/process.py", line 88, in process Apr 21 09:30:16 alex-virtual-machine drak-postprocess[866]: outputs = plugin.handler(self.current_task, task_resources, self.backend.minio) Apr 21 09:30:16 alex-virtual-machine drak-postprocess[866]: File "/opt/venvs/drakcore/lib/python3.8/site-packages/drakcore/postprocess/generate_graphs.py", line 31, in generate_graphs Apr 21 09:30:16 alex-virtual-machine drak-postprocess[866]: minio.fput_object("drakrun", f"{analysis_uid}/graph.dot", os.path.join(output_dir, 'graph.dot')) Apr 21 09:30:16 alex-virtual-machine drak-postprocess[866]: File "/opt/venvs/drakcore/lib/python3.8/site-packages/minio/api.py", line 628, in fput_object Apr 21 09:30:16 alex-virtual-machine drak-postprocess[866]: with open(file_path, 'rb') as file_data: Apr 21 09:30:16 alex-virtual-machine drak-postprocess[866]: FileNotFoundError: [Errno 2] No such file or directory: '/tmp/tmpa60t04kq/graph.dot' Apr 21 09:30:21 alex-virtual-machine drak-postprocess[866]: ERROR:root:Failed to parse 14 lines generated by unknown Apr 21 09:30:22 alex-virtual-machine drak-postprocess[866]: [2021-04-21 09:30:22,843][INFO] Skipping generate_wireshark_key_file, missing resources Apr 21 09:30:22 alex-virtual-machine drak-postprocess[866]: INFO:karton.drakrun.processor:Skipping generate_wireshark_key_file, missing resources Apr 21 09:30:22 alex-virtual-machine drak-postprocess[866]: [2021-04-21 09:30:22,844][INFO] Skipping generate_ipt_disasm, missing resources Apr 21 09:30:22 alex-virtual-machine drak-postprocess[866]: INFO:karton.drakrun.processor:Skipping generate_ipt_disasm, missing resources Apr 21 09:30:23 alex-virtual-machine drak-postprocess[866]: [2021-04-21 09:30:23,988][INFO] Task done - 6f5d5c45-c5f9-4e80-a494-7b1f43970d5b Apr 21 09:30:23 alex-virtual-machine drak-postprocess[866]: INFO:karton.drakrun.processor:Task done - 6f5d5c45-c5f9-4e80-a494-7b1f43970d5b

I'm using :

Ubuntu 18.04 Windows 7 (VM) Drakvuf-bundle 0.8 Drakrun v0.15.0 Drakcore v0.15.0

Any ideas what is wrong? Thank you.

vornick commented 3 years ago

Hi, the problem is relevant for me as well. As I understand it, the drakmon.log is incorrectly processed in the drakparse.py. The output should be a .csv file for the procmon2Dot. I found the following error in my log

Apr 21 13:53:25 sandbox drak-postprocess[838]: ERROR:root:BUG: Unparseable log entry!
Apr 21 13:53:25 sandbox drak-postprocess[838]: b'{"Plugin":"syscall","TimeStamp":"1619013060.964546","PID":2480,"PPID":2436,"TID":2484,"Us$Apr 21 13:53:25 sandbox drak-postprocess[838]: Traceback (most recent call last):
Apr 21 13:53:25 sandbox drak-postprocess[838]:   File "/opt/venvs/drakcore/lib/python3.8/site-packages/drakcore/postprocess/drakparse.py",$Apr 21 13:53:25 sandbox drak-postprocess[838]:     line_obj = json.loads(line)
Apr 21 13:53:25 sandbox drak-postprocess[838]:   File "/usr/lib/python3.8/json/__init__.py", line 357, in loads
Apr 21 13:53:25 sandbox drak-postprocess[838]:     return _default_decoder.decode(s)
Apr 21 13:53:25 sandbox drak-postprocess[838]:   File "/usr/lib/python3.8/json/decoder.py", line 337, in decode
Apr 21 13:53:25 sandbox drak-postprocess[838]:     obj, end = self.raw_decode(s, idx=_w(s, 0).end())
Apr 21 13:53:25 sandbox drak-postprocess[838]:   File "/usr/lib/python3.8/json/decoder.py", line 353, in raw_decode
Apr 21 13:53:25 sandbox drak-postprocess[838]:     obj, end = self.scan_once(s, idx)
Apr 21 13:53:25 sandbox drak-postprocess[838]: json.decoder.JSONDecodeError: Invalid control character at: line 1 column 370 (char 369)
Apr 21 13:53:25 sandbox drak-postprocess[838]: ERROR:root:BUG: Unparseable log entry!
Apr 21 13:53:25 sandbox drak-postprocess[838]: b'{"Plugin":"rpcmon","TimeStamp":"1619013069.589649","PID":896,"PPID":496,"TID":2524,"UserN$Apr 21 13:53:25 sandbox drak-postprocess[838]: Traceback (most recent call last):
Apr 21 13:53:25 sandbox drak-postprocess[838]:   File "/opt/venvs/drakcore/lib/python3.8/site-packages/drakcore/postprocess/drakparse.py",$Apr 21 13:53:25 sandbox drak-postprocess[838]:     line_obj = json.loads(line)
Apr 21 13:53:25 sandbox drak-postprocess[838]:   File "/usr/lib/python3.8/json/__init__.py", line 343, in loads
Apr 21 13:53:25 sandbox drak-postprocess[838]:     s = s.decode(detect_encoding(s), 'surrogatepass')
Apr 21 13:53:25 sandbox drak-postprocess[838]: UnicodeDecodeError: 'utf-8' codec can't decode bytes in position 201-202: invalid continuat$Apr 21 13:53:26 sandbox drak-postprocess[838]: ERROR:root:BUG: Unparseable log entry!
Apr 21 13:53:26 sandbox drak-postprocess[838]: b'{"Plugin":"rpcmon","TimeStamp":"1619013076.186950","PID":896,"PPID":496,"TID":1604,"UserN$Apr 21 13:53:26 sandbox drak-postprocess[838]: Traceback (most recent call last):
Apr 21 13:53:26 sandbox drak-postprocess[838]:   File "/opt/venvs/drakcore/lib/python3.8/site-packages/drakcore/postprocess/drakparse.py",$Apr 21 13:53:26 sandbox drak-postprocess[838]:     line_obj = json.loads(line)
Apr 21 13:53:26 sandbox drak-postprocess[838]:   File "/usr/lib/python3.8/json/__init__.py", line 357, in loads
Apr 21 13:53:26 sandbox drak-postprocess[838]:     return _default_decoder.decode(s)
Apr 21 13:53:26 sandbox drak-postprocess[838]:   File "/usr/lib/python3.8/json/decoder.py", line 337, in decode
Apr 21 13:53:26 sandbox drak-postprocess[838]:     obj, end = self.raw_decode(s, idx=_w(s, 0).end())
Apr 21 13:53:26 sandbox drak-postprocess[838]:   File "/usr/lib/python3.8/json/decoder.py", line 353, in raw_decode
Apr 21 13:53:26 sandbox drak-postprocess[838]:     obj, end = self.scan_once(s, idx)
Apr 21 13:53:26 sandbox drak-postprocess[838]: json.decoder.JSONDecodeError: Invalid control character at: line 1 column 202 (char 201)
Apr 21 13:53:30 sandbox drak-postprocess[838]: procmon2dot (Build 48u)

I also tried to parse the log separately by running the script and saw a similar errors:

ERROR:root:BUG: Failed to parse log entry.
{"Plugin":"syscall","TimeStamp":"1619013174.936639","PID":636,"PPID":496,"TID":2844,"UserName":"SessionID","UserId":0,"ProcessName":"\\Device\\HarddiskVolume2\\Windows\\System32\\svchost.exe","Method":"NtCreateThreadEx","EventUID":"0x2a0d1b","Module":"nt","vCPU":1,"CR3":"0x8b7d7000","Syscall":165,"NArgs":11,"ThreadHandle":"0xfffff880047437e0","DesiredAccess":"0x1fffff","ObjectAttributes":"0xfffff880047437e8","ProcessHandle":"0xffffffff800002b8","StartRoutine":"0x7754fbc0","Argument":"0x22dfd0","CreateFlags":"0x1","ZeroBits":"0x0","StackSize":"0x8000","MaximumStackSize":"0x80000","AttributeList":"0xfffff88004743830"}
Traceback (most recent call last):
  File "D:\Python_code\drakparse.py", line 177, in parse_logs
    converted = str(plugin_obj(line_obj))
  File "D:\Python_code\drakparse.py", line 110, in __init__
    super().__init__(obj, "Thread Create", "")
  File "D:\Python_code\drakparse.py", line 13, in __init__
    self.timestamp = datetime.utcfromtimestamp(float(obj["TimeStamp"])).strftime("%-I:%-M:%-S.%f %p")
ValueError: Invalid format string
icedevml commented 3 years ago

Hi, thanks for the reports.

This compatibility layer between DRAKVUF Engine and ProcDOT is unfortunately pretty hard to maintain. We don't want to maintain this integration anymore and instead we will propose some alternative (custom) solution.

didelphodon commented 3 years ago

Sad to hear 'bout that. Actually, ProcDOT's import format didn't change since I shared the technical specs regarding the import format with you guys. If you need some hint let me know.

vornick commented 3 years ago

I found a solution to this problem: Process proc2dot successfully finished and i see error after that :

Apr 21 09:30:16 alex-virtual-machine drak-postprocess[866]: Collecting Procmon data ...
Apr 21 09:30:16 alex-virtual-machine drak-postprocess[866]: 117 lines
Apr 21 09:30:16 alex-virtual-machine drak-postprocess[866]: 23 processes
Apr 21 09:30:16 alex-virtual-machine drak-postprocess[866]: 90 threads
Apr 21 09:30:16 alex-virtual-machine drak-postprocess[866]: 0 files
Apr 21 09:30:16 alex-virtual-machine drak-postprocess[866]: 0 registry keys
Apr 21 09:30:16 alex-virtual-machine drak-postprocess[866]: 0 servers
Apr 21 09:30:16 alex-virtual-machine drak-postprocess[866]: 0 connections
Apr 21 09:30:16 alex-virtual-machine drak-postprocess[866]: Done.
......
Apr 21 09:30:16 alex-virtual-machine drak-postprocess[866]: minio.fput_object("drakrun", f"{analysis_uid}/graph.dot", os.path.join(output_dir, 'graph.dot'))
Apr 21 09:30:16 alex-virtual-machine drak-postprocess[866]: File "/opt/venvs/drakcore/lib/python3.8/site-packages/minio/api.py", line 628, in fput_object
Apr 21 09:30:16 alex-virtual-machine drak-postprocess[866]: with open(file_path, 'rb') as file_data:
Apr 21 09:30:16 alex-virtual-machine drak-postprocess[866]: FileNotFoundError: [Errno 2] No such file or directory: '/tmp/tmpa60t04kq/graph.dot'

it is clear that the minio.fput_object does not find the file graph.dot in output_dir. The problem is that the file (result of work tempfile.temporarydirectory function) delete before it push into the minio function. "It will be destroyed as soon as it is closed " - https://docs.python.org/3/library/tempfile.html Solution is simple - add 4 spaces before the minio.fput_object in file /opt/venvs/drakcore/lib/python3.8/site-packages/drakcore/postprocess/generate_graphs.py. Then the temp file (tmp/tmpa60t04kq/graph.dot) will be deleted after passing to the function: image And restart drak-postprocess service

Alex1under commented 3 years ago

I found a solution to this problem: Process proc2dot successfully finished and i see error after that :

Apr 21 09:30:16 alex-virtual-machine drak-postprocess[866]: Collecting Procmon data ...
Apr 21 09:30:16 alex-virtual-machine drak-postprocess[866]: 117 lines
Apr 21 09:30:16 alex-virtual-machine drak-postprocess[866]: 23 processes
Apr 21 09:30:16 alex-virtual-machine drak-postprocess[866]: 90 threads
Apr 21 09:30:16 alex-virtual-machine drak-postprocess[866]: 0 files
Apr 21 09:30:16 alex-virtual-machine drak-postprocess[866]: 0 registry keys
Apr 21 09:30:16 alex-virtual-machine drak-postprocess[866]: 0 servers
Apr 21 09:30:16 alex-virtual-machine drak-postprocess[866]: 0 connections
Apr 21 09:30:16 alex-virtual-machine drak-postprocess[866]: Done.
......
Apr 21 09:30:16 alex-virtual-machine drak-postprocess[866]: minio.fput_object("drakrun", f"{analysis_uid}/graph.dot", os.path.join(output_dir, 'graph.dot'))
Apr 21 09:30:16 alex-virtual-machine drak-postprocess[866]: File "/opt/venvs/drakcore/lib/python3.8/site-packages/minio/api.py", line 628, in fput_object
Apr 21 09:30:16 alex-virtual-machine drak-postprocess[866]: with open(file_path, 'rb') as file_data:
Apr 21 09:30:16 alex-virtual-machine drak-postprocess[866]: FileNotFoundError: [Errno 2] No such file or directory: '/tmp/tmpa60t04kq/graph.dot'

it is clear that the minio.fput_object does not find the file graph.dot in output_dir. The problem is that the file (result of work tempfile.temporarydirectory function) delete before it push into the minio function. "It will be destroyed as soon as it is closed " - https://docs.python.org/3/library/tempfile.html Solution is simple - add 4 spaces before the minio.fput_object in file /opt/venvs/drakcore/lib/python3.8/site-packages/drakcore/postprocess/generate_graphs.py. Then the temp file (tmp/tmpa60t04kq/graph.dot) will be deleted after passing to the function: image And restart drak-postprocess service

Yeah, u are right, this works for me. Thank you=) But i get "white screen" in analysys report. shot111 When i tried to launch procdot manually, i also got "white screen" untill turning on "dumb" view. Though in spec there is no words about that. As i remember it turn on/off some sort of aggregation and so on. Do u get something like mine?

Alex1under commented 3 years ago

UPD. I tried all the same in win10 guest and get normal picture. image

didelphodon commented 3 years ago

the reason for a blank/white screen when not using dumb mode is usually caused by a missing launcher. the latter can be defined manually in standalone ProcDOT or via a specific procmon csv row constellation, which is described in my shared specs document.

Alex1under @.***> schrieb am Mo. 26. Apr. 2021 um 12:49:

UPD. I tried all the same in win10 guest and get normal picture. [image: image] https://user-images.githubusercontent.com/62007804/116071132-2cb07880-a696-11eb-867e-66c5de4bf90a.png

— You are receiving this because you commented. Reply to this email directly, view it on GitHub https://github.com/CERT-Polska/drakvuf-sandbox/issues/520#issuecomment-826732440, or unsubscribe https://github.com/notifications/unsubscribe-auth/ACT27VJL52NPQUWPEEVEO7TTKVAL5ANCNFSM43KRQUSA .