Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Improvement to process.py logging #2005

Merged
merged 3 commits into from
Mar 15, 2024

Conversation

rkoumis
Copy link
Contributor

@rkoumis rkoumis commented Mar 11, 2024

Log the image name as well as the process ID; added tests.
Also, restore the process is_alive check, disabled 4 years ago.

Credit: @nbargnesi

Sample log entries:

2024-03-10 12:12:13,411 [lib.api.process] DEBUG: getting exit code for <Process 17492 aspnet_compiler.exe>
2024-03-10 12:12:13,411 [lib.api.process] DEBUG: <Process 17492 aspnet_compiler.exe> exit code is 259
2024-03-10 12:12:13,411 [lib.api.process] DEBUG: <Process 17492 aspnet_compiler.exe> is still active

@doomedraven
Copy link
Collaborator

LGTM, what about you @kevoreilly ?

@kevoreilly
Copy link
Owner

I've just tested it and seen that the log spamming that apparently prompted me to disable the is_alive check 4 years ago is brought back with this PR:

2024-03-11 14:58:47,577 [lib.api.process] INFO: injected into 64-bit <Process 1496 svchost.exe>
2024-03-11 14:58:48,265 [lib.api.process] DEBUG: getting exit code for <Process 3928 msiexec.exe>
2024-03-11 14:58:48,265 [lib.api.process] DEBUG: <Process 3928 msiexec.exe> exit code is 259
2024-03-11 14:58:48,265 [lib.api.process] DEBUG: <Process 3928 msiexec.exe> is still active
2024-03-11 14:58:48,265 [lib.api.process] DEBUG: getting exit code for <Process 832 svchost.exe>
2024-03-11 14:58:48,265 [lib.api.process] DEBUG: <Process 832 svchost.exe> exit code is 259
2024-03-11 14:58:48,265 [lib.api.process] DEBUG: <Process 832 svchost.exe> is still active
2024-03-11 14:58:48,265 [lib.api.process] WARNING: OpenProcess(PROCESS_ALL_ACCESS, ...) failed for process 696
2024-03-11 14:58:48,265 [lib.api.process] DEBUG: opening process with limited info 696
2024-03-11 14:58:48,265 [lib.api.process] DEBUG: getting exit code for <Process 696 services.exe>
2024-03-11 14:58:48,265 [lib.api.process] DEBUG: <Process 696 services.exe> exit code is 259
2024-03-11 14:58:48,265 [lib.api.process] DEBUG: <Process 696 services.exe> is still active
2024-03-11 14:58:48,265 [lib.api.process] DEBUG: getting exit code for <Process 1804 msiexec.exe>
2024-03-11 14:58:48,265 [lib.api.process] DEBUG: <Process 1804 msiexec.exe> exit code is 259
2024-03-11 14:58:48,265 [lib.api.process] DEBUG: <Process 1804 msiexec.exe> is still active
2024-03-11 14:58:48,265 [lib.api.process] DEBUG: getting exit code for <Process 1724 msiexec.exe>
2024-03-11 14:58:48,265 [lib.api.process] DEBUG: <Process 1724 msiexec.exe> exit code is 259
2024-03-11 14:58:48,265 [lib.api.process] DEBUG: <Process 1724 msiexec.exe> is still active
2024-03-11 14:58:48,265 [lib.api.process] DEBUG: getting exit code for <Process 6104 MSIB284.tmp>
2024-03-11 14:58:48,265 [lib.api.process] DEBUG: <Process 6104 MSIB284.tmp> exit code is 259
2024-03-11 14:58:48,265 [lib.api.process] DEBUG: <Process 6104 MSIB284.tmp> is still active
2024-03-11 14:58:48,265 [lib.api.process] DEBUG: getting exit code for <Process 4364 explorer.exe>
2024-03-11 14:58:48,265 [lib.api.process] DEBUG: <Process 4364 explorer.exe> exit code is 259
2024-03-11 14:58:48,265 [lib.api.process] DEBUG: <Process 4364 explorer.exe> is still active
2024-03-11 14:58:48,265 [lib.api.process] DEBUG: getting exit code for <Process 1056 rundll32.exe>
2024-03-11 14:58:48,265 [lib.api.process] DEBUG: <Process 1056 rundll32.exe> exit code is 259
2024-03-11 14:58:48,265 [lib.api.process] DEBUG: <Process 1056 rundll32.exe> is still active
2024-03-11 14:58:48,265 [lib.api.process] DEBUG: getting exit code for <Process 1496 svchost.exe>
2024-03-11 14:58:48,265 [lib.api.process] DEBUG: <Process 1496 svchost.exe> exit code is 259
2024-03-11 14:58:48,265 [lib.api.process] DEBUG: <Process 1496 svchost.exe> is still active
2024-03-11 14:58:49,280 [lib.api.process] DEBUG: getting exit code for <Process 3928 msiexec.exe>
2024-03-11 14:58:49,280 [lib.api.process] DEBUG: <Process 3928 msiexec.exe> exit code is 259
2024-03-11 14:58:49,280 [lib.api.process] DEBUG: <Process 3928 msiexec.exe> is still active
2024-03-11 14:58:49,280 [lib.api.process] DEBUG: getting exit code for <Process 832 svchost.exe>
2024-03-11 14:58:49,280 [lib.api.process] DEBUG: <Process 832 svchost.exe> exit code is 259
2024-03-11 14:58:49,280 [lib.api.process] DEBUG: <Process 832 svchost.exe> is still active
2024-03-11 14:58:49,280 [lib.api.process] WARNING: OpenProcess(PROCESS_ALL_ACCESS, ...) failed for process 696
2024-03-11 14:58:49,280 [lib.api.process] DEBUG: opening process with limited info 696
2024-03-11 14:58:49,280 [lib.api.process] DEBUG: getting exit code for <Process 696 services.exe>
2024-03-11 14:58:49,280 [lib.api.process] DEBUG: <Process 696 services.exe> exit code is 259
2024-03-11 14:58:49,280 [lib.api.process] DEBUG: <Process 696 services.exe> is still active
2024-03-11 14:58:49,280 [lib.api.process] DEBUG: getting exit code for <Process 1804 msiexec.exe>
2024-03-11 14:58:49,280 [lib.api.process] DEBUG: <Process 1804 msiexec.exe> exit code is 259
2024-03-11 14:58:49,280 [lib.api.process] DEBUG: <Process 1804 msiexec.exe> is still active
2024-03-11 14:58:49,280 [lib.api.process] DEBUG: getting exit code for <Process 1724 msiexec.exe>
2024-03-11 14:58:49,280 [lib.api.process] DEBUG: <Process 1724 msiexec.exe> exit code is 259
2024-03-11 14:58:49,280 [lib.api.process] DEBUG: <Process 1724 msiexec.exe> is still active
2024-03-11 14:58:49,280 [lib.api.process] DEBUG: getting exit code for <Process 6104 MSIB284.tmp>
2024-03-11 14:58:49,280 [lib.api.process] DEBUG: <Process 6104 MSIB284.tmp> exit code is 259
2024-03-11 14:58:49,280 [lib.api.process] DEBUG: <Process 6104 MSIB284.tmp> is still active
2024-03-11 14:58:49,280 [lib.api.process] DEBUG: getting exit code for <Process 4364 explorer.exe>
2024-03-11 14:58:49,280 [lib.api.process] DEBUG: <Process 4364 explorer.exe> exit code is 259
2024-03-11 14:58:49,280 [lib.api.process] DEBUG: <Process 4364 explorer.exe> is still active
2024-03-11 14:58:49,280 [lib.api.process] DEBUG: getting exit code for <Process 1056 rundll32.exe>
2024-03-11 14:58:49,280 [lib.api.process] DEBUG: <Process 1056 rundll32.exe> exit code is 259
2024-03-11 14:58:49,280 [lib.api.process] DEBUG: <Process 1056 rundll32.exe> is still active
2024-03-11 14:58:49,280 [lib.api.process] DEBUG: getting exit code for <Process 1496 svchost.exe>
2024-03-11 14:58:49,280 [lib.api.process] DEBUG: <Process 1496 svchost.exe> exit code is 259
2024-03-11 14:58:49,280 [lib.api.process] DEBUG: <Process 1496 svchost.exe> is still active

