Hey Eric,

Seems odd. Are you able to share the overcloud deploy command you're using, a tar of the environment files you're including and could you also share the plan-environment.yaml file from swift?

So, for example if you're storing your templates in /home/stack/templates, and you have a script called overcloud_deploy.sh in /home/stack. The commands would be:

1. Grab the plan-environment.yaml file from swift:
$ cd /home/stack
$ OS_CLOUD=undercloud openstack object save overcloud plan-environment.yaml

2. Tar them all up
$ tar -czvf templates_and_plan.tar /home/stack/templates/ /home/stack/overcloud_deploy.sh /home/stack/plan-environment.yaml

Thanks, we'll take a look at that data.

(In reply to Brendan Shephard from comment #1)
> Hey Eric,
> 
> Seems odd. Are you able to share the overcloud deploy command you're using,
> a tar of the environment files you're including and could you also share the
> plan-environment.yaml file from swift?
> 
> So, for example if you're storing your templates in /home/stack/templates,
> and you have a script called overcloud_deploy.sh in /home/stack. The
> commands would be:
> 
> 1. Grab the plan-environment.yaml file from swift:
> $ cd /home/stack
> $ OS_CLOUD=undercloud openstack object save overcloud plan-environment.yaml
> 
> 2. Tar them all up
> $ tar -czvf templates_and_plan.tar /home/stack/templates/
> /home/stack/overcloud_deploy.sh /home/stack/plan-environment.yaml
> 
> Thanks, we'll take a look at that data.

Just added all of the templates I was planning to use, but note that I ran into this issue using a minimal deployment command (not even worth putting inside a deploy script):

(undercloud) [stack.lab ~]$ openstack overcloud deploy --templates -e templates/node-info.yaml -e containers-prepare-parameter-notag-satellite.yaml

Hey Eric,

The data within the plan looks good. I did suspect there might be an issue there, but alas, it seems fine. 

Is this related to a support case? Or just your own lab? Are you able to provide all of the logs for the environment in /var/log?  Must be something related to mistral invoking the container prepare compared to the cli. I would like to see what Mistral was doing there to see if there are some clues.

(In reply to Brendan Shephard from comment #4)
> Hey Eric,
> 
> The data within the plan looks good. I did suspect there might be an issue
> there, but alas, it seems fine. 
> 
> Is this related to a support case? Or just your own lab? Are you able to
> provide all of the logs for the environment in /var/log?  Must be something
> related to mistral invoking the container prepare compared to the cli. I
> would like to see what Mistral was doing there to see if there are some
> clues.

I was testing the process of defaulting to image-release tags as I was going to suggest my customer to use it (based on the recommendation on [0]). Since it didn't work in my test, I discouraged them from using it on the case that is attached to that BZ (which was for a different issue). So, I don't exactly have a case for this specific problem, and all logs come from my lab. I will attach a tar of the logs in some minutes.


[0] https://bugzilla.redhat.com/show_bug.cgi?id=2083720#c6

Hey Eric,

Thanks. I'll try and reproduce this if I can't get anything from the logs. I assume this is Satellite 6.10 because of the authentication and lack of port 5000 in the container URL?

(In reply to Brendan Shephard from comment #7)
> Hey Eric,
> 
> Thanks. I'll try and reproduce this if I can't get anything from the logs. I
> assume this is Satellite 6.10 because of the authentication and lack of port
> 5000 in the container URL?

No, it's 6.11, and it was already when I ran into this for the first time a couple of months ago.


[root.lab ~]# rpm -q satellite
satellite-6.11.3-1.el7sat.noarch

Yeah ok cool. Glad I went with 6.11 for my test env then. It was still syncing in containers when I jumped offline this afternoon, so I'll see if I can reproduce this with a 16.2 environment.

I'll be interested to see what error Satellite is returning to there. Since we seem to be sending a token that we have got as a result of authenticating using the username and password.


I'll get back to you with results and hopefully a solution.

I'm assuming it works fine if you disable authentication on the registry right?

(In reply to Brendan Shephard from comment #10)
> Yeah ok cool. Glad I went with 6.11 for my test env then. It was still
> syncing in containers when I jumped offline this afternoon, so I'll see if I
> can reproduce this with a 16.2 environment.
> 
> I'll be interested to see what error Satellite is returning to there. Since
> we seem to be sending a token that we have got as a result of authenticating
> using the username and password.
> 

I enabled debug on satellite, but it doesn't help much: 

~~~
[root.lab ~]# egrep b5a84b99 /var/log/foreman/production.log
2022-10-17T13:39:47 [I|app|b5a84b99] Started GET "/v2/keller-library-osp_16_2_cv-osp_containers-cinder-api/tags/list" for 192.168.122.245 at 2022-10-17 13:39:47 +0000
2022-10-17T13:39:47 [I|app|b5a84b99] Processing by Katello::Api::Registry::RegistryProxiesController#tags_list as */*
2022-10-17T13:39:47 [I|app|b5a84b99]   Parameters: {"repository"=>"keller-library-osp_16_2_cv-osp_containers-cinder-api"}
2022-10-17T13:39:47 [I|app|b5a84b99]   Rendering api/v2/errors/unauthorized.json.rabl within api/v2/layouts/error_layout
2022-10-17T13:39:47 [I|app|b5a84b99]   Rendered api/v2/errors/unauthorized.json.rabl within api/v2/layouts/error_layout (Duration: 2.6ms | Allocations: 2657)
2022-10-17T13:39:47 [I|app|b5a84b99] Filter chain halted as :registry_authorize rendered or redirected
2022-10-17T13:39:47 [I|app|b5a84b99] Completed 401 Unauthorized in 22ms (Views: 5.4ms | ActiveRecord: 4.3ms | Allocations: 11222)
2022-10-17T13:39:47 [D|app|b5a84b99] With body: {
 b5a84b99 |   "error": {"message":"Unable to authenticate user "}
 b5a84b99 | }
 b5a84b99 | 
 b5a84b99 | 
[root.lab ~]# 
~~~

> 
> I'll get back to you with results and hopefully a solution.
> 
> I'm assuming it works fine if you disable authentication on the registry
> right?


I don't know where on satellite I would disable authentication to the built-in registry. If you can point me to instructions I'll give it a try.

Hmm yeah, doesn't tell us much there.

For disabling Auth on the container pulls. That can be done with the steps outlined here I believe:
https://access.redhat.com/documentation/en-us/red_hat_satellite/6.11/html/managing_content/managing_container_images_content-management#Managing_Container_Registry_Authentication_content-management

So, I:

1. Enabled unauthenticated pull, tested curl without credentials:

(undercloud) [stack.lab ~]$ curl https://satellite.keller.lab:443/v2/keller-library-osp_16_2_cv-osp_containers-cinder-api/tags/list 2>/dev/null | jq .
{
  "name": "keller-library-osp_16_2_cv-osp_containers-cinder-api",
  "tags": [
    "16.2",
    "16.2.3",
    "16.2.3-11.1661380875"
  ]
}

2. Disabled "ContainerImageRegistryLogin" on containers-prepare-parameter-notag-satellite.yaml:

(undercloud) [stack.lab ~]$ sed -i 's/\(ContainerImageRegistryLogin:\) true/\1 false/' containers-prepare-parameter-notag-satellite.yaml
(undercloud) [stack.lab ~]$ 


3. Deleted overcloud:

(undercloud) [stack.lab ~]$ openstack overcloud delete overcloud -y
Undeploying stack overcloud...
No stack found ('overcloud'), skipping delete
Deleting plan overcloud...
Success.
(undercloud) [stack.lab ~]$


4. Deployed overcloud until I saw that it passed the point of the error:

(undercloud) [stack.lab ~]$ date ; openstack overcloud deploy --templates -e templates/node-info.yaml -e containers-prepare-parameter-notag-satellite.yaml ;date
Mon Oct 17 17:26:35 CEST 2022
/usr/lib/python3.6/site-packages/openstack/resource.py:351: DeprecationWarning: inspect.getargspec() is deprecated since Python 3.0, use inspect.signature() or inspect.getfullargspec()
  len(inspect.getargspec(type_).args) > 1)
Creating Swift container to store the plan
Creating plan from template files in: /tmp/tripleoclient-y1awzx_f/tripleo-heat-templates
Plan created.
Processing templates in the directory /tmp/tripleoclient-y1awzx_f/tripleo-heat-templates
/usr/lib/python3.6/site-packages/openstack/resource.py:351: DeprecationWarning: inspect.getargspec() is deprecated since Python 3.0, use inspect.signature() or inspect.getfullargspec()
  len(inspect.getargspec(type_).args) > 1)
WARNING: Following parameter(s) are defined but not currently used in the deployment plan. These parameters may be valid but not in use due to the service or deployment configuration. CtlplaneNetworkAttributes
Deploying templates in the directory /tmp/tripleoclient-y1awzx_f/tripleo-heat-templates
Initializing overcloud plan deployment
Creating overcloud Heat stack
2022-10-17 15:30:41Z [overcloud]: CREATE_IN_PROGRESS  Stack CREATE started
2022-10-17 15:30:43Z [overcloud.RabbitCookie]: CREATE_IN_PROGRESS  state changed
2022-10-17 15:30:43Z [overcloud.RabbitCookie]: CREATE_COMPLETE  state changed
2022-10-17 15:30:44Z [overcloud.ControllerRoleUserData]: CREATE_IN_PROGRESS  state changed
2022-10-17 15:30:45Z [overcloud.ControllerRoleUserData]: CREATE_IN_PROGRESS  Stack CREATE started
2022-10-17 15:30:45Z [overcloud.ControllerRoleUserData.userdata]: CREATE_IN_PROGRESS  state changed
2022-10-17 15:30:45Z [overcloud.ControllerRoleUserData.userdata]: CREATE_COMPLETE  state changed


5. Repeated 3 and 4 a couple more times. It worked every time (of course)


The interesting part, I should mention, is that I have found that when authentication *is* enabled, I ran into the issue maybe 4 out of 5 times or so. Every now and then it *doesn't* fail, for whatever reason. Then I kill the deploy, delete the overcloud, retry, and then it fails again.

Ok, I have reproduced this now. 

So it seems we are able to authenticate fine and it works the first time. The problem seems to come when we try to re-use a token and get a 401. So we try to re-authenticate here:
https://github.com/openstack/tripleo-common/blob/stable/train/tripleo_common/image/image_uploader.py#L256

And something about that re-auth process is not working. Each attempt to re-auth just yields another 401.


I'll keep digging into this and see what I can figure out.

Hey,

So, after reproducing this. I added some debug code in the mitral_executor container, restarted the container and tried again. But I haven't been able to reproduce it since unfortunately. I removed the debug code, tried again. Did a minor update, tried again. But alas, I'm having no luck.

I was just wondering if restarting your mistral_executor container gives you similar results?
If you systemctl restart tripleo_mistral_executor and then try the deployment again, are you still able to reproduce the error?

I tried different variations a couple of times each, and I've not been able to find a way to make it fail all the times. Restarting mistral_executor between attempts does seem to make it work [0].

Once it works, the way I have found to make it fail again has always been to delete the overcloud. It has succeeded 5 times in a row, with and without mistral_executor restarts in the middle, and it was only when I deleted the overcloud that it failed again [1].

[0]
(undercloud) [stack.lab ~]$ date ; openstack overcloud deploy --templates -e templates/node-info.yaml -e containers-prepare-parameter-tag-satellite.yaml
Wed Oct 19 10:14:33 CEST 2022
/usr/lib/python3.6/site-packages/openstack/resource.py:351: DeprecationWarning: inspect.getargspec() is deprecated since Python 3.0, use inspect.signature() or inspect.getfullargspec()
  len(inspect.getargspec(type_).args) > 1)
Removing the current plan files
Uploading new plan files
Temporary Swift GET/PUT URL parameters have successfully been updated.
Plan updated.
Processing templates in the directory /tmp/tripleoclient-fvnew9e4/tripleo-heat-templates
/usr/lib/python3.6/site-packages/openstack/resource.py:351: DeprecationWarning: inspect.getargspec() is deprecated since Python 3.0, use inspect.signature() or inspect.getfullargspec()
  len(inspect.getargspec(type_).args) > 1)
