24 Aug
2022
24 Aug
'22
2:02 a.m.
I tested out the latest change posted here
https://review.opendev.org/c/openstack/sushy/+/853209
This solved the issue, things work fine now with session auth. Thanks for
that! Much appreciated.
Wade
On Tue, Aug 16, 2022 at 9:22 AM Wade Albright <the.wade.albright@gmail.com>
wrote:
> Thanks Julia! When I get a chance I will test that out and report back. I
> may not be able to get to it right away as the system where I could
> reproduce this issue reliably is in use by another team now.
>
>
>
> On Mon, Aug 15, 2022 at 5:27 PM Julia Kreger <juliaashleykreger@gmail.com>
> wrote:
>
>> Well, that is weird. If I grok it as-is, it almost looks like the BMC
>> returned an empty response.... It is not a failure mode we've seen or
>> had reported (afaik) up to this point.
>>
>> That being said, we should be able to invalidate the session and
>> launch a new client...
>>
>> I suspect https://review.opendev.org/c/openstack/sushy/+/853209
>> should fix things up. I suspect we will look at just invalidating the
>> session upon any error.
>>
>> On Mon, Aug 15, 2022 at 11:47 AM Wade Albright
>> <the.wade.albright@gmail.com> wrote:
>> >
>> > 1) There are sockets open briefly when the conductor is trying to
>> connect. After three tries the node is set to maintenance mode and there
>> are no more sockets open.
>> > 2) My (extremely simple) code was not using connection: close. I was
>> just running "requests.get("
>> https://10.12.104.174/redfish/v1/Systems/System.Embedded.1",
>> verify=False, auth=('xxxx', 'xxxx'))" in a loop. I just tried it with
>> headers={'Connection':'close'} and it doesn't seem to make any difference.
>> Works fine either way.
>> >
>> > I was able to confirm that the problem only happens when using session
>> auth. With basic auth it doesn't happen.
>> >
>> > Versions I'm using here are ironic 18.2.1 and sushy 3.12.2.
>> >
>> > Here are some fresh logs from the node having the problem:
>> >
>> > 2022-08-15 10:34:21.726 208875 INFO ironic.conductor.task_manager
>> [req-a66441d0-45a6-4e27-96d9-f26bf9c83725 fcba8c03bfd649cfbb39a907426b3338
>> b679510ddb6540ca9454e26841f65c89 - default default] Node
>> 0c304cea-8ae2-4a12-b658-dec05c190f88 moved to provision state "deploying"
>> from state "active"; target provision state is "active"
>> > 2022-08-15 10:34:22.553 208875 INFO ironic.conductor.utils
>> [req-a66441d0-45a6-4e27-96d9-f26bf9c83725 fcba8c03bfd649cfbb39a907426b3338
>> b679510ddb6540ca9454e26841f65c89 - default default] Node
>> 0c304cea-8ae2-4a12-b658-dec05c190f88 current power state is 'power on',
>> requested state is 'power off'.
>> > 2022-08-15 10:34:35.185 208875 INFO ironic.conductor.utils
>> [req-a66441d0-45a6-4e27-96d9-f26bf9c83725 fcba8c03bfd649cfbb39a907426b3338
>> b679510ddb6540ca9454e26841f65c89 - default default] Successfully set node
>> 0c304cea-8ae2-4a12-b658-dec05c190f88 power state to power off by power off.
>> > 2022-08-15 10:34:35.200 208875 WARNING ironic.common.pxe_utils
>> [req-a66441d0-45a6-4e27-96d9-f26bf9c83725 fcba8c03bfd649cfbb39a907426b3338
>> b679510ddb6540ca9454e26841f65c89 - default default] IPv6 is enabled and the
>> DHCP driver appears set to a plugin aside from "neutron". Node
>> 0c304cea-8ae2-4a12-b658-dec05c190f88 may not receive proper DHCPv6 provided
>> boot parameters.
>> > 2022-08-15 10:34:38.246 208875 INFO ironic.conductor.deployments
>> [req-a66441d0-45a6-4e27-96d9-f26bf9c83725 fcba8c03bfd649cfbb39a907426b3338
>> b679510ddb6540ca9454e26841f65c89 - default default] Deploying on node
>> 0c304cea-8ae2-4a12-b658-dec05c190f88, remaining steps: [{'step':
>> 'pre_deploy', 'priority': 200, 'argsinfo': None, 'interface': 'deploy'},
>> {'step': 'deploy', 'priority': 100, 'argsinfo': None, 'interface':
>> 'deploy'}, {'step': 'write_image', 'priority': 80, 'argsinfo': None,
>> 'interface': 'deploy'}, {'step': 'tear_down_agent', 'priority': 40,
>> 'argsinfo': None, 'interface': 'deploy'}, {'step':
>> 'switch_to_tenant_network', 'priority': 30, 'argsinfo': None, 'interface':
>> 'deploy'}, {'step': 'boot_instance', 'priority': 20, 'argsinfo': None,
>> 'interface': 'deploy'}]
>> > 2022-08-15 10:34:38.255 208875 INFO ironic.conductor.deployments
>> [req-a66441d0-45a6-4e27-96d9-f26bf9c83725 fcba8c03bfd649cfbb39a907426b3338
>> b679510ddb6540ca9454e26841f65c89 - default default] Executing {'step':
>> 'pre_deploy', 'priority': 200, 'argsinfo': None, 'interface': 'deploy'} on
>> node 0c304cea-8ae2-4a12-b658-dec05c190f88
>> > 2022-08-15 10:35:27.158 208875 INFO
>> ironic.drivers.modules.ansible.deploy
>> [req-a66441d0-45a6-4e27-96d9-f26bf9c83725 fcba8c03bfd649cfbb39a907426b3338
>> b679510ddb6540ca9454e26841f65c89 - default default] Ansible pre-deploy step
>> complete on node 0c304cea-8ae2-4a12-b658-dec05c190f88
>> > 2022-08-15 10:35:27.159 208875 INFO ironic.conductor.deployments
>> [req-a66441d0-45a6-4e27-96d9-f26bf9c83725 fcba8c03bfd649cfbb39a907426b3338
>> b679510ddb6540ca9454e26841f65c89 - default default] Node
>> 0c304cea-8ae2-4a12-b658-dec05c190f88 finished deploy step {'step':
>> 'pre_deploy', 'priority': 200, 'argsinfo': None, 'interface': 'deploy'}
>> > 2022-08-15 10:35:27.160 208875 INFO ironic.conductor.deployments
>> [req-a66441d0-45a6-4e27-96d9-f26bf9c83725 fcba8c03bfd649cfbb39a907426b3338
>> b679510ddb6540ca9454e26841f65c89 - default default] Deploying on node
>> 0c304cea-8ae2-4a12-b658-dec05c190f88, remaining steps: [{'step': 'deploy',
>> 'priority': 100, 'argsinfo': None, 'interface': 'deploy'}, {'step':
>> 'write_image', 'priority': 80, 'argsinfo': None, 'interface': 'deploy'},
>> {'step': 'tear_down_agent', 'priority': 40, 'argsinfo': None, 'interface':
>> 'deploy'}, {'step': 'switch_to_tenant_network', 'priority': 30, 'argsinfo':
>> None, 'interface': 'deploy'}, {'step': 'boot_instance', 'priority': 20,
>> 'argsinfo': None, 'interface': 'deploy'}]
>> > 2022-08-15 10:35:27.176 208875 INFO ironic.conductor.deployments
>> [req-a66441d0-45a6-4e27-96d9-f26bf9c83725 fcba8c03bfd649cfbb39a907426b3338
>> b679510ddb6540ca9454e26841f65c89 - default default] Executing {'step':
>> 'deploy', 'priority': 100, 'argsinfo': None, 'interface': 'deploy'} on node
>> 0c304cea-8ae2-4a12-b658-dec05c190f88
>> > 2022-08-15 10:35:32.037 208875 INFO ironic.conductor.utils
>> [req-a66441d0-45a6-4e27-96d9-f26bf9c83725 fcba8c03bfd649cfbb39a907426b3338
>> b679510ddb6540ca9454e26841f65c89 - default default] Successfully set node
>> 0c304cea-8ae2-4a12-b658-dec05c190f88 power state to power on by rebooting.
>> > 2022-08-15 10:35:32.037 208875 INFO ironic.conductor.deployments
>> [req-a66441d0-45a6-4e27-96d9-f26bf9c83725 fcba8c03bfd649cfbb39a907426b3338
>> b679510ddb6540ca9454e26841f65c89 - default default] Deploy step {'step':
>> 'deploy', 'priority': 100, 'argsinfo': None, 'interface': 'deploy'} on node
>> 0c304cea-8ae2-4a12-b658-dec05c190f88 being executed asynchronously, waiting
>> for driver.
>> > 2022-08-15 10:35:32.051 208875 INFO ironic.conductor.task_manager
>> [req-a66441d0-45a6-4e27-96d9-f26bf9c83725 fcba8c03bfd649cfbb39a907426b3338
>> b679510ddb6540ca9454e26841f65c89 - default default] Node
>> 0c304cea-8ae2-4a12-b658-dec05c190f88 moved to provision state "wait
>> call-back" from state "deploying"; target provision state is "active"
>> > 2022-08-15 10:39:54.726 208875 INFO ironic.conductor.task_manager
>> [req-fdd7319b-85b5-4adb-9773-ff64fd1423b2 - - - - -] Node
>> 0c304cea-8ae2-4a12-b658-dec05c190f88 moved to provision state "deploying"
>> from state "wait call-back"; target provision state is "active"
>> > 2022-08-15 10:39:54.741 208875 INFO ironic.conductor.deployments
>> [req-fdd7319b-85b5-4adb-9773-ff64fd1423b2 - - - - -] Deploying on node
>> 0c304cea-8ae2-4a12-b658-dec05c190f88, remaining steps: [{'step':
>> 'write_image', 'priority': 80, 'argsinfo': None, 'interface': 'deploy'},
>> {'step': 'tear_down_agent', 'priority': 40, 'argsinfo': None, 'interface':
>> 'deploy'}, {'step': 'switch_to_tenant_network', 'priority': 30, 'argsinfo':
>> None, 'interface': 'deploy'}, {'step': 'boot_instance', 'priority': 20,
>> 'argsinfo': None, 'interface': 'deploy'}]
>> > 2022-08-15 10:39:54.748 208875 INFO ironic.conductor.deployments
>> [req-fdd7319b-85b5-4adb-9773-ff64fd1423b2 - - - - -] Executing {'step':
>> 'write_image', 'priority': 80, 'argsinfo': None, 'interface': 'deploy'} on
>> node 0c304cea-8ae2-4a12-b658-dec05c190f88
>> > 2022-08-15 10:42:24.738 208875 WARNING
>> ironic.drivers.modules.agent_base [-] Node
>> 0c304cea-8ae2-4a12-b658-dec05c190f88 is currently locked, skipping
>> heartbeat processing (will retry on the next heartbeat):
>> ironic.common.exception.NodeLocked: Node
>> 0c304cea-8ae2-4a12-b658-dec05c190f88 is locked by host
>> sjc06-c01-irn01.ops.ringcentral.com, please retry after the current
>> operation is completed.
>> > 2022-08-15 10:44:29.788 208875 WARNING
>> ironic.drivers.modules.agent_base [-] Node
>> 0c304cea-8ae2-4a12-b658-dec05c190f88 is currently locked, skipping
>> heartbeat processing (will retry on the next heartbeat):
>> ironic.common.exception.NodeLocked: Node
>> 0c304cea-8ae2-4a12-b658-dec05c190f88 is locked by host
>> sjc06-c01-irn01.ops.ringcentral.com, please retry after the current
>> operation is completed.
>> > 2022-08-15 10:47:24.830 208875 WARNING
>> ironic.drivers.modules.agent_base [-] Node
>> 0c304cea-8ae2-4a12-b658-dec05c190f88 is currently locked, skipping
>> heartbeat processing (will retry on the next heartbeat):
>> ironic.common.exception.NodeLocked: Node
>> 0c304cea-8ae2-4a12-b658-dec05c190f88 is locked by host
>> sjc06-c01-irn01.ops.ringcentral.com, please retry after the current
>> operation is completed.
>> > 2022-08-15 11:05:59.544 208875 INFO
>> ironic.drivers.modules.ansible.deploy
>> [req-fdd7319b-85b5-4adb-9773-ff64fd1423b2 - - - - -] Ansible complete
>> deploy on node 0c304cea-8ae2-4a12-b658-dec05c190f88
>> > 2022-08-15 11:06:00.141 208875 ERROR ironic.conductor.utils
>> [req-fdd7319b-85b5-4adb-9773-ff64fd1423b2 - - - - -] Node
>> 0c304cea-8ae2-4a12-b658-dec05c190f88 failed deploy step {'step':
>> 'write_image', 'priority': 80, 'argsinfo': None, 'interface': 'deploy'}
>> with unexpected error: ("Connection broken: InvalidChunkLength(got length
>> b'', 0 bytes read)", InvalidChunkLength(got length b'', 0 bytes read)):
>> requests.exceptions.ChunkedEncodingError: ("Connection broken:
>> InvalidChunkLength(got length b'', 0 bytes read)", InvalidChunkLength(got
>> length b'', 0 bytes read))
>> > 2022-08-15 11:06:00.218 208875 ERROR ironic.conductor.task_manager
>> [req-fdd7319b-85b5-4adb-9773-ff64fd1423b2 - - - - -] Node
>> 0c304cea-8ae2-4a12-b658-dec05c190f88 moved to provision state "deploy
>> failed" from state "deploying"; target provision state is "active":
>> requests.exceptions.ChunkedEncodingError: ("Connection broken:
>> InvalidChunkLength(got length b'', 0 bytes read)", InvalidChunkLength(got
>> length b'', 0 bytes read))
>> > 2022-08-15 11:06:28.774 208875 WARNING ironic.conductor.manager
>> [req-dd0abde9-3364-4828-8907-b42fe4cc9c66 - - - - -] During
>> sync_power_state, could not get power state for node
>> 0c304cea-8ae2-4a12-b658-dec05c190f88, attempt 1 of 3. Error: ("Connection
>> broken: InvalidChunkLength(got length b'', 0 bytes read)",
>> InvalidChunkLength(got length b'', 0 bytes read)).:
>> requests.exceptions.ChunkedEncodingError: ("Connection broken:
>> InvalidChunkLength(got length b'', 0 bytes read)", InvalidChunkLength(got
>> length b'', 0 bytes read))
>> > 2022-08-15 11:06:53.710 208875 WARNING ironic.conductor.manager
>> [req-dd0abde9-3364-4828-8907-b42fe4cc9c66 - - - - -] During
>> sync_power_state, could not get power state for node
>> 0c304cea-8ae2-4a12-b658-dec05c190f88, attempt 2 of 3. Error: ("Connection
>> broken: InvalidChunkLength(got length b'', 0 bytes read)",
>> InvalidChunkLength(got length b'', 0 bytes read)).:
>> requests.exceptions.ChunkedEncodingError: ("Connection broken:
>> InvalidChunkLength(got length b'', 0 bytes read)", InvalidChunkLength(got
>> length b'', 0 bytes read))
>> > 2022-08-15 11:07:53.727 208875 WARNING ironic.conductor.manager
>> [req-dd0abde9-3364-4828-8907-b42fe4cc9c66 - - - - -] During
>> sync_power_state, could not get power state for node
>> 0c304cea-8ae2-4a12-b658-dec05c190f88, attempt 3 of 3. Error: ("Connection
>> broken: InvalidChunkLength(got length b'', 0 bytes read)",
>> InvalidChunkLength(got length b'', 0 bytes read)).:
>> requests.exceptions.ChunkedEncodingError: ("Connection broken:
>> InvalidChunkLength(got length b'', 0 bytes read)", InvalidChunkLength(got
>> length b'', 0 bytes read))
>> > 2022-08-15 11:08:53.704 208875 ERROR ironic.conductor.manager
>> [req-dd0abde9-3364-4828-8907-b42fe4cc9c66 - - - - -] During
>> sync_power_state, max retries exceeded for node
>> 0c304cea-8ae2-4a12-b658-dec05c190f88, node state None does not match
>> expected state 'power on'. Updating DB state to 'None' Switching node to
>> maintenance mode. Error: ("Connection broken: InvalidChunkLength(got length
>> b'', 0 bytes read)", InvalidChunkLength(got length b'', 0 bytes read)):
>> requests.exceptions.ChunkedEncodingError: ("Connection broken:
>> InvalidChunkLength(got length b'', 0 bytes read)", InvalidChunkLength(got
>> length b'', 0 bytes read))
>> > 2022-08-15 11:13:53.750 208875 ERROR ironic.conductor.manager
>> [req-dd0abde9-3364-4828-8907-b42fe4cc9c66 - - - - -] During
>> sync_power_state, max retries exceeded for node
>> 0c304cea-8ae2-4a12-b658-dec05c190f88, node state None does not match
>> expected state 'None'. Updating DB state to 'None' Switching node to
>> maintenance mode. Error: ("Connection broken: InvalidChunkLength(got length
>> b'', 0 bytes read)", InvalidChunkLength(got length b'', 0 bytes read)):
>> requests.exceptions.ChunkedEncodingError: ("Connection broken:
>> InvalidChunkLength(got length b'', 0 bytes read)", InvalidChunkLength(got
>> length b'', 0 bytes read))
>> >
>> >
>> > On Fri, Aug 12, 2022 at 9:06 PM Julia Kreger <
>> juliaashleykreger@gmail.com> wrote:
>> >>
>> >> Two questions:
>> >>
>> >> 1) do you see open sockets to the BMCs in netstat output?
>> >> 2) is your code using ‘connection: close’? Or are you using sushy?
>> >>
>> >> Honestly, this seems *really* weird with current sushy versions, and
>> is kind of reminiscent of a cached session which is using kept alive
>> sockets.
>> >>
>> >> If you could grep out req-b6dd74da-1cc7-4c63-b58e-b7ded37007e9 to see
>> what the prior couple of conductor actions were, that would give us better
>> context as to what is going on.
>> >>
>> >> -Julia
>> >>
>> >> On Fri, Aug 12, 2022 at 3:11 PM Wade Albright <
>> the.wade.albright@gmail.com> wrote:
>> >>>
>> >>> Sorry for the spam. The openssl issue may have been a red herring. I
>> am not able to reproduce the issue directly with my own python code. I was
>> trying to fetch something that required authentication. After I added the
>> correct auth info it works fine. I am not able to cause the same error as
>> is happening in the Ironic logs.
>> >>>
>> >>> Anyway I'll do some more testing and report back.
>> >>>
>> >>> On Fri, Aug 12, 2022 at 2:14 PM Wade Albright <
>> the.wade.albright@gmail.com> wrote:
>> >>>>
>> >>>> I'm not sure why this problem only now started showing up, but it
>> appears to be unrelated to Ironic. I was able to reproduce it directly
>> outside of Ironic using a simple python program using urllib to get URLs
>> from the BMC/redfish interface. Seems to be some combination of a buggy
>> server SSL implementation and newer openssl 1.1.1. Apparently it doesn't
>> happen using openssl 1.0.
>> >>>>
>> >>>> I've found some information about possible workarounds but haven't
>> figured it out yet. If I do I'll update this thread just in case anyone
>> else runs into it.
>> >>>>
>> >>>> On Fri, Aug 12, 2022 at 8:13 AM Wade Albright <
>> the.wade.albright@gmail.com> wrote:
>> >>>>>
>> >>>>> So I seem to have run into a new issue after upgrading to the newer
>> versions to fix the password change issue.
>> >>>>>
>> >>>>> Now I am randomly getting errors like the below. Once I hit this
>> error for a given node, no operations work on the node. I thought maybe it
>> was an issue with the node itself, but it doesn't seem like it. The BMC
>> seems to be working fine.
>> >>>>>
>> >>>>> After a conductor restart, things start working again. Has anyone
>> seen something like this?
>> >>>>>
>> >>>>> Log example:
>> >>>>> 2022-08-12 07:45:33.227 1563371 ERROR ironic.conductor.utils [- - -
>> - -] Node ef5a2502-680b-4933-a0ee-6737e57ce1c5 failed deploy step {'step':
>> 'write_image', 'priority':
>> >>>>> 80, 'argsinfo': None, 'interface': 'deploy'} with unexpected error:
>> ("Connection broken: InvalidChunkLength(got length b'', 0 bytes read)",
>> InvalidChunkLength(got length b'', 0 bytes read)): requests.exceptions.
>> >>>>> ChunkedEncodingError: ("Connection broken: InvalidChunkLength(got
>> length b'', 0 bytes read)", InvalidChunkLength(got length b'', 0 bytes
>> read))
>> >>>>> 2022-08-12 07:45:33.227 1563371 ERROR ironic.conductor.utils
>> Traceback (most recent call last):
>> >>>>> 2022-08-12 07:45:33.227 1563371 ERROR ironic.conductor.utils File
>> "/usr/local/lib/python3.6/site-packages/urllib3/response.py", line 697, in
>> _update_chunk_length
>> >>>>> 2022-08-12 07:45:33.227 1563371 ERROR ironic.conductor.utils
>> self.chunk_left = int(line, 16)
>> >>>>> 2022-08-12 07:45:33.227 1563371 ERROR ironic.conductor.utils
>> ValueError: invalid literal for int() with base 16: b''
>> >>>>> 2022-08-12 07:45:33.227 1563371 ERROR ironic.conductor.utils
>> >>>>> 2022-08-12 07:45:33.227 1563371 ERROR ironic.conductor.utils During
>> handling of the above exception, another exception occurred:
>> >>>>> 2022-08-12 07:45:33.227 1563371 ERROR ironic.conductor.utils
>> >>>>> 2022-08-12 07:45:33.227 1563371 ERROR ironic.conductor.utils
>> Traceback (most recent call last):
>> >>>>> 2022-08-12 07:45:33.227 1563371 ERROR ironic.conductor.utils File
>> "/usr/local/lib/python3.6/site-packages/urllib3/response.py", line 438, in
>> _error_catcher
>> >>>>> 2022-08-12 07:45:33.227 1563371 ERROR ironic.conductor.utils
>> yield
>> >>>>> 2022-08-12 07:45:33.227 1563371 ERROR ironic.conductor.utils File
>> "/usr/local/lib/python3.6/site-packages/urllib3/response.py", line 764, in
>> read_chunked
>> >>>>> 2022-08-12 07:45:33.227 1563371 ERROR ironic.conductor.utils
>> self._update_chunk_length()
>> >>>>> 2022-08-12 07:45:33.227 1563371 ERROR ironic.conductor.utils File
>> "/usr/local/lib/python3.6/site-packages/urllib3/response.py", line 701, in
>> _update_chunk_length
>> >>>>> 2022-08-12 07:45:33.227 1563371 ERROR ironic.conductor.utils
>> raise InvalidChunkLength(self, line)
>> >>>>> 2022-08-12 07:45:33.227 1563371 ERROR ironic.conductor.utils
>> urllib3.exceptions.InvalidChunkLength: InvalidChunkLength(got length b'', 0
>> bytes read)
>> >>>>> 2022-08-12 07:45:33.227 1563371 ERROR ironic.conductor.utils
>> >>>>> 2022-08-12 07:45:33.227 1563371 ERROR ironic.conductor.utils During
>> handling of the above exception, another exception occurred:
>> >>>>> 2022-08-12 07:45:33.227 1563371 ERROR ironic.conductor.utils
>> >>>>> 2022-08-12 07:45:33.227 1563371 ERROR ironic.conductor.utils
>> Traceback (most recent call last):
>> >>>>> 2022-08-12 07:45:33.227 1563371 ERROR ironic.conductor.utils File
>> "/usr/local/lib/python3.6/site-packages/requests/models.py", line 760, in
>> generate
>> >>>>> 2022-08-12 07:45:33.227 1563371 ERROR ironic.conductor.utils
>> for chunk in self.raw.stream(chunk_size, decode_content=True):
>> >>>>> 2022-08-12 07:45:33.227 1563371 ERROR ironic.conductor.utils File
>> "/usr/local/lib/python3.6/site-packages/urllib3/response.py", line 572, in
>> stream
>> >>>>> 2022-08-12 07:45:33.227 1563371 ERROR ironic.conductor.utils
>> for line in self.read_chunked(amt, decode_content=decode_content):
>> >>>>> 2022-08-12 07:45:33.227 1563371 ERROR ironic.conductor.utils File
>> "/usr/local/lib/python3.6/site-packages/urllib3/response.py", line 793, in
>> read_chunked
>> >>>>> 2022-08-12 07:45:33.227 1563371 ERROR ironic.conductor.utils
>> self._original_response.close()
>> >>>>> 2022-08-12 07:45:33.227 1563371 ERROR ironic.conductor.utils File
>> "/usr/lib64/python3.6/contextlib.py", line 99, in __exit__
>> >>>>> 2022-08-12 07:45:33.227 1563371 ERROR ironic.conductor.utils
>> self.gen.throw(type, value, traceback)
>> >>>>> 2022-08-12 07:45:33.227 1563371 ERROR ironic.conductor.utils File
>> "/usr/local/lib/python3.6/site-packages/urllib3/response.py", line 455, in
>> _error_catcher
>> >>>>> 2022-08-12 07:45:33.227 1563371 ERROR ironic.conductor.utils
>> raise ProtocolError("Connection broken: %r" % e, e)
>> >>>>> 2022-08-12 07:45:33.227 1563371 ERROR ironic.conductor.utils
>> urllib3.exceptions.ProtocolError: ("Connection broken:
>> InvalidChunkLength(got length b'', 0 bytes read)", InvalidChunkLength(got
>> length b'', 0 bytes r
>> >>>>> ead))
>> >>>>>
>> >>>>> On Wed, Jul 20, 2022 at 2:04 PM Wade Albright <
>> the.wade.albright@gmail.com> wrote:
>> >>>>>>
>> >>>>>> I forgot to mention, that using session auth solved the problem
>> after upgrading to the newer versions that include the two mentioned
>> patches.
>> >>>>>>
>> >>>>>> On Wed, Jul 20, 2022 at 7:36 AM Wade Albright <
>> the.wade.albright@gmail.com> wrote:
>> >>>>>>>
>> >>>>>>> Switching to session auth solved the problem, and it seems like
>> the better way to go anyway for equipment that supports it. Thanks again
>> for all your help!
>> >>>>>>>
>> >>>>>>> Wade
>> >>>>>>>
>> >>>>>>> On Tue, Jul 19, 2022 at 5:37 PM Julia Kreger <
>> juliaashleykreger@gmail.com> wrote:
>> >>>>>>>>
>> >>>>>>>> Just to provide a brief update for the mailing list. It looks
>> like
>> >>>>>>>> this is a case of use of Basic Auth with the BMC, where we were
>> not
>> >>>>>>>> catching the error properly... and thus not reporting the
>> >>>>>>>> authentication failure to ironic so it would catch, and initiate
>> a new
>> >>>>>>>> client with the most up to date password. The default, typically
>> used
>> >>>>>>>> path is Session based authentication as BMCs generally handle
>> internal
>> >>>>>>>> session/user login tracking in a far better fashion. But not
>> every BMC
>> >>>>>>>> supports sessions.
>> >>>>>>>>
>> >>>>>>>> Fix in review[0] :)
>> >>>>>>>>
>> >>>>>>>> -Julia
>> >>>>>>>> [0] https://review.opendev.org/c/openstack/sushy/+/850425
>> >>>>>>>>
>> >>>>>>>> On Mon, Jul 18, 2022 at 4:15 PM Julia Kreger
>> >>>>>>>> <juliaashleykreger@gmail.com> wrote:
>> >>>>>>>> >
>> >>>>>>>> > Excellent, hopefully I'll be able to figure out why Sushy is
>> not doing
>> >>>>>>>> > the needful... Or if it is and Ironic is not picking up on it.
>> >>>>>>>> >
>> >>>>>>>> > Anyway, I've posted
>> >>>>>>>> > https://review.opendev.org/c/openstack/ironic/+/850259 which
>> might
>> >>>>>>>> > handle this issue. Obviously a work in progress, but it
>> represents
>> >>>>>>>> > what I think is happening inside of ironic itself leading into
>> sushy
>> >>>>>>>> > when cache access occurs.
>> >>>>>>>> >
>> >>>>>>>> > On Mon, Jul 18, 2022 at 4:04 PM Wade Albright
>> >>>>>>>> > <the.wade.albright@gmail.com> wrote:
>> >>>>>>>> > >
>> >>>>>>>> > > Sounds good, I will do that tomorrow. Thanks Julia.
>> >>>>>>>> > >
>> >>>>>>>> > > On Mon, Jul 18, 2022 at 3:27 PM Julia Kreger <
>> juliaashleykreger@gmail.com> wrote:
>> >>>>>>>> > >>
>> >>>>>>>> > >> Debug would be best. I think I have an idea what is going
>> on, and this
>> >>>>>>>> > >> is a similar variation. If you want, you can email them
>> directly to
>> >>>>>>>> > >> me. Specifically only need entries reported by the sushy
>> library and
>> >>>>>>>> > >> ironic.drivers.modules.redfish.utils.
>> >>>>>>>> > >>
>> >>>>>>>> > >> On Mon, Jul 18, 2022 at 3:20 PM Wade Albright
>> >>>>>>>> > >> <the.wade.albright@gmail.com> wrote:
>> >>>>>>>> > >> >
>> >>>>>>>> > >> > I'm happy to supply some logs, what verbosity level
>> should i use? And should I just embed the logs in email to the list or
>> upload somewhere?
>> >>>>>>>> > >> >
>> >>>>>>>> > >> > On Mon, Jul 18, 2022 at 3:14 PM Julia Kreger <
>> juliaashleykreger@gmail.com> wrote:
>> >>>>>>>> > >> >>
>> >>>>>>>> > >> >> If you could supply some conductor logs, that would be
>> helpful. It
>> >>>>>>>> > >> >> should be re-authenticating, but obviously we have a
>> larger bug there
>> >>>>>>>> > >> >> we need to find the root issue behind.
>> >>>>>>>> > >> >>
>> >>>>>>>> > >> >> On Mon, Jul 18, 2022 at 3:06 PM Wade Albright
>> >>>>>>>> > >> >> <the.wade.albright@gmail.com> wrote:
>> >>>>>>>> > >> >> >
>> >>>>>>>> > >> >> > I was able to use the patches to update the code, but
>> unfortunately the problem is still there for me.
>> >>>>>>>> > >> >> >
>> >>>>>>>> > >> >> > I also tried an RPM upgrade to the versions Julia
>> mentioned had the fixes, namely Sushy 3.12.1 - Released May 2022 and Ironic
>> 18.2.1 - Released in January 2022. But it did not fix the problem.
>> >>>>>>>> > >> >> >
>> >>>>>>>> > >> >> > I am able to consistently reproduce the error.
>> >>>>>>>> > >> >> > - step 1: change BMC password directly on the node
>> itself
>> >>>>>>>> > >> >> > - step 2: update BMC password (redfish_password) in
>> ironic with 'openstack baremetal node set <nodename> --driver-info
>> redfish_password='newpass'
>> >>>>>>>> > >> >> >
>> >>>>>>>> > >> >> > After step 1 there are errors in the logs entries like
>> "Session authentication appears to have been lost at some point in time"
>> and eventually it puts the node into maintenance mode and marks the power
>> state as "none."
>> >>>>>>>> > >> >> > After step 2 and taking the host back out of
>> maintenance mode, it goes through a similar set of log entries puts the
>> node into MM again.
>> >>>>>>>> > >> >> >
>> >>>>>>>> > >> >> > After the above steps, a conductor restart fixes the
>> problem and operations work normally again. Given this it seems like there
>> is still some kind of caching issue.
>> >>>>>>>> > >> >> >
>> >>>>>>>> > >> >> > On Sat, Jul 16, 2022 at 6:01 PM Wade Albright <
>> the.wade.albright@gmail.com> wrote:
>> >>>>>>>> > >> >> >>
>> >>>>>>>> > >> >> >> Hi Julia,
>> >>>>>>>> > >> >> >>
>> >>>>>>>> > >> >> >> Thank you so much for the reply! Hopefully this is
>> the issue. I'll try out the patches next week and report back. I'll also
>> email you on Monday about the versions, that would be very helpful to know.
>> >>>>>>>> > >> >> >>
>> >>>>>>>> > >> >> >> Thanks again, really appreciate it.
>> >>>>>>>> > >> >> >>
>> >>>>>>>> > >> >> >> Wade
>> >>>>>>>> > >> >> >>
>> >>>>>>>> > >> >> >>
>> >>>>>>>> > >> >> >>
>> >>>>>>>> > >> >> >> On Sat, Jul 16, 2022 at 4:36 PM Julia Kreger <
>> juliaashleykreger@gmail.com> wrote:
>> >>>>>>>> > >> >> >>>
>> >>>>>>>> > >> >> >>> Greetings!
>> >>>>>>>> > >> >> >>>
>> >>>>>>>> > >> >> >>> I believe you need two patches, one in ironic and
>> one in sushy.
>> >>>>>>>> > >> >> >>>
>> >>>>>>>> > >> >> >>> Sushy:
>> >>>>>>>> > >> >> >>>
>> https://review.opendev.org/c/openstack/sushy/+/832860
>> >>>>>>>> > >> >> >>>
>> >>>>>>>> > >> >> >>> Ironic:
>> >>>>>>>> > >> >> >>>
>> https://review.opendev.org/c/openstack/ironic/+/820588
>> >>>>>>>> > >> >> >>>
>> >>>>>>>> > >> >> >>> I think it is variation, and the comment about
>> working after you restart the conductor is the big signal to me. I’m on a
>> phone on a bad data connection, if you email me on Monday I can see what
>> versions the fixes would be in.
>> >>>>>>>> > >> >> >>>
>> >>>>>>>> > >> >> >>> For the record, it is a session cache issue, the bug
>> was that the service didn’t quite know what to do when auth fails.
>> >>>>>>>> > >> >> >>>
>> >>>>>>>> > >> >> >>> -Julia
>> >>>>>>>> > >> >> >>>
>> >>>>>>>> > >> >> >>>
>> >>>>>>>> > >> >> >>> On Fri, Jul 15, 2022 at 2:55 PM Wade Albright <
>> the.wade.albright@gmail.com> wrote:
>> >>>>>>>> > >> >> >>>>
>> >>>>>>>> > >> >> >>>> Hi,
>> >>>>>>>> > >> >> >>>>
>> >>>>>>>> > >> >> >>>> I'm hitting a problem when trying to update the
>> redfish_password for an existing node. I'm curious to know if anyone else
>> has encountered this problem. I'm not sure if I'm just doing something
>> wrong or if there is a bug. Or if the problem is unique to my setup.
>> >>>>>>>> > >> >> >>>>
>> >>>>>>>> > >> >> >>>> I have a node already added into ironic with all
>> the driver details set, and things are working fine. I am able to run
>> deployments.
>> >>>>>>>> > >> >> >>>>
>> >>>>>>>> > >> >> >>>> Now I need to change the redfish password on the
>> host. So I update the password for redfish access on the host, then use an
>> 'openstack baremetal node set <node> --driver-info
>> redfish_password=<newpass>' command to set the new redfish_password.
>> >>>>>>>> > >> >> >>>>
>> >>>>>>>> > >> >> >>>> Once this has been done, deployment no longer
>> works. I see redfish authentication errors in the logs and the operation
>> fails. I waited a bit to see if there might just be a delay in updating the
>> password, but after awhile it still didn't work.
>> >>>>>>>> > >> >> >>>>
>> >>>>>>>> > >> >> >>>> I restarted the conductor, and after that things
>> work fine again. So it seems like the password is cached or something. Is
>> there a way to force the password to update? I even tried removing the
>> redfish credentials and re-adding them, but that didn't work either. Only a
>> conductor restart seems to make the new password work.
>> >>>>>>>> > >> >> >>>>
>> >>>>>>>> > >> >> >>>> We are running Xena, using rpm installation on
>> Oracle Linux 8.5.
>> >>>>>>>> > >> >> >>>>
>> >>>>>>>> > >> >> >>>> Thanks in advance for any help with this issue.
>>
>