jborean93/pypsrp

Can not return error info in nested powershell even the scripts is finished until time out

bigdavidwong opened this issue · 3 comments

bigdavidwong commented

Hi Jordan,

At first, really thanks for your tools, it really helps me a lot!

Now I have some trouble when I am using it in exchange connections. If I want to create an email account which can not be created(account already existed or name already used by system), the powershell will not return the error info even it happened, and the only thing I can do is waiting, then get an bad http response;

here is my program steps:

  1. create an RunspacePool in exchange server, with default configuration;
  2. create PowerShell named ps;
  3. execute any scripts in ps and begin invoke;
  4. create a nested_powershell in ps named nsps;
  5. execute core scripts:
    New-Mailbox -UserPrincipalName network@mydomain.com -Name network -DisplayName testnetwork -OrganizationalUnit ExchangePublic -Password (ConvertTo-SecureString "Test!@#123" -AsPlainText -Force)
  6. invoke nsps;
  7. end invoke ps;

issue happened after step 6, and after a few minutes, I got some errors like this:

2022-07-08 15:47:47,069 | ERROR | process: 5188 | powershell_tools.py >> execute_nested_cmd | 274 | LOGGER-PsClient | : HTTPConnectionPool(host='test-mailbox02.mydomain.com', port=5985): Read timed out. (read timeout=120)
Traceback (most recent call last):
  File "D:\Win_pythonProject\lib\site-packages\urllib3\connectionpool.py", line 449, in _make_request
    six.raise_from(e, None)
  File "<string>", line 3, in raise_from
  File "D:\Win_pythonProject\lib\site-packages\urllib3\connectionpool.py", line 444, in _make_request
    httplib_response = conn.getresponse()
  File "C:\Program Files\Python37\lib\http\client.py", line 1369, in getresponse
    response.begin()
  File "C:\Program Files\Python37\lib\http\client.py", line 310, in begin
    version, status, reason = self._read_status()
  File "C:\Program Files\Python37\lib\http\client.py", line 271, in _read_status
    line = str(self.fp.readline(_MAXLINE + 1), "iso-8859-1")
  File "C:\Program Files\Python37\lib\socket.py", line 589, in readinto
    return self._sock.recv_into(b)
socket.timeout: timed out

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "D:\Win_pythonProject\lib\site-packages\requests\adapters.py", line 450, in send
    timeout=timeout
  File "D:\Win_pythonProject\lib\site-packages\urllib3\connectionpool.py", line 786, in urlopen
    method, url, error=e, _pool=self, _stacktrace=sys.exc_info()[2]
  File "D:\Win_pythonProject\lib\site-packages\urllib3\util\retry.py", line 550, in increment
    raise six.reraise(type(error), error, _stacktrace)
  File "D:\Win_pythonProject\lib\site-packages\urllib3\packages\six.py", line 770, in reraise
    raise value
  File "D:\Win_pythonProject\lib\site-packages\urllib3\connectionpool.py", line 710, in urlopen
    chunked=chunked,
  File "D:\Win_pythonProject\lib\site-packages\urllib3\connectionpool.py", line 451, in _make_request
    self._raise_timeout(err=e, url=url, timeout_value=read_timeout)
  File "D:\Win_pythonProject\lib\site-packages\urllib3\connectionpool.py", line 341, in _raise_timeout
    self, url, "Read timed out. (read timeout=%s)" % timeout_value
urllib3.exceptions.ReadTimeoutError: HTTPConnectionPool(host='test-mailbox02.mydomain.com', port=5985): Read timed out. (read timeout=120)

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "D:/pythonProject/it_team/Tools/powershell_tools.py", line 256, in execute_nested_cmd
    nested_shell.invoke()
  File "D:\Win_pythonProject\lib\site-packages\pypsrp\powershell.py", line 1218, in invoke
    return self.end_invoke()
  File "D:\Win_pythonProject\lib\site-packages\pypsrp\powershell.py", line 1190, in end_invoke
    self.poll_invoke()
  File "D:\Win_pythonProject\lib\site-packages\pypsrp\powershell.py", line 1391, in poll_invoke
    responses = self.runspace_pool._receive(self.id, timeout=timeout)
  File "D:\Win_pythonProject\lib\site-packages\pypsrp\powershell.py", line 682, in _receive
    response = self.shell.receive("stdout", command_id=command_id, timeout=timeout)[2]["stdout"]
  File "D:\Win_pythonProject\lib\site-packages\pypsrp\shell.py", line 244, in receive
    self.resource_uri, receive, option_set=options, selector_set=self._selector_set, timeout=timeout
  File "D:\Win_pythonProject\lib\site-packages\pypsrp\wsman.py", line 367, in receive
    res = self.invoke(WSManAction.RECEIVE, resource_uri, resource, option_set, selector_set, timeout)
  File "D:\Win_pythonProject\lib\site-packages\pypsrp\wsman.py", line 470, in invoke
    response = self.transport.send(xml)
  File "D:\Win_pythonProject\lib\site-packages\pypsrp\wsman.py", line 837, in send
    return self._send_request(prep_request)
  File "D:\Win_pythonProject\lib\site-packages\pypsrp\wsman.py", line 840, in _send_request
    response = self.session.send(request, timeout=(self.connection_timeout, self.read_timeout))  # type: ignore[union-attr] # This should not happen
  File "D:\Win_pythonProject\lib\site-packages\requests\sessions.py", line 645, in send
    r = adapter.send(request, **kwargs)
  File "D:\Win_pythonProject\lib\site-packages\requests\adapters.py", line 532, in send
    raise ReadTimeout(e, request=request)
requests.exceptions.ReadTimeout: HTTPConnectionPool(host='test-mailbox02.mydomain.com', port=5985): Read timed out. (read timeout=120)

(False, 'ps_5bb91ceac3234c209608c6e0f3fbdfe8', {'opt_id': 'ps_5bb91ceac3234c209608c6e0f3fbdfe8', 'errors': "HTTPConnectionPool(host='test-mailbox02.mydomain.com', port=5985): Read timed out. (read timeout=120)"})
2022-07-08 15:47:47,304 | ERROR | process: 5188 | powershell_tools.py >> end_client | 242 | LOGGER-PsClient | 异常: Bad HTTP response returned from the server. Code: 400, Content: ''
Traceback (most recent call last):
  File "D:\Win_pythonProject\lib\site-packages\pypsrp\wsman.py", line 474, in invoke
    raise self._parse_wsman_fault(err.response_text)
  File "D:\Win_pythonProject\lib\site-packages\pypsrp\wsman.py", line 598, in _parse_wsman_fault
    xml = ET.fromstring(xml_text)
  File "C:\Program Files\Python37\lib\xml\etree\ElementTree.py", line 1316, in XML
    return parser.close()
  File "<string>", line None
xml.etree.ElementTree.ParseError: no element found: line 1, column 0

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "D:/pythonProject/it_team/Tools/powershell_tools.py", line 235, in end_client
    _ps_exchange.invoke()
  File "D:\Win_pythonProject\lib\site-packages\pypsrp\powershell.py", line 1217, in invoke
    self.begin_invoke(input, add_to_history, apartment_state, redirect_shell_error_to_out, remote_stream_options)
  File "D:\Win_pythonProject\lib\site-packages\pypsrp\powershell.py", line 1152, in begin_invoke
    self._invoke(create_pipeline)
  File "D:\Win_pythonProject\lib\site-packages\pypsrp\powershell.py", line 1427, in _invoke
    resp = self.runspace_pool.shell.command("", arguments=[first_frag], command_id=self.id)
  File "D:\Win_pythonProject\lib\site-packages\pypsrp\shell.py", line 151, in command
    return self.wsman.command(self.resource_uri, cmd, option_set=options, selector_set=self._selector_set)
  File "D:\Win_pythonProject\lib\site-packages\pypsrp\wsman.py", line 268, in command
    res = self.invoke(WSManAction.COMMAND, resource_uri, resource, option_set, selector_set, timeout)
  File "D:\Win_pythonProject\lib\site-packages\pypsrp\wsman.py", line 481, in invoke
    raise err
  File "D:\Win_pythonProject\lib\site-packages\pypsrp\wsman.py", line 470, in invoke
    response = self.transport.send(xml)
  File "D:\Win_pythonProject\lib\site-packages\pypsrp\wsman.py", line 837, in send
    return self._send_request(prep_request)
  File "D:\Win_pythonProject\lib\site-packages\pypsrp\wsman.py", line 862, in _send_request
    raise WinRMTransportError("http", code, response_text)
pypsrp.exceptions.WinRMTransportError: Bad HTTP response returned from the server. Code: 400, Content: ''

this kind of problem not just happened in Exchange, I remembered it also happened when I was using it to handle dns problem in my windows dns server, and I am really upset I forget what scripts I used when that happened;

looking forward to your reply!

jborean93 commented

It's hard to tell what might be happening here but essentially the server is not responding to a request when getting the output back. It's receiving a read timeout after 120 seconds as per

requests.exceptions.ReadTimeout: HTTPConnectionPool(host='test-mailbox02.mydomain.com', port=5985): Read timed out. (read timeout=120)

What is curious is that this is happening when the client is sending a WSMan Receive command which itself has an operation timeout of 20 seconds. The lower operation timeout here should be firing before the HTTP read timeout occurred which tells me the server is not even processing the read request. What this is I'm not sure but something critical has failed on the server.

Can you explain why you are using a nested prompt. This could be causing problems as there are now essentially 2 WSMan commands present on the remote host and something may not be working properly. Nested commands is not something I've really played with too much before.

bigdavidwong commented

Thanks for your reply!

Actually the core reason I used nested shell is: I want to handle multiple scripts in one connection, that will save lots of time especially when I have to import a session in powershell at first to process target scripts, and I found the nested shell can do this job when I was reading your code...

But now I've found a new way to solve this problem from issue https://github.com/jborean93/pypsrp/issues/106#issuecomment-845644289, I can create another PowerShell object from RunspacePool to handle multiple scripts in one connection, and the problem I got in nested shell will not happen in this way, this kind of shell always returned me the specific errors.

In conclusion, some kind of powershell errors could not be handled and returned in nested powershell, and in exactly the same situation, this problem will not occur in normal powershell.

At the end, since I've found a solution, please consider it a bug report~

Again, thanks for your reply and your excellent tools!

jborean93 commented

Glad you found a solution, using a Runspace Pool with multiple runspaces is definitely the preferred option over a nested pipeline to run things concurrently. Nested pipelines are definitely an edge case that I've never fully understood. I'll see if I can try and replicate this outside of Exchange as that adds another layer into the mix but ultimately I'm not sure if this is a bug or working as intended from a protocol perspective.