WARNING: Following parameter(s) are defined but not currently used in the deployment plan. These parameters may be valid but not in use due to the service or deployment configuration. CtlplaneNetworkAttributes
Deploying templates in the directory /tmp/tripleoclient-fvnew9e4/tripleo-heat-templates
Initializing overcloud plan deployment
401 Client Error: Unauthorized for url: https://satellite.keller.lab:443/v2/keller-library-osp_16_2_cv-osp_containers-cinder-api/tags/list
Exception occured while running the command
Traceback (most recent call last):
...
(undercloud) [stack.lab ~]$ sudo systemctl restart tripleo_mistral_executor
(undercloud) [stack.lab ~]$ 
(undercloud) [stack.lab ~]$ date ; openstack overcloud deploy --templates -e templates/node-info.yaml -e containers-prepare-parameter-tag-satellite.yaml
Wed Oct 19 10:19:15 CEST 2022
/usr/lib/python3.6/site-packages/openstack/resource.py:351: DeprecationWarning: inspect.getargspec() is deprecated since Python 3.0, use inspect.signature() or inspect.getfullargspec()
  len(inspect.getargspec(type_).args) > 1)
Removing the current plan files
Uploading new plan files
Temporary Swift GET/PUT URL parameters have successfully been updated.
Plan updated.
Processing templates in the directory /tmp/tripleoclient-48hqwfeo/tripleo-heat-templates
/usr/lib/python3.6/site-packages/openstack/resource.py:351: DeprecationWarning: inspect.getargspec() is deprecated since Python 3.0, use inspect.signature() or inspect.getfullargspec()
  len(inspect.getargspec(type_).args) > 1)
