GetLocalProfiles hangs

[JimmyAstle]

In running some tests the "Enumerating user profiles" steps hangs and never returns. In looking through the source the action looks to be executing fine but never returns the results. The StdOut from the step looks good and the correct user,sid information is displayed. I have a feeling something is hanging that await task.

My Test Env information: DC - Win2012R2 2 Member Clients - Win10 Enterprise x64 (10.0.14393 N/A Build 14393)

Im leveraging this issue as an opportunity to learn the code base and dig into logging an whatnot so any information you are willing to share to help troubleshoot would be awesome. I have put in a false command-line parameter to reg query in the source and was able to get this task to fail and then eventually continue but Im stuck in trying to fix this.

Thanks and keep up the awesome work!

[dm-mitre]

We use the python standard library logging so if you are familiar with that you already have a leg up. CALDERA should be outputting logging messages into the terminal that you start the python server on. First thing to look for is any kind of exception that might be being thrown.

One thing to check is whether the hang happens while executing a step, or somewhere else in the code. While CALDERA is in the middle of executing a step, that step will be blue on the web page. steps that are done running will be either red or green. It may appear that CALDERA is hanging on a step, but if its not blue its actually done running and hung somewhere else.

[dm-mitre]

I should also mention that you can check the Status/Phase/Action indicators in the "Operation Overview" box to see what is going on when CALDERA is hung.

[JimmyAstle]

Just following up on this. Here is the stack trace:

WARNING:app.logic.planner:Planning run took 0.01453027900000059 seconds and returned 12 actions
WARNING:app.logic.planner:Dedupping took 9.106000000258518e-06 seconds and returned 1 actions
WARNING:app.logic.planner:Optimization pruning took 2.4675000000584646e-05 seconds and returned 0 actions
WARNING:app.logic.planner:Recursion took 0.02431391299999852 seconds and explored 1 actions
WARNING:app.logic.planner:Action Breakdown:
WARNING:app.logic.planner:    1: GetLocalProfiles
WARNING:app.logic.planner:    0: WMIRemoteProcessCreate
DEBUG:app.logic.planner:Processed 1 plans
INFO:app.operation.operation:Planning time took: 0.03938897799999985 seconds
INFO:app.operation.operation:Running step get_local_profiles
INFO:app.server:Planner closed
Process Process-1:
Traceback (most recent call last):
  File "/usr/lib/python3.5/multiprocessing/process.py", line 249, in _bootstrap
    self.run()
  File "/usr/lib/python3.5/multiprocessing/process.py", line 93, in run
    self._target(*self._args, **self._kwargs)
  File "/root/caldera/caldera/app/server.py", line 165, in sigint_handler
    target()
  File "/root/caldera/caldera/app/server.py", line 306, in planner_process
    loop.run_until_complete(start_operations(rebuild_mappings))
  File "/usr/lib/python3.5/asyncio/base_events.py", line 466, in run_until_complete
    return future.result()
  File "/usr/lib/python3.5/asyncio/futures.py", line 293, in result
    raise self._exception
  File "/usr/lib/python3.5/asyncio/tasks.py", line 239, in _step
    result = coro.send(None)
  File "/root/caldera/caldera/app/updates.py", line 127, in start_operations
    await s.loop()
  File "/root/caldera/caldera/app/operation/operation.py", line 299, in loop
    await self._perform_next_step()
  File "/root/caldera/caldera/app/operation/operation.py", line 612, in _perform_next_step
    success = await next_step.action(*args)
  File "/root/caldera/caldera/app/operation/operation_steps.py", line 965, in action
    profile_path = q[key]['ProfileImagePath'].data
KeyError: 'ProfileImagePath'
ERROR:aiohttp.access:Error in logging
Traceback (most recent call last):
  File "/root/caldera/caldera/app/api.py", line 188, in query_jobs
    jobs = [(await Job.wait_next(query))]
  File "/root/caldera/caldera/app/engine/database.py", line 161, in wait_next
    _, c = await global_tailer.wait(cls._get_collection().full_name, filters)
  File "/root/caldera/caldera/app/engine/oplog.py", line 118, in wait
    return await tqueue.get()
  File "/usr/lib/python3.5/asyncio/queues.py", line 167, in get
    yield from getter
  File "/usr/lib/python3.5/asyncio/futures.py", line 380, in __iter__
    yield self  # This tells Task to wait for completion.
  File "/usr/lib/python3.5/asyncio/tasks.py", line 304, in _wakeup
    future.result()
  File "/usr/lib/python3.5/asyncio/futures.py", line 285, in result
    raise CancelledError
