Project

General

Profile

Bug #26004 » virt-who-debug.txt

Ludwig Bayerlein, 02/06/2019 03:01 PM

 
2019-02-06 14:54:37,194 [virtwho.rhsm_log DEBUG] MainProcess(22022):MainThread @config.py:all_drop_dir_config_sections:1293 - There are files in '/etc/virt-who.d/' not ending in '*.conf' is this intentional?
2019-02-06 14:54:37,196 [virtwho.rhsm_log WARNING] MainProcess(22022):MainThread @config.py:init_config:1457 - [global]: Value for "interval" not set, using default: 3600
2019-02-06 14:54:37,196 [virtwho.rhsm_log WARNING] MainProcess(22022):MainThread @config.py:init_config:1457 - [global]: Value for "oneshot" not set, using default: False
2019-02-06 14:54:37,196 [virtwho.rhsm_log WARNING] MainProcess(22022):MainThread @config.py:init_config:1457 - [global]: Value for "log_per_config" not set, using default: False
2019-02-06 14:54:37,197 [virtwho.rhsm_log WARNING] MainProcess(22022):MainThread @config.py:init_config:1457 - [global]: Value for "print_" not set, using default: False
2019-02-06 14:54:37,197 [virtwho.rhsm_log WARNING] MainProcess(22022):MainThread @config.py:init_config:1457 - [global]: Value for "reporter_id" not set, using default: mmu110-32b128613e894681a6128ac0299ee1b8
2019-02-06 14:54:37,197 [virtwho.rhsm_log WARNING] MainProcess(22022):MainThread @config.py:init_config:1457 - [global]: Value for "log_dir" not set, using default: /var/log/rhsm
2019-02-06 14:54:37,197 [virtwho.rhsm_log WARNING] MainProcess(22022):MainThread @config.py:init_config:1457 - [global]: Value for "configs" not set, using default: []
2019-02-06 14:54:37,197 [virtwho.rhsm_log WARNING] MainProcess(22022):MainThread @config.py:init_config:1457 - [global]: Value for "log_file" not set, using default: rhsm.log
2019-02-06 14:54:37,197 [virtwho.rhsm_log WARNING] MainProcess(22022):MainThread @config.py:init_config:1457 - [VC1_IT]: Value for "simplified_vim" not set, using default: True
2019-02-06 14:54:37,197 [virtwho.rhsm_log WARNING] MainProcess(22022):MainThread @config.py:init_config:1457 - [VC1_IT]: Value for "is_hypervisor" not set, using default: True
2019-02-06 14:54:37,198 [virtwho.rhsm_log DEBUG] MainProcess(22022):MainThread @executor.py:__init__:54 - Using config named 'VC1_IT'
2019-02-06 14:54:37,198 [virtwho.rhsm_log INFO] MainProcess(22022):MainThread @main.py:main:159 - Using configuration "VC1_IT" ("esx" mode)
2019-02-06 14:54:37,198 [virtwho.rhsm_log INFO] MainProcess(22022):MainThread @main.py:main:161 - Using reporter_id='mmu110-32b128613e894681a6128ac0299ee1b8'
2019-02-06 14:54:37,206 [rhsm.https DEBUG] MainProcess(22022):MainThread @https.py:<module>:56 - Using standard libs to provide httplib and ssl
2019-02-06 14:54:37,200 [virtwho.main DEBUG] MainProcess(22022):MainThread @executor.py:run:187 - Starting infinite loop with 3600 seconds interval
2019-02-06 14:54:37,216 [virtwho.main DEBUG] MainProcess(22022):Thread-2 @virt.py:run:383 - Thread 'VC1_IT' started
2019-02-06 14:54:37,216 [virtwho.main DEBUG] MainProcess(22022):Thread-2 @esx.py:_prepare:133 - Log into ESX
2019-02-06 14:54:37,222 [virtwho.destination_-5950565710343276615 DEBUG] MainProcess(22022):Thread-3 @virt.py:run:383 - Thread 'destination_-5950565710343276615' started
2019-02-06 14:54:37,484 [virtwho.main DEBUG] MainProcess(22022):Thread-2 @esx.py:_prepare:136 - Creating ESX event filter
2019-02-06 14:54:42,551 [virtwho.main INFO] MainProcess(22022):Thread-2 @virt.py:_send_data:935 - Report for config "VC1_IT" gathered, placing in datastore
2019-02-06 14:54:43,456 [rhsm.connection INFO] MainProcess(22022):Thread-3 @connection.py:__init__:868 - Connection built: host=amu855 port=443 handler=/rhsm auth=identity_cert ca_dir=/etc/rhsm/ca/ insecure=0
2019-02-06 14:54:43,456 [rhsm.connection DEBUG] MainProcess(22022):Thread-3 @connection.py:_request:543 - Making request: GET /rhsm/status/
2019-02-06 14:54:43,455 [virtwho.destination_-5950565710343276615 INFO] MainProcess(22022):Thread-3 @virt.py:_send_data:598 - Hosts-to-guests mapping for config "VC1_IT": 1 hypervisors and 55 guests found
2019-02-06 14:54:43,455 [virtwho.destination_-5950565710343276615 INFO] MainProcess(22022):Thread-3 @virt.py:_send_data:629 - Sending updated Host-to-guest mapping to "rs" including 1 hypervisors and 55 guests
2019-02-06 14:54:43,455 [virtwho.destination_-5950565710343276615 DEBUG] MainProcess(22022):Thread-3 @subscriptionmanager.py:_connect:189 - Authenticating with certificate: /etc/pki/consumer/cert.pem
2019-02-06 14:54:43,502 [rhsm.connection INFO] MainProcess(22022):Thread-3 @connection.py:_request:586 - Response: status=200, request="GET /rhsm/status/"
2019-02-06 14:54:43,505 [rhsm.connection DEBUG] MainProcess(22022):Thread-3 @connection.py:_request:543 - Making request: GET /rhsm/consumers/4fbd7f60-eb61-4f96-a402-53001bd52a3b
2019-02-06 14:54:43,585 [rhsm.connection INFO] MainProcess(22022):Thread-3 @connection.py:_request:586 - Response: status=200, request="GET /rhsm/consumers/4fbd7f60-eb61-4f96-a402-53001bd52a3b"
2019-02-06 14:54:43,587 [rhsm.connection DEBUG] MainProcess(22022):Thread-3 @connection.py:_request:543 - Making request: GET /rhsm/consumers/4fbd7f60-eb61-4f96-a402-53001bd52a3b/owner
2019-02-06 14:54:43,644 [rhsm.connection INFO] MainProcess(22022):Thread-3 @connection.py:_request:586 - Response: status=200, request="GET /rhsm/consumers/4fbd7f60-eb61-4f96-a402-53001bd52a3b/owner"
2019-02-06 14:54:43,645 [rhsm.connection DEBUG] MainProcess(22022):Thread-3 @connection.py:_request:543 - Making request: GET /rhsm/status
2019-02-06 14:54:43,644 [virtwho.destination_-5950565710343276615 DEBUG] MainProcess(22022):Thread-3 @subscriptionmanager.py:_is_rhsm_server_async:296 - Checking if server has capability 'hypervisor_async'
2019-02-06 14:54:43,699 [rhsm.connection INFO] MainProcess(22022):Thread-3 @connection.py:_request:586 - Response: status=200, request="GET /rhsm/status"
2019-02-06 14:54:43,700 [rhsm.connection DEBUG] MainProcess(22022):Thread-3 @connection.py:_load_manager_capabilities:913 - Server has the following capabilities: [u'instance_multiplier', u'derived_product', u'vcpu', u'cert_v3', u'remove_by_pool_id', u'storage_band', u'cores', u'hypervisors_async', u'org_level_content_access', u'guest_limit', u'ram', u'batch_bind']
2019-02-06 14:54:43,703 [rhsm.connection DEBUG] MainProcess(22022):Thread-3 @connection.py:_request:543 - Making request: POST /rhsm/hypervisors/rs?reporter_id=mmu110-32b128613e894681a6128ac0299ee1b8&cloaked=False&env=Library%2FDefault_RHEL7
2019-02-06 14:54:43,700 [virtwho.destination_-5950565710343276615 DEBUG] MainProcess(22022):Thread-3 @subscriptionmanager.py:_is_rhsm_server_async:300 - Server has capability 'hypervisors_async'
2019-02-06 14:54:43,702 [virtwho.destination_-5950565710343276615 DEBUG] MainProcess(22022):Thread-3 @subscriptionmanager.py:hypervisorCheckIn:246 - Host-to-guest mapping being sent to 'rs': {
"hypervisors": [
{
"hypervisorId": {
"hypervisorId": "vmu147"
},
"name": "vmu147",
"guestIds": [
{
"guestId": "42280194-00d6-d167-05e4-c4e726ef77b8",
"state": 1,
"attributes": {
"active": 1,
"virtWhoType": "esx"
}
},
{
"guestId": "422802f8-a6eb-545e-651c-25acff847c1f",
"state": 5,
"attributes": {
"active": 0,
"virtWhoType": "esx"
}
},
{
"guestId": "4228070d-4225-a6bb-5cb3-daf1420dfe5a",
"state": 1,
"attributes": {
"active": 1,
"virtWhoType": "esx"
}
},
{
"guestId": "422811af-4c13-f09b-e883-c0767d84af1e",
"state": 1,
"attributes": {
"active": 1,
"virtWhoType": "esx"
}
},
{
"guestId": "42281712-ffd8-36be-144e-064673fd2cef",
"state": 5,
"attributes": {
"active": 0,
"virtWhoType": "esx"
}
},
{
"guestId": "42281aae-24e3-51b0-87c5-74a987b7c5a8",
"state": 1,
"attributes": {
"active": 1,
"virtWhoType": "esx"
}
},
{
"guestId": "42281af9-f6c2-1725-d4f1-376f7eefdacc",
"state": 1,
"attributes": {
"active": 1,
"virtWhoType": "esx"
}
},
{
"guestId": "42281b02-6f0f-8acd-a165-f73eae02a31e",
"state": 1,
"attributes": {
"active": 1,
"virtWhoType": "esx"
}
},
{
"guestId": "42281f97-3c9e-2cd9-0ca6-0edf8704b845",
"state": 1,
"attributes": {
"active": 1,
"virtWhoType": "esx"
}
},
{
"guestId": "4228227a-e9b0-9cf6-e5af-d49a2e4eae9b",
"state": 1,
"attributes": {
"active": 1,
"virtWhoType": "esx"
}
},
{
"guestId": "42283bbf-0310-3a47-98c2-f8ef1f55a6aa",
"state": 1,
"attributes": {
"active": 1,
"virtWhoType": "esx"
}
},
{
"guestId": "4228470f-d51b-0f88-2288-b8fcc08a9bac",
"state": 1,
"attributes": {
"active": 1,
"virtWhoType": "esx"
}
},
{
"guestId": "422847d7-ca1c-919c-2694-467a2438a76c",
"state": 1,
"attributes": {
"active": 1,
"virtWhoType": "esx"
}
},
{
"guestId": "42284a98-d6e3-13ff-5670-e5736fb9d6f9",
"state": 1,
"attributes": {
"active": 1,
"virtWhoType": "esx"
}
},
{
"guestId": "4228566b-fc6f-c612-5e99-6a0c0ee5228c",
"state": 1,
"attributes": {
"active": 1,
"virtWhoType": "esx"
}
},
{
"guestId": "422858f4-4874-3ae3-b37d-3b0dcf633799",
"state": 1,
"attributes": {
"active": 1,
"virtWhoType": "esx"
}
},
{
"guestId": "42285c4e-20d7-634b-9d04-042e20f9dda8",
"state": 1,
"attributes": {
"active": 1,
"virtWhoType": "esx"
}
},
{
"guestId": "422862a0-7fe9-17c2-c854-db31c80b4612",
"state": 5,
"attributes": {
"active": 0,
"virtWhoType": "esx"
}
},
{
"guestId": "42286fbd-7943-f584-79d5-3b40d76ba574",
"state": 1,
"attributes": {
"active": 1,
"virtWhoType": "esx"
}
},
{
"guestId": "422870c5-a5da-e934-1764-04d006af14cf",
"state": 1,
"attributes": {
"active": 1,
"virtWhoType": "esx"
}
},
{
"guestId": "422876db-d346-f404-0c02-42404d97bb73",
"state": 5,
"attributes": {
"active": 0,
"virtWhoType": "esx"
}
},
{
"guestId": "422879f6-f410-52c3-f1f2-32246d2a3269",
"state": 1,
"attributes": {
"active": 1,
"virtWhoType": "esx"
}
},
{
"guestId": "42287e39-a849-cb25-3f48-1fa79904d18d",
"state": 1,
"attributes": {
"active": 1,
"virtWhoType": "esx"
}
},
{
"guestId": "42288793-ff8e-4436-dd31-bb246fd5bbfc",
"state": 1,
"attributes": {
"active": 1,
"virtWhoType": "esx"
}
},
{
"guestId": "422887d4-0b72-5d85-1865-18f77c846c67",
"state": 5,
"attributes": {
"active": 0,
"virtWhoType": "esx"
}
},
{
"guestId": "422887d4-0b72-5d85-1865-18f77c846c67",
"state": 5,
"attributes": {
"active": 0,
"virtWhoType": "esx"
}
},
{
"guestId": "42288eb3-0ca7-2b1f-81cf-507977a94e17",
"state": 1,
"attributes": {
"active": 1,
"virtWhoType": "esx"
}
},
{
"guestId": "4228903f-f30b-c0cf-e63e-54e2e2071f7c",
"state": 1,
"attributes": {
"active": 1,
"virtWhoType": "esx"
}
},
{
"guestId": "422891ed-44bc-82f1-cea0-a7175ae64bb5",
"state": 1,
"attributes": {
"active": 1,
"virtWhoType": "esx"
}
},
{
"guestId": "4228a0f7-25cf-0594-48b8-da801c75da94",
"state": 1,
"attributes": {
"active": 1,
"virtWhoType": "esx"
}
},
{
"guestId": "4228ac1f-00bc-fb42-22bd-908ecf6786a8",
"state": 5,
"attributes": {
"active": 0,
"virtWhoType": "esx"
}
},
{
"guestId": "4228aeb1-be56-fb21-39eb-9839cec9e9c4",
"state": 5,
"attributes": {
"active": 0,
"virtWhoType": "esx"
}
},
{
"guestId": "4228b31d-8675-b3c6-5625-8e41b399b813",
"state": 1,
"attributes": {
"active": 1,
"virtWhoType": "esx"
}
},
{
"guestId": "4228b39b-7464-6ef4-8afc-73d986abd820",
"state": 5,
"attributes": {
"active": 0,
"virtWhoType": "esx"
}
},
{
"guestId": "4228b42f-5490-330e-24df-b8dc139c2e6b",
"state": 1,
"attributes": {
"active": 1,
"virtWhoType": "esx"
}
},
{
"guestId": "4228bc43-af6b-087c-db95-5197b58889e1",
"state": 1,
"attributes": {
"active": 1,
"virtWhoType": "esx"
}
},
{
"guestId": "4228c44c-9c12-9f5a-d5ea-3476c3e79a82",
"state": 5,
"attributes": {
"active": 0,
"virtWhoType": "esx"
}
},
{
"guestId": "4228c690-6d9c-1e01-1499-fb5c9721d5ff",
"state": 1,
"attributes": {
"active": 1,
"virtWhoType": "esx"
}
},
{
"guestId": "4228c6c6-f8e9-d44b-a60d-ef8b757ae1a8",
"state": 1,
"attributes": {
"active": 1,
"virtWhoType": "esx"
}
},
{
"guestId": "4228cc0d-4942-ec1b-cb17-37866a7f39be",
"state": 1,
"attributes": {
"active": 1,
"virtWhoType": "esx"
}
},
{
"guestId": "4228cce5-010b-bfb9-8083-e00352b3efe0",
"state": 1,
"attributes": {
"active": 1,
"virtWhoType": "esx"
}
},
{
"guestId": "4228d6ec-f26b-2f8f-8a43-ad33a65cbc26",
"state": 1,
"attributes": {
"active": 1,
"virtWhoType": "esx"
}
},
{
"guestId": "4228d9fe-12f5-2c52-5c87-e52ef7d3364e",
"state": 1,
"attributes": {
"active": 1,
"virtWhoType": "esx"
}
},
{
"guestId": "4228da60-8daf-4507-d501-42afac921212",
"state": 1,
"attributes": {
"active": 1,
"virtWhoType": "esx"
}
},
{
"guestId": "4228df48-1651-aeec-f98f-775d50bb63d0",
"state": 1,
"attributes": {
"active": 1,
"virtWhoType": "esx"
}
},
{
"guestId": "4228df7b-896c-548f-cdaf-c99cfe0c72e3",
"state": 1,
"attributes": {
"active": 1,
"virtWhoType": "esx"
}
},
{
"guestId": "4228df84-c297-77a3-fd60-26b20ef20b35",
"state": 1,
"attributes": {
"active": 1,
"virtWhoType": "esx"
}
},
{
"guestId": "4228eecd-797a-c925-090b-8499042f1fbc",
"state": 5,
"attributes": {
"active": 0,
"virtWhoType": "esx"
}
},
{
"guestId": "4228f181-573a-99f8-c2b9-e1a6b80cfc9e",
"state": 1,
"attributes": {
"active": 1,
"virtWhoType": "esx"
}
},
{
"guestId": "4228f1a3-b9a2-76f2-9a4b-be83dbd427c7",
"state": 1,
"attributes": {
"active": 1,
"virtWhoType": "esx"
}
},
{
"guestId": "4228f57e-43db-b189-2617-6d598b7cc0f2",
"state": 5,
"attributes": {
"active": 0,
"virtWhoType": "esx"
}
},
{
"guestId": "4228f8e0-355c-fb99-fbf6-b52ba7e1b825",
"state": 1,
"attributes": {
"active": 1,
"virtWhoType": "esx"
}
},
{
"guestId": "4228f8ee-65f2-115b-750b-d34a50b5c89f",
"state": 1,
"attributes": {
"active": 1,
"virtWhoType": "esx"
}
},
{
"guestId": "4228f90e-2928-fc32-fae0-498c0d29540b",
"state": 1,
"attributes": {
"active": 1,
"virtWhoType": "esx"
}
},
{
"guestId": "4228fc9d-c825-192b-bf95-3ffc10e11fa0",
"state": 1,
"attributes": {
"active": 1,
"virtWhoType": "esx"
}
}
],
"facts": {
"hypervisor.type": "VMware ESXi",
"cpu.cpu_socket(s)": "2",
"hypervisor.cluster": "Cluster-5(RedHat)",
"hypervisor.version": "6.0.0"
}
}
]
}
2019-02-06 14:54:43,967 [rhsm.connection INFO] MainProcess(22022):Thread-3 @connection.py:_request:586 - Response: status=200, request="POST /rhsm/hypervisors/rs?reporter_id=mmu110-32b128613e894681a6128ac0299ee1b8&cloaked=False&env=Library%2FDefault_RHEL7"
2019-02-06 14:54:58,983 [rhsm.connection INFO] MainProcess(22022):Thread-3 @connection.py:__init__:868 - Connection built: host=amu855 port=443 handler=/rhsm auth=identity_cert ca_dir=/etc/rhsm/ca/ insecure=0
2019-02-06 14:54:58,983 [rhsm.connection DEBUG] MainProcess(22022):Thread-3 @connection.py:_request:543 - Making request: GET /rhsm/status/
2019-02-06 14:54:58,983 [virtwho.destination_-5950565710343276615 DEBUG] MainProcess(22022):Thread-3 @subscriptionmanager.py:_connect:189 - Authenticating with certificate: /etc/pki/consumer/cert.pem
2019-02-06 14:54:59,036 [rhsm.connection INFO] MainProcess(22022):Thread-3 @connection.py:_request:586 - Response: status=200, request="GET /rhsm/status/"
2019-02-06 14:54:59,037 [rhsm.connection DEBUG] MainProcess(22022):Thread-3 @connection.py:_request:543 - Making request: GET /rhsm/consumers/4fbd7f60-eb61-4f96-a402-53001bd52a3b
2019-02-06 14:54:59,118 [rhsm.connection INFO] MainProcess(22022):Thread-3 @connection.py:_request:586 - Response: status=200, request="GET /rhsm/consumers/4fbd7f60-eb61-4f96-a402-53001bd52a3b"
2019-02-06 14:54:59,119 [rhsm.connection DEBUG] MainProcess(22022):Thread-3 @connection.py:_request:543 - Making request: GET /rhsm/consumers/4fbd7f60-eb61-4f96-a402-53001bd52a3b/owner
2019-02-06 14:54:59,175 [rhsm.connection INFO] MainProcess(22022):Thread-3 @connection.py:_request:586 - Response: status=200, request="GET /rhsm/consumers/4fbd7f60-eb61-4f96-a402-53001bd52a3b/owner"
2019-02-06 14:54:59,176 [rhsm.connection DEBUG] MainProcess(22022):Thread-3 @connection.py:_request:543 - Making request: GET /rhsm/jobs/hypervisor_update_8692afb3-20be-4044-88ff-074b5c852f79?result_data=True
2019-02-06 14:54:59,176 [virtwho.destination_-5950565710343276615 DEBUG] MainProcess(22022):Thread-3 @subscriptionmanager.py:check_report_state:344 - Checking status of job hypervisor_update_8692afb3-20be-4044-88ff-074b5c852f79
2019-02-06 14:54:59,225 [rhsm.connection INFO] MainProcess(22022):Thread-3 @connection.py:_request:586 - Response: status=200, request="GET /rhsm/jobs/hypervisor_update_8692afb3-20be-4044-88ff-074b5c852f79?result_data=True"
2019-02-06 14:54:59,226 [virtwho.destination_-5950565710343276615 DEBUG] MainProcess(22022):Thread-3 @subscriptionmanager.py:check_report_state:369 - Number of mappings unchanged: 1
2019-02-06 14:54:59,226 [virtwho.destination_-5950565710343276615 INFO] MainProcess(22022):Thread-3 @subscriptionmanager.py:check_report_state:370 - Mapping for config "destination_-5950565710343276615" updated
2019-02-06 14:56:19,438 [virtwho.main INFO] MainProcess(22022):Thread-2 @virt.py:_send_data:935 - Report for config "VC1_IT" gathered, placing in datastore
2019-02-06 14:56:24,644 [virtwho.main DEBUG] MainProcess(22022):MainThread @executor.py:terminate:225 - virt-who is shutting down
2019-02-06 14:56:25,319 [virtwho.destination_-5950565710343276615 DEBUG] MainProcess(22022):Thread-3 @virt.py:run:402 - Thread 'destination_-5950565710343276615' terminated
2019-02-06 14:56:29,681 [virtwho.main INFO] MainProcess(22022):Thread-2 @esx.py:logout:401 - Can't log out from ESX: Server raised fault: 'The session is not authenticated.'
2019-02-06 14:56:29,681 [virtwho.main DEBUG] MainProcess(22022):Thread-2 @virt.py:run:402 - Thread 'VC1_IT' terminated
(4-4/5)