WARNING: Following parameter(s) are defined but not currently used in the deployment plan. These parameters may be valid but not in use due to the service or deployment configuration. CtlplaneNetworkAttributes
Deploying templates in the directory /tmp/tripleoclient-48hqwfeo/tripleo-heat-templates
Initializing overcloud plan deployment
Creating overcloud Heat stack             <-- WORKED


[1]
(undercloud) [stack.lab ~]$ openstack overcloud delete overcloud -y
Undeploying stack overcloud...
Waiting for messages on queue 'tripleo' with no timeout.
Deleting plan overcloud...
Success.
(undercloud) [stack.lab ~]$ date ; openstack overcloud deploy --templates -e templates/node-info.yaml -e containers-prepare-parameter-tag-satellite.yaml
Wed Oct 19 11:11:30 CEST 2022
/usr/lib/python3.6/site-packages/openstack/resource.py:351: DeprecationWarning: inspect.getargspec() is deprecated since Python 3.0, use inspect.signature() or inspect.getfullargspec()
  len(inspect.getargspec(type_).args) > 1)
Creating Swift container to store the plan
Creating plan from template files in: /tmp/tripleoclient-yd88dm8n/tripleo-heat-templates
Plan created.
Processing templates in the directory /tmp/tripleoclient-yd88dm8n/tripleo-heat-templates
/usr/lib/python3.6/site-packages/openstack/resource.py:351: DeprecationWarning: inspect.getargspec() is deprecated since Python 3.0, use inspect.signature() or inspect.getfullargspec()
  len(inspect.getargspec(type_).args) > 1)