concurrent.futures._base.CancelledError

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/local/lib/python3.5/dist-packages/aiohttp/helpers.py", line 554, in __get__
    return inst._cache[self.name]
KeyError: 'remote'

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/local/lib/python3.5/dist-packages/aiohttp/helpers.py", line 521, in log
    for key, value in fmt_info:
  File "/usr/local/lib/python3.5/dist-packages/aiohttp/helpers.py", line 513, in <genexpr>
    for key, method in self._methods)
  File "/usr/local/lib/python3.5/dist-packages/aiohttp/helpers.py", line 473, in _format_a
    ip = request.remote
  File "/usr/local/lib/python3.5/dist-packages/aiohttp/helpers.py", line 556, in __get__
    val = self.wrapped(inst)
  File "/usr/local/lib/python3.5/dist-packages/aiohttp/web_request.py", line 321, in remote
    peername = transport.get_extra_info('peername')
  File "/usr/lib/python3.5/asyncio/sslproto.py", line 306, in get_extra_info
    return self._ssl_protocol._get_extra_info(name, default)
  File "/usr/lib/python3.5/asyncio/sslproto.py", line 546, in _get_extra_info
    return self._transport.get_extra_info(name, default)
AttributeError: 'NoneType' object has no attribute 'get_extra_info'
ERROR:aiohttp.access:Error in logging
Traceback (most recent call last):
  File "/root/caldera/caldera/app/api.py", line 188, in query_jobs
    jobs = [(await Job.wait_next(query))]
  File "/root/caldera/caldera/app/engine/database.py", line 161, in wait_next
    _, c = await global_tailer.wait(cls._get_collection().full_name, filters)
  File "/root/caldera/caldera/app/engine/oplog.py", line 118, in wait
    return await tqueue.get()
  File "/usr/lib/python3.5/asyncio/queues.py", line 167, in get
    yield from getter
  File "/usr/lib/python3.5/asyncio/futures.py", line 380, in __iter__
    yield self  # This tells Task to wait for completion.
  File "/usr/lib/python3.5/asyncio/tasks.py", line 304, in _wakeup
    future.result()
  File "/usr/lib/python3.5/asyncio/futures.py", line 285, in result
    raise CancelledError
concurrent.futures._base.CancelledError

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/local/lib/python3.5/dist-packages/aiohttp/helpers.py", line 554, in __get__
    return inst._cache[self.name]
KeyError: 'remote'

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/local/lib/python3.5/dist-packages/aiohttp/helpers.py", line 521, in log
    for key, value in fmt_info:
  File "/usr/local/lib/python3.5/dist-packages/aiohttp/helpers.py", line 513, in <genexpr>
    for key, method in self._methods)
  File "/usr/local/lib/python3.5/dist-packages/aiohttp/helpers.py", line 473, in _format_a
    ip = request.remote
  File "/usr/local/lib/python3.5/dist-packages/aiohttp/helpers.py", line 556, in __get__
    val = self.wrapped(inst)
  File "/usr/local/lib/python3.5/dist-packages/aiohttp/web_request.py", line 321, in remote
    peername = transport.get_extra_info('peername')
  File "/usr/lib/python3.5/asyncio/sslproto.py", line 306, in get_extra_info
    return self._ssl_protocol._get_extra_info(name, default)
  File "/usr/lib/python3.5/asyncio/sslproto.py", line 546, in _get_extra_info
    return self._transport.get_extra_info(name, default)
AttributeError: 'NoneType' object has no attribute 'get_extra_info'

In looking things over it looks like the output on Win10 for the reg query command has changed. it now has a space in the first line:

Based on the test case here: https://github.com/mitre/caldera/blob/65084276694bd297fdb4d880ed9b39f3a93a52ee/caldera/tests/parser_tests_data/reg_query.output

I think something in the parser.py query parser might not be handling that space correctly?

The victim in this case in Win 10 Ent Build 14393 x64

[ArtificialErmine]

This issue occurred with a fairly out of date (at this point, not at the time) version of Caldera. If the problem occurs again after upgrading to the most recent version of Caldera and adversary mode, feel free to re-open the issue or create a new one, and we can investigate the parsing system further, as that is likely the culprit behind this issue. In the mean time, the issue is being closed due to lack of activity.