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.

Sign up for GitHub

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

Jump to bottom

Added debug logging on container lifecycles #689

Merged
merged 11 commits into from
Dec 28, 2022
Merged

Added debug logging on container lifecycles #689

merged 11 commits into from
Dec 28, 2022

Conversation

ramo-j
Copy link
Collaborator

@ramo-j ramo-j commented Dec 20, 2022 •
edited
Loading

Adding in logging information to assist in debugging container issues with complex recipes. Log example from grr_flow_collect (new lines in bold):

$ DFTIMEWOLF_NO_CURSES=1 poetry run python3 -m dftimewolf.cli.dftimewolf_recipes grr_flow_collect --grr_server_url http:https://10.152.0.12:8000 --grr_username admin --grr_password password C.1facf5562db006ad,C.fec0d977e47fb213,C.a4187e1a91937d51,C.8c769deeb2964e69 77DE05B946A90F6E,55449F640F3E5B5C,31F6E0183E423BC7,C461AAD1B45EC172 reason /tmp/out/
[2022-12-20 02:56:03,210] [dftimewolf          ] DEBUG    Logging to stdout and /tmp/dftimewolf-run-20221220_025603_1ggzelak.log
[2022-12-20 02:56:03,210] [dftimewolf          ] SUCCESS  Success!
[2022-12-20 02:56:03,210] [dftimewolf          ] DEBUG    Recipe data path: /home/ramoj_google_com/code/dftimewolf/data
[2022-12-20 02:56:03,210] [dftimewolf          ] DEBUG    Configuration loaded from: /home/ramoj_google_com/code/dftimewolf/data/config.json
[2022-12-20 02:56:03,229] [dftimewolf          ] INFO     Loading recipe grr_flow_collect...
[2022-12-20 02:56:03,229] [dftimewolf          ] DEBUG    Loading module GRRFlowCollector from dftimewolf.lib.collectors.grr_hosts
[2022-12-20 02:56:03,850] [dftimewolf          ] DEBUG    Loading module LocalFilesystemCopy from dftimewolf.lib.exporters.local_filesystem
[2022-12-20 02:56:03,851] [dftimewolf          ] INFO     Loaded recipe grr_flow_collect with 2 modules
[2022-12-20 02:56:03,851] [dftimewolf          ] DEBUG    GRRFlowCollector:
[2022-12-20 02:56:03,851] [dftimewolf          ] DEBUG      hostnames              'C.1facf5562db006ad,C.fec0d977e47fb213,C.a4187e1a91937d51,C.8c769deeb2964e69'
[2022-12-20 02:56:03,851] [dftimewolf          ] DEBUG      flow_ids               '77DE05B946A90F6E,55449F640F3E5B5C,31F6E0183E423BC7,C461AAD1B45EC172'
[2022-12-20 02:56:03,851] [dftimewolf          ] DEBUG      reason                 'reason'
[2022-12-20 02:56:03,851] [dftimewolf          ] DEBUG      grr_server_url         'http:https://10.152.0.12:8000'
[2022-12-20 02:56:03,851] [dftimewolf          ] DEBUG      grr_username           'admin'
[2022-12-20 02:56:03,851] [dftimewolf          ] DEBUG      grr_password           'password'
[2022-12-20 02:56:03,851] [dftimewolf          ] DEBUG      approvers              None
[2022-12-20 02:56:03,852] [dftimewolf          ] DEBUG      verify                 True
[2022-12-20 02:56:03,852] [dftimewolf          ] DEBUG      skip_offline_clients   False
[2022-12-20 02:56:03,852] [dftimewolf          ] DEBUG    LocalFilesystemCopy:
[2022-12-20 02:56:03,852] [dftimewolf          ] DEBUG      target_directory       '/tmp/out/'
[2022-12-20 02:56:03,852] [dftimewolf          ] DEBUG      compress               False
[2022-12-20 02:56:03,852] [dftimewolf          ] DEBUG    
[2022-12-20 02:56:03,852] [dftimewolf          ] INFO     Running preflights...
[2022-12-20 02:56:03,852] [dftimewolf          ] INFO     Setting up modules...
[2022-12-20 02:56:03,852] [dftimewolf          ] INFO     Setting up module: GRRFlowCollector
[2022-12-20 02:56:03,852] [dftimewolf          ] INFO     Setting up module: LocalFilesystemCopy
[2022-12-20 02:56:03,904] [GRRFlowCollector    ] INFO     Searching for client: C.1facf5562db006ad
[2022-12-20 02:56:04,429] [GRRFlowCollector    ] INFO     Found active client: C.1facf5562db006ad
[2022-12-20 02:56:04,430] [GRRFlowCollector    ] INFO     Client last seen: 2022-12-20T02:47:00+0000 (9 minutes ago)
[2022-12-20 02:56:04,481] [GRRFlowCollector    ] WARNING  Flow 77DE05B946A90F6E not found in C.1facf5562db006ad
[2022-12-20 02:56:04,533] [GRRFlowCollector    ] WARNING  Flow 55449F640F3E5B5C not found in C.1facf5562db006ad
[2022-12-20 02:56:04,588] [dftimewolf          ] DEBUG    GRRFlowCollector is storing a grr_flow container: C.1facf5562db006ad:31F6E0183E423BC7
[2022-12-20 02:56:04,639] [GRRFlowCollector    ] WARNING  Flow C461AAD1B45EC172 not found in C.1facf5562db006ad
[2022-12-20 02:56:04,640] [GRRFlowCollector    ] INFO     Searching for client: C.fec0d977e47fb213
[2022-12-20 02:56:04,746] [GRRFlowCollector    ] INFO     Found active client: C.fec0d977e47fb213
[2022-12-20 02:56:04,746] [GRRFlowCollector    ] INFO     Client last seen: 2022-12-20T02:47:03+0000 (9 minutes ago)
[2022-12-20 02:56:04,798] [GRRFlowCollector    ] WARNING  Flow 77DE05B946A90F6E not found in C.fec0d977e47fb213
[2022-12-20 02:56:04,852] [dftimewolf          ] DEBUG    GRRFlowCollector is storing a grr_flow container: C.fec0d977e47fb213:55449F640F3E5B5C
[2022-12-20 02:56:04,904] [GRRFlowCollector    ] WARNING  Flow 31F6E0183E423BC7 not found in C.fec0d977e47fb213
[2022-12-20 02:56:04,956] [GRRFlowCollector    ] WARNING  Flow C461AAD1B45EC172 not found in C.fec0d977e47fb213
[2022-12-20 02:56:04,957] [GRRFlowCollector    ] INFO     Searching for client: C.a4187e1a91937d51
[2022-12-20 02:56:05,064] [GRRFlowCollector    ] INFO     Found active client: C.a4187e1a91937d51
[2022-12-20 02:56:05,064] [GRRFlowCollector    ] INFO     Client last seen: 2022-12-20T02:51:19+0000 (5 minutes ago)
[2022-12-20 02:56:05,118] [dftimewolf          ] DEBUG    GRRFlowCollector is storing a grr_flow container: C.a4187e1a91937d51:77DE05B946A90F6E
[2022-12-20 02:56:05,170] [GRRFlowCollector    ] WARNING  Flow 55449F640F3E5B5C not found in C.a4187e1a91937d51
[2022-12-20 02:56:05,222] [GRRFlowCollector    ] WARNING  Flow 31F6E0183E423BC7 not found in C.a4187e1a91937d51
[2022-12-20 02:56:05,273] [GRRFlowCollector    ] WARNING  Flow C461AAD1B45EC172 not found in C.a4187e1a91937d51
[2022-12-20 02:56:05,274] [GRRFlowCollector    ] INFO     Searching for client: C.8c769deeb2964e69
[2022-12-20 02:56:05,380] [GRRFlowCollector    ] INFO     Found active client: C.8c769deeb2964e69
[2022-12-20 02:56:05,381] [GRRFlowCollector    ] INFO     Client last seen: 2022-12-20T02:52:01+0000 (4 minutes ago)
[2022-12-20 02:56:05,433] [GRRFlowCollector    ] WARNING  Flow 77DE05B946A90F6E not found in C.8c769deeb2964e69
[2022-12-20 02:56:05,484] [GRRFlowCollector    ] WARNING  Flow 55449F640F3E5B5C not found in C.8c769deeb2964e69
[2022-12-20 02:56:05,536] [GRRFlowCollector    ] WARNING  Flow 31F6E0183E423BC7 not found in C.8c769deeb2964e69
[2022-12-20 02:56:05,590] [dftimewolf          ] DEBUG    GRRFlowCollector is storing a grr_flow container: C.8c769deeb2964e69:C461AAD1B45EC172
[2022-12-20 02:56:05,590] [dftimewolf          ] INFO     Modules successfully set up!
[2022-12-20 02:56:05,590] [dftimewolf          ] INFO     Running modules...
[2022-12-20 02:56:05,591] [dftimewolf          ] INFO     Running module: GRRFlowCollector
[2022-12-20 02:56:05,591] [dftimewolf          ] DEBUG    GRRFlowCollector is retrieving 4 grr_flow containers:
[2022-12-20 02:56:05,591] [dftimewolf          ] DEBUG      * C.1facf5562db006ad:31F6E0183E423BC7 - origin: GRRFlowCollector
[2022-12-20 02:56:05,591] [dftimewolf          ] DEBUG      * C.fec0d977e47fb213:55449F640F3E5B5C - origin: GRRFlowCollector
[2022-12-20 02:56:05,591] [dftimewolf          ] DEBUG      * C.a4187e1a91937d51:77DE05B946A90F6E - origin: GRRFlowCollector
[2022-12-20 02:56:05,591] [dftimewolf          ] DEBUG      * C.8c769deeb2964e69:C461AAD1B45EC172 - origin: GRRFlowCollector
[2022-12-20 02:56:05,591] [dftimewolf          ] INFO     Running 4 threads, max 10 simultaneous for module GRRFlowCollector
[2022-12-20 02:56:05,592] [dftimewolf          ] DEBUG    Launching GRRFlowCollector.Process thread with C.1facf5562db006ad:31F6E0183E423BC7 from GRRFlowCollector
[2022-12-20 02:56:05,592] [dftimewolf          ] DEBUG    Launching GRRFlowCollector.Process thread with C.fec0d977e47fb213:55449F640F3E5B5C from GRRFlowCollector
[2022-12-20 02:56:05,592] [dftimewolf          ] DEBUG    Launching GRRFlowCollector.Process thread with C.a4187e1a91937d51:77DE05B946A90F6E from GRRFlowCollector
[2022-12-20 02:56:05,593] [dftimewolf          ] DEBUG    Launching GRRFlowCollector.Process thread with C.8c769deeb2964e69:C461AAD1B45EC172 from GRRFlowCollector
[2022-12-20 02:56:05,592] [GRRFlowCollector    ] INFO     [ThreadPoolExecutor-0_0] Searching for client: C.1facf5562db006ad
[2022-12-20 02:56:05,592] [GRRFlowCollector    ] INFO     [ThreadPoolExecutor-0_1] Searching for client: C.fec0d977e47fb213
[2022-12-20 02:56:05,593] [GRRFlowCollector    ] INFO     [ThreadPoolExecutor-0_2] Searching for client: C.a4187e1a91937d51
[2022-12-20 02:56:05,593] [GRRFlowCollector    ] INFO     [ThreadPoolExecutor-0_3] Searching for client: C.8c769deeb2964e69
[2022-12-20 02:56:05,712] [GRRFlowCollector    ] INFO     [ThreadPoolExecutor-0_0] Found active client: C.1facf5562db006ad
[2022-12-20 02:56:05,713] [GRRFlowCollector    ] INFO     [ThreadPoolExecutor-0_1] Found active client: C.fec0d977e47fb213
[2022-12-20 02:56:05,713] [GRRFlowCollector    ] INFO     [ThreadPoolExecutor-0_0] Client last seen: 2022-12-20T02:47:00+0000 (9 minutes ago)
[2022-12-20 02:56:05,714] [GRRFlowCollector    ] INFO     [ThreadPoolExecutor-0_1] Client last seen: 2022-12-20T02:47:03+0000 (9 minutes ago)
[2022-12-20 02:56:05,714] [GRRFlowCollector    ] INFO     [ThreadPoolExecutor-0_0] 31F6E0183E423BC7: Waiting to finish
[2022-12-20 02:56:05,714] [GRRFlowCollector    ] INFO     [ThreadPoolExecutor-0_1] 55449F640F3E5B5C: Waiting to finish
[2022-12-20 02:56:05,715] [GRRFlowCollector    ] INFO     [ThreadPoolExecutor-0_3] Found active client: C.8c769deeb2964e69
[2022-12-20 02:56:05,717] [GRRFlowCollector    ] INFO     [ThreadPoolExecutor-0_2] Found active client: C.a4187e1a91937d51
[2022-12-20 02:56:05,719] [GRRFlowCollector    ] INFO     [ThreadPoolExecutor-0_3] Client last seen: 2022-12-20T02:52:01+0000 (4 minutes ago)
[2022-12-20 02:56:05,719] [GRRFlowCollector    ] INFO     [ThreadPoolExecutor-0_2] Client last seen: 2022-12-20T02:51:19+0000 (5 minutes ago)
[2022-12-20 02:56:05,720] [GRRFlowCollector    ] INFO     [ThreadPoolExecutor-0_3] C461AAD1B45EC172: Waiting to finish
[2022-12-20 02:56:05,720] [GRRFlowCollector    ] INFO     [ThreadPoolExecutor-0_2] 77DE05B946A90F6E: Waiting to finish
[2022-12-20 02:56:05,772] [GRRFlowCollector    ] INFO     [ThreadPoolExecutor-0_0] 31F6E0183E423BC7: Complete
[2022-12-20 02:56:05,776] [GRRFlowCollector    ] INFO     [ThreadPoolExecutor-0_1] 55449F640F3E5B5C: Complete
[2022-12-20 02:56:05,779] [GRRFlowCollector    ] INFO     [ThreadPoolExecutor-0_3] C461AAD1B45EC172: Complete
[2022-12-20 02:56:05,781] [GRRFlowCollector    ] INFO     [ThreadPoolExecutor-0_2] 77DE05B946A90F6E: Complete
[2022-12-20 02:56:09,495] [GRRFlowCollector    ] INFO     [ThreadPoolExecutor-0_2] 77DE05B946A90F6E: Downloaded: /tmp/tmpd3zlmi0l/grr-client-debian.c.ramoj-playground.internal/77DE05B946A90F6E
[2022-12-20 02:56:09,496] [dftimewolf          ] DEBUG    GRRFlowCollector is storing a file container: /tmp/tmpd3zlmi0l/grr-client-debian.c.ramoj-playground.internal/77DE05B946A90F6E/grr-client-debian.c.ramoj-playground.internal
[2022-12-20 02:56:10,250] [GRRFlowCollector    ] INFO     [ThreadPoolExecutor-0_3] C461AAD1B45EC172: Downloaded: /tmp/tmpd3zlmi0l/grr-client-ubuntu.c.ramoj-playground.internal/C461AAD1B45EC172
[2022-12-20 02:56:10,251] [dftimewolf          ] DEBUG    GRRFlowCollector is storing a file container: /tmp/tmpd3zlmi0l/grr-client-ubuntu.c.ramoj-playground.internal/C461AAD1B45EC172/grr-client-ubuntu.c.ramoj-playground.internal
[2022-12-20 02:56:10,322] [GRRFlowCollector    ] INFO     [ThreadPoolExecutor-0_1] 55449F640F3E5B5C: Downloaded: /tmp/tmpd3zlmi0l/grr-client-centos.c.ramoj-playground.internal/55449F640F3E5B5C
[2022-12-20 02:56:10,323] [dftimewolf          ] DEBUG    GRRFlowCollector is storing a file container: /tmp/tmpd3zlmi0l/grr-client-centos.c.ramoj-playground.internal/55449F640F3E5B5C/grr-client-centos.c.ramoj-playground.internal
[2022-12-20 02:56:16,147] [GRRFlowCollector    ] INFO     [ThreadPoolExecutor-0_0] 31F6E0183E423BC7: Downloaded: /tmp/tmpd3zlmi0l/grr-client-windows.c.ramoj-playground.internal./31F6E0183E423BC7
[2022-12-20 02:56:16,148] [dftimewolf          ] DEBUG    GRRFlowCollector is storing a file container: /tmp/tmpd3zlmi0l/grr-client-windows.c.ramoj-playground.internal./31F6E0183E423BC7/grr-client-windows.c.ramoj-playground.internal.
[2022-12-20 02:56:16,148] [dftimewolf          ] INFO     Module GRRFlowCollector finished execution
[2022-12-20 02:56:16,149] [dftimewolf          ] INFO     Running module: LocalFilesystemCopy
[2022-12-20 02:56:16,149] [dftimewolf          ] DEBUG    LocalFilesystemCopy is popping 4 file containers:
[2022-12-20 02:56:16,149] [dftimewolf          ] DEBUG      * /tmp/tmpd3zlmi0l/grr-client-debian.c.ramoj-playground.internal/77DE05B946A90F6E/grr-client-debian.c.ramoj-playground.internal - origin: GRRFlowCollector
[2022-12-20 02:56:16,149] [dftimewolf          ] DEBUG      * /tmp/tmpd3zlmi0l/grr-client-ubuntu.c.ramoj-playground.internal/C461AAD1B45EC172/grr-client-ubuntu.c.ramoj-playground.internal - origin: GRRFlowCollector
[2022-12-20 02:56:16,149] [dftimewolf          ] DEBUG      * /tmp/tmpd3zlmi0l/grr-client-centos.c.ramoj-playground.internal/55449F640F3E5B5C/grr-client-centos.c.ramoj-playground.internal - origin: GRRFlowCollector
[2022-12-20 02:56:16,149] [dftimewolf          ] DEBUG      * /tmp/tmpd3zlmi0l/grr-client-windows.c.ramoj-playground.internal./31F6E0183E423BC7/grr-client-windows.c.ramoj-playground.internal. - origin: GRRFlowCollector
[2022-12-20 02:56:16,149] [LocalFilesystemCopy ] INFO     /tmp/tmpd3zlmi0l/grr-client-debian.c.ramoj-playground.internal/77DE05B946A90F6E -> /tmp/out/
[2022-12-20 02:56:16,157] [dftimewolf          ] DEBUG    LocalFilesystemCopy is storing a file container: /tmp/out//
[2022-12-20 02:56:16,157] [LocalFilesystemCopy ] INFO     /tmp/tmpd3zlmi0l/grr-client-ubuntu.c.ramoj-playground.internal/C461AAD1B45EC172 -> /tmp/out/
[2022-12-20 02:56:16,166] [dftimewolf          ] DEBUG    LocalFilesystemCopy is storing a file container: /tmp/out//
[2022-12-20 02:56:16,166] [LocalFilesystemCopy ] INFO     /tmp/tmpd3zlmi0l/grr-client-centos.c.ramoj-playground.internal/55449F640F3E5B5C -> /tmp/out/
[2022-12-20 02:56:16,175] [dftimewolf          ] DEBUG    LocalFilesystemCopy is storing a file container: /tmp/out//
[2022-12-20 02:56:16,175] [LocalFilesystemCopy ] INFO     /tmp/tmpd3zlmi0l/grr-client-windows.c.ramoj-playground.internal./31F6E0183E423BC7 -> /tmp/out/
[2022-12-20 02:56:16,228] [dftimewolf          ] DEBUG    LocalFilesystemCopy is storing a file container: /tmp/out//
[2022-12-20 02:56:16,228] [dftimewolf          ] INFO     Module LocalFilesystemCopy finished execution
[2022-12-20 02:56:16,229] [dftimewolf          ] INFO     Recipe grr_flow_collect executed successfully!
[2022-12-20 02:56:16,229] [dftimewolf          ] INFO     No statistics collected during execution.
[2022-12-20 02:56:16,229] [dftimewolf          ] INFO     0 stat entries collected during execution.