WARNING: Following parameter(s) are defined but not currently used in the deployment plan. These parameters may be valid but not in use due to the service or deployment configuration. CtlplaneNetworkAttributes
Deploying templates in the directory /tmp/tripleoclient-yd88dm8n/tripleo-heat-templates
Initializing overcloud plan deployment
401 Client Error: Unauthorized for url: https://satellite.keller.lab:443/v2/keller-library-osp_16_2_cv-osp_containers-cinder-api/tags/list
Exception occured while running the command
Traceback (most recent call last):

Hey, just sharing an update on this.

I haven't figured it out just yet. But, interestingly this doesn't seem to happen at all on 16.1. If I pull the 16.2 mistral containers to my 16.1 undercloud. I can reproduce it over and over again in the same way. So it has to be something to do with the 16.2 libraries in the mistral containers. So that kind of narrows it down a little bit, I can start looking at what differences exist between those versions and hopefully find something additional.

So something happened between these two versions:

Working:
openstack-tripleo-common-11.3.3-0.20200611110656.f7715be.el8ost.noarch
python3-tripleo-common-11.3.3-0.20200611110656.f7715be.el8ost.noarch


Install an updated version in the containers:
openstack-tripleo-common-11.7.1-2.20220920004738.8cefa87.el8osttrunk.noarch.rpm                 openstack-tripleo-common-containers-11.7.1-2.20220920004738.8cefa87.el8osttrunk.noarch.rpm
openstack-tripleo-common-container-base-11.7.1-2.20220920004738.8cefa87.el8osttrunk.noarch.rpm  python3-tripleo-common-11.7.1-2.20220920004738.8cefa87.el8osttrunk.noarch.rpm

