search

juju / python-libjuju

Python library for the Juju API
Apache License 2.0
59 stars 100 forks source link

[Bug]: Conecting to model is stuck in loop (version 2.9) #805

Closed tbaumann closed 1 year ago

tbaumann commented 1 year ago

Description

I just ran my code for the first time in production. The juju version is a little different but I expected to be fine with the latest 2.9 release.

First I tried juju==2.9.11 and then later juju==2.9.38.1.

Connecting seems to hang in a loop. When I enable debug I see it reconnects to the API socket all the time.

Juju cli works just fine. Any idea what's causing this?

[02/27/23 12:31:57] DEBUG    DEBUG:asyncio:Using selector: EpollSelector                                                                                                 selector_events.py:59
                    DEBUG    DEBUG:websockets.protocol:client - state = CONNECTING                                                                                             protocol.py:225
                    DEBUG    DEBUG:websockets.protocol:client - event = connection_made(<asyncio.sslproto._SSLProtocolTransport object at 0x7facc5270d60>)                    protocol.py:1193
                    DEBUG    DEBUG:websockets.protocol:client - state = OPEN                                                                                                   protocol.py:289
                    DEBUG    DEBUG:juju.client.connection:Driver connected to juju wss://100.115.0.216:17070/model/f9a61fc1-09b9-4f00-81c8-731a61fd7e97/api                  connection.py:810
                    DEBUG    DEBUG:juju.client.connection:connection 140380009976880 -> {                                                                                    connection.py:598
                               "type": "Admin",                                                                                                                                               
                               "request": "Login",                                                                                                                                            
                               "version": 3,                                                                                                                                                  
                               "params": {                                                                                                                                                    
                                 "auth-tag": "user-admin",                                                                                                                                    
                                 "credentials": "d9050d044691b4efb8637e18dab6c368"                                                                                                            
                               },                                                                                                                                                             
                               "request-id": 1                                                                                                                                                
                             }                                                                                                                                                                
                    DEBUG    DEBUG:websockets.protocol:client > Frame(fin=True, opcode=1, data=b'{\n  "type": "Admin",\n  "request": "Login",\n  "version": 3,\n  "params":    protocol.py:898
                             {\n    "auth-tag": "user-admin",\n    "credentials": "d9050d044691b4efb8637e18dab6c368"\n  },\n  "request-id": 1\n}', rsv1=False, rsv2=False,                    
                             rsv3=False)                                                                                                                                                      
                    DEBUG    DEBUG:websockets.protocol:client < Frame(fin=False, opcode=1,                                                                                     protocol.py:886
                             data=b'{"request-id":1,"response":{"servers":[[{"value":"100.115.0.216","type":"ipv4","scope":"public","port":17070},{"value":"127.0.0.1","type":                
                             "ipv4","scope":"local-machine","port":17070},{"value":"::1","type":"ipv6","scope":"local-machine","port":17070}],[{"value":"100.115.0.217","type"                
                             :"ipv4","scope":"public","port":17070},{"value":"127.0.0.1","type":"ipv4","scope":"local-machine","port":17070},{"value":"::1","type":"ipv6","sco                
                             pe":"local-machine","port":17070}],[{"value":"100.115.0.198","type":"ipv4","scope":"public","port":17070},{"value":"127.0.0.1","type":"ipv4","sco                
                             pe":"local-machine","port":17070},{"value":"::1","type":"ipv6","scope":"local-machine","port":17070}]],"model-tag":"model-f9a61fc1-09b9-4f00-81c8                
                             -731a61fd7e97","controller-tag":"controller-4a1bd089-c100-45f6-8bfe-224b4d0dc747","user-info":{"display-name":"","identity":"user-admin","control                
                             ler-access":"superuser","model-access":"admin"},"facades":[{"name":"Action","versions":[2,3,4,5,6,7]},{"name":"ActionPruner","versions":[1]},{"na                
                             me":"Agent","versions":[2,3]},{"name":"AgentTools","versions":[1]},{"name":"AllWatcher","versions":[1,2]},{"name":"Annotations","versions":[2]},{                
                             "name":"Application","versions":[1,2,3,4,5,6,7,8,9,10,11,12,13,14]},{"name":"ApplicationScaler","versions":[1]},{"name":"Backups","versions":[1,2                
                             ,3]},{"name":"Block","versions":[2]},{"name":"Bundle","versions":[1,2,3,4,5,6]},{"name":"CAASAdmission","versions":[1]},{"name":"CAASAgent","vers                
                             ions":[1,2]},{"name":"CAASApplication","versions":[1]},{"name":"CAASApplicationProvisioner","versions":[1]},{"name":"CAASFirewaller","versions":[                
                             1]},{"name":"CAASFirewallerEmbedded","versions":[1]},{"name":"CAASModelConfigManager","versions":[1]},{"name":"CAASModelOperator","versions":[1]}                
                             ,{"name":"CAASOperator","versions":[1]},{"name":"CAASOperatorProvisioner","versions":[1]},{"name":"CAASOperatorUpgrader","versions":[1]},{"name":                
                             "CAASUnitProvisioner","versions":[2]},{"name":"CharmDownloader","versions":[1]},{"name":"CharmHub","versions":[1]},{"name":"CharmRevisionUpdater"                
                             ,"versions":[2]},{"name":"Charms","versions":[2,3,4]},{"name":"Cleaner","versions":[2]},{"name":"Client","versions":[1,2,3,4,5]},{"name":"Credent                
                             ialManager","versions":[1]},{"name":"CredentialValidator","versions":[1,2]},{"name":"CrossModelRelations","versions":[1,2]},{"name":"Deployer","v                
                             ersions":[1]},{"name":"DiskManager","versions":[2]},{"name":"EntityWatcher","versions":[2]},{"name":"EnvironUpgrader","versions":[1]},{"name":"Ex                
                             ternalControllerUpdater","versions":[1]},{"name":"FanConfigurer","versions":[1]},{"name":"FilesystemAttachmentsWatcher","versions":[2]},{"name":"                
                             FirewallRules","versions":[1]},{"name":"Firewaller","versions":[3,4,5,6,7]},{"name":"HighAvailability","versions":[2]},{"name":"HostKeyReporter",                
                             "versions":[1]},{"name":"ImageManager","versions":[2]},{"name":"ImageMetadata","versions":[3]},{"name":"ImageMetadataManager","versions":[1]},{"n                
                             ame":"InstanceMutater","versions":[1,2,3]},{"name":"InstancePoller","versions":[3,4]},{"name":"KeyManager","versions":[1]},{"name":"KeyUpdater","                
                             versions":[1]},{"name":"LeadershipService","versions":[2]},{"name":"LifeFlag","versions":[1]},{"name":"LogForwarding","versions":[1]},{"name":"Lo                
                             gger","versions":[1]},{"name":"MachineActions","versions":[1]},{"name":"MachineManager","versions":[2,3,4,5,6,7]},{"name":"MachineUndertaker","ve                
                             rsions":[1]},{"name":"Machiner","versions":[1,2,3,4,5]},{"name":"MeterStatus","versions":[1,2]},{"name":"MetricsAdder","versions":[2]},{"name":"M                
                             etricsDebug","versions":[2]},{"name":"MetricsManager","versions":[1]},{"name":"MigrationFlag","versions":[1]},{"name":"MigrationMaster","versions                
                             ":[1,2,3]},{"name":"MigrationMinion","versions":[1]},{"name":"MigrationStatusWatcher","versions":[1]},{"name":"ModelConfig","versions":[1,2,3]},{                
                             "name":"ModelGeneration","versions":[1,2,3,4]},{"name":"NotifyWatcher","versions":[1]},{"name":"OfferStatusWatcher","versions":[1]},{"name":"Payl                
                             oads","versions":[1]},{"name":"PayloadsHookContext","versions":[1]},{"name":"Pinger","versions":[1]},{"name":"Provisioner","versions":[3,4,5,6,7,                
                             8,9,10,11]},{"name":"ProxyUpd', rsv1=False, rsv2=False, rsv3=False)                                                                                              
                    DEBUG    DEBUG:websockets.protocol:client < Frame(fin=True, opcode=0,                                                                                      protocol.py:886
                             data=b'ater","versions":[1,2]},{"name":"RaftLease","versions":[1,2]},{"name":"Reboot","versions":[2]},{"name":"RelationStatusWatcher","versions":                
                             [1]},{"name":"RelationUnitsWatcher","versions":[1]},{"name":"RemoteRelationWatcher","versions":[1]},{"name":"RemoteRelations","versions":[1,2]},{                
                             "name":"Resources","versions":[1,2]},{"name":"ResourcesHookContext","versions":[1]},{"name":"Resumer","versions":[2]},{"name":"RetryStrategy","ve                
                             rsions":[1]},{"name":"SSHClient","versions":[1,2,3]},{"name":"SecretsManager","versions":[1]},{"name":"SecretsRotationWatcher","versions":[1]},{"                
                             name":"Singular","versions":[2]},{"name":"Spaces","versions":[2,3,4,5,6]},{"name":"StatusHistory","versions":[2]},{"name":"Storage","versions":[3                
                             ,4,5,6]},{"name":"StorageProvisioner","versions":[3,4]},{"name":"StringsWatcher","versions":[1]},{"name":"Subnets","versions":[2,3,4]},{"name":"U                
                             ndertaker","versions":[1]},{"name":"UnitAssigner","versions":[1]},{"name":"Uniter","versions":[4,5,6,7,8,9,10,11,12,13,14,15,16,17,18]},{"name":"                
                             UpgradeSeries","versions":[1,2,3]},{"name":"UpgradeSteps","versions":[1,2]},{"name":"Upgrader","versions":[1]},{"name":"VolumeAttachmentPlansWatc                
                             her","versions":[1]},{"name":"VolumeAttachmentsWatcher","versions":[2]}],"server-version":"2.9.33"}}\n', rsv1=False, rsv2=False, rsv3=False)                     
                    DEBUG    DEBUG:juju.client.connection:connection 140380009976880 <- {'request-id': 1, 'response': {'servers': [[{'value': '100.115.0.216', 'type':       connection.py:621
                             'ipv4', 'scope': 'public', 'port': 17070}, {'value': '127.0.0.1', 'type': 'ipv4', 'scope': 'local-machine', 'port': 17070}, {'value': '::1',                     
                             'type': 'ipv6', 'scope': 'local-machine', 'port': 17070}], [{'value': '100.115.0.217', 'type': 'ipv4', 'scope': 'public', 'port': 17070},                        
                             {'value': '127.0.0.1', 'type': 'ipv4', 'scope': 'local-machine', 'port': 17070}, {'value': '::1', 'type': 'ipv6', 'scope': 'local-machine',                      
                             'port': 17070}], [{'value': '100.115.0.198', 'type': 'ipv4', 'scope': 'public', 'port': 17070}, {'value': '127.0.0.1', 'type': 'ipv4', 'scope':                  
                             'local-machine', 'port': 17070}, {'value': '::1', 'type': 'ipv6', 'scope': 'local-machine', 'port': 17070}]], 'model-tag':                                       
                             'model-f9a61fc1-09b9-4f00-81c8-731a61fd7e97', 'controller-tag': 'controller-4a1bd089-c100-45f6-8bfe-224b4d0dc747', 'user-info':                                  
                             {'display-name': '', 'identity': 'user-admin', 'controller-access': 'superuser', 'model-access': 'admin'}, 'facades': [{'name': 'Action',                        
                             'versions': [2, 3, 4, 5, 6, 7]}, {'name': 'ActionPruner', 'versions': [1]}, {'name': 'Agent', 'versions': [2, 3]}, {'name': 'AgentTools',                        
                             'versions': [1]}, {'name': 'AllWatcher', 'versions': [1, 2]}, {'name': 'Annotations', 'versions': [2]}, {'name': 'Application', 'versions': [1,                  
                             2, 3, 4, 5, 6, 7, 8, 9, 10, 11, 12, 13, 14]}, {'name': 'ApplicationScaler', 'versions': [1]}, {'name': 'Backups', 'versions': [1, 2, 3]},                        
                             {'name': 'Block', 'versions': [2]}, {'name': 'Bundle', 'versions': [1, 2, 3, 4, 5, 6]}, {'name': 'CAASAdmission', 'versions': [1]}, {'name':                     
                             'CAASAgent', 'versions': [1, 2]}, {'name': 'CAASApplication', 'versions': [1]}, {'name': 'CAASApplicationProvisioner', 'versions': [1]},                         
                             {'name': 'CAASFirewaller', 'versions': [1]}, {'name': 'CAASFirewallerEmbedded', 'versions': [1]}, {'name': 'CAASModelConfigManager',                             
                             'versions': [1]}, {'name': 'CAASModelOperator', 'versions': [1]}, {'name': 'CAASOperator', 'versions': [1]}, {'name':                                            
                             'CAASOperatorProvisioner', 'versions': [1]}, {'name': 'CAASOperatorUpgrader', 'versions': [1]}, {'name': 'CAASUnitProvisioner', 'versions':                      
                             [2]}, {'name': 'CharmDownloader', 'versions': [1]}, {'name': 'CharmHub', 'versions': [1]}, {'name': 'CharmRevisionUpdater', 'versions': [2]},                    
                             {'name': 'Charms', 'versions': [2, 3, 4]}, {'name': 'Cleaner', 'versions': [2]}, {'name': 'Client', 'versions': [1, 2, 3, 4, 5]}, {'name':                       
                             'CredentialManager', 'versions': [1]}, {'name': 'CredentialValidator', 'versions': [1, 2]}, {'name': 'CrossModelRelations', 'versions': [1,                      
                             2]}, {'name': 'Deployer', 'versions': [1]}, {'name': 'DiskManager', 'versions': [2]}, {'name': 'EntityWatcher', 'versions': [2]}, {'name':                       
                             'EnvironUpgrader', 'versions': [1]}, {'name': 'ExternalControllerUpdater', 'versions': [1]}, {'name': 'FanConfigurer', 'versions': [1]},                         
                             {'name': 'FilesystemAttachmentsWatcher', 'versions': [2]}, {'name': 'FirewallRules', 'versions': [1]}, {'name': 'Firewaller', 'versions': [3,                    
                             4, 5, 6, 7]}, {'name': 'HighAvailability', 'versions': [2]}, {'name': 'HostKeyReporter', 'versions': [1]}, {'name': 'ImageManager', 'versions':                  
                             [2]}, {'name': 'ImageMetadata', 'versions': [3]}, {'name': 'ImageMetadataManager', 'versions': [1]}, {'name': 'InstanceMutater', 'versions':                     
                             [1, 2, 3]}, {'name': 'InstancePoller', 'versions': [3, 4]}, {'name': 'KeyManager', 'versions': [1]}, {'name': 'KeyUpdater', 'versions': [1]},                    
                             {'name': 'LeadershipService', 'versions': [2]}, {'name': 'LifeFlag', 'versions': [1]}, {'name': 'LogForwarding', 'versions': [1]}, {'name':                      
                             'Logger', 'versions': [1]}, {'name': 'MachineActions', 'versions': [1]}, {'name': 'MachineManager', 'versions': [2, 3, 4, 5, 6, 7]}, {'name':                    
                             'MachineUndertaker', 'versions': [1]}, {'name': 'Machiner', 'versions': [1, 2, 3, 4, 5]}, {'name': 'MeterStatus', 'versions': [1, 2]}, {'name':                  
                             'MetricsAdder', 'versions': [2]}, {'name': 'MetricsDebug', 'versions': [2]}, {'name': 'MetricsManager', 'versions': [1]}, {'name':                               
                             'MigrationFlag', 'versions': [1]}, {'name': 'MigrationMaster', 'versions': [1, 2, 3]}, {'name': 'MigrationMinion', 'versions': [1]}, {'name':                    
                             'MigrationStatusWatcher', 'versions': [1]}, {'name': 'ModelConfig', 'versions': [1, 2, 3]}, {'name': 'ModelGeneration', 'versions': [1, 2, 3,                    
                             4]}, {'name': 'NotifyWatcher', 'versions': [1]}, {'name': 'OfferStatusWatcher', 'versions': [1]}, {'name': 'Payloads', 'versions': [1]},                         
                             {'name': 'PayloadsHookContext', 'versions': [1]}, {'name': 'Pinger', 'versions': [1]}, {'name': 'Provisioner', 'versions': [3, 4, 5, 6, 7, 8,                    
                             9, 10, 11]}, {'name': 'ProxyUpdater', 'versions': [1, 2]}, {'name': 'RaftLease', 'versions': [1, 2]}, {'name': 'Reboot', 'versions': [2]},                       
                             {'name': 'RelationStatusWatcher', 'versions': [1]}, {'name': 'RelationUnitsWatcher', 'versions': [1]}, {'name': 'RemoteRelationWatcher',                         
                             'versions': [1]}, {'name': 'RemoteRelations', 'versions': [1, 2]}, {'name': 'Resources', 'versions': [1, 2]}, {'name': 'ResourcesHookContext',                   
                             'versions': [1]}, {'name': 'Resumer', 'versions': [2]}, {'name': 'RetryStrategy', 'versions': [1]}, {'name': 'SSHClient', 'versions': [1, 2,                     
                             3]}, {'name': 'SecretsManager', 'versions': [1]}, {'name': 'SecretsRotationWatcher', 'versions': [1]}, {'name': 'Singular', 'versions': [2]},                    
                             {'name': 'Spaces', 'versions': [2, 3, 4, 5, 6]}, {'name': 'StatusHistory', 'versions': [2]}, {'name': 'Storage', 'versions': [3, 4, 5, 6]},                      
                             {'name': 'StorageProvisioner', 'versions': [3, 4]}, {'name': 'StringsWatcher', 'versions': [1]}, {'name': 'Subnets', 'versions': [2, 3, 4]},                     
                             {'name': 'Undertaker', 'versions': [1]}, {'name': 'UnitAssigner', 'versions': [1]}, {'name': 'Uniter', 'versions': [4, 5, 6, 7, 8, 9, 10, 11,                    
                             12, 13, 14, 15, 16, 17, 18]}, {'name': 'UpgradeSeries', 'versions': [1, 2, 3]}, {'name': 'UpgradeSteps', 'versions': [1, 2]}, {'name':                           
                             'Upgrader', 'versions': [1]}, {'name': 'VolumeAttachmentPlansWatcher', 'versions': [1]}, {'name': 'VolumeAttachmentsWatcher', 'versions':                        
                             [2]}], 'server-version': '2.9.33'}}                                                                                                                              
⠋ Connecting to model                    DEBUG    DEBUG:juju.model:Starting watcher task                                                                                                              model.py:1135
                    DEBUG    DEBUG:juju.client.connection:connection 140380009976880 -> {                                                                                    connection.py:598
                               "type": "ModelConfig",                                                                                                                                         
                               "request": "ModelGet",                                                                                                                                         
                               "version": 2,                                                                                                                                                  
                               "params": {},                                                                                                                                                  
                               "request-id": 2                                                                                                                                                
                             }                                                                                                                                                                
                    DEBUG    DEBUG:websockets.protocol:client > Frame(fin=True, opcode=1, data=b'{\n  "type": "ModelConfig",\n  "request": "ModelGet",\n  "version": 2,\n      protocol.py:898
                             "params": {},\n  "request-id": 2\n}', rsv1=False, rsv2=False, rsv3=False)                                                                                        
                    DEBUG    DEBUG:juju.client.connection:connection 140380009976880 -> {                                                                                    connection.py:598
                               "type": "Pinger",                                                                                                                                              
                               "request": "Ping",                                                                                                                                             
                               "version": 1,                                                                                                                                                  
                               "params": {},                                                                                                                                                  
                               "request-id": 3                                                                                                                                                
                             }                                                                                                                                                                
                    DEBUG    DEBUG:websockets.protocol:client > Frame(fin=True, opcode=1, data=b'{\n  "type": "Pinger",\n  "request": "Ping",\n  "version": 1,\n  "params":    protocol.py:898
                             {},\n  "request-id": 3\n}', rsv1=False, rsv2=False, rsv3=False)                                                                                                  
                    DEBUG    DEBUG:websockets.protocol:client < Frame(fin=True, opcode=1, data=b'{"request-id":3,"response":{}}\n', rsv1=False, rsv2=False, rsv3=False)        protocol.py:886
                    DEBUG    DEBUG:juju.client.connection:connection 140380009976880 <- {'request-id': 3, 'response': {}}                                                    connection.py:621
                    DEBUG    DEBUG:websockets.protocol:client < Frame(fin=False, opcode=1,                                                                                     protocol.py:886
                             data=b'{"request-id":2,"response":{"config":{"agent-metadata-url":{"value":"https://juju-agents.repo.in.pan-net.eu/dev/","source":"controller"},"                
                             agent-stream":{"value":"released","source":"controller"},"agent-version":{"value":"2.9.33","source":"model"},"apt-ftp-proxy":{"value":"http://100                
                             .115.0.10:8000","source":"controller"},"apt-http-proxy":{"value":"http://100.115.0.10:8000","source":"controller"},"apt-https-proxy":{"value":"ht                
                             tp://100.115.0.10:8000","source":"controller"},"apt-mirror":{"value":"","source":"default"},"apt-no-proxy":{"value":"","source":"default"},"autom                
                             atically-retry-hooks":{"value":true,"source":"default"},"backup-dir":{"value":"","source":"default"},"charmhub-url":{"value":"https://api.charmhu                
                             b.io","source":"default"},"cloudinit-userdata":{"value":"apt:\\n  disable_suites: [backports]\\n  preserve_sources_list: false\\n  primary:\\n                   
                             - arches: [amd64]\\n      uri: http://ubuntu.repo.in.pan-net.eu/dev/ubuntu\\nca-certs:\\n  trusted:\\n  ## easyrsa_ca.crt\\n  - |\\n                             
                             -----BEGIN CERTIFICATE-----\\n    
[snip]
                             TCCzx83cye5B8AOGqm5IE+KYPBOWUGkiM5sKLRG7cu90dZvgmXwqdxE1IjMjIcJE\\n    uirOFgN7Ny4=\\n    -----END                                                               
                             CERTIFICATE-----\\n","source":"controller"},"container-image-metadata-url":{"value":"https://lxd-images.repo.in.pan-net.eu/dev/","source":"contro                
                             ller"},"container-image-stream":{"value":"released","source":"controller"},"container-inherit-properties":{"value":"","source":"default"},"contai                
                             ner-networking-method":{"value":"provider","source":"model"},"default-series":{"value":"focal","source":"default"},"default-space":{"value":"","s                
                             ource":"default"},"development":{"value":false,"source":"default"},"disable-network-management":{"value":false,"source":"default"},"disable-telem                
                             etry":{"value":false,"source":"default"},"egress-subnets":{"value":"","source":"default"},"enable-os-refresh-update":{"value":true,"source":"defa                
                             ult"},"enable-os-upgrade":{"value":true,"source":"default"},"fan-config":{"value":"","source":"default"},"firewall-mode":{"value":"instance","sou                
                             rce":"default"},"ftp-proxy":{"value":"","source":"default"},"http-proxy":{"value":"","source":"default"},"https-proxy":{"value":"","source":"defa                
                             ult"},"ignore-machine-addresses":{"value":false,"source":"default"},"image-metadata-url":{"value":"","source":"default"},"image-stream":{"value":                
                             "released","source":"default"},"juju-ftp-proxy":{"value":"","source":"default"},"juju-http-proxy":{"value":"http://100.115.0.10:8000","source":"c                
                             ontroller"},"juju-https-proxy":{"value":"http://100.115.0.10:8000","source":"controller"},"juju-no-proxy":{"value":"127.0.0.1,localhost,::1,100.1                
                             15.0.0/24","source":"controller"},"logforward-enabled":{"value":false,"source":"default"},"logging-config":{"value":"\\u003croot\\u003e=INFO","so                
                             urce":"model"},"logging-output":{"value":"","source":"default"},"lxd-snap-channel":{"value":"latest/stable","source":"default"},"max-action-resul                
                             ts-age":{"value":"336h","source":"default"},"max-action-results-size":{"value":"5G","source":"default"},"max-status-history-age":{"value":"336h",                
                             "source":"default"},"max-status-history-size":{"value":"5G","source":"default"},"name":{"value":"openstack","source":"model"},"net-bond-reconfigu                
                             re-delay":{"value":17,"source":"default"},"no-proxy":{"value":"127.0.0.1,localhost,::1","source":"default"},"num-container-provision-workers":{"v                
                             alue":4,"source":"default"},"num-provision-workers":{"value":16,"source":"default"},"provisioner-harvest-mode":{"value":"destroyed","source":"def                
                             ault"},"proxy-ssh":{"value":false,"source":"default"},"resource-tags":{"value":{},"source":"model"},"snap-http-proxy":{"value":"http://100.115.0.                
                             10:8000","source":"model"},"snap-https-proxy":{"value":"http://100.115.0.10:8000","source":"model"},"snap-store-assertions":{"value":"","source":                
                             "default"},"snap-store-proxy":{"value":"","source":"default"},"snap-store-proxy-url":{"value":"","source":"default"},"ssl-hostname-verification":                
                             {"value":true,"source":"default"},"storage-default-block-source":{"value":"maas","source":"model"},"test-mode":{"value":false,"source":"default"}                
                             ,"transmit-vendor-metrics":{"value":true,"source":"default"},"type":{"value":"maas","source":"model"},"update-status-hook-interval":{"value":"5m"                
                             ,"source":"default"},"uuid":{"value":"f9a61fc1-09b9-4f00-81c8-731a61fd7e97","source":"model"}}}}\n', rsv1=False, rsv2=False, rsv3=False)                         
                    DEBUG    DEBUG:websockets.protocol:client < Frame(fin=True, opcode=0, data=b'', rsv1=False, rsv2=False, rsv3=False)                                        protocol.py:886
                    DEBUG    DEBUG:juju.client.connection:connection 140380009976880 <- {'request-id': 2, 'response': {'config': {'agent-metadata-url': {'value':            connection.py:621
                             'https://juju-agents.repo.in.pan-net.eu/dev/', 'source': 'controller'}, 'agent-stream': {'value': 'released', 'source': 'controller'},                           
                             'agent-version': {'value': '2.9.33', 'source': 'model'}, 'apt-ftp-proxy': {'value': 'http://100.115.0.10:8000', 'source': 'controller'},                         
                             'apt-http-proxy': {'value': 'http://100.115.0.10:8000', 'source': 'controller'}, 'apt-https-proxy': {'value': 'http://100.115.0.10:8000',                        
                             'source': 'controller'}, 'apt-mirror': {'value': '', 'source': 'default'}, 'apt-no-proxy': {'value': '', 'source': 'default'},                                   
                             'automatically-retry-hooks': {'value': True, 'source': 'default'}, 'backup-dir': {'value': '', 'source': 'default'}, 'charmhub-url': {'value':                   
                             'https://api.charmhub.io', 'source': 'default'}, 'cloudinit-userdata': {'value': 'apt:\n  disable_suites: [backports]\n  preserve_sources_list:                  
                             false\n  primary:\n    - arches: [amd64]\n      uri: http://ubuntu.repo.in.pan-net.eu/dev/ubuntu\nca-certs:\n  trusted:\n  ## easyrsa_ca.crt\n                   
                             - |\n    -----BEGIN CERTIFICATE-----\n    
[snip]
                             -  QIbyJBcK8dUIlr0NdTu/WZ5wHeXAyFbZWZvMgb77\n    -----END CERTIFICATE-----\n                  
                             -----BEGIN CERTIFICATE-----\n    
[snip]
45vmGlGkVTQZR+ye1P5fJlavIJ7InYcds50vuUQ7oEYM0WFmFmKP09U5JKwKiB2o\n                         
                             TCCzx83cye5B8AOGqm5IE+KYPBOWUGkiM5sKLRG7cu90dZvgmXwqdxE1IjMjIcJE\n    uirOFgN7Ny4=\n    -----END CERTIFICATE-----\n', 'source': 'controller'},                   
                             'container-image-metadata-url': {'value': 'https://lxd-images.repo.in.pan-net.eu/dev/', 'source': 'controller'}, 'container-image-stream':                       
                             {'value': 'released', 'source': 'controller'}, 'container-inherit-properties': {'value': '', 'source': 'default'},                                               
                             'container-networking-method': {'value': 'provider', 'source': 'model'}, 'default-series': {'value': 'focal', 'source': 'default'},                              
                             'default-space': {'value': '', 'source': 'default'}, 'development': {'value': False, 'source': 'default'}, 'disable-network-management':                         
                             {'value': False, 'source': 'default'}, 'disable-telemetry': {'value': False, 'source': 'default'}, 'egress-subnets': {'value': '', 'source':                     
                             'default'}, 'enable-os-refresh-update': {'value': True, 'source': 'default'}, 'enable-os-upgrade': {'value': True, 'source': 'default'},                         
                             'fan-config': {'value': '', 'source': 'default'}, 'firewall-mode': {'value': 'instance', 'source': 'default'}, 'ftp-proxy': {'value': '',                        
                             'source': 'default'}, 'http-proxy': {'value': '', 'source': 'default'}, 'https-proxy': {'value': '', 'source': 'default'},                                       
                             'ignore-machine-addresses': {'value': False, 'source': 'default'}, 'image-metadata-url': {'value': '', 'source': 'default'}, 'image-stream':                     
                             {'value': 'released', 'source': 'default'}, 'juju-ftp-proxy': {'value': '', 'source': 'default'}, 'juju-http-proxy': {'value':                                   
                             'http://100.115.0.10:8000', 'source': 'controller'}, 'juju-https-proxy': {'value': 'http://100.115.0.10:8000', 'source': 'controller'},                          
                             'juju-no-proxy': {'value': '127.0.0.1,localhost,::1,100.115.0.0/24', 'source': 'controller'}, 'logforward-enabled': {'value': False, 'source':                   
                             'default'}, 'logging-config': {'value': '<root>=INFO', 'source': 'model'}, 'logging-output': {'value': '', 'source': 'default'},                                 
                             'lxd-snap-channel': {'value': 'latest/stable', 'source': 'default'}, 'max-action-results-age': {'value': '336h', 'source': 'default'},                           
                             'max-action-results-size': {'value': '5G', 'source': 'default'}, 'max-status-history-age': {'value': '336h', 'source': 'default'},                               
                             'max-status-history-size': {'value': '5G', 'source': 'default'}, 'name': {'value': 'openstack', 'source': 'model'},                                              
                             'net-bond-reconfigure-delay': {'value': 17, 'source': 'default'}, 'no-proxy': {'value': '127.0.0.1,localhost,::1', 'source': 'default'},                         
                             'num-container-provision-workers': {'value': 4, 'source': 'default'}, 'num-provision-workers': {'value': 16, 'source': 'default'},                               
                             'provisioner-harvest-mode': {'value': 'destroyed', 'source': 'default'}, 'proxy-ssh': {'value': False, 'source': 'default'}, 'resource-tags':                    
                             {'value': {}, 'source': 'model'}, 'snap-http-proxy': {'value': 'http://100.115.0.10:8000', 'source': 'model'}, 'snap-https-proxy': {'value':                     
                             'http://100.115.0.10:8000', 'source': 'model'}, 'snap-store-assertions': {'value': '', 'source': 'default'}, 'snap-store-proxy': {'value': '',                   
                             'source': 'default'}, 'snap-store-proxy-url': {'value': '', 'source': 'default'}, 'ssl-hostname-verification': {'value': True, 'source':                         
                             'default'}, 'storage-default-block-source': {'value': 'maas', 'source': 'model'}, 'test-mode': {'value': False, 'source': 'default'},                            
                             'transmit-vendor-metrics': {'value': True, 'source': 'default'}, 'type': {'value': 'maas', 'source': 'model'}, 'update-status-hook-interval':                    
                             {'value': '5m', 'source': 'default'}, 'uuid': {'value': 'f9a61fc1-09b9-4f00-81c8-731a61fd7e97', 'source': 'model'}}}}                                            
                    DEBUG    DEBUG:juju.client.connection:connection 140380009976880 -> {                                                                                    connection.py:598
                               "type": "Client",                                                                                                                                              
                               "request": "WatchAll",                                                                                                                                         
                               "version": 2,                                                                                                                                                  
                               "params": {},                                                                                                                                                  
                               "request-id": 4                                                                                                                                                
                             }                                                                                                                                                                
                    DEBUG    DEBUG:websockets.protocol:client > Frame(fin=True, opcode=1, data=b'{\n  "type": "Client",\n  "request": "WatchAll",\n  "version": 2,\n           protocol.py:898
                             "params": {},\n  "request-id": 4\n}', rsv1=False, rsv2=False, rsv3=False)                                                                                        
⠙ Connecting to model                    DEBUG    DEBUG:websockets.protocol:client < Frame(fin=True, opcode=1, data=b'{"request-id":4,"response":{"watcher-id":"1"}}\n', rsv1=False, rsv2=False,    protocol.py:886
                             rsv3=False)                                                                                                                                                      
                    DEBUG    DEBUG:juju.client.connection:connection 140380009976880 <- {'request-id': 4, 'response': {'watcher-id': '1'}}                                   connection.py:621
                    DEBUG    DEBUG:juju.client.connection:connection 140380009976880 -> {                                                                                    connection.py:598
                               "type": "AllWatcher",                                                                                                                                          
                               "request": "Next",                                                                                                                                             
                               "version": 1,                                                                                                                                                  
                               "params": {},                                                                                                                                                  
                               "Id": "1",                                                                                                                                                     
                               "request-id": 5                                                                                                                                                
                             }                                                                                                                                                                
                    DEBUG    DEBUG:websockets.protocol:client > Frame(fin=True, opcode=1, data=b'{\n  "type": "AllWatcher",\n  "request": "Next",\n  "version": 1,\n           protocol.py:898
                             "params": {},\n  "Id": "1",\n  "request-id": 5\n}', rsv1=False, rsv2=False, rsv3=False)                                                                          
⠸ Connecting to model                    DEBUG    DEBUG:websockets.protocol:client ! failing WebSocket connection in the OPEN state: 1009 [no reason]                                              protocol.py:1108
                    DEBUG    DEBUG:websockets.protocol:client - state = CLOSING                                                                                               protocol.py:1139
                    DEBUG    DEBUG:websockets.protocol:client > Frame(fin=True, opcode=8, data=b'\x03\xf1', rsv1=False, rsv2=False, rsv3=False)                               protocol.py:1142
[02/27/23 12:32:02] DEBUG    DEBUG:websockets.protocol:client x closing TCP connection                                                                                        protocol.py:1053

Urgency

Casually reporting

Python-libjuju version

2.9.38.1

Juju version

2.9.33

Reproduce / Test

model = await connect_model()
juanmanuel-tirado commented 1 year ago

I have not seen that behaviour before.

Just to discard an issue with the current version. Could you try and older release juju==2.9.10 or juju==3.0.4 to check if it keeps failing?

tbaumann commented 1 year ago

Interesting.

juju==2.9.10

                    WARNING  WARNING:juju.client.connection:unknown facade EnvironUpgrader                                                                                   connection.py:873
                    WARNING  WARNING:juju.client.connection:unexpected facade EnvironUpgrader found, unable to decipher version to use                                       connection.py:897
                    DEBUG    DEBUG:juju.client.connection:connection 140639884821216 -> {                                                                                    connection.py:597
                               "type": "Pinger",                                                                                                                                              
                               "request": "Ping",                                                                                                                                             
                               "version": 1,                                                                                                                                                  
                               "params": {},                                                                                                                                                  
                               "request-id": 8                                                                                                                                                
                             }                                                                                                                                                                
                    DEBUG    DEBUG:websockets.protocol:client > Frame(fin=True, opcode=1, data=b'{\n  "type": "Pinger",\n  "request": "Ping",\n  "version": 1,\n  "params":    protocol.py:898
                             {},\n  "request-id": 8\n}', rsv1=False, rsv2=False, rsv3=False)                                                                                                  
                    DEBUG    DEBUG:websockets.protocol:client > Frame(fin=True, opcode=1, data=b'{\n  "type": "Pinger",\n  "request": "Ping",\n  "version": 1,\n  "params":    protocol.py:898
                             {},\n  "request-id": 6\n}', rsv1=False, rsv2=False, rsv3=False)                                                                                                  
                    DEBUG    DEBUG:websockets.protocol:client < Frame(fin=True, opcode=1, data=b'{"request-id":8,"response":{}}\n', rsv1=False, rsv2=False, rsv3=False)        protocol.py:886
                    DEBUG    DEBUG:websockets.protocol:client < Frame(fin=True, opcode=1, data=b'{"request-id":6,"response":{}}\n', rsv1=False, rsv2=False, rsv3=False)        protocol.py:886
                    DEBUG    DEBUG:juju.client.connection:connection 140639884821216 <- {'request-id': 8, 'response': {}}                                                    connection.py:620
                    DEBUG    DEBUG:juju.client.connection:connection 140639884821216 <- {'request-id': 6, 'response': {}}                                                    connection.py:620
⠼ Connecting to model[02/27/23 13:28:12] DEBUG    DEBUG:juju.client.connection:connection 140639884821216 -> {                                                                                    connection.py:597
                               "type": "Pinger",                                                                                                                                              
                               "request": "Ping",                                                                                                                                             
                               "version": 1,                                                                                                                                                  
                               "params": {},                                                                                                                                                  
                               "request-id": 9                                                                                                                                                
                             }                                                                                                                                                                
                    DEBUG    DEBUG:websockets.protocol:client > Frame(fin=True, opcode=1, data=b'{\n  "type": "Pinger",\n  "request": "Ping",\n  "version": 1,\n  "params":    protocol.py:898
                             {},\n  "request-id": 9\n}', rsv1=False, rsv2=False, rsv3=False)                                                                                                  
                    DEBUG    DEBUG:websockets.protocol:client < Frame(fin=True, opcode=1, data=b'{"request-id":9,"response":{}}\n', rsv1=False, rsv2=False, rsv3=False)        protocol.py:886
                    DEBUG    DEBUG:juju.client.connection:connection 140639884821216 <- {'request-id': 9, 'response': {}}                                                    connection.py:620
⠧ Connecting to model[02/27/23 13:28:22] DEBUG    DEBUG:websockets.protocol:client > Frame(fin=True, opcode=9, data=b'\x90s.5', rsv1=False, rsv2=False, rsv3=False)                                 protocol.py:898
                    DEBUG    DEBUG:websockets.protocol:client < Frame(fin=True, opcode=10, data=b'\x90s.5', rsv1=False, rsv2=False, rsv3=False)                                protocol.py:886
                    DEBUG    DEBUG:websockets.protocol:client - received solicited pong: 90732e35                                                                              protocol.py:848
⠏ Connecting to model                    DEBUG    DEBUG:juju.client.connection:connection 140639884821216 -> {                                                                                    connection.py:597
                               "type": "Pinger",                                                                                                                                              
                               "request": "Ping",                                                                                                                                             
                               "version": 1,                                                                                                                                                  
                               "params": {},                                                                                                                                                  
                               "request-id": 10                                                                                                                                               
                             }                                                                                                                                                                
                    DEBUG    DEBUG:websockets.protocol:client > Frame(fin=True, opcode=1, data=b'{\n  "type": "Pinger",\n  "request": "Ping",\n  "version": 1,\n  "params":    protocol.py:898
                             {},\n  "request-id": 10\n}', rsv1=False, rsv2=False, rsv3=False)                                                                                                 
                    DEBUG    DEBUG:websockets.protocol:client < Frame(fin=True, opcode=1, data=b'{"request-id":10,"response":{}}\n', rsv1=False, rsv2=False, rsv3=False)       protocol.py:886
                    DEBUG    DEBUG:juju.client.connection:connection 140639884821216 <- {'request-id': 10, 'response': {}}                                                   connection.py:620
⠼ Connecting to model[02/27/23 13:28:32] DEBUG    DEBUG:juju.client.connection:connection 140639884821216 -> {                                                                                    connection.py:597
                               "type": "Pinger",                                                                                                                                              
                               "request": "Ping",                                                                                                                                             
                               "version": 1,                                                                                                                                                  
                               "params": {},                                                                                                                                                  
                               "request-id": 11                                                                                                                                               
                             }                                                                                                                                                                
                    DEBUG    DEBUG:websockets.protocol:client > Frame(fin=True, opcode=1, data=b'{\n  "type": "Pinger",\n  "request": "Ping",\n  "version": 1,\n  "params":    protocol.py:898
                             {},\n  "request-id": 11\n}', rsv1=False, rsv2=False, rsv3=False)                                                                                                 
                    DEBUG    DEBUG:websockets.protocol:client < Frame(fin=True, opcode=1, data=b'{"request-id":11,"response":{}}\n', rsv1=False, rsv2=False, rsv3=False)       protocol.py:886
                    DEBUG    DEBUG:juju.client.connection:connection 140639884821216 <- {'request-id': 11, 'response': {}}                                                   connection.py:620
⠧ Connecting to model[02/27/23 13:28:42] DEBUG    DEBUG:websockets.protocol:client > Frame(fin=True, opcode=9, data=b'\x11\xf5\x9cO', rsv1=False, rsv2=False, rsv3=False)                           protocol.py:898
⠇ Connecting to model                    DEBUG    DEBUG:websockets.protocol:client < Frame(fin=True, opcode=10, data=b'\x11\xf5\x9cO', rsv1=False, rsv2=False, rsv3=False)                          protocol.py:886
                    DEBUG    DEBUG:websockets.protocol:client - received solicited pong: 11f59c4f                                                                              protocol.py:848
⠏ Connecting to model                    DEBUG    DEBUG:juju.client.connection:connection 140639884821216 -> {                                                                                    connection.py:597
                               "type": "Pinger",                                                                                                                                              
                               "request": "Ping",                                                                                                                                             
                               "version": 1,                                                                                                                                                  
                               "params": {},                                                                                                                                                  
                               "request-id": 12                                                                                                                                               
                             }                                                                                                                                                                
                    DEBUG    DEBUG:websockets.protocol:client > Frame(fin=True, opcode=1, data=b'{\n  "type": "Pinger",\n  "request": "Ping",\n  "version": 1,\n  "params":    protocol.py:898
                             {},\n  "request-id": 12\n}', rsv1=False, rsv2=False, rsv3=False)                                                                                                 
                    DEBUG    DEBUG:websockets.protocol:client < Frame(fin=True, opcode=1, data=b'{"request-id":12,"response":{}}\n', rsv1=False, rsv2=False, rsv3=False)       protocol.py:886
                    DEBUG    DEBUG:juju.client.connection:connection 140639884821216 <- {'request-id': 12, 'response': {}}                                                   connection.py:620

So no change there.

But juju==3.0.4 works! This is really fascinating and unexpected since libjuju 3.X dropped support for 2.9.X juju... What should I use now as juju 2.9 user?

juanmanuel-tirado commented 1 year ago

3.0.4 is a transition version, it still provides support for 2.9.

This is weird because 2.9.38.1 was tested with juju 2.9.38 and we didn't find this problem. I'm curious if this only happens for versions older than 2.9.38.

tbaumann commented 1 year ago

Which version should I use to retain support of juju 2.9? As I will be on that version for quite some time. I assumed whatever the latest libjuju 2.9.x is the latest is right.

jameinel commented 1 year ago

So python-libjuju 3.0.* should support both 2.9 and 3.0, though it uses 3.0 semantics. However, that moves you closer to being ready to move to 3.1 in the future (3.1 is the one that actually drops support for 2.9).

tbaumann commented 1 year ago

Ah good, so I should target version 3.0 in my code. Because it has some API breaks vs. 2.9 which I had targeted with my code so far. I will do anything that will give me some level of stability with regards to compatibility.

juanmanuel-tirado commented 1 year ago

Anyway, I've just tried with a fresh 2.9.33 controller and I could connect, add a model, and deploy an ubuntu charm. Couldn't reproduce this connectivity issue.

juanmanuel-tirado commented 1 year ago

I will close this issue as there is a workaround for this and we can't reproduce it right now.

tbaumann commented 1 year ago

Unfortunately I'm not even surprised. Because this worked with my test models. Just the first time I ran it in 'production' it failed like this. But what could be the issue?

Anyway, if I can stay on version 3.0 then I probably don't need to know...

juanmanuel-tirado commented 1 year ago

From the trace it looks like the server simply cut the connection. And this was done after the negotiation of the facades. I cannot say right now what could be the reason for this. It would probably require some additional investigation checking the controller logs.