@kevoreilly
Copy link
Owner

If we can quiten these messages down to an 'acceptable' level then I think it should be ok.

@rkoumis rkoumis marked this pull request as draft March 11, 2024 18:25
@kevoreilly kevoreilly marked this pull request as ready for review March 11, 2024 21:58
Log the image name as well as the process ID; added tests.
Also, restore the process is_alive check, disabled 4 years ago.
Consequently, commented out excessive logging.
Credit: @nbargnesi
@rkoumis
Copy link
Contributor Author

rkoumis commented Mar 12, 2024

I've commented out the verbose / spammy logging, @kevoreilly @doomedraven

I squashed the commits back down to one, and now I realize I probably shouldn't have, sorry. Anyhow, that's what I did. Let me know if any questions.

@doomedraven
Copy link
Collaborator

im not having time right now to test, was you able to test @kevoreilly latest commit? if no i will do that in 1-2 days

@kevoreilly
Copy link
Owner

Yep I'll test it tomorrow

@rkoumis
Copy link
Contributor Author

rkoumis commented Mar 15, 2024

no rush but please take another look when you get a chance

@kevoreilly
Copy link
Owner

I've been running this on my main server for the last few days - I just need to check the logs.

@kevoreilly
Copy link
Owner

I wonder if this line is ok:

log.debug("Failed getting exit code for %s", self)

Is self not gonna bomb as not a string type?

@rkoumis
Copy link
Contributor Author

rkoumis commented Mar 15, 2024

The new __str__() method will take care of converting a Process to a string. That's how come in your first round of testing you saw messages like

DEBUG: <Process 4364 explorer.exe> is still active
    def __str__(self):
        """Get a string representation of this process."""
        image_name = self.get_image_name() or "???"
        return f"<{self.__class__.__name__} {self.pid} {image_name}>"

@kevoreilly kevoreilly merged commit d532a71 into kevoreilly:master Mar 15, 2024
3 of 5 checks passed
@kevoreilly
Copy link
Owner

Thank you!

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

3 participants