Restart the containers and it's broken. So something between 11.3.3 and 11.7.1 is the issue.


I'll dig into that and hopefully get back to you with an answer.

Ok, seems to be introduce by:
https://review.opendev.org/c/openstack/tripleo-common/+/756514

And I proposed this as a potential solution:
https://review.opendev.org/c/openstack/tripleo-common/+/862887

Essentially, it tries to lookup a key that doesn't exist in the bearer token:
https://github.com/openstack/tripleo-common/blob/stable/train/tripleo_common/image/image_uploader.py#L322

There is no "expires_in" field. If I print the token, we can see it is "expires_at":
2022-10-28 04:56:15.363 7 INFO tripleo_common.image.image_uploader [-] bshephar-debug: Printing {'token': '$2a$09$1b6453892473a467d0737uJ56J02CLEXEkOaX0pdLWgLMlg.qWDSi', 'expires_at': '2022-10-28T04:54:58.296Z', 'issued_at': '2022-10-17T23:45:09.306Z'}


So my patch fixes that, along with the expiration time computation. I'll need to add a unittest for this to make sure we don't repeat that in the future. But feel free to test out that patch by manually patching the mistral_executor container if you like.

We'll proceed with the proposed patch to work around the Satellite bearer token issue at this stage. I'll back port it to Train once it's merged and we'll ensure it ships with a upcoming z-stream
https://review.opendev.org/c/openstack/tripleo-common/+/862887

Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory (Red Hat OpenStack Platform 16.2.5 (Train) bug fix and enhancement advisory), and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

https://access.redhat.com/errata/RHBA-2023:1763

(In reply to Brendan Shephard from comment #19)
> Ok, seems to be introduce by:
> https://review.opendev.org/c/openstack/tripleo-common/+/756514

Have you seen this BZ?https://bugzilla.redhat.com/show_bug.cgi?id=2165527 I learned from the assignee of that BZ that it appears that tokens were not properly shared and instead threads were overriding them. 
https://bugzilla.redhat.com/show_bug.cgi?id=2165527#c14

> 
> And I proposed this as a potential solution:
> https://review.opendev.org/c/openstack/tripleo-common/+/862887
> 
> Essentially, it tries to lookup a key that doesn't exist in the bearer token:
> https://github.com/openstack/tripleo-common/blob/stable/train/tripleo_common/
> image/image_uploader.py#L322
> 
> There is no "expires_in" field. If I print the token, we can see it is
> "expires_at":
> 2022-10-28 04:56:15.363 7 INFO tripleo_common.image.image_uploader [-]
> bshephar-debug: Printing {'token':
> '$2a$09$1b6453892473a467d0737uJ56J02CLEXEkOaX0pdLWgLMlg.qWDSi',
> 'expires_at': '2022-10-28T04:54:58.296Z', 'issued_at':
> '2022-10-17T23:45:09.306Z'}
> 
> 
> So my patch fixes that, along with the expiration time computation. I'll
> need to add a unittest for this to make sure we don't repeat that in the
> future. But feel free to test out that patch by manually patching the
> mistral_executor container if you like.