Fixes #688

@ramo-j ramo-j marked this pull request as ready for review December 20, 2022 03:10
@ramo-j ramo-j requested a review from tomchop December 20, 2022 03:10
tomchop
tomchop requested changes Dec 20, 2022
View reviewed changes
dftimewolf/lib/state.py Outdated Show resolved Hide resolved
dftimewolf/lib/state.py Outdated Show resolved Hide resolved
dftimewolf/lib/state.py Outdated Show resolved Hide resolved
@ramo-j
Copy link
Collaborator Author

ramo-j commented Dec 21, 2022

Log excerpt with the PR notes incorporated:

<snip>
[2022-12-20 23:59:11,006] [dftimewolf          ] DEBUG    RandomRuntimeName is storing a file container: /tmp/tmp8d7a8efk/grr-client-windows.c.ramoj-playground.internal./31F6E0183E423BC7/grr-client-windows.c.ramoj-playground.internal.
[2022-12-20 23:59:11,006] [dftimewolf          ] INFO     Module RandomRuntimeName finished execution
[2022-12-20 23:59:11,006] [dftimewolf          ] INFO     Running module: LocalFilesystemCopy
[2022-12-20 23:59:11,007] [dftimewolf          ] DEBUG    LocalFilesystemCopy is retrieving 4 file containers - pop == True
[2022-12-20 23:59:11,007] [dftimewolf          ] DEBUG      * /tmp/tmp8d7a8efk/grr-client-debian.c.ramoj-playground.internal/77DE05B946A90F6E/grr-client-debian.c.ramoj-playground.internal - origin: RandomRuntimeName
[2022-12-20 23:59:11,007] [dftimewolf          ] DEBUG      * /tmp/tmp8d7a8efk/grr-client-centos.c.ramoj-playground.internal/55449F640F3E5B5C/grr-client-centos.c.ramoj-playground.internal - origin: RandomRuntimeName
[2022-12-20 23:59:11,007] [dftimewolf          ] DEBUG      * /tmp/tmp8d7a8efk/grr-client-ubuntu.c.ramoj-playground.internal/C461AAD1B45EC172/grr-client-ubuntu.c.ramoj-playground.internal - origin: RandomRuntimeName
[2022-12-20 23:59:11,007] [dftimewolf          ] DEBUG      * /tmp/tmp8d7a8efk/grr-client-windows.c.ramoj-playground.internal./31F6E0183E423BC7/grr-client-windows.c.ramoj-playground.internal. - origin: RandomRuntimeName
<snip>

@ramo-j ramo-j requested a review from tomchop December 21, 2022 02:12
tomchop
tomchop requested changes Dec 21, 2022
View reviewed changes
dftimewolf/lib/state.py Outdated Show resolved Hide resolved
dftimewolf/lib/state.py Outdated Show resolved Hide resolved
@ramo-j ramo-j requested a review from tomchop December 28, 2022 02:46
tomchop
tomchop approved these changes Dec 28, 2022
View reviewed changes
Copy link
Collaborator

@tomchop tomchop left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

LGTM, thanks for implementing these changes! As a note for a potential future PR - we should probably do the same for the StreamContainer function no?

@tomchop tomchop merged commit 70aa36f into log2timeline:main Dec 28, 2022
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Reviewers

@tomchop tomchop tomchop approved these changes

Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

Successfully merging this pull request may close these issues.

Track source and destination of containers to simplify debugging
2 participants
@ramo-j